jstedfast / MailKit

A cross-platform .NET library for IMAP, POP3, and SMTP.
http://www.mimekit.net
MIT License
6.17k stars 818 forks source link

Done token won't cancel IMap IdleAsync #1697

Closed szguoxz closed 7 months ago

szguoxz commented 8 months ago

When donetoken is expired, the idleasync won't exit for my Gmail IMap connection. I monitored the protocol log, S: + idling C: DONE

I can see DONE is written.

I looked into the source code, found the stream handling is weird. Maybe I don't understand the code, why is it not async stream code? public void Write (byte[] buffer, int offset, int count, CancellationToken cancellationToken) This function seems way tom complicated for a normal async stream, but again, maybe there is a reason.

Anyway, This happens to me all the time. It worked for a while, then happens again. By the way, I am monitoring a couple gmail accounts at the same time, not sure if that means anything.

I've also noticed, I set the done token to cancel in 5 minutes, it actually got canceled after 21 minutes.

Anyway, this is way too weird. And it works if I cancel the done token myself. But it won't work if the done token cancels itself.

jstedfast commented 8 months ago

If the C: DONE\r\n text is in the log, it should mean that the DONE command was flushed through the socket layer.

That would suggest that the ImapClient is stuck waiting for a response from the server.

The way to check this would be to download a program such as wireshark to sniff the TCP/IP packets between your machine and the server to see what has been sent/received.

I looked into the source code, found the stream handling is weird. Maybe I don't understand the code, why is it not async stream code? public void Write (byte[] buffer, int offset, int count, CancellationToken cancellationToken) This function seems way tom complicated for a normal async stream, but again, maybe there is a reason.

I'm guessing you were looking at ImapStream.Write (byte[] buffer, int offset, int count, CancellationToken cancellationToken) and yes, it's a little complicated, but not too bad.

What it is doing is buffering the output data so that we avoid sending small packets unnecessarily (i.e. if the caller is making smallish writes).

Then the ImapStream.Flush(CancellationToken cancellationToken) method should get called, and that is what will flush the output buffer to the socket, and indeed, that is where you'll find that the "DONE\r\n" command is written to the protocol logger.

By the way, I am monitoring a couple gmail accounts at the same time, not sure if that means anything.

I can't think of a reason that should matter, but at this point, all I can do is guess.

I've also noticed, I set the done token to cancel in 5 minutes, it actually got canceled after 21 minutes.

How are you timing that? And what are you using to trigger the cancellation? Are you using CancellationTokenSource(TimeSpan)?

Anyway, this is way too weird. And it works if I cancel the done token myself. But it won't work if the done token cancels itself.

I can't explain that, honestly.

Can you check if you are cancelling the cancellationToken before cancelling the doneToken?

I know from past experience that that used to cause hangs. I can't remember if I found a way to fix that or not.

szguoxz commented 8 months ago

I think I know what is going on now. It's GMAIL pulling the shit. Basically GMAIL decide not to comply with the protocol. DONE command will or will not cancel the idle will depend on how GMAIL feels.

My observation is : When my done token cancels and send the DONE command, GMAIL ignores it (sometimes hornor it). Then if a new message arrives, it will honor the DONE command.

I guess GMAIL thinks I cancel too early, which is a waste of its resource, force me to stay up to the last minute. Either reaches the maximum waiting period, or something happened with the inbox.

It works for me, actually better, as I am tired to guess when GMAIL will disconnect me. Now I just wait for it to disconnect me, or if a new email comes in, I can cancel the idle and start to process it right away.

By the way, I never touch the cancellation token, as that means I want to stop the operation.

szguoxz commented 8 months ago

I'm guessing you were looking at ImapStream.Write (byte[] buffer, int offset, int count, CancellationToken cancellationToken) and yes, it's a little complicated, but not too bad.

When code gets this complicated, there tends to be a bug. When I see the code, I was surprised. As CancellationToken usually only used in Async Task system. And your code is a sync stream.

You said it might hang some time. Is it possible that the code is way too old, and dotnet has changed its way of handling things? I am just saying! :-) I just feel the code does not comply with the latest best practice of DOTNET async idiom.

szguoxz commented 8 months ago

Now I believe it's a bug, it hangs. I need to find out a way to fix this. This is ODD. Also, after so many trial and error, I found if I set done token to cancel after 2 minutes, it works fine. anything longer than 2 minutes, like 5 minutes, will cause it to hang.

I tested it even more , basically 2,3,4 minutes works. 5 minutes or more, it hangs!

jstedfast commented 8 months ago

When it hangs, what are the values of the Send/ReceiveTimeout properties of the underlying Socket?

And is it hanging in ImapStream.ReadAhead?

Are you using ImapClient.Idle()? Or ImapClient.IdleAsync()?

2 minutes is the default timeout for network sockets on most systems, so it sounds suspicious.

In ImapCommand.Step/Async(), there is code that sets the timeout to infinity when idling.

I suspect that might not be working for you for some reason.

szguoxz commented 8 months ago

I didn't go into that deep. But here are some information:

  1. I use IdleAsync
  2. It works for 2 minutes, 3 minutes, 4 minutes, but not 5 minutes.
  3. When I set it to 4 or less minutes, I can see that we send the done command when the token expires, and it exits, every works as expected.
  4. when it hangs, it eventually will be disconnected after 20, 30 or 40 minutes. Right now, I set it to 4 minutes, the longest time possible. And it works beautifully.

on a side note: I have this event attahced to inbox: client.Inbox.CountChanged += (x, y) => { hasnewmessage = true; doneidle.cancel(); }

My question is: if I detect the client got disconnected, and I reconnect it immediately. Now, do I need to reattach the event? I mean, will the inbox folder got reinitialized?

My code is quite simple, I will paste it here: CancellationTokenSource doneidle = new(); bool hasnewmessage = false; await ReconnectAsync(); client.Inbox.CountChanged += (x, y) => { hasnewmessage = true; doneidle.Cancel(); logger.Info($"new email arrived for {email}"); };

    while (!cts.IsCancellationRequested)
        try
        {
            await ReconnectAsync();
            if (hasnewmessage && await ProcessMessageAsync() > 0) continue;
            logger.Info($"start idle now {email}");
            doneidle = new CancellationTokenSource(TimeSpan.FromMinutes(4));
            hasnewmessage = false;
            await client.IdleAsync(doneidle.Token, cts.Token);
            logger.Info($"done idle {email}");
        }
        catch (ImapProtocolException ex) {}
        catch (IOException ex) {}
        catch (OperationCanceledException ex)
        {
            break;
        }
        catch (Exception e)
        {
            logger.Error($"something went wrong {email}", e);
            break;
        }

Thanks,

jstedfast commented 8 months ago

You will not need to reattach event handlers unless you connect to a different server.

jstedfast commented 7 months ago

Oh, I see the problem.

client.Inbox.CountChanged += (x, y) => { hasnewmessage = true; doneidle.cancel(); }

The problem is that that code only captures the doneidle instance that is live when that delegate is created. Once it gets cancelled, it's done.

You shouldn't use a delegate like this. You should provide an actual method handler.

szguoxz commented 7 months ago

That's not the case. I recreated the instance every time when I started to idleasync. It captures the reference to doneidle. I have been using .net for over 20 years, I was careful. :-)

szguoxz commented 7 months ago

Besides, I works fine when I set it to 4 minutes. It finished idle every 4 minutes. and when new messages arrive, it exits the idle immediately.

So, yea, they all point to the same doneidle.

It's laughable that we discuss the dotnet syntax. I have logged the doneidle hashcode when new messages arrive, proves that they are the same instance: inside the countchanged, and the one I recreated.

anyway, everything works as expected when I set the time to 4 minutes. 5 or more, it won't work,

client.Inbox.CountChanged += (x, y) =>
{
  hasNewMessage = true;
  doneIdle.Cancel();
  logger.Info($"new email arrived for {email}, hash: {doneIdle.GetHashCode()}");
};

 doneIdle = new CancellationTokenSource(TimeSpan.FromMinutes(4));
    hasNewMessage = false;
    logger.Info($"start idle now {email}, hash: {doneIdle.GetHashCode()}");
    await client.IdleAsync(doneIdle.Token, cts.Token);