Nut upsdev - Jan 2021 - Need to Preserve Driver Startup Log (stderr) in Syslog

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.

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