Re: Plugin virtual, Horde BAD IMAP QRESYNC not enabled

15 Nov 2017


      It seems that horde forgots to re-enable QRESYNC after connection
timeout. Regarding the connection timeout, do you see anything in
dovecot logs?
Aki
On 15.11.2017 12:51, Jakob Schürz wrote:
...
Hi there!
This is the horde-imap. Hope this helps more to find out, what's the
problem with QRESYNC and dovecots virtual-plugin

...
...
Wed, 15 Nov 2017 08:45:21 +0000
Connection to: imap://aldebaran.local/ Server connection took 0,0031
seconds.
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE IDLE XDOVECOT STARTTLS AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5
AUTH=DIGEST-MD5] Dovecot ready.
C: 1 [AUTHENTICATE response (username: jakob)]
S: + PDQzMjM5OTUxOTUyNTgxNzYuMTUxMDczNTUyMUBhbGRlYmFyYW4+
C: amFrb2IgYzlkYWZiNGEzNDE1ZGJkZjRlNjIwNzUzMDYxM2QxMmQ=
S: 1 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS
THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT
CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC
ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE
XDOVECOT SPECIAL-USE QUOTA ACL RIGHTS=texk] Logged in
Command 1 took 0,0146 seconds.
CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
C: 2 ENABLE QRESYNC
C: 3 SELECT Virtual$Alle
S: * ENABLED QRESYNC
S: 2 OK Enabled (0.000 + 0.000 secs).
Command 2 took 0,0002 seconds.
S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft unknown-0
unknown-1 unknown-2 unknown-3 unknown-5 unknown-4 unknown-6 unknown-7
unknown-8 unknown-9 unknown-11 unknown-10 unknown-14 unknown-15
unknown-12 NonJunk unknown-13 unknown-16 unknown-21 unknown-17
unknown-19 unknown-23 unknown-20 unknown-22 unknown-18 unknown-24
unknown-25)
S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft
unknown-0 unknown-1 unknown-2 unknown-3 unknown-5 unknown-4 unknown-6
unknown-7 unknown-8 unknown-9 unknown-11 unknown-10 unknown-14
unknown-15 unknown-12 NonJunk unknown-13 unknown-16 unknown-21
unknown-17 unknown-19 unknown-23 unknown-20 unknown-22 unknown-18
unknown-24 unknown-25 \*)] Flags permitted.
S: * 43507 EXISTS
S: * 1 RECENT
S: * OK [UNSEEN 20448] First unseen.
S: * OK [UIDVALIDITY 1510698551] UIDs valid
S: * OK [UIDNEXT 49827] Predicted next UID
S: * OK [HIGHESTMODSEQ 723] Highest
S: 3 OK [READ-WRITE] Select completed (0.000 + 0.000 secs).
Command 3 took 1,4967 seconds.
CACHE: Stored metadata (_m,uidvalid [Virtual$Alle])
C: 4 NAMESPACE
S: * NAMESPACE (("INBOX$" "$")("Virtual$" "$")("Mailarchiv$" "$"))
(("shared$" "$")) (("Roseggergasse$" "$"))
S: 4 OK Namespace completed (0.000 + 0.000 secs).
Command 4 took 0,0004 seconds.
C: 5 UID FETCH 43543 (ENVELOPE)
S: * 37224 FETCH (UID 43543 ENVELOPE ("Wed, 15 Nov 2017 00:10:24
+0100" "Plugin virtual, Horde BAD IMAP QRESYNC not enabled"
(("=?UTF-8?Q?Jakob_Sch=c3=bcrz?=" NIL "wertstoffe" "nurfuerspam.de"))
(("=?UTF-8?Q?Jakob_Sch=c3=bcrz?=" NIL "wertstoffe" "nurfuerspam.de"))
(("=?UTF-8?Q?Jakob_Sch=c3=bcrz?=" NIL "wertstoffe" "nurfuerspam.de"))
((NIL NIL "dovecot" "dovecot.org")) NIL NIL NIL
"3da0743d-74a8-5f06-faf7-4909214ea976@nurfuerspam.de"))
S: 5 OK Fetch completed (0.001 + 0.000 secs).
Command 5 took 0,0021 seconds.
CACHE: Stored messages [Virtual$Alle; 43543]
CACHE: Retrieved messages (HICstruct,HICdg [Virtual$Alle; 43543])
C: 6 UID FETCH 43543 (BODYSTRUCTURE)
S: * 37224 FETCH (UID 43543 BODYSTRUCTURE (("application"
"pgp-encrypted" NIL NIL "PGP/MIME version identification" "7bit" 12
NIL NIL NIL NIL)("application" "octet-stream" ("name" "encrypted.asc")
NIL "OpenPGP encrypted message" "7bit" 5081 NIL ("inline" ("filename"
"encrypted.asc")) NIL NIL) "encrypted" ("protocol"
"application/pgp-encrypted" "boundary"
"eMatq9f6Lg0pepTtPTDNXeNsoOg7mLskm") NIL NIL NIL))
S: 6 OK Fetch completed (0.001 + 0.000 secs).
Command 6 took 0,0039 seconds.
CACHE: Stored messages [Virtual$Alle; 43543]
C: 7 UID FETCH 43543 (BODY[HEADER])
S: * 37224 FETCH (UID 43543 BODY[HEADER] {728}
FCC: imap://jakob@localhost/INBOX/Sent
X-Identity-Key: id7
X-Account-Key: account1
To: dovecot@dovecot.org
From: =?UTF-8?Q?Jakob_Sch=c3=bcrz?= wertstoffe@nurfuerspam.de
Subject: Plugin virtual, Horde BAD IMAP QRESYNC not enabled
X-Enigmail-Draft-Status: N1110
Message-ID: 3da0743d-74a8-5f06-faf7-4909214ea976@nurfuerspam.de
Date: Wed, 15 Nov 2017 00:10:24 +0100
X-Mozilla-Draft-Info: internal/draft; vcard=0; receipt=0; DSN=0;
uuencode=0;  attachmentreminder=0; deliveryformat=4
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101
Thunderbird/52.4.0
MIME-Version: 1.0
Content-Type: multipart/encrypted;
protocol="application/pgp-encrypted";
boundary="eMatq9f6Lg0pepTtPTDNXeNsoOg7mLskm"
S: )
S: 7 OK Fetch completed (0.001 + 0.000 secs).
...
...
Command 7 took 0,0013 seconds.
C: 8 UID FETCH 43543 (BINARY.PEEK[1])
ERROR: read/timeout error.
ERROR: Server closed the connection.
Connection to: imap://aldebaran.local/ Server connection took 0,002
seconds.
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE IDLE XDOVECOT STARTTLS AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5
AUTH=DIGEST-MD5] Dovecot ready.
C: 9 [AUTHENTICATE response (username: jakob)]
S: + PDYzNDg5MDI0MjIxMzIwNTUuMTUxMDczNTUyM0BhbGRlYmFyYW4+
C: amFrb2IgZGIxMzA2OTE3MDE4MDY1MGY4NWEyMGI5ZGEwOTRkNWM=
S: 9 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS
THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT
CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC
ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE
XDOVECOT SPECIAL-USE QUOTA ACL RIGHTS=texk] Logged in
Command 9 took 0,0126 seconds.
C: 10 SELECT Virtual$Alle (QRESYNC (1510698551 723 43543))
S: 10 BAD Error in IMAP command SELECT: QRESYNC not enabled (0.000 +
0.000 secs).
Command 10 took 0,0002 seconds.
CACHE: Retrieved messages (HICenv,HICdg [Virtual$Alle; 43543])
Best whishes
Jakob
Am 15.11.2017 um 01:46 schrieb Michael Slusarz:
...
Probably better to get the full protocol debug log from the Horde/IMP
side.  Instructions on how to enable that can be found in
imp/config/backends.php. See:
https://github.com/horde/imp/blob/master/config/backends.php#L288
rawlog output below only shows what Dovecot is returning - would be
more useful to see the entire client round-trip transactions however.
...
On November 14, 2017 at 4:15 PM Jakob Schürz
wertstoffe@nurfuerspam.de wrote:
Hi there!
I'm new on this list, so hello to all!
First i want say, that dovecot is a really great mailserver. I use it
since many years for my private usecase. I'm planning to setup a new
Mailserver, so i'm fiddeling around to understand dovecot better and
get
a "perfect" Mailserver. (Linux and Win10) Outlook, k9mail and the
gmail-app on android.
I want to leave google behind me, so i'm searching for a good server
for
cloudbased  and selfhosted calendar- and addressbook-server.
On some discussion in debianforum.de i got the hint, to use horde.
So i installed horde from pear. Got ActiveSync working with the Android
and Outlook. Mails, Calendar and Addressbook... very fine.
But then i run into a gotcha.
There is a problem  with some mails in dovecots virtual mailboxes.
I tried a lot to find out, how to debug this. First i thought, it's a
problem from horde, because the problem is only with horde-client.
Some Emails are not shown in horde. Exactly, they are not shown in
horde
on dovecots virtual mailboxes (plugin virtual in a separate virtual
namespace)
If i try to open this email in its original directory, it gets opened
without any problem.
So, when i try to open it from within the virtual mailbox, i get
this error:
---8<------
Nov 14 23:29:52 aldebaran dovecot[2495]: imap(jakob): Panic: file
index-mail-binary.c: line 586 (index_mail_get_binary_stream): assertion
failed: (mail->data.stream != NULL)
Nov 14 23:29:52 aldebaran dovecot[2495]: imap(jakob): Error: Raw
backtrace: /usr/lib/dovecot/libdovecot.so.0(+0x95272) [0x7f671137e272]
-> /usr/lib/dovecot/libdovecot.so.0(+0x9536d) [0x7f671137e36d] ->
/usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f6711314951] ->
/usr/lib/dovecot/libdovecot-storage.so.0(index_mail_get_binary_stream+0x238)
[0x7f67116b3de8] ->
/usr/lib/dovecot/libdovecot-storage.so.0(mail_get_binary_stream+0x60)
[0x7f6711640fa0] ->
/usr/lib/dovecot/libdovecot-storage.so.0(imap_msgpart_open+0x139)
[0x7f67116f40f9] -> dovecot/imap jakob 192.168.0.14 UID
FETCH [0x55bef3095bbc] -> dovecot/imap jakob 192.168.0.14
UID FETCH [0x55bef3093fb6] -> dovecot/imap jakob
192.168.0.14 UID FETCH [0x55bef30950e9] ->
dovecot/imap jakob 192.168.0.14 UID FETCH
[0x55bef3086d9b] -> dovecot/imap jakob 192.168.0.14 UID
FETCH [0x55bef3092735] -> dovecot/imap jakob
192.168.0.14 UID FETCH [0x55bef30909c2] -> dovecot/imap
jakob 192.168.0.14 UID FETCH [0x55bef3090a4c] ->
dovecot/imap jakob 192.168.0.14 UID FETCH
[0x55bef3090e55] -> dovecot/imap jakob 192.168.0.14 UID
FETCH [0x55bef30913c6] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x52) [0x7f6711392dd2]
-> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109)
[0x7f6711394409] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x3c)
[0x7f6711392e6c] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38)
[0x7f6711393018] ->
/usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13)
[0x7f671131ae93] -> dovecot/imap jakob 192.168.0.14 UID
FETCH [0x55bef3083e68] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)
[0x7f6710f6a2b1]
-> dovecot/imap jakob 192.168.0.14 UID FETCH
[0x55bef3083fea]
Nov 14 23:29:52 aldebaran dovecot[2495]: imap(jakob): Fatal: master:
service(imap): child 2704 killed with signal 6 (core dumps disabled)
---8<------
So i activated rawlog as after-login executeable. The IMAP-dialog when
opening this email is:
---8<------
9 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE
IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS
THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT
CHILDREN
NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH
ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE XDOVECOT
SPECIAL-USE QUOTA ACL RIGHTS=texk] Logged in
10 BAD Error in IMAP command SELECT: QRESYNC not enabled (0.000 + 0.000
secs).
11 OK No quota (0.000 + 0.000 secs).
---8<------
If found only one Report for this problem, but on regular imap-folders,
and there was not really a solution. This report is from 2015.
On regular folders, i have no problem with this emails, only on virtual
folders.
So i think, it is a problem of the virtual-plugin.
Here is one of this failing emails:
---8<------
Return-path: jakob@mydomain.example
Envelope-to: jakob@mydomain.example
Delivery-date: Mon, 13 Nov 2017 09:23:52 +0100
Received: from 1.2.3.4.wireless.dyn.drei.com ([1.2.3.4]
helo=marketingnh)
by mydomain.example with esmtpsa
(TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256)
(Exim 4.89)
(envelope-from jakob@mydomain2.example)
id 1eEA24-0002AR-IW
for jakob@mydomain.example; Mon, 13 Nov 2017 09:23:52 +0100
From: Microsoft Outlook jakob@mydomain.example
To: =?utf-8?B?SmFrb2J1cyBTY2jDvHJ6?= jakob@mydomain.example
MIME-Version: 1.0
Content-Type: text/html;
charset="utf-8"
Content-Transfer-Encoding: 8bit
Message-Id: E1eEA24-0002AR-IW@mydomain.example
Date: Mon, 13 Nov 2017 09:23:52 +0100
X-SA-Exim-Connect-IP: 178.114.188.235
X-SA-Exim-Mail-From: jakob@mydomain.example
X-Spam-Checker-Version: SpamAssassin 3.4.1 (2015-04-28) on aldebaran
X-Spam-Level:
X-Spam-Status: No, score=0.7 required=5.0
tests=ALL_TRUSTED,HTML_MESSAGE,
HTML_MIME_NO_HTML_TAG,MIME_HTML_ONLY,TVD_RCVD_IP autolearn=no
autolearn_force=no version=3.4.1
Subject: =?utf-8?B?TWljcm9zb2Z0IE91dGxvb2stVGVzdG5hY2hyaWNodA==?=
X-SA-Exim-Version: 4.2.1 (built Tue, 02 Aug 2016 21:08:31 +0000)
X-SA-Exim-Scanned: Yes (on aldebaran.mydomain.example)
Diese E-Mail-Nachricht wurde von Microsoft Outlook automatisch wÃ¤hrend
des Testens der Kontoeinstellungen gesendet.
---8<------
my dovecot-config is:
---8<------
# dovecot -n
# 2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.16 (fed8554)
# OS: Linux 4.13.0-trunk-amd64 x86_64 Debian 9.1 btrfs
auth_mechanisms = plain login cram-md5 digest-md5
auth_socket_path = /var/run/dovecot/auth-userdb
first_valid_uid = 1000
imap_capability = +XDOVECOT
imap_client_workarounds = tb-extra-mailbox-sep
lda_mailbox_autocreate = yes
lda_mailbox_autosubscribe = yes
listen = *, ::1
login_trusted_networks = 127.0.0.1/8 192.168.0.0/24 192.168.1.0/24
172.17.0.0/24 172.18.0.0/24
mail_debug = yes
mail_gid = vmail
mail_home =  /var/mail/%u
mail_location =
maildir:/var/mail/%u/Maildir:LAYOUT=fs:INDEX=/var/lib/dovecot/db/indexes/Maildir/%u:CONTROL=/var/lib/dovecot/db/control/Maildir/%u
mail_plugins = zlib quota acl listescape mail_log notify virtual
mail_privileged_group = vmail
mail_server_admin = mailto:jakob@xundeenergie.at
mail_shared_explicit_inbox = yes
mail_uid = vmail
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope
encoded-character vacation subaddress comparator-i;ascii-numeric
relational regex imap4flags copy include variables body enotify
environment mailbox date index ihave duplicate mime foreverypart
extracttext
mmap_disable = yes
namespace {
hidden = no
ignore_on_failure = no
inbox = no
list = children
location =
maildir:/var/mail/%%u/Maildir:LAYOUT=fs:INDEX=/var/lib/dovecot/db/indexes/%u/shared/%%u:INDEXPVT=/var/lib/dovecot/db/indexes/%u/shared/%%u
   prefix = shared$%%u$
separator = $
subscriptions = no
type = shared
}
namespace {
hidden = no
inbox = no
list = children
location =
maildir:/var/mail/mailarchiv/%u/:LAYOUT=fs:INDEX=/var/lib/dovecot/db/indexes/%u/mailarchiv:INDEXPVT=/var/lib/dovecot/db/indexes/%u/mailarchiv
   mailbox incoming {
auto = create
}
mailbox outgoing {
auto = create
}
prefix = Mailarchiv$
separator = $
subscriptions = no
type = public
}
namespace {
list = children
location =
maildir:/var/mail/public/:LAYOUT=fs:INDEX=/var/lib/dovecot/db/indexes/public/%u:INDEXPVT=/var/lib/dovecot/db/indexes/public/%u
   prefix = Roseggergasse$
separator = $
subscriptions = no
type = public
}
namespace Virtual {
hidden = no
list = children
location =
virtual:/var/mail/virtual:INDEX=/var/lib/dovecot/db/indexes/virtual/%u:INDEXPVT=/var/lib/dovecot/db/indexes/virtual/%u
   mailbox "Deleted Messages" {
auto = no
special_use = \Trash
}
mailbox Drafts {
auto = no
special_use = \Drafts
}
mailbox Entwürfe {
auto = no
special_use = \Drafts
}
mailbox "Gelöschte Elemente" {
auto = no
special_use = \Trash
}
mailbox "Gelöschte Objekte" {
auto = no
special_use = \Trash
}
mailbox Gesendet {
auto = no
special_use = \Sent
}
mailbox "Gesendete Elemente" {
auto = no
special_use = \Sent
}
mailbox "Gesendete Objekte" {
auto = no
special_use = \Sent
}
mailbox Mistkübel {
auto = no
special_use = \Trash
}
mailbox Papierkorb {
auto = no
special_use = \Trash
}
mailbox Sent {
auto = no
special_use = \Sent
}
mailbox "Sent Messages" {
auto = no
special_use = \Sent
}
mailbox Trash {
auto = no
special_use = \Trash
}
mailbox Virtual$Alle {
comment = All my messages
}
mailbox Virtual$Markierte {
comment = All my unread messages
}
mailbox "Virtual$Neue Mails" {
comment = All my unread messages
}
mailbox "Virtual$Ungelesene Mails" {
comment = All my unread messages
}
prefix = Virtual$
separator = $
subscriptions = no
}
namespace inbox {
hidden = no
inbox = yes
location =
mailbox Archiv {
auto = no
special_use = \Archive
}
mailbox Archive {
auto = no
special_use = \Archive
}
mailbox Archives {
auto = no
special_use = \Archive
}
mailbox "Deleted Messages" {
auto = no
special_use = \Trash
}
mailbox Drafts {
auto = no
special_use = \Drafts
}
mailbox Entwürfe {
auto = no
special_use = \Drafts
}
mailbox "Gelöschte Elemente" {
auto = no
special_use = \Trash
}
mailbox "Gelöschte Objekte" {
auto = no
special_use = \Trash
}
mailbox Gesendet {
auto = no
special_use = \Sent
}
mailbox "Gesendete Elemente" {
auto = no
special_use = \Sent
}
mailbox "Gesendete Objekte" {
auto = no
special_use = \Sent
}
mailbox Important {
auto = no
}
mailbox Junk {
auto = subscribe
autoexpunge = 30 days
special_use = \Junk
}
mailbox Mistkübel {
auto = no
special_use = \Trash
}
mailbox Papierkorb {
auto = no
special_use = \Trash
}
mailbox Sent {
auto = subscribe
special_use = \Sent
}
mailbox "Sent Messages" {
auto = no
special_use = \Sent
}
mailbox Spam {
auto = no
special_use = \Junk
}
mailbox Trash {
auto = no
special_use = \Trash
}
mailbox Wichtig {
auto = create
}
prefix = INBOX$
separator = $
subscriptions = no
}
namespace subscriptions {
hidden = yes
list = no
location =
prefix =
subscriptions = yes
}
passdb {
args = scheme=CRYPT username_format=%u /etc/dovecot/users
driver = passwd-file
}
plugin {
acl = vfile:/etc/dovecot/dovecot-acl:cache_secs=300
acl_anyone = allow
acl_shared_dict = file:/var/lib/dovecot/db/shared-mailboxes.db
fts =  lucene
fts_autoindex =  yes
fts_autoindex_max_recent_msgs =  80
fts_decoder =  decode2text.sh
fts_index_timeout =  90
fts_lucene =  whitespace_chars=@. normalize no_snowball
mail_home =  /var/mail/%u
setting_name = sieve, managedsieve
sieve =
file:/var/spool/dovecot/sieve/%n;active=/var/spool/dovecot/sieve/%n/%n.sieve
}
postmaster_address = postmaster@localhost
protocols = " imap lmtp sieve sieve"
service anvil {
unix_listener anvil-auth-penalty {
mode = 00
}
}
service auth {
unix_listener auth-client {
group = vmail
mode = 0666
user = vmail
}
unix_listener auth-userdb {
group = vmail
mode = 0666
user = vmail
}
}
service imap-login {
inet_listener imap {
port = 143
}
inet_listener imaps {
port = 993
ssl = yes
}
process_min_avail = 1
}
service imap {
executable = imap postlogin
process_limit = 1024
}
service postlogin {
executable = script-login -d rawlog
}
ssl = required
ssl_cert = 
Hope you can help me. It's a certain showstopper for me...
Greetings
Jakob

Re: Plugin virtual, Horde BAD IMAP QRESYNC not enabled

Aki Tuomi