Re: [Dovecot] Wrong message information
Timo Sirainen wrote: I think this will finally fix it: http://hg.dovecot.org/dovecot-1.1/rev/5f481022db04 This has finally gotten rid of the problem: no more 1970 in rawlog after three days of logging. Thanks! Anders.
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: On Tue, 2008-06-03 at 17:28 +0200, Anders wrote: I have not been able to reproduce this at will, but do see 1-Jan-1970 in rawlog about two times every day now (with some 80 accounts and probably thousands of deliveries). Could you try with the attached debug patch? What does it log when it happens? Hi Timo, thanks for pursuing this issue. The logfile is quite busy, let me know if I missed something when cutting out the relevant entries (attached). As far as I can tell, there was no other activity on the mailbox when this happend. BTW, the procmail recipe is delivering each message to two folders. I think that this should not make a difference, as each Maildir is separate. Thanks again, Anders. Jun 6 09:17:17 mail postfix/pipe[16884]: AC581107827A: to=[EMAIL PROTECTED], relay=vprocmail, delay=1.2, delays=0.04/0/0/1.1, dsn=2.0.0, status=sent (delivered via vprocmail service) Jun 6 09:17:17 mail postfix/qmgr[31007]: AC581107827A: removed Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): uidlist: uid=18929 not found, refreshed=1, again= Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): do_try: uid=18929 file name not found Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): uidlist: uid=18929 not found, refreshed=1, again= Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): uidlist: uid=18929 not found, refreshed=1, again= Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): do_try: uid=18929 file name not found Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): uidlist: uid=18929 not found, refreshed=1, again= Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): do_try: uid=18929 file name not found Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): received date lookup failed Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): uidlist: uid=18929 not found, refreshed=1, again= Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): do_try: uid=18929 file name not found Jun 6 09:17:17 mail dovecot: IMAP([EMAIL PROTECTED]): do_try: uid=18929 file=1212736637.17889_0.mail.dom.ain not found Jun 6 09:17:17 mail last message repeated 3 times Jun 6 09:17:18 mail dovecot: imap-login: Login: user=[EMAIL PROTECTED], method=PLAIN, rip=130.227.149.6, lip=130.227.149.5, TLS
Re: [Dovecot] Wrong message information
On Fri, 2008-06-06 at 09:45 +0200, Anders wrote: Timo Sirainen wrote: On Tue, 2008-06-03 at 17:28 +0200, Anders wrote: I have not been able to reproduce this at will, but do see 1-Jan-1970 in rawlog about two times every day now (with some 80 accounts and probably thousands of deliveries). Could you try with the attached debug patch? What does it log when it happens? Hi Timo, thanks for pursuing this issue. The logfile is quite busy, let me know if I missed something when cutting out the relevant entries (attached). As far as I can tell, there was no other activity on the mailbox when this happend. BTW, the procmail recipe is delivering each message to two folders. I think that this should not make a difference, as each Maildir is separate. I think this will finally fix it: http://hg.dovecot.org/dovecot-1.1/rev/5f481022db04 Wonder why it never happened in my stress tests. signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
On Tue, 2008-06-03 at 17:28 +0200, Anders wrote:
I have not been able to reproduce this at will, but do see 1-Jan-1970 in
rawlog about two times every day now (with some 80 accounts and probably
thousands of deliveries).
Could you try with the attached debug patch? What does it log when it
happens?
diff -r e043135e971d src/lib-storage/index/maildir/maildir-mail.c
--- a/src/lib-storage/index/maildir/maildir-mail.c Tue Jun 03 16:04:32 2008 +0300
+++ b/src/lib-storage/index/maildir/maildir-mail.c Tue Jun 03 18:54:27 2008 +0300
@@ -116,8 +116,10 @@
if (index_mail_get_received_date(_mail, date_r) == 0)
return 0;
- if (maildir_mail_stat(_mail, st) 0)
+ if (maildir_mail_stat(_mail, st) 0) {
+ i_warning(received date lookup failed);
return -1;
+ }
*date_r = data-received_date = st.st_mtime;
return 0;
diff -r e043135e971d src/lib-storage/index/maildir/maildir-uidlist.c
--- a/src/lib-storage/index/maildir/maildir-uidlist.c Tue Jun 03 16:04:32 2008 +0300
+++ b/src/lib-storage/index/maildir/maildir-uidlist.c Tue Jun 03 18:54:27 2008 +0300
@@ -831,6 +831,7 @@
enum maildir_uidlist_rec_flag *flags_r)
{
const char *fname;
+ bool refresh = FALSE;
fname = maildir_uidlist_lookup_nosync(uidlist, uid, flags_r);
if (fname == NULL) {
@@ -839,6 +840,7 @@
after the last mailbox sync */
if (maildir_uidlist_refresh(uidlist) 0)
return NULL;
+ refresh = TRUE;
} else {
/* the uidlist doesn't exist. */
if (maildir_storage_sync_force(uidlist-mbox, uid) 0)
@@ -847,6 +849,8 @@
/* try again */
fname = maildir_uidlist_lookup_nosync(uidlist, uid, flags_r);
+ i_warning(uidlist: uid=%u not found, refreshed=%d, again=%s,
+ uid, refresh, fname == NULL ? : fname);
}
return fname;
diff -r e043135e971d src/lib-storage/index/maildir/maildir-util.c
--- a/src/lib-storage/index/maildir/maildir-util.c Tue Jun 03 16:04:32 2008 +0300
+++ b/src/lib-storage/index/maildir/maildir-util.c Tue Jun 03 18:54:27 2008 +0300
@@ -24,9 +24,10 @@
int ret;
fname = maildir_uidlist_lookup(mbox-uidlist, uid, flags);
- if (fname == NULL)
+ if (fname == NULL) {
+ i_warning(do_try: uid=%u file name not found, uid);
return -2; /* expunged */
-
+ }
if ((flags MAILDIR_UIDLIST_REC_FLAG_NEW_DIR) != 0) {
/* probably in new/ dir */
T_BEGIN {
@@ -45,6 +46,8 @@
path = t_strconcat(mbox-path, /cur/, fname, NULL);
ret = callback(mbox, path, context);
} T_END;
+ if (ret == 0)
+ i_warning(do_try: uid=%u file=%s not found, uid, fname);
return ret;
}
signature.asc
Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
Anders wrote: Well, I got another report about a 1970 timestamp :-(. Now I have enabled rawlog for all users that are still on Procmail delivery. Will this be useful? Is there something else that I can do? Hi. I now caught this issue once with rawlog. I hope Squirrelmail does not mangle it too badly: In mkl5 IDLE DONE g6uu UID FETCH 18660:* (UID FLAGS RFC822.SIZE BODY.PEEK[HEADER] INTERNALDATE) ppj9 IDLE DONE Out + idling * 15 EXISTS mkl5 OK Idle completed. * 15 FETCH (UID 18660 FLAGS () RFC822.SIZE 0 INTERNALDATE 01-Jan-1970 00:00:00 + BODY[HEADER] NIL) g6uu OK Fetch completed. + idling * OK Still here ppj9 OK Idle completed. Doing the same FETCH by hand now gives the right information. It seems that whenever this problem shows up, two messages are delivered at roughly the same time, and it is the later one that has its information zeroed out. Here is stat(1) output from the message above, and the one that arrived right before it: File: `1212044868.8445_0.mail:2,' Size: 6331Blocks: 16 IO Block: 4096 regular file Device: fd00h/64768dInode: 124977206 Links: 1 Access: (0600/-rw---) Uid: ( 5000/ vmail) Gid: ( 5000/ vmail) Access: 2008-05-29 09:42:59.0 +0200 Modify: 2008-05-29 09:07:48.0 +0200 Change: 2008-05-29 09:22:30.0 +0200 File: `1212044877.8482_0.mail:2,S' Size: 6242Blocks: 16 IO Block: 4096 regular file Device: fd00h/64768dInode: 124977209 Links: 1 Access: (0600/-rw---) Uid: ( 5000/ vmail) Gid: ( 5000/ vmail) Access: 2008-05-29 09:42:59.0 +0200 Modify: 2008-05-29 09:07:57.0 +0200 Change: 2008-05-29 09:23:53.0 +0200 Nine seconds is well above the time spent delivering a message on this server. Cheers, Anders.
Re: [Dovecot] Wrong message information
Anders wrote: Hopefully it is all fixed, then. Well, I got another report about a 1970 timestamp :-(. Now I have enabled rawlog for all users that are still on Procmail delivery. Will this be useful? Is there something else that I can do? Cheers, Anders.
Re: [Dovecot] Wrong message information
On Mon, 2008-05-26 at 00:18 +0200, Anders wrote: Timo Sirainen [EMAIL PROTECTED] writes: I could yesterday also reproduce the broken INTERNALDATE pretty easily, but I can't anymore after that patch.. I can now reproduce one problem quite easily, with: $ A=6 ; ./send_fetch_test.py [EMAIL PROTECTED] pw file sleep $A; ./send_fetch_test.py [EMAIL PROTECTED] pw file The A sleep value is the runtime of the script. If I have the mailbox open and in IDLE, 2 seems to work out. So the trick is to have the second instance expunge the mailbox just as the first instance is about to receive its message. Oh, that's expected behavior then. If you're trying to FETCH a message that has already been expunged and Dovecot doesn't have the necessary information already in its cache file, there are only a few bad choices Dovecot can do: a) lie about the message's contents by using unknown values (this is what you're seeing now) b) Disconnect the client c) Don't return any information and reply NO to the FETCH command. This can cause problems with some clients. If you're using Dovecot's deliver and it already knows that INTERNALDATE and RFC822.SIZE are wanted to be cached (i.e. you didn't delete any dovecot* files between the send_fetch_test.py), deliver should have written those to the cache file and IMAP *usually* would be able to look up the values from there even after the message is expunged. signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: On Mon, 2008-05-26 at 00:18 +0200, Anders wrote: Timo Sirainen [EMAIL PROTECTED] writes: I could yesterday also reproduce the broken INTERNALDATE pretty easily, but I can't anymore after that patch.. I can now reproduce one problem quite easily, with: [...] Oh, that's expected behavior then. If you're trying to FETCH a message that has already been expunged and Dovecot doesn't have the necessary information already in its cache file, there are only a few bad choices Dovecot can do: Thanks for the explanation. That also covers why deliver would fail if I cleared out the Maildir. I had a hunch that this was expected, so I carefully called it a problem rather than an error :-). Hopefully it is all fixed, then. Cheers, Anders.
Re: [Dovecot] Wrong message information
On Sun, 2008-05-25 at 13:02 +0200, Anders wrote: Timo Sirainen wrote: On Fri, 2008-05-23 at 11:12 +0200, Anders wrote: Timo Sirainen wrote: Right, that helped me to reproduce it. Fixed: http://hg.dovecot.org/dovecot-1.1/rev/cb1c6c942768 Hi again. That fixed my testcase as well, but now I just got another report of a mail with an epoch date. It turns out that I can still get in trouble if running the send_fetch_test script concurrently, with eventual output like this: 2008-05-23 10:54:27.123649 Got valid RFC822.SIZE 1104: 1 (UID 1255 FLAGS () INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 1104) Right.. This should help: http://hg.dovecot.org/dovecot-1.1/rev/d920ec986c34 That does not seem to change anything. I have been cherry picking patches since 1.1.rc4, can you think of other recent changes that I need? I am waiting for rc6 for a complete upgrade. Nothing else should be needed. Note that the size is actually correct now, most of the time, so it is not exactly the same issue as initially. I could yesterday also reproduce the broken INTERNALDATE pretty easily, but I can't anymore after that patch.. signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: On Fri, 2008-05-23 at 11:12 +0200, Anders wrote: Timo Sirainen wrote: Right, that helped me to reproduce it. Fixed: http://hg.dovecot.org/dovecot-1.1/rev/cb1c6c942768 Hi again. That fixed my testcase as well, but now I just got another report of a mail with an epoch date. It turns out that I can still get in trouble if running the send_fetch_test script concurrently, with eventual output like this: 2008-05-23 10:54:27.123649 Got valid RFC822.SIZE 1104: 1 (UID 1255 FLAGS () INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 1104) Right.. This should help: http://hg.dovecot.org/dovecot-1.1/rev/d920ec986c34 That does not seem to change anything. I have been cherry picking patches since 1.1.rc4, can you think of other recent changes that I need? I am waiting for rc6 for a complete upgrade. Note that the size is actually correct now, most of the time, so it is not exactly the same issue as initially. Also, I set up the test account wrongly, and then actually had this issue with Dovecot deliver as well. It triggers most easily by removing the Maildir completely, and then running send_fetch_test.py twice at the same time. Regards, Anders.
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: I could yesterday also reproduce the broken INTERNALDATE pretty easily, but I can't anymore after that patch.. So what can I do to help you reproduce it? I am still getting it quite often, though I am unable to create a scenario where it always shows up. Anders.
Re: [Dovecot] Wrong message information
Timo Sirainen [EMAIL PROTECTED] writes: I could yesterday also reproduce the broken INTERNALDATE pretty easily, but I can't anymore after that patch.. I can now reproduce one problem quite easily, with: $ A=6 ; ./send_fetch_test.py [EMAIL PROTECTED] pw file sleep $A; ./send_fetch_test.py [EMAIL PROTECTED] pw file The A sleep value is the runtime of the script. If I have the mailbox open and in IDLE, 2 seems to work out. So the trick is to have the second instance expunge the mailbox just as the first instance is about to receive its message. That gives me output like this (with the two processes mixed): ['./send_fetch_test.py', '[EMAIL PROTECTED]', 'pw', 'file'] 2008-05-26 00:06:13.190925 Sent 30 bytes to [EMAIL PROTECTED] 2008-05-26 00:06:13.191258 No messages in INBOX. Waiting... 2008-05-26 00:06:14.191755 No messages in INBOX. Waiting... 2008-05-26 00:06:15.192545 No messages in INBOX. Waiting... 2008-05-26 00:06:16.193528 No messages in INBOX. Waiting... 2008-05-26 00:06:17.194486 No messages in INBOX. Waiting... 2008-05-26 00:06:18.198344 No messages in INBOX. Waiting... ['./send_fetch_test.py', '[EMAIL PROTECTED]', 'pw', 'file'] 2008-05-26 00:06:19.188813 Sent 30 bytes to [EMAIL PROTECTED] 2008-05-26 00:06:19.189098 No messages in INBOX. Waiting... 2008-05-26 00:06:19.198841 ERROR: Got invalid RFC822.SIZE 0: 1 (UID 1368 FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0) 2008-05-26 00:06:20.189559 No messages in INBOX. Waiting... 2008-05-26 00:06:20.199554 ERROR: Got invalid RFC822.SIZE 0: 1 (UID 1368 FLAGS (\Deleted \Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0) 2008-05-26 00:06:21.190381 No messages in INBOX. Waiting... 2008-05-26 00:06:21.200448 ERROR: Got invalid RFC822.SIZE 0: 1 (UID 1368 FLAGS (\Deleted \Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0) 2008-05-26 00:06:22.191418 No messages in INBOX. Waiting... 2008-05-26 00:06:22.201470 ERROR: Got invalid RFC822.SIZE 0: 1 (UID 1368 FLAGS (\Deleted \Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0) 2008-05-26 00:06:23.192353 No messages in INBOX. Waiting... 2008-05-26 00:06:23.207362 ERROR: Got invalid RFC822.SIZE 0: 1 (UID 1368 FLAGS (\Deleted \Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0) 2008-05-26 00:06:24.193537 No messages in INBOX. Waiting... 2008-05-26 00:06:24.208543 Got valid RFC822.SIZE 1104: 2 (UID 1369 FLAGS (\Recent) INTERNALDATE 26-May-2008 00:06:19 +0200 RFC822.SIZE 1104) 2008-05-26 00:06:25.194555 Got valid RFC822.SIZE 1104: 1 (UID 1369 FLAGS () INTERNALDATE 26-May-2008 00:06:19 +0200 RFC822.SIZE 1104) I can only get this with Procmail delivery, not Dovecot deliver. Anders.
Re: [Dovecot] Wrong message information
On Fri, 2008-05-23 at 11:12 +0200, Anders wrote: Timo Sirainen wrote: Right, that helped me to reproduce it. Fixed: http://hg.dovecot.org/dovecot-1.1/rev/cb1c6c942768 Hi again. That fixed my testcase as well, but now I just got another report of a mail with an epoch date. It turns out that I can still get in trouble if running the send_fetch_test script concurrently, with eventual output like this: 2008-05-23 10:54:27.123649 Got valid RFC822.SIZE 1104: 1 (UID 1255 FLAGS () INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 1104) Right.. This should help: http://hg.dovecot.org/dovecot-1.1/rev/d920ec986c34 signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: Right, that helped me to reproduce it. Fixed: http://hg.dovecot.org/dovecot-1.1/rev/cb1c6c942768 Hi again. That fixed my testcase as well, but now I just got another report of a mail with an epoch date. It turns out that I can still get in trouble if running the send_fetch_test script concurrently, with eventual output like this: 2008-05-23 10:54:27.123649 Got valid RFC822.SIZE 1104: 1 (UID 1255 FLAGS () INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 1104) It does not fail every time, but quite often. I guess it depends on the exact timing of me starting the second instance. It still only fails with procmail delivery, not Dovecot's deliver. Regards, Anders.
Re: [Dovecot] Wrong message information
On Sun, 2008-05-11 at 01:57 +0200, Anders wrote: Timo Sirainen wrote: Does procmail deliver the mails correctly, i.e. first writes to tmp/ directory and then links (or renames) to new/ directory? (You're really using maildir format, not MH format where filenames begin with msg.?) I have confirmed from inotifywait output that the file is correctly created in tmp/ and linked into new/. No MH format. Something that may be helpful has shown up: the problem is only visible when I already have the mailbox open in Thunderbird while running the test script. Probably, you are using a test account that you do not have open? Right, that helped me to reproduce it. Fixed: http://hg.dovecot.org/dovecot-1.1/rev/cb1c6c942768 signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: On Fri, 2008-05-09 at 18:12 +0200, Anders wrote: Timo Sirainen wrote: On May 9, 2008, at 10:42 AM, Asheesh Laroia wrote: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. Seems not ;-) I confirm it not being fixed. Can you reproduce it using the information in http://dovecot.org/list/dovecot/2008-March/029402.html ? Could you also post your dovecot -n output? Yes, this reproduces it. I had to change the delay down from 1s, though: I can't reproduce it myself. Does it still break if you disable all plugins? And I guess you're using Dovecot's deliver to save mails? We have a combination of Dovecot's deliver and some old procmail recipies. I now see that the problem is only present with procmail delivery, *not* when using Dovecot's deliver. Disabling plugins does not seem to change things. I reloaded config with SIGHUP, is that sufficient? I would rather avoid restarting the server completely, but can do it if it is needed. Thanks, Anders.
Re: [Dovecot] Wrong message information
On Sat, 2008-05-10 at 14:24 +0200, Anders wrote: Timo Sirainen wrote: On Fri, 2008-05-09 at 18:12 +0200, Anders wrote: Timo Sirainen wrote: On May 9, 2008, at 10:42 AM, Asheesh Laroia wrote: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. Seems not ;-) I confirm it not being fixed. Can you reproduce it using the information in http://dovecot.org/list/dovecot/2008-March/029402.html ? Could you also post your dovecot -n output? Yes, this reproduces it. I had to change the delay down from 1s, though: I can't reproduce it myself. Does it still break if you disable all plugins? And I guess you're using Dovecot's deliver to save mails? We have a combination of Dovecot's deliver and some old procmail recipies. I now see that the problem is only present with procmail delivery, *not* when using Dovecot's deliver. Does procmail deliver the mails correctly, i.e. first writes to tmp/ directory and then links (or renames) to new/ directory? (You're really using maildir format, not MH format where filenames begin with msg.?) Disabling plugins does not seem to change things. I reloaded config with SIGHUP, is that sufficient? Yes. signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: Does procmail deliver the mails correctly, i.e. first writes to tmp/ directory and then links (or renames) to new/ directory? (You're really using maildir format, not MH format where filenames begin with msg.?) I have confirmed from inotifywait output that the file is correctly created in tmp/ and linked into new/. No MH format. Something that may be helpful has shown up: the problem is only visible when I already have the mailbox open in Thunderbird while running the test script. Probably, you are using a test account that you do not have open? Cheers, Anders.
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: On May 8, 2008, at 6:15 PM, Anders wrote: We have a few users that every so often get empty data in their message overview. From and subject are empty, and the date is 1-Jan-1970. When opening the message in full view, all things are fine. Also, the data in the actual maildir file is fine. It looks a lot like the issue described here: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. Seems not ;-) The server is Linux, ext3, no NFS, and Dovecot 1.1.rc4. Do you use quota? We have quota plugin enabled, but these users have no quota set. The few clients that have had this problem so far have been Outlook Express. I wouldn't be surprised if it was OE's fault. We upgraded from 0.99 recently, and the problem has just appeared now. I guess Dovecot is involved somehow, or at least able to work around OE. No quota plugin before, though. What can be done to debug this? Enable rawlogs for the users experiencing it. Then when they see the problem for a message, check if there's anything in rawlogs that shows wrong replies. http://wiki.dovecot.org/Debugging/Rawlog I will enable that, and probably post the logs when it happens again. Thanks! Cheers, Anders.
Re: [Dovecot] Wrong message information
On Fri, 9 May 2008, Anders wrote: Timo Sirainen wrote: On May 8, 2008, at 6:15 PM, Anders wrote: We have a few users that every so often get empty data in their message overview. From and subject are empty, and the date is 1-Jan-1970. When opening the message in full view, all things are fine. Also, the data in the actual maildir file is fine. It looks a lot like the issue described here: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. Seems not ;-) I confirm it not being fixed. The server is Linux, ext3, no NFS, and Dovecot 1.1.rc4. Do you use quota? I run Linux on amd64, no NFS, ext3, Dovecot built from the nightly .deb repository posted earlier. We have quota plugin enabled, but these users have no quota set. I don't have it enabled. The few clients that have had this problem so far have been Outlook Express. I wouldn't be surprised if it was OE's fault. I'm using alpine and getting the same issue. I would, I guess, suggest adding an assert in the Dovecot that the date isn't epoch start. What can be done to debug this? Enable rawlogs for the users experiencing it. Then when they see the problem for a message, check if there's anything in rawlogs that shows wrong replies. http://wiki.dovecot.org/Debugging/Rawlog I guess I'll do that myself, too. I will enable that, and probably post the logs when it happens again. Thanks! Same here. -- Asheesh. -- Give me enough medals, and I'll win any war. -- Napoleon
Re: [Dovecot] Wrong message information
On May 9, 2008, at 10:42 AM, Asheesh Laroia wrote: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. Seems not ;-) I confirm it not being fixed. Can you reproduce it using the information in http://dovecot.org/list/dovecot/2008-March/029402.html ? Could you also post your dovecot -n output? PGP.sig Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
Timo Sirainen wrote: On May 9, 2008, at 10:42 AM, Asheesh Laroia wrote: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. Seems not ;-) I confirm it not being fixed. Can you reproduce it using the information in http://dovecot.org/list/dovecot/2008-March/029402.html ? Could you also post your dovecot -n output? Yes, this reproduces it. I had to change the delay down from 1s, though: [...] 2008-05-09 18:11:01.101262 No messages in INBOX. Waiting... 2008-05-09 18:11:01.111258 No messages in INBOX. Waiting... 2008-05-09 18:11:01.121290 No messages in INBOX. Waiting... 2008-05-09 18:11:01.131291 No messages in INBOX. Waiting... 2008-05-09 18:11:01.141324 ERROR: Got invalid RFC822.SIZE 0: 1 (UID 1726 FLAGS () INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0) 2008-05-09 18:11:02.141339 ERROR: Got invalid RFC822.SIZE 0: 1 (UID 1726 FLAGS () INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0) 2008-05-09 18:11:03.141281 Got valid RFC822.SIZE 3132: 1 (UID 1726 FLAGS () INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 3132) The dovecot -n is in here: http://dovecot.org/list/dovecot/2008-May/030470.html Thanks, Anders.
Re: [Dovecot] Wrong message information
On Fri, 2008-05-09 at 18:12 +0200, Anders wrote: Timo Sirainen wrote: On May 9, 2008, at 10:42 AM, Asheesh Laroia wrote: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. Seems not ;-) I confirm it not being fixed. Can you reproduce it using the information in http://dovecot.org/list/dovecot/2008-March/029402.html ? Could you also post your dovecot -n output? Yes, this reproduces it. I had to change the delay down from 1s, though: I can't reproduce it myself. Does it still break if you disable all plugins? And I guess you're using Dovecot's deliver to save mails? signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information
On May 8, 2008, at 6:15 PM, Anders wrote: We have a few users that every so often get empty data in their message overview. From and subject are empty, and the date is 1-Jan-1970. When opening the message in full view, all things are fine. Also, the data in the actual maildir file is fine. It looks a lot like the issue described here: http://dovecot.org/list/dovecot/2008-March/029282.html That was fixed in v1.1. The server is Linux, ext3, no NFS, and Dovecot 1.1.rc4. Do you use quota? The few clients that have had this problem so far have been Outlook Express. I wouldn't be surprised if it was OE's fault. What can be done to debug this? Enable rawlogs for the users experiencing it. Then when they see the problem for a message, check if there's anything in rawlogs that shows wrong replies. http://wiki.dovecot.org/Debugging/Rawlog PGP.sig Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information reported shortly after delivery
Can you reproduce it without your IMAP client? For example using imaptest (http://imapwiki.org/ImapTest) as the client and running: Hi, Here's some more information on how to easily reproduce the problem. First, I'd like to describe my environment: OS - RHEL4, FS - ext3, dovecot 1.0.12. See dovecot -n at end of message. Messages are delivered via dovecot deliver invoked by postfix. The problem is reproduced when the system is completely idle - no user is logged in, except the test user. I wrote a short python script (attached) that reproduces the problem very easily. The script sends an email via SMTP, then IMAP fetches from inbox to check when message arrives. Once it arrives it checks if the size is zero and reports it. The script ends when dovecot reports a non-zero message size. The script consistently reproduces the problem on every RHEL4 server I tested (weak and strong) and with any file size. The script is run as ./send_fetch_test.py USER PASSWORD FILE [SERVER] FILE - any file. Contents doesn't matter. NOTE - The script initially deletes all messages from inbox just to minimize output. The problem occurs also when other messages exist. Here's a sample output: 2008-03-09 17:00:41.449833 Sent 1011 bytes to [EMAIL PROTECTED] 2008-03-09 17:00:41.472034 No messages in INBOX. Waiting... 2008-03-09 17:00:42.480654 No messages in INBOX. Waiting... 2008-03-09 17:00:43.487617 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:44.494382 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:45.501444 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:46.550623 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:47.593704 Got valid RFC822.SIZE 1509: 1 (FLAGS (\Recent) INTERNALDATE 09-Mar-2008 17:00:41 +0200 RFC822.SIZE 1509 UID 63) For this output I attached also the IMAP network capture and a strace of the imap process. dovecot -n: # 1.0.12: /usr/local/etc/dovecot.conf log_timestamp: “%Y-%m-%d %H:%M:%S ” protocols: imap listen: *:143 ssl_disable: yes disable_plaintext_auth: no login_dir: /usr/local/var/run/dovecot/login login_executable: /usr/local/libexec/dovecot/imap-login login_process_per_connection: no first_valid_uid: 150 last_valid_uid: 150 dotlock_use_excl: yes fsync_disable: yes maildir_copy_with_hardlinks: yes maildir_copy_preserve_filename: yes mail_plugins: quota imap_quota auth default: mechanisms: plain login user: nobody master_user_separator: * passdb: driver: sql args: /usr/local/etc/dovecot-sql.conf passdb: driver: passwd-file args: /usr/local/etc/dovecot.masterusers master: yes userdb: driver: prefetch userdb: driver: sql args: /usr/local/etc/dovecot-sql.conf socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: postfix group: postfix master: path: /var/run/dovecot/auth-master mode: 432 user: vmail group: mail plugin: quota: maildir:storage=1024 I hope this helps, Thanks, Ron Never miss a thing. Make Yahoo your home page. http://www.yahoo.com/r/hs send_fetch_test.tgz Description: application/compressed
Re: [Dovecot] Wrong message information reported shortly after delivery
On Sun, 2008-03-09 at 09:01 -0700, Ron Avriel wrote: Can you reproduce it without your IMAP client? For example using imaptest (http://imapwiki.org/ImapTest) as the client and running: Hi, Here's some more information on how to easily reproduce the problem. First, I'd like to describe my environment: OS - RHEL4, FS - ext3, dovecot 1.0.12. See dovecot -n at end of message. Messages are delivered via dovecot deliver invoked by postfix. The problem is reproduced when the system is completely idle - no user is logged in, except the test user. Thanks, in my previous tests I didn't use quota plugin with deliver which was needed to notice this. The problem is: 1. deliver adds message appended to index file 2. quota plugin runs for a while 3. deliver updates filename-uid mapping in dovecot-uidlist The problem is when: 1.5. imap sees the new message from index file and wants to fetch its size (or something else). But it doesn't find the filename from dovecot-uidlist, so it assumes the message has been expunged and returns a default value for the fetch, in rfc822.size case it returns 0. The fix would be to write dovecot-uidlist before index file. v1.1 actually does this already and this bug isn't reproducible there. But this isn't that easy to fix in v1.0 without changing code more than I'd like to. With v1.0 uidlist updating goes like: 1. Create dovecot-uidlist.lock 2. Write uidlist to the dovecot-uidlist.lock 3. rename() it to dovecot-uidlist This can't be done before index is updated, because the lock would be lost too early. v1.1 does this: 1. Create dovecot-uidlist.lock 2. Write uidlist to dovecot-uidlist.tmp 3. rename() .tmp to dovecot-uidlist 4. Delete dovecot-uidlist.lock Since you're the first one to notice this problem, I think I'd rather not risk breaking v1.0 with this change.. signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information reported shortly after delivery
Thanks, in my previous tests I didn't use quota plugin with deliver which was needed to notice this. The problem is: 1. deliver adds message appended to index file 2. quota plugin runs for a while 3. deliver updates filename-uid mapping in dovecot-uidlist Thanks for the quick answer. Why does it take four seconds (!) from the time dovecot first reports an invalid message information until the correct information is reported? The time is measured for the delivery of a 1KB message to an empty mailbox on a completely idle system. 2008-03-09 17:00:41.449833 Sent 1011 bytes to [EMAIL PROTECTED] 2008-03-09 17:00:41.472034 No messages in INBOX. Waiting... 2008-03-09 17:00:42.480654 No messages in INBOX. Waiting... 2008-03-09 17:00:43.487617 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:44.494382 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:45.501444 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:46.550623 ERROR: Got invalid RFC822.SIZE 0: 1 (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 63) 2008-03-09 17:00:47.593704 Got valid RFC822.SIZE 1509: 1 (FLAGS (\Recent) INTERNALDATE 09-Mar-2008 17:00:41 +0200 RFC822.SIZE 1509 UID 63) Thanks again, Ron Never miss a thing. Make Yahoo your home page. http://www.yahoo.com/r/hs
Re: [Dovecot] Wrong message information reported shortly after delivery
On Mar 7, 2008, at 9:36 AM, Ron Avriel wrote: On Thu, 2008-03-06 at 08:21 -0800, Ron Avriel wrote: If an IMAP fetch is issued some short time after a message was delivered with dovecot deliver then dovecot reports wrong (zero) values for that new message. Afterward, it reports the information OK. What OS/filesystem do you use? I don't see how this is possible. The mails are first written to tmp/ directory and then they're atomically rename()d to the new/ or cur/ directory. I also tested this myself, rapidly sending the same FETCH command 1000 times/sec while delivering 40MB mails to the maildir. The size was always correct. I'm using standard out of the box Redhat EL 4 with an ext3 filesystem. Since I can reproduce it easily on different RHEL4 machines, tell me what additional information you'd like. Can you reproduce it without your IMAP client? For example using imaptest (http://imapwiki.org/ImapTest) as the client and running: ./imaptest logout=0 - fetch=100 user=testuser pass=testpass host=imap.host.org Or if you can give me access to some server where you can instruct me how to reproduce it, that would work too. PGP.sig Description: This is a digitally signed message part
[Dovecot] Wrong message information reported shortly after delivery
Hi, If an IMAP fetch is issued some short time after a message was delivered with dovecot deliver then dovecot reports wrong (zero) values for that new message. Afterward, it reports the information OK. This causes problems to our IMAP client. The problem is easily reproduced with a large message on a slow machine. I'm using dovecot 1.0.10 Here's a sample trace: 1 uid fetch 1:* fast * 1 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:20:50 +0200 RFC822.SIZE 3378380 UID 1) * 2 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:21:40 +0200 RFC822.SIZE 3378380 UID 2) * 3 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:23:38 +0200 RFC822.SIZE 3378380 UID 3) * 4 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:40:06 +0200 RFC822.SIZE 3378380 UID 4) 1 OK Fetch completed. Here dovecot reports a new message (5) arrived 1 uid fetch 1:* fast * 1 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:20:50 +0200 RFC822.SIZE 3378380 UID 1) * 2 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:21:40 +0200 RFC822.SIZE 3378380 UID 2) * 3 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:23:38 +0200 RFC822.SIZE 3378380 UID 3) * 4 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:40:06 +0200 RFC822.SIZE 3378380 UID 4) * 5 EXISTS * 5 RECENT 1 OK Fetch completed. This is where dovecot reports wrong information about message 5 1 uid fetch 1:* fast * 1 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:20:50 +0200 RFC822.SIZE 3378380 UID 1) * 2 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:21:40 +0200 RFC822.SIZE 3378380 UID 2) * 3 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:23:38 +0200 RFC822.SIZE 3378380 UID 3) * 4 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:40:06 +0200 RFC822.SIZE 3378380 UID 4) * 5 FETCH (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 5) 1 OK Fetch completed. The same wrong information is repeated 1 uid fetch 1:* fast * 1 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:20:50 +0200 RFC822.SIZE 3378380 UID 1) * 2 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:21:40 +0200 RFC822.SIZE 3378380 UID 2) * 3 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:23:38 +0200 RFC822.SIZE 3378380 UID 3) * 4 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:40:06 +0200 RFC822.SIZE 3378380 UID 4) * 5 FETCH (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 5) 1 OK Fetch completed. The same wrong information is repeated several times 1 uid fetch 1:* fast * 1 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:20:50 +0200 RFC822.SIZE 3378380 UID 1) * 2 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:21:40 +0200 RFC822.SIZE 3378380 UID 2) * 3 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:23:38 +0200 RFC822.SIZE 3378380 UID 3) * 4 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:40:06 +0200 RFC822.SIZE 3378380 UID 4) * 5 FETCH (FLAGS (\Recent) INTERNALDATE 01-Jan-1970 00:00:00 + RFC822.SIZE 0 UID 5) 1 OK Fetch completed. Trace truncated here Finally, correct information is reported 1 uid fetch 1:* fast * 1 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:20:50 +0200 RFC822.SIZE 3378380 UID 1) * 2 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:21:40 +0200 RFC822.SIZE 3378380 UID 2) * 3 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:23:38 +0200 RFC822.SIZE 3378380 UID 3) * 4 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:40:06 +0200 RFC822.SIZE 3378380 UID 4) * 5 FETCH (FLAGS (\Recent) INTERNALDATE 06-Mar-2008 17:41:07 +0200 RFC822.SIZE 3378380 UID 5) dovecot -n: # 1.0.10: /etc/dovecot.conf log_timestamp: “%Y-%m-%d %H:%M:%S ” protocols: imap listen: *:143 ssl_disable: yes login_dir: /var/run/dovecot/login login_executable: /usr/libexec/dovecot/imap-login login_process_per_connection: no first_valid_uid: 150 last_valid_uid: 150 dotlock_use_excl: yes fsync_disable: yes maildir_copy_with_hardlinks: yes maildir_copy_preserve_filename: yes mail_plugins: quota imap_quota auth default: mechanisms: plain login user: nobody master_user_separator: * passdb: driver: sql args: /etc/dovecot-sql.conf passdb: driver: passwd-file args: /etc/dovecot.masterusers master: yes userdb: driver: prefetch userdb: driver: sql args: /etc/dovecot-sql.conf socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: postfix group: postfix master: path: /var/run/dovecot/auth-master mode: 432 user: vmail group: mail plugin: quota: maildir:storage=1024 Thanks, Ron Never miss a thing. Make Yahoo your home page. http://www.yahoo.com/r/hs
Re: [Dovecot] Wrong message information reported shortly after delivery
On Thu, 2008-03-06 at 08:21 -0800, Ron Avriel wrote: If an IMAP fetch is issued some short time after a message was delivered with dovecot deliver then dovecot reports wrong (zero) values for that new message. Afterward, it reports the information OK. What OS/filesystem do you use? I don't see how this is possible. The mails are first written to tmp/ directory and then they're atomically rename()d to the new/ or cur/ directory. I also tested this myself, rapidly sending the same FETCH command 1000 times/sec while delivering 40MB mails to the maildir. The size was always correct. signature.asc Description: This is a digitally signed message part
Re: [Dovecot] Wrong message information reported shortly after delivery
On Thu, 2008-03-06 at 08:21 -0800, Ron Avriel wrote: If an IMAP fetch is issued some short time after a message was delivered with dovecot deliver then dovecot reports wrong (zero) values for that new message. Afterward, it reports the information OK. What OS/filesystem do you use? I don't see how this is possible. The mails are first written to tmp/ directory and then they're atomically rename()d to the new/ or cur/ directory. I also tested this myself, rapidly sending the same FETCH command 1000 times/sec while delivering 40MB mails to the maildir. The size was always correct. I'm using standard out of the box Redhat EL 4 with an ext3 filesystem. Since I can reproduce it easily on different RHEL4 machines, tell me what additional information you'd like. Thanks again, Ron Never miss a thing. Make Yahoo your home page. http://www.yahoo.com/r/hs
