357284 - protocol errors should log to Error Console, not modal alerts. "The current command did not succeed ... Protocol Error: "Unidentifiable command specified" to two commands, "getacl" and "myrights". Proxy wants return ACL but IMAP server doesn't return ACL.

Status: NEW

(Thunderbird :: General, defect)

Description

[Kenneth Herron]

I first experienced this with TB 1.5.0.x. I've just updated to a nightly trunk build and it still occurs. For my corporate email I connect to a Mirapoint IMAP proxy which connects to a backend server. The backend was migrated a few months ago to MS Exchange. Since then, every time TB accesses a folder--including inbox--for the first time after being started, I get two annoying modal alerts about IMAP protocol errors.

Typical behavior is as follows:

1) Start TB. It displays a (cached?) copy of my IMAP folder list and a (cached) list of INBOX messages in the message list. Then an alert displays: "The current command did not succeed. The mail server responded: Protocol Error: "Unidentifiable command specified"... This is a modal window so TB stops processing.

2) Click "OK" to dismiss the alert. An identical alert reappears.

3) Click "OK" on the second alert. TB finishes starting up, but doesn't display any new contents of INBOX.

4) Click on another folder. TB displays the old (cached?) contents of the folder, then the same two alerts appear and have to be dismissed. Any new contents of the folder are not displayed.

5) Click on the Inbox folder. The folder contents display normally, including any new messages.

6) Click on the folder from step 4. The folder contents display normally, including any new messages.

According to a protocol log which I'll attach, Exchange is returning "Unidentifiable command specified" to two commands, "getacl" and "myrights", which TB sends the first time it accesses each mailbox. TB displays a modal alert for each of these. When I reenter the folder things work fine for the rest of the session, which implies that these aren't really important errors.

Furthermore the actual alert dialog is pretty useless, since it doesn't say what TB was trying to do at the time. I'm a sophisticated user and I had to look up the instructions for a protocol log to troubleshoot this. Someone who didn't know about the logging feature would have absolutely no way to tell what was failing.

Comment 1

[Kenneth Herron]

Attachment: Sample protocol log

Comment 2

[Kenneth Herron]

Attachment: Sample alert

Comment 3

[David :Bienvenu]

the server claims to support ACL in its capabilities, but barfs when we try to use an ACL command - that's basically a violation of the ACL RFC - we could ignore it, but we can't tell the difference between  a broken server and a server that's trying to tell us of an actual interesting error.

Comment 4

[David :Bienvenu]

In this case, is it the proxy that's broken?

Comment 5

[Kenneth Herron]

I'm not an IMAP protocol expert, but I'll stipulate that the server probably shouldn't advertise the ACL feature and then reject the commands when TB tries to use them. However, that's not the point of this bug. The point is that TB's behavior when it encounters this situation is completely useless.

The error dialog is just about as annoying as it could be. It's modal, and it appears twice for each mailbox even though it's complaining about a server-wide condition. The error message is completely uninformative; I had to create a protocol log to find out what commands were failing.

I as an end user have absolutely no way of fixing the server's ACL behavior. And TB functions perfectly well whether the ACL commands succeed or not. What value is there in displaying these errors? At the least, why can't TB remember that this server's ACL support is broken?

Comment 6

[Nikolay Shopik]

I suggest using Error Console for logging such messages, and if error occurs shoe message in status bar only and log to error console it.

Comment 7

[Nikolay Shopik]

Can we have attention to this? Error console is good place for these messages, especially with timestamps.

Comment 8

[Bruno Harbulot]

One of my accounts has just been migrated to MS Exchange 2010, with IMAP support enabled. I'm using Thunderbird 3.0.5 on Linux.

It seems to work OK, but we regularly get messages saying "The current command did not succeed.  The mail server responded:Command Error. 12

."

The problem has been reproduced by a number of users.

I've looked at the logs, and it seems to be caused by this:
    S-INBOX:SendData: 7 myrights "INBOX"

The advertised capabilities are as follows:
    * CAPABILITY IMAP4 IMAP4REV1 NAMESPACE IDLE LITERAL+ UIDPLUS ACL QUOTA MULTIAPPEND MAILBOX-REFERRALS LOGIN-REFERRALS SCAN SORT THREAD=REFEREN
CES THREAD=ORDEREDSUBJECT


While I understand the server should probably not respond with a "BAD" status when it advertises ACL support, displaying this as a popup can become really annoying. (Other IMAP clients don't show the same behaviour.)

I'd support logging this somewhere else, as it has already been suggested.

Comment 9

[Terry Child]

Hi All

I have the same problem as Bruno above - Exchange 2010 IMAP returns BAD Command Error. 12 messages. These popup constantly in the TB GUI.

Client:
Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.2.13) Gecko/20101207 Thunderbird/3.1.7

Server: Exchange 2010 imap.

Anyone know how to stop this?

The IMAP log is below (server details obfuscated):

4952[5375880]: ImapThreadMainLoop entering [this=6ff3800]
0[f2a140]: 6ff3800:myserver:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
4952[5375880]: 6ff3800:myserver:NA:ProcessCurrentURL: entering
4952[5375880]: 6ff3800:myserver:NA:ProcessCurrentURL:imap://myaccount@myserver:993/select%3E/INBOX:  = currentUrl
4952[5375880]: ReadNextLine [stream=7409f68 nb=99 needmore=0]
4952[5375880]: 6ff3800:myserver:NA:CreateNewLineFromSocket: * OK myserver IMAP4rev1 Proxy Server v1.2.4 ready

4952[5375880]: 6ff3800:myserver:NA:SendData: 1 capability

4952[5375880]: ReadNextLine [stream=7409f68 nb=168 needmore=0]
4952[5375880]: 6ff3800:myserver:NA:CreateNewLineFromSocket: * CAPABILITY IMAP4 IMAP4REV1 NAMESPACE IDLE LITERAL+ UIDPLUS ACL QUOTA MULTIAPPEND MAILBOX-REFERRALS LOGIN-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT

4952[5375880]: ReadNextLine [stream=7409f68 nb=27 needmore=0]
4952[5375880]: 6ff3800:myserver:NA:CreateNewLineFromSocket: 1 OK CAPABILITY completed

4952[5375880]: try to log in
4952[5375880]: IMAP auth: server caps 0xC6335, pref 0x1006, failed 0x0, avail caps 0x4
4952[5375880]: (GSSAPI = 0x1000000, CRAM = 0x20000, NTLM = 0x100000, MSN =  0x200000, PLAIN = 0x1000, LOGIN = 0x2, old-style IMAP login = 0x4)
4952[5375880]: trying auth method 0x4
4952[5375880]: got new password
4952[5375880]: IMAP: trying auth method 0x4
4952[5375880]: old-style auth
4952[5375880]: 6ff3800:myserver:NA:SendData: Logging suppressed for this command (it probably contained authentication information)
4952[5375880]: ReadNextLine [stream=7409f68 nb=23 needmore=0]
4952[5375880]: 6ff3800:myserver:NA:CreateNewLineFromSocket: 3 OK LOGIN completed.

4952[5375880]: login succeeded
4952[5375880]: 6ff3800:myserver:A:SendData: 4 namespace

4952[5375880]: ReadNextLine [stream=7409f68 nb=32 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * NAMESPACE (("" "/")) NIL NIL

4952[5375880]: ReadNextLine [stream=7409f68 nb=27 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: 4 OK NAMESPACE completed.

4952[5375880]: 6ff3800:myserver:A:SendData: 5 lsub "" "*"

4952[5375880]: ReadNextLine [stream=7409f68 nb=31 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" "Deleted Items"

4952[5375880]: ReadNextLine [stream=7409f68 nb=22 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" Drafts

4952[5375880]: ReadNextLine [stream=7409f68 nb=21 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" INBOX

4952[5375880]: ReadNextLine [stream=7409f68 nb=23 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" Journal

4952[5375880]: ReadNextLine [stream=7409f68 nb=29 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" "Junk E-Mail"

4952[5375880]: ReadNextLine [stream=7409f68 nb=21 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" Notes

4952[5375880]: ReadNextLine [stream=7409f68 nb=22 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" Outbox

4952[5375880]: ReadNextLine [stream=7409f68 nb=28 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" "Sent Items"

4952[5375880]: ReadNextLine [stream=7409f68 nb=24 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" Contacts

4952[5375880]: ReadNextLine [stream=7409f68 nb=21 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" Tasks

4952[5375880]: ReadNextLine [stream=7409f68 nb=21 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LSUB () "/" Trash

4952[5375880]: ReadNextLine [stream=7409f68 nb=22 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: 5 OK LSUB completed.

4952[5375880]: 6ff3800:myserver:A:SendData: 6 list "" "INBOX"

4952[5375880]: ReadNextLine [stream=7409f68 nb=41 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * LIST (\Marked \HasChildren) "/" INBOX

4952[5375880]: ReadNextLine [stream=7409f68 nb=22 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: 6 OK LIST completed.

4952[5375880]: 6ff3800:myserver:A:SendData: 7 select "INBOX"

4952[5375880]: ReadNextLine [stream=7409f68 nb=15 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * 1130 EXISTS

4952[5375880]: ReadNextLine [stream=7409f68 nb=12 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * 1 RECENT

4952[5375880]: ReadNextLine [stream=7409f68 nb=61 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)

4952[5375880]: ReadNextLine [stream=7409f68 nb=91 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags

4952[5375880]: ReadNextLine [stream=7409f68 nb=48 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * OK [UNSEEN 1119] Is the first unseen message

4952[5375880]: ReadNextLine [stream=7409f68 nb=43 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * OK [UIDVALIDITY 1367] UIDVALIDITY value

4952[5375880]: ReadNextLine [stream=7409f68 nb=56 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: * OK [UIDNEXT 101196] The next unique identifier value

4952[5375880]: ReadNextLine [stream=7409f68 nb=37 needmore=0]
4952[5375880]: 6ff3800:myserver:A:CreateNewLineFromSocket: 7 OK [READ-WRITE] SELECT completed.

4952[5375880]: 6ff3800:myserver:S-INBOX:SendData: 8 myrights "INBOX"

4952[5375880]: ReadNextLine [stream=7409f68 nb=25 needmore=0]
4952[5375880]: 6ff3800:myserver:S-INBOX:CreateNewLineFromSocket: 8 BAD Command Error. 12

4952[5375880]: 6ff3800:myserver:S-INBOX:SendData: 9 getacl "INBOX"

4952[5375880]: ReadNextLine [stream=7409f68 nb=25 needmore=0]
4952[5375880]: 6ff3800:myserver:S-INBOX:CreateNewLineFromSocket: 9 BAD Command Error. 12

4952[5375880]: 6ff3800:myserver:S-INBOX:SendData: 10 IDLE

4952[5375880]: ReadNextLine [stream=7409f68 nb=41 needmore=0]
4952[5375880]: 6ff3800:myserver:S-INBOX:CreateNewLineFromSocket: + IDLE accepted, awaiting DONE command.

4952[5375880]: 6ff3800:myserver:S-INBOX:SendData: DONE

4952[5375880]: 6ff3800:myserver:S-INBOX:SendData: 11 close

4952[5375880]: 6ff3800:myserver:S-INBOX:SendData: 12 logout

4952[5375880]: 6ff3800:myserver:S-INBOX:TellThreadToDie: close socket connection
4952[5375880]: ImapThreadMainLoop leaving [this=6ff3800]

Comment 10

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #1)
> Sample protocol log

(By Kenneth Herron, bug opener)  
Greeting from server.
  OK Mirapoint IMAP4PROXY 3.5.8-GR server ready
Even though you server returns ACL in capability response, you server returns 'BAD Protocol Error: "Unidentifiable command specified"' to '7 getacl "INBOX"
' and '8 myrights "INBOX"'.

(In reply to comment #8)

(By Terry Child)
Greeting from server in log..
  OK myserver IMAP4rev1 Proxy Server v1.2.4 ready

(Q1) Terry Child, what is real greeting from your server?

Even though you server returns ACL in capability response, you server returns 'BAD Command Error. 12' and '9 BAD Command Error. 12' to '8 myrights "INBOX"' and '9 getacl "INBOX"'.

Bruno Harbulot also says "Command Error. 12" in comment #8, and his case is with "MS Exchange 2010, with IMAP support enabled".

(Q2) Terry Child, "MS Exchange 2010" is used?

(Q3) As Tb has bug 564642, CAPABILITY command is not issued by Tb after authentication(login). Does you server return capability response without ACL for CAPABILITY command after authentication?

(Q3) Kenneth Herron(bug opener), what is meaning of "Unidentifiable command specified" of 'BAD Protocol Error: "Unidentifiable command specified"' in your IMAP server?

(Q4) Bruno Harbulot and Terry Child, what is meaning of "12" of 'BAD Command Error. 12' in your IMAP server?

(Q5) If ACL response from server to CAPABILITY just after greeting is correct, it looks for command string part.
Does your server expect MYRIGHTS(or GETACL) instead of myrights(or getacl)?

(Q6) Or, does your server expect 'myrights(or getacl) INBOX' instead of 'myrights(or getacl) "INBOX"'?

(Q7) Greeting from server in other problem reporter's case is next.
     OK Mirapoint IMAP4PROXY 3.5.8-GR server ready
     OK myserver IMAP4rev1 Proxy Server v1.2.4 ready 
Bruno Harbulot, what greeting is returned from server? Is string "proxy" seen in greeting?

(Q8) What proxy software do you use in IMAP server access?
     What IMAP software does your IMAP server use?

Following is a web page found by Google search for "mirapont proxy imap acl".
> http://comments.gmane.org/gmane.mail.imap.general/1167
> Re: [Imap-protocol] changed capabilities after login
> On Thu, 31 Aug 2006, ...

Poster of the article says;
> The word "PROXY" in the Mirapoint banner makes me guess (haha) that while 
> the first CAPABILITY response is generated by Mirapoint's software, once 
> you log in it just goes into a 'pass through' mode talking to some other 
> IMAP server.  Thus the different capabilities before and after authentication.
>
> You should consult the Mirapoint documentation: there may be a way to 
> configure the (pre-authentication) capabilities that it announces. 
Removing ACL from that set would be a more friendly behavior by the server.

I guess this bug is caused by bug 564642.
If so, a workaroud is: Remove ACL from initial greeting generated by Mirapoint, if you use Mirapoint as proxy software and it's possible.

Comment 11

[WADA:World Anti-bad-Duping Agency]

> http://cvs.se.lemche.net/cgi-bin/viewvc.cgi/eLibrary/Mirapoint/MOS/3.3/protocol3_3.pdf?revision=1.1
> Mirapoint Administration Protocol Reference
> Set
> Sets the value of the specified parameter.
> Syntax
> tag Imap Set parameter value
> parameter is one of:
>(snip)
> Proxycapability—takes as value an ASCII printable string that the proxy
> reproduces in response to a CAPABILITY command. Either IMAP4 or
> IMAP4rev1 must be present in the string. If IMAP4 is not present, IMAP4rev1
> must be the first capability. If IMAP4 is present, it must be the first capability.
>(snip)
> The proxy capability string is limited to 512 bytes, and must contain
> printable alpha-numeric characters with only one newline.
> This parameter is intended for experienced IMAP administrators only.
> Do not use this parameter for proxying Mirapoint message servers.
> A null value returns to default.

Is defaulted capability response of Mirapoint used by Proxycapability=null in your evironment?
Is your Mirapoint set up of Proxycapability appropriate?

If IMAP4rev1 only is returned from Mirapoint IMAP proxy to Tb to first capability after greeting, Tb perhaps issues capability command after authentication. If it's right, and if your IMAP server supports simple plain text login(usually true if SSL is used), it can be a workaround of bug 564642.

Comment 12

[Terry Child]

(In reply to comment #10)
> (In reply to comment #1)
> > Sample protocol log
> 
> (By Kenneth Herron, bug opener)  
> Greeting from server.
>   OK Mirapoint IMAP4PROXY 3.5.8-GR server ready
> Even though you server returns ACL in capability response, you server returns
> 'BAD Protocol Error: "Unidentifiable command specified"' to '7 getacl "INBOX"
> ' and '8 myrights "INBOX"'.
> 
> (In reply to comment #8)
> 
> (By Terry Child)
> Greeting from server in log..
>   OK myserver IMAP4rev1 Proxy Server v1.2.4 ready
> 
> (Q1) Terry Child, what is real greeting from your server?

As above except the server name is the real server DNS name.

> 
> Even though you server returns ACL in capability response, you server returns
> 'BAD Command Error. 12' and '9 BAD Command Error. 12' to '8 myrights "INBOX"'
> and '9 getacl "INBOX"'.
> 
> Bruno Harbulot also says "Command Error. 12" in comment #8, and his case is
> with "MS Exchange 2010, with IMAP support enabled".
> 
> (Q2) Terry Child, "MS Exchange 2010" is used?

Yes.

> 
> (Q3) As Tb has bug 564642, CAPABILITY command is not issued by Tb after
> authentication(login). Does you server return capability response without ACL
> for CAPABILITY command after authentication?

Yes! I think you've found the problem:

I just did the following using telnet:

* OK myserver IMAP4rev1 XXX Proxy Server v1.2.4 ready
001 CAPABILITY
* CAPABILITY IMAP4 IMAP4REV1 NAMESPACE IDLE STARTTLS LITERAL+ UIDPLUS ACL QUOTA MULTIAPPEND MAILBOX-REFERRALS LOGIN-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT
001 OK CAPABILITY completed
002 LOGIN [username] [password]
002 OK LOGIN completed.
003 CAPABILITY
* CAPABILITY IMAP4 IMAP4rev1 AUTH=GSSAPI AUTH=PLAIN STARTTLS IDLE NAMESPACE LITERAL+
003 OK CAPABILITY completed.


> 
> (Q3) Kenneth Herron(bug opener), what is meaning of "Unidentifiable command
> specified" of 'BAD Protocol Error: "Unidentifiable command specified"' in your
> IMAP server?
> 
> (Q4) Bruno Harbulot and Terry Child, what is meaning of "12" of 'BAD Command
> Error. 12' in your IMAP server?
> 

Don't know I don't manage the server - but guess it is because it doesn't like the ACL commands.

> (Q5) If ACL response from server to CAPABILITY just after greeting is correct,
> it looks for command string part.
> Does your server expect MYRIGHTS(or GETACL) instead of myrights(or getacl)?
> 
> (Q6) Or, does your server expect 'myrights(or getacl) INBOX' instead of
> 'myrights(or getacl) "INBOX"'?
> 
> (Q7) Greeting from server in other problem reporter's case is next.
>      OK Mirapoint IMAP4PROXY 3.5.8-GR server ready
>      OK myserver IMAP4rev1 Proxy Server v1.2.4 ready 
> Bruno Harbulot, what greeting is returned from server? Is string "proxy" seen
> in greeting?
> 
> (Q8) What proxy software do you use in IMAP server access?
>      What IMAP software does your IMAP server use?
> 
> Following is a web page found by Google search for "mirapont proxy imap acl".
> > http://comments.gmane.org/gmane.mail.imap.general/1167
> > Re: [Imap-protocol] changed capabilities after login
> > On Thu, 31 Aug 2006, ...
> 
> Poster of the article says;
> > The word "PROXY" in the Mirapoint banner makes me guess (haha) that while 
> > the first CAPABILITY response is generated by Mirapoint's software, once 
> > you log in it just goes into a 'pass through' mode talking to some other 
> > IMAP server.  Thus the different capabilities before and after authentication.
> >
> > You should consult the Mirapoint documentation: there may be a way to 
> > configure the (pre-authentication) capabilities that it announces. 
> Removing ACL from that set would be a more friendly behavior by the server.
> 
> I guess this bug is caused by bug 564642.
> If so, a workaroud is: Remove ACL from initial greeting generated by Mirapoint,
> if you use Mirapoint as proxy software and it's possible.

Thanks - I'll ask the server managers if they can do this.

Comment 13

[WADA:World Anti-bad-Duping Agency]

FYI.
Following is for similar case, and an example of bypass by "perdition proxy".
> http://trac.roundcube.net/ticket/1485750
> To work around this, we've temporarily added an additional perdition proxy
> which reports the same CAPABILITY list as the Cyrus servers in question,
> which resolves the issue.