[imp] Login via imp successful but list mboxes leads to immediate logout

Thu Nov 12 12:51:19 UTC 2015

On 11.11.2015 17:46, Michael J Rubinsky wrote:
>
> Quoting Herbert Pophal <pophal at tubit.tu-berlin.de>:
>
>> Webmail Edition 5.1.3
>> IMP 6.2.2
>> PHP 5.5.24/5.6.8 (fcgid connected)
>> imap server: RHEL 6.6
>> cyrus-imapd-2.3.16-6.el6_2.5

NOPE: 2.3.16-13.el6_6, Sorry

>>
>> Using these PHP versions, login (via imp) works, and horde portal
>> shows up. Clicking Mail leads to immediate logout with message: IMAP
>> error reported by server.
>>
>> logfile says:
>> Nov 11 12:15:27 webhaupt-test HORDE: [imp] Login success for blafasel
>> (172.26.16.4) (forwarded for [130.149.2.58]) to
>> {imap://mailbox.tu-berlin.de/} [pid 24577 on line 157 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/imp/lib/Auth.php"]
>>
>> Nov 11 12:15:28 webhaupt-test HORDE: [imp] [listMailboxes] IMAP error
>> reported by server. [pid 24577 on line 726 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/imp/lib/Imap.php"]
>>
>> Nov 11 12:15:28 webhaupt-test HORDE: [imp] [listMailboxes] IMAP error
>> reported by server. [pid 24577 on line 726 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/imp/lib/Imap.php"]
>>
>> Nov 11 12:15:29 webhaupt-test HORDE: [imp] [listMailboxes] IMAP error
>> reported by server. [pid 24577 on line 726 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/imp/lib/Imap.php"]
>>
>> Nov 11 12:15:34 webhaupt-test HORDE: [imp] [listMailboxes] IMAP error
>> reported by server. [pid 24577 on line 726 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/imp/lib/Imap.php"]
>>
>> Nov 11 12:15:34 webhaupt-test HORDE: [imp] [listMailboxes] IMAP error
>> reported by server. [pid 24577 on line 726 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/imp/lib/Imap.php"]
>>
>> Nov 11 12:15:34 webhaupt-test HORDE: [imp] IMAP error reported by
>> server. [pid 24577 on line 606 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/imp/lib/Application.php"]
>>
>> Nov 11 12:15:34 webhaupt-test HORDE: [horde] User opha4000 logged out
>> of Horde (172.26.16.4) [pid 24577 on line 107 of
>> "/afs/tu-berlin.de/units/tubit/www/horde-test.tubit/htdocs/horde-5/login.php"]
>>
>>
>> Preferences/Mail/Personal Information logs out as well, with same
>> message.
>>
>>
>> PHP 5.5.18 works so far.
>> Any hints, except horde upgrade?
>
> An IMAP log might be useful as well. See imp/config/backends.php

Thanks for that hint. I originally considered to include an excerpt from 
cyrus log, but this didn't tell me anything useful.

This looks suspicious: "S: 6 BAD Unexpected extra arguments to Lsub", 
and that the output lacks "LIST" commands.

PHP 5.5.24 (crashes):
------------------------------
 >> Thu, 12 Nov 2015 10:30:36 +0100
 >> Connection to: imap://mailbox.tu-berlin.de/
 >> Server connection took 0.0076 seconds.
S: * OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ STARTTLS 
LOGINDISABLED AUTH=GSSAPI SASL-IR COMPRESS=DEFLATE] mail.tu-berlin.de 
Cyrus IMAP Murder v2.3.16-Fedora-RPM-2.3.16-13.el6_6 server ready
C: 1 STARTTLS
S: 1 OK Begin TLS negotiation now
 >> Command 1 took 0.0018 seconds.
 >> Successfully completed TLS negotiation.
C: 2 CAPABILITY
S: * CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ AUTH=LOGIN 
AUTH=PLAIN AUTH=GSSAPI SASL-IR COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA 
MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN 
MULTIAPPEND BINARY SORT SORT=MODSEQ THREAD=ORDEREDSUBJECT 
THREAD=REFERENCES ANNOTATEMORE CATENATE CONDSTORE SCAN IDLE LISTEXT 
LIST-SUBSCRIBED X-NETSCAPE URLAUTH
S: 2 OK Completed
 >> Command 2 took 0.0026 seconds.
C: 3 AUTHENTICATE PLAIN [INITIAL CLIENT RESPONSE (username: blafasel)]
S: 3 OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ LOGINDISABLED 
COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE 
UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT 
SORT=MODSEQ THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE 
CATENATE CONDSTORE SCAN IDLE LISTEXT LIST-SUBSCRIBED X-NETSCAPE URLAUTH] 
Success (tls protection)
 >> Command 3 took 0.1761 seconds.
 >> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
C: 4 LOGOUT
S: * BYE LOGOUT received
S: 4 OK Completed
 >> Command 4 took 0.001 seconds.
------------------------------
 >> Thu, 12 Nov 2015 10:30:37 +0100
 >> Connection to: imap://mailbox.tu-berlin.de/
 >> Server connection took 0.003 seconds.
S: * OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ STARTTLS 
LOGINDISABLED AUTH=GSSAPI SASL-IR COMPRESS=DEFLATE] mail.tu-berlin.de 
Cyrus IMAP Murder v2.3.16-Fedora-RPM-2.3.16-13.el6_6 server ready
C: 1 STARTTLS
S: 1 OK Begin TLS negotiation now
 >> Command 1 took 0.0011 seconds.
 >> Successfully completed TLS negotiation.
C: 2 [INITIAL CLIENT RESPONSE (username: blafasel)]
S: +
C: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
S: 2 OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ LOGINDISABLED 
COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE 
UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT 
SORT=MODSEQ THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE 
CATENATE CONDSTORE SCAN IDLE LISTEXT LIST-SUBSCRIBED X-NETSCAPE URLAUTH] 
Success (tls protection)
 >> Command 2 took 0.0957 seconds.
 >> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
C: 3 NAMESPACE
S: * NAMESPACE (("" "/")) (("Other Users/" "/")) (("Shared Folders/" "/"))
S: 3 OK Completed
 >> Command 3 took 0.005 seconds.
C: 4 LSUB "" INBOX
C: 5 LSUB "" *
C: 6 LSUB "" "Other Users/*"""
C: 7 LSUB "" "Shared Folders/*"""
S: * LSUB (\Noinferiors) "/" "INBOX"
S: 4 OK Completed (0.010 secs 0 calls)
 >> Command 4 took 0.1241 seconds.
S: * LSUB (\Noinferiors) "/" "INBOX"
S: * LSUB () "/" "Drafts"
S: * LSUB () "/" "Sent"
S: * LSUB () "/" "Trash"
S: * LSUB () "/" "persabt"
S: * LSUB () "/" "shuttle"
S: * LSUB () "/" "spam"
S: * LSUB () "/" "spektrum"
S: * LSUB () "/" "tc"
S: * LSUB () "/" "tubit"
S: 5 OK Completed (0.000 secs 0 calls)
 >> Command 5 took 0.1269 seconds.
S: 6 BAD Unexpected extra arguments to Lsub
 >> Command 6 took 0.1269 seconds.
S: 7 BAD Unexpected extra arguments to Lsub
 >> Command 7 took 0.1303 seconds.
C: 8 LSUB "" INBOX
C: 9 LSUB "" *
C: 10 LSUB "" "Other Users/*"""
C: 11 LSUB "" "Shared Folders/*"""
S: * LSUB (\Noinferiors) "/" "INBOX"
S: 8 OK Completed (0.000 secs 0 calls)
 >> Command 8 took 0.0018 seconds.
S: * LSUB (\Noinferiors) "/" "INBOX"
S: * LSUB () "/" "Drafts"
S: * LSUB () "/" "Sent"
S: * LSUB () "/" "Trash"
S: * LSUB () "/" "persabt"
S: * LSUB () "/" "shuttle"
S: * LSUB () "/" "spam"
S: * LSUB () "/" "spektrum"
S: * LSUB () "/" "tc"
S: * LSUB () "/" "tubit"
S: 9 OK Completed (0.000 secs 0 calls)
 >> Command 9 took 0.0434 seconds.
S: 10 BAD Unexpected extra arguments to Lsub
 >> Command 10 took 0.0435 seconds.
S: 11 BAD Unexpected extra arguments to Lsub
 >> Command 11 took 0.0436 seconds.
C: 12 LSUB "" INBOX
C: 13 LSUB "" *
C: 14 LSUB "" "Other Users/*"""
C: 15 LSUB "" "Shared Folders/*"""
S: * LSUB (\Noinferiors) "/" "INBOX"
S: 12 OK Completed (0.000 secs 0 calls)
 >> Command 12 took 0.0018 seconds.
S: * LSUB (\Noinferiors) "/" "INBOX"
S: * LSUB () "/" "Drafts"
S: * LSUB () "/" "Sent"
S: * LSUB () "/" "Trash"
S: * LSUB () "/" "persabt"
S: * LSUB () "/" "shuttle"
S: * LSUB () "/" "spam"
S: * LSUB () "/" "spektrum"
S: * LSUB () "/" "tc"
S: * LSUB () "/" "tubit"
S: 13 OK Completed (0.000 secs 0 calls)
 >> Command 13 took 0.0036 seconds.
S: 14 BAD Unexpected extra arguments to Lsub
 >> Command 14 took 0.0434 seconds.
S: 15 BAD Unexpected extra arguments to Lsub
 >> Command 15 took 0.0437 seconds.
C: 16 LOGOUT
S: * BYE LOGOUT received
S: 16 OK Completed
 >> Command 16 took 0.001 seconds.
------------------------------
 >> Thu, 12 Nov 2015 10:33:57 +0100
 >> Connection to: imap://mailbox.tu-berlin.de/
 >> Server connection took 0.0048 seconds.
S: * OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ STARTTLS 
LOGINDISABLED AUTH=GSSAPI SASL-IR COMPRESS=DEFLATE] mail.tu-berlin.de 
Cyrus IMAP Murder v2.3.16-Fedora-RPM-2.3.16-13.el6_6 server ready
C: 1 STARTTLS
S: 1 OK Begin TLS negotiation now
 >> Command 1 took 0.0009 seconds.
 >> Successfully completed TLS negotiation.
C: 2 [INITIAL CLIENT RESPONSE (username: blafasel)]
S: +
C: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
S: 2 OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ LOGINDISABLED 
COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE 
UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT 
SORT=MODSEQ THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE 
CATENATE CONDSTORE SCAN IDLE LISTEXT LIST-SUBSCRIBED X-NETSCAPE URLAUTH] 
Success (tls protection)
 >> Command 2 took 0.1292 seconds.
 >> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
C: 3 NAMESPACE
S: * NAMESPACE (("" "/")) (("Other Users/" "/")) (("Shared Folders/" "/"))
S: 3 OK Completed
 >> Command 3 took 0.0017 seconds.
C: 4 LSUB "" INBOX
C: 5 LSUB "" *
C: 6 LSUB "" "Other Users/*"""
C: 7 LSUB "" "Shared Folders/*"""
S: * LSUB (\Noinferiors) "/" "INBOX"
S: 4 OK Completed (0.000 secs 0 calls)
 >> Command 4 took 0.0109 seconds.
S: * LSUB (\Noinferiors) "/" "INBOX"
S: * LSUB () "/" "Drafts"
S: * LSUB () "/" "Sent"
S: * LSUB () "/" "Trash"
S: * LSUB () "/" "persabt"
S: * LSUB () "/" "shuttle"
S: * LSUB () "/" "spam"
S: * LSUB () "/" "spektrum"
S: * LSUB () "/" "tc"
S: * LSUB () "/" "tubit"
S: 5 OK Completed (0.000 secs 0 calls)
 >> Command 5 took 0.0126 seconds.
S: 6 BAD Unexpected extra arguments to Lsub
 >> Command 6 took 0.052 seconds.
S: 7 BAD Unexpected extra arguments to Lsub
 >> Command 7 took 0.053 seconds.
C: 8 LOGOUT
S: * BYE LOGOUT received
S: 8 OK Completed
 >> Command 8 took 0.001 seconds.
------------------------------------------------------------------------------------------------

PHP 5.5.18 (imp page shows up):
------------------------------
 >> Thu, 12 Nov 2015 11:08:03 +0100
 >> Connection to: imap://mailbox.tu-berlin.de/
 >> Slow Command: 5.008 seconds
 >> Server connection took 5.008 seconds.
S: * OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ STARTTLS 
LOGINDISABLED AUTH=GSSAPI SASL-IR COMPRESS=DEFLATE] mail.tu-berlin.de 
Cyrus IMAP Murder v2.3.16-Fedora-RPM-2.3.16-13.el6_6 server ready
C: 1 STARTTLS
S: 1 OK Begin TLS negotiation now
 >> Command 1 took 0.0013 seconds.
 >> Successfully completed TLS negotiation.
C: 2 CAPABILITY
S: * CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ AUTH=PLAIN 
AUTH=GSSAPI AUTH=LOGIN SASL-IR COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA 
MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN 
MULTIAPPEND BINARY SORT SORT=MODSEQ THREAD=ORDEREDSUBJECT 
THREAD=REFERENCES ANNOTATEMORE CATENATE CONDSTORE SCAN IDLE LISTEXT 
LIST-SUBSCRIBED X-NETSCAPE URLAUTH
S: 2 OK Completed
 >> Command 2 took 0.0016 seconds.
C: 3 AUTHENTICATE PLAIN [INITIAL CLIENT RESPONSE (username: opha4000)]
S: 3 OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ LOGINDISABLED 
COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE 
UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT 
SORT=MODSEQ THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE 
CATENATE CONDSTORE SCAN IDLE LISTEXT LIST-SUBSCRIBED X-NETSCAPE URLAUTH] 
Success (tls protection)
 >> Command 3 took 0.0905 seconds.
 >> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
C: 4 LOGOUT
S: * BYE LOGOUT received
S: 4 OK Completed
 >> Command 4 took 0.001 seconds.
------------------------------
 >> Thu, 12 Nov 2015 11:08:09 +0100
 >> Connection to: imap://mailbox.tu-berlin.de/
 >> Server connection took 0.0046 seconds.
S: * OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ STARTTLS 
LOGINDISABLED AUTH=GSSAPI SASL-IR COMPRESS=DEFLATE] mail.tu-berlin.de 
Cyrus IMAP Murder v2.3.16-Fedora-RPM-2.3.16-13.el6_6 server ready
C: 1 STARTTLS
S: 1 OK Begin TLS negotiation now
 >> Command 1 took 0.001 seconds.
 >> Successfully completed TLS negotiation.
C: 2 [INITIAL CLIENT RESPONSE (username: opha4000)]
S: +
C: b3BoYTQwMDAAb3BoYTQwMDAAbzp3cTM1VHJh
S: 2 OK [CAPABILITY IMAP4 IMAP4rev1 LITERAL+ ID 
MUPDATE=mupdate://mupdate-2-febe.intern.tu-berlin.de/ LOGINDISABLED 
COMPRESS=DEFLATE ACL RIGHTS=kxte QUOTA MAILBOX-REFERRALS NAMESPACE 
UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY SORT 
SORT=MODSEQ THREAD=ORDEREDSUBJECT THREAD=REFERENCES ANNOTATEMORE 
CATENATE CONDSTORE SCAN IDLE LISTEXT LIST-SUBSCRIBED X-NETSCAPE URLAUTH] 
Success (tls protection)
 >> Command 2 took 0.0529 seconds.
 >> CACHE: Using the Horde_Imap_Client_Cache_Backend_Cache storage driver.
C: 3 NAMESPACE
S: * NAMESPACE (("" "/")) (("Other Users/" "/")) (("Shared Folders/" "/"))
S: 3 OK Completed
 >> Command 3 took 0.003 seconds.
C: 4 LSUB "" INBOX
C: 5 LSUB "" *
C: 6 LSUB "" "Other Users/*"
C: 7 LSUB "" "Shared Folders/*"
S: * LSUB (\Noinferiors) "/" "INBOX"
S: 4 OK Completed (0.000 secs 0 calls)
 >> Command 4 took 0.0114 seconds.
S: * LSUB (\Noinferiors) "/" "INBOX"
S: * LSUB () "/" "Drafts"
S: * LSUB () "/" "Sent"
S: * LSUB () "/" "Trash"
S: * LSUB () "/" "persabt"
S: * LSUB () "/" "shuttle"
S: * LSUB () "/" "spam"
S: * LSUB () "/" "spektrum"
S: * LSUB () "/" "tc"
S: * LSUB () "/" "tubit"
S: 5 OK Completed (0.000 secs 0 calls)
 >> Command 5 took 0.0137 seconds.
S: 6 OK Completed (0.000 secs 0 calls)
 >> Command 6 took 0.053 seconds.
S: 7 OK Completed (0.000 secs 0 calls)
 >> Command 7 took 0.0528 seconds.
C: 8 LIST "" INBOX
C: 9 LIST "" *
C: 10 LIST "" "Other Users/*"
C: 11 LIST "" "Shared Folders/*"
S: * LIST (\Noinferiors) "/" "INBOX"
S: 8 OK Completed (0.000 secs 2 calls)
 >> Command 8 took 0.001 seconds.
S: * LIST (\Noinferiors) "/" "INBOX"
S: * LIST (\HasNoChildren) "/" "Drafts"
S: * LIST (\HasNoChildren) "/" "Sent"
S: * LIST (\HasNoChildren) "/" "Trash"
S: * LIST (\HasNoChildren) "/" "persabt"
S: * LIST (\HasNoChildren) "/" "shuttle"
S: * LIST (\HasNoChildren) "/" "spam"
S: * LIST (\HasNoChildren) "/" "spektrum"
S: * LIST (\HasNoChildren) "/" "tc"
S: * LIST (\HasNoChildren) "/" "tubit"
S: 9 OK Completed (0.090 secs 11 calls)
 >> Command 9 took 0.1033 seconds.
S: 10 OK Completed (0.070 secs 1 calls)
 >> Command 10 took 0.1772 seconds.
S: 11 OK Completed (0.020 secs 1 calls)
 >> Command 11 took 0.199 seconds.
...
C: 27 GETQUOTAROOT INBOX
S: * QUOTAROOT INBOX INBOX
S: * QUOTA INBOX (STORAGE 176543 5242880)
S: 27 OK Completed
 >> Command 27 took 0.002 seconds.
C: 28 LOGOUT
S: * BYE LOGOUT received
S: 28 OK Completed
 >> Command 28 took 0.0015 seconds.