[Dovecot] Unexpected behaviour when deleteing a big mailbox

Thu Mar 22 15:22:18 EET 2007

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Wed, 21 Mar 2007, Timo Sirainen wrote:

> On Wed, 2007-03-21 at 16:38 +0100, Steffen Kaiser wrote:
>> I noticed with EXPUNGE that the client feedback is sent after all messages
>> are deleted, when this is the same with COPY, could one sent some feedback
>> to the client in order to keep the connection open?
>
> Does the attached patch help?

Yes!

The connection stays alive the whole time.

I did two tests:

1) I closed Thunderbird after 15min.
The server performed the COPY command. They stayed in box1 and appeared in 
Trash. (Due to the COPY/Mark delete/Expunge sequence got broken).

2) I moved all messages again into Trash, this time waited.

During expunging there is this problem:

dovecot: Mar 22 13:35:20 Info: IMAP(dvtest) [18381]: expunged: uid=83803, 
msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box1
dovecot: Mar 22 13:35:20 Info: IMAP(dvtest) [18381]: expunged: uid=83804, 
msgid=<xxxxxxxx.xxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box1
dovecot: Mar 22 13:35:39 Error: IMAP(dvtest) [18381]: Maildir 
/mnt/mailcache/dvtest/.box1 sync: UID inserted in the middle of mailbox 
(16251 > 6588, file = 1174389173.P6520Q1M362610.ux-2s11-9:2,Fdc)
dovecot: Mar 22 13:35:39 Info: IMAP(dvtest) [18381]: Disconnected: Mailbox 
is in inconsistent state, please relogin.

[[snip log of a login as dvtest]]
dovecot: Mar 22 13:35:39 Error: IMAP(dvtest) [18381]: Maildir 
/mnt/mailcache/dvtest/.box1 sync: UID inserted in the middle of mailbox 
(16251 > 6588, file = 1174389173.P6520Q1M362610.ux-2s11-9:2,Fdc)
dovecot: Mar 22 13:35:40 Error: IMAP(dvtest) [18384]: Corrupted index 
cache file /var/cache/dovecot/31045/index/.box1/dovecot.index.cache: 
indexid changed
- -> These are the only "Error:" lines in the server log.

102 message were still in box1. (Well, of more than 80'000!)

====

Then I disabled log throddling, pointed pine to the Trash folder with
167'606 messages, marked them as deleted and expunged them. And they were 
gone.

====

Then I started up Thunderbird again, in order to check Trash etc. and, 
eventually, deleted the file 102 messages from box1.:

dovecot: Mar 22 14:05:09 Error: IMAP(dvtest) [18444]: Maildir 
/mnt/mailcache/dvtest/.box1 sync: UID < next_uid (16251 < 83805, file = 
1174390126.P30568Q0M945620.ux-2s11-9:2,RSTbde)
dovecot: Mar 22 14:05:09 Info: IMAP(dvtest) [18444]: Disconnected: Mailbox 
is in inconsistent state, please relogin.
dovecot: Mar 22 14:05:09 Error: IMAP(dvtest) [18444]: file client.c: line 
404 (_client_input): assertion failed: (!client->handling_input)
dovecot: Mar 22 14:05:09 Error: IMAP(dvtest) [18444]: Raw backtrace: imap 
[0x80b58e1] -> imap [0x80b57fc] -> imap [0x805bdf7] -> imap [0x8058406] -> 
imap [0x8058669] -> imap [0x805870c] -> imap(cmd_idle+0x144) [0x8058894] 
- -> imap [0x805b628] -> imap [0x805b6b7] -> imap(_client_input+0x6c) 
[0x805bd3c] -> imap(io_loop_handler_run+0x152) [0x80bb8b2] -> 
imap(io_loop_run+0x28) [0x80bab78] -> imap(main+0x4b0) [0x8063d50] -> 
/lib/tls/i686/cmov/libc.so.6(__libc_start_main+0xc8) [0xb7e0eea8] -> imap 
[0x8056871]
dovecot: Mar 22 14:05:09 Error: child 18444 (imap) killed with signal 6

gdb tells:
Core was generated by `imap [dvtest 10.20.10.63]'.
Program terminated with signal 6, Aborted.
#0  0xffffe410 in __kernel_vsyscall ()
(gdb) bt full
#0  0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1  0xb7e22811 in raise () from /lib/tls/i686/cmov/libc.so.6
No symbol table info available.
#2  0xb7e23fb9 in abort () from /lib/tls/i686/cmov/libc.so.6
No symbol table info available.
#3  0x080b58ea in i_internal_panic_handler (fmt=0x80c5a08 "file %s: line 
%d (%s): assertion failed: (%s)",
     args=0xbfbab1f4 "\003\026\r\b\224\001") at failures.c:403
         backtrace = 0x80d6448 "imap [0x80b58e1] -> imap [0x80b57fc] -> 
imap [0x805bdf7] -> imap [0x8058406] -> imap [0x8058669] -> imap 
[0x805870c] -> imap(cmd_idle+0x144) [0x8058894] -> imap [0x805b628] -> 
imap [0x805b6b7] -> imap"...
#4  0x080b57fc in i_panic (format=0x80c5a08 "file %s: line %d (%s): 
assertion failed: (%s)") at failures.c:183
         args = 0xbfbab1f4 "\003\026\r\b\224\001"
#5  0x0805bdf7 in _client_input (context=0x80e10c8) at client.c:404
         client = (struct client *) 0x80e10c8
         cmd = <value optimized out>
         __PRETTY_FUNCTION__ = "_client_input"
#6  0x08058406 in idle_finish (ctx=0x80e4350, done_ok=false) at 
cmd-idle.c:71
         client = (struct client *) 0x80e10c8
#7  0x08058669 in cmd_idle_continue (cmd=0x80e110c) at cmd-idle.c:220
         client = (struct client *) 0x80e10c8
         ctx = (struct cmd_idle_context *) 0x80e4350
#8  0x0805870c in idle_sync_now (box=<value optimized out>, ctx=0x80e4350) 
at cmd-idle.c:157
         __PRETTY_FUNCTION__ = "idle_sync_now"
#9  0x08058894 in cmd_idle (cmd=0x80e110c) at cmd-idle.c:273
         client = (struct client *) 0x80e10c8
         ctx = (struct cmd_idle_context *) 0x80e4350
         interval = <value optimized out>
#10 0x0805b628 in client_handle_input (cmd=0x80e110c) at client.c:335
         client = (struct client *) 0x80e10c8
         __PRETTY_FUNCTION__ = "client_handle_input"
#11 0x0805b6b7 in client_handle_input (cmd=0x80e110c) at client.c:392
         client = (struct client *) 0x80e10c8
         __PRETTY_FUNCTION__ = "client_handle_input"
#12 0x0805bd3c in _client_input (context=0x80e10c8) at client.c:435
         client = (struct client *) 0x80e10c8
         cmd = (struct client_command_context *) 0x80e110c
         __PRETTY_FUNCTION__ = "_client_input"
#13 0x080bb8b2 in io_loop_handler_run (ioloop=0x80de9b0) at 
ioloop-poll.c:199
         ctx = (struct ioloop_handler_context *) 0x80de9d8
         pollfd = <value optimized out>
         tv = {tv_sec = 0, tv_usec = 620373}
         io = (struct io *) 0x81160e8
         t_id = 2
         msecs = <value optimized out>
         ret = 0
         call = <value optimized out>
#14 0x080bab78 in io_loop_run (ioloop=0x80de9b0) at ioloop.c:323
No locals.
#15 0x08063d50 in main (argc=Cannot access memory at address 0x480c
) at main.c:287
         home = 0x0

Bye,

- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iQEVAwUBRgKDDS9SORjhbDpvAQJa3wf+PDXIniMhbRvxXEuKSGiy1mibA0TjVgEs
3VdlcmMaKrDa0yDNUI69y01sODbkfkeLznsu/UBH5p/qroTo5tWOsPz01BJjHHJn
p1tXppkKxT9UdI7FjGTIu2yyc/SLEjHRrM+NRg8vQgPoSIVFbYi3uaDRDO/9WShr
p4Tt1nJ8zyvm+fTL5VzdNLOd4iHjBIvUOLPfIxgyyE10nkwEgcaqwPiU4SOCuk4l
yqVedrDP1xGmH0JyoMkehrGP3w+WITMK6PuwtpeWX+YXE4USjuijewqILHQ1gIuy
z72spc/SQKBrZTaI3PTRGtKhdYeQ37btKlDH9r4oUNcwPjGZ//BYfg==
=dny2
-----END PGP SIGNATURE-----