[Dovecot] segv when Mailbox is in inconsistent state, please relogin.
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Hello,
for testing I have different filesystems on various block devices, which I mount on /mnt/mailcache as needed; however, the indexes and caches are located on /var/cache, hence, they get out of sync easily. No offense. Hoever, the web page (http://dovecot.org/bugreport.html) states that every signal 11 is a bug and will be fixed, so here it goes:
running Linux x32, Debian Etch, Dovecot rc23, MUA: Thunderbird. It occurs to me that the data on /var/cache must be younger than the one on /mnt/mailcache; e.g. when you re-login after the segv, it works fine. There seems to be one segv per folder with messages.
Logs: dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): Loading modules from directory: /usr/local/lib/dovecot/imap dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): Module loaded: /usr/local/lib/dovecot/imap/lib10_quota_plugin.so dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): Module loaded: /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): Effective uid=1012, gid=1000, home=/home/dvtest dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): maildir: data=/mnt/mailcache/dvtest/MailDir:CONTROL=/var/cache/dovecot/1012/control:INDEX=/var/cache/dovecot/1012/index dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): maildir: root=/mnt/mailcache/dvtest/MailDir, index=/var/cache/dovecot/1012/index, control=/var/cache/dovecot/1012/control, inbox= dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): fs quota add storage dir = /mnt/mailcache/dvtest/MailDir dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): fs quota block device = /dev/mapper/mailstaff-mailcache dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): fs quota mount point = /mnt/mailcache dovecot: Feb 21 14:40:54 Info: IMAP(dvtest): Disconnected: Mailbox is in inconsistent state, please relogin.
==> dovecot.log <== dovecot: Feb 21 14:40:54 Error: IMAP(dvtest): Maildir /mnt/mailcache/dvtest/MailDir sync: UID < next_uid (1 < 2, file = 1171969061.P22107Q0M366705.ux-2s11-9:2,S) dovecot: Feb 21 14:40:54 Error: IMAP(dvtest): Sending log messages too fast, throttling.. dovecot: Feb 21 14:40:54 Error: child 27323 (imap) killed with signal 11
==> dovecot.info <== dovecot: Feb 21 14:41:02 Info: IMAP(dvtest): Disconnected: Logged out
gdb output:
warning: Can't read pathname for load map: Input/output error. Reading symbols from /lib/tls/i686/cmov/libdl.so.2...done. Loaded symbols for /lib/tls/i686/cmov/libdl.so.2 Reading symbols from /lib/tls/i686/cmov/libc.so.6...done. Loaded symbols for /lib/tls/i686/cmov/libc.so.6 Reading symbols from /lib/ld-linux.so.2...done. Loaded symbols for /lib/ld-linux.so.2 Reading symbols from /usr/local/lib/dovecot/imap/lib10_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib10_quota_plugin.so Reading symbols from /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so...done. Loaded symbols for /usr/local/lib/dovecot/imap/lib11_imap_quota_plugin.so Core was generated by `imap [dvtest 10.20.10.63]'. Program terminated with signal 11, Segmentation fault. #0 o_stream_uncork (stream=0x0) at ostream.c:60 60 if (stream->closed) (gdb) bt full #0 o_stream_uncork (stream=0x0) at ostream.c:60 _stream = <value optimized out> #1 0x0805ba08 in _client_input (context=0x80df0f0) at client.c:431 client = (struct client *) 0x80df0f0 cmd = (struct client_command_context *) 0x80df134 #2 0x080ba550 in io_loop_handler_run (ioloop=0x80dd9b0) at ioloop-select.c:139 tv = {tv_sec = 0, tv_usec = 984000} io = (struct io *) 0x80df230 t_id = 2 ret = 1 #3 0x080b9868 in io_loop_run (ioloop=0x80dd9b0) at ioloop.c:284 No locals. #4 0x08063910 in main (argc=Cannot access memory at address 0x2 ) at main.c:285 No locals.
:~# dovecot -n
/usr/local/etc/dovecot.conf
log_path: /var/tmp/dovecot.log info_log_path: /var/tmp/dovecot.info ssl_disable: yes disable_plaintext_auth: no verbose_ssl: yes login_dir: /usr/local/var/run/dovecot/login login_executable: /usr/local/libexec/dovecot/imap-login verbose_proctitle: yes mail_location: maildir:/mnt/mailcache/%u/MailDir:CONTROL=/var/cache/dovecot/%i/control:INDEX=/var/cache/dovecot/%i/index mail_debug: yes mail_drop_priv_before_exec: yes mail_plugins: quota imap_quota auth default: mechanisms: plain login cache_size: 10 verbose: yes debug: yes debug_passwords: yes passdb: driver: pam args: cache_key=%u dovecot userdb: driver: passwd plugin: quota: fs
Bye,
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.6 (GNU/Linux)
iQEVAwUBRdxPmi9SORjhbDpvAQLTnQf/Qms2Ffp2g4tx0llz8UiaGdF27sRJLsHO UaF/aMmXL8E4Q6CXhbTMqU3Qzcczko6cnMuYKkL8m3OMNwosLccWoOpxqB1PAu5Y 4CtEpDt/v8O2m6OAFFk9UCXTtH4dZP41qrGHNpzj/8Bs597difLWe7N/nTl4K95f cS1n4NULV0+scSub1CfZkvHZeSxAHgr9e0zGby/PRPbsHeDG++NgwAfXR2zQVyEj vWWjDawD/5W9xlF8+eQ3fxVlil5xYLN8/t5C/2CDaR0nc/WXKk+PZFdpBkD22S5j iQN5zsX8Qf0FHxxm0eX1EsrKZKvvUeBQEMcqqcKXpT4F8L8pxfyRhg== =XMpZ -----END PGP SIGNATURE-----
On Wed, 2007-02-21 at 14:56 +0100, Steffen Kaiser wrote:
Hoever, the web page (http://dovecot.org/bugreport.html) states that every signal 11 is a bug and will be fixed, so here it goes:
Yes.
I don't get this though. I've checked all the code paths that I can think of, and I can't see why the stream would ever be NULL there. Do you still have the core file? Could you show me the output of:
fr 1 p *client p *cmd
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 22 Feb 2007, Timo Sirainen wrote:
you still have the core file? Could you show me the output of:
No unfortunately not. But I'll keep the younger core files (with segv on over quota).
Bye,
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.6 (GNU/Linux)
iQEVAwUBRd6ufy9SORjhbDpvAQIDFQgAqTb46qaukgQi68ClkgVgkxkXA+LC9WAz NBvalh5gD9nGAKq9Ifp4TzFgswjMqBfC7ubBaWcm1QA5aoE+ZkdAcbjnluEgtuTZ MUInqFTlhlYGB1hGqTGsvTMl6gbhX0B1ofYsYihkos7GLNh307X27IxidoF96GmW h7yPxkcMIivyxlCZ8oD2jhK1nkq6ZNavF9QT73ukK1LITwxWO5hUGfALZF6uwwG4 eyteIy1QDWjwAXJ9ZWlK1aV2WQbFrqZTOJwJAP3+8zuk21slPzw0sTTrE8D+4o88 kaJpWgPKKAQ6lgcQwqKTSk8GCLci1GFTt4jmAZ9gVYxYo3YYwzEi3w== =dTLE -----END PGP SIGNATURE-----
On Thu 22 Feb 2007 at 03:57PM, Timo Sirainen wrote:
I've just hit what I think is the same bug or something similar, running 1.0rc24, while I was messing around with TBird 2.0 b2-- I did a bunch of different things with different settings, and quit and restarted the client numerous times, so I don't know exactly what triggered it. The message count of "814" means this is probably my "spam" folder.
(dbx) where =>[1] o_stream_uncork(stream = (nil)), line 60 in "ostream.c" [2] _client_input(context = 0xc32f0), line 431 in "client.c" [3] io_loop_handler_run(ioloop = 0xc0ae8), line 199 in "ioloop-poll.c" [4] io_loop_run(ioloop = 0xc0ae8), line 284 in "ioloop.c" [5] main(argc = -4195263, argv = 0xb4c00, envp = 0xb5f6c), line 287 in "main.c"
(dbx) dump _stream = 0xc2000000 stream = (nil)
(dbx) up
(dbx) dump client = 0xc32f0 ret = 1 context = 0xc32f0 cmd = 0xc3334
(dbx) print *client *client = { fd_in = 0 fd_out = 1 io = (nil) input = (nil) output = (nil) namespaces = 0xc2c00 mailbox = (nil) keywords = { pool = (nil) keywords = { buffer = 0xc7580 element_size = 4U } } select_counter = 1U messages_count = 814U recent_count = 0 last_input = 1172553559 last_output = 1172553557 bad_counter = 0 parser = (nil) cmd = { client = 0xc32f0 pool = (nil) tag = (nil) name = (nil) func = (nil) context = (nil) uid = 0 param_error = 0 } disconnected = 1U destroyed = 1U command_pending = 0 input_pending = 0 output_pending = 0 rawlog = 0 input_skip_line = 1U }
(dbx) print *cmd *cmd = { client = 0xc32f0 pool = (nil) tag = (nil) name = (nil) func = (nil) context = (nil) uid = 0 param_error = 0 }
-- Daniel Price - Solaris Kernel Engineering - dp@eng.sun.com - blogs.sun.com/dp
On Mon, 2007-02-26 at 21:38 -0800, Dan Price wrote:
I don't get this. It looks like client_destroy() is called while handling input commands, but I can't find any code path that could do it. I added asserts to make it crash in client_destroy(), so if that happens maybe I can get it fixed:
participants (3)
-
Dan Price
-
Steffen Kaiser
-
Timo Sirainen