Re: shepherd logging

Re: shepherd logging

[Danny Milosavljevic]

Aaand it works on Linux - shepherd messages show up on the console and eventually
end up in syslog (I checked).  Integration is surprisingly easy and safe (shepherd
already does line buffering manually):

diff --git a/gnu/packages/admin.scm b/gnu/packages/admin.scm
index ccf62a6e2..168495c14 100644
--- a/gnu/packages/admin.scm
+++ b/gnu/packages/admin.scm
@@ -169,7 +169,15 @@ and provides a \"top-like\" mode (monitoring).")
               (patches (search-patches "shepherd-close-fds.patch"))))
     (build-system gnu-build-system)
     (arguments
-     '(#:configure-flags '("--localstatedir=/var")))
+     '(#:configure-flags '("--localstatedir=/var")
+       #:tests? #f ; I broke them, sorry
+       #:phases
+       (modify-phases %standard-phases
+        (add-after 'unpack 'patch-kmsg
+          (lambda _
+            (substitute* "modules/shepherd/support.scm"
+             (("%localstatedir \"/log/shepherd.log\"") "\"/dev/kmsg\""))
+            #t)))))
     (native-inputs
      `(("pkg-config" ,pkg-config)

Timestamp is printed twice, though (shepherd prints one, too).

$ cat /var/log/messages
[...]
Feb 16 23:01:58 localhost vmunix: [    9.178841] Console: switching to colour frame buffer device 160x50
Feb 16 23:01:58 localhost vmunix: [    9.198267] i915 0000:00:02.0: fb0: inteldrmfb frame buffer device
Feb 16 23:01:58 localhost vmunix: [    9.229274] 2018-02-16 23:01:32 Service udev has been started. <----- hellooooo
Feb 16 23:01:58 localhost vmunix: [   25.232541] NET: Registered protocol family 38

Note: 9.229274 is [Fr Feb 16 23:01:32 2018] (as checked by "dmesg -T"),
so syslogd is kinda off here.  Maybe they print the time of their /dev/kmsg
readout action... that would be weird.

Maybe this would remove the duplicate timestamp:

diff --git a/modules/shepherd/comm.scm b/modules/shepherd/comm.scm
index 0228f63..4048315 100644
--- a/modules/shepherd/comm.scm
+++ b/modules/shepherd/comm.scm
@@ -51,6 +51,7 @@
             start-logging
             stop-logging
             %current-client-socket
+            %current-logfile-date-format
             shepherd-output-port))
 
 ^L
@@ -200,6 +201,9 @@ on service '~a':")
   ;; Socket of the client currently talking to the daemon.
   (make-parameter #f))
 
+(define %current-logfile-date-format
+  (make-parameter default-logfile-date-format))
+
 ;; We provide our own output mechanism, because we have certain
 ;; special needs; most importantly, we want to send output to herd
 ;; sometimes.
@@ -228,7 +232,7 @@ on service '~a':")
             (let* ((log (lambda (x)
                           (display x log-output-port)))
                    (init-line (lambda ()
-                                (log (strftime "%Y-%m-%d %H:%M:%S "
+                                (log (strftime %current-logfile-date-format
                                                (localtime (current-time)))))))
               (init-line)
               (for-each log (reverse buffer))
diff --git a/modules/shepherd/support.scm b/modules/shepherd/support.scm
index bb01edc..0df97ea 100644
--- a/modules/shepherd/support.scm
+++ b/modules/shepherd/support.scm
@@ -285,6 +285,11 @@ TARGET should be a string representing a filepath + name."
       (string-append %localstatedir "/log/shepherd.log")
       (string-append %user-config-dir "/shepherd.log")))
 
+(define default-logfile-date-format
+   (if (zero? (getuid))
+       (format #f "[~d]: " (getpid))
+       "%Y-%m-%d %H:%M:%S "))
+
 ;; Configuration file.
 (define (default-config-file)
   "Return the default configuration file---either the user's file, or the

Doesn't work on the Hurd (even cat /dev/klog hangs the Hurd).

Re: shepherd logging; console-agetty-service

[Danny Milosavljevic]

Hi Ludo,

On Sat, 17 Feb 2018 17:20:06 +0100
ludo@gnu.org (Ludovic Courtès) wrote:

> Actually, could [shepherd] use syslog(3), which writes to /dev/log?

As far as I understand the meaning overload in Linux, there's these:

* syslog(2) - accesses the kernel log ringbuffer directly.
glibc (rightly) pretends this doesn't exist.
* /dev/kmsg - userspace access to read and write to the kernel
log ringbuffer.  It doesn't really work like a regular file.
If you write(2) to it, that gets interpreted as a *line*
of max length (1024 - 32) and this line gets added to the
ringbuffer as a new message.
Reading is weird too - but we won't use that directly.
* syslog(3) - actually writes to /dev/log, a socket, which is
usually listened to by a user-space process like syslogd.
No kernel involved anywhere (well, I guess the BSD socket
layer is involved...).

If shepherd used /dev/log in the beginning that would mean that
syslogd would have to be running before shepherd starts up.

So syslogd would have pid 1, I guess ;)

If we instead used /dev/kmsg, there would not really be a hard dependency.
Linux takes care that the messages are printed to the console
until a syslogd (maybe) appears, at which point syslogd will
log the already-printed (to /dev/kmsg) messages to its output files.

syslogd also fetches LATER messages from /dev/kmsg and
appends them to its output files likewise as time goes by.

So the UNIXy good-enough way would be for us to only use /dev/kmsg, the end :)

The complete way (which would avoid a hypothetical problem of overloading
the ringbuffer with messages so we would lose some of them) would be
to have shepherd start out using /dev/kmsg and switch over to using /dev/log
when it's there (maybe use inotify and watch until /dev/log appears).
Switch back to /dev/kmsg if /dev/log breaks again.

Also possible would be to have shepherd provide /dev/log to user services
and have shepherd proxy them to /dev/kmsg - that sounds like a real easy way
to get into a cycle if we aren't careful - although it would be conceptually
nicer.

In fact, the Linux kernel could have done that transparently.  They probably
just didn't like the failover handling involved :)

Also, I checked glibc misc/syslog.c vsyslog and they fall back to
/dev/console - disappointing.
They could have fallen back to /dev/kmsg ...

But then if syslogd crashed nobody would re-enable console logging and it wouldn't
be seen until syslogd started up again...  it's actually starting to get
complicated again :)

> > Also a way of capturing stderr and stdout (and maybe even /dev/log) of services
> > would be nice.  
> 
> Yes.  Though again capturing service stdout/stderr is kinda redundant
> with what syslogd does.  What I like in journald is the fact that it
> unifies all logging facilities, and also connects them to service
> management.

Yeah, its nice nowadays after one gets used to it.

In the end, it depends on whether one wants a system overview or a
service-by-service overview.

Older UNIX had lots of small programs working together in harmony to
achieve one task that the user cared about.

If you just watched the logs of one of them that wouldn't really help
that much because you'd not see the parts the other guys did.

And if you then watched *their* logs in an extra terminal or something
you've have to manually cobble together the timeline in your head to
make sense of what you are seeing.

Sometimes some of the services involved were on other machines.

So it was understandable that syslogd came to be a "global" thing
(sometimes on a central server only).

Nowadays with all the huge-ish services like dnsmasq which do
everything on their own (DNS, DHCP, TFTP, kitchensink) just checking
its log is enough.

Not sure how (or whether) to unify both use cases.

> Right, so we’d need shepherd to filter these and pass them through
> syslog(3), which ensures correct message formatting.  That’s what
> <https://cgit.freedesktop.org/systemd/systemd/tree/src/journal/journald-kmsg.c>
> does apparently (thanks for the link!).

Yeah.