Scheduler not running/Mails not processed

Since a few day the scheduler is not working properly. First i thought it was just because of some unprocessable mails so i fired up
zammad run rails r 'Channel::EmailParser.process_unprocessable_mails' and thought everything was fine.
But apparently something else is blocking Zammad to work properly.

  • Used Zammad version: [zammad 4.0.0]
  • Used Zammad installation type:package
  • Operating system: Ubuntu 18.04.

Actual behavior:

Scheduler not running under monitoring
Emails doesn’t get processed

I, [2021-04-29T06:05:36.869292 #16576-46973096098160]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2021-04-29T06:05:36.882490 #16576-46973096098160]  INFO -- : fetching imap (outlook.office365.com/zammad@hit-suetterlin.de port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=XOAUTH2)
I, [2021-04-29T06:05:37.715871 #16576-46973096098160]  INFO -- :  - no message
I, [2021-04-29T06:05:37.715948 #16576-46973096098160]  INFO -- : done
I, [2021-04-29T06:05:37.730165 #16576-46973096098160]  INFO -- : ended Channel.fetch took: 0.865971363 seconds.
I, [2021-04-29T06:05:38.153279 #16576-46973024647600]  INFO -- : Scheduler running...
I, [2021-04-29T06:05:38.156385 #16576-46973024647600]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2021-04-29T06:05:38.160745 #16576-46973095459480]  INFO -- : execute Ticket.process_auto_unassign (try_count 0)...
I, [2021-04-29T06:05:38.162406 #16576-46973095459480]  INFO -- : ended Ticket.process_auto_unassign took: 0.005677045 seconds.
I, [2021-04-29T06:05:47.832093 #621-69840644155540]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:47 +0200
I, [2021-04-29T06:05:47.838194 #621-69840644155540]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:47.838284 #621-69840644155540]  INFO -- :   Parameters: {"data"=>{"event"=>"login"}}
I, [2021-04-29T06:05:47.843151 #621-69840644155540]  INFO -- : client(2685562622) new client connection
I, [2021-04-29T06:05:47.845466 #621-69840644155540]  INFO -- : Completed 200 OK in 7ms (Views: 0.2ms | ActiveRecord: 0.3ms)
I, [2021-04-29T06:05:47.876290 #621-69840644155540]  INFO -- : Started POST "/api/v1/message_receive" for 37.201.138.73 at 2021-04-29 06:05:47 +0200
I, [2021-04-29T06:05:47.880606 #621-69840644155540]  INFO -- : Processing by LongPollingController#message_receive as JSON
I, [2021-04-29T06:05:47.880687 #621-69840644155540]  INFO -- :   Parameters: {"client_id"=>"2685562622"}
I, [2021-04-29T06:05:47.909333 #621-69840638571120]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:47 +0200
I, [2021-04-29T06:05:47.915943 #621-69840638571120]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:47.916027 #621-69840638571120]  INFO -- :   Parameters: {"client_id"=>"2685562622", "data"=>{"event"=>"login", "fingerprint"=>"-1489638817"}}
I, [2021-04-29T06:05:47.921956 #621-69840638571120]  INFO -- : Completed 200 OK in 6ms (Views: 0.1ms | ActiveRecord: 0.2ms)
I, [2021-04-29T06:05:47.954110 #621-69840638571120]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:47 +0200
I, [2021-04-29T06:05:47.958457 #621-69840638571120]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:47.958529 #621-69840638571120]  INFO -- :   Parameters: {"client_id"=>"2685562622", "data"=>{"event"=>"login", "session_id"=>"ca2aa7d05e4ac804f6401a3ac349fa54", "fingerprint"=>"-1489638817"}}
I, [2021-04-29T06:05:47.964642 #621-69840638571120]  INFO -- : Completed 200 OK in 6ms (Views: 0.2ms | ActiveRecord: 0.3ms)
I, [2021-04-29T06:05:47.997397 #621-69840638571120]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:47 +0200
I, [2021-04-29T06:05:48.001733 #621-69840638571120]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:48.001796 #621-69840638571120]  INFO -- :   Parameters: {"client_id"=>"2685562622", "data"=>{"event"=>"chat_status_agent"}}
I, [2021-04-29T06:05:48.007098 #621-69840638571120]  INFO -- : Completed 200 OK in 5ms (Views: 0.1ms | ActiveRecord: 0.2ms)
I, [2021-04-29T06:05:48.040849 #621-69840638571120]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:48 +0200
I, [2021-04-29T06:05:48.045156 #621-69840638571120]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:48.045240 #621-69840638571120]  INFO -- :   Parameters: {"client_id"=>"2685562622", "data"=>{"event"=>"ticket_overview_select", "data"=>{"view"=>"all_open"}}}
I, [2021-04-29T06:05:48.052311 #621-69840638571120]  INFO -- : Completed 200 OK in 7ms (Views: 0.2ms | ActiveRecord: 0.3ms)
I, [2021-04-29T06:05:48.084983 #621-69840638571120]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:48 +0200
I, [2021-04-29T06:05:48.089263 #621-69840638571120]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:48.089335 #621-69840638571120]  INFO -- :   Parameters: {"client_id"=>"2685562622", "data"=>{"event"=>"ticket_overview_select", "data"=>{"view"=>"all_open"}}}
I, [2021-04-29T06:05:48.095086 #621-69840638571120]  INFO -- : Completed 200 OK in 6ms (Views: 0.2ms | ActiveRecord: 0.2ms)
I, [2021-04-29T06:05:48.122368 #621-69840638571120]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:48 +0200
I, [2021-04-29T06:05:48.126681 #621-69840638571120]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:48.126752 #621-69840638571120]  INFO -- :   Parameters: {"client_id"=>"2685562622", "data"=>{"event"=>"ticket_overview_select", "data"=>{"view"=>"all_open"}}}
I, [2021-04-29T06:05:48.132497 #621-69840638571120]  INFO -- : Completed 200 OK in 6ms (Views: 0.2ms | ActiveRecord: 0.3ms)
I, [2021-04-29T06:05:48.166390 #16576-46973024647600]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2021-04-29T06:05:48.166505 #16576-46973024647600]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2021-04-29T06:05:48.166538 #16576-46973024647600]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2021-04-29T06:05:48.166569 #16576-46973024647600]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2021-04-29T06:05:48.166754 #16576-46973024647600]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
E, [2021-04-29T06:05:48.885339 #615-47079581710740] ERROR -- : #<JSON::ParserError: 783: unexpected token at ''>
E, [2021-04-29T06:05:48.885825 #615-47079581710740] ERROR -- : error in reading/parsing session file '/opt/zammad/tmp/websocket_production/2685562622/session', remove session.
E, [2021-04-29T06:05:48.885805 #621-69840644155540] ERROR -- : Invalid client_id in receive loop! (Exceptions::UnprocessableEntity)
/opt/zammad/app/controllers/long_polling_controller.rb:93:in `rescue in message_receive'
/opt/zammad/app/controllers/long_polling_controller.rb:62:in `message_receive'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:194:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:18:in `block (4 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:180:in `subscribed'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:17:in `block (3 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:180:in `subscribed'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:16:in `block (2 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/app/controllers/application_controller/handles_transitions.rb:14:in `handle_transaction'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.5/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:134:in `process'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionview-5.2.4.5/lib/action_view/rendering.rb:32:in `process'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:191:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:252:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `each'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:840:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:420:in `call_app!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-saml-1.10.1/lib/omniauth/strategies/saml.rb:89:in `other_phase'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:190:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/builder.rb:45:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:98:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:38:in `call_app'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `block in call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:28:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/engine.rb:524:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
I, [2021-04-29T06:05:48.886582 #621-69840644155540]  INFO -- : Completed 422 Unprocessable Entity in 1006ms (Views: 0.2ms | ActiveRecord: 0.2ms)
I, [2021-04-29T06:05:48.921563 #621-46975308830680]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:48 +0200
I, [2021-04-29T06:05:48.926434 #621-46975308830680]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:48.926508 #621-46975308830680]  INFO -- :   Parameters: {"data"=>{"event"=>"login"}}
I, [2021-04-29T06:05:48.930742 #621-46975308830680]  INFO -- : client(8351907350) new client connection
I, [2021-04-29T06:05:48.932580 #621-46975308830680]  INFO -- : Completed 200 OK in 6ms (Views: 0.2ms | ActiveRecord: 0.3ms)
I, [2021-04-29T06:05:48.963954 #621-46975308830680]  INFO -- : Started POST "/api/v1/message_receive" for 37.201.138.73 at 2021-04-29 06:05:48 +0200
I, [2021-04-29T06:05:48.968192 #621-46975308830680]  INFO -- : Processing by LongPollingController#message_receive as JSON
I, [2021-04-29T06:05:48.968270 #621-46975308830680]  INFO -- :   Parameters: {"client_id"=>"8351907350"}
I, [2021-04-29T06:05:49.975414 #621-46975308830680]  INFO -- : Completed 200 OK in 1007ms (Views: 0.2ms | ActiveRecord: 0.4ms)
I, [2021-04-29T06:05:50.012076 #621-46975308747400]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:50 +0200
I, [2021-04-29T06:05:50.018042 #621-46975308747400]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:50.018145 #621-46975308747400]  INFO -- :   Parameters: {"client_id"=>"8351907350", "data"=>{"event"=>"spool"}}
I, [2021-04-29T06:05:50.021928 #621-46975325617560]  INFO -- : Started POST "/api/v1/message_receive" for 37.201.138.73 at 2021-04-29 06:05:50 +0200
I, [2021-04-29T06:05:50.029321 #621-46975325617560]  INFO -- : Processing by LongPollingController#message_receive as JSON
I, [2021-04-29T06:05:50.029604 #621-46975325617560]  INFO -- :   Parameters: {"client_id"=>"8351907350"}
I, [2021-04-29T06:05:50.127318 #621-46975308747400]  INFO -- : Completed 200 OK in 109ms (Views: 0.2ms | ActiveRecord: 3.0ms)
I, [2021-04-29T06:05:50.161458 #621-69840638571120]  INFO -- : Started POST "/api/v1/message_send" for 37.201.138.73 at 2021-04-29 06:05:50 +0200
I, [2021-04-29T06:05:50.167380 #621-69840638571120]  INFO -- : Processing by LongPollingController#message_send as JSON
I, [2021-04-29T06:05:50.167480 #621-69840638571120]  INFO -- :   Parameters: {"client_id"=>"8351907350", "data"=>{"event"=>"chat_status_agent"}}
I, [2021-04-29T06:05:50.175333 #621-69840638571120]  INFO -- : Completed 200 OK in 8ms (Views: 0.2ms | ActiveRecord: 0.4ms)
I, [2021-04-29T06:05:50.248232 #16576-46973095222680]  INFO -- : execute Import::OTRS.diff_worker (try_count 0)...
I, [2021-04-29T06:05:50.248728 #16576-46973095222680]  INFO -- : ended Import::OTRS.diff_worker took: 0.010341076 seconds.
E, [2021-04-29T06:05:51.035805 #615-47079581710740] ERROR -- : #<JSON::ParserError: 783: unexpected token at ''>
E, [2021-04-29T06:05:51.036348 #621-46975325617560] ERROR -- : Invalid client_id in receive loop! (Exceptions::UnprocessableEntity)
/opt/zammad/app/controllers/long_polling_controller.rb:93:in `rescue in message_receive'
/opt/zammad/app/controllers/long_polling_controller.rb:62:in `message_receive'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:194:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:18:in `block (4 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:180:in `subscribed'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:17:in `block (3 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:180:in `subscribed'
/opt/zammad/app/controllers/application_controller/has_secure_content_security_policy_for_downloads.rb:16:in `block (2 levels) in <module:HasSecureContentSecurityPolicyForDownloads>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/app/controllers/application_controller/handles_transitions.rb:14:in `handle_transaction'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.5/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:134:in `process'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionview-5.2.4.5/lib/action_view/rendering.rb:32:in `process'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:191:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:252:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `each'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `serve'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:840:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:420:in `call_app!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-saml-1.10.1/lib/omniauth/strategies/saml.rb:89:in `other_phase'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:190:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:192:in `call!'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/strategy.rb:169:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/omniauth-1.9.1/lib/omniauth/builder.rb:45:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:98:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:38:in `call_app'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `block in call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:28:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/railties-5.2.4.5/lib/rails/engine.rb:524:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

Any idea what might be wrong or caused the scheduler to stop?

Sorry I can’t follow.
The snippet of your log file you shared contain a fetching process (receiving mail) and indicate the scheduler seems to be running at least somehow.

What exactly is your issue, sending out mails?
Please try to be precise for scheduler based issues, otherwise you’ll send me into the wrong rabbit hole.

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