493263 - IMAP getquotaroot command intermittently fails with "BAD Command" error on Exchange 2007

Status: RESOLVED INVALID

(MailNews Core :: Networking: IMAP, defect)

Description

[Jonathan Harris]

User-Agent:       Mozilla/5.0 (X11; U; Linux x86_64; en-GB; rv:1.9.0.10) Gecko/2009042523 Ubuntu/9.04 (jaunty) Firefox/3.0.10
Build Identifier: Mozilla/5.0 (X11; U; Linux x86_64; en-GB; rv:1.9.0.10) Gecko/2009042523 Ubuntu/9.04 (jaunty) Firefox/3.0.10

Selecting a folder on an Microsoft Exchange 2007 server, accessed over IMAP, fails intermittently. When it fails no error message is displayed, but the folder is shown as empty and any downloaded email is discarded.
The IMAP log shows that the Exchange server is returning a "BAD Command" error.


Reproducible: Sometimes

Steps to Reproduce:
Click on a folder in the folder tree.

Actual Results:  
Folder is shown as empty.
Any downloaded emails in the folder are discarded from Thunderbird's index so that the next time you click on the folder all the email headers and content have to be downloaded again.

Expected Results:  
The folder should contain messages.
Ideally the reason that the getquotaroot command fails should be fixed. But as a fallback, when this error occurs Thunderbird should not discard all the headers and content of the messages in the folder.


Log with NSPR_LOG_MODULES=imap:5, starting with the click on the folder:

582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-OSC:CreateNewLineFromSocket: 10 OK IDLE completed.
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-OSC:ProcessCurrentURL: entering
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-OSC:ProcessCurrentURL:imap://[e-mail]:143/select%3E/Test2:  = currentUrl
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-OSC:SendData: 11 select "Test2"
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=12 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: * 1 EXISTS
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=12 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: * 0 RECENT
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=61 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=91 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=44 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: * OK [UIDVALIDITY 11594] UIDVALIDITY value
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=51 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: * OK [UIDNEXT 4] The next unique identifier value
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=38 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: 11 OK [READ-WRITE] SELECT completed.
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:SendData: 12 getquotaroot "Test2"
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=26 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: 12 BAD Command Error. 12
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:SendData: 13 UID fetch 1:* (FLAGS)
582850896[7fbb30bab7f0]: ReadNextLine [stream=304a0580 nb=29 needmore=0]
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:S-Test2:CreateNewLineFromSocket: * BYE Connection closed. 14
582850896[7fbb30bab7f0]: 30d64640:mex07a.emailsrvr.com:NA:TellThreadToDie: close socket connection
582850896[7fbb30bab7f0]: ImapThreadMainLoop leaving [this=30d64640]


Output of "tcpdump -A tcp port imap2":
18:24:34.967722 IP 72.4.117.9.imap2 > 192.168.1.4.36364: P 1:24(23) ack 6 win 46 <nop,nop,timestamp 1892703868 15910543>
E..K..@.....H.u	........UV
rJz.V.....f.....
p.^|....10 OK IDLE completed.

18:24:34.967778 IP 192.168.1.4.36364 > 72.4.117.9.imap2: . ack 24 win 116 <nop,nop,timestamp 15910573 1892703868>
E..4.G@.@.......H.u	....Jz.VUV
....t+W.....
....p.^|
18:24:34.969110 IP 192.168.1.4.36364 > 72.4.117.9.imap2: P 6:25(19) ack 24 win 116 <nop,nop,timestamp 15910573 1892703868>
E..G.H@.@.......H.u	....Jz.VUV
....tr......
....p.^|11 select "Test2"

18:24:35.091001 IP 72.4.117.9.imap2 > 192.168.1.4.36364: . ack 25 win 46 <nop,nop,timestamp 1892703991 15910573>
E..4..@.....H.u	........UV
.Jz.i....+......
p.^.....
18:24:35.101610 IP 72.4.117.9.imap2 > 192.168.1.4.36364: P 24:333(309) ack 25 win 46 <nop,nop,timestamp 1892704001 15910573>
E..i..@.....H.u	........UV
.Jz.i....1C.....
p._.....* 1 EXISTS
* 0 RECENT

18:24:35.103078 IP 192.168.1.4.36364 > 72.4.117.9.imap2: P 25:50(25) ack 333 win 139 <nop,nop,timestamp 15910607 1892704001>
E..M.I@.@.......H.u	....Jz.iUV......$/.....
....p._.12 getquotaroot "Test2"
18:24:35.185395 IP 72.4.117.9.imap2 > 192.168.1.4.36364: . ack 50 win 46 <nop,nop,timestamp 1892704085 15910607>
E..4..@.....H.u	........UV..Jz......)A.....
p._U....
18:24:35.223223 IP 72.4.117.9.imap2 > 192.168.1.4.36364: P 333:388(55) ack 50 win 46 <nop,nop,timestamp 1892704123 15910607>
E..k..@.....H.u	........UV..Jz......L......
p._{....12 BAD Command Error. 12
18:24:35.223392 IP 72.4.117.9.imap2 > 192.168.1.4.36364: F 388:388(0) ack 50 win 46 <nop,nop,timestamp 1892704123 15910607>
E..4..@.....H.u	........UV..Jz......(......
p._{....
18:24:35.224173 IP 192.168.1.4.36364 > 72.4.117.9.imap2: P 50:76(26) ack 389 win 139 <nop,nop,timestamp 15910637 1892704123>
E..N.J@.@.......H.u	....Jz..UV......A......
....p._{13 UID fetch 1:* (FLAGS)
18:24:35.235926 IP 192.168.1.4.36364 > 72.4.117.9.imap2: F 76:76(0) ack 389 win 139 <nop,nop,timestamp 15910640 1892704123>
E..4.K@.@.......H.u	....Jz..UV......(J.....
....p._{
18:24:35.306320 IP 72.4.117.9.imap2 > 192.168.1.4.36364: R 1431702518:1431702518(0) win 0
E..(..@.....H.u	........UV......P...A?..
18:24:35.317876 IP 72.4.117.9.imap2 > 192.168.1.4.36364: R 1431702518:1431702518(0) win 0
E..(..@.....H.u	........UV......P...A?..

Comment 1

[Jonathan Harris]

Thunderbird version is 2.0.0.21 (20090409)
Ubuntu binary package 2.0.0.21+nobinonly-0ubuntu1.9.0.4.1 (jaunty)

Comment 2

[WADA:World Anti-bad-Duping Agency]

> S-Test2:SendData: 12 getquotaroot "Test2"
> S-Test2:CreateNewLineFromSocket: 12 BAD Command Error. 12

"BAD Command Error." to getquotaroot is (1) real server side error, or (2) bad behavior for IMAP client(especially for Tb) when server is in maintenance.
Gmail IMAP also behaves bad for Tb when server is in maintenance(see bug 423354 comment #8).
If current bug summary correctly represents issue of this bug, INVALID.

> Actual Results:  
> Folder is shown as empty.
> Any downloaded emails in the folder are discarded from Thunderbird's index
> so that the next time you click on the folder all the email headers and content
have to be downloaded again.

This problem after "BAD to qutaroot" looks same as Bug 492183 which is closed as DUP of Bug 213827.

Comment 3

[Ludovic Hirlimann [:Usul]]

Imap support has been greatly enhanced do you also see this behavior with Thunderbird 3.0 beta 2 ?

Comment 4

[Jonathan Harris]

After further investigation, turns out that the service provider is running a transparent IMAP proxy that is advertising the QUOTA capability which the "real" underlying Exchange 2007 server does not support. So it's not surprising that TB is getting confused. So suggest marking this as INVALID.

Incidentally I tried with 3.0b2 - the fix for Bug 213827 did not help and folder contents are still lost.

Comment 5

[WADA:World Anti-bad-Duping Agency]

Closing as INVALID.