Robert Tomanek
2007-Sep-02 18:24 UTC
[Dovecot] IMAP: Disconnected: BUG: Unknown internal error (Dovecot 1.0.3)
Hi, I am getting the following error in the server mail logfile:> Sep 2 18:39:44 h648123 dovecot: IMAP(<account>)(<PID>): Disconnected: BUG: Unknown internal error(mail_debug is on, but there is not really much context for this in the log file, ie. no log events for several minutes, and then it appears, all of a sudden). On the client side, it looks like this (with some context in case it matters; no exact times though, sorry):> [...] > S: * 17699 FETCH (UID 18226 FLAGS (\Seen)) > S: * 17700 FETCH (UID 18227 FLAGS (\Seen)) > S: * 17701 FETCH (UID 18228 FLAGS (\Seen)) > S: * 17702 FETCH (UID 18229 FLAGS (\Seen)) > S: * 17703 FETCH (UID 18230 FLAGS (\Seen)) > S: * 17704 FETCH (UID 18231 FLAGS (\Seen)) > S: * 17705 FETCH (UID 18232 FLAGS (\Seen)) > S: * 17706 FETCH (UID 18233 FLAGS (\Seen)) > S: * 17707 FETCH (UID 18234 FLAGS (\Seen)) > S: * 17708 FETCH (UID 18235 FLAGS (\Seen)) > S: * 17711 EXISTS > S: * 1 RECENT > S: U00328 OK Fetch completed. > C: U00329 UID FETCH 18238:* (UID RFC822.SIZE ENVELOPE BODYSTRUCTURE INTERNALDATE FLAGS) > S: * 17711 FETCH (UID 18238 RFC822.SIZE 0 INTERNALDATE "01-01-1970 00:00:00 +0000" FLAGS (\Seen \Recent) ENVELOPE (NIL NIL NIL NIL NIL NIL NIL NIL NIL NIL) BODYSTRUCTURE ("text" "plain" NIL NIL NIL "7bit" 0 0 NIL NIL NIL NIL NIL NIL NIL)) > S: U00329 OK Fetch completed. > C: U00330 UID FETCH 18238 (INTERNALDATE FLAGS) > C: U00331 UID FETCH 18238 (INTERNALDATE FLAGS RFC822.HEADER) > S: ) > S: !! Empty response received > S: * BYE BUG: Unknown internal error > S: !! Socket status 0 > > > *** Session finished : 2007-09-02 18:39:50, 18:39:50It occurs relatively often (several times a day), under no specific conditions (sometimes it is hours after the session was started, sometimes it is at the beginning -- really, nothing regular here). The client connection is simply closed. I am not getting a core dump for this; I am not sure whether I am supposed to. I configured Dovecot according to the instructions at http://www.dovecot.org/bugreport.html and core dumps generally work on my system, eg. I can force one using 'kill -s SIGSEGV <PID>' (where <PID> is a PID of one of the imap processes). What do I do with it? I am running Dovecot 1.0.3 (compiled from sources) on Suse 9.3. The client is The Bat! 3.99.x Professional. Client is allowed to open several concurrent connections to the IMAP server. 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
Robert Tomanek
2007-Sep-03 21:16 UTC
[Dovecot] IMAP: Disconnected: BUG: Unknown internal error (Dovecot 1.0.3)
Hi, Sunday, September 2, 2007, 20:24:04, you wrote:> I am getting the following error in the server mail logfile: >> Sep 2 18:39:44 h648123 dovecot: IMAP(<account>)(<PID>): Disconnected: BUG: >> Unknown internal error > I am running Dovecot 1.0.3 (compiled from sources) on Suse 9.3.I did one more thing: using gdb I attached to all 'imap' processes and set a breakpoint at the only place in the code where "Unknown internal error" appears (that is 'index_storage_get_last_error' in lib-storage/index/index-storage.c) in order to get backtrace for it (which may or may not help). See for yourselves:> (gdb) break index-storage.c:452 > Breakpoint 1 at 0x807eec7: file index-storage.c, line 452. > (gdb) continue > Continuing. > > Breakpoint 1, index_storage_get_last_error (storage=0x80cca90, syntax_error_r=0x0, temporary_error_r=0xbffff8ef) > at index-storage.c:452 > 452 *temporary_error_r = TRUE; > (gdb) bt full > #0 index_storage_get_last_error (storage=0x80cca90, syntax_error_r=0x0, temporary_error_r=0xbffff8ef) > at index-storage.c:452 > No locals. > #1 0x08097765 in mail_storage_get_last_error (storage=0x0, syntax_error_r=0xbffff8ee, temporary_error_r=0xbffff8ef) > at mail-storage.c:345 > No locals. > #2 0x080573b1 in cmd_fetch_finish (ctx=<value optimized out>) at cmd-fetch.c:90 > storage = (struct mail_storage *) 0x80cca90 > error = <value optimized out> > syntax = false > temporary_error = 8 > cmd = (struct client_command_context *) 0x80ccdbc > ok_message = 0x80b395b "OK Fetch completed." > #3 0x08057623 in cmd_fetch (cmd=0x80ccdbc) at cmd-fetch.c:173 > client = (struct client *) 0x80ccd78 > ctx = (struct imap_fetch_context *) 0x80cf010 > args = <value optimized out> > search_arg = (struct mail_search_arg *) 0x80cefd8 > messageset = <value optimized out> > ret = <value optimized out> > #4 0x0805a0de in cmd_uid (cmd=0x80ccdbc) at cmd-uid.c:19 > cmd_name = 0x80cd078 "FETCH" > #5 0x0805a616 in client_handle_input (cmd=0x80ccdbc) at client.c:335 > client = (struct client *) 0x80ccd78 > #6 0x0805a73a in client_handle_input (cmd=0x80ccdbc) at client.c:389 > client = (struct client *) 0x80ccd78 > #7 0x0805ac4c in _client_input (context=0x80ccd78) at client.c:432 > client = (struct client *) 0x80ccd78 > cmd = (struct client_command_context *) 0x80ccdbc > ret = 2 > #8 0x080aa441 in io_loop_handler_run (ioloop=0x80cb9b0) at ioloop-epoll.c:203 > ctx = (struct ioloop_handler_context *) 0x80cb9d8 > list = (struct io_list *) 0x80ccf48 > io = (struct io *) 0x80ccf28 > tv = {tv_sec = 0, tv_usec = 927459} > events_count = 4 > t_id = 2 > msecs = <value optimized out> > ret = 1 > i = 0 > j = 0 > call = <value optimized out> > #9 0x080a9889 in io_loop_run (ioloop=0x80cb9b0) at ioloop.c:329 > No locals. > #10 0x08062087 in main (argc=1, argv=0xbffffaf4, envp=0xbffffafc) at main.c:290 > plugin_dir = <value optimized out>Any thoughts here? One more piece of info that might (?) be interesting -- I have just run a grep on historical logs and it seems the bug never occured on previous versions of Dovecot I had been running in the past (first it was stock Suse 9.3 Dovecot 0.99.14, then a self-compiled 1.0.rc27). The only difference (apart from the actual source code, of course) between 1.0.rc27 and the current 1.0.3 that might play any role are the configure flags: - 1.0.rc27: ./configure --with-pam - 1.0.3 : ./configure --with-ioloop=best --with-ldap --with-sql --with-mysql --with-pam This resulted in using epoll() for 1.0.3 and poll() for 1.0.rc27; both versions are using dnotify. BTW, 'uname -a' returns: Linux h648123 2.6.11.4-21.9-default #1 Fri Aug 19 11:58:59 UTC 2005 i686 athlon i386 GNU/Linux -- Best regards, Robert Tomanek mailto:rth23 at poczta.onet.pl
Robert Tomanek
2007-Sep-09 09:56 UTC
[Dovecot] IMAP: Disconnected: BUG: Unknown internal error (Dovecot 1.0.x)
Hi, Monday, September 3, 2007, 23:16:07, you wrote:> One more piece of info that might (?) be interesting -- I have just > run a grep on historical logs and it seems the bug never occured on > previous versions of Dovecot I had been running in the past (first > it was stock Suse 9.3 Dovecot 0.99.14, then a self-compiled > 1.0.rc27).> The only difference (apart from the actual source code, of course) > between 1.0.rc27 and the current 1.0.3 that might play any role are > the configure flags: > - 1.0.rc27: ./configure --with-pam > - 1.0.3 : ./configure --with-ioloop=best --with-ldap --with-sql > --with-mysql --with-pam > This resulted in using epoll() for 1.0.3 and poll() for 1.0.rc27; > both versions are using dnotify.OK, I am now positive this has nothing to do with epoll() vs. poll() (which was unlikely anyway but I wanted to test it just in case). I have just compiled 1.0.5 with poll() -- which means that its config and compilation options are pretty much the same as with the previous versions -- and the bug occurs again, just as it did with 1.0.3/epoll(). Looking at the backtrace and the code, it seems imap_fetch_deinit() is failing. -- Best regards, Robert Tomanek mailto:rth23 at poczta.onet.pl
Timo Sirainen
2007-Sep-22 14:23 UTC
[Dovecot] IMAP: Disconnected: BUG: Unknown internal error (Dovecot 1.0.3)
On Sun, 2007-09-02 at 20:24 +0200, Robert Tomanek wrote:> > C: U00331 UID FETCH 18238 (INTERNALDATE FLAGS RFC822.HEADER) > > S: * BYE BUG: Unknown internal errorThis should fix it: http://hg.dovecot.org/dovecot-1.0/rev/a3300666c111 -------------- 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/20070922/e2acc0e8/attachment-0002.bin>
Robert Tomanek
2007-Sep-24 16:12 UTC
[Dovecot] IMAP: Disconnected: BUG: Unknown internal error (Dovecot 1.0.3)
Hello Timo, Saturday, September 22, 2007, 16:23:57, you wrote:> On Sun, 2007-09-02 at 20:24 +0200, Robert Tomanek wrote: >> > C: U00331 UID FETCH 18238 (INTERNALDATE FLAGS RFC822.HEADER) >> > S: * BYE BUG: Unknown internal error> This should fix it: http://hg.dovecot.org/dovecot-1.0/rev/a3300666c111Running a patched version of 1.0.5 since yesterday, so far so good... Thanks! -- Best regards, Robert Tomanek mailto:rth23 at poczta.onet.pl