dovecot - Mar 2008 - DoveCot IMAP and "inconsistent state" messages

I need some help troubleshooting this problem.  It only shows up with 
IMAP connections.  I initially thought it was related to SquirrelMail 
(because it gives me an 'EXPUNGE' error), but after attempting to send 
IMAP commands directly to the server as shown below, I'm thinking there 
is something else going on.

The system configuration is PostFix as the MTA delivering to procmail in 
the mailbox (maildir format), with Dovecot handling POP3 and IMAP

Postfix is version 2.3.3
Dovecot is version 1.0.rc15
procmail is version 3.22 2001/09/10
kernel is 2.6.18-53.1.14.el5, CentOS 5

There is additional info about the system configuration after the 
command sequence and log entries below.  I've left my typos in, just in 
case they somehow bear on the problem.  I omitted about 2050 messages 
from the mailbox FETCH listing, since they were all identical but for 
the message number, and I didn't figure you'd want to read all of that. 
:)

Command sequence:
[me at myserver~]$ telnet locahost 143
locahost/143: Name or service not known
[me at myserver~]$ telnet localhost 143
Trying 127.0.0.1...
Connected to localhost.localdomain (127.0.0.1).
Escape character is '^]'.
* OK myserver awaiting command
login me mypass
login BAD Error in IMAP command received by server.
a001 login me mypass
a001 OK Logged in.
a002 list "Mail" "*"
a002 OK List completed.
a003 list "Folders" "*"
a003 OK List completed.
a004 list "Inbox"
a004 BAD Error in IMAP command LIST: Invalid arguments.
a005 list "Inbox" "*"
* LIST (\HasNoChildren) "." "INBOX"
a005 OK List completed.
a006 list "" "*"
* LIST (\HasNoChildren) "." "Drafts"
* LIST (\HasNoChildren) "." "Spam"
* LIST (\HasNoChildren) "." "Trash"
* LIST (\HasNoChildren) "." "Sent"
* LIST (\HasNoChildren) "." "INBOX"
a006 OK List completed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] 
Flags permitted.
* 2088 EXISTS
* 1 RECENT
* OK [UNSEEN 2088] First unseen.
* OK [UIDVALIDITY 1190322195] UIDs valid
* OK [UIDNEXT 89700] Predicted next UID
a007 OK [READ-WRITE] Select completed.
a008 FETCH l:* FLAGS
a008 BAD Error in IMAP command FETCH: Invalid messageset
a008 FETCH 1:* FLAGS
* 1 FETCH (FLAGS (\Seen))
* 2 FETCH (FLAGS (\Seen))
* 3 FETCH (FLAGS (\Seen))
* 4 FETCH (FLAGS (\Seen))
* 5 FETCH (FLAGS (\Seen))
* 6 FETCH (FLAGS (\Seen))
.
.
.
* 2083 FETCH (FLAGS (\Seen))
* 2084 FETCH (FLAGS (\Seen))
* 2085 FETCH (FLAGS (\Seen))
* 2086 FETCH (FLAGS (\Seen))
* 2087 FETCH (FLAGS (\Seen))
* 2088 FETCH (FLAGS (\Recent))
* BYE Mailbox is in inconsistent state, please relogin.
Connection closed by foreign host.


These are the corresponding entries from my mail syslog during the same 
time period.  I've included the postfix entries, as they might be 
relevant to the problem.

Mar 31 13:55:14 myserver dovecot: imap-login: Login: user=<me>, 
method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured
Mar 31 13:55:33 myserver dovecot: pop3-login: Login: user=<me>, 
method=PLAIN, rip=xxx.xxx.xxx.xxx, lip=yyy.yyy.yyy.yyy
Mar 31 13:55:35 myserver dovecot: POP3(me): Disconnected: Logged out 
top=0/0, retr=1/18590, del=2/2089, size=10863040
Mar 31 13:56:29 myserver postfix/smtpd[26589]: connect from 
unknown[79.165.160.211]
Mar 31 13:56:30 myserver postfix/smtpd[26589]: 1A57E2F7E6: 
client=unknown[79.165.160.211]
Mar 31 13:56:30 myserver postfix/cleanup[26646]: 1A57E2F7E6: 
message-id=<000901c89360$061afdf8$11e5c1ae at qawbud>
Mar 31 13:56:35 myserver postfix/qmgr[2254]: 1A57E2F7E6: 
from=<amsonson at impsat.com.ar>, size=61232, nrcpt=1 (queue active)
Mar 31 13:56:36 myserver postfix/smtpd[26651]: connect from 
localhost.localdomain [127.0.0.1]
Mar 31 13:56:36 myserver postfix/smtpd[26651]: C98262F893: 
client=localhost.localdomain [127.0.0.1]
Mar 31 13:56:36 myserver postfix/cleanup[26646]: C98262F893: 
message-id=<000901c89360$061afdf8$11e5c1ae at qawbud>
Mar 31 13:56:36 myserver postfix/smtpd[26651]: disconnect from 
localhost.localdomain [127.0.0.1]
Mar 31 13:56:36 myserver amavis[26499]: (26499-03) Passed SPAMMY, 
[79.165.160.211] [79.165.160.211] <amsonson at impsat.com.ar> -> 
<me at digitalvoice.com>, Message-ID: 
<000901c89360$061afdf8$11e5c1ae at qawbud>, mail_id: 47TfQi44++zM, Hits: 
17.608, size: 61232, queued_as: C98262F893, 1372 ms
Mar 31 13:56:36 myserver postfix/smtp[26648]: 1A57E2F7E6: 
to=<me at mydomain.com>, orig_to=<postmaster at digitalvoice.com>, 
relay=127.0.0.1[127.0.0.1]:10024, delay=6.8, delays=5.4/0.01/0.01/1.4, 
dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as C98262F893)Mar 31 
13:56:36 myserver postfix/qmgr[2254]: C98262F893: 
from=<amsonson at impsat.com.ar>, size=62235, nrcpt=1 (queue active)
Mar 31 13:56:36 myserver postfix/qmgr[2254]: 1A57E2F7E6: removed
Mar 31 13:56:36 myserver postfix/local[26653]: C98262F893: 
to=<me at mydomain.com>, relay=local, delay=0.12, delays=0.1/0.01/0/0.01, 
dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)
Mar 31 13:56:36 myserver postfix/qmgr[2254]: C98262F893: removed
Mar 31 13:58:07 myserver dovecot: pop3-login: Login: user=<someone>, 
method=PLAIN, rip=xxx.xxx.xxx.xxx, lip=yyy.yyy.yyy.yyy
Mar 31 13:58:07 myserver dovecot: POP3(someone): Disconnected: Logged 
out top=0/0, retr=0/0, del=0/291, size=11570114
Mar 31 14:00:58 myserver dovecot: IMAP(me): Maildir /home/me/.Maildir 
sync: UID inserted in the middle of mailbox (85953 > 85053, file = 
msg.XL7B:2,)
Mar 31 14:00:58 myserver dovecot: IMAP(me): Disconnected: Mailbox is in 
inconsistent state, please relogin.

output of dovecot -n:
# /etc/dovecot.conf
listen: *
login_dir: /var/run/dovecot/login
login_executable(default): /usr/libexec/dovecot/imap-login
login_executable(imap): /usr/libexec/dovecot/imap-login
login_executable(pop3): /usr/libexec/dovecot/pop3-login
login_greeting: myserver awaiting command
mail_location: maildir:~/.Maildir
mail_executable(default): /usr/libexec/dovecot/imap
mail_executable(imap): /usr/libexec/dovecot/imap
mail_executable(pop3): /usr/libexec/dovecot/pop3
mail_plugin_dir(default): /usr/lib/dovecot/imap
mail_plugin_dir(imap): /usr/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/pop3
auth default:
  mechanisms: plain login
  passdb:
    driver: pam
  userdb:
    driver: passwd
  socket:
    type: listen
    client:
      path: /var/spool/postfix/private/auth
      mode: 432
      user: postfix
      group: postdrop
    master:


So, now I've got two questions:

   1. Is accessing a mailbox via POP3 and IMAP at the same time
      considered to be a Bad Thing?
   2. Is having procmail drop messages directly into the directory that
      the IMAP process is scanning a Bad Thing?
   3. Is there a better/preferred way to have Postfix/procmail deliver
      mail to the maildir that will keep Dovecot IMAP happy? (There
      don't seem to be any issues with pure POP3 access).


Thanks in advance for your help, and if there's anything else you need 
to know that I can provide, please ask.  I've tried to provide as much 
information up front as I can.

Later,
Chris

On 3/31/2008, Chris Richards (gizmo at giz-works.com)
wrote:
> Dovecot is version 1.0.rc15 
Upgrade please - rc15 is very old...

-- 

Best regards,

Charles

On Mon, 2008-03-31 at 15:10 -0500, Chris Richards wrote:
> Dovecot is version 1.0.rc15
I agree with others that it would be a good idea to upgrade from rc15,
but..
> Mar 31 14:00:58 myserver dovecot: IMAP(me): Maildir /home/me/.Maildir 
> sync: UID inserted in the middle of mailbox (85953 > 85053, file = 
> msg.XL7B:2,)
This is a procmail configuration problem:
http://wiki.dovecot.org/MailboxFormat/Maildir#procmail

-------------- 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/20080401/d324d314/attachment-0002.bin>

Timo Sirainen wrote:
> On Mon, 2008-03-31 at 15:10 -0500, Chris Richards wrote:
>   
>> Dovecot is version 1.0.rc15
>>     
>
> I agree with others that it would be a good idea to upgrade from rc15,
> but..
>   
I'm working on this....
>> Mar 31 14:00:58 myserver dovecot: IMAP(me): Maildir /home/me/.Maildir 
>> sync: UID inserted in the middle of mailbox (85953 > 85053, file = 
>> msg.XL7B:2,)
>>     
>
> This is a procmail configuration problem:
> http://wiki.dovecot.org/MailboxFormat/Maildir#procmail
>   
Ok, As I read this, basically you're saying that I need to append the / 
to my delivery dirs?  Or that I need to append the / and only deliver to 
Maildir, instead of Maildir/new?

Here's my .procmailrc
# .procmailrc
# routes incoming mail to appropriate destinations
PATH=/usr/bin:/usr/sbin:/bin:/sbin
MAILDIR=$HOME/.Maildir # all mailboxes live here
DEFAULT=$MAILDIR/new/ # This is where incoming mail goes
LOGFILE=$HOME/.procmail_log
DELIVER="/usr/lib/dovecot/deliver"
SHELL=/bin/sh
:0:
* ^X-Spam-Flag: YESS
* ^X-Spam-Level: \*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*\*
$MAILDIR/.Spam/new/

I changed the .procmailrc to append the / to the dir.  Is that all I 
need to do?

Thanks,
Chris

At 11:20 AM +0300 4/1/08, Timo Sirainen wrote:
>On Mon, 2008-03-31 at 15:10 -0500, Chris Richards wrote:
>>  Dovecot is version 1.0.rc15
>
>I agree with others that it would be a good idea to upgrade from rc15,
>but..
>
>>  Mar 31 14:00:58 myserver dovecot: IMAP(me): Maildir /home/me/.Maildir
>>  sync: UID inserted in the middle of mailbox (85953 > 85053, file
>>  msg.XL7B:2,)
>
>This is a procmail configuration problem:
>http://wiki.dovecot.org/MailboxFormat/Maildir#procmail
That's a surprise. I saw that and considered it, but I interpreted it 
to mean that mh delivery from procmail into a Maildir's 'new' 
subdirectory created a file with the inode *number* in the filename.

I was suspecting the UID lock issue fixed in rc26: 
http://www.dovecot.org/list/dovecot-news/2007-March/000035.html

Which does not explain how Dovecot could reuse a UID, but that just 
seemed weird and wrong in any case...


-- 
Bill Cole
bill at scconsult.com

>> Mar 31 14:00:58 myserver dovecot: IMAP(me): Maildir /home/me/.Maildir 
>> sync: UID inserted in the middle of mailbox (85953 > 85053, file = 
>> msg.XL7B:2,)
>>     
>
> This is a procmail configuration problem:
> http://wiki.dovecot.org/MailboxFormat/Maildir#procmail
Just wanted to say thanks for the help.  You guys have made me a hero.

After reading the PostFix group and this group, and spending about a day 
sorting through a bunch of spam configuration stuff, I've got our mail 
server purring like a kitten.  So I went to see the CTO this afternoon 
and explained the situation with the policy about RPMs.  After him 
commenting that he had noticed a substantial drop in spam, his response 
was basically "You seem to have a clue; do whatever you think is 
appropriate."


Thanks again, guys.

Later,
Chris

> I need some help troubleshooting this problem.  It only shows up with IMAP
> connections.  I initially thought it was related to SquirrelMail (because
> it gives me an 'EXPUNGE' error), but after attempting to send IMAP
commands
> directly to the server as shown below, I'm thinking there is something
else
> going on.
Did you ever figure out this problem? I'm having what appears to be the
exact
same issue with SquirrelMail. Running Dovecot 1.0.14 (Maildir) and 
Squirrelmail 1.4.15, both from and on Debian. Procmail is occasionally 
dropping in mail in the background, which the previous message indicated 
might be related.

Debug log shows:

Jul 21 14:27:41 betty dovecot: IMAP(foobar): Maildir 
/var/vpopmail/domains/foobar.baz/foobar/Maildir sync: UID inserted in the 
middle of mailbox (4412 > 4385, file = 1214817167.16333_0.betty:2,RST)
Jul 21 14:27:41 betty dovecot: IMAP(foobar): Disconnected: Mailbox is in 
inconsistent state, please relogin.

Symptom is us the typically unhelpful expunge error message from SM, or even 
connection dropped on regular fetches, and user is logged out.

Any help would be greatly appreciated, as none of my testing thus far have 
made any difference, and I can't seem to find any hints elsewhere.
Could upgrading to 1.1 help at all? (I'd rather not try unless I know for 
sure)

TIA

-- 
  -==-                  -=-                  -==-
   Christer Mjellem Strand               yitzhaq
   System administrator             ICQ: 9557698
   GSM +47 922 000 12     JID: yitzhaq at jabber.no
  -==-                  -=-                  -==-