Emails stuck in wallace queue until wallace is restarted
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	adomaitis
	Mar 1 2018, 1:22 PM

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

Details

Ticket Type: Task

Revisions and Commits

rP pykolab
	Closed	D577 With this patch I'm trying to introduce a file-type object in logger, which could swallow everything thrown to stderr (and possibly stdout) and redirect to python logger. Python smtplib debug mode prints everything to stderr, but when wallace runs...

Related Objects

Mentioned In: rP10f1c173941d: With this patch I'm trying to introduce a file-type object in logger, which…

Event Timeline

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 subscribed.Apr 25 2018, 3:43 PM

adomaitis added a revision: D577: With this patch I'm trying to introduce a file-type object in logger, which could swallow everything thrown to stderr (and possibly stdout) and redirect to python logger. Python smtplib debug mode prints everything to stderr, but when wallace runs....May 2 2018, 11:08 AM

adomaitis mentioned this in rP10f1c173941d: With this patch I'm trying to introduce a file-type object in logger, which….May 17 2018, 8:56 AM

pasik subscribed.Jan 24 2019, 3:30 PM

vanmeeuwen lowered the priority of this task from 60 to Normal.Mar 28 2019, 8:12 AM

• Revinbeer25415 subscribed.Dec 4 2020, 5:57 PM

This comment was removed by sicherha-admin.

sicherha-admin subscribed.Dec 5 2020, 7:43 AM