Hi,
ever since we upgraded our webmail service (new server, new webmail
version, new PHP version with opcode cache, new Linux version, new
imapproxy version, ...) we've seen an increase of lines like this in
the logfile:
Jun 17 08:34:16 webmail in.imapproxyd[22721]: IMAP_Line_Read(): connection
closed prematurely.
We've had that happen in the past, too, but much more infrequently.
With the new environment, it's certain to happen several times a day.
Considering we've got all these new components, figuring out what may
be causing this is a bit difficult, of course. I've tried upgrading to
the latest SVN version of imapproxy, but that didn't help. After
looking at the source code for a while, I tried to add some debug
information to the logfile entries in order to better pin down the
exact place where the problem occurs. (There a two places where
"connection closed prematurely" could happen.) Unfortunately, I'm not
that much of a C programmer and have trouble understanding all the code
that's there, but the code changes I made at least still compile.
Here's what the code near the end of the function IMAP_Line_Read in
imapcommon.c looks like now:
Status = IMAP_Read(ITD->conn, &ITD->ReadBuf[ITD->BytesInReadBuffer],
(sizeof ITD->ReadBuf - ITD->BytesInReadBuffer ) );
if ( Status == 0 )
{
syslog(LOG_WARNING, "%s: connection closed prematurely. sd [%d].
(line 1788 of imapcommon.c)", fn, ITD->conn->sd);
return(-1);
}
else if ( Status == -1 )
{
syslog(LOG_ERR, "%s: IMAP_Read() failed: %s", fn, strerror(errno) );
return(-1);
}
So, basically, I added the "ITD->conn->sd" info to the logfile message,
but I'm not certain that this variable can be used in this context.
Can anyone confirm that this OK?
After putting that code into service, I didn't have to wait long for
the first lines in the logfile with this additional info to appear.
Based on the output of that log message, I looked for information which
user that specific sd had been assigned before in order to search for
patterns there. (I've been suspecting this problem to have something
to do with some users having several connections open or cached when
looking around with the XPROXY_DUMPICC command.) To my surprise, in all
cases I found, the sd in question had been expired before and there was
no indication that it has been re-assigned. So the logfile entries
looked like this:
Jun 21 13:56:37 webmail in.imapproxyd[29720]: Expiring server sd [26]
Jun 21 13:57:31 webmail in.imapproxyd[29720]: IMAP_Line_Read(): connection
closed prematurely. sd [26]. (line 1788 of imapcommon.c)
At least in this one case, I was able to gather the info from all the
different logfiles together and match the different entries. (If the
logfile entries help in debugging this, I can post the anonymized
entries here.) In the end, it looks very much like the imapproxy
(re-)used an expired connection to the IMAP server instead of the newly
created one for the user that just logged in.
If this is true, it would mean that the problem is not with the
IMAP_Line_Read code that I spent time looking at, but instead with some
other code which actually assigns the sds to user connections. Do you
agree so far? Does anyone have suggestions how to further investigate
this? Or where to look for the problem in the code?
Thanks,
Jens
------------------------------------------------------------------------------
-----
squirrelmail-imapproxy mailing list
Posting guidelines: http://squirrelmail.org/postingguidelines
List address: squirrelmail-imapproxy@lists.sourceforge.net
List archives: http://news.gmane.org/gmane.mail.squirrelmail.imapproxy
List info (subscribe/unsubscribe/change options):
https://lists.sourceforge.net/lists/listinfo/squirrelmail-imapproxy
