Duplicate Authenticated event in ImapClient

[SylwesterZarebski]

Describe the bug
After updating to newest 2.1.0.3 NuGet package i observe two Authenticated events instead of one.
Previous version was 2.0.4.

To Reproduce
I hope this code excerpt will help (original code has additional logging and multiple cancellation token checks):

imapClient = new ImapClient();
imapClient.Connected += onClientConnected;
imapClient.Authenticated += onClientAuthenticated;
imapClient.Disconnected += onClientDisconnected;
imapClient.Connect(uri, ct);
...
private void onClientConnected(object sender, EventArgs e)
{
    logger.Info("Connected with: " + uri);
    imapClient.AuthenticationMechanisms.Remove("XOAUTH2");
    imapClient.Authenticate(credentials, ct);
}
private void onClientAuthenticated(object sender, AuthenticatedEventArgs e)
{
    logger.Debug("Authenticated to: " + uri);
    // Some after auth code
}

Expected behavior
My onClientAuthenticated method should be called once, but is twice.

Screenshots
NET Framework 4.6, Windows 2008 R2
From my application log:

[2018-12-10 16:08:22.4837] Info EmailWatcherElement.onClientConnected: Connected with: ...
[2018-12-10 16:08:22.9710] Debug EmailWatcherElement.onClientAuthenticated: Authenticated to: ...
[2018-12-10 16:08:23.0003] Debug EmailWatcherElement.onClientAuthenticated: Detected trash: Trash
[2018-12-10 16:08:23.0169] Debug EmailWatcherElement.onClientAuthenticated: Authenticated to: ...
[2018-12-10 16:08:23.0169] Debug EmailWatcherElement.onClientAuthenticated: Detected trash: Trash

[jstedfast]

I added some unit tests for this here: 76f6252

But I am unable to replicate the problem. Are you sure you didn't just accidentally add a listener for the event twice?

[SylwesterZarebski]

I've checked it multiple times to be sure.
After going to 2.0.7 i've got:

[2018-12-10 17:46:59.3235] Error EmailWatcherElement.onClientConnected: Authentication error:
System.ArgumentNullException: Value cannot be null.
Parameter name: message
   at MailKit.AuthenticatedEventArgs..ctor(String message)
   at MailKit.MailService.OnAuthenticated(String message)
   at MailKit.Net.Imap.ImapClient.<AuthenticateAsync>d__77.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MailKit.Net.Imap.ImapClient.Authenticate(Encoding encoding, ICredentials credentials, CancellationToken cancellationToken)
   at MailKit.MailService.Authenticate(ICredentials credentials, CancellationToken cancellationToken)
   at Service.EmailWatcherElement.onClientConnected(Object sender, EventArgs e) in C:\Service\Watcher\Email\EmailWatcher.cs:line 197
[2018-12-10 17:46:59.3430] Debug EmailWatcherElement.onClientAuthenticated: Authenticated to: ...
[2018-12-10 17:46:59.3714] Debug EmailWatcherElement.onClientAuthenticated: Detected trash: Trash

Could it be multiple authentication tries/methods going parallel or something?

[jstedfast]

Nope, it doesn't try to authenticate with different methods in parallel.

The ArgumentNullException is a known bug in 2.0.7 that I fixed in 2.1.0.

Could you get me a stack for each of the Authenticated event callbacks? As far as I can tell, as soon as an authentication mechanism succeeds, it returns from the Authenticate() method and no more attempts are made. I cannot figure out how it's even possible for the event to be emitted more than once.

[jstedfast]

Note: 2.0.6 doesn't have the ArgumentNullException, pretty sure that bug is exclusive to 2.0.7.

Here's the original bug report for that bug: #774

[SylwesterZarebski]

I try to log full stack tomorrow in work. Thanks for help.

[SylwesterZarebski]

Both stacktraces:

[2018-12-11 09:08:38.2356] Trace EmailWatcherElement.onClientAuthenticated: Stacktrace:
   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at Service.EmailWatcherElement.onClientAuthenticated(Object sender, AuthenticatedEventArgs e) in C:\Service\Watcher\Email\EmailWatcher.cs:line 208
   at MailKit.MailService.OnAuthenticated(String message)
   at MailKit.Net.Imap.ImapClient.<OnAuthenticatedAsync>d__81.MoveNext()
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
   at MailKit.Net.Imap.ImapClient.OnAuthenticatedAsync(String message, Boolean doAsync, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapClient.<AuthenticateAsync>d__84.MoveNext()
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
   at MailKit.Net.Imap.ImapClient.AuthenticateAsync(Encoding encoding, ICredentials credentials, Boolean doAsync, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapClient.Authenticate(Encoding encoding, ICredentials credentials, CancellationToken cancellationToken)
   at MailKit.MailService.Authenticate(ICredentials credentials, CancellationToken cancellationToken)
   at Service.EmailWatcherElement.onClientConnected(Object sender, EventArgs e) in C:\Service\Watcher\Email\EmailWatcher.cs:line 197
   at MailKit.MailService.OnConnected(String host, Int32 port, SecureSocketOptions options)
   at MailKit.Net.Imap.ImapClient.<ConnectAsync>d__89.MoveNext()
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
   at MailKit.Net.Imap.ImapClient.ConnectAsync(String host, Int32 port, SecureSocketOptions options, Boolean doAsync, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapClient.Connect(String host, Int32 port, SecureSocketOptions options, CancellationToken cancellationToken)
   at MailKit.MailService.Connect(Uri uri, CancellationToken cancellationToken)
   at Service.EmailWatcherElement.reconnect() in C:\Service\Watcher\Email\EmailWatcher.cs:line 258
   at Service.EmailWatcherElement.Run(Uri uri, NetworkCredential credentials) in C:\Service\Watcher\Email\EmailWatcher.cs:line 174
   at Service.EmailWatcher.<>c__DisplayClass4_0.<Start>b__0() in C:\Service\Watcher\Email\EmailWatcher.cs:line 64
   at System.Threading.Tasks.Task.Execute()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
   at System.Threading.Tasks.Task.ExecuteEntry(Boolean bPreventDoubleExecution)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

[2018-12-11 09:08:38.3137] Trace EmailWatcherElement.onClientAuthenticated: Stacktrace:
   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at Service.EmailWatcherElement.onClientAuthenticated(Object sender, AuthenticatedEventArgs e) in C:\Service\Watcher\Email\EmailWatcher.cs:line 208
   at MailKit.MailService.OnAuthenticated(String message)
   at MailKit.Net.Imap.ImapClient.<OnAuthenticatedAsync>d__81.MoveNext()
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
   at MailKit.Net.Imap.ImapClient.OnAuthenticatedAsync(String message, Boolean doAsync, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapClient.<ConnectAsync>d__89.MoveNext()
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[TStateMachine](TStateMachine& stateMachine)
   at MailKit.Net.Imap.ImapClient.ConnectAsync(String host, Int32 port, SecureSocketOptions options, Boolean doAsync, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapClient.Connect(String host, Int32 port, SecureSocketOptions options, CancellationToken cancellationToken)
   at MailKit.MailService.Connect(Uri uri, CancellationToken cancellationToken)
   at Service.EmailWatcherElement.reconnect() in C:\Service\Watcher\Email\EmailWatcher.cs:line 258
   at Service.EmailWatcherElement.Run(Uri uri, NetworkCredential credentials) in C:\Service\Watcher\Email\EmailWatcher.cs:line 174
   at Service.EmailWatcher.<>c__DisplayClass4_0.<Start>b__0() in C:\Service\Watcher\Email\EmailWatcher.cs:line 64
   at System.Threading.Tasks.Task.Execute()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
   at System.Threading.Tasks.Task.ExecuteEntry(Boolean bPreventDoubleExecution)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

[jstedfast]

Your second stacktrace shows that the Authenticated event is being fired from client.Connect()

Are you sure these aren't 2 different connections?

[jstedfast]

Oh, I see your problem... you are calling client.Authenticate() from within the client's Connected event handler.

MailKit 2.1.x was changed to check the Authenticated state of the client once connected in case the IMAP server didn't require authentication (e.g. had a * PREAUTH greeting).

The code is doing this:

OnConnected (host, port, options);

if (engine.state == ImapEngineState.Authenticated)
	await OnAuthenticatedAsync (string.Empty, doAsync, cancellationToken).ConfigureAwait (false);

Since you are authenticating from within the OnConnected(), by the time it gets to the Authenticated check afterwards, you've authenticated so it calls OnAuthenticated() again.

[SylwesterZarebski]

I suspected the same fragment after quick analysis. Could it be done another way - i mean one of two, my code rewrite or MailKit?

[jstedfast]

Yea, I can just capture the state before calling OnConnected() and then check the saved state instead of the actual state afterwards.

[SylwesterZarebski]

Thanks a lot for Your help :-) 🥇

[SylwesterZarebski]

PS. Is it possible to prepare new NuGet version?