Re: [Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-09 Thread Jan-Frode Myklebust 
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(u...@example.co,192.168.11.16): ldap_bind() failed: No such object

after patch:

Sep  9 08:50:50 popimap2 dovecot: auth: 
ldap(u...@example.co,192.168.42.15): unknown user



  -jf

[Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-08 Thread Jan-Frode Myklebust 
I've had 18 instances of this error the last 24 hours:

Sep  8 08:56:00 popimap1 dovecot::  lmtp(10529, first.l...@example.om): 
mGdAOtdlaE4hKQAAg/aw4w: 
msgid=b8fa3d5b230184409450d51d522678404e5...@asp-ex02.asp.lan: save failed to 
INBOX: BUG: Unknown internal error

17 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 deliveries


The 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

Re: [Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-08 Thread Timo Sirainen 
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.l...@example.om): 
 mGdAOtdlaE4hKQAAg/aw4w: 
 msgid=b8fa3d5b230184409450d51d522678404e5...@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?

Re: [Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-08 Thread Jan-Frode Myklebust 
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

Re: [Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-08 Thread Timo Sirainen 
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

Re: [Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-08 Thread Jan-Frode Myklebust 
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.crit

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.

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

Re: [Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-08 Thread Timo Sirainen 
On Thu, 2011-09-08 at 12:44 +0200, Jan-Frode Myklebust wrote:


 Sep  8 08:56:00 popimap1 dovecot::  lmtp(10529, 
 first.l...@example.om): mGdAOtdlaE4hKQAAg/aw4w: 
 msgid=b8fa3d5b230184409450d51d522678404e5...@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?
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,

Re: [Dovecot] lmtp -- save failed to INBOX: BUG: Unknown internal error

2011-09-08 Thread Jan-Frode Myklebust 
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