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?