[Dovecot] status=undeliverable (lost connection with mail.larptreff.de[private/dovecot-lmtp] while sending MAIL FROM)
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Good morning dovecot-community,
I noticed a strange log-entry since the last day:
Nov 7 08:34:42 hetzner postfix/lmtp[3764]: 61CB01A3938: to=jg+introversion@larptreff.de, relay=mail.larptreff.de[private/dovecot-lmtp], delay=0.05, delays=0.01/0.01/0.02/0.01, dsn=4.4.2, status=undeliverable (lost connection with mail.larptreff.de[private/dovecot-lmtp] while sending MAIL FROM)
Thankfully I've configured a cronjob for a daily pflogsumm-report, but I don't understand this. It worked for months like a charm.
It seems this only happens on mails with "+"-Delimiter.
In my opinion there is only one thing which could cause this problem: I updated my dovecot on 2013/11/04 from 2.2.6-1~auto+36 to 2.2.7-1~auto+2
maillog: http://pastebin.com/WDGfEjdp
doveconf -n: http://pastebin.com/ay6dxiUf
I will try to downgrade again, did someone have a clue? Changelog from 2.2.7 didn't show changes on lmtp.
Best regards, Jan -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJSe0cCAAoJENEKhqzzuxPlLOsH/iQLHuYXH/8HQJI1cyOQ/Xkl KK010kT9EwOZCax+xputF1Cyg9XSCGBwMBA8YFWjTk57EVfNZ4RZLCkpZQU8b0X/ SsDq7jyh8QTBf7K2LEs34L6g2OMbuhv3Hl+D/RqBm09HPoBUGJZEM5ZQu28QE7rD GETa3XkQPwMyo+3GwWXmAzg3wz4tOEGg6meaOzQlGVJshQpSKbDjvln5RtsVc1Qh X9Xa4HdEesH/NXxr6uKUUEjHcp67BLWvmZHrDDIOp4dATqxDbq29QGfiJFvURKur DJZ2hbPPgEFf/Wdf5l3PXfV2OgnubyLiTgRZ7pb+xFNUAlJ2YCeRv5CUigLaps8= =0Jya -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Additional note: Downgrade impossible because
http://xi.rename-it.nl/debian/
didn't have the 2.2.6 packages anymore. :( -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJSe0hjAAoJENEKhqzzuxPljrwH/0GGwoFVPZVEfqvM0QuvRduB qCu1MtscKaiSyaXp5m5I2kfZ0TJL1BcARMGEjeDaCULQf6Z3v197EDHCto9VL0eT acUCC1YnbKKiTmkETvIFP2zZwmkthur6hOOmGWn02SDvpIdiPq0nKMaD8fxTnETd r4dafw8fkTpEJXiEHk9AZv9xcTOdEbZz66gNb0gN3hNs5+uVF1wjznv1JfnFys1u JSufXKBmmASBzPqTsMmEJ9KT+IFEDzH5GWWo0RD15RgF8Lpr883XWfmX3WjK8Tbw Mbwfr+PinkAJ/B1DflzaIWfklNXReh298WdcUAZVL0aT9/Cg7xicHQ5RBrGhBl4= =kjqG -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 7 Nov 2013, Jan Phillip Greimann wrote:
maillog: http://pastebin.com/WDGfEjdp
are there some other log files, too? In it one sees that the recipient jg+introversion@larptreff.de is successfully interpreted as jg@larptreff.de and data seems to be good as well: maildir++: root=/var/vmail/larptreff.de/jg/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/larptreff.de/jg/Maildir
But I don't see any log entry about that a deliviery has been tried at all.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBUntTkV3r2wJMiz2NAQL7aQgApEPYGOhO5QQB/8xj0QbPHg7CIH8u2j5b GrbyXPTHjag5U+vIqooY8SkBzRzBAzN5RhWg0Ss3gy9dkxzukZWjb3jfF7nMrvGa AQ9q30nex0Lq/WTmzsEvsnSctwBCtggM2IQZbsz1uKBM1L2KaOY5Gp9CUsPqhN8A QHkxvHVllX6gxOFw6/RoFYnFrrbUHZ1dNA+iSkQfA44oiCC/fGQGOExsoq1ODZ2w Bahm31Ul5Yls1SquwHQEXraGhXxczPkBl7LPXwNiPM0p/t9ad/ItfonEQxBVGfS3 wMHMhH+iJaE8Qyc5G2Am6Z6mytWcidwAUj+BO/CYpgt5Hk2adpaJ2w== =Qaog -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Hello Steffen,
no other logs. :-/
That's even the only one with lmtp-debug-messages, now all log entries look like that:
http://pastebin.com/raw.php?i=zFeC9Ncr
I want to make a workaround in postfix like rewrite jg+*@larptreff.de -> jg@larptreff.de but I can't find a solution for relay-domains. (sending my mails via relay-domain to dovecot)
Regards Jan
Am 07.11.2013 09:47, schrieb Steffen Kaiser:
On Thu, 7 Nov 2013, Jan Phillip Greimann wrote:
maillog: http://pastebin.com/WDGfEjdp
are there some other log files, too? In it one sees that the recipient jg+introversion@larptreff.de is successfully interpreted as jg@larptreff.de and data seems to be good as well: maildir++: root=/var/vmail/larptreff.de/jg/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/larptreff.de/jg/Maildir
But I don't see any log entry about that a deliviery has been tried at all.
-- Steffen Kaiser
-----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJSe1l0AAoJENEKhqzzuxPl+msIAJ6EuLwig/M1G4XS7hUSvnjH /KtJYVF6Ove3a1iWqVyYk2DIxgJBDcyjJwmw+U6pjnoDxap1p+sgVpgcLwTBvV7v GVbwFNfoGKjarSVYAknH0LiLzw0DUCItzt2Ga7mU4ngeTopPnSK0Qvu0hMF1lnu+ HpHmwyJZC40A1d0BewoIciK6/R9ZFLsc325sShn8sFz77pWGyC0VR/tJ2Q0qKLcQ Yr8Fhs/+nsOkrkTxEJvhHJNaxnsnO2PBupKe57YOCl+awTlPbtIcpOJnqVgfKznO j5+qua0nPaifHTpmz7DCKlFAdM3jv25HQ6Ow0Nr6rE0cVftFs1GWjUWyDUDXB+o= =Dy+Z -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 7 Nov 2013, Jan Phillip Greimann wrote:
That's even the only one with lmtp-debug-messages, now all log entries look like that:
is this some sort of LMTP ahead to probe the recipient? Greylisting perhaps with local recipients? Does " decided action=PREPEND X-policyd-weight: using cached result;" mean that no action has been performed, but the negative result cached already will be returned. Do you have a corresponding lmtp log entry?
To test LMTP try this:
telnet to your LMTP port, or for an Unix socket:
socat - UNIX:/var/run/dovecot/lmtp
Then speak LMTP:
LHLO loc mail from:bounce-mc.us5_9954939.11045-jg+introversion=larptreff.de@mail33.wdc03.rsgsv.net rcpt to:jg+introversion@larptreff.de quit
and without the +detail in rcpt to. If you get to enter the QUIT without losing you connection, your postfix log entry does not makes sense to me. 2xx responses are successful, 4xx temporary error, 5xx errors. You should not see no other resonse codes.
See the Dovecot log and probably monitor the system for an abort or segfault of a Dovecot LMTP process.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBUnteFV3r2wJMiz2NAQIb4gf9G55K7x6znpmts4/5cg2YLq7de0rRF1DA Aunjb4nss66fGz/Dj3bHf4k8AyR4nkwhw4PrSTE+rtMNhAZu7qo9jL6gpS7B1X6o B6CXNg/tlM8QAR2p21Q42Aa4I+W6a9nVVzaAckrZbOfIaDb0qcDEcmBKlfujRDTU E76CWS6ZIadDXk1pTOz6S0VBmmaDY0Avavm+IyOUAYC8Y4DDmJZlAmKfzek055L3 qqP44V4p+dqvgVDu72F+Pv9Xsvag6y8lb39nJ1JUzpKBH52sC+l7TVs2EPsrrLwf aRj882qjnwqVX5NuFk1Rb05Ohj2chZnE/ByelKD4EUW7XZxk+LFp5g== =w8ZQ -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Am 07.11.2013 10:32, schrieb Steffen Kaiser:
On Thu, 7 Nov 2013, Jan Phillip Greimann wrote:
That's even the only one with lmtp-debug-messages, now all log entries look like that:
is this some sort of LMTP ahead to probe the recipient? Greylisting perhaps with local recipients? Does " decided action=PREPEND X-policyd-weight: using cached result;" mean that no action has been performed, but the negative result cached already will be returned. Do you have a corresponding lmtp log entry?
I've enabled dovecots debug-log after the problems happened, so there are no corresponding lmtp logs.
To test LMTP try this:
telnet to your LMTP port, or for an Unix socket:
socat - UNIX:/var/run/dovecot/lmtp
Then speak LMTP:
LHLO loc mail from:bounce-mc.us5_9954939.11045-jg+introversion=larptreff.de@mail33.wdc03.rsgsv.net
rcpt to:jg+introversion@larptreff.de quit
and without the +detail in rcpt to. If you get to enter the QUIT without losing you connection, your postfix log entry does not makes sense to me. 2xx responses are successful, 4xx temporary error, 5xx errors. You should not see no other resonse codes.
Okay, the log entries make no sense at all it seems. With socat it works like charm.
See the Dovecot log and probably monitor the system for an abort or segfault of a Dovecot LMTP process.
As far as I see there are no segfaults. Postfix and dovecot are logging to syslog --> mail.log, and there is only the given output.
Regards Jan -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJSe2LAAAoJENEKhqzzuxPllZUH/jm3eCAPMhnmGShj1V0qwZnA YbmrEfLBjqm8Yh3KMhmyzZLDF6wkv4JEFJJGpeHlfQ1yRuHb7QZ0/z0hVceQCkOp JSv7+o9QWurRMbQmcu/CzL5JFz2p9SLN4vRReAgXWmavCazwzgnzeoDzf705rajy 2rMlwwLn0VGVAykFP0IHTLL+ldWaCCur0A98mHe3lKeK9OOGbBrrdDoW+VSMQVUi x60vBHmcoN0L3EKXYyVC1G2BMPXNC/RiT4ElAjJCNA7M0kKyPtU5ZVsiiEUFYWm1 btrizND9+8bMI/T1axjw5Jv94HqKC6KIJMXprwipuXWUeA68snUIDy17wFqEa1U= =E8P3 -----END PGP SIGNATURE-----
On 7.11.2013, at 11.52, Jan Phillip Greimann jg@softjury.de wrote:
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Am 07.11.2013 10:32, schrieb Steffen Kaiser:
On Thu, 7 Nov 2013, Jan Phillip Greimann wrote:
That's even the only one with lmtp-debug-messages, now all log entries look like that:
is this some sort of LMTP ahead to probe the recipient? Greylisting perhaps with local recipients? Does " decided action=PREPEND X-policyd-weight: using cached result;" mean that no action has been performed, but the negative result cached already will be returned. Do you have a corresponding lmtp log entry?
I've enabled dovecots debug-log after the problems happened, so there are no corresponding lmtp logs.
Dovecot debug logs rarely help with any random problems you have, they’re mostly there to find out configuration mistakes. More interesting would be to know if you see ANY error/warning messages in Dovecot logs (Fatal, Panic, Error, Warning). You’ll also see the last 1000 error messages since dovecot started with “doveadm log errors”.
Timo Sirainen tss@iki.fi wrote:
Sorry, but neither my log files starting a week ago ...
More interesting would be to know if you see ANY error/warning messages in Dovecot logs (Fatal, Panic, Error, Warning).
... nor ...
You’ll also see the last 1000 error messages since dovecot started with “doveadm log errors”.
... show any messages, none. This is 2.2.7 (775b1e025939).
Regards, Michael
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Am 07.11.2013 19:30, schrieb Michael Grimm:
Timo Sirainen tss@iki.fi wrote:
Sorry, but neither my log files starting a week ago ...
More interesting would be to know if you see ANY error/warning messages in Dovecot logs (Fatal, Panic, Error, Warning).
... nor ...
You’ll also see the last 1000 error messages since dovecot started with “doveadm log errors”.
... show any messages, none. This is 2.2.7 (775b1e025939).
Regards, Michael
Same here, no errors or any logs. Only since 2.2.7.
Regards, Jan -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJSfKnPAAoJENEKhqzzuxPlWb8H/05dv4jQASaIYyKUi5CPRpNO /TXkUKBwqOVgGBo5mxW06ppfao6zICfEYQUS+Xk131CugXkfamCiFaZD/lHaa5ib dOz8wGuJuuZ9VXw4+J4GXpAIcxhV9OFNibehzpeHTmFe/1SmtS3iHoan85hHNqc6 cDcdCet7fF56yYBGcGNCf1uQvCxgVWcvKZ2QkyP6MfoOay8g88J1V+Di9iJTJzXz 9899lcWl8w2I6vUaexaw2o63s19POsjLHVbx7BPvDtF0ohG960yfGxIJ7qDTX3Kn D0AOIUanmsGgdXifUudJlMfh2KKAXuOhgHYa5ODM42g+8QNSKRddmQla5ARoSqw= =RPY6 -----END PGP SIGNATURE-----
- Jan Phillip Greimann jg@softjury.de 2013.11.08 10:07:
Same here, no errors or any logs. Only since 2.2.7.
Yep. Same here.
On 2013-11-07 4:12 AM, Jan Phillip Greimann jg@softjury.de wrote:
That's even the only one with lmtp-debug-messages, now all log entries look like that:
Please don't post configs, logs, etc to pastebin... just paste them inline.
Many people won't bother to click unknown/untrusted links, and it also will eventually break the list history (if the content is ever moved or removed from pastebin)...
--
Best regards,
*/Charles/*
On 2013-11-07 8:53, Jan Phillip Greimann wrote:
This is dovecot 2.2.7, postfix 2.10.2, all addresses type virtual mailbox domain class, and dovecot/lmtp delivery.
I noticed a strange log-entry since the last day:
Nov 7 08:34:42 hetzner postfix/lmtp[3764]: 61CB01A3938: to=jg+introversion@larptreff.de, relay=mail.larptreff.de[private/dovecot-lmtp], delay=0.05, delays=0.01/0.01/0.02/0.01, dsn=4.4.2, status=undeliverable (lost connection with mail.larptreff.de[private/dovecot-lmtp] while sending MAIL FROM)
I noticed as well, that some of my addresses lead to unusual rejections never anticipated before:
postfix/lmtp[1234]: 3dFbVw2NVmz6SL: to=example@example.com, relay=mx1.example.com[private/dovecot-lmtp], delay=0.04, delays=0.03/0/0/0.01, dsn=4.4.2, status=undeliverable (lost connection with mx1.example.com[private/dovecot-lmtp] while sending MAIL FROM)
It seems this only happens on mails with "+"-Delimiter.
In my case regular addresses are rejected as well (see example).
What I really do not understand is that out of e.g. 50 different recipient addresses of one virtual mailbox domain only a few are rejected, the other pass as usual. This is not random, some addresses pass always, others fail reproducible.
In my opinion there is only one thing which could cause this problem: I updated my dovecot on 2013/11/04 from 2.2.6-1~auto+36 to 2.2.7-1~auto+2
I updated two days ago.
I will try to downgrade again, did someone have a clue?
I have no clue what leads to those random rejections of recipient addresses. After setting ...
| warn_if_reject reject_unverified_recipient
... those mails are accepted. But I do consider this a temporary workaround.
Regards, Michael
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
In my opinion there is only one thing which could cause this problem: I updated my dovecot on 2013/11/04 from 2.2.6-1~auto+36 to 2.2.7-1~auto+2
I updated two days ago.
@Timo, did you changed something within LMTP? ;-D
I will try to downgrade again, did someone have a clue?
I have no clue what leads to those random rejections of recipient addresses. After setting ...
| warn_if_reject reject_unverified_recipient
... those mails are accepted. But I do consider this a temporary workaround.
This workaround did it for me too, hope this is considered as a bug and fixed soon.
Regards, Michael
Regards, Jan -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.12 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJSe2ZJAAoJENEKhqzzuxPlQdsH/Rtl1E3e6CkMqVxAZjgZ7TRs VaPaZLaAVefF7LdxNaiK71XNyXlgAOqJ9Hxr1x7QTO5Z6akMp40yAZF0cII7SD0j buTQ8QKoqWOra+J8S11SAYLqbHsi2N8DbOjQ1v+uXk4cweHSGmuAeLT5ZiHWdT/H 5ZN5LifbmCk7bSWyN53SvZiEC81/XMIdaSGuFxA3bpaxyoYlfvq1y569fQdDYTIJ da3kO4l0VaNDhcWGrR8pMr5PFAPF6Z/lw575M54IcMeWzrzgyDbXETOhN488D4xI +vd79wUakeivOPD0MOxutst93TExZmLr8sxsqFB6nREx75U2iEEbSgbgPsMg8oo= =CIQ6 -----END PGP SIGNATURE-----
Michael Grimm trashcan@odo.in-berlin.de wrote:
I noticed as well, that some of my addresses lead to unusual rejections never anticipated before:
That had been post 2.2.7 (775b1e025939):
postfix/lmtp[1234]: 3dFbVw2NVmz6SL: to=example@example.com, relay=mx1.example.com[private/dovecot-lmtp], delay=0.04, delays=0.03/0/0/0.01, dsn=4.4.2, status=undeliverable (lost connection with mx1.example.com[private/dovecot-lmtp] while sending MAIL FROM)
IMHO, it had been introduced by revision 10c0aae82d0d.
Back to release 2.2.7 (b5b118701aa8):
| postfix/lmtp[28069]: 3dLJQG3TxWzFbH: to=example@example.com,
| relay=mx1.example.com[private/dovecot-lmtp], delay=0.02,
| delays=0.01/0/0/0.02, dsn=2.1.5, status=deliverable (250 2.1.5 OK)
FYI and regards, Michael
On 15.11.2013, at 0.25, Michael Grimm trashcan@odo.in-berlin.de wrote:
Michael Grimm trashcan@odo.in-berlin.de wrote:
I noticed as well, that some of my addresses lead to unusual rejections never anticipated before:
That had been post 2.2.7 (775b1e025939):
postfix/lmtp[1234]: 3dFbVw2NVmz6SL: to=example@example.com, relay=mx1.example.com[private/dovecot-lmtp], delay=0.04, delays=0.03/0/0/0.01, dsn=4.4.2, status=undeliverable (lost connection with mx1.example.com[private/dovecot-lmtp] while sending MAIL FROM)
IMHO, it had been introduced by revision 10c0aae82d0d.
Hmm. What if you get the latest version and just reverse this one change? I won’t see any obvious reason why it would change this, but I guess it could be possible in less obvious ways. Is this reproduceable, i.e. are all of these Postfix checks always failing or just rarely or most of the time or ..? And was this only with the Postfix user existence check or were LMTP deliveries in general failing?
On 15.11.2013, at 00:35, Timo Sirainen tss@iki.fi wrote:
On 15.11.2013, at 0.25, Michael Grimm trashcan@odo.in-berlin.de wrote:
IMHO, it had been introduced by revision 10c0aae82d0d.
Hmm. What if you get the latest version and just reverse this one change?
How can I achieve that with hg, sorry I am not that familiar with hg. First "hg pull -u" and then?
I won’t see any obvious reason why it would change this, but I guess it could be possible in less obvious ways. Is this reproduceable, i.e. are all of these Postfix checks always failing or just rarely or most of the time or ..?
During my recent testing most if not all postfix user checks failed. I can't remember how many, sorry, because I also had to clean-up my postfix configuration as well.
And was this only with the Postfix user existence check or were LMTP deliveries in general failing?
It had been status=undeliverable, thus mails didn't become delivered in my case. Only after adding "warn_if_reject reject_unverified_recipient" in smtpd_recipient_restrictions they became delivered.
Regards, Michael
On 15.11.2013, at 0.52, Michael Grimm trashcan@odo.in-berlin.de wrote:
On 15.11.2013, at 00:35, Timo Sirainen tss@iki.fi wrote:
On 15.11.2013, at 0.25, Michael Grimm trashcan@odo.in-berlin.de wrote:
IMHO, it had been introduced by revision 10c0aae82d0d.
Hmm. What if you get the latest version and just reverse this one change?
How can I achieve that with hg, sorry I am not that familiar with hg. First "hg pull -u" and then?
cd …/dovecot-2.2 hg export 10c0aae82d0d > diff patch -p0 -R < diff
And was this only with the Postfix user existence check or were LMTP deliveries in general failing?
It had been status=undeliverable, thus mails didn't become delivered in my case. Only after adding "warn_if_reject reject_unverified_recipient" in smtpd_recipient_restrictions they became delivered.
But I think there were two steps: 1) During SMTP RCPT TO, check is mail can be delivered via LMTP RCPT TO, 2) actually deliver mail via LMTP. Where 1) failed (except with warn_if_reject), but 2) succeeded? Where both were basically doing the same thing, except I suppose with some actual difference. Or were the mails really not delivered via LMTP but something else?
On 15.11.2013, at 00:56, Timo Sirainen tss@iki.fi wrote:
On 15.11.2013, at 0.52, Michael Grimm trashcan@odo.in-berlin.de wrote:
On 15.11.2013, at 00:35, Timo Sirainen tss@iki.fi wrote:
On 15.11.2013, at 0.25, Michael Grimm trashcan@odo.in-berlin.de wrote:
IMHO, it had been introduced by revision 10c0aae82d0d.
Hmm. What if you get the latest version and just reverse this one change?
How can I achieve that with hg, sorry I am not that familiar with hg. First "hg pull -u" and then?
cd …/dovecot-2.2 hg export 10c0aae82d0d > diff patch -p0 -R < diff
Done, but I had to do answer (-->):
mail> patch -p0 -R < diff
Hmm... Looks like a unified diff to me...
The text leading up to this was:
--------------------------
|# HG changeset patch
|# User Timo Sirainen <tss@iki.fi>
|# Date 1383514035 -7200
|# Sun Nov 03 23:27:15 2013 +0200
|# Node ID 10c0aae82d0dee0b0107c2262db50d5f6984c181
|# Parent 653d5a81a22e73ff91264f7e7277b1c0206574ec
|ostream: Mark stream closed before handling its callback to avoid infinite loops.
|The callback could call o_stream_copy_error_from_parent(), which in turn
|would try to close the same ostream again.
|
|diff -r 653d5a81a22e -r 10c0aae82d0d src/lib/ostream.c
|--- a/src/lib/ostream.c Sun Nov 03 22:04:53 2013 +0200
|+++ b/src/lib/ostream.c Sun Nov 03 23:27:15 2013 +0200
----------------------------> File to patch: src/lib/ostream.c Patching file src/lib/ostream.c using Plan A... Hunk #1 succeeded at 46. done
Dovecot v2.2.7 (87ff0023fe79+) starting up. And I can confirm, that again, no status=undeliverable show up.
And was this only with the Postfix user existence check or were LMTP deliveries in general failing?
It had been status=undeliverable, thus mails didn't become delivered in my case. Only after adding "warn_if_reject reject_unverified_recipient" in smtpd_recipient_restrictions they became delivered.
But I think there were two steps: 1) During SMTP RCPT TO, check is mail can be delivered via LMTP RCPT TO, 2) actually deliver mail via LMTP. Where 1) failed (except with warn_if_reject), but 2) succeeded? Where both were basically doing the same thing, except I suppose with some actual difference. Or were the mails really not delivered via LMTP but something else?
I am not sure, if I do understand you correctly. My setup is:
postfix smtpd dovecot/lmtp user authentication postfix --> amavisd amavisd/lmtp --> postfix final deliver by dovecot/lmtp
Here's a log excerpt with v2.2.7 (87ff0023fe79+):
postfix/smtpd[66223]: connect from example.org[10.100.100.200]
postfix/smtpd[66223]: Anonymous TLS connection established from example.org[10.100.100.200]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
Nov 15 01:14:29
HTH, Michael
Is there more detail needed to finally solve this? The temporary fails caused by LMTP not reaching the 'RCPT TO' stage get pretty annoying in the light of backscatter hitting the server:
Nov 19 08:16:09 spectre postfix/smtpd[21386]: NOQUEUE: reject: RCPT from emea01-am1-ndr.ptr.protection.outlook.com[157.56.116.99]: 450 4.1.1 DC21DEC5-D7F9-41FE-B16C-1ECC8536C40F@leuxner.net: Recipient address rejected: unverified address: lost connection with spectre.leuxner.net[private/dovecot-lmtp] while sending MAIL FROM; from=cocacola0004@mentesbrim.onmicrosoft.com to=DC21DEC5-D7F9-41FE-B16C-1ECC8536C40F@leuxner.net proto=ESMTP helo=
To reproduce simply add 'reject_unverified_recipient' to 'smtpd_recipient_restrictions'...
Thomas Leuxner skrev den 2013-11-19 08:35:
Is there more detail needed to finally solve this? The temporary fails caused by LMTP not reaching the 'RCPT TO' stage get pretty annoying in the light of backscatter hitting the server:
Nov 19 08:16:09 spectre postfix/smtpd[21386]: NOQUEUE: reject: RCPT from emea01-am1-ndr.ptr.protection.outlook.com[157.56.116.99]: 450 4.1.1 DC21DEC5-D7F9-41FE-B16C-1ECC8536C40F@leuxner.net: Recipient address rejected: unverified address: lost connection with spectre.leuxner.net[private/dovecot-lmtp] while sending MAIL FROM; from=cocacola0004@mentesbrim.onmicrosoft.com to=DC21DEC5-D7F9-41FE-B16C-1ECC8536C40F@leuxner.net proto=ESMTP helo=
To reproduce simply add 'reject_unverified_recipient' to 'smtpd_recipient_restrictions'...
is dovecot knowing all alias addresses ?, with dovecot-lda its done in postfix before delivering to dovecot-lda, so if the recipient here is a valid mailbox it should work, but i think dovecot needs alias support to be used same way as postfix does
when it works it would be a dream, seems we are not there yet
Maybe http://hg.dovecot.org/dovecot-2.2/rev/5f946b807706 solves this also? I’m not sure why it started happening with v2.2.7 though.
On 15.11.2013, at 2.31, Michael Grimm trashcan@odo.in-berlin.de wrote:
On 15.11.2013, at 00:56, Timo Sirainen tss@iki.fi wrote:
On 15.11.2013, at 0.52, Michael Grimm trashcan@odo.in-berlin.de wrote:
On 15.11.2013, at 00:35, Timo Sirainen tss@iki.fi wrote:
On 15.11.2013, at 0.25, Michael Grimm trashcan@odo.in-berlin.de wrote:
IMHO, it had been introduced by revision 10c0aae82d0d.
Hmm. What if you get the latest version and just reverse this one change?
How can I achieve that with hg, sorry I am not that familiar with hg. First "hg pull -u" and then?
cd …/dovecot-2.2 hg export 10c0aae82d0d > diff patch -p0 -R < diff
Done, but I had to do answer (-->):
mail> patch -p0 -R < diff Hmm... Looks like a unified diff to me... The text leading up to this was:
|# HG changeset patch |# User Timo Sirainen tss@iki.fi |# Date 1383514035 -7200 |# Sun Nov 03 23:27:15 2013 +0200 |# Node ID 10c0aae82d0dee0b0107c2262db50d5f6984c181 |# Parent 653d5a81a22e73ff91264f7e7277b1c0206574ec |ostream: Mark stream closed before handling its callback to avoid infinite loops. |The callback could call o_stream_copy_error_from_parent(), which in turn |would try to close the same ostream again. | |diff -r 653d5a81a22e -r 10c0aae82d0d src/lib/ostream.c |--- a/src/lib/ostream.c Sun Nov 03 22:04:53 2013 +0200 |+++ b/src/lib/ostream.c Sun Nov 03 23:27:15 2013 +0200
--> File to patch: src/lib/ostream.c Patching file src/lib/ostream.c using Plan A... Hunk #1 succeeded at 46. done
Dovecot v2.2.7 (87ff0023fe79+) starting up. And I can confirm, that again, no status=undeliverable show up.
And was this only with the Postfix user existence check or were LMTP deliveries in general failing?
It had been status=undeliverable, thus mails didn't become delivered in my case. Only after adding "warn_if_reject reject_unverified_recipient" in smtpd_recipient_restrictions they became delivered.
But I think there were two steps: 1) During SMTP RCPT TO, check is mail can be delivered via LMTP RCPT TO, 2) actually deliver mail via LMTP. Where 1) failed (except with warn_if_reject), but 2) succeeded? Where both were basically doing the same thing, except I suppose with some actual difference. Or were the mails really not delivered via LMTP but something else?
I am not sure, if I do understand you correctly. My setup is:
postfix smtpd dovecot/lmtp user authentication postfix --> amavisd amavisd/lmtp --> postfix final deliver by dovecot/lmtp
Here's a log excerpt with v2.2.7 (87ff0023fe79+):
postfix/smtpd[66223]: connect from example.org[10.100.100.200] postfix/smtpd[66223]: Anonymous TLS connection established from example.org[10.100.100.200]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits) Nov 15 01:14:29
example.org sendmail[66221]: STARTTLS=client, relay=[10.100.100.1], version=TLSv1/SSLv3, verify=FAIL, cipher=DHE-RSA-AES256-SHA, bits=256/256 postfix/cleanup[66227]: 3dLKn10bdfzFNF: message-id=3dLKn10bdfzFNF@mx2.example.com postfix/qmgr[64303]: 3dLKn10bdfzFNF: from=double-bounce@example.com, size=241, nrcpt=1 (queue active) dovecot: lmtp(66091): Connect from local dovecot: lmtp(66091): Disconnect from local: Successful quit postfix/lmtp[66228]: 3dLKn10bdfzFNF: to=localuser@example.com, orig_to=example@example.com, relay=mx2.example.com[private/dovecot-lmtp], delay=0.04, delays=0.02/0/0/0.02, dsn=2.1.5, status=deliverable (250 2.1.5 OK) postfix/qmgr[64303]: 3dLKn10bdfzFNF: removed Nov 15 01:14:32 mail.example.invalid postfix/smtpd[66223]: 3dLKn40f9wzFNG: client=example.org[10.100.100.200] Nov 15 01:14:32 mail.example.invalid postfix/cleanup[66227]: 3dLKn40f9wzFNG: message-id=201311150014.rAF0ETps066221@example.org Nov 15 01:14:32 example.org sendmail[66221]: rAF0ETps066221: to=example@example.com, ctladdr=root (0/0), delay=00:00:03, xdelay=00:00:03, mailer=relay, pri=30047, relay=[10.100.100.1] [10.100.100.1], dsn=2.0.0, stat=Sent (Ok: queued as 3dLKn40f9wzFNG) Nov 15 01:14:32 mail.example.invalid postfix/qmgr[64303]: 3dLKn40f9wzFNG: from=root@example.org, size=616, nrcpt=1 (queue active) Nov 15 01:14:32 mail.example.invalid postfix/smtpd[66223]: disconnect from example.org[10.100.100.200] Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) loaded policy bank "MYNETS" Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) LMTP::10024 /var/amavis/tmp/amavis-20131115T011432-66086-mM3ZSPVh: root@example.net -> localuser@example.com SIZE=616 Received: from mx2.example.com ([10.100.100.1]) by mx2.example.com (mx2.example.com [10.100.100.1]) (amavisd-new, port 10024) with LMTP for localuser@example.com; Fri, 15 Nov 2013 01:14:32 +0100 (CET) Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) Checking: CYYtr0l_C3qa MYNETS [10.100.100.200] root@example.net -> localuser@example.com Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) p001 1 Content-Type: text/plain, size: 3 B, name: Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) wbl: whitelisted sender root@example.net Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) spam-tag, root@example.net -> localuser@example.com, No, score=x tagged_above=-999 required=6.2 WHITELISTED tests=[] autolearn=unavailable Nov 15 01:14:32 mail.example.invalid postfix/smtpd[66232]: connect from mail.example.invalid[10.100.100.1] Nov 15 01:14:32 mail.example.invalid postfix/smtpd[66232]: 3dLKn42SQHzFNR: client=mail.example.invalid[10.100.100.1], orig_queue_id=3dLKn40f9wzFNG, orig_client=example.org[10.100.100.200] Nov 15 01:14:32 mail.example.invalid postfix/cleanup[66227]: 3dLKn42SQHzFNR: message-id=201311150014.rAF0ETps066221@example.org Nov 15 01:14:32 mail.example.invalid postfix/qmgr[64303]: 3dLKn42SQHzFNR: from=root@example.net, size=1266, nrcpt=1 (queue active) Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) FWD from root@example.net -> localuser@example.com,BODY=7BIT 250 2.0.0 from MTA(smtp:[10.100.100.1]:10025): 250 2.0.0 Ok: queued as 3dLKn42SQHzFNR Nov 15 01:14:32 mail.example.invalid dovecot: lmtp(66091): Connect from local Nov 15 01:14:32 mail.example.invalid dovecot: lmtp(66091, localuser): copy from <lmtp DATA>: box=INBOX, uid=475527, msgid=201311150014.rAF0ETps066221@example.org, flags=() Nov 15 01:14:32 mail.example.invalid dovecot: lmtp(66091, localuser): QoteB2VnhVIrAgEASjbbSg: sieve: msgid=201311150014.rAF0ETps066221@example.org: stored mail into mailbox 'INBOX' Nov 15 01:14:32 mail.example.invalid postfix/lmtp[66228]: 3dLKn42SQHzFNR: to=localuser@example.com, relay=mx2.example.com[private/dovecot-lmtp], delay=0.12, delays=0.02/0/0/0.1, dsn=2.0.0, status=sent (250 2.0.0 localuser@example.com QoteB2VnhVIrAgEASjbbSg Saved) Nov 15 01:14:32 mail.example.invalid dovecot: lmtp(66091): Disconnect from local: Successful quit Nov 15 01:14:32 mail.example.invalid postfix/qmgr[64303]: 3dLKn42SQHzFNR: removed Nov 15 01:14:32 mail.example.invalid amavis[66086]: (66086-01) Passed CLEAN {RelayedInternal}, MYNETS LOCAL [10.100.100.200]:40204 [10.100.100.200] root@example.net -> localuser@example.com, Queue-ID: 3dLKn40f9wzFNG, Message-ID: 201311150014.rAF0ETps066221@example.org, mail_id: CYYtr0l_C3qa, Hits: -, size: 608, queued_as: 3dLKn42SQHzFNR, 290 ms Nov 15 01:14:32 mail.example.invalid postfix/lmtp[66230]: 3dLKn40f9wzFNG: to=localuser@example.com, orig_to=example@example.com, relay=10.100.100.1[10.100.100.1]:10024, delay=3.4, delays=3.1/0/0/0.29, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[10.100.100.1]:10025): 250 2.0.0 Ok: queued as 3dLKn42SQHzFNR) Nov 15 01:14:32 mail.example.invalid postfix/qmgr[64303]: 3dLKn40f9wzFNG: removed HTH, Michael
- Timo Sirainen tss@iki.fi 2013.11.19 16:22:
Maybe http://hg.dovecot.org/dovecot-2.2/rev/5f946b807706 solves this also? I’m not sure why it started happening with v2.2.7 though.
Nov 19 17:01:13 spectre postfix/qmgr[627]: 3dPBbY13b0z1s: from=double-bounce@spectre.leuxner.net, size=271, nrcpt=1 (queue active) Nov 19 17:01:13 spectre postfix/smtpd[6870]: 3dPBbY1566z1w: client=sam.dfn-cert.de[193.174.13.196] Nov 19 17:01:13 spectre postfix/lmtp[6877]: 3dPBbY13b0z1s: to=tlx@leuxner.net, orig_to=security@leuxner.net, relay=spectre.leuxner.net[private/dovecot-lmtp], delay=0.01, delays=0/0/0/0.01, dsn=2.1.5, status=deliverable (250 2.1.5 OK)
First tests look good. Thanks for looking into this.
Timo Sirainen tss@iki.fi wrote:
Maybe http://hg.dovecot.org/dovecot-2.2/rev/5f946b807706 solves this also? I’m not sure why it started happening with v2.2.7 though.
That did the trick. No more status=undeliverable here as well.
Thanks and regards, Michael
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Am 19.11.2013 16:22, schrieb Timo Sirainen:
Maybe http://hg.dovecot.org/dovecot-2.2/rev/5f946b807706 solves this also? I’m not sure why it started happening with v2.2.7 though.
Hi Timo,
Is this patch included in v2.2.8? I will still wait for a v2.2.8 stable-build on xi.rename-it.nl.
Best regards Jan -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.14 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iQEcBAEBAgAGBQJSjKCEAAoJENEKhqzzuxPl/moH/32ob9kzWYrpBihUGYSx9p/V Bk4z3I2FGc3Mvq2WKkZ9+82KoJ2PZAOn7Z16g0J6MLTyjVuSdluj2HZRNRVgLNaY 58cnp9BfrBDFa8ZAQ3a1L6/p4JH522NiihDO0l1q7x5sLRsBvgMPuC5GHhXPt/sQ H1gaymLQST4PBH+0xNuh3a7AWH//vCN3eGcSthj2HFg04JyOh+KUqiLO8SgggqQp QLL6cnSlNFBCVbNxdw0I3tsReDHExNXTF+PukDoZEt3lYtEPs9VbiIm3UrY6XqfA z+ELS4lcJHbBhsFCqjDLS9PmQoyDwaCImQER0lp0ZwXgsUlum4UYGJTU/LselAY= =nHaC -----END PGP SIGNATURE-----
Jan Phillip Greimann jg@softjury.de wrote:
Am 19.11.2013 16:22, schrieb Timo Sirainen:
Is this patch included in v2.2.8?
Yes, it is.
Regards, Michael
participants (7)
-
Benny Pedersen
-
Charles Marcus
-
Jan Phillip Greimann
-
Michael Grimm
-
Steffen Kaiser
-
Thomas Leuxner
-
Timo Sirainen