[Dovecot] dovecot-deliver occasionally fails to deliver, leaving no clues
Hello,
I have a FreeBSD 7.1 x86 system using dovecot with postfix and a mysql
user database. Everything works completely fine, except that on
occasion dovecot-deliver fails. When postfix tries to redeliver the
message in about 15 minutes, it succeeds. So this isn't a very big
problem, just an annoying puzzle.
Here's the postfix log. At first, I thought it could be a postfix , relay=dovecot, delay=0.04, delays=0.
01/0/0/0.03, dsn=4.3.0, status=deferred (temporary failure) I turned on delivery logging to see what I'd get, and I simply get this:
deliver(xxxxxx@xxxxx.xxx): Oct 17 00:36:22 Info: Loading modules from Dovecot is not dumping core, or even printing out any error message log_path = /var/log/delivery.log
info_log_path = /var/log/delivery.log
mail_debug = yes
auth_debug = yes
auth_verbose = yes Any clue as to what could be going on here? Thanks,
Lucas
delivery problem.
Oct 17 00:36:22 xxxxxxx postfix/pipe[16017]: 41E581CC5B: to=
directory: /usr/local/lib/dovecot/lda
deliver(xxxxxx@xxxxx.xxx): Oct 17 00:36:22 Info: Module loaded: /usr/
local/lib/dovecot/lda/lib90_cmusieve_plugin.so
(normally, here it would print out more info about the user, as "auth
input" lines, but it doesn't when it fails in this way)
that I can see. I have all logging turned on (except for passwords),
and I still seem to get nothing. I've attached my dovecot -n output,
which doesn't seem to contain the logging I have set up for deliver:
On Fri, 2008-10-17 at 12:47 -0700, Lucas Madar wrote:
I turned on delivery logging to see what I'd get, and I simply get this: deliver(xxxxxx@xxxxx.xxx): Oct 17 00:36:22 Info: Loading modules from
directory: /usr/local/lib/dovecot/lda deliver(xxxxxx@xxxxx.xxx): Oct 17 00:36:22 Info: Module loaded: /usr/ local/lib/dovecot/lda/lib90_cmusieve_plugin.so (normally, here it would print out more info about the user, as "auth
input" lines, but it doesn't when it fails in this way)
Applying this patch probably makes it log that "auth lookup failed": http://hg.dovecot.org/dovecot-1.1/rev/b085c58fcf14
But in that case the auth process should already have logged errors.
log_path: /var/log/pickup.log info_log_path: /var/log/pickup.log
I'd suggest using different files for these. Errors are written to log_path, and that log file should always stay empty. It's a lot easier to notice errors when they're not surrounded by a lot of useless logging.
I guess you could already just grep for "Error:" or "Warning:" from the pickup.log to see if there are some auth errors.
On Oct 18, 2008, at 4:00 AM, Timo Sirainen wrote:
On Fri, 2008-10-17 at 12:47 -0700, Lucas Madar wrote:
I turned on delivery logging to see what I'd get, and I simply get
this: deliver(xxxxxx@xxxxx.xxx): Oct 17 00:36:22 Info: Loading modules from directory: /usr/local/lib/dovecot/lda deliver(xxxxxx@xxxxx.xxx): Oct 17 00:36:22 Info: Module loaded: /usr/ local/lib/dovecot/lda/lib90_cmusieve_plugin.so (normally, here it would print out more info about the user, as "auth input" lines, but it doesn't when it fails in this way)Applying this patch probably makes it log that "auth lookup failed": http://hg.dovecot.org/dovecot-1.1/rev/b085c58fcf14
But in that case the auth process should already have logged errors.
I applied this patch and now I get:
deliver(x@x): Oct 21 09:51:55 Info: Loading modules from directory: / usr/local/lib/dovecot/lda deliver(x@x): Oct 21 09:51:55 Info: Module loaded: /usr/local/lib/ dovecot/lda/lib90_cmusieve_plugin.so deliver(x@x): Oct 21 09:51:55 Error: Auth lookup returned failure
The auth process is not logging any errors. I suppose I can stick more
debugs into the auth process and see what happens. I'm using mysql as
an auth backend, and the server isn't particularly loaded. Any other
ideas?
log_path: /var/log/pickup.log info_log_path: /var/log/pickup.log
I'd suggest using different files for these. Errors are written to log_path, and that log file should always stay empty. It's a lot
easier to notice errors when they're not surrounded by a lot of useless logging.I guess you could already just grep for "Error:" or "Warning:" from
the pickup.log to see if there are some auth errors.
My server is relatively low traffic, which does not make these logs
too busy to read.
Thanks, Lucas
On Tue, 2008-10-21 at 14:47 -0700, Lucas Madar wrote:
deliver(x@x): Oct 21 09:51:55 Error: Auth lookup returned failure
The auth process is not logging any errors.
See if these two help:
http://hg.dovecot.org/dovecot-1.1/rev/4608e1bfb505 http://hg.dovecot.org/dovecot-1.1/rev/2108e44c3ba4
On Oct 21, 2008, at 3:08 PM, Timo Sirainen wrote:
On Tue, 2008-10-21 at 14:47 -0700, Lucas Madar wrote:
deliver(x@x): Oct 21 09:51:55 Error: Auth lookup returned failure
The auth process is not logging any errors.
See if these two help:
http://hg.dovecot.org/dovecot-1.1/rev/4608e1bfb505 http://hg.dovecot.org/dovecot-1.1/rev/2108e44c3ba4
Ok, I've added those. It takes about six hours until one of these
delivery failures happens.
Meanwhile, I turned on auth_verbose for the main process, and now I
get these pretty frequently:
dovecot: Oct 21 15:31:58 Panic: auth(default): file auth-worker- server.c: line 282 (auth_worker_call): assertion failed: (conn-
requests_left > 0)
(Shouldn't these have been logged without auth_verbose? or is this a
result of your patches?)
- Lucas
On Tue, 2008-10-21 at 15:37 -0700, Lucas Madar wrote:
On Oct 21, 2008, at 3:08 PM, Timo Sirainen wrote:
On Tue, 2008-10-21 at 14:47 -0700, Lucas Madar wrote:
deliver(x@x): Oct 21 09:51:55 Error: Auth lookup returned failure
The auth process is not logging any errors.
See if these two help:
http://hg.dovecot.org/dovecot-1.1/rev/4608e1bfb505 http://hg.dovecot.org/dovecot-1.1/rev/2108e44c3ba4
Ok, I've added those. It takes about six hours until one of these
delivery failures happens. Meanwhile, I turned on auth_verbose for the main process, and now I
get these pretty frequently:dovecot: Oct 21 15:31:58 Panic: auth(default): file auth-worker- server.c: line 282 (auth_worker_call): assertion failed: (conn-
requests_left > 0)
Sorry, the other one of the patches didn't work right. Apply this: http://hg.dovecot.org/dovecot-1.1/rev/147a57cd312f
On Oct 21, 2008, at 3:48 PM, Timo Sirainen wrote:
On Tue, 2008-10-21 at 14:47 -0700, Lucas Madar wrote:
deliver(x@x): Oct 21 09:51:55 Error: Auth lookup returned failure
The auth process is not logging any errors.
... Sorry, the other one of the patches didn't work right. Apply this: http://hg.dovecot.org/dovecot-1.1/rev/147a57cd312f
This patch appears to have fixed the problem entirely. :)
Thanks!
- Lucas
On Wed, 2008-10-22 at 09:59 -0700, Lucas Madar wrote:
On Oct 21, 2008, at 3:48 PM, Timo Sirainen wrote:
On Tue, 2008-10-21 at 14:47 -0700, Lucas Madar wrote:
deliver(x@x): Oct 21 09:51:55 Error: Auth lookup returned failure
The auth process is not logging any errors.
... Sorry, the other one of the patches didn't work right. Apply this: http://hg.dovecot.org/dovecot-1.1/rev/147a57cd312f
This patch appears to have fixed the problem entirely. :)
BTW. The bug showed up only because you had auth_worker_max_request_count set to non-zero. Is there a reason why this isn't zero? It was only meant for fixing problems with PAM, but you're not using PAM.
On Oct 22, 2008, at 11:09 AM, Timo Sirainen wrote:
BTW. The bug showed up only because you had auth_worker_max_request_count set to non-zero. Is there a reason why this isn't zero? It was only meant for fixing problems with PAM, but you're not using PAM.
I figured that any bugs that might crop up (either in dovecot or
mysql) might be mitigated by the auth worker eventually restarting
itself. It seemed like the only negative consequence would be
performance, and with such a low volume I wasn't concerned.
Thanks for a wonderful program and awesome tech support!
- Lucas
participants (2)
-
Lucas Madar
-
Timo Sirainen