<div dir="ltr">To follow up: this did not fix the problem. </div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Oct 21, 2016 at 2:45 PM, Daniel Povey <span dir="ltr"><<a href="mailto:dpovey@gmail.com" target="_blank">dpovey@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div>I just want to follow up on this that I believe I have found the reason for this bug and I have a solution which I am testing out.</div><div><br></div><div>In the output of `systemctl status systemd-journald` it says:</div><div> Active: failed (Result: start-limit) <br></div><div>and this is related to the systemd mechanism to stop cycles where services keep restarting. It's related to the configs</div><div>StartLimitIntervalSec= [defaults to DefaultStartLimitIntervalSec=<wbr>10 sec by default]</div><div>StartLimitBurst= [defaults to DefaultStartLimitBurst=5 by default]<br></div><div><br></div><div>so that if a service is restarted 5 times within 10 seconds, it's not restarted any more to avoid wasting resources.</div><div>What seems to happen is that if systemd-journal-flush.service sends the signal SIGUSR1 to systemd-journald and systemd-journald wasn't ready to handle it for some reason (e.g. had just been started, or there was some hangup), then systemd-journald is restarted, and systemd-journal-flush.service immediately restarts also. Again systemd-journald won't be ready to handle the signal as it hasn't had time to run the signal handler, and the cycle repeats 5 times until the systemd-journald service hits the StartLimitBurst and dies. I verified using `lastcomm` (we have process accounting enabled) that this did in fact happen.</div><div><br></div><div>The way I am trying to fix it is to introduce a restart delay of 10 seconds into the systemd-journal-flush service. See the config file below; the only new line that differs from the defaults in /lib/systemd/system/systemd-<wbr>journal-flush.service is the line RestartSec=10. </div><div><br></div><div>Dan</div><div><br></div>
<div><br></div><div><br></div>======<br><div><div>cat /etc/systemd/system/systemd-<wbr>journal-flush.service</div><div># This file is part of systemd.</div><div>#</div><div># systemd is free software; you can redistribute it and/or modify it</div><div># under the terms of the GNU Lesser General Public License as published by</div><div># the Free Software Foundation; either version 2.1 of the License, or</div><div># (at your option) any later version.</div><div><br></div><div>[Unit]</div><div>Description=Trigger Flushing of Journal to Persistent Storage</div><div>Documentation=man:systemd-<wbr>journald.service(8) man:journald.conf(5)</div><div>DefaultDependencies=no</div><div>Requires=systemd-journald.<wbr>service</div><div>After=systemd-journald.service local-fs.target remote-fs.target</div><div>Before=systemd-user-sessions.<wbr>service</div><div># Don't re-start this service too often, or we can get into a cycle where</div><div># if this service was run just after systemd-journald was started, it</div><div># fails to handle the signal, causing that service to be restarted</div><div># and this servie to be immediately restarted also, until we hit</div><div># the limit of StartLimitBurst=5 restarts and systemd-journald</div><div># dies.</div><div>RestartSec=10</div><div><br></div><div>[Service]</div><div>ExecStart=/bin/systemctl kill --kill-who=main --signal=SIGUSR1 systemd-journald.service</div><div>Type=oneshot</div></div><div><br></div></div><div class="HOEnZb"><div class="h5"><div class="gmail_extra"><br><div class="gmail_quote">On Sat, Oct 15, 2016 at 9:48 PM, Daniel Povey <span dir="ltr"><<a href="mailto:dpovey@gmail.com" target="_blank">dpovey@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Another observation about this bug, which might be helpful.<div><br></div><div>If the signal is sent to systemd-journald via</div><div>/bin/systemctl kill --kill-who=main --signal=SIGUSR1 systemd-journald.service<br></div><div>then messages like the following show up in the kernel messages from `dmesg -T`, like:</div><div><br></div><div>[Sat Oct 15 21:02:35 2016] systemd-journald[26517]: Received request to flush runtime journal from PID 1<br></div><div><br></div><div>but they don't show up in the output of 'journalctl -r'. </div><div>In /etc/systemd/journald.conf<wbr>, it says:</div><div><br></div><div><div>#MaxLevelStore=debug<br></div><div>#MaxLevelSyslog=debug</div></div><div><br></div><div>so I would have thought the same messages would go to both places. </div><div>I don't know if I'm misunderstanding something here..</div><div><br></div><div>Dan</div><div><br></div><div><br></div><div><br></div><div><br></div></div><div class="m_4169527543777189301HOEnZb"><div class="m_4169527543777189301h5"><div class="gmail_extra"><br><div class="gmail_quote">On Sat, Oct 15, 2016 at 9:07 PM, Daniel Povey <span dir="ltr"><<a href="mailto:dpovey@gmail.com" target="_blank">dpovey@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">BTW, I attach the output from `systemd-analyze dump`, as dump.txt.<div>It would be great if the debian people could help us look into this.</div><div>Lennart has a policy that his team will only look into bug reports in the latest two versions of systemd, and obviously we are well behind that.</div><div><br></div><div>Dan</div><div><br></div></div><div class="m_4169527543777189301m_5673777638877430937HOEnZb"><div class="m_4169527543777189301m_5673777638877430937h5"><div class="gmail_extra"><br><div class="gmail_quote">On Sat, Oct 15, 2016 at 8:53 PM, Daniel Povey <span dir="ltr"><<a href="mailto:dpovey@gmail.com" target="_blank">dpovey@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><br><div>I just want to report that we are suffering from this bug, and it is quite frequent.</div><div>This is with version 215-17+deb8u5 .</div><div><br></div><div><p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)">root@a12:~# systemctl status systemd-journald</p>
<p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)"><span style="color:rgb(188,48,28)"><b>*</b></span> systemd-journald.service - Journal Service</p>
<p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)"> Loaded: loaded (/lib/systemd/system/systemd-j<wbr>ournald.service; static)</p>
<p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)"> Active: <span style="color:rgb(188,48,28)"><b>failed</b></span> (Result: start-limit) since Sat 2016-10-15 12:01:57 EDT; 8h ago</p>
<p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)"> Docs: man:systemd-journald.service(8<wbr>)</p>
<p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)"> man:journald.conf(5)</p>
<p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)"> Process: 51561 ExecStart=/lib/systemd/systemd<wbr>-journald <span style="color:rgb(188,48,28)"><b>(code=killed, signal=USR1)</b></span></p>
<p style="margin:0px;font-size:12px;line-height:normal;font-family:menlo;background-color:rgb(241,241,241)"> Main PID: 51561 (code=killed, signal=USR1)</p></div><div><br></div><div><br></div></div>
</blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>