[Nut-upsuser] Spurious messages on start

[Arjen de Korte]

>> Yes, this was what I tried first and it made no difference. upsdrvctl
>> seems to wait until the driver is fully initialized and only then goes
>> into the background.
> Looks like I hadn't tried it with a 30 second sleep. Putting a "sleep
> 30" between upsdrvctl and upsd also works so I guess the problem is
> there.

See below.

> Using -DDDDD on upsd seems to stop it from going in the background, so
> upsmon doesn't get to run. Since the problem seems to be between the
> driver and upsd that's probably ok.

Yes. I should have warned you for that (my apologies).

> /var/log/daemon.log shows this:
>
> Nov 16 00:48:46 ulisses newhidups[5196]: Startup successful
> Nov 16 00:48:46 ulisses upsd[5197]: /etc/nut/upsd.conf is world readable
> Nov 16 00:48:46 ulisses upsd[5197]: Connected to UPS [mge1200]:
> newhidups-auto
> Nov 16 00:48:46 ulisses upsd[5197]: /etc/nut/upsd.users is world readable
> Nov 16 00:48:55 ulisses upsd[5197]: Pinging UPS [mge1200]
> Nov 16 00:48:57 ulisses upsd[5197]: UPS [mge1200]: dump is done

This is indicative of where the problems lie. The dump should have
completed before pinging the driver. The fact that it didn't tells us that
the initial dump has either failed or took too long, which should have
prevented this in the first place.

> Nov 16 00:49:02 ulisses upsd[5197]: Got PONG from UPS [mge1200]
> Nov 16 00:49:10 ulisses upsd[5197]: Pinging UPS [mge1200]
> Nov 16 00:49:14 ulisses upsd[5197]: Got PONG from UPS [mge1200]
> Nov 16 00:49:22 ulisses upsd[5197]: Pinging UPS [mge1200]
> Nov 16 00:49:22 ulisses upsd[5197]: Got PONG from UPS [mge1200]
> Nov 16 00:49:30 ulisses upsd[5197]: Pinging UPS [mge1200]
> Nov 16 00:49:34 ulisses upsd[5197]: Got PONG from UPS [mge1200]
> Nov 16 00:49:42 ulisses upsd[5197]: Pinging UPS [mge1200]
> (...)
>
> And outputs on the command line:
>
> /etc/nut/upsd.conf is world readable
> Connected to UPS [mge1200]: newhidups-auto
> /etc/nut/upsd.users is world readable
> Network UPS Tools upsd 2.0.4
> Synchronizing........ giving up

You see, there it is. Apparently the initial dump takes more than the 15
seconds that are hardcoded in upsd. Or it may have failed alltogether.

> Pinging UPS [mge1200]
> UPS [mge1200]: dump is done

Similar as above, this is the 'wrong' order of things.

> Got PONG from UPS [mge1200]
> Pinging UPS [mge1200]
> Got PONG from UPS [mge1200]
> Pinging UPS [mge1200]
> (...)
>
> I guess the problem is that "Synchronizing..." step.

Indeed. Either the driver needs more time to dump all the data than is
allowed for in upsd or it could also be that the first connection to the
driver always fails. Since we first declare a driver stale before
(re)connecting, this will show a similar effect. I have fixed the latter
in the trunk (we now try to reconnect first), so you might want to check
out if this solves your problem. If not, we probably need to increase the
timeout for the synchronization in upsd to see if that fixes this.

Kind regards, Arjen