Infos:
- Used Zammad version: stable/3.5.0
- Used Zammad installation source: source
- Operating system: Debian buster
- Browser + version: -
Expected behavior:
- logs not flodded with errors
Actual behavior:
Steps to reproduce the behavior:
I, [2020-09-23T12:07:55.263111 #68660-46964187847140] INFO -- : 2020-09-23T12:07:55+0200: [Worker(host:hades.faked.org pid:68660)] Job SearchIndexJob [18c2d981-1e24-4ec8-a4ff-97ccb07a88b2] from DelayedJob(default) with arguments: ["StatsStore", 1] (id=2424036) (queue=default) RUNNING
I, [2020-09-23T12:07:55.280118 #68660-46964187847140] INFO -- : Performing SearchIndexJob (Job ID: 18c2d981-1e24-4ec8-a4ff-97ccb07a88b2) from DelayedJob(default) with arguments: "StatsStore", 1
I, [2020-09-23T12:07:55.293246 #68660-46964187847140] INFO -- : # curl -X post "http://127.0.0.1:9200/zammad_production_stats_store/_doc/1?pipeline=zammad97903069524"
I, [2020-09-23T12:07:55.297340 #68660-46964187847140] INFO -- : # 400
E, [2020-09-23T12:07:55.298999 #68660-46964187847140] ERROR -- : Unable to process post request to elasticsearch URL 'http://127.0.0.1:9200/zammad_production_stats_store/_doc/1?pipeline=zammad97903069524'. Check the response and payload for detailed information:
Response:
#<UserAgent::Result:0x00007f74fcbc3ba8 @success=false, @body="{\"error\":{\"root_cause\":[{\"type\":\"illegal_argument_exception\",\"reason\":\"field [article] not present as part of path [article]\"}],\"type\":\"illegal_argument_exception\",\"reason\":\"field [article] not present as part of path [article]\"},\"status\":400}", @data=nil, @code="400", @content_type=nil, @error="Client Error: #<Net::HTTPBadRequest 400 Bad Request readbody=true>!">
Payload:
{"id":1,"stats_store_object_id":1,"o_id":3,"key":"dashboard","related_o_id":null,"related_stats_store_object_id":null,"data":{"StatsTicketWaitingTime":{"handling_time":0,"average_per_agent":0,"state":"supergood","percent":0.0},"StatsTicketEscalation":{"used_for_average":0,"average_per_agent":0.0,"state":"supergood","own":0,"total":0},"StatsTicketChannelDistribution":{"channels":{"email":{"icon":"email","inbound":15,"outbound":5,"inbound_in_percent":100,"outbound_in_percent":100},"phone":{"icon":"phone","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0},"web":{"icon":"web","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0},"twitter":{"icon":"twitter","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0},"facebook":{"icon":"facebook","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0}}},"StatsTicketLoadMeasure":{"used_for_average":9.6,"average_per_agent":33.9,"percent":9.6,"state":"supergood","own":34,"total":353,"average_per_agent_in_percent":100.0},"StatsTicketInProcess":{"used_for_average":2.9,"average_per_agent":2.9,"state":"supergood","in_process":1,"percent":2.9,"total":34},"StatsTicketReopen":{"used_for_average":0.0,"percent":0.0,"average_per_agent":0.0,"state":"supergood","count":0,"total":1}},"created_by_id":1,"created_at":"2019-02-01T13:18:52.000Z","updated_at":"2020-09-23T06:14:26.748Z","stats_store_object":"User","stats_store_object_ref":{"id":3,"organization_id":null,"login":"jan@faked.org","firstname":"Jan","lastname":"Grewe","email":"jan@faked.org","web":"","phone":"","fax":"","mobile":"","department":"","street":"","zip":"","city":"","country":"","address":"","vip":false,"verified":false,"active":true,"note":"","last_login":"2020-05-14T14:10:09.772Z","out_of_office":false,"out_of_office_start_at":null,"out_of_office_end_at":null,"out_of_office_replacement_id":null,"preferences":{"notification_config":{"matrix":{"create":{"criteria":{"owned_by_me":true,"owned_by_nobody":true,"no":false},"channel":{"email":true,"online":true}},"update":{"criteria":{"owned_by_me":true,"owned_by_nobody":true,"no":false},"channel":{"email":true,"online":true}},"reminder_reached":{"criteria":{"owned_by_me":true,"owned_by_nobody":false,"no":false},"channel":{"email":true,"online":true}},"escalation":{"criteria":{"owned_by_me":true,"owned_by_nobody":false,"no":false},"channel":{"email":true,"online":true}}}},"locale":"en-us","intro":true,"tickets_open":0,"tickets_closed":1},"updated_by_id":1,"created_by_id":1,"created_at":"2019-02-01T13:08:50.000Z","updated_at":"2020-05-14T14:10:09.781Z","permissions":["admin","admin.user","admin.group","admin.role","admin.organization","admin.overview","admin.text_module","admin.time_accounting","admin.macro","admin.tag","admin.calendar","admin.sla","admin.scheduler","admin.report_profile","admin.channel_web","admin.channel_formular","admin.channel_email","admin.channel_twitter","admin.channel_facebook","admin.channel_telegram","admin.channel_sms","admin.channel_chat","admin.branding","admin.setting_system","admin.security","admin.ticket","admin.package","admin.integration","admin.api","admin.object","admin.translation","admin.monitoring","admin.maintenance","admin.session","user_preferences","user_preferences.password","user_preferences.notifications","user_preferences.access_token","user_preferences.language","user_preferences.linked_accounts","user_preferences.device","user_preferences.avatar","user_preferences.calendar","user_preferences.out_of_office","report","ticket.agent","chat.agent","cti.agent","admin.knowledge_base","knowledge_base.reader","knowledge_base.editor","admin.trigger"],"role_ids":[1,2]}}
Payload size: 0M
E, [2020-09-23T12:07:55.300167 #68660-46964187847140] ERROR -- : Error performing SearchIndexJob (Job ID: 18c2d981-1e24-4ec8-a4ff-97ccb07a88b2) from DelayedJob(default) in 19.91ms: RuntimeError (Unable to process post request to elasticsearch URL 'http://127.0.0.1:9200/zammad_production_stats_store/_doc/1?pipeline=zammad97903069524'. Check the response and payload for detailed information:
Response:
#<UserAgent::Result:0x00007f74fcbc3ba8 @success=false, @body="{\"error\":{\"root_cause\":[{\"type\":\"illegal_argument_exception\",\"reason\":\"field [article] not present as part of path [article]\"}],\"type\":\"illegal_argument_exception\",\"reason\":\"field [article] not present as part of path [article]\"},\"status\":400}", @data=nil, @code="400", @content_type=nil, @error="Client Error: #<Net::HTTPBadRequest 400 Bad Request readbody=true>!">
Payload:
{"id":1,"stats_store_object_id":1,"o_id":3,"key":"dashboard","related_o_id":null,"related_stats_store_object_id":null,"data":{"StatsTicketWaitingTime":{"handling_time":0,"average_per_agent":0,"state":"supergood","percent":0.0},"StatsTicketEscalation":{"used_for_average":0,"average_per_agent":0.0,"state":"supergood","own":0,"total":0},"StatsTicketChannelDistribution":{"channels":{"email":{"icon":"email","inbound":15,"outbound":5,"inbound_in_percent":100,"outbound_in_percent":100},"phone":{"icon":"phone","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0},"web":{"icon":"web","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0},"twitter":{"icon":"twitter","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0},"facebook":{"icon":"facebook","inbound":0,"outbound":0,"inbound_in_percent":0,"outbound_in_percent":0}}},"StatsTicketLoadMeasure":{"used_for_average":9.6,"average_per_agent":33.9,"percent":9.6,"state":"supergood","own":34,"total":353,"average_per_agent_in_percent":100.0},"StatsTicketInProcess":{"used_for_average":2.9,"average_per_agent":2.9,"state":"supergood","in_process":1,"percent":2.9,"total":34},"StatsTicketReopen":{"used_for_average":0.0,"percent":0.0,"average_per_agent":0.0,"state":"supergood","count":0,"total":1}},"created_by_id":1,"created_at":"2019-02-01T13:18:52.000Z","updated_at":"2020-09-23T06:14:26.748Z","stats_store_object":"User","stats_store_object_ref":{"id":3,"organization_id":null,"login":"jan@faked.org","firstname":"Jan","lastname":"Grewe","email":"jan@faked.org","web":"","phone":"","fax":"","mobile":"","department":"","street":"","zip":"","city":"","country":"","address":"","vip":false,"verified":false,"active":true,"note":"","last_login":"2020-05-14T14:10:09.772Z","out_of_office":false,"out_of_office_start_at":null,"out_of_office_end_at":null,"out_of_office_replacement_id":null,"preferences":{"notification_config":{"matrix":{"create":{"criteria":{"owned_by_me":true,"owned_by_nobody":true,"no":false},"channel":{"email":true,"online":true}},"update":{"criteria":{"owned_by_me":true,"owned_by_nobody":true,"no":false},"channel":{"email":true,"online":true}},"reminder_reached":{"criteria":{"owned_by_me":true,"owned_by_nobody":false,"no":false},"channel":{"email":true,"online":true}},"escalation":{"criteria":{"owned_by_me":true,"owned_by_nobody":false,"no":false},"channel":{"email":true,"online":true}}}},"locale":"en-us","intro":true,"tickets_open":0,"tickets_closed":1},"updated_by_id":1,"created_by_id":1,"created_at":"2019-02-01T13:08:50.000Z","updated_at":"2020-05-14T14:10:09.781Z","permissions":["admin","admin.user","admin.group","admin.role","admin.organization","admin.overview","admin.text_module","admin.time_accounting","admin.macro","admin.tag","admin.calendar","admin.sla","admin.scheduler","admin.report_profile","admin.channel_web","admin.channel_formular","admin.channel_email","admin.channel_twitter","admin.channel_facebook","admin.channel_telegram","admin.channel_sms","admin.channel_chat","admin.branding","admin.setting_system","admin.security","admin.ticket","admin.package","admin.integration","admin.api","admin.object","admin.translation","admin.monitoring","admin.maintenance","admin.session","user_preferences","user_preferences.password","user_preferences.notifications","user_preferences.access_token","user_preferences.language","user_preferences.linked_accounts","user_preferences.device","user_preferences.avatar","user_preferences.calendar","user_preferences.out_of_office","report","ticket.agent","chat.agent","cti.agent","admin.knowledge_base","knowledge_base.reader","knowledge_base.editor","admin.trigger"],"role_ids":[1,2]}}
Payload size: 0M):
/opt/zammad/lib/search_index_backend.rb:895:in `make_request_and_validate'
/opt/zammad/lib/search_index_backend.rb:145:in `add'
/opt/zammad/app/models/concerns/has_search_index_backend.rb:168:in `search_index_update_backend'
/opt/zammad/app/jobs/search_index_job.rb:26:in `update_search_index'
/opt/zammad/app/jobs/search_index_job.rb:22:in `perform'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/execution.rb:39:in `block in perform_now'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/opt/zammad/app/jobs/concerns/has_active_job_lock.rb:12:in `block (2 levels) in <module:HasActiveJobLock>'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/i18n-1.8.3/lib/i18n.rb:313:in `with_locale'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/logging.rb:26:in `block (4 levels) in <module:Logging>'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `instrument'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/logging.rb:25:in `block (3 levels) in <module:Logging>'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/logging.rb:46:in `block in tag_logger'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:28:in `tagged'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `tagged'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/logging.rb:46:in `tag_logger'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/logging.rb:22:in `block (2 levels) in <module:Logging>'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/execution.rb:38:in `perform_now'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/execution.rb:24:in `block in execute'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/railtie.rb:28:in `block (4 levels) in <class:Railtie>'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/reloader.rb:73:in `block in wrap'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/reloader.rb:72:in `wrap'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/railtie.rb:27:in `block (3 levels) in <class:Railtie>'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/execution.rb:22:in `execute'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/activejob-5.2.4.4/lib/active_job/queue_adapters/delayed_job_adapter.rb:42:in `perform'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/backend/base.rb:81:in `block in invoke_job'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:61:in `block in initialize'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:66:in `execute'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/backend/base.rb:78:in `invoke_job'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:230:in `block (2 levels) in run'
/opt/zammad/.rvm/rubies/ruby-2.6.6/lib/ruby/2.6.0/timeout.rb:93:in `block in timeout'
/opt/zammad/.rvm/rubies/ruby-2.6.6/lib/ruby/2.6.0/timeout.rb:103:in `timeout'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:230:in `block in run'
/opt/zammad/.rvm/rubies/ruby-2.6.6/lib/ruby/2.6.0/benchmark.rb:308:in `realtime'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:229:in `run'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:312:in `block in reserve_and_run_one_job'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:61:in `block in initialize'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:66:in `execute'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:312:in `reserve_and_run_one_job'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:213:in `block in work_off'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:212:in `times'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/delayed_job-4.1.7/lib/delayed/worker.rb:212:in `work_off'
/opt/zammad/app/models/scheduler.rb:372:in `block (3 levels) in worker'
/opt/zammad/.rvm/rubies/ruby-2.6.6/lib/ruby/2.6.0/benchmark.rb:308:in `realtime'
/opt/zammad/app/models/scheduler.rb:370:in `block (2 levels) in worker'
/opt/zammad/app/models/scheduler.rb:366:in `loop'
/opt/zammad/app/models/scheduler.rb:366:in `block in worker'
/opt/zammad/.rvm/gems/ruby-2.6.6/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
E, [2020-09-23T12:07:55.300242 #68660-46964187847140] ERROR -- : Retrying SearchIndexJob in #<Proc:0x0000556d67b99ba8@/opt/zammad/app/jobs/search_index_job.rb:6 (lambda)> seconds, due to a StandardError. The original exception was nil.
I, [2020-09-23T12:07:55.327436 #68660-46964187847140] INFO -- : Enqueued SearchIndexJob (Job ID: 18c2d981-1e24-4ec8-a4ff-97ccb07a88b2) to DelayedJob(default) at 2020-09-23 10:08:25 UTC with arguments: "StatsStore", 1
I, [2020-09-23T12:07:55.334881 #68660-46964187847140] INFO -- : 2020-09-23T12:07:55+0200: [Worker(host:hades.faked.org pid:68660)] Job SearchIndexJob [18c2d981-1e24-4ec8-a4ff-97ccb07a88b2] from DelayedJob(default) with arguments: ["StatsStore", 1] (id=2424036) (queue=default) COMPLETED after 0.0716
I, [2020-09-23T12:07:58.381965 #68660-46964191330820] INFO -- : execute Import::OTRS.diff_worker (try_count 0)...
I, [2020-09-23T12:07:58.382174 #68660-46964191330820] INFO -- : ended Import::OTRS.diff_worker took: 0.009128637 seconds.