Closed Bug 1315533 Opened 8 years ago Closed 2 years ago

IMAP FETCH BODY.PEEK endless loop

Categories

(MailNews Core :: Networking: IMAP, defect)

Product:
MailNews Core
Component:
Networking: IMAP
Platform:
x86_64
Windows 10
Type:
defect
Priority:
Not set
Severity:
critical

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1770811

People

(Reporter: jm+mozbugz, Unassigned)

References

Details

(Keywords: hang)

Attachments

(1 file)

Mailserver verbose IMAP log
946.27 KB, text/plain
Details
Attached file Mailserver verbose IMAP log —
User Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:45.0) Gecko/20100101 Firefox/45.0 Build ID: 20160304113541 Steps to reproduce: Difficult to reproduce. Actual results: The IMAP session gets stuck in a loop. You see that for a certain message (which I think no longer exists) TB issues FETCH/BODY.PEEK commands and increments the offset until it becomes negative, and then positive again, and then negative etc. It never stops. For that mailbox, ID 1473 is actually something very old, as that Inbox at least contains lots of messages. Here is what I get searching the account on the mailserver for the message ID: 1309 Jul 26 11:27 ./INBOX.IMAP/Archive.IMAP/2015.IMAP/md50000001473.msg 100 Aug 24 10:35 ./INBOX.IMAP/Archive.IMAP/2016.IMAP/CronAlleng.IMAP/MD50000001473.msg 21093 Mar 25 2016 ./Sent.IMAP/md50000001473.msg 1485 Oct 12 05:00 ./sys.xxx.IMAP/md50000001473.msg I am including the relevant part of the mailserver log. I have a feeling that this may be more frequent for people working with message filters (moving messages to subfolders etc.) as opposed to not using message filters. Mailserver is Alt-N MDaemon Messaging Server FWIW. Expected results: It should not have ended up in an endless loop but instead stopped at some point and/or spit out an error.
OS: Unspecified → Windows 10
Hardware: Unspecified → x86_64
BTW the same was the case previously on Windows 7 x86.
Is more than one user in your organization experiencing this? > I have a feeling that this may be more frequent for people working with message filters (moving messages to subfolders etc.) as opposed to not using message filters. And can you elaborate on this statement?
Severity: normal → critical
Component: Untriaged → Networking: IMAP
Keywords: hang
Product: Thunderbird → MailNews Core
Version: 45 Branch → 45
(In reply to Wayne Mery (:wsmwk, NI for questions) from comment #2) > Is more than one user in your organization experiencing this? Yes, looking over the last months/years we had this with more than one user. They recently all got a fresh Windows with fresh TB profile, but as it seems that doesn't help. > > > I have a feeling that this may be more frequent for people working with message filters (moving messages to subfolders etc.) as opposed to not using message filters. > > And can you elaborate on this statement? Not really, most of the times the affected people were "power users" from IT, however it happened to "regular" users also. Maybe we should disregard that statement of mine for now. Maybe simply the more you use the software, the more likely the problem occurs, without any regard to any additional features being used.
We have had another case. This is a user who has several IMAP accounts configured. As it looks like, TB is trying to poll a message ID from the wrong account: The user had several IMAP sessions on the server (logged in with different accounts). There was a message with UID 80553 in one account. However the mailserver log clearly shows that UID being polled by the other session (the account where no such UID exists). I have created a job monitoring mailserver logs to find other cases. I'll keep you posted.
Same thing again in our logs from yesterday. One should note that one of the accounts is always used by several users, if that matters. (Maybe some other user has moved or removed a message from the shared account, but the local TB has not seen the message disappearing yet. Upon polling, the UID somehow "bleeds over" to the other account configured in that user's TB.)
IMAP log. (1) After Inbox open, Thunderbirs gets UID of all messages. > Sun 2016-11-06 11:25:24.565: 02: [609844] <-- 7 UID fetch 1:* (FLAGS) > Sun 2016-11-06 11:25:24.565: 01: [609844] --> Sending FETCH response (not logged)... > Sun 2016-11-06 11:25:24.568: 03: [609844] --> 7 OK FETCH completed (2) Because UID=1473 is returned from you server, requests UID fetch 1473 with BODY.PEEK[] (first log) > Sun 2016-11-06 11:25:34.345: 02: [609844] <-- 64 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) > ==> What is returned to Thunderbird from your server? > note: it took 000 msec > Sun 2016-11-06 11:25:34.345: 03: [609844] --> 64 OK FETCH completed (3) Many "UID fetch 1473 with BODY.PEEK[]" are logged. > Sun 2016-11-06 11:26:20.718: 02: [609844] <-- 1514 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) > ==> What is returned to Thunderbird from your server? > note: it took 000 msec > Sun 2016-11-06 11:26:20.718: 03: [609844] --> 1514 OK FETCH completed (Q1) What is returned to Thunderbird from your server for the "UID fetch 1473 with BODY.PEEK[]"? (Q2) What is returned to Thunderbird from your server for "UID fetch 1473 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS ( ... )"? I guess UID=1473 is garbage at server. I guess server returns null data to "UID fetch 1473 with BODY.PEEK[]" and returns OK. If so, what is correct behavior of IMAP client? Null header data, null mail data, are valid or proper in protocol named IMAP? If so, Tb may retry to get mail data because previous fetch of the mail is incomplete due to null data. If UID=1473 is not returned to "UID fetch 1:* (FLAGS)" upon Inbox open(after select Inbox), I believe that almost all IMAP clients including Thunderbird won't issue "uid an-action 1473". If fetch response is not logged at server, please get Thunderbird side IMAP log(NSPR log). Please see "User Story" field of Bug 402793 for getting NSPR log.
(In reply to jm from comment #4) > The user had several IMAP sessions on the server (logged in with different > accounts). There was a message with UID 80553 in one account. > However the mailserver log clearly shows that UID being polled by the other > session (the account where no such UID exists). UID in IMAP is "per Mbox value" which starts from 1 with increment by 1 in the mbox. So, multiple mbox in same IMAP server/different IMAP servers can have same UID=80553 at same time. What is evidence of that "request for UID=80553 of MboxA of AccountA" was sent to "UID=80553 of MboxB of AccountB which is non-existent in the MboxB" by Thunderbird? Please note following. If "an mboxX of an IMAP accountX" is shared, next can happen. (1) Both ClientA and ClientB knows UID=80553 of mboxX of accountX (2) ClientA deletes or moves UID=80553(\Deleted flag is stored). (3) If access to UID=80553 happens at ClientB before ClientB knows about "\deleted is stored to UID=80553", "UID an-action 80553" is sent by ClientB. Even if user of ClientA thinks UID=80553 is deleted, UID=80553(with \Deleted flag) surely exists in mboxX of accountX until expunged is executed by someone. (4) If expunge is requested by ClientA or expunge is executed by server before ClientB knows about "\deleted is stored to UID=80553" and before ClientB knows about "UID=80553 is expunged", (UID=80553 doesn't exist anymore after expunge) access to UID=80553 from ClientB can occur. If IDLE is not used, above is pretty normal phenomenon. When IDLE is used, (3) is usually normal phenomenon, because many IMAP servers won't pass "flag state change" via. IDLE. When IDLE is used, (4) is usually rare, because almost all IMAP servers pass "expunged state" via. IDLE. Please don't use B.M.O as support forum. If corporate environment, please open bug at B.M.O only for actual bug of Tb(flaw in code of Tb) with evidence data of actual bug of Tb.
Hi, Let me reply to the questions to which I have answers (or comments) thus far: > (1) After Inbox open, Thunderbirs gets UID of all messages. > (2) Because UID=1473 is returned from you server, > requests UID fetch 1473 with BODY.PEEK[] (first log) > (3) Many "UID fetch 1473 with BODY.PEEK[]" are logged. Why would so many be necessary? >> Sun 2016-11-06 11:26:20.718: 02: [609844] <-- 1514 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) >> ==> What is returned to Thunderbird from your server? >> note: it took 000 msec >> Sun 2016-11-06 11:26:20.718: 03: [609844] --> 1514 OK FETCH completed > (Q1) What is returned to Thunderbird from your server for the "UID fetch 1473 > with BODY.PEEK[]"? What was returned at that time, we do not know. I will get back with a full example once it happens again and/or if we can reproduce. > (Q2) What is returned to Thunderbird from your server for "UID fetch 1473 (UID > RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS ( ... )"? When I try this _right now_ with a non-existing message, the server returns "fetch completed": a UID fetch 2 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To x-spam-status x-spam-flag)]) a OK FETCH completed Again, I will get back with a full example once it happens again and/or if we can reproduce. > I guess UID=1473 is garbage at server. > I guess server returns null data to "UID fetch 1473 with BODY.PEEK[]" and > returns OK. When I try this _right now_, it does return nothing and says OK. a UID fetch 2 (UID RFC822.SIZE BODY.PEEK[]) a OK FETCH completed > If so, what is correct behavior of IMAP client? > Null header data, null mail data, are valid or proper in protocol named IMAP? > If so, Tb may retry to get mail data because previous fetch of the mail is > incomplete due to null data. I guess... it seems to be ok with RFC to return OK for a non-existing message after UID FETCH command. rfc3501#section-6.4.8: "A non-existent unique identifier is ignored without any error message generated.".... >> The user had several IMAP sessions on the server (logged in with different >> accounts). There was a message with UID 80553 in one account. >> However the mailserver log clearly shows that UID being polled by the other >> session (the account where no such UID exists). > UID in IMAP is "per Mbox value" which starts from 1 with increment by 1 in the > mbox. > So, multiple mbox in same IMAP server/different IMAP servers can have same > UID=80553 at same time. > What is evidence of that "request for UID=80553 of MboxA of AccountA" was sent > to > "UID=80553 of MboxB of AccountB which is non-existent in the MboxB" by > Thunderbird? The evidence is that the filestructure on the mailserver is a continuously incrementing integer. AccountB is very far from 80553 mails. But AccountA was exactly at around 80700-something mails (with 80553 no longer existing) when we looked. This makes it very believable that the ID from AccountA "bled over" to AccountB. > Please note following. > If "an mboxX of an IMAP accountX" is shared, next can happen. > .... I agree. The main question here is why ClientB then starts looping (in a certain scenario). > Please don't use B.M.O as support forum. > If corporate environment, please open bug at B.M.O only for actual bug of > Tb(flaw in code of Tb) with evidence data of actual bug of Tb. I think that if TB polling for a _negative offset_ inside a message (as shown in the server log) and then running in circles is not a bug, then I do not know what is. Last, let me note that we should all be happy that TB is still used in corporate environments with all the pull toward Exchange (or more precisely Outlook). ;-)
(In reply to jm from comment #8) > I guess... it seems to be ok with RFC to return OK for a non-existing > message after UID FETCH command. rfc3501#section-6.4.8: "A non-existent > unique identifier is ignored without any error message generated.".... https://tools.ietf.org/html/rfc3501#section-6.4.8 > 6.4.8. UID Command > > A non-existent unique identifier is ignored without any error > message generated. Thus, it is possible for a UID FETCH command > to return an OK without any data or a UID COPY or UID STORE to > return an OK without performing any operations. But it's for "Non-Existent UID". Can "UID=x returned to UID fettch 1:* Flags from server" be non-existent UID? If a UID=X is deleted(\Deleted is stored) and expunged just after server returned the UID=x to "UID fettch 1:* Flags", the "non-existent UID=x" condition can occur, and server can return null data and OK for the non^existent UID=x. But, is the "OK response with null data" indicator of "non-existent UID"? If non-existent UID=x, server MUST NOT return the UID=x upon next "select mbox, uid fetch 1:* Flags". If not, does rfc3501 allow any UID number in response to "uid fetch 1:* Flags"? > The main question here is why ClientB then starts looping (in a certain scenario). It's perhaps simple. (1) Once Tb considers that UID=x exist on server, Tb won't remove the UID=x unless: (1-a) the UID=x is not returned to UID fetch 1:* Flags after select mbox(folder open). (1-b) "UID=x is expunged state" is notified from server via. IDLE or via. command response.. (2) Tb doesn't consider "null data + OK to UID FETCH x" as "non-existent UID=x". (3) Because of "returned data=null + OK", "fetch of header/mail data" is incomplete for T. So, Tb retries "uid fetch x body[]". (4) (1) occurs by: (4-1) UID=x is returned to "UID FETCH 1:* Flags upon folder open" (4-2) Due to Tb's bug, request to UID=x of other mbox(including other mbox of other account) is wrongly executed at different mbox. IIRC, bug like "request to UID=x of mboxA is wrongly executed at mboxB of same account" existed, but it was already resolved. I don't know problem like "request to UID=x of mboxA is wrongly executed at mboxB of different account". Because RFC3501 allows "null data + OK for non-existent UID=x", I think Thunderbird is better to treat "null data + OK to uid fetch" as "non-existent UID".
To bug opener: No progress? What is actual bug of Thunderbird(flaw in code/implementation/design of Thunderbird) in this your bug report at B.M.O?
Flags: needinfo?(jm+mozbugz)
Actual bug (for now, until more specific reproduction is available) is polling imap body with negative offset. At least when the body peek offset overflows into negative numbers should processing be stopped.
(In reply to jm from comment #11) > Actual bug (for now, until more specific reproduction is available) is polling imap body with negative offset. > At least when the body peek offset overflows into negative numbers should processing be stopped. message larger than 2GB? (32bits signed integer is used internally) If 4GB(32bits unsigned integer is used), negative number doesn't occur.
(In reply to WADA from comment #12) > message larger than 2GB? (32bits signed integer is used internally) > If 4GB(32bits unsigned integer is used), negative number doesn't occur. What I am trying to tell you (if you look at the entirety of the server log that I provided) is that not only is TB stuck in a BODY.PEEK[] loop, but it also starts looping over the (probably non-existent) message at some point: Sun 2016-11-06 11:26:26.975: 02: [609844] <-- 3789 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) Sun 2016-11-06 11:26:26.975: 03: [609844] --> 3789 OK FETCH completed Sun 2016-11-06 11:26:26.977: 02: [609844] <-- 3790 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) Sun 2016-11-06 11:26:26.977: 03: [609844] --> 3790 OK FETCH completed Sun 2016-11-06 11:26:26.979: 02: [609844] <-- 3791 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) Sun 2016-11-06 11:26:26.979: 03: [609844] --> 3791 OK FETCH completed Sun 2016-11-06 11:26:26.981: 02: [609844] <-- 3792 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) Sun 2016-11-06 11:26:26.981: 03: [609844] --> 3792 OK FETCH completed Sun 2016-11-06 11:26:26.983: 02: [609844] <-- 3793 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) Sun 2016-11-06 11:26:26.983: 03: [609844] --> 3793 OK FETCH completed Sun 2016-11-06 11:26:27.015: 02: [609844] <-- 3794 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) Sun 2016-11-06 11:26:27.015: 03: [609844] --> 3794 OK FETCH completed ... Sun 2016-11-06 11:26:29.418: 02: [609844] <-- 3800 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<0.65536>) Sun 2016-11-06 11:26:29.418: 03: [609844] --> 3800 OK FETCH completed Sun 2016-11-06 11:26:29.419: 02: [609844] <-- 3801 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<65536.65536>) Sun 2016-11-06 11:26:29.419: 03: [609844] --> 3801 OK FETCH completed Sun 2016-11-06 11:26:29.421: 02: [609844] <-- 3802 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<131072.65536>) Sun 2016-11-06 11:26:29.421: 03: [609844] --> 3802 OK FETCH completed Sun 2016-11-06 11:26:29.422: 02: [609844] <-- 3803 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<196608.65536>) Sun 2016-11-06 11:26:29.422: 03: [609844] --> 3803 OK FETCH completed Sun 2016-11-06 11:26:29.423: 02: [609844] <-- 3804 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<262144.65536>) Sun 2016-11-06 11:26:29.423: 03: [609844] --> 3804 OK FETCH completed ... Sun 2016-11-06 11:27:03.059: 02: [609844] <-- 36565 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<2147287040.65536>) Sun 2016-11-06 11:27:03.059: 03: [609844] --> 36565 OK FETCH completed Sun 2016-11-06 11:27:03.060: 02: [609844] <-- 36566 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<2147352576.65536>) Sun 2016-11-06 11:27:03.060: 03: [609844] --> 36566 OK FETCH completed Sun 2016-11-06 11:27:03.061: 02: [609844] <-- 36567 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<2147418112.65536>) Sun 2016-11-06 11:27:03.061: 03: [609844] --> 36567 OK FETCH completed Sun 2016-11-06 11:27:03.061: 02: [609844] <-- 36568 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<-2147483648.65536>) Sun 2016-11-06 11:27:03.061: 03: [609844] --> 36568 OK FETCH completed Sun 2016-11-06 11:27:03.062: 02: [609844] <-- 36569 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<-2147418112.65536>) ... Sun 2016-11-06 11:27:36.580: 02: [609844] <-- 69333 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<-196608.65536>) Sun 2016-11-06 11:27:36.580: 03: [609844] --> 69333 OK FETCH completed Sun 2016-11-06 11:27:36.581: 02: [609844] <-- 69334 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<-131072.65536>) Sun 2016-11-06 11:27:36.581: 03: [609844] --> 69334 OK FETCH completed Sun 2016-11-06 11:27:36.582: 02: [609844] <-- 69335 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<-65536.65536>) Sun 2016-11-06 11:27:36.582: 03: [609844] --> 69335 OK FETCH completed Sun 2016-11-06 11:27:36.583: 02: [609844] <-- 69336 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<0.65536>) Sun 2016-11-06 11:27:36.583: 03: [609844] --> 69336 OK FETCH completed Sun 2016-11-06 11:27:36.584: 02: [609844] <-- 69337 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<65536.65536>) Sun 2016-11-06 11:27:36.584: 03: [609844] --> 69337 OK FETCH completed Sun 2016-11-06 11:27:36.585: 02: [609844] <-- 69338 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<131072.65536>) Sun 2016-11-06 11:27:36.585: 03: [609844] --> 69338 OK FETCH completed Sun 2016-11-06 11:27:36.586: 02: [609844] <-- 69339 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<196608.65536>) Sun 2016-11-06 11:27:36.586: 03: [609844] --> 69339 OK FETCH completed Sun 2016-11-06 11:27:36.587: 02: [609844] <-- 69340 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<262144.65536>) Sun 2016-11-06 11:27:36.587: 03: [609844] --> 69340 OK FETCH completed ... ... (It never stops)
> <-- 36567 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<2147418112.65536>) > --> 36567 OK FETCH completed > <-- 36568 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<-2147483648.65536>) > --> 36568 OK FETCH completed It looks that your server returns "null data + OK" to any request on UID=1473, despite that your server returned UID=1473 to any "select Inbox + uid fetch 1:* Flags" from IMAP client. Is "non existent UID to uid fetch 1:* Flags" allowed by protocol named IMAP? IIRC, what allowed is "non existent UID in uid action a:b,c:d,...,y:z from IMAP client" only... When unsigned 32bits integer, 2147418112 = 0x7FFF0000, 2147418112+65536 = 0x80000000 = 2147483648 If the 0xF0000000 is interpreted as 32bits signed integer, it's -2147483648. Because RFC822.SIZE is positive value, Thunderbird perhaps uses 32bits unsigned integer for it. However, the "32bits unsigned integer value" is treated as "32bits signed integer" upon requsting data chunk. Repeated request. > (a) <-- UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) > (b) <-- UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<0.65536>) > <-- UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<2147418112.65536>) > <-- UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]<-2147483648.65536>) Difference between (a) and (b) is perhaps as follows. (a) : header fetch by "uid fetch 1473 RFC822.SIZE... body[header.fields(subject, ...)" is incomplete due to "null data + OK" => retry forever (b) : fetch of entire mail data by auto-sync. because very large RFC822.SIZE was retunrned from your server(perhaps 4GB, or larger than it, maybe ZERO, or not returnred), request data with 65536 bytes chunk(64KB chunk) for the 4GB data length. due to "null data + OK" to any request, fetch of entire data is incomplete => retry forever Is your IMAP server properly configured? If your problem consistently occurs on the UID=1473, why Thunderbird side imap log is still not provided for actual server response data such as RFC822.SIZE, returned headers and so on? "null data + OK only without RFC822.SIZE etc." to any request with UID=1473? If so, Thunderbird may treat "null RFC822.SIZE(or ZERO)/non-returned RFC822.SIZE" as 4GB.
FYI. "No RFC822.SIZE from server -> request 64KB chunk until 4GB" may be a regression by Bug 92111. Due to wrong RFC822.SIZE returned by MS, quirks was implemented for such case. (i) Ignore RFC822.SIZE returned from server. (ii) Request 64KB chunk until server returns EndOfData+OK response. This quirks is applied to any imap server, even if server is pretty well configured and is absolutely RFC compliant. This quirks is not optional for bad server like MS's server only. Thunderbird relies on that any imap server is well configured and is RFC compliant. A Thunderbird's weak point is that he can not work well with pretty bad imap server like MS's one.
First, you assume UID 1473 was returned by UID FETCH 1:*. I assume this was not the case. Currently we have no data to prove either assumption because there is no reproduction of the problem so far. (Please note that we have cranked up the logging of the server and next time we will know.) BTW I did provide an example of how the server reacts to a definitely non-existent message in Comment 8: > a UID fetch 2 (UID RFC822.SIZE BODY.PEEK[]) > a OK FETCH completed And you also see in the mailserver log how it intially reacted to famous message 1473: > Sun 2016-11-06 11:25:42.665: 02: [609844] <-- 174 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) > Sun 2016-11-06 11:25:42.665: 03: [609844] --> 174 OK FETCH completed Is that what you call "null"? Please note that UID 1473 was only an example for that specific situation (that specific constellation of accounts at that specific point in time).
(In reply to jm from comment #16) > And you also see in the mailserver log how it intially reacted to famous message 1473: > Is that what you call "null"? Yes. > > a UID fetch 2 (UID RFC822.SIZE BODY.PEEK[]) > > a OK FETCH completed > > > Sun 2016-11-06 11:25:42.665: 02: [609844] <-- 174 UID fetch 1473 (UID RFC822.SIZE BODY.PEEK[]) > > Sun 2016-11-06 11:25:42.665: 03: [609844] --> 174 OK FETCH completed Does these server side log mean "no data is returned to client as response to UID fetch 1473" and "OK response only is returned"? If so, phenomenon can be explained. (A) Your server never returns data to "uid fetch 1473 any data" and returns OK response only, if the UID=1473 is non-existent UID for your server. (B) Thunderbird doesn't consider "no response data, OK response only to uid fetch 1473 some-data" as "non-existent UID". (C) Thunderbird can't handle error situation of "no response data+OK to uid fetch 1473 body[] and so on" and "no response data+OK to uid fetch 1473 body[]<Offset.65536>". (D) Thunderbird can't handle error situation of "no RFC822.SIZE data+OK to uid fetch 1473 RFC822.SIZE other-data". (E) Negative offset in "uid fetch 1473 body[]<Offset.65536>" itself is absolutely irrelevant to phenomenon of this bug, because your server's behavior is (A). (i) If UID=1473 was not returned to "select Inbox + uid fetch 1:* Flags" at a cached connection, what Thunderbird does always do at least upon "restart of Thunderbird->open Inbox" and after each "Go Work Offline->go Work Online->open Inbox", Thunderbird considers that the UID=1473 doesn't exist at server and removes all data related to UID=1473 even when Thunderbird already held data relevant to UID=1473. (ii) If UID=1473 was returned to "select Inbox + uid fetch 1:* Flags", Thunderbird creates entry(msgDBHdr) for the UID=1473 if Thunderbird didn't know about it, and accesses to server with the known UID=1473. So, I can't imagine "no UID=1473 in server response to uid fetch 1:* Flags". It's perhaps: - UID=1473 is held in index data of mails at your MDaemon server. - Data relevant to UID=1473 is not held in database for mail data at your MDaemon server. Anyway, please provide server response data to "uid fetch 1:* Flags" what is requested by Thunderbird upon each "restart of Thunderbird->open Inbox" or after each "go Work Offline->go Work Online->open Inbox".
Please find following a new example. You will see that IDs from one account are "bleeding" over to the other account. There are three sessions from that client going on: --- Session 182891 --- Account A --- SELECT Sent --- Mon 2016-11-21 06:51:30.788: 01: [182891] Session 182891; child 0141 Mon 2016-11-21 06:51:30.788: 05: [182891] Accepting IMAP connection from 172.16.1.110:49306 to mail:143 Mon 2016-11-21 06:51:38.324: 01: [182891] Authenticated as A ... Mon 2016-11-21 06:51:41.043: 02: [182891] <-- 13 select "Sent" ... Mon 2016-11-21 06:51:41.277: 02: [182891] <-- 17 UID fetch 1:* (FLAGS) Mon 2016-11-21 06:51:41.277: 03: [182891] --> * 1 FETCH (UID 61 FLAGS (\Seen)) ... Mon 2016-11-21 06:51:41.282: 03: [182891] --> * 196 FETCH (UID 323 FLAGS (\Seen)) Mon 2016-11-21 06:51:41.282: 03: [182891] --> 17 OK FETCH completed Mon 2016-11-21 06:51:41.478: 02: [182891] <-- 18 IDLE Mon 2016-11-21 06:51:41.478: 03: [182891] --> + idling Mon 2016-11-21 07:11:57.003: 04: [182891] Connection timed out Mon 2016-11-21 07:11:57.003: 03: [182891] --> * BYE connection timed out Mon 2016-11-21 07:11:57.003: 01: [182891] IMAP session terminated, (Bytes in/out: 360/11286) This is unspectacular, however the info that there are three concurrent sessions might be important. --- Session 182892 --- Account A --- SELECT Inbox --- Mon 2016-11-21 06:51:33.925: 01: [182892] Session 182892; child 0141 Mon 2016-11-21 06:51:33.925: 05: [182892] Accepting IMAP connection from 172.16.1.110:49308 to mail:143 Mon 2016-11-21 06:51:38.325: 01: [182892] Authenticated as A ... Mon 2016-11-21 06:51:41.769: 02: [182892] <-- 21 select "INBOX" ... Mon 2016-11-21 06:51:41.808: 02: [182892] <-- 23 UID fetch 1:* (FLAGS) Mon 2016-11-21 06:51:41.808: 03: [182892] --> * 1 FETCH (UID 1 FLAGS (\Seen)) Mon 2016-11-21 06:51:41.808: 03: [182892] --> * 2 FETCH (UID 63 FLAGS (\Seen)) ... Mon 2016-11-21 06:51:41.815: 03: [182892] --> * 233 FETCH (UID 1220 FLAGS (\Recent)) Mon 2016-11-21 06:51:41.815: 03: [182892] --> * 234 FETCH (UID 1221 FLAGS (\Recent)) Mon 2016-11-21 06:51:41.815: 03: [182892] --> * 235 FETCH (UID 1222 FLAGS (\Recent)) Mon 2016-11-21 06:51:41.815: 03: [182892] --> 23 OK FETCH completed Account A INBOX highest mail ID is ~ 1222. There indeed is a mail with ID 1221 (this becomes important below). --- Session 182893 --- Account B --- SELECT Inbox --- Mon 2016-11-21 06:51:36.928: 01: [182893] Session 182893; child 0142 Mon 2016-11-21 06:51:36.928: 05: [182893] Accepting IMAP connection from 172.16.1.110:49310 to mail:143 Mon 2016-11-21 06:51:38.332: 01: [182893] Authenticated as B ... Mon 2016-11-21 06:51:42.370: 02: [182893] <-- 35 select "INBOX" ... Mon 2016-11-21 06:51:42.375: 02: [182893] <-- 37 UID fetch 1:* (FLAGS) Mon 2016-11-21 06:51:42.375: 03: [182893] --> * 1 FETCH (UID 4 FLAGS (\Seen)) ... on 2016-11-21 06:51:42.381: 03: [182893] --> * 205 FETCH (UID 535 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 206 FETCH (UID 536 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> 37 OK FETCH completed Mon 2016-11-21 06:51:42.603: 02: [182893] <-- 38 UID fetch 4:5,16:536 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)]) Mon 2016-11-21 06:51:42.614: 03: [182893] --> * 1 FETCH (UID 4 RFC822.SIZE 5446 FLAGS (\Seen) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {412} Mon 2016-11-21 06:51:42.618: 03: [182893] --> * 2 FETCH (UID 5 RFC822.SIZE 19593 FLAGS (\Seen) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {435} ... Mon 2016-11-21 06:51:44.590: 03: [182893] --> * 204 FETCH (UID 534 RFC822.SIZE 1045924 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority Reference s Newsgroups In-Reply-To Content-Type Reply-To)] {403} Mon 2016-11-21 06:51:44.598: 03: [182893] --> * 205 FETCH (UID 535 RFC822.SIZE 11078 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {497} Mon 2016-11-21 06:51:44.617: 03: [182893] --> * 206 FETCH (UID 536 RFC822.SIZE 61359 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {460} Mon 2016-11-21 06:51:44.617: 03: [182893] --> 38 OK FETCH completed *** It is done looking at mails from Account B *** *** Now it starts looking for IDs that can only come from Account A (or it makes them up) *** Mon 2016-11-21 06:51:45.054: 02: [182893] <-- 43 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) Mon 2016-11-21 06:51:45.054: 03: [182893] --> 43 OK FETCH completed Mon 2016-11-21 06:51:45.085: 02: [182893] <-- 44 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) Mon 2016-11-21 06:51:45.085: 03: [182893] --> 44 OK FETCH completed Mon 2016-11-21 06:51:45.090: 02: [182893] <-- 45 UID fetch 1218 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:45.090: 03: [182893] --> 45 OK FETCH completed Mon 2016-11-21 06:51:45.093: 02: [182893] <-- 46 UID fetch 1218 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:45.093: 03: [182893] --> 46 OK FETCH completed Mon 2016-11-21 06:51:45.113: 02: [182893] <-- 47 UID fetch 1219 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:45.113: 03: [182893] --> 47 OK FETCH completed Mon 2016-11-21 06:51:45.203: 02: [182893] <-- 48 UID fetch 1219 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:45.203: 03: [182893] --> 48 OK FETCH completed Mon 2016-11-21 06:51:45.216: 02: [182893] <-- 49 UID fetch 1220 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:45.216: 03: [182893] --> 49 OK FETCH completed Mon 2016-11-21 06:51:45.220: 02: [182893] <-- 50 UID fetch 1220 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:45.220: 03: [182893] --> 50 OK FETCH completed Mon 2016-11-21 06:51:45.223: 02: [182893] <-- 51 UID fetch 1221 (UID RFC822.SIZE BODY.PEEK[]<0.65536>) Mon 2016-11-21 06:51:45.223: 03: [182893] --> 51 OK FETCH completed Mon 2016-11-21 06:51:45.224: 02: [182893] <-- 52 UID fetch 1221 (UID RFC822.SIZE BODY.PEEK[]<65536.65536>) Mon 2016-11-21 06:51:45.224: 03: [182893] --> 52 OK FETCH completed Mon 2016-11-21 06:51:45.225: 02: [182893] <-- 53 UID fetch 1221 (UID RFC822.SIZE BODY.PEEK[]<131072.65536>) Mon 2016-11-21 06:51:45.225: 03: [182893] --> 53 OK FETCH completed Mon 2016-11-21 06:51:45.226: 02: [182893] <-- 54 UID fetch 1221 (UID RFC822.SIZE BODY.PEEK[]<196608.65536>) Mon 2016-11-21 06:51:45.226: 03: [182893] --> 54 OK FETCH completed ... ... ... Account B INBOX highest mail ID is ~ 536. Clearly, there is no reason to ask for any message ID > 536 in Account B (session 182893). You see that ID 1221 must clearly something be coming from information pertaining to Account A. The main problem thus is: Why does Account B try to poll an ID existing only in Account A? The secondary problem is: Why does it start to loop if that mail does not exist? (If it would be polling the correct account in the first place, that problem probably would not exist, but it still is a problem.)
(In reply to jm from comment #18) > Account B INBOX highest mail ID is ~ 536. > Clearly, there is no reason to ask for any message ID > 536 in Account B (session 182893). > You see that ID 1221 must clearly something be coming from information pertaining to Account A. > The main problem thus is: Why does Account B try to poll an ID existing only in Account A? It seems that non-existent UID doesn't come from "uid fetch 1:* Flags" just after restart. (Q1) Is it sure that there is no UID=1214:1222 in any mbox of any account of your MDaemon server except AccountA/Inbox? Single PC/single Thunderbird, so the UID=1214:1222 surely came from Thunderbird activity on different account/different mbox? "Session" and # of it is identifier in your MDaemon. > --- Session 182891 --- Account A --- SELECT Sent --- [182891] Session 182891; child 0141 > --- Session 182892 --- Account A --- SELECT Inbox --- [182892] Session 182892; child 0141 > --- Session 182893 --- Account B --- SELECT Inbox --- [182893] Session 182893; child 0142 In OS/Socket level, call it "Cached-Connection", as called in Thunderbird. 1. Cached-Connection-X/Sent of PC-A-Thunderbird-A <-> Session for AccountA/Sent in MDaemon 2. Cached-Connection-Y/Inbox of PC-A-Thunderbird-A <-> Session for AccountA/Inbox in MDaemon 3. Cached-Connection-Z/Inbox of PC-B-Thunderbird-B <-> Session for AccountB/Inbox in MDaemon If mapping between OS/Socket level Cached-Connection <-> SessionID/childID in MDaemon is somehow changed, such phenomenon can occur. (Q2) No such bug in MDaemon? Is MDaemon newest version? (Q3) Was following actually sent by PC-B-Thunderbird-B for AccountB/Inbox?? It was sent from PC-A-Thunderbird-A for AccountA/Inbox, wasn't it? > [182893] <-- 43 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) (Q4) PC-A and PC-B in above context is PC-A === PC-B? PC-A-Thunderbird-A === PC-B-Thunderbird-B? BODY.PEEK[TEXT]<0.2048> is issued by Thunderbird upon new mail detection in order to get top 2048 bytes of mail body for showing top part of body data in new mail alert. Because it looks that IDLE is used in your environment, the newly detected mails(UID=1214:1222 in this case) was perhaps notified from server to Thunderbird via IDLE instead of upon first access to Inbox just after restart. It may be bug in "New mail alert" of Thunderbird, but I still suspect server side problem. (Q5) What happened at [182893] just before following was logged? If it was "notification via IDLE for UID=1214:1222", phenomenon is explained. (Q6) What happened at "[182891] Session 182891; child 0141" and "[182892] Session 182892; child 0141" when following was logged? > Mon 2016-11-21 06:51:45.054: 03: [182893] --> 43 OK FETCH completed > Mon 2016-11-21 06:51:45.085: 02: [182893] <-- 44 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) Because nothing occurs while IDLE state(max 30 minutes) unless event like "new mail" occurs at server, or unless IMAP client sends DONE and terminate IDLE state and sends next IMAP command, "Swapping out all resources related to a Session" like technique is used in many cases. (Q7) No problem in IDLE support etc. in MDaemon? "Order Received" column value in Thunderbird is messageKey, and if IMAP folder, UID is used for the messageKey in Thunderbird. (Q8) What is shown for UID=1214:1222 at PC-A-Thunderbird-A/Sent, PC-A-Thunderbird-A/Inbox, and PC-B-Thunderbird-B/Inbox? (Q9) Are you employee of MDaemon support company? Anyway, because it looks that your problem occurs so frequently, if imap logging is enabled all time at a Thunderbird in your environment, I think "Thunderbird side imap log when problem occurred" can be obtained. > The secondary problem is: Why does it start to loop if that mail does not exist? > (If it would be polling the correct account in the first place, that problem probably would not exist, but it still is a problem.) See my comment #17, please.
Another funny phenomenon. > Mon 2016-11-21 06:51:45.054: 03: [182893] --> 43 OK FETCH completed > Mon 2016-11-21 06:51:45.085: 02: [182893] <-- 44 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) > Mon 2016-11-21 06:51:45.085: 03: [182893] --> 44 OK FETCH completed > Mon 2016-11-21 06:51:45.090: 02: [182893] <-- 45 UID fetch 1218 (UID RFC822.SIZE BODY.PEEK[]) > Mon 2016-11-21 06:51:45.090: 03: [182893] --> 45 OK FETCH completed > | > Mon 2016-11-21 06:51:45.220: 02: [182893] <-- 50 UID fetch 1220 (UID RFC822.SIZE BODY.PEEK[]) > Mon 2016-11-21 06:51:45.220: 03: [182893] --> 50 OK FETCH completed > Mon 2016-11-21 06:51:45.223: 02: [182893] <-- 51 UID fetch 1221 (UID RFC822.SIZE BODY.PEEK[]<0.65536>) > | > Mon 2016-11-21 06:51:45.226: 02: [182893] <-- 54 UID fetch 1221 (UID RFC822.SIZE BODY.PEEK[]<196608.65536>) > Mon 2016-11-21 06:51:45.226: 03: [182893] --> 54 OK FETCH completed Why BODY.PEEK[] for UID=18 to 20 but BODY.PEEK[]<Offset.65536> for UID=21? It's parhaps because "message size in unsol response for new mail via IDLE" is dsifferent. If large size, Thunderbird gets mail data by 64KB chunk. Anyway, without actual response data from server to Thunderbird, all is always "guess" only.
> (Q1) Is it sure that there is no UID=1214:1222 in any mbox of any account of your MDaemon server except AccountA/Inbox? Since we have thousands of accounts, I wouldn't be able to tell. > In OS/Socket level, call it "Cached-Connection", as called in Thunderbird. > 1. Cached-Connection-X/Sent of PC-A-Thunderbird-A <-> Session for AccountA/Sent in MDaemon > 2. Cached-Connection-Y/Inbox of PC-A-Thunderbird-A <-> Session for AccountA/Inbox in MDaemon > 3. Cached-Connection-Z/Inbox of PC-B-Thunderbird-B <-> Session for AccountB/Inbox in MDaemon No! It's the same PC and the same Thunderbird. Only different accounts inside same Thunderbird. There is no PC-B. It's all from the same IP address and same PC and same Thunderbird process. > (Q2) No such bug in MDaemon? Is MDaemon newest version? No, not 100% up-to-date. But almost. > (Q5) What happened at [182893] just before following was logged? > If it was "notification via IDLE for UID=1214:1222", phenomenon is explained. Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 199 FETCH (UID 529 FLAGS (\Seen)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 200 FETCH (UID 530 FLAGS (\Seen)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 201 FETCH (UID 531 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 202 FETCH (UID 532 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 203 FETCH (UID 533 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 204 FETCH (UID 534 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 205 FETCH (UID 535 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 206 FETCH (UID 536 FLAGS (\Recent)) Mon 2016-11-21 06:51:42.381: 03: [182893] --> 37 OK FETCH completed Mon 2016-11-21 06:51:42.603: 02: [182893] <-- 38 UID fetch 4:5,16:536 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)]) ... Mon 2016-11-21 06:51:44.590: 03: [182893] --> * 204 FETCH (UID 534 RFC822.SIZE 1045924 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {403} Mon 2016-11-21 06:51:44.598: 03: [182893] --> * 205 FETCH (UID 535 RFC822.SIZE 11078 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {497} Mon 2016-11-21 06:51:44.617: 03: [182893] --> * 206 FETCH (UID 536 RFC822.SIZE 61359 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {460} Mon 2016-11-21 06:51:44.617: 03: [182893] --> 38 OK FETCH completed Mon 2016-11-21 06:51:44.931: 02: [182893] <-- 39 UID fetch 1214 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:44.931: 03: [182893] --> 39 OK FETCH completed Mon 2016-11-21 06:51:44.936: 02: [182893] <-- 40 UID fetch 1215 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:44.936: 03: [182893] --> 40 OK FETCH completed Mon 2016-11-21 06:51:44.948: 02: [182893] <-- 41 UID fetch 1216 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:44.948: 03: [182893] --> 41 OK FETCH completed Mon 2016-11-21 06:51:44.952: 02: [182893] <-- 42 UID fetch 1217 (UID RFC822.SIZE BODY.PEEK[]) Mon 2016-11-21 06:51:44.952: 03: [182893] --> 42 OK FETCH completed Mon 2016-11-21 06:51:45.054: 02: [182893] <-- 43 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) Mon 2016-11-21 06:51:45.054: 03: [182893] --> 43 OK FETCH completed Mon 2016-11-21 06:51:45.085: 02: [182893] <-- 44 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) Mon 2016-11-21 06:51:45.085: 03: [182893] --> 44 OK FETCH completed Mon 2016-11-21 06:51:45.090: 02: [182893] <-- 45 UID fetch 1218 (UID RFC822.SIZE BODY.PEEK[]) > (Q9) Are you employee of MDaemon support company? No, we are the end user, and this time we will get to the bottom of this. > Anyway, because it looks that your problem occurs so frequently, if imap logging is enabled all time at a Thunderbird in your environment, I think "Thunderbird side imap log when problem occurred" can be obtained. We can't just enable IMAP log on a thousand workstations. We have to work with what we have on the server and some admin workstations. I have another idea. It looks like PC department might have messed up TB profiles for some users on network drive (different accounts having same "Local directory" in "Server Settings"). I'll get back to you on that. Concerning Comment 19: > Does these server side log mean "no data is returned to client as response to UID fetch 1473" and "OK response only is returned"? > If so, phenomenon can be explained. > (A) Your server never returns data to "uid fetch 1473 any data" and returns OK response only, if the UID=1473 is non-existent UID for your server. > (B) Thunderbird doesn't consider "no response data, OK response only to uid fetch 1473 some-data" as "non-existent UID". Maybe it should, see RFC 3501: > 6.4.8. UID Command > > A non-existent unique identifier is ignored without any error > message generated. Thus, it is possible for a UID FETCH command > to return an OK without any data or a UID COPY or UID STORE to > return an OK without performing any operations.
(In reply to jm from comment #21) > > (Q5) What happened at [182893] just before following was logged? > > If it was "notification via IDLE for UID=1214:1222", phenomenon is explained. > > Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 199 FETCH (UID 529 FLAGS (\Seen)) > | > Mon 2016-11-21 06:51:42.381: 03: [182893] --> * 206 FETCH (UID 536 FLAGS (\Recent)) > Mon 2016-11-21 06:51:42.381: 03: [182893] --> 37 OK FETCH completed > Mon 2016-11-21 06:51:42.603: 02: [182893] <-- 38 UID fetch 4:5,16:536 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)]) > ... > Mon 2016-11-21 06:51:44.598: 03: [182893] --> * 205 FETCH (UID 535 RFC822.SIZE 11078 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {497} > Mon 2016-11-21 06:51:44.617: 03: [182893] --> * 206 FETCH (UID 536 RFC822.SIZE 61359 FLAGS (\Recent) BODY[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type Reply-To)] {460} > Mon 2016-11-21 06:51:44.617: 03: [182893] --> 38 OK FETCH completed > > Mon 2016-11-21 06:51:44.931: 02: [182893] <-- 39 UID fetch 1214 (UID RFC822.SIZE BODY.PEEK[]) > Mon 2016-11-21 06:51:44.931: 03: [182893] --> 39 OK FETCH completed > Mon 2016-11-21 06:51:44.936: 02: [182893] <-- 40 UID fetch 1215 (UID RFC822.SIZE BODY.PEEK[]) > Mon 2016-11-21 06:51:44.936: 03: [182893] --> 40 OK FETCH completed > Mon 2016-11-21 06:51:44.948: 02: [182893] <-- 41 UID fetch 1216 (UID RFC822.SIZE BODY.PEEK[]) > Mon 2016-11-21 06:51:44.948: 03: [182893] --> 41 OK FETCH completed > Mon 2016-11-21 06:51:44.952: 02: [182893] <-- 42 UID fetch 1217 (UID RFC822.SIZE BODY.PEEK[]) > Mon 2016-11-21 06:51:44.952: 03: [182893] --> 42 OK FETCH completed > Mon 2016-11-21 06:51:45.054: 02: [182893] <-- 43 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) > Mon 2016-11-21 06:51:45.054: 03: [182893] --> 43 OK FETCH completed > Mon 2016-11-21 06:51:45.085: 02: [182893] <-- 44 UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048>) > Mon 2016-11-21 06:51:45.085: 03: [182893] --> 44 OK FETCH completed > Mon 2016-11-21 06:51:45.090: 02: [182893] <-- 45 UID fetch 1218 (UID RFC822.SIZE BODY.PEEK[]) If request for UID=1214 to 1222 here is for new mail at this connection(this account/this mbox), first request should be "uid fetch list-of-uids (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From ... Reply-To)])" for message header fetch, as done in 38. However, first request for the UID=1214:1222 in log is: > UID fetch xxx (UID RFC822.SIZE BODY.PEEK[]) for UID=1214 to 1222 > UID fetch 1214:1222 (UID BODY.PEEK[HEADER.FIELDS (Content-Type Content-Transfer-Encoding)] BODY.PEEK[TEXT]<0.2048> It may be; - Filter move at other account/mbox(AccountA, move from Inbox to Other, is suspected). If so, it's "move within an account"(move is copy+store \deleted, or uid move xxx Target), - Or, if Body is contained in filter condition, entire mail body is fetched for Body condition. - Request while/after filter move is requested or dispatched at other cached connection. "other cached connection" may be one for same account, but may be one for different account. - Even if "request after filter move at move Target" is lost, moved mail will be fetched sooner or later at move Target folder. - Even if "fetch entire mail for Body condition" is executed at different connection, fetch result is perhaps notified to filter. (Q10) What happened at Inbox of AccountA around above logs? If requested UID exists, data is normally returned. If requested UID doesn't exist, server usually returns NO. In this case, IIRC, error is notified or reported at activity manager. However, if error during filter move, error may not be reported. If server returns "no data + OK only" when non-existent UID, phenomenon you saw occurs. Following is list of bugs relevant to new mail notification which was found by quick search for "new mail notification". > Bug 375717 - New mail notification (mail alert/preview text) shows old items > Bug 516010 - new mail notifications shows mismatched subjects and message excerpts > Bug 654447 - new mail pop-up often notifies of previous read email not new email > Bug 918141 - Wrong count of new messages in notification > Bug 1292963 - New email notification is empty with concurrent filtering operation, neither completes This kind of phenomenon may be relevant to problem you saw.
Note: Multiple IMAP accounts of same server/different userID in a Thunderbird, is usually rare condition.
(In reply to WADA from comment #23) > Note: Multiple IMAP accounts of same server/different userID in a > Thunderbird, is usually rare condition. If you mean rare as in less than 1 percent, I would not be so sure. I'll bet many business users have more than one account on same server. For example, I (but not using myself as being statistically significant) have about 10 gmail accounts and 3 work accounts.
FYI. Simplest case : duplicate accounts due to bug 303542. Account-1 : Initially defined with Host1/User1, then changed to HostX/UserX hostname =Host1 / userName =User1 realhostname=HostX / realuserName=UserX <=used in login Account-2 : Defined with Host1/User1 => hostname=Host1/userName=User1 is used. <= used in login no realhostname / no realuserName If this occurs, following can happen. AccountA : internal url=imap://UserB%40x%2Ey%2Ez@HostB:143 <==== same as AccountB type=imap,port=143 hostname =HostB / userName =UserB@x.y.z <==== same as AccountB realhostname=HostA / realuserName=UserA@x.y.z <= used in login AccountB : internal url=imap://UserB%40x%2Ey%2Ez@HostB:143 <==== same as AccountA type=imap,port=143 hostname=HostB/userName=UserB@x.y.z <= used in login And, power user knows "Manual Config" in auto-config and "server name/user name change" in account setting. When both are accessed at different time, there is perhaps no problem. However, if access to Inbox happened same time at both AccountA and AccountB, imap command may be sent to other connection due to same internal url, and imap response may be passed to other account due to same internal url. Following is imap log of imap request(list %, list %/% at INBOX) for imap account with hostname=imap.gmail.com,userName=yatter.one@gmail.com. > [12584] 8680[cf01fb0]: e971800:imap.gmail.com:S-INBOX:ProcessCurrentURL:imap://yatter%2Eone%40gmail%2Ecom@imap.gmail.com:993/listfolder%3E/INBOX: = currentUrl Unieque-key for request looks ServerURL+FolderPath generated from hostname+userName. If duplicate account happens, and if special condition happens, request may be sent to different account due to duplicate internal url. Following is imap log of "uid fetch" command response at connection(INBOX is already selected) for imap account with hostname=imap.gmail.com. > 8680[cf01fb0]: e971800:imap.gmail.com:S-INBOX:CreateNewLineFromSocket: > * 3 FETCH (UID 67040 FLAGS (\Seen)) As seen in log, unieque-key looks hostname+FolderPath when response. If duplicate account happens, and if special condition happens, this response may be passed to different account due to duplicate internal url. (In reply to Wayne Mery (:wsmwk, NI for questions) from comment #24) > (In reply to WADA from comment #23) > For example, I (but not using myself as being statistically significant) have > about 10 gmail accounts and 3 work accounts. Free mail accounts case is foul play :-) We can get many free accounts from Gmail, Yahoo!, MS etc. I also have 6 Gmail accounts, 3 Yahoo! accounts, 4 Yahoo! Japan accounts, 2 MS accounts, .... But I don't think such many free mail addresses are freely used in business environment. In corporate environment, I think many companies prohibit access to external mail server for security reason.
Flags: needinfo?(jm+mozbugz)
See Also: → 1770811

The reporter, jm, appears to be gone. Shall we call this a duplicate of bug 1770811. Or incomplete?

Flags: needinfo?(gds)

I looked at this bug a while back here bug 1770811 comment 25 and wasn't sure if it was a dup. But maybe it is since both were endless loops asking the server for something. So I would go with just closing this as a duplicate of bug 1770811.

Flags: needinfo?(gds)
Status: UNCONFIRMED → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: