<div dir="auto"><div><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Mon, Feb 7, 2022, 19:43 Wols Lists <<a href="mailto:antlists@youngman.org.uk">antlists@youngman.org.uk</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">On 07/02/2022 14:06, Mantas Mikulėnas wrote:<br>
> On Mon, Feb 7, 2022 at 2:54 PM Wols Lists <<a href="mailto:antlists@youngman.org.uk" target="_blank" rel="noreferrer">antlists@youngman.org.uk</a> <br>
> <mailto:<a href="mailto:antlists@youngman.org.uk" target="_blank" rel="noreferrer">antlists@youngman.org.uk</a>>> wrote:<br>
> <br>
> Bear in mind I did have a malformed scarletdme.service file, it was<br>
> missing "Type=forking", but it shouldn't be bringing down unrelated<br>
> services, should it?<br>
> <br>
> This is the output from dovecot, which clearly failed to start on<br>
> boot...<br>
> <br>
> thewolery /dev # systemctl status dovecot<br>
> × dovecot.service - Dovecot IMAP/POP3 email server<br>
> Loaded: loaded (/lib/systemd/system/dovecot.service; enabled;<br>
> vendor preset: disabled)<br>
> Active: failed (Result: exit-code) since Mon 2022-02-07 07:55:11<br>
> GMT; 3min 53s ago<br>
> Docs: man:dovecot(1)<br>
> <a href="https://doc.dovecot.org/" rel="noreferrer noreferrer" target="_blank">https://doc.dovecot.org/</a> <<a href="https://doc.dovecot.org/" rel="noreferrer noreferrer" target="_blank">https://doc.dovecot.org/</a>><br>
> Process: 1511 ExecStart=/usr/sbin/dovecot -F (code=killed,<br>
> signal=TERM)<br>
> Process: 1529 ExecStop=/usr/bin/doveadm stop (code=exited,<br>
> status=75)<br>
> Main PID: 1511 (code=killed, signal=TERM)<br>
> CPU: 22ms<br>
> <br>
> Feb 07 07:55:09 thewolery systemd[1]: Started Dovecot IMAP/POP3 email<br>
> server.<br>
> Feb 07 07:55:11 thewolery doveadm[1529]: Fatal: Dovecot is not running<br>
> (read from /run/dovecot/ma><br>
> Feb 07 07:55:11 thewolery systemd[1]: dovecot.service: Control process<br>
> exited, code=exited, statu><br>
> Feb 07 07:55:11 thewolery systemd[1]: dovecot.service: Failed with<br>
> result 'exit-code'.<br>
> thewolery /dev # systemctl restart dovecot<br>
> <br>
> But both samba and sshd failed similarly. I have vague recollections<br>
> somewhere of seeing a reference to qm in either the sshd or samba<br>
> output<br>
> pre-restart, but don't know how to get back to it. (qm is the program<br>
> started by scarletdme.service.)<br>
> <br>
> Any ideas, anybody suspect it might be a bug in systemd? I've fixed the<br>
> scarletdme.service, but it's a bit weird that it's the first time I<br>
> booted with the broken .service, and three (at least) other services<br>
> failed. Although my system does seem to have stability problems, so I<br>
> don't know for certain where to place any blame.<br>
> <br>
> <br>
> Have you checked the whole `journalctl -b` for messages that happened <br>
> around the actual failure? Could be just about anything, from services <br>
> getting stopped due to their dependencies failing, to something missing <br>
> due to *lack of* dependencies, to OOM killing random processes...<br>
> <br>
eb 07 07:55:09 thewolery systemd[1]: Reached target Socket Units.<br>
Feb 07 07:55:09 thewolery systemd[1]: Reached target Basic System.<br>
Feb 07 07:55:09 thewolery systemd[1]: Condition check resulted in <br>
Save/Restore Sound Card State being skipped.<br>
Feb 07 07:55:09 thewolery systemd[1]: Condition check resulted in Manage <br>
Sound Card State (restore and store) being skipped.<br>
Feb 07 07:55:09 thewolery systemd[1]: Reached target Sound Card.<br>
Feb 07 07:55:09 thewolery systemd[1]: Started D-Bus System Message Bus.<br>
Feb 07 07:55:09 thewolery systemd[1]: Started Dovecot IMAP/POP3 email <br>
server.<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Postfix Mail Transport <br>
Agent...<br>
Feb 07 07:55:09 thewolery systemd[1]: Started ScarletDME service start.<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Samba SMB Daemon...<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting OpenSSH server daemon...<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting User Login Management...<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Permit User Sessions...<br>
Feb 07 07:55:09 thewolery systemd[1]: Finished Permit User Sessions.<br>
Feb 07 07:55:09 thewolery qm[1513]: ScarletDME (64 Bit) has been started<br>
Feb 07 07:55:09 thewolery systemd-journald[1105]: Journal stopped<br>
Feb 07 07:55:10 thewolery systemd-journald[1105]: Received SIGTERM from <br>
PID 1521 (qm).<br></blockquote></div></div><div dir="auto"><br></div><div dir="auto">Well that's interesting.</div><div dir="auto"><br></div><div dir="auto">Looks like the 'qm' service here randomly killed systemd-journald – this alone can cause several problems, as many services' stdout goes to journald, so killing it would cause many services to get -EPIPE as soon as they log a message.</div><div dir="auto"><br></div><div dir="auto"><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Feb 07 07:55:09 thewolery systemd[1]: Started Dovecot IMAP/POP3 email <br>
server.<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Postfix Mail Transport <br>
Agent...<br>
Feb 07 07:55:09 thewolery systemd[1]: Started ScarletDME service start.<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Samba SMB Daemon...<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting OpenSSH server daemon...<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting User Login Management...<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Permit User Sessions...<br>
Feb 07 07:55:09 thewolery systemd[1]: Finished Permit User Sessions.<br>
Feb 07 07:55:09 thewolery qm[1513]: ScarletDME (64 Bit) has been started<br>
Feb 07 07:55:09 thewolery systemd-journald[1105]: Journal stopped<br>
Feb 07 07:55:10 thewolery systemd-journald[1105]: Received SIGTERM from <br>
PID 1521 (qm).<br></blockquote></div></div><div dir="auto"><br></div><div dir="auto">It does that again.</div><div dir="auto"><br></div><div dir="auto"><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Feb 07 07:55:10 thewolery systemd[1]: systemd-journald.service: <br>
Scheduled restart job, restart counter is at 1.<br>
Feb 07 07:55:10 thewolery systemd[1]: Stopped Journal Service.<br>
Feb 07 07:55:10 thewolery systemd[1]: Starting Journal Service...<br>
Feb 07 07:55:10 thewolery systemd-journald[1539]: Journal started<br>
Feb 07 07:55:10 thewolery systemd-journald[1539]: System Journal <br>
(/var/log/journal/053db4036a25efc6f8d2186a603c3f79) is 768.4M, m>Feb 07 <br>
07:55:09 thewolery systemd[1]: dbus.service: Deactivated successfully.<br>
Feb 07 07:55:09 thewolery lvm[1285]: dmeventd detected break while being <br>
idle for 1644220509 second(s), exiting.<br>
Feb 07 07:55:09 thewolery systemd[1]: smb.service: Failed with result <br>
'protocol'.<br></blockquote></div></div><div dir="auto"><br></div><div dir="auto">I'm not sure what happened here, but it *could* be that it died due to the journald stdout pipe being broken (which happens when the receiving end, i.e. journald, dies).</div><div dir="auto"><br></div><div dir="auto"><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Feb 07 07:55:09 thewolery lvm[1285]: dmeventd shutting down.<br>
Feb 07 07:55:09 thewolery systemd[1]: Failed to start Samba SMB Daemon.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: You have a memory leak (not <br>
released memory pool):<br>
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Deactivated <br>
successfully.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018000c40] library<br>
Feb 07 07:55:10 thewolery systemd[1]: Started Journal Service.<br>
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Consumed <br>
1.986s CPU time.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x55a9444f6ed0] command<br>
Feb 07 07:55:09 thewolery systemd[1]: sshd.service: Control process <br>
exited, code=killed, status=15/TERM</blockquote></div></div><div dir="auto"><br></div><div dir="auto">Given previous messages, I'm strongly suspecting that qm killed this one, too.</div><div dir="auto"><br></div><div dir="auto"><br></div><div dir="auto"><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018004470] pending_delete<br>
Feb 07 07:55:09 thewolery systemd[1]: sshd.service: Failed with result <br>
'signal'.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f70180044c0] config<br>
Feb 07 07:55:09 thewolery systemd[1]: Failed to start OpenSSH server daemon.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018004600] config<br>
Feb 07 07:55:09 thewolery systemd[1]: systemd-logind.service: <br>
Deactivated successfully.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018004650] config<br>
Feb 07 07:55:09 thewolery systemd[1]: Started User Login Management.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018024c00] dev_cache<br>
Feb 07 07:55:09 thewolery systemd[1]: scarletdme.service: Deactivated <br>
successfully.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018028ee0] text_orphan<br>
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Scheduled <br>
restart job, restart counter is at 1.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f701802d0e0] format_instance<br>
Feb 07 07:55:09 thewolery systemd[1]: systemd-logind.service: Scheduled <br>
restart job, restart counter is at 1.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f701802fd10] sysfs<br>
Feb 07 07:55:09 thewolery systemd[1]: Started D-Bus System Message Bus.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018030400] filter regex<br>
Feb 07 07:55:09 thewolery systemd[1]: Stopped User Login Management.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7018034460] mirror_dso<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Load Kernel Module drm...<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f701803a680] snapshot_state<br>
Feb 07 07:55:09 thewolery systemd[1]: Stopped Rule-based Manager for <br>
Device Events and Files.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7010000c40] snapshot_state<br>
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Consumed <br>
1.986s CPU time.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7014000c40] snapshot_state<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting Rule-based Manager for <br>
Device Events and Files...<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: [0x7f7008000c40] snapshot_state<br>
Feb 07 07:55:09 thewolery systemd[1]: modprobe@drm.service: Deactivated <br>
successfully.<br>
Feb 07 07:55:09 thewolery dmeventd[1285]: Internal error: Unreleased <br>
memory pool(s) found.<br>
Feb 07 07:55:09 thewolery systemd[1]: Finished Load Kernel Module drm.<br>
Feb 07 07:55:09 thewolery systemd[1]: Starting User Login Management...<br>
Feb 07 07:55:09 thewolery systemd[1]: Started Rule-based Manager for <br>
Device Events and Files.<br>
Feb 07 07:55:10 thewolery systemd-logind[1528]: New seat seat0.<br></blockquote></div></div><div dir="auto"><br></div><div dir="auto">Basically you have *a lot* of service daemons getting killed – some of them restart cleanly, others not – and it looks a bit like scarletdme is the one doing it. It even looks like it ended up killing itself, too.</div><div dir="auto"><br></div><div dir="auto">Some of the errors seem unrelated, e.g. dmeventd's complaints are probably just fallout of unclean restarts.</div><div dir="auto"><br></div><div dir="auto"><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
Nothing obvious before that - a couple of lines in yellow that I ought <br>
to investigate, but dunno why they'd be a problem ...<br>
<br>
Trouble is, I'm not used to debugging dodgy systems, and I've only just <br>
started using systemd seeing as I run gentoo, and that's not its default...<br>
<br>
Cheers,<br>
Wol<br>
</blockquote></div></div></div>