Message delivered twice caused by an LMTP error "Got unexpected reply" during upgrade to 2.3
Hi all, we are upgrading our dovecot platform from:
dovecot --version
2.2.15.14 (39f57c379ded+)
to
dovecot --version
2.3.2.1 (0719df592)
Our platform is debian based and it is configured as director and backend proxy.
We have just upgrade only 4 servers (2 directors and 2 backends) and when the lmtp traffic flow goes through an upgraded director and a not-upgraded backend sometimes the following error has been arised: Aug 6 14:31:28 monti-director07 dovecot: lmtp(13463): Error: eMFVIKA/aFuXNAAAhXvSMA: Failed to send message to <test2@internalinboundcm.eu> at 192.168.72.135:24: Got unexpected reply (1/1 at 210 ms) Aug 6 14:31:28 monti-director07 dovecot: lmtp(13463): Error: eMFVIKA/aFuXNAAAhXvSMA: Failed to send message to <test2@internalinboundcm.eu> at 192.168.72.135:24: Got unexpected reply (1/1 at 210 ms)
where 172.20.44.7 (monti-director07) is a dovecot 2.3.2.1 192.168.72.135 (monti-backend07) is a dovecot 2.2.15.14
When that error occurs an email is delivered twice, as you can see from the following logs.
On smtp server you can see the temp fail (by the upgraded director 172.20.44.7), retry and delivered (by a not-upgraded director 172.20.44.3): 20180806 14:31:28.772 core context="Temporary_Delivery_Failure", _fromemail="test1@internalinboundcm.eu", _toemail="test2@internalinboundcm.eu", _tos="test2@internalinboundcm.eu", _size="80294", dip=172.20.44.7 dport=24 type=lmtp msg="4.4.0 Remote server not answering (bad reply)" duration=5 mailfrom=6/6/0/0 rcptto=6/6/0/0 data=6/5/1/0 tls=0/0 20180806 14:32:28.032 core context="Message_Delivered", _fromemail="test1@internalinboundcm.eu", _toemail="test2@internalinboundcm.eu", _tos="test2@internalinboundcm.eu", _size="80294", dip=172.20.44.3 dport=24 type=lmtp msg="2.0.0 <test2@internalinboundcm.eu> AS1CJtQ/aFsqMAAAj5cnUg Saved" duration=21457 mailfrom=3586/3586/0/0 rcptto=3586/3586/0/0 data=3586/3584/2/0 tls=0/0
and on backend server there are the related two delivered log entries: Aug 6 14:31:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<f0WZF5c/aFuPdgAAj5cnUg>: copy from <lmtp DATA>: box=INBOX, uid=2727, msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu> Aug 6 14:31:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<f0WZF5c/aFuPdgAAj5cnUg>: f0WZF5c/aFuPdgAAj5cnUg: msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu>: saved mail to INBOX Aug 6 14:32:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<AS1CJtQ/aFsqMAAAj5cnUg>: copy from <lmtp DATA>: box=INBOX, uid=2728, msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu> Aug 6 14:32:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<AS1CJtQ/aFsqMAAAj5cnUg>: AS1CJtQ/aFsqMAAAj5cnUg: msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu>: saved mail to INBOX
This is the strace output of dovecot lmtp director process (13463): 13463 1533558688.759362 read(8, "250 2.0.0 <test2@internalinboundcm.eu> f0WZF5c/aFuPdgAAj5cnUg Saved\r\n", 8012) = 71 <0.000028> 13463 1533558688.759493 sendto(14, "<19>Aug 6 14:31:28 dovecot: lmtp(13463): Error: eMFVIKA/aFuXNAAAhXvSMA: Failed to send message to <test2@internalinboundcm.eu> at 192.168.72.135:24: Got unexpected reply (1/1 at 210 ms)", 188, MSG_NOSIGNAL, NULL, 0) = 188 <0.000037>
So it receives the "Saved" message from backend but it arises the "Got unexpected reply" error anyway.
From tcpdump we have noticed the QUIT response is missed on lmtp trasaction after the "Saved" message from backend at DATA stage: 220 monti-backend07.it.dadainternal Dovecot ready. LHLO monti-director07.it.dadainternal 250-monti-backend07.it.dadainternal 250-8BITMIME 250-ENHANCEDSTATUSCODES 250 PIPELINING MAIL FROM:<test1@internalinboundcm.eu> RCPT TO:<test2@internalinboundcm.eu> DATA ...truncated message
. 250 2.0.0 <test2@internalinboundcm.eu> f0WZF5c/aFuPdgAAj5cnUg Saved
While it should be something like this:
220 monti-backend07.it.dadainternal Dovecot ready. LHLO monti-director07.it.dadainternal 250-monti-backend07.it.dadainternal 250-8BITMIME 250-ENHANCEDSTATUSCODES 250 PIPELINING MAIL FROM:<test1@internalinboundcm.eu> RCPT TO:<test2@internalinboundcm.eu> DATA ...truncated message
. 250 2.0.0 <test2@internalinboundcm.eu> f0WZF5c/aFuPdgAAj5cnUg Saved QUIT 221 2.0.0 OK
It follows the both dovecot configurations:
2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf
OS: Linux 4.9.0-7-amd64 x86_64 Debian 9.5
auth_cache_negative_ttl = 0 auth_verbose = yes auth_worker_max_count = 350 director_mail_servers = 192.168.72.129 192.168.72.130 192.168.72.131 192.168.72.132 192.168.72.133 192.168.72.134 192.168.72.135 192.168.72.136 192.168.72.137 192.168.72.138 192.168.72.139 192.168.72.140 192.168.72.141 192.168.72.142 192.168.72.143 192.168.72.144 192.168.72.145 192.168.72.146 192.168.72.147 192.168.72.148 192.168.72.149 director_servers = 172.20.44.1 172.20.44.2 172.20.44.3 172.20.44.4 172.20.44.5 172.20.44.6 172.20.44.7 172.20.44.8 disable_plaintext_auth = no doveadm_password = # hidden, use -P to show it doveadm_port = 24242 lmtp_proxy = yes log_timestamp = "%Y-%m-%d %H:%M:%S " login_log_format_elements = user=<%Lu> method=%m rip=%r lip=%l mpid=%e %c session=<%{session}> mail_log_prefix = "%s(%Lu)<%{session}>: " mail_max_userip_connections = 500 passdb { args = /etc/dovecot/dovecot-sql.conf driver = sql skip = authenticated } protocols = imap pop3 lmtp service auth-worker { user = dovecot } service auth { client_limit = 0 } service director { fifo_listener login/proxy-notify { mode = 0666 } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service doveadm { inet_listener { port = 24242 } } service imap-login { client_limit = 12000 executable = imap-login director process_limit = 0 process_min_avail = 4 service_count = 0 } service ipc { unix_listener ipc { user = $default_internal_user } } service lmtp { client_limit = 1 executable = lmtp -L inet_listener lmtp { port = 24 } process_limit = 240 process_min_avail = 20 service_count = 1 } service pop3-login { client_limit = 12000 executable = pop3-login director process_limit = 0 process_min_avail = 4 service_count = 0 } ssl = no userdb { driver = prefetch } userdb { args = /etc/dovecot/dovecot-sql.conf driver = sql } verbose_proctitle = yes protocol doveadm { auth_socket_path = director-userdb } protocol lmtp { auth_socket_path = director-userdb mail_plugins = }
2.2.15.14 (39f57c379ded+): /etc/dovecot/dovecot.conf
OS: Linux 3.2.0-4-amd64 x86_64 Debian 7.9
auth_cache_negative_ttl = 0 auth_worker_max_count = 500 default_vsz_limit = 1 G disable_plaintext_auth = no doveadm_password = first_valid_uid = 508 last_valid_uid = 508 lda_mailbox_autocreate = yes log_timestamp = "%Y-%m-%d %H:%M:%S " login_log_format_elements = user=<%Lu> method=%m rip=%r lip=%l mpid=%e %c session=<%{session}> login_trusted_networks = 192.168.72.201 192.168.72.202 192.168.72.203 192.168.72.204 192.168.72.205 192.168.72.206 192.168.72.207 192.168.72.208 mail_fsync = always mail_gid = 508 mail_location = maildir:~/Maildir mail_log_prefix = "%s(%Lu)<%{session}>: " mail_max_userip_connections = 30 mail_plugins = notify mail_log quota mail_uid = 508 maildir_very_dirty_syncs = yes mmap_disable = yes namespace { hidden = yes list = no location = prefix = separator = . } namespace inbox { inbox = yes location = mailbox Drafts { auto = create special_use = \Drafts } mailbox Sent { auto = create special_use = \Sent } mailbox Spam { auto = create special_use = \Junk } mailbox Trash { auto = create special_use = \Trash } prefix = INBOX. separator = . } passdb { args = /etc/dovecot/dovecot-sql.conf driver = sql skip = authenticated } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid quota = dict:User quota::file:%h/dovecot-quota quota_exceeded_message = Quota exceeded quota_rule2 = Trash:storage=+100M quota_warning = storage=100%% quota-warning -q 100 -n %n -d %d -e OverQuota quota_warning2 = storage=80%% quota-warning -q 80 -n %n -d %d -e FillQuota quota_warning3 = -storage=99%% quota-warning -q 99 -n %n -d %d -e InQuota sieve = ~/.dovecot.sieve sieve_extensions = +editheader sieve_max_redirects = 15 sieve_vacation_default_period = 1h } quota_full_tempfail = yes service auth-worker { user = dovecot } service auth { client_limit = 15000 } service doveadm { inet_listener { port = 24242 } } service imap-login { process_limit = 0 process_min_avail = 16 service_count = 0 } service imap { executable = imap postlogin process_limit = 7000 service_count = 2300 } service lmtp { client_limit = 1 executable = lmtp -L inet_listener lmtp { address = 192.168.72.129 127.0.0.1 port = 24 } process_limit = 240 process_min_avail = 20 service_count = 10 } service pop3-login { process_limit = 0 process_min_avail = 16 service_count = 0 } service pop3 { executable = pop3 postlogin process_limit = 7000 service_count = 2300 } ssl = no submission_host = userdb { driver = prefetch } userdb { args = /etc/dovecot/dovecot-sql.conf driver = sql } verbose_proctitle = yes protocol imap { imap_client_workarounds = delay-newmail mail_plugins = notify mail_log quota imap_quota } protocol pop3 { pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_fast_size_lookups = yes pop3_no_flag_updates = yes pop3_uidl_format = %f } protocol lmtp { mail_plugins = notify mail_log quota sieve passdb { args = /etc/dovecot/dovecot-lmtp.conf driver = sql name = } userdb { args = /etc/dovecot/dovecot-lmtp.conf driver = sql name = result_failure = return-fail skip = never } }
Please could someone help me? How can I fix that error, in order to avoid the duplicated email?
Thanks in advance Regards,
Gabriele Nencioni System Administrator eml gabriele.nencioni@register.it
Hi,
Op 07/08/2018 om 09:35 schreef Gabriele Nencioni:
Hi all, we are upgrading our dovecot platform from:
dovecot --version
2.2.15.14 (39f57c379ded+)
Great! A mummy from ancient times.
That is going to make reproducing the circumstances here a bit difficult (difficult to get that compiled here anymore). I cannot reproduce anything like that so far with current versions.
Can you make a pcap log of the LMTP communication between the two Dovecot hosts? That may give me a clue on which side of the communication is causing the issue.
Regards,
Stephan.
to
dovecot --version
2.3.2.1 (0719df592)
Our platform is debian based and it is configured as director and backend proxy.
We have just upgrade only 4 servers (2 directors and 2 backends) and when the lmtp traffic flow goes through an upgraded director and a not-upgraded backend sometimes the following error has been arised: Aug 6 14:31:28 monti-director07 dovecot: lmtp(13463): Error: eMFVIKA/aFuXNAAAhXvSMA: Failed to send message to <test2@internalinboundcm.eu> at 192.168.72.135:24: Got unexpected reply (1/1 at 210 ms) Aug 6 14:31:28 monti-director07 dovecot: lmtp(13463): Error: eMFVIKA/aFuXNAAAhXvSMA: Failed to send message to <test2@internalinboundcm.eu> at 192.168.72.135:24: Got unexpected reply (1/1 at 210 ms)
where 172.20.44.7 (monti-director07) is a dovecot 2.3.2.1 192.168.72.135 (monti-backend07) is a dovecot 2.2.15.14
When that error occurs an email is delivered twice, as you can see from the following logs.
On smtp server you can see the temp fail (by the upgraded director 172.20.44.7), retry and delivered (by a not-upgraded director 172.20.44.3): 20180806 14:31:28.772 core context="Temporary_Delivery_Failure", _fromemail="test1@internalinboundcm.eu", _toemail="test2@internalinboundcm.eu", _tos="test2@internalinboundcm.eu", _size="80294", dip=172.20.44.7 dport=24 type=lmtp msg="4.4.0 Remote server not answering (bad reply)" duration=5 mailfrom=6/6/0/0 rcptto=6/6/0/0 data=6/5/1/0 tls=0/0 20180806 14:32:28.032 core context="Message_Delivered", _fromemail="test1@internalinboundcm.eu", _toemail="test2@internalinboundcm.eu", _tos="test2@internalinboundcm.eu", _size="80294", dip=172.20.44.3 dport=24 type=lmtp msg="2.0.0 <test2@internalinboundcm.eu> AS1CJtQ/aFsqMAAAj5cnUg Saved" duration=21457 mailfrom=3586/3586/0/0 rcptto=3586/3586/0/0 data=3586/3584/2/0 tls=0/0
and on backend server there are the related two delivered log entries: Aug 6 14:31:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<f0WZF5c/aFuPdgAAj5cnUg>: copy from <lmtp DATA>: box=INBOX, uid=2727, msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu> Aug 6 14:31:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<f0WZF5c/aFuPdgAAj5cnUg>: f0WZF5c/aFuPdgAAj5cnUg: msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu>: saved mail to INBOX Aug 6 14:32:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<AS1CJtQ/aFsqMAAAj5cnUg>: copy from <lmtp DATA>: box=INBOX, uid=2728, msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu> Aug 6 14:32:28 monti-backend07 dovecot: lmtp(test2@internalinboundcm.eu)<AS1CJtQ/aFsqMAAAj5cnUg>: AS1CJtQ/aFsqMAAAj5cnUg: msgid=<005b01d42d80$2101fff0$6305ffd0$@internalinboundcm.eu>: saved mail to INBOX
This is the strace output of dovecot lmtp director process (13463): 13463 1533558688.759362 read(8, "250 2.0.0 <test2@internalinboundcm.eu> f0WZF5c/aFuPdgAAj5cnUg Saved\r\n", 8012) = 71 <0.000028> 13463 1533558688.759493 sendto(14, "<19>Aug 6 14:31:28 dovecot: lmtp(13463): Error: eMFVIKA/aFuXNAAAhXvSMA: Failed to send message to <test2@internalinboundcm.eu> at 192.168.72.135:24: Got unexpected reply (1/1 at 210 ms)", 188, MSG_NOSIGNAL, NULL, 0) = 188 <0.000037>
So it receives the "Saved" message from backend but it arises the "Got unexpected reply" error anyway.
From tcpdump we have noticed the QUIT response is missed on lmtp trasaction after the "Saved" message from backend at DATA stage: 220 monti-backend07.it.dadainternal Dovecot ready. LHLO monti-director07.it.dadainternal 250-monti-backend07.it.dadainternal 250-8BITMIME 250-ENHANCEDSTATUSCODES 250 PIPELINING MAIL FROM:<test1@internalinboundcm.eu> RCPT TO:<test2@internalinboundcm.eu> DATA ...truncated message
. 250 2.0.0 <test2@internalinboundcm.eu> f0WZF5c/aFuPdgAAj5cnUg Saved
While it should be something like this:
220 monti-backend07.it.dadainternal Dovecot ready. LHLO monti-director07.it.dadainternal 250-monti-backend07.it.dadainternal 250-8BITMIME 250-ENHANCEDSTATUSCODES 250 PIPELINING MAIL FROM:<test1@internalinboundcm.eu> RCPT TO:<test2@internalinboundcm.eu> DATA ...truncated message
. 250 2.0.0 <test2@internalinboundcm.eu> f0WZF5c/aFuPdgAAj5cnUg Saved QUIT 221 2.0.0 OK
It follows the both dovecot configurations:
2.3.2.1 (0719df592): /etc/dovecot/dovecot.conf
OS: Linux 4.9.0-7-amd64 x86_64 Debian 9.5
auth_cache_negative_ttl = 0 auth_verbose = yes auth_worker_max_count = 350 director_mail_servers = 192.168.72.129 192.168.72.130 192.168.72.131 192.168.72.132 192.168.72.133 192.168.72.134 192.168.72.135 192.168.72.136 192.168.72.137 192.168.72.138 192.168.72.139 192.168.72.140 192.168.72.141 192.168.72.142 192.168.72.143 192.168.72.144 192.168.72.145 192.168.72.146 192.168.72.147 192.168.72.148 192.168.72.149 director_servers = 172.20.44.1 172.20.44.2 172.20.44.3 172.20.44.4 172.20.44.5 172.20.44.6 172.20.44.7 172.20.44.8 disable_plaintext_auth = no doveadm_password = # hidden, use -P to show it doveadm_port = 24242 lmtp_proxy = yes log_timestamp = "%Y-%m-%d %H:%M:%S " login_log_format_elements = user=<%Lu> method=%m rip=%r lip=%l mpid=%e %c session=<%{session}> mail_log_prefix = "%s(%Lu)<%{session}>: " mail_max_userip_connections = 500 passdb { args = /etc/dovecot/dovecot-sql.conf driver = sql skip = authenticated } protocols = imap pop3 lmtp service auth-worker { user = dovecot } service auth { client_limit = 0 } service director { fifo_listener login/proxy-notify { mode = 0666 } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service doveadm { inet_listener { port = 24242 } } service imap-login { client_limit = 12000 executable = imap-login director process_limit = 0 process_min_avail = 4 service_count = 0 } service ipc { unix_listener ipc { user = $default_internal_user } } service lmtp { client_limit = 1 executable = lmtp -L inet_listener lmtp { port = 24 } process_limit = 240 process_min_avail = 20 service_count = 1 } service pop3-login { client_limit = 12000 executable = pop3-login director process_limit = 0 process_min_avail = 4 service_count = 0 } ssl = no userdb { driver = prefetch } userdb { args = /etc/dovecot/dovecot-sql.conf driver = sql } verbose_proctitle = yes protocol doveadm { auth_socket_path = director-userdb } protocol lmtp { auth_socket_path = director-userdb mail_plugins = }
2.2.15.14 (39f57c379ded+): /etc/dovecot/dovecot.conf
OS: Linux 3.2.0-4-amd64 x86_64 Debian 7.9
auth_cache_negative_ttl = 0 auth_worker_max_count = 500 default_vsz_limit = 1 G disable_plaintext_auth = no doveadm_password = first_valid_uid = 508 last_valid_uid = 508 lda_mailbox_autocreate = yes log_timestamp = "%Y-%m-%d %H:%M:%S " login_log_format_elements = user=<%Lu> method=%m rip=%r lip=%l mpid=%e %c session=<%{session}> login_trusted_networks = 192.168.72.201 192.168.72.202 192.168.72.203 192.168.72.204 192.168.72.205 192.168.72.206 192.168.72.207 192.168.72.208 mail_fsync = always mail_gid = 508 mail_location = maildir:~/Maildir mail_log_prefix = "%s(%Lu)<%{session}>: " mail_max_userip_connections = 30 mail_plugins = notify mail_log quota mail_uid = 508 maildir_very_dirty_syncs = yes mmap_disable = yes namespace { hidden = yes list = no location = prefix = separator = . } namespace inbox { inbox = yes location = mailbox Drafts { auto = create special_use = \Drafts } mailbox Sent { auto = create special_use = \Sent } mailbox Spam { auto = create special_use = \Junk } mailbox Trash { auto = create special_use = \Trash } prefix = INBOX. separator = . } passdb { args = /etc/dovecot/dovecot-sql.conf driver = sql skip = authenticated } plugin { mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid quota = dict:User quota::file:%h/dovecot-quota quota_exceeded_message = Quota exceeded quota_rule2 = Trash:storage=+100M quota_warning = storage=100%% quota-warning -q 100 -n %n -d %d -e OverQuota quota_warning2 = storage=80%% quota-warning -q 80 -n %n -d %d -e FillQuota quota_warning3 = -storage=99%% quota-warning -q 99 -n %n -d %d -e InQuota sieve = ~/.dovecot.sieve sieve_extensions = +editheader sieve_max_redirects = 15 sieve_vacation_default_period = 1h } quota_full_tempfail = yes service auth-worker { user = dovecot } service auth { client_limit = 15000 } service doveadm { inet_listener { port = 24242 } } service imap-login { process_limit = 0 process_min_avail = 16 service_count = 0 } service imap { executable = imap postlogin process_limit = 7000 service_count = 2300 } service lmtp { client_limit = 1 executable = lmtp -L inet_listener lmtp { address = 192.168.72.129 127.0.0.1 port = 24 } process_limit = 240 process_min_avail = 20 service_count = 10 } service pop3-login { process_limit = 0 process_min_avail = 16 service_count = 0 } service pop3 { executable = pop3 postlogin process_limit = 7000 service_count = 2300 } ssl = no submission_host = userdb { driver = prefetch } userdb { args = /etc/dovecot/dovecot-sql.conf driver = sql } verbose_proctitle = yes protocol imap { imap_client_workarounds = delay-newmail mail_plugins = notify mail_log quota imap_quota } protocol pop3 { pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_fast_size_lookups = yes pop3_no_flag_updates = yes pop3_uidl_format = %f } protocol lmtp { mail_plugins = notify mail_log quota sieve passdb { args = /etc/dovecot/dovecot-lmtp.conf driver = sql name = } userdb { args = /etc/dovecot/dovecot-lmtp.conf driver = sql name = result_failure = return-fail skip = never } }
Please could someone help me? How can I fix that error, in order to avoid the duplicated email?
Thanks in advance Regards,
Gabriele Nencioni System Administrator eml gabriele.nencioni@register.it
On 08/08/2018 06:04 PM, Stephan Bosch wrote:
Hi Hi and thanks for your reply. Can you make a pcap log of the LMTP communication between the two Dovecot hosts? That may give me a clue on which side of the communication is causing the issue.
Yes sure, where I can send it? Here on list or at your address?
Regards
Gabriele Nencioni System Administrator eml gabriele.nencioni@register.it
participants (2)
-
Gabriele Nencioni
-
Stephan Bosch