Message delivered twice caused by an LMTP error "Got unexpected reply" during upgrade to 2.3
Stephan Bosch
stephan at rename-it.nl
Wed Aug 8 19:04:36 EEST 2018
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 at 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 at 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 at internalinboundcm.eu",
> _toemail="test2 at internalinboundcm.eu",
> _tos="test2 at 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 at internalinboundcm.eu",
> _toemail="test2 at internalinboundcm.eu",
> _tos="test2 at internalinboundcm.eu", _size="80294", dip=172.20.44.3
> dport=24 type=lmtp msg="2.0.0 <test2 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at internalinboundcm.eu>
> RCPT TO:<test2 at internalinboundcm.eu>
> DATA
> ...truncated message
>
>
> .
> 250 2.0.0 <test2 at 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 at internalinboundcm.eu>
> RCPT TO:<test2 at internalinboundcm.eu>
> DATA
> ...truncated message
>
>
> .
> 250 2.0.0 <test2 at 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 at register.it
More information about the dovecot
mailing list