Bug#762700: systemd: journald fails to forward most boot messages to syslog

[Christian Seiler]

I did some more tests on this and there is one key thing that I
misunderstood: SO_SNDBUF of the socket that is used to send the
datagrams is used as a limit in the kernel, not of the socket syslog
uses to receive them.

I actually tried setting SendBuffer=1 and ReceiveBuffer=1 on
syslog.socket (to set the buffers to just 1 byte, so no message should
get through) and it didn't change a thing.

Thus, setting SendBuffer=8M on syslog.socket will have no effect. It
has to be set on the socket used to forward the data from the journal.
This is actually mentioned in the upstream commit that was referenced
in this bug report, I just didn't understand it at first. And
fortunately, journald reuses the /dev/log socket for forwarding the
syslog messages, to one can easily just set it on that one. And
indeed, playing around with on systemd-journald-dev-log.socket's
SendBuffer DOES have an impact.

Finally, the service I posted before has a slight problem, since it
doesn't take into account that in some container setups, /proc/sys
might be readonly. Therefore,
ConditionPathIsReadWrite=/proc/sys/net/unix/max_dgram_qlen should be
added, to make sure the value can be changed before attempting it.




To summarize my views on this bug:

  - RATIONALE: this bug breaks syslog compared to sysvinit at boot and
    under some circumstances.

       ** For the boot process: I do NOT say this because some early-
          boot messages get discarded, those weren't available before
          anyway.

    However, a lot of services are ordered after $syslog (sysvinit) or
    with DefaultDependencies (which implies that logging is available),
    so the boot messages of THOSE services should be recorded by
    syslog (and were under sysvinit). Since they are now started in
    parallel to the syslog daemon (no explicit ordering anymore,
    because the presence of the socket and the journal (should) imply
    working logging in a systemd world), since the syslog daemon takes
    a bit of time to initialize, and since during that time the socket
    datagram queue is full (there are typically more than 11 early-boot
    messages that fill up the initial queue), some of the log messages
    of those services can get lost (and will under any Jessie
    installation I've tested), although they are not under sysvinit
    (because of explicit ordering after the syslog daemon).

    Also, under certain circumstances (the original reporter of this
    bug has confirmed this), with a limit of just 11 datagrams, the
    queue could fill up after boot sometimes. I personally have only
    managed to reproduce this under extreme circumstances so far, but
    I haven't tried using NetworkManager yet (as suggested).

  - SOLUTION (mostly the same as before, but SendBuffer is set on a
    different unit and a Condition is added to the service):

       1. Increase max_dgram_qlen to a reasonable value. The easiest
          way is via a systemd service:

          /lib/systemd/system/systemd-setup-dgram-qlen.service:
          [Unit]
          DefaultDependencies=no
          Before=syslog.socket
          ConditionPathIsReadWrite=/proc/sys/net/unix/max_dgram_qlen

          [Service]
          Type=oneshot
          ExecStart=/sbin/sysctl -w net.unix.max_dgram_qlen=512
          StandardOutput=null

          Add the following to /lib/systemd/systemd/syslog.socket:
          Wants=systemd-setup-dgram-qlen.service

       2. Make it even more robust by applying the patch from upstream
          to increase the send buffer on the socket journald uses to
          forward syslog messages, i.e. add
          SendBuffer=8M
          to /lib/systemd/system/systemd-journald-dev-log.socket
          (NOT syslog.socket!)

(As said before, the values 512 and 8M are debatable, although 8M is
typically used within systemd's source code, so it's probably a good
value to use. 512 seems like a reasonable compromise to me: typically,
up to ~ 100 boot messages will be generated before syslog is started
on systems I've tried this on, so using something that's 5x higher
seems like a good safety net without increasing this to crazy high
numbers. Note that the 8M limit will apply independently.)

I've been using this on a Jessie system for the past couple of days
(well, drop-ins in /etc, actually), and I didn't notice any
side-effects so far.

Christian