[Dovecot] dovecot 1.0-test69 io hangs
Jens Laas
jens.laas at data.slu.se
Fri May 13 15:01:40 EEST 2005
(05.05.13 kl.12:36) Jens Laas skrev följande till Andrew Hucthings:
> (05.05.13 kl.08:41) Andrew Hucthings skrev följande till dovecot at dovecot.org:
>
>> Hi Jens,
>>
>> You have to create a dovecot.rawlog directory in the user's home
>> directory (or what dovecot thinks is that directory). That way you
>> limit the logging to problematic users.
>
> Thanks.
>
> Its seems like this is a heisenbug.
> When I use rawlog the hang problem does not show itself.
> (Likewise it took longer to show when I patched in some extra logging,
> so the load of the machine/connection seems to be involved.)
>
> Ill try to think of something else...
>
> Cheers,
> Jens
>
Ive implemented a lot of logging with i_info.
It seems like input from client is disabled and never reenabled.
(The more logging I do the harder it seems to be to trigger the hang..)
Log:
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8185 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8186 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): client_send_line: disabling
input wi:false
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8187 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): client_input: handled 3 cmds
dovecot: May 13 13:49:39 Info: POP3(jenslt): client_output: enabling input
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8188 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8189 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8190 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): client_send_line: disabling
input wi:false
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8191 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8192 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): RETR: fetch 8193 begin
dovecot: May 13 13:49:39 Info: POP3(jenslt): client_input: handled 6 cmds
dovecot: May 13 13:49:44 Info: POP3(jenslt): io_loop_handler_run: 4 sec
timeout in poll(5999)
.. and here we are stuck
Ill attach the relevant patches for this kind of logging.
They are all incremental patches on top of the nice logging patch
previously posted here by .. someone i forgot.
The first attchment is the general logging patch. The rest are my debug
patches.
Cheers,
Jens
>>
>> Regards
>> Andrew
>>
>> On Fri, 2005-05-13 at 09:07 +0200, Jens Laas wrote:
>>> I've been testing test69 with pop3 (under Linux and with mbox).
>>> I began testing with a large inbox (11000 mails) and it seems the
>>> communication between dovecot and the mailclient (evolution) stalls after
>>> 1000-2000 messages transferred.
>>>
>>> I've looked in to the (non-trivial) io functionality of dovecot.
>>> What I see is that io_loop_handler_run() in ioloop-poll.c does not
>>> signal any more data (and eventually the whole thing timeouts).
>>>
>>> Evolution downloads the mailbox fine via qpopper.
>>>
>>> I tried turning on rawlog:
>>> mail_executable = /usr/libexec/dovecot/rawlog /usr/libexec/dovecot/pop3
>>>
>>> I cannot find any logfile.. I must be missing something.
>>>
>>> Any help or ideas ?
>>>
>>> Cheers,
>>> Jens
>>>
>>> -----------------------------------------------------------------------
>>> 'This mail automatically becomes portable when carried.'
>>> -----------------------------------------------------------------------
>>> Jens Låås Email: jens.laas at data.slu.se
>>> Department of Computer Services, SLU Phone: +46 18 67 35 15
>>> Vindbrovägen 1
>>> P.O. Box 7079
>>> S-750 07 Uppsala
>>> SWEDEN
>>> -----------------------------------------------------------------------
>>>
>> --
>> Andrew Hutchings (A-Wing)
>> Linux Guru - Netserve Consultants Ltd. - www.domaincity.co.uk
>> Admin - North Wales Linux User Group - www.nwlug.org.uk
>> BOFH excuse 58: high pressure system failure
>>
>
> -----------------------------------------------------------------------
> 'This mail automatically becomes portable when carried.'
> -----------------------------------------------------------------------
> Jens Låås Email: jens.laas at data.slu.se
> Department of Computer Services, SLU Phone: +46 18 67 35 15
> Vindbrovägen 1
> P.O. Box 7079
> S-750 07 Uppsala
> SWEDEN
> -----------------------------------------------------------------------
>
-----------------------------------------------------------------------
'This mail automatically becomes portable when carried.'
-----------------------------------------------------------------------
Jens Låås Email: jens.laas at data.slu.se
Department of Computer Services, SLU Phone: +46 18 67 35 15
Vindbrovägen 1
P.O. Box 7079
S-750 07 Uppsala
SWEDEN
-----------------------------------------------------------------------
-------------- next part --------------
diff -urdpNX /usr/share/dontdiff dovecot-1.0-test69.vanilla/src/imap-login/client-authenticate.c dovecot-1.0-test69/src/imap-login/client-authenticate.c
--- dovecot-1.0-test69.vanilla/src/imap-login/client-authenticate.c 2005-01-08 17:59:03.000000000 +0300
+++ dovecot-1.0-test69/src/imap-login/client-authenticate.c 2005-05-09 10:52:38.418290440 +0400
@@ -188,7 +188,12 @@ static void sasl_callback(struct client
client_send_tagline(client, "OK Logged in.");
client_destroy(client, t_strconcat(
- "Login: ", client->common.virtual_user, NULL));
+ "Login: ", client->common.virtual_user,
+ ", method: ", client->common.auth_mech_name,
+ client->common.secured ? ", SSL" : "",
+ ", lip: [", net_ip2addr(&client->common.local_ip),
+ "], rip:",
+ NULL));
break;
case SASL_SERVER_REPLY_AUTH_FAILED:
if (args != NULL) {
diff -urdpNX /usr/share/dontdiff dovecot-1.0-test69.vanilla/src/pop3/client.c dovecot-1.0-test69/src/pop3/client.c
--- dovecot-1.0-test69.vanilla/src/pop3/client.c 2005-04-29 15:37:34.000000000 +0400
+++ dovecot-1.0-test69/src/pop3/client.c 2005-05-09 10:52:38.437287552 +0400
@@ -156,12 +156,12 @@ struct client *client_create(int hin, in
i_error("Couldn't open INBOX: %s",
mail_storage_get_last_error(storage, &syntax_error));
client_send_line(client, "-ERR No INBOX for user.");
- client_destroy(client);
+ client_destroy(client, "No INBOX for user.");
return NULL;
}
if (!init_mailbox(client)) {
- client_destroy(client);
+ client_destroy(client, "Mailbox init failed");
return NULL;
}
@@ -173,8 +173,18 @@ struct client *client_create(int hin, in
return client;
}
-void client_destroy(struct client *client)
+static const char *client_stats(struct client *client)
+{
+ return t_strdup_printf("top=%d, retr=%d, del=%d/%d",
+ client->top_bytes, client->retr_bytes,
+ client->deleted_count, client->messages_count);
+}
+
+void client_destroy(struct client *client, const char *reason)
{
+ if (reason != NULL)
+ i_info("%s %s", reason, client_stats(client));
+
if (client->cmd != NULL) {
/* deinitialize command */
i_stream_close(client->input);
@@ -204,8 +214,11 @@ void client_destroy(struct client *clien
io_loop_stop(ioloop);
}
-void client_disconnect(struct client *client)
+void client_disconnect(struct client *client, const char *reason)
{
+ if (reason != NULL)
+ i_info("%s %s", reason, client_stats(client));
+
(void)o_stream_flush(client->output);
i_stream_close(client->input);
@@ -266,7 +279,7 @@ void client_send_storage_error(struct cl
if (mailbox_is_inconsistent(client->mailbox)) {
client_send_line(client, "-ERR Mailbox is in inconsistent "
"state, please relogin.");
- client_disconnect(client);
+ client_disconnect(client, "Mailbox is in inconsistent state.");
return;
}
@@ -295,12 +308,12 @@ static void client_input(void *context)
switch (i_stream_read(client->input)) {
case -1:
/* disconnected */
- client_destroy(client);
+ client_destroy(client, "Disconnected");
return;
case -2:
/* line too long, kill it */
client_send_line(client, "-ERR Input line too long.");
- client_destroy(client);
+ client_destroy(client, "Input line too long.");
return;
}
@@ -323,13 +336,13 @@ static void client_input(void *context)
}
} else if (++client->bad_counter > CLIENT_MAX_BAD_COMMANDS) {
client_send_line(client, "-ERR Too many bad commands.");
- client_disconnect(client);
+ client_disconnect(client, "Too many bad commands.");
}
}
o_stream_uncork(client->output);
if (client->output->closed)
- client_destroy(client);
+ client_destroy(client, NULL);
}
static int client_output(void *context)
@@ -338,7 +351,7 @@ static int client_output(void *context)
int ret;
if ((ret = o_stream_flush(client->output)) < 0) {
- client_destroy(client);
+ client_destroy(client, NULL);
return 1;
}
@@ -371,13 +384,13 @@ static void idle_timeout(void *context _
if (my_client->cmd != NULL) {
if (ioloop_time - my_client->last_output >=
CLIENT_OUTPUT_TIMEOUT)
- client_destroy(my_client);
+ client_destroy(my_client, "Disconnected for inactivity.");
} else {
if (ioloop_time - my_client->last_input >=
CLIENT_IDLE_TIMEOUT) {
client_send_line(my_client,
"-ERR Disconnected for inactivity.");
- client_destroy(my_client);
+ client_destroy(my_client, "Disconnected for inactivity.");
}
}
}
@@ -392,7 +405,7 @@ void clients_deinit(void)
{
if (my_client != NULL) {
client_send_line(my_client, "-ERR Server shutting down.");
- client_destroy(my_client);
+ client_destroy(my_client, "Server shutting down.");
}
timeout_remove(to_idle);
diff -urdpNX /usr/share/dontdiff dovecot-1.0-test69.vanilla/src/pop3/client.h dovecot-1.0-test69/src/pop3/client.h
--- dovecot-1.0-test69.vanilla/src/pop3/client.h 2004-12-16 23:50:12.000000000 +0300
+++ dovecot-1.0-test69/src/pop3/client.h 2005-05-09 10:52:38.440287096 +0400
@@ -30,6 +30,10 @@ struct client {
uoff_t deleted_size;
uint32_t last_seen;
+ unsigned int top_bytes;
+ unsigned int retr_bytes;
+ unsigned int *byte_counter;
+
unsigned char *deleted_bitmask;
unsigned int deleted:1;
@@ -39,10 +43,10 @@ struct client {
/* Create new client with specified input/output handles. socket specifies
if the handle is a socket. */
struct client *client_create(int hin, int hout, struct mail_storage *storage);
-void client_destroy(struct client *client);
+void client_destroy(struct client *client, const char *reason);
/* Disconnect client connection */
-void client_disconnect(struct client *client);
+void client_disconnect(struct client *client, const char *reason);
/* Send a line of data to client */
int client_send_line(struct client *client, const char *fmt, ...)
diff -urdpNX /usr/share/dontdiff dovecot-1.0-test69.vanilla/src/pop3/commands.c dovecot-1.0-test69/src/pop3/commands.c
--- dovecot-1.0-test69.vanilla/src/pop3/commands.c 2005-05-08 13:37:43.000000000 +0400
+++ dovecot-1.0-test69/src/pop3/commands.c 2005-05-09 10:52:38.476281624 +0400
@@ -217,7 +217,7 @@ static int cmd_quit(struct client *clien
if (client->deleted) {
if (!expunge_mails(client)) {
client_send_storage_error(client);
- client_disconnect(client);
+ client_disconnect(client, "Storage error during logout.");
return TRUE;
}
}
@@ -230,7 +230,7 @@ static int cmd_quit(struct client *clien
else
client_send_line(client, "+OK Logging out, messages deleted.");
- client_disconnect(client);
+ client_disconnect(client, "Logout.");
return TRUE;
}
@@ -311,6 +311,7 @@ static void fetch_callback(struct client
break;
ctx->last = data[i-1];
i_stream_skip(ctx->stream, i);
+ *client->byte_counter += i;
}
if (o_stream_get_buffer_used_size(client->output) >= 4096) {
@@ -326,6 +327,8 @@ static void fetch_callback(struct client
if (o_stream_send(client->output, &add, 1) < 0)
break;
+ *client->byte_counter += 1;
+
ctx->last = add;
if (add == 0x80)
i_stream_skip(ctx->stream, 1);
@@ -335,11 +338,13 @@ static void fetch_callback(struct client
if (ctx->last != '\n') {
/* didn't end with CRLF */
(void)o_stream_send(client->output, "\r\n", 2);
+ *client->byte_counter += 2;
}
if (!ctx->in_body && (client_workarounds & WORKAROUND_OE_NS_EOH) != 0) {
/* Add the missing end of headers line. */
(void)o_stream_send(client->output, "\r\n", 2);
+ *client->byte_counter += 2;
}
client_send_line(client, ".");
@@ -405,6 +410,8 @@ static int cmd_retr(struct client *clien
if (client->last_seen <= msgnum)
client->last_seen = msgnum+1;
+ client->byte_counter = &client->retr_bytes;
+
fetch(client, msgnum, (uoff_t)-1);
return TRUE;
}
@@ -468,6 +475,8 @@ static int cmd_top(struct client *client
if (get_size(client, args, &max_lines) == NULL)
return FALSE;
+ client->byte_counter = &client->top_bytes;
+
fetch(client, msgnum, max_lines);
return TRUE;
}
diff -urdpNX /usr/share/dontdiff dovecot-1.0-test69.vanilla/src/pop3-login/client-authenticate.c dovecot-1.0-test69/src/pop3-login/client-authenticate.c
--- dovecot-1.0-test69.vanilla/src/pop3-login/client-authenticate.c 2005-03-08 23:26:56.000000000 +0300
+++ dovecot-1.0-test69/src/pop3-login/client-authenticate.c 2005-05-09 10:52:38.480281016 +0400
@@ -161,7 +161,12 @@ static void sasl_callback(struct client
client_send_line(client, "+OK Logged in.");
client_destroy(client, t_strconcat(
- "Login: ", client->common.virtual_user, NULL));
+ "Login: ", client->common.virtual_user,
+ ", auth: ", client->common.auth_mech_name,
+ client->common.secured ? ", SSL" : "",
+ ", lip: [", net_ip2addr(&client->common.local_ip),
+ "], rip:",
+ NULL));
break;
case SASL_SERVER_REPLY_AUTH_FAILED:
if (args != NULL) {
-------------- next part --------------
--- src/pop3/commands.c.orig 2005-05-11 14:51:24.000000000 +0200
+++ src/pop3/commands.c 2005-05-13 13:40:18.921320144 +0200
@@ -47,6 +47,7 @@
if (client->deleted) {
if (client->deleted_bitmask[num / CHAR_BIT] &
(1 << (num % CHAR_BIT))) {
+ i_info("get_msgnum: msg %u is deleted", num+1);
client_send_line(client, "-ERR Message is deleted.");
return NULL;
}
@@ -98,16 +99,24 @@
unsigned int msgnum;
if (get_msgnum(client, args, &msgnum) == NULL)
- return FALSE;
+ {
+ i_info("DELE msg does not exits or is deleted %s", args);
+ return FALSE;
+ }
if (!client->deleted) {
+ i_info("DELE creating bitmap of size %u with room for %u msgs",
+ MSGS_BITMASK_SIZE(client),
+ MSGS_BITMASK_SIZE(client)*CHAR_BIT);
client->deleted_bitmask = i_malloc(MSGS_BITMASK_SIZE(client));
client->deleted = TRUE;
}
- client->deleted_bitmask[msgnum / CHAR_BIT] |= 1 << (msgnum % CHAR_BIT);
+ client->deleted_bitmask[msgnum / CHAR_BIT] |= (1 << (msgnum % CHAR_BIT));
client->deleted_count++;
client->deleted_size += client->message_sizes[msgnum];
+ i_info("DELE msg %u deleted (%u/%u deleted)",
+ msgnum, client->deleted_count, client->messages_count);
client_send_line(client, "+OK Marked to be deleted.");
return TRUE;
}
@@ -153,13 +162,17 @@
client->cmd = cmd_list_callback;
client->cmd_context = ctx;
+ i_info("LIST *");
cmd_list_callback(client);
} else {
unsigned int msgnum;
if (get_msgnum(client, args, &msgnum) == NULL)
- return FALSE;
-
+ {
+ i_info("LIST no such msg %u", msgnum);
+ return FALSE;
+ }
+ i_info("LIST %u", msgnum);
client_send_line(client, "+OK %u %"PRIuUOFF_T, msgnum+1,
client->message_sizes[msgnum]);
}
@@ -175,6 +188,7 @@
static int cmd_noop(struct client *client, const char *args __attr_unused__)
{
+ i_info("NOOP");
client_send_line(client, "+OK");
return TRUE;
}
@@ -188,7 +202,10 @@
int ret = TRUE;
if (client->deleted_bitmask == NULL)
+ {
+ i_info("expunge: no deleted messages");
return TRUE;
+ }
memset(&search_arg, 0, sizeof(search_arg));
search_arg.type = SEARCH_ALL;
@@ -201,6 +218,8 @@
1 << (idx % CHAR_BIT)) != 0) {
if (mail_expunge(mail) < 0) {
ret = FALSE;
+ i_info("expunge: failed to expunge %u",
+ idx/CHAR_BIT);
break;
}
}
@@ -209,11 +228,13 @@
if (mailbox_search_deinit(ctx) < 0)
ret = FALSE;
+ i_info("expunge: done");
return ret;
}
static int cmd_quit(struct client *client, const char *args __attr_unused__)
{
+ i_info("QUIT");
if (client->deleted) {
if (!expunge_mails(client)) {
client_send_storage_error(client);
@@ -221,15 +242,16 @@
return TRUE;
}
}
-
mailbox_transaction_commit(client->trans, MAILBOX_SYNC_FLAG_FULL_WRITE);
client->trans = NULL;
+ i_info("QUIT: transaction commit done");
if (!client->deleted)
client_send_line(client, "+OK Logging out.");
else
client_send_line(client, "+OK Logging out, messages deleted.");
+ i_info("QUIT: disconnecting");
client_disconnect(client, "Logout.");
return TRUE;
}
@@ -405,14 +427,19 @@
unsigned int msgnum;
if (get_msgnum(client, args, &msgnum) == NULL)
+ {
+ i_info("RETR: no such msg %s", args);
return FALSE;
+ }
if (client->last_seen <= msgnum)
client->last_seen = msgnum+1;
client->byte_counter = &client->retr_bytes;
+ i_info("RETR: fetch %u begin", msgnum);
fetch(client, msgnum, (uoff_t)-1);
+ //i_info("RETR: fetch %u done", msgnum);
return TRUE;
}
@@ -422,6 +449,7 @@
struct mail *mail;
struct mail_search_arg search_arg;
+ i_info("RSET");
client->last_seen = 0;
if (client->deleted) {
@@ -458,6 +486,7 @@
static int cmd_stat(struct client *client, const char *args __attr_unused__)
{
+ i_info("STAT");
client_send_line(client, "+OK %u %"PRIuUOFF_T, client->
messages_count - client->deleted_count,
client->total_size - client->deleted_size);
@@ -469,6 +498,7 @@
unsigned int msgnum;
uoff_t max_lines;
+ i_info("TOP");
args = get_msgnum(client, args, &msgnum);
if (args == NULL)
return FALSE;
@@ -614,6 +644,7 @@
struct cmd_uidl_context *ctx;
if (*args == '\0') {
+ i_info("UIDL *");
client_send_line(client, "+OK");
ctx = cmd_uidl_init(client, 0);
list_uids_iter(client, ctx);
@@ -621,8 +652,12 @@
unsigned int msgnum;
if (get_msgnum(client, args, &msgnum) == NULL)
+ {
+ i_info("UIDL no such msg %u", msgnum);
return FALSE;
+ }
+ i_info("UIDL msg %u", msgnum);
ctx = cmd_uidl_init(client, msgnum+1);
if (!list_uids_iter(client, ctx))
client_send_line(client, "-ERR Message not found.");
-------------- next part --------------
--- src/pop3/client.c.orig 2005-05-12 13:54:41.000000000 +0200
+++ src/pop3/client.c 2005-05-13 13:28:03.095182720 +0200
@@ -254,6 +254,8 @@
if (client->io != NULL) {
/* no more input until client has read
our output */
+ i_info("client_send_line: disabling input wi:%s",
+ client->waiting_input?"true":"false");
io_remove(client->io);
client->io = NULL;
@@ -292,10 +294,12 @@
{
struct client *client = context;
char *line, *args;
+ int cmdcount=0;
if (client->cmd != NULL) {
/* we're still processing a command. wait until it's
finished. */
+ i_info("client_input: still processing command, disabling input");
io_remove(client->io);
client->io = NULL;
client->waiting_input = TRUE;
@@ -338,7 +342,9 @@
client_send_line(client, "-ERR Too many bad commands.");
client_disconnect(client, "Too many bad commands.");
}
+ cmdcount++;
}
+ i_info("client_input: handled %d cmds", cmdcount);
o_stream_uncork(client->output);
if (client->output->closed)
@@ -366,12 +372,20 @@
OUTBUF_THROTTLE_SIZE/2 && client->io == NULL &&
client->cmd == NULL) {
/* enable input again */
+ i_info("client_output: enabling input");
client->io = io_add(i_stream_get_fd(client->input), IO_READ,
client_input, client);
}
if (client->cmd == NULL && client->io != NULL && client->waiting_input)
client_input(client);
+ else
+ {
+ if (client->waiting_input)
+ {
+ i_info("client->waiting_input == TRUE");
+ }
+ }
return client->cmd == NULL;
}
-------------- next part --------------
--- src/lib/ioloop-poll.c.orig 2005-05-12 14:11:53.640361168 +0200
+++ src/lib/ioloop-poll.c 2005-05-13 08:15:16.426617376 +0200
@@ -134,14 +134,32 @@
struct timeval tv;
struct io *io;
unsigned int t_id;
- int msecs, ret, call;
+ int msecs, msec_wait, ret, call;
/* get the time left for next timeout task */
msecs = io_loop_get_wait_time(ioloop->timeouts, &tv, NULL);
- ret = poll(data->fds, data->fds_pos, msecs);
- if (ret < 0 && errno != EINTR)
- i_fatal("poll(): %m");
+ while(1)
+ {
+ msec_wait = 4000;
+ if(msecs > 4000)
+ msecs -= 4000;
+ else
+ {
+ if(msecs >= 0)
+ {
+ msec_wait = msecs;
+ msecs = 0;
+ }
+ }
+
+ ret = poll(data->fds, data->fds_pos, msec_wait);
+ if (ret < 0 && errno != EINTR)
+ i_fatal("poll(): %m");
+ if( (ret == 0) && msec_wait == 4000 )
+ i_info("io_loop_handler_run: 4 sec timeout in poll(%d)", msecs);
+ if( (ret > 0) || msecs == 0) break;
+ }
/* execute timeout handlers */
io_loop_handle_timeouts(ioloop);
More information about the dovecot
mailing list