Some time ago, we got "lucky" and this happened on one of our test systems as well. Before, it had only occured on the "production" server, where Horde's debug level is lower and we cannot experiment like we can on the test system. I had always considered this to be a problem of the IMAP proxy, but now it seems to me it might be Horde's IMAP client causing this. However, it's still very difficult to see what actually is the cause of this - I couldn't really find a way to debug this. Maybe someone can give me a hint?
When the problem occured, I did several tests on the system to rule out different areas where the problem might be located. For one, restarting the IMAP proxy didn't help. Also, the problem did persist through the reload/restart of the Apache server running Horde, so it can't be some strange bug with the opcode cache or something like that. Thirdly, the problem did not occur when using (a) another browser from the same PC to connect to Horde using another username to login and (b) using the same username as before to login. So it seems the problem is somehow tied to a specific session within Horde.
Using strace, I was able to record the IMAP session (from the IMAP proxy's point of view) when the problem occured:
5229 set_robust_list(0x7fd9e26139e0, 24) = 05229 write(8, "* OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE XIMAPPROXY] foobar123.uni-koeln.de Cyrus IMAP v2.4.17-Invoca-RPM-2.4.17-6.RRZK server ready\r\n", 140) = 140 5229 poll([{fd=8, events=POLLIN}], 1, 1800000) = 1 ([{fd=8, revents=POLLIN}])
5229 read(8, "1 CAPABILITY\r\n", 8192) = 145229 write(8, "* 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 URLAUTH URLAUTH=BINARY X-NETSCAPE COMPRESS=DEFLATE XIMAPPROXY\r\n1 OK Completed\r\n", 383) = 383 5229 poll([{fd=8, events=POLLIN}], 1, 1800000) = 1 ([{fd=8, revents=POLLIN}])
5229 read(8, "", 8192) = 05229 sendto(3, "<20>Nov 9 15:53:10 in.imapproxyd[2739]: IMAP_Line_Read(): connection closed prematurely. sd [8]. (1513)", 104, MSG_NOSIGNAL, NULL, 0) = 104
5229 close(8) = 0 5229 madvise(0x7fd9e1c13000, 10465280, MADV_DONTNEED) = 0 5229 _exit(0) = ? 5229 +++ exited with 0 +++So in this case, only the first IMAP command ("1 CAPABILITY") is sent properly. After that, there is no data sent at all - no IMAP tag, to end-of-line characters. Here's what Horde's logfile had to say around that time:
2015-11-09T15:53:10+01:00 WARN: HORDE [imp] [openMailbox] Mail server denied authentication. [pid 29472 on line 730 of "[...]/imp/lib/Imap.php"] 2015-11-09T15:53:10+01:00 DEBUG: HORDE 1. Horde_Core_Ajax_Application->doAction() [...]/services/ajax.php:61
2. call_user_func() /usr/share/pear/Horde/Core/Ajax/Application.php:175 3. IMP_Ajax_Application_Handler_Dynamic->dynamicInit()4. Horde_Core_Ajax_Application->callAction() [...]/imp/lib/Ajax/Application/Handler/Dynamic.php:442
5. call_user_func() /usr/share/pear/Horde/Core/Ajax/Application.php:257 6. IMP_Ajax_Application_Handler_Common->viewPort()7. IMP_Ajax_Application->viewPortData() [...]/imp/lib/Ajax/Application/Handler/Common.php:108 8. IMP_Ajax_Application_ListMessages->listMessages() [...]/imp/lib/Ajax/Application.php:262 9. IMP_Imap->openMailbox() [...]/imp/lib/Ajax/Application/ListMessages.php:126
10. IMP_Imap->__call() [...]/imp/lib/Ajax/Application/ListMessages.php:126 11. Horde_Core_Ajax_Application->doAction() [...]/services/ajax.php:61 12. call_user_func() /usr/share/pear/Horde/Core/Ajax/Application.php:175 13. IMP_Ajax_Application_Handler_Dynamic->dynamicInit()14. Horde_Core_Ajax_Application->callAction() [...]/imp/lib/Ajax/Application/Handler/Dynamic.php:442
15. call_user_func() /usr/share/pear/Horde/Core/Ajax/Application.php:257 16. IMP_Ajax_Application_Handler_Common->viewPort()17. IMP_Ajax_Application->viewPortData() [...]/imp/lib/Ajax/Application/Handler/Common.php:108 18. IMP_Ajax_Application_ListMessages->listMessages() [...]/imp/lib/Ajax/Application.php:262 19. IMP_Imap->openMailbox() [...]/imp/lib/Ajax/Application/ListMessages.php:126
20. IMP_Imap->__call() [...]/imp/lib/Ajax/Application/ListMessages.php:126 21. call_user_func_array() [...]/imp/lib/Imap.php:718 22. Horde_Imap_Client_Base->openMailbox()23. Horde_Imap_Client_Base->login() /usr/share/pear/Horde/Imap/Client/Base.php:1024 24. Horde_Imap_Client_Socket->_login() /usr/share/pear/Horde/Imap/Client/Base.php:831
A bit later, I recorded another IMAP session of the same user, which is a bit different but still very strange (again, an strace from the IMAP proxy):
[pid 7234] set_robust_list(0x7fd9e26139e0, 24) = 0[pid 7234] write(8, "* OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE XIMAPPROXY] foobar123.uni-koeln.de Cyrus IMAP v2.4.17-Invoca-RPM-2.4.17-6.RRZK server ready\r\n", 140) = 140 [pid 7234] poll([{fd=8, events=POLLIN}], 1, 1800000) = 1 ([{fd=8, revents=POLLIN}])
[pid 7234] read(8, "1 CAPABILITY\r\n", 8192) = 14[pid 7234] write(8, "* 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 URLAUTH URLAUTH=BINARY X-NETSCAPE COMPRESS=DEFLATE XIMAPPROXY\r\n1 OK Completed\r\n", 383) = 383 [pid 7234] poll([{fd=8, events=POLLIN}], 1, 1800000) = 1 ([{fd=8, revents=POLLIN}])
[pid 7234] read(8, "\r\n", 8192) = 2 [pid 7234] write(8, "* BAD Invalid tag\r\n", 19) = 19[pid 7234] poll([{fd=8, events=POLLIN}], 1, 1800000) = 1 ([{fd=8, revents=POLLIN}])
[pid 7234] read(8, "\4", 8192) = 1 [pid 7234] read(8, "\r\n", 8191) = 2 [pid 7234] write(8, "* BAD Invalid tag\r\n", 19) = 19[pid 7234] poll([{fd=8, events=POLLIN}], 1, 1800000) = 1 ([{fd=8, revents=POLLIN}])
[pid 7234] read(8, "2 LOGOUT\r\n", 8192) = 10 [pid 7234] write(8, "* BYE LOGOUT received\r\n2 OK Completed\r\n", 39) = 39 [pid 7234] close(8) = 0 [pid 7234] madvise(0x7fd9e1c13000, 10465280, MADV_DONTNEED) = 0 [pid 7234] _exit(0) = ? [pid 7234] +++ exited with 0 +++Here, an empty command (but including end-of-line markers) is being sent after the "CAPABILITY" command, and then there seems to be an EOF character plus the end-of-line marks. Very strange, don't you think?
I did also try to use strace on the Apache process with the PHP processes attached, but that logfile is huge (there are lots of syscalls going on) and I don't know what to look for, so it's bit of a needle and haystack problem there.
Any suggestions on how to further investigate this problem would be very much appreciated.
Jens
smime.p7s
Description: S/MIME Cryptographic Signature
-- imp mailing list Frequently Asked Questions: http://wiki.horde.org/FAQ To unsubscribe, mail: imp-unsubscr...@lists.horde.org
