[systemd-devel] Odd behaviour on boot

Mon Feb 7 17:43:39 UTC 2022

On 07/02/2022 14:06, Mantas Mikulėnas wrote:
> On Mon, Feb 7, 2022 at 2:54 PM Wols Lists <antlists at youngman.org.uk 
> <mailto:antlists at youngman.org.uk>> wrote:
> 
>     Bear in mind I did have a malformed scarletdme.service file, it was
>     missing "Type=forking", but it shouldn't be bringing down unrelated
>     services, should it?
> 
>     This is the output from dovecot, which clearly failed to start on
>     boot...
> 
>     thewolery /dev # systemctl status dovecot
>     × dovecot.service - Dovecot IMAP/POP3 email server
>            Loaded: loaded (/lib/systemd/system/dovecot.service; enabled;
>     vendor preset: disabled)
>            Active: failed (Result: exit-code) since Mon 2022-02-07 07:55:11
>     GMT; 3min 53s ago
>              Docs: man:dovecot(1)
>     https://doc.dovecot.org/ <https://doc.dovecot.org/>
>           Process: 1511 ExecStart=/usr/sbin/dovecot -F (code=killed,
>     signal=TERM)
>           Process: 1529 ExecStop=/usr/bin/doveadm stop (code=exited,
>     status=75)
>          Main PID: 1511 (code=killed, signal=TERM)
>               CPU: 22ms
> 
>     Feb 07 07:55:09 thewolery systemd[1]: Started Dovecot IMAP/POP3 email
>     server.
>     Feb 07 07:55:11 thewolery doveadm[1529]: Fatal: Dovecot is not running
>     (read from /run/dovecot/ma>
>     Feb 07 07:55:11 thewolery systemd[1]: dovecot.service: Control process
>     exited, code=exited, statu>
>     Feb 07 07:55:11 thewolery systemd[1]: dovecot.service: Failed with
>     result 'exit-code'.
>     thewolery /dev # systemctl restart dovecot
> 
>     But both samba and sshd failed similarly. I have vague recollections
>     somewhere of seeing a reference to qm in either the sshd or samba
>     output
>     pre-restart, but don't know how to get back to it. (qm is the program
>     started by scarletdme.service.)
> 
>     Any ideas, anybody suspect it might be a bug in systemd? I've fixed the
>     scarletdme.service, but it's a bit weird that it's the first time I
>     booted with the broken .service, and three (at least) other services
>     failed. Although my system does seem to have stability problems, so I
>     don't know for certain where to place any blame.
> 
> 
> Have you checked the whole `journalctl -b` for messages that happened 
> around the actual failure? Could be just about anything, from services 
> getting stopped due to their dependencies failing, to something missing 
> due to *lack of* dependencies, to OOM killing random processes...
> 
eb 07 07:55:09 thewolery systemd[1]: Reached target Socket Units.
Feb 07 07:55:09 thewolery systemd[1]: Reached target Basic System.
Feb 07 07:55:09 thewolery systemd[1]: Condition check resulted in 
Save/Restore Sound Card State being skipped.
Feb 07 07:55:09 thewolery systemd[1]: Condition check resulted in Manage 
Sound Card State (restore and store) being skipped.
Feb 07 07:55:09 thewolery systemd[1]: Reached target Sound Card.
Feb 07 07:55:09 thewolery systemd[1]: Started D-Bus System Message Bus.
Feb 07 07:55:09 thewolery systemd[1]: Started Dovecot IMAP/POP3 email 
server.
Feb 07 07:55:09 thewolery systemd[1]: Starting Postfix Mail Transport 
Agent...
Feb 07 07:55:09 thewolery systemd[1]: Started ScarletDME service start.
Feb 07 07:55:09 thewolery systemd[1]: Starting Samba SMB Daemon...
Feb 07 07:55:09 thewolery systemd[1]: Starting OpenSSH server daemon...
Feb 07 07:55:09 thewolery systemd[1]: Starting User Login Management...
Feb 07 07:55:09 thewolery systemd[1]: Starting Permit User Sessions...
Feb 07 07:55:09 thewolery systemd[1]: Finished Permit User Sessions.
Feb 07 07:55:09 thewolery qm[1513]: ScarletDME (64 Bit) has been started
Feb 07 07:55:09 thewolery systemd-journald[1105]: Journal stopped
Feb 07 07:55:10 thewolery systemd-journald[1105]: Received SIGTERM from 
PID 1521 (qm).
Feb 07 07:55:09 thewolery systemd[1]: Started Dovecot IMAP/POP3 email 
server.
Feb 07 07:55:09 thewolery systemd[1]: Starting Postfix Mail Transport 
Agent...
Feb 07 07:55:09 thewolery systemd[1]: Started ScarletDME service start.
Feb 07 07:55:09 thewolery systemd[1]: Starting Samba SMB Daemon...
Feb 07 07:55:09 thewolery systemd[1]: Starting OpenSSH server daemon...
Feb 07 07:55:09 thewolery systemd[1]: Starting User Login Management...
Feb 07 07:55:09 thewolery systemd[1]: Starting Permit User Sessions...
Feb 07 07:55:09 thewolery systemd[1]: Finished Permit User Sessions.
Feb 07 07:55:09 thewolery qm[1513]: ScarletDME (64 Bit) has been started
Feb 07 07:55:09 thewolery systemd-journald[1105]: Journal stopped
Feb 07 07:55:10 thewolery systemd-journald[1105]: Received SIGTERM from 
PID 1521 (qm).
Feb 07 07:55:10 thewolery systemd[1]: systemd-journald.service: 
Scheduled restart job, restart counter is at 1.
Feb 07 07:55:10 thewolery systemd[1]: Stopped Journal Service.
Feb 07 07:55:10 thewolery systemd[1]: Starting Journal Service...
Feb 07 07:55:10 thewolery systemd-journald[1539]: Journal started
Feb 07 07:55:10 thewolery systemd-journald[1539]: System Journal 
(/var/log/journal/053db4036a25efc6f8d2186a603c3f79) is 768.4M, m>Feb 07 
07:55:09 thewolery systemd[1]: dbus.service: Deactivated successfully.
Feb 07 07:55:09 thewolery lvm[1285]: dmeventd detected break while being 
idle for 1644220509 second(s), exiting.
Feb 07 07:55:09 thewolery systemd[1]: smb.service: Failed with result 
'protocol'.
Feb 07 07:55:09 thewolery lvm[1285]: dmeventd shutting down.
Feb 07 07:55:09 thewolery systemd[1]: Failed to start Samba SMB Daemon.
Feb 07 07:55:09 thewolery dmeventd[1285]: You have a memory leak (not 
released memory pool):
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Deactivated 
successfully.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018000c40] library
Feb 07 07:55:10 thewolery systemd[1]: Started Journal Service.
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Consumed 
1.986s CPU time.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x55a9444f6ed0] command
Feb 07 07:55:09 thewolery systemd[1]: sshd.service: Control process 
exited, code=killed, status=15/TERM
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018004470] pending_delete
Feb 07 07:55:09 thewolery systemd[1]: sshd.service: Failed with result 
'signal'.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f70180044c0] config
Feb 07 07:55:09 thewolery systemd[1]: Failed to start OpenSSH server daemon.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018004600] config
Feb 07 07:55:09 thewolery systemd[1]: systemd-logind.service: 
Deactivated successfully.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018004650] config
Feb 07 07:55:09 thewolery systemd[1]: Started User Login Management.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018024c00] dev_cache
Feb 07 07:55:09 thewolery systemd[1]: scarletdme.service: Deactivated 
successfully.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018028ee0] text_orphan
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Scheduled 
restart job, restart counter is at 1.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f701802d0e0] format_instance
Feb 07 07:55:09 thewolery systemd[1]: systemd-logind.service: Scheduled 
restart job, restart counter is at 1.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f701802fd10] sysfs
Feb 07 07:55:09 thewolery systemd[1]: Started D-Bus System Message Bus.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018030400] filter regex
Feb 07 07:55:09 thewolery systemd[1]: Stopped User Login Management.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7018034460] mirror_dso
Feb 07 07:55:09 thewolery systemd[1]: Starting Load Kernel Module drm...
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f701803a680] snapshot_state
Feb 07 07:55:09 thewolery systemd[1]: Stopped Rule-based Manager for 
Device Events and Files.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7010000c40] snapshot_state
Feb 07 07:55:09 thewolery systemd[1]: systemd-udevd.service: Consumed 
1.986s CPU time.
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7014000c40] snapshot_state
Feb 07 07:55:09 thewolery systemd[1]: Starting Rule-based Manager for 
Device Events and Files...
Feb 07 07:55:09 thewolery dmeventd[1285]:  [0x7f7008000c40] snapshot_state
Feb 07 07:55:09 thewolery systemd[1]: modprobe at drm.service: Deactivated 
successfully.
Feb 07 07:55:09 thewolery dmeventd[1285]: Internal error: Unreleased 
memory pool(s) found.
Feb 07 07:55:09 thewolery systemd[1]: Finished Load Kernel Module drm.
Feb 07 07:55:09 thewolery systemd[1]: Starting User Login Management...
Feb 07 07:55:09 thewolery systemd[1]: Started Rule-based Manager for 
Device Events and Files.
Feb 07 07:55:10 thewolery systemd-logind[1528]: New seat seat0.

Nothing obvious before that - a couple of lines in yellow that I ought 
to investigate, but dunno why they'd be a problem ...

Trouble is, I'm not used to debugging dodgy systems, and I've only just 
started using systemd seeing as I run gentoo, and that's not its default...

Cheers,
Wol