Microsoft Azure App OAuth2 Login Callback Phase takes very long

  • Used Zammad version: 5.3.1-1676465796.746f9768.focal
  • Used Zammad installation type: package
  • Operating system: Ubuntu 20.04
  • Browser + version: any browser

Expected behavior:

  • After redirecting to the callback url, the user should be redirected to the dashboard in an appropriate time

Actual behavior:

  • The azure token endpoint redirects to the redirect url of the ticket system instance. The logs show that a callback phase has started. Now, it takes around 15-20sec until it responds with HTTP 302 and redirects to the dashboard. A second before the response the log file says that “Reading image from tempfile '#Tempfile:/tmp/avatar20230220-2977-30l81j.jpeg”. When the redirect comes, the log file says “Completed 302 Found in 101ms (ActiveRecord: 35.5ms | Allocations: 23343)”.

Steps to reproduce the behavior:

  • It suddenly occured after having the system running for more than three years now.

What exactly takes 20 seconds to load.
Until you see the initial Zammad application page or loading through all tabs your user has open?

Hi,
I’ve got the exact same problem on v5.2.3 on an Ubuntu Server 22.04.2 LTS. Will try to update to the latest version of Zammad to check whether that helps.
He’s probably tracking the time till initial page render of the zammad application page, at least I am. In my case, this issue was there since the installation at the end of august of 2022.

Here are my logs:

I, [2023-03-07T16:27:44.822343 #658-4771060]  INFO -- : Started POST "/auth/microsoft_office365" for xx.xx.xx.xx at 2023-03-07 16:27:44 +0000
I, [2023-03-07T16:27:44.834665 #658-4771060]  INFO -- : (microsoft_office365) Request phase initiated.
I, [2023-03-07T16:27:45.162019 #658-4769360]  INFO -- : Started GET "/auth/microsoft_office365/callback?code=[FILTERED]&state=xxxx&session_state=xxxxx" for xx.xx.xx.xx at 2023-03-07 16:27:45 +0000
I, [2023-03-07T16:27:45.168507 #658-4769360]  INFO -- : (microsoft_office365) Callback phase initiated.
I, [2023-03-07T16:27:49.421367 #1004260-109380]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2023-03-07T16:27:59.421942 #1004260-109380]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2023-03-07T16:28:04.153223 #658-4769360]  INFO -- : Processing by SessionsController#create_omniauth as HTML
I, [2023-03-07T16:28:04.153417 #658-4769360]  INFO -- :   Parameters: {"code"=>"[FILTERED]", "state"=>"xxxxx", "session_state"=>"xxxxx", "provider"=>"microsoft_office365"}
I, [2023-03-07T16:28:04.246018 #658-4769360]  INFO -- : Reading image from tempfile '#<Tempfile:/tmp/avatar20230307-658-gnza09.jpeg>'
I, [2023-03-07T16:28:04.327384 #658-4769360]  INFO -- : Redirected to https://xxxxx.xx/
I, [2023-03-07T16:28:04.330047 #658-4769360]  INFO -- : Completed 302 Found in 176ms (ActiveRecord: 64.3ms | Allocations: 20220)
I, [2023-03-07T16:28:04.363774 #658-4769240]  INFO -- : Started GET "/" for xx.xx.xx.xx at 2023-03-07 16:28:04 +0000
I, [2023-03-07T16:28:04.373676 #658-4769240]  INFO -- : Processing by InitController#index as HTML
I, [2023-03-07T16:28:04.384602 #658-4769240]  INFO -- :   Rendered init/index.html.erb within layouts/application (Duration: 0.3ms | Allocations: 67)
I, [2023-03-07T16:28:04.385900 #658-4769240]  INFO -- :   Rendered layout layouts/application.html.erb (Duration: 1.6ms | Allocations: 510)
I, [2023-03-07T16:28:04.387690 #658-4769240]  INFO -- : Completed 200 OK in 14ms (Views: 2.4ms | ActiveRecord: 4.0ms | Allocations: 2949)
I, [2023-03-07T16:28:04.553063 #658-4769540]  INFO -- : Started POST "/api/v1/signshow" for xx.xx.xx.xx at 2023-03-07 16:28:04 +0000
I, [2023-03-07T16:28:04.568528 #658-4769540]  INFO -- : Processing by SessionsController#show as JSON
I, [2023-03-07T16:28:04.568659 #658-4769540]  INFO -- :   Parameters: {"fingerprint"=>"276055661"}
I, [2023-03-07T16:28:05.230605 #658-4769540]  INFO -- : Completed 200 OK in 662ms (Views: 59.4ms | ActiveRecord: 83.0ms | Allocations: 179555)
I, [2023-03-07T16:28:05.280114 #658-4769160]  INFO -- : Started GET "/api/v1/translations/lang/de-de?_=1678206484507" for xx.xx.xx.xx at 2023-03-07 16:28:05 +0000
I, [2023-03-07T16:28:05.295355 #658-4769160]  INFO -- : Processing by TranslationsController#lang as JSON
I, [2023-03-07T16:28:05.295769 #658-4769160]  INFO -- :   Parameters: {"_"=>"1678206484507", "locale"=>"de-de"}
I, [2023-03-07T16:28:05.605571 #658-4769160]  INFO -- : Completed 200 OK in 309ms (Views: 230.2ms | ActiveRecord: 55.2ms | Allocations: 50195)
I, [2023-03-07T16:28:05.720487 #658-4769320]  INFO -- : Started GET "/api/v1/users/image/65378b0c17fee52b25a1333b27eee1a2" for xx.xx.xx.xx at 2023-03-07 16:28:05 +0000
I, [2023-03-07T16:28:05.732638 #658-4769320]  INFO -- : Processing by UsersController#image as HTML
I, [2023-03-07T16:28:05.732776 #658-4769320]  INFO -- :   Parameters: {"hash"=>"65378b0c17fee52b25a1333b27eee1a2"}
I, [2023-03-07T16:28:05.740931 #658-4771180]  INFO -- : Started GET "/api/v1/activity_stream?full=true&limit=25&_=1678206484508" for xx.xx.xx.xx at 2023-03-07 16:28:05 +0000
I, [2023-03-07T16:28:05.745022 #658-4584820]  INFO -- : Started GET "/api/v1/first_steps?_=1678206484509" for xx.xx.xx.xx at 2023-03-07 16:28:05 +0000
I, [2023-03-07T16:28:05.754862 #658-4584820]  INFO -- : Processing by FirstStepsController#index as JSON
I, [2023-03-07T16:28:05.755196 #658-4584820]  INFO -- :   Parameters: {"_"=>"1678206484509"}
I, [2023-03-07T16:28:05.764913 #658-4771180]  INFO -- : Processing by ActivityStreamController#show as JSON
I, [2023-03-07T16:28:05.765024 #658-4771180]  INFO -- :   Parameters: {"full"=>"true", "limit"=>"25", "_"=>"1678206484508"}
I, [2023-03-07T16:28:05.794828 #658-4769320]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 1)
I, [2023-03-07T16:28:05.797553 #658-4769320]  INFO -- : Sent data avatar (3.1ms)
I, [2023-03-07T16:28:05.799069 #658-4769320]  INFO -- : Completed 200 OK in 66ms (Views: 2.9ms | ActiveRecord: 39.5ms | Allocations: 23320)
I, [2023-03-07T16:28:05.807772 #658-4584820]  INFO -- : Completed 200 OK in 52ms (Views: 0.4ms | ActiveRecord: 33.0ms | Allocations: 18362)
I, [2023-03-07T16:28:06.002526 #658-4771180]  INFO -- : Completed 200 OK in 237ms (Views: 17.8ms | ActiveRecord: 71.9ms | Allocations: 69642)
I, [2023-03-07T16:28:06.089825 #658-4771300]  INFO -- : Started GET "/api/v1/users/image/313e166492d1125f1a47fa4cd0382020" for xx.xx.xx.xx at 2023-03-07 16:28:06 +0000
I, [2023-03-07T16:28:06.105453 #658-4771300]  INFO -- : Processing by UsersController#image as HTML
I, [2023-03-07T16:28:06.105615 #658-4771300]  INFO -- :   Parameters: {"hash"=>"313e166492d1125f1a47fa4cd0382020"}
I, [2023-03-07T16:28:06.139026 #658-4771300]  INFO -- :   Rendered text template (Duration: 0.0ms | Allocations: 1)
I, [2023-03-07T16:28:06.139355 #658-4771300]  INFO -- : Sent data avatar (1.7ms)
I, [2023-03-07T16:28:06.141895 #658-4771300]  INFO -- : Completed 200 OK in 36ms (Views: 0.7ms | ActiveRecord: 12.1ms | Allocations: 4167)
I, [2023-03-07T16:28:06.387251 #658-4771260]  INFO -- : Started GET "/api/v1/cti/log?_=1678206484510" for xx.xx.xx.xx at 2023-03-07 16:28:06 +0000
I, [2023-03-07T16:28:06.401662 #658-4771260]  INFO -- : Processing by CtiController#index as JSON
I, [2023-03-07T16:28:06.401806 #658-4771260]  INFO -- :   Parameters: {"_"=>"1678206484510"}
I, [2023-03-07T16:28:06.436253 #658-4771260]  INFO -- : Completed 200 OK in 34ms (Views: 0.4ms | ActiveRecord: 12.5ms | Allocations: 5887)

It is the duration between the oauth2 callback request and the dashboard when it is visible in the browser. It seems like the same problem as jok has.

If it’s the application responding too slow to the initial connect request, then you’d want to have a look at Zammad’s WEB_CONCURRENCY which might not be high enough.

Please see:
Configuration via Environment Variables — Zammad documentation (performance tuning section)