[imp] Imp LDAP Error: [listMailboxes] IMAP error reported by server

Sun Feb 8 17:00:09 UTC 2015

We are using the latest debian packages for these apps:

- Cyrus version 2.4.17+caldav~beta10-16
- PHP 5.6.5 (updated yesterday before problem started, changes below)
- Horde 5.2.1, Imp 6.2.2

The PHP updates were described as follows:

php5 (5.6.5+dfsg-1) unstable; urgency=medium

   * New upstream version 5.6.5+dfsg
   * Security vulnerabilities fixed:
    + Core
     - Fixed bug #68710 (Use After Free Vulnerability in PHP's
       unserialize()). (CVE-2015-0231)
    + CGI:
     - Fixed bug #68618 (out of bounds read crashes
       php-cgi). (CVE-2014-9427)
    + EXIF:
     - Fixed bug #68799: Free called on unitialized
       pointer. (CVE-2015-0232)
   * Update patches for 5.6.5 release

The problem is that now when you login to Horde, the portal comes up 
with an empty mail block (ie, no inbox display) BUT the block with 
Newest Unseen Messages is fine.  If you try to go to Imp to see your 
email you are logged out with the onscreen error "IMAP error reported by 
server."

IMAP access using other mail clients like Thunderbird and K9 on my phone 
works fine.

I think the problem is somewhere in the new PHP 5.6.5, but so far I have 
not been able to find any sort of smoking gun that points to exactly 
which change is the problem.

Syslog in Horde debug mode reports the lines below for HORDE [imp] and 
Cyrus. You can see the original login success for IMAP, then several 
failures of 'listMailBoxes' as I navigated from the opening portal, to 
the config to enable debug logging and back to the portal to click on 
the Mail portal block and document the error.  I only included the 
relevant Cyrus & Horde log entries (there are a LOT of them) for the 
initial login + failure and the debug failure.

FYI, the Cyrus "fetching user_deny.db entry for.." log entries are 
normal.  I am not a Cyrus guru so I am not sure why they are there, but 
they have always been there before this issue started and are also there 
when checking my IMAP email with Thunderbird or K9.

Opening log lines after initial login
------------------------------
Relevant Cyrus log entries
2015-02-08T09:00:11.838713-06:00 yorick cyrus/imap[12713]: accepted 
connection
2015-02-08T09:00:11.846537-06:00 yorick cyrus/imap[12713]: imapd:Loading 
hard-coded DH parameters
2015-02-08T09:00:11.896982-06:00 yorick cyrus/imap[12713]: skiplist: 
checkpointed /var/lib/cyrus/tls_sessions.db (0 records, 144 bytes) in 0 
seconds
2015-02-08T09:00:11.898033-06:00 yorick cyrus/imap[12713]: TLS Server 
Name Indication (SNI) Extension: "yorick.ironicdesign.com"
2015-02-08T09:00:11.901231-06:00 yorick cyrus/imap[12713]: SSL_accept() 
incomplete -> wait
2015-02-08T09:00:11.936647-06:00 yorick cyrus/imap[12713]: SSL_accept() 
succeeded -> done
2015-02-08T09:00:11.936718-06:00 yorick cyrus/imap[12713]: starttls: 
TLSv1.2 with cipher ECDHE-RSA-AES128-SHA (128/128 bits new) no 
authentication
2015-02-08T09:00:11.955812-06:00 yorick cyrus/imap[12713]: fetching 
user_deny.db entry for 'andydorman at comehome.net'
2015-02-08T09:00:11.955996-06:00 yorick cyrus/imap[12713]: login: 
yorick.ironicdesign.com [192.168.0.23] andydorman at comehome.net PLAIN+TLS 
User logged in SESSIONID=<cyrus-12713-1423407611-1>
2015-02-08T09:00:11.956166-06:00 yorick cyrus/imap[12713]: fetching 
user_deny.db entry for 'andydorman at comehome.net'

Associated Horde log entry
2015-02-08T09:00:12.786789-06:00 yorick HORDE: [imp] Login success for 
andydorman at comehome.net (50.130.11.148) to 
{imap://yorick.ironicdesign.com/} [pid 12953 on line 157 of 
"/usr/share/horde/imp/lib/Auth.php"]

Relevant Cyrus log entries
2015-02-08T09:00:21.531238-06:00 yorick cyrus/imap[12713]: fetching 
user_deny.db entry for 'andydorman at comehome.net'
2015-02-08T09:00:22.979405-06:00 yorick cyrus/imap[12713]: open: user 
andydorman at comehome.net opened INBOX
2015-02-08T09:00:22.983673-06:00 yorick cyrus/imap[12713]: SQUAT 
returned 278 messages

Associated Horde log entry
2015-02-08T09:00:21.540598-06:00 yorick HORDE: [imp] [listMailboxes] 
IMAP error reported by server. [pid 12953 on line 726 of 
"/usr/share/horde/imp/lib/Imap.php"]

Horde imp log lines while navigating back to portal
------------------------------
2015-02-08T09:01:24.916679-06:00 yorick HORDE: [imp] [listMailboxes] 
IMAP error reported by server. [pid 13019 on line 726 of 
"/usr/share/horde/imp/lib/Imap.php"]
2015-02-08T09:02:21.096915-06:00 yorick HORDE: [imp] Load config file 
(conf.php; app: imp) [pid 13019 on line 109 of 
"/usr/share/php/Horde/Registry/Loadconfig.php"]
2015-02-08T09:02:21.117365-06:00 yorick HORDE: [imp] Load config file 
(hooks.php; app: imp) [pid 13019 on line 109 of 
"/usr/share/php/Horde/Registry/Loadconfig.php"]

Log lines after Horde debug loging enabled
------------------------------

Relevant Cyrus log entries
2015-02-08T09:02:32.456729-06:00 yorick cyrus/imap[12975]: accepted 
connection
2015-02-08T09:02:32.465951-06:00 yorick cyrus/imap[12975]: imapd:Loading 
hard-coded DH parameters
2015-02-08T09:02:32.573783-06:00 yorick cyrus/imap[12975]: skiplist: 
checkpointed /var/lib/cyrus/tls_sessions.db (0 records, 144 bytes) in 0 
seconds
2015-02-08T09:02:32.575039-06:00 yorick cyrus/imap[12975]: TLS Server 
Name Indication (SNI) Extension: "yorick.ironicdesign.com"
2015-02-08T09:02:32.578300-06:00 yorick cyrus/imap[12975]: SSL_accept() 
incomplete -> wait
2015-02-08T09:02:32.616723-06:00 yorick cyrus/imap[12975]: SSL_accept() 
succeeded -> done
2015-02-08T09:02:32.616741-06:00 yorick cyrus/imap[12975]: starttls: 
TLSv1.2 with cipher ECDHE-RSA-AES128-SHA (128/128 bits new) no 
authentication
2015-02-08T09:02:32.625185-06:00 yorick cyrus/imap[12975]: fetching 
user_deny.db entry for 'andydorman at comehome.net'
2015-02-08T09:02:32.663492-06:00 yorick cyrus/imap[12975]: login: 
yorick.ironicdesign.com [192.168.0.23] andydorman at comehome.net PLAIN+TLS 
User logged in SESSIONID=<cyrus-12975-1423407752-1>
2015-02-08T09:02:32.663630-06:00 yorick cyrus/imap[12975]: fetching 
user_deny.db entry for 'andydorman at comehome.net'
2015-02-08T09:02:32.722465-06:00 yorick cyrus/imap[12975]: USAGE 
andydorman at comehome.net user: 0.012000 sys: 0.008000

Associated Horde log entries
2015-02-08T09:02:32.716420-06:00 yorick HORDE: [imp] [listMailboxes] 
IMAP error reported by server. [pid 13019 on line 726 of 
"/usr/share/horde/imp/lib/Imap.php"]
2015-02-08T09:02:32.716713-06:00 yorick HORDE:  1. require() 
/usr/share/horde/admin/config/index.php:462#012 2. 
Horde_Notification_Handler->notify() 
/usr/share/horde/templates/admin/menu.inc:22#012 3. 
Horde_Core_Notification_Handler_Decorator_Base->notify() 
/usr/share/php/Horde/Notification/Handler.php:317#012 4. 
IMP_Notification_Handler_Decorator_NewmailNotify->_notify() 
/usr/share/php/Horde/Core/Notification/Handler/Decorator/Base.php:100#012 5. 
Horde_Injector->getInstance() 
/usr/share/horde/imp/lib/Notification/Handler/Decorator/NewmailNotify.php:67#012 
6. Horde_Injector->createInstance() 
/usr/share/php/Horde/Injector.php:258#012 7. 
Horde_Injector_Binder_Factory->create() 
/usr/share/php/Horde/Injector.php:224#012 8. IMP_Factory_Ftree->create() 
/usr/share/php/Horde/Injector/Binder/Factory.php:111#012 9. 
IMP_Ftree->__construct() 
/usr/share/horde/imp/lib/Factory/Ftree.php:47#01210. IMP_Ftree->init() 
/usr/share/horde/imp/lib/Ftree.php:111#01211. 
IMP_Ftree_Account_Imap->getList() 
/usr/share/horde/imp/lib/Ftree.php:178#01212. IMP_Imap->listMailboxes() 
/usr/share/horde/imp/lib/Ftree/Account/Imap.php:102#01213. 
IMP_Imap->__call() 
/usr/share/horde/imp/lib/Ftree/Account/Imap.php:102#01214. require() 
/usr/share/horde/admin/config/index.php:462#01215. 
Horde_Notification_Handler->notify() 
/usr/share/horde/templates/admin/menu.inc:22#01216. 
Horde_Core_Notification_Handler_Decorator_Base->notify() 
/usr/share/php/Horde/Notification/Handler.php:317#01217. 
IMP_Notification_Handler_Decorator_NewmailNotify->_notify() 
/usr/share/php/Horde/Core/Notification/Handler/Decorator/Base.php:100#01218. 
Horde_Injector->getInstance() 
/usr/share/horde/imp/lib/Notification/Handler/Decorator/NewmailNotify.php:67#01219. 
Horde_Injector->createInstance() 
/usr/share/php/Horde/Injector.php:258#01220. 
Horde_Injector_Binder_Factory->create() 
/usr/share/php/Horde/Injector.php:224#01221. IMP_Factory_Ftree->create() 
/usr/share/php/Horde/Injector/Binder/Factory.php:111#01222. 
IMP_Ftree->__construct() 
/usr/share/horde/imp/lib/Factory/Ftree.php:47#01223. IMP_Ftree->init() 
/usr/share/horde/imp/lib/Ftree.php:111#01224. 
IMP_Ftree_Account_Imap->getList() 
/usr/share/horde/imp/lib/Ftree.php:178#01225. IMP_Imap->listMailboxes() 
/usr/share/horde/imp/lib/Ftree/Account/Imap.php:102#01226. 
IMP_Imap->__call() 
/usr/share/horde/imp/lib/Ftree/Account/Imap.php:102#01227. 
call_user_func_array() /usr/share/horde/imp/lib/Imap.php:718#01228. 
Horde_Imap_Client_Base->listMailboxes()#01229. 
Horde_Imap_Client_Socket->_listMailboxes() 
/usr/share/php/Horde/Imap/Client/Base.php:1367#01230. 
Horde_Imap_Client_Socket->_getMailboxList() 
/usr/share/php/Horde/Imap/Client/Socket.php:1272#01231. 
Horde_Imap_Client_Socket->_sendCmd() 
/usr/share/php/Horde/Imap/Client/Socket.php:1430#01232. 
Horde_Imap_Client_Socket->_sendCmdChunk() 
/usr/share/php/Horde/Imap/Client/Socket.php:4135#01233. 
Horde_Imap_Client_Socket->_getLine() 
/usr/share/php/Horde/Imap/Client/Socket.php:4205

In summary: I think this is being caused by the PHP update yesterday. 
Cyrus did not change and is working fine with other clients and Horde 
did not change either.  If anyone has any ideas about what I could check 
for in PHP, it would be greatly appreciated.

-- 
Andy Dorman