production.log does not report anything!
EntraID reports a successful signin
Hi @baz. Error code 500 without any entry in the production.log file? This never happened to me. There is something, pretty sure.
production log empty. But I find something in STDOUT from Docker:
, [2025-02-27T00:16:53.105675#1-184640] INFO – : Started GET “/api/v1/external_credentials/microsoft365/callback?code=[FILTERED]&session_state=00228409-c01e-c52a-d72a-55115f24d8rr” for x.x.x.x at 2025-02-27 00:16:53 +0100
I, [2025-02-27T00:16:53.111487#1-184640] INFO – : Processing by ExternalCredentialsController#callback as HTML
I, [2025-02-27T00:16:53.111667#1-184640] INFO – : Parameters: {“code”=>“[FILTERED]”, “session_state”=>“00228409-c01e-c52a-d72a-55115f24d8rr”, “provider”=>“microsoft365”}
E, [2025-02-27T00:16:57.168999#1-184640] ERROR – : Request failed! (code: 0)
E, [2025-02-27T00:16:57.169400#1-184640] 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/handles_transitions.rb:16:in `handle_transaction’
I, [2025-02-27T00:16:57.173447#1-184640] INFO – : Completed 500 Internal Server Error in 4062ms (Views: 0.9ms | ActiveRecord: 3.1ms | Allocations: 7595)
I tried this:
the new instance is working well, but the MS365 channel. OAUTH2 error in existing IMAP connection, and error 500 if I try to reconnect it to 365.
scheduler is reporting:
lib/background_services/service/process_scheduled_jobs/manager.rb:72:in `block in start'
E, [2025-02-28T19:09:56.242499#1-184180] ERROR -- : Can't use Channel::Driver::Imap: #<RuntimeError: Failed to refresh XOAUTH2 access_token of provider 'microsoft365': Request failed! (code: 0)>
E, [2025-02-28T19:09:56.242619#1-184180] 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'
reauthenticating reports error 500 and rails logs
I, [2025-02-28T19:14:45.588903#1-185500] INFO – : Processing by ExternalCredentialsController#callback as HTML
I, [2025-02-28T19:14:45.589126#1-185500] INFO – : Parameters: {“code”=>“[FILTERED]”, “session_state”=>“0022d229-b2a1-9881-dffe-5a571adde942”, “provider”=>“microsoft365”}
E, [2025-02-28T19:14:50.326104#1-185500] ERROR – : Request failed! (code: 0)
E, [2025-02-28T19:14:50.386124#1-185500] 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/handles_transitions.rb:16:in `handle_transaction’
I, [2025-02-28T19:14:50.651594#1-185500] INFO – : Completed 500 Internal Server Error in 5058ms (Views: 178.7ms | ActiveRecord: 41.7ms | Allocations: 7604)
Hi,
I loaded some debug code in microsoft365.rb.
The response from " response = UserAgent.post(uri.to_s, params)
" is “Response: #<UserAgent::Result:0x00007f2b4ebe15b0 @success=false, @body=nil, @data=nil, @code=0, @content_type=nil, @error=”#<Net::OpenTimeout: Failed to open TCP connection to login.microsoftonline.com:443 (execution expired)>“, @header=nil>”
a curl -v https://login.microsoftonline.com reports all is fine and output ends with …
So?
You’re mixing Microsoft 365 Channels and the Microsoft 365 Authentication.
The callback URLs are fundamentally different. You may want to re-visit the correct documentation page.
I solved changed UserAgent class to have longer timeout (and NOTHING ELSE):
begin
total_timeout = options[:total_timeout] || 60
open_timeout = options[:open_timeout] || 30 # Timeout di apertura socket
read_timeout = options[:read_timeout] || 30 # Timeout di lettura
handled_open_timeout(options[:open_socket_tries]) do
Timeout.timeout(total_timeout) do
http.open_timeout = open_timeout
http.read_timeout = read_timeout
response = http.request(request)
return process(request, response, uri, count, params, options)
end
end
rescue => e
Rails.logger.error "HTTP POST Request failed! URL: #{url}, Error: #{e.inspect}"
log(url, request, nil, options)
Result.new(
error: e.inspect,
success: false,
code: 0,
)
end
This points to be something in your environment then. No Zammad issue.
at least a minimum of debug support… log is totally helpless
And I have simply a docker installation that may run out of the box (or better, simply run IN the box: I’m using docker to avoid environment problems).
There isn’t any way to find the problem.
Oh you actually answered the problem part yourself already.
You pointed out that increasing timeout values “solved” your problem.
So you have latency issues of some kind - that’s however not Zammad stack specific, but environment specific and thus we cannot help you.
For this reason, the log will also not be useful to you, as the issue is in the transit between Zammad and Microsoft.
ok. This not explain why a container running old version on the same server is working well, but ok. I understand this make sense from you point of view. BTW I’m running Zammad on a first class Cloud provider, with high performance and low latency connection, but ok.
However also refresh token does not work. Every 1 hour I’m out of IMAP an need to reauthenticate and cannot find any way to debug.
This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.