dovecot - Jul 2013 - mails delivered to the wrong user when using lmtp_proxy and reject_unverified_recipient

Hi,

looks like we detected a serious bug in dovecot's lmtp proxying where
e-mails are delivered to the wrong user.

The setup is:

*) Dovecot is configured with "lmtp_proxy=yes"

# Support proxying to other LMTP/SMTP servers by performing passdb lookups.
lmtp_proxy = yes

*) Postfix uses "dynamic recipient verification", so Postfix starts
sending a (verify) mail by LMTP to dovecot, but quits the lmtp-session
right after the RCPT TO:. No DATA-stage is reached in the protocol and
no real e-mail is sent. But Postfix had a LMTP-connection for "user1".

*) Just some seconds later a "real" e-mail to "user2" has to
be
delivered to dovecot by LMTP. But Dovecot will deliver this mail to the
wrong "user1" instead of "user2". Looks like dovecot re-uses
the (still
opened?) lmtp-proxy-connection from "user1" to deliver an e-mail to
"user2".

Have a log at the protocol:

1) There's a verify call to user1 from Postfix:

Jul 19 13:49:49 mailms postfix/lmtp[9842]: DE653280C51:
to=<user1 at example.com>, relay=localhost[127.0.0.1]:24, conn_use=2,
delay=120, delays=117/0.45/0/2.5, dsn=2.1.5, status=deliverable (250
2.1.5 OK)

2) Just five seconds later the e-mail to user2 (see Postfix' point of
view in the last line) is delivered to user2 (see result from Dovecot in
the last line):

Jul 19 13:50:04 mailms dovecot: lmtp(10965, kraemer): save: box=INBOX,
uid=49880, msgid=<59798276-E5D1-4053-A570-9901B731DF5D at example.come>,
size=11020
Jul 19 13:50:04 mailms dovecot: lmtp(10965, kraemer):
1zTeKrMn6VHVKgAAhyqEuA:
msgid=<59798276-E5D1-4053-A570-9901B731DF5D at example.com>: saved mail to
INBOX
Jul 19 13:50:04 mailms postfix/lmtp[10953]: C25FC280BE5:
to=<user2 at example.com>, relay=localhost[127.0.0.1]:24, conn_use=19,
delay=116, delays=115/0.53/0/0.33, dsn=2.0.0, status=sent (250 2.0.0
<user2> 1zTeKrMn6VHVKgAAhyqEuA Saved)


Same with user3 and user4:

Jul 19 14:47:53 mailms postfix/lmtp[10845]: C389A2809D7:
to=<user3 at example.com>, relay=localhost[127.0.0.1]:24, delay=4.7,
delays=3.7/0.87/0/0.19, dsn=2.1.5, status=deliverable (250 2.1.5 OK)
Jul 19 14:47:55 mailms dovecot: lmtp(26546, fs211113): save: box=INBOX,
uid=8504, msgid=<928729810.113.1374238063381 at example.com>, size=233151
Jul 19 14:47:55 mailms dovecot: lmtp(26546, fs211113):
MbMvI2816VGyZwAAhyqEuA: msgid=<928729810.113.1374238063381 at
example.com>:
saved mail to INBOX
Jul 19 14:47:55 mailms postfix/lmtp[22524]: 6F0D2280A6E:
to=<user4 at example.com>, relay=localhost[127.0.0.1]:24, conn_use=2,
delay=10, delays=8.4/1/0/0.8, dsn=2.0.0, status=sent (250 2.0.0 <user3>
MbMvI2816VGyZwAAhyqEuA Saved)



The user itself is quite normal in the user database (but has a
mailhost=127.0.0.1 set):

root at mailms:/etc/dovecot/conf.d# doveadm user user2 at example.com
userdb: user2 at example.com
  uid       : 5000
  gid       : 5000
  home      : /srv/mail/user2

root at mailms:/etc/dovecot/conf.d# doveadm auth user2 at example.com
Password:
passdb: user2 at example.com auth failed
extra fields:
  user=user2

Peer


-- 
Heinlein Support GmbH
Schwedter Str. 8/9b, 10119 Berlin

http://www.heinlein-support.de

Tel: 030 / 405051-42
Fax: 030 / 405051-19

Zwangsangaben lt. ?35a GmbHG: HRB 93818 B / Amtsgericht
Berlin-Charlottenburg,
Gesch?ftsf?hrer: Peer Heinlein -- Sitz: Berlin

doveconf -n and postconf -n output might shed some light?

On 2013-07-19 11:11 AM, Peer Heinlein <p.heinlein at heinlein-support.de> 
wrote:
> Hi,
>
> looks like we detected a serious bug in dovecot's lmtp proxying where
> e-mails are delivered to the wrong user.
>
> The setup is:
>
> *) Dovecot is configured with "lmtp_proxy=yes"
>
> # Support proxying to other LMTP/SMTP servers by performing passdb lookups.
> lmtp_proxy = yes
>
> *) Postfix uses "dynamic recipient verification", so Postfix
starts
> sending a (verify) mail by LMTP to dovecot, but quits the lmtp-session
> right after the RCPT TO:. No DATA-stage is reached in the protocol and
> no real e-mail is sent. But Postfix had a LMTP-connection for
"user1".
>
> *) Just some seconds later a "real" e-mail to "user2"
has to be
> delivered to dovecot by LMTP. But Dovecot will deliver this mail to the
> wrong "user1" instead of "user2". Looks like dovecot
re-uses the (still
> opened?) lmtp-proxy-connection from "user1" to deliver an e-mail
to "user2".
>
> Have a log at the protocol:
>
> 1) There's a verify call to user1 from Postfix:
>
> Jul 19 13:49:49 mailms postfix/lmtp[9842]: DE653280C51:
> to=<user1 at example.com>, relay=localhost[127.0.0.1]:24, conn_use=2,
> delay=120, delays=117/0.45/0/2.5, dsn=2.1.5, status=deliverable (250
> 2.1.5 OK)
>
> 2) Just five seconds later the e-mail to user2 (see Postfix' point of
> view in the last line) is delivered to user2 (see result from Dovecot in
> the last line):
>
> Jul 19 13:50:04 mailms dovecot: lmtp(10965, kraemer): save: box=INBOX,
> uid=49880, msgid=<59798276-E5D1-4053-A570-9901B731DF5D at
example.come>,
> size=11020
> Jul 19 13:50:04 mailms dovecot: lmtp(10965, kraemer):
> 1zTeKrMn6VHVKgAAhyqEuA:
> msgid=<59798276-E5D1-4053-A570-9901B731DF5D at example.com>: saved
mail to
> INBOX
> Jul 19 13:50:04 mailms postfix/lmtp[10953]: C25FC280BE5:
> to=<user2 at example.com>, relay=localhost[127.0.0.1]:24,
conn_use=19,
> delay=116, delays=115/0.53/0/0.33, dsn=2.0.0, status=sent (250 2.0.0
> <user2> 1zTeKrMn6VHVKgAAhyqEuA Saved)
>
>
> Same with user3 and user4:
>
> Jul 19 14:47:53 mailms postfix/lmtp[10845]: C389A2809D7:
> to=<user3 at example.com>, relay=localhost[127.0.0.1]:24, delay=4.7,
> delays=3.7/0.87/0/0.19, dsn=2.1.5, status=deliverable (250 2.1.5 OK)
> Jul 19 14:47:55 mailms dovecot: lmtp(26546, fs211113): save: box=INBOX,
> uid=8504, msgid=<928729810.113.1374238063381 at example.com>,
size=233151
> Jul 19 14:47:55 mailms dovecot: lmtp(26546, fs211113):
> MbMvI2816VGyZwAAhyqEuA: msgid=<928729810.113.1374238063381 at
example.com>:
> saved mail to INBOX
> Jul 19 14:47:55 mailms postfix/lmtp[22524]: 6F0D2280A6E:
> to=<user4 at example.com>, relay=localhost[127.0.0.1]:24, conn_use=2,
> delay=10, delays=8.4/1/0/0.8, dsn=2.0.0, status=sent (250 2.0.0
<user3>
> MbMvI2816VGyZwAAhyqEuA Saved)
>
>
>
> The user itself is quite normal in the user database (but has a
> mailhost=127.0.0.1 set):
>
> root at mailms:/etc/dovecot/conf.d# doveadm user user2 at example.com
> userdb: user2 at example.com
>    uid       : 5000
>    gid       : 5000
>    home      : /srv/mail/user2
>
> root at mailms:/etc/dovecot/conf.d# doveadm auth user2 at example.com
> Password:
> passdb: user2 at example.com auth failed
> extra fields:
>    user=user2
>
> Peer
>
>

-- 

Best regards,

Charles Marcus
I.T. Director
Media Brokers International, Inc.
678.514.6224 | 678.514.6299 fax

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Fri, 19 Jul 2013, Peer Heinlein wrote:
> looks like we detected a serious bug in dovecot's lmtp proxying where
> e-mails are delivered to the wrong user.
>
> The setup is:
>
> *) Dovecot is configured with "lmtp_proxy=yes"
>
> # Support proxying to other LMTP/SMTP servers by performing passdb lookups.
> lmtp_proxy = yes
>
> *) Postfix uses "dynamic recipient verification", so Postfix
starts
> sending a (verify) mail by LMTP to dovecot, but quits the lmtp-session
> right after the RCPT TO:. No DATA-stage is reached in the protocol and
> no real e-mail is sent. But Postfix had a LMTP-connection for
"user1".
>
> *) Just some seconds later a "real" e-mail to "user2"
has to be
> delivered to dovecot by LMTP. But Dovecot will deliver this mail to the
> wrong "user1" instead of "user2". Looks like dovecot
re-uses the (still
> opened?) lmtp-proxy-connection from "user1" to deliver an e-mail
to "user2".
Is the communication between postfix and Dovecot LMTP encrypted? If not, 
can you trace the LMTP transmission using something like wireshark or 
strace? So one get the impression of:

+ how many connections uses postfix to communicate with LMTP
+ which LMTP commands are transmitted in which order on which connection

- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

iQEVAwUBUezjJF3r2wJMiz2NAQJNAwf/RfmOLlAb1BTw/b2hSNGPiz/USdrQUQhw
6ryPDZdOY89ajemNUbKgXDHUPQb1fgjex3magY1Ri2xLW0fQVZdggF6d4T5+vpD3
E+TMfd2go0Dnp9GeVi+As7EcrXBfuN/9hwnkdAnyBDNEwZMmHORXpu5OseGMZqWD
CsK8hvdbcsqMycy1pP0r+gOWm63nRQ0phn4l18zd5r7181kYGn87V3nV8gF5rAXi
U0uyzHhyia/YV6Gto34MEsL4oRUeBxQFBkbYGKstbBofOLlk955bJRNyOI2Toid7
ehkcTfWPmJoI1MlBur0bMPJZ2fefLce0Dy17sv6l/H4SQyp4p/VDMA==T+dr
-----END PGP SIGNATURE-----

On 19.7.2013, at 18.11, Peer Heinlein <p.heinlein at heinlein-support.de>
wrote:
> looks like we detected a serious bug in dovecot's lmtp proxying where
> e-mails are delivered to the wrong user.
> 
> The setup is:
> 
> *) Dovecot is configured with "lmtp_proxy=yes"
> 
> # Support proxying to other LMTP/SMTP servers by performing passdb lookups.
> lmtp_proxy = yes
> 
> *) Postfix uses "dynamic recipient verification", so Postfix
starts
> sending a (verify) mail by LMTP to dovecot, but quits the lmtp-session
> right after the RCPT TO:. No DATA-stage is reached in the protocol and
> no real e-mail is sent. But Postfix had a LMTP-connection for
"user1".
> 
> *) Just some seconds later a "real" e-mail to "user2"
has to be
> delivered to dovecot by LMTP. But Dovecot will deliver this mail to the
> wrong "user1" instead of "user2". Looks like dovecot
re-uses the (still
> opened?) lmtp-proxy-connection from "user1" to deliver an e-mail
to "user2".
As others mentioned, seeing what Postfix <-> Dovecot (and Dovecot proxy
<-> Dovecot backend) talk to each others would help. I can't reproduce
this in an easy way and the code looks correct also: All proxied connections are
dropped on LHLO and RSET. The proxy connections also aren't being reused
between different incoming LMTP connections.