Closed Bug 1325192 Opened 7 years ago Closed 7 years ago

IMAP4rev1 -- notification of new mail takes hours if max cached server connections > 1 (mobile.charter.net returns UID of new mail to only "uid fetch 1:*" just after "select Inbox")

Categories

(MailNews Core :: Networking: IMAP, defect)

Product:
MailNews Core
Component:
Networking: IMAP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED INVALID

People

(Reporter: jackkistler, Unassigned)

References

Details

User Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:50.0) Gecko/20100101 Firefox/50.0
Build ID: 20161208153507

Steps to reproduce:

This is a followon to bug report 1324077 which, while it was describing the same external symptom devolved into a discussion of the RFC 3501 protocol failure to describe the proper handling of blanks in mailbox names. I have renamed my folder and sub-folder names to eliminate any blanks.

BUT the external symptom persists.

I uninstalled and reinstalled TB as completely as I could. I even lost my address book. 

I created a message to myself and sent it. I waited until the message finally appeared in my inbox, which took an hour and a half. 
During this time someone else sent me a message. It also didn't appear in my INBOX until the message I sent to myself appeared. It took about 40 minutes to appear. Both messages appeared in my INBOX at the same time. I have "Account settings" -> "Server settings" -> "Check for new messages every " set to 10 minutes. 

I have also sent test messages to myself (with it not showing up in my mail box for 10+ minutes), shut down and restarted TB, at which time the message appeared in my INBOX immediately. 

I am running the IMAP logging as given me in bug #1324077 and have log data that can be viewed in my Dropbox at:
https://www.dropbox.com/s/beylj8v6db9khbn/imapi.log?dl=0
for where the message didn't show up after 10 minutes, and I waited 1.5 hours and the message finally showed up in my mailbox.
Then I restarted TB with the trace procedure and sent another test message to myself, waited 13 minutes and clicked the INBOX folder name, then waited another 10 minutes and clicked the "get messages" button. The trace log is at: 
https://www.dropbox.com/s/oyjg78ag8yox1np/imapj.log?dl=0



Actual results:

No external response to either clicking "INBOX" or "Get Messages". After about 1.5 hours, message appears in INBOX folder.


Expected results:

Messages should have appeared in the INBOX after the 10 minute timer timed out, after clicking INBOX folder, or after clicking "Get Messages".
See Also: → 1324077
response to WADA comment #31 in bug 1324077
"Jack Kistler, please check following in STAT response from your server is correct or not.
> "(MESSAGES 1 RECENT 0 UNSEEN 0 UIDNEXT 1001)"

If value of each feild returned from server is incorrect, even when Tb interprets non-quoted mboxname part as mboxname, "imap client including Tb who uses STAT" doesn't try to fetch data for new mail, because "new mail exists or not" is determined from values returned from server.
Because I can't know about "what value is correct value" by your report, explanation only, I'm impossible to know about correctness of values in your imap log."


WADA, I am assuming you meant this comment for this bug report, since bug 1324077 is now all about the server not quoting mboxname on server "STATUS" response. 

I am going to run another test tomorrow morning to verify, but I don't think I saw any action initiated for the 10 minute refresh timeout, when I clicked on the "Inbox" folder name in the client "Inbox" display, or when I clicked on the "Get Messages" button in the "Inbox" display. Actually, after reading the RFC 3501, I may have been mislead into thinking I should have seen TB send a "Select" command for "Inbox" instead, but I didn't see this either. Did I miss it? Now my question is -- what should I be looking for as the initiation of communication for these cases?
I ran a test this morning (I am at UTC-8 -- PST). The log is in my Dropbox at 
https://www.dropbox.com/s/gl7dj2e5t00eb0p/imapk.log?dl=0
I tried to keep it as uncluttered as I could. Here were my steps and the times done (I will use UTC for times); 
19:36:20 Started TB from bat file in admin mode.
19:38:00 Created and sent test message "test2a". Message did not appear in my inbox. I did not check my "sent" folder.
19:40:00 Clicked my "Inbox" folder. No activity shown in the IMAP log.
19:42:00 Clicked the "Get Messages" button.
19:44:00 Closed TB using "File" -> "exit". 

I will run another test; 1) Start TB from the bat file in admin mode, create a test msg "test3a" (subject = test3a), and leave TB up until either I get the message in my inbox or 2 hours passes, then close TB.
Actually left it up for 6 hours. 
IMAP log is at: https://www.dropbox.com/s/o04u6sfsowkbb42/imapl.log?dl=0
I started TB at 21:45:11 UTC
I sent a message with subject = test3a at 21:47:11 UTC
I see in the log where the message was sent at:
2016-12-23 21:47:14.129000 UTC - 6352[c5faa70]: e14c000:mobile.charter.net:A:SendData: To: Jack Kistler <jackkistler@charter.net>

I see in the log where the message was downloaded into the "sent" folder at 2016-12-23 21:47:26.337000 UTC

I see activity in the log that looks about the correct interval for the 10 minute refresh timer at 
2016-12-23 21:55:27.130000 UTC
2016-12-23 22:05:27.029000 UTC
and
2016-12-23 22:15:27.060000 UTC
--- followed by a close socket connection at:
2016-12-23 22:25:27.086000 UTC
--- immediately followed by what looks like a new login negotiation which includes the download of the message into the INBOX via what looks like a client command: 
2016-12-23 22:25:28.352000 UTC - 7208[153986d0]: c989800:mobile.charter.net:S-INBOX:SendData: 9 UID fetch 1564 (UID RFC822.SIZE BODY.PEEK[])
I recommend you to utilize Debugview in your imap log cheking. (see bug 1324077 comment #12)
You can see Tb's activity in imap log without terminating/restarting Thunderbird.

If Inbox is already opened and selected at a cached connection, uid fetch NextUID:* Flags() is issued by Tb upon each new mail check interval, because STATUS command can not be used for "already selected mbox at a cached connection".
Is this logged?

Server response to it is usually for Highest UID which is usually already fetched by imap client, because "new mail exists upon every new mail check even after all new mail was fetched" is usually rare.
  uid fetch 3001:* Flags()
  => response from server is for UID=3000 which imap client already knows if new UID doesn't exist.
  => response from server is for UID=3001 or larger if new mail(new/larger UID) exists in Inbox.
     Imap clients can know about new mail by this response from server.
When I looked your imap log, STATUS for many folders are seen. This merely annoyance for imap log checking.
If you are checking about "new mail in Inbox", I recommend to stop new mail check of other than Inbox.
STATUS may be issued by auto-sync. When checking "new mail in Inbox", I recommend you to stop auto-sync when you want to check imap log.
response to WADA comment #5
I have seen all of those STATUS requests many times and, as you said, have found them more annoying than useful. I have also wondered why it is doing that. 

I like your idea of stopping the auto-sync, but have not been able to find where to turn it off. Please point the way for me?
New mail check for other than Inbox : Folder Properties, Include this folder when new mail check => Uncheck
Auto-sync : Tools,Options,Advanced,General,Config Editor
            mail.server.default.autosync_offline_stores = true -> false
            mail.server.server#.autosync_offline_stores = true -> false, if this row exists
Restart of Thunderbird is usually needed after such change.
If log volume is reduced, log check is easier, so disabling excess log is needed as I already wrote in bug 1324077 comment #22.
WADA, something interesting just happened. I changed the "Maximum nunber of server connections to cache" from the default value of 5 to 1 and now if I click a subfolder then click Inbox my Inbox refreshes immediately. "Get Messages" also works now. I am now checking the timed refresh.
reference WADA comment #7
I checked all folders and all of them seem to have defaulted to unchecked.
response to jackkistler comment #8 
Also, if Inbox is selected clicking it does NOT cause a refresh.
Response to jackkistler #8.
With "Maximum number of server connections to cache" set to 1 timed refresh works. The only thing I see not working is getting a refresh when clicking on Inbox while Inbox is selected.
response to jackkistler # 11 
I put the IMAP log on my Dropbox at https://www.dropbox.com/s/4b7ydiuhqwuxnab/imapn.log?dl=0

response to WADA comment #7
I was unable to find the "auto-sync" options you were pointing me to, as I was unable to find "Config Editor" in "Tools,Options,Advanced,General,Config Editor".
(In reply to Jack Kistler from comment #12)

Tools->Options, Advanced, General Tab, Config Editor button

No hit by Google search for "Config Editor" or "Thunderbird Config Editor"?
FYI.

Difference between "max cached connections > 1" and "max cached connections = 1".
(A) "max cached connections > 1"
Inbox is most important mbox, so 1 connection is dedicated to Inbox, and Inbox is always selected at the connection once opened.
When not selected at any connection, uid fetch 1:* Flags is used upon first open of Inbox.
Server access is done only when required(e.g. header only was fetched. entire mail data is needed to display mail)
When new mail check, uid fetch NextUID:* Flags() is issued to obtain info about new mail from server,
because STATUS command can not be used for mbox already selected at a connection.
For other mbox which is not selected at any connection, STATUS is used to obtain info about new mail from server.
(B) "max cached connections = 1"
If other mbox is selected at only one connection, select state of Inbox is cleared(closed).
Upon new mail check interval, because Inbox is not selected at any connection, STATUS command is used for Inbox.
If Inbox is clicked when other mbox is selected at folder pane,
only one connection is used for Inbox again, and select Inbox, uid fetch 1:* Flsags() is issued,
because NextUID previously Thunderbird knew may be changed at server.
"max cached connections = 1 && no IDLE command use" style is usually ordinal/normal method of mailer on mobile device, because "keeping connection always" == usually "waste of valuable/expensive packets".
(Reply to WADA comment 13)
My mistake. I went the wrong way (tools->options,general tab) Sorry about the misunderstanding. 

I want to make absolutely certain I understand your notation - There is an extreme warning before the list comes up. The current line doesn't even appear the same when copied and pasted. Copy and past gives: 
"mail.server.default.autosync_offline_stores;true" 
I see this is a toggle and have changed it to false. The other line you mentioned doesn't exist as you mentioned as a possibility.

I see the log showing TB using the command "GETQUOTAROOT" but can't find it in RFC 3501. The use and response looks straight forward to my inexperienced eye, but it would be nice if I had a specification to go by.

I am now going to test again with the autosync_offline change.
(In reply to Jack Kistler from comment #16)
> I see the log showing TB using the command "GETQUOTAROOT" but can't find it in RFC 3501.

Many are defined by "rfc for extension" and "extensions server supports" is notified to imap client via. CAPABILITY response.
I just saw something that I am curious about. When I send a message after transmitting the message to the server TB "selects" the "sent" mbox and the server sends the message to TB and TB stores it in the "Sent" folder (which seems to be to be correct). But TB still shows Inbox as selected on my display. but doesn't the server think "Sent" is still selected? Does this cause TB to be confused later? Is TB continuing to communicate to the server thinking "INBOX" is still selected? Does TB always send a select "INBOX" for the interval refresh and the Get Messages? Obviously it must if I have selected another folder and switch to Inbox.
Have you read comment #14? Have you tried to use DebugView for checking log while Thunderbird is running?

Even if Inbox is selected at a cached connection and IDLE is not used, as I wrote, new message is periodically checked by "uid fetch NextUID:* Flags()" at the connection where Inbox is selected, upon each new mail check interval.
If server doesn't return UID of new mails to this request, any imap client can not know about new message which has UID wheree NextUID<=UID.
Server returns UID of new mails to "select Inbox + uid fetch 1:* Flags()" only?
I was unable to get DebugView to run. I am on win8.1, which the website didn't say was supported. 

new message is periodically checked by "uid fetch NextUID:* Flags()" at the connection where Inbox is selected, upon each new mail check interval. This started working when I turned autosync off.

What about my question in comment 18? If Inbox is selected and the last "Select" it saw was "Select Sent" shouldn't TB issue a "Select INBOX" if I click on the Inbox folder?
(In reply to Jack Kistler from comment #20)
> What about my question in comment 18? If Inbox is selected and the last
> "Select" it saw was "Select Sent" shouldn't TB issue a "Select INBOX" if I
> click on the Inbox folder?

Depends on "max cached connections". Read comment #14, please.

> new message is periodically checked by "uid fetch NextUID:* Flags()" at the
> connection where Inbox is selected, upon each new mail check interval.
> This started working when I turned autosync off.

Is your observation and conclusion correct? Are you sure about it? Is there evdence(data what proves it) of it?
(Reply to WADA comment 21
>> new message is periodically checked by "uid fetch NextUID:* Flags()" at the
>>connection where Inbox is selected, upon each new mail check interval.
>> This started working when I turned autosync off.

>Is your observation and conclusion correct? Are you sure about it? Is there evdence(data what proves >it) of it?

No. I just turned autosync off and timed interval works. So I am going to try and find out where it changed.
(Correction to my comment #22

No. I just turned autosync back to "true" and timed interval is still working. Now I have to try and find out where it started working.
(reference to my comments 22 and 23)
See my comments 8, 9, 10, 11, and 12. This is where it all started working -- except for when Inbox is highlighted on my display and I click Inbox. This was the result of changing "Maximum number of server connections to cache" from the default value of 5 to 1.
I just completed two test runs, one with "Maximum number of server connections to cache" = 2 (in my Dropbox at https://www.dropbox.com/s/auhejfywext7mfa/imapo.log?dl=0) and one with "Maximum number of server connections to cache" = 1 (in my Dropbox at https://www.dropbox.com/s/8mk2zw23yggh8ff/imapp.log?dl=0). 

I ran the steps in these session as close to identical as I could to show the differences. 
In test run for max caches = 2:
Max caches = 2            Time (UTC)   Results seen in TB display
Start TB                  18:57:40
Sent test msg "2c"        19:00:00
clicked Inbox             19:01:00     message did NOT appear in Inbox
clicked "Get Message"     19:02:00     message did NOT appear in Inbox
Sent msg 2e               19:03:00
clicked a subfolder AARP  19:04:00
clicked Inbox             19:04:10     messages did NOT appear in Inbox
sent msg 2f               19:05:00
Wait for time interval    19:07:40     messages did NOT appear in Inbox

In test run for max caches = 1:
Max caches = 1            Time (UTC)   Results seen in TB display
Start TB                  19:17:58
Sent test msg "4a"        19:19:00
clicked Inbox             19:19:30     message did NOT appear in Inbox
clicked "Get Message"     19:20:00     message appeared in Inbox
Sent msg 4b               19:20:30
clicked a subfolder AARP  19:21:00
clicked Inbox             19:21:30     message appeared in Inbox
sent msg 4c               19:22:30
Wait for time interval    19:27:58     message appeared in Inbox

I checked on the web and found several hits talking about the reasons for changing the "max cached connections" but all of them were in response to message saying that the max cached connections of the server were exceeded. I didn't see anything in the trace logs where TB and the server communicated anything about the number of caches the server supported. Can you find it in these logs?

I did see where you have to be careful about more than one computer connected to the server on the same account. I have two computers using a master account and a sub account. Now that I have seen the results of changing max cached connections on one computer I changed the same setting to 1 on the other computer and I am seeing the same improvement in the results. 

So the difference is definitely the "Maximum number of server connections to cache" between =1 and >1.
Have you actually read and understood bug 1325192 comment #14?

Complement explanation.
Even when "max cached connection=1", once an mbox is opened and is kept open(selected at folder pane, and no other event happen on other folder", the selected/opened mbox/folder is slected at only one connection.
So, when new mail check interval, uid fetch NextUID:* Flags() is used for the already selected mbox at cached connection.
This is applicable to Inbox too.
So, to force "uid fetch 1:* Flags() for Inbox, "select other-than-Inbox" at the only one connection is needed.
This is achieved by "click other than Inbox, then click Inbox again" if "max cached connections=1".

Even thoghh Thunderbird reuests "uid fetch NextUID:* Flags()" upon each new mail check interval according to rfc3501, why Thunderbird can not obtain info about new mail in Inbox from your server?
Even thoghh Thunderbird reuests "status an-mbox" upon each new mail check interval according to rfc3501, why Thunderbird can not obtain info about new mail in the an-mbox from your server?

What is actual bug of Tb(flaw in code of Tb) in your this bug?

.
I now see the problem and it is the server. When using more than 1 connection to the server the server is failing to return the UID of the unseen messages, so TB can't know to fetch them. The bypass for users is to set the max server connections to 1 and reduce the refresh time interval.

For clarity of other users I am on Win8.1 and my email server is Charter.net. Charter is using code on their server that was supplied by "Openwave Messaging" for IMAP level 4 revision 1 last updated on Apr 4, 2016. Per:
------ 
ID ("name" "Email Mx" "version" "M.9.00.023.01 201-2473-194" "vendor" "Openwave Messaging" "support-url" "http://support.openwave.com" "date" "Mon Apr  4 21:15:22 PDT 2016")
-----------
Thanks for the update
Status: UNCONFIRMED → RESOLVED
Closed: 7 years ago
Component: Untriaged → Networking: IMAP
Product: Thunderbird → MailNews Core
Resolution: --- → INVALID
Summary: IMAP4rev1 -- notification of new mail takes hours → IMAP4rev1 -- notification of new mail takes hours if max cached server connections > 1
Summary: IMAP4rev1 -- notification of new mail takes hours if max cached server connections > 1 → IMAP4rev1 -- notification of new mail takes hours if max cached server connections > 1 (mobile.charter.net returns UID of new mail to only "uid fetch 1:*" just after "select Inbox")
Although this issue is currently closed I have noticed a number of other issues related to Charter and would like to recommend that they be tied together, perhaps marking them as duplicates of each other. Here are the pertinent specifics of why I think this is a good idea. 

 In the efforts I made to debug this problem with the help of WADA I found out that the IMAP server code Charter is (I just checked again today) using produced a trace entry that read

"ID ("name" "Email Mx" "version" "M.9.00.023.01 201-2473-194" "vendor" "Openwave Messaging" "support-url" "http://support.openwave.com" "date" "Mon Apr  4 21:15:22 PDT 2016")"

I think the key items related to this problem in this ID response is that the code was vended by "Openwave Messaging" and the last update was "Mon Apr 4 21:15:22 PDT 2016". It would be interesting to find out when the first failure with TB users using Charter occurred and when Charter installed this version of their IMAP server code. It may also be interested in what other IMAP servers (ATT and gmail come to mind as having been reported here) and finding out whether they also had this version of Openwave Messaging in use at the time of failure and whether or not they received an update or switched to another IMAP server code vendor. 

Also, on the web, I found a news item dated March 02, 2016 04:30 PM Eastern Standard Time that "Synchronoss Technologies" going to acquire (buy out?) Openwave Messaging, which I assume happened shortly there after. Further research on the web implies that the acquisition of Openwave messaging by Synchronoss Technologies occurred the next day, March 3rd.

I also found items on the web that imply that Openwave Messaging changed its name to Unwired Planet, but I was unable to find anything further on this,, not even a web page for Unwired Planet.

Furthermore, attempts to connect to "http://support.openwave.com"  gives a "Server not found" in Firebird.

Also, the Charter web site has directions for connecting Desktops to their IMAP server that is different from that for mobile devices. I have attempted to use those instructions, since I am on a desktop, and it DOES NOT WORK, which leads me to suspect that this is the reason TB uses Charter's "mobile" connection procedure.

With all of this, it looks like Charter is caught in a bad situation that only they can extract themselves from. There must be some way we can encourage them to do so, but I have had no success in reaching anyone at Charter that is even willing to admit that they have a problem. I am unable to change to another IMAP provider. They have become the "only store in town" were I live.

There are two things TB can do to soften the impact of this problem on TB users:
1) Make the default for the number of connections to the server 1. 
2) Prevent users from creating sub-folders with blanks in their names.
Please change the last paragraph to read: 

There are two things TB can do to soften the impact of this problem on TB users that are connected to the Charter mobile IMAP server:
1) Make the default for the number of connections to the server 1. 
2) Prevent users from creating sub-folders with blanks in their names.
(In reply to Jack Kistler from comment #31)
> Please change the last paragraph to read: 
> 
> There are two things TB can do to soften the impact of this problem on TB
> users that are connected to the Charter mobile IMAP server:
> 1) Make the default for the number of connections to the server 1. 
> 2) Prevent users from creating sub-folders with blanks in their names.

These are not "what Tb can do". These are "what user of both Charter net and Thunderbird can do on Thunderbird".
And, it's not sufficient. In addition to above, follwoing is needed.
3) Disable IDLE command use.
   If IDLE is used, Tb issues "uid fetch NextUID:* Flags" upon next new mail check iterval,
   and broken Charter net won't return UID of new mail.
4) If accessed Inbox, click other than Inbox(call MboxXXX) at folder pane of Thunderbird.
   => "select MboxXXX" is issued by Thunderbird => Inbox is de-selected at the only one cached connection.
   => Upon next new mail check interval, one of next is done by Thunderbird.
      a) select Inbox at the only one cached connection -> uid fectch 1:* Flags -> new mail will be detected
      b) Because MboxXXX is selected at the only one cached connection, STATUS Inbox is issued for Inbox
         In this case, Charter net doesn't look to return correct STATUS response.
         -> New mail in Inbox can not be detected by procedure 4).
5) If 4) / b) occurs, following is needed.
5-1) After access of mbox of Cherter net, go Work Offline => all connections with server is closed
5-2) Click account => No mbox is selected at folder pane
     => Go Work Online => Because no mbox is selected, login to server is not done at this step.
     (you can do Subscribe. login/subscribe is done without "select an-mbox" at a cached connection)
5-3) Upon next new mail check interval, Thunderbird logins to server, and does do following.
     select Inbox, uid fetch 1:* Flags, as done upon startup.

After closing of Bug 1324077 and this bug(Bug 1325192) as INVALID, I found bug 1231592.
Same problem as this bug was reported to bug 1231592 comment #16, but other confusions are involved in that bug and bug summary of that bug is mainly for these confusions instead of problem of Charter net found by this bug.
- In IMAP, delete a mail == uid store XX *Flags(\Deleted).
  If IMAP delete model != Just mark as deleted, "UID=XX of Inbox where \Deleted is stored" is not shown at Threaqd pane.
  Because \Deleted flag of IMAP is usually not referred by Web Mail, the "deleted mail in Inbox" is shown by Web mail.
  => User is confused
- Problem of this bug occurs on mail moved to Trash(by delete mail) at Trash or mail moved to Spam(by mark as Junk).
  Problem of this bug occurs on mail moved back to Inbox(from Trash) and mail moved back to Inbox(from Spam).
  => User is confused
 
After it, I found some bugs relevant to Charter net. As usual, some bugs are closed as dup of a bug, and as usual, analysys of problem are not done.
 Bug 1258429 are closed as INVALID, because same error report as Bug 1324077 is involved. (Syntax error when space in mbox name)
 Bug 1274833, Bug 1280816, Bug 1287735 are closed as DUP of Bug 1258429, merely becuase problem with Charter net.
You need to log in before you can comment on or make changes to this bug.