[horde] Strange error accessing emails via activesync - crashes dovecot. Accessing the same mailbox via IMAp works as expected.

Mon Jan 2 15:23:20 UTC 2017

Debug should be sufficient.

--
mike
Sent from mobile
________________________________
From: Torben Dannhauer <torben at dannhauer.info>
Sent: Jan 2, 2017 6:18 AM
To: horde at lists.horde.org
Subject: Re: [horde] Strange error accessing emails via activesync -  
crashes dovecot. Accessing the same mailbox via IMAp works as expected.

>
> Zitat von Michael J Rubinsky <mrubinsk at horde.org>:
>
>> Enable the  IMAP debug log in imp's backends.php file so we can see  
>> the IMAP conversation.
>
> is debug sufficient, or do is debug_raw better?
>
> thanks,
> Torben
>
>>
>> --
>> mike
>> Sent from mobile
>> ________________________________
>> From: Torben Dannhauer <torben at dannhauer.info>
>> Sent: Dec 31, 2016 5:11 PM
>> To: dovecot at listen.jpberlin.de; horde at lists.horde.org
>> Subject: [horde] Strange error accessing emails via activesync -  
>> crashes dovecot. Accessing the same mailbox via IMAp works as  
>> expected.
>>
>>> Hi,
>>>
>>>
>>>
>>> in my old PHP 5.6 Horde Setup, I have a client with activeSync errors: The
>>> users iphone (several devices, so it is device independent) stopps syncing
>>> emails premature and throws warnings in Horde and crashes the dovecot mail
>>> server. When accessing the emails via pure imap (webmailer or imap client),
>>> everything works as expected.
>>>
>>>
>>>
>>> The Horde logs a lot of this errors ("The email server reported an error"):
>>>
>>> 2016-12-31T22:30:48+01:00 ERR: Der E-Mail-Server hat einen IMAP-Fehler
>>> gemeldet.
>>>
>>> 2016-12-31T22:30:48+01:00 ERR: [19643] Unknown backend error skipping
>>> message: Der E-Mail-Server hat einen IMAP-Fehler gemeldet.
>>>
>>> 2016-12-31T22:30:48+01:00 ERR: [19643] Unable to fetch message: Der
>>> E-Mail-Server hat einen IMAP-Fehler gemeldet.
>>>
>>> 2016-12-31T22:30:48+01:00 ERR: Der E-Mail-Server hat einen IMAP-Fehler
>>> gemeldet.
>>>
>>>
>>>
>>> , usually followed by
>>>
>>> 2016-12-31T22:32:22+01:00 ERR: [21693]
>>> Horde_ActiveSync_Collections::getBackendIdForFolderUid failed  
>>> because folder
>>> was not found in cache.
>>>
>>>
>>>
>>> I watched simultaneous the imap server's standard log and got lots of this
>>> messages:
>>>
>>> Dec 31 22:42:54 jeeves dovecot: imap-login: Login: user=<user at domain.tld>,
>>> method=PLAIN, rip=IPv6-ADDRESS, lip=IPv6-ADDRESS, mpid=24524, TLS, TLSv1.2
>>> with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
>>>
>>> Dec 31 22:42:54 jeeves dovecot: imap(user at domain.tld): Disconnected: Logged
>>> out in=6119 out=6906
>>>
>>> Dec 31 22:42:55 jeeves dovecot: imap-login: Login: user=<user at domain.tld>,
>>> method=PLAIN, rip=IPv6-ADDRESS, lip=IPv6-ADDRESS, mpid=24526, TLS, TLSv1.2
>>> with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
>>>
>>> Dec 31 22:42:55 jeeves dovecot: imap(user at domain.tld): Disconnected: Logged
>>> out in=2757 out=78187
>>>
>>> Dec 31 22:42:55 jeeves dovecot: imap-login: Login: user=<user at domain.tld>,
>>> method=PLAIN, rip=IPv6-ADDRESS, lip=IPv6-ADDRESS, mpid=24528, TLS, TLSv1.2
>>> with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
>>>
>>> Dec 31 22:42:55 jeeves dovecot: imap(user at domain.tld): Disconnected: Logged
>>> out in=6119 out=7995
>>>
>>> Dec 31 22:42:56 jeeves dovecot: imap-login: Login: user=<user at domain.tld>,
>>> method=PLAIN, rip=IPv6-ADDRESS, lip=IPv6-ADDRESS, mpid=24530, TLS, TLSv1.2
>>> with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
>>>
>>> Dec 31 22:42:56 jeeves dovecot: imap(user at domain.tld): Disconnected: Logged
>>> out in=2585 out=89960
>>>
>>> Dec 31 22:42:56 jeeves dovecot: imap-login: Login: user=<user at domain.tld>,
>>> method=PLAIN, rip=IPv6-ADDRESS, lip=IPv6-ADDRESS, mpid=24532, TLS, TLSv1.2
>>> with cipher DHE-RSA-AES256-GCM-SHA384 (256/256 bits)
>>>
>>> Dec 31 22:42:56 jeeves dovecot: imap(user at domain.tld): Disconnected: Logged
>>> out in=6119 out=9188
>>>
>>> Is it normal that EAS uasage triggers a high frequency of imap
>>> logins/logouts?
>>>
>>>
>>>
>>>
>>>
>>> Additionally I observerd in the mailservers error log the following crash
>>> report (happens immediatly after the hi frequency logins stop):
>>>
>>> Dec 31 22:46:58 jeeves dovecot: imap(user at domain.tld): Panic: file
>>> istream-qp-decoder.c: line 102 (i_stream_qp_decoder_read):  
>>> assertion failed:
>>> (ret < 0)
>>>
>>> Dec 31 22:46:58 jeeves dovecot: imap(user at domain.tld): Error: Raw  
>>> backtrace:
>>> /usr/lib/dovecot/libdovecot.so.0(+0x6b6fe) [0x7fc2481d66fe] ->
>>> /usr/lib/dovecot/libdovecot.so.0(+0x6b7ec) [0x7fc2481d67ec] ->
>>> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7fc24818d8fb] ->
>>> /usr/lib/dovecot/libdovecot.so.0(+0x58c2f) [0x7fc2481c3c2f] ->
>>> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x53) [0x7fc2481df7b3] ->
>>> /usr/lib/dovecot/libdovecot.so.0(+0x7a08a) [0x7fc2481e508a] ->
>>> /usr/lib/dovecot/libdovecot.so.0(+0x7a1e5) [0x7fc2481e51e5] ->
>>> /usr/lib/dovecot/libdovecot.so.0(+0x7a383) [0x7fc2481e5383] ->
>>> /usr/lib/dovecot/libdovecot.so.0(i_stream_read+0x53) [0x7fc2481df7b3] ->
>>> /usr/lib/dovecot/libdovecot.so.0(i_stream_read_data+0x3d) [0x7fc2481e007d]
>>> -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xa139e) [0x7fc2484e639e] ->
>>> /usr/lib/dovecot/libdovecot-storage.so.0(index_mail_get_binary_stream+0x76)
>>> [0x7 fc2484e6876] ->
>>> /usr/lib/dovecot/libdovecot-storage.so.0(mail_get_binary_stream+0x5e)
>>> [0x7fc2484bd42e] ->
>>> /usr/lib/dovecot/libdovecot-storage.so.0(imap_msgpart_open+0x139)
>>> [0x7fc24851e5e9] -> dovecot/imap [user at domain.tld IPv6-ADDRESS UID
>>> FETCH](+0x1c0de) [0x7fc2489a50de] -> dovecot/imap [user at domain.tld
>>> IPv6-ADDRESS UID FETCH](+0x1a85a) [0x7fc2489a385a] -> dovecot/imap
>>> [user at domain.tld IPv6-ADDRESS UID FETCH](imap_fetch_more+0x37)
>>> [0x7fc2489a4957] -> dovecot/imap [user at domain.tld IPv6-ADDRESS UID
>>> FETCH](cmd_fetch+0x340) [0x7fc248998070] -> dovecot/imap [user at domain.tld
>>> IPv6-ADDRESS UID FETCH](command_exec+0x3c) [0x7fc2489a209c] -> dovecot/imap
>>> [user at domain.tld IPv6-ADDRESS UID FETCH](+0x17fb2) [0x7fc2489a0fb2] ->
>>> dovecot/imap [user at domain.tld IPv6-ADDRESS UID FETCH](+0x18066)
>>> [0x7fc2489a1066] -> dovecot/imap [user at domain.tld IPv6-ADDRESS UID
>>> FETCH](client_handle_input+0x13d) [0x7fc2489a139d] -> dovecot/imap
>>> [user at domain.tld IPv6-ADDRESS UID FETCH](client_input+0x85)  
>>> [0x7fc2489a1745]
>>> -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x3f) [0x7fc2481e7d0f]
>>> -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0xf9)
>>> [0x7fc2481e8d09] ->
>>> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x9) [0x7fc2481e7d79]
>>> -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7fc2481e7df8] ->
>>> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7fc248192dc3]
>>>
>>> Dec 31 22:46:58 jeeves dovecot: imap(user at domain.tld): Fatal: master:
>>> service(imap): child 24952 killed with signal 6 (core dumps disabled)
>>>
>>>
>>>
>>> What makes dovecot crash when using exchange activesync, but it works as
>>> expected when using imap directly? What does horde EAS while  
>>> accing the imap
>>> backend?
>>>
>>>
>>>
>>> My setup is:
>>>
>>> Debian Jessie
>>>
>>> Dovecot 2.2.13-12
>>>
>>> Apache 2.4.10
>>>
>>> PHP 5.6.29
>>>
>>> Horde current stable releases
>>>
>>>
>>>
>>> Has anyone a idea where to go on searching? It seems a bit strange and I'm
>>> currently out of ideas..
>>>
>>> Ill sent this in copy to dovecot list.
>>>
>>>
>>>
>>> Thanks and happy new year!
>>>
>>>
>>>
>>> Torben
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>>
>>> --
>>> Horde mailing list
>>> Frequently Asked Questions: http://horde.org/faq/
>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>
>
>
>
> -- 
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/
> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>