thr3ads.net - dovecot - [Dovecot] Wrong message information reported shortly after delivery [Mar 2008]

If this information is useful, please help other people find it:
Share via:

Ron Avriel

2008-Mar-06 16:21 UTC

[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 +0000"
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 +0000"
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 +0000"
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

Timo Sirainen

2008-Mar-06 23:23 UTC

head link

[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.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20080307/bb96cff8/attachment-0002.bin>

Ron Avriel

2008-Mar-07 07:36 UTC

head link

[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

Ron Avriel

2008-Mar-09 16:01 UTC

head link

[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 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-0002.bin>

Ron Avriel

2008-Mar-10 05:59 UTC

head link

[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 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)


Thanks again,
Ron




     
____________________________________________________________________________________
Never miss a thing.  Make Yahoo your home page. 
http://www.yahoo.com/r/hs

Apparently Analagous Threads

Search for more possibly parallel threads

dovecot - Mar 2008 - Wrong message information reported shortly after delivery

[Dovecot] Wrong message information reported shortly after delivery

[Dovecot] Wrong message information reported shortly after delivery

[Dovecot] Wrong message information reported shortly after delivery

[Dovecot] Wrong message information reported shortly after delivery

[Dovecot] Wrong message information reported shortly after delivery

Apparently Analagous Threads