After upgrade No Mails and Delayed::Backend::ActiveRecord::Job id: 66271

mpmichael · February 21, 2019, 5:42pm

Used Zammad version: 2.9
Used Zammad installation source: package
Operating system: Ubuntu 18.04
Browser + version: All

Expected behavior:

getting new mails in the Zammad System

Actual behavior:

No incomming mails after Migration from 2.8 to 2.9*
production.log says:
!ruby/object:BackgroundJobSearchIndex\nobject: …", last_error: nil, run_at: “2019-02-21 13:21:45”, locked_at: “2019-02-21 13:21:48”, failed_at: nil, locked_by: “host:support pid:4542”, queue: nil, created_at: “2019-02-21 13:21:45”, updated_at: “2019-02-21 13:21:45”> started.
I, [2019-02-21T18:30:20.788876 #32627-47118102630240] INFO – : Scheduler stopped.
I, [2019-02-21T18:30:25.018794 #32682-47383166005080] INFO – : Setting.set(‘product_logo’, “aaeb0d9c989555578264eb66f5d7eb26.png”)
I, [2019-02-21T18:30:28.096018 #32682-47383166005080] INFO – : Scheduler started.
I, [2019-02-21T18:30:28.101647 #32682-47383166005080] INFO – : Cleanup of left over locked delayed jobs 2019-02-21 17:30:28 UTC started.
I, [2019-02-21T18:30:28.118224 #32682-47383166005080] INFO – : Checking left over delayed job #<Delayed::Backend::ActiveRecord::Job id: 66271, priority: 0, attempts: 0, handler: “— !ruby/object:BackgroundJobSearchIndex\nobject: …”, last_error: nil, run_at: “2019-02-21 13:21:45”, locked_at: “2019-02-21 13:21:48”, failed_at: nil, locked_by: “host:support pid:4542”, queue: nil, created_at: “2019-02-21 13:21:45”, updated_at: “2019-02-21 13:21:45”> started.
I, [2019-02-21T18:30:28.154159 #32682-47383166005080] INFO – : Scheduler stopped.
I, [2019-02-21T18:30:28.745952 #32413-47327281204700] INFO – : Started GET “/api/v1/channels_email?=1550766608278" for 213.61.104.94 at 2019-02-21 18:30:28 +0100
I, [2019-02-21T18:30:28.767469 #32413-47327281204700] INFO – : Processing by ChannelsEmailController#index as JSON
I, [2019-02-21T18:30:28.767658 #32413-47327281204700] INFO – : Parameters: {"”=>“1550766608278”}
I, [2019-02-21T18:30:28.814040 #32413-47327281204700] INFO – : Completed 200 OK in 46ms (Views: 6.3ms | ActiveRecord: 5.6ms)

In Zammad:

* scheduler may not run (last execution of SessionHelper.cleanup_expired about 2 hours over) - please contact your system administrator

My guess is - that there is a Job blocking the system. I already tried to reboot, to restart the Services - but no change.
I would be happy if anyone could give me a idea to solve this Problem.
BR
Martin

mpmichael · February 21, 2019, 5:53pm

Hello,

i just tried (via console)

zammad run rails c
Channel.fetch

And the zammad imported my testmails. So it seems to be a Problem with the scheduler or with the “Jobs”.
BR
Martin

MrGeneration · February 21, 2019, 6:56pm

What does
zammad run rails c

Delayed::Job.count
Delayed::Job.first
Delayed::Job.last

say?

Above is the only thing coming in the logfile?
Any other errors in production log maybe?

mpmichael · February 21, 2019, 7:39pm

Hello,

thank’s for the reply! In the Logfile - there is only this error since some hours.

The result from the commands are:

irb(main):001:0> Delayed::Job.count
=> 401

irb(main):002:0> Delayed::Job.first
=> #<Delayed::Backend::ActiveRecord::Job id: 66271, priority: 0, attempts: 0, handler: "--- !ruby/object:BackgroundJobSearchIndex\nobject: ...", last_error: nil, run_at: "2019-02-21 13:21:45", locked_at: "2019-02-21 13:21:48", failed_at: nil, locked_by: "host:support pid:4542", queue: nil, created_at: "2019-02-21 13:21:45", updated_at: "2019-02-21 13:21:45">

irb(main):003:0> Delayed::Job.last
=> #<Delayed::Backend::ActiveRecord::Job id: 66671, priority: 0, attempts: 0, handler: "--- `!ruby/object:ActiveJob::QueueAdapters::Delayed...", last_error: nil, run_at: "2019-02-21 19:25:42", locked_at: nil, failed_at: nil, locked_by: nil, queue: "default", created_at: "2019-02-21 19:25:42", updated_at: "2019-02-21 19:25:42">`

I could not finde more errors - but after the Upgrade I had to install some missing modules - mentioned here: [solved] Update Zammad 2.9 Via Deb not working (Ubuntu 18.04)

Best regards
Martin

mpmichael · February 21, 2019, 7:45pm

Hello again,

could it be a good idea (in this case) to delete the Job 66671? And if yes - how could this be done?
Best regards
Martin

mpmichael · February 21, 2019, 8:26pm

Hello,

I guess I solved my Problem now. First of all - I did a snapshot (System is a virtual Server)

then I did these commands:

zammad run rails c
Delayed::Job.find(xxxxx).destroy

xxxxx is the Id of my Job (found in the LogFile)

After that - i got these Errors (which where repaired by the System):

I, [2019-02-21T21:07:59.363689 #14334-47278008061760]  INFO -- : 2019-02-21T21:07:59+0100: [Worker(host:support pid:14334)] Job BackgroundJobSearchIndex (id=66280) RUNNING
E, [2019-02-21T21:07:59.364187 #14334-47278008061760] ERROR -- : 2019-02-21T21:07:59+0100: [Worker(host:support pid:14334)] Job BackgroundJobSearchIndex (id=66280) FAILED permanently with Delayed::DeserializationError: Job failed to load: undefined class/module BackgroundJobSearchIndex. Handler: "--- !ruby/object:BackgroundJobSearchIndex\nobject: User\no_id: 5\n"
I, [2019-02-21T21:08:03.284981 #14334-70127991671480]  INFO -- : Started job thread for 'Import Jobs' (ImportJob.start_registered)...
I, [2019-02-21T21:08:03.306752 #14334-70127991671480]  INFO -- : execute ImportJob.start_registered (try_count 0)...
I, [2019-02-21T21:08:03.372795 #14334-47278008061760]  INFO -- : 2019-02-21T21:08:03+0100: [Worker(host:support pid:14334)] Job BackgroundJobSearchIndex (id=66281) RUNNING
E, [2019-02-21T21:08:03.373476 #14334-47278008061760] ERROR -- : 2019-02-21T21:08:03+0100: [Worker(host:support pid:14334)] Job BackgroundJobSearchIndex (id=66281) FAILED permanently with Delayed::DeserializationError: Job failed to load: undefined class/module BackgroundJobSearchIndex. Handler: "--- !ruby/object:BackgroundJobSearchIndex\nobject: User\no_id: 7\n"
I, [2019-02-21T21:08:06.307369 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 2fbeb71a-4940-4cb4-b00b-a1e344d5d6ee) to DelayedJob(default) with arguments: "User", 98
I, [2019-02-21T21:08:06.320001 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: cb7cfaa1-944c-4932-84b9-b243ffed6b59) to DelayedJob(default) with arguments: "Organization", 171
I, [2019-02-21T21:08:06.329224 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 6277ebdb-4460-48ac-b942-c44cf942ac6b) to DelayedJob(default) with arguments: "User", 122
I, [2019-02-21T21:08:06.338157 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 92b4666b-1ff9-4286-a5c1-62d0cec0245e) to DelayedJob(default) with arguments: "User", 4
I, [2019-02-21T21:08:06.347219 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 3ee9f3b2-e202-40f7-a2bb-a09542915bce) to DelayedJob(default) with arguments: "User", 5
I, [2019-02-21T21:08:06.354833 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: e9670786-4a4c-42b2-b1b2-cbcea7788cfe) to DelayedJob(default) with arguments: "User", 7
I, [2019-02-21T21:08:06.361725 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 95078423-b5b8-4efb-a8ad-166b24c7c22a) to DelayedJob(default) with arguments: "User", 42
I, [2019-02-21T21:08:06.370061 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: bbc5e19c-9a1d-44b6-9b08-bdb3d6e62f04) to DelayedJob(default) with arguments: "User", 102
I, [2019-02-21T21:08:06.596537 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 6e22cfe1-619a-4e32-b327-bd2d05596afa) to DelayedJob(default) with arguments: "User", 102
I, [2019-02-21T21:08:06.604301 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 79e35ee7-b552-484b-8618-332f0ed72de7) to DelayedJob(default) with arguments: "Organization", 171
I, [2019-02-21T21:08:06.610375 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 1671a016-8266-4481-8ff8-4429e3661a93) to DelayedJob(default) with arguments: "User", 122
I, [2019-02-21T21:08:06.616554 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 2ddde868-0d2f-4267-9cca-b53c030dc2a7) to DelayedJob(default) with arguments: "User", 4
I, [2019-02-21T21:08:06.625018 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 88df1f11-f05f-42a7-9f5f-f01f652a84a5) to DelayedJob(default) with arguments: "User", 5
I, [2019-02-21T21:08:06.631051 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: da547729-d601-4319-af91-9cfc739f651c) to DelayedJob(default) with arguments: "User", 7
I, [2019-02-21T21:08:06.636701 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 02882d5a-c4c2-44fa-9b58-5210eb6cdf2a) to DelayedJob(default) with arguments: "User", 42
I, [2019-02-21T21:08:06.641969 #14334-70127991671480]  INFO -- : Enqueued SearchIndexJob (Job ID: 80889d53-cd19-4963-9e43-08c2e464367a) to DelayedJob(default) with arguments: "User", 98

Then I went into the GUI. Selected:

Settings
Monitoring
Restart services

Now - the System is working fine again. I can see it in the Log:

I, [2019-02-21T21:18:33.410928 #14334-47277951692640]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-02-21T21:18:33.411082 #14334-47277951692640]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-02-21T21:18:33.411142 #14334-47277951692640]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-02-21T21:18:33.411188 #14334-47277951692640]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-02-21T21:18:33.411559 #14334-47277951692640]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep

Best regards
Martin

MrGeneration · February 22, 2019, 10:40am

That’s odd, thanks for the follow up!
Keep us updated in case the issue appears again

system · June 22, 2019, 10:40am

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