Re: question on lmtp logged message
Em 03/07/14 14:31, Timo Sirainen escreveu: On 25.6.2014, at 18.45, Leonardo Rodrigues wrote: I have dovecot running for IMAP4/POP3 and also local delivery through LMTP. It's working just fine, absolutely no problem on that, setup is fine. Anyway, sometimes LMTP seems to not be able to deliver some messages and keep them on postfixqueue. And on the next or third try, the message gets delivered successfully. The logged message, however, is not helping me identify what is happening.Example: (error - message was expunged) Jun 25 11:49:39 correio postfix/lmtp[21835]: ADB0A1AC05108: to=, relay=correio.domain.com.br[private/dovecot-lmtp], conn_use=6, delay=13, delays=0.07/0/0/13, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) I guess the only good fix for this is to just get rid of this deduplication feature for now: http://hg.dovecot.org/dovecot-2.2/rev/51274bf2a47d Hopefully people don't rely on this feature too much. Timo, Is it expected deliveries through LMTP to get slower with this patch ? I mean ... despite i was seeing the 'message was expunged' some few times a day, after applying the patch they really dissapear, but my deliveries starts to apparently get slower. I dont have real numbers to prove that, i can only guanratee that my queues are starting to grow up a lot with to-be-local-delivered messages. I experienced that last week after running the patched version for some hours. Reverted to plain 2.2.13 and queues were successfully emptied after some minutes. This weekend i installed the 2.2.13 patched one again and, by this morning, queues are growing again. I really do not understand dovecot internals and, sincerily, dont even know if i'm using some feature that depends on deduplication. Fact is that i'm running a pretty busy server and those 'message was expunged' situations werent a real problem. When it happened, message would be on the queue and probably delivered some minutes later, on the 1st or 2nd queue run after that. But if removing this deduplication tests/feature will slow down that much the deliveries, i'm afraid that, overall, the non-patched version is better to me. -- Atenciosamente / Sincerily, Leonardo Rodrigues Solutti Tecnologia http://www.solutti.com.br Minha armadilha de SPAM, NÃO mandem email gertru...@solutti.com.br My SPAMTRAP, do not email it
Re: question on lmtp logged message
Em 03/07/14 14:31, Timo Sirainen escreveu: On 25.6.2014, at 18.45, Leonardo Rodrigues wrote: I have dovecot running for IMAP4/POP3 and also local delivery through LMTP. It's working just fine, absolutely no problem on that, setup is fine. Anyway, sometimes LMTP seems to not be able to deliver some messages and keep them on postfixqueue. And on the next or third try, the message gets delivered successfully. The logged message, however, is not helping me identify what is happening.Example: (error - message was expunged) Jun 25 11:49:39 correio postfix/lmtp[21835]: ADB0A1AC05108: to=, relay=correio.domain.com.br[private/dovecot-lmtp], conn_use=6, delay=13, delays=0.07/0/0/13, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) I guess the only good fix for this is to just get rid of this deduplication feature for now: http://hg.dovecot.org/dovecot-2.2/rev/51274bf2a47d Hopefully people don't rely on this feature too much. Hi Timo, I patched the 2.2.13 tree source, recompiled and installed. I'll let it run for some days and look again if the messages dissapeared. I'm still getting some few of these everyday, so noticing if they dissapeared or continue to happen will be easy. -- Atenciosamente / Sincerily, Leonardo Rodrigues Solutti Tecnologia http://www.solutti.com.br Minha armadilha de SPAM, NÃO mandem email gertru...@solutti.com.br My SPAMTRAP, do not email it
Re: question on lmtp logged message
On 25.6.2014, at 18.45, Leonardo Rodrigues wrote: >I have dovecot running for IMAP4/POP3 and also local delivery through > LMTP. It's working just fine, absolutely no problem on that, setup is fine. > >Anyway, sometimes LMTP seems to not be able to deliver some messages and > keep them on postfixqueue. And on the next or third try, the message gets > delivered successfully. The logged message, however, is not helping me > identify what is happening.Example: > > (error - message was expunged) > Jun 25 11:49:39 correio postfix/lmtp[21835]: ADB0A1AC05108: > to=, > relay=correio.domain.com.br[private/dovecot-lmtp], conn_use=6, delay=13, > delays=0.07/0/0/13, dsn=4.2.0, status=deferred (host > correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 > Message was expunged (received-date) (in > reply to end of DATA command)) I guess the only good fix for this is to just get rid of this deduplication feature for now: http://hg.dovecot.org/dovecot-2.2/rev/51274bf2a47d Hopefully people don't rely on this feature too much.
Re: question on lmtp logged message
Hi Steffen, Em 26/06/14 11:06, Steffen Kaiser escreveu: maildir_copy_with_hardlinks is set on my server, too. It's the default now. I do not see these errors. Can you check if the failed recipient is _never_ the first one? I remember some discussions about that the Dovecot LDA has to re-open the storred message of the first recipient, in order to spool it for the other ones. That caused problems because the server used an user-specific encryption key. If that applies to LMTP, too, this might become problematic, if the first recipient deletes the message very quickly. Therefore my question, if the error pops up for the second recipient and maybe all following ones. Just did some more scripting and got a total of 1413 distinct emails (distinct queueids) that suffered from this 'message was expunged' problem on the 36 hours i got the problems. As noted before, not even a single one of these 1413 were nrcpt=1. Problems were from nrcpt=2 or greater. So, whatever this is, it really seems to NOT affect single recipient messages. As you suspected, on those 1413 the very first recipient ALWAYS got a status=sent from dovecot/lmtp. "Message was expunged" never happened on the very first recipient delivery. About the first user (the first delivered message) checking the message right after delivery, i tried to confirm that by the logs. To make things a little easier, i used nrcpt=2 and nrcpt=3 situations, just to avoid posting lots of logs here. Case #1 1st recipient delivery OK, failed on 2nd recipient, just delivered successfully on 2nd try Jun 25 17:08:53 correio postfix/qmgr[3059]: 2AFA01BF7496F: from=, size=49366, nrcpt=2 (queue active) Jun 25 17:09:52 correio postfix/lmtp[6029]: 2AFA01BF7496F: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=59, delays=0.01/47/0/12, dsn=2.0.0, status=sent (250 2.0.0 UbjnEywqq1MTPwAAHvf8vg Saved) Jun 25 17:09:55 correio postfix/lmtp[6029]: 2AFA01BF7496F: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=63, delays=0.01/47/0/16, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) Jun 25 17:24:11 correio postfix/lmtp[26595]: 2AFA01BF7496F: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=918, delays=908/0/0/10, dsn=2.0.0, status=sent (250 2.0.0 hWS4JMorq1OIdAAAHvf8vg Saved) and in fact the first recipient was checking its email during the LMTP delivery. This is the actual order of the logs: Jun 25 17:09:47 correio dovecot: pop3-login: Login: user=, method=PLAIN, rip=10.253.x.x, lip=10.252.x.x, mpid=21164 Jun 25 17:09:52 correio postfix/lmtp[6029]: 2AFA01BF7496F: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=59, delays=0.01/47/0/12, dsn=2.0.0, status=sent (250 2.0.0 UbjnEywqq1MTPwAAHvf8vg Saved) Jun 25 17:09:52 correio dovecot: pop3(fabio.k...@domain.com.br), rip=10.253.x.x, lip=10.252.x.x: Disconnected: Logged out top=0/0, retr=1/49582, del=1/1, size=49550 and by the size= of the 'disconnected' pop3 log (size=49550) and the size from qmgr (size=49366), user really seems to have checked (and deleted after that) exactly the message right BEFORE the 2nd recipient delivery was tried by LMTP Case #2 1st and 2nd recipient delivery OK, failed on 3rd recipient, just delivered successfully on 2nd try Jun 25 10:00:31 correio postfix/qmgr[804]: EFEB31A4BB227: from=, size=26667, nrcpt=3 (queue active) Jun 25 10:00:47 correio postfix/lmtp[6549]: EFEB31A4BB227: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=16, delays=0/0/0/16, dsn=2.0.0, status=sent (250 2.0.0 uTsNO+/HqlOHGQAAHvf8vg Saved) Jun 25 10:00:54 correio postfix/lmtp[6549]: EFEB31A4BB227: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=22, delays=0/0/0/22, dsn=2.0.0, status=sent (250 2.0.0 uTsNO+/HqlOHGQAAHvf8vg Saved) Jun 25 10:00:55 correio postfix/lmtp[6549]: EFEB31A4BB227: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=24, delays=0/0/0/24, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) Jun 25 10:03:57 correio postfix/lmtp[7312]: EFEB31A4BB227: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=205, delays=202/1/0/2.2, dsn=2.0.0, status=sent (250 2.0.0 j1dRAU/IqlN6QAAAHvf8vg Saved) 1st recipient in fact checked email (and deleted the message) right after the delivery. Actual log sequence is: Jun 25 10:00:40 correio dovecot: pop3-login: Login: user=, method=PLAIN, rip=10.253.22.56, lip=10.252.38.2, mpid=7233 Jun 25 10:00:47 correio postfix/lmtp[6549]: EFEB31A4BB227: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=16, delays=0/0/0/16, dsn=2.0.0, status=sent (250 2.0.0 uTsNO+/HqlOHGQAAHvf8vg Saved) Jun 25 10:00:48 correio dovecot: pop3(
Re: question on lmtp logged message
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 On Thu, 26 Jun 2014, Leonardo Rodrigues wrote: Em 26/06/14 03:32, Steffen Kaiser escreveu: On Wed, 25 Jun 2014, Leonardo Rodrigues wrote: Anyway, sometimes LMTP seems to not be able to deliver some messages and keep them on postfixqueue. And on the next or third try, the message gets delivered successfully. The logged message, however, is not helping me identify what is happening.Example: (error - message was expunged) Jun 25 11:49:39 correio postfix/lmtp[21835]: ADB0A1AC05108: to=, relay=correio.domain.com.br[private/dovecot-lmtp], conn_use=6, delay=13, delays=0.07/0/0/13, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) What does the Dovecot log says for the delivery attempt? exactly what's reported by postfix, no extra information there Jun 25 11:49:39 correio dovecot: lmtp(766, vanilson.parre...@domain.com.br): 645hNV7hqlP+AgAAHvf8vg: msgid=: save failed to INBOX: Message was expunged (received-date) How many recipients does the message has and, if so, what about the other recipients? After analyzing lots of cases (made a script for doing that), this seems to occur only on messages with more than 1 recipient, usually on messages with lots of recipients (>10) altough i got some on messages with 2 or 3. Some days ago, when trying to optimize somethings on the server, i changed two dovecot parameters: maildir_copy_with_hardlinks to yes pop3_fast_size_lookups to yes previously, both were no. I have returned both values to 'no' and this situation, 'message was expunged' seems to not be occurring anymore. Can this behavior by any chance related to these settings ? maildir_copy_with_hardlinks is set on my server, too. It's the default now. I do not see these errors. Can you check if the failed recipient is _never_ the first one? I remember some discussions about that the Dovecot LDA has to re-open the storred message of the first recipient, in order to spool it for the other ones. That caused problems because the server used an user-specific encryption key. If that applies to LMTP, too, this might become problematic, if the first recipient deletes the message very quickly. Therefore my question, if the error pops up for the second recipient and maybe all following ones. - -- Steffen Kaiser -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.11 (GNU/Linux) iQEVAwUBU6wo4Hz1H7kL/d9rAQIstQf/T1gj/rSwe68Lz8TkdsRbDdnFCp8XHmSP EDsoCapxWxfJi9Vb7wXHoklHeqb9Qxj2lYF+130/wIRQytJge26PnRHjR+CGl5Y6 2QMfpUyHvSoRD6aRI5DTLy4UI2ZLZJt4U22vkyMrjvDeXk8IYW+kShP17fRT0n7W tiESIuoOn2RMBhlHktrhJhvTIvwj4tI6cO9oSHJayG3gD+tYvK5Hpd7b6/PEMY+w NTn4Y7CWyzlsop4K7EgcODsxgSuFjA8YLZqK3Ugi3bmji3rEkdI65fIowPOv4vey oHnDk7u6+gv9vzKRBI09jgqigV+n01T6aUwF3ignghuMngpm2sEE7g== =g8Gw -END PGP SIGNATURE-
Re: question on lmtp logged message
Em 26/06/14 03:32, Steffen Kaiser escreveu: On Wed, 25 Jun 2014, Leonardo Rodrigues wrote: Anyway, sometimes LMTP seems to not be able to deliver some messages and keep them on postfixqueue. And on the next or third try, the message gets delivered successfully. The logged message, however, is not helping me identify what is happening.Example: (error - message was expunged) Jun 25 11:49:39 correio postfix/lmtp[21835]: ADB0A1AC05108: to=, relay=correio.domain.com.br[private/dovecot-lmtp], conn_use=6, delay=13, delays=0.07/0/0/13, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) What does the Dovecot log says for the delivery attempt? exactly what's reported by postfix, no extra information there Jun 25 11:49:39 correio dovecot: lmtp(766, vanilson.parre...@domain.com.br): 645hNV7hqlP+AgAAHvf8vg: msgid=: save failed to INBOX: Message was expunged (received-date) How many recipients does the message has and, if so, what about the other recipients? After analyzing lots of cases (made a script for doing that), this seems to occur only on messages with more than 1 recipient, usually on messages with lots of recipients (>10) altough i got some on messages with 2 or 3. Some days ago, when trying to optimize somethings on the server, i changed two dovecot parameters: maildir_copy_with_hardlinks to yes pop3_fast_size_lookups to yes previously, both were no. I have returned both values to 'no' and this situation, 'message was expunged' seems to not be occurring anymore. Can this behavior by any chance related to these settings ? -- Atenciosamente / Sincerily, Leonardo Rodrigues Solutti Tecnologia http://www.solutti.com.br Minha armadilha de SPAM, NÃO mandem email gertru...@solutti.com.br My SPAMTRAP, do not email it
Re: question on lmtp logged message
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 On Wed, 25 Jun 2014, Leonardo Rodrigues wrote: Anyway, sometimes LMTP seems to not be able to deliver some messages and keep them on postfixqueue. And on the next or third try, the message gets delivered successfully. The logged message, however, is not helping me identify what is happening.Example: (error - message was expunged) Jun 25 11:49:39 correio postfix/lmtp[21835]: ADB0A1AC05108: to=, relay=correio.domain.com.br[private/dovecot-lmtp], conn_use=6, delay=13, delays=0.07/0/0/13, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) What does the Dovecot log says for the delivery attempt? How many recipients does the message has and, if so, what about the other recipients? - -- Steffen Kaiser -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.11 (GNU/Linux) iQEVAwUBU6u+ZHz1H7kL/d9rAQKh9Af8DNlglX8tfG4MpApNOO/Xx5VUsrNX4lxe cXp8RXjY6pl+MGWctd3zMcjCBocXP0MXbe3P2tMRsw7/vINi8EBkcA4B70gWLiRB Fo3XW40FUbCmnckNsi7ctzmwnV+tzk6KxEl8sl0n5RCMQ8joSjcdGXJ1IKOpla+G jtCAEs9nag0vXG5/ckmbybA/u41hAwBqEBbOZxeAByn2wUICOY9dYljR78dKApSy 8rQsbh5SSihVdXZ9EXcqbSsK88MTkq8nnV6jCNaTSv9R2YKVB+ViFiYm/a7LXiqt XAOm7dEWAZ1IIrvfjdEMSzwwwbeOnCgRl5UXOj+rT/STYPfb4Mb2wQ== =Kxhj -END PGP SIGNATURE-
question on lmtp logged message
Hi, I have dovecot running for IMAP4/POP3 and also local delivery through LMTP. It's working just fine, absolutely no problem on that, setup is fine. Anyway, sometimes LMTP seems to not be able to deliver some messages and keep them on postfixqueue. And on the next or third try, the message gets delivered successfully. The logged message, however, is not helping me identify what is happening.Example: (error - message was expunged) Jun 25 11:49:39 correio postfix/lmtp[21835]: ADB0A1AC05108: to=, relay=correio.domain.com.br[private/dovecot-lmtp], conn_use=6, delay=13, delays=0.07/0/0/13, dsn=4.2.0, status=deferred (host correio.domain.com.br[private/dovecot-lmtp] said: 451 4.2.0 Message was expunged (received-date) (in reply to end of DATA command)) (successfull delivery) Jun 25 12:34:42 correio postfix/lmtp[6411]: ADB0A1AC05108: to=, relay=correio.domain.com.br[private/dovecot-lmtp], delay=2716, delays=2714/0/0/2.3, dsn=2.0.0, status=sent (250 2.0.0 U7pOLAHsqlPvMgAAHvf8vg Saved) During these two log entries, absolutely nothing was changed, no configuration, absolutely nothing. Everything is local, i mean, no NFS involved. So, finally, question is: what does the 'message was expunged' message given from LMTP means ??? This is happening quite often but, as i mentionted, sooner or later all messages are getting delivered. It's working despite the delay this is causing. [root@correio log]# dovecot --version 2.2.13 -- Atenciosamente / Sincerily, Leonardo Rodrigues Solutti Tecnologia http://www.solutti.com.br Minha armadilha de SPAM, NÃO mandem email gertru...@solutti.com.br My SPAMTRAP, do not email it
