I’m still fighting with this issue, so I raised the log level to debug and I captured the following trace:
I, [2024-07-15T09:01:10.648109#51368-148900] INFO -- : Started POST "/auth/saml" for 192.168.1.12 at 2024-07-15 09:01:10 +0200
D, [2024-07-15T09:01:10.668530#51368-148900] DEBUG -- : (saml) Request phase initiated.
D, [2024-07-15T09:01:10.669996#51368-148900] DEBUG -- : Created AuthnRequest: <samlp:AuthnRequest AssertionConsumerServiceURL='https://zammad-test.me.org/auth/saml/callback' Destination='https://zammad-test.me.org/Shibboleth.sso/Login' ID='_68990709-eea6-451b-b3c5-734e091dfd35' IssueInstant='2024-07-15T07:01:10Z' Version='2.0' xmlns:saml='urn:oasis:names:tc:SAML:2.0:assertion' xmlns:samlp='urn:oasis:names:tc:SAML:2.0:protocol'><saml:Issuer>https://zammad-test.me.org/auth/saml/metadata</saml:Issuer><samlp:NameIDPolicy AllowCreate='true' Format='urn:mace:dir:attribute-def:mail'/></samlp:AuthnRequest>
I, [2024-07-15T09:01:10.830220#51368-149020] INFO -- : Started GET "/" for 192.168.1.12 at 2024-07-15 09:01:10 +0200
I, [2024-07-15T09:01:10.835453#51368-149020] INFO -- : Processing by InitController#index as HTML
D, [2024-07-15T09:01:10.838136#51368-149020] DEBUG -- : User Load (0.7ms) SELECT "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1 [["LIMIT", 1]]
D, [2024-07-15T09:01:10.840090#51368-149020] DEBUG -- : CACHE User Load (0.0ms) SELECT "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1 [["LIMIT", 1]]
D, [2024-07-15T09:01:10.841503#51368-149020] DEBUG -- : User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
D, [2024-07-15T09:01:10.847495#51368-149020] DEBUG -- : Permission Pluck (0.9ms) SELECT "permissions"."name" FROM "permissions" INNER JOIN "permissions_roles" ON "permissions"."id" = "permissions_roles"."permission_id" INNER JOIN "roles" ON "permissions_roles"."role_id" = "roles"."id" INNER JOIN "roles_users" ON "roles"."id" = "roles_users"."role_id" WHERE "roles_users"."user_id" = $1 AND "roles"."active" = $2 AND "permissions"."active" = $3 [["user_id", 1], ["active", true], ["active", true]]
D, [2024-07-15T09:01:10.851996#51368-149020] DEBUG -- : Rendering layout layouts/application.html.erb
D, [2024-07-15T09:01:10.852220#51368-149020] DEBUG -- : Rendering init/index.html.erb within layouts/application
I, [2024-07-15T09:01:10.853217#51368-149020] INFO -- : Rendered init/index.html.erb within layouts/application (Duration: 0.8ms | Allocations: 437)
I, [2024-07-15T09:01:10.855111#51368-149020] INFO -- : Rendered layout layouts/application.html.erb (Duration: 2.9ms | Allocations: 1722)
D, [2024-07-15T09:01:10.860130#51368-149020] DEBUG -- : Setting Load (0.6ms) SELECT "settings".* FROM "settings" WHERE "settings"."area" = $1 ORDER BY "settings"."name" ASC [["area", "Transaction::Backend::Sync"]]
I, [2024-07-15T09:01:10.860793#51368-149020] INFO -- : Completed 200 OK in 25ms (Views: 4.9ms | ActiveRecord: 3.3ms | Allocations: 7885)
I, [2024-07-15T09:01:10.959790#51368-149320] INFO -- : Started POST "/api/v1/signshow" for 192.168.1.12 at 2024-07-15 09:01:10 +0200
I, [2024-07-15T09:01:10.965215#51368-149320] INFO -- : Processing by SessionsController#show as JSON
I, [2024-07-15T09:01:10.965421#51368-149320] INFO -- : Parameters: {"fingerprint"=>"1689343078"}
D, [2024-07-15T09:01:10.966632#51368-149320] DEBUG -- : User Load (0.3ms) SELECT "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1 [["LIMIT", 1]]
D, [2024-07-15T09:01:10.967388#51368-149320] DEBUG -- : CACHE User Load (0.0ms) SELECT "users".* FROM "users" WHERE "users"."id" IS NULL LIMIT $1 [["LIMIT", 1]]
Apparently the login is successful, If, after being redirected to the login page, I inspect /Shibboleth.sso/Session
, I can see my Shibboleth login being performed well.
Is it zammad not understanding some session variable hence requesting the login over and over?