Zammad runs into timeout then stops fetching new mails

itkfm · November 27, 2024, 1:16pm

Infos:

Used Zammad version: 6.4.0-1731337700.f66ab5c6.bookworm
Used Zammad installation type: package
Operating system: Debian 12
Browser + version: Google Chrome 131, Firefox 132

Expected behavior:

Zammad continuously fetches incoming mail.

Actual behavior:

Zammad log that it can’t process an email.
Then stops processing incoming mail at all.

Steps to reproduce the behavior:

No idea yet.

Logs

Too long. See follow up messages.

Workaround

Manually run Channel.fetch in the rails console.
- Some of them took a few seconds to process.
  - What’s Zammad’s timeout?
  - Can I manually increase it? (Is it the timeout from database.yml?)
Then restarting Zammad brings the mail processing back up.

itkfm · November 27, 2024, 1:19pm

`$ grep imap /var/log/zammad/production.log`

System is happily processing various mailboxes (names redacted), then runs into an issue and imap is no further mentioned in the log anywhere after that.

I, [2024-11-27T10:03:42.465718#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:03:43.011687#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:04:13.458394#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:13.963448#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:14.823816#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:15.633012#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:04:15.929998#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:16.702893#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:18.621580#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:27.505156#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:28.217027#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:04:58.593819#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:04:59.022685#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:05:00.024228#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:00.662919#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:01.673025#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:20.115491#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:21.508616#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:22.811652#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:05:23.301692#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:54.355834#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:56.187792#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:57.027608#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:05:58.499745#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:58.989603#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:05:59.414743#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:00.241904#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:01.416741#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:06:02.115898#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:33.335209#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:34.774877#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:36.012087#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:06:36.765997#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:37.553190#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:38.771762#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:40.357239#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:06:41.465090#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:06:42.747062#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:13.653400#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:15.273539#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:16.292726#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:18.125715#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:07:18.588970#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:31.776272#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:34.101802#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:35.612736#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:07:38.546211#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:08:10.008519#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:08:12.516232#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:08:14.932284#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:08:17.266770#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:08:20.049328#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:08:22.209032#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:08:23.129144#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:08:25.112809#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:08:27.226466#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:08:58.415771#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:09:01.273490#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:09:04.115967#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:09:05.918272#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:09:08.123985#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:09:53.192109#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:09:56.124132#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:09:59.254341#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:10:01.956531#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:10:37.150204#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:10:39.381005#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:10:41.242853#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:10:43.903674#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:10:47.079018#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:11:28.219441#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:11:31.328142#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:11:35.610939#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:11:38.520684#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:12:12.574411#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:12:15.486804#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:12:19.049969#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:12:22.964155#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:12:26.433888#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:12:29.969458#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:12:33.467098#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:12:36.829584#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:12:38.027793#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:13:11.313102#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:13:14.873825#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:13:19.390857#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:13:22.470167#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:13:26.391094#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:13:29.452109#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:13:32.701365#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:13:35.936599#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:13:39.431547#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:13.432419#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:17.251138#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:20.943857#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:25.460480#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:14:28.957413#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:32.800367#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:40.116284#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:43.914403#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:14:52.232626#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:15:27.459567#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:15:31.406385#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:15:35.231064#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:15:38.684942#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:15:42.162045#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:20:20.753253#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:20:29.912100#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:23:04.332735#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/office@sister-company.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:23:09.902900#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.org port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:23:50.729606#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@company.tld port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=true,auth_type=LOGIN)
I, [2024-11-27T10:26:28.573709#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:26:38.169222#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:26:45.651000#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:26:51.201160#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:32:15.149920#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:32:25.105085#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'

itkfm · November 27, 2024, 1:19pm

`grep -B 10 -A 25 imap /var/log/zammad/production.log`

Through this command we find out where the actual error happens.
We’ll look at this further.

E, [2024-11-27T10:41:55.940786#1074230-180020] ERROR -- : Can't process email. Run the following command to get the message for issue report at https://github.com/zammad/zammad/issues:
  zammad run rails r "puts FailedEmail.find(114).data"
E, [2024-11-27T10:41:55.953825#1074230-180020] ERROR -- : execution expired (Timeout::Error)
app/models/channel/email_parser.rb:151:in `process_with_timeout'
app/models/channel/email_parser.rb:131:in `process'
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'
app/models/channel.rb:64:in `fetch'
app/models/channel.rb:36:in `fetch'

itkfm · November 27, 2024, 1:20pm

`grep '#1074230-180020' -B 25 -A 25 /var/log/zammad/production.log`

Mailboxes and triggers (they contain mailbox + department names) redacted.
I’ve also filtered this log to remove unrelated messages next to the grep matches.

I, [2024-11-27T10:23:55.877031#1074230-180020]  INFO -- :  - message 1/1
--
I, [2024-11-27T10:23:56.612335#1074230-180020]  INFO -- : Process email with msgid '<d45d321ff87c7bd6d7aef187250b64f3@client1.tld>'
--
I, [2024-11-27T10:24:10.824358#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=50610
--
I, [2024-11-27T10:24:12.756812#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
--
I, [2024-11-27T10:24:27.911266#1074230-180020]  INFO -- : Execute trigger (mb1@example.com: auto reply (on new tickets)/32) for this object (Ticket:281095/Loop:1)
I, [2024-11-27T10:24:35.559937#1074230-180020]  INFO -- : Execute trigger (service@sister-company.example.com - Notiz/38) for this object (Ticket:281095/Loop:1)
--
I, [2024-11-27T10:25:04.832677#1074230-180020]  INFO -- : Do not execute recursive triggers per default until Zammad 3.0. With Zammad 3.0 and higher the following trigger is executed 'service@sister-company.example.com - Notiz' on Ticket:281095. Please review your current triggers and change them if needed.
--
I, [2024-11-27T10:26:28.573709#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb3@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
--
I, [2024-11-27T10:26:34.392228#1074230-180020]  INFO -- :  - no message
--
I, [2024-11-27T10:26:38.169222#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.test port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
--
I, [2024-11-27T10:26:44.760731#1074230-180020]  INFO -- :  - no message
I, [2024-11-27T10:26:44.783134#1074230-487080]  INFO -- : ended Stats.generate took: 219.727089582 seconds.
--
I, [2024-11-27T10:26:45.651000#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/main@holding.example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
--
I, [2024-11-27T10:26:50.317494#1074230-180020]  INFO -- :  - no message
--
I, [2024-11-27T10:26:51.201160#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb1@example.com port=993,ssl=true,starttls=false,folder=INBOX/Zammad,keep_on_server=false,auth_type=LOGIN)
--
I, [2024-11-27T10:26:55.472726#1074230-180020]  INFO -- :  - message 1/2
--
I, [2024-11-27T10:26:56.824959#1074230-180020]  INFO -- : Process email with msgid '<68718820.1db40ac.afb7df1.5a86@client2.tld>'
--
I, [2024-11-27T10:27:16.303995#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=50611
--
I, [2024-11-27T10:27:22.225704#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
--
I, [2024-11-27T10:27:38.190828#1074230-180020]  INFO -- : Execute trigger (External Software Support Agent (Service Company TypE)/93) for this object (Ticket:281096/Loop:1)
I, [2024-11-27T10:27:38.261624#1074230-180020]  INFO -- : NOTICE create - self.created_by_id is different: 50611/1
--
I, [2024-11-27T10:27:55.307918#1074230-180020]  INFO -- : Execute trigger (mb1@example.com - Notiz/34) for this object (Ticket:281096/Loop:1)
--
I, [2024-11-27T10:28:46.337342#1074230-180020]  INFO -- : Do not execute recursive triggers per default until Zammad 3.0. With Zammad 3.0 and higher the following trigger is executed 'mb1@example.com - Notiz' on Ticket:281096. Please review your current triggers and change them if needed.
--
I, [2024-11-27T10:29:21.994053#1074230-180020]  INFO -- :  - message 2/2
I, [2024-11-27T10:29:26.947786#1074230-180020]  INFO -- : Process email with msgid '<ec1c9edca2af716dbc4941073ce57d36@example.com>'
I, [2024-11-27T10:29:31.805230#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=50
I, [2024-11-27T10:29:36.252726#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-sender found Agent
I, [2024-11-27T10:29:36.261798#1074230-180020]  INFO -- : set_attributes_by_x_headers found Ticket::Article::Sender lookup for 'Agent'
I, [2024-11-27T10:29:36.268987#1074230-180020]  INFO -- : set_attributes_by_x_headers assign Ticket::Article sender_id=1
I, [2024-11-27T10:29:36.269113#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
--
I, [2024-11-27T10:30:01.648077#1074230-180020]  INFO -- : Execute trigger (mb1@example.com - Notiz/34) for this object (Ticket:281097/Loop:1)
--
I, [2024-11-27T10:30:40.536971#1074230-180020]  INFO -- : Do not execute recursive triggers per default until Zammad 3.0. With Zammad 3.0 and higher the following trigger is executed 'mb1@example.com - Notiz' on Ticket:281097. Please review your current triggers and change them if needed.
--
I, [2024-11-27T10:32:15.149920#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/service@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:32:24.261930#1074230-180020]  INFO -- :  - no message
I, [2024-11-27T10:32:25.105085#1074230-180020]  INFO -- : fetching imap (imap.mailbox.org/mb2@example.com port=993,ssl=true,starttls=false,folder=INBOX,keep_on_server=false,auth_type=LOGIN)
I, [2024-11-27T10:32:28.875796#1074230-191760]  INFO -- : execute Job.run (try_count 0)...
I, [2024-11-27T10:32:32.765799#1074230-180020]  INFO -- :  - message 1/4
I, [2024-11-27T10:32:37.405670#1074230-180020]  INFO -- : Process email with msgid '<6746e4d0ac496_280ac2183e433362@client4.tld>'
--
I, [2024-11-27T10:32:40.417100#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=28589
--
I, [2024-11-27T10:32:46.347006#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
--
I, [2024-11-27T10:33:04.930132#1074230-180020]  INFO -- : Execute trigger (mb2: auto reply (on new tickets)/1) for this object (Ticket:281098/Loop:1)
--
E, [2024-11-27T10:35:37.796895#1074230-180020] ERROR -- : Can't process email. Run the following command to get the message for issue report at https://github.com/zammad/zammad/issues:
  zammad run rails r "puts FailedEmail.find(112).data"
E, [2024-11-27T10:35:37.796963#1074230-180020] ERROR -- : execution expired (Timeout::Error)
app/models/channel/email_parser.rb:151:in `process_with_timeout'
app/models/channel/email_parser.rb:131:in `process'
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'
app/models/channel.rb:64:in `fetch'
app/models/channel.rb:36:in `fetch'
(eval):1:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:23:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:16:in `block in run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `times'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:8:in `run'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:10:in `run'
lib/background_services/service/process_scheduled_jobs/manager.rb:84:in `block in start_in_thread'
lib/application_handle_info.rb:19:in `use'
lib/background_services/service/process_scheduled_jobs/manager.rb:82:in `start_in_thread'
lib/background_services/service/process_scheduled_jobs/manager.rb:73:in `block (2 levels) in start'
lib/background_services/service/process_scheduled_jobs/manager.rb:72:in `block in start'
I, [2024-11-27T10:35:37.863460#1074230-180020]  INFO -- :  - message 2/4
I, [2024-11-27T10:35:42.802481#1074230-180020]  INFO -- : Process email with msgid '<79e4cab148668d291ba79766169c0415@example.com>'
I, [2024-11-27T10:35:45.747281#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=6
--
I, [2024-11-27T10:35:55.202680#1074230-499400]  INFO -- : ended Ticket.process_auto_unassign took: 6.322070886 seconds.
I, [2024-11-27T10:35:55.337762#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-sender found Agent
I, [2024-11-27T10:35:55.349654#1074230-180020]  INFO -- : set_attributes_by_x_headers found Ticket::Article::Sender lookup for 'Agent'
I, [2024-11-27T10:35:56.044152#1074230-180020]  INFO -- : set_attributes_by_x_headers assign Ticket::Article sender_id=1
--
I, [2024-11-27T10:35:56.753135#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
--
E, [2024-11-27T10:38:45.195782#1074230-180020] ERROR -- : Failed enqueuing TicketUserTicketCounterJob to DelayedJob(default): Timeout::ExitException (execution expired)
E, [2024-11-27T10:38:51.415731#1074230-180020] ERROR -- : Can't process email. Run the following command to get the message for issue report at https://github.com/zammad/zammad/issues:
  zammad run rails r "puts FailedEmail.find(113).data"
E, [2024-11-27T10:38:51.415796#1074230-180020] ERROR -- : execution expired (Timeout::Error)
app/models/channel/email_parser.rb:151:in `process_with_timeout'
app/models/channel/email_parser.rb:131:in `process'
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'
app/models/channel.rb:64:in `fetch'
app/models/channel.rb:36:in `fetch'
(eval):1:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:23:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:16:in `block in run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `times'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:8:in `run'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:10:in `run'
lib/background_services/service/process_scheduled_jobs/manager.rb:84:in `block in start_in_thread'
lib/application_handle_info.rb:19:in `use'
lib/background_services/service/process_scheduled_jobs/manager.rb:82:in `start_in_thread'
lib/background_services/service/process_scheduled_jobs/manager.rb:73:in `block (2 levels) in start'
lib/background_services/service/process_scheduled_jobs/manager.rb:72:in `block in start'
--
I, [2024-11-27T10:38:53.084618#1074230-180020]  INFO -- :  - message 3/4
--
I, [2024-11-27T10:38:58.428833#1074230-180020]  INFO -- : Process email with msgid '<1850cf41-a5b8-42de-9cdf-073c7b4a8aad@client3.tld'
--
I, [2024-11-27T10:39:00.499220#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=8991
--
I, [2024-11-27T10:39:06.586762#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
--
I, [2024-11-27T10:39:27.691220#1074230-180020]  INFO -- : Execute trigger (mb2: auto reply (on new tickets)/1) for this object (Ticket:281100/Loop:1)
--
I, [2024-11-27T10:40:17.562186#1074230-180020]  INFO -- : Execute trigger (STEX: Rechnung bezahlt/11) for this object (Ticket:281100/Loop:1)
--
E, [2024-11-27T10:41:55.940786#1074230-180020] ERROR -- : Can't process email. Run the following command to get the message for issue report at https://github.com/zammad/zammad/issues:
  zammad run rails r "puts FailedEmail.find(114).data"
E, [2024-11-27T10:41:55.953825#1074230-180020] ERROR -- : execution expired (Timeout::Error)
app/models/channel/email_parser.rb:151:in `process_with_timeout'
app/models/channel/email_parser.rb:131:in `process'
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'
app/models/channel.rb:64:in `fetch'
app/models/channel.rb:36:in `fetch'
(eval):1:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:23:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:16:in `block in run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `times'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:8:in `run'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:10:in `run'
lib/background_services/service/process_scheduled_jobs/manager.rb:84:in `block in start_in_thread'
lib/application_handle_info.rb:19:in `use'
lib/background_services/service/process_scheduled_jobs/manager.rb:82:in `start_in_thread'
lib/background_services/service/process_scheduled_jobs/manager.rb:73:in `block (2 levels) in start'
lib/background_services/service/process_scheduled_jobs/manager.rb:72:in `block in start'
I, [2024-11-27T10:41:56.053743#1074230-180020]  INFO -- :  - message 4/4
--
I, [2024-11-27T10:42:14.903151#1074230-180020]  INFO -- : Process email with msgid '<BEUP281MB3528F7CAF7440A1F77B8731CDE282@CLIENT4.tld>'
I, [2024-11-27T10:42:17.020027#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-ticket-customer_id found. Assign customer_id=9348
I, [2024-11-27T10:42:22.929867#1074230-180020]  INFO -- : set_attributes_by_x_headers header x-zammad-article-preferences found. Assign preferences={"send-auto-response"=>true, "is-auto-response"=>false}
--
I, [2024-11-27T10:42:50.921149#1074230-180020]  INFO -- : Execute trigger (mb2: auto reply (on new tickets)/1) for this object (Ticket:281101/Loop:1)

itkfm · November 27, 2024, 1:20pm

Unprocessable email?

“Hey, Zammad says, there’s unprocessable mail to report.” – Well…
The unprocessable mails aren’t faulty at all. They are just unprocessable because of whatever went wrong and lead to the timeout. I can just export and import them to have them processed as-is.

# zammad run rake zammad:email_parser:failed_email:export_all
3 failed email(s) exported:
  /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/112.eml
  /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/113.eml
  /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/114.eml
Done.

# zammad run rake zammad:email_parser:failed_email:import /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/
3 file(s) imported and successfully reprocessed:
  /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/112.eml
  /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/113.eml
  /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/114.eml
Deleting directory /opt/zammad/tmp/failed-email-f81c1ade-0732-46df-b7c2-7baf54aad29e/.
Done.

itkfm · November 27, 2024, 1:21pm

Database connections

Not sure whether relevant as I’m not sure what causes the timeout.

`grep max_connections /etc/postgresql/15/main/postgresql.conf`

max_connections = 4000			# (change requires restart)

`cat /opt/zammad/config/database.yml`

production:
  adapter: postgresql
  database: zammad
  pool: 75
  timeout: 5000
  encoding: utf8
  username: <REDACTED>
  password: <REDACTED>

MrGeneration · November 27, 2024, 3:05pm

Can you please provide the complete traceback when the timeout occurs? It looks cut down drastically which is an issue if you want someone to check where it actually dies.

itkfm · November 27, 2024, 3:14pm

Zammad runs into timeout then stops fetching new mails - #4 by itkfm should have the full trace.

E, [2024-11-27T10:41:55.940786#1074230-180020] ERROR -- : Can't process email. Run the following command to get the message for issue report at https://github.com/zammad/zammad/issues:
  zammad run rails r "puts FailedEmail.find(114).data"
E, [2024-11-27T10:41:55.953825#1074230-180020] ERROR -- : execution expired (Timeout::Error)
app/models/channel/email_parser.rb:151:in `process_with_timeout'
app/models/channel/email_parser.rb:131:in `process'
app/models/channel/driver/imap.rb:359:in `block in fetch'
app/models/channel/driver/imap.rb:295:in `each'
app/models/channel/driver/imap.rb:295:in `fetch'
app/models/channel.rb:64:in `fetch'
app/models/channel.rb:36:in `fetch'
(eval):1:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:23:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:16:in `block in run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `times'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:8:in `run'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:10:in `run'
lib/background_services/service/process_scheduled_jobs/manager.rb:84:in `block in start_in_thread'
lib/application_handle_info.rb:19:in `use'
lib/background_services/service/process_scheduled_jobs/manager.rb:82:in `start_in_thread'
lib/background_services/service/process_scheduled_jobs/manager.rb:73:in `block (2 levels) in start'
lib/background_services/service/process_scheduled_jobs/manager.rb:72:in `block in start'
I, [2024-11-27T10:41:56.053743#1074230-180020]  INFO -- :  - message 4/4

Is there anything missing here? (If so, just let me know and I’ll dive into the log file again.)

TRNoelli · November 27, 2024, 4:23pm

I think we have a similar issue since some weeks.
Everyday we have unprocessed E-Mails but after running the following commands everything is processed.

We have added some measures against it, mainly regarding performance / Ressources and i will add them tomorrow, together with logs, traces and systeminfo.

zammad run rake zammad:email_parser:failed_email:export_all
6 failed email(s) exported:
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/101.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/102.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/103.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/104.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/105.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/106.eml
Done.
 ~ $ zammad run rake zammad:email_parser:failed_email:import /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/
libpng warning: iCCP: cHRM chunk does not match sRGB
6 file(s) imported and successfully reprocessed:
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/102.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/103.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/106.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/101.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/104.eml
  /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/105.eml
Deleting directory /opt/zammad/tmp/failed-email-43367145-1d71-4ee7-b960-8495f9ebbbf2/.
Done.

TRNoelli · November 28, 2024, 10:52am

Okay, so here is the promised additional info.

OS: Ubuntu 22.04.5 LTS
Install-Method: Package-Manager
Elasticsearch: yes, Version 7.17.25
Zammad Version: 6.3.1-1730874676.5c5b5fba.jammy
Database: postgresql-14

Ressources:

vCPUs: 8
RAM: 12GB
Swap: 2GB
HDD-1: 120GB
HDD-2: 110GB (Backup)

Zammad Infos about our installation size, what are recommendations for such a installation?:

Overview.count → 68
User.count → 31459
Ticket.count → 94134
Organization.count → 17

Attached is a Log about the unprocessable mails and some Utilization Stats.
Later i got some Database Errors - also attached.

Performance Optimization from the zammad Documentation is in place - Postgres Connection Pool is also 2000.
In addition swappiness was reduced to 1 - because we had issues with elasticsearch on another instance.


E, [2024-11-28T10:27:10.173831#409300-151520] ERROR -- : Can't process email. Run the following command to get the message for issue report at https://github.com/zammad/zammad/issues:
  zammad run rails r "puts FailedEmail.find(107).data"
E, [2024-11-28T10:27:10.173903#409300-151520] ERROR -- : execution expired (Timeout::Error)
app/models/channel/email_parser.rb:141:in `process_with_timeout'
app/models/channel/email_parser.rb:121:in `process'
app/models/channel/driver/imap.rb:323:in `block in fetch'
app/models/channel/driver/imap.rb:259:in `each'
app/models/channel/driver/imap.rb:259:in `fetch'
app/models/channel.rb:62:in `fetch'
app/models/channel.rb:36:in `fetch'
(eval):1:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:48:in `eval_job_method'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:23:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:16:in `block in run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `times'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:15:in `run_loop'
lib/background_services/service/process_scheduled_jobs/job_executor/continuous.rb:8:in `run'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:10:in `run'
lib/background_services/service/process_scheduled_jobs/manager.rb:84:in `block in start_in_thread'
lib/application_handle_info.rb:19:in `use'
lib/background_services/service/process_scheduled_jobs/manager.rb:82:in `start_in_thread'
lib/background_services/service/process_scheduled_jobs/manager.rb:73:in `block (2 levels) in start'
lib/background_services/service/process_scheduled_jobs/manager.rb:72:in `block in start'
I, [2024-11-28T10:27:13.748151#409300-149120]  INFO -- : ProcessScheduledJobs running...
I, [2024-11-28T10:27:16.333077#409300-149120]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2024-11-28T10:27:16.333155#409300-149120]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2024-11-28T10:27:16.333238#409300-149120]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2024-11-28T10:27:16.333317#409300-149120]  INFO -- : Running job thread for 'Process pending tickets.' (Ticket.process_pending) status is: sleep
I, [2024-11-28T10:27:16.333352#409300-149120]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2024-11-28T10:27:16.333972#409300-149120]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
I, [2024-11-28T10:27:16.334051#409300-149120]  INFO -- : Running job thread for 'Generate user-based stats.' (Stats.generate) status is: sleep

Log about the Database Pool:

E, [2024-11-28T11:31:08.574680#409300-83681780] ERROR -- : execute Stats.generate (try_count 0) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.304 seconds); all pooled connections were in use> in: 5.303887681 seconds.

Monitoring:

Do you need something else?
Is this related or shall i move it into another Thread?

TRNoelli · November 28, 2024, 12:10pm

There is another Symptom, zammad-worker-1 was restarted, i think this could be because he runs out of memory. But why is this worker using so much memory?

Again the Error with the Database Connections, i will try and monitor the current database connections from Postgres.

E, [2024-11-28T11:42:32.110951#409300-83808820] ERROR -- : execute Chat.cleanup_close (try_count 2) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 6.715 seconds); all pooled connections were in use> in: 6.71570331 seconds.
E, [2024-11-28T11:42:32.111308#409300-83759900] ERROR -- : thread_client 844660 exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 6.679 seconds); all pooled connections were in use>
E, [2024-11-28T11:42:32.111527#409300-83759900] ERROR -- : /opt/zammad/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.8.5/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:126:in `block in wait_poll'

Monitoring:

MrGeneration · November 28, 2024, 12:22pm

TRNoelli:

E, [2024-11-28T11:42:32.111308#409300-83759900] ERROR -- : thread_client 844660 exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 6.679 seconds); all pooled connections were in use>

You may want to configure your database server to our recommendation:
https://docs.zammad.org/en/latest/appendix/configure-database-server.html

TRNoelli · November 28, 2024, 12:38pm

Thanks for your response.
IMHO i have done all of the recommendations, or am i missing something?

postgres=# SHOW ALL ;

max_connections                        | 2000                                    | Sets the maximum number of concurrent connections.
shared_buffers                         | 2GB                                     | Sets the number of shared memory buffers used by the server.
temp_buffers                           | 256MB                                   | Sets the maximum number of temporary buffers used by each session.
work_mem                               | 10MB                                    | Sets the maximum memory to be used for query workspaces.
max_stack_depth                        | 5MB                                     | Sets the maximum stack depth, in kilobytes.

MrGeneration · November 28, 2024, 12:53pm

Maybe a restart as Zammad clearly complains about connections being “used up”

TRNoelli · December 2, 2024, 3:52pm

Hey there,

i restarted the instance on Thursday, Friday looked promising.
But today there are again unprocessable Mails.

Errors show again something with Pooled Connections:

E, [2024-12-02T16:07:45.748391#855-400154280] ERROR -- : thread_client 324020 exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.021 seconds); all pooled connections were in use>
E, [2024-12-02T16:07:45.766424#855-400154280] ERROR -- : /opt/zammad/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.8.5/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:126:in `block in wait_poll'
E, [2024-12-02T16:07:45.771467#855-400170780] ERROR -- : Can't reconnect to database #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.017 seconds); all pooled connections were in use>
E, [2024-12-02T16:07:45.771706#855-400150240] ERROR -- : thread_client 323800 exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.017 seconds); all pooled connections were in use>
E, [2024-12-02T16:07:45.818594#855-400150240] ERROR -- : /opt/zammad/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.8.5/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:126:in `block in wait_poll'
E, [2024-12-02T16:07:45.764175#855-400165720] ERROR -- : execute ExternalCredential::Exchange.refresh_token (try_count 1) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.021 seconds); all pooled connections were in use> in: 5.021211833 seconds.
E, [2024-12-02T16:07:45.771883#855-400165040] ERROR -- : thread_client 324460 exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.017 seconds); all pooled connections were in use>
E, [2024-12-02T16:07:45.893552#855-400165040] ERROR -- : /opt/zammad/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.8.5/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:126:in `block in wait_poll'
I, [2024-12-02T16:07:48.863366#851-10712460]  INFO -- : Started GET "/api/v1/monitoring/health_check?_" for 10.254.0.68 at 2024-12-02 16:07:48 +0100
I, [2024-12-02T16:07:48.870149#851-10712460]  INFO -- : Processing by MonitoringController#health_check as JSON
... 
some more INFO
...
I, [2024-12-02T16:07:50.598537#851-10723060]  INFO -- : Completed 200 OK in 36ms (Views: 1.3ms | ActiveRecord: 6.8ms | Allocations: 13786)
E, [2024-12-02T16:07:54.155174#855-400167460] ERROR -- : execute DataPrivacyTaskJob.perform_now (try_count 1) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 10.162 seconds); all pooled connections were in use> in: 10.161812869 seconds.
E, [2024-12-02T16:07:56.255982#855-400165720] ERROR -- : Can't reconnect to database #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 10.400 seconds); all pooled connections were in use>
E, [2024-12-02T16:07:56.272671#855-400170780] ERROR -- : execute Ticket.process_auto_unassign (try_count 1) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 8.721 seconds); all pooled connections were in use> in: 8.720898291 seconds.
I, [2024-12-02T16:07:56.290076#855-149080]  INFO -- : ProcessScheduledJobs running...

But i’m monitoring Postgres Connections now, and they seem very low, considering the limit of 2000:

What are some recommendations for a installation of our size, shall i give the Machine more RAM / SWAP?

Best regards