[Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error
I've had 18 instances of this error the last 24 hours:
Sep 8 08:56:00 popimap1 dovecot:: lmtp(10529, first.last@example.om): mGdAOtdlaE4hKQAAg/aw4w: msgid=<B8FA3D5B230184409450D51D522678404E5052@ASP-EX02.ASP.lan>: save failed to INBOX: BUG: Unknown internal error17 on lmtp-server A, and one on lmtp-server B.
On server A it was a message with 55 recepients, where 17 failed initially -- and the was then successfully delivered.
lmtp pid 10529, 08:55:57-08:56:01 - 11 successfull deliveries, 17 BUGs
lmtp pid 10609, 08:56:00 - 1 successfull deliveries
lmtp pid 31291, 08:56:06 - 2 successfull deliveries
lmtp pid 10482, 08:56:04-06 - 3 successfull deliveries
lmtp pid 6738, 08:56:06 - 1 successfull deliveries
lmtp pid 24488, 08:56:06-07 - 5 successfull deliveries
lmtp pid 7101, 08:56:01-07 - 19 successfull deliveries
lmtp pid 21330, 08:56:08 - 1 successfull deliveries
lmtp pid 2177, 08:56:09 - 3 successfull deliveries
lmtp pid 7085, 08:56:10 - 3 successfull deliveries
lmtp pid 6633, 08:56:08-10 - 6 successfull deliveriesThe one on lmtp-server B was a different msgid from A, and also had several recepients (6). It was successfully delivered to the recepient that initially failed the same second.
Config here:
# 2.0.14: /etc/dovecot/dovecot.conf # OS: Linux 2.6.18-194.26.1.el5 x86_64 Red Hat Enterprise Linux Server release 5.5 (Tikanga) auth_verbose = yes auth_verbose_passwords = sha1 disable_plaintext_auth = no mail_gid = 3000 mail_location = maildir:~/:INDEX=/indexes/%1u/%1.1u/%u mail_plugins = quota mail_uid = 3000 mmap_disable = yes namespace { inbox = yes location = prefix = INBOX. type = private } passdb { args = /etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { quota = maildir:User quota } service auth-worker { user = $default_internal_user } service auth { client_limit = 4396 } service imap-login { inet_listener imap { address = * port = 143 } } service imap { executable = /usr/local/sbin/imap-wrapper.sh process_limit = 2048 } service lmtp { client_limit = 1 inet_listener lmtp { address = * port = 24 } process_limit = 25 } service pop3-login { inet_listener pop3 { address = * port = 110 } } service pop3 { executable = /usr/local/sbin/pop-wrapper.sh process_limit = 2048 } ssl = no userdb { args = /etc/dovecot/dovecot-ldap.conf.ext driver = ldap } protocol lmtp { mail_plugins = quota } protocol imap { imap_client_workarounds = delay-newmail mail_plugins = quota imap_quota } protocol pop3 { mail_plugins = quota pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_uidl_format = UID%u-%v }
-jf
On Thu, 2011-09-08 at 09:56 +0200, Jan-Frode Myklebust wrote:
I've had 18 instances of this error the last 24 hours:
Sep 8 08:56:00 popimap1 dovecot:: lmtp(10529, first.last@example.om): mGdAOtdlaE4hKQAAg/aw4w: msgid=<B8FA3D5B230184409450D51D522678404E5052@ASP-EX02.ASP.lan>: save failed to INBOX: BUG: Unknown internal error
Hmm. These are pretty annoying to find. I looked through the sources and.. Well, found one possible reason for it. Try applying these patches and see what it says then:
http://hg.dovecot.org/dovecot-2.0/raw-rev/858298eb101f http://hg.dovecot.org/dovecot-2.0/raw-rev/323ab62983b6
Or were there any actual errors logged before this message?
On Thu, Sep 08, 2011 at 11:53:26AM +0300, Timo Sirainen wrote:
Hmm. These are pretty annoying to find. I looked through the sources and.. Well, found one possible reason for it. Try applying these patches and see what it says then:
http://hg.dovecot.org/dovecot-2.0/raw-rev/858298eb101f http://hg.dovecot.org/dovecot-2.0/raw-rev/323ab62983b6
Thanks, applied.. Will let you know if/when it happens again.
Or were there any actual errors logged before this message?
I couldn't find any.. but these BUG:-messages were logged as debug or info level syslog messages, which quickly drowns in everything else on busy pop/imap-servers.
-jf
On 8.9.2011, at 13.28, Jan-Frode Myklebust wrote:
I couldn't find any.. but these BUG:-messages were logged as debug or info level syslog messages, which quickly drowns in everything else on busy pop/imap-servers.
That's why I prefer logging errors and warnings to separate logs. Those errors logs should always stay empty. You can do this either by configuring syslog or just setting e.g.:
log_path = /var/log/dovecot-errors.log info_log_path = syslog
On Thu, Sep 08, 2011 at 01:31:22PM +0300, Timo Sirainen wrote:
I couldn't find any.. but these BUG:-messages were logged as debug or info level syslog messages, which quickly drowns in everything else on busy pop/imap-servers.
That's why I prefer logging errors and warnings to separate logs. Those errors logs should always stay empty. You can do this either by configuring syslog or just setting e.g.:
log_path = /var/log/dovecot-errors.log info_log_path = syslog
We have that trough syslog:
mail.debug -/var/log/maillog.debug
mail.* -/var/log/maillog
mail.warning -/var/log/maillog.warning
mail.err -/var/log/maillog.errors
mail.crit -/var/log/maillog.critbut these BUG-messages only ended up in /var/log/maillog and /var/log/maillog.debug, so I think they were logged with wrong severity.
But "those errors logs should always stay empty" isn't quite true for us.., since every failed ldap bind() authentication is logged as an error:
$ sudo wc -l maillog.errors
2063 maillog.errors
$ sudo head -1 maillog.errors ; sudo tail -1 maillog.errors
Sep 8 04:02:43 popimap1 dovecot: auth: Error: ldap(user2,192.168.42.15): ldap_bind() failed: No such object
Sep 8 12:39:46 popimap1 dovecot: auth: Error: ldap(user1,192.168.42.15): ldap_bind() failed: No such object-jf
On Thu, 2011-09-08 at 12:44 +0200, Jan-Frode Myklebust wrote:
Sep 8 08:56:00 popimap1 dovecot:: lmtp(10529, first.last@example.om): mGdAOtdlaE4hKQAAg/aw4w: msgid=<B8FA3D5B230184409450D51D522678404E5052@ASP-EX02.ASP.lan>: save failed to INBOX: BUG: Unknown internal error
..
but these BUG-messages only ended up in /var/log/maillog and /var/log/maillog.debug, so I think they were logged with wrong severity.
The message is logged with info-level, because it's the "what happened to the message" line. It's basically the same message that gets logged every time, regardless of what happened to the message. What should have happened above was:
Error: something bad happened to your message Info: save failed to INBOX: Internal error occurred.
So you should have gotten one error and one info message, but because of some bug you didn't get any error.
But "those errors logs should always stay empty" isn't quite true for us.., since every failed ldap bind() authentication is logged as an error:
$ sudo wc -l maillog.errors 2063 maillog.errors $ sudo head -1 maillog.errors ; sudo tail -1 maillog.errors Sep 8 04:02:43 popimap1 dovecot: auth: Error: ldap(user2,192.168.42.15): ldap_bind() failed: No such object Sep 8 12:39:46 popimap1 dovecot: auth: Error: ldap(user1,192.168.42.15): ldap_bind() failed: No such object
It shouldn't be behaving like that.. Are you saying that all "unknown user" failures are logged as those errors?
I get without auth_bind_userdn:
Sep 08 15:56:08 auth: Info: ldap(foo,127.0.0.1): unknown user
With auth_bind_userdn:
Sep 08 16:00:12 auth: Info: ldap(foo,127.0.0.1): invalid credentials
So the "No such object" isn't expected.. Maybe different LDAP servers work in different ways?.. Yours appears to give out the difference between "user doesn't exist" and "wrong password"? Does the attached patch change these to "unknown user" messages?
On Thu, Sep 08, 2011 at 04:03:58PM +0300, Timo Sirainen wrote:
It shouldn't be behaving like that.. Are you saying that all "unknown user" failures are logged as those errors?
Seems so yes.
I get without auth_bind_userdn:
Sep 08 15:56:08 auth: Info: ldap(foo,127.0.0.1): unknown user
With auth_bind_userdn:
Sep 08 16:00:12 auth: Info: ldap(foo,127.0.0.1): invalid credentials
So the "No such object" isn't expected.. Maybe different LDAP servers work in different ways?..
We're using centos directory server - aka - red hat directory server - aka - 389ds. With: auth_verbose = yes auth_verbose_passwords = sha1 (which doesn't work) userdb { args = /etc/dovecot/dovecot-ldap.conf.ext driver = ldap } hosts = ldapm1.example.net:389 ldapm2.example.net:389 auth_bind = yes auth_bind_userdn = uid=%n,ou=people,o=%d,o=ISP,o=example,c=NO base = ou=people,o=%d,o=ISP,o=example,c=NO deref = never scope = onelevel user_attrs = mailMessageStore=home, mailLocation=mail, mailQuota=mailQuota=quota_rule=*:storage=%$ user_filter = (&(objectClass=examplePerson)(uid=%n)) Could maybe also be the user_filter or auth_bind_userdn that's turning it into an error ?
Yours appears to give out the difference between "user doesn't exist" and "wrong password"? Does the attached patch change these to "unknown user" messages?
diff -r 8de8752b2e94 src/auth/passdb-ldap.c --- a/src/auth/passdb-ldap.c Thu Sep 08 13:41:20 2011 +0300 +++ b/src/auth/passdb-ldap.c Thu Sep 08 16:03:21 2011 +0300 @@ -157,6 +157,10 @@ } auth_request_log_info(auth_request, "ldap", "%s", str); passdb_result = PASSDB_RESULT_PASSWORD_MISMATCH; + } else if (ret == LDAP_NO_SUCH_OBJECT) { + passdb_result = PASSDB_RESULT_USER_UNKNOWN; + auth_request_log_info(auth_request, "ldap", + "unknown user"); } else { auth_request_log_error(auth_request, "ldap", "ldap_bind() failed: %s",
I've done a bit too many unscheduled changes today... will see if I can sneak this in tomorrow :-) -jf
On Thu, Sep 08, 2011 at 04:03:58PM +0300, Timo Sirainen wrote:
So the "No such object" isn't expected.. Maybe different LDAP servers work in different ways?.. Yours appears to give out the difference between "user doesn't exist" and "wrong password"? Does the attached patch change these to "unknown user" messages?
Yes it does.
Before patch:
Sep 9 08:46:43 popimap2 dovecot: auth: Error: ldap(user@example.co,192.168.11.16): ldap_bind() failed: No such objectafter patch:
Sep 9 08:50:50 popimap2 dovecot: auth: ldap(user@example.co,192.168.42.15): unknown user-jf
participants (2)
-
Jan-Frode Myklebust
-
Timo Sirainen