Tickets :: [#13274] Sporadic IMAP login errors

6.0.0-alpha12

6/12/25

Summary	Sporadic IMAP login errors
Queue	Horde Framework Packages
Queue Version	Git master
Type	Bug
State	Resolved
Priority	1. Low
Owners	slusarz (at) horde (dot) org
Requester	thomas.jarosch (at) intra2net (dot) com
Created	06/20/2014 (4010 days ago)
Due
Updated	07/02/2014 (3998 days ago)
Assigned	07/01/2014 (3999 days ago)
Resolved	07/02/2014 (3998 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

07/02/2014 09:32:27 PM	Michael Slusarz	Comment #9 Assigned to Michael Slusarz State ⇒ Resolved	Reply to this comment
Marking as resolved, since there is at least some evidence that other fixes have caused this issue to disappear. Reopen if you can reliably reproduce in the future.

07/02/2014 01:20:27 PM	Thomas Jarosch	Comment #8	Reply to this comment
Seems to me like this is the root cause (?) http://lists.horde.org/archives/horde/Week-of-Mon-20140630/051907.html yeah, I hoped that's the cause but it wasn't so: 1. The session ID is only regenerated every six hours. Since I first suspected this bug to be the root cause I've modified the Session.php code to trigger regenerate() if I touch a file in /tmp :) -> all stable, session ID gets regenerated Also the encryption bug does not trash data, it only stored it unencrypted. Session.php still works fine. 2. The sporadic login error also appeared a few minutes after using a fresh session. (the VM is shutdown over night) Unfortunately it did not happen again yet, I test it every day. I suspect it was some combination of ~~#13283~~ / #13284 and my cookie-less setup.

07/01/2014 06:00:43 PM	Michael Slusarz	Comment #7 State ⇒ Feedback	Reply to this comment
Seems to me like this is the root cause (?) http://lists.horde.org/archives/horde/Week-of-Mon-20140630/051907.html

06/27/2014 02:58:02 PM	Thomas Jarosch	Comment #6	Reply to this comment
My first shot in the dark was that the session data somehow got corrupted. But that was not true, I was able to decrypt the Horde_Secret encrypted password manually. So something else broke down, but it didn't happen again yet. Now I've written a small script that controls Firefox and clicks through all the horde apps in the top navigation bar. I'll let that run for a few hours and see if it breaks or not.

06/25/2014 06:43:09 PM	Michael Slusarz	Comment #5	Reply to this comment
Not really following what's happening in here. In short: are you saying the issue is with the session data becoming corrupted? I've never seen this so I can't provide any insight into that line of inquiry.

06/25/2014 10:09:32 AM	Thomas Jarosch	Comment #4	Reply to this comment
Ok, I found out how to trigger the specific "No password provided" backtrace: Just corrupt the Horde_Secret encrypted password in the session file :D As I kept the PHP session file when the bug occurred the second time, I was able to decrypt the stored IMAP password successfully using the session ID as key. This basically means the encrypted password was intact. So either Horde_Secret somehow delivered a wrong secret key for the decryption or the encryption engine (Horde_Crypt_Blowfish) itself had problems. Even when I revert the recent Horde_Secret fixes and try to trigger the specific buggy cookie behavior, all is fine. Strangely though this was not a one time "page load" issue: The broken session stayed broken, even when I entered different horde URLs into the browser while keeping the same session ID. Since I have debug verification code in Horde_Pack already, I'll now do the same for Horde_Secret: Verify decryption on Horde_Secret::write().

06/23/2014 12:18:01 PM	Thomas Jarosch	Comment #3	Reply to this comment
Ok, so I was unable to trigger it again last week. I've re-enabled the PLAIN auth mech in Socket.php as I didn't expect it to be related to CRAM-MD5. Tadaaaa, it just happend. Debug trace in IMAP_Client: 2014-06-24T10:38:30+02:00 NOTICE: HORDE [turba] TOMJ: setParam(password): foobar [pid 15671 on line 533 of "/datastore/D 2014-06-24T10:38:30+02:00 NOTICE: HORDE [turba] TOMJ: getParam(password) called [pid 15671 on line 488 of "/datastore/DEV 2014-06-24T10:38:30+02:00 NOTICE: HORDE [turba] TOMJ: getParam(password): foobar [pid 15671 on line 490 of "/datastore/D 2014-06-24T10:38:30+02:00 NOTICE: HORDE [turba] TOMJ: getParam(password) called [pid 15671 on line 488 of "/datastore/DEV 2014-06-24T10:38:30+02:00 NOTICE: HORDE [turba] TOMJ: getParam(password): foobar [pid 15671 on line 490 of "/datastore/D 2014-06-24T10:38:47+02:00 NOTICE: HORDE [turba] TOMJ: getParam(password) called [pid 17126 on line 488 of "/datastore/DEV 2014-06-24T10:38:47+02:00 NOTICE: HORDE [turba] TOMJ: getParam(): password not set [pid 17126 on line 492 of "/datastore/ 2014-06-24T10:38:47+02:00 ERR: HORDE [turba] No password provided. [pid 17126 on line 190 of "/datastore/DEVEL/framework/ Interesting to see that setParam(password) is never called for PID 17126. I'm using a file based session handler so it was easy to capture the content of the session file. The odd part is, that the session stays "destroyed" even when I use a different horde app (just modified the URL in the browser). Wild guess: The encrypted password in the session data somehow get's corrupted. I'll add verification code to Horde_Pack to test the result of pack() inside pack() again. If it's not the same as the input, I'll log it. That might or might not confirm ~~#13275~~ for this issue.

06/20/2014 03:07:20 PM	Thomas Jarosch	Comment #2 New Attachment: debug_imap_crash.patch	Reply to this comment
I could not trigger it anymore. Attached is my debug log patch for reference. I'm wondering if it's somehow related to ~~#13275~~: What if we pass data outside the ASCII range to Horde_Session / Horde_Secret. If that's processed by Horde_Pack, it might go wrong. I've inspected Horde_Support_Randomid(), but that produces base64()-safe ids. Anyhow, let's see if this happens again...

06/20/2014 09:08:31 AM	Thomas Jarosch	Comment #1 Milestone ⇒ State ⇒ Unconfirmed Patch ⇒ No Queue ⇒ Horde Framework Packages Summary ⇒ Sporadic IMAP login errors Type ⇒ Bug Priority ⇒ 1. Low	Reply to this comment
Hi, I'm currently testing git "master" and from time to time I'm facing very sporadic IMAP login errors. They seem to happen randomly when I click around the UI of the apps. This will generate IMAP traffic in my case since I'm using a Kolab backend. I didn't see anything like that before using the old FRAMEWORK_5_1 code. The horde log shows it can authenticate successfully and then on the next request it's broken: ---------------------------------------- 2014-06-21T09:59:07+02:00 NOTICE: HORDE [horde] Login success for admin to horde (172.16.1.145) [pid 2207 on line 164 of "/datastore/DEVEL/horde/login.php"] 2014-06-21T09:59:19+02:00 WARN: HORDE [imp] [login] Mail server denied authentication. [pid 2207 on line 732 of "/datastore/DEVEL/imp/lib/Imap.php"] 2014-06-21T09:59:19+02:00 WARN: HORDE PHP ERROR: json_encode() [<a href='function.json-encode'>function.json-encode</a>]: Invalid UTF-8 sequence in argument [pid 2207 on line 45 of "/datastore/DEVEL/framework/Pack/lib/Horde/Pack/Driver/Json.php"] 2014-06-21T09:59:19+02:00 WARN: HORDE PHP ERROR: json_encode() [<a href='function.json-encode'>function.json-encode</a>]: Invalid UTF-8 sequence in argument [pid 2207 on line 45 of "/datastore/DEVEL/framework/Pack/lib/Horde/Pack/Driver/Json.php"] 2014-06-21T09:59:19+02:00 WARN: HORDE PHP ERROR: json_encode() [<a href='function.json-encode'>function.json-encode</a>]: Invalid UTF-8 sequence in argument [pid 2207 on line 45 of "/datastore/DEVEL/framework/Pack/lib/Horde/Pack/Driver/Json.php"] 2014-06-21T09:59:19+02:00 WARN: HORDE PHP ERROR: json_encode() [<a href='function.json-encode'>function.json-encode</a>]: Invalid UTF-8 sequence in argument [pid 2207 on line 45 of "/datastore/DEVEL/framework/Pack/lib/Horde/Pack/Driver/Json.php"] 2014-06-21T09:59:19+02:00 WARN: HORDE PHP ERROR: json_encode() [<a href='function.json-encode'>function.json-encode</a>]: Invalid UTF-8 sequence in argument [pid 2207 on line 45 of "/datastore/DEVEL/framework/Pack/lib/Horde/Pack/Driver/Json.php"] 2014-06-21T09:59:20+02:00 ERR: HORDE [kronolith] No password provided. [pid 2207 on line 123 of "/datastore/DEVEL/framework/Share/lib/Horde/Share/Kolab.php"] ... ("the no password provided" message repeats for all horde apps using a Kolab backend) ---------------------------------------- The corresponding syslog from cyrus-imapd 2.4.17: ---------------------------------------- Jun 21 09:59:07 horde-git imaploc[3887]: starttls: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits new) no authentication Jun 21 09:59:07 horde-git imaploc[3887]: login: horde-git.m.i2n [127.0.0.1] admin PLAIN+TLS User logged in SESSIONID=<horde-git.m.i2n-3887-1403337547-1> Jun 21 09:59:07 horde-git imaploc[3887]: USAGE admin user: 0.012000 sys: 0.000000 Jun 21 09:59:07 horde-git imaploc[3941]: badlogin: horde-git.m.i2n [127.0.0.1] CRAM-MD5 [SASL(-13): authentication failure: incorrect digest response] Jun 21 09:59:10 horde-git imaploc[3941]: badlogin: horde-git.m.i2n [127.0.0.1] PLAIN [SASL(-13): authentication failure: Password verification failed] Jun 21 09:59:13 horde-git imaploc[3941]: badlogin: horde-git.m.i2n [127.0.0.1] plaintext admin SASL(-13): authentication failure: checkpass failed Jun 21 09:59:16 horde-git imaploc[3941]: badlogin: horde-git.m.i2n [127.0.0.1] plaintext admin SASL(-13): authentication failure: checkpass failed ---------------------------------------- I also have a backtrace of the "No password provided" error message but I doubt it's of any use: ---------------------------------------- 1. Horde_Registry::appInit() /datastore/DEVEL/turba/index.php:14 2. Horde_Registry->pushApp() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:299 3. Horde_Registry->_pushAppError() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1606 4. Horde_Registry::appInit() /datastore/DEVEL/turba/index.php:14 5. Horde_Registry->pushApp() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:299 6. Horde_Registry->callAppMethod() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1601 7. call_user_func_array() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1201 8. Horde_Registry_Application->init() 9. Turba_Application->_init() /datastore/DEVEL/framework/Core/lib/Horde/Registry/Application.php:105 10. Turba::getConfigFromShares() /datastore/DEVEL/turba/lib/Application.php:114 11. Turba_Driver_Kolab->createShare() /datastore/DEVEL/turba/lib/Turba.php:564 12. Turba::createShare() /datastore/DEVEL/turba/lib/Driver/Kolab.php:975 13. Horde_Registry::appInit() /datastore/DEVEL/turba/index.php:14 14. Horde_Registry->pushApp() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:299 15. Horde_Registry->callAppMethod() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1601 16. call_user_func_array() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1201 17. Horde_Registry_Application->init() 18. Turba_Application->_init() /datastore/DEVEL/framework/Core/lib/Horde/Registry/Application.php:105 19. Turba::getConfigFromShares() /datastore/DEVEL/turba/lib/Application.php:114 20. Turba_Driver_Kolab->createShare() /datastore/DEVEL/turba/lib/Turba.php:564 21. Turba::createShare() /datastore/DEVEL/turba/lib/Driver/Kolab.php:975 22. Horde_Core_Share_Driver->newShare() /datastore/DEVEL/turba/lib/Turba.php:675 23. Horde_Core_Share_Driver->__call() /datastore/DEVEL/turba/lib/Turba.php:675 24. call_user_func_array() /datastore/DEVEL/framework/Core/lib/Horde/Core/Share/Driver.php:63 25. Horde_Share_Base->newShare() 26. Horde_Share_Object_Kolab->set() /datastore/DEVEL/framework/Share/lib/Horde/Share/Base.php:419 27. Horde_Share_Kolab->constructFolderName() /datastore/DEVEL/framework/Share/lib/Horde/Share/Object/Kolab.php:232 28. Horde_Registry::appInit() /datastore/DEVEL/turba/index.php:14 29. Horde_Registry->pushApp() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:299 30. Horde_Registry->callAppMethod() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1601 31. call_user_func_array() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1201 32. Horde_Registry_Application->init() 33. Turba_Application->_init() /datastore/DEVEL/framework/Core/lib/Horde/Registry/Application.php:105 34. Turba::getConfigFromShares() /datastore/DEVEL/turba/lib/Application.php:114 35. Turba_Driver_Kolab->createShare() /datastore/DEVEL/turba/lib/Turba.php:564 36. Turba::createShare() /datastore/DEVEL/turba/lib/Driver/Kolab.php:975 37. Horde_Core_Share_Driver->newShare() /datastore/DEVEL/turba/lib/Turba.php:675 38. Horde_Core_Share_Driver->__call() /datastore/DEVEL/turba/lib/Turba.php:675 39. call_user_func_array() /datastore/DEVEL/framework/Core/lib/Horde/Core/Share/Driver.php:63 40. Horde_Share_Base->newShare() 41. Horde_Share_Object_Kolab->set() /datastore/DEVEL/framework/Share/lib/Horde/Share/Base.php:419 42. Horde_Share_Kolab->constructFolderName() /datastore/DEVEL/framework/Share/lib/Horde/Share/Object/Kolab.php:232 43. Horde_Kolab_Storage_List_Tools->getNamespace() /datastore/DEVEL/framework/Share/lib/Horde/Share/Kolab.php:187 44. Horde_Kolab_Storage_Driver_Decorator_Timer->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/List/Tools.php:276 45. Horde_Kolab_Storage_Driver_Decorator_Base->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Timer.php:187 46. Horde_Kolab_Storage_Driver_Decorator_Log->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Base.php:310 47. Horde_Kolab_Storage_Driver_Decorator_Base->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Log.php:262 48. Horde_Kolab_Storage_Driver_Imap->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Base.php:310 49. Horde_Registry::appInit() /datastore/DEVEL/turba/index.php:14 50. Horde_Registry->pushApp() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:299 51. Horde_Registry->callAppMethod() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1601 52. call_user_func_array() /datastore/DEVEL/framework/Core/lib/Horde/Registry.php:1201 53. Horde_Registry_Application->init() 54. Turba_Application->_init() /datastore/DEVEL/framework/Core/lib/Horde/Registry/Application.php:105 55. Turba::getConfigFromShares() /datastore/DEVEL/turba/lib/Application.php:114 56. Turba_Driver_Kolab->createShare() /datastore/DEVEL/turba/lib/Turba.php:564 57. Turba::createShare() /datastore/DEVEL/turba/lib/Driver/Kolab.php:975 58. Horde_Core_Share_Driver->newShare() /datastore/DEVEL/turba/lib/Turba.php:675 59. Horde_Core_Share_Driver->__call() /datastore/DEVEL/turba/lib/Turba.php:675 60. call_user_func_array() /datastore/DEVEL/framework/Core/lib/Horde/Core/Share/Driver.php:63 61. Horde_Share_Base->newShare() 62. Horde_Share_Object_Kolab->set() /datastore/DEVEL/framework/Share/lib/Horde/Share/Base.php:419 63. Horde_Share_Kolab->constructFolderName() /datastore/DEVEL/framework/Share/lib/Horde/Share/Object/Kolab.php:232 64. Horde_Kolab_Storage_List_Tools->getNamespace() /datastore/DEVEL/framework/Share/lib/Horde/Share/Kolab.php:187 65. Horde_Kolab_Storage_Driver_Decorator_Timer->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/List/Tools.php:276 66. Horde_Kolab_Storage_Driver_Decorator_Base->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Timer.php:187 67. Horde_Kolab_Storage_Driver_Decorator_Log->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Base.php:310 68. Horde_Kolab_Storage_Driver_Decorator_Base->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Log.php:262 69. Horde_Kolab_Storage_Driver_Imap->getNamespace() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Decorator/Base.php:310 70. Horde_Imap_Client_Base->login() /datastore/DEVEL/framework/Kolab_Storage/lib/Horde/Kolab/Storage/Driver/Imap.php:295 71. Horde_Imap_Client_Socket->_login() /datastore/DEVEL/framework/Imap_Client/lib/Horde/Imap/Client/Base.php:784 ---------------------------------------- What I'm wondering about: Does the failed CRAM-MD5 authentication kill the stored password or is a "lost password" the cause for the failing CRAM-MD5 authentication? ;) I'll try to add debug code to the CRAM-MD5 code to log the password it uses. Let's see if that sheds any light on this. Other ideas welcome ;) Cheers, Thomas