.CountChanged not fired randomly

DierkDroth commented 2 years ago

I'm chasing an issue with a Microsoft 365 account (CondStore=false) where InBox.CountChanged is randomly not triggered when calling IMapClient.NoOpAsync.

I double checked that I'm subscribed to InBox.CountChanged
it happened several hours after the connection got restored in the morning as I 'woke up' my laptop after 'sending it to sleep' the night before
this happens very rarely. I could take a couple of days being connected until I would see it again

This is MailKitLite 3.3.0.

Would you have any idea where I could start looking?

jstedfast commented 2 years ago

Most likely this means that the folder wasn't re-selected after re-connecting.

ImapFolder.OnExists(int count) is where the event would get thrown
ImapEngine.ProcessUntaggedResponse() is where that above method gets called in response to a NOOP untagged response.

Notice that it only does this if the folder is != null, though.

At the top of that method, we have:

var folder = current.Folder ?? Selected;

The current variable refers to the current command being executed. The Folder property will only be set if the command is an operation on a folder, so for NOOP it will always be null but the Selected variable is the currently selected folder as tracked by the ImapEngine which shouldn't be null unless a folder hasn't been selected (aka opened) yet.

DierkDroth commented 2 years ago

@jstedfast thanks for your feedback.

I'm not sure I understand. My re-connect logic is the exact same logic as on initial connect - aka the apps goes through a full connect cycle - which is:

(disposing old IMapClient)
create new IMapClient instance
.ConnectSync
.AuthenticateAsync
getting IMapClient.InBox
.FetchAsync 'outstanding' messages
subscribe InBox.CountChanged/.MessageExpunged/.MessageFlagsChanged
IMapClient.NoOpAsync every minute

What am I missing on re-establishing a broken connection?

jstedfast commented 2 years ago

Well, let me ask you this:

How do you know it's not being fired correctly?

If the expectation is that when you send a message to the account, you should get a CountChanged event, that's not necessarily going to happen as quickly as you may think - it all depends on the server providing timely notifications.

It would not be unreasonable to assume that if you can see it in your webmail browser window, it should be seen by the IMAP client as well, but again, that's not always the case.

These webmail clients are not using IMAP and often the IMAP support is a second-class citizen compared to the native protocol of the server.

With Exchange, the IMAP interface is actually running as a separate process from the server itself and has a cache which it needs to periodically update, so this isn't instantanious and explains why the webmail client can see messages before the IMAP client can.

DierkDroth commented 2 years ago

@jstedfast thanks for follow up.

On the case above I'm comparing my app with Outlook desktop client on Windows 11 (running both on the same laptop). I did not see .CountChanged being triggered for several minutes and several .NoOpAsync calls.

However, I also got a similar report from a customer who compared my app with their Outlook desktop client as well.

What would be a reasobale time until ultimately .CountChanged should be fired - provided my app would call .NoOpAsync verey minute?

jstedfast commented 2 years ago

Honestly, I'm not sure. It takes as long as it takes :-)

DierkDroth commented 2 years ago

Well, my customer reports missing mails several days back. However, this might actually by a different issue and not related to what I saw on my laptop...

Let me ask you this: another way to update INBOX.UidNext would be closing and re-opening the INBOX folder ... which I could do every minute. Is there any (performance?) impact which should prevent my doing that. Note: in an operational environment this logic would be run by server which would manage thousands of IMAP accounts...

jstedfast commented 2 years ago

my customer reports missing mails several days back

That's not likely the same issue

Let me ask you this: another way to update INBOX.UidNext would be closing and re-opening the INBOX folder ... which I could do every minute. Is there any (performance?) impact which should prevent my doing that.

That all depends on the server. I would recommend against closing it, though. Just call Open() again if you go this route.

DierkDroth commented 2 years ago

@jstedfast thanks.

That's interesting. Right now I have this logic - which is called after .CountChanged was triggered

if (inbox.IsOpen)
    await inBox.CloseAsync(false, cts.Token);
await inbox.OpenAsync(FolderAccess.ReadWrite, cts.Token);

Are you saying I just should leave .CloseAsync? Wouldn'y repeatitive calls of .OpenAsync stack up some resource consumption?

Also, back to the original issue: if a mail was seen in Outlook desktop client (not WEB client), wouldn't that mean that I could expect .CountChanged being called if I called .NoOpAsync?

jstedfast commented 2 years ago

Are you saying I just should leave .CloseAsync? Wouldn'y repeatitive calls of .OpenAsync stack up some resource consumption?

Correct, CloseAsync() is not really necessary. The IMAP server is supposed to handle this.

The SELECT and EXAMINE commands implicitly close the previously opened folder (if there was one).

Also, back to the original issue: if a mail was seen in Outlook desktop client (not WEB client), wouldn't that mean that I could expect .CountChanged being called if I called .NoOpAsync?

Only if Outlook was configured to use IMAP.

DierkDroth commented 2 years ago

@jstedfast thanks for your support.

I'll close this issue for now, since I have a suspicion there's a logic flaw in my side which I wanted to better understand first ...

DierkDroth commented 2 years ago

@jstedfast unfortunately I will have to re-open that issue. I just a case where:

I started my MailKit client at 10:59 UTC and subscribed to INBOX on a Microsoft 365 account (no indication that there would be something wrong. Could I even check?!?). This is CONDSTORE=false
I sent an email from my iCloud account at 11:13 UTC. That email was received by my Outlook client at 11:14 UTC.
my MailKit client did not fire any .CountChanged event
I shutdown the MailKit client and restarted it immediately at 11:17 UTC where the email was pulled correctly right on startup
I confirmed by a test mail (from a different Microsoft 365 account) that after restart the MailKit client then received mails as expected

This leaves me suspicous that for some reason there is a random condition where .CountChanged is not fired.

Any idea what I could check?

jstedfast commented 2 years ago

First you need to verify in the logs that the server is even notifying the client. Look for a corresponding "* # EXISTS" line.

My bet is that the server isn't sending one.

DierkDroth commented 2 years ago

@jstedfast understand. I will turn on the in-depth tracing again ....

DierkDroth commented 2 years ago

@jstedfast I just had another case - fortunately with full traces on. Here is what I found:

appears the server was killing the connection. I got a 'An existing connection was forcibly closed by the remote host.' exception
my code goes through a proper re-connect logic which is -- creating a new IMapClient instance -- .ConnectAsync -> success -- get INBOX from imapClient.Inbox -- subscribe to INBOX.CountChanged
mails should be coming in a couple of hours later -> .CountChanged not fired, nor is there any message from the IMAP server
I sent another mail -> .CountChanged again not fired, nor is there any message from the IMAP server
Outlook client saw both mails
I fired up a 2nd instance of my app on the same machine -> got both mails right on connect -> good

I have a suspicion there is something wrong with subscribing to INBOX.CountChanged after reconnect. This is MailKitLite 3.3.0, again on a Microsoft 365 (CONDSTORE=false) account

Would you have any idea what might be going wrong?

jstedfast commented 2 years ago

I've investigated this to death the last time you reported it and I found nothing. I even wrote unit tests to test this scenario and again, it works 100%.

DierkDroth commented 2 years ago

@jstedfast I appreciate the efforts you spent. Still, there is an issue - not sure where and what though...

A couple of questions come to mind:

do your test scenarios cover a case where the socket got killed by 'some external' cause - to replicate scenario above?
how could I try to replicate the scenario and what could I use to 'kill the socket' from outside the app?

Also FYI, I restarted the (failing) client from above and it immediately received both emails as expected.

jstedfast commented 2 years ago

how could I try to replicate the scenario and what could I use to 'kill the socket' from outside the app?

Unplug your network cable.

DierkDroth commented 2 years ago

@jstedfast I'm on a WIFI. Turning that off throws a different exception.

So I installed TcpView and killed the socket connection on all my mail accounts. This got me the exception as expected but unfortunately I could not reproduce the issue.

What else could I try?

Also: It's surprising that this is always is the same Microsoft 365 account. I have no another Microsoft 365 connected + an iCloud accunt + a GMail account + a GMX account ... none of the shows the problem (so far).

jstedfast commented 2 years ago

mails should be coming in a couple of hours later -> .CountChanged not fired, nor is there any message from the IMAP server

I sent another mail -> .CountChanged again not fired, nor is there any message from the IMAP server

Does this mean there is no * # EXISTS response in the imap logs?

If so, you're done. You've discovered the problem.

DierkDroth commented 2 years ago

Correct, there is no message from the IMAP server at all.

Which is why I suspect there is something wrong with the subscription. Curious, I see no messages going out as I subscribe (= attaching an event handler to INBOX.CountChanged) ... whereas every .NoOpAsync in fact appears to send something out the IMAP server. Is that expected?

Also, below is the trace of what I got on my reconnect. May be that helps?!?

2022-08-18 04:11:27:887 Imap.Connected: 'imaps://outlook.office365.com:993/' 2022-08-18 04:11:27:893 Imap.S: OK The Microsoft Exchange IMAP4 service is ready. [QQBTADkAUABSADAANABDAEEAMAAwADgAMgAuAGUAdQByAHAAcgBkADAANAAuAHAAcgBvAGQALgBvAHUAdABsAG8AbwBrAC4AYwBvAG0A] 2022-08-18 04:11:27:893 Imap.C: Q00000000 CAPABILITY 2022-08-18 04:11:27:931 Imap.S: CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+ 2022-08-18 04:11:27:931 Imap.S: Q00000000 OK CAPABILITY completed. 2022-08-18 04:11:27:932 Imap.C: Q00000001 AUTHENTICATE PLAIN AGRpZXJrLmRyb3RoQG5pbmphdHJhZGVyLmNvbQAyTW9PN083dHNiM0hMa3U4ajJvaExCZGROZVAxY2ZSSw== 2022-08-18 04:11:32:452 Imap.S: Q00000001 OK AUTHENTICATE completed. 2022-08-18 04:11:32:452 Imap.C: Q00000002 CAPABILITY 2022-08-18 04:11:32:579 Imap.S: CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CLIENTACCESSRULES CLIENTNETWORKPRESENCELOCATION BACKENDAUTHENTICATE CHILDREN IDLE NAMESPACE LITERAL+ 2022-08-18 04:11:32:579 Imap.S: Q00000002 OK CAPABILITY completed. 2022-08-18 04:11:32:580 Imap.C: Q00000003 NAMESPACE 2022-08-18 04:11:32:707 Imap.S: NAMESPACE (("" "/")) NIL NIL 2022-08-18 04:11:32:707 Imap.S: Q00000003 OK NAMESPACE completed. 2022-08-18 04:11:32:707 Imap.C: Q00000004 LIST "" "INBOX" 2022-08-18 04:11:32:852 Imap.S: LIST (\Marked \HasChildren) "/" INBOX 2022-08-18 04:11:32:852 Imap.S: Q00000004 OK LIST completed. 2022-08-18 04:11:32:852 Imap.C: Q00000005 SELECT INBOX 2022-08-18 04:11:33:035 Imap.S: 0 EXISTS 2022-08-18 04:11:33:035 Imap.S: 0 RECENT 2022-08-18 04:11:33:035 Imap.S: FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent) 2022-08-18 04:11:33:035 Imap.S: OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags 2022-08-18 04:11:33:035 Imap.S: OK [UIDVALIDITY 14] UIDVALIDITY value 2022-08-18 04:11:33:035 Imap.S: OK [UIDNEXT 1933] The next unique identifier value 2022-08-18 04:11:33:035 Imap.S: Q00000005 OK [READ-WRITE] SELECT completed. 2022-08-18 04:11:33:035 Imap.C: Q00000006 LIST "" "%" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" Archive 2022-08-18 04:11:33:239 Imap.S: LIST (\HasChildren) "/" Calendar 2022-08-18 04:11:33:239 Imap.S: LIST (\HasChildren) "/" Contacts 2022-08-18 04:11:33:239 Imap.S: LIST (\HasChildren) "/" "Conversation History" 2022-08-18 04:11:33:239 Imap.S: LIST (\Marked \HasChildren \Trash) "/" "Deleted Items" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" Done 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren \Drafts) "/" Drafts 2022-08-18 04:11:33:239 Imap.S: LIST (\Marked \HasChildren) "/" INBOX 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" Journal 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren \Junk) "/" "Junk Email" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "News Feed" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" Notes 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" Outbox 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "Quick Step Settings1" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "Quick Step Settings2" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "RSS Feeds" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "RSS Subscriptions" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "Search results" 2022-08-18 04:11:33:239 Imap.S: LIST (\Marked \HasNoChildren \Sent) "/" "Sent Items" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "Suggested Contacts" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasChildren) "/" "Sync Issues" 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" Tasks 2022-08-18 04:11:33:239 Imap.S: LIST (\HasNoChildren) "/" "Working Set" 2022-08-18 04:11:33:239 Imap.S: Q00000006 OK LIST completed. 2022-08-18 04:11:33:239 Imap.C: Q00000007 SUBSCRIBE Done 2022-08-18 04:11:33:369 Imap.S: Q00000007 OK SUBSCRIBE completed. 2022-08-18 04:11:33:370 Imap.C: Q00000008 LIST "" "%" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" Archive 2022-08-18 04:11:33:512 Imap.S: LIST (\HasChildren) "/" Calendar 2022-08-18 04:11:33:512 Imap.S: LIST (\HasChildren) "/" Contacts 2022-08-18 04:11:33:512 Imap.S: LIST (\HasChildren) "/" "Conversation History" 2022-08-18 04:11:33:512 Imap.S: LIST (\Marked \HasChildren \Trash) "/" "Deleted Items" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" Done 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren \Drafts) "/" Drafts 2022-08-18 04:11:33:512 Imap.S: LIST (\Marked \HasChildren) "/" INBOX 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" Journal 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren \Junk) "/" "Junk Email" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "News Feed" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" Notes 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" Outbox 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "Quick Step Settings1" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "Quick Step Settings2" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "RSS Feeds" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "RSS Subscriptions" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "Search results" 2022-08-18 04:11:33:512 Imap.S: LIST (\Marked \HasNoChildren \Sent) "/" "Sent Items" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "Suggested Contacts" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasChildren) "/" "Sync Issues" 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" Tasks 2022-08-18 04:11:33:512 Imap.S: LIST (\HasNoChildren) "/" "Working Set" 2022-08-18 04:11:33:512 Imap.S: Q00000008 OK LIST completed. 2022-08-18 04:11:33:512 Imap.C: Q00000009 LIST "" "%" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" Archive 2022-08-18 04:11:33:648 Imap.S: LIST (\HasChildren) "/" Calendar 2022-08-18 04:11:33:648 Imap.S: LIST (\HasChildren) "/" Contacts 2022-08-18 04:11:33:648 Imap.S: LIST (\HasChildren) "/" "Conversation History" 2022-08-18 04:11:33:648 Imap.S: LIST (\Marked \HasChildren \Trash) "/" "Deleted Items" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" Done 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren \Drafts) "/" Drafts 2022-08-18 04:11:33:648 Imap.S: LIST (\Marked \HasChildren) "/" INBOX 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" Journal 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren \Junk) "/" "Junk Email" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "News Feed" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" Notes 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" Outbox 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "Quick Step Settings1" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "Quick Step Settings2" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "RSS Feeds" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "RSS Subscriptions" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "Search results" 2022-08-18 04:11:33:648 Imap.S: LIST (\Marked \HasNoChildren \Sent) "/" "Sent Items" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "Suggested Contacts" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasChildren) "/" "Sync Issues" 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" Tasks 2022-08-18 04:11:33:648 Imap.S: LIST (\HasNoChildren) "/" "Working Set" 2022-08-18 04:11:33:648 Imap.S: Q00000009 OK LIST completed.

jstedfast commented 2 years ago

Curious, I see no messages going out as I subscribe (= attaching an event handler to INBOX.CountChanged) ... whereas every .NoOpAsync in fact appears to send something out the IMAP server. Is that expected?

Yes, that is expected. There's no IMAP command to subscribe to a "CountChanged" event, it's just hard-coded as part of the protocol to send * # EXISTS when the count changes. MailKit's ImapFolder class just uses C# events to relay that notification up to you. If you don't subscribe, the ImapFolder.Count property still changes, you just don't get an event.

Anyway, back to the issue...

Correct, there is no message from the IMAP server at all.

That means there's nothing you or I can do to "fix" the CountChanged event not firing.

The problem is the server.

DierkDroth commented 2 years ago

@jstedfast well, this quite concerning given that Microsoft 365 is not a small player in even trying to move all their legacy exchange customers to 365.

If this renders MailKit 'useless' for Microsoft 365 then this would be quite a desaster.

Is there an alternate approach to check if the account has new mails which should be pulled?

DierkDroth commented 2 years ago

Is there anything else which I could double check to make sure I'm not screwing up things on my side?

DierkDroth commented 2 years ago

@jstedfast here is another 'wild' speculation.

The account is an OAuth2 authentication. Could it be that the token is 'silently' expired by the server. I mean in case above there have been several hours between the successful reconnect and the first - and failed - mail receipt. May be the token 'somehow' expired?!?

jstedfast commented 2 years ago

Could it be that the token is 'silently' expired by the server.

Unlikely but anything is possible?

Is there an alternate approach to check if the account has new mails which should be pulled?

You could try closing the folder and then reopening it. Or switching to another folder and then switching back.

ekalchev commented 2 years ago

I can confirm we had similar issue with Microsoft imap and we found that the problem was that IMAP wasn't sending EXISTS when it should and the problem wasn't in MailKit. The effect from for the user was that sometimes we couldn't detect there a new mail in Inbox. I can't remember much, because it was long time ago so don't ask me for details.

DierkDroth commented 2 years ago

@ekalchev thanks for confirming the issue. I was challenging my mental sanity already ;-)

Anyway, have you guys been able to resolve/work around the issue? If so, do you have any recollection on how you achieved that?

jstedfast commented 2 years ago

@DierkDroth back in my GNOME Evolution developer days, we tried various tricks to work around similar problems. My recollection is that switching folders was the most fruitful option.

Basically the idea is to force the server to drop its cache of the currently selected folder and then forcing it to reload it.

These days, there is an UNSELECT command which may be a better option.

if (client.Capabilities.HasFlag (ImapCapabilities.Unselect)) {
    // Unselect the folder to force the server to drop its in-memory folder state.
    folder.Close (expunge: false);
} else {
    // Select a different folder to force the server to drop this folder's in-memory state.
    anotherFolder.Open (FolderAccess.ReadWrite);
}

// Re-open the folder
folder.Open (FolderAccess.ReadWrite);

In the above code snippet, I check for the UNSELECT capability because ImapFolder.Close(bool expunge, CancellationToken cancellationToken) is a no-op when expunge: false for IMAP servers that don't support the UNSELECT command. IMAP's CLOSE command (expunge: true) will expunge the folder and you probably don't want to do that.

As with all work-arounds for glitchy IMAP servers, YMMV.

DierkDroth commented 2 years ago

@jstedfast thanks for the hint.

Do you recall how frequently you guys did that? Once per hour? Else?

Also, would you know if this problem occurs on others than MS 365 servers as well?

jstedfast commented 2 years ago

I don't remember, but I wouldn't be surprised if it was Exchange back then, too.

DierkDroth commented 2 years ago

@jstedfast thanks again

I'm about implementing a logic where your code above is executed if

this is a CONDSTORE=false account (not sure if that is good idea, but so far I only have seen it on CONDSTORE=false accounts)
for more than 1 hour there was no .CountChanged event fired

We'll see how that goes...

DierkDroth commented 2 years ago

@jstedfast this issue is killing me. I just got it again and mails are missed.

Here is what I see when doing the 'unselect logic' as per above:

2022-08-30 13:15:24:860 Imap.C: G00000577 UNSELECT
2022-08-30 13:15:24:977 Imap.S: G00000577 OK UNSELECT completed.
2022-08-30 13:15:24:984 Imap.C: G00000578 SELECT INBOX
2022-08-30 13:15:25:266 Imap.S: * 1 EXISTS
2022-08-30 13:15:25:266 Imap.S: * 0 RECENT
2022-08-30 13:15:25:266 Imap.S: * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
2022-08-30 13:15:25:266 Imap.S: * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
2022-08-30 13:15:25:266 Imap.S: * OK [UNSEEN 1] Is the first unseen message
2022-08-30 13:15:25:266 Imap.S: * OK [UIDVALIDITY 14] UIDVALIDITY value
2022-08-30 13:15:25:266 Imap.S: * OK [UIDNEXT 2146] The next unique identifier value
2022-08-30 13:15:25:266 Imap.S: G00000578 OK [READ-WRITE] SELECT completed.

Next I do a .NoOpAsync

2022-08-30 13:15:25:266 Imap.C: G00000579 NOOP
2022-08-30 13:15:25:384 Imap.S: G00000579 OK NOOP completed.

... and that's all I get, no .CountChanged triggered ...

The last (successful) connect attempt + subscription to INBOX events was done here

2022-08-30 04:27:06:390 (6627c663-3646-456e-b6dd-18dfff4417f3) Mail.MailClient.ConnectAsync: mailAccount='XXXX'
...
2022-08-30 04:27:11:110 (6627c663-3646-456e-b6dd-18dfff4417f3) Mail.MailClient.SubscribeMailFolderEvents: mailAccount='XXXX'

Lastly, I disconnected and reconnected the account (while I left the app running) and all missing mails came in as expected.

Would you have any idea what else I could try?

jstedfast commented 2 years ago

How many messages are in the folder counting the new message(s)? 2?

What I would expect to see is this response to the NoOpAsync:

2022-08-30 13:15:25:266 Imap.C: G00000579 NOOP
2022-08-30 13:15:25:384 Imap.S: * 2 EXISTS
2022-08-30 13:15:25:384 Imap.S: G00000579 OK NOOP completed.

DierkDroth commented 2 years ago

Nope, the very next .NoOpAsync - and the following ones - only have what I pasted above Here is another one a few minutes later:

2022-08-30 13:22:26:205 Imap.C: G00000586 NOOP
2022-08-30 13:22:26:322 Imap.S: G00000586 OK NOOP completed.

Or are you looking for something different?

jstedfast commented 2 years ago

Without the * # EXISTS response, there will be no CountChanged event is all I'm saying

DierkDroth commented 2 years ago

@jstedfast yep, sound like we're back to square #1. What a nightmare ...

Would you have any other idea on what I could try?

jstedfast commented 2 years ago

It looks like you tried the UNSELECT/SELECT idea based on the logs, which was the best idea I had.

The only other idea I have is to try playing with the ImapFolder.Check() method (or CheckAsync).

Perhaps some combination of that plus the UNSELECT/SELECT will work?

DierkDroth commented 2 years ago

Thanks @jstedfast. I'll give it try ...

I'm sorry to say this (to you), but I'm starting to hate the MS 365 mail servers...

DierkDroth commented 12 months ago

@jstedfast well, I'm back to this issue since I got a few more report recently.

Question in your proposal above: Could IMapFolder.Check be issued as the folder is closed as well (would this actually make any sense?!?) or 'only' as the IMapFolder is open?

jstedfast commented 12 months ago

I think the folder has to be open.

DierkDroth commented 12 months ago

Thanks @jstedfast

DierkDroth commented 12 months ago

@jstedfast I'm still chewing on the most recent reports and went back to your sample implementation here where you made the important statement which my code is relying on as well: If messages have been expunged, then the MessageExpunged event should also fire and it should fire *before* the CountChanged event fires.

I'm just hitting the bushes: have you ever seen a case where MessageExpunged would be fired after CountChanged. If so, then this might be an explanation for what I'm seeing when analyzing the reports.

jstedfast commented 12 months ago

I have not, but I suppose that it is possible

DierkDroth commented 12 months ago

Thanks for your continued support @jstedfast. I left another sponsor payment...

I'm now trying an approach which would not rely on MessageExpungedbeing fired before CountChanged. I'll see if that would improve the situation...

DierkDroth commented 6 months ago

@jstedfast this appears to be a never ending story: after several months without any issue I now again got a report from the customer that mails would not make it through.

My current implementation goes every hour through this logic:

close the INBOX folder
open a different folder
close that folder
open INBOX folder This is in an attempt to force the IMAP server to clear its cache. Aparrently, it does not help...

I asked the customer to completely close the connection (= dispose the IMAP client) and connect again and as expected all missing emails came through. So the only 'sledge hammer' logic I could think of is disposing the IMAP client every hour and open it again.

Could you think of another less impactful option before I tried that? Would you have any objections in principle against the 'brute force' approach above?

jstedfast commented 6 months ago

Ouch :(

Sounds like the brute force option is the only option.

Just to confirm, the Office365 server is really not sending the * # EXISTS notification (after some period of time)?

Have you tried submitting a bug report to the Office365 team? I think when I asked them how to go about that, they said there's a Feedback menu item or something somewhere. I don't use Office365 myself, so I'm not sure where it would be.

They'll probably want logs and/or other info that would allow them to investigate via telemetry (maybe account name and a rough time of day? I'm not sure, just guessing)

DierkDroth commented 6 months ago

@jstedfast thanks again for getting back to me. Unfortunately I don't have logs on that case. I would have to turn on detailed logs for the production server and have them running again for months ... not an appealing option, I guess.

Are you aware of any reason to not try the 'brute force' approach (on CONDSTORE=false accounts)?

jstedfast commented 6 months ago

I'm not aware of any reason not to try the brute force approach, so it should be ok to do.

Even with CONDSTORE=true, it should be ok to do.

DierkDroth commented 6 months ago

Thanks @jstedfast. OK, I'll give it try...

DierkDroth commented 1 month ago

@jstedfast it came to my attention that the 'brute force' approach for CONDSTORE=false accounts has a downside: there are users out there who have gazillions of mails in their INBOX (for whatever reason). Processing these mails in a 'brute force' approach e.g. every hour will put some unwelcome stress on the IMAP server as well as on my own infrastructure.

I now have the idea to only process 'the last 100 mails' on disconnect/reconnect. Right now I have this code to fetch the unique IDs:

List<UniqueId> uniqueIds = ((ulong) MailAccount.HighestModSeq > 0
        ? await inboxFolder.FetchAsync(0, -1, (ulong) MailAccount.HighestModSeq, MessageSummaryItems.UniqueId, cts.Token)
        : await inboxFolder.FetchAsync(minIndex, -1, MessageSummaryItems.UniqueId, cts.Token)).Select(m => m.UniqueId)
    .ToList()
    .GroupBy(o => o.Id)             // remove duplicates
    .Select(o => o.First())
    .ToList();

How could I modify the MailAccount.HighestModSeq == 0 branch (CONDSTORE=false) to only get the latest 100 mails on disconnect/reconnect?

Would you have an idea for a smarter approach than mine?

jstedfast / MailKit

.CountChanged not fired randomly #1401