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 test1@imap4test.com 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 +0000" 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 +0000" 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 +0000" 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 +0000" 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
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:
- deliver adds "message appended" to index file
- quota plugin runs for a while
- 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:
- Create dovecot-uidlist.lock
- Write uidlist to the dovecot-uidlist.lock
- 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:
- Create dovecot-uidlist.lock
- Write uidlist to dovecot-uidlist.tmp
- rename() .tmp to dovecot-uidlist
- 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..
participants (2)
-
Ron Avriel
-
Timo Sirainen