Dbus-daemon high memory

General
1

I just installed octopi the other day, and I've noticed that dbus-daemon slowly increases in memory until eventually it starts swapping, and eventually OOM killer takes action. I tried running dbus-monitor, but it didn't really show anything useful. Has anyone else seen this and/or know what could be causing it?

Here's dbus-monitor output. I let it run for a minute before ^C. The two messages listed show immediately, and then nothing:

root@octoprint:~# dbus-monitor 
signal time=1572051303.143484 sender=org.freedesktop.DBus -> destination=:1.0 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.0"
signal time=1572051303.143624 sender=org.freedesktop.DBus -> destination=:1.0 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.0"
^C
root@octoprint:~#

root@octoprint:~# ps aux --sort '-%mem' | head
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
message+   366  0.7 40.9 373436 366872 ?       Ss   Oct25   3:34 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
pi         454  1.6  7.5 233728 68016 ?        Sl   Oct25   8:05 /home/pi/oprint/bin/python2 /home/pi/oprint/bin/octoprint serve --host=127.0.0.1 --port=5000
haproxy    601  0.0  1.0  11852  9316 ?        S    Oct25   0:00 /usr/sbin/haproxy-master
haproxy    602  0.0  0.7  11852  6580 ?        Ss   Oct25   0:12 /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /run/haproxy.pid -Ds
root         1  0.5  0.6  28136  6092 ?        Ss   Oct25   2:47 /sbin/init
root     26221  0.0  0.6  11660  5804 ?        Ss   00:36   0:00 sshd: root@pts/0
root       604  0.0  0.5  10208  5332 ?        Ss   Oct25   0:00 /usr/sbin/sshd -D
root       104  0.0  0.5  26248  5252 ?        Ss   Oct25   0:02 /lib/systemd/systemd-journald
root     26225  0.0  0.5   9188  4608 ?        Ss   00:36   0:00 /lib/systemd/systemd --user
root@octoprint:~#
2

dbus is a messaging provider and a bit like sockets perhaps. It's typically used for program-to-program communication. Presumably a pair of applications aren't configured correctly. You might look for errors in the octoprint.log. You'd especially try to run in safe mode to compare/contrast.

3

This was from a stock octopi install, with no plugins installed. I restarted in safemode, but dbus-daemon is still taking up 50% of memory (and slowly climbing). The only thing I see that's of warning/error level is a bunch of these:

root@octoprint:/home/pi/.octoprint/logs# tail -n 20 octoprint.log
2019-10-26 23:51:18,094 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 17.33ms
2019-10-26 23:51:18,112 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 8.82ms
2019-10-26 23:51:18,130 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 9.00ms
2019-10-26 23:51:18,148 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 9.22ms
2019-10-26 23:51:25,036 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 16.81ms
2019-10-26 23:51:25,065 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 16.73ms
2019-10-26 23:51:49,026 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 11.25ms
2019-10-26 23:51:49,042 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 8.87ms
2019-10-26 23:51:49,065 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 13.61ms
2019-10-26 23:51:49,124 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 17.57ms
2019-10-26 23:51:49,153 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 16.73ms
2019-10-26 23:51:56,039 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 20.10ms
2019-10-26 23:51:56,067 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 17.12ms
2019-10-26 23:52:20,028 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 16.71ms
2019-10-26 23:52:20,057 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 17.44ms
2019-10-26 23:52:20,111 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 9.79ms
2019-10-26 23:52:20,131 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 10.67ms
2019-10-26 23:52:20,151 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 8.98ms
2019-10-26 23:52:27,036 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 8.87ms
2019-10-26 23:52:27,054 - tornado.access - WARNING - 409 GET /api/printer (::ffff:192.168.10.54) 8.83ms
root@octoprint:/home/pi/.octoprint/logs#
4

It sounds a lot like this to be honest. Visit here and search for 409 throughout.

Something thinks that your OctoPrint isn't connected to the printer at least in theory. Perhaps @foosel could weigh in here.

5

Common culprit of this at least in my household is the Home Assistant integration which will regularly poll the printer endpoint. I need to find the time to prep a PR at some point that switches said integration over to socket communication...

6

Also just for the record for the general topic here: OctoPrint itself does absolutely nothing via dbus. So safe mode cannot influence that.

I'd suggest to start digging in the system logs, maybe they contain a clue.

Also: What version of OctoPi?

7

Maybe the original poster would recognize the mentioned IP address as that of either their own workstation or something else on the network like a Home Assistant or similar.

8

I don't think that those log entries have anything at all to do with dbus running wild here though.

9

We do in fact have home assistant, and that IP address is the address of it. Though it's also running zabbix, which is monitoring it. However, I don't believe it's zabbix as I'm not seeing this issue anywhere else. I'll try shutting off home assistant's access to it and see if that resolves the issue.

root@octoprint:~# /home/pi/oprint/bin/octoprint --version
octoprint, version 1.3.12
root@octoprint:~#

I had just downloaded octopi a night or two before this started, 2018-11-13-octopi-stretch-lite-0.16.0.img and doing a system update after.

10

I've never seen this behaviour on a clean install of OctoPi of 0.16, I wonder if something in the system update went wrong or caused issues.

11

Honestly, my own Orbi router will promiscuously try to determine who-is-who from a hostname and capabilities standpoint. So if it exists on my network, Orbi has tried to repeatedly ask a somewhat innocent-yet-stupid question every minute, basically: who are you? It's querying a non-existent endpoint (which I forget). Perhaps yours is doing the same.

12

@foosel it's certainly possible. Based on an image from over a year ago, there was a lot to update. With the Home Assistant portion shut off, I'm not seeing the issue anymore, so it definitely seems to be something to do with the way that HA is interacting with octoprint.

@OutsourcedGuru I have Ubiquiti hardware here. It doesn't seem to be doing anything untoward on the network as far as this is concerned. But it's possible?

13

Looks like I spoke too soon. Woke up this morning to an alert that I had high memory usage on the octopi box. May attempt a re-build this weekend.

root@octoprint:~# ps aux --sort '-%mem' | head
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
message+   383  0.5 61.0 551568 546400 ?       Ss   Oct30   5:42 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
pi         464  0.9  7.3 239680 65864 ?        Sl   Oct30   9:19 /home/pi/oprint/bin/python2 /home/pi/oprint/bin/octoprint serve --host=127.0.0.1 --port=5000
haproxy    620  0.0  1.0  11852  9348 ?        S    Oct30   0:00 /usr/sbin/haproxy-master
haproxy    621  0.0  0.7  11852  6644 ?        Ss   Oct30   0:02 /usr/sbin/haproxy -f /etc/haproxy/haproxy.cfg -p /run/haproxy.pid -Ds
root         1  0.4  0.6  28000  6032 ?        Ss   Oct30   4:23 /sbin/init
root     32194  0.2  0.6  11528  5712 ?        Ss   12:43   0:00 sshd: ******** [priv]
root       113  0.0  0.6  12448  5492 ?        Ss   Oct30   0:02 /lib/systemd/systemd-journald
root       624  0.0  0.5  10208  5264 ?        Ss   Oct30   0:01 /usr/sbin/sshd -D
*******  32203  0.1  0.5   9656  5040 ?        Ss   12:43   0:00 /lib/systemd/systemd --user
root@octoprint:~#
14

My logs are absolutely full of this message - up to 5 times per second. It appears to be Home Assistant, but I have no idea why it would poll so frequently. Running both Home Assistant and OctoPrint in Docker on a NUC, so I guess it has a bit more horsepower than a Pi.

I had problems connecting to the printer this morning, so I'm going to have to rip out the Home Assistant integration, which is a shame.

1 Like