dovecot - Oct 2008 - 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  
delivery problem.
Oct 17 00:36:22 xxxxxxx postfix/pipe[16017]: 41E581CC5B: to=<xxxx at
xxxxx.xxx
 >, 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 at xxxxx.xxx): Oct 17 00:36:22 Info: Loading modules from  
directory: /usr/local/lib/dovecot/lda
deliver(xxxxxx at 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)

Dovecot is not dumping core, or even printing out any error message  
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:

   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

-------------- next part --------------
A non-text attachment was scrubbed...
Name: dovecot-n.conf
Type: application/octet-stream
Size: 2150 bytes
Desc: not available
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20081017/c9366afe/attachment-0002.obj>
-------------- next part --------------

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 at xxxxx.xxx): Oct 17 00:36:22 Info: Loading modules from  
> directory: /usr/local/lib/dovecot/lda
> deliver(xxxxxx at 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.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20081018/9750df89/attachment-0002.bin>

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 at xxxxx.xxx): Oct 17 00:36:22 Info: Loading modules
from
>> directory: /usr/local/lib/dovecot/lda
>> deliver(xxxxxx at 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 at x): Oct 21 09:51:55 Info: Loading modules from directory: / 
usr/local/lib/dovecot/lda
deliver(x at x): Oct 21 09:51:55 Info: Module loaded: /usr/local/lib/ 
dovecot/lda/lib90_cmusieve_plugin.so
deliver(x at 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