Office365 Mail fetching unreliable, emails dissappear

Technical assistance
1

Infos:

  • Used Zammad version: 3.1.x
  • Used DB: Postgresql 11
  • Used Ruby: 2.3.3p222
  • Used Zammad installation source: (source, package, …) package
  • Operating system: Debian 9
  • Browser + version: Chrome, Firefox, doesn’t matter

Expected behavior:

  • Emails from Office365 Accounts automatically fetched. Emails added to Tickets or created new ones.

Actual behavior:

The fetching of emails worked fine. But maybe since the latest update it works unreliable. Can’t determine a time, dissapearing ist hard to recognize.

The current procedure
Emails get fetched from O365 account and deleted then from Zammad (saw it live in several O365-Accounts.
Healtch-Check and the email window in the frontend doesn’t show any failure.
Every 2nd to maybe 10th Email dissapears.
Copy of an Email put manually in the inbox can work properly, but it’s not assured. (I startet now an outlook-rule, copy each Email to an backup-folder)
No new Ticket or updated Ticket.
No Log-Entry with errors.
No Mail in /opt/zammad/tmp/unprocessable_mail
No change after reboot
Changed Email-Settings to Keep on Server. No change.

Steps to reproduce the behavior:

Summarized with Actual behavior
*

2

Oh boy, that really doesn’t sound like the correct way.
Up to now I didn’t see that in any system.

One thing before we continue:
Please ensure that your ruby version your Zammad uses it not 2.3.x or 2.4.x. Zammad 3.1 requries Ruby 2.5.5 (see: https://docs.zammad.org/en/latest/prerequisites-software.html#ruby-programming-language ).

Normally that’s something the package installation would take care of. Checking on command line directly might not be reliable in that case (so you might ignore it because it doesn’t affect you).

Now back to topic…
If you -somehow- can reproduce this, it would be amazing to have the production log of that moment where the mail “gets fetched but somehow not”.

While you’re at it, please ensure that Zammad really didn’t fetch and cleanly import the mail. Sometimes tickets will hit groups agents don’t have rights on.

Also, if you’re searching for such tickets, ensure your search index is up to date and you have no left over background jobs ( zammad run rails r 'p Delayed::Job.count'will do a great job here, you want that returned value near to 0).

Also it’s possible that your overview just doesn’t refresh and thus it looks like the ticket isn’t there (while it is).

Hopefully this helps you further. :slight_smile:

3

Thanks for the quick response.

Checked Ruby in the vendor folder. 2.5.5. Have Ruby 2.3.3 globally. But this seems not to be the problem. Look further down.
zammad run rails r ‘p Delayed::Job.count’. Result: = 0 I hope so fervently this works.
Have more than enough memory free (24 of 32), also no problem with diskspace.
Userrights shouldn’t be the problem, all Agents can access all groups. Issue comes along in different groups. Hits F5 myself a lot of times. Cleared Browsercache. Not the solution.
Have a look into Postgres and looked for the email-adress and the belonging ids of the disappeared emails. Cant find the missing entries, which must be there

Live watching the Emails arriving in O365 after a short while away. Several Accounts. Also a brand new. With no rules for the inbox.

Now a big surprise:
Have the same Issue with a brand new Zammad Installation on Debian 9. Just installed LAMP, Postgresql, elasticsearch and Zammad a few days ago, for another purpose. Anyway a cool reference system.
Sent 10 Emails from Gmail to O365 and 20 % loss. From Mailbox.org to O365 1 of 7 lost.
Also tried to sent Emails just to an open ticket, also some lost.

The last lines of my log with the receiving of the 7/6 mails from mailbox.org on the “new” server.
If you want more, I send it to you gladly.

I, [2019-08-21T20:20:35.335661 #569-47447612491140]  INFO -- : Send email to: 'SENDER2@MAILBOX.ORG' (from COMPANYA <RECIPIENT@O365MAIL.DE>)
I, [2019-08-21T20:20:35.374656 #569-47447612491140]  INFO -- : Performed TicketArticleCommunicateEmailJob (Job ID: af620bd4-3761-49db-a6b7-70703edbb5b5) from DelayedJob(default) in 1529.39ms
I, [2019-08-21T20:20:35.386531 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job TicketArticleCommunicateEmailJob [af620bd4-3761-49db-a6b7-70703edbb5b5] from DelayedJob(default) with arguments: [29] (id=73) (queue=default) COMPLETED after 1.5805
I, [2019-08-21T20:20:35.413047 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job Transaction::BackgroundJob (id=74) RUNNING
I, [2019-08-21T20:20:35.478508 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job Transaction::BackgroundJob (id=74) COMPLETED after 0.0653
I, [2019-08-21T20:20:35.492661 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job Transaction::BackgroundJob (id=75) RUNNING
E, [2019-08-21T20:20:35.573509 #569-47447612491140] ERROR -- : undefined method `first' for nil:NilClass (NoMethodError)
/opt/zammad/lib/signature_detection.rb:42:in `block in find_signature'
/opt/zammad/lib/signature_detection.rb:29:in `each'
/opt/zammad/lib/signature_detection.rb:29:in `find_signature'
/opt/zammad/lib/signature_detection.rb:137:in `by_user_id'
/opt/zammad/lib/signature_detection.rb:172:in `rebuild_user'
/opt/zammad/app/models/transaction/signature_detection.rb:48:in `perform'
/opt/zammad/app/models/observer/transaction.rb:62:in `execute_singel_backend'
/opt/zammad/app/models/transaction/background_job.rb:30:in `block in perform'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/opt/zammad/app/models/transaction/background_job.rb:26:in `perform'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/backend/base.rb:81:in `block in invoke_job'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:61:in `block in initialize'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:66:in `execute'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/backend/base.rb:78:in `invoke_job'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:230:in `block (2 levels) in run'
/opt/zammad/vendor/ruby-2.5.5/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'
/opt/zammad/vendor/ruby-2.5.5/lib/ruby/2.5.0/timeout.rb:103:in `timeout'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:230:in `block in run'
/opt/zammad/vendor/ruby-2.5.5/lib/ruby/2.5.0/benchmark.rb:308:in `realtime'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:229:in `run'
/opt/zammad/vendor/bundle/ruby/2.5.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.5.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:61:in `block in initialize'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:66:in `execute'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:312:in `reserve_and_run_one_job'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:213:in `block in work_off'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:212:in `times'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/delayed_job-4.1.7/lib/delayed/worker.rb:212:in `work_off'
/opt/zammad/app/models/scheduler.rb:367:in `block (3 levels) in worker'
/opt/zammad/vendor/ruby-2.5.5/lib/ruby/2.5.0/benchmark.rb:308:in `realtime'
/opt/zammad/app/models/scheduler.rb:365:in `block (2 levels) in worker'
/opt/zammad/app/models/scheduler.rb:361:in `loop'
/opt/zammad/app/models/scheduler.rb:361:in `block in worker'
/opt/zammad/vendor/bundle/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
I, [2019-08-21T20:20:35.719077 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job Transaction::BackgroundJob (id=75) COMPLETED after 0.2262
I, [2019-08-21T20:20:35.734537 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job TicketUserTicketCounterJob [41f22fc8-8779-4d09-b830-a108942ad514] from DelayedJob(default) with arguments: [5, 5] (id=76) (queue=default) RUNNING
I, [2019-08-21T20:20:35.779745 #569-47447612491140]  INFO -- : Performing TicketUserTicketCounterJob (Job ID: 41f22fc8-8779-4d09-b830-a108942ad514) from DelayedJob(default) with arguments: 5, 5
I, [2019-08-21T20:20:35.787462 #569-47447612491140]  INFO -- : Performed TicketUserTicketCounterJob (Job ID: 41f22fc8-8779-4d09-b830-a108942ad514) from DelayedJob(default) in 7.54ms
I, [2019-08-21T20:20:35.802506 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job TicketUserTicketCounterJob [41f22fc8-8779-4d09-b830-a108942ad514] from DelayedJob(default) with arguments: [5, 5] (id=76) (queue=default) COMPLETED after 0.0678
I, [2019-08-21T20:20:35.817948 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job UserDeviceLogJob [3f7aeaab-dce2-40f4-abac-4c59d50db6c5] from DelayedJob(default) with arguments: ["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:69.0) Gecko/20100101 Firefox/69.0", "192.168.23.60", 3, "2104103984", "session"] (id=77) (queue=default) RUNNING
I, [2019-08-21T20:20:35.860521 #569-47447612491140]  INFO -- : Performing UserDeviceLogJob (Job ID: 3f7aeaab-dce2-40f4-abac-4c59d50db6c5) from DelayedJob(default) with arguments: "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:69.0) Gecko/20100101 Firefox/69.0", "192.168.23.60", 3, "2104103984", "session"
I, [2019-08-21T20:20:35.892287 #569-47447612491140]  INFO -- : Performed UserDeviceLogJob (Job ID: 3f7aeaab-dce2-40f4-abac-4c59d50db6c5) from DelayedJob(default) in 31.57ms
I, [2019-08-21T20:20:35.905005 #569-47447612491140]  INFO -- : 2019-08-21T20:20:35+0200: [Worker(host:debian pid:569)] Job UserDeviceLogJob [3f7aeaab-dce2-40f4-abac-4c59d50db6c5] from DelayedJob(default) with arguments: ["Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:69.0) Gecko/20100101 Firefox/69.0", "192.168.23.60", 3, "2104103984", "session"] (id=77) (queue=default) COMPLETED after 0.0869
I, [2019-08-21T20:20:38.790956 #565-46913101285120]  INFO -- : Started GET "/" for 192.168.23.60 at 2019-08-21 20:20:38 +0200
I, [2019-08-21T20:20:38.797442 #565-46913101285120]  INFO -- : Processing by InitController#index as HTML
I, [2019-08-21T20:20:38.799081 #565-46913101285120]  INFO -- :   Rendering init/index.html.erb within layouts/application
I, [2019-08-21T20:20:38.799245 #565-46913101285120]  INFO -- :   Rendered init/index.html.erb within layouts/application (0.1ms)
I, [2019-08-21T20:20:38.802013 #565-46913101285120]  INFO -- : Completed 200 OK in 4ms (Views: 1.4ms | ActiveRecord: 0.7ms)
I, [2019-08-21T20:20:40.982417 #565-46913101285720]  INFO -- : Started POST "/api/v1/signshow" for 192.168.23.60 at 2019-08-21 20:20:40 +0200
I, [2019-08-21T20:20:40.988857 #565-46913101285720]  INFO -- : Processing by SessionsController#show as JSON
I, [2019-08-21T20:20:40.988950 #565-46913101285720]  INFO -- :   Parameters: {"fingerprint"=>"2104103984"}
I, [2019-08-21T20:20:41.325730 #565-46913101285720]  INFO -- : Completed 200 OK in 337ms (Views: 102.2ms | ActiveRecord: 27.6ms)
I, [2019-08-21T20:20:41.464068 #565-46913101286840]  INFO -- : Started GET "/api/v1/translations/lang/de-de?_=1566411717668" for 192.168.23.60 at 2019-08-21 20:20:41 +0200
I, [2019-08-21T20:20:41.473420 #565-46913101286840]  INFO -- : Processing by TranslationsController#lang as JSON
I, [2019-08-21T20:20:41.473532 #565-46913101286840]  INFO -- :   Parameters: {"_"=>"1566411717668", "locale"=>"de-de"}
I, [2019-08-21T20:20:41.621167 #565-46913101286840]  INFO -- : Completed 200 OK in 147ms (Views: 37.8ms | ActiveRecord: 2.3ms)
I, [2019-08-21T20:20:42.032781 #565-46913101285400]  INFO -- : Started GET "/api/v1/ticket_overviews?_=1566411717669" for 192.168.23.60 at 2019-08-21 20:20:42 +0200
I, [2019-08-21T20:20:42.036159 #565-46913101286340]  INFO -- : Started GET "/api/v1/ticket_overviews?view=all_open&_=1566411717670" for 192.168.23.60 at 2019-08-21 20:20:42 +0200
I, [2019-08-21T20:20:42.043341 #565-46913101286340]  INFO -- : Processing by TicketOverviewsController#show as JSON
I, [2019-08-21T20:20:42.043465 #565-46913101286340]  INFO -- :   Parameters: {"view"=>"all_open", "_"=>"1566411717670"}
I, [2019-08-21T20:20:42.045746 #565-46913101285400]  INFO -- : Processing by TicketOverviewsController#show as JSON
I, [2019-08-21T20:20:42.048424 #565-46913101285400]  INFO -- :   Parameters: {"_"=>"1566411717669"}
I, [2019-08-21T20:20:42.311970 #565-46913101285400]  INFO -- : Completed 200 OK in 263ms (Views: 0.5ms | ActiveRecord: 48.5ms)
I, [2019-08-21T20:20:42.343215 #565-46913101286340]  INFO -- : Completed 200 OK in 297ms (Views: 10.2ms | ActiveRecord: 214.5ms)
I, [2019-08-21T20:20:42.695473 #565-46913101285120]  INFO -- : Started GET "/api/v1/cti/log?_=1566411717671" for 192.168.23.60 at 2019-08-21 20:20:42 +0200
I, [2019-08-21T20:20:42.701933 #565-46913101285120]  INFO -- : Processing by CtiController#index as JSON
I, [2019-08-21T20:20:42.702037 #565-46913101285120]  INFO -- :   Parameters: {"_"=>"1566411717671"}
I, [2019-08-21T20:20:42.718358 #565-46913101285120]  INFO -- : Completed 200 OK in 16ms (Views: 0.4ms | ActiveRecord: 5.3ms)
I, [2019-08-21T20:20:43.091854 #565-46913101285720]  INFO -- : Started GET "/api/v1/first_steps?_=1566411717672" for 192.168.23.60 at 2019-08-21 20:20:43 +0200
I, [2019-08-21T20:20:43.099008 #565-46913101285720]  INFO -- : Processing by FirstStepsController#index as JSON
I, [2019-08-21T20:20:43.099154 #565-46913101285720]  INFO -- :   Parameters: {"_"=>"1566411717672"}
I, [2019-08-21T20:20:43.123570 #565-46913101285720]  INFO -- : Completed 200 OK in 24ms (Views: 0.8ms | ActiveRecord: 7.7ms)
I, [2019-08-21T20:20:44.090526 #565-46913101286840]  INFO -- : Started GET "/api/v1/text_modules/?full=true&_=1566411717673" for 192.168.23.60 at 2019-08-21 20:20:44 +0200
I, [2019-08-21T20:20:44.096945 #565-46913101286840]  INFO -- : Processing by TextModulesController#index as JSON
I, [2019-08-21T20:20:44.097037 #565-46913101286840]  INFO -- :   Parameters: {"full"=>"true", "_"=>"1566411717673"}
I, [2019-08-21T20:20:44.134948 #565-46913101286840]  INFO -- : Completed 200 OK in 38ms (Views: 14.7ms | ActiveRecord: 5.5ms)
I, [2019-08-21T20:20:44.180950 #565-46913101285400]  INFO -- : Started GET "/api/v1/ticket_customer?customer_id=4&_=1566411717674" for 192.168.23.60 at 2019-08-21 20:20:44 +0200
I, [2019-08-21T20:20:44.188129 #565-46913101285400]  INFO -- : Processing by TicketsController#ticket_customer as JSON
I, [2019-08-21T20:20:44.188255 #565-46913101285400]  INFO -- :   Parameters: {"customer_id"=>"4", "_"=>"1566411717674"}
I, [2019-08-21T20:20:44.190085 #565-46913101286340]  INFO -- : Started GET "/api/v1/tickets/3?all=true&_=1566411717675" for 192.168.23.60 at 2019-08-21 20:20:44 +0200
I, [2019-08-21T20:20:44.198384 #565-46913101286340]  INFO -- : Processing by TicketsController#show as JSON
I, [2019-08-21T20:20:44.198504 #565-46913101286340]  INFO -- :   Parameters: {"all"=>"true", "_"=>"1566411717675", "id"=>"3"}
I, [2019-08-21T20:20:44.235646 #565-46913101285400]  INFO -- : Completed 200 OK in 47ms (Views: 5.0ms | ActiveRecord: 20.8ms)
I, [2019-08-21T20:20:44.296344 #565-46913101286340]  INFO -- : Completed 200 OK in 96ms (Views: 5.5ms | ActiveRecord: 38.7ms)
I, [2019-08-21T20:20:46.149770 #565-46913101285120]  INFO -- : Started PUT "/api/v1/taskbar/4" for 192.168.23.60 at 2019-08-21 20:20:46 +0200
I, [2019-08-21T20:20:46.156475 #565-46913101285120]  INFO -- : Processing by TaskbarController#update as JSON
I, [2019-08-21T20:20:46.156620 #565-46913101285120]  INFO -- :   Parameters: {"key"=>"Ticket-3", "client_id"=>"123", "callback"=>"TicketZoom", "state"=>{"ticket"=>{}, "article"=>{"form_id"=>"410080518"}}, "params"=>{"ticket_id"=>3, "overview_id"=>4, "init"=>true}, "prio"=>2, "notify"=>false, "active"=>false, "attachments"=>[], "updated_at"=>"2019-08-21T17:55:21.889Z", "id"=>"4"}
I, [2019-08-21T20:20:46.261535 #565-46913101285120]  INFO -- : Completed 200 OK in 105ms (Views: 0.6ms | ActiveRecord: 72.3ms)
I, [2019-08-21T20:20:57.641753 #569-47447602394880]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2019-08-21T20:20:57.644221 #569-47447602394880]  INFO -- : fetching imap (imap-mail.outlook.com/RECIPIENT@O365MAIL.DE port=993,ssl=true,starttls=false,folder=ztest,keep_on_server=true)
I, [2019-08-21T20:20:58.209074 #569-47447602394880]  INFO -- :  - no message
I, [2019-08-21T20:20:58.209177 #569-47447602394880]  INFO -- : done
I, [2019-08-21T20:21:07.554042 #569-47447553000960]  INFO -- : Scheduler running...
I, [2019-08-21T20:21:07.564671 #569-47447553000960]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-08-21T20:21:07.564818 #569-47447553000960]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-08-21T20:21:07.564916 #569-47447553000960]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2019-08-21T20:21:07.565013 #569-47447553000960]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-08-21T20:21:07.565109 #569-47447553000960]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-08-21T20:21:07.565886 #569-47447553000960]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-08-21T20:21:28.286679 #569-47447602394880]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2019-08-21T20:21:28.289019 #569-47447602394880]  INFO -- : fetching imap (imap-mail.outlook.com/RECIPIENT@O365MAIL.DE port=993,ssl=true,starttls=false,folder=ztest,keep_on_server=true)
I, [2019-08-21T20:21:28.901099 #569-47447602394880]  INFO -- :  - no message
I, [2019-08-21T20:21:28.901197 #569-47447602394880]  INFO -- : done
I, [2019-08-21T20:21:57.633384 #569-47447609612600]  INFO -- : execute Ticket.process_escalation (try_count 0)...
4

A small update: Register a gmail address and 18 of 18 mails were fetched. Seems to be an issue with o365, but no idea why.

5

Dirty Workaround. Now fetching mails with pop3. works for me.

6

Thanks for the detailed feedback.
Maybe @thorsteneckel can help here (I hope that’s enough info for him :smiley: )

Altough, he’s currently on vacation, so answers might take a bit.

7

I can’t anything of value. I’d agree that it has something to do with O365 :scream:

The error you posted looks like an actual issue. However, it isn’t related to that. There seem to be messages where the signature detection fails. Would be great to know how to reproduce this.

8

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