[Dovecot] Wrong message information reported shortly after delivery

[Ron Avriel]

> 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 at 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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: send_fetch_test.tgz
Type: application/x-compressed
Size: 6922 bytes
Desc: not available
Url : http://dovecot.org/pipermail/dovecot/attachments/20080309/051ce608/attachment.bin