Shepherd redirect stdout/stderr to syslog

Shepherd redirect stdout/stderr to syslog

[David Craven]

Hi,

I'm having difficulties debugging a service that logs it's output to
tty1. I can't scroll the output - so the debug messages aren't very
useful. Is redirecting stdout/stderr to syslog something that
make-forkexec-constructor could/should do? Or is there already a way
to get the output I'm not aware of?

Thanks!
David

Re: Shepherd redirect stdout/stderr to syslog

[David Craven]

> Is redirecting stdout/stderr to syslog something that
> make-forkexec-constructor could/should do?

I looked into what would be involved. I included a diff that I didn't
test and don't expect to work.

The reason why I don't expect this to work is that running echo
"hello" > /dev/log errors. stracing logger "hello" shows that it makes
use of the socket and sendmsg syscalls instead of the usual open and
write syscalls. I don't understand why though, since what's the point
of everything being a file if they don't share the same interface?

diff --git a/modules/shepherd/service.scm b/modules/shepherd/service.scm
index 49f6e8b..69c1cc2 100644
--- a/modules/shepherd/service.scm
+++ b/modules/shepherd/service.scm
@@ -712,12 +712,18 @@ false."

      ;; Close all the file descriptors except stdout and stderr.
      (let ((max-fd (max-file-descriptors)))
+       ;; Redirect stdin to use /dev/null
        (catch-system-error (close-fdes 0))
-
        ;; Make sure file descriptor zero is used, so we don't end up reusing
        ;; it for something unrelated, which can confuse some packages.
        (dup2 (open-fdes "/dev/null" O_RDONLY) 0)

+       ;; Redirect stout and stderr to use /dev/log
+       (catch-system-error (close-fdes 1))
+       (catch-system-error (close-fdes 2))
+       (dup2 (open-fdes "/dev/log" O_WRONLY) 1)
+       (dup2 (open-fdes "/dev/log" O_WRONLY) 2)
+
        (let loop ((i 3))
          (when (< i max-fd)
            (catch-system-error (close-fdes i))

Re: Shepherd redirect stdout/stderr to syslog

[Ludovic Courtès]

David Craven <david@craven.ch> skribis:

>> Is redirecting stdout/stderr to syslog something that
>> make-forkexec-constructor could/should do?
>
> I looked into what would be involved. I included a diff that I didn't
> test and don't expect to work.
>
> The reason why I don't expect this to work is that running echo
> "hello" > /dev/log errors. stracing logger "hello" shows that it makes
> use of the socket and sendmsg syscalls instead of the usual open and
> write syscalls. I don't understand why though, since what's the point
> of everything being a file if they don't share the same interface?

The important thing is the special format, which includes the date:

  sendto(3, "<13>Sep  5 23:09:51 ludo: foo", 29, 0, NULL, 0) = 29

misc/syslog.c:193 in glibc implements this.

So we would need to pipe each daemon’s stdout/stderr to the Shepherd
itself, which would select(2) on all these, prepend the right prefix,
and write that to /dev/log, I think.

Ludo’.

[PATCH] service: Honor #:log-file in make-forkexec-constructor.

[David Craven]

* modules/shepherd/service.scm (exec-command): Redirect stdout and
  stderr to log-file.
  (fork+exec-command): Pass log-file to exec-command.
  (make-forkexec-constructor): Cleanup log-file. Pass log-file to
  fork+exec-command.
* doc/shepherd.texi (@deffn): Update documentation.
---
 doc/shepherd.texi            |  5 +++++
 modules/shepherd/service.scm | 43 ++++++++++++++++++++++++++++++++++---------
 2 files changed, 39 insertions(+), 9 deletions(-)

diff --git a/doc/shepherd.texi b/doc/shepherd.texi
index edb2039..d7ce3fe 100644
--- a/doc/shepherd.texi
+++ b/doc/shepherd.texi
@@ -835,6 +835,7 @@ execution of the @var{command} was successful, @code{#t} if not.
   [#:user #f] @
   [#:group #f] @
   [#:pid-file #f] @
+  [#:log-file #f] @
   [#:directory (default-service-directory)] @
   [#:environment-variables (default-environment-variables)]
 Return a procedure that forks a child process, closes all file
@@ -848,6 +849,10 @@ the procedure will be the PID of the child process.
 When @var{pid-file} is true, it must be the name of a PID file
 associated with the process being launched; the return value is the PID
 read from that file, once that file has been created.
+
+When @var{log-file} is true, it must be the name of a file. The file will
+be removed if it exists and the services stdout and stderr will be
+redirected to it.
 @end deffn
 
 @deffn {procedure} make-kill-destructor [@var{signal}]
diff --git a/modules/shepherd/service.scm b/modules/shepherd/service.scm
index 49f6e8b..d3fb348 100644
--- a/modules/shepherd/service.scm
+++ b/modules/shepherd/service.scm
@@ -687,6 +687,7 @@ number that was read (a PID)."
                        #:key
                        (user #f)
                        (group #f)
+                       (log-file #f)
                        (directory (default-service-directory))
                        (environment-variables (default-environment-variables)))
   "Run COMMAND as the current process from DIRECTORY, and with
@@ -712,12 +713,27 @@ false."
 
      ;; Close all the file descriptors except stdout and stderr.
      (let ((max-fd (max-file-descriptors)))
-       (catch-system-error (close-fdes 0))
 
+       ;; Redirect stdin to use /dev/null
+       (catch-system-error (close-fdes 0))
        ;; Make sure file descriptor zero is used, so we don't end up reusing
        ;; it for something unrelated, which can confuse some packages.
        (dup2 (open-fdes "/dev/null" O_RDONLY) 0)
 
+       (when log-file
+         (catch #t
+           (lambda ()
+             ;; Redirect stout and stderr to use LOG-FILE.
+             (catch-system-error (close-fdes 1))
+             (catch-system-error (close-fdes 2))
+             (dup2 (open-fdes log-file (logior O_CREAT O_WRONLY)) 1)
+             (dup2 (open-fdes log-file (logior O_CREAT O_WRONLY)) 2))
+           (lambda (key . args)
+             (format (current-error-port)
+                     "failed to open log-file ~s:~%" log-file)
+             (print-exception (current-error-port) #f key args)
+             (primitive-exit 1))))
+
        (let loop ((i 3))
          (when (< i max-fd)
            (catch-system-error (close-fdes i))
@@ -760,6 +776,7 @@ false."
                             #:key
                             (user #f)
                             (group #f)
+                            (log-file #f)
                             (directory (default-service-directory))
                             (environment-variables
                              (default-environment-variables)))
@@ -770,6 +787,7 @@ its PID."
         (exec-command command
                       #:user user
                       #:group group
+                      #:log-file log-file
                       #:directory directory
                       #:environment-variables environment-variables)
         pid)))
@@ -798,24 +816,31 @@ once that file has been created."
                (group #f)
                (directory (default-service-directory))
                (environment-variables (default-environment-variables))
-               (pid-file #f))
+               (pid-file #f)
+               (log-file #f))
       (let ((command (if (string? command)
                          (begin
                            (warn-deprecated-form)
                            (list command))
                          command)))
         (lambda args
-          (when pid-file
-            (catch 'system-error
-              (lambda ()
-                (delete-file pid-file))
-              (lambda args
-                (unless (= ENOENT (system-error-errno args))
-                  (apply throw args)))))
+          (define (clean-up file)
+            (when file
+              (catch 'system-error
+                (lambda ()
+                  (delete-file file))
+                (lambda args
+                  (unless (= ENOENT (system-error-errno args))
+                    (apply throw args))))))
+
+          (clean-up pid-file)
+          (clean-up log-file)
 
           (let ((pid (fork+exec-command command
+
                                         #:user user
                                         #:group group
+                                        #:log-file log-file
                                         #:directory directory
                                         #:environment-variables
                                         environment-variables)))
-- 
2.9.0

Re: [PATCH] service: Honor #:log-file in make-forkexec-constructor.

[David Craven]

Not syslog, but helps with debugging...

Re: [PATCH] service: Honor #:log-file in make-forkexec-constructor.

[Danny Milosavljevic]

On Tue, 6 Sep 2016 14:36:35 +0200
David Craven <david@craven.ch> wrote:

> Not syslog, but helps with debugging...

That definitely helps - however, in the long run, I think that using syslog is better. Syslog does the splitting up in different files (or not) and onto different machines (or not), filtering (or not), log rotation etc. So it makes sense to make services use syslog instead of rolling-your-own filtering, splitting, networking etcetc 267843 times. That said the services should just use syslog on their own - we could only guess when a new log message starts.

I checked out the syslog wire format - it's not difficult. The only thing to keep in mind is that the local sockets wants a NUL terminator (if it's a stream socket) but a network node doesn't (makes sense - the network thing is UDP packets and the message is just one packet long). I think always including it doesn't hurt.
The prefix is (facility << 3) | priority in angle brackets.

https://www.gnu.org/software/anubis/manual/html_section/anubis_11.html seems to already support syslog, maybe we can copy it from there.

https://netkiller.github.io/python/library/syslog.html small public domain implementation of syslog client in Python.

https://tools.ietf.org/html/rfc5424#section-6.1 lists message length limits.

Or we could pipe the output to "logger" from inetutils.

Re: [PATCH] service: Honor #:log-file in make-forkexec-constructor.

[David Craven]

>> Not syslog, but helps with debugging...

> That definitely helps - however, in the long run, I think that using syslog is better.

I agree, but someone has to write it...

> Syslog does the splitting up in different files (or not) and onto different machines
> (or not), filtering (or not), log rotation etc. So it makes sense to make services
> use syslog instead of rolling-your-own filtering, splitting, networking etcetc 267843
> times.

I don't intend to reimplement any of this. I just needed a way to dump
stuff to a file instead of a tty. It's intended for usage during
development of services, not for deployment. As Ludo mentioned it's
not quite as simple as just redirecting stdout/sderr and needs some
support in shepherd. Someone who actually runs services that require
high availability will have to contribute better logging support ;)

> That said the services should just use syslog on their own

Many services expect stdout/stderr to be handled. I don't think that
every service needs to reimplement basic logging functionality.
systemd allows to set a services stdout and stderr to either
journal/syslog/file/tty, so new services written for systemd expect
this to be taken care of.

> we could only guess when a new log message starts

New lines are a pretty good guess.

Re: [PATCH] service: Honor #:log-file in make-forkexec-constructor.

[Ludovic Courtès]

David Craven <david@craven.ch> skribis:

> * modules/shepherd/service.scm (exec-command): Redirect stdout and
>   stderr to log-file.
>   (fork+exec-command): Pass log-file to exec-command.
>   (make-forkexec-constructor): Cleanup log-file. Pass log-file to
>   fork+exec-command.
> * doc/shepherd.texi (@deffn): Update documentation.

Pushed, thanks!

Ludo’.