Internal quota calculation error (redis), double mail delivery

[Timo Sirainen]

On 06 Apr 2016, at 22:14, Tom Sommer <mail at tomsommer.dk> wrote:
> 
> 
> 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/Dictionary
> 
> Yea, 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?

I don't know. Possibly a hanging TCP connection. That's why I was asking about the firewall. If it's not that, I don't really know. And yes, just shrinking this without the below fix won't help anything.

>> 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
> 
> I see a lot of them, but none repeated after eachother. It's more of a random pattern.

Maybe something triggers after 30 seconds elsewhere that also aborts the lookup..

>> 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.

Closing a connection is fine. That causes Dovecot to just reconnect.

> What about the issue of lmtp saving the mail, but sending an error back to Director?

I guess the LMTP proxy_timeout in director is 30 seconds or lower. If backend's timeouts are smaller than that, director won't have to disconnect LMTP due to timeout and there won't be duplicates. Or just increase the director's proxy_timeout to several minutes.