| Summary: | UnexpectedResponseReceived Unhandled ENABLED response␍␊ENABLE ␊␊ | ||
|---|---|---|---|
| Product: | [Unmaintained] trojita | Reporter: | Dennis Schridde <heri+kde> |
| Component: | IMAP | Assignee: | Trojita default assignee <trojita-bugs> |
| Status: | RESOLVED FIXED | ||
| Severity: | normal | ||
| Priority: | NOR | ||
| Version: | git | ||
| Target Milestone: | --- | ||
| Platform: | Other | ||
| OS: | Linux | ||
| Latest Commit: | http://commits.kde.org/trojita/8152670c3715769753ceec5ac55a04853b086450 | Version Fixed In: | |
| Sentry Crash Report: | |||
Actually it does not happen when open "any" folder. It happens when I open one folder and afterwards open another. 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)? 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? 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? 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 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 Thanks! I tried 0.5.git.1437920489.7bd16b2 and it seems to work with our server now. |
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