dovecot - May 2010 - Problems with the IMAP proxy after upgrading from dovecot 1.1.16 to 1.211

We have frequent timeout problems after upgrading our imap servers  
from dovecot 1.1.16 to dovecot 1.2.11. One server acts as proxy only,  
and the other one is the "real" imap server". The credentials for
the
proxy service are stored in a remote MYSQL database.

There were no trouble with dovecot 1.1.16. But now, with the most  
recent version, we get frequent login failures. It seems dovecot  
reconnects too late to the MySQL database after a timeout, after  
sending the SQL query. Here's a piece of my log file:

May  7 14:46:32 ttt dovecot: auth(default): new auth connection: pid=5136
May  7 14:46:42 ttt dovecot: auth(default): client in:  
AUTH^I1^IPLAIN^Iservice=imap^Isecured^Ilip=xxx.xxx.xxx.xxx^Irip=yyy.yyy.yyy.yyy^Ilport=sss^Irport=26480^Iresp=<hidden>
May  7 14:46:42 ttt dovecot: auth-worker(default):  
sql(uid,yyy.yyy.yyy.yyy): query: SELECT NULL as password, destuser,  
host, 'zzz' as port, 'Y' as proxy, '0' as proxy_timeout,
'Y' as
nopassword, 'Y' as nodelay from accounts where user ='uid';
May  7 14:47:42 ttt dovecot: auth(default):  
worker-server(uid,yyy.yyy.yyy.yyy): Aborted: Lookup timed out
May  7 14:47:42 ttt dovecot: auth-worker(default): mysql: Connected to  
lll.lll.lll.lll (imapauth)
May  7 14:47:44 ttt dovecot: auth(default): client out:  
FAIL^I1^Iuser=uid^Itemp
May  7 14:47:49 ttt dovecot: imap-login: Disconnected (auth failed, 1  
attempts): user=<uid>, method=PLAIN, rip=yyy.yyy.yyy.yyy,  
lip=xxx.xxx.xxx.xxx, TLS
May  7 14:48:26 ttt dovecot: auth(default): new auth connection: pid=5159
May  7 14:48:47 ttt dovecot: auth(default): client in:  
AUTH^I1^IPLAIN^Iservice=imap^Isecured^Ilip=xxx.xxx.xxx.xxx^Irip=yyy.yyy.yyy.yyy^Ilport=sss^Irport=6243^Iresp=<hidden>
May  7 14:48:47 ttt dovecot: auth-worker(default):  
sql(uid,yyy.yyy.yyy.yyy): query: SELECT NULL as password, destuser,  
host, 'zzz' as port, 'Y' as proxy, '0' as proxy_timeout,
'Y' as
nopassword, 'Y' as nodelay from accounts where user ='uid';
May  7 14:48:47 ttt dovecot: auth(default): client out:  
OK^I1^Iuser=uid^Idestuser=luid^Ihost=mmm.mmm.mmm.mmm^Iport=zzz^Iproxy^Iproxy_timeout=0^Ipass=<hidden>
May  7 14:48:47 ttt dovecot: imap-login: proxy(uid): started proxying  
to mmm.mmm.mmm.mmm:zzz/luid: user=<uid>, method=PLAIN,  
rip=yyy.yyy.yyy.yyy, lip=xxx.xxx.xxx.xxx, TLS
May  7 14:48:48 ttt dovecot: imap-login: proxy(uid): disconnecting  
yyy.yyy.yyy.yyy

As you can see, the second login attempt is always successful. Of  
course I've tried out various values (0, 60, 90, 300) for the  
proxy_timeout parameter - but without any success.

On pe, 2010-05-07 at 15:35 +0200, Holger Richter wrote:
> May  7 14:47:42 ttt dovecot: auth(default): 
worker-server(uid,yyy.yyy.yyy.yyy): Aborted: Lookup timed out
> May  7 14:47:42 ttt dovecot: auth-worker(default): mysql: Connected to  
> lll.lll.lll.lll (imapauth) 
"Lookup timed out" really shouldn't be happening.. That sounds
like
Dovecot's MySQL connections hangs after a while? You have some stateful
firewall between Dovecot and MySQL that drops idling connections and
afterwards starts dropping the connection's packets?

>> >> May  7 14:47:42 ttt dovecot: auth(default):
>> >> worker-server(uid,yyy.yyy.yyy.yyy): Aborted: Lookup timed out
>> >> May  7 14:47:42 ttt dovecot: auth-worker(default): mysql:
Connected to
>> >> lll.lll.lll.lll (imapauth)
>> >
>> > "Lookup timed out" really shouldn't be happening..
That sounds like
>> > Dovecot's MySQL connections hangs after a while? You have some
stateful
>> > firewall between Dovecot and MySQL that drops idling connections
and
>> > afterwards starts dropping the connection's packets?
>>
>> Indeed, there is a firewall with stateful inspection between Dovecot
>> and MySQL.
>
> Right, so the "Lookup timed out" works as intended. But I guess
it
> should automatically retry when that happens. There would still be that
> 1 minute delay before that happens though.
>
>>  The only workaround is a downgrade to Dovecot 1.1.20.
>
> Wonder what v1.1 does differently. I can't think of anything, really.
> The main fundamental problem is still that mysql connection hangs and
> the hang can't be detected/avoided. I think the right fix here would be
> to change your firewall settings..
>
>> I think my problem has to do with the changes in
>> src/auth/auth-worker-server.c in changeset 8859.
>
> 8559:b0bc4519332f?
Yep.