M365 broken: Failed to refresh XOAUTH2 access_token

yoursql719 · November 11, 2024, 2:12pm

Hi,

I´m using the latest version of zammad 6.4 at debian 12. Since today no new tickets can be imported from M365:

Failed to refresh XOAUTH2 access_token of provider 'microsoft365': Request failed!

I haven´t changed anything at this connection and the secrets are valid. Can it be related to zammad 6.4?

MrGeneration · November 11, 2024, 4:30pm

Your production.log will contain a much more detailed traceback. I’d say your secret is no longer valid / expired.

yoursql719 · November 11, 2024, 6:39pm

Thanks. The secret was updated two months ago and expires in 2026 - so I don´t think so.

The production.log says:

E, [2024-11-11T19:33:15.619683#6566-179920] ERROR -- : Can't use Channel::Driver::Imap: #<RuntimeError: Failed to refresh XOAUTH2 access_token of provider 'microsoft365': Request failed! (code: 0)>
E, [2024-11-11T19:33:15.619703#6566-179920] ERROR -- : Failed to refresh XOAUTH2 access_token of provider 'microsoft365': Request failed! (code: 0) (RuntimeError)
app/models/channel.rb:370:in `rescue in refresh_xoauth2!'
app/models/channel.rb:355:in `refresh_xoauth2!'
app/models/channel.rb:58:in `fetch'
app/models/channel.rb:36:in `fetch'
(eval):1:in `eval_job_method'

Re authentication and admin grant buttons give a 500 error:

E, [2024-11-11T19:43:04.383135#6566-179860] ERROR -- : https://geo.zammad.com/lookup?ip=91.114.81.36: #<RuntimeError: 0/>
I, [2024-11-11T19:43:04.389901#6566-179860]  INFO -- : 2024-11-11T19:43:04+0100: [Worker(host:support pid:6566)] Job UserDeviceLogJob [c0ef3b4e-3510-40e4-ae5e-ca1706b17dcc] from DelayedJob(default) with arguments: ["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/130.0.0.0 Safari/537.36", "91.114.81.36", 4, "-1868058830", "session"] (id=2889264) (queue=default) COMPLETED after 2.0447
I, [2024-11-11T19:43:05.343788#6566-179880]  INFO -- : ProcessScheduledJobs running...
I, [2024-11-11T19:43:05.345426#6566-179880]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2024-11-11T19:43:05.345487#6566-179880]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2024-11-11T19:43:05.345655#6566-179880]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2024-11-11T19:43:05.345704#6566-179880]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2024-11-11T19:43:05.345750#6566-179880]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
I, [2024-11-11T19:43:14.496786#6557-230460]  INFO -- : Started GET "/api/v1/external_credentials/microsoft365/callback?code=[FILTERED]&session_state=2e50528a-8913-4a02-938c-1e1a5ac264ac" for 91.114.81.36 at 2024-11-11 19:43:14 +0100
I, [2024-11-11T19:43:14.505682#6557-230460]  INFO -- : Processing by ExternalCredentialsController#callback as HTML
I, [2024-11-11T19:43:14.505756#6557-230460]  INFO -- :   Parameters: {"code"=>"[FILTERED]", "session_state"=>"2e50528a-8913-4a02-938c-1e1a5ac264ac", "provider"=>"microsoft365"}
I, [2024-11-11T19:43:15.347172#6566-179880]  INFO -- : ProcessScheduledJobs running...
I, [2024-11-11T19:43:15.349115#6566-179880]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2024-11-11T19:43:15.349230#6566-179880]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2024-11-11T19:43:15.349421#6566-179880]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2024-11-11T19:43:15.349473#6566-179880]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2024-11-11T19:43:15.349519#6566-179880]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
E, [2024-11-11T19:43:18.527653#6557-230460] ERROR -- : Request failed! (code: 0)
E, [2024-11-11T19:43:18.528101#6557-230460] ERROR -- : Request failed! (code: 0) (RuntimeError)
lib/external_credential/microsoft365.rb:209:in `authorize_tokens'
lib/external_credential/microsoft365.rb:46:in `link_account'
app/models/external_credential.rb:21:in `link_account'
app/controllers/external_credentials_controller.rb:43:in `callback'
app/controllers/application_controller/has_download.rb:17:in `block (4 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:16:in `block (3 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:15:in `block (2 levels) in <module:HasDownload>'
app/controllers/application_controller/handles_transitions.rb:16:in `handle_transaction'
I, [2024-11-11T19:43:18.536784#6557-230460]  INFO -- : Completed 500 Internal Server Error in 4030ms (Views: 2.5ms | ActiveRecord: 1.9ms | Allocations: 7009)
I, [2024-11-11T19:43:23.979425#6566-179920]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2024-11-11T19:43:25.351052#6566-179880]  INFO -- : ProcessScheduledJobs running...
I, [2024-11-11T19:43:25.352449#6566-179880]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2024-11-11T19:43:25.352525#6566-179880]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2024-11-11T19:43:25.352767#6566-179880]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2024-11-11T19:43:25.352879#6566-179880]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2024-11-11T19:43:25.353271#6566-179880]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep

MrGeneration · November 11, 2024, 7:08pm

Check firewall / proxy configuration?

yoursql719 · November 11, 2024, 7:24pm

Firewall didn’t changed and nginx vhost is the same. Is it possible to get more debug Infos?

fliebe92 · November 11, 2024, 7:35pm

Why is https://geo.zammad.com/lookup?ip=91.114.81.36 returning a 500 error in your instance?

yoursql719 · November 11, 2024, 8:06pm

When 500 error is returned by your instance the error is at your side, isn’t it? I don’t know how I could debut it. Any hints?

MrGeneration · November 11, 2024, 8:20pm

No geo definitely is not returning that error 500. I am still opting for a proxy. proxy habdling was improved as far as I am aware.

yoursql719 · November 12, 2024, 6:34am

Thanks, I´ve checked nginx config. It is the same like at /opt/zammad/contrib/nginx/…

fliebe92 · November 12, 2024, 6:37am

When 500 error is returned by your instance the error is at your side, isn’t it? I don’t know how I could debut it. Any hints?

Nope, it’s working fine here. I still think it’s something in your environment.

yoursql719 · November 12, 2024, 6:40am

OK, is there any debug log I can activate for more specific errors? I´m wondering why it worked before version 6.4.

fliebe92 · November 12, 2024, 7:08am

You can try to disable the service that was mentioned in your log. If this is working afterward, you know, there really is an issue in your environment.

yoursql719 · November 12, 2024, 7:14am

Thanks, I´ve disabled the service:

But it does not solve the problem. I´ven´t seen the geo ip error for now.

I´ve deleted the m365 mail channel and I am trying to re-create it, but it does not work:

I, [2024-11-12T08:10:55.119381#26146-238440]  INFO -- : Started GET "/api/v1/external_credentials/microsoft365/link_account" for 91.114.81.36 at 2024-11-12 08:10:55 +0100
I, [2024-11-12T08:10:55.123503#26146-238440]  INFO -- : Processing by ExternalCredentialsController#link_account as HTML
I, [2024-11-12T08:10:55.123553#26146-238440]  INFO -- :   Parameters: {"provider"=>"microsoft365"}
I, [2024-11-12T08:10:55.132074#26146-238440]  INFO -- : Redirected to https://login.microsoftonline.com/b111a29e-7c92-4659-a8a1-fe1657045032/oauth2/v2.0/authorize?access_type=offline&client_id=60616fdf-450a-4159-ac78-2ecb92781d07&prompt=login&redirect_uri=https%3A%2F%2Fsupport.xy.at%2Fapi%2Fv1%2Fexternal_credentials%2Fmicrosoft365%2Fcallback&response_type=code&scope=https%3A%2F%2Foutlook.office.com%2FIMAP.AccessAsUser.All+https%3A%2F%2Foutlook.office.com%2FSMTP.Send+offline_access+openid+profile+email
I, [2024-11-12T08:10:55.133125#26146-238440]  INFO -- : Completed 302 Found in 10ms (ActiveRecord: 1.7ms | Allocations: 5317)
I, [2024-11-12T08:11:00.127303#26159-190300]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2024-11-12T08:11:00.128050#26159-190300]  INFO -- : ended Channel.fetch took: 0.003813451 seconds.
I, [2024-11-12T08:11:02.350147#26146-233880]  INFO -- : Started GET "/api/v1/external_credentials/microsoft365/callback?code=[FILTERED]&session_state=d7eafb77-80cc-4465-86ea-13237690bc31" for 91.114.81.36 at 2024-11-12 08:11:02 +0100
I, [2024-11-12T08:11:02.355162#26146-233880]  INFO -- : Processing by ExternalCredentialsController#callback as HTML
I, [2024-11-12T08:11:02.355259#26146-233880]  INFO -- :   Parameters: {"code"=>"[FILTERED]", "session_state"=>"d7eafb77-80cc-4465-86ea-13237690bc31", "provider"=>"microsoft365"}
I, [2024-11-12T08:11:04.403892#26159-179880]  INFO -- : ProcessScheduledJobs running...
I, [2024-11-12T08:11:04.405647#26159-179880]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2024-11-12T08:11:04.405740#26159-179880]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2024-11-12T08:11:04.405799#26159-179880]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2024-11-12T08:11:04.405828#26159-179880]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2024-11-12T08:11:04.406585#26159-179880]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
E, [2024-11-12T08:11:06.365713#26146-233880] ERROR -- : Request failed! (code: 0)
E, [2024-11-12T08:11:06.366035#26146-233880] ERROR -- : Request failed! (code: 0) (RuntimeError)
lib/external_credential/microsoft365.rb:209:in `authorize_tokens'
lib/external_credential/microsoft365.rb:46:in `link_account'
app/models/external_credential.rb:21:in `link_account'
app/controllers/external_credentials_controller.rb:43:in `callback'
app/controllers/application_controller/has_download.rb:17:in `block (4 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:16:in `block (3 levels) in <module:HasDownload>'
app/controllers/application_controller/has_download.rb:15:in `block (2 levels) in <module:HasDownload>'
app/controllers/application_controller/handles_transitions.rb:16:in `handle_transaction'
I, [2024-11-12T08:11:06.368579#26146-233880]  INFO -- : Completed 500 Internal Server Error in 4013ms (Views: 0.7ms | ActiveRecord: 2.3ms | Allocations: 6892)

Also I´ve recreated the app secret and set it again at zammad:

What I can see at the log of the azure app: the user, which holds the mail channel (support@xy.at) is part of the log, but the status is interrupted at azure:

So the login at the azure app seems to happen, but not properly handled by zammad?

MrGeneration · November 12, 2024, 12:03pm

I’m talking about a system proxy or generally a proxy server that’s configured in Zammad for it to use. Response code 0 indicates that there’s no communication at all.

yoursql719 · November 12, 2024, 12:10pm

Debian itself has no proxy configured. Zammad also:

yoursql719 · November 13, 2024, 11:47am

I fixed it by myown. Disabling ipv6 traffic & rebooting did the trick at /etc/sysctl.d/90-disable-ipv6.conf:

net.ipv6.conf.all.disable_ipv6 = 1

system · November 20, 2024, 11:48am

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.