Failed to run background job TriggerWebhookJob

ecomsilio · December 11, 2020, 9:37am

Infos:

Used Zammad version: 3.6.x
Used Zammad installation source: (source, package, …) package
Operating system: Cent OS 7
Browser + version: Mac OS 10.15.6 + Chrome 87.0.4280.67

I have set up a Trigger to call a webhook on each update of a ticket. Currently this is only for test purposes. I would add more filters in future but we don’t have that many update in this specific system and only 2 people working in Zammad at the same time.

I worked withour any errors since I updated to 3.6.about 2 weeks ago. Since than nothing was changed on the server.

As of yesterday I started to see errors in the health check:

Issues: Failed to run background job #1 'TriggerWebhookJob' 2 time(s) with 8 attempt(s).

The production logs show the following:

I, [2020-12-11T08:11:43.250131 #35562-47364092114300]  INFO -- : 2020-12-11T08:11:43+0100: [Worker(host:zammad pid:35562)] Job TriggerWebhookJob [d96c870b-a9e1-4324-8b14-82501089efaa] from DelayedJob(default) with arguments: [{"_aj_globalid"=>"gid://zammad/Trigger/7"}, {"_aj_globalid"=>"gid://zammad/Ticket/8506"}, nil] (id=686404) (queue=default) RUNNING
I, [2020-12-11T08:11:43.273053 #35562-47364092114300]  INFO -- : Performing TriggerWebhookJob (Job ID: d96c870b-a9e1-4324-8b14-82501089efaa) from DelayedJob(default) with arguments: #<GlobalID:0x00005627a02e3588 @uri=#<URI::GID gid://zammad/Trigger/7>>, #<GlobalID:0x00005627a02e29d0 @uri=#<URI::GID gid://zammad/Ticket/8506>>, nil
E, [2020-12-11T08:11:43.430420 #35562-47364092114300] ERROR -- : Error performing TriggerWebhookJob (Job ID: d96c870b-a9e1-4324-8b14-82501089efaa) from DelayedJob(default) in 157.2ms: TriggerWebhookJob::RequestError (TriggerWebhookJob::RequestError):
/opt/zammad/app/jobs/trigger_webhook_job.rb:27:in `perform'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/execution.rb:39:in `block in perform_now'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/i18n-1.8.5/lib/i18n.rb:313:in `with_locale'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/logging.rb:26:in `block (4 levels) in <module:Logging>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `instrument'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/logging.rb:25:in `block (3 levels) in <module:Logging>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/logging.rb:46:in `block in tag_logger'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:28:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `tagged'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/logging.rb:46:in `tag_logger'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/logging.rb:22:in `block (2 levels) in <module:Logging>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/execution.rb:38:in `perform_now'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/execution.rb:24:in `block in execute'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/railtie.rb:28:in `block (4 levels) in <class:Railtie>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/reloader.rb:73:in `block in wrap'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/execution_wrapper.rb:87:in `wrap'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/reloader.rb:72:in `wrap'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/railtie.rb:27:in `block (3 levels) in <class:Railtie>'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `instance_exec'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/execution.rb:22:in `execute'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/activejob-5.2.4.4/lib/active_job/queue_adapters/delayed_job_adapter.rb:42:in `perform'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/backend/base.rb:81:in `block in invoke_job'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:61:in `block in initialize'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:66:in `execute'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/backend/base.rb:78:in `invoke_job'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:230:in `block (2 levels) in run'
/opt/zammad/vendor/ruby-2.6.6/lib/ruby/2.6.0/timeout.rb:93:in `block in timeout'
/opt/zammad/vendor/ruby-2.6.6/lib/ruby/2.6.0/timeout.rb:103:in `timeout'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:230:in `block in run'
/opt/zammad/vendor/ruby-2.6.6/lib/ruby/2.6.0/benchmark.rb:308:in `realtime'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:229:in `run'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:312:in `block in reserve_and_run_one_job'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:61:in `block in initialize'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:66:in `execute'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:312:in `reserve_and_run_one_job'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:213:in `block in work_off'
/opt/zammad/vendor/bundle/ruby/2.6.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:212:in `times'
/opt/zammad/vendor/bundle/ruby/2.6.0/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/vendor/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/vendor/bundle/ruby/2.6.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
E, [2020-12-11T08:11:43.430554 #35562-47364092114300] ERROR -- : Retrying TriggerWebhookJob in #<Proc:0x000056279e8b6a48@/opt/zammad/app/jobs/trigger_webhook_job.rb:16 (lambda)> seconds, due to a TriggerWebhookJob::RequestError. The original exception was nil.
I, [2020-12-11T08:11:43.436621 #35562-47364092114300]  INFO -- : Enqueued TriggerWebhookJob (Job ID: d96c870b-a9e1-4324-8b14-82501089efaa) to DelayedJob(default) at 2020-12-11 07:11:53 UTC with arguments: #<GlobalID:0x000056279fb12368 @uri=#<URI::GID gid://zammad/Trigger/7>>, #<GlobalID:0x000056279fb3eb98 @uri=#<URI::GID gid://zammad/Ticket/8506>>, nil
I, [2020-12-11T08:11:43.440740 #35562-47364092114300]  INFO -- : 2020-12-11T08:11:43+0100: [Worker(host:zammad pid:35562)] Job TriggerWebhookJob [d96c870b-a9e1-4324-8b14-82501089efaa] from DelayedJob(default) with arguments: [{"_aj_globalid"=>"gid://zammad/Trigger/7"}, {"_aj_globalid"=>"gid://zammad/Ticket/8506"}, nil] (id=686404) (queue=default) COMPLETED after 0.1905

What could be the reason for this error?

Many thanks,
Gijs

ecomsilio · December 11, 2020, 10:06am

This is what the health check currently looks:

{
    "healthy": false,
    "message": "Failed to run background job #1 'TriggerWebhookJob' 2 time(s) with 7 attempt(s).",
    "issues": ["Failed to run background job #1 'TriggerWebhookJob' 2 time(s) with 7 attempt(s)."],
    "actions": [],
    "token": "2JPWsnxxxxxxxxxxxxxxxxxxxxxxxxxxxxhij7jw"
}

ecomsilio · December 11, 2020, 10:37am

Issue fixed. The other side of the webhook answered with an error.
I fixed it so that it does answer with 200 and the error log in Zammad is empty now again.
So my own mistake.

Cheers,
Gijs

system · April 10, 2021, 10:37am

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