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

[Rob Crittenden]

On 1/22/21 3:52 PM, Tom Li via Nut-upsdev wrote:
> Hello everyone.
> 
> If you follow GitHub, you would know that I'm working on a NUT
> driver for my Huawei UPS2000. The driver is almost completed.
> But while developing the driver, I've noticed a frustrating
> syslog problem that may confuse the user. I seriously need to
> hear your suggestions.
> 
> When a NUT driver is started (by upsdrvctl start), like many
> other Unix programs, it runs the following sequence:
> 
> 1. Run as a foreground process.
> 2. Do some basic initialization, log to stderr.
> 3. fork()
> 4. Run as a daemon, redirect log to syslog.
> 
> This is reasonable and standard. The problem, however, is that
> upsdrv_initinfo() and upsdrv_updateinfo() are first called before
> forking, as a result, the log messages is only sent to stderr,
> not syslog. On a traditional server setup (i.e. an init script
> calls upsdrvctl, a syslog daemon collects logs, and unattended
> boot, like my FreeBSD server), those startup messages are lost.
> 
> However, those lost messages can be urgent - For example, in my
> driver, if the UPS inverter has failed, I set an alarm word and
> also log a detailed error message using upslogx(). However, if the
> alarm is raised just after the server is freshly started, the log
> is sent to stderr instead and lost. The admin may either miss the
> error until much later, or keep staring at the mysterious alarm
> word without finding anything relevant in syslog. Similarly, I
> think logging other errors, such as invalid config values, is
> also needed.
> 
> So far, my solution is to maintain a "first call" flag in the
> function upsdrv_updateinfo() - if it's the 1st call, I assume
> the log is sent to stdout and lost, so the log is not suppressed.
> During the 2nd call, the previous messages are relogged, so
> that they can show in the syslog. But it's rather convoluted
> and inelegant. I'd like to see it solved at upslogx()'s level.
> 
> 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