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

Gabriele Nencioni gabriele.nencioni at register.it
Tue Aug 7 10:35:44 EEST 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 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