329204 – UnexpectedResponseReceived: Unhandled ENABLE response ENABLE CONDSTOREQRESYNC

Bug 329204 - UnexpectedResponseReceived: Unhandled ENABLE response ENABLE CONDSTOREQRESYNC

Summary: UnexpectedResponseReceived: Unhandled ENABLE response ENABLE CONDSTOREQRESYNC

Status:	RESOLVED FIXED

Alias:	None

Product:	trojita
Classification:	Unmaintained
Component:	IMAP (show other bugs)
Version:	0.3.96
Platform:	unspecified Linux

Importance:	NOR major
Target Milestone:	---
Assignee:	Trojita default assignee

URL:
Keywords:

Depends on:
Blocks:

Reported:	2013-12-24 15:33 UTC by Martin Sandsmark
Modified:	2015-07-18 09:50 UTC (History)
CC List:	1 user (show)

See Also:
Latest Commit:	http://commits.kde.org/trojita/9b651b3919dcfbfb98c2fc01a04e354f8407b7f6
Version Fixed In:
Sentry Crash Report:

Attachments
Add an attachment

Note You need to log in before you can comment on or make changes to this bug.

Description Martin Sandsmark 2013-12-24 15:33:40 UTC

When entering a specific folder I get this error message: UnexpectedResponseReceived: Unhandled ENABLE response ENABLE CONDSTOREQRESYNC


Reproducible: Always

Comment 1 Martin Sandsmark 2013-12-24 15:37:49 UTC

And I got this when I tried to turn off offline mode, maybe related?: UnexpectedResponseReceived: Unhandled ENABLE response ENABLE CONDSTORE


Debug output from the log pane:
16:34:54.320 *** Looking up imap.mykolab.com...
16:34:54.320 conn Resolving hostname...
16:34:54.347 *** Connecting to imap.mykolab.com:993 (SSL)...
16:34:54.347 conn Connecting to the IMAP server...
16:34:54.414 *** Negotiating encryption...
16:34:54.414 conn Starting encryption (SSL)...
16:34:54.642 *** [Socket is encrypted now; no errors]
16:34:54.642 conn Checking certificates (SSL)...
16:34:54.643 conn Checking capabilities...
16:34:54.729 <<< * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE MUPDATE=mupdate://mupdate.kolabsys.net/ AUTH=LOGIN AUTH=PLAIN SASL-IR] bs109.kolabsys.net Cyrus IMAP Murder v2.4.17-Kolab-2.4.17-1.el6.kolab_3.0 server re
(+ 5 more bytes)
16:34:54.730 conn Logging in...
16:34:54.730 >>> [LOGIN command goes here]
16:34:54.799 <<< y0 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY TH
(+ 289 more bytes)
16:34:54.799 conn Activating compression...
16:34:54.804 >>> y1 COMPRESS DEFLATE␍␊
16:34:54.860 <<< y1 OK DEFLATE active␍␊
16:34:54.860 conn Logged in.
16:34:54.862 Imap::Mailbox::OpenConnectionTask OpenConnectionTask: Logged in. Completed
16:34:54.862 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.862 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:54.862 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox  Activated
16:34:54.863 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN ITK/Unix Activated
16:34:54.864 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING ITK/Unix Synchronizing mailbox
16:34:54.864 Imap::Mailbox::IdTask Activated
16:34:54.868 Imap::Mailbox::EnableTask Activated
16:34:54.868 >>> y2 LIST "" "%" RETURN (SUBSCRIBED CHILDREN)␍␊
16:34:54.868 >>> y3 SELECT "ITK/Unix" (CONDSTORE)␍␊
16:34:54.869 >>> y4 ID ("name" "Trojita" "os" "Qt/4.8.5; X11; Linux; " "version" "v0.3.96")␍␊
16:34:54.869 >>> y5 ENABLE QRESYNC␍␊
16:34:54.962 <<< * LIST (\Noinferiors \Subscribed) "/" "INBOX"␍␊
16:34:54.962 <<< * LIST (\Subscribed \HasNoChildren) "/" "Blog"␍␊
16:34:54.962 <<< * LIST (\Subscribed \HasNoChildren) "/" "Calendar"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Configuration"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Contacts"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Drafts"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Facebook"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Files"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Freebusy"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Github"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Google Plus"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasChildren) "/" "ITK"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Journal"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasChildren) "/" "KDE"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "LWN"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "LinkedIn"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Listadmin"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Notes"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Owncloud"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Qt"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Sent"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Spam"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "TG"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Tasks"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Trash"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Wikia"␍␊
16:34:54.963 <<< * LIST (\Subscribed \HasNoChildren) "/" "Youtube"␍␊
16:34:54.963 <<< y2 OK Completed (0.010 secs)␍␊
16:34:54.965 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox  Completed
16:34:54.966 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.967 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:54.967 Imap::Mailbox::NumberOfMessagesTask attached to INBOX Activated
16:34:54.969 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.970 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.971 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.972 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.973 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.974 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.975 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.976 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.977 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.978 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.979 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.980 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.981 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.982 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.983 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.984 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.986 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.987 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.989 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.991 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.993 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.995 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.997 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:54.998 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:55.000 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:55.001 Imap::Mailbox::GetAnyConnectionTask Activated
16:34:55.004 >>> y6 STATUS INBOX (MESSAGES UNSEEN RECENT)␍␊
16:34:55.005 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.005 Imap::Mailbox::NumberOfMessagesTask attached to Blog Activated
16:34:55.005 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.006 Imap::Mailbox::NumberOfMessagesTask attached to Calendar Activated
16:34:55.006 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.007 Imap::Mailbox::NumberOfMessagesTask attached to Configuration Activated
16:34:55.007 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.008 Imap::Mailbox::NumberOfMessagesTask attached to Contacts Activated
16:34:55.008 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.008 Imap::Mailbox::NumberOfMessagesTask attached to Drafts Activated
16:34:55.008 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.009 Imap::Mailbox::NumberOfMessagesTask attached to Facebook Activated
16:34:55.009 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.010 Imap::Mailbox::NumberOfMessagesTask attached to Files Activated
16:34:55.010 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.010 Imap::Mailbox::NumberOfMessagesTask attached to Freebusy Activated
16:34:55.010 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.011 Imap::Mailbox::NumberOfMessagesTask attached to Github Activated
16:34:55.011 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.012 Imap::Mailbox::NumberOfMessagesTask attached to Google Plus Activated
16:34:55.012 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.012 Imap::Mailbox::NumberOfMessagesTask attached to ITK Activated
16:34:55.012 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.013 Imap::Mailbox::NumberOfMessagesTask attached to Journal Activated
16:34:55.013 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.013 Imap::Mailbox::NumberOfMessagesTask attached to KDE Activated
16:34:55.014 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.014 Imap::Mailbox::NumberOfMessagesTask attached to LinkedIn Activated
16:34:55.014 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.015 Imap::Mailbox::NumberOfMessagesTask attached to Listadmin Activated
16:34:55.015 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.015 Imap::Mailbox::NumberOfMessagesTask attached to LWN Activated
16:34:55.015 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.016 Imap::Mailbox::NumberOfMessagesTask attached to Notes Activated
16:34:55.016 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.016 Imap::Mailbox::NumberOfMessagesTask attached to Owncloud Activated
16:34:55.016 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.017 Imap::Mailbox::NumberOfMessagesTask attached to Qt Activated
16:34:55.017 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.017 Imap::Mailbox::NumberOfMessagesTask attached to Sent Activated
16:34:55.017 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.018 Imap::Mailbox::NumberOfMessagesTask attached to Spam Activated
16:34:55.018 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.018 Imap::Mailbox::NumberOfMessagesTask attached to Tasks Activated
16:34:55.018 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.019 Imap::Mailbox::NumberOfMessagesTask attached to TG Activated
16:34:55.019 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.019 Imap::Mailbox::NumberOfMessagesTask attached to Trash Activated
16:34:55.019 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.020 Imap::Mailbox::NumberOfMessagesTask attached to Wikia Activated
16:34:55.020 Imap::Mailbox::GetAnyConnectionTask Completed
16:34:55.021 Imap::Mailbox::NumberOfMessagesTask attached to Youtube Activated
16:34:55.039 >>> y7 STATUS Blog (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y8 STATUS Calendar (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y9 STATUS Configuration (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y10 STATUS Contacts (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y11 STATUS Drafts (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y12 STATUS Facebook (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y13 STATUS Files (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y14 STATUS Freebusy (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y15 STATUS Github (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y16 STATUS "Google Plus" (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y17 STATUS ITK (MESSAGES UNSEEN RECENT)␍␊
16:34:55.039 >>> y18 STATUS Journal (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y19 STATUS KDE (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y20 STATUS LinkedIn (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y21 STATUS Listadmin (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y22 STATUS LWN (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y23 STATUS Notes (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y24 STATUS Owncloud (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y25 STATUS Qt (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y26 STATUS Sent (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y27 STATUS Spam (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y28 STATUS Tasks (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y29 STATUS TG (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y30 STATUS Trash (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y31 STATUS Wikia (MESSAGES UNSEEN RECENT)␍␊
16:34:55.040 >>> y32 STATUS Youtube (MESSAGES UNSEEN RECENT)␍␊
16:34:55.051 <<< * ENABLED CONDSTORE␍␊
16:34:55.051 <<< * 5744 EXISTS␍␊
16:34:55.051 <<< * 0 RECENT␍␊
16:34:55.051 <<< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)␍␊
16:34:55.051 <<< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Ok␍␊
16:34:55.051 <<< * OK [UNSEEN 5744] Ok␍␊
16:34:55.051 <<< * OK [UIDVALIDITY 1376089534] Ok␍␊
16:34:55.051 <<< * OK [UIDNEXT 5745] Ok␍␊
16:34:55.051 <<< * OK [HIGHESTMODSEQ 5800] Ok␍␊
16:34:55.051 <<< * OK [URLMECH INTERNAL] Ok␍␊
16:34:55.051 <<< y3 OK [READ-WRITE] Completed␍␊
16:34:55.051 <<< * ID ("name" "Cyrus IMAPD" "version" "v2.4.17-Kolab-2.4.17-1.el6.kolab_3.0 d1df8aff 2012-12-01" "vendor" "Project Cyrus" "support-url" "http://www.cyrusimap.org" "os" "Linux" "os-version" "2.6.32-358.
(+ 401 more bytes)
16:34:55.051 <<< y4 OK Completed␍␊
16:34:55.051 <<< * ENABLED QRESYNC␍␊
16:34:55.051 <<< y5 OK Completed␍␊
16:34:55.051 Imap::Mailbox::KeepMailboxOpenTask [invalid mailboxIndex] Failed: Asked to die
16:34:55.051 Imap::Mailbox::ObtainSynchronizedMailboxTask [invalid mailboxIndex] Failed: Asked to die
16:34:55.051 Imap::Mailbox::IdTask Failed: Asked to die
16:34:55.051 Imap::Mailbox::EnableTask Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to INBOX Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Blog Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Calendar Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Configuration Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Contacts Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Drafts Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Facebook Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Files Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Freebusy Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Github Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Google Plus Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to ITK Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Journal Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to KDE Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to LinkedIn Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Listadmin Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to LWN Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Notes Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Owncloud Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Qt Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Sent Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Spam Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Tasks Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to TG Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Trash Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Wikia Failed: Asked to die
16:34:55.052 Imap::Mailbox::NumberOfMessagesTask attached to Youtube Failed: Asked to die
16:34:55.052 *** Connection killed.
16:34:55.052 UnexpectedResponseReceived Unhandled ENABLE response␍␊ENABLE CONDSTORE␊␊

Comment 2 Jan Kundrát 2013-12-24 17:24:19 UTC

Previously, Trojita was too fast and issued the SELECT command for opening a mailbox too early. This was fixed by commit c4d559b06984b301ddab98be2973ff43f0ca58f9, and looking at the code, I think that the current version is correct and will work correctly even in this situation.

Could you please give the git version a try? Please reopen this bug and submit the error log if you can reproduce that with the version from git.

Comment 3 Martin Sandsmark 2013-12-24 22:52:02 UTC

Got this with a build from git: UnexpectedResponseReceived: Unhandled ENABLE response ENABLE CONDSTOREQRESYNC

 
23:50:18.677 ThreadingMsgListModel for INBOX ThreadingMsgListModel::wantThreading: THREAD contains info about UID 34181 (or higher), mailbox has 34181
23:50:21.885 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN INBOX Activated
23:50:21.888 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING INBOX Synchronizing mailbox
23:50:24.211 >>> y32 SELECT INBOX (QRESYNC (1188510423 26029 (6490,9736,11359,12170,12576,12779,12880,12931,12956,12969,12975,12978 16276,22728,31125,32665,33519,33871,34037,34129,34157,34171,34177,34180)))␍␊
23:50:24.701 <<< * ENABLED CONDSTORE QRESYNC␍␊
23:50:24.702 <<< * 14287 EXISTS␍␊
23:50:24.702 <<< * 0 RECENT␍␊
23:50:24.702 <<< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen unknown-2 unknown-0 unknown-1 $REPLIED $ATTACHMENT $SIGNED $FORWARDED)␍␊
23:50:24.702 <<< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen unknown-2 unknown-0 unknown-1 $REPLIED $ATTACHMENT $SIGNED $FORWARDED \*)] Ok␍␊
23:50:24.702 <<< * OK [UNSEEN 42] Ok␍␊
23:50:24.702 <<< * OK [UIDVALIDITY 1376056550] Ok␍␊
23:50:24.702 <<< * OK [UIDNEXT 14953] Ok␍␊
23:50:24.702 <<< * OK [HIGHESTMODSEQ 15757] Ok␍␊
23:50:24.702 <<< * OK [URLMECH INTERNAL] Ok␍␊
23:50:24.702 <<< y32 OK [READ-WRITE] Completed␍␊
23:50:24.703 Imap::Mailbox::KeepMailboxOpenTask attached to Blog Failed: Asked to die
23:50:24.703 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN Blog Failed: Asked to die
23:50:24.703 Imap::Mailbox::KeepMailboxOpenTask attached to INBOX [shouldExit] Failed: Asked to die
23:50:24.703 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING INBOX Failed: Asked to die
23:50:24.703 *** Connection killed.
23:50:24.703 UnexpectedResponseReceived Unhandled ENABLE response␍␊ENABLE CONDSTOREQRESYNC␊␊

Comment 4 Jan Kundrát 2013-12-24 23:57:13 UTC

Martin, please attach the full log from the session, right from the moment you logged in. From this snippet it looks as if the server was sending the ENABLED response repeatedly and while reconnecting, which is rather strange. I would like to have a full trace available to make sure that my interpretation is correct.

Comment 5 Martin Sandsmark 2013-12-25 20:34:04 UTC

 
21:32:41.489 Imap::Mailbox::OpenConnectionTask OpenConnectionTask:  Activated
21:32:41.496 *** Looking up imap.mykolab.com...
21:32:41.496 conn Resolving hostname...
21:32:41.496 *** Connecting to imap.mykolab.com:993 (SSL)...
21:32:41.496 conn Connecting to the IMAP server...
21:32:41.579 *** Negotiating encryption...
21:32:41.579 conn Starting encryption (SSL)...
21:32:41.769 *** [Socket is encrypted now; no errors]
21:32:41.769 conn Checking certificates (SSL)...
21:32:41.770 conn Checking capabilities...
21:32:41.862 <<< * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE MUPDATE=mupdate://mupdate.kolabsys.net/ AUTH=LOGIN AUTH=PLAIN SASL-IR] bs109.kolabsys.net Cyrus IMAP Murder v2.4.17-Kolab-2.4.17-1.el6.kolab_3.0 server re
(+ 5 more bytes)
21:32:41.862 conn Logging in...
21:32:41.863 >>> [LOGIN command goes here]
21:32:41.936 <<< y0 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY TH
(+ 290 more bytes)
21:32:41.936 conn Activating compression...
21:32:41.939 >>> y1 COMPRESS DEFLATE␍␊
21:32:41.986 <<< y1 OK DEFLATE active␍␊
21:32:41.986 conn Logged in.
21:32:41.987 Imap::Mailbox::IdTask Activated
21:32:41.991 Imap::Mailbox::EnableTask Activated
21:32:41.991 Imap::Mailbox::OpenConnectionTask OpenConnectionTask: Logged in. Completed
21:32:41.992 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:41.992 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:41.992 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox  Activated
21:32:41.993 >>> y2 ID ("name" "Trojita" "os" "Qt/4.8.5; X11; Linux; " "version" "v0.3.96-154-gef050ca")␍␊
21:32:41.993 >>> y3 ENABLE QRESYNC␍␊
21:32:41.993 >>> y4 LIST "" "%" RETURN (SUBSCRIBED CHILDREN)␍␊
21:32:42.044 <<< * ID ("name" "Cyrus IMAPD" "version" "v2.4.17-Kolab-2.4.17-1.el6.kolab_3.0 d1df8aff 2012-12-01" "vendor" "Project Cyrus" "support-url" "http://www.cyrusimap.org" "os" "Linux" "os-version" "2.6.32-358.
(+ 401 more bytes)
21:32:42.044 <<< y2 OK Completed␍␊
21:32:42.044 Imap::Mailbox::IdTask Completed
21:32:42.140 <<< * ENABLED CONDSTORE QRESYNC␍␊
21:32:42.140 <<< y3 OK Completed␍␊
21:32:42.140 <<< * LIST (\Noinferiors \Subscribed) "/" "INBOX"␍␊
21:32:42.140 <<< * LIST (\Subscribed \HasNoChildren) "/" "Blog"␍␊
21:32:42.140 <<< * LIST (\Subscribed \HasNoChildren) "/" "Calendar"␍␊
21:32:42.140 <<< * LIST (\Subscribed \HasNoChildren) "/" "Configuration"␍␊
21:32:42.140 <<< * LIST (\Subscribed \HasNoChildren) "/" "Contacts"␍␊
21:32:42.140 <<< * LIST (\Subscribed \HasNoChildren) "/" "Drafts"␍␊
21:32:42.140 <<< * LIST (\Subscribed \HasNoChildren) "/" "Facebook"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Files"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Freebusy"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Github"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Google Plus"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasChildren) "/" "ITK"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Journal"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasChildren) "/" "KDE"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "LWN"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "LinkedIn"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Listadmin"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Notes"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Owncloud"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Qt"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Sent"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Spam"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "TG"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Tasks"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Trash"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Wikia"␍␊
21:32:42.141 <<< * LIST (\Subscribed \HasNoChildren) "/" "Youtube"␍␊
21:32:42.141 <<< y4 OK Completed (0.010 secs)␍␊
21:32:42.141 Imap::Mailbox::EnableTask Completed
21:32:42.145 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox  Completed
21:32:42.147 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:42.149 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:42.149 Imap::Mailbox::NumberOfMessagesTask attached to INBOX Activated
21:32:42.151 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:42.152 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:42.152 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:42.153 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:42.153 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:42.154 Imap::Mailbox::GetAnyConnectionTask Activated
21:32:42.157 >>> y5 STATUS INBOX (MESSAGES UNSEEN RECENT)␍␊
21:32:42.157 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:42.157 Imap::Mailbox::NumberOfMessagesTask attached to Blog Activated
21:32:42.157 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:42.157 Imap::Mailbox::NumberOfMessagesTask attached to Calendar Activated
21:32:42.158 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:42.158 Imap::Mailbox::NumberOfMessagesTask attached to Configuration Activated
21:32:42.158 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:42.158 Imap::Mailbox::NumberOfMessagesTask attached to Contacts Activated
21:32:42.158 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:42.158 Imap::Mailbox::NumberOfMessagesTask attached to Drafts Activated
21:32:42.158 Imap::Mailbox::GetAnyConnectionTask Completed
21:32:42.159 Imap::Mailbox::NumberOfMessagesTask attached to Facebook Activated
21:32:42.160 >>> y6 STATUS Blog (MESSAGES UNSEEN RECENT)␍␊
21:32:42.160 >>> y7 STATUS Calendar (MESSAGES UNSEEN RECENT)␍␊
21:32:42.160 >>> y8 STATUS Configuration (MESSAGES UNSEEN RECENT)␍␊
21:32:42.160 >>> y9 STATUS Contacts (MESSAGES UNSEEN RECENT)␍␊
21:32:42.160 >>> y10 STATUS Drafts (MESSAGES UNSEEN RECENT)␍␊
21:32:42.160 >>> y11 STATUS Facebook (MESSAGES UNSEEN RECENT)␍␊
21:32:42.211 <<< * STATUS INBOX (MESSAGES 14289 RECENT 1 UNSEEN 632)␍␊
21:32:42.211 <<< y5 OK Completed␍␊
21:32:42.211 Imap::Mailbox::NumberOfMessagesTask attached to INBOX Completed
21:32:42.271 <<< * STATUS Blog (MESSAGES 14 RECENT 0 UNSEEN 0)␍␊
21:32:42.271 <<< y6 OK Completed␍␊
21:32:42.272 Imap::Mailbox::NumberOfMessagesTask attached to Blog Completed
21:32:42.361 <<< * STATUS Calendar (MESSAGES 0 RECENT 0 UNSEEN 0)␍␊
21:32:42.361 <<< y7 OK Completed␍␊
21:32:42.361 <<< * STATUS Configuration (MESSAGES 0 RECENT 0 UNSEEN 0)␍␊
21:32:42.361 <<< y8 OK Completed␍␊
21:32:42.361 <<< * STATUS Contacts (MESSAGES 0 RECENT 0 UNSEEN 0)␍␊
21:32:42.361 <<< y9 OK Completed␍␊
21:32:42.361 <<< * STATUS Drafts (MESSAGES 0 RECENT 0 UNSEEN 0)␍␊
21:32:42.361 <<< y10 OK Completed␍␊
21:32:42.361 <<< * STATUS Facebook (MESSAGES 984 RECENT 0 UNSEEN 0)␍␊
21:32:42.361 <<< y11 OK Completed␍␊
21:32:42.362 Imap::Mailbox::NumberOfMessagesTask attached to Calendar Completed
21:32:42.362 Imap::Mailbox::NumberOfMessagesTask attached to Configuration Completed
21:32:42.363 Imap::Mailbox::NumberOfMessagesTask attached to Contacts Completed
21:32:42.363 Imap::Mailbox::NumberOfMessagesTask attached to Drafts Completed
21:32:42.364 Imap::Mailbox::NumberOfMessagesTask attached to Facebook Completed
21:32:45.921 ThreadingMsgListModel for INBOX ThreadingMsgListModel::wantThreading: THREAD contains info about UID 34181 (or higher), mailbox has 34181
21:32:45.959 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN INBOX Activated
21:32:45.960 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING INBOX Synchronizing mailbox
21:32:45.975 >>> y12 SELECT INBOX (QRESYNC (1188510423 26029 (6490,9736,11359,12170,12576,12779,12880,12931,12956,12969,12975,12978 16276,22728,31125,32665,33519,33871,34037,34129,34157,34171,34177,34180)))␍␊
21:32:46.044 <<< * ENABLED CONDSTORE QRESYNC␍␊
21:32:46.044 <<< * 14289 EXISTS␍␊
21:32:46.044 <<< * 1 RECENT␍␊
21:32:46.044 <<< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen unknown-2 unknown-0 unknown-1 $REPLIED $ATTACHMENT $SIGNED $FORWARDED)␍␊
21:32:46.044 <<< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen unknown-2 unknown-0 unknown-1 $REPLIED $ATTACHMENT $SIGNED $FORWARDED \*)] Ok␍␊
21:32:46.044 <<< * OK [UNSEEN 42] Ok␍␊
21:32:46.044 <<< * OK [UIDVALIDITY 1376056550] Ok␍␊
21:32:46.044 <<< * OK [UIDNEXT 14955] Ok␍␊
21:32:46.044 <<< * OK [HIGHESTMODSEQ 15760] Ok␍␊
21:32:46.044 <<< * OK [URLMECH INTERNAL] Ok␍␊
21:32:46.044 <<< y12 OK [READ-WRITE] Completed␍␊
21:32:46.045 Imap::Mailbox::KeepMailboxOpenTask attached to INBOX Failed: Asked to die
21:32:46.045 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING INBOX Failed: Asked to die
21:32:46.045 *** Connection killed.
21:32:46.045 UnexpectedResponseReceived Unhandled ENABLE response␍␊ENABLE CONDSTOREQRESYNC␊␊

Comment 6 Jan Kundrát 2013-12-25 22:05:07 UTC

Thanks. It seems that Kolab is erroneously sending extra untagged ENABLED in context where this is not allowed. Filed upstream bug at [1], review request which fixes this in Trojita at [2].

[1] https://issues.kolab.org/show_bug.cgi?id=2708
[2] https://git.reviewboard.kde.org/r/114666/

Comment 7 Martin Sandsmark 2013-12-25 22:29:09 UTC

Seems to fix it for me.

Thanks!

Comment 8 Jan Kundrát 2013-12-25 22:39:15 UTC

Git commit 9b651b3919dcfbfb98c2fc01a04e354f8407b7f6 by Jan Kundrát.
Committed on 25/12/2013 at 21:46.
Pushed by jkt into branch 'master'.

IMAP: ignore extra ENABLED CONDSTORE QRESYNC responses when syncing a mailbox

Apparently at least some versions of Kolab are happy to send out unsolicited
ENABLED responses during the SELECT processing despite the fact that the QRESYNC
has been already enabled explicitly. This is in violation of my understanding of
RFC 5161. Reported to Kolab at https://issues.kolab.org/show_bug.cgi?id=2708 .

Thanks to Martin Sandsmark <martin.sandsmark@kde.org> for reporting this and
patiently providing logs until I was sure where the problem is. Much
appreciated!
REVIEW: 114666

M  +14   -0    src/Imap/Tasks/ObtainSynchronizedMailboxTask.cpp
M  +1    -0    src/Imap/Tasks/ObtainSynchronizedMailboxTask.h
M  +16   -2    tests/Imap/test_Imap_Tasks_ObtainSynchronizedMailbox.cpp
M  +4    -0    tests/Imap/test_Imap_Tasks_ObtainSynchronizedMailbox.h

http://commits.kde.org/trojita/9b651b3919dcfbfb98c2fc01a04e354f8407b7f6

Comment 9 Jan Kundrát 2015-07-18 09:50:02 UTC

Git commit 8152670c3715769753ceec5ac55a04853b086450 by Jan Kundrát.
Committed on 18/07/2015 at 08:59.
Pushed by gerrit into branch 'master'.

IMAP: Ignore empty ENABLED responses when switching mailboxes

Some versions of Cyrus send out extra ENABLED responses. Trojita already
contains code (see bug 329204) for filtering them out in case they look
relevant to CONDSTORE or QRESYNC, but it turns out that sometimes we get
back an empty ENABLED as well.

There is a couple of options here, either to play the guessing game and
add a kludge to silently eat the empty ENABLED to fix this particular
bug, or to change the code to accept any possible ENABLED response while
switching mailboxes.
Related: bug 350006
Upstream-Bug: https://bugzilla.cyrusimap.org/show_bug.cgi?id=3898
Change-Id: I7ce7e663108d5b64a46580fb4aaa57c4cf379445

M  +11   -1    src/Imap/Tasks/ObtainSynchronizedMailboxTask.cpp
M  +15   -1    tests/Imap/test_Imap_Tasks_ObtainSynchronizedMailbox.cpp
M  +2    -1    tests/Imap/test_Imap_Tasks_ObtainSynchronizedMailbox.h

http://commits.kde.org/trojita/8152670c3715769753ceec5ac55a04853b086450