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

Mon Feb 9 00:03:08 UTC 2015

Horde doesn't use php-imap at all. 

-mike
Sent from mobile. 

From: Andy Dorman <adorman at ironicdesign.com>
Sent: Feb 8, 2015 6:17 PM
To: imp at lists.horde.org
Subject: Re: [imp] Imp LDAP Error: [listMailboxes] IMAP error reported  
by server

> 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
>
> -- 
> imp mailing list
> Frequently Asked Questions: http://wiki.horde.org/FAQ
> To unsubscribe, mail: imp-unsubscribe at lists.horde.org
>