Moving emails in google (continuation of #68)

[alasdair-richardson]

Dan. I raised an issue last month and you apparently fixed it really quickly (thanks). Unfortunately i still have a problem - don't know if I didn't test it properly but that is probably the case. You did some stuff to enable creating folders (aka labels) in google mail then to move an email using
var uniqueId = await mailFolderClient.MoveToAsync(messageSummary, destinationFolderFullName,

This works when i first start the monitor - all emails currently sitting in the inbox are delivered to the monitor, stored locally then moved to the Processed folder on GoogleMail. But when a new email arrives in the inbox this does not happen - the above code returns null rather than a uniqueId. My monitor code looks like the following (have taken out the stuff related to my processing of the emails)

using MailKit;
using MailKitSimplified.Receiver.Abstractions;
using MailKitSimplified.Receiver.Extensions;
using MimeKit;

namespace Caa.Api.Email;

public class MailMonitor : BackgroundService
{
private const string processedFolder = "Processed";

private readonly IImapReceiver imapReceiver;
private readonly IServiceScope serviceScope;
private readonly ILogger<MailMonitor> logger;

public MailMonitor(IServiceScopeFactory serviceScopeFactory, ILoggerFactory loggerFactory)
{
    serviceScope = serviceScopeFactory.CreateScope();
    imapReceiver = serviceScope.ServiceProvider.GetRequiredService<IImapReceiver>();
    logger = loggerFactory.CreateLogger<MailMonitor>();
}

protected override async Task ExecuteAsync(CancellationToken ct = default)
{
    logger.LogInformation("MailMonitor starting ..");
    var destination = await imapReceiver.MailFolderClient
        .GetOrCreateFolderAsync(processedFolder, ct);
    if (destination is null)
        throw new Exception("Could not create Processed mail folder");
    await MonitorAsync(ct);
}

private async Task MonitorAsync(CancellationToken ct = default)
{
    await imapReceiver.MonitorFolder
        .SetMessageSummaryItems(MessageSummaryItems.Envelope)
        .OnMessageArrival((m) => Incoming(m, ct))
        .OnMessageDeparture((m) => Departing(m))
        .IdleAsync(ct);
}

private async Task Incoming(IMessageSummary summary, CancellationToken ct)
{
    logger.LogDebug("Incoming {s}", summary.Envelope.Subject);
    
    // Store and process the MimeMessage locally
    
    // Move to processed folder on server
    var uniqueId = await imapReceiver.MailFolderClient
        .MoveToAsync(summary, processedFolder, ct);
    // this is loggin null after the initial emails in the inbox at startup have been moved
    // i.e. when new emails arrive
    logger.LogDebug("After arrival move return uniqueId: {U}", uniqueId?.ToString() ?? "null");
}

private void Departing(IMessageSummary m)
{
    logger.LogInformation("Departing {s}", m.Envelope.Subject);
}

public override void Dispose()
{
    logger.LogInformation("MailMonitor ending ..");
    serviceScope.Dispose();
    base.Dispose();
}

}

The logging at startup looks like

2024-07-30 11:38:13.3175 [DEBUG] Caa.Api.Email.MailMonitor: Incoming testing 1 2 3
2024-07-30 11:39:12.0670 [DEBUG] Caa.Api.Email.MailMonitor: After arrival move return uniqueId: 37
2024-07-30 11:39:24.0752 [ INFO] Caa.Api.Email.MailMonitor: Departing testing 1 2 3

and later when a new email arrives

2024-07-30 11:41:13.3175 [DEBUG] Caa.Api.Email.MailMonitor: Incoming testing 0 1 2
2024-07-30 11:41:12.0670 [DEBUG] Caa.Api.Email.MailMonitor: After arrival move return uniqueId: null

[alasdair-richardson]

Also i sometimes get an exception after the email has arrived

2024-07-30 12:08:13.6878 [ INFO] MailKitSimplified.Receive: IMAP protocol exception, checking connection. MailKit.Net.Imap.ImapProtocolException: The IMAP server has unexpectedly disconnected.
   at MailKit.Net.Imap.ImapStream.ReadAheadAsync(Int32 atleast, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapStream.ReadTokenAsync(String specials, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapCommand.StepAsync()
   at MailKit.Net.Imap.ImapEngine.IterateAsync()
   at MailKit.Net.Imap.ImapEngine.RunAsync(ImapCommand ic)
   at MailKit.Net.Imap.ImapClient.NoOpAsync(CancellationToken cancellationToken)
   at MailKitSimplified.Receiver.Services.MailFolderMonitor.ProcessMessagesArrivedAsync(Boolean firstConnection, CancellationToken cancellationToken)
   at MailKitSimplified.Receiver.Services.MailFolderMonitor.WaitForNewMessagesAsync(CancellationToken cancellationToken)

It does not seem to recover, ie stops receiving emails at that point. I don't know if this is during the MoveAsync operation. What I see is that after the exception is logged I just get

2024-07-30 12:08:14.3520 [DEBUG] Caa.Api.Email.MailMonitor: Incoming testing 4 5 6 

It never does the other log message for the uniqueId result of the move operation. I'm guessing the exception gets logged immediately but the other log message is queueing up ro something ...

[alasdair-richardson]

Actually weirder than that. It does seem to have reconnected but it is not calling my Incoming method. So just seeing

2024-07-30 13:38:49.6063 [DEBUG] MailKitSimplified.Receive: imap.gmail.com referencing-test@antisemitism.org INBOX message #42 arrived. 

but nothing else?

[danzuep]

I've fixed a bug where the source folder was null which might have caused the issues you found, try the latest pre-release.

[alasdair-richardson]

Ok thanks will try tomorrow morning.

[alasdair-richardson]

I upgraded to 2.11.5-tags-v2-11-5-rc0001 which I think is the latest version. I'm afraid it made no difference. I have followed the code through and we get to the following line in MailFolderClient.MoveOrCopyAsync (line 397)
resultUid = await source.MoveToAsync(messageUid, destination, cancellationToken).ConfigureAwait(false);
At this point destination is pointing to the right folder (Processed) but it is not open. Then we get into the MailKit stuff which I'm afraid i do not understand. It goes to another MoveToAsync which just converts the messageUid to an array. then it does a bunch of checks and eventually we get to IMapFolder line 5723

			UniqueIdSet dest = null;
			UniqueIdSet src = null;

			foreach (var ic in Engine.QueueCommands (cancellationToken, this, "UID MOVE %s %F\r\n", uids, destination)) {
				await Engine.RunAsync (ic).ConfigureAwait (false);

				ProcessMoveToResponse (ic, destination, ref src, ref dest);
			}

			if (dest == null)
				return UniqueIdMap.Empty;

after the loop dest is null. So the mail has not been moved. When i run through the code at start up - ie when the move is working, I see the destination folder is not open then either - in fact I cannot see at all what the difference is between the 2 cases ....

[danzuep]

Good work on the investigation, but I don't think you're debugging with the latest version if it's stopping at MailFolderClient.MoveOrCopyAsync on line 397. The code should be going through line 390 then line 302.

[alasdair-richardson]

so is htis not the latest 2.11.5-tags-v2-11-5-rc0001 ?? (it was the latest according to nuget) anyhow i wil take a look a bit later in case my investigation missed out a bit ...

[danzuep]

That is the latest. Not sure why line 397 doesn't match what's on here though.

[alasdair-richardson]

Ok I realised I am looking at the code in my IDE which has been decompiled and looks somewhat different to the source code. So the line I referenced above where it went off into MailKit code is actually line 318 in your source code ... sorry for the confusion.

[danzuep]

So it's still not working then? I've tested it on Gmail and it was working for me.

[alasdair-richardson]

I looked at your profile and it seems you are based in HK. Do you ever sleep? anyway thanks for your continued help on this, I will look at your test tomorrow I have probably done something simple wrong ... us old people do need a bit of down time!

[alasdair-richardson]

Ok I updated to the latest copy of your code. I tried to bring my mail monitor in line with your code in MonitorMoveAsync.

1. I created the DestinationFolder in ExecuteAsync (using your new method with the createNotFound flag)
   DestinationFolder = await mailFolderClient.GetFolderAsync(Processed, true, ct);
   DesitnationFolder now being a property of MailMonitor
2. I also added mailFolderClient from the service scope
   mailFolderClient = serviceScope.ServiceProvider.GetRequiredService<IMailFolderClient>();
   I had to do this as at step 3 imapReceiver.MailFolderClient.MoveToAsync() is giving me a folder not open exception
3. Then when the email arrives I move using the DestinationFolder

var uniqueId = await mailFolderClient
            .MoveToAsync(summary.UniqueId, DestinationFolder, ct);

The end result is

1. if I process the message in the inbox they all get moved, then all subsequent ones which arrive do not get moved.
2. if I set the ignore existing messages, the first message I send does get moved, but not subsequent ones.
3. to reproduce your test I tried as step 2 (ignoring existing messages) but send 2 emails in v quick succession (as in your test) then they both get moved - but subsequent ones do not.

Difficult to get my head round this!

[alasdair-richardson]

I was considering just moving to the gmail api for processing these incoming mails. Have you ever tried that, do you have any advice?

[alasdair-richardson]

I was also thinking of a) polling every few minuted=s and processing the emails, or b) deleting them after receiving rather than trying to move them. the move was intended as a belt and braces while we get everything up and running in case we decide we need to go and look at the original emails for some reason. but obviously the first approach would be preferable ...

[alasdair-richardson]

ok deleting after downloading is working. This is not ideal but I can progress with some other stuff that has got a bit held up. I would be interested if you could extend your test to involve more emails with a greater time between as that seemed to make a difference in my testing.

[danzuep]

Thanks for testing that, I should be able to get it to fail on my end too now so I can investigate it. In the meantime, have you tried copying before deleting? An even simpler workaround for an unmonitored mailbox would be to just label it as read, or if it is monitored you could use flags. I'll see if I can figure out what's going on here too though as I used to use it when I had a client who wanted it.

[danzuep]

I was caching the source mail folder, but now that I've stopped doing that the issue you found appears to be resolved. Please close this thread if that's the case.

[alasdair-richardson]

Ok we have to take grandchildren out for the day today but I will retest first thing tomorrow (Wednesday).

[danzuep]

I've fixed the folder issue with messageSummary, so this is now safe to use:
var uniqueId = await mailFolderClient.MoveToAsync(messageSummary, destinationFolder, cancellationToken);

[alasdair-richardson]

I pulled your latest version. All appeared fine in testing this morning - it processed a couple of emails sitting in the inbox, then a few more i sent over the next 10 mintes. However when I sent another email almost 3 hours later I got the exception seen below. I have included the last successful read and move at 11:53

2024-08-07 11:53:21.5670 [DEBUG] Caa.Api.Email.MailMonitor: Incoming testing 4 
2024-08-07 11:53:21.9330 [DEBUG] Caa.Api.Email.MailMonitor: After arrival move return uniqueId: 62 
2024-08-07 11:53:26.6315 [ INFO] MailKitSimplified.Receive: imap.gmail.com referencing-test@antisemitism.org INBOX message #68 departure processed. 
2024-08-07 14:43:47.8126 [ INFO] MailKitSimplified.Receive: IMAP protocol exception, checking connection. MailKit.Net.Imap.ImapProtocolException: The IMAP server has unexpectedly disconnected.
   at MailKit.Net.Imap.ImapStream.ReadAheadAsync(Int32 atleast, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapStream.ReadTokenAsync(String specials, CancellationToken cancellationToken)
   at MailKit.Net.Imap.ImapCommand.StepAsync()
   at MailKit.Net.Imap.ImapEngine.IterateAsync()
   at MailKit.Net.Imap.ImapEngine.RunAsync(ImapCommand ic)
   at MailKit.Net.Imap.ImapClient.NoOpAsync(CancellationToken cancellationToken)
   at MailKitSimplified.Receiver.Services.MailFolderMonitor.ProcessMessagesArrivedAsync(Boolean firstConnection, CancellationToken cancellationToken)
   at MailKitSimplified.Receiver.Services.MailFolderMonitor.WaitForNewMessagesAsync(CancellationToken cancellationToken)
2024-08-07 14:43:48.4505 [DEBUG] MailKitSimplified.Receive: imap.gmail.com referencing-test@antisemitism.org INBOX message #69 arrived. 
2024-08-07 14:43:48.4928 [DEBUG] Caa.Api.Email.MailMonitor: Incoming test 5 
2024-08-07 14:43:48.6119 [ERROR] MailKitSimplified.Receive: Error occurred processing arrival queue item. imap.gmail.com referencing-test@antisemitism.org INBOX #69. MailKit.ServiceNotConnectedException: The ImapClient is not connected.
   at MailKit.Net.Imap.ImapFolder.CheckState(Boolean open, Boolean rw)
   at MailKit.Net.Imap.ImapFolder.GetEnumerator()+MoveNext()
   at Microsoft.Extensions.Logging.LogValuesFormatter.TryFormatArgumentIfNullOrEnumerable[T](T value, Object& stringValue)
   at Microsoft.Extensions.Logging.LogValuesFormatter.Format(Object[] values)
   at NLog.Extensions.Logging.NLogLogger.CreateLogEventInfo[TState](LogLevel nLogLogLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at NLog.Extensions.Logging.NLogLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.Logger.<Log>g__LoggerLog|14_0[TState](LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func`3 formatter, List`1& exceptions, TState& state)

[danzuep]

Glad to hear the emails are moving fine now, I'll close this move issue then. I've made a new issue for the disconnection after 3 hours.