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

Andy Dorman adorman at ironicdesign.com
Mon Feb 9 13:41:11 UTC 2015 

> 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
>>
> On 02/08/2015 06:03 PM, Michael J Rubinsky wrote:> Horde doesn't use php-imap at all.
>>
>> -mike
>> Sent from mobile.
>>

OK, that is good to know and explains why I have not been able to find 
any calls to it.

-- 
Andy Dorman

More information about the imp mailing list