[imp] Imp LDAP Error: [listMailboxes] IMAP error reported by server
Andy Dorman
adorman at ironicdesign.com
Sun Feb 8 23:00:12 UTC 2015
On 02/08/2015 04:34 PM, Andy Dorman wrote:
> 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.
>
OK, I am NOT a expert PHP programmer, but if someone would pass along a
"horde friendly" log line I could put in
Horde/Imap/Client/Socket.php->_sendCmd that could log the exact $cmd
command or pipeline object that is being sent to Cyrus via php-imap, I
would be happy to put it on our dev server and to document the results
when we get this failure.
Specific command input and output results would definitely help in
filing a bug report for php-ldap. I really want to show that Horde is
passing a perfectly legitimate command to php-imap and that command
works fine when passed manually but fails when passed via php-imap.
--
Andy Dorman
More information about the imp
mailing list