[horde] ActiveSync/IMP error with latest GIT

Thu Feb 27 10:49:46 UTC 2014

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Wed, 26 Feb 2014, Michael M Slusarz wrote:

> Quoting Joerg Pulz <Joerg.Pulz at frm2.tum.de>:
>
>> 
>> On Wed, 26 Feb 2014, Joerg Pulz wrote:
>>> 
>>> Now, when the client attempts to sync messages i get the following errors:
>>> 
>>> 2014-02-26T10:31:54+01:00 INFO: [16619] 
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX, 407672)
>>> 2014-02-26T10:31:54+01:00 ERR: [16619] Message gone or error reading 
>>> message from server: Not Found
>>> 2014-02-26T10:31:54+01:00 INFO: [16619] Updating state during change
>>> 2014-02-26T10:31:54+01:00 INFO: [16619] 
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX, 407673)
>>> 2014-02-26T10:31:54+01:00 ERR: [16619] Message gone or error reading 
>>> message from server: Not Found
>>> 2014-02-26T10:31:54+01:00 INFO: [16619] Updating state during change
>>> 2014-02-26T10:31:54+01:00 INFO: [16619] 
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX, 407674)
>>> 2014-02-26T10:31:54+01:00 ERR: [16619] Message gone or error reading 
>>> message from server: Not Found
>>> 2014-02-26T10:31:54+01:00 INFO: [16619] Updating state during change
>>> ..... and so on
>> 
>> Just found this which seems to be related to the error above:
>> WARN: HORDE PHP ERROR: Invalid argument supplied for foreach() [pid 16103 
>> on line 2582 of "/.../horde/libs/Horde/Imap/Client/Socket.php"]
>
> This has been fixed ... at least the prevention of the PHP error message.
>
> However, this indicates that the underlying IMAP FETCH call was faulty for 
> some reason.  So it would be great if you could grab an IMAP log (see 
> imp/config/backends.php) of an event when this occurs.

Michael,

thanks for your response.
It seems that this is related to the BINARY extension of 
curys-imapd-2.4.17.

Here is the relevant part of the log:
- ------------------------------
>> Thu, 27 Feb 2014 08:38:45 +0100
>> Server connection took 0.0023 seconds.
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE STARTTLS AUTH=PLAIN AUTH=DIGEST-MD5 AUTH=CRAM-MD5 AUTH=GSSAPI SASL-IR] imap.frm2.tum.de Cyrus IMAP v2.4.17 server ready
C: 1 STARTTLS
S: 1 OK Begin TLS negotiation now
>> Command 1 took 0.0004 seconds.
>> Successfully completed TLS negotiation.
C: 2 CAPABILITY
S: * CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE LIST-EXTENDED WITHIN QRESYNC SCAN XLIST URLAUTH URLAUTH=BINARY X-NETSCAPE AUTH=PLAIN AUTH=DIGEST-MD5 AUTH=CRAM-MD5 AUTH=GSSAPI SASL-IR COMPRESS=DEFLATE IDLE
S: 2 OK Completed
>> Command 2 took 0.0009 seconds.
3 [SASL-IR AUTHENTICATE Command - method: PLAIN, username: XXXXX]
>> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
C: 4 ENABLE QRESYNC
C: 5 NAMESPACE
S: * ENABLED CONDSTORE QRESYNC
S: 4 OK Completed
>> Command 4 took 0.0004 seconds.
S: * NAMESPACE (("INBOX." ".")) (("user." ".")) (("" "."))
S: 5 OK Completed
>> Command 5 took 0.0009 seconds.
C: 6 STATUS INBOX (MESSAGES UIDNEXT UIDVALIDITY HIGHESTMODSEQ)
S: * STATUS INBOX (MESSAGES 6290 UIDNEXT 407698 UIDVALIDITY 1326378038 HIGHESTMODSEQ 31038)
S: 6 OK Completed
>> Command 6 took 0.0007 seconds.
C: 7 EXAMINE INBOX
S: * 6290 EXISTS
S: * 0 RECENT
S: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $MDNSent Junk NonJunk $Forwarded $has_cal $NotJunk $Junk)
S: * OK [PERMANENTFLAGS ()] Ok
S: * OK [UNSEEN 4085] Ok
S: * OK [UIDVALIDITY 1326378038] Ok
S: * OK [UIDNEXT 407698] Ok
S: * OK [HIGHESTMODSEQ 31038] Ok
S: * OK [URLMECH INTERNAL] Ok
S: 7 OK [READ-ONLY] Completed
>> Command 7 took 0.0031 seconds.
>> CACHE: Stored metadata (_m,uidvalid [INBOX])
>> SEARCH: Expired from cache [INBOX]
C: 8 UID SEARCH RETURN (ALL COUNT) SENTSINCE 20-Feb-2014
S: * ESEARCH (TAG "8") UID ALL 407477,407482:407484,407487:407488,407520,407525,407531:407532,407554,407577:407578,407585:407586,407589,407591,407594,407601:407602,407604:407605,407607,407610:407613,407618,407634,407636,407659,407670,407672,407676,407678:407681,407683:407690,407692,407697 COUNT 48
S: 8 OK Completed (48 msgs in 0.008 secs)
>> Command 8 took 0.0079 seconds.
>> CACHE: Stored metadata (_s,_i [INBOX])
>> SEARCH: Saved search to cache (a8ec7e98a4c461110ee413a302e68b6f3e30674c [INBOX])
C: 9 UID FETCH 407477,407482:407484,407487:407488,407520,407525,407531:407532,407554,407577:407578,407585:407586,407589,407591,407594,407601:407602,407604:407605,407607,407610:407613,407618,407634,407636,407659,407670,407672,407676,407678:407681,407683:407690,407692,407697 (FLAGS)
S: * 6243 FETCH (FLAGS (\Answered \Seen) UID 407477)
S: * 6244 FETCH (FLAGS (\Seen) UID 407482)
S: * 6245 FETCH (FLAGS (\Seen) UID 407483)
S: * 6246 FETCH (FLAGS (\Seen) UID 407484)
S: * 6247 FETCH (FLAGS (\Seen) UID 407487)
S: * 6248 FETCH (FLAGS (\Seen) UID 407488)
S: * 6249 FETCH (FLAGS (\Seen $Forwarded) UID 407520)
S: * 6250 FETCH (FLAGS (\Answered \Seen) UID 407525)
S: * 6251 FETCH (FLAGS (\Seen) UID 407531)
S: * 6252 FETCH (FLAGS (\Seen) UID 407532)
S: * 6253 FETCH (FLAGS (\Seen) UID 407554)
S: * 6254 FETCH (FLAGS (\Seen) UID 407577)
S: * 6255 FETCH (FLAGS (\Seen) UID 407578)
S: * 6256 FETCH (FLAGS (\Seen) UID 407585)
S: * 6257 FETCH (FLAGS (\Seen) UID 407586)
S: * 6258 FETCH (FLAGS (\Seen) UID 407589)
S: * 6259 FETCH (FLAGS (\Seen) UID 407591)
S: * 6260 FETCH (FLAGS (\Seen) UID 407594)
S: * 6261 FETCH (FLAGS (\Seen) UID 407601)
S: * 6262 FETCH (FLAGS (\Seen) UID 407602)
S: * 6263 FETCH (FLAGS (\Seen) UID 407604)
S: * 6264 FETCH (FLAGS (\Seen) UID 407605)
S: * 6265 FETCH (FLAGS (\Seen) UID 407607)
S: * 6266 FETCH (FLAGS (\Seen) UID 407610)
S: * 6267 FETCH (FLAGS (\Seen) UID 407611)
S: * 6268 FETCH (FLAGS (\Answered \Seen) UID 407612)
S: * 6269 FETCH (FLAGS (\Seen) UID 407613)
S: * 6270 FETCH (FLAGS (\Seen) UID 407618)
S: * 6271 FETCH (FLAGS (\Seen) UID 407634)
S: * 6272 FETCH (FLAGS (\Seen) UID 407636)
S: * 6273 FETCH (FLAGS (\Seen) UID 407659)
S: * 6274 FETCH (FLAGS (\Seen) UID 407670)
S: * 6275 FETCH (FLAGS (\Seen) UID 407672)
S: * 6276 FETCH (FLAGS (\Answered \Seen) UID 407676)
S: * 6277 FETCH (FLAGS (\Seen) UID 407678)
S: * 6278 FETCH (FLAGS (\Seen) UID 407679)
S: * 6279 FETCH (FLAGS (\Seen) UID 407680)
S: * 6280 FETCH (FLAGS (\Seen) UID 407681)
S: * 6281 FETCH (FLAGS (\Answered \Seen) UID 407683)
S: * 6282 FETCH (FLAGS (\Answered \Seen) UID 407684)
S: * 6283 FETCH (FLAGS (\Answered \Seen) UID 407685)
S: * 6284 FETCH (FLAGS (\Seen) UID 407686)
S: * 6285 FETCH (FLAGS () UID 407687)
S: * 6286 FETCH (FLAGS (\Seen) UID 407688)
S: * 6287 FETCH (FLAGS (\Seen) UID 407689)
S: * 6288 FETCH (FLAGS (\Seen) UID 407690)
S: * 6289 FETCH (FLAGS (\Seen) UID 407692)
S: * 6290 FETCH (FLAGS () UID 407697)
S: 9 OK Completed (0.000 sec)
>> Command 9 took 0.008 seconds.
>> CACHE: Stored messages [INBOX; 407477,407482:407484,407487:407488,407520,407525,407531:407532,407554,407577:407578,407585:407586,407589,407591,407594,407601:407602,407604:407605,407607,407610:407613,407618,407634,407636,407659,407670,407672,407676,407678:407681,407683:407690,407692,407697]
>> CACHE: Retrieved messages (HICenv,HICflags,HICstruct,HICdg [INBOX; 407477])
C: 10 UID FETCH 407477 (BODYSTRUCTURE ENVELOPE BODY.PEEK[HEADER])
S: * 6243 FETCH (UID 407477 ENVELOPE (.............

- -> <Message header>

S: 10 OK Completed (0.008 sec)
>> Command 10 took 0.0255 seconds.
>> CACHE: Stored messages [INBOX; 407477]
C: 11 UID FETCH 407477 (BINARY.SIZE[0] BINARY.SIZE[1] BINARY.PEEK[1.1.2] BINARY.PEEK[1.1.1])
S: 11 BAD Invalid binary section
>> Command 11 took 0.0003 seconds.
>> CACHE: Retrieved messages (HICenv,HICflags,HICstruct,HICdg [INBOX; 407482])
C: 12 UID FETCH 407482 (BODYSTRUCTURE ENVELOPE BODY.PEEK[HEADER])
S: * 6244 FETCH (UID 407482 ENVELOPE (.............

- -> <Message header>

S: 12 OK Completed (0.000 sec)
>> Command 12 took 0.111 seconds.
>> CACHE: Stored messages [INBOX; 407482]
C: 13 UID FETCH 407482 (BINARY.SIZE[0] BINARY.SIZE[1] BINARY.PEEK[1.1.2] BINARY.PEEK[1.1.1])
S: 13 BAD Invalid binary section
>> Command 13 took 0.0004 seconds.

- -> <more fetching of message headers>

C: 106 LOGOUT
S: * BYE LOGOUT received
S: 106 OK Completed
>> Command 106 took 0.0004 seconds.
- ------------------------------

For now, i've disabled the BINARY capability in the imp backend 
configuration using:
$servers['advanced']['capability_ignore'] = array('BINARY');

After that configuration change clients can now sync without further 
errors as long as i set the horde auth backend to application->imp instead 
of LDAP, but thats another story.

Is the above related to a cyrus-imapd problem/bug or is the request sent 
by imp wrong?
With 5.1.6-git from 7th of december 2013 everything was fine.

Kind regards
Joerg

- -- 
The beginning is the most important part of the work.
 				-Plato
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.22 (FreeBSD)

iD8DBQFTDxhNSPOsGF+KA+MRAl85AJ9gVi43uhY9gUSxZUGJIB5qvEo+wACglHkw
8z5cG08V1JQ7NYp9sKlGWvw=
=/Pqw
-----END PGP SIGNATURE-----