46295 - IMAP fetching error

Status: VERIFIED DUPLICATE of bug 103171

(MailNews Core :: Networking: IMAP, defect, P3)

Description

[Henrik Gemal]

I have a message on my Exchange IMAP server that gives me an error every time I 
try to access it. Both with Netscape 4.74 and Mozilla, while Outlook Express is 
fine.
The error I'm getting is:
"NO Unspecified error"
and short after:
"BAD Protokolfejl: "Invalid FETCH_ITEM in FETCH command"

Comment 1

[Henrik Gemal]

Attachment: IMAP log with error...

Comment 2

[Karen Huang]

I cannot reproduce this problem by using today's 07-24-09-M17 windows commercial 
build.
Can you attach the specific message that you are trying to fetch that message 
from the MS Exchange IMAP server?
Adding MS Exchange on the summary and interop for the keywords.

Comment 3

[Henrik Gemal]

I can reproduce this error all the time on 11 large (29KB+) mails I have on my 
Exchange server. If I save one of the mails and send it to my self again I'm not 
seeing the problem.
It doesn't matter in which folder I have the mail.

Is there anything I can do to help?

Outlook Express IMAP log:
IMAP: 00:34:29 [tx] 000A UID FETCH 11793 (BODY.PEEK[] UID)
IMAP: 00:34:30 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:30 [rx] * 51 FETCH (BODY[] {30541}
IMAP: 00:34:30 [rx] Buffer (literal) of length 4815
IMAP: 00:34:31 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:31 [rx] Buffer (literal) of length 4824
IMAP: 00:34:33 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:33 [rx] Buffer (literal) of length 4824
IMAP: 00:34:33 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:33 [rx] Buffer (literal) of length 1072
IMAP: 00:34:35 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:35 [rx] Buffer (literal) of length 4824
IMAP: 00:34:37 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:37 [rx] Buffer (literal) of length 4824
IMAP: 00:34:38 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:38 [rx] Buffer (literal) of length 4824
IMAP: 00:34:38 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:38 [rx] Buffer (literal) of length 534
IMAP: 00:34:38 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 00:34:38 [rx]  UID 11793)
IMAP: 00:34:38 [rx] 000A OK FETCH fuldført.

Comment 4

[Karen Huang]

Can you attach that specific mail message here? Thanks.

Comment 5

[Henrik Gemal]

Attachment: This is one of the mail where Mozilla/Netscape gets it wrong

Comment 6

[Scott MacGregor]

looks like a mime part on demand fetching problem if I'm reading our log vs
outlooks log correctly. Our body fetch isn't getting sent correctly:
1372[25ac9d0]: tarkin.ost.tele.dk:S-INBOX/Projects/MailHotel:SendData: 4 UID
fetch 8 (BODYSTRUCTURE)
1372[25ac9d0]:
tarkin.ost.tele.dk:S-INBOX/Projects/MailHotel:CreateNewLineFromSocket: * 8 FETCH
(BODYSTRUCTURE (("TEXT" "PLAIN" ("CHARSET" "US-ASCII") NIL NIL "7BIT" 1024 18
NIL NIL NIL)("APPLICATI
1372[25ac9d0]:
tarkin.ost.tele.dk:S-INBOX/Projects/MailHotel:CreateNewLineFromSocket: 4 OK
FETCH fuldført.
1372[25ac9d0]: tarkin.ost.tele.dk:S-INBOX/Projects/MailHotel:SendData: 5 UID
fetch 8 (BODY[HEADER] BODY[1.MIME] BODY[2.MIME])
1372[25ac9d0]:
tarkin.ost.tele.dk:S-INBOX/Projects/MailHotel:CreateNewLineFromSocket: 5 NO
Unspecified error

re-assignging to bienvenu

Comment 7

[David :Bienvenu]

Henrik, can you try the log again? It seems to have been chopped off to more or
less just the imap server greeting. 

Comment 8

[Henrik Gemal]

Attachment: Full IMAP log of the session

Comment 9

[Henrik Gemal]

It's quite annoying that the logging lines seems to be cut after 200 chars. 
Anything to do?

Comment 10

[David :Bienvenu]

The 200 char limit is a limitation of the logging component we're using (in
NSPR). We could either try to get the NSPR guys to fix it (not likely) or break
up the lines ourselves. I worry a little about the performance impact of doing
the latter.

I'm not convinced that we're sending bad protocol - it looks more like a server
error. From this bug and the other one with software.com, it looks like Outlook
Express doesn't fetch mime parts singly, but fetches the whole message, so it
would never see this problem. I'll look into it some more.

Comment 11

[Henrik Gemal]

I've filed bug 46630 on the 200 char limit.

Comment 12

[scottputterman]

Mail triage is marking nsbeta3-

Comment 13

[Henrik Gemal]

About the 200 char limit. This is what has been added to bug 46630:
------------------
SeaMonkey uses the NSPRPUB_CLIENT_BRANCH of
NSPR.  This is why you don't see the fix in
the SeaMonkey version of the file prlog.c.
If you need this fix for SeaMonkey, we need
to get approval from brendan or waterson.
I would recommend that you work around this bug.
Is it possible to change your logging code so
that each line is < 200 char long?
------------------

Comment 14

[David :Bienvenu]

adding keyword

Comment 15

[scottputterman]

marking nsbeta1-

Comment 16

[Henrik Gemal]

Kind of found of this one, but I need some inside help.

First Mozilla sends:
SendData: 26 UID fetch 27497 (BODY[16]<0.10240>)

Then it sends:
SendData: 27 UID fetch 27497 (BODY[16]<10240.-8668>)
CreateNewLineFromSocket: 27 BAD Protokolfejl: "Invalid FETCH_ITEM in FETCH 
command"

The second fetch is wrong. BUT: How are the numbers inside the <> calculated? 
Are they calculated by the size of data returned or what? Please help...

Comment 17

[David :Bienvenu]

they're calculated based on the size of the message as reported by the imap server.

Comment 18

[Henrik Gemal]

Ok. so now it's getting weird since I'm only seeing this error in my Exchange 
mailbox. "size of the message as reported by the imap server". Can the size 
reported been seen in the IMAP log?
It seems that the servers (an Exchange and an InterMail) returns the same, but 
Mozilla only works on my InterMail.

Comment 19

[David :Bienvenu]

sure, the size can be seen in the log, both when we download the header for the
message and put it in the. msf file, and when we download the message itself. Do
both servers return the same size for both requests? There is something bad
going on, but I'm not sure what it is. I'd have to look at the code to see why
we'd get a negative number of bytes to fetch.

Comment 20

[Henrik Gemal]

Just for record. It's always: <10240.-8668> I have a single mail that produces 7 
10240.-8668>. Weird that it's always "-8668" ...

My InterMail has:
SendData: 23 UID fetch 1084 (BODY[16]<0.10240>)
CreateNewLineFromSocket: * 1 FETCH (BODY[16]<0> {10240}
CreateNewLineFromSocket: 23 OK UID FETCH completed
SendData: 24 UID fetch 1084 (BODY[16]<10240.10240>)
CreateNewLineFromSocket: * 1 FETCH (BODY[16]<10240> {10240}

While my Exchange has:
SendData: 26 UID fetch 27497 (BODY[16]<0.10240>)
CreateNewLineFromSocket: * 184 FETCH (BODY[16]<0> {10240}
CreateNewLineFromSocket: ILKhuag3p/lQaZTVrPv4hw UID 27497)
CreateNewLineFromSocket: 26 OK FETCH fuldført.
SendData: 27 UID fetch 27497 (BODY[16]<10240.-8668>)
CreateNewLineFromSocket: 27 BAD Protokolfejl: "Invalid FETCH_ITEM in FETCH 
command"
SendData: 28 UID fetch 27497 (BODY[16])
CreateNewLineFromSocket: * 184 FETCH (BODY[16] {55434}
CreateNewLineFromSocket:  UID 27497)
CreateNewLineFromSocket: 28 OK FETCH fuldført.

Whenever Mozilla tries to split up the fetch using the <size.size> on my 
exchange it goes wrong. When does Mozilla use the <size.size>? Is that when the 
part to fetch is bigger than 10240? Since just fetching BODY[16] without the 
<size.size> is a success.

Comment 21

[Henrik Gemal]

"return the same size for both requests?"
I'm not sure where to see the size that the server return...?

Comment 22

[David :Bienvenu]

delete the .msf file for the folder in question, and then click on the folder.
That will download all the info for each message, including the size. Then,
click on the message, and we'll ask for the size again.

Comment 23

[Henrik Gemal]

Just reproduces this on my InterMail IMAP server:

SendData: 31 UID fetch 1168 (BODY[16]<14336.-12152>)
CreateNewLineFromSocket: 31 BAD Invalid attribute list in UID FETCH

I had 3 mails A, B and C. Selected C and pressed Delete, B was then selected. 
Pressed Delete. A was then selected. IMAP error...

Comment 24

[Henrik Gemal]

In build 20011101:
UID fetch 4756 (BODY[1]<10240.-9434>)

Comment 25

[David :Bienvenu]

Henrik, is this fixed now? I believe this was a dup of bug 103171, which was
fixed on 12-03.

Comment 26

[David :Bienvenu]

dup.

*** This bug has been marked as a duplicate of 103171 ***

Comment 27

[Henrik Gemal]

dupe=ok