Infos:
- Used Zammad version: 3.1
- Used Zammad installation source: docker
- Operating system: CentOS
We are running Zammad in Docker using -3.1.0-32
version for now and have some issues.
I should mention that we were upgrading from 2.8 to 3.1 and have experienced a multitude of issues. We at the moment have a lot of workarounds running, such as ‘rake jobs:work’ to get delayed task to be processed and would appreciate some assistance.
At the moment the most important issue is Error 1, emails not being properly processed into Zammad without a script to occasionally process them. Would be good to at least have some insight into this:
Error 1) In the Zammad scheduler process we have the following errors
They are the same as: E-Mails cant be processed - RecordNotFound - #3 by commanderape
Here is our logs:
I, [2020-01-08T03:01:03.284929 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 4374880d-0336-4654-be3f-8e123f533bc9) to DelayedJob(default) with arguments: "User", 6
"ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/3a96e14ea07cd5d705927167467be986.eml, please create an issue at https://github.com/zammad/zammad/issues"
"ERROR: #<ActiveRecord::RecordNotFound: Couldn't find Ticket without an ID>"
E, [2020-01-08T03:01:03.592264 #1-69999712716540] ERROR -- : ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/3a96e14ea07cd5d705927167467be986.eml, please create an issue at https://github.com/zammad/zammad/issues
E, [2020-01-08T03:01:03.592300 #1-69999712716540] ERROR -- : Couldn't find Ticket without an ID (ActiveRecord::RecordNotFound)
and yes after that I could run >rails r ‘Channel::EmailParser.process_unprocessable_mails’
which processed them all without any errors, but we don’t want to constantly run this on a cron job to process emails. (Another one of our workarounds atm)
**Error 2)**Also in Scheduler we could see a problem that appears from time to time.
ActiveRecord::ConnectionTimeoutError - could not obtain a database connection within 5 seconds. The max pool size is currently 50; consider increasing it
Then we raise timeout from 5sec to 10sec. Seems like it helped a little because before that change we had that error every 15minutes. Now it is about once every 2 hours.
Error 3) Another issue is that I have a Delayed::Job.count() increasing up to hundreds and thousands (may become 10k jobs) and the only solution for me is to run jobs:work
inside a container. It starts to process all jobs and continue to process them nice, but again this is another work around)
gosu 1000:1000 rake jobs:work
I could guess that it is caused because of errors in scheduler mentioned above.
But in that process we also receive some errors from time to time:
log
/usr/local/bundle/gems/rake-12.3.2/exe/rake:27:in `'
Tasks: TOP => jobs:work
(See full trace by running task with --trace)
WARNING: terminating connection because of crash of another server process
DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT: In a moment you should be able to reconnect to the database and repeat your command.
rake aborted!
ActiveRecord::StatementInvalid: PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
: UPDATE "delayed_jobs" SET "locked_by" = NULL, "locked_at" = NULL WHERE "delayed_jobs"."locked_by" = $1
/usr/local/bundle/gems/rake-12.3.2/exe/rake:27:in `'
Caused by:
PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
/usr/local/bundle/gems/rake-12.3.2/exe/rake:27:in `'
Caused by:
PG::Error: invalid encoding name: utf8
/usr/local/bundle/gems/rake-12.3.2/exe/rake:27:in `'
Caused by:
ActiveRecord::StatementInvalid: PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
: UPDATE "delayed_jobs" SET locked_at = '2020-01-08 04:11:14.386955', locked_by = 'host:e67b914f058d pid:1' WHERE id IN (SELECT "delayed_jobs"."id" FROM "delayed_jobs" WHERE ((run_at <= '2020-01-08 04:11:14.386472' AND (locked_at IS NULL OR locked_at < '2020-01-08 00:11:14.386498') OR locked_by = 'host:e67b914f058d pid:1') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1 FOR UPDATE) RETURNING *
**Error 4)**The same as described here:
Our logs:
>E, [2020-01-07T03:46:44.883545 #1-47276871602100] ERROR -- : Unable to get asset for 'customer': #<NameError: uninitialized constant Customer>
Don’t know what to do with that
Error 5) I have noticed this error as well:
Mosty saw this at each start of the service after it was rebooted
E, [2020-01-07T03:45:41.312836 #1-47276855767320] ERROR -- : undefined method `first' for nil:NilClass (NoMethodError)
p.s.
some more long logs
I, [2020-01-08T05:11:52.538255 #1-69999712716540] INFO -- : execute Channel.fetch (try_count 0)...
I, [2020-01-08T05:11:52.544544 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/quotes-zammad port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:11:52.988588 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:11:52.988681 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:11:52.999612 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/kkts_it port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:11:53.234404 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:11:53.234518 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:11:53.249797 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/hpdemo port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:11:53.475366 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:11:53.475418 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:11:53.485808 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/issues port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:11:53.713328 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:11:53.713392 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:11:53.724839 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/bookings@kkts.com.au port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:11:54.565158 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:11:54.565232 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:24.581077 #1-69999712716540] INFO -- : execute Channel.fetch (try_count 0)...
I, [2020-01-08T05:12:24.583496 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/quotes-zammad port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:12:24.808119 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:24.808221 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:24.819328 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/kkts_it port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:12:25.043624 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:25.043662 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:25.052124 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/hpdemo port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:12:25.506691 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:25.506758 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:25.516692 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/issues port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:12:25.749541 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:25.749608 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:25.759934 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/bookings@kkts.com.au port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:12:26.230881 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:26.230921 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:56.243370 #1-69999712716540] INFO -- : execute Channel.fetch (try_count 0)...
I, [2020-01-08T05:12:56.245518 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/quotes-zammad port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:12:56.595543 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:56.595613 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:56.605897 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/kkts_it port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:12:56.831371 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:56.831428 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:56.840636 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/hpdemo port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:12:57.053070 #1-69999712716540] INFO -- : - message 1/1
I, [2020-01-08T05:12:57.535248 #1-69999712716540] INFO -- : Process email with msgid '<DF4PR8401MB103512605DC02CAB030DF5ADA93E0@DF4PR8401MB1035.NAMPRD84.PROD.OUTLOOK.COM>'
I, [2020-01-08T05:12:57.571767 #1-69999712716540] INFO -- : process filter Bookings ...
I, [2020-01-08T05:12:57.572310 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, "Kotitsas, Louie" <elias.kotitsas@hp.com>, "McCutcheon, Cindy (Inside Sales Lead)" <cindy.mccutcheon@hp.com>' on bookings@kkts.com.au, but should
I, [2020-01-08T05:12:57.572370 #1-69999712716540] INFO -- : process filter Quotes ...
I, [2020-01-08T05:12:57.572613 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, "Kotitsas, Louie" <elias.kotitsas@hp.com>, "McCutcheon, Cindy (Inside Sales Lead)" <cindy.mccutcheon@hp.com>' on quotes@kkts.com.au, but should
I, [2020-01-08T05:12:57.572669 #1-69999712716540] INFO -- : process filter hpdemo ...
I, [2020-01-08T05:12:57.574026 #1-69999712716540] INFO -- : perform 'x-zammad-ticket-group_id' = '{"value"=>"8"}'
I, [2020-01-08T05:12:57.574081 #1-69999712716540] INFO -- : process filter issues ...
I, [2020-01-08T05:12:57.574331 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, "Kotitsas, Louie" <elias.kotitsas@hp.com>, "McCutcheon, Cindy (Inside Sales Lead)" <cindy.mccutcheon@hp.com>' on issues@kkts.com.au, but should
I, [2020-01-08T05:12:57.574388 #1-69999712716540] INFO -- : process filter kkts_it ...
I, [2020-01-08T05:12:57.574605 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, "Kotitsas, Louie" <elias.kotitsas@hp.com>, "McCutcheon, Cindy (Inside Sales Lead)" <cindy.mccutcheon@hp.com>' on kkts_it@mail.kkts.com.au, but should
I, [2020-01-08T05:12:57.617277 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 6eac7259-9d59-4042-969e-ac7443c41d13) to DelayedJob(default) with arguments: "Ticket", 93278
I, [2020-01-08T05:12:57.622080 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 27b1708e-ff8b-4ca5-ad44-e0e5e9f81eea) to DelayedJob(default) with arguments: "User", 6401
I, [2020-01-08T05:12:57.633720 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 05adf9b8-612e-4de4-8ca6-e118f38b2233) to DelayedJob(default) with arguments: "StatsStore", 20253
I, [2020-01-08T05:12:57.636500 #1-69999712716540] INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
I, [2020-01-08T05:12:57.769243 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 66d6bada-3cf3-403c-bcf9-585063880ac6) to DelayedJob(default) with arguments: "Ticket", 93278
I, [2020-01-08T05:12:57.774018 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: ee367a49-dd79-40f2-9962-e22ed32d0dca) to DelayedJob(default) with arguments: "User", 6401
"ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/c0f1c6bde272ae8f26ccc05628d3ab81.eml, please create an issue at https://github.com/zammad/zammad/issues"
"ERROR: #<ActiveRecord::RecordNotFound: Couldn't find Ticket::Article without an ID>"
E, [2020-01-08T05:12:58.078986 #1-69999712716540] ERROR -- : ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/c0f1c6bde272ae8f26ccc05628d3ab81.eml, please create an issue at https://github.com/zammad/zammad/issues
E, [2020-01-08T05:12:58.079049 #1-69999712716540] ERROR -- : Couldn't find Ticket::Article without an ID (ActiveRecord::RecordNotFound)
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/finder_methods.rb:433:in `find_with_ids'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/finder_methods.rb:69:in `find'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/querying.rb:5:in `find'
/usr/local/bundle/gems/composite_primary_keys-11.2.0/lib/composite_primary_keys/core.rb:24:in `find'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/persistence.rb:609:in `block in reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/scoping/default.rb:34:in `block in unscoped'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation.rb:281:in `scoping'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/scoping/default.rb:34:in `unscoped'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/persistence.rb:609:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/attribute_methods/dirty.rb:31:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/associations.rb:255:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/autosave_association.rb:231:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/aggregations.rb:15:in `reload'
/opt/zammad/app/models/channel/email_parser.rb:303:in `_process'
/opt/zammad/app/models/channel/email_parser.rb:115:in `block in process'
/usr/local/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'
/usr/local/lib/ruby/2.5.0/timeout.rb:33:in `block in catch'
/usr/local/lib/ruby/2.5.0/timeout.rb:33:in `catch'
/usr/local/lib/ruby/2.5.0/timeout.rb:33:in `catch'
/usr/local/lib/ruby/2.5.0/timeout.rb:108:in `timeout'
/opt/zammad/app/models/channel/email_parser.rb:114:in `process'
/opt/zammad/app/models/channel/driver/imap.rb:254:in `block in fetch'
/opt/zammad/app/models/channel/driver/imap.rb:211:in `each'
/opt/zammad/app/models/channel/driver/imap.rb:211:in `fetch'
/opt/zammad/app/models/channel.rb:56:in `fetch'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/opt/zammad/app/models/channel.rb:30:in `fetch'
(eval):1:in `_start_job'
/opt/zammad/app/models/scheduler.rb:286:in `eval'
/opt/zammad/app/models/scheduler.rb:286:in `_start_job'
/opt/zammad/app/models/scheduler.rb:239:in `block (2 levels) in start_job'
/opt/zammad/app/models/scheduler.rb:237:in `loop'
/opt/zammad/app/models/scheduler.rb:237:in `block in start_job'
/usr/local/bundle/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
I, [2020-01-08T05:12:58.124981 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:58.135220 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/issues port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:12:58.363360 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:58.363482 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:12:58.373119 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/bookings@kkts.com.au port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:12:59.609926 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:12:59.609996 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:13:29.626284 #1-69999712716540] INFO -- : execute Channel.fetch (try_count 0)...
I, [2020-01-08T05:13:29.628559 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/quotes-zammad port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:13:30.094857 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:13:30.094912 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:13:30.106024 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/kkts_it port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:13:30.338665 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:13:30.338721 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:13:30.348578 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/hpdemo port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:13:30.565098 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:13:30.565164 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:13:30.575706 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/issues port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:13:30.801823 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:13:30.801877 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:13:30.811443 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/bookings@kkts.com.au port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:13:31.339060 #1-69999712716540] INFO -- : - message 1/1
I, [2020-01-08T05:13:31.500708 #1-69999712716540] INFO -- : Process email with msgid '<1578460503185909564@mail.kkts.com.au>'
I, [2020-01-08T05:13:31.522683 #1-69999712716540] INFO -- : process filter Bookings ...
I, [2020-01-08T05:13:31.524619 #1-69999712716540] INFO -- : perform 'x-zammad-ticket-group_id' = '{"value"=>"2"}'
I, [2020-01-08T05:13:31.524712 #1-69999712716540] INFO -- : process filter Quotes ...
I, [2020-01-08T05:13:31.525191 #1-69999712716540] INFO -- : not matching x-any-recipient:'bookings@kkts.com.au' on quotes@kkts.com.au, but should
I, [2020-01-08T05:13:31.525244 #1-69999712716540] INFO -- : process filter hpdemo ...
I, [2020-01-08T05:13:31.525529 #1-69999712716540] INFO -- : not matching x-any-recipient:'bookings@kkts.com.au' on hpdemo@kkts.com.au, but should
I, [2020-01-08T05:13:31.525571 #1-69999712716540] INFO -- : process filter issues ...
I, [2020-01-08T05:13:31.525889 #1-69999712716540] INFO -- : not matching x-any-recipient:'bookings@kkts.com.au' on issues@kkts.com.au, but should
I, [2020-01-08T05:13:31.525931 #1-69999712716540] INFO -- : process filter kkts_it ...
I, [2020-01-08T05:13:31.526222 #1-69999712716540] INFO -- : not matching x-any-recipient:'bookings@kkts.com.au' on kkts_it@mail.kkts.com.au, but should
I, [2020-01-08T05:13:31.528778 #1-69999712716540] INFO -- : set_attributes_by_x_headers header x-zammad-ticket-group_id found. Assign group_id=2
I, [2020-01-08T05:13:31.528933 #1-69999712716540] INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=6
I, [2020-01-08T05:13:31.556124 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 12283317-d65c-4bc8-91ad-bcbb020b48ff) to DelayedJob(default) with arguments: "Ticket", 93350
I, [2020-01-08T05:13:31.562970 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 190b1d41-bd1b-452c-b4d9-a76a7a7b6010) to DelayedJob(default) with arguments: "User", 6
I, [2020-01-08T05:13:31.570163 #1-69999712716540] INFO -- : set_attributes_by_x_headers header x-zammad-article-sender found Agent
I, [2020-01-08T05:13:31.570261 #1-69999712716540] INFO -- : set_attributes_by_x_headers found Ticket::Article::Sender lookup for 'Agent'
I, [2020-01-08T05:13:31.570771 #1-69999712716540] INFO -- : set_attributes_by_x_headers assign Ticket::Article sender_id=1
I, [2020-01-08T05:13:31.571016 #1-69999712716540] INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
I, [2020-01-08T05:13:31.655410 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 33d0e896-921c-4661-bea2-d8d3a39ebbd9) to DelayedJob(default) with arguments: "Ticket", 93350
I, [2020-01-08T05:13:31.662495 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 96f0bafc-9024-4095-af03-cb05e638fe44) to DelayedJob(default) with arguments: "User", 6
"ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/d0a022be16d59a0e864fe16e1a2086c7.eml, please create an issue at https://github.com/zammad/zammad/issues"
"ERROR: #<ActiveRecord::RecordNotFound: Couldn't find Ticket without an ID>"
E, [2020-01-08T05:13:31.936427 #1-69999712716540] ERROR -- : ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/d0a022be16d59a0e864fe16e1a2086c7.eml, please create an issue at https://github.com/zammad/zammad/issues
E, [2020-01-08T05:13:31.936502 #1-69999712716540] ERROR -- : Couldn't find Ticket without an ID (ActiveRecord::RecordNotFound)
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/finder_methods.rb:433:in `find_with_ids'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/finder_methods.rb:69:in `find'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/querying.rb:5:in `find'
/usr/local/bundle/gems/composite_primary_keys-11.2.0/lib/composite_primary_keys/core.rb:24:in `find'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/persistence.rb:609:in `block in reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/scoping/default.rb:34:in `block in unscoped'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation.rb:281:in `scoping'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/scoping/default.rb:34:in `unscoped'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/persistence.rb:609:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/attribute_methods/dirty.rb:31:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/associations.rb:255:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/autosave_association.rb:231:in `reload'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/aggregations.rb:15:in `reload'
/opt/zammad/app/models/channel/email_parser.rb:302:in `_process'
/opt/zammad/app/models/channel/email_parser.rb:115:in `block in process'
/usr/local/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'
/usr/local/lib/ruby/2.5.0/timeout.rb:33:in `block in catch'
/usr/local/lib/ruby/2.5.0/timeout.rb:33:in `catch'
/usr/local/lib/ruby/2.5.0/timeout.rb:33:in `catch'
/usr/local/lib/ruby/2.5.0/timeout.rb:108:in `timeout'
/opt/zammad/app/models/channel/email_parser.rb:114:in `process'
/opt/zammad/app/models/channel/driver/imap.rb:254:in `block in fetch'
/opt/zammad/app/models/channel/driver/imap.rb:211:in `each'
/opt/zammad/app/models/channel/driver/imap.rb:211:in `fetch'
/opt/zammad/app/models/channel.rb:56:in `fetch'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/usr/local/bundle/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/opt/zammad/app/models/channel.rb:30:in `fetch'
(eval):1:in `_start_job'
/opt/zammad/app/models/scheduler.rb:286:in `eval'
/opt/zammad/app/models/scheduler.rb:286:in `_start_job'
/opt/zammad/app/models/scheduler.rb:239:in `block (2 levels) in start_job'
/opt/zammad/app/models/scheduler.rb:237:in `loop'
/opt/zammad/app/models/scheduler.rb:237:in `block in start_job'
/usr/local/bundle/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
I, [2020-01-08T05:13:31.980599 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:14:01.995587 #1-69999712716540] INFO -- : execute Channel.fetch (try_count 0)...
I, [2020-01-08T05:14:01.999311 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/quotes-zammad port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:14:02.379880 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:14:02.379943 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:14:02.393698 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/kkts_it port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false)
I, [2020-01-08T05:14:03.464821 #1-69999712716540] INFO -- : - no message
I, [2020-01-08T05:14:03.464885 #1-69999712716540] INFO -- : done
I, [2020-01-08T05:14:03.475380 #1-69999712716540] INFO -- : fetching imap (mail.kkts.com.au/hpdemo port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true)
I, [2020-01-08T05:14:04.769123 #1-69999712716540] INFO -- : - message 1/1
I, [2020-01-08T05:14:05.035208 #1-69999712716540] INFO -- : Process email with msgid '<CS1PR8401MB072832607946D5F9B2DC45B4E53E0@CS1PR8401MB0728.NAMPRD84.PROD.OUTLOOK.COM>'
I, [2020-01-08T05:14:05.079159 #1-69999712716540] INFO -- : process filter Bookings ...
I, [2020-01-08T05:14:05.080549 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, Otis Chen <otis.chen@jbhifi.com.au>' on bookings@kkts.com.au, but should
I, [2020-01-08T05:14:05.080606 #1-69999712716540] INFO -- : process filter Quotes ...
I, [2020-01-08T05:14:05.080817 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, Otis Chen <otis.chen@jbhifi.com.au>' on quotes@kkts.com.au, but should
I, [2020-01-08T05:14:05.080860 #1-69999712716540] INFO -- : process filter hpdemo ...
I, [2020-01-08T05:14:05.082852 #1-69999712716540] INFO -- : perform 'x-zammad-ticket-group_id' = '{"value"=>"8"}'
I, [2020-01-08T05:14:05.082910 #1-69999712716540] INFO -- : process filter issues ...
I, [2020-01-08T05:14:05.083147 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, Otis Chen <otis.chen@jbhifi.com.au>' on issues@kkts.com.au, but should
I, [2020-01-08T05:14:05.083198 #1-69999712716540] INFO -- : process filter kkts_it ...
I, [2020-01-08T05:14:05.083429 #1-69999712716540] INFO -- : not matching x-any-recipient:'AU HP DEMO <hpdemo@kkts.com.au>, Otis Chen <otis.chen@jbhifi.com.au>' on kkts_it@mail.kkts.com.au, but should
I, [2020-01-08T05:14:05.162831 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: b8109a6e-88e1-488f-aa0e-86ea1a60c1f2) to DelayedJob(default) with arguments: "Ticket", 86736
I, [2020-01-08T05:14:05.168433 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 9d5087de-6932-49a9-82a8-986e7f1c1efa) to DelayedJob(default) with arguments: "User", 7091
I, [2020-01-08T05:14:05.182639 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: bd8f6960-9f87-4356-ad29-6c3a70cd0f83) to DelayedJob(default) with arguments: "StatsStore", 20254
I, [2020-01-08T05:14:05.186573 #1-69999712716540] INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
I, [2020-01-08T05:14:05.278402 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: 7034f9f4-9311-440f-9f4a-8132aacee30e) to DelayedJob(default) with arguments: "Ticket", 86736
I, [2020-01-08T05:14:05.283828 #1-69999712716540] INFO -- : Enqueued SearchIndexJob (Job ID: a2dd80af-0abf-4da9-a4ed-d5984c92e820) to DelayedJob(default) with arguments: "User", 7091
E, [2020-01-08T05:14:05.472638 #1-69999712716540] ERROR -- : missing session file for '47213409905700', remove session.
"ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/4e87687c36449778629abebc67501b78.eml, please create an issue at https://github.com/zammad/zammad/issues"
"ERROR: #<ActiveRecord::RecordNotFound: Couldn't find Ticket::Article without an ID>"
E, [2020-01-08T05:14:05.582677 #1-69999712716540] ERROR -- : ERROR: Can't process email, you will find it for bug reporting under /opt/zammad/tmp/unprocessable_mail/4e87687c36449778629abebc67501b78.eml, please create an issue at https://github.com/zammad/zammad/issues