MailClient.NoOpAsync not triggering .CountChanged?!?

[DierkDroth]

I have a customer who reports that my app would miss incoming mails.

Details:

• customer was working with the app and moved emails using the app from INBOX to a dedicated archive folder
• he also moved mails from INBOX to that archive folder using outlook
• he then experienced that an email which was received by Outlook did not make it to the app while he was working with the app

I checked traces and found this:
2021-11-13 15:53:39:915 Mail.MailClient.NoOpAsync: mailAccount='#mail account#'
2021-11-13 15:53:39:915 Imap.C: D00000026 NOOP
2021-11-13 15:53:39:939 Imap.S: * 1 RECENT
2021-11-13 15:53:39:939 Imap.S: * 1 EXISTS
2021-11-13 15:53:39:939 Imap.S: D00000026 OK NOOP completed.

The 2 lines '1 RECENT' and '1 EXISTS' are different than the other .NoOpAsync polls which I do every minute. However, it appears they did not trigger .CountChanged (I only now added traces to confirm, so I have no hard evidence yet at this point).

Would you have any idea why .CountChanged might not have been triggered?

Thanks in advance

[jstedfast]

I need more of the log to know

[DierkDroth]

@jstedfast which parts would you need? When connecting, to see what features the IMAP server has?

Other than that there only are the recurring .NoOpAsync calls every minute, which don't show anything around that time - apparently since there was no mail coming in (nor sent)

[jstedfast]

I need to see at least the SELECT or EXAMINE command and any other EXISTS/EXPUNGE notifications leading up to the one you pasted.

Remember: IMAP is a state-driven protocol. That means that MailKit tracks that state. Consider the following theoretical exchange:

C: D00000025 SELECT INBOX
S: ...
S: * 1 EXISTS
S: ...
S: D00000025 OK SELECT completed.
C: D00000026 NOOP
S: * 1 RECENT
S: * 1 EXISTS
S: D00000026 OK NOOP completed.

That wouldn't emit a CountChanged event because it was already known that 1 message existed.

[DierkDroth]

@jstedfast ok, here is the last action (it really was the prior .NoOpAsync) on this account before the one above:

2021-11-13 15:52:39:877 Mail.MailClient.NoOpAsync: mailAccount='#account#'
2021-11-13 15:52:39:878 Imap.C: D00000025 NOOP
2021-11-13 15:52:39:898 Imap.S: D00000025 OK NOOP completed.

And here is the last 'real' action on that account:

2021-11-13 15:50:07:001 Imap.C: D00000021 UID STORE 57985 +FLAGS.SILENT (\Deleted)
2021-11-13 15:50:07:047 Imap.S: D00000021 OK STORE completed.
2021-11-13 15:50:07:047 Imap.C: D00000022 UID EXPUNGE 57985
2021-11-13 15:50:07:115 Imap.S: * 1 EXPUNGE
2021-11-13 15:50:07:115 Imap.S: * 0 EXISTS
2021-11-13 15:50:07:172 Imap.S: D00000022 OK EXPUNGE completed.

Does this help?

[jstedfast]

Unfortunately I don't think it does. I'm pretty sure I have unit tests for exactly this scenario, so I was expecting something more ... unexpected I guess.

[DierkDroth]

@jstedfast thank for your feedback.

Does you comment suggest you would consider this a bug in MailKit?
Would you need some other info from me?

[jstedfast]

No, it means that I have unit tests that test this exact scenario and those unit tests pass, thereby suggesting there is no bug in MailKit.

I'm looking over the code right now and you should have gotten 2 CountChanged events. One when the server sent * 1 EXPUNGE, none for the following * 0 EXISTS (because it was emitted as a result of the previous EXPUNGE notification) and then a CountChanged event is emitted as a result of * 1 EXISTS in the next NOOP.

Are you sure that you are subscribed to the CountChanged events on this particular folder?

[DierkDroth]

@jstedfast to clarify ... may be I'm doing something wrong here:

• upon connect I subscribe to the .CountChanged, .MessageExpunged, .MessageFlagsChanged events of INBOX
• however, there is an 'archive' folder which I have to 'switch to' at times and have to close INBOX
• on opening INBOX again I do not subscribe to the events above again.

Could that be the source of the problem?

[jstedfast]

That shouldn't be an issue.

[DierkDroth]

@jstedfast odd .. I kinda was hoping I did screw it up there ;-)

[DierkDroth]

... to make sure we're on the same page. When working on the 'archive' folder my code does this:

INBOX.CloseAsync
Archive.OpenAsync
.... do stuff ...
Archive.CloseAsync
INBOX.OpenAsync (but don't subscribe to events above again)

[jstedfast]

Correct

[DierkDroth]

@jstedfast what could be done to trace down the issue? What next steps would you suggest?

[jstedfast]

Do you log anything in your callback? Can that be tied to the protocol log?

[DierkDroth]

@jstedfast I deployed a version of my app with enhanced traces. I'll get back to you as I had more evidence...

[jstedfast]

I've redesigned this in master to always emit CountChanged when the IMAP server sends an EXISTS notification.

[DierkDroth]

Thanks @jstedfast

[DierkDroth]

A while back we discussed MailKitLight. Is the code change available there as well?

[jstedfast]

Yes, v3.0 will include a MailKitLite

[DierkDroth]

Great, thanks @jstedfast

[DierkDroth]

I forgot to ask: what's the ETA For 3.0?

[jstedfast]

MailKit v3.0.0 has been released with this feature.

[DierkDroth]

Excellent! Thanks @jstedfast

[DierkDroth]

@jstedfast I just switched to MailKitLite 3.0 (from MailKit 2.X) and found that still the BouncyCastle assembly is needed upon building. A while back we discussed that you wanted to remove the BouncyCastle dependency from the MailKitLite 3.X version.

Am I missing something?

[jstedfast]

Sorry, looks like the nuget package accidentally referenced MimeKit instead of MimeKitLite

Look for v3.0.0.1

[DierkDroth]

@jstedfast hmmm ... I just updated to MailKitLite 3.0.0.1 (and have not installed MimeKitLite) and now am getting tons of these errors:

2>C:\Users\ddroth\Documents\Unusual.CRM\Unusual.Common\Mail\MailClient.cs(82,34,82,56): error CS0012: The type 'FormatOptions' is defined in an assembly that is not referenced. You must add a reference to assembly 'MimeKit, Version=3.0.0.0, Culture=neutral, PublicKeyToken=bede1c8a46c66814'. 2>C:\Users\ddroth\Documents\Unusual.CRM\Unusual.Common\Mail\MailClient.cs(534,20,534,41): error CS0012: The type 'HeaderId' is defined in an assembly that is not referenced. You must add a reference to assembly 'MimeKit, Version=3.0.0.0, Culture=neutral, PublicKeyToken=bede1c8a46c66814'. 2>C:\Users\ddroth\Documents\Unusual.CRM\Unusual.Common\Mail\MailClient.cs(547,37,547,63): error CS0012: The type 'MimeMessage' is defined in an assembly that is not referenced. You must add a reference to assembly 'MimeKit, Version=3.0.0.0, Culture=neutral, PublicKeyToken=bede1c8a46c66814'.

What am I doing wrong?

[jstedfast]

try 3.0.0.2

[DierkDroth]

Thanks that worked. I'll deploy a build shortly to see if this made a difference...

[DierkDroth]

@jstedfast unfortunately the issue still appears to exist.

Here are the latest findings on the customer's account (Office 365, no CondStore support):

// PC goes to hibernate and tries a .NoApAsync after wake up which fails -> expected
2022-01-18 07:49:59:088 Mail.MailClient.StartAsync.Exception2: mailAccount='<account>' System.IO.IOException: An existing connection was forcibly closed by the remote host.

// my app then goes through a full re-connect 
2022-01-18 07:50:00:804 Mail.MailClient.ConnectAsync.Connected: mailAccount='<account>' condStore=False mailAccount.HighestModSeq=0 mailAccount.UidNext=63728 lastCountSeen=3 uidNext=63752

// ... and tries to fetch mails up to 63752. There only is a single 'real' mail for all those IDs, which is fine.

// then it issues.NoOpAsync every minute. Here is the last one right before disconnect
2022-01-18 14:52:47:852 Mail.MailClient.NoOpAsync.End: mailAccount='<account>' verifyUidNext=False mailAccount.UidNext=63752 uidNext=63752

// Until then not a single .CountChanged/.MessageExpunged/.MessageFlagsChanged was fired (I have traces in place)

// then the customer disconnect and re-connect and .. surprise! There in fact are more mails
2022-01-18 15:00:35:252 Mail.MailClient.ConnectAsync.Connected: mailAccount='<account>' condStore=False mailAccount.HighestModSeq=0 mailAccount.UidNext=63752 lastCountSeen=10 uidNext=63812

// ... which my app is happy to fetch

Appears, something prevents the relevant events being fired.

Any idea what that could be?

[jstedfast]

Are you 100% positive the server sent an EXISTS notification?

[DierkDroth]

Hmm ... I see this in my traces

2022-01-18 08:43:22:015 Mail.MailClient.NoOpAsync.Start: mailAccount='<account>' isActive=True
2022-01-18 08:43:22:016 Imap.C: F00000088 NOOP
2022-01-18 08:43:22:037 Imap.S: * 3 RECENT
2022-01-18 08:43:22:037 Imap.S: * 5 EXISTS
2022-01-18 08:43:22:037 Imap.S: F00000088 OK NOOP completed.
2022-01-18 08:43:22:037 Mail.MailClient.NoOpAsync.End: mailAccount='<account>' verifyUidNext=False mailAccount.UidNext=63752 uidNext=63752

Does this help?

[jstedfast]

Is that for the Archived folder? or the INBOX? Did you subscribe to the events for that mailbox?

Can you get me a full protocol log? Maybe with that, I'll be able to construct a unit test that will reproduce the issue.

(Feel free to check out the ImapClient unit tests and you'll see how I can essentially replay IMAP sessions from the logs)

[DierkDroth]

This is the INBOX folder (not the ARCHIVE folder).

Here is the trace file - I removed/replaced any sensitive information. Please search for "< account >", that's the account in question.

MailKit.zip

[jstedfast]

Ok, so I think the issue is caused by the fact that you are getting disconnected and reconnecting. When that happens, the existing cache of ImapFolders is wiped out in the ImapEngine (used by the ImapClient) effectively making the ImapFolders that you have references to invalid.

The reason your INBOX folder isn't getting events is because client.Inbox is a different object to the one you have a reference to once you reconnect.

In other words, client.Inbox is getting the events, but you only added event handlers to the previous session's Inbox folder and so that old reference isn't getting any events.

[DierkDroth]

Thanks @jstedfast. This in fact might be the cause of trouble. I changed by code accordingly and left another donation.

[jstedfast]

I was looking at some IMAP code last night and I remembered that I had attempted to implement "smarter" ImapFOlder caching such that if you reconnected/authenticated with the same username, it would not wipe out the cache.

So I could be wrong with my diagnosis. Let me know if you are still running into problems.

[DierkDroth]

@jstedfast thanks will do as I got feedback from the customer.