[Nut-upsdev] Need to Preserve Driver Startup Log (stderr) in Syslog

[Tom Li]

On Fri, Jan 22, 2021 at 05:55:48PM -0500, Rob Crittenden wrote:
> On 1/22/21 3:52 PM, Tom Li via Nut-upsdev wrote:
> > What is your suggestion to solve the problem [0]?
> > 
> > My proposed solution is:
> > 
> > diff --git a/drivers/main.c b/drivers/main.c
> > index 788c5fd0..87e3cf4c 100644
> > --- a/drivers/main.c
> > +++ b/drivers/main.c
> > @@ -686,6 +686,14 @@ int main(int argc, char **argv)
> >          dstate_setinfo("driver.version.internal", "%s", upsdrv_info.version);
> >          dstate_setinfo("driver.name", "%s", progname);
> > +       /*
> > +        * If we are not debugging, send the early startup logs generated by
> > +        * upsdrv_initinfo() and upsdrv_updateinfo() to both stderr (already
> > +        * doing it) and syslog.
> > +        */
> > +       if ( (nut_debug_level == 0) && (!dump_data) )
> > +               syslogbit_set();
> > +
> >          /* get the base data established before allowing connections */
> >          upsdrv_initinfo();
> >          upsdrv_updateinfo();
> > 
> > Is it an acceptable patch?
> > 
> > Thanks,
> > Tom Li
> > 
> > [0] BTW, my first thought was to patch the code and fork() earlier,
> > before upsdrv_updateinfo() is called. However, a series of checks
> > for "battery.charge" and "battery.runtime" follows right after it,
> > which may cause EXIT_FAILURE errors - those logs should be visible
> > in stderr. So a patch to simply moving fork() up is not acceptable.
> 
> How about checking for a tty. No tty == syslog. Then running from the cli
> will give nice output but running from a service will log.
> 
> rob

It doesn't work. When the init script starts the driver, the initial output
is written to the system console, which is a tty, even if nobody can see it
on a server (as I said, on a traditional init+sylog *nix server, there's no
systemd to help you rebinding and catching it, and because our driver already
daemonize itself, there is no additional daemonization in the init script to
close the tty for us).

Also, running the driver in debug mode and redirecting stdout/stderr to a file
is common during troubleshooting. If we switch between stderr/syslog using
isatty(), the debug log is unexpectedly sent to syslog instead, so we still
need to check the debug flags first - so the patch to implement your and my
proposal is practically the same one. Another option is not to touch stderr,
keep it as-is, and only to decide whether to use syslog. But we don't fork in
debug mode, and a non-daemon should not spam the syslog. So we still need to
check the debug flags. So in the end, I think what matters is the debug flag,
not the output.

To elaborate: The behavior of the existing driver framework is that:
regardless of whether it's started from a tty or a script, it forks to the
background and writes to syslog (with the exception of the startup message).
Unless we are debugging ("nut_debug_level" or "dump_data"), stay at the
foreground, and send logs from stderr. 

1. By default, upslogx() writes to stderr
2. Do driver initialization
3. If we are not debugging:
   - fork to the background
   - turn off stderr and turn on syslog
4. Otherwise, don't fork and keep writing to stderr

So effectively, debug flags are our "do not fork" flag. The well understood
syslog policy is - fork = syslog, nofork = nosyslog. Our problem now is that
driver initialization occurs before forking. My proposed patch is to turn
on syslog a bit earlier if we know we are going to fork anyway.

Cheers,
Tom Li