Mails missed due to disconnection of account idler thread, requiring backend restart

[ronjouch]

Under a yet-to-be-understood scenario, mailnag (and I don't know if it's the backend or the Shell extension) starts to completely fail:

• Shell icon remains at 0 / "no new email" state
• New emails aren't seen
• Marking emails as seen/unseen in my IMAP client has no impact, icon remains blank

I'm sometimes able to recover from this state by restarting the backend (using mailnag's preferences On/Off button) UPDATE 2017-06-21 ~and restarting Shell (Alt+F2, r), and I think both restarts are needed (which is why I say I don't know if it's a backend or frontend issue :-/ )~

This happens every few days on my machine, and I have no idea how to get a more precise idea of the bug.

→ How can I get more debug info/logs (both backend and extension) to help me/you understand what's wrong? Thanks 🙂.

mailnag 1.2.1 running on Shell 3.24.2 on Arch Linux x64

[ronjouch]

@pulb update to the original description (which I'm updating): I'm always able to recover a functional mailnag by restarting the backend, using Mailnag Settings → Off → On → Close window. My original description was confused due to misunderstanding the fact that the backend restart is done on window close, not on On/Off button click.

Help to get more debug info/logs still very welcome to better understand what's going on 🙂.

[pulb]

Hi! Thanks for reporting this issue and sorry for the late reply, I'm very busy these days :( The on/off button itself indeed has no effect, it just determines if the mailnag daemon shall be restarted or terminated after closing the prefs window. So just closing the prefs window is sufficient in order to restart the daemon.

Do you still get gnome-shell notifcations (in the upper middle of the screen) when mailnag starts to fail? Are there any special events occuring before mailnag start to fail? Like laptop standby or loss of inet connectivity?

What email provider are you using?

You can try to get more debug information by running journalctl -b _COMM=mailnag in a terminal.

[ronjouch]

Hi @pulb, thanks for the feedback 👍.

• When mailnag starts to fail, no I no longer get gnome-shell extension count/sound/notifications (that's what my description meant by "Shell icon remains at 0 / 'no new email' state")
• I'm not sure of special events before mailnag starts to fail. But yes, both laptop standby and inet connectivity loss are recurring events in my daily usage. Will try to think about it next time it fails.
• I'm using the Gmail provider.

Thanks for the tip for logs, I'll try that at next failure. Thanks! 🙂

[schiessle]

I have the same issue, using the mail server of my web hosting service.

On the log I see every 5 minutes (which is the interval I set in the mailnag.cfg):

Jul 28 12:21:59 potato mailnag[1579]: INFO (2017-07-28 12:21:59): Checking 1 email account(s).

so it seems like the mailnag daemon works just fine, but the gnome-shell extension no longer updates. As mentioned by @ronjouch earlier in this thread, if I open the mailnag settings and close them again the extensions gets reloaded and updated correctly... A few hours later it fails again to update.

[pulb]

@schiessle: Thanks for this very useful info. So this is a POP3 account? Did you seee any gnome-shell warnings/errors in journalctl when this happened?

Am 28. Juli 2017 12:25:03 MESZ schrieb "Björn Schießle" [email protected]:

I have the same issue, using the mail server of my web hosting service.

On the log I see every 5 minutes:

Jul 28 12:21:59 potato mailnag[1579]: INFO (2017-07-28 12:21:59):
Checking 1 email account(s).

so it seems like the mailnag daemon works just fine, but the gnome-shell extension no longer updates. As said earlier in this thread if I open the mailnag settings and close them again the extensions gets reloaded and updated correctly... A few hours later it fails again to update.

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/pulb/mailnag-gnome-shell/issues/47#issuecomment-318617940

[schiessle]

@pulb no, it is a imap account but I only check a subset of my mail folders so I can't enable push-imap. I couldn't find any gnome-shell warning or errors in journalctl.

[schiessle]

Ah, that's interesting. Let's say I start with a mailbox of 5 unread messages. Mailnag notifies me about it correctly. Then I open my mail client and read them. Now all mails are marked as read but the applet will still show 5 unread messages even if I click on "Check for Mail". Now I go back to my mail client and mark one mail as unread, click on "Check for Mail" on the applet again and the applet updates the status successfully and shows this one unread message.

Maybe the whole problem is that mailnag doesn't detect if some mail only changes from read to unread and that's why it feels like it stops updating?

[ronjouch]

@pulb I finally have news about this bug! (Sorry for the long wait.) Looks like the problem is due to mailnag "disconnecting" account checking threads. See below output of journalctl -b _COMM=mailnag:

1. First lines are normal mailnag operation, checking my Gmail account during the night.
2. At 06:49 (this is mailnag entirely on its own; I didn't do anything, was asleep) mailnag reports having "disconnected" the "Idler thread" for my Gmail.
3. Then after waking up, at 9:31 I notice I have emails in Thunderbird that mailnag didn't notify about, and I press on mailnag-gnome-shell-ext "Check For Mail" two times (thus the last two lines): see how it's now Checking 0 email account(s).

Does that ring a bell? Feel free to ask for more debug info.

Nov 27 04:58:37 t mailnag[22849]: INFO (2017-11-27 04:58:37): Checking 1 email account(s).
Nov 27 05:08:37 t mailnag[22849]: INFO (2017-11-27 05:08:37): Checking 1 email account(s).
Nov 27 05:18:37 t mailnag[22849]: INFO (2017-11-27 05:18:37): Checking 1 email account(s).
Nov 27 05:28:37 t mailnag[22849]: INFO (2017-11-27 05:28:37): Checking 1 email account(s).
Nov 27 05:38:37 t mailnag[22849]: INFO (2017-11-27 05:38:37): Checking 1 email account(s).
Nov 27 05:48:38 t mailnag[22849]: INFO (2017-11-27 05:48:38): Checking 1 email account(s).
Nov 27 05:58:38 t mailnag[22849]: INFO (2017-11-27 05:58:38): Checking 1 email account(s).
Nov 27 06:08:38 t mailnag[22849]: INFO (2017-11-27 06:08:38): Checking 1 email account(s).
Nov 27 06:18:38 t mailnag[22849]: INFO (2017-11-27 06:18:38): Checking 1 email account(s).
Nov 27 06:28:39 t mailnag[22849]: INFO (2017-11-27 06:28:39): Checking 1 email account(s).
Nov 27 06:38:39 t mailnag[22849]: INFO (2017-11-27 06:38:39): Checking 1 email account(s).
Nov 27 06:48:40 t mailnag[22849]: INFO (2017-11-27 06:48:40): Checking 1 email account(s).
Nov 27 06:49:30 t mailnag[22849]: INFO (2017-11-27 06:49:30): Idler thread for account 'mygmailusernamehere (Gmail)' has been disconnected
Nov 27 09:31:06 t mailnag[22849]: INFO (2017-11-27 09:31:06): Checking 0 email account(s).
Nov 27 09:32:00 t mailnag[22849]: INFO (2017-11-27 09:32:00): Checking 0 email account(s).

Then, as usual, a backend restart succeeds into fixing the problem:

Nov 27 09:41:39 t mailnag[22849]: INFO (2017-11-27 09:41:39): Shutting down...
Nov 27 09:41:39 t mailnag[22849]: INFO (2017-11-27 09:41:39): Idler closed
Nov 27 09:41:39 t mailnag[22849]: INFO (2017-11-27 09:41:39): Plugins disabled successfully.
Nov 27 09:41:41 t mailnag[13738]: INFO (2017-11-27 09:41:41): Successfully enabled plugin 'soundplugin'.
Nov 27 09:41:41 t mailnag[13738]: INFO (2017-11-27 09:41:41): Successfully enabled plugin 'dbusplugin'.
Nov 27 09:41:41 t mailnag[13738]: INFO (2017-11-27 09:41:41): Checking 1 email account(s).

This is mailnag-1.2.1-1 and mailnag-gnome-shell-3.26.0-1, both from AUR, running on an up-to-date Arch with Shell 3.26.2.

---

EDIT looks like problem can also appear without triggering logging of that Idler thread for account '...' has been disconnected message. I just faced the bug again, and this time here's the log; notice the change at lines 6-7 below from 1 to 0 checked email accounts, but without the 'has been disconnected' log. As usual, restarting Mailnag restores functionality (final line).

Nov 27 13:44:19 t mailnag[13738]: INFO (2017-11-27 13:44:19): Checking 1 email account(s).
Nov 27 14:03:39 t mailnag[13738]: INFO (2017-11-27 14:03:39): Checking 1 email account(s).
Nov 27 14:03:39 t mailnag[13738]: WARNING (2017-11-27 14:03:39): No internet connection.
Nov 27 14:04:35 t mailnag[13738]: INFO (2017-11-27 14:04:35): Checking 1 email account(s).
Nov 27 14:08:20 t mailnag[13738]: INFO (2017-11-27 14:08:20): Checking 1 email account(s).
Nov 27 14:10:35 t mailnag[13738]: INFO (2017-11-27 14:10:35): Checking 1 email account(s).
Nov 27 14:25:14 t mailnag[13738]: INFO (2017-11-27 14:25:14): Checking 0 email account(s).
Nov 27 14:26:36 t mailnag[13738]: INFO (2017-11-27 14:26:36): Checking 0 email account(s).
Nov 27 14:26:46 t mailnag[13738]: INFO (2017-11-27 14:26:46): Shutting down...
Nov 27 14:26:56 t mailnag[13738]: WARNING (2017-11-27 14:26:56): Cleanup takes too long. Enforcing termination.
Nov 27 14:26:58 t mailnag[22879]: INFO (2017-11-27 14:26:58): Successfully enabled plugin 'soundplugin'.
Nov 27 14:26:58 t mailnag[22879]: INFO (2017-11-27 14:26:58): Successfully enabled plugin 'dbusplugin'.
Nov 27 14:26:58 t mailnag[22879]: INFO (2017-11-27 14:26:58): Checking 1 email account(s).

[pulb]

@ronjouch: Many thanks for this very useful investigation. I'll have a closer look as soon as I find time. Unfortunately I'm currently very busy with real life stuff.