[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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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/1fd44e0634ac312d0960f39f9518b71e08248...
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@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@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@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@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@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@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@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/1fd44e0634ac312d0960f39f9518b71e08248...
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@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@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@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@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@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@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@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@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/1fd44e0634ac312d0960f39f9518b71e08248...
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@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@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@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@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@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@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@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@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/1fd44e0634ac312d0960f39f9518b71e08248...
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@gol.com Global OnLine Japan/Rakuten Communications
http://www.gol.com/
On 24.04.2017 04:05, Christian Balzer wrote:
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@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@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@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@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@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@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@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/1fd44e0634ac312d0960f39f9518b71e08248...
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
It seems we still have some of these unsquashed, we'll look into this further.
Aki
participants (2)
-
Aki Tuomi
-
Christian Balzer