TaskCancelledException in ImapFolder.FetchAsync

[RichardD2]

Describe the bug I have an MVC5 application which is using IMAP to load messages from Office365. The code lists the UniqueId and InternalDate of the messages in the inbox, then uses FetchAsync to fetch the following properties for the loaded message IDs:

• UniqueId;
• Flags;
• Envelope;
• PreviewText;
• BodyStructure;
• The X-Priority header;

We have received a message which causes this method to throw a TaskCancelledException. This happens even if we pass in CancellationToken.None, so it's not our code that's cancelling the operation.

Platform (please complete the following information):

• OS: Windows (reproduced on 11 and Server 2019)
• .NET Runtime: .NET Framework
• .NET Framework: .NET 4.8
• MailKit Version: 3.3.0

Exception

System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MailKit.Net.Imap.ImapEngine.<ProcessUntaggedResponseAsync>d__189.MoveNext() in D:\src\MailKit\MailKit\Net\Imap\ImapEngine.cs:line 2234
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at MailKit.Net.Imap.ImapCommand.<StepAsync>d__84.MoveNext() in D:\src\MailKit\MailKit\Net\Imap\ImapCommand.cs:line 915
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at MailKit.Net.Imap.ImapEngine.<IterateAsync>d__190.MoveNext() in D:\src\MailKit\MailKit\Net\Imap\ImapEngine.cs:line 2345
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at MailKit.Net.Imap.ImapEngine.<RunAsync>d__191.MoveNext() in D:\src\MailKit\MailKit\Net\Imap\ImapEngine.cs:line 2366
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at MailKit.Net.Imap.ImapFolder.<FetchAsync>d__193.MoveNext() in D:\src\MailKit\MailKit\Net\Imap\ImapFolderFetch.cs:line 1048
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
  at (my code...)

Protocol Logs

Connected to imaps://outlook.office365.com:993/ S: * OK The Microsoft Exchange IMAP4 service is ready. [TABPADYAUAAxADIAMwBDAEEAMAAwADMANwAuAEcAQgBSAFAAMQAyADMALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==] C: B00000000 CAPABILITY S: * CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+ S: B00000000 OK CAPABILITY completed. C: B00000001 AUTHENTICATE PLAIN ******** S: B00000001 NO AUTHENTICATE failed. C: B00000002 LOGIN "" "" S: B00000002 OK LOGIN completed. C: B00000003 CAPABILITY S: * CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CLIENTACCESSRULES CLIENTNETWORKPRESENCELOCATION BACKENDAUTHENTICATE CHILDREN IDLE NAMESPACE LITERAL+ S: B00000003 OK CAPABILITY completed. C: B00000004 NAMESPACE S: * NAMESPACE (("" "/")) NIL NIL S: B00000004 OK NAMESPACE completed. C: B00000005 LIST "" "INBOX" S: * LIST (\Marked \HasChildren) "/" INBOX S: B00000005 OK LIST completed. C: B00000006 LIST "" INBOX/Ignore S: * LIST (\Marked \HasNoChildren) "/" INBOX/Ignore S: B00000006 OK LIST completed. C: B00000007 EXAMINE INBOX/Ignore S: * 1 EXISTS S: * 1 RECENT S: * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent) S: * OK [PERMANENTFLAGS ()] Permanent flags S: * OK [UIDVALIDITY 4340] UIDVALIDITY value S: * OK [UIDNEXT 3] The next unique identifier value S: B00000007 OK [READ-ONLY] EXAMINE completed. C: B00000008 UID FETCH 2 (UID FLAGS ENVELOPE BODYSTRUCTURE BODY.PEEK[HEADER.FIELDS (X-PRIORITY)]) S: * 1 FETCH (UID 2 FLAGS (\Seen \Recent) ENVELOPE ("Tue, 2 Aug 2022 15:01:06 +0000" "Returned mail: see transcript for details" (("Mail Delivery Subsystem" NIL "MAILER-DAEMON" "hermes.gatewaynet.com")) NIL NIL ((NIL NIL "MAILBOX" "OUR-DOMAIN")) NIL NIL NIL "<202208021501.272F16D4031920@HERMES-GATEWAYNET-COM>") BODYSTRUCTURE ((NIL NIL NIL NIL NIL "7BIT" 563 NIL NIL NIL NIL)("message" "delivery-status" NIL NIL NIL "7BIT" 658 NIL NIL NIL NIL)("message" "rfc822" NIL NIL NIL "8bit" 0 ("Tue, 2 Aug 2022 15:00:47 +0000" "[POSSIBLE SPAM 11.4] Invoices now overdue - 115365#" ((NIL NIL "MAILBOX" "OUR-DOMAIN")) NIL NIL ((NIL NIL "accounts" "OTHER-DOMAIN") (NIL NIL "safety" "OTHER-DOMAIN") (NIL NIL "USER" "OUR-DOMAIN")) NIL NIL NIL "<1IOGPFNLIHU4.377MHPZYJQ6E3@OUR-SERVER>") ((("text" "plain" ("charset" "utf-8") NIL NIL "8bit" 597 16 NIL NIL NIL NIL)(("text" "html" ("charset" "utf-8") NIL NIL "7BIT" 1611 26 NIL NIL NIL NIL)("image" "png" ("name" "0.dat") "<1KWGPFNLIHU4.4RR7HCVM8MQQ1@OUR-SERVER>" NIL "base64" 14172 NIL ("inline" ("filename" "0.dat")) NIL "0.dat")("image" "png" ("name" "1.dat") "<1KWGPFNLIHU4.UWJ8R86RE2KA2@OUR-SERVER>" NIL "base64" 486 NIL ("inline" ("filename" "1.dat")) NIL "1.dat")("image" "png" ("name" "2.dat") "<1KWGPFNLIHU4.EC7HN124OJC32@OUR-SERVER>" NIL "base64" 506 NIL ("inline" ("filename" "2.dat")) NIL "2.dat")("image" "png" ("name" "3.dat") "<1KWGPFNLIHU4.WM1ALJTG745F1@OUR-SERVER>" NIL "base64" 616 NIL ("inline" ("filename" "3.dat")) NIL "3.dat")("image" "png" ("name" "4.dat") "<1KWGPFNLIHU4.1B42S5EVSF4B2@OUR-SERVER>" NIL "base64" 22470 NIL ("inline" ("filename" "4.dat")) NIL "4.dat") "related" ("boundary" "=-5nEE2FIlRoeXkJyZAHV8UA==" "type" "text/html") NIL NIL) "alternative" ("boundary" "=-1sRjeMizXVbc5nGIFXbARA==") NIL NIL)("application" "pdf" ("name" "Reminder.pdf") "<RJ2DSFNLIHU4.UUVSNNY5Z3ER@OUR-SERVER>" NIL "base64" 359650 NIL ("attachment" ("filename" "Reminder.pdf" "size" "262820")) NIL NIL) "mixed" ("boundary" "=-EJwVTfPtacyNnTqY4DPQ0A==") NIL NIL) 0 NIL NIL NIL NIL) "report" ("report-type" "delivery-status" "boundary" "272F16D4031920.1659452466/hermes.gatewaynet.com") NIL NIL) BODY[HEADER.FIELDS (X-PRIORITY)] {2} S: S: )

Additional context After moving the affected message out of the folder, the FetchAsync command works as expected.

Using GetMessageAsync, I am able to load the affected message without any problems.

[jstedfast]

I haven't had time to look at this, but the only explanation I can think of is that the timeout is due to not receiving the command tag response and so I/O times out.

[RichardD2]

I've set the Timeout to 600_000; with a folder that just contains the problematic message, I get the exception in a couple of seconds.

A fetch request for many more messages, without that one in the folder, completes successfully in under a minute.

[jstedfast]

I/O is the only place anywhere in the IMAP code that throws a OperationCanceledException

[RichardD2]

It's definitely not a timeout issue.

I've stepped through the code for this message:

• ImapFolderFetch.FetchSummaryItems encounters the BODYSTRUCTURE atom;
• That calls ImapUtils.ParseBodyAsync, which finds an OpenParen token;
• That calls ImapUtils.ParseMultipartAsync, which calls ImapUtils.ParseBodyAsync;
• That finds a Nil token, and calls ImapUtils.ParseMultipartAsync;
• That reaches line 1121, which calls ReadStringTokenAsync to get the subtype;
• That reads a Nil token, and throws ImapEngine.UnexpectedToken - an ImapProtocolException;
• By the time that gets back to ImapEngine line 2234 (ProcessUntaggedResponseAsync), the exception has become a TaskCancelledException;

If I change the code to call Fetch instead of FetchAsync, I get a more sensible exception:

MailKit.Net.Imap.ImapProtocolException
  HResult=0x80131500
  Message=Syntax error in BODYSTRUCTURE. Unexpected token: NIL
  Source=MailKit
  StackTrace:
   at MailKit.Net.Imap.ImapUtils.ReadStringToken(ImapEngine engine, String format, CancellationToken cancellationToken) in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapUtils.cs:line 695
   at MailKit.Net.Imap.ImapUtils.ReadStringTokenAsync(ImapEngine engine, String format, Boolean doAsync, CancellationToken cancellationToken) in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapUtils.cs:line 717
   at MailKit.Net.Imap.ImapUtils.<ParseMultipartAsync>d__39.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapUtils.cs:line 1121
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at MailKit.Net.Imap.ImapUtils.<ParseBodyAsync>d__40.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapUtils.cs:line 1205
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at MailKit.Net.Imap.ImapUtils.<ParseMultipartAsync>d__39.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapUtils.cs:line 1107
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at MailKit.Net.Imap.ImapUtils.<ParseBodyAsync>d__40.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapUtils.cs:line 1205
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at MailKit.Net.Imap.ImapFolder.FetchSummaryItems(ImapEngine engine, MessageSummary message, CancellationToken cancellationToken) in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapFolderFetch.cs:line 281
   at MailKit.Net.Imap.ImapFolder.FetchSummaryItemsAsync(ImapEngine engine, ImapCommand ic, Int32 index, Boolean doAsync) in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapFolderFetch.cs:line 721
   at MailKit.Net.Imap.ImapEngine.<ProcessUntaggedResponseAsync>d__189.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapEngine.cs:line 2234
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at MailKit.Net.Imap.ImapCommand.<StepAsync>d__84.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapCommand.cs:line 915
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at MailKit.Net.Imap.ImapEngine.<IterateAsync>d__190.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapEngine.cs:line 2342
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable.ConfiguredTaskAwaiter.GetResult()
   at MailKit.Net.Imap.ImapEngine.<RunAsync>d__191.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapEngine.cs:line 2366
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at MailKit.Net.Imap.ImapFolder.<FetchAsync>d__200.MoveNext() in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapFolderFetch.cs:line 1390
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at MailKit.Net.Imap.ImapFolder.Fetch(Int32 min, Int32 max, IFetchRequest request, CancellationToken cancellationToken) in C:\Users\richa\source\repos\MailKit\MailKit\Net\Imap\ImapFolderFetch.cs:line 1458
   at MailKit.IMailFolderExtensions.Fetch(IMailFolder folder, Int32 min, Int32 max, MessageSummaryItems items, IEnumerable`1 headers, CancellationToken cancellationToken) in C:\Users\richa\source\repos\MailKit\MailKit\IMailFolderFetchExtensions.cs:line 1781
   at TestImap.Program.<Main>d__0.MoveNext() in C:\Users\richa\source\repos\MailKit\TestImap\Program.cs:line 24

I'm not sure why the async version is throwing the sensible ImapProtocolException exception away and replacing it with a TaskCancelledException, or whether there's any way to avoid the exception for messages which are malformed in this way.

[jstedfast]

Okay, so I think the problem may then be the ContinueWith statement here: https://github.com/jstedfast/MailKit/blob/ae36c45ca02f6fbdb280a5e85cf28c0cab13d04d/MailKit/Net/Imap/ImapFolderFetch.cs#L715-L718

I was trying to be crafty and prevent the compiler from generating AsyncBuilder state machines, but I likely caused this problem as a side effect. My guess right now is that it may have something to do with the TaskContinuationOptions.OnlyOnRanToCompletion. Maybe it throws TaskCanceledException if it gets an exception?

[RichardD2]

That seems to be correct:

async Task Foo() => throw new InvalidOperationException("BANG!");
void FooCompleted(Task t) => Console.WriteLine("Foo completed");

async Task Main()
{
    try
    {
        await Foo().ContinueWith(
            FooCompleted,
            CancellationToken.None,
            TaskContinuationOptions.OnlyOnRanToCompletion,
            TaskScheduler.Default);
    }
    catch (InvalidOperationException)
    {
        Console.WriteLine("PASS: Got the expected exception...");
    }
    catch (TaskCanceledException)
    {
        Console.WriteLine("FAIL: Got the wrong exception.");
    }
}

.NET 4.7.2: https://dotnetfiddle.net/QJP3nd

.NET 6: https://dotnetfiddle.net/6nCxU5

Both versions catch the TaskCanceledException rather than the expected InvalidOperationException.

[jstedfast]

Whether my assumption is correct or not, the ContinueWith is kinda gross, so I'm working on a cleaner solution.

[jstedfast]

Awesome, thanks for checking that for me - good to know my fix is likely to solve this :-)

Also, thanks for digging into the Async vs Sync idea, because that was a huge help in narrowing in on this and saved me a ton of time.

[RichardD2]

Is there any workaround to fetch the details of the seemingly-corrupt message? Or do I need to fall back to the full GetMessage method if the Fetch method fails?

[jstedfast]

Now that we have the TaskCanceledException issue resolved, my next step will be to look into the ImapProtocolException.

Hopefully I can find a work-around for that, too.

[RichardD2]

Excellent news, thanks. 👍

[jstedfast]

Okay, so the problem is the very first body part:

(NIL NIL NIL NIL NIL "7BIT" 563 NIL NIL NIL NIL)

MailKit sees the NIL as the first token and assumes that it must be a multipart with no children and then gets the next token (another NIL) and blows up because the subtype is NIL.

This is what you outlined in one of your previous comments.

Technically, NIL is not allowed as the multipart children list, but it's a very common for IMAP servers to send that when a multipart contains no children.

In your case, because the very first child of the multipart/report has no part headers at all, your IMAP server is using NIL to represent the type and subtype values (what it should do is send "text" "plain" ... since MIME specifies that as the default when a part has no Content-Type header).

body-type-1part = (body-type-basic / body-type-msg / body-type-text)
                  [SP body-ext-1part]

body-type-basic = media-basic SP body-fields
                    ; MESSAGE subtype MUST NOT be "[RFC822](https://www.rfc-editor.org/rfc/rfc822)"

media-basic     = ((DQUOTE ("APPLICATION" / "AUDIO" / "IMAGE" /
                  "MESSAGE" / "VIDEO") DQUOTE) / string) SP
                  media-subtype
                    ; Defined in [[MIME-IMT](https://www.rfc-editor.org/rfc/rfc3501.html#ref-MIME-IMT)]

media-subtype   = string
                    ; Defined in [[MIME-IMT](https://www.rfc-editor.org/rfc/rfc3501.html#ref-MIME-IMT)]

string          = quoted / literal

The media-basic and media-subtypes are never supposed to be NIL and so when the media-basic token is NIL, I figured we were safe to assume that it was a multipart with no children, but you have hit an example where that assumption is wrong.

I think I'll need to modify code to be able to peek multiple tokens ahead for this case, because I don't know of any other way to solve this :(

[jstedfast]

I haven't had time to get around to working on this much, unfortunately, but figured it was time to make a 3.4.0 release anyway.

The 3.4.0 release contains the TaskCanceledException fix but does not resolve the core issue in this bug report :(

Hopefully I'll have some free time soon.

[RichardD2]

Thanks for letting me know. 👍

[jstedfast]

The status update on this is that this it has been more complicated than first anticipated. That said, my goal is to have this fixed for the next release.

[RichardD2]

Thanks for the update.

Based on the "duplicate" issue, do you think it's worth changing the title of this issue to make it easier to find, now that you've fixed the original bug?

[carmanj]

The status update on this is that this it has been more complicated than first anticipated. That said, my goal is to have this fixed for the next release.

I appreciate the update! I'm happy to test on the inboxes I'm having this issue with, whenever you have something committed.

Thanks! Justin

[jstedfast]

Yea, probably worth changing.

Anyway, it's times like this that I'm thankful that I added unit tests for all of the workarounds for all of the other breakages. haha.

I have a fix locally for this particular issue, but it broke other work-arounds. That's where I'm having to rethink how to go about all of these work-arounds for the various breakages I've added work-arounds for.

This particular one throws a wrench in the works because of all the NILs.

[jstedfast]

Okay, this should be fixed now.

You'll be able to grab the package from https://www.myget.org/feed/mimekit/package/nuget/MailKit and the version number will likely be 3.4.1.514 once it finishes building.

There's a date stamp next to each package version, so just look for a build that was released today.

[jstedfast]

3.4.1.515 is a simplified version of the fix.

[carmanj]

Okay, this should be fixed now.

You'll be able to grab the package from https://www.myget.org/feed/mimekit/package/nuget/MailKit and the version number will likely be 3.4.1.514 once it finishes building.

There's a date stamp next to each package version, so just look for a build that was released today.

Awesome, thanks so much for so quickly taking care of this!

[RichardD2]

Thanks for sorting this. Do you have a timescale for pushing the update to the main NuGet site?

[jstedfast]

Yea, I was planning to make a new release this past weekend but life got in the way.

This coming weekend is going to be no-good for me because I plan to spend time with the wifey for our anniversary. Next week, she'll be on a business trip so I'll have a lot of time after work to work on this if I don't get around to it this week.

In other words, if it doesn't happen by Thursday this week, it'll happen early next week.

[RichardD2]

Thanks for letting me know. Hope you have a good anniversary! 😁

[carmanj]

Thanks for letting me know. Hope you have a good anniversary! 😁

Looks like this was released in 3.4.2 a few days ago. :)