Closed Bug 1708981 Opened 3 years ago Closed 3 years ago

Thunderbird doesn't check my Fastmail account automatically for new mail (actually, not really Fastmail specific)

Categories

(MailNews Core :: Networking: IMAP, defect)

Product:
MailNews Core
Component:
Networking: IMAP
Type:
defect

Tracking

(thunderbird_esr91 wontfix)

Status:
RESOLVED FIXED
Milestone:
94 Branch
Tracking Flags:
Tracking Status
thunderbird_esr91 --- wontfix

People

(Reporter: omgitsraven, Assigned: gds)

References

Details

Attachments

(1 file, 11 obsolete files)

status-idle-fix-v3.patch
29.33 KB, patch
gds
: review+
Details | Diff | Splinter Review

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:88.0) Gecko/20100101 Firefox/88.0

Steps to reproduce:

I have four accounts. All of them are set to "check for new messages at startup". All of them are set to "check for new messages every 1 minutes". When I launch Thunderbird, a moment later, three of my accounts will be marked as having new mail, and the fourth won't. But when I go to "Get Messages > Get All New Messages", suddenly the fourth account also knows that it has new messages.

For what it's worth: the three working ones are gmail accounts, and the one that behaves strangely is a Fastmail account.

Actual results:

I've gone days without knowing that there's been mail waiting for me on Fastmail, even though it's set to check every minute, just because of not happening to click on its folder (which also causes it to check for-real) or clicking "get all new messages" (which I rarely do since it's SUPPOSED to be checking automatically).

Expected results:

It should be checking all the addresses automatically since they're all set to.

Is the Fastmail account an IMAP or POP account?

Component: Untriaged → Networking
Flags: needinfo?(omgitsraven)
OS: Unspecified → Windows 10
Product: Thunderbird → MailNews Core
Hardware: Unspecified → x86_64
Summary: Thunderbird doesn't check all accounts automatically → Thunderbird doesn't check my Fastmail account automatically

It's an IMAP account.

Flags: needinfo?(omgitsraven)
Component: Networking → Networking: IMAP

That seems to get reported periodically, see for example bug 1610807 and friends. Does it work on a new profile? You can create on in Help > Troubleshooting Information, or by starting Thunderbird -p. (For POP3 is was bug 1584861 comment #15.)

I've created a whole new profile, and just confirmed that it's still happening on the new profile too.

See Also: → 1610807, 1707987
Summary: Thunderbird doesn't check my Fastmail account automatically → Thunderbird doesn't check my Fastmail account automatically for new mail

The check new mail on startup only works for Inbox, which I assume is where the reporter is expected new mail. Other folder set to check new mail in them only work on the timed interval (I think). Anyhow, an IMAP:5 log may help to see what is happening during startup. You should see a "select" URL attempted on each Inbox that is configured to check new mail on startup. https://wiki.mozilla.org/MailNews:Logging.

Attached file START-ONLY_imap.log.moz_log (obsolete) —

Here is an imap:5 log of just launching Thunderbird and then closing it once the green progress bar in the lower-right disappears.

Attached file START-THEN-MANUAL_imap.moz_log (obsolete) —

Here is an imap:5 log of launching Thunderbird, then performing a manual "get all new messages", then waiting a moment, then closing Thunderbird.

Attached file START-THEN-AUTO_imap.moz_log (obsolete) —

Here is an imap:5 log of launching Thunderbird, then leaving it open for a few minutes, with all the email accounts set to check for new messages every 1 minute.

All logs show TB doing mostly what it should. On startup, INBOX is imap SELECTed and the server provides TB with the responses to parse. However, for each case the EXISTS response is 0 to 3 (meaning how many messages are setting in the INBOX, old or new) and the RECENT response is 0 meaning the server doesn't have any messages marked unread. A variation of this occurs on all accounts.

On the log START-THEN-MANUAL log, when the get message button is clicked the log shows a NOOP occurring on each server, including fastmail, as it should. The response to each NOOP is empty indicating the server has nothing new to report (no change in RECENT or EXISTS).

Only the START-THEN-AUTO log seems maybe a bit off, not sure. It appears that maybe two timed checks for new mail occurred for the gmail accounts (one minute apart) but only one NOOP was sent to the fastmail server. The timed check also causes NOOP to occur and in all cases there was no RECENT or EXISTS responses indicating there was no new mail on any server, including the fastmail. So, other than that there was only 1 fastmail NOOP during the less than 3 minute log duration, I don't see a problem here either. Leaving TB running for maybe a full 5 minutes instead a less than 3 would probably show TB sending fastmail a NOOP more than once (fastmail was authenticate last so maybe it just got a late start and only did one NOOP).

So a better log might have the fastmail account having received a known new mail and then start TB and record the logs so we see in the logs if the new message is detected or not. So a re-do of the START-THEN-AUTO log with a known new mail present on the fastmail server and with a longer (maybe 5 minute with mail timer at 1 minute) duration would be helpful.
Thanks!

Ok!! I spent ages unable to reproduce the bug while debug mode was running, until I finally realised: it must be something that only occurs after Thunderbird has been open for a sufficiently long time. So I opened it in debug mode before I went to bed, then woke up in the morning and tried sending myself some emails to my fastmail addresses from another account, and I finally caught it in the act!

To clarify one important point: I have two Fastmail email aliases, which both go to separate folders in a single inbox.

Fascinatingly, exactly what happened wasn't quite what I expected:

  1. At 13:03 UTC, I opened the web interface to one of my Gmail accounts in a browser (so Thunderbird wouldn't be involved), and I emailed raven.works@raven.works (one of my two fastmail addresses) an email with the subject "test to rw@rw"
  2. I waited ten minutes, and it never arrived (as far as Thunderbird was concerned).
  3. At 13:13 UTC, I (once again from web gmail) emailed hazel@fraticelli.info (my other fastmail account) an email with the subject "test to hazel email"
  4. It actually arrived in Thunderbird after a few minutes... and the "rw@rw" one still had NOT!
  5. I clicked the folder on my fastmail account that corresponds to the address which had NOT received the mail yet... and as soon as I did, the missing mail arrived.

I tried skimming through the log myself to see if there was anything interesting in it, but honestly it's mostly over my head: the one thing that I DID notice was, at 13:04 UTC (i.e. shortly after sending the first email that never arrived on its own), thunderbird suddenly began absolutely spamming the log with a huge number of messages! Hopefully you can make sense of exactly why, but that seems like some sort of smoking gun...

Since the logging was running for around 12 hours, the log file is much too big to attach here -- but also, since it was running all night, it also caught the contents of several semi-personal emails (all automated, but containing things like unsubscribe links, etc...) so I'd rather send it directly to you if possible? You can pass it around internally for the purposes of debugging, I'd just rather not have it sitting on the open web. Where can I send the link?

Just remembered one more detail that I didn't mention:

between step 4 and 5: I did "check all mail" and it STILL didn't find the mail! Only opening the folder made it appear -- even though the folder is set to "when getting new messages for this account, always check this folder"!

You can send the log directly to the address in my bugzilla profile (gds at chartertn dot net).

To clarify one important point: I have two Fastmail email aliases, which both go to separate folders in a single inbox.

Not sure I understand this. Do these aliases appear as separate accounts in TB?

thunderbird suddenly began absolutely spamming the log with a huge number of messages!

Curious to know what this is when I see the log!

You can send the log directly to the address in my bugzilla profile (gds at chartertn dot net).

Sent! Thanks!

Not sure I understand this. Do these aliases appear as separate accounts in TB?

Nope; Fastmail lets you have unlimited "email addresses", but you pay per inbox, so I have a single inbox with two sorting rules, to move each address's mail into one of two folders. So my "inbox" is always empty (other than the two subfolders), and new mail shows up in one of the two subfolders. (Technically one of the addresses is the "real" address for the account and the other is the alias, but I can send and receive with both, the way it's configured now.)

(In reply to omgitsraven from comment #10)

  1. At 13:03 UTC, I opened the web interface to one of my Gmail accounts in a browser (so Thunderbird wouldn't be involved), and I emailed raven.works@raven.works (one of my two fastmail addresses) an email with the subject "test to rw@rw"
  2. I waited ten minutes, and it never arrived (as far as Thunderbird was concerned).

It appears you were selected on Inbox/Ravenworks and TB sent a imap NOOP every minute like it should. However, the fastmail imap server didn't
send a untagged response within the noop indicating there is new mail so TB didn't detect anything.

  1. At 13:13 UTC, I (once again from web gmail) emailed hazel@fraticelli.info (my other fastmail account) an email with the subject "test to hazel email"
  2. It actually arrived in Thunderbird after a few minutes... and the "rw@rw" one still had NOT.

I do see where a new message in Inbox/Fraticelli is found here:

2021-08-02 13:15:03.974000 UTC - [(null) 2852: IMAP]: I/IMAP 0000024F4C2B3000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/Fraticelli (MESSAGES 3 RECENT 1 UIDNEXT 552 UNSEEN 1)

The previous STATUS response (1 minute earlier) show 1 few messages:

2021-08-02 13:14:03.998000 UTC - [(null) 2852: IMAP]: I/IMAP 0000024F4C2B3000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/Fraticelli (MESSAGES 2 RECENT 0 UIDNEXT 551 UNSEEN 0)

However, in the log I never see the header "Subject: test to hazel" appear in the log for fastmail. I do see it on the gmail being fetched and stored. My guess is that only the number of unread messages changed on folder Inbox/Fraticelli and you never opened the folder to read the message. I also never see an imap SELECT to the Inbox/Fraticelli folder which should be in the log if you opened the folder.

  1. I clicked the folder on my fastmail account that corresponds to the address which had NOT received the mail yet... and as soon as I did, the missing mail arrived.

Yes, I see in the log where the message if fetched from Inbox/Ravenworks mailbox on the server. It appears that you were already selected on that folder and there was also imap IDLE going on so the server should have provided a response indicating that new mail is available, but it didn't, it seems. Here's where the message header is fetched:

2021-08-02 13:20:38.485000 UTC - [(null) 2852: IMAP]: I/IMAP 0000024F4A6B2000:imap.fastmail.com:S-INBOX/RavenWorks:SendData: 4142 UID fetch 195 (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)])

I tried skimming through the log myself to see if there was anything interesting in it, but honestly it's mostly over my head: the one thing that I DID notice was, at 13:04 UTC (i.e. shortly after sending the first email that never arrived on its own), thunderbird suddenly began absolutely spamming the log with a huge number of messages! Hopefully you can make sense of exactly why, but that seems like some sort of smoking gun...

Other than the lack of responses indicating new messages for NOOP and STATUS commands, I don't see anything unusual in the log. It is somewhat difficult to parse since it contains the gmail stuff too. It might helpful if you could repeat your logging but disable the gmail accounts and only leave the fastmail. You can do that by going to the gmail server setting and uncheck

  • Check for new mail at startup
  • Check for new mail every X minutes
  • Notify immediately for new mail

Restart TB then repeat the procedure you did before but don't touch any of the gmail folders while recording the log. Also, let me know exactly which fastmail folders you touch/click while recording the log. Also, the time information you provides is very helpful.

Also, you say it only fails if left running for a long time. Maybe two logs would be helpful, one short-term that works and then a long term that has the problem. In both cases you send test messages externally to the addresses. That would be interesting to see, I think.

Bron, If you are monitoring fastmail related TB bugs, it really looks to me like this user's fastmail server (Cyrus I think) is not reporting new mail via untagged response to imap NOOP. I've tested with other servers (mostly dovecot and openwave) and new messages are detected via NOOP.

The TB user/fastmail customer is wanting to check for new mail in sub-folders of Inbox. If the sub-folder is not imap SELECT-ed, TB sends an imap STATUS which does detect new mail. But if the sub-folder is imap SELECT-ed, TB sends a NOOP instead and he never see any untagged responses when new mail is known to be present. I'm not sure why but this is how the legacy TB code works.

Flags: needinfo?(brong)

Thanks gene. Yeah, it's Cyrus IMAP. NOOP should definitely work if the connection is alive. We test NOOP behaviour in our test environment, but we don't have a NOOP test running in production, so it's possible that something is wrong in the environment there!

So let's try it :)

I logged in as one of my test users test5@brong.net :

openssl s_client -connect imap.fastmail.com:993 -crlf
[...]
. CREATE subfolder
. OK [MAILBOXID (c4e890f7-667d-4e94-a01d-8b71a9e01d2a)] Completed
. SELECT subfolder
* 0 EXISTS
* 0 RECENT
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
* OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Ok
* OK [UIDVALIDITY 1628077350] Ok
* OK [UIDNEXT 1] Ok
* OK [HIGHESTMODSEQ 77848] Ok
* OK [MAILBOXID (c4e890f7-667d-4e94-a01d-8b71a9e01d2a)] Ok
* OK [URLMECH INTERNAL] Ok
* OK [ANNOTATIONS 65536] Ok
. OK [READ-WRITE] Completed

Then I sent myself an email to 'test5+subfolder@brong.net' which delivers into that folder, and a little while later, I ran:

. NOOP
* 1 EXISTS
* 1 RECENT
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen $IsTrusted $X-ME-Annot-2)
* OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $IsTrusted $X-ME-Annot-2 \*)] Ok
. OK Completed

That looks right to me.

Let's try IDLE

. IDLE
+ idling
* 2 EXISTS
* 2 RECENT

Yep, that worked fine too.

So as far as I can see, it's working fine - at least on my test accounts in FM production. I would be surprised for this to be broken, since I know the shape of the code which handles NOOP pretty well, but it's always possible that we broke something.

@omgitsraven - if you open a support request (email support@fastmail.com, or fill the form at https://fastmail.com/support/ ) and ask for telemetry to be enabled on your account, we can watch for the NOOP commands that Thunderbird is sending and see how it aligns with the auditlog records for emails arriving. Tell the team you'd like Bron to take a look and they'll tag me in.

Flags: needinfo?(brong)

I've sent Fastmail support an email about telemetry, I'll let you know when I hear back (although I assume they'd let you know anyway!) Thanks!

This gives me a little happiness every time I read it :)

2021-07-25 22:49:10.951000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD91B5000:imap.fastmail.com:A:SendData: 62 COMPRESS DEFLATE
2021-07-25 22:49:10.974000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD91B5000:imap.fastmail.com:A:CreateNewLineFromSocket: 62 OK DEFLATE active

My only significant contribution to Thunderbird code - and still saves us quite a lot of bandwidth overall, given that Thunderbird is one of the more popular clients!

So.

All the log lines for IMAP appear to have the hostname in them, so grepping for imap.fastmail.com, it looks like:

START ONLY - idles on INBOX

START THEN AUTO - selects INBOX, issues a single noop, then idles on INBOX. A second connection calls status on each mailbox. Nothing from the NOOP:

2021-07-25 22:49:09.846000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 60 noop

In fact, here's everything that connection did from the select. Nothing in the INBOX.

2021-07-25 22:47:42.167000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:SendData: 56 select "INBOX"
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * 0 EXISTS
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * 0 RECENT
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $X-ME-Annot-2 $IsMailingList $IsNotification $HasAttachment $HasTD $IsTrusted $junk $notjunk NonJunk)
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $X-ME-Annot-2 $IsMailingList $IsNotification $HasAttachment $HasTD $IsTrusted $junk $notjunk NonJunk \*)] Ok
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * OK [UIDVALIDITY 1596310366] Ok
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * OK [UIDNEXT 19] Ok
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * OK [HIGHESTMODSEQ 15086] Ok
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * OK [MAILBOXID (8a30f10a-2cab-4519-8e3f-da31c8d5fb8a)] Ok
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * OK [URLMECH INTERNAL] Ok
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: * OK [ANNOTATIONS 65536] Ok
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:A:CreateNewLineFromSocket: 56 OK [READ-WRITE] Completed
2021-07-25 22:47:42.198000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 57 myrights "INBOX"
2021-07-25 22:47:42.229000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: * MYRIGHTS INBOX lrswipkxtecdn
2021-07-25 22:47:42.229000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: 57 OK Completed
2021-07-25 22:47:42.229000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 58 getquotaroot "INBOX"
2021-07-25 22:47:42.258000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: * QUOTAROOT INBOX INBOX
2021-07-25 22:47:42.258000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: * QUOTA INBOX (STORAGE 361117 29297664)
2021-07-25 22:47:42.258000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: 58 OK Completed
2021-07-25 22:47:42.259000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 59 IDLE
2021-07-25 22:47:42.296000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: + idling
2021-07-25 22:49:09.811000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: DONE
2021-07-25 22:49:09.846000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: 59 OK Completed
2021-07-25 22:49:09.846000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:ProcessCurrentURL: entering
2021-07-25 22:49:09.846000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:ProcessCurrentURL:imap://hazel%40fraticelli%2Einfo@imap.fastmail.com:993/select%3E/INBOX:  = currentUrl
2021-07-25 22:49:09.846000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 60 noop
2021-07-25 22:49:09.873000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: 60 OK Completed
2021-07-25 22:49:09.874000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 61 getquotaroot "INBOX"
2021-07-25 22:49:09.903000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: * QUOTAROOT INBOX INBOX
2021-07-25 22:49:09.916000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: * QUOTA INBOX (STORAGE 361117 29297664)
2021-07-25 22:49:09.916000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: 61 OK Completed
2021-07-25 22:49:09.918000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 62 IDLE
2021-07-25 22:49:09.950000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:CreateNewLineFromSocket: + idling
2021-07-25 22:50:15.619000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: DONE
2021-07-25 22:50:15.619000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 63 close
2021-07-25 22:50:15.619000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:SendData: 64 logout
2021-07-25 22:50:15.654000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CE93C3000:imap.fastmail.com:S-INBOX:TellThreadToDie: close socket connection

And here's the parallel STATUS commands:

2021-07-25 22:47:50.432000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Archive (MESSAGES 566 RECENT 0 UIDNEXT 572 UNSEEN 0)
2021-07-25 22:47:50.544000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Archive/2021 (MESSAGES 11 RECENT 0 UIDNEXT 13 UNSEEN 0)
2021-07-25 22:47:50.946000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Drafts (MESSAGES 0 RECENT 0 UIDNEXT 713 UNSEEN 0)
2021-07-25 22:47:51.347000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/Fraticelli (MESSAGES 6 RECENT 0 UIDNEXT 546 UNSEEN 0)
2021-07-25 22:47:51.746000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/RavenWorks (MESSAGES 0 RECENT 0 UIDNEXT 185 UNSEEN 0)
2021-07-25 22:47:52.151000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Sent (MESSAGES 330 RECENT 0 UIDNEXT 331 UNSEEN 0)
2021-07-25 22:49:09.852000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Archive (MESSAGES 566 RECENT 0 UIDNEXT 572 UNSEEN 0)
2021-07-25 22:49:11.025000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD91B5000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Drafts (MESSAGES 0 RECENT 0 UIDNEXT 713 UNSEEN 0)
2021-07-25 22:49:11.063000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/Fraticelli (MESSAGES 6 RECENT 0 UIDNEXT 546 UNSEEN 0)
2021-07-25 22:49:11.088000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD91B5000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/RavenWorks (MESSAGES 0 RECENT 0 UIDNEXT 185 UNSEEN 0)
2021-07-25 22:49:11.119000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Sent (MESSAGES 330 RECENT 0 UIDNEXT 331 UNSEEN 0)
2021-07-25 22:49:11.149000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD91B5000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Spam (MESSAGES 0 RECENT 0 UIDNEXT 14 UNSEEN 0)
2021-07-25 22:49:11.184000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD6DDF800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Trash (MESSAGES 33 RECENT 0 UIDNEXT 158 UNSEEN 0)

OK, let's check the manual one.

Again, only INBOX is selected, and the NOOP returns nothing.

And the STATUS commands are the same too:

2021-07-25 22:36:25.194000 UTC - [(null) 25496: IMAP]: I/IMAP 000001A671444000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Archive (MESSAGES 566 RECENT 0 UIDNEXT 572 UNSEEN 0)
2021-07-25 22:36:25.509000 UTC - [(null) 25496: IMAP]: I/IMAP 000001A671441800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Drafts (MESSAGES 0 RECENT 0 UIDNEXT 713 UNSEEN 0)
2021-07-25 22:36:25.538000 UTC - [(null) 25496: IMAP]: I/IMAP 000001A671444000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/Fraticelli (MESSAGES 6 RECENT 0 UIDNEXT 546 UNSEEN 0)
2021-07-25 22:36:25.562000 UTC - [(null) 25496: IMAP]: I/IMAP 000001A671441800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS INBOX/RavenWorks (MESSAGES 0 RECENT 0 UIDNEXT 185 UNSEEN 0)
2021-07-25 22:36:25.589000 UTC - [(null) 25496: IMAP]: I/IMAP 000001A671444000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Sent (MESSAGES 330 RECENT 0 UIDNEXT 331 UNSEEN 0)
2021-07-25 22:36:25.615000 UTC - [(null) 25496: IMAP]: I/IMAP 000001A671441800:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Spam (MESSAGES 0 RECENT 0 UIDNEXT 14 UNSEEN 0)
2021-07-25 22:36:25.643000 UTC - [(null) 25496: IMAP]: I/IMAP 000001A671444000:imap.fastmail.com:A:CreateNewLineFromSocket: * STATUS Trash (MESSAGES 33 RECENT 0 UIDNEXT 158 UNSEEN 0)

I guess - maybe it's the STATUS I should be debugging? This is with INBOX selected (same connection)

BEFORE:

. STATUS subfolder (UIDNEXT MESSAGES UNSEEN RECENT)
* STATUS subfolder (MESSAGES 2 RECENT 0 UIDNEXT 3 UNSEEN 2)
. OK Completed

AFTER

. STATUS subfolder (UIDNEXT MESSAGES UNSEEN RECENT)
* STATUS subfolder (MESSAGES 3 RECENT 1 UIDNEXT 4 UNSEEN 3)
. OK Completed

That all looks good to me. I could try with a separate connection as well, but it's still going to be the same. There's nothing special about having a selected folder for STATUS on other folders. (status on the selected folder is a protocol violation, but we handle it sensibly)

(In reply to omgitsraven from comment #17)

I've sent Fastmail support an email about telemetry, I'll let you know when I hear back (although I assume they'd let you know anyway!) Thanks!

Telemetry enabled :) @omgitsraven, please update the ticket with accurate timestamps for when you next have the issue, along with as much as possible about the specific message and which folder you expected to find it in. I'm about to head to bed (it's late in Australia now) so I'll take a look tomorrow.

OK! I'll be at work for a bit, but I'll try and experiment with reproducing it tonight. Thanks!

OK actually, I squeezed in one more test; based on your discussion, I selected one of the folders first, before emailing both accounts, and I was able to reproduce the bug without staying up all night, heh. (Thank you for narrowing that down, I hadn't realised that was the one thing I coincidentally hadn't tried until my overnight test...)

The new process was this:

  1. Launch Thunderbird in logging mode
  2. Click the "RavenWorks" folder of my fastmail account
  3. Click one of my gmail accounts (not sure whether this is necessary, but it's what I did last time, so I did it again this time.)
  4. Opened web gmail, and emailed raven.works@raven.works
  5. Waited a few minutes, and saw that Thunderbird received it correctly (even though I thought that the highlighted folder was the one that would be bugged?)
  6. Opened web gmail again, and emailed hazel@fraticelli.info
  7. Waited a few minutes, and saw that it was NOT arriving in Thunderbird!
  8. Opened web FASTmail, and checked that there was indeed new mail in both folders
  9. Did "get all new messages"; it still didn't arrive.
  10. Selected the Fraticelli folder in Thunderbird, and the new message arrived.

Attaching the log momentarily!

In the imap.log.moz_log above I'm see an IDLE response of * 4 EXISTS and on the SELECT it was * 3 EXISTS. This is for folder Inbox/Fraticelli which didn't receive the new mail. Line 60139 of the log.

  1. Did "get all new messages"; it still didn't arrive.
  2. Selected the Fraticelli folder in Thunderbird, and the new message arrived.

I see a select of Inbox/Fraticelli near the top of the log. Did you select (click) it then or much later into the log? Or maybe TB just connected on its own.

Anyhow, this doesn't look right that TB doesn't respond to the increase in "exists" count from IDLE. Maybe the original log file has this issue too. I really didn't look that close at IDLE responses which Bron mentioned above. That might explain why I see nothing reported by NOOPs.

Reporter omgitsraven, as an experiment you might try disabling IDLE "immediate notification" in server settings since you are checking manually every minute anyhow. But then again, if TB is sometimes ignoring changes in untagged EXISTS count, it may not matter.

There's honestly a chance that I misremembered the sequence of events... I might have clicked both at first, but I think at the very least I left it on the other folder? I may have gotten confused though, I'm sorry if that's the case.

And wow, I never even noticed the "allow immediate server notifications" setting. Why is it possible to have that AND "check every X minutes" both enabled, isn't that redundant?

I've disabled it for now; I'll try running another test tonight and get back to you. Thanks!

In the original log (not attached, link sent via email, 44M) I also see the IDLE for Inbox/RavenWorks reporting an increase by one in the IDLE/EXISTS response. So the server is doing the right thing and TB is dropping the ball, it appears. It is on this line:

2021-08-02 13:03:53.915000 UTC - [(null) 2852: IMAP]: I/IMAP 0000024F4A6B2000:imap.fastmail.com:S-INBOX/RavenWorks:CreateNewLineFromSocket: * 2 EXISTS

This is an untagged response within an IDLE. On the original select, the EXISTS count was reported as 1. (Also, the RECENT count went from 0 to 1, after the IDLE DONE was sent by TB:

2021-08-02 13:04:02.860000 UTC - [(null) 2852: IMAP]: I/IMAP 0000024F4A6B2000:imap.fastmail.com:S-INBOX/RavenWorks:CreateNewLineFromSocket: * 1 RECENT

(In reply to omgitsraven from comment #24)

And wow, I never even noticed the "allow immediate server notifications" setting. Why is it possible to have that AND "check every X minutes" both enabled, isn't that redundant?ox

The "immediate notification" option only applies to Inbox (not necessarily subfolders of Inbox) and any other folder in the imap "SELECTed" state. By default you can have up to 5 connections to various folders but always to Inbox and if you select "immediate" TB will do IDLE on each SELECTed connection. But only Inbox is guaranteed to be selected so if you need to receive mail in other folders (like Inbox/RavenWorks) and you haven't clicked on it to select it, you have to poll for mail with the timer.

Also, with the timer set to 1m and immediate turned on, every minute the IDLE command has to be completed (TB sends DONE) and then a NOOP is sent and then IDLE is re-established again, only to last another minute before the next NOOP to poll for new messages. However, even with all this activity, TB should still work and detect new messages, but apparently sometimes it doesn't.

I've disabled it for now; I'll try running another test tonight and get back to you. Thanks!

Just to be clear, disabling the immediate notification thing is just a work-around. Something seem to be wrong with detecting new messages in non-Inbox folders. And to be honest, I've seen similar reports but never got the detailed testing and help from the users to determine the cause. Hopefully, we'll find something now. So thanks for your help. And thanks to Bron too.

(In reply to Bron Gondwana from comment #18)

This gives me a little happiness every time I read it :)

2021-07-25 22:49:10.951000 UTC - [(null) 6964: IMAP]: I/IMAP 0000018CD91B5000:imap.fastmail.com:A:SendData: 62 COMPRESS DEFLATE

My only significant contribution to Thunderbird code - and still saves us quite a lot of bandwidth overall, given that Thunderbird is one of the more popular clients!

Yes, I studied this once when trying to help someone who was writing their own imap server to support compression. I was very impressed with the code and with its documentation in the "bug" report that went with it. Don't think there has been any real bugs reported against this at all! Works with gmail too and probably others.

omgitsraven, I'm curious as to why these folders listed below seem to have imap STATUS done for them about every minute in your logs. Do you have these or some of these set to be checked for new mail on fastmail account?

Archive
Archive/2021
Drafts
Sent
Spam
Trash

Not sure if this is contributing to the problem. On my setup I don't see extra folders being checked for new mail. Also, on mine after IDLE reports new mail. TB does a SELECT url on the folder which causes, eventually, the folder flags to be fetched and the new mail detected. On yours, when IDLE detects the folder change, TB does a STATUS on one of the above folders and never fetches the flags for the changed folder, thus never detecting the new message.

Of course, checking any folder you want to or even all folders shouldn't cause a problem (other than using a lot of network).

Yes, I just set everything to check every minute automatically -- I guess there'd be no reason to know about things in my drafts/trash/archive come to think of it, I just set it for everything as a matter of habit...

Is it actually that much bandwidth, by 2021 standards?

Yes, I just set everything to check every minute automatically

Ok, good to know. Just wanted to make sure that you had made the settings.

Is it actually that much bandwidth, by 2021 standards?

Probably not, actually.

I did seem to duplicate the problem once where new mail was not detected after adding, like yours, my special folders to be checked. However, since then I haven't been able to cause the problem and new mail in non-Inbox folders are detected. So I doubt that the checks on the special folder really has an effect.

(In reply to omgitsraven from comment #21)

Let me make sure I completely understand what you were doing when you saw the problem:

The new process was this:

  1. Launch Thunderbird in logging mode
  2. Click the "RavenWorks" folder of my fastmail account
  3. Click one of my gmail accounts (not sure whether this is necessary, but it's what I did last time, so I did it again this time.)

Did you click the top level gmail account or a folder in the gmail account?

  1. Opened web gmail, and emailed raven.works@raven.works
  2. Waited a few minutes, and saw that Thunderbird received it correctly (even though I thought that the highlighted folder was the one that would be bugged?)

By "received it correctly" do you mean the Inbox/RavenWorks folder became bold and showed the new unread count. Did you open the email too?
Inbox/RavenWorks is the highlighted folder, I assume, since you click on it in step 2?

  1. Opened web gmail again, and emailed hazel@fraticelli.info
  2. Waited a few minutes, and saw that it was NOT arriving in Thunderbird!

By "NOT arriving" I assume you mean that Inbox/Fraticelli did go bold and show the expected unread count?

  1. Opened web FASTmail, and checked that there was indeed new mail in both folders
  2. Did "get all new messages"; it still didn't arrive.

Same question. What determined "didn't arrive"? I assume folder didn't go bold and unread count didn't show.

  1. Selected the Fraticelli folder in Thunderbird, and the new message arrived.

Sorry for the probably obvious questions but want to make sure I understand your exact meaning.

Did you click the top level gmail account or a folder in the gmail account?

A folder (to see a list of mail, rather than the list of buttons and so on related to the account).

By "received it correctly" do you mean the Inbox/RavenWorks folder became bold and showed the new unread count.

Yes.

Did you open the email too?

I can't entirely remember now but I'm pretty sure I didn't.

Inbox/RavenWorks is the highlighted folder, I assume, since you click on it in step 2?

The most recently highlighted folder of my fastmail account, but the ACTUALLY highlighted folder was the inbox of my Gmail account still (step 3).

By "NOT arriving" I assume you mean that Inbox/Fraticelli did go bold and show the expected unread count?

Inbox/Fraticelli did not go bold and did not show the expected unread count; it remained un-bold with no numbers next to it.

Same question. What determined "didn't arrive"? I assume folder didn't go bold and unread count didn't show.

Correct.

Sorry for the probably obvious questions but want to make sure I understand your exact meaning.

It's okay, it's worth being thorough! I assumed that this would mostly have been clarified by the log, but in hindsight I guess the nature of a bug means you can't entirely rely on what the program thinks is happening, heh.

OK, finally got around to running another round of tests, and actually, for a minute I was convinced that disabling immediate notifications had fixed it, but in fact it hasn't!

I disabled the setting, then performed the same test as previously (select a separate gmail account's inbox, then email both fastmail addresses from my web browser) and both folders lit up like they should! I did the same thing again to make sure it wasn't a fluke, and again, both folders lit up! Then I turned the setting back on and did a third test, and honestly, I can't remember what the third test's result was any more unfortunately, because the real point is: I then turned the setting back OFF again to do one more test to produce a log for you, and in fact: the bug DID happen with the setting off this time!

In short, the two takeaways here are:

  1. The bug doesn't reproduce consistently
  2. The bug still occurs even with "allow immediate server notifications" unchecked.

I'll momentarily attach a log of the bug occurring with "allow immediate server notifications" unchecked; I believe the order of events was

  1. Launch Thunderbird in debug mode with the setting already unchecked, and the 'fraticelli' folder selected.
  2. Select my gmail inbox folder
  3. Open my web browser, and email both fastmail addresses from web gmail
  4. Within 2 minutes, the RavenWorks folder was lit up bold and suffixed "(1)"
  5. After 5 minutes, the Fraticelli folder still was not
  6. I clicked the (already bold) RavenWorks folder just out of curiosity, and nothing happened to the Fraticelli folder
  7. I clicked the Fraticelli folder, and it immediately became bold and suffixed "(1)"
Attached file with immediate notification disabled (obsolete) —

This is similar to what I have been able to duplicate with "immediate" (idle) enabled. Your "fraticelli" connection is handling most of the status checks on the folders listed in comment 28 which should be OK. However, during the check for status on Archive folder (with connection imap selected to Inbox/Fraticelli) the server reports a change in EXISTS and RECENT (log lines 1734 and 1737) that TB ignores so the new message isn't detected. TB expects to see the change reported via NOOP which it sends later, but since the server has already reported the changes, NOOP doesn't see any untagged EXISTS and RECENT. Eventually you click on Inbox/Fraticelli folder which triggers a re-select of an already selected folder, causing ProcessImapMailbox() to be called which does the complete fetches to detect the change and the new mail is detected and fetched.

With idle (immediate) enabled, I'm seeing a similar problem in that the EXISTS/RECENT is reported while idle is running but are not acted on by TB. I found a partial fix for this (with idle enabled) but the new mail is detected but fetched only on the timed interval, not immediately. Without my "fix" the new email is not detected until you click the folder. (I found a very consistent procedure to duplicate this but any variation usually causes an immediate detection.)

Anyhow, I'll go ahead and mark this report as NEW. I'm working on trying to find a general fix that handles both immediate and non-immediate cases.

Assignee: nobody → gds
Status: UNCONFIRMED → NEW
Ever confirmed: true

@gene smith - interesting

Obviously the server is allows to send the EXISTS and RECENT lines whenever it wants, "unsolicited" and all that - however I see the point that maybe not sending them in response to a STATUS check on a different folder would make sense... I'll check the Cyrus code and see how hard it would be to make that change.

I don't think any client is expecting to be guaranteed an unsolicited response to that command.

I think https://github.com/cyrusimap/cyrus-imapd/pull/3605 will do the right thing here. The other interesting command that I see in the telemetry is myrights - but that appears to already not do a imapd_check in Cyrus, so it won't refresh the exists counts.

I found a possible fix in the TB status sending code. If the destination mailbox for STATUS matches the selected mailbox, it reverts to a sending a noop and checks for change in EXISTS before and after and triggers a folder update if it see a difference. I added the same thing to the status sending code when it sends a real status so that should fix what the reporter omgitsraven saw without your Cyrus fix (I think). However, there may be other commands where this needs to be checked too.

FYI, here's the current STATUS sending code (at the point where it does NOOP instead of STATUS):
https://searchfox.org/comm-central/rev/bdf1197238d795a88782e8ef8bf12facc7560247/mailnews/imap/src/nsImapProtocol.cpp#6699

Bron, do you know if Cyrus or other servers send unilateral (unsolicited) untagged responses at any time like RFC 3501 says they can? It seems like TB is really only prepared to receive unilaterals for IDLE responses. I need to look closer at this with my local Dovecot.

Sending NOOP rather than STATUS for the selected folder is definitely good behaviour. STATUS on the selected mailbox was actually forbidden by RFC3501 (not that anybody paid attention to that).

The issue with Cyrus was that it was also sending unsolicited updates to the selected mailbox's status when a STATUS command was issued for a different mailbox. I've written a fix for that which should be deployed at Fastmail within a couple of days, and will be included in the next Cyrus release as well as the next bugfix minor versions for the past couple of releases.

Certainly there are other servers which send unsolicited responses whenever. This "fix" in Cyrus is about being more conservative in what we send rather than any requirement in the RFC.

I think the STATUS problem is more with TB than with the current Cyrus. TB should respond appropriately to untagged responses no matter when they occur which, at least during STATUS, it doesn't.

STATUS on the selected mailbox was actually forbidden by RFC3501 (not that anybody paid attention to that).

Actually, I think it's a SHOULD NOT and instead of a SHALL/MUST NOT: https://datatracker.ietf.org/doc/html/rfc3501#page-44

Note: The STATUS command is intended to access the
           status of mailboxes other than the currently selected
           mailbox.  Because the STATUS command can cause the
           mailbox to be opened internally, and because this
           information is available by other means on the selected
           mailbox, the STATUS command SHOULD NOT be used on the
           currently selected mailbox.

But, right below, for detecting new messages it's a MUST NOT:

The STATUS command MUST NOT be used as a "check for new
           messages in the selected mailbox" operation (refer to
           sections 7, 7.3.1, and 7.3.2 for more information about
           the proper method for new message checking).

Anyhow, I guess TB got this right.

I should probably provide omgitsraven a "try" build so he can test my fix with the "broken" Cyrus before you deploy the fix. (Or I need to install a local unpatched Cyrus along side Dovecot.)

Yeah, I'll be deploying the "fixed" Cyrus fairly soon - probably tomorrow if it passes all the tests along the way. Not a massive stress to hold off another day or two though.

Attached patch status-idle-fix-WIP.diff (obsolete) — — Splinter Review

I've kicked-off a "try" build with my Work In Progress changes. So, Bron, if you could hold off the deploy of the Cyrus fix until omgitsraven can maybe test this and see if it helps I would appreciate it.

omgitsraven, here's the link to the try build: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=f9336b113e5e31d0a921625dde8eeff08795d0e8
When this finishes there should be a green "B" next to "Windows 2012 x64 opt". Click the green "B" and you will see a menu appear with an "Artifacts" selection. Select "Artifacts" and there will appear a long list and you download "target.installer.exe". This will allow you to install a daily TB version with my patch, status-idle-fix-WIP.diff, applied.

Hopefully, this will fix the last problem with Idle/immediate turned off regarding STATUS with the un-patched Cyrus/Fastmail server.

It also should allow changes detected with imap IDLE (immediate) to be detected and not completely dropped, but still detected only on the timed "check for mail" interval. However, I'm not asking you to test this since I can test it here and doesn't involve Cyrus/Fastmail.

Thanks to both of you!

Well, looks like there is some kind of "bustage" on the comm-central/try tree right now. I see my try build failed as well as another before it. I don't see anything in the try log about my changes causing an "ERROR -" so I'll check back a bit later and see if it is resolved.
Edit: looks like it's being worked on here bug 1724635

Yep, holding off for a bit! Hopefully you can get it tested today and I'll roll changes tomorrow :)

Magnus, what's the trick to getting my "try" build to not fail on missing nimbus.h like was fixed in bug 1724635? Others try builds seem to be working but mine's not. FWIW, your fixes show up in searchfox under comm-central but not under mozilla-central.
My latest attempt is here:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=f49a569a866df73e297f452528d85cc7c88a9249

(In reply to Bron Gondwana from comment #43)

Yep, holding off for a bit! Hopefully you can get it tested today and I'll roll changes tomorrow :)

Unable to get the try build to reporter omgitsraven today due to ???. Hopefully tomorrow I can get the build to work.

Flags: needinfo?(mkmelin+mozilla)

Probably this fixes it I think:

+++ b/.gecko_rev.yml
@@ -1,11 +1,11 @@
 ---
 GECKO_BASE_REPOSITORY: https://hg.mozilla.org/mozilla-unified
-GECKO_HEAD_REPOSITORY: https://hg.mozilla.org/mozilla-central
+GECKO_HEAD_REPOSITORY: https://hg.mozilla.org/integration/autoland
 GECKO_HEAD_REF: default

omgitsraven, if the build works you can now find it here:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=6b3bafa32dda060423f8d2cc1d4724ffd3a4de01
The instructions in comment 41 apply.

Flags: needinfo?(mkmelin+mozilla)

It should work without anything special now: bug 1724635 was merged to mozilla-central only a few hours ago (your previous trys were before that).

I've tested it in the Thunderbird Daily build four times so far, and it's worked fine each time!
The bug seems to not happen consistently, so this COULD just be a coincidence, but it's a good sign at least! Thank you!

I've tested it in the Thunderbird Daily build four times so far, and it's worked fine each time!
The bug seems to not happen consistently, so this COULD just be a coincidence, but it's a good sign at least! Thank you!

Ok, thanks for testing it and sorry for the delay in getting it to you.

I thinks I've found the root problem that occurs when idle (immediate) is enabled. Somehow one of the folders that is being checked for new messages that doesn't have idle enable (e.g., Trash in your case) is getting associated with the folder update that idle response is supposed to trigger. So the folder associated with the idle never gets updated so its folder (mailbox) change is missed.

Maybe I can find a solution, not sure. It's pretty complicated code written long ago by people long gone and there is no formal documentation.

I found a solution, at least it works for me.
But before describing it, here's my steps for duplicating the bug with the current release or latest trunk code:

  1. Test with an account that supports imap IDLE (immediate notification), e.g., fastmail/cyrus, or dovecot.
  2. Mark several folders as "check this folder for new mail". I selected a set like in comment 28.
  3. For the account set "check for new mail on tb start", "check for new mail every 1 minute" and "allow immediate notification"
  4. Make sure the number of cached connections is 5, the default in advanced server setting.
  5. Create a folder called Queue and a folder called Three (names are arbitrary, that's just what mine are called).
  6. Make sure folder Three has no unread messages present, or no messages, doesn't matter.
  7. Mark folder Three as "check this folder for new mail". Don't mark folder Queue as checked for new mail.
  8. Click to select folder Queue and shutdown TB
  9. Re-start TB, folder Queue will be selected.
  10. Click folder Three and then go back to (click) folder Queue.
  11. Open the same imap account on a 2nd TB or other client. From a folder other than Queue or Three of the account or from a completely different account on the 2nd client, copy an unread message to folder Three
  12. On the original TB client, while selected on folder Queue, observe that folder Three doesn't become bold with a new unread count in parenthesis even after several message retrieval intervals.
  13. On original TB, click folder Three and observer that the unread count (1) and the message summary appear in bold.

FYI - the new code was deployed to all Fastmail accounts yesterday, 'STATUS' on a different folder will no longer cause unsolicited status updates for the selected folder.

Wonderful to hear, thank you!! I've done one last test on my usual Thunderbird install and it seems to be working for me -- I guess I'll keep you posted if I ever catch it happening again, but for now it's looking good :) Thanks!

Why it fails:
Folder Three is imap SELECTed due to step 10 above. It remains in IDLE state waiting for a response indicating new messages for 1 minute (the check for new messages, biff, interval). It then exits IDLE state and its connection is used to send a STATUS to one of the folders in the "check this folder for new messages" set. The connection remains imap selected on folder Three but the destination folder (called the folder sink) switches to the folder being checked for new mail with imap STATUS. It then goes back to IDLE state on the selected folder Three for another biff interval and then exits idle and checks STATUS on another folder in the list as set in Step 2 above. The variable that holds the folder sink now points to the folder being checked for status instead of Three and then the connection goes back to IDLE state and watches for new messages on folder Three. The Idle/check status cycle continues with biff interval period but eventually, during idle, a new message is detected on folder Three (e.g., caused by step 11 above and the EXISTS count is reported). The code that activates a response to detect new message during idle uses the folder sink pointer which is not pointing to folder Three as the design expects. This causes a status check on a folder other than Three so the detection of new mail in folder Three during idle is never acted upon.

Here's the point in the code where the problem occurs:
https://searchfox.org/comm-central/rev/dc30a5c99706435363248e97bca67b782aa01070/mailnews/imap/src/nsImapProtocol.cpp#1498
m_imapMailFolderSink is pointing to the last folder for which status was checked (e.g., Archives) and not to the folder currently imap selected and for which a new message was detected during IDLE (Three). So OnNewIdleMessages() gets called for the wrong folder and the new message is not seen.

Attached patch status-idle-fix.diff (obsolete) — — Splinter Review

The fix is to obtain and use a new folder sink called m_imapMailFolderSinkIdle and use that in HandleIdleResponses() instead of m_imapMailFolderSink which is usually incorrect if there are non-Inbox folders marked for new mail checks during biff.
m_imapMailFolderSinkIdle only points to the currently selected folder which is what is required to detect new messages during IDLE.

omgitsraven, Here's a new "try" build with this fix. It also handles the issue that Bron fixed on the Cyrus server.
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=1f5076b846dfd1f6e17bc034aa23fad9dee06c18

Attachment #9235433 - Attachment is obsolete: true
Attachment #9235882 - Flags: feedback?(benc)

omgitsraven, This fix should also allow you to switch back on "immediate" so you should see new mail very quickly in the 4 most recently opened folders and not just on the timed interval.
TB gives Inbox highest priority for checking new mail since imap expects most new mail to appear there. In your case, you don't receive any mail in Inbox but in the two sub-folders of Inbox. You have tb set to check for new mail in Inbox/RavenWorks and Inbox/Fraticelli but there is no guarantee that they will be imap selected and then go to IDLE mode and provide "immediate" notification of new mail. So the only way to try to cause "immediate" email detection on these folders is to fairly often visit them. (But from the logs you have provided these two folders are selected and doing IDLE, so you are visiting them enough to cause them to be selected.)

Edit, P/S: To test the effectiveness of this latest try build, you need to keep checking the folders in comment 28 for new mail like you always have. I.e., ensure TB configuration is setup the same way it was when you reported this bug.

Comment on attachment 9235882 [details] [diff] [review]
status-idle-fix.diff

Review of attachment 9235882 [details] [diff] [review]:
-----------------------------------------------------------------

Just to recap, to make sure I'm understanding the issue correctly:
Periodic "New Mail" checks are performed on non-SELECTed folders, using the STATUS command. The responses are untagged, and are being mistaken for IDLE responses (on the SELECTed folder).
A connection cannot issue a STATUS command until it finishes any active IDLE (by sending DONE), right?

So, with this patch:
- `m_imapMailFolderSink` holds the target sink (folder) for normal non-idle operations (and may or may not correspond to the SELECTed mailbox)
- `m_imapMailFolderSinkIdle` holds the target sink (folder) for idle operations only (ie always points at the SELECTed mailbox)

Which sounds basically sensible to me.
It _kind_ of feels like the connection should already have enough info about where to send untagged responses without an extra member variable, but... well... it's the IMAP codebase. Big and complicated and poked about with and tweaked and mauled over many years :-)

::: mailnews/imap/src/nsImapProtocol.cpp
@@ +6761,5 @@
>        m_imapMailFolderSink->UpdateImapMailboxStatus(this, new_spec);
> +    // Respond to possible untagged EXISTS response like for NOOP above.
> +    if (m_imapMailFolderSink &&
> +        (GetServerStateParser().NumberOfRecentMessages() ||
> +         prevNumMessages != GetServerStateParser().NumberOfMessages()))

It looks like `prevNumMessages` could still be undefined at this point in some cases?
Attachment #9235882 - Flags: feedback?(benc) → feedback+

Hi Ben,
Thanks for the feedback. Sorry for the delay in responding. I've made a few tweaks to the code and will submit a formal patch real soon, maybe tomorrow (Thur). But I wanted to do some testing with a local Cyrus server and its taken me all day today to get it working, but I finally did. This is to check my fix for the issue that Bron fixed in his Fastmail/Cyrus server (comment 34/comment 35). The fix for it in the last diff doesn't look quite right to me so I'll test it some tomorrow and see how it goes. I've installed an older Cyrus version from my linux distro that doesn't have Bron's patch. I couldn't duplicate the problem with my local Dovecot so decided to try it with Cyrus.

Hi Gene, thank you for your interest in this bug.
In this moment I'm using Thunderbird 78.13.0 on Thunderbird and I didn't see the bug anymore. I don't know if this is already the right patched version or not.

Thanks

Hi Erik, There have not been any changes yet to any release version that fixes this, so your version 78.13 doesn't have any changes for this issue.
I'm not sure why you don't see the problem any more but it is somewhat random and not always easy to reproduced.
if I remember correctly, you have server-side filters that put messages in non-Inbox folders at the server and you weren't always seeing new mail indications in these folders. I think you are using idle (immediate notification) and check for new messages every X minutes which is more or less how the reporter here (omgitsraven) has TB configured.

I've actually been confused about this too -- I haven't had this problem for a while now, in my release version of Thunderbird? I was under the impression that some fix went live on the Fastmail side of things to mitigate it, but I might have misunderstood the thread, I admit it's largely over my head.... it might also just be a coindience of course, given how inconsistently the bug reproduces under normal use.

Sorry I haven't gotten around to trying the latest test build, I'll try and give it a shot this weekend.

Responses to Ben's feedback:

A connection cannot issue a STATUS command until it finishes any active IDLE (by sending DONE), right?

Yes (Easy question first.)
In IDLE, tb just receives and parses whatever the server sends which is "untagged" items that report changes. This is usually just "EXISTS" responses that reports the total number of messages in the mailbox (folder), RECENT which is the number of recent or new messages or FETCH responses when messages have been expunged. Tb just records the new counts associated with EXISTS and RECENT but doesn't really do any action directly when it sees these untagged responses. It just triggers tb to get a more detailed status about the mailbox.

Periodic "New Mail" checks are performed on non-SELECTed folders, using the STATUS command. The responses are untagged, and are being mistaken for IDLE responses (on the SELECTed folder).

I'm wouldn't say anything is "mistaken for IDLE responses". What's happening is on the biff interval a connection SELECTed on folder A and in IDLE is needed run a STATUS url to check for new mail on a not-selected folder B where folder B is one of the non-Inbox folders configured to be checked for new mail. This causes the folder sink m_imapMailFolderSink to change from folder A to B. The connection then runs the STATUS url causing the imap STATUS to be obtained for folder B, which works as expected and will detect new messages in folder B using the connection still SELECTed on folder A. The connection then goes back into IDLE. The biff interval occurs again and the connection SELECTed on folder A may be used to check the STATUS for other folders too like C and D, and this works fine (where C and D are also in the set of non-Inbox folder to be checked for new mail).

A problem can occur when IDLE on the connection SELECTed to folder A sees a response indicating there is new mail in folder A. The folder sink m_imapMailFolderSink may be pointing to folder B or C or D or others and not folder A. The response to IDLE is handled by nsImapProtocol::HandleIdleResponses() oftren uses the wrong folder sink and a folder other than A gets updated here: Maybe wrong folder sink. This causes the changes in folder A to be missed.

So, with this patch:

  • m_imapMailFolderSink holds the target sink (folder) for normal non-idle operations (and may or may not correspond to the SELECTed mailbox)
  • m_imapMailFolderSinkIdle holds the target sink (folder) for idle operations only (ie always points at the SELECTed mailbox)

Yes, this is right. Just to be clear, under default configuration, where only Inbox is checked for new mail, with the patch (status-idle-fix.diff) both "sinks" will correspond to (point to) the currently selected folder for the connection.

Which sounds basically sensible to me.
It kind of feels like the connection should already have enough info about where to send untagged responses without an extra member variable, but... well... it's the IMAP codebase. Big and complicated and poked about with and tweaked and mauled over many years :-)

It looks to me like this bug has been present as far back as TB imap history goes, at least to when code was imported to HG from CVS per searchfox "blame" feature.
I tried just saving the sink value obtained on the first SELECT into a new sink variable and use it for "idle" responses but that didn't work or crashed. So just getting a new and dedicated sink worked better.

It looks like prevNumMessages could still be undefined at this point in some cases?

I think I had convoluted rationale that it was OK, but probably not. I'll fix that.

This gets into the other aspect of this bug not really involving IDLE. The function nsImapProtocol::OnStatusForFolder occurs when a folder is checked for new mail. If the folder being checked is not the currently SELECTed folder on the connection, an imap STATUS is sent to the not-SELECTed folder. During the STATUS response, the non-SELECTed folder may report new messages as intended. But also during the STATUS response the SELECTed folder may send untagged responses, e.g., EXISTS, RECENT, if the SELECTed folder has new messages. This happens very consistently with the Cyrus server I am currently testing Cyrus IMAP 3.0.13-Debian-3.0.13-5 especially when IDLE (immediate) is disabled. But Bron has changed (fixed) this in his latest Cyrus release (STATUS no longer responds with untagged items for the SELECTed folder). I'm was unable to see this with my local Dovecot but I don't see that an imap server doing this violates the imap RFC in any way and other servers may do this. Without the fix these possible untagged responses are ignored causing new mail to not be detected at the timed interval.

However, in status-idle-fix.diff there is an error that causes this not to work.

+    // Respond to possible untagged EXISTS response like for NOOP above.
+    if (m_imapMailFolderSink &&
+        (GetServerStateParser().NumberOfRecentMessages() ||
+         prevNumMessages != GetServerStateParser().NumberOfMessages()))
+      m_imapMailFolderSink->OnNewIdleMessages();

The last line above needs to use m_imapMailFolderSinkIdle-> so OnNewIdleMessages() is called for the SELECTed folder and not the folder being STATUS checked. Also, the if should be if (m_imapMailFolderSinkIdle &&....
At the top where Noop() is called because the SELECTed folder is the same as the folder being checked for STATUS, it uses m_imapMailFolderSink->.... That's OK because both "sink" pointers reference the SELECTed folder.

In both places where OnNewIdleMessages() is called, just to be clear, this is not really responding to IDLE, just that the equivalent action is done since the same type of untagged responses are seen as with a true IDLE response. (Maybe this is what you mean by "mistaken for idle"?)

I'll submit a new/improved patch shortly. Sorry for the long write-up.

(In reply to omgitsraven from comment #60)

I've actually been confused about this too -- I haven't had this problem for a while now, in my release version of Thunderbird? I was under the impression that some fix went live on the Fastmail side of things to mitigate it, but I might have misunderstood the thread, I admit it's largely over my head.... it might also just be a coindience of course, given how inconsistently the bug reproduces under normal use.

Sorry I haven't gotten around to trying the latest test build, I'll try and give it a shot this weekend.

The Fastmail/Cyrus fix only fixed the problem when IDLE is disabled. omgitsraven, I think your setup will work OK with TB release with fastmail (with Bron's changes deployed) as long as you keep IDLE (immediate) turned off.

I've found a way to duplicate the bug if I do the steps in comment 49. But any variation often causes it to detect new mail on non-inbox folders (like it should). So just with day-to-day activities it may work and then not work (to detect new mail in random non-inbox folders that is).

Thanks, but I wouldn't bother testing that old "try" build since I can pretty much reproduces the issues here and see if my changes work or not. Maybe I'll have another "try" build you can test later to verify that it really works for an end user.

Oh, you're right, I forgot -- I do indeed have 'immediate' mode turned off now, on my ordinary version of Thunderbird.

And, alright, good to know! I'll keep an eye out for new "try" builds, then. Thanks!

Attached patch status-idle-fix-v2.diff (obsolete) — — Splinter Review

Here's an updated diff for feedback.

In nsImapProtocol::SetupSinkProxy() I am obtaining m_imapMailFolderSinkIdle when the url is SELECT. It is really only needed when one or more non-Inbox folders are checked for new mail. Determining if there is one or more non-Inbox folders that the user has configured to be checked for new mail is not obvious how to do, to me at least. So I just get the new sink value on each SELECT url and where m_imapMailFolderSinkIdle is used I just have to make sure it is not null.

In nsImapProtocol::OnStatusForFolder, for the non-Noop() full STATUS case I obtain the initial value of prevNumMessages only if the connection is in selected state. I moved the check for a change outside of the check for STATUS success or failure and use the correct m_imapMailFolderSinkIdle and only if connection is in selected state. So this should correct the issue you pointed out (and also work correctly since I'm using the right sink pointer now).

If this looks OK I'll submit a formal patch. There are also some added logging indicated by strings with "gds:" in them. I'm not sure if I should get rid of them or just strip out the "gds:" and leave them in.

Attachment #9235882 - Attachment is obsolete: true
Attachment #9237142 - Flags: feedback?(benc)
Comment on attachment 9237142 [details] [diff] [review]
status-idle-fix-v2.diff

Review of attachment 9237142 [details] [diff] [review]:
-----------------------------------------------------------------

Firstly, thanks for the great writeup in Comment 61 - much appreciated!

This patch looks OK I think, but I've got some questions:

1) `m_imapMailFolderSinkIdle` is really tracking the currently SELECTed folder now, right? Why not make that explicit, and call it `m_imapSelectedFolderSink` or something?
2) what happens when the SELECTed folder is renamed/deleted or something? I'd guess `m_imapMailFolderSinkIdle` would need to be updated appropriately.
3) the `nsImapServerResponseParser` is already tracking the SELECTed IMAP mailbox name. Would be nice if we could easily map that to the correct foldersink "on the fly", so we don't have to track the SELECTed folder in nsImapProtocol too. But I realise that might be unrealistic.
4) my understanding of IMAP is that pretty much _every_ request should result in untagged responses (for the SELECTed folder). Which is why NOOP is still useful. The handling for such untagged responses should be the same regardless of the command issued - IDLE, NOOP, etc (even STATUS: any response other than a "STATUS" response refers to the SELECTed folder). This seems like a good argument in support of 1 - the SELECTed folder is potentially needed by all requests, not just IDLE.
5) Is nsImapFolderSink.OnNewIdleMessages() misleadingly named? It seems like it's used as more of a general "there's been some server activity in this folder" prod (if you think so, I'll look into it in a followup bug).
Attachment #9237142 - Flags: feedback?(benc) → feedback+

Started testing a renamed folder and didn't see any big problems other than that the rename leaves the folder not selected (new connection in Authenticated state). So you have to click it to re-select. Also, it removes the "check for new mail" flag so you have to re-set that again if you want it. But these aren't related to my changes.

I did notice one new IDLE problem but not sure why I didn't see it before (edit: probably because I was previously testing with idle/immediate turned off in tb). If the server reports the EXISTS and RECENT after the DONE is sent by TB, this is not seen as a IDLE response by TB. The IDLE rfc says these should be sent by the server. It doesn't say anything about the client but I would assume it should respond to these like EXISTS and RECENT that occur before DONE.
Then again, it appears the connection was in IDLE for about 30s before the DONE was sent, so why did the Cyrus server only report the EXISTS and RECENT after the DONE? I think I saw this several times when I noticed IDLE didn't seem to detect the new message quickly. Maybe a question for Bron.

A bit later the server responded to another IDLE with an untagged FETCH indicating the 24th message is RECENT. This triggered the response and the new messages were detected. I've never noticed this before either. Don't see why changing the folder name would causes this, especially after several TB restarts.

I'll look closer at this tomorrow and address Ben's other comments.

Bron, FYI, the Cyrus version I'm using is this: Cyrus IMAP 3.0.13-Debian-3.0.13-5 as supplied with Ubuntu 20.04. If you need more info, like TB imap logs, let me know. Thanks.

Flags: needinfo?(brong)
See Also: → 1725911

Back on this again, it does appear that my cyrus server setup has some problem with "idle" functionality. From the "systemctl status cyrus-imap.service" output I see this:

 cyrus-imapd.service - Cyrus IMAP/POP3 daemons
     Loaded: loaded (/lib/systemd/system/cyrus-imapd.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2021-08-27 02:00:35 EDT; 5min ago
   Main PID: 41110 (cyrmaster)
      Tasks: 9 (limit: 18795)
     Memory: 32.1M
     CGroup: /system.slice/cyrus-imapd.service
             ├─41110 /usr/sbin/cyrmaster -l 32 -C /etc/imapd.conf -M /etc/cyrus.conf
             ├─41125 /usr/lib/cyrus/bin/idled
             ├─41133 notifyd
             ├─41382 imapd -U 30
             ├─41383 imapd -U 30
             ├─41384 imapd -U 30
             ├─41385 imapd -U 30
             ├─41470 imapd -U 30
             └─41476 imapd -U 30

Aug 27 02:04:07 xps17lt cyrus/imap[41385]: IDLE: error sending message INIT to idled for mailbox user.gene.thre: Server(s) unavailable to complete operation. Falling back to polling every 60 seconds.

This is after uncommenting

        #idled		cmd="idled"

in /etc/cyrus.conf

Anyhow, to work around this I set

# Unix domain socket that idled listens on.
imapidlepoll: 15
idlesocket: /run/cyrus/socket/idle

in /etc/imapd.conf so that the idle poll time is shorter, 15s, than the default of 60s. So now I'm seeing the idle responses (EXISTS/RECENT) before the DONE is sent after about 15s as expected.

I'll spent too much time trying to figure this out (why IDLE is not working right) so I'll continue with this tomorrow and submit the next patch then.

Bron, if you are reading this, my cyrus setup is bare-bones. Just the server with nothing else like postfix or sendmail. Also no TLS. The way I get emails into it is via imap APPEND which works OK for what I'm doing. I do see some errors with status when I start the service and I don't know if they are related to why "idled" via the unix socket isn't working:

cyrus-imapd.service - Cyrus IMAP/POP3 daemons
     Loaded: loaded (/lib/systemd/system/cyrus-imapd.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2021-08-27 02:20:45 EDT; 3s ago
   Main PID: 41608 (cyrmaster)
      Tasks: 3 (limit: 18795)
     Memory: 7.9M
     CGroup: /system.slice/cyrus-imapd.service
             ├─41608 /usr/sbin/cyrmaster -l 32 -C /etc/imapd.conf -M /etc/cyrus.conf
             ├─41623 /usr/lib/cyrus/bin/idled
             └─41631 notifyd

Aug 27 02:20:45 xps17lt cyrus/cyr_expire[41624]: Expired 0 and expunged 0 out of 110 messages from 13 mailboxes
Aug 27 02:20:45 xps17lt cyrus/cyr_expire[41624]: duplicate_prune: pruning back 3.00 days
Aug 27 02:20:45 xps17lt cyrus/cyr_expire[41624]: duplicate_prune: purged 0 out of 0 entries
Aug 27 02:20:45 xps17lt cyrus/tls_prune[41627]: DBERROR: reading /var/lib/cyrus/db/skipstamp, assuming the worst: No such file or directory
Aug 27 02:20:45 xps17lt cyrus/tls_prune[41627]: tls_prune: /var/lib/cyrus/tls_sessions.db not found, nothing to do
Aug 27 02:20:45 xps17lt cyrus/notify[41631]: DBERROR: reading /var/lib/cyrus/db/skipstamp, assuming the worst: No such file or directory
Aug 27 02:20:45 xps17lt cyrus/notify[41631]: locking disabled: couldn't open socket lockfile /var/lib/cyrus/socket/notify-0.lock: No such file or directory
Aug 27 02:20:45 xps17lt cyrus/ctl_cyrusdb[41630]: DBERROR: reading /var/lib/cyrus/db/skipstamp, assuming the worst: No such file or directory
Aug 27 02:20:45 xps17lt cyrus/ctl_cyrusdb[41630]: checkpointing cyrus databases
Aug 27 02:20:45 xps17lt cyrus/ctl_cyrusdb[41630]: done checkpointing cyrus databases

I finally fixed the problem with my cyrus setup and idled (instant non-polled idle) is working.

I had to manually create directory /var/lib/cyrus/db and the file /var/lib/cyrus/db/skipstamp and chown them to cyrus:mail.
Also, had to create directory /var/lib/cyrus/socket and chown it to cyrus:mail.
Then systemctl restart cyrus-imapd.service and all problems went away.

But this setup error did reveal another way that imap IDLE responses could be ignored.

Flags: needinfo?(brong)

I'm glad you figured it out, and sorry for not getting back to you! That was indeed my first thought "is idled working?"

The complexity of setting up Cyrus environment so all the bits work certainly is a thing - were you installing from sourcecode there?

You shouldn't need to create skipstamp, cyrus will create it itself. Having said that, if you're using a recent enough version, twoskip is much better than skiplist.

Yes I didn't realize the not-polled/interrupt driven idle in cyrus required a separate daemon (idled).
I'm not running the latest cyrus source since I wanted to test w/o the fix you made so I'm running the ubuntu version labeled Cyrus IMAP 3.0.13-Debian-3.0.13-5. I didn't notice the idled problem at first since I was testing without idle enabled on TB.

(In reply to Ben Campbell from comment #65)

Comment on attachment 9237142 [details] [diff] [review]
status-idle-fix-v2.diff

This patch looks OK I think, but I've got some questions:

  1. m_imapMailFolderSinkIdle is really tracking the currently SELECTed
    folder now, right? Why not make that explicit, and call it
    m_imapSelectedFolderSink or something?

Yes, I agree. I'm now calling it m_imapMailFolderSinkSelected.

  1. what happens when the SELECTed folder is renamed/deleted or something?
    I'd guess m_imapMailFolderSinkIdle would need to be updated appropriately.

I responded to this in comment 66, but to keep it all together, here's what I said:
Started testing a renamed folder and didn't see any big problems other than that the rename leaves the folder not selected (new connection in Authenticated state). So you have to click it to re-select. Also, it removes the "check for new mail" flag so you have to re-set that again if you want it. But these aren't related to my changes.

  1. the nsImapServerResponseParser is already tracking the SELECTed IMAP
    mailbox name. Would be nice if we could easily map that to the correct
    foldersink "on the fly", so we don't have to track the SELECTed folder in
    nsImapProtocol too. But I realise that might be unrealistic.

Guess I'm not understanding your point here.

  1. my understanding of IMAP is that pretty much every request should
    result in untagged responses (for the SELECTed folder).

The imap rfc here https://datatracker.ietf.org/doc/html/rfc3501#section-7 states

In the selected state, the
server checks the mailbox for new messages as part of command
execution.  Normally, this is part of the execution of every command;
hence, a NOOP command suffices to check for new messages.  If new
messages are found, the server sends untagged EXISTS and RECENT
responses reflecting the new size of the mailbox.

So I guess it is more accurate to say the every command in selected state could result in untagged responses for the selected folder.

Which is why NOOP is
still useful. The handling for such untagged responses should be the same
regardless of the command issued - IDLE, NOOP, etc (even STATUS: any
response other than a "STATUS" response refers to the SELECTed folder). This
seems like a good argument in support of 1 - the SELECTed folder is
potentially needed by all requests, not just IDLE.

I've changed nsImapProtocol::OnStatusForFolder() to only use m_imapMailFolderSinkSelected where it calls OnNewIdleMessages(). So now OnNewIdleMessages() is only called for m_imapMailFolderSinkSelected at 4 places.
I'm think that's what you are suggesting here.

There may be other commands like FETCH that occur in selected state and they don't check for new messages. But I've never noticed EXISTS or RECENT being reported during FETCH or any other commands except NOOP, IDLE and STATUS (and STATUS maybe only for un-patched Cyrus).

  1. Is nsImapFolderSink.OnNewIdleMessages() misleadingly named? It seems like
    it's used as more of a general "there's been some server activity in this
    folder" prod (if you think so, I'll look into it in a followup bug).

I guess that was its original intent, to only handle idle. But now it also handles noop, status and response to idle DONE (in next diff). But I've made comments in the code indicating when it's not really handling IDLE so to me the misleading name is not a problem.

I need to submit another follow-up diff or patch. Sorry for the delay in responding to this.

Attached patch status-idle-fix.patch (obsolete) — — Splinter Review

I'll describe the changes from status-idle-fix-v2.diff.

1. SetupSinkProxy() m_imapMailFolderSinkSelected

In SetupSinkProxy() m_imapMailFolderSinkSelected is now typically just set equal to m_imapMailFolderSink since, when the URL is requesting an imap SELECT, they are both referencing the same folder. I also allow for the possibility that a new "...SinkSelected" would have to be allocated but I've never seen this occur in my testing.

2. Handle idle responses 1st in main loop

In OnInputStreamReady(), which is called on a socket transport thread and detects when an an IDLE response has occurred and triggers the main loop of an imap thread to run, I'm setting a new variable true, m_idleResponseReadyToHandle, instead of m_nextUrlReadyToRun.

This avoids a possible race where a URL (triggered on main/UI thread) and the idle response (on socket thread) occur close in time. With the original code it's possible that the URL processing in the main imap thread loop, ImapThreadMainLoop(), could cause the idle response to be ignored, since the URL is given priority (the idle response is handled only if there is no URL to processes). When the main loop wakes up, it now firsts checks if m_idleResponseReadyToHandle (set by the socket thread) is set and processes the idle response and resets m_idleResponseReadyToHandle. If m_nextUrlReadyToRun is also set, it triggers the main loop to run again to handle the URL with no delay on the next loop.

3. Avoid Idle/Status/Idle/... cycles

In the main loop, ImapThreadMainLoop(), I've made several changes to fix an issue I've noticed when there are several non-Inbox folders that the user has configured to be checked for new mail on the timed interval and imap idle is also in use. The connection will exit idle and check the status on a non-Inbox folder and then re-enter idle and then almost immediately exist idle again and check status on another non-inbox folder. This cycle can repeat many times, if there are a lot of non-Inbox folders to check before returning to idle and remaining there until the next "check for new mail" interval occurs.

Now instead of immediately returning to idle after each URL is run, I set a flag, idlePending, and reduce the loop wait time temporarily down to 1 second and only if no URL needs to be processed during the 1 second wait, then go into idle. The loop sleep time is then set back to its default of 60 seconds.

4. Add check for new mail on DONE command in EndIdle()

I observed with the Cyrus server that idle response can occur when exiting idle mode with the DONE command (comment 66 and later). So I've added a check for EXISTS and RECENT in EndIdle() on sending DONE like was added for OnStatusForFolder() when sending NOOP and STATUS and handle it like a normal idle response (before DONE).

5. Log() calls have extra parameter "gds"

For the Log() calls I've added, to find them in the IMAP log I've included an "extra" parameter as a static string "gds". This is just temporary and I'll remove them and in the Log() calls replace it with nullptr. Some or maybe all of the new Log() calls might be removed in the final version since I mostly added them for debug purposes.

6. "Try" build results

It appears that these changes haven't broken any tests based on this "try" run:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=cdc176fb3322749e4e50eb8f5bb0c61983091dce
I've also tested this successfully quite a bit with Dovecot, Cyrus and Gmail servers.

Attachment #9233027 - Attachment is obsolete: true
Attachment #9233028 - Attachment is obsolete: true
Attachment #9233030 - Attachment is obsolete: true
Attachment #9234669 - Attachment is obsolete: true
Attachment #9235309 - Attachment is obsolete: true
Attachment #9239422 - Flags: review?(benc)
Attached patch status-idle-fix-v3.diff (obsolete) — — Splinter Review

I may have not made it clear that item 2 in comment 73 only attempts to fix what looks to me like a possible problem. I've never actually seen this hypothetical race occur (idle response detected on socket at same time as a URL causing the idle response to be missed).

Also, item 3 in comment 73 only prevents unnecessary cycling into and out of idle state. It doesn't affect the actual bug as reported or cause anything else bad to occur.

So I've attached a diff with items 2 and 3 stripped out.

Comment on attachment 9239422 [details] [diff] [review]
status-idle-fix.patch

Review of attachment 9239422 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me!
I first reviewed the patch in Comment 74 before I realised there wasn't an r? on it. This patch is a superset of that one, so feel free to apply this r+ to that patch if you prefer :-)
(and if I didn't mention it already, thanks so much for all the hard work you've poured into this one, Gene!)

::: mailnews/imap/src/nsImapProtocol.cpp
@@ +6795,5 @@
> +  if (GetServerStateParser().GetIMAPstate() ==
> +      nsImapServerResponseParser::kFolderSelected)
> +    prevNumMessages = GetServerStateParser().NumberOfMessages();
> +  else
> +    imapSelected = false;

if we go through this branch, prevNumMessages will be left undefined. It is used in a conditional down below (line 6826). Some of the other conditions down there could mean it doesn't matter, but it's not obviously safe.
Attachment #9239422 - Flags: review?(benc) → review+
Attached patch status-idle-fix-v2.patch (obsolete) — — Splinter Review

Ben, Sorry to ask for another review but I noticed something right before submitting a final update to the patch. I was going to increase the time before going into idle from 1 second to 2 seconds and realized that this provides a larger window where new mail can arrive and not be detected by idle until the idle DONE is sent. So I now check for untagged responses before AsyncWait() is called on the IDLE command response.

Note: Even without a delay of going into idle, there is a possibility that mailbox changes might be missed or delayed before entering idle mode.

To accommodate the AsyncWait(), the responses to the IDLE command are handled in a special way in the parser code and was added years ago in bug 141369. I added a new inline function to the parser code to return if the imap command response sees any untagged response and use this to determine in the the protocol code if an folder update is needed. This replaces checking for a explicit untagged EXISTS and RECENT in a couple places (but not for STATUS responses) so you also now get an update if a message is deleted or a flag is changed.

A big change is in nsImapProtocol::HandleIdleResponses(). It is still called from the main loop when the socket thread detects incoming data in idle mode. I also now use it to handle the responses to the IDLE command itself, in Idle(), to now detect any untagged responses that occur before calling AsyncWait(). (Original Idle() would only parse a single line containing the "continuation" response.) This will catch any untagged responses that occur before or after the "continuation" response '+' that the server sends in response to IDLE command itself.

HandleIdleResponses() also now returns a bool which is false only if the IDLE command returns a BAD or NO response. The return is not checked when HandleIdleResponses is called from the main loop since it doesn't deal with tagged responses there.

I've retested this against Dovecot, Courier, Cyrus and gmail imap servers with good results.

From comment 75:

if we go through this branch, prevNumMessages will be left undefined. It is used in a conditional down below (line 6826). Some of the other conditions down there could mean it doesn't matter, but it's not obviously safe.

This should be resolved now. (It is also the only place I check explicitly for EXISTS and RECENT.)

Attachment #9239422 - Attachment is obsolete: true
Attachment #9239453 - Attachment is obsolete: true
Attachment #9240456 - Flags: review?(benc)
Attachment #9237142 - Attachment is obsolete: true
Attachment #9239422 - Attachment is obsolete: false

(In reply to gene smith from comment #73) -- for Bron

4. Add check for new mail on DONE command in EndIdle()

I observed with the Cyrus server that idle response can occur when exiting idle mode with the DONE command (comment 66 and later). So I've added a check for EXISTS and RECENT in EndIdle() on sending DONE like was added for OnStatusForFolder() when sending NOOP and STATUS and handle it like a normal idle response (before DONE).

Bron (if you're still reading this), with Cyrus with "idled" enabled and working, if a new message occurs right before the imap IDLE command is sent, the response to IDLE ('+' continuation) does not report the new message with untagged EXISTS. Instead, after idle mode is entered and tb is waiting for a server response for 15 seconds the EXISTS is sent by cyrus. But if the new messages arrives after IDLE is sent, it is reported with EXISTS immediately and tb sees the new message (almost) immediately.
I think the reason for the 15 second delay in reporting the EXISTS is due to my setting in /etc/imapd.conf "imapidlepoll 15". If I remove this setting, cyrus defaults imapidlepoll to 60 seconds so, with my tb biff time set to 1 minute, the new messages is seen in the response to imap DONE 1 minute later.
I don't see this with dovecot, courier or gmail. If the new mail arrives right before IDLE is sent, the EXISTS response occurs right after the '+' continuation response to IDLE and tb sees the new message then with no delay. So it appears the cyrus "idled" only works when the new mail is detected after IDLE is sent; otherwise the new mail is detected by polling.

(In reply to gene smith from comment #77)

Bron (if you're still reading this), with Cyrus with "idled" enabled and working, if a new message occurs right before the imap IDLE command is sent, the response to IDLE ('+' continuation) does not report the new message with untagged EXISTS. Instead, after idle mode is entered and tb is waiting for a server response for 15 seconds the EXISTS is sent by cyrus. But if the new messages arrives after IDLE is sent, it is reported with EXISTS immediately and tb sees the new message (almost) immediately.
I think the reason for the 15 second delay in reporting the EXISTS is due to my setting in /etc/imapd.conf "imapidlepoll 15". If I remove this setting, cyrus defaults imapidlepoll to 60 seconds so, with my tb biff time set to 1 minute, the new messages is seen in the response to imap DONE 1 minute later.

Ooh, interesting. We do the same index_check before we start idling that we do on each time.

Oh... heh. We didn't flush the output. So the EXISTS didn't actually get sent over the wire until the first timeout or event. OK, that's easily fixed :)

https://github.com/cyrusimap/cyrus-imapd/pull/3664

Here's the entire diff:

diff --git a/imap/imapd.c b/imap/imapd.c
index 1d94b2b8f8..bb0d90df54 100644
--- a/imap/imapd.c
+++ b/imap/imapd.c
@@ -3279,6 +3279,7 @@ static void cmd_idle(char *tag)
         idling = 1;
 
         index_release(imapd_index);
+        prot_flush(imapd_out);
         while ((flags = idle_wait(imapd_in->fd))) {
             if (deadline_exceeded(&deadline)) {
                 syslog(LOG_DEBUG, "timeout for user '%s' while idling",
Summary: Thunderbird doesn't check my Fastmail account automatically for new mail → Thunderbird doesn't check my Fastmail account automatically for new mail (actually, not really Fastmail specific)
Comment on attachment 9240456 [details] [diff] [review]
status-idle-fix-v2.patch

Review of attachment 9240456 [details] [diff] [review]:
-----------------------------------------------------------------

I have to admit I don't understand all the nuances here (IMAP code is just too complex to really reason about all the possible side effects), but your reasoning all seems sound and the code looks fine to me.
A couple of nits, but r+.

::: mailnews/imap/src/nsImapProtocol.cpp
@@ +698,1 @@
>    if (m_runningUrl) {

I'd probably take the opportunity to simplify things and early-out here if there's no m_runningUrl), especially as the function grows in size/complexity.

@@ +701,5 @@
>        (void)m_runningUrl->GetImapMailFolderSink(
>            getter_AddRefs(aImapMailFolderSink));
>        if (aImapMailFolderSink) {
>          m_imapMailFolderSink = new ImapMailFolderSinkProxy(aImapMailFolderSink);
> +        newFolderSink = m_imapMailFolderSink;

While this works, it seems confusing (setting a bool var to a pointer value).
Why not just use:
```
newFolderSink = true;
```
(operator new will never return null)

@@ +711,5 @@
> +    // Obtain a sink proxy for the folder to be imap SELECTed on this connection
> +    // by the nsImapSelectFolder URL. It is needed to handle untagged IDLE
> +    // responses and untagged responses such as during NOOP or STATUS to detect
> +    // new mail for the SELECTed folder.
> +    if (m_runningUrl) {

I don't think this is needed (it already checks m_runningUrl at the start of the function).
Attachment #9240456 - Flags: review?(benc) → review+

if (m_runningUrl) {

I'd probably take the opportunity to simplify things and early-out here if there's no m_runningUrl), especially as the function grows in size/complexity.

Did it. When function entered, !m_runningUrl now does an immediate return of NS_OK.
This did require that everything below had to be moved two spaces to the left. (Hopefully won't grow any more.)

  •    newFolderSink = m_imapMailFolderSink;

While this works, it seems confusing (setting a bool var to a pointer value).
Why not just use:

newFolderSink = true;

(operator new will never return null)

I was thinking in terms of malloc. But you're right, I didn't know that about new. Now setting newFolderSink to true like you recommend.

  • if (m_runningUrl) {

I don't think this is needed (it already checks m_runningUrl at the start of the function).

Right. Fixed it.

Ok, made the changes and of course clang format complained but let it fix it. Compiles OK and a quick retest seems to work OK. So I'll set the check-in flag.
Thanks for the feedback and reviews!

Attachment #9239422 - Attachment is obsolete: true
Attachment #9240456 - Attachment is obsolete: true
Attachment #9241000 - Flags: review+
Attachment #9240456 - Attachment is obsolete: false

The checkin is requested for status-idle-fix-v3.patch which includes some minor changes requested in the review of status-idle-fix-v2.patch by Ben Campbell / benc.

Keywords: checkin-needed-tb
Status: NEW → ASSIGNED
status-thunderbird_esr91: --- → wontfix
OS: Windows 10 → All
Hardware: x86_64 → All
Target Milestone: --- → 94 Branch
Attachment #9240456 - Attachment is obsolete: true

Pushed by mkmelin@iki.fi:
https://hg.mozilla.org/comm-central/rev/5c3a8f08480c
Improve new mail detection for imap IDLE and non-Inbox folders. r=benc

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Keywords: checkin-needed-tb
Resolution: --- → FIXED
Regressions: 1747173
See Also: → 1745130
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: