Error fetching emails with many attachments

labforcode · May 27, 2019, 1:34pm

Infos:

Used Zammad version: 2.9.x
Used Zammad installation source: (source, package, …)
Operating system: CentOS 7
Browser + version: Firefox, version 67, x64

Expected behavior:

Fetch e-mails no mistakes.

Actual behavior:

When fetching e-mail with attachments, there is the error - “Channel: Email::Account in Can’t use Channel::Driver::Imap: #<Timeout::Error: execution expired>”

Steps to reproduce the behavior:

In tests for use of the tool, when retrieving emails with PDF attachments, there was a return of the previously mentioned error.

Emails with 25, 35, 45 and 50 attachments, with maximum size within the allowed by Gmail, I think 25MB, there was no error return mentioned.

However, when trying to perform the test with 70 PDF files attached to the email, there was a return of the error, with this, the application stopped fetching for emails.

I searched the documentation for the number of attachments in the email, but found no relevant information. I know that Zammad has the parameter “E-mail > Settings > Maximum Email Size”, which determines the maximum size in MB of emails and not the number of files attached.

In my confugurations, this parameter has its value of 150 MB and the emails that I am sending do not reach 25MB, even with the 70 attachments.

So, do you have any idea of any additional parameters about this?

MrGeneration · May 27, 2019, 11:41pm

It would be great to get known of “the error” as in “error messages” or "logfiles
Right now this is more of a crystall ballish fishing in the dark

labforcode · May 28, 2019, 12:12pm

Hi, Mr. Generation !

After checking the log production, I noticed the message mentioned above. So I looked for more information on the project and found the file imap.rb. This file contains the “FETCH_MSG_TIMEOUT = 4.minutes” statement.

Now, analyzing the written code, I changed the value from 4 to 16, restarted the Zammad service and the application downloaded the e-mail with more than 70 attachments.

I took the test, increasing to the maximum load of attached files for the GMAIL email, with 25MB, being a total of 90 files attached, the email was downloaded and the ticket generated without errors, apparently.

At this point, I read the log again and realized that with this change, the error:

“Can not use Channel :: Driver :: Imap: # <EOFError: end of file reached>”

was registered, but the emails are downloaded and the Tickets generated.

Would you have any consideration?

Sorry for not sending the log file.

labforcode · May 28, 2019, 8:01pm

I, [2019-05-28T16:07:15.816658 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:07:15.845630 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:07:17.655082 #15924-47410885812020]  INFO -- :  - message 1/1
I, [2019-05-28T16:07:24.068204 #15924-47410825834320]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-05-28T16:08:24.069988 #15924-47410825834320]  INFO -- : Scheduler running...
I, [2019-05-28T16:08:24.075655 #15924-47410825834320]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-05-28T16:08:24.075729 #15924-47410825834320]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-05-28T16:08:24.075809 #15924-47410825834320]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-05-28T16:08:24.076032 #15924-47410825834320]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-05-28T16:08:24.076080 #15924-47410825834320]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2019-05-28T16:08:24.076556 #15924-47410825834320]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-05-28T16:08:33.311457 #15924-70327073120560]  INFO -- : execute Job.run (try_count 0)...
I, [2019-05-28T16:08:53.433289 #15924-70327072085300]  INFO -- : execute Import::OTRS.diff_worker (try_count 0)...
I, [2019-05-28T16:09:24.077025 #15924-47410825834320]  INFO -- : Scheduler running...
I, [2019-05-28T16:09:24.082719 #15924-47410825834320]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-05-28T16:09:24.082792 #15924-47410825834320]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-05-28T16:09:24.082838 #15924-47410825834320]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-05-28T16:09:24.083154 #15924-47410825834320]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-05-28T16:09:24.083205 #15924-47410825834320]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2019-05-28T16:09:24.083376 #15924-47410825834320]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-05-28T16:10:24.084255 #15924-47410825834320]  INFO -- : Scheduler running...
I, [2019-05-28T16:10:24.089962 #15924-47410825834320]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-05-28T16:10:24.090071 #15924-47410825834320]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-05-28T16:10:24.090127 #15924-47410825834320]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-05-28T16:10:24.090358 #15924-47410825834320]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-05-28T16:10:24.090406 #15924-47410825834320]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2019-05-28T16:10:24.090580 #15924-70327072666680]  INFO -- : Started job thread for 'Process auto unassign tickets' (Ticket.process_auto_unassign)...
I, [2019-05-28T16:10:24.094319 #15924-70327072666680]  INFO -- : execute Ticket.process_auto_unassign (try_count 0)...
I, [2019-05-28T16:10:24.099724 #15924-70327072666680]  INFO -- :  ...stopped thread for 'Ticket.process_auto_unassign'
I, [2019-05-28T16:10:34.092518 #15924-47410825834320]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-05-28T16:10:34.094542 #15924-70327076408820]  INFO -- : Started job thread for 'Generate user based stats.' (Stats.generate)...
I, [2019-05-28T16:10:34.099921 #15924-70327076408820]  INFO -- : execute Stats.generate (try_count 0)...
I, [2019-05-28T16:10:35.044241 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: ae8b7713-c767-4e14-a268-d8868ce58260) to DelayedJob(default) with arguments: "StatsStore", 1
I, [2019-05-28T16:10:35.063720 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: 7807b295-ecbe-47bc-9955-68c8eb2ab276) to DelayedJob(default) with arguments: "StatsStore", 2
I, [2019-05-28T16:10:35.080715 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: 75455246-8731-4950-9f49-f3d071c0ceb6) to DelayedJob(default) with arguments: "StatsStore", 3
I, [2019-05-28T16:10:35.102364 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: 7b372aa2-ac5e-464e-b8aa-a1055d241094) to DelayedJob(default) with arguments: "StatsStore", 4
I, [2019-05-28T16:10:35.126502 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: b0c466b9-f8f6-4aa0-b25b-22e712370bf5) to DelayedJob(default) with arguments: "StatsStore", 5
I, [2019-05-28T16:10:35.151689 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: bc4bf179-f65a-4162-8a79-9b37a969ffea) to DelayedJob(default) with arguments: "StatsStore", 6
I, [2019-05-28T16:10:35.173299 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: 57020943-5e19-4139-9e3a-53f7b820ac2e) to DelayedJob(default) with arguments: "StatsStore", 7
I, [2019-05-28T16:10:35.194268 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: 43586576-3f61-47cb-aa02-7cd5afb7a520) to DelayedJob(default) with arguments: "StatsStore", 8
I, [2019-05-28T16:10:35.213603 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: ea81bf8d-f3f0-45e7-9656-051dbb0b0c0a) to DelayedJob(default) with arguments: "StatsStore", 9
I, [2019-05-28T16:10:35.231891 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: cfe20f03-10c2-49c0-a429-335cf87d2cd3) to DelayedJob(default) with arguments: "StatsStore", 10
I, [2019-05-28T16:10:35.263414 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: deeb1053-a8f0-44e4-b905-b670e641e18f) to DelayedJob(default) with arguments: "StatsStore", 11
I, [2019-05-28T16:10:35.287486 #15924-70327076408820]  INFO -- : Enqueued SearchIndexJob (Job ID: f393a247-579c-4fbd-b056-c7b77e29500b) to DelayedJob(default) with arguments: "StatsStore", 12
I, [2019-05-28T16:10:35.296188 #15924-70327076408820]  INFO -- :  ...stopped thread for 'Stats.generate'
I, [2019-05-28T16:10:37.336478 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4251) (queue=default) RUNNING
I, [2019-05-28T16:10:37.362263 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: ae8b7713-c767-4e14-a268-d8868ce58260) from DelayedJob(default) with arguments: "StatsStore", 1
I, [2019-05-28T16:10:37.381322 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/1?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:37.397750 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:37.397892 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: ae8b7713-c767-4e14-a268-d8868ce58260) from DelayedJob(default) in 35.51ms
I, [2019-05-28T16:10:37.401040 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4251) (queue=default) COMPLETED after 0.0645
I, [2019-05-28T16:10:37.404486 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4252) (queue=default) RUNNING
I, [2019-05-28T16:10:37.421609 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: 7807b295-ecbe-47bc-9955-68c8eb2ab276) from DelayedJob(default) with arguments: "StatsStore", 2
I, [2019-05-28T16:10:37.433076 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/2?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:37.445689 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:37.445827 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: 7807b295-ecbe-47bc-9955-68c8eb2ab276) from DelayedJob(default) in 24.11ms
I, [2019-05-28T16:10:37.448550 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4252) (queue=default) COMPLETED after 0.0440
I, [2019-05-28T16:10:37.451459 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4253) (queue=default) RUNNING
I, [2019-05-28T16:10:37.467402 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: 75455246-8731-4950-9f49-f3d071c0ceb6) from DelayedJob(default) with arguments: "StatsStore", 3
I, [2019-05-28T16:10:37.478862 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/3?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:37.489124 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:37.489249 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: 75455246-8731-4950-9f49-f3d071c0ceb6) from DelayedJob(default) in 21.75ms
I, [2019-05-28T16:10:37.492033 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4253) (queue=default) COMPLETED after 0.0405
I, [2019-05-28T16:10:37.495263 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4254) (queue=default) RUNNING
I, [2019-05-28T16:10:37.511666 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: 7b372aa2-ac5e-464e-b8aa-a1055d241094) from DelayedJob(default) with arguments: "StatsStore", 4
I, [2019-05-28T16:10:37.522967 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/4?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:37.554992 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:37.555132 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: 7b372aa2-ac5e-464e-b8aa-a1055d241094) from DelayedJob(default) in 43.38ms
I, [2019-05-28T16:10:37.558097 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4254) (queue=default) COMPLETED after 0.0628
I, [2019-05-28T16:10:37.564759 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4255) (queue=default) RUNNING
I, [2019-05-28T16:10:37.582625 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: b0c466b9-f8f6-4aa0-b25b-22e712370bf5) from DelayedJob(default) with arguments: "StatsStore", 5
I, [2019-05-28T16:10:37.608148 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/5?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:37.619892 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:37.620029 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: b0c466b9-f8f6-4aa0-b25b-22e712370bf5) from DelayedJob(default) in 37.29ms
I, [2019-05-28T16:10:37.622660 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4255) (queue=default) COMPLETED after 0.0578
I, [2019-05-28T16:10:37.626357 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4256) (queue=default) RUNNING
I, [2019-05-28T16:10:37.649677 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: bc4bf179-f65a-4162-8a79-9b37a969ffea) from DelayedJob(default) with arguments: "StatsStore", 6
I, [2019-05-28T16:10:37.665257 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/6?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:37.676308 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:37.676439 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: bc4bf179-f65a-4162-8a79-9b37a969ffea) from DelayedJob(default) in 26.65ms
I, [2019-05-28T16:10:37.679281 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4256) (queue=default) COMPLETED after 0.0528
I, [2019-05-28T16:10:37.683032 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4257) (queue=default) RUNNING
I, [2019-05-28T16:10:37.828562 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: 57020943-5e19-4139-9e3a-53f7b820ac2e) from DelayedJob(default) with arguments: "StatsStore", 7
I, [2019-05-28T16:10:37.856990 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/7?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:37.900273 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:37.900399 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: 57020943-5e19-4139-9e3a-53f7b820ac2e) from DelayedJob(default) in 71.72ms
I, [2019-05-28T16:10:37.906712 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4257) (queue=default) COMPLETED after 0.2236
I, [2019-05-28T16:10:37.912807 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:37-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4258) (queue=default) RUNNING
I, [2019-05-28T16:10:37.951982 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: 43586576-3f61-47cb-aa02-7cd5afb7a520) from DelayedJob(default) with arguments: "StatsStore", 8
I, [2019-05-28T16:10:37.973656 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/8?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:38.058614 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:38.058757 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: 43586576-3f61-47cb-aa02-7cd5afb7a520) from DelayedJob(default) in 106.67ms
I, [2019-05-28T16:10:38.080948 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4258) (queue=default) COMPLETED after 0.1680
I, [2019-05-28T16:10:38.104902 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4259) (queue=default) RUNNING
I, [2019-05-28T16:10:38.120784 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: ea81bf8d-f3f0-45e7-9656-051dbb0b0c0a) from DelayedJob(default) with arguments: "StatsStore", 9
I, [2019-05-28T16:10:38.230098 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/9?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:38.240150 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:38.240266 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: ea81bf8d-f3f0-45e7-9656-051dbb0b0c0a) from DelayedJob(default) in 119.39ms
I, [2019-05-28T16:10:38.243142 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4259) (queue=default) COMPLETED after 0.1382
I, [2019-05-28T16:10:38.246046 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4260) (queue=default) RUNNING
I, [2019-05-28T16:10:38.262105 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: cfe20f03-10c2-49c0-a429-335cf87d2cd3) from DelayedJob(default) with arguments: "StatsStore", 10
I, [2019-05-28T16:10:38.273740 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/10?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:38.282958 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:38.283088 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: cfe20f03-10c2-49c0-a429-335cf87d2cd3) from DelayedJob(default) in 20.88ms
I, [2019-05-28T16:10:38.285955 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4260) (queue=default) COMPLETED after 0.0398
I, [2019-05-28T16:10:38.288955 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4261) (queue=default) RUNNING
I, [2019-05-28T16:10:38.305535 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: deeb1053-a8f0-44e4-b905-b670e641e18f) from DelayedJob(default) with arguments: "StatsStore", 11
I, [2019-05-28T16:10:38.317751 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/11?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:38.368250 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:38.368496 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: deeb1053-a8f0-44e4-b905-b670e641e18f) from DelayedJob(default) in 62.85ms
I, [2019-05-28T16:10:38.371596 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4261) (queue=default) COMPLETED after 0.0825
I, [2019-05-28T16:10:38.395492 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4262) (queue=default) RUNNING
I, [2019-05-28T16:10:38.418045 #15924-47410885863400]  INFO -- : Performing SearchIndexJob (Job ID: f393a247-579c-4fbd-b056-c7b77e29500b) from DelayedJob(default) with arguments: "StatsStore", 12
I, [2019-05-28T16:10:38.451892 #15924-47410885863400]  INFO -- : # curl -X POST "http://127.0.0.1:9200/zammad_production/StatsStore/12?pipeline=zammad230149442451" \
I, [2019-05-28T16:10:38.506026 #15924-47410885863400]  INFO -- : # 200
I, [2019-05-28T16:10:38.506158 #15924-47410885863400]  INFO -- : Performed SearchIndexJob (Job ID: f393a247-579c-4fbd-b056-c7b77e29500b) from DelayedJob(default) in 88.0ms
I, [2019-05-28T16:10:38.513782 #15924-47410885863400]  INFO -- : 2019-05-28T16:10:38-0300: [Worker(host:zammad.localdomain pid:15924)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=4262) (queue=default) COMPLETED after 0.1182
I, [2019-05-28T16:10:43.175999 #15924-47410888270000]  INFO -- : execute Ticket.process_escalation (try_count 0)...
E, [2019-05-28T16:11:19.675993 #15924-47410885812020] ERROR -- : Unable to fetch email from 1/1 from server (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br): #<Timeout::Error: execution expired>
E, [2019-05-28T16:11:19.676104 #15924-47410885812020] ERROR -- : Can't use Channel::Driver::Imap: #<Timeout::Error: execution expired>
E, [2019-05-28T16:11:19.676134 #15924-47410885812020] ERROR -- : execution expired (Timeout::Error)
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:111:in `sleep'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:111:in `wait'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/net/imap.rb:1189:in `get_tagged_response'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/net/imap.rb:1248:in `block in send_command'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/net/imap.rb:1230:in `send_command'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/net/imap.rb:1399:in `block in fetch_internal'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/net/imap.rb:1397:in `fetch_internal'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/net/imap.rb:811:in `fetch'
/opt/zammad/app/models/channel/driver/imap.rb:239:in `block (2 levels) in fetch'
/opt/zammad/app/models/channel/driver/imap.rb:401:in `block in timeout'
/opt/zammad/vendor/ruby-2.4.4/lib/ruby/2.4.0/timeout.rb:108:in `timeout'
/opt/zammad/app/models/channel/driver/imap.rb:400:in `timeout'
/opt/zammad/app/models/channel/driver/imap.rb:238:in `block in fetch'
/opt/zammad/app/models/channel/driver/imap.rb:210:in `each'
/opt/zammad/app/models/channel/driver/imap.rb:210:in `fetch'
/opt/zammad/app/models/channel.rb:56:in `fetch'
/opt/zammad/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.6.2/lib/active_record/relation/delegation.rb:39:in `each'
/opt/zammad/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.6.2/lib/active_record/relation/delegation.rb:39: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'
/opt/zammad/vendor/bundle/ruby/2.4.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
I, [2019-05-28T16:11:44.095890 #15924-47410825834320]  INFO -- : Scheduler running...
I, [2019-05-28T16:11:44.102072 #15924-47410825834320]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-05-28T16:11:44.102304 #15924-47410825834320]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-05-28T16:11:44.102441 #15924-47410825834320]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-05-28T16:11:44.102568 #15924-47410825834320]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-05-28T16:11:44.102619 #15924-47410825834320]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2019-05-28T16:11:44.102842 #15924-47410825834320]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-05-28T16:11:49.702512 #15924-47410885812020]  INFO -- : execute Channel.fetch (try_count 0)...
I, [2019-05-28T16:11:49.704129 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:11:52.605667 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:11:52.605735 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:11:52.621214 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:11:53.445982 #15924-70327072085300]  INFO -- : execute Import::OTRS.diff_worker (try_count 0)...
I, [2019-05-28T16:11:54.483394 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:11:54.483454 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:11:54.499485 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:11:56.398049 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:11:56.398115 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:11:56.414345 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:11:59.544382 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:11:59.544591 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:11:59.564508 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:01.409660 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:12:01.409738 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:12:01.425025 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:03.245834 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:12:03.245896 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:12:03.261795 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:05.080199 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:12:05.080289 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:12:05.095182 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:06.909327 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:12:06.909388 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:12:06.924315 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:08.766240 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:12:08.766316 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:12:08.781339 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:10.658964 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:12:10.659029 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:12:10.675275 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:12.500691 #15924-47410885812020]  INFO -- :  - no message
I, [2019-05-28T16:12:12.500752 #15924-47410885812020]  INFO -- : done
I, [2019-05-28T16:12:12.516160 #15924-47410885812020]  INFO -- : fetching imap (imap.xxxxxxx.com.br/xxx@xxxxxxxx.com.br port=143,ssl=false,starttls=false,folder=INBOX,keep_on_server=true)
I, [2019-05-28T16:12:14.354196 #15924-47410885812020]  INFO -- :  - message 1/1
I, [2019-05-28T16:12:44.104481 #15924-47410825834320]  INFO -- : Scheduler running...
I, [2019-05-28T16:12:44.114764 #15924-47410825834320]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-05-28T16:12:44.114879 #15924-47410825834320]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-05-28T16:12:44.114927 #15924-47410825834320]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-05-28T16:12:44.115097 #15924-47410825834320]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-05-28T16:12:44.115149 #15924-47410825834320]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2019-05-28T16:12:44.115194 #15924-47410825834320]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-05-28T16:13:33.320284 #15924-70327073120560]  INFO -- : execute Job.run (try_count 0)...
I, [2019-05-28T16:13:44.116843 #15924-47410825834320]  INFO -- : Scheduler running...
I, [2019-05-28T16:13:44.123480 #15924-47410825834320]  INFO -- : Running job thread for 'Process escalation tickets' (Ticket.process_escalation) status is: sleep
I, [2019-05-28T16:13:44.123550 #15924-47410825834320]  INFO -- : Running job thread for 'Check Channels' (Channel.fetch) status is: sleep
I, [2019-05-28T16:13:44.123621 #15924-47410825834320]  INFO -- : Running job thread for 'Import OTRS diff load' (Import::OTRS.diff_worker) status is: sleep
I, [2019-05-28T16:13:44.123825 #15924-47410825834320]  INFO -- : Running job thread for 'Check streams for Channel' (Channel.stream) status is: sleep
I, [2019-05-28T16:13:44.123870 #15924-47410825834320]  INFO -- : Running job thread for 'Generate Session data' (Sessions.jobs) status is: sleep
I, [2019-05-28T16:13:44.124149 #15924-47410825834320]  INFO -- : Running job thread for 'Execute jobs' (Job.run) status is: sleep
I, [2019-05-28T16:14:21.747963 #15924-47410825834320]  INFO -- : Scheduler stopped.

MrGeneration · May 30, 2019, 5:04pm

I think that timeout if intentional. Not sure how comon so many attachments within one system.
But anyway, I think @thorsteneckel can give better Feedback on this (if he finds some spare time )

thorsteneckel · June 3, 2019, 6:56am

That indicates a syntax error. Please understand that we can’t give support for custom changes.

labforcode · June 3, 2019, 5:33pm

Thank you for your help

system · October 1, 2019, 5:46pm

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