[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:50
It 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@poczta.onet.pl
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@poczta.onet.pl
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@poczta.onet.pl
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/a3300666c111
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/a3300666c111
Running a patched version of 1.0.5 since yesterday, so far so good...
Thanks!
-- Best regards, Robert Tomanek mailto:rth23@poczta.onet.pl
participants (2)
-
Robert Tomanek
-
Timo Sirainen