log: Overhaul Windows Logger with Pipes and FHs by johnwparent · Pull Request #51791 · spack/spack

johnwparent · 2025-12-19T20:03:03Z

Redo how we handle IO direction for logging on Windows

Previous we closed sys.stdout, replaced it with a new buffer pointing at the logging file, and then dup2'd to redirect stdout. The logfile was then read from a thread, controlled by the main spack thread, and said reader thread forwarded on the logging context to main Spack's dup'd stdout.

This is deeply insufficient for a number of use cases:

It did not support filtering, unicode, control characters, or force_echo

All echo, including force_echo when supported, was racey, due to the disparate mechanisms by which reader thread behavior was controlled vs the context from which it obtained information. I.e. the reader thread could be killed or echo turned off, before any stdout buffers could be flushed (or whatever out-of-sync ordering) and the reader thread wouldn't see the log output it was supposed to echo prior to turning echo off or terminating.

Nested logging, or cached references to stdout and stderr were invalidated. Previously, on io redirection, we were closing stdout and replacing it with our new buffer. On io restoration, we were restored a buffer pointing at console stdout to sys.stdout, but any cached references to stdout (i.e. nested logging contexts or pytest) were invalidated.

Now we:

do not close whatever sys.stdout refers to, we mearly store a reference to it
do not construct a new buffer from python's api, instead we perform redirection from the ground up, starting with fhs to fds and compose a buffer from the existing fh's fd.
Use pipes for communication with our reader thread, which enables filtering, control characters, etc and allows for non racey echo behavior.

At a glance:

Redirects IO starting at the Windows file handle (fh) level
Properly maps fhs to fds, and obtains the appropriate buffer wrapping each
Enables proper subprocess io redirection inheritance
Manages shared file handles between stderr and stdout on redirect
Properly redirects IO at each level of handling, kernel, C, and python
Ensures cached references to console streams are not invalidated
Ensures correct order of release for buffers -> fhs

Moves toward a unified logging class by introducing fundamental support
for the concepts leveraged by the non Windows logger classes like pipes

Also enabled logging testing for Windows

Adds a test for nested logging context managers.

Redo how we handle IO direction for logging on Windows Previous we closed sys.stdout, replaced it with a new buffer pointing at the logging file, and then dup2'd to redirect stdout. The logfile was then read from a thread, controlled by the main spack thread, and said thread forwarded on the logging context to main Spack's dup'd stdout. This is deeply insufficient for a number of use cases: It did not support filtering, unicode, control characters, or force_echo All echo, including force_echo if it did support, was racey, due to the disparate mechanism for which the reader thread had to control thread behavior vs where it was obtaining information. I.e. the reader thread could be killed or echo turned off from pyhon, before any stdout buffers could be flushed and the reader thread wouldn't see the log output it was supposed to echo before turning echo off or terminating. Nested logging, or cached references to stdout and stderr were invalidated Previously, on io redirection, we were closing stdout and replacing it with our new buffer. On io restoration, we were restored a buffer pointing at console stdout to sys.stdout, but any cached references to stdout (i.e. nested logging contexts or pytest) were invalidated. Now we: * do not close whatever sys.stdout refers to, we mearly store a reference to it * do not construct a new buffer from python's api, instead we perform redirection from the ground up, starting with fhs to fds and compose a buffer from the existing fh's fd. * Use pipes for communication with our reader thread, which enables filtering, control characters, etc and allows for non racey echo behavior. At a glance: * Redirects IO starting at the Windows file handle (fh) level * Properly maps fhs to fds, and obtains the appropriate buffer wrapping each * Enables proper subprocess io redirection inheritance * Manages shared file handles between stderr and stdout on redirect * Properly redirects IO at each level of handling, kernel, C, and python * Ensures cached references to console streams are not invalidated * Ensures correct order of release for buffers -> fhs Moves toward a unified logging class by introducing fundamental support for the concepts leveraged by the non Windows logger classes like pipes Signed-off-by: John Parent <john.parent@kitware.com>

Signed-off-by: John Parent <john.parent@kitware.com>

haampie · 2025-12-30T14:17:24Z

I haven't looked at this in detail, but just wondering if you've seen class Tee in new_installer.py as well? The log_output bits will likely go away with the old installer.

johnwparent · 2025-12-30T15:10:18Z

I haven't looked at this in detail, but just wondering if you've seen class Tee in new_installer.py as well? The log_output bits will likely go away with the old installer.

Ahh, I have not. Perhaps this PR should be refactored in favor of supporting Tee on Windows then. I'm away at the moment, but I'll look at it once I'm back.

Thanks for pointing that out.

haampie · 2025-12-30T21:54:12Z

Let's chat about it on Slack another time :) have a good holidays!

scheibelp

Not complete, but I have a few preliminary requests and questions

scheibelp · 2025-12-22T23:03:44Z

lib/spack/spack/llnl/util/tty/log.py

+                # Flush the system stream before redirection
+                sys_stream.flush()
+        except BaseException:
+            # swallow flush errors


This would indicate mismanagement wouldn't it? We might want to log this at the debug level.

Yes, this would indicate an incorrectly timed flush, added debug logging.

scheibelp · 2025-12-23T20:45:49Z

lib/spack/spack/llnl/util/tty/log.py

-        # Flush and close sys_stream - also closes the file descriptor (fd)
-        sys_stream = getattr(sys, self.sys_attr)
-        sys_stream.flush()
-        sys_stream.close()


Does this address the case where a context-manager-like functionality above this has saved a reference to sys.stdout?

Yes, we're only closing IO components owned by this logging redirect instance.

scheibelp · 2026-03-03T23:58:10Z

lib/spack/spack/test/llnl/util/tty/log.py

        # Check captured output (echoed content)
        # Note: 'logged' is not echoed because force_echo() scope ended
-        assert capfd.readouterr()[0] == "echo\n"
+        # "print(echo)" above automatically uses an "\r\n" on Windows


(minor) add Note: or something to indicate this is not a continuation of prior note

Oh yeah good point. Thanks.

scheibelp · 2026-03-04T00:24:49Z

lib/spack/spack/llnl/util/tty/log.py

+        dup_redirect_h = dup_fh(redirect_h)
+        # ensure inheritable handles
+        os.set_handle_inheritable(redirect_h, True)
+        # Todo: investigate if this is neccesary if we do the above before the handle dup


Question(s): Can this be determined before a merge? I think redirect_h is what's being used by subprocs, and I would have expected that's the only one that needs to be inheritable.

Investigating now.

scheibelp · 2026-03-04T00:52:00Z

lib/spack/spack/llnl/util/tty/log.py

+            raise KeyError(self.sys_attr)
+
+        self.saved_stream = getattr(sys, self.sys_attr)
+        self.saved_std_fd = self.saved_stream.fileno()


Do we need to track this explicitly? It seems to always be available via self.saved_stream.fileno()

If I'm right but you still think it should be tracked, I can think on that. I worry about situations where duplicate data is maintained with separate references though.

I think it's safer to track it explicitly yes. Basically it allows us to have a consistent idea of what fd we're using to replace whatever the std stream happens to be at redirection time without needing to consider the state of saved_stream.

scheibelp · 2026-03-04T01:00:25Z

lib/spack/spack/test/llnl/util/tty/log.py

+        # "print(echo)" above automatically uses an "\r\n" on Windows
+        # and will replace any \n with \r\n (so end=\n does not work)
+        # \r\n is expected and correct here
+        newline = "\r\n" if sys.platform == "win32" else "\n"


It looks like redirect_stream is setting newline="\n",, so does that not have any effect?

It's been a little while but IIRC this is an artifact of pytest and capfd. If you look at the check above where we are able to use \n consistently in the file output, that is the effect of setting newline in redirect_stream.

scheibelp · 2026-03-04T06:40:10Z

lib/spack/spack/llnl/util/tty/log.py

+            read.close()
+            log_writer.close()
+            stdout.flush()
+            stdout.close()


I don't think you should have to flush before you close.

You are correct, removed.

scheibelp · 2026-03-04T06:57:36Z

lib/spack/spack/llnl/util/tty/log.py

+                    # the pipe is closed or otherwise inaccesible
+                    return
+                norm_data = data.decode(encoding="utf-8", errors="replace")
+                # stdout.write(data.decode())


scheibelp · 2026-03-04T06:59:25Z

lib/spack/spack/llnl/util/tty/log.py

+                    output = clean_line
+                    if filter_fn:
+                        output = filter_fn(output)
+                    enc = stdout.encoding


(minor) Can this check be done outside the loop (and e.g. define a lambda here?

Might be worth printing a warning if the encoding is not utf-8

Also question: is there a reason you can't consume the bytes from the pipe and pass them directly through without detecting/matching encoding?

Windows love utf-16 (wide), so depending what stdout is, it may be utf-16, which is normal and expected, particularly if we're in nested logging contexts and stdout is a pipe.

Also question: is there a reason you can't consume the bytes from the pipe and pass them directly through without detecting/matching encoding?

The encoding we're reading may not match the encoding of the output, without this output is often garbled/unreadable (or mandarin characters, I hit those a lot without this)

scheibelp

Not complete, but I have some preliminary requests/questions

Signed-off-by: John Parent <john.parent@kitware.com>

MacOS GH CI tests have some issue with coverage not finding the "bin" module that also does not occur with local testing on mac, linux, or Windows. Loosen the check so the extra error cruft of converage does not cause the test to fail, and we still check what we need to check Signed-off-by: John Parent <john.parent@kitware.com>

johnwparent marked this pull request as draft December 19, 2025 20:03

johnwparent requested a review from scheibelp December 19, 2025 20:03

johnwparent added 8 commits December 19, 2025 15:14

Can't annotate type only avail on Windows

110ece4

Signed-off-by: John Parent <john.parent@kitware.com>

No dup_fh on non Windows

d1be931

Signed-off-by: John Parent <john.parent@kitware.com>

filter_fn is optional

94cb7b4

Signed-off-by: John Parent <john.parent@kitware.com>

windows only method

9bdfa4f

Signed-off-by: John Parent <john.parent@kitware.com>

How did this pass style?

9fce914

Signed-off-by: John Parent <john.parent@kitware.com>

Import fixes

28ae55d

Signed-off-by: John Parent <john.parent@kitware.com>

sigh, mypy

b01469e

Signed-off-by: John Parent <john.parent@kitware.com>

io isolation in new logging test

9eaf50c

Signed-off-by: John Parent <john.parent@kitware.com>

johnwparent mentioned this pull request Jan 31, 2026

WIP: Unify loggers #51904

Draft

3 tasks

johnwparent linked an issue Mar 2, 2026 that may be closed by this pull request

Tee functionality during build broken on Windows #29673

Open

3 tasks

scheibelp reviewed Mar 4, 2026

View reviewed changes

johnwparent added 2 commits April 1, 2026 20:19

wip

7e6e49d

Signed-off-by: John Parent <john.parent@kitware.com>

Quick review updates

0ec67ff

Signed-off-by: John Parent <john.parent@kitware.com>

github-actions bot added the unit-tests label Apr 2, 2026

Conversation

johnwparent commented Dec 19, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

haampie commented Dec 30, 2025

Uh oh!

johnwparent commented Dec 30, 2025

Uh oh!

haampie commented Dec 30, 2025

Uh oh!

scheibelp left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

scheibelp left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

johnwparent commented Dec 19, 2025 •

edited

Loading