Page MenuHomePhabricator

Systemd restart loop of timer filled the disk on tegmen
Closed, ResolvedPublic

Description

Systemd started looping a restart of the update-etcd-mw-config-lastindex.service service, that is triggered by a systemd timer. The root cause is not clear but that filled the root partition due to syslog spam.

Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service failed to run 'start' task: Resource temporarily unavailable
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.
Jul 11 09:32:32 tegmen systemd[1]: Unit update-etcd-mw-config-lastindex.service entered failed state.
Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service failed to run 'start' task: Resource temporarily unavailable
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.

So far one of the proposal has been to try to move the timer to an on calendar event. Unsure if that might help. As of today we don't have a way to repro it, it has happened only once.

The Max concurrent service checks message logged has been fixed already, so not anymore an issue, and kinda unrelated to the real root cause here.

Original description

tegmen went down (T199318) and when I logged in to see what might have caused the crash I noticed that the root partition was full, there's a 32G syslog.1 file (daemon.log is also 30G) which is mostly filled with log lines like

Jul 11 07:06:54 tegmen icinga: #011Max concurrent service checks (6000) has been reached. Nudging (...)

For some reason this didn't occur on einsteinium. In T1242 the limit was raised from 3200 to 6000, maybe with increased checks we need to bump it again?

Event Timeline

Change 445375 had a related patch set uploaded (by Alexandros Kosiaris; owner: Alexandros Kosiaris):
[operations/puppet@production] icinga: Bump max_concurrent_checks to 10k

https://gerrit.wikimedia.org/r/445375

I've cleaned the 33G file so that the host could recover, I'm looking at the other overly big log files cause we'd had at least one fallout from that that is the update-etcd-mw-config-lastindex.service that on failure was trying to start in a loop.

Shortly after a puppet run, this was logged:

Jul 11 09:31:12 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:31:13 tegmen systemd[1]: Started Update the etcd last modified index for MediaWiki config.
Jul 11 09:31:52 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:31:53 tegmen systemd[1]: Started Update the etcd last modified index for MediaWiki config.
Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service failed to run 'start' task: Resource temporarily unavailable
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.
Jul 11 09:32:32 tegmen systemd[1]: Unit update-etcd-mw-config-lastindex.service entered failed state.
Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service failed to run 'start' task: Resource temporarily unavailable
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.
Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service failed to run 'start' task: Resource temporarily unavailable
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.
Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service failed to run 'start' task: Resource temporarily unavailable
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.
Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service failed to run 'start' task: Resource temporarily unavailable
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.
Jul 11 09:32:32 tegmen systemd[1]: Starting Update the etcd last modified index for MediaWiki config...
Jul 11 09:32:32 tegmen systemd[1]: update-etcd-mw-config-lastindex.service start request repeated too quickly, refusing to start.
Jul 11 09:32:32 tegmen systemd[1]: Failed to start Update the etcd last modified index for MediaWiki config.
[.... SNIP message repeated 93119893 times ....]

I didn't find the root cause of why the update-etcd-mw-config-lastindex.service started failing but it seems that was the cause of filling the disk and making the host unresponsive. After the reboot there was no more messages of this type.

I'll review the systemd unit file to make sure systemd cannot loop again at this frequency for the restarts.

I've saved a part of the 30GB daemon log into daemon.20180711.T199413.log. I'll follow up with changes for the systemd unit/timer.

Change 445375 merged by Alexandros Kosiaris:
[operations/puppet@production] icinga: Bump max_concurrent_checks to 10k

https://gerrit.wikimedia.org/r/445375

Volans renamed this task from Max concurrent service checks reached on tegmen to Systemd restart loop of timer filled the disk on tegmen.Sep 18 2018, 2:30 PM
Volans removed Volans as the assignee of this task.
Volans updated the task description. (Show Details)

Mentioned in SAL (#wikimedia-operations) [2018-10-05T09:16:22Z] <volans> rebooting tegmen, console stuck, possible re-occurrence of T199413 (to be confirmed)

Sorry, false alarm, it was unrelated.

Change 465197 had a related patch set uploaded (by Volans; owner: Volans):
[operations/puppet@production] etcd-config: add check for directory

https://gerrit.wikimedia.org/r/465197

Change 465197 merged by Volans:
[operations/puppet@production] etcd-config: add check for directory

https://gerrit.wikimedia.org/r/465197

Volans claimed this task.

This hasn't repro in months and we're moving to stretch on the Icinga hosts. Resolving for now, feel free to re-open if this happens again.