[horde] Strange error accessing emails via activesync - crashes dovecot. Accessing the same mailbox via IMAp works as expected.
Torben Dannhauer
torben at dannhauer.info
Wed Jan 4 22:14:54 UTC 2017
Zitat von Michael J Rubinsky <mrubinsk at horde.org>:
> You added it to the "smtp" config array. Move it to the outer array.
Dooh, that was my error. *shame*
now I figured out the corresponding log (see below)
This log raises two questions:
a) what causes the crash of the imap server
b) why does it not recover?
Regarding a): Maybe this is a bug in dovecot (but haven't found a
specific hint, just a guess). Currently I'm using 2.2.13 and I could
upgrade to 2.2.26 without too much work, but I try to avoid unplannend
and only minimal tested upgrades on production servers. So maybe
fixing b) is a good intermediate solution till regular overhaul.. My
guess for the cause of b) is that after a connection loss and
reconnect, the mailbox selection is not restored..
Michael, and ideas on that?
Thanks,
Torben
Log snippet:
-------------------
S: 19 OK Fetch completed.
>> Command 19 took 0,0006 seconds.
C: 20 UID FETCH 10703 (BINARY.SIZE[1] BINARY.PEEK[1])
>> ERROR: read/timeout error.
>> ERROR: Server closed the connection.
>> Connection to: imap://server.tld/
>> Server connection took 0,0002 seconds.
S: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID
ENABLE IDLE STARTTLS AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
C: 21 STARTTLS
S: 21 OK Begin TLS negotiation now.
>> Command 21 took 0,0001 seconds.
>> Successfully completed TLS negotiation.
C: 22 AUTHENTICATE PLAIN [INITIAL CLIENT RESPONSE (username: user at domain.tld)]
S: 22 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 SPECIAL-USE
BINARY MOVE QUOTA ACL RIGHTS=texk] Logged in
>> Command 22 took 0,0078 seconds.
C: 23 EXAMINE INBOX (QRESYNC (1179390893 5731
6538,6566,6579,6615:6616,6659,6675,6890:6891,6903,6972,6986,6997,7002,7018,7124,7152,7159,7163:7164,7193,7203,7221,7269,7276,7294:7295,7302,7307,7315,7319,7329,7331:7332,7343,7346,7349,7354,7360,7364,7369,7375,7377,7381,7389:7392,7404,7409,7412,7416,7419:7420,7424,7429,7435,7444,7447,7454,7463:7464,7469:7470,7504,7507,7509:7510,7514:7515,7517,7521:7522,7528:7529,7538:7539,7541,7543,7546,7549:7550,7552,7554,7557,7561:7563,7565,7567:7569,7577,7582,7585:7587,7591:7592,7597,7600,7602:7605,7610,7627,7631,7633:7634,7643,7657,7661,7665:7668,7672:7673,7675,7695,7698,7702,7720:7721,7724:7728,7732,7734,7742,7745,7754:7755,7757,7760:7761,7768,7770:7771,7775,7778,7783:7784,7788:7789,7791,7793:7795,7799,7805,7807,7811:7812,7814:7815,7817:7819,7821:7825,7835,7839:7842,7845:7847,7857:7861,7866,7870:7873,7876,7879,7882,7887:7891,7893,7895:7896,7900:7903,7907,7910,7913,7918,7920:7924,7926:7927,7929,7931:7932,7934,7937:7938,7947:7949,7952:7953,7956:7958,7960,7962:7965,7967:7968,7972,7974,7978,7985,798
7,7989,7992:7996,7998,8000:8004,8006,8009,8011:8012,8014:8016,8022:8025,8029,8031:8032,8035,8037,8041,8056,8059,8062,8067:8068,8076:8077,8085:8087,8091:8093,8101,8106,8112:8114,8127:8130,8158,8167,8169,8184,8191:8192,8196,8220,8226,8228,8233:8235,8242,8244,8246,8251,8253:8254,8257:8258,8260,8263,8267,8271,8273:8274,8276,8278,8280,8285,8294,8298,8312,8318,8327:8328,8331:8332,8338:8339,8343,8350,8352,8357,8362:8363,8370,8372,8374,8376:8378,8381:8382,8386,8388,8390,8392,8394,8397:8398,8401:8403,8407,8409:8412,8415,8421,8424,8429,8436,8444,8446:8451,8454,8457:8458,8465,8467:8469,8471,8474,8479:8485,8488,8492,8497,8500,8507,8516,8531,8533,8538:8539,8541,8543:8545,8548:8549,8551:8561,8564:8572,8574:8587,8590:8594,8598:8636,8638:8641,8643:8648,8650:8694,8696:8703,8705:8722,8726:8765,8767:8827,8829,8831:8901,8903:8923,8925:8929,8931,8933:8935,8937:8939,8941:8971,8973:8976,8978:8985,8987:9009,9011:9012,9015:9017,9020:9033,9035:9064,9066:9104,9107:9113,9116:9133,9135:9143,9148:9168,9170:9173,9
175:9178,9180:9197,9201:9216,9218:9232,9234:9247,9249:9256,9258:9305,9307:9309,9311:9379,9382:9392,9394:9395,9397:9403,9405:9409,9411:9428,9430:9450,9452:9494,9497:9511,9513:9541,9543:9544,9546:9562,9564,9566:9570,9572:9575,9577:9600,9602:9609,9611:9629,9632:9648,9651:9653,9657,9660:9666,9675:9677,9679:9685,9687:9693,9696:9701,9703:9712,9714:9718,9720:9737,9739:9745,9747:9754,9756:9758,9760,9763:9770,9772:9776,9778:9785,9787:9810,9812:9827,9829:9850,9852,9855:9857,9861:9878,9881:9895,9897:9911,9918:9929,9931:9932,9934:9937,9939:9942,9945:9947,9950:9951,9953:9958,9960:9961,9963:9964,9966,9968:9969,9971:9983,9987:10000,10002:10004,10007:10008,10010:10021,10023:10024,10026:10027,10032:10035,10037,10040:10046,10049:10056,10058:10062,10064,10066:10071,10074:10076,10079:10083,10085,10087:10089,10091:10095,10098:10100,10102:10109,10121:10122,10126:10127,10130:10140,10142,10146,10148:10155,10160:10209,10211:10218,10220:10229,10232:10239,10241:10243,10245:10263,10268:10272,10274:10275,10277:1
0279,10281:10282,10286:10291,10296,10298:10302,10305:10307,10310:10312,10314:10317,10319:10323,10327:10330,10332:10334,10336,10339,10342:10344,10347,10350:10352,10356,10358,10360:10362,10365:10371,10374,10376:10383,10385,10387:10394,10396,10398:10403,10405:10413,10416,10418,10420:10433,10435:10443,10446:10447,10453:10462,10464,10466,10468:10476,10478:10480,10482,10484:10485,10487:10488,10490:10491,10493,10495,10502:10509,10512,10515,10517,10521,10525:10527,10529:10533,10536,10538:10542,10544,10548,10551,10553:10554,10556,10559:10561,10563:10564,10566,10571,10575:10579,10581:10582,10584,10586:10589,10591,10594,10596:10597,10599,10602,10604:10605,10607,10610:10611,10614:10622,10629:10635,10637:10642,10645:10647,10649:10652,10657:10661,10663:10665,10667:10670,10672:10679,10681:10682,10684:10688,10690:10693,10695:10703,12234:12250,12252,12254:12279,12281:12285,12287:12323,12326:12328,12330:12337,12339:12341,12343,12346:12347,12349:12353,12355:12374,12376:12378))
S: 23 BAD Error in IMAP command EXAMINE: QRESYNC not enabled
>> Command 23 took 0,0006 seconds.
C: 24 UID SEARCH RETURN (ALL SAVE COUNT) UID 10705
S: 24 BAD No mailbox selected.
>> Command 24 took 0,0003 seconds.
C: 25 UID SEARCH RETURN (ALL SAVE COUNT) UID 10709
S: 25 BAD No mailbox selected.
>> Command 25 took 0,0002 seconds.
C: 26 UID SEARCH RETURN (ALL SAVE COUNT) UID 10710
S: 26 BAD No mailbox selected.
>> Command 26 took 0,0002 seconds.
C: 27 UID SEARCH RETURN (ALL SAVE COUNT) UID 10714
S: 27 BAD No mailbox selected.
>> Command 27 took 0,0003 seconds.
C: 28 UID SEARCH RETURN (ALL SAVE COUNT) UID 10715
-------------------
>
> --
> mike
> Sent from mobile
> ________________________________
> From: Torben Dannhauer <torben at dannhauer.info>
> Sent: Jan 3, 2017 11:44 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>:
>>
>>> Debug should be sufficient.
>>
>>
>> Hmm
>>
>> Debugging does not work, did I miss something?
>>
>> My backends.local.php:
>>
>> <snip>
>> $servers['imap'] = array(
>> 'disabled' => false,
>> 'name' => 'IMAP Server',
>> 'hostspec' => 'DOMAIN',
>> 'hordeauth' => 'full',
>> 'protocol' => 'imap',
>> 'port' => 143,
>> 'secure' => 'tls',
>> 'maildomain' => 'DOMAIN',
>> 'cache' => 'cache',
>> 'acl' => true,
>> 'preferred' => 'DOMAIN',
>> 'quota' => array(
>> 'driver' => 'imap',
>> ),
>> 'smtp' => array(
>> 'auth' => true,
>> 'debug' => '/tmp/imap.log',
>> 'localhost' => 'DOMAIN',
>> 'host' => 'DOMAIN',
>> 'password' => null,
>> 'port' => 25,
>> 'username' => null
>> ),
>> <snap>
>>
>>
>>
>>>
>>> --
>>> 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
>>>>
>>>
>>>
>>> --
>>> 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
>>
>
>
> --
> Horde mailing list
> Frequently Asked Questions: http://horde.org/faq/
> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
More information about the horde
mailing list