Emails stuck in wallace queue until wallace is restarted
Open, 60Public

Description

I've got a report, that email was stuck in wallace queue for 12 hours. It went away after wallace restart.
Here is pykolab log:

2018-02-27 07:30:18,210 pykolab.wallace DEBUG [31012]: Worker process PoolWorker-1967 initializing
2018-02-27 07:30:20,709 pykolab.wallace DEBUG [31012]: Resource Management called for ('/var/spool/pykolab/wallace/tmp3Bld0S',), {}
2018-02-27 07:30:20,710 pykolab.wallace DEBUG [31012]: Renaming '/var/spool/pykolab/wallace/tmp3Bld0S' to '/var/spool/pykolab/wallace/resources/incoming/tmp3Bld0S'
2018-02-27 07:30:20,711 pykolab.wallace DEBUG [31012]: Message is not an iTip message (non-multipart message)
2018-02-27 07:30:20,711 pykolab.wallace INFO Message is not an iTip message or does not contain any (valid) iTip.
2018-02-27 07:30:20,711 pykolab.wallace DEBUG [31012]: No itips, no resources, pass along '/var/spool/pykolab/wallace/resources/incoming/tmp3Bld0S'
2018-02-27 07:30:20,711 pykolab.wallace DEBUG [31012]: Invitation policy executing for '/var/spool/pykolab/wallace/resources/incoming/tmp3Bld0S', False
2018-02-27 07:30:20,711 pykolab.wallace DEBUG [31012]: Renaming '/var/spool/pykolab/wallace/resources/incoming/tmp3Bld0S' to '/var/spool/pykolab/wallace/invitationpolicy/incoming/tmp3Bld0S'
2018-02-27 07:30:20,712 pykolab.wallace DEBUG [31012]: Message is not an iTip message (non-multipart message)
2018-02-27 07:30:20,712 pykolab.wallace INFO Message is not an iTip message or does not contain any (valid) iTip objects.
2018-02-27 07:30:20,712 pykolab.wallace DEBUG [31012]: No itips, no users, pass along '/var/spool/pykolab/wallace/invitationpolicy/incoming/tmp3Bld0S'
2018-02-27 07:30:20,712 pykolab.wallace INFO Accepting message in /var/spool/pykolab/wallace/invitationpolicy/incoming/tmp3Bld0S (by module wallace)
2018-02-27 07:30:20,712 pykolab.wallace DEBUG [31012]: Accepting message in: '/var/spool/pykolab/wallace/invitationpolicy/incoming/tmp3Bld0S'
2018-02-27 07:30:20,712 pykolab.wallace DEBUG [31012]: recipients: ['<recipient removed>']

Looking at postfix maillog I found:

Feb 27 07:30:20 prod-mail postfix/smtpd[31000]: connect from localhost[127.0.0.1]
Feb 27 07:35:20 prod-mail postfix/smtpd[31000]: timeout after CONNECT from localhost[127.0.0.1]

It looks like after timeout wallace did not try to resend message again.
The message is a simple email with not iTips.
wallace-0.8.7-2.3.el7.kolab_16.noarch

adomaitis created this task.Mar 1 2018, 1:22 PM

Postfix verbose logging shows this:

Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: connection established
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: master_notify: status 0
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: name_mask: resource
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: name_mask: software
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: connect from localhost[127.0.0.1]
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_list_match: localhost: no match
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_list_match: 127.0.0.1: no match
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_hostname: localhost ~? 127.0.0.0/8
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: smtp_stream_setup: maxtime=300 enable_deadline=0
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_hostname: localhost ~? 127.0.0.0/8
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: > localhost[127.0.0.1]: 220 mail.server.com ESMTP Postfix
Mar  8 20:03:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: watchdog_pat: 0x559232efc1c0
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: smtp_get: timeout
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: > localhost[127.0.0.1]: 421 4.4.2 mail.server.com Error: timeout exceeded
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_hostname: localhost ~? 127.0.0.0/8
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: timeout after CONNECT from localhost[127.0.0.1]
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: disconnect from localhost[127.0.0.1]
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: master_notify: status 1
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: connection closed
Mar  8 20:08:17 prod-mail-proxy-1.pao1.server.com postfix/smtpd[22547]: watchdog_stop: 0x559232efc1c0
juwo added a subscriber: juwo.Apr 25 2018, 3:43 PM