Re: [Dovecot] Stalled imaptest10 process
On Tue, 2007-03-20 at 12:26 +0100, Steffen Kaiser wrote: - 46. stalled for 1786 secs in APPEND I started getting these also after enabling quota and using 100 clients. I guess the Maildir++ counting just slows it down so much that processes start to hang. With 10 clients there were no hangs. maildir_copy_preserve_filename: yes This setting also doesn't seem to work that great with stress testing, causing the Append with UID x but next_uid is y errors. I'll see if I can get it fixed. I also found some bugs related to saving mails with maildir when quota plugin is enabled. signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Stalled imaptest10 process
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 On Wed, 21 Mar 2007, Timo Sirainen wrote: bug in imaptest.. Do you get the hangs (without the patch) without making imaptest do copying? Not that I noticed them. Because imaptest is working on the same mailbox simultaneously, it hard to simulate. In normal work I found no stalls at all. Info: dvtest: Mailbox is in inconsistent state, please relogin. This indicates an error. But none of these log lines were errors. Try grep Error|tail -20, what does it show? Some internal errors. nothing else (also without the tail). In the server log I have this: In total, during the 2 houres the following errors got logged: 347x Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log: Append with UID 83684, but next_uid = 83685 50x Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log: invalid new transaction log sequence (291 = 291) 2x orrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log: start_offset (500) file size (24) 216x View synchronization from transaction log for index /var/cache/dovecot/31045/index/.box0/dovecot.index failed: Append with UID 116034, but next_uid = 116035 1x broken sync positions in index file /var/cache/dovecot/31045/index/.box1/dovecot.index 1x Fixed index file /var/cache/dovecot/31045/index/.box1/dovecot.index: log file sync pos 185,388 - 186, 24 21x Unexpected transaction log desync with index /var/cache/dovecot/31045/index/.box1/dovecot.index I used: grep Error: dovecot.log to get the errors and tested with sort - -u, that there is no duplicate line. == dovecot: Mar 21 15:37:08 Error: IMAP(dvtest) [10591]: Fixed index file /var/cache/dovecot/31045/index/.Trash/dovecot.index: first_recent_u id_lowwater 121713 - 121271 dovecot: Mar 21 15:37:08 Error: IMAP(dvtest) [10591]: Corrupted index file /var/cache/dovecot/31045/index/.Trash/dovecot.index: Record fie ld keywords points outside record size (12 12+2) dovecot: Mar 21 15:37:08 Error: IMAP(dvtest) [10591]: Corrupted index file /var/cache/dovecot/31045/index/.Trash/dovecot.index: Record fie ld keywords points outside record size (12 12+2) dovecot: Mar 21 15:37:11 Error: IMAP(dvtest) [10558]: Corrupted index file /var/cache/dovecot/31045/index/.Trash/dovecot.index: Record fie ld keywords points outside record size (12 12+2) dovecot: Mar 21 15:37:11 Error: IMAP(dvtest) [10558]: Corrupted index file /var/cache/dovecot/31045/index/.Trash/dovecot.index: Record fie ld keywords points outside record size (12 12+2) dovecot: Mar 21 15:37:12 Error: IMAP(dvtest) [10558]: Corrupted index cache file /var/cache/dovecot/31045/index/.Trash/dovecot.index.cache : indexid changed dovecot: Mar 20 17:53:12 Error: IMAP(dvtest) [1704]: View synchronization from transaction log for index /var/cache/dovecot/31045/index/.b ox0/dovecot.index failed: Append with UID 115022, but next_uid = 115024 dovecot: Mar 20 17:53:43 Error: IMAP(dvtest) [2332]: View synchronization from transaction log for index /var/cache/dovecot/31045/index/.b ox0/dovecot.index failed: Append with UID 115310, but next_uid = 115311 dovecot: Mar 20 17:53:45 Error: IMAP(dvtest) [2379]: Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log : Append with UID 83595, but next_uid = 83596 dovecot: Mar 20 17:53:45 Error: IMAP(dvtest) [2330]: Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log : Append with UID 83595, but next_uid = 83596 dovecot: Mar 20 17:54:00 Error: IMAP(dvtest) [2508]: View synchronization from transaction log for index /var/cache/dovecot/31045/index/.b ox0/dovecot.index failed: Append with UID 115458, but next_uid = 115459 dovecot: Mar 20 17:54:04 Error: IMAP(dvtest) [2736]: Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log : Append with UID 83684, but next_uid = 83685 dovecot: Mar 20 17:54:04 Error: IMAP(dvtest) [2703]: Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log : Append with UID 83684, but next_uid = 83685 dovecot: Mar 20 17:54:05 Error: IMAP(dvtest) [2478]: Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log : Append with UID 83684, but next_uid = 83685 dovecot: Mar 20 17:54:06 Error: IMAP(dvtest) [2595]: Corrupted transaction log file /var/cache/dovecot/31045/index/.box1/dovecot.index.log : Append with UID 83684, but next_uid = 83685 dovecot: Mar 20 17:55:05 Error: IMAP(dvtest) [3724]: View synchronization from transaction log for index /var/cache/dovecot/31045/index/.b ox0/dovecot.index failed: Append with UID 116034, but next_uid = 116035 Bye, - -- Steffen Kaiser -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.6 (GNU/Linux) iQEVAwUBRgI1ti9SORjhbDpvAQKo4gf+M1RjxtUSmpuZnf6X9m9Dp88K8lR46Dhz IwclcC1H31YazpW5yK5oeT448SRzeSdw5NZZDcFVXLnCJRMAMkcT1bAuy7+1NvpX
Re: [Dovecot] Stalled imaptest10 process
On Thu, 2007-03-22 at 08:52 +0100, Steffen Kaiser wrote: In total, during the 2 houres the following errors got logged: 347x Corrupted transaction log file This are probably the real problem causing everything else. /var/cache/dovecot/31045/index/.box1/dovecot.index.log: Append with UID 83684, but next_uid = 83685 .. 216x View synchronization from transaction log for index /var/cache/dovecot/31045/index/.box0/dovecot.index failed: Append with UID 116034, but next_uid = 116035 Are they all like this? box1 is your destination box, which had the real errors, and box0 had only view sync errors? Were you doing anything else to the box1? Like did any IMAP client have the mailbox open, or anything? Or was it just getting thousands of messages put into it? signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Stalled imaptest10 process
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 On Tue, 20 Mar 2007, Timo Sirainen wrote: http://dovecot.org/patches/debug/imap-append-hang-debug.diff The maximum stalled time for all three commands is 23 secs now. That's OK, I think. However, imaptest10 finished after approx. 2 houres. The last log entries of imaptest are plenty of: Error: COPY failed: Some of the requested messages no longer exist. In this time the following info had been logged 88 times: Info: dvtest: Mailbox is in inconsistent state, please relogin. There are no core dumps. The last lines of the dovecot.log file are: dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115951, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115953, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115954, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115959, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: Disconnected: Mailbox is in inconsistent state, please relogin. dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3504]: expunged: uid=115924, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=115986, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=115998, msgid=[EMAIL PROTECTED], box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=116000, msgid=[EMAIL PROTECTED], box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=116004, msgid=[EMAIL PROTECTED], box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3530]: expunged: uid=116008, msgid=[EMAIL PROTECTED], box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3530]: expunged: uid=116018, msgid=[EMAIL PROTECTED], box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3530]: Disconnected dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3504]: expunged: uid=115926, msgid=(null), box=box0 [[snip 40 identical lines]] dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: expunged: uid=115960, msgid=(null), box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: expunged: uid=115961, msgid=(null), box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3504]: Disconnected: Too many invalid IMAP commands. dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: expunged: uid=115981, msgid=(null), box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: Disconnected: Mailbox is in inconsistent state, please relogin. Bye, - -- Steffen Kaiser -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.6 (GNU/Linux) iQEVAwUBRgDsXi9SORjhbDpvAQJKAwf+NqNFsXb0DWkFm7hMV03dlqONpI9cTbqS gNLCooXiyjLM8E74PjrSzKflYjq94cRwkud+vO0Nf9h8uqtJyIjIOXYT3gSoKCo2 ceRsdmoiQXmYwsywx+uWvTNKgy7wnIRd4zpkKE00R3KzAZ4UMl2Cul+oTzrzTENi rN+JX0giDLPQ73hS1pTDAaJ9fkXT3Or0obr8C8NWlquHiaq/02kpCYUnJvJUx8+h DHmZ60aj2D4sbiyxK7dUOlepuLSsmPnAA/Z/DHnGO0TRvaHVbWTN2YmCAFRJrawF DHk8N7IwWDhQYPPQl8LEohmTIyZwKSHZixGWACsqTu5Jsh7ovVYEAQ== =+8ZV -END PGP SIGNATURE-
Re: [Dovecot] Stalled imaptest10 process
On Wed, 2007-03-21 at 09:26 +0100, Steffen Kaiser wrote: -BEGIN PGP SIGNED MESSAGE- Hash: SHA1 On Tue, 20 Mar 2007, Timo Sirainen wrote: http://dovecot.org/patches/debug/imap-append-hang-debug.diff The maximum stalled time for all three commands is 23 secs now. That's OK, I think. Hmm. Wonder if it means that there's a bug in Dovecot. Or that there's a bug in imaptest.. Do you get the hangs (without the patch) without making imaptest do copying? However, imaptest10 finished after approx. 2 houres. The last log entries of imaptest are plenty of: Error: COPY failed: Some of the requested messages no longer exist. Well, that's pretty normal. COPY command fails if any of the requested messages had been expunged already by another session. Info: dvtest: Mailbox is in inconsistent state, please relogin. This indicates an error. dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115951, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115953, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115954, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115959, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: Disconnected: Mailbox is in inconsistent state, please relogin. .. But none of these log lines were errors. Try grep Error|tail -20, what does it show? signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Stalled imaptest10 process
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 On Tue, 20 Mar 2007, Timo Sirainen wrote: Oh, and was imaptest10 also compiled against rc27 sources? Because rc27 fixed this: Yes. I compiled imaptest10 within rc27's source dir. I'll try the patch. Bye, - -- Steffen Kaiser -BEGIN PGP SIGNATURE- Version: GnuPG v1.4.6 (GNU/Linux) iQEVAwUBRf/uAi9SORjhbDpvAQKViQgAzBsUO5wcAFiBL4FmPP27Cx7sxCmPuIQG u8lLhY/oUVgz5ge27yJjGril4b2MGBbppPxWXbNtDVVQPtEnsKGGpUPqCarmZwK6 0mCMPOizmoATqhdbZ1kNsrgbu/eY30Fpz2ramluTGuDlOkEbpxDRHMdMvUAEwKiP UGa6BzdnTC/25yKBgZwbw9gAut5bfOr6OWtFBIp5aKpPTdYHl0I5oEBaZ+osnkfw NNYu32WPgAKUm4Qb0OxUM3YtAJvCrsl/UVGMBAO/H4bz8a0/6OT6RuAERzUo9v63 Xsqbd0MJEvPDzByVACAwDxfCQDybeqMtLJOmp49tuMJYog3YvHAApw== =XEtG -END PGP SIGNATURE-
