[Nut-upsuser] Upssched 100% CPU after updating Debian 12

[Jim Klimov]

FWIW, I wonder if this is a fallout of PR #1274 :
https://github.com/networkupstools/nut/pull/1274/files
and specifically
https://github.com/networkupstools/nut/commit/550064930e369fb3a322c3b28ffff8b4acf53532
which added a `sock_read()` loop continuation effectively if `pconf_char()`
returned 0.

Just grasping at straws here (since it is a change a couple of months
before the release was cut), because if ALL of those 128 reads (skipped
above) did return 0, we should not have got to this line.

The comment added here "*O_NDELAY with zero bytes means nothing to read but
since read() follows a successful select() with ready file descriptor, ret
shouldn't be 0*" - that might be misleading too, since per internet:

> The result of O_nonblock and O_ndelay is to make I/O into non-blocking
mode (non-blocking), return immediately without reading the data or the
write buffer full, without blocking the wait.
>
> The difference is that, in a read operation, if the data is not read,
O_ndelay causes the I/O function to return 0 immediately, but this gives
rise to a problem, because the read to the end of the file (EOF) is
returned 0, so it is impossible to distinguish between the cases.
Therefore, O_nonblock is generated, it will return 1 when the data is not
read, and set errno to Eagain.
>
> O_ndelay was introduced in earlier versions of System V, and when coding,
it is recommended that POSIX-defined o_nonblock,o_nonblock be set at open
and Fcntl.

Jim




On Tue, Jun 13, 2023 at 10:41 AM Jim Klimov <jimklimov+nut at gmail.com> wrote:

> Thanks for the interesting puzzle to crunch!
>
> Looking at these few bread-crumbs, I wager an educated guess that this
> loops in `sendcmd()` (where CLI child processes talk to a daemonized copy
> which tracks the timers for events), around here:
> https://github.com/networkupstools/nut/blob/v2.8.0/clients/upssched.c#L583-L626
> for the daemon and here for the child:
> https://github.com/networkupstools/nut/blob/v2.8.0/clients/upssched.c#L762-L787
>
> In both cases we run an infinite loop with `select()` to wait up to 1
> second and `read()` from the pipe. The common expectation is that if there
> is nothing to read, the program blocks in `select()` waiting for a reply
> from the kernel, and only returns after the specified timeout - to the
> point that some `sleep()` with sub-second precision implementations do just
> that on systems that lack `usleep()`.
>
> With `select()` in your capture posting an array of FDs `[7 10]` I'd say
> it is the parent loop, and one of those is the `pipefd` and another is the
> FD for socket connection to talk to a particular child on the other side of
> the pipe.
>
> Here I must guess that either the `pselect6()` implementation behaves
> differently which would be surprising after decades worth of expected
> behavior, or that it for some reason decides that the FD #7 (whoever that
> is) raised the hand but was then silent (0 bytes read).
>
> The next clue is 128 reads, which leads to
> https://github.com/networkupstools/nut/blob/v2.8.0/clients/upssched.c#L485
> `sock_read()` method which indeed does up to `US_MAX_READ==128` attempts to
> read one byte from a connection (so from the CLI/child counterpart) at a
> time - so that is who FD#7 gotta be.
>
> So it is just at this point that I get stuck explaining what happens and
> why :) Possibly there was a child or CLI counterpart process which died and
> somehow the connection did not get closed (which would return a `read()`
> error and evict it from the conn list), e.g. frozen/zombified, or something
> else connected to the pipe (antivirus heh?) and loiters there, or something
> else I could not think of quickly...
>
> The next clue could be to look at who is connected to the pipe file, maybe
> with `fuser`, or look in `ps -ef` if there are other `upssched` processes
> present, or look in `/proc/PIDNUM/fd/` of the daemonized and looping
> `upssched`...
>
> If anyone decides to track through the code, the potential processing loop
> goes
>     checkconf -> conf_arg -> parse_at -> sendcmd -> daemon if needed ->
> start_daemon -> conn_add(pipefd) or sock_read(conn)
> with short-lived child processes (command-line launched from `upsmon`)
> parsing the configuration to pick the part relevant to them per envvars,
> and talk to the daemon (fork one if needed) to start/cancel the timers.
>
> Jim
>
> On Tue, Jun 13, 2023 at 8:33 AM Kari Lempiäinen <
> kari.lempiainen at summerday.net> wrote:
>
>> Hi,
>>
>> I ran the strace command while upssched was 100% CPU hungry. This is what
>> I got:
>>
>> 1686633611.702798 read(7, "", 1)        = 0 <0.000004>
>> 1686633611.702816 read(7, "", 1)        = 0 <0.000004>
>> 1686633611.702834 pselect6(11, [7 10], NULL, NULL, {tv_sec=1, tv_nsec=0},
>> NULL) = 1 (in [7], left {tv_sec=0, tv_nsec=999998800}) <0.000006>
>> 1686633611.702862 read(7, "", 1)        = 0 <0.000004>
>> 1686633611.702880 read(7, "", 1)        = 0 <0.000004>
>> .
>> .
>> .
>> 1686633611.705206 read(7, "", 1)        = 0 <0.000004>
>> 1686633611.705224 read(7, "", 1)        = 0 <0.000004>
>> 1686633611.705242 pselect6(11, [7 10], NULL, NULL, {tv_sec=1, tv_nsec=0},
>> NULL) = 1 (in [7], left {tv_sec=0, tv_nsec=999999204}) <0.000005>
>> 1686633611.705268 read(7, "", 1)        = 0 <0.000004>
>> 1686633611.705288 read(7, "", 1)        = 0 <0.000302>
>>
>> there are 128 "read(7" lines between every pselect6 lines (I did count
>> the read lines for couple of blocks, 128 in each of them). Nothing else in
>> the strace log, just read and pselect lines for the short time I let strace
>> to run.
>>
>> Any help from this?
>>
>> Best regards,
>> Kari
>> ------------------------------
>>
>> *<more history snapped>*
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://alioth-lists.debian.net/pipermail/nut-upsuser/attachments/20230613/77dc9849/attachment-0001.htm>