dovecot - May 2010 - auth: Error: PLAIN(user): Request 27511.1 timeouted after 150 secs, state=3

Since upgrading from Dovecot 2.0.beta4 + patches
http://hg.dovecot.org/dovecot-2.0/rev/96496e1d3d12 and
http://hg.dovecot.org/dovecot-2.0/rev/aefa279e2c70 to Dovecot 2.0.beta
5, I have started to see the subject error from Dovecot for SASL
authentications. It doesn't happen every time, but it happens more often
than not. It doesn't seem to affect Postfix's acceptance of the message.

One other change made about the same time as the dovecot upgrade that
may be involved is the addition of

smtpd_sasl_authenticated_header = yes

in Postfix.

Here is a sequence of relevant log messages for one incoming message.

May 12 10:59:59 sbh16 postfix/smtpd[27511]: connect from
msapiro.net[68.183.193.239]

May 12 11:00:00 sbh16 postfix/smtpd[27511]: 076A36900A9:
client=msapiro.net[68.183.193.239], sasl_method=PLAIN, sasl_username=mark

May 12 11:00:00 sbh16 postfix/smtpd[27511]: disconnect from
msapiro.net[68.183.193.239]

May 12 11:00:00 sbh16 postfix/cleanup[27513]: 076A36900A9: hold: header
Received: from [192.168.0.4] (msapiro.net [68.183.193.239])??(using
TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits))??(No client
certificate requested)??(Authenticated sender: mark)??by sbh16.song from
msapiro.net[68.183.193.239]; from=<mark at msapiro.net>
to=<xxx at example.com> proto=ESMTP helo=<[192.168.0.4]>

May 12 11:00:00 sbh16 postfix/cleanup[27513]: 076A36900A9:
message-id=<4BEAECA2.7060300 at msapiro.net>

May 12 11:00:12 sbh16 MailScanner[25960]: Requeue: 076A36900A9.A66FD to
B52366900BA

May 12 11:02:29 sbh16 dovecot: auth: Error: PLAIN(mark): Request 27511.1
timeouted after 150 secs, state=3

Note that the timeout occurs, about 149 seconds after Postfix has
accepted and queued the message.

[root at sbh16 ~]# dovecot -n
# 2.0.beta5: /usr/local/etc/dovecot/dovecot.conf
# OS: Linux 2.6.18-8.1.14.el5 i686 CentOS release 5 (Final)
auth_mechanisms = plain apop login
auth_worker_max_count = 5
mail_location = mbox:~/Mail:INBOX=/var/spool/mail/%u
mail_privileged_group = mail
mbox_write_locks = fcntl dotlock
passdb {
  args = /usr/local/etc/dovecot.passwd
  driver = passwd-file
}
passdb {
  driver = pam
}
protocols = imap pop3
service auth {
  unix_listener /var/spool/postfix/private/auth {
    mode = 0666
  }
}
ssl_cert = </etc/postfix/sbh16-cert.pem
ssl_key = </etc/postfix/sbh16-key.pem
userdb {
  driver = passwd
}
[root at sbh16 ~]#

Excerpt from postconf -n

smtpd_sasl_auth_enable = yes
smtpd_sasl_authenticated_header = yes
smtpd_sasl_path = private/auth
smtpd_sasl_type = dovecot

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan

On 12.5.2010, at 20.48, Mark Sapiro wrote:
> May 12 11:02:29 sbh16 dovecot: auth: Error: PLAIN(mark): Request 27511.1
> timeouted after 150 secs, state=3
http://hg.dovecot.org/dovecot-2.0/rev/1a3c9bd45b11 should help with this.

Timo Sirainen wrote:
>On 12.5.2010, at 20.48, Mark Sapiro wrote:
>
>> May 12 11:02:29 sbh16 dovecot: auth: Error: PLAIN(mark): Request
27511.1
>> timeouted after 150 secs, state=3
>
>http://hg.dovecot.org/dovecot-2.0/rev/1a3c9bd45b11 should help with this.

That seems to fix it. Thanks Timo.

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan