Messageserver5 infinite loop

Bug Reports
#1

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:

  1. Set up IMAP account with IDLE support.
  2. 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.

1 Like
Community meeting on IRC 28th September 2023
Cannot check Emails (internet works) / messageserver5 Eats 100% CPU of 1 Core (and battery)
Cannot check Emails (internet works) / messageserver5 Eats 100% CPU of 1 Core (and battery)
#2

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?

#3

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.

1 Like
#4

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).

#5

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.

1 Like
#6

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)

#7

I wish someone had pointed me to the messagingframework repo. I realized it wasn’t proprietary quite by accident and now I think I’ve found the bug.
https://github.com/sailfishos/messagingframework/blob/master/rpm/0003-SSO-integration.patch#L3267
This loop is where messageserver5 gets stuck forever. One of my email accounts has a password containing two escape characters meaning this condition gets entered twice, however the saved begin iterator is invalidated by the insert call right below it from the first escaped character.
The fix is extremely simple:
+ it = result.begin() + (pos + 1);
into
+ it = (begin = result.begin()) + (pos + 1);
or alternatively always use result.begin() and remove the saved begin iterator.
The reason it seems random is probably just down to the luck of the draw from a realloc call somewhere as to whether it moves the memory or not.

#8

How about a PR then?

#9

It appears I have been sniped.

Leaving this here for posterity:

From beae0496442caa1dc0e4b052cfccd0a0b40d210e Mon Sep 17 00:00:00 2001
From: Joakim Sindholt <opensource@zhasha.com>
Date: Mon, 5 Aug 2024 17:40:38 +0200
Subject: [PATCH] quoteIMAPString: fix use of invalidated iterator

The saved begin iterator is invalidated by the insert() call but does
not get re-saved and as a result any string containing 2 or more
characters that need escaping might calculate invalid positions after
the first escape and potentially crash or get stuck in an infinite loop
depending on whether or not the begin iterator happens to be in the same
place or not after insert().
---
 rpm/0003-SSO-integration.patch | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/rpm/0003-SSO-integration.patch b/rpm/0003-SSO-integration.patch
index f9cb62d..54c3b63 100644
--- a/rpm/0003-SSO-integration.patch
+++ b/rpm/0003-SSO-integration.patch
@@ -3260,11 +3260,11 @@ index 00000000..00ad7e73
 +    // We need to quote this string because it is not an atom
 +    QString result(input);
 +
-+    QString::iterator begin = result.begin(), it = begin;
++    QString::iterator it = result.begin();
 +    while (it != result.end()) {
 +        // We need to escape any characters specially treated in quotes
 +        if ((*it) == '\\' || (*it) == '"') {
-+            int pos = (it - begin);
++            int pos = (it - result.begin());
 +            result.insert(pos, '\\');
 +            it = result.begin() + (pos + 1);
 +        }
-- 
2.44.2