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 'andydor...@comehome.net'
2015-02-08T09:00:11.955996-06:00 yorick cyrus/imap[12713]: login:
yorick.ironicdesign.com [192.168.0.23] andydor...@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 'andydor...@comehome.net'
Associated Horde log entry
2015-02-08T09:00:12.786789-06:00 yorick HORDE: [imp] Login success for
andydor...@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 'andydor...@comehome.net'
2015-02-08T09:00:22.979405-06:00 yorick cyrus/imap[12713]: open: user
andydor...@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 'andydor...@comehome.net'
2015-02-08T09:02:32.663492-06:00 yorick cyrus/imap[12975]: login:
yorick.ironicdesign.com [192.168.0.23] andydor...@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 'andydor...@comehome.net'
2015-02-08T09:02:32.722465-06:00 yorick cyrus/imap[12975]: USAGE
andydor...@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.
--
Andy Dorman
--
imp mailing list
Frequently Asked Questions: http://wiki.horde.org/FAQ
To unsubscribe, mail: imp-unsubscr...@lists.horde.org
