[Tickets #13274] Sporadic IMAP login errors

noreply at bugs.horde.org noreply at bugs.horde.org
Fri Jun 20 09:08:32 UTC 2014 

DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.

Ticket URL: http://bugs.horde.org/ticket/13274
------------------------------------------------------------------------------
  Ticket             | 13274
  Created By         | Thomas Jarosch <thomas.jarosch at intra2net.com>
  Summary            | Sporadic IMAP login errors
  Queue              | Horde Framework Packages
  Version            | Git master
  Type               | Bug
  State              | Unconfirmed
  Priority           | 1. Low
  Milestone          |
  Patch              |
  Owners             |
------------------------------------------------------------------------------


Thomas Jarosch <thomas.jarosch at intra2net.com> (2014-06-20 09:08) wrote:

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

More information about the bugs mailing list