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@msapiro.net to=xxx@example.com proto=ESMTP helo=<[192.168.0.4]>
May 12 11:00:00 sbh16 postfix/cleanup[27513]: 076A36900A9: message-id=4BEAECA2.7060300@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@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 =
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@msapiro.net The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan