enable non-blocking reads for streaming outputs

[lexming]

This fixes an issue with EB5 on our cluster, running installs with --logtostdout hangs after executing /usr/share/lmod/lmod/libexec/lmod python --terse --show-hidden avail in the early stages. However, same installs without --logtostdout go fine. An manually executing that lmod command also works fine.

Issue seems to be with long/slow commands in streaming mode. The reading action on the output hinders the completion of the command. This PR enables read in non-blocking mode to avoid this issue.

Changelog:

• use same non-blockig mechanism for streaming and QA command runs
• replace fix reads at 128 bytes with readline: this does not change functionality as 128 bytes is a (longish) line and this improves readability of logs
• ensure that last piece of output is printed in logs

[lexming]

@branfosj do not merge yet, there is a minor issue to fix. Now the output looks like:

== 2025-02-06 15:35:33,429 run.py:555 DEBUG Obtained more stdout: b''
== 2025-02-06 15:35:33,932 run.py:555 DEBUG Obtained more stdout: b''
== 2025-02-06 15:35:34,032 run.py:555 DEBUG Obtained more stdout: b''
== 2025-02-06 15:35:34,133 run.py:555 DEBUG Obtained more stdout: b'INFO: gcc: numpy/core/src/multiarray/datetime_busdaycal.c\n'
== 2025-02-06 15:35:34,133 run.py:555 DEBUG Obtained more stdout: b''
== 2025-02-06 15:35:34,233 run.py:555 DEBUG Obtained more stdout: b''
== 2025-02-06 15:35:34,334 run.py:555 DEBUG Obtained more stdout: b''

== 2025-02-06 15:35:34,944 run.py:555 DEBUG Obtained more stdout: b'INFO: gcc: numpy/core/src/multiarray/descriptor.c\n'
== 2025-02-06 15:35:34,944 run.py:555 DEBUG Obtained more stdout: b''
== 2025-02-06 15:35:35,044 run.py:555 DEBUG Obtained more stdout: b'INFO: gcc: numpy/core/src/multiarray/dlpack.c\n'
== 2025-02-06 15:35:35,045 run.py:555 DEBUG Obtained more stdout: b''
== 2025-02-06 15:35:35,147 run.py:555 DEBUG Obtained more stdout: b''

possible issue

[lexming]

@branfosj if all test pas, this is ready. Now the debug logs are properly formatted:

== 2025-02-07 01:41:14,654 run.py:530 DEBUG Captured stdout: INFO: gcc: numpy/core/src/multiarray/datetime_busdaycal.c
== 2025-02-07 01:41:15,756 run.py:530 DEBUG Captured stdout: INFO: gcc: numpy/core/src/multiarray/descriptor.c
== 2025-02-07 01:41:17,359 run.py:530 DEBUG Captured stdout: INFO: gcc: numpy/core/src/multiarray/dlpack.c
== 2025-02-07 01:41:17,660 run.py:530 DEBUG Captured stdout: INFO: gcc: numpy/core/src/multiarray/dtypemeta.c
== 2025-02-07 01:41:18,061 run.py:530 DEBUG Captured stdout: INFO: gcc: numpy/core/src/multiarray/dragon4.c
== 2025-02-07 01:41:19,564 run.py:530 DEBUG Captured stdout: INFO: gcc: numpy/core/src/multiarray/dtype_transfer.c

[lexming]

On a side note, this PR also removes the following print message:

print_msg(f"(streaming) output for command '{cmd_str}':")

AFAICT this is a leftover from 4.9 that does not align with the behavior of run_shell_cmd in 5.0. run_shell_cmd in 5.0.x is not streaming anything to output. It reads stdout dynamically in blocks of 128 bytes, but those are gathered into an output variable which is only printed once and in full.