[imp] Imp LDAP Error: [listMailboxes] IMAP error reported by server
Andy Dorman
adorman at ironicdesign.com
Sun Feb 8 23:17:13 UTC 2015
On 02/08/2015 05:00 PM, Andy Dorman wrote:
> 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.
>
DOHHH! I mean a bug report for php-IMAP, not php-ldap. The issue (I
think) is with php-imap or something in php-fpm that changed in 5.6.5 to
cause our use of php-imap list command to return either NO or BAD.
--
Andy Dorman
More information about the imp
mailing list