[imp] Imp LDAP Error: [listMailboxes] IMAP error reported by server
Andy Dorman
adorman at ironicdesign.com
Sun Feb 8 22:34:14 UTC 2015
On 02/08/2015 11:00 AM, Andy Dorman wrote:
> 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.
>
I see where the error "IMAP error reported by server" is generated in
Horde/Imap/Client/Socket.php . But I have so far been unable to track
down a way to determine exactly what IMAP call is generating the error.
The error message indicates "listMailboxes" is the problem call, and the
logs indicate SSL/TLS negotiation and authentication is fine.
But when I manually connect to the IMAP server, I can list mailboxes
with no trouble as shown below.
openssl s_client -starttls imap -connect localhost:143
. OK Completed
a1 LOGIN andydorman at comehome.net mypassword
a1 OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxte QUOTA
MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN
MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SORT SORT=MODSEQ
SORT=DISPLAY THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE
LIST-EXTENDED WITHIN QRESYNC SCAN XLIST X-REPLICATION URLAUTH
URLAUTH=BINARY LOGINDISABLED AUTH=PLAIN AUTH=LOGIN COMPRESS=DEFLATE
IDLE] User logged in SESSIONID=<cyrus-23123-1423426833-1>
a2 LIST "" "*"
I get the full list of all mailboxes
...
a2 OK Completed (0.002 secs 53 calls)
a3 EXAMINE INBOX
...
a3 OK [READ-ONLY] Completed
a4 LOGOUT
* BYE LOGOUT received
a4 OK Completed
So I am now trying to find exactly what command is being sent to Cyrus
to request the list of mailboxes to see if I can recreate the problem
with a manual tls imap connection.
--
Andy Dorman
More information about the imp
mailing list