Bug 350006 - UnexpectedResponseReceived Unhandled ENABLED response␍␊ENABLE ␊␊
Summary: UnexpectedResponseReceived Unhandled ENABLED response␍␊ENABLE ␊␊
Status: RESOLVED FIXED
Alias: None
Product: trojita
Classification: Applications
Component: IMAP (show other bugs)
Version: git
Platform: Other Linux
: NOR normal
Target Milestone: ---
Assignee: Trojita default assignee
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-07-07 17:16 UTC by Dennis Schridde
Modified: 2015-07-28 08:28 UTC (History)
0 users

See Also:
Latest Commit:
Version Fixed In:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Dennis Schridde 2015-07-07 17:16:38 UTC
Whenever I open any IMAP folder in Trojita, it aborts the connection and says: UnexpectedResponseReceived Unhandled ENABLED response␍␊ENABLE ␊␊

Connection logs:
```
19:10:39.964 Imap::Mailbox::OpenConnectionTask OpenConnectionTask:  Activated
19:10:39.970 *** Looking up popix.urz.uni-heidelberg.de...
19:10:39.970 conn Resolving hostname...
19:10:39.971 *** Connecting to popix.urz.uni-heidelberg.de:143...
19:10:39.971 conn Connecting to the IMAP server...
19:10:39.972 *** Connection established
19:10:39.972 *** Connected
19:10:39.972 conn Checking capabilities...
19:10:39.974 <<< * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE MUPDATE=mupdate://cyrus-portal/ STARTTLS AUTH=PLAIN AUTH=LOGIN SASL-IR] cyrus-portal01 Cyrus IMAP Murder v2.4.17-Fedora-RPM-2.4.17-8.el7_1 server ready␍␊
19:10:39.974 conn Asking for encryption...
19:10:39.974 >>> y0 STARTTLS␍␊
19:10:39.978 *** STARTTLS
19:10:39.978 <<< y0 OK Begin TLS negotiation now␍␊
19:10:39.978 conn Starting encryption (STARTTLS)...
19:10:39.986 *** [Socket is encrypted now; no errors]
19:10:39.986 conn Checking certificates (STARTTLS)...
19:10:39.986 conn Checking capabilities (after STARTTLS)...
19:10:39.986 >>> y1 CAPABILITY␍␊
19:10:39.988 <<< * 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 THREAD=
(+ 205 more bytes)
19:10:39.988 <<< y1 OK Completed␍␊
19:10:39.988 conn Logging in...
19:10:39.989 >>> [LOGIN command goes here]
19:10:40.043 <<< y2 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
(+ 278 more bytes)
19:10:40.043 conn Activating compression...
19:10:40.043 >>> y3 COMPRESS DEFLATE␍␊
19:10:40.043 <<< y3 OK DEFLATE active␍␊
19:10:40.044 conn Logged in.
19:10:40.044 Imap::Mailbox::IdTask Activated
19:10:40.044 Imap::Mailbox::EnableTask Activated
19:10:40.044 Imap::Mailbox::OpenConnectionTask OpenConnectionTask: Logged in. Completed
19:10:40.044 Imap::Mailbox::GetAnyConnectionTask Activated
19:10:40.045 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:40.045 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox  Activated
19:10:40.045 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:40.045 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox cron Activated
19:10:40.045 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:40.045 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox SyncShare Activated
19:10:40.045 >>> y4 ID ("name" "Trojita" "os" "Qt/4.8.6; X11; Linux; Ubuntu 14.04.2 LTS" "version" "0.5")␍␊
19:10:40.045 >>> y5 ENABLE QRESYNC␍␊
19:10:40.045 >>> y6 LIST "" "%" RETURN (SUBSCRIBED CHILDREN)␍␊
19:10:40.045 >>> y7 LIST "" "cron/%" RETURN (SUBSCRIBED CHILDREN)␍␊
19:10:40.045 >>> y8 LIST "" "SyncShare/%" RETURN (SUBSCRIBED CHILDREN)␍␊
19:10:40.048 <<< * ID ("name" "Cyrus IMAPD" "version" "v2.4.17-Fedora-RPM-2.4.17-8.el7_1 d1df8aff 2012-12-01" "vendor" "Project Cyrus" "support-url" "http://www.cyrusimap.org" "os" "Linux" "os-version" "3.10.0-229.4.2
(+ 402 more bytes)
19:10:40.048 <<< y4 OK Completed␍␊
19:10:40.048 Imap::Mailbox::IdTask Completed
19:10:40.091 <<< * ENABLED CONDSTORE QRESYNC␍␊
19:10:40.092 <<< y5 OK Completed␍␊
19:10:40.092 <<< * LIST (\Noinferiors \Subscribed) "/" "INBOX"␍␊
19:10:40.092 <<< * LIST (\Subscribed \HasNoChildren) "/" "Drafts"␍␊
19:10:40.092 <<< * LIST (\Subscribed \HasNoChildren) "/" "Sent"␍␊
19:10:40.092 <<< * LIST (\Subscribed \HasNoChildren) "/" "Trash"␍␊
19:10:40.092 <<< * LIST (\Subscribed \HasNoChildren) "/" "BBB"␍␊
19:10:40.092 <<< * LIST (\Subscribed \HasChildren) "/" "AAA"␍␊
19:10:40.092 <<< y6 OK Completed (0.000 secs)␍␊
19:10:40.092 <<< y7 OK Completed (0.000 secs)␍␊
19:10:40.092 <<< y8 OK Completed (0.000 secs)␍␊
19:10:40.092 Imap::Mailbox::EnableTask Completed
19:10:40.092 Imap::Mailbox::ListChildMailboxesTask Listing stuff below mailbox  Completed
19:10:40.093 Imap::Mailbox::ListChildMailboxesTask [invalid mailboxIndex] Failed: Mailbox no longer available -- weird timing?
19:10:40.093 Imap::Mailbox::ListChildMailboxesTask [invalid mailboxIndex] Failed: Mailbox no longer available -- weird timing?
19:10:41.670 Imap::Mailbox::GetAnyConnectionTask Activated
19:10:41.670 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:41.670 Imap::Mailbox::NumberOfMessagesTask attached to INBOX Activated
19:10:41.692 Imap::Mailbox::GetAnyConnectionTask Activated
19:10:41.692 Imap::Mailbox::GetAnyConnectionTask Activated
19:10:41.693 Imap::Mailbox::GetAnyConnectionTask Activated
19:10:41.693 Imap::Mailbox::GetAnyConnectionTask Activated
19:10:41.694 Imap::Mailbox::GetAnyConnectionTask Activated
19:10:41.714 >>> y9 STATUS INBOX (MESSAGES UNSEEN RECENT)␍␊
19:10:41.715 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:41.715 Imap::Mailbox::NumberOfMessagesTask attached to BBB Activated
19:10:41.715 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:41.716 Imap::Mailbox::NumberOfMessagesTask attached to AAA Activated
19:10:41.716 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:41.716 Imap::Mailbox::NumberOfMessagesTask attached to Drafts Activated
19:10:41.716 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:41.716 Imap::Mailbox::NumberOfMessagesTask attached to Sent Activated
19:10:41.716 Imap::Mailbox::GetAnyConnectionTask Completed
19:10:41.716 Imap::Mailbox::NumberOfMessagesTask attached to Trash Activated
19:10:41.717 >>> y10 STATUS BBB (MESSAGES UNSEEN RECENT)␍␊
19:10:41.717 >>> y11 STATUS AAA (MESSAGES UNSEEN RECENT)␍␊
19:10:41.717 >>> y12 STATUS Drafts (MESSAGES UNSEEN RECENT)␍␊
19:10:41.717 >>> y13 STATUS Sent (MESSAGES UNSEEN RECENT)␍␊
19:10:41.717 >>> y14 STATUS Trash (MESSAGES UNSEEN RECENT)␍␊
19:10:41.719 <<< * STATUS INBOX (MESSAGES 683 RECENT 0 UNSEEN 0)␍␊
19:10:41.719 <<< y9 OK Completed␍␊
19:10:41.720 Imap::Mailbox::NumberOfMessagesTask attached to INBOX Completed
19:10:41.720 <<< * STATUS BBB (MESSAGES 6 RECENT 0 UNSEEN 0)␍␊
19:10:41.721 <<< y10 OK Completed␍␊
19:10:41.721 Imap::Mailbox::NumberOfMessagesTask attached to BBB Completed
19:10:41.756 <<< * STATUS AAA (MESSAGES 41 RECENT 0 UNSEEN 0)␍␊
19:10:41.756 <<< y11 OK Completed␍␊
19:10:41.756 <<< * STATUS Drafts (MESSAGES 2 RECENT 0 UNSEEN 1)␍␊
19:10:41.756 <<< y12 OK Completed␍␊
19:10:41.756 <<< * STATUS Sent (MESSAGES 441 RECENT 0 UNSEEN 0)␍␊
19:10:41.756 <<< y13 OK Completed␍␊
19:10:41.756 <<< * STATUS Trash (MESSAGES 18 RECENT 0 UNSEEN 0)␍␊
19:10:41.756 <<< y14 OK Completed␍␊
19:10:41.756 Imap::Mailbox::NumberOfMessagesTask attached to AAA Completed
19:10:41.757 Imap::Mailbox::NumberOfMessagesTask attached to Drafts Completed
19:10:41.757 Imap::Mailbox::NumberOfMessagesTask attached to Sent Completed
19:10:41.757 Imap::Mailbox::NumberOfMessagesTask attached to Trash Completed
19:10:44.245 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN BBB Activated
19:10:44.246 conn Opening mailbox...
19:10:44.247 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING BBB Synchronizing mailbox
19:10:44.247 >>> y15 SELECT BBB (CONDSTORE)␍␊
19:10:44.251 <<< * ENABLED CONDSTORE QRESYNC␍␊
19:10:44.251 <<< * 6 EXISTS␍␊
19:10:44.251 <<< * 0 RECENT␍␊
19:10:44.251 <<< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)␍␊
19:10:44.251 <<< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Ok␍␊
19:10:44.251 <<< * OK [UIDVALIDITY 1415390491] Ok␍␊
19:10:44.251 <<< * OK [UIDNEXT 7] Ok␍␊
19:10:44.251 <<< * OK [HIGHESTMODSEQ 10] Ok␍␊
19:10:44.251 <<< * OK [URLMECH INTERNAL] Ok␍␊
19:10:44.251 <<< y15 OK [READ-WRITE] Completed␍␊
19:10:44.251  Warning: unhandled untagged OK with a response code
19:10:44.251 conn Synchronising mailbox...
19:10:44.252 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING BBB Full synchronization
19:10:44.252 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SYNCING_UIDS BBB Syncing UIDs
19:10:44.252 >>> y16 UID SEARCH RETURN (ALL) ALL␍␊
19:10:44.256 <<< * ESEARCH (TAG "y16") UID ALL 1:6␍␊
19:10:44.256 <<< y16 OK Completed (6 msgs in 0.000 secs)␍␊
19:10:44.257 conn Mailbox opened.
19:10:44.259 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SYNCING_FLAGS BBB UIDs synchronized
19:10:44.259 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SYNCING_FLAGS BBB Syncing flags
19:10:44.259 >>> y17 FETCH 1:6 (FLAGS)␍␊
19:10:44.270 <<< * 1 FETCH (FLAGS (\Seen))␍␊
19:10:44.270 <<< * 2 FETCH (FLAGS (\Seen))␍␊
19:10:44.270 <<< * 3 FETCH (FLAGS (\Seen))␍␊
19:10:44.270 <<< * 4 FETCH (FLAGS (\Seen))␍␊
19:10:44.270 <<< * 5 FETCH (FLAGS (\Seen))␍␊
19:10:44.270 <<< * 6 FETCH (FLAGS (\Seen))␍␊
19:10:44.270 <<< y17 OK Completed (0.000 sec)␍␊
19:10:44.270 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_DONE BBB Flags synchronized
19:10:44.271 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_DONE BBB "First interesting message" doesn't look terribly interesting (\Seen), scrolling to the end at 5 instead
19:10:44.271 conn Mailbox opened.
19:10:44.274 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_DONE BBB Completed
19:10:44.274 Imap::Mailbox::KeepMailboxOpenTask attached to BBB Activated
19:10:44.274 Imap::Mailbox::FetchMsgMetadataTask BBB: UIDs 1:6 Activated
19:10:44.274 >>> y18 UID FETCH 1:6 (ENVELOPE INTERNALDATE BODYSTRUCTURE RFC822.SIZE BODY.PEEK[HEADER.FIELDS (References List-Post)])␍␊
19:10:44.277 <<< * 1 FETCH (UID 1 INTERNALDATE " 7-Nov-2014 12:00:03 +0100" RFC822.SIZE 4661 ENVELOPE ("Fri, 7 Nov 2014 11:59:40 +0100" XXX
(+ 448 more bytes)
19:10:44.277 <<< * 2 FETCH (UID 2 INTERNALDATE " 3-Nov-2014 15:38:58 +0100" RFC822.SIZE 4675 ENVELOPE ("Mon, 3 Nov 2014 15:38:43 +0100" XXX
(+ 438 more bytes)
19:10:44.277 <<< * 3 FETCH (UID 3 INTERNALDATE " 3-Nov-2014 15:38:57 +0100" RFC822.SIZE 7997 ENVELOPE ("Mon, 3 Nov 2014 15:38:43 +0100" XXX
(+ 464 more bytes)
19:10:44.277 <<< * 4 FETCH (UID 4 INTERNALDATE " 3-Nov-2014 15:42:37 +0100" RFC822.SIZE 2192 ENVELOPE ("Mon, 03 Nov 2014 15:42:13 +0100" XXX
(+ 543 more bytes)
19:10:44.278 <<< * 5 FETCH (UID 5 INTERNALDATE " 3-Nov-2014 14:31:50 +0100" RFC822.SIZE 2322 ENVELOPE ("Mon, 03 Nov 2014 14:30:41 +0100" XXX
(+ 667 more bytes)
19:10:44.316 <<< * 6 FETCH (UID 6 INTERNALDATE "24-Feb-2015 10:18:24 +0100" RFC822.SIZE 4731 ENVELOPE ("Tue, 24 Feb 2015 10:18:15 +0100" XXX
(+ 447 more bytes)
19:10:44.316 <<< y18 OK Completed (0.000 sec)␍␊
19:10:44.316 Imap::Mailbox::FetchMsgMetadataTask BBB: UIDs 1:6 Completed
19:10:45.938 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_WAIT_FOR_CONN AAA Activated
19:10:45.938 conn Waiting for another mailbox...
19:10:45.952 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING AAA Synchronizing mailbox
19:10:45.964 >>> y19 SELECT AAA (QRESYNC (1415390286 96 (21,32,38,41 21,32,38,41)))␍␊
19:10:45.976 <<< * ENABLED␍␊
19:10:45.976 <<< * OK [CLOSED] Ok␍␊
19:10:45.976 <<< * 41 EXISTS␍␊
19:10:45.976 <<< * 0 RECENT␍␊
19:10:45.976 <<< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $FORWARDED)␍␊
19:10:45.976 <<< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $FORWARDED \*)] Ok␍␊
19:10:45.976 <<< * OK [UIDVALIDITY 1415390286] Ok␍␊
19:10:45.976 <<< * OK [UIDNEXT 42] Ok␍␊
19:10:45.976 <<< * OK [HIGHESTMODSEQ 96] Ok␍␊
19:10:45.976 <<< * OK [URLMECH INTERNAL] Ok␍␊
19:10:45.976 <<< y19 OK [READ-WRITE] Completed␍␊
19:10:45.976 Imap::Mailbox::KeepMailboxOpenTask attached to AAA Failed: The connection is being killed for unspecified reason
19:10:45.976 Imap::Mailbox::ObtainSynchronizedMailboxTask STATE_SELECTING AAA Failed: The connection is being killed for unspecified reason
19:10:45.976 *** Connection killed.
19:10:45.976 UnexpectedResponseReceived Unhandled ENABLED response␍␊ENABLE ␊␊
```

System is Ubuntu 14.04 with KDE backports (4:4.14.2-0ubuntu1~ubuntu14.04~ppa1) and Trojita 0.5 from the OpenSuse build service. Version 0.5.git.1434288468.99a6faf is also affected.

Reproducible: Always
Comment 1 Dennis Schridde 2015-07-07 17:21:51 UTC
Actually it does not happen when open "any" folder. It happens when I open one folder and afterwards open another.
Comment 2 Thomas Lübking 2015-07-07 19:02:18 UTC
Looks like a server error - the response is "ENABLE ␊␊" (notice the double LF)

https://tools.ietf.org/html/rfc3501#section-2.2
----------------------------------------------------------
2.2.    Commands and Responses

   [...]

   All interactions transmitted by client and server are in the form of
   lines, that is, strings that end with a CRLF.  The protocol receiver
   of an IMAP4rev1 client or server is either reading a line, or is
   reading a sequence of octets with a known count followed by a line.

----------------------------------------------------------

Since there's a small chance trojita or the network stack screw bytes locally, can you reproduce this with another mail server (eventually even not with another cyrus server, could be a broken config or something)?
Comment 3 Dennis Schridde 2015-07-09 17:26:00 UTC
So the server always writes a double LF instead of CRLF? And you are sure that ENABLED vs. ENABLE, which the error message suggests, is not the actual issue?
Comment 4 Dennis Schridde 2015-07-09 17:36:35 UTC
Wireshark logs (before Trojita issues STARTTLS):
* OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE MUPDATE=mupdate://cyrus-portal/ STARTTLS AUTH=PLAIN AUTH=LOGIN SASL-IR] cyrus-portal01 Cyrus IMAP Murder v2.4.17-Fedora-RPM-2.4.17-8.el7_1 server ready\x0d\x0a

So the linefeeds seem to be correct. Maybe they are just wrong in the debug console?
Comment 5 Jan Kundrát 2015-07-17 17:47:46 UTC
This is a bug in Cyrus, so I reported [1] it to their upstream. A quick workaround is to disable QRESYNC and CONDSTORE extensions in Trojita (IMAP -> Settings -> IMAP -> Blacklist protocol extensions).

A patch which relaxes Trojita's expectations is available for review at [2].

[1] https://bugzilla.cyrusimap.org/show_bug.cgi?id=3898
[2] https://gerrit.vesnicky.cesnet.cz/r/464
Comment 6 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 329204
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
Comment 7 Dennis Schridde 2015-07-28 08:28:48 UTC
Thanks! I tried 0.5.git.1437920489.7bd16b2 and it seems to work with our server now.