Bug#852229: failing to log output at boot time

[Christian Hofstaedtler]

* 積丹尼 Dan Jacobson <jidanni at jidanni.org> [170122 18:13]:
> Package: systemd
> Version: 232-12
> 
> As you see in Bug#852194, systemd is failing to log its output at boot time.

It's hard to understand which message you're exactly refering to,
but I've found some weirdness:

I've made systemd-modules-load.service fail (echo athingthatdoesnotexist >> /etc/modules),
and in 232-13, there is indeed this message in the journal:

    Jan 22 19:21:00 sxl systemd[1]: Listening on Journal Socket.
    Jan 22 19:21:00 sxl systemd-journald[302]: Journal started
    Jan 22 19:21:00 sxl systemd-journald[302]: Runtime journal (/run/log/journal/48e9d21e953d4a28860cd5e78cddae4c) is 0B, max 0B, 0B free.
    Jan 22 19:21:00 sxl systemd-modules-load[303]: Failed to find module 'athingthatdoesnotexist'

Previously this was longer, indicating that systemd-modules-load.service
failed to start. (I saw the extra messages when running stretch with 232-8,
but downgrading systemd, systemd-sysv, libsystemd0 to 232-8 does not
make the messages reappear.)
Messages as appearing in syslog, previously:
    Jan 22 19:12:46 sxl systemd-modules-load[309]: Failed to find module 'athingthatdoesnotexist'
    Jan 22 19:12:46 sxl systemd[1]: systemd-modules-load.service: Main process exited, code=exited, status=1/FAILURE
    Jan 22 19:12:46 sxl systemd[1]: Failed to start Load Kernel Modules.
    Jan 22 19:12:46 sxl systemd[1]: systemd-modules-load.service: Unit entered failed state.
    Jan 22 19:12:46 sxl systemd[1]: systemd-modules-load.service: Failed with result 'exit-code'.


Also, with 232-13, systemctl status does not show the error that's
present in the journal:

    root at sxl:~# date ; systemctl status systemd-modules-load.service
    Sun Jan 22 19:25:41 CET 2017
    ● systemd-modules-load.service - Load Kernel Modules
       Loaded: loaded (/lib/systemd/system/systemd-modules-load.service; static; vendor preset: enabled)
       Active: failed (Result: exit-code) since Sun 2017-01-22 19:21:00 CET; 4min 41s ago
         Docs: man:systemd-modules-load.service(8)
               man:modules-load.d(5)
     Main PID: 303 (code=exited, status=1/FAILURE)
    
    Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

If the error happens after boot, status works as expected:

    root at sxl:~# systemctl stop systemd-modules-load.service
    root at sxl:~# systemctl start systemd-modules-load.service
    Job for systemd-modules-load.service failed because the control process exited with error code.
    See "systemctl status systemd-modules-load.service" and "journalctl -xe" for details.
    root at sxl:~# systemctl status systemd-modules-load.service
    ● systemd-modules-load.service - Load Kernel Modules
       Loaded: loaded (/lib/systemd/system/systemd-modules-load.service; static; vendor preset: enabled)
       Active: failed (Result: exit-code) since Sun 2017-01-22 19:29:18 CET; 2s ago
         Docs: man:systemd-modules-load.service(8)
               man:modules-load.d(5)
      Process: 1306 ExecStart=/lib/systemd/systemd-modules-load (code=exited, status=1/FAILURE)
     Main PID: 1306 (code=exited, status=1/FAILURE)
    
    Jan 22 19:29:18 sxl systemd[1]: Starting Load Kernel Modules...
    Jan 22 19:29:18 sxl systemd[1]: systemd-modules-load.service: Main process exited, code=exited, status=1/FAILURE
    Jan 22 19:29:18 sxl systemd[1]: Failed to start Load Kernel Modules.
    Jan 22 19:29:18 sxl systemd[1]: systemd-modules-load.service: Unit entered failed state.
    Jan 22 19:29:18 sxl systemd[1]: systemd-modules-load.service: Failed with result 'exit-code'.

So, wild guess... race condition between journald starting and services starting just after it?

-ch (puzzled)