dovecot - Apr 2017 - [BUG] client state / Message count mismatch with imap-hibernate and mixed POP3/IMAP access

Hello,

this is on Debian Jessie box, dovecot 2.2.27 from backports,
imap-hibernate obviously enabled. 

I've been seeing a few of these since starting this cluster (see previous
mail), they all follow the same pattern, a user who accesses their mailbox
with both POP3 and IMAP deletes mails with POP3 and the IMAP
(imap-hibernate really) is getting confused and upset about this:

---

Apr  6 09:55:49 mbx11 dovecot: imap-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.113, mpid=951561,
secured, session=<2jBV+HRM1Pbc9w8u>
Apr  6 10:01:06 mbx11 dovecot: pop3-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.41, mpid=35447,
secured, session=<uZw7C3VM9vfc9w8u>
Apr  6 10:01:07 mbx11 dovecot: pop3(redacted at gol.com): Disconnected: Logged
out top=0/0, retr=0/0, del=1/1, size=20674 session=<uZw7C3VM9vfc9w8u>
Apr  6 10:01:07 mbx11 dovecot: imap(redacted at gol.com): Error: imap-master:
Failed to import client state: Message count mismatch after handling expunges (0
!= 1)
Apr  6 10:01:07 mbx11 dovecot: imap(redacted at gol.com): Client state
initialization failed in=0 out=0 head=<0> del=<0> exp=<0>
trash=<0> session=<2jBV+HRM1Pbc9w8u>
Apr  6 10:01:15 mbx11 dovecot: imap-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.113, mpid=993303,
secured, session=<6QC6C3VMF/jc9w8u>
Apr  6 10:07:42 mbx11 dovecot: imap-hibernate(redacted at gol.com): Connection
closed in=85 out=1066 head=<0> del=<0> exp=<0> trash=<0>
session=<6QC6C3VMF/jc9w8u>

---

Didn't see these errors before introducing imap-hibernate, but then again
this _could_ be something introduced between 2.2.13 (previous generation
of servers) and .27, but I highly doubt it.

My reading of the log is that the original IMAP session
(<2jBV+HRM1Pbc9w8u>) fell over and terminated, resulting in the client to
start up a new session.
If so and with no false data/state transmitted to the client it would be
not ideal, but not a critical problem either. 

Would be delighted if Aki or Timo could comment on this.


If you need any further data, let me know.

Christian
-- 
Christian Balzer        Network/Systems Engineer                
chibi at gol.com   	Global OnLine Japan/Rakuten Communications
http://www.gol.com/

On 06.04.2017 07:02, Christian Balzer wrote:
>
> Hello,
>
> this is on Debian Jessie box, dovecot 2.2.27 from backports,
> imap-hibernate obviously enabled. 
>
> I've been seeing a few of these since starting this cluster (see
previous
> mail), they all follow the same pattern, a user who accesses their mailbox
> with both POP3 and IMAP deletes mails with POP3 and the IMAP
> (imap-hibernate really) is getting confused and upset about this:
>
> ---
>
> Apr  6 09:55:49 mbx11 dovecot: imap-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.113, mpid=951561,
secured, session=<2jBV+HRM1Pbc9w8u>
> Apr  6 10:01:06 mbx11 dovecot: pop3-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.41, mpid=35447,
secured, session=<uZw7C3VM9vfc9w8u>
> Apr  6 10:01:07 mbx11 dovecot: pop3(redacted at gol.com): Disconnected:
Logged out top=0/0, retr=0/0, del=1/1, size=20674
session=<uZw7C3VM9vfc9w8u>
> Apr  6 10:01:07 mbx11 dovecot: imap(redacted at gol.com): Error:
imap-master: Failed to import client state: Message count mismatch after
handling expunges (0 != 1)
> Apr  6 10:01:07 mbx11 dovecot: imap(redacted at gol.com): Client state
initialization failed in=0 out=0 head=<0> del=<0> exp=<0>
trash=<0> session=<2jBV+HRM1Pbc9w8u>
> Apr  6 10:01:15 mbx11 dovecot: imap-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.113, mpid=993303,
secured, session=<6QC6C3VMF/jc9w8u>
> Apr  6 10:07:42 mbx11 dovecot: imap-hibernate(redacted at gol.com):
Connection closed in=85 out=1066 head=<0> del=<0> exp=<0>
trash=<0> session=<6QC6C3VMF/jc9w8u>
>
> ---
>
> Didn't see these errors before introducing imap-hibernate, but then
again
> this _could_ be something introduced between 2.2.13 (previous generation
> of servers) and .27, but I highly doubt it.
>
> My reading of the log is that the original IMAP session
> (<2jBV+HRM1Pbc9w8u>) fell over and terminated, resulting in the
client to
> start up a new session.
> If so and with no false data/state transmitted to the client it would be
> not ideal, but not a critical problem either. 
>
> Would be delighted if Aki or Timo could comment on this.
>
>
> If you need any further data, let me know.
>
> Christian
Hi!

You could try updating to 2.2.28, if possible. I believe this bug is
fixed in 2.2.28, with
https://github.com/dovecot/core/commit/1fd44e0634ac312d0960f39f9518b71e08248b65

Aki

Hello,

On Thu, 6 Apr 2017 09:24:23 +0300 Aki Tuomi wrote:
> On 06.04.2017 07:02, Christian Balzer wrote:
> >
> > Hello,
> >
> > this is on Debian Jessie box, dovecot 2.2.27 from backports,
> > imap-hibernate obviously enabled. 
> >
> > I've been seeing a few of these since starting this cluster (see
previous
> > mail), they all follow the same pattern, a user who accesses their
mailbox
> > with both POP3 and IMAP deletes mails with POP3 and the IMAP
> > (imap-hibernate really) is getting confused and upset about this:
> >
> > ---
> >
> > Apr  6 09:55:49 mbx11 dovecot: imap-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.113, mpid=951561,
secured, session=<2jBV+HRM1Pbc9w8u>
> > Apr  6 10:01:06 mbx11 dovecot: pop3-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.41, mpid=35447,
secured, session=<uZw7C3VM9vfc9w8u>
> > Apr  6 10:01:07 mbx11 dovecot: pop3(redacted at gol.com):
Disconnected: Logged out top=0/0, retr=0/0, del=1/1, size=20674
session=<uZw7C3VM9vfc9w8u>
> > Apr  6 10:01:07 mbx11 dovecot: imap(redacted at gol.com): Error:
imap-master: Failed to import client state: Message count mismatch after
handling expunges (0 != 1)
> > Apr  6 10:01:07 mbx11 dovecot: imap(redacted at gol.com): Client state
initialization failed in=0 out=0 head=<0> del=<0> exp=<0>
trash=<0> session=<2jBV+HRM1Pbc9w8u>
> > Apr  6 10:01:15 mbx11 dovecot: imap-login: Login: user=<redacted at
gol.com>, method=PLAIN, rip=xxx.xxx.x.46, lip=xxx.xxx.x.113, mpid=993303,
secured, session=<6QC6C3VMF/jc9w8u>
> > Apr  6 10:07:42 mbx11 dovecot: imap-hibernate(redacted at gol.com):
Connection closed in=85 out=1066 head=<0> del=<0> exp=<0>
trash=<0> session=<6QC6C3VMF/jc9w8u>
> >
> > ---
> >
> > Didn't see these errors before introducing imap-hibernate, but
then again
> > this _could_ be something introduced between 2.2.13 (previous
generation
> > of servers) and .27, but I highly doubt it.
> >
> > My reading of the log is that the original IMAP session
> > (<2jBV+HRM1Pbc9w8u>) fell over and terminated, resulting in the
client to
> > start up a new session.
> > If so and with no false data/state transmitted to the client it would
be
> > not ideal, but not a critical problem either. 
> >
> > Would be delighted if Aki or Timo could comment on this.
> >
> >
> > If you need any further data, let me know.
> >
> > Christian  
> 
> Hi!
> 
> You could try updating to 2.2.28, if possible. I believe this bug is
> fixed in 2.2.28, with
>
https://github.com/dovecot/core/commit/1fd44e0634ac312d0960f39f9518b71e08248b65
> 
Ah yes, that looks like the culprit indeed.

I shall poke the powers that be over at Debian bugs to expedite the 2.2.28
release and backport.

Christian
-- 
Christian Balzer        Network/Systems Engineer                
chibi at gol.com   	Global OnLine Japan/Rakuten Communications
http://www.gol.com/