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

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/

Hello Aki, Timo,

according to git this fix should be in 2.2.27, which I'm running, so I
guess this isn't it or something else is missing.
See:
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=859700

Regards,

Christian

On Thu, 6 Apr 2017 15:37:33 +0900 Christian Balzer wrote:
> 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/

Hello,

On Thu, 6 Apr 2017 20:04:38 +0900 Christian Balzer wrote:
> Hello Aki, Timo,
> 
> according to git this fix should be in 2.2.27, which I'm running, so I
> guess this isn't it or something else is missing.
> See:
> https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=859700
> 
Any update on this?

Christian
> Regards,
> 
> Christian
> 
> On Thu, 6 Apr 2017 15:37:33 +0900 Christian Balzer wrote:
> 
> > 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/