Hi all, thanks for your time! Please let me know if this isn't the right
spot for this, or if I should file a bug.
I'm on debian buster, package versions for ones in question are:
systemd - 241-7~deb10u8
prometheus-node-exporter - 0.17.0+ds-3+b11
dbus - 1.12.20-0+deb10u1
pacemaker - 2.0.1-5+deb10u1
This has been a bit of a head scratcher for me and some others for some
time now. Quick environmental description; I have two-node clusters running
buster,
supporting pacemaker with some systemd and other typed resources, and
exporting metrics via prometheus-node-exporter.
There is also a service that once a minute, from the "active" node in the 2
node cluster, logs into the other node via rsync over ssh.
Bizarrely, with enough uptime systemd-logind, prometheus-node-exporter, and
pacemaker, will all start to log errors of the type:
"Failed to activate service
'org.freedesktop.systemd1'".
This of course causes pacemaker to snipe the "failed" node since the
resources there can no longer pass the status checks.
Uptime varies wildly between reproductions. Currently we've observed 5,
with uptimes of 45,48,62,81,100 days respectively. The only difference in
those incidents
is that the machine with an uptime of 48 days before it was hit was not
running any of the pacemaker resources. I'm going to include some of the
logs from this machine
in particular as it seems to be the most "pure" reproduction of the issue,
and is the only one that survived pacemaker's ire.
The first incidence of the error from systemd-logind:
Jul 31 19:50:50 nosferatu systemd-logind[4042]: New session 125887 of user
rsync-user.
Jul 31 19:50:50 nosferatu systemd-logind[4042]: Session 125887 logged out.
Waiting for processes to exit.
Jul 31 19:50:50 nosferatu systemd-logind[4042]: Removed session 125887.
Jul 31 19:51:50 nosferatu systemd-logind[4042]: New session 125889 of user
rsync-user.
Jul 31 19:51:51 nosferatu systemd-logind[4042]: Session 125889 logged out.
Waiting for processes to exit.
Jul 31 19:51:51 nosferatu systemd-logind[4042]: Removed session 125889.
Jul 31 19:52:52 nosferatu systemd-logind[4042]: Failed to start user
service 'user@999.service', ignoring: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Jul 31 19:53:17 nosferatu systemd-logind[4042]: Failed to start session
scope session-125891.scope: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Jul 31 19:53:42 nosferatu systemd-logind[4042]: Failed to stop user service
'user@999.service', ignoring: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Jul 31 19:54:07 nosferatu systemd-logind[4042]: Failed to start user
service 'user@999.service', ignoring: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Jul 31 19:54:32 nosferatu systemd-logind[4042]: Failed to start session
scope session-125892.scope: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Jul 31 19:54:57 nosferatu systemd-logind[4042]: Failed to stop user service
'user@999.service', ignoring: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)
Dbus-daemon logs a similar error:
Jun 20 12:45:01 nosferatu systemd[1]: Started D-Bus System Message Bus.
Jul 31 19:52:27 nosferatu dbus-daemon[4047]: [system] Failed to activate
service 'org.freedesktop.systemd1': timed out
(service_start_timeout=25000ms)
Prometheus-node-exporter reports the same:
Jun 20 12:45:01 nosferatu prometheus-node-exporter[4025]:
time="2022-06-20T09:45:01-07:00" level=info msg=" - vmstat"
source="node_exporter.go:104"
Jun 20 12:45:01 nosferatu prometheus-node-exporter[4025]:
time="2022-06-20T09:45:01-07:00" level=info msg=" - xfs"
source="node_exporter.go:104"
Jun 20 12:45:01 nosferatu prometheus-node-exporter[4025]:
time="2022-06-20T09:45:01-07:00" level=info msg=" - zfs"
source="node_exporter.go:104"
Jun 20 12:45:01 nosferatu prometheus-node-exporter[4025]:
time="2022-06-20T09:45:01-07:00" level=info msg="Listening on :9100"
source="node_exporter.go:170"
Jul 31 19:52:27 nosferatu prometheus-node-exporter[4025]:
time="2022-07-31T16:52:27-07:00" level=error msg="ERROR: systemd collector
failed after 0.351864s: couldn't get units: Failed to activate service
'org.freedesktop.systemd1': timed out (service_start_timeout=25000ms)"
source="collector.go:132"
>From the logs, it appears that prometheus-node-exporter is the first one to
hit the problem, and then is joined in a degraded waltz by systemd-logind
until 1 second after midnight, when;
Aug 01 00:00:01 nosferatu dbus-daemon[4047]: [system] Successfully
activated service 'org.freedesktop.systemd1'
Then after this, systemd-logind and prometheus-node-exporter stop failing
with the timeout message, but something interesting happens; systemd-logind
loses the ability to fully close
the new sessions being opened, and eventually the once-a-minute login
process causes the node to max out on user sessions.
You can sort of see this in the logs, since no longer are sessions removed
after the "Waiting for processes to exit message";
Aug 07 13:48:50 nosferatu systemd-logind[4042]: New session 136763 of user
rsync-user.
Aug 07 13:48:50 nosferatu systemd-logind[4042]: Session 136763 logged out.
Waiting for processes to exit.
Aug 07 13:49:50 nosferatu systemd-logind[4042]: New session 136764 of user
rsync-user.
Aug 07 13:49:50 nosferatu systemd-logind[4042]: Session 136764 logged out.
Waiting for processes to exit. <-8192 total user sessions active here
Aug 21 21:12:51 nosferatu systemd-logind[4042]: Power key pressed. <- When
I rebooted the machine over IPMI so I could log in :(
Aug 21 21:12:51 nosferatu systemd-logind[4042]: Powering Off...
I know from other instances that performing `start-stop-daemon --stop
--quiet --pidfile <PIDOFASERVICE>` causes systemd to reload with the same
message in dbus of
"Successfully activated service"..., so I imagine this resurrection
occurred due to some nightly service, though what exactly I cannot tell,
since logs had been rotated before I started to look at the system.
Of additional though maybe spurious interest is the fact that login
sessions increment oddly; scanning the logs, the session number goes up by
2 for every new connection,
except on the 10th connection or so, where it goes up by 3.
I have tried checking for session leaks with loginctl, bus connection leaks
with busctl, confirmed that the OOM killer wasn't active, confirmed that
CPU util was within reason,
and most other common-sense checks. The systems are otherwise healthy, and
so far this hasn't happened on the same machine twice.
As you may imagine, I'm thoroughly flummoxed by this issue, and insofar
I've been unable to reproduce it by doing things like increasing the
interval of the prometheus collector or the rsync service. Normally, I'd
just update
and presume that'd solve the issue, but without knowledge of *why *this
issue is occuring I'm hesitant to call anything a fix.
Does this ring any bells to anyone? Any known bugs I'm hitting here with
some subcomponent? Does anyone have any advice for useful debug steps that
could get me closer to a solution?
I've also got many, many, more logs available if there's anything that may
be of use.
Cheers, and thanks ever so much for your time and attention!
Christian
