Messageserver5 infinite loop

zhasha · 6 July 2023 11:55

REPRODUCIBILITY: 75%-ish
OS VERSION: 4.5.0.19
HARDWARE: Xperia 10 II
UI LANGUAGE: English
REGRESSION: Present since Jolla 1 years and years ago, I don’t remember exactly.

DESCRIPTION:

When establishing a connection to my dovecot IMAP proxy to GMail there’s a chance that messageserver5 goes into what I assume is an infinite event loop. Assume because I can’t find the source code for messageserver5 and I don’t have strace or gdb to dig deeper. I don’t know that it’s inherently tied to the IMAP proxy. I have 4 IMAP accounts set up on the same server with 2 of them set to use IDLE but having reproduced it twice today it was seemingly the proxy account both times.

PRECONDITIONS:

It happens pretty regularly when I leave WiFi and the IMAP IDLE connection times out but while trying to get a baseline on WiFi today it happened seemingly without timing out and while still on WiFi.

STEPS TO REPRODUCE:

Set up IMAP account with IDLE support.
Leave WiFi range for an hour.

EXPECTED RESULT:

Messageserver5 keeps working.

ACTUAL RESULT:

Messageserver5 locks up in an infinite loop, uses 100% of 1 CPU core (12.5% on my Xperia 10 II) and doesn’t respond to the built-in e-mail client and ceases to log anything. The e-mail client will just say “Updating account…” forever if I try to sync. Killing and restarting messageserver5 brings it back to life.

MODIFICATIONS:

Chum and OpenRepos but no patches. It’s been happening since long before Chum even existed.

ADDITIONAL INFORMATION:

I have compiled logs from both messageserver5 and dovecot. Benefit of it being my own server I suppose. Messageserver5 went into an infinite loop at 10:27 and 12:31. From what I can see it establishes 2 connections for the proxy account and one of them it doesn’t bother to authenticate so it gets closed after 3 minutes for inactivity. The second is presumably kept open but gets closed in the first example after I killed messageserver5 and in the second example after I came back home and it went on WiFi.

Jul  6 10:27:17 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Started proxying to <74.125.205.108> (0.494 secs): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=192.168.0.226, lip=server.ip.addr.ess, TLS, session
=<8ka3SM3/JKzAqADi>
Jul  6 10:27:18 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Started proxying to <74.125.205.108> (0.466 secs): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=192.168.0.226, lip=server.ip.addr.ess, TLS, session
=<kDXCSM3/IqzAqADi>
Jul  6 10:27:19 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Disconnected by server (0s idle, in=209, out=138783): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=192.168.0.226, lip=server.ip.addr.ess, TLS, sess
ion=<kDXCSM3/IqzAqADi>
Jul  6 10:30:19 wirbelwind dovecot[341790]: imap-login: Disconnected: Inactivity (no auth attempts in 180 secs): user=<>, rip=192.168.0.226, lip=server.ip.addr.ess, TLS, session=<xL6aU83/JqzAqADi>
Jul  6 10:51:54 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Disconnected by client (1477s idle, in=114, out=801): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=192.168.0.226, lip=server.ip.addr.ess, TLS: Conn
ection closed, session=<8ka3SM3/JKzAqADi>

Messageserver5 ends on a positive note around line 16400:

[16568] Jul 06 10:27:19 [Debug] IMAP :  "7" RECV: * 3134 FETCH (UID 4872 MODSEQ (784592) FLAGS (\Seen))
[16568] Jul 06 10:27:19 [Debug] IMAP :  "7" RECV: * 3135 FETCH (UID 4873 MODSEQ (784914) FLAGS (\Seen))
[16568] Jul 06 10:27:19 [Debug] IMAP :  "7" RECV: * 3136 FETCH (UID 4874 MODSEQ (785122) FLAGS (\Seen))
[16568] Jul 06 10:27:19 [Debug] IMAP :  "7" RECV: a006 OK Success
[16568] Jul 06 10:27:19 [Debug] Messaging :  Action completed 71159018160130 result success
[16568] Jul 06 10:27:19 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[16568] Jul 06 10:27:19 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[16568] Jul 06 10:27:19 [Debug] Messaging :  Running action RetrieveMessageListRequest 71159018160131
[16568] Jul 06 10:27:19 [Debug] Messaging :  Setting imap strategy 31ImapRetrieveMessageListStrategy
[16568] Jul 06 10:27:19 [Debug] IMAP :  "9" About to open connection "regular-account-1@regular-domain.com" "mail.server.com"
[16568] Jul 06 10:27:19 [Debug] Messaging :  QMailTransport::Socket::Socket SET PROXY host= "" port= 0
[16568] Jul 06 10:27:19 [Debug] Messaging :  Opening connection -  "mail.server.com" : 993  SSL
[16568] Jul 06 10:27:19 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[16568] Jul 06 10:27:19 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[16568] Jul 06 10:27:19 [Debug] IMAP :  "7" SEND a007 LOGOUT
[16568] Jul 06 10:27:19 [Debug] Messaging :  IMAP : connection established
[16568] Jul 06 10:27:19 [Debug] Messaging :  IMAP : Secure connection established
[16568] Jul 06 10:27:19 [Debug] IMAP :  "9" RECV: * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ AUTH=PLAIN AUTH=LOGIN] Dovecot ready.

And later:

Jul  6 12:31:48 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Started proxying to <74.125.205.108> (0.724 secs): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=213.237.109.54, lip=server.ip.addr.ess, TLS, session=<i8EABs//xBPV7W02>
Jul  6 12:31:49 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Started proxying to <74.125.205.108> (0.445 secs): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=213.237.109.54, lip=server.ip.addr.ess, TLS, session=<WnQSBs//whPV7W02>
Jul  6 12:31:50 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Disconnected by server (0s idle, in=317, out=93296): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=213.237.109.54, lip=server.ip.addr.ess, TLS, session=<WnQSBs//whPV7W02>
Jul  6 12:34:50 wirbelwind dovecot[341790]: imap-login: Disconnected: Inactivity (no auth attempts in 180 secs): user=<>, rip=213.237.109.54, lip=server.ip.addr.ess, TLS, session=<8sruEM//xhPV7W02>
Jul  6 13:01:54 wirbelwind dovecot[341790]: imap-login: proxy(proxy-account@proxy-domain.com,74.125.205.108:993): Disconnected by client: read(size=188) failed: Connection reset by peer (1806s idle, in=114, out=801): user=<proxy-account@proxy-domain.com>, method=PLAIN, rip=213.237.109.54, lip=server.ip.addr.ess, TLS: read(size=188) failed: Connection reset by peer, session=<i8EABs//xBPV7W02>

I don’t know if this means messageserver5 went down another code path but it ends on a similar note:

[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3132 FETCH (UID 4870 MODSEQ (784413) FLAGS (\Seen))
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3133 FETCH (UID 4871 MODSEQ (784413) FLAGS (\Seen))
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3134 FETCH (UID 4872 MODSEQ (784592) FLAGS (\Seen))
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3135 FETCH (UID 4873 MODSEQ (784914) FLAGS (\Seen))
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3136 FETCH (UID 4874 MODSEQ (785122) FLAGS (\Seen))
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3137 FETCH (UID 4875 MODSEQ (785178) FLAGS ())
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: a005 OK Success
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" SEND a006 UID FETCH 4875 (FLAGS UID INTERNALDATE RFC822.SIZE BODYSTRUCTURE RFC822.HEADER)
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3137 FETCH (UID 4875 RFC822.SIZE 14485 RFC822.HEADER {8548}
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: <8548 literal bytes received>
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV:  MODSEQ (785178) INTERNALDATE "06-Jul-2023 09:20:21 +0000" FLAGS () BODYSTRUCTURE (("TEXT" "PLAIN" ("CHARSET" "utf-8") NIL NIL "QUOTED-PRINTABLE" 1194 24 NIL NIL NIL)("TEXT" "HTML" ("CHARSET" "utf-8") NIL NIL "QUOTED-PRINTABLE" 3836 77 NIL NIL NIL) "ALTERNATIVE" ("BOUNDARY" "Apple-Mail=_A7C1F910-D4BA-4869-99C3-ADAFADA02194") NIL NIL))
[26265] Jul 06 12:31:49 [Debug] Messaging :  Checking for attachments to download
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: a006 OK Success
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" SEND a007 UID FETCH 4875 (FLAGS UID RFC822.SIZE BODY.PEEK[])
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * 3137 FETCH (UID 4875 RFC822.SIZE 14485 MODSEQ (785178) FLAGS () BODY[] {14485}
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: <14485 literal bytes received>
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: )
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: a007 OK Success
[26265] Jul 06 12:31:49 [Debug] Messaging :  Checking for attachments to download
[26265] Jul 06 12:31:49 [Debug] Messaging :  Push email established for account 7 "proxy-account@proxy-domain.com"
[26265] Jul 06 12:31:49 [Debug] Messaging :  Action completed 112807316029445 result success
[26265] Jul 06 12:31:49 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[26265] Jul 06 12:31:49 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[26265] Jul 06 12:31:49 [Debug] Messaging :  Running action RetrieveMessageListRequest 112807316029446
[26265] Jul 06 12:31:49 [Debug] Messaging :  Setting imap strategy 31ImapRetrieveMessageListStrategy
[26265] Jul 06 12:31:49 [Debug] IMAP :  "9" About to open connection "regular-account-1@regular-domain.com" "mail.server.com"
[26265] Jul 06 12:31:49 [Debug] Messaging :  QMailTransport::Socket::Socket SET PROXY host= "" port= 0
[26265] Jul 06 12:31:49 [Debug] Messaging :  Opening connection -  "mail.server.com" : 993  SSL
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" SEND a008 LOGOUT
[26265] Jul 06 12:31:49 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[26265] Jul 06 12:31:49 [Debug] IMAP :  void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "proxy-account@proxy-domain.com"
[26265] Jul 06 12:31:49 [Debug] Messaging :  IMAP : connection established
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: * BYE LOGOUT Requested
[26265] Jul 06 12:31:49 [Debug] IMAP :  "7" RECV: a008 OK 73 good day (Success)

I thought this might have had something to do with dovecot but having just done a major update with no change in behavior I think the most likely cause is messageserver5 sitting in a poll loop not responding to some event.

ohnonot · 14 December 2023 20:35

I have noticed something has been eating battery recently.

htop showed messageserver5 running full power on 1 CPU, all the time. I couldn’t open the Email app (“Not responding”).

killall messageserver5
or
systemctl --user stop messagserver5
did nothing at first, but in the end the process/service died. Then I couldn’t restart the service.

Now, about 10min later, I managed to restart the service and the process is running, taking 100% of 1 CPU again.

In fact, now the symptoms are even more like you describe: the Email app is responsive, but updating/syncing an account never finishes.

I am connected via WLAN and have 2 mail accounts: 1 normal IMAP/SMTP, 1 Google.

I cannot see any messageserver5 logs. journalctl -f gives me this when I open the Email app:

Dec 14 22:29:47 XA2 dbus-daemon[4913]: dbus-daemon[4913]: [session uid=100000 pid=4913] Activating service name='com.jolla.email.ui' requested by ':1.921' (uid=100000 pid=24763 comm="/usr/libexec/mliteremoteaction com.jolla.email.ui ")
Dec 14 22:29:47 XA2 art[24591]: warning: ignoring argument: -prestart
Dec 14 22:29:47 XA2 art[24591]: [D] unknown:0 - Messaging :  opening database
Dec 14 22:29:47 XA2 dbus-daemon[4913]: dbus-daemon[4913]: [session uid=100000 pid=4913] Successfully activated service 'com.jolla.email.ui'
Dec 14 22:29:48 XA2 invoker[5281]: WARNING: An inactive plugin is misbehaving - tried to show a window!
Dec 14 22:29:48 XA2 invoker[5281]: WARNING: requestActivate() called for  QQuickView(0x227350)  which has Qt::WindowDoesNotAcceptFocus set.
Dec 14 22:29:48 XA2 lipstick[4973]: [W] unknown:0 - WindowPixmapItem does not have a source texture, cover will be dropped..
Dec 14 22:29:48 XA2 booster-browser[24771]: [D] unknown:0 - Using Wayland-EGL
Dec 14 22:29:48 XA2 lipstick[4973]: [D] onCompleted:264 - coverActionIndicators created jolla-email.desktop
Dec 14 22:29:48 XA2 art[24591]: [W] unknown:0 - Could not open "/usr/share/sailfish-browser/data/ua-update.json.in"
Dec 14 22:29:48 XA2 art[24591]: [W] unknown:0 - "/home/defaultuser/.cache/com.jolla/email/.mozilla/ua-update.json" parse error "illegal value" at offset 0

The last 2 lines look relevant.

I’ll try to delete the cache.

PS: what is the purpose of messageserver5?

zhasha · 16 December 2023 09:33

Messageserver5 is the process that actually talks to your mail server. Jolla-email is just the GUI frontend to it.

In the interim I think I’ve accidentally deleted the full logs I linked here but I might also have made some progress in narrowing it down accidentally. I recently blocked all incoming traffic to dovecot from all but 2 IPs meaning my phone can no longer connect when not on WiFi. The issue seems related to the time between me leaving WiFi range and coming back into it. The firewall is just dropping packets (ie. not sending TCP REJECTs) so that might have an impact on behavior. The 100% CPU usage only happens when it’s able to successfully reconnect to dovecot and I think it’s more likely to happen when the duration of the disconnect is shorter. It’s happening significantly less often now that it can’t reconnect on mobile internet.

ohnonot · 17 December 2023 12:31

Removing the above mentioned cache did nothing.

It seems my issue is different from yours as messageserver5 just stays on 100% CPU all the time, it’s not a temporary problem.

Could you confirm this? Because then I’d start a new thread.

Meanwhile I killed messageserver5, then masked the service which had the obvious outcome of no messageserver5 process at all, and no new mail.

Unmasking & reboot: back to messageserver5 constantly eating away at one core.

I did this now and will start collecting logs.
Unfortunately I still cannot restart messageserver5.service or start messageserver5 manually, have to reboot (and nothing in the newly created log file either).

zhasha · 17 December 2023 13:00

It depends on what you mean by “stays on 100% CPU all the time.”
Once it gets into the infinite loop it stays there until I SIGKILL it. A few times I’ve seen it respawn immediately on 100% CPU but for the most part, when it respawns immediately, it will only temporarily use a fair bit of CPU and then calm down after a few seconds; though it will usually just stay dead until I open jolla-email, meaning I get no email notifications in the meantime.
Just to be clear: I’m sending it SIGKILL and not ever interacting with it via systemd. I might be able to attach strace or gdb to it next time if that would help.

ohnonot · 18 December 2023 17:11

I can see that my logs look nothing like yours and I’ll treat this as a separate problem.

Of course your assistance would still be appreciated: Cannot check Emails (internet works) / messageserver5 Eats 100% CPU of 1 Core (and battery)