dovecot - Sep 2007 - imap process consuming 100% CPU (Dovecot 1.0.3)

Hi,

 I have yet another problem with Dovecot: sometimes (rarely, maybe
 once every few days) one of the imap processes will 'hang',
 consuming all available CPU time. It does not seem to 'finish' in any
 reasonable amount of time (in one instance I waited a few days). This
 process will not even exit gracefully, it needs to be killed with
 'kill -9 <PID>'.

 It has just happened again. The output from gdb is:
> # gdb attach 29401
> GNU gdb 6.3
> Copyright 2004 Free Software Foundation, Inc.
> GDB is free software, covered by the GNU General Public License, and you
are
> welcome to change it and/or distribute copies of it under certain
conditions.
> Type "show copying" to see the conditions.
> There is absolutely no warranty for GDB.  Type "show warranty"
for details.
> This GDB was configured as "i586-suse-linux"...attach: No such
file or directory.
> 
> Attaching to process 29401
> Reading symbols from /usr/local/libexec/dovecot/imap...done.
> Using host libthread_db library "/lib/tls/libthread_db.so.1".
> Reading symbols from /lib/libdl.so.2...done.
> Loaded symbols for /lib/libdl.so.2
> Reading symbols from /lib/tls/libc.so.6...done.
> Loaded symbols for /lib/tls/libc.so.6
> Reading symbols from /lib/ld-linux.so.2...done.
> Loaded symbols for /lib/ld-linux.so.2
> 0x0806049d in imap_sync_more (ctx=0x80d9770) at imap-sync.c:104
> 104                     if (ctx->seq == 0) {
> (gdb) bt full
> #0  0x0806049d in imap_sync_more (ctx=0x80d9770) at imap-sync.c:104
>         flags = 1075042320
>         keywords = <value optimized out>
>         str = (string_t *) 0x80c31e0
>         ret = 1
> #1  0x08060797 in cmd_sync_continue (cmd=0x80ccdbc) at imap-sync.c:207
>         ctx = (struct cmd_sync_context *) 0x80cf000
>         ret = <value optimized out>
> #2  0x0805ad5a in _client_output (context=0x80ccd78) at client.c:465
>         cmd = (struct client_command_context *) 0x80ccdbc
>         ret = 0
> #3  0x080af0bd in stream_send_io (context=0x80cceb0) at ostream-file.c:356
>         ostream = (struct ostream *) 0x80ccee0
>         ret = <value optimized out>
> #4  0x080aa441 in io_loop_handler_run (ioloop=0x80cb9b0) at
ioloop-epoll.c:203
>         ctx = (struct ioloop_handler_context *) 0x80cb9d8
>         list = (struct io_list *) 0x80d7780
>         io = (struct io *) 0x80dc430
>         tv = {tv_sec = 2, tv_usec = 540048}
>         events_count = 4
>         t_id = 2
>         msecs = <value optimized out>
>         ret = 1
>         i = 0
>         j = 1
>         call = <value optimized out>
> #5  0x080a9889 in io_loop_run (ioloop=0x80cb9b0) at ioloop.c:329
> No locals.
> #6  0x08062087 in main (argc=1, argv=0xbffffaf4, envp=0xbffffafc) at
main.c:290
>         plugin_dir = <value optimized out>
 Mail log does not reveal anything immediately interesting.

 Thoughts?

 Server config ('dovecot -n -c
/etc/dovecot/dovecot.conf'):
> # 1.0.3: /etc/dovecot/dovecot.conf
> base_dir: /var/run/dovecot/
> protocols: imap imaps pop3 pop3s
> ssl_ca_file: /etc/ssl/current/cacert.pem
> ssl_cert_file: /etc/ssl/current/server.pem
> ssl_key_file: /etc/ssl/current/private.pem
> disable_plaintext_auth: no
> login_dir: /var/run/dovecot//login
> login_executable(default): /usr/local/libexec/dovecot/imap-login
> login_executable(imap): /usr/local/libexec/dovecot/imap-login
> login_executable(pop3): /usr/local/libexec/dovecot/pop3-login
> first_valid_uid: 50
> mail_debug: yes
> mail_drop_priv_before_exec: yes
> mail_executable(default): /usr/local/libexec/dovecot/imap
> mail_executable(imap): /usr/local/libexec/dovecot/imap
> mail_executable(pop3): /usr/local/libexec/dovecot/pop3
> mail_plugin_dir(default): /usr/local/lib/dovecot/imap
> mail_plugin_dir(imap): /usr/local/lib/dovecot/imap
> mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3
> mail_log_prefix: %Us(%u)(%p):
> pop3_uidl_format(default):
> pop3_uidl_format(imap):
> pop3_uidl_format(pop3): %08Xu%08Xv
> auth default:
>   debug_passwords: yes
>   passdb:
>     driver: passwd-file
>     args: /etc/dovecot/passwd
>   userdb:
>     driver: passwd-file
>     args: /etc/dovecot/passwd
>   socket:
>     type: listen
>     client:
>       path: /var/spool/postfix/private/auth
>       mode: 432
>       user: postfix
>       group: postfix
-- 
Best regards,
 Robert Tomanek                         mailto:rth23 at poczta.onet.pl

Hi,

Sunday, September 2, 2007, 22:42:37, you wrote:
>> 0x0806049d in imap_sync_more (ctx=0x80d9770) at imap-sync.c:104
>> 104                     if (ctx->seq == 0) {
 A short follow-up on this, looks like an infinite loop to me, unless
 some threading magic is supposed to happen here:
> (gdb) step
> 120                             if (ctx->sync_rec.seq1 >
ctx->messages_count)
> (gdb)
> 104                     if (ctx->seq == 0) {
> (gdb)
> 117                     if (ctx->sync_rec.seq2 >
ctx->messages_count) {
> (gdb)
> 120                             if (ctx->sync_rec.seq1 >
ctx->messages_count)
> (gdb)
> 104                     if (ctx->seq == 0) {
> (gdb)
> 117                     if (ctx->sync_rec.seq2 >
ctx->messages_count) {
> (gdb)
> 120                             if (ctx->sync_rec.seq1 >
ctx->messages_count)
> (gdb) print ctx->seq
> $1 = 8317
> (gdb) print ctx->sync_rec.seq1
> $2 = 8318
> (gdb) print ctx->sync_rec.seq2
> $3 = 8320
> (gdb) print ctx->messages_count
> $4 = 8317
 The corresponding code in imap-sync.c is:
103:        for (;;) {
104:                if (ctx->seq == 0) {
105:                        /* get next one */
106:                        ret = mailbox_sync_next(ctx->sync_ctx,
107:                                                &ctx->sync_rec);
108:                        if (ret <= 0) {
109:                                if (ret == 0) {
110:                                        /* all finished ok */
111:                                        ret = 1;
112:                                }
113:                                break;
114:                        }
115:                }
116:
117:               if (ctx->sync_rec.seq2 > ctx->messages_count) {
118:                        /* don't send change notifications of messages
we
119:                           haven't even announced to client yet */
120:                        if (ctx->sync_rec.seq1 >
ctx->messages_count)
121:                                continue;
122:                        ctx->sync_rec.seq2 = ctx->messages_count;
123:                }
 ...
185:        }

-- 
Best regards,
 Robert Tomanek                           mailto:rth23 at poczta.onet.pl

> 
> Hi,
> 
>  I have yet another problem with Dovecot: sometimes (rarely, maybe
>  once every few days) one of the imap processes will 'hang',
>  consuming all available CPU time. It does not seem to 'finish' in
any
>  reasonable amount of time (in one instance I waited a few days). 
....
> 
>  Robert Tomanek                         mailto:rth23 at poczta.onet.pl
We have also seen this behavior, running Dovecot 1.0 on AIX.  
Thanks for your debug work on it Robert.

Jackie
---
Jackie Hunt                                                       
ACNS                                    Voice:  (970) 663-3789     
Colorado State University               FAX:    (970) 491-1958
Fort Collins, CO  80523                 Email:  jackie.hunt at colostate.edu