[imp] IMAP sessions not starting correctly

Tue Nov 24 17:16:15 UTC 2015

We're using Horde along with the IMAP Proxy originally developed for the 
Squirrelmail project.  While this works out quite well most of the time, 
there are, however, occasional problems with IMAP sessions not working 
properly.  In the IMAP proxy's log file, there would be a line reading 
"IMAP_Line_Read(): connection closed prematurely".  Since we were not 
able to forcefully produce this behavior, it has always been hard to debug.

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) = 0
5229  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) = 14
5229  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)                 = 0
5229  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

-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 4986 bytes
Desc: S/MIME Cryptographic Signature
URL: <http://lists.horde.org/archives/imp/attachments/20151124/0ab10591/attachment.bin>