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 '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.
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 andydor...@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-unsubscr...@lists.horde.org
