dovecot - Jul 2007 - More Descriptive Logging Needed

(Everything herein refers to dovecot-1.0.1.)

I'm sorry to say that I've been having troubles with dovecot.  While 
attempting to troubleshoot them, I've found the existing logs to be lacking.

In particular, I've had a lot of difficulty with the client<->server 
connection disconnecting, but the only message I get in the logs is 
"Disconnected".  After dissecting the code a bit, I've found quite
a
number of places where the code will close the connection logging 
nothing more than the word "Disconnected", or worse, it will not
specify
a reason in which case the code in client_destroy() will log the default 
"Disconnected".  Because of this, isolating the offending code has
been
a bit difficult.  (I realize the problem may lie with the client, but I 
cannot even begin to program a work around until I isolate the exact 
place and cause of failure.)

In an attempt to change the logging to be more descriptive myself, I 
already changed src/imap/cmd-fetch.c:85 on my own copy of dovecot from:
client_disconnect(cmd->client, "Disconnected");
to:
client_disconnect(cmd->client, "Disconnected in FETCH");
This makes the logging both more descriptive and more in line with other 
parts of code, like src/imap/cmd-append.c:50 which already say:
client_destroy(client, "Disconnected in APPEND");

As luck would have it, my problem was not in the FETCH command.


I'm now looking at the client_read() function in 
src/imap-login/client.c:318-334.  If I'm reading the code right, then 
"i_stream_read(client->input)" returning "-1" means that
the
socket/stream is already disconnected, right?  In other words, some 
function attempted to read off of a socket/stream that was already 
closed, right?  If so, shouldn't the client_read() function not have 
been called in the first place?

Please let me know if I'm wrong.  I've been banging my head against the 
wall trying to make sense of all the different code.  Any assistance you 
can offer would be appreciated.

Joseph D. Wagner

On Sat, 2007-07-14 at 23:58 -0700, Joseph D. Wagner
wrote:
> In an attempt to change the logging to be more descriptive myself, I 
> already changed src/imap/cmd-fetch.c:85 on my own copy of dovecot from:
> client_disconnect(cmd->client, "Disconnected");
> to:
> client_disconnect(cmd->client, "Disconnected in FETCH");
> This makes the logging both more descriptive and more in line with other 
> parts of code, like src/imap/cmd-append.c:50 which already say:
> client_destroy(client, "Disconnected in APPEND");
"Disconnected" simply means that the connection got disconnected (ie.
Dovecot didn't do it). I didn't think it matters in which command it
gets disconnected, so it doesn't try to log that.

Maybe you should just enable rawlog and see what happens before it gets
disconnected? http://dovecot.org/bugreport.html#sniffing
> I'm now looking at the client_read() function in 
> src/imap-login/client.c:318-334.  If I'm reading the code right, then 
> "i_stream_read(client->input)" returning "-1" means
that the
> socket/stream is already disconnected, right?  In other words, some 
> function attempted to read off of a socket/stream that was already 
> closed, right?  If so, shouldn't the client_read() function not have 
> been called in the first place?
Not necessarily. It returns -1 also if the socket just got disconnected
while it was trying to read().

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20070715/3be53ebc/attachment-0002.bin>