[imp] Login via imp successful but list mboxes leads to immediate logout
Jan Schneider
jan at horde.org
Fri Nov 13 09:16:21 UTC 2015
Zitat von Herbert Pophal <pophal at tubit.tu-berlin.de>:
> 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/*"""
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
This is the issue.
I remember seeing this recently, please check the mailing list archive
and bug tracker.
> 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.
> --
> imp mailing list
> Frequently Asked Questions: http://wiki.horde.org/FAQ
> To unsubscribe, mail: imp-unsubscribe at lists.horde.org
--
Jan Schneider
The Horde Project
http://www.horde.org/
More information about the imp
mailing list