Tom Sommer
2016-Apr-06 13:54 UTC
Internal quota calculation error (redis), double mail delivery
Sometimes my redis connection times out, both for pop3, imap and lmtp. I have no idea why, when I do a "doveadm quota recalc -u" it works just fine? I'm thinking the connection is lost somehow and not retried? Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: redis: Lookup timed out in 30.000 secs Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: Internal quota calculation error Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: Internal quota calculation error Apr 06 15:42:00 lmtp(xxx at xxx.com): Info: xxxx: msgid=<xxxx at xxxx.com>: saved mail to INBOX Apr 06 15:49:23 lmtp(xxx at xxx.com): Info: xxxx: msgid=<xxxx at xxxx.com>: saved mail to INBOX <-- Same mail This happens a lot, and it's really bad, because the mail is actually saved correctly, but the error is reported back to the Director, causing the delivery to be retried by the MTA - so the mail actually lands *twice* in the user's inbox. Thanks -- Tom
Timo Sirainen
2016-Apr-06 18:27 UTC
Internal quota calculation error (redis), double mail delivery
On 06 Apr 2016, at 16:54, Tom Sommer <mail at tomsommer.dk> wrote:> > Sometimes my redis connection times out, both for pop3, imap and lmtp. I have no idea why, when I do a "doveadm quota recalc -u" it works just fine? > I'm thinking the connection is lost somehow and not retried? > > Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: redis: Lookup timed out in 30.000 secs > Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: Internal quota calculation error > Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: Internal quota calculation error > Apr 06 15:42:00 lmtp(xxx at xxx.com): Info: xxxx: msgid=<xxxx at xxxx.com>: saved mail to INBOX > Apr 06 15:49:23 lmtp(xxx at xxx.com): Info: xxxx: msgid=<xxxx at xxxx.com>: saved mail to INBOX <-- Same mail > > This happens a lot, and it's really bad, because the mail is actually saved correctly, but the error is reported back to the Director, causing the delivery to be retried by the MTA - so the mail actually lands *twice* in the user's inbox.1) Shrink the timeout in Redis with timeout_msecs parameter. http://wiki2.dovecot.org/Dictionary 2) Actually it looks like the timeout handling code doesn't work at all. It simply keeps on logging timeouts until it succeeds or the connection gets disconnected. Do you see such repeated timeout logs, or does the connection also happen to get closed exactly at 30 seconds anyway? This fixes: https://github.com/dovecot/core/commit/2fb829dc7cc8c61dee925a15e51768a4b82e45da 3) Is there some firewall between Dovecot and Redis that closes idling connections and causes them to hang? Dovecot doesn't close idle Redis connections, although I suppose it would be useful too. The attached patch probably helps here by adding a new idle_timeout_msecs setting. I didn't finish testing it. -------------- next part -------------- A non-text attachment was scrubbed... Name: redis-idle-timeout.diff Type: application/octet-stream Size: 3197 bytes Desc: not available URL: <http://dovecot.org/pipermail/dovecot/attachments/20160406/bc79a1e6/attachment.obj> -------------- next part --------------
Tom Sommer
2016-Apr-06 19:14 UTC
Internal quota calculation error (redis), double mail delivery
On 2016-04-06 20:27, Timo Sirainen wrote:> On 06 Apr 2016, at 16:54, Tom Sommer <mail at tomsommer.dk> wrote: >> >> Sometimes my redis connection times out, both for pop3, imap and lmtp. >> I have no idea why, when I do a "doveadm quota recalc -u" it works >> just fine? >> I'm thinking the connection is lost somehow and not retried? >> >> Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: redis: Lookup timed out in >> 30.000 secs >> Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: Internal quota calculation >> error >> Apr 06 15:42:00 lmtp(xxx at xxx.com): Error: Internal quota calculation >> error >> Apr 06 15:42:00 lmtp(xxx at xxx.com): Info: xxxx: msgid=<xxxx at xxxx.com>: >> saved mail to INBOX >> Apr 06 15:49:23 lmtp(xxx at xxx.com): Info: xxxx: msgid=<xxxx at xxxx.com>: >> saved mail to INBOX <-- Same mail >> >> This happens a lot, and it's really bad, because the mail is actually >> saved correctly, but the error is reported back to the Director, >> causing the delivery to be retried by the MTA - so the mail actually >> lands *twice* in the user's inbox. > > 1) Shrink the timeout in Redis with timeout_msecs parameter. > http://wiki2.dovecot.org/DictionaryYea, but why is it taking 30 seconds anyway? I'll try and lower it, but I suspect I'll just get 10.000 secs errors instead?> 2) Actually it looks like the timeout handling code doesn't work at > all. It simply keeps on logging timeouts until it succeeds or the > connection gets disconnected. Do you see such repeated timeout logs, > or does the connection also happen to get closed exactly at 30 seconds > anyway? This fixes: > https://github.com/dovecot/core/commit/2fb829dc7cc8c61dee925a15e51768a4b82e45daI see a lot of them, but none repeated after eachother. It's more of a random pattern.> 3) Is there some firewall between Dovecot and Redis that closes idling > connections and causes them to hang? Dovecot doesn't close idle Redis > connections, although I suppose it would be useful too. The attached > patch probably helps here by adding a new idle_timeout_msecs setting. > I didn't finish testing it.No firewall at all. I'm unsure if redis closes idle connections, that could be the cause of it. What about the issue of lmtp saving the mail, but sending an error back to Director? Thanks :) -- Tom