Mailnag stops working after waking from suspend

[mfreeman72]

When I suspend my laptop and later wake it up again, Mailnag stops checking for e-mail. To get it working again, I have to restart the daemon (usually by opening and closing mailnag-config).

This is the same as what has been reported at pulb/mailnag#186

A workaround suggested in that discussion was to force a mailnag restart after every wake-up, which I've been having trouble implementing for some reason. But ideally, I'd rather see it fixed within the program itself instead of hacky workarounds.

This is a copy/paste from logs I posted at that bug report:

mike@ASUS-TUF-Gaming:~$ journalctl -b _COMM=mailnag
Jul 24 07:20:32 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:20:32): Successfully enabled plugin 'libnotifyplugin'.
Jul 24 07:20:32 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:20:32): Successfully enabled plugin 'goaplugin'.
Jul 24 07:20:32 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:20:32): Checking 1 email account(s).
Jul 24 07:22:31 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:22:31): Checking 1 email account(s).
Jul 24 07:22:47 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:22:47): Checking 1 email account(s).
Jul 24 07:22:53 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:22:53): Checking 1 email account(s).
Jul 24 07:32:54 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:32:54): Checking 1 email account(s).
Jul 24 07:36:31 ASUS-TUF-Gaming mailnag[2970]: ERROR (2024-07-24 07:36:31): Idle callback for account 'mikefreeman1972@gmail.com' returned an error (<class 'Mailnag.common.imaplib2.IMAP4.abort'> - socket error: <class 'OSError'> - Too many read 0).
Jul 24 07:36:31 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:36:31): Resetting connection for account 'mikefreeman1972@gmail.com'
Jul 24 07:36:31 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:36:31): Idler thread for account 'mikefreeman1972@gmail.com' has been disconnected
Jul 24 07:36:31 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:36:31): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com'.
Jul 24 07:36:37 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:36:37): Successfully reconnected Idler thread for account 'mikefreeman1972@gmail.com'.
Jul 24 07:36:37 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:36:37): Checking 1 email account(s).
Jul 24 07:46:37 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:46:37): Checking 1 email account(s).
Jul 24 07:47:23 ASUS-TUF-Gaming mailnag[2970]: ERROR (2024-07-24 07:47:23): Idle callback for account 'mikefreeman1972@gmail.com' returned an error (<class 'Mailnag.common.imaplib2.IMAP4.abort'> - connection terminated).
Jul 24 07:47:23 ASUS-TUF-Gaming mailnag[2970]: ERROR (2024-07-24 07:47:23): Idle callback for account 'mikefreeman1972@gmail.com' returned an error (<class 'Mailnag.common.imaplib2.IMAP4.abort'> - connection terminated).
Jul 24 07:47:23 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:47:23): Resetting connection for account 'mikefreeman1972@gmail.com'
Jul 24 07:47:23 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:47:23): Idler thread for account 'mikefreeman1972@gmail.com' has been disconnected
Jul 24 07:47:23 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:47:23): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com'.
Jul 24 07:47:25 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:47:25): Successfully reconnected Idler thread for account 'mikefreeman1972@gmail.com'.
Jul 24 07:47:25 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:47:25): Checking 1 email account(s).
Jul 24 07:57:26 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 07:57:26): Checking 1 email account(s).
Jul 24 08:04:41 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:04:41): Checking 1 email account(s).
Jul 24 08:14:42 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:14:42): Checking 1 email account(s).
Jul 24 08:16:33 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:16:33): Checking 1 email account(s).
Jul 24 08:26:34 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:26:34): Checking 1 email account(s).
Jul 24 08:31:11 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:31:11): Checking 1 email account(s).
Jul 24 08:41:12 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:41:12): Checking 1 email account(s).
Jul 24 08:51:14 ASUS-TUF-Gaming mailnag[2970]: ERROR (2024-07-24 08:51:14): Idle callback for account 'mikefreeman1972@gmail.com' returned an error (<class 'Mailnag.common.imaplib2.IMAP4.abort'> - socket error: <class 'OSError'> - Too many read 0).
Jul 24 08:51:14 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:51:14): Resetting connection for account 'mikefreeman1972@gmail.com'
Jul 24 08:51:14 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:51:14): Idler thread for account 'mikefreeman1972@gmail.com' has been disconnected
Jul 24 08:51:14 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:51:14): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com'.
Jul 24 08:51:16 ASUS-TUF-Gaming mailnag[2970]: ERROR (2024-07-24 08:51:16): Failed to reconnect Idler thread for account 'mikefreeman1972@gmail.com' (b'[AUTHENTICATIONFAILED] Invalid credentials (Failure)').
Jul 24 08:51:16 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:51:16): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com' in 5 minutes
Jul 24 08:56:16 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:56:16): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com'.
Jul 24 08:56:18 ASUS-TUF-Gaming mailnag[2970]: ERROR (2024-07-24 08:56:18): Failed to reconnect Idler thread for account 'mikefreeman1972@gmail.com' (b'[AUTHENTICATIONFAILED] Invalid credentials (Failure)').
Jul 24 08:56:18 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 08:56:18): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com' in 5 minutes
Jul 24 09:01:18 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 09:01:18): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com'.
Jul 24 09:01:21 ASUS-TUF-Gaming mailnag[2970]: ERROR (2024-07-24 09:01:21): Failed to reconnect Idler thread for account 'mikefreeman1972@gmail.com' (b'[AUTHENTICATIONFAILED] Invalid credentials (Failure)').
Jul 24 09:01:21 ASUS-TUF-Gaming mailnag[2970]: INFO (2024-07-24 09:01:21): Trying to reconnect Idler thread for account 'mikefreeman1972@gmail.com' in 5 minutes

[tikank]

Reading that log it shows pretty ok (I suppose) until 08:51:16 where is invalid credentials error. "Socket error" is imaplib2's way to tell that IMAP connection is lost. Then mailnag tries to reconnect...

I tried to repeat this and with about half an hour suspend IMAP server disconnected and when machine was resumed mailnag reconnected normally.

I wonder if this is Gmail specific or does this happen other IMAP servers also. How long the laptop needs to be suspended until this happens? Or does this happen every time after suspend? What version of mailnag you are running? 2.2.0?

[mfreeman72]

I'm using the GOA plugin to connect, if that makes any difference. I can attempt to connect to GMail via normal IMAP instead and see if that makes a difference. I don't have any other e-mail servers I can try, unfortunately. This happens every time, regardless of how long or short the suspend is. I'm using mailnag 2.2.0.

[mfreeman72]

Ok. I turned off the GOA plugin and connected to my gmail account through Mailnag's normal "GMail" option, using an application-specific password given by Google. There is a slight difference this time. It connects and gets my mail until I suspend. After a suspend, it stops checking. But in the logs, there is no longer any errors about failing to reconnect. It just doesn't check anymore. I let it sit there for 30 minutes. The last thing the log shows is the last time it checked my e-mail. No errors, just nothing.

[tikank]

If I understand correctly GOA plugin might give oauth2 access token to Mailnag, and Mailnag uses that to authenticate to Gmail server. If/when the token expires (in about an hour?), that could explain invalid credentials error. Then GOA plugin/Mailnag should refresh the token, but I don't see any code to do that. This might be one bug. I am not sure.

So, another issue is why Mailnag does not reconnect/continue checking without GOA plugin, when it uses username+password login...

[tikank]

Oh, there is a bug report about expiration pulb/mailnag-goa-plugin#7 .

[mfreeman72]

Good catch! I discovered another thing to add to the conversation. While not using the GOA plugin, my first test above was with relatively short duration sleep cycles. But after letting it sleep for quite a while (like an hour or more), suddenly it came back to life and started checking for e-mail again. I'm not sure what made the difference, but I'll keep testing to see if I can come up with which exact situations cause the problem and which don't.

[mfreeman72]

So, from my experimentation, I found that mailnag 2.2.0 doesn't immediately start checking mail after waking up. It seems to average somewhere between 15-30 minutes after waking up before it will start letting me know there is new mail again. It does give me an error in the log at the end of that 15-30 minute time frame:

ERROR (2024-10-16 10:22:18): Idle callback for account 'mikefreeman1972@gmail.com (Gmail)' returned an error (<class 'Mailnag.common.imaplib2.IMAP4.abort'> - socket error: <class 'OSError'> - Too many read 0).

It's like there's a timeout or something that it waits for before it will decide there's a problem and retry the connection. As soon as this error is given, it starts checking again.

Again, this is with the normal GMail login through mailnag, and NOT with the GOA plugin.

[tikank]

I'll look what I can find.
At least there is idle timeout (in config file), but it is by default 10 minutes, so it does not match that 15-30 min (or it is broken...).

[mfreeman72]

I hadn't considered looking at the config file. Maybe just for kicks, I'll change that timeout to something fairly short (something like 3 to 5 minutes) and see what happens. In my testing, what I do is put my system to sleep, and have someone send me an e-mail, or send myself one. Once I get the notification that GMail received the e-mail on my phone, I'll wake up the computer and wait for mailnag to notify me of the e-mail. By the time the notification pops up, the notification will say something to the effect that the e-mail was received 29 minutes ago, or 23 minutes ago, or whatever. So I'll see if changing the timeout in the config shortens that timeframe any.

[tikank]

I have not found any other relevant timeout parameters.
There is read timeout (default 30 sec) in imaplib2, but it just stops read poll.
On idle timeout mailnagger sends data to server and that should trigger failure in socket, if connection is lost.