Scheduler dies with `apply2files` #3563

MrGeneration · 2021-05-17T07:31:35Z

Infos:

Used Zammad version: 4.0 / stable and earlier (seen on 3.6 too)
Installation method (source, package, ..): any
Operating system: any
Database + version: should be any, seen on postgresql only as of now
Elasticsearch version: any
Browser + version: any
Tickets: #1085473, #1087862

Expected behavior:

Scheduler does not die on e.g. high load situations.

Actual behavior:

On specific situations ( I suspect load / I/O) the scheduler dies and does not recover.

scheduler_err.log

#<Thread:0x00007f66482fb498@/opt/zammad/vendor/bundle/ruby/2.6.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:471 run> terminated with exception (report_on_exception is true):
/opt/zammad/lib/sessions.rb:780:in `rescue in thread_client': STOP thread_client for client .47437312945960 after 10 tries (RuntimeError)
       from /opt/zammad/lib/sessions.rb:755:in `thread_client'
       from /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
       from /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'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache/file_store.rb:91:in `delete': No such file or directory @ apply2files - /opt/zammad/tmp/cache_file_store_production/4A2/770/Ticket%3A%3A25875 (Errno::ENOENT)
       from /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache/file_store.rb:91:in `delete_entry'
       from /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache/strategy/local_cache.rb:155:in `delete_entry'
       from /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache.rb:350:in `block in read'
       from /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache.rb:663:in `block in instrument'
       from /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:170:in `instrument'
       from /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache.rb:663:in `instrument'
       from /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.5/lib/active_support/cache.rb:345:in `read'
       from /opt/zammad/lib/cache.rb:47:in `get'
       from /opt/zammad/app/models/application_model/has_cache.rb:50:in `cache_get'
       from /opt/zammad/app/models/application_model/can_lookup.rb:28:in `lookup'
       from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:155:in `block (2 levels) in push'
       from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:152:in `each'
       from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:152:in `block in push'
       from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:139:in `each'
       from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:139:in `push'
       from /opt/zammad/lib/sessions/client.rb:67:in `each'
       from /opt/zammad/lib/sessions/client.rb:67:in `block in fetch'
       from /opt/zammad/lib/sessions/client.rb:23:in `loop'
       from /opt/zammad/lib/sessions/client.rb:23:in `fetch'
       from /opt/zammad/lib/sessions/client.rb:7:in `initialize'
       from /opt/zammad/lib/sessions.rb:756:in `new'
       from /opt/zammad/lib/sessions.rb:756:in `thread_client'
       from /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
       from /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'

corresponding line within production.log:

E, [2021-05-17T08:33:05.426642 #2850-70270425327420] ERROR -- : thread_client 9725258750 exited with error #<Errno::ENOENT: No such file or directory @ apply2files - /opt/zammad/tmp/cache_file_store_production/6B8/780/Ticket%3A%3Aaws%3A%3A578>
E, [2021-05-17T08:33:05.426703 #2850-70270425327420] ERROR -- : /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/cache/file_store.rb:91:in `delete'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/cache/file_store.rb:91:in `delete_entry'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/cache/strategy/local_cache.rb:155:in `delete_entry'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:350:in `block in read'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:663:in `block in instrument'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/notifications.rb:170:in `instrument'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:663:in `instrument'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:345:in `read'
/opt/zammad/lib/cache.rb:47:in `get'
/opt/zammad/app/models/application_model/can_associations.rb:122:in `attributes_with_association_ids'
/opt/zammad/app/models/ticket/assets.rb:33:in `assets'
/opt/zammad/lib/sessions/backend/base.rb:31:in `asset_push'
/opt/zammad/lib/sessions/backend/ticket_overview_list.rb:158:in `block (2 levels) in push'
/opt/zammad/lib/sessions/backend/ticket_overview_list.rb:152:in `each'
/opt/zammad/lib/sessions/backend/ticket_overview_list.rb:152:in `block in push'
/opt/zammad/lib/sessions/backend/ticket_overview_list.rb:139:in `each'
/opt/zammad/lib/sessions/backend/ticket_overview_list.rb:139:in `push'
/opt/zammad/lib/sessions/client.rb:67:in `each'
/opt/zammad/lib/sessions/client.rb:67:in `block in fetch'
/opt/zammad/lib/sessions/client.rb:23:in `loop'
/opt/zammad/lib/sessions/client.rb:23:in `fetch'
/opt/zammad/lib/sessions/client.rb:7:in `initialize'
/opt/zammad/lib/sessions.rb:756:in `new'
/opt/zammad/lib/sessions.rb:756:in `thread_client'
/opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
  /usr/local/rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

Steps to reproduce the behavior:

¯_(ツ)_/¯

Yes I'm sure this is a bug and no feature request or a general question.

The text was updated successfully, but these errors were encountered:

MrGeneration · 2021-05-20T15:00:16Z

Note sure if this applies to database connections as well, I currently am watching these kind of issues:

scheduler_err.log:

#<Thread:0x00007fbe54354e58@/usr/local/rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:471 run> terminated with exception (report_on_exception is true):
/opt/zammad/lib/sessions.rb:780:in `rescue in thread_client': STOP thread_client for client .88208440 after 10 tries (RuntimeError)
        from /opt/zammad/lib/sessions.rb:755:in `thread_client'
        from /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
/usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `async_exec': PG::UnableToSend: server closed the connection unexpectedly (ActiveRecord::StatementInvalid)
        This probably means the server terminated abnormally
        before or while processing the request.
: SELECT  1 AS one 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 AND ("permissions"."name") IN ($4, $5) LIMIT $6
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
        from /usr/local/rvm/rubies/ruby-2.6.6/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:478:in `select'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:70:in `select_all'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/query_cache.rb:106:in `select_all'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:77:in `select_one'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation/finder_methods.rb:322:in `block in exists?'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation.rb:584:in `skip_query_cache_if_necessary'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation/finder_methods.rb:322:in `exists?'
        from /opt/zammad/app/models/concerns/can_be_authorized.rb:29:in `permissions?'
        from /opt/zammad/app/models/activity_stream.rb:110:in `list'
        from /opt/zammad/app/models/user.rb:267:in `activity_stream'
        from /opt/zammad/lib/sessions/backend/activity_stream.rb:17:in `load'
        from /opt/zammad/lib/sessions/backend/activity_stream.rb:54:in `push'
        from /opt/zammad/lib/sessions/client.rb:67:in `each'
        from /opt/zammad/lib/sessions/client.rb:67:in `block in fetch'
        from /opt/zammad/lib/sessions/client.rb:23:in `loop'
        from /opt/zammad/lib/sessions/client.rb:23:in `fetch'
        from /opt/zammad/lib/sessions/client.rb:7:in `initialize'
        from /opt/zammad/lib/sessions.rb:756:in `new'
        from /opt/zammad/lib/sessions.rb:756:in `thread_client'
        from /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
/usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `async_exec': server closed the connection unexpectedly (PG::UnableToSend)
        This probably means the server terminated abnormally
        before or while processing the request.
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
        from /usr/local/rvm/rubies/ruby-2.6.6/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:478:in `select'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:70:in `select_all'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/query_cache.rb:106:in `select_all'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:77:in `select_one'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation/finder_methods.rb:322:in `block in exists?'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation.rb:584:in `skip_query_cache_if_necessary'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation/finder_methods.rb:322:in `exists?'
        from /opt/zammad/app/models/concerns/can_be_authorized.rb:29:in `permissions?'
        from /opt/zammad/app/models/activity_stream.rb:110:in `list'
        from /opt/zammad/app/models/user.rb:267:in `activity_stream'
        from /opt/zammad/lib/sessions/backend/activity_stream.rb:17:in `load'
        from /opt/zammad/lib/sessions/backend/activity_stream.rb:54:in `push'
        from /opt/zammad/lib/sessions/client.rb:67:in `each'
        from /opt/zammad/lib/sessions/client.rb:67:in `block in fetch'
        from /opt/zammad/lib/sessions/client.rb:23:in `loop'
        from /opt/zammad/lib/sessions/client.rb:23:in `fetch'
        from /opt/zammad/lib/sessions/client.rb:7:in `initialize'
        from /opt/zammad/lib/sessions.rb:756:in `new'
        from /opt/zammad/lib/sessions.rb:756:in `thread_client'
        from /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
        from /usr/local/rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
RuntimeError: STOP thread_client for client .88208440 after 10 tries
  /opt/zammad/lib/sessions.rb:780:in `rescue in thread_client'
  /opt/zammad/lib/sessions.rb:755:in `thread_client'
  /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
  /usr/local/rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

production.log:

E, [2021-05-20T13:21:51.390980 #15198-70227716646700] ERROR -- : thread_client 88208440 exited with error #<ActiveRecord::StatementInvalid: PG::UnableToSend: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
: SELECT  1 AS one 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 AND ("permissions"."name") IN ($4, $5) LIMIT $6>
E, [2021-05-20T13:21:51.391042 #15198-70227716646700] ERROR -- : /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `async_exec'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
  /usr/local/rvm/rubies/ruby-2.6.6/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:478:in `select'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:70:in `select_all'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/query_cache.rb:106:in `select_all'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/connection_adapters/abstract/database_statements.rb:77:in `select_one'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation/finder_methods.rb:322:in `block in exists?'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation.rb:584:in `skip_query_cache_if_necessary'
  /usr/local/rvm/gems/ruby-2.6.6/gems/activerecord-5.2.4.5/lib/active_record/relation/finder_methods.rb:322:in `exists?'
  /opt/zammad/app/models/concerns/can_be_authorized.rb:29:in `permissions?'
  /opt/zammad/app/models/activity_stream.rb:110:in `list'
  /opt/zammad/app/models/user.rb:267:in `activity_stream'
  /opt/zammad/lib/sessions/backend/activity_stream.rb:17:in `load'
  /opt/zammad/lib/sessions/backend/activity_stream.rb:54:in `push'
  /opt/zammad/lib/sessions/client.rb:67:in `each'
  /opt/zammad/lib/sessions/client.rb:67:in `block in fetch'
  /opt/zammad/lib/sessions/client.rb:23:in `loop'
  /opt/zammad/lib/sessions/client.rb:23:in `fetch'
  /opt/zammad/lib/sessions/client.rb:7:in `initialize'
  /opt/zammad/lib/sessions.rb:756:in `new'
  /opt/zammad/lib/sessions.rb:756:in `thread_client'
  /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
  /usr/local/rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
I, [2021-05-20T13:21:52.089138 #15198-16431520]  INFO -- : Scheduler running...
I, [2021-05-20T13:21:52.115744 #15198-100444560]  INFO -- : execute Ticket.process_auto_unassign (try_count 0)...
I, [2021-05-20T13:21:52.121658 #15198-100444560]  INFO -- : ended Ticket.process_auto_unassign took: 0.013620879 seconds.
I, [2021-05-20T13:21:52.484738 #15198-100098620]  INFO -- : 2021-05-20T13:21:52+0200: [Worker(host:host.tld pid:15198)] Error while reserving job: PG::UnableToSend: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
: UPDATE "delayed_jobs" SET locked_at = '2021-05-20 11:21:52.484005', locked_by = 'host:host.tld pid:15198' WHERE id IN (SELECT  "delayed_jobs"."id" FROM "delayed_jobs" WHERE ((run_at <= '2021-05-20 11:21:52.483519' AND (locked_at IS NULL OR locked_at < '2021-05-20 07:21:52.483538') OR locked_by = 'host:host.tld pid:15198') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1 FOR UPDATE) RETURNING *
E, [2021-05-20T13:21:52.931773 #15198-100637540] ERROR -- : execute Channel.stream (try_count 0) exited with error #<ActiveRecord::StatementInvalid: PG::UnableToSend: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
: SELECT "channels".* FROM "channels" WHERE (active = TRUE AND area LIKE '%::Account')> in: 2123171.196019423 seconds.

MrGeneration · 2021-06-08T08:32:06Z

I'm currently seeing about 5 instances (no matter if SaaS or package installation) per week that are affected by this issue.

MrGeneration · 2021-07-07T14:26:10Z

By now it's 10+ instances.

martini · 2021-10-27T11:20:52Z

@MrGeneration Is this issue still present? Or has it decreased/disappeared since Zammad 5.0?

MrGeneration · 2021-11-03T16:31:39Z

Yes, just appeared on a current stable 5.0.2!

MrGeneration · 2021-11-19T16:38:46Z

Fresh sample:

#<Thread:0x000000000747cc58 /opt/zammad/lib/sessions.rb:533 run> terminated with exception (report_on_exception is true):
/opt/zammad/lib/sessions.rb:603:in `rescue in thread_client': STOP thread_client for client .642600 after 10 tries (RuntimeError)
        from /opt/zammad/lib/sessions.rb:578:in `thread_client'
        from /opt/zammad/lib/sessions.rb:534:in `block (3 levels) in jobs'
/usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/cache/file_store.rb:95:in `delete': No such file or directory @ apply2files - /opt/zammad/tmp/cache_file_store_production/468/D90/Ticket%3A%3A5822 (Errno::ENOENT)
        from /usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/cache/file_store.rb:95:in `delete_entry'
        from /usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/cache/strategy/local_cache.rb:155:in `delete_entry'
        from /usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/cache.rb:360:in `block in read'
        from /usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/cache.rb:686:in `block in instrument'
        from /usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/notifications.rb:182:in `instrument'
        from /usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/cache.rb:686:in `instrument'
        from /usr/local/rvm/gems/ruby-2.7.4/gems/activesupport-6.0.4.1/lib/active_support/cache.rb:355:in `read'
        from /opt/zammad/app/models/application_model/has_cache.rb:52:in `cache_get'
        from /opt/zammad/app/models/application_model/can_lookup.rb:29:in `lookup'
        from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:157:in `block (2 levels) in push'
        from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:154:in `each'
        from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:154:in `block in push'
        from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:141:in `each'
        from /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:141:in `push'
        from /opt/zammad/lib/sessions/client.rb:69:in `each'
        from /opt/zammad/lib/sessions/client.rb:69:in `block in fetch'
        from /opt/zammad/lib/sessions/client.rb:25:in `loop'
        from /opt/zammad/lib/sessions/client.rb:25:in `fetch'
        from /opt/zammad/lib/sessions/client.rb:9:in `initialize'
        from /opt/zammad/lib/sessions.rb:579:in `new'
        from /opt/zammad/lib/sessions.rb:579:in `thread_client'
        from /opt/zammad/lib/sessions.rb:534:in `block (3 levels) in jobs'
bundler: failed to load command: script/scheduler.rb (script/scheduler.rb)
RuntimeError: STOP thread_client for client .642600 after 10 tries
  /opt/zammad/lib/sessions.rb:603:in `rescue in thread_client'
  /opt/zammad/lib/sessions.rb:578:in `thread_client'
  /opt/zammad/lib/sessions.rb:534:in `block (3 levels) in jobs'

du -h --max-depth=1 tmp/
158M    tmp/cache_file_store_production
312K    tmp/websocket_production
82M     tmp/cache
16K     tmp/pids
0       tmp/websocket

MrGeneration · 2022-01-12T16:12:34Z

Found this in production.log today on a 4.0:

E, [2022-01-12T17:10:18.460731 #27246-69867880158340] ERROR -- : thread_client 47189514724960 exited with error #<Errno::ENOENT: No such file or directory @ apply2files - /opt/zammad/tmp/cache_file_store_production/509/D00/Location%3A%3A292>
E, [2022-01-12T17:10:18.464578 #27246-69867880158340] ERROR -- : /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache/file_store.rb:91:in `delete'
  /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache/file_store.rb:91:in `delete_entry'
  /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache/strategy/local_cache.rb:155:in `delete_entry'
  /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:350:in `block in read'
  /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:663:in `block in instrument'
  /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/notifications.rb:170:in `instrument'
  /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:663:in `instrument'
  /opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.6/lib/active_support/cache.rb:345:in `read'
  /opt/zammad/lib/cache.rb:47:in `get'
  /opt/zammad/app/models/application_model/has_cache.rb:50:in `cache_get'
  /opt/zammad/app/models/application_model/can_lookup.rb:28:in `lookup'
  /opt/zammad/app/models/organization/assets.rb:96:in `block in assets'
  /opt/zammad/app/models/organization/assets.rb:93:in `each'
  /opt/zammad/app/models/organization/assets.rb:93:in `assets'
  /opt/zammad/app/models/user/assets.rb:98:in `assets'
  /opt/zammad/app/models/ticket/assets.rb:45:in `block in assets'
  /opt/zammad/app/models/ticket/assets.rb:38:in `each'
  /opt/zammad/app/models/ticket/assets.rb:38:in `assets'
  /opt/zammad/lib/sessions/backend/base.rb:31:in `asset_push'
  /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:158:in `block (2 levels) in push'
  /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:152:in `each'
  /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:152:in `block in push'
  /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:139:in `each'
  /opt/zammad/lib/sessions/backend/ticket_overview_list.rb:139:in `push'
  /opt/zammad/lib/sessions/client.rb:67:in `each'
  /opt/zammad/lib/sessions/client.rb:67:in `block in fetch'
  /opt/zammad/lib/sessions/client.rb:23:in `loop'
  /opt/zammad/lib/sessions/client.rb:23:in `fetch'
  /opt/zammad/lib/sessions/client.rb:7:in `initialize'
  /opt/zammad/lib/sessions.rb:756:in `new'
  /opt/zammad/lib/sessions.rb:756:in `thread_client'
  /opt/zammad/lib/sessions.rb:711:in `block (3 levels) in jobs'
  /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

Might help.

rolfschmidt · 2022-04-05T08:41:56Z

The issue situation here might get better with the cache changes we did this week. We should verify this on 5.2 release.

0b6010c

mantas · 2022-10-12T06:32:29Z

@MrGeneration is this still a thing with recent cache changes and Redis?

MrGeneration · 2022-10-12T14:21:41Z

@MrGeneration is this still a thing with recent cache changes and Redis?

What cache changes? Could you please expect me not to know every little code change in every detail?
If you're talking about the clean up job: It won't improve the situation if it's after a long day, right?

Redis

Not every system has to use redis so no, ignore Redis in this scenario.

fliebe92 · 2023-06-13T10:16:36Z

@mantas > Is this issue handled by you? Just asking, because you're assigned...

mantas · 2023-06-13T10:48:47Z

@fliebe92 I'm not actively working on this one. Same situation as with #3601 .

MrGeneration added bug verified prioritised by payment labels May 17, 2021

MrGeneration added this to To do in OLD Workflow Jun 8, 2021

thorsteneckel assigned mantas Jun 8, 2021

thorsteneckel added this to the 4.1.1 milestone Jun 8, 2021

MrGeneration mentioned this issue Jul 29, 2021

Zammad UI should silently discard Cache / apply2file errors #3685

Closed

zammad locked and limited conversation to collaborators Jul 29, 2021

thorsteneckel modified the milestones: 4.1.1, 5.0.1 Sep 23, 2021

zammad deleted a comment from mantas Oct 27, 2021

mgruner modified the milestones: 5.0.2, 5.0.3 Oct 29, 2021

rolfschmidt removed this from To do in OLD Workflow Dec 7, 2021

mgruner modified the milestones: 5.0.3, 5.0.4 Dec 7, 2021

mgruner modified the milestones: 5.0.4, 5.1.1 Mar 14, 2022

mgruner modified the milestones: 5.1.1, 5.1.2 Apr 20, 2022

mgruner removed this from the 5.1.2 milestone Jun 21, 2022

mgruner added this to the 5.2.1 milestone Jun 21, 2022

mgruner modified the milestones: 5.2.1, 5.2.2 Jul 5, 2022

mgruner modified the milestones: 5.2.2, 5.2.3 Sep 13, 2022

mgruner modified the milestones: 5.2.3, 5.2.4 Sep 30, 2022

fliebe92 modified the milestones: 5.2.4, 5.3.1 Nov 22, 2022

mgruner modified the milestones: 5.3.1, 5.3.2 Dec 21, 2022

fliebe92 modified the milestones: 5.3.2, 5.4.1 Mar 14, 2023

mgruner modified the milestones: 5.4.1, 5.4.2 Apr 12, 2023

dominikklein removed this from the 5.4.2 milestone Jun 1, 2023

fliebe92 added the background worker label Jun 13, 2023

fliebe92 unassigned mantas Jun 13, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Scheduler dies with `apply2files` #3563

Scheduler dies with `apply2files` #3563

MrGeneration commented May 17, 2021 •

edited

MrGeneration commented May 20, 2021

MrGeneration commented Jun 8, 2021

MrGeneration commented Jul 7, 2021

martini commented Oct 27, 2021

MrGeneration commented Nov 3, 2021

MrGeneration commented Nov 19, 2021 •

edited

MrGeneration commented Jan 12, 2022

rolfschmidt commented Apr 5, 2022

mantas commented Oct 12, 2022

MrGeneration commented Oct 12, 2022

fliebe92 commented Jun 13, 2023

mantas commented Jun 13, 2023

Scheduler dies with apply2files #3563

Scheduler dies with apply2files #3563

Comments

MrGeneration commented May 17, 2021 • edited

Infos:

Expected behavior:

Actual behavior:

Steps to reproduce the behavior:

MrGeneration commented May 20, 2021

MrGeneration commented Jun 8, 2021

MrGeneration commented Jul 7, 2021

martini commented Oct 27, 2021

MrGeneration commented Nov 3, 2021

MrGeneration commented Nov 19, 2021 • edited

MrGeneration commented Jan 12, 2022

rolfschmidt commented Apr 5, 2022

mantas commented Oct 12, 2022

MrGeneration commented Oct 12, 2022

fliebe92 commented Jun 13, 2023

mantas commented Jun 13, 2023

Scheduler dies with `apply2files` #3563

Scheduler dies with `apply2files` #3563

MrGeneration commented May 17, 2021 •

edited

MrGeneration commented Nov 19, 2021 •

edited