Message delivered twice caused by an LMTP error "Got unexpected reply" during upgrade to 2.3

7 Aug 2018


      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

Gabriele Nencioni

Thanks in advance Regards,

Stephan Bosch

Thanks in advance Regards,

Gabriele Nencioni

Regards

tags

participants (2)