Session dbus daemon is quickly saturated with match rules, exceeding configuration limits.

[ProMarbler14]

Expected behavior

The session's dbus daemon should not be saturated with match rules for a single connection just by using the terminal emulator.

Actual behavior

The session's dbus daemon receives repeated AddMatch method calls (?) for every keypress the terminal receives. After being used for a while, the system journal log becomes spammed with warnings like this:
[session uid=1000 pid=552] Connection ":1.33" is not allowed to add more match rules (increase limits in configuration file if required; max_match_rules_per_connection=50000)
Observing the session message bus with dbus-monitor reveals repeated messages like this:
method call time=1521644024.563761 sender=:1.32 -> destination=org.freedesktop.DBus serial=724 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch string "type='signal',interface='ca.desrt.dconf.Writer',path='/ca/desrt/dconf/Writer/user',arg0path='/org/mate/terminal/global/'" method return time=1521644024.563816 sender=org.freedesktop.DBus -> destination=:1.32 serial=714 reply_serial=724

Steps to reproduce the behavior

Open a terminal window and start pressing/typing keys, including meta keys like shift.

MATE general version

1.20.0

Package version

1.20.0

Linux Distribution

Arch Linux

Link to downstream report of your Distribution

currently none

[alexarnaud]

There are downstream reports about this issue:

• https://bugzilla.redhat.com/show_bug.cgi?id=1427721
• https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=894251

Best regards.

[alexarnaud]

@ProMarbler14 Are you still able to reproduce the issue ? On Debian, the user has indicated that the issue has been solved by an upgrade.

Best regards.

[Safari77]

I get those dbus spams all the time, mate-terminal 1.20.0, Fedora 27.
I wonder why the dbus folks want to log every time limit is reached, instead of only once per connection when limit is reached. I guess people notice a bit better when you get 300 logs a minute?

That debian reporter didn't say whether he is still using mate-terminal.

[xdmitry]

I have similar issue on Fedora 28, also had it on 27 and 26

I'm using mate-terminal-1.20.0-2.fc28.x86_64 at the moment

[tofurky]

i'm seeing the same. i just now traced it to mate-terminal. this is ubuntu 18.04 amd64 with ubuntu's 1.20.1 build.

apps that connect to d-bus and/or spawn a service (in this case org.freedesktop.Notifications) seem to trigger this, at least in part. connection ':1.51' is mate-terminal, according to the d-feet utility.

May 27 21:51:50 aquos dbus-daemon[1425]: message repeated 31 times: [ [session uid=1000 pid=1425] Connection ":1.51" is not allowed to add more match rules (increase limits in configuration file if required; max_match_rules_per_connection=50000)]
May 27 21:51:50 aquos dbus-daemon[1425]: [session uid=1000 pid=1425] Activating service name='org.freedesktop.Notifications' requested by ':1.1356' (uid=1000 pid=31710 comm="pkcs11-tool --test --module /usr/lib/x86_64-linux-")
May 27 21:51:50 aquos dbus-daemon[1425]: [session uid=1000 pid=1425] Successfully activated service 'org.freedesktop.Notifications'
...
May 27 22:01:19 aquos dbus-daemon[1425]: message repeated 110 times: [ [session uid=1000 pid=1425] Connection ":1.51" is not allowed to add more match rules (increase limits in configuration file if required; max_match_rules_per_connection=50000)]
May 27 22:01:19 aquos dbus-daemon[1425]: [session uid=1000 pid=1425] Activating service name='org.freedesktop.Notifications' requested by ':1.1383' (uid=1000 pid=32654 comm="notify-send running notify-send from mate-terminal")
May 27 22:01:19 aquos dbus-daemon[1425]: [session uid=1000 pid=1425] Successfully activated service 'org.freedesktop.Notifications'

[tofurky]

i keep seeing this so decided to take a look at what my session dbus has in memory using gcore:

root@aquos:~# gcore 1532
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f3af4313b77 in epoll_wait (epfd=4, events=0x7fff2f343fc0, maxevents=64, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
30	../sysdeps/unix/sysv/linux/epoll_wait.c: No such file or directory.
warning: target file /proc/1532/cmdline contained unexpected null characters
Saved corefile core.1532
root@aquos:~# strings core.1532 |sort|uniq -c|sort -nr|head
  50466 ca.desrt.dconf.Writer
  50465 /ca/desrt/dconf/Writer/user
  49997 /org/mate/terminal/global/
  14136 Writer/u1
   8218 al/globa1
   3731 DBus
   1134 BXIV
   1115 iXIV
   1102 (XIV
   1099 kXIV

so, maybe something to do with dconf?

[tofurky]

okay, i found the commit(s):

matt@aquos:~/devel/mate/mate-terminal$ git blame -L 2991,2991 -L 2924,2924 src/terminal-window.c
294ce367 (Pablo Barciela 2017-12-26 01:37:17 +0100 2924)     settings = g_settings_new ("org.mate.terminal.global");
7ebc9d18 (Pablo Barciela 2017-11-10 00:40:58 +0100 2991)     settings = g_settings_new ("org.mate.terminal.global"); 

the commit which introduced the g_settings_new leak for every keystroke is 7ebc9d1 "add the abbility to switch tabs using [ctrl+tab] and [ctrl+shift+tab]"

294ce36 is probably leaking to a lesser extent as well, but i haven't tested it.

this newly added callback is invoked for every keypress which then creates a new handle to org.mate.terminal.global, which matches up with the memory dump i took of dbus-daemon. i confirmed this is the cause by reverting 7ebc9d1 and recompiling. i had a root terminal open like so, and was able to see the leak happening in real-time. pid 1532 here is my session dbus instance.

watch -n1 "gcore 1532 >>/dev/null 2>&1 ; strings core.1532| sort|uniq -c|sort -nr|head; rm core.1532"

@sc0w should maybe the GSettingsObject be cached between callback invocations and/or this commit otherwise refactored?

since ctrl+page up/page down already worked to switch tabs, should that same mechanism be used here or is there something i'm missing? it seems there must be a more efficient way to do this than entering that callback on every keypress, regardless of if it's leaking memory or not.

[sc0w]

how to reproduce this issue step by step?

where is that logs?

I can't see that with journalctl -f using mate-terminal 1.20.0 and pressing keys

[tofurky]

@sc0w by default on at least ubuntu, there is a setting in /usr/share/dbus-1/session.conf
<limit name="max_match_rules_per_connection">50000</limit>
since mate-terminal now leaks a dbus connection/match rule for every keystroke after that commit, it becomes evident after 50,000 keystrokes.

if you wanted to trigger it sooner for debugging purposes, obviously you could lower 50000 to another number. i gave a watch command in my previous post that lets you see the leak in real-time.

i looked further into how all the other key shortcuts are done. they are defined in terminal-accels.c. i think any other keyboard shortcuts should be added to that existing framework, including this one. that way we're not wasting cpu cycles setting up (and tearing down, if the leak was fixed) a dbus connection with every keystroke.

i'm not sure if there's an existing place in the codebase to handle mouse clicks, but if so i think 294ce36 should be migrated to use that as well, since it is also leaking.

[cryobry]

Same issue.

I tried the simple fix of adding ctrl-tab to the accelerator configuration, and of course that didn't work because something (gtk? vte?) is eating the modifier. After poking around I think that @sc0w's implementation is close to being the only feasible way of implementing this. Caching the setting value is probably the best option here.

[sc0w]

Please test #241