First Last Prev Next    This bug is not in your last search results.
Bug 39953 - 40_mail.20_mail_delivery_via_submission_port.test fails
40_mail.20_mail_delivery_via_submission_port.test fails
Status: NEW
Product: UCS Test
Classification: Unclassified
Component: Mail
unspecified
Other Linux
: P5 normal (vote)
: ---
Assigned To: Mail maintainers
:
Depends on:
Blocks:
  Show dependency tree / graph
 
Reported: 2015-11-14 09:24 CET by Stefan Gohmann
Modified: 2016-10-05 20:20 CEST (History)
1 user (show)

See Also:
What kind of report is it?: Development Internal
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Stefan Gohmann univentionstaff 2015-11-14 09:24:18 CET 
The test case 20_mail_delivery_via_submission_port fails since a few days. For example on a S3 master:

http://jenkins.knut.univention.de:8080/job/UCS-4.1/job/UCS-4.1-0/job/Autotest%20MultiEnv/104/SambaVersion=s3,Systemrolle=master/testReport/40_mail/20_mail_delivery_via_submission_port/test/

*** BEGIN *** ['/usr/bin/python', '20_mail_delivery_via_submission_port'] ***
*** 40_mail/20_mail_delivery_via_submission_port *** Mail delivery via submission port ***
*** START TIME: 2015-11-13 20:23:28 ***
*** Entering with-statement of NetworkRedirector()
Create mail/dovecot/logging/auth_debug
Create mail/dovecot/logging/auth_debug_passwords
Create mail/dovecot/logging/auth_verbose
Create mail/dovecot/logging/auth_verbose_passwords
Create mail/dovecot/logging/mail_debug
File: /etc/dovecot/conf.d/10-logging.conf
File: /usr/sbin/univention-sa-learn
Multifile: /etc/postfix/ldap.sharedfolderlocal
Creating users/user object with {'username': 'vvwu3uwhqv', 'set': {'password': 'univention', 'mailHomeServer': 'master090.autotest090.local', 'mailPrimaryAddress': 'stqyvm77ao@autotest090.local'}, 'firstname': 'f71eukjjej', 'lastname': 'm7pnqz4ndw', 'position': 'cn=users,dc=autotest090,dc=local', 'password': 'univention'}
<closed file '<fdopen>', mode 'rb' at 0x1c6cf60>
*** Adding network loop (1.2.3.4 <--> 4.3.2.1)
*** ['/sbin/iptables', '-t', 'mangle', '-A', 'OUTPUT', '-d', '1.2.3.4', '-j', 'TOS', '--set-tos', '0x04']
*** ['/sbin/iptables', '-t', 'nat', '-A', 'OUTPUT', '-d', '1.2.3.4', '-j', 'DNAT', '--to-destination', '10.210.138.137']
*** ['/sbin/iptables', '-t', 'nat', '-A', 'POSTROUTING', '-m', 'tos', '--tos', '0x04', '-j', 'SNAT', '--to-source', '4.3.2.1']
*** ['/sbin/iptables', '-t', 'mangle', '-A', 'OUTPUT', '-d', '4.3.2.1', '-j', 'TOS', '--set-tos', '0x08']
*** ['/sbin/iptables', '-t', 'nat', '-A', 'OUTPUT', '-d', '4.3.2.1', '-j', 'DNAT', '--to-destination', '10.210.138.137']
*** ['/sbin/iptables', '-t', 'nat', '-A', 'POSTROUTING', '-m', 'tos', '--tos', '0x08', '-j', 'SNAT', '--to-source', '1.2.3.4']
*** Sending mail: recipients=['stqyvm77ao@autotest090.local'] sender='tarpit@example.com' subject='Testmessage Fri Nov 13 20:23:31 2015' idstring='no id string' gtube=False server='4.3.2.1' port=587 tls=True username='stqyvm77ao@autotest090.local' password='univention' HELO/EHLO='ucstest.26219.example.com'
send: 'ehlo ucstest.26219.example.com\r\n'
reply: '250-master090.autotest090.local\r\n'
reply: '250-PIPELINING\r\n'
reply: '250-SIZE 10240000\r\n'
reply: '250-VRFY\r\n'
reply: '250-ETRN\r\n'
reply: '250-STARTTLS\r\n'
reply: '250-ENHANCEDSTATUSCODES\r\n'
reply: '250-8BITMIME\r\n'
reply: '250 DSN\r\n'
reply: retcode (250); Msg: master090.autotest090.local
PIPELINING
SIZE 10240000
VRFY
ETRN
STARTTLS
ENHANCEDSTATUSCODES
8BITMIME
DSN
send: 'STARTTLS\r\n'
reply: '220 2.0.0 Ready to start TLS\r\n'
reply: retcode (220); Msg: 2.0.0 Ready to start TLS
send: 'ehlo ucstest.26219.example.com\r\n'
reply: '250-master090.autotest090.local\r\n'
reply: '250-PIPELINING\r\n'
reply: '250-SIZE 10240000\r\n'
reply: '250-VRFY\r\n'
reply: '250-ETRN\r\n'
reply: '250-AUTH PLAIN LOGIN\r\n'
reply: '250-AUTH=PLAIN LOGIN\r\n'
reply: '250-ENHANCEDSTATUSCODES\r\n'
reply: '250-8BITMIME\r\n'
reply: '250 DSN\r\n'
reply: retcode (250); Msg: master090.autotest090.local
PIPELINING
SIZE 10240000
VRFY
ETRN
AUTH PLAIN LOGIN
AUTH=PLAIN LOGIN
ENHANCEDSTATUSCODES
8BITMIME
DSN
send: 'AUTH PLAIN AHN0cXl2bTc3YW9AYXV0b3Rlc3QwOTAubG9jYWwAdW5pdmVudGlvbg==\r\n'
reply: '235 2.7.0 Authentication successful\r\n'
reply: retcode (235); Msg: 2.7.0 Authentication successful
send: 'mail FROM:<tarpit@example.com> size=530\r\n'
reply: '250 2.1.0 Ok\r\n'
reply: retcode (250); Msg: 2.1.0 Ok
send: 'rcpt TO:<stqyvm77ao@autotest090.local>\r\n'
reply: '250 2.1.5 Ok\r\n'
reply: retcode (250); Msg: 2.1.5 Ok
send: 'data\r\n'
reply: '354 End data with <CR><LF>.<CR><LF>\r\n'
reply: retcode (354); Msg: End data with <CR><LF>.<CR><LF>
data: (354, 'End data with <CR><LF>.<CR><LF>')
send: 'Content-Type: multipart/mixed; boundary="===============0979042705920776848=="\r\nMIME-Version: 1.0\r\nFrom: tarpit@example.com\r\nTo: stqyvm77ao@autotest090.local\r\nDate: Fri, 13 Nov 2015 20:23:31 +0000\r\nSubject: Testmessage Fri Nov 13 20:23:31 2015\r\nUCS-TEST: no id string\r\nMessage-Id: 5107ab80-8a6e-11e5-ab67-0230249757d7.rvkx9tlrpc@autotest090.local\r\n\r\n--===============0979042705920776848==\r\nContent-Type: text/plain; charset="us-ascii"\r\nMIME-Version: 1.0\r\nContent-Transfer-Encoding: 7bit\r\n\r\n1447464211.52\r\n--===============0979042705920776848==--\r\n.\r\n'
stqyvm77ao@autotest090.local is waiting for an email; should be delivered = True
reply: '250 2.0.0 Ok: queued as 95E2A2319C\r\n'
reply: retcode (250); Msg: 2.0.0 Ok: queued as 95E2A2319C
data: (250, '2.0.0 Ok: queued as 95E2A2319C')
send: 'quit\r\n'
reply: '221 2.0.0 Bye\r\n'
reply: retcode (221); Msg: 2.0.0 Bye
*** Sending mail: recipients=['stqyvm77ao@autotest090.local'] sender='tarpit@example.com' subject='Testmessage Fri Nov 13 20:23:32 2015' idstring='no id string' gtube=False server='4.3.2.1' port=587 tls=True username=None password=None HELO/EHLO='ucstest.26219.example.com'
send: 'ehlo ucstest.26219.example.com\r\n'
reply: '250-master090.autotest090.local\r\n'
reply: '250-PIPELINING\r\n'
reply: '250-SIZE 10240000\r\n'
reply: '250-VRFY\r\n'
reply: '250-ETRN\r\n'
reply: '250-STARTTLS\r\n'
reply: '250-ENHANCEDSTATUSCODES\r\n'
reply: '250-8BITMIME\r\n'
reply: '250 DSN\r\n'
reply: retcode (250); Msg: master090.autotest090.local
PIPELINING
SIZE 10240000
VRFY
ETRN
STARTTLS
ENHANCEDSTATUSCODES
8BITMIME
DSN
send: 'STARTTLS\r\n'
reply: '220 2.0.0 Ready to start TLS\r\n'
reply: retcode (220); Msg: 2.0.0 Ready to start TLS
send: 'ehlo ucstest.26219.example.com\r\n'
reply: '250-master090.autotest090.local\r\n'
reply: '250-PIPELINING\r\n'
reply: '250-SIZE 10240000\r\n'
reply: '250-VRFY\r\n'
reply: '250-ETRN\r\n'
reply: '250-AUTH PLAIN LOGIN\r\n'
reply: '250-AUTH=PLAIN LOGIN\r\n'
reply: '250-ENHANCEDSTATUSCODES\r\n'
reply: '250-8BITMIME\r\n'
reply: '250 DSN\r\n'
reply: retcode (250); Msg: master090.autotest090.local
PIPELINING
SIZE 10240000
VRFY
ETRN
AUTH PLAIN LOGIN
AUTH=PLAIN LOGIN
ENHANCEDSTATUSCODES
8BITMIME
DSN
send: 'mail FROM:<tarpit@example.com> size=530\r\n'
reply: '250 2.1.0 Ok\r\n'
reply: retcode (250); Msg: 2.1.0 Ok
send: 'rcpt TO:<stqyvm77ao@autotest090.local>\r\n'
reply: '250 2.1.5 Ok\r\n'
reply: retcode (250); Msg: 2.1.5 Ok
send: 'data\r\n'
reply: '354 End data with <CR><LF>.<CR><LF>\r\n'
reply: retcode (354); Msg: End data with <CR><LF>.<CR><LF>
data: (354, 'End data with <CR><LF>.<CR><LF>')
send: 'Content-Type: multipart/mixed; boundary="===============3568243491773976161=="\r\nMIME-Version: 1.0\r\nFrom: tarpit@example.com\r\nTo: stqyvm77ao@autotest090.local\r\nDate: Fri, 13 Nov 2015 20:23:32 +0000\r\nSubject: Testmessage Fri Nov 13 20:23:32 2015\r\nUCS-TEST: no id string\r\nMessage-Id: 51b2a4ae-8a6e-11e5-ab67-0230249757d7.el81v3l4rz@autotest090.local\r\n\r\n--===============3568243491773976161==\r\nContent-Type: text/plain; charset="us-ascii"\r\nMIME-Version: 1.0\r\nContent-Transfer-Encoding: 7bit\r\n\r\n1447464212.64\r\n--===============3568243491773976161==--\r\n.\r\n'
reply: '250 2.0.0 Ok: queued as A37782319C\r\n'
reply: retcode (250); Msg: 2.0.0 Ok: queued as A37782319C
data: (250, '2.0.0 Ok: queued as A37782319C')
send: 'quit\r\n'
stqyvm77ao@autotest090.local is waiting for an email; should be delivered = True
reply: '221 2.0.0 Bye\r\n'
reply: retcode (221); Msg: 2.0.0 Bye
### FAIL ###
Mail sent with token = '1447464212.64' to stqyvm77ao@autotest090.local un-expectedly not delivered
###      ###
============================== /var/log/auth.log ==============================
Nov 13 20:23:31 master090 PAM-univentionmailcyrus[26196]: continuing as user vvwu3uwhqv
Nov 13 20:25:01 master090 CRON[26289]: pam_unix(cron:session): session opened for user root by (uid=0)
Nov 13 20:25:01 master090 CRON[26289]: pam_unix(cron:session): session closed for user root
===============================================================================
============================== /var/log/mail.log ==============================
Nov 13 20:23:31 master090 postfix/smtpd[26143]: connect from unknown[1.2.3.4]
Nov 13 20:23:31 master090 postfix/smtpd[26143]: 95E2A2319C: client=unknown[1.2.3.4], sasl_method=PLAIN, sasl_username=vvwu3uwhqv
Nov 13 20:23:31 master090 postfix/cleanup[26030]: 95E2A2319C: message-id=5107ab80-8a6e-11e5-ab67-0230249757d7.rvkx9tlrpc@autotest090.local
Nov 13 20:23:31 master090 postfix/qmgr[25932]: 95E2A2319C: from=<tarpit@example.com>, size=755, nrcpt=1 (queue active)
Nov 13 20:23:31 master090 postfix/smtpd[26143]: disconnect from unknown[1.2.3.4]
Nov 13 20:23:31 master090 postfix/smtpd[26123]: BF01728CCB: client=localhost[127.0.0.1], orig_queue_id=95E2A2319C, orig_client=unknown[1.2.3.4]
Nov 13 20:23:31 master090 postfix/cleanup[26030]: BF01728CCB: message-id=5107ab80-8a6e-11e5-ab67-0230249757d7.rvkx9tlrpc@autotest090.local
Nov 13 20:23:31 master090 postfix/qmgr[25932]: BF01728CCB: from=<tarpit@example.com>, size=1479, nrcpt=1 (queue active)
Nov 13 20:23:31 master090 amavis[25978]: (25978-04) Passed CLEAN {RelayedInbound}, [1.2.3.4]:47790 [1.2.3.4] <tarpit@example.com> -> <stqyvm77ao@autotest090.local>, Queue-ID: 95E2A2319C, Message-ID: <5107ab80-8a6e-11e5-ab67-0230249757d7.rvkx9tlrpc@autotest090.local>, mail_id: beuHXXqwVj_5, Hits: 1.243, size: 755, queued_as: BF01728CCB, 163 ms
Nov 13 20:23:31 master090 postfix/smtp[26031]: 95E2A2319C: to=<stqyvm77ao@autotest090.local>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.19, delays=0.02/0/0/0.16, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as BF01728CCB)
Nov 13 20:23:31 master090 postfix/qmgr[25932]: 95E2A2319C: removed
Nov 13 20:23:31 master090 postfix/lmtp[26034]: BF01728CCB: to=<stqyvm77ao@autotest090.local>, relay=master090.autotest090.local[private/dovecot-lmtp], delay=0.06, delays=0.03/0/0/0.03, dsn=2.0.0, status=sent (250 2.0.0 <stqyvm77ao@autotest090.local> WlJeGAWNRlYMZgAA9Xj3Iw Saved)
Nov 13 20:23:31 master090 postfix/qmgr[25932]: BF01728CCB: removed
Nov 13 20:23:32 master090 postfix/smtpd[26197]: connect from unknown[1.2.3.4]
Nov 13 20:23:32 master090 postfix/smtpd[26197]: A37782319C: client=unknown[1.2.3.4]
Nov 13 20:23:32 master090 postfix/cleanup[26030]: A37782319C: message-id=51b2a4ae-8a6e-11e5-ab67-0230249757d7.el81v3l4rz@autotest090.local
Nov 13 20:23:32 master090 postfix/qmgr[25932]: A37782319C: from=<tarpit@example.com>, size=754, nrcpt=1 (queue active)
Nov 13 20:23:32 master090 postfix/smtpd[26197]: disconnect from unknown[1.2.3.4]
Nov 13 20:23:33 master090 postfix/smtpd[26033]: 0C30928CCB: client=localhost[127.0.0.1], orig_queue_id=A37782319C, orig_client=unknown[1.2.3.4]
Nov 13 20:23:33 master090 postfix/cleanup[26030]: 0C30928CCB: message-id=51b2a4ae-8a6e-11e5-ab67-0230249757d7.el81v3l4rz@autotest090.local
Nov 13 20:23:33 master090 postfix/qmgr[25932]: 0C30928CCB: from=<tarpit@example.com>, size=1521, nrcpt=1 (queue active)
Nov 13 20:23:33 master090 amavis[25977]: (25977-05) Passed SPAM {RelayedTaggedInbound}, [1.2.3.4]:47794 [1.2.3.4] <tarpit@example.com> -> <stqyvm77ao@autotest090.local>, Queue-ID: A37782319C, Message-ID: <51b2a4ae-8a6e-11e5-ab67-0230249757d7.el81v3l4rz@autotest090.local>, mail_id: hh4NpPtkO9hC, Hits: 5.436, size: 754, queued_as: 0C30928CCB, 393 ms
Nov 13 20:23:33 master090 postfix/smtp[26199]: A37782319C: to=<stqyvm77ao@autotest090.local>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.43, delays=0.04/0/0/0.39, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0C30928CCB)
Nov 13 20:23:33 master090 postfix/qmgr[25932]: A37782319C: removed
Nov 13 20:23:33 master090 postfix/lmtp[26034]: 0C30928CCB: to=<stqyvm77ao@autotest090.local>, relay=master090.autotest090.local[private/dovecot-lmtp], delay=0.1, delays=0.02/0/0/0.08, dsn=2.0.0, status=sent (250 2.0.0 <stqyvm77ao@autotest090.local> X1JeGAWNRlYMZgAA9Xj3Iw Saved)
Nov 13 20:23:33 master090 postfix/qmgr[25932]: 0C30928CCB: removed
===============================================================================
Unsetting mail/dovecot/logging/mail_debug
Unsetting mail/dovecot/logging/auth_verbose_passwords
Unsetting mail/dovecot/logging/auth_verbose
Unsetting mail/dovecot/logging/auth_debug
Unsetting mail/dovecot/logging/auth_debug_passwords
File: /etc/dovecot/conf.d/10-logging.conf
File: /usr/sbin/univention-sa-learn
Multifile: /etc/postfix/ldap.sharedfolderlocal
Cleanup after exception: <type 'exceptions.SystemExit'> 1
Performing UCSTestUDM cleanup...
UCSTestUDM cleanup done
*** Leaving with-statement of NetworkRedirector()
*** NetworkRedirector.revert_network_settings()
*** Removing network loop (1.2.3.4 <--> 4.3.2.1)
*** ['/sbin/iptables', '-t', 'mangle', '-D', 'OUTPUT', '-d', '1.2.3.4', '-j', 'TOS', '--set-tos', '0x04']
*** ['/sbin/iptables', '-t', 'nat', '-D', 'OUTPUT', '-d', '1.2.3.4', '-j', 'DNAT', '--to-destination', '10.210.138.137']
*** ['/sbin/iptables', '-t', 'nat', '-D', 'POSTROUTING', '-m', 'tos', '--tos', '0x04', '-j', 'SNAT', '--to-source', '4.3.2.1']
*** ['/sbin/iptables', '-t', 'mangle', '-D', 'OUTPUT', '-d', '4.3.2.1', '-j', 'TOS', '--set-tos', '0x08']
*** ['/sbin/iptables', '-t', 'nat', '-D', 'OUTPUT', '-d', '4.3.2.1', '-j', 'DNAT', '--to-destination', '10.210.138.137']
*** ['/sbin/iptables', '-t', 'nat', '-D', 'POSTROUTING', '-m', 'tos', '--tos', '0x08', '-j', 'SNAT', '--to-source', '1.2.3.4']
*** END TIME: 2015-11-13 20:25:03 ***
*** TEST DURATION (H:MM:SS.ms): 0:01:35.337422 ***
*** END *** 1 ***
Comment 1 Stefan Gohmann univentionstaff 2015-11-14 09:25:55 CET 
I've disabled the test case for UCS 4.1: r65511
Comment 2 Sönke Schwardt-Krummrich univentionstaff 2015-11-14 10:20:43 CET 
During manual runs on KVM machines, this test passes without problems. The jenkins log looks ok. Seems to be a timing issue.
First Last Prev Next    This bug is not in your last search results.