1842655 - Network unavailability affects oauth2 authentication and future mail updates - Get Messages (get new messages) not triggered automatically when network connectivity returns

Status: RESOLVED DUPLICATE of bug 1854586

(Thunderbird :: General, defect, P2)

Description

[Alex Franchuk [:afranchuk]]

Lately my network connection has been inconsistent. A few times now I've found that if the network is unavailable when Thunderbird (115.0b1) starts up, it doesn't seem to update mail again until I manually trigger a message retrieval (potentially hours later). I would have expected it to retrieve mail correctly whenever the connection was present during a periodic update (I have my server set up to be checked every 10 minutes).

It's unclear what is failing when the IMAP folders are polled. I can try to simulate the situation (as my connection has since stabilized) with additional logging. Maybe this has something to do with the Allow immediate server notifications when new messages arrive setting (which I have enabled)?

Comment 1

[Richard Leger]

Hi Wayne,

Fyi, I noticed this as well, I can confirm currently happening in 115.0b6 (64-bit) on Windows 10. Seems to be a regression.

If Thunderbird is already opened on Inbox folder for example, you lost connectivity for a while, and the network status change from disconnected to connected, TB seems no longer able to detect the change of network connectivity status and run a Get Messages by itself automatically as connectivity returns.

The current workarounds are either to:

• click the Get Messages manually
• click on another folder and click back on the original one (e.g Inbox) which trigger the Get Messages
• wait for delay that triggered automatic Get Messages every now and then - During the delay you therefore not receiving any new emails.

Thought to let you know for info.

Regards,
Richard

Comment 2

[Richard Leger]

Fyi, some end-users also reported TB not checking for email at startup, that may be related to this bug as well possibly:
https://thunderbird.topicbox.com/groups/beta/Ta81baa6528150ede/not-checking-for-new-emails-at-startup

Comment 3

[Calum Mackay]

See also bug 1843190, where get new messages doesn't seem to help.

Comment 4

[gene smith]

I tried to simulate the reported problem by moving my laptop out of wifi range, let the attempts to check for new mail timeout and exit the imap threads and then return the laptop to within wifi range and a new message immediately came in. I'm also seeing in the IMAP:4 log a noop request every 1 minutes checking for new mail (set to minimum time) before going out of range and after returning. So it seems to be working for me.

Maybe recording an IMAP:4 log would help as I described here: bug 1843190 comment 12.
If you can duplicate the problem fairly quickly and don't need to record the log for a long time, you can leave off the rotate:N option.
More details on recording the IMAP:4 log are here: https://wiki.mozilla.org/MailNews:Logging
Note: this says to use IMAP:5 but IMAP:4 is produces a more compact and just as useful result.

Comment 5

[Richard Leger]

Attachment: image.png

Fyi, I disable wireless put my computer to sleep while Thunderbird was opened, wait couple of days, awake my computer with TB opened, reconnect the wireless network. No new email arriving in Inbox with the attached appearing in the status bar... they may appear themselves after the option "check for messages every X minutes" delay has passed... while TB shall be able to receive them immediately as soon as network is reconnected.

Comment 6

[gene smith]

they may appear themselves after the option "check for messages every X minutes" delay has passed.

Looks like the first attempt to connect and poll for new message after the computer woke up couldn't get the connection for some reason "Looked up" staying for a long time means that (usually, for me).

Comment 7

[Alex Franchuk [:afranchuk]]

I was able to somewhat trivially reproduce this. I closed (exited) Thunderbird, turned off my internet connection, then opened Thunderbird. For good measure I waited about 10 minutes; during this time I sent an email to the account that is configured in Thunderbird. I then turned my internet connection back on. I waited for about an hour but Thunderbird never attempted to retrieve mail. Then I clicked Get Messages and the mail came in.

I did this with IMAP:4 logging. Below is the log before it stopped polling. No other log statements came out until I manually triggered a message retrieval.

2023-07-19 12:13:28.418685 UTC - [Parent 4985: Main Thread]: I/IMAP check for auth'd:imap://[e-mail]@imap.gmail.com:993/discoverallboxes
2023-07-19 12:13:28.418876 UTC - [Parent 4985: IMAP]: D/IMAP ImapThreadMainLoop entering [this=7f2b59a3c900]
2023-07-19 12:13:28.419145 UTC - [Parent 4985: Main Thread]: I/IMAP check for auth'd:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:13:28.419148 UTC - [Parent 4985: Main Thread]: I/IMAP no auth, cnt 1 & no TLS error - q URL:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:13:28.419149 UTC - [Parent 4985: Main Thread]: I/IMAP queuing url:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:13:28.428152 UTC - [Parent 4985: Main Thread]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2023-07-19 12:13:28.428176 UTC - [Parent 4985: Main Thread]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:SetupSinkProxy: got m_imapMailFolderSink
2023-07-19 12:13:28.428188 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:ProcessCurrentURL: entering
2023-07-19 12:13:28.428192 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:ProcessCurrentURL:imap://[e-mail]:993/discoverallboxes:  = currentUrl
2023-07-19 12:13:28.444731 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b001e
2023-07-19 12:13:28.447765 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:TellThreadToDie: close socket connection
2023-07-19 12:13:28.447769 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:CreateNewLineFromSocket: (null)
2023-07-19 12:13:28.447771 UTC - [Parent 4985: IMAP]: D/IMAP SetConnectionStatus(0x804b001e)
2023-07-19 12:13:28.447774 UTC - [Parent 4985: IMAP]: D/IMAP URL failed with code 0x804b001e (imap://[e-mail]:993/discoverallboxes)
2023-07-19 12:13:28.452913 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b59a3c900:imap.gmail.com:NA:ProcessCurrentURL: aborting queued urls
2023-07-19 12:13:28.458641 UTC - [Parent 4985: IMAP]: D/IMAP ImapThreadMainLoop leaving [this=7f2b59a3c900]
2023-07-19 12:13:28.568361 UTC - [Parent 4985: Main Thread]: I/IMAP check for auth'd:imap://[e-mail]@imap.gmail.com:993/discoverallboxes
2023-07-19 12:13:28.568591 UTC - [Parent 4985: IMAP]: D/IMAP ImapThreadMainLoop entering [this=7f2b4f503f00]
2023-07-19 12:13:28.568618 UTC - [Parent 4985: Main Thread]: I/IMAP check for auth'd:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:13:28.568621 UTC - [Parent 4985: Main Thread]: I/IMAP no auth, cnt 1 & no TLS error - q URL:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:13:28.568622 UTC - [Parent 4985: Main Thread]: I/IMAP queuing url:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:13:28.576922 UTC - [Parent 4985: Main Thread]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:SetupWithUrlCallback: clearing IMAP_CONNECTION_IS_OPEN
2023-07-19 12:13:28.576943 UTC - [Parent 4985: Main Thread]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:SetupSinkProxy: got m_imapMailFolderSink
2023-07-19 12:13:28.577078 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:ProcessCurrentURL: entering
2023-07-19 12:13:28.577082 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:ProcessCurrentURL:imap://[e-mail]:993/discoverallboxes:  = currentUrl
2023-07-19 12:13:28.587905 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b001e
2023-07-19 12:13:28.592211 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:TellThreadToDie: close socket connection
2023-07-19 12:13:28.592215 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:CreateNewLineFromSocket: (null)
2023-07-19 12:13:28.592217 UTC - [Parent 4985: IMAP]: D/IMAP SetConnectionStatus(0x804b001e)
2023-07-19 12:13:28.592220 UTC - [Parent 4985: IMAP]: D/IMAP URL failed with code 0x804b001e (imap://[e-mail]:993/discoverallboxes)
2023-07-19 12:13:28.592730 UTC - [Parent 4985: IMAP]: I/IMAP 7f2b4f503f00:imap.gmail.com:NA:ProcessCurrentURL: aborting queued urls
2023-07-19 12:13:28.592743 UTC - [Parent 4985: IMAP]: D/IMAP ImapThreadMainLoop leaving [this=7f2b4f503f00]
2023-07-19 12:23:41.549226 UTC - [Parent 4985: Main Thread]: I/IMAP check for auth'd:imap://[e-mail]@imap.gmail.com:993/discoverallboxes
2023-07-19 12:23:41.549250 UTC - [Parent 4985: Main Thread]: I/IMAP no auth, cnt 0, pwd empty & no win - q URL:imap://[e-mail]@imap.gmail.com:993/discoverallboxes
2023-07-19 12:23:41.549257 UTC - [Parent 4985: Main Thread]: I/IMAP queuing url:imap://[e-mail]@imap.gmail.com:993/discoverallboxes
2023-07-19 12:23:41.549332 UTC - [Parent 4985: Main Thread]: I/IMAP check for auth'd:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:23:41.549338 UTC - [Parent 4985: Main Thread]: I/IMAP no auth, cnt 0, pwd empty & no win - q URL:imap://[e-mail]@imap.gmail.com:993/select>/INBOX
2023-07-19 12:23:41.549343 UTC - [Parent 4985: Main Thread]: I/IMAP queuing url:imap://[e-mail]@imap.gmail.com:993/select>/INBOX

Comment 8

[Wayne Mery (:wsmwk)]

Log is useful?

Comment 9

[gene smith]

(In reply to Wayne Mery (:wsmwk) from comment #8)

Log is useful?

Yes it is. This is interesting:

I/IMAP no auth, cnt 0, pwd empty & no win - q URL:imap://[e-mail]:993/select>/INBOX

Seems to have lost the password/authentication token somehow. Need know how the reporter is authenticating. Since gmail it must be oauth2. Is there a master password being used?

Comment 10

[gene smith]

I'm seeing the problem with gmail as described in comment 7. With TB started with network off it keeps repeating the "no auth, cnt 0 ..." stuff on every check for new message interval even after the network is turned back on and never attempts to make a connection to the server.
However with a plain password server with just TLS security this doesn't happen and connection occur on next check message interval once the network returns.
I'll debug this now.
Probably don't need more info from reporter so clearing the NI.

Comment 11

[gene smith]

Attachment: oauth2-wont-login-with-net-initially-down.diff

The attached patch fixes the problem as described in comment 0 by Alex Franchuk. I don't think it addresses the other comments by Richard Leger and Calum McKay.

It's caused by an issue I've seen before. With oauth2 (e.g., gmail) the password (actually a random looking token string) appears to be empty when it's not. I need to look closer at this before submitting a formal patch for approval.

Comment 12

[Wayne Mery (:wsmwk)]

So not a regression?

Comment 13

[gene smith]

I think it's a regression of Bug 1768121 as described in bug 1854586 comment 9 3rd paragraph. I think this bug (bug 1842655) and bug 1854586 are pretty much duplicates.
My proposed fix is to revert the changes of bug 1768121 and other bugs that it caused as in this try build: https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=b05198b4024b2e85054dc11f1884b09a32723244
However, this would leave bug 1768121 unfixed, which is a pretty rare problem, I think.

Comment 14

[Richard Leger]

Fyi, it seems to affect TB 119.0b6 (64-bit), I often have to press the Get Message button to have my Inbox updated especially if TB is already open when the network is getting re-connected after a period of disconnection. TB still does not detect network change and do not run automatically Get Message upon network re-connection it seems.

Comment 15

[gene smith]

Hi Richard,
The only bug I was able to duplicate (and know of a fix for) is if tb is started with the network down and then the network comes back. The last time I tried to duplicate what you describe: "Tb and network working ok, then network goes down for a while and then comes back and TB doesn't get new mail without clicking Get Messages" I wasn't able to duplicate.
I tested this extensively with Calum Mackay in bug 1843190.
Richard, you do have "check for new messages every X minutes" set? Also, curious how you are loosing you network connection. Maybe the way I tested it doesn't have the same effect as how your network connection is lost.
Can you duplicate the problem just by disabling and then enabling wifi/ethernet in windows with TB running?

Comment 16

[Richard Leger]

Hi Gene,

Thank you for your attempt to look into it.
I haven't been really be able myself to reproduce the issue easily at will, I just notice it, when it happens. It could be linked to bug 1843190 as it tends to happen more after several hours indeed.

(In reply to gene smith from comment #15)

The only bug I was able to duplicate (and know of a fix for) is if tb is started with the network down and then the network comes back. The last time I tried to duplicate what you describe: "Tb and network working ok, then network goes down for a while and then comes back and TB doesn't get new mail without clicking Get Messages" I wasn't able to duplicate.

I mean that TB does not immediately run Get Message upon network status change it seems.
Is it maybe happening only after a while or in certain circumstance quite possible.

Richard, you do have "check for new messages every X minutes" set?

I do have TB set to check for new message every 5mn but that mean if I access TB while my network was down and it is re-established, I have to wait for 5mn before getting new messages.
This means I miss messages because I think I have not received any message so I may start another task to discover later that I have received 20msg suddenly out of the blue which were not in the view before, while they were send/received before I re-connected!

Also, curious how you are loosing you network connection.

I use a 4G mobile connection on my phone so sometime I am away from the computer, it gets disconnected from the network while TB remains open, when I come back it re-connects automatically to the network, but TB does not immediately run the Get Messages upon network status change such as a re-connection (or a VPN connection established for example, some may access emails only via such connection, this is just to give an idea of possible network status change that may occur but they could be many reason for the network to disconnect or change, even just temporarily).
This may also happen if your computer goes to sleep and is restarted from sleep... assuming that network is disconnected in sleep mode. Hope that make sense.

Maybe the way I tested it doesn't have the same effect as how your network connection is lost.

Well if you wait 5-10mn as your "check for new messages every X minutes" is set, then the message will arrive at some point, I am more referring to the ability of TB not to have to wait for this lapse of time to check for message when the network is re-connected and to do it automatically upon the event of return of network connectivity so I don't have to wait for receiving messages or to think to manually press the Get Message button (which by default is not visible, I had to add it manually in the UI), they would pop-up automatically upon (re-)connection...

Can you duplicate the problem just by disabling and then enabling wifi/ethernet in windows with TB running?

Well I don't disable the wifi, I disable or disconnect my Personal Hotspot on the phone simulating a lost of Internet connection. The wifi remain ON on the computer but disconnected. When I re-enable the connection on the phone, the computer re-connect automatically to my phone and Internet.

Perhpas the issue may be more visible if TB attempted to Get Message automatically (as per time delay - every X mn) just before the connection was re-established. I don't really know...

A network (re-)connection with Internet access shall trigger an event in TB that cause it to Get Message immediately upon that event, is that the case? Not just to wait for Xmn delay to expire to do so, which is still convenient as the network connection remain established afterwards.

Ideally with IMAP, message shall be pushed to the email client as soon as received, or network connection re-established and TB is online, no need to wait for Xmn delay... That would be the ideal solution.

Also I am wondering if perhaps it could be link to the Get Message action not being completed after Xmn delay due to network disconnection and then TB retry regularly to every Ymn delay that may increase overtime... a bit like Gmail does... so when network comes back you still have to wait for the Ymn delay to expire before TB get new messages? It is what Gmail does but they show a yellow pop-up warning indicating when Gmail will retry automatically in Ymn time, with a Retry Now button that you can activate manually for immediate check. Not ideal either but at least you can see what is happening... and control it...

Hope that make sense.

Comment 17

[Richard Leger]

I don't know if it may matter, but my IMAP account synchronisation setting are:

• unticked - Keep message in all folders...
  -- in Advanced... Inbox and Inbox>Sent are ticked though, for the account
• Disk Space - Synchronise the most recent 3 days

This way I only cache in Inbox and Sent 3 days worth of email, just in case of network disconnection I can keep accessing recent messages.

Comment 18

[gene smith]

I'm closing this (as described by reporter in comment 0 and comment 7) as a duplicate of of the now resolved bug 1854586 (changes should now be in daily).
Issues raised here by Calum Mackay and Richard Leger, if valid, are probably different bugs.