releng: fix logging inside interactive xonsh

I don't know when this broke, it seems like it happened since the 24.05
upgrade, so xonsh 0.15.

What happened is that xonsh was trying to intercept log output, which
explodes if you have the logger survive past one command input. This is,
however, impossible to avoid if you are trying to use logging when you
import releng from inside xonsh for interactive use!

The error below is because the memory handler backing the stdout/stderr
of the one command that's just been run was closed after the command
completed.

Change-Id: I2be642aebf93da9818d08ff8b97c2e72ba5ac581

--- Logging error ---
Traceback (most recent call last):
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/logging/__init__.py", line 1113, in emit
    stream.write(msg + self.terminator)
  File "/nix/store/34951j60xcsw6zj4v8lsaf491acv0by3-python3-3.11.9-env/lib/python3.11/site-packages/xonsh/base_shell.py", line 183, in write
    self.mem.write(s)
ValueError: I/O operation on closed file.
Call stack:
  File "/nix/store/xgdp1p1gv8ni1awnkzyqasnn6gz5wlvx-xonsh-0.15.1/bin/xonsh", line 8, in <module>
    sys.exit(main())
  File "/nix/store/34951j60xcsw6zj4v8lsaf491acv0by3-python3-3.11.9-env/lib/python3.11/site-packages/xonsh/main.py", line 470, in main
    sys.exit(main_xonsh(args))
  File "/nix/store/34951j60xcsw6zj4v8lsaf491acv0by3-python3-3.11.9-env/lib/python3.11/site-packages/xonsh/main.py", line 514, in main_xonsh
    shell.shell.cmdloop()
  File "/nix/store/34951j60xcsw6zj4v8lsaf491acv0by3-python3-3.11.9-env/lib/python3.11/site-packages/xonsh/ptk_shell/shell.py", line 406, in cmd
loop
    line = self.singleline(auto_suggest=auto_suggest)
  File "/nix/store/34951j60xcsw6zj4v8lsaf491acv0by3-python3-3.11.9-env/lib/python3.11/site-packages/xonsh/ptk_shell/shell.py", line 374, in sin
gleline
    line = self.prompter.prompt(**prompt_args)
  File "/nix/store/34951j60xcsw6zj4v8lsaf491acv0by3-python3-3.11.9-env/lib/python3.11/site-packages/prompt_toolkit/shortcuts/prompt.py", line 1
026, in prompt
    return self.app.run(
  File "/nix/store/34951j60xcsw6zj4v8lsaf491acv0by3-python3-3.11.9-env/lib/python3.11/site-packages/prompt_toolkit/application/application.py",
 line 1002, in run
    return asyncio.run(coro)
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/asyncio/runners.py", line 189, in run
    with Runner(debug=debug) as runner:
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/asyncio/runners.py", line 59, in __enter__
    self._lazy_init()
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/asyncio/runners.py", line 137, in _lazy_init
    self._loop = events.new_event_loop()
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/asyncio/events.py", line 810, in new_event_loop
    return get_event_loop_policy().new_event_loop()
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/asyncio/events.py", line 699, in new_event_loop
    return self._loop_factory()
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/asyncio/unix_events.py", line 64, in __init__
    super().__init__(selector)
  File "/nix/store/7hnr99nxrd2aw6lghybqdmkckq60j6l9-python3-3.11.9/lib/python3.11/asyncio/selector_events.py", line 54, in __init__
    logger.debug('Using selector: %s', selector.__class__.__name__)
Message: 'Using selector: %s'
Arguments: ('EpollSelector',)

Change-Id: I90959809129aaf96aad4577599031688599ed85e

1 files changed, 51 insertions, 11 deletions

diff --git a/releng/__init__.py b/releng/__init__.py
index 59d1709b9..179ea3e2b 100644
--- a/releng/__init__.py
+++ b/releng/__init__.py
@@ -1,8 +1,12 @@
 from xonsh.main import setup
+
 setup()
 del setup
 
 import logging
+import sys
+
+import xonsh.base_shell
 
 from . import environment
 from . import create_release
@@ -13,19 +17,55 @@ from . import docker
 from . import docker_assemble
 from . import gitutils
 
-rootLogger = logging.getLogger()
-rootLogger.setLevel(logging.DEBUG)
-log = logging.getLogger(__name__)
-log.setLevel(logging.DEBUG)
 
-fmt = logging.Formatter('{asctime} {levelname} {name}: {message}',
-                        datefmt='%b %d %H:%M:%S',
-                        style='{')
+def setup_logging():
+    """
+    Sets up logging to work properly. The following are intended to work:
+    - ipython/xonsh configuration files adding log handlers out of band
+    - Reloading the module in xonsh/ipython not causing Bonus Loggers (which is
+      why we check if there is already a handler. This also helps the previous
+      case)
+    - Importing the releng module from xonsh and poking at it interactively
+    """
+
+    LEVELS = {
+        # Root logger must be DEBUG so that anything else can be DEBUG
+        None: logging.DEBUG,
+        # Everything in releng
+        __name__: logging.DEBUG,
+        # Log spam caused by prompt_toolkit
+        'asyncio': logging.INFO,
+    }
+
+    for name, level in LEVELS.items():
+        logger = logging.getLogger(name)
+        logger.setLevel(level)
+
+    root_logger = logging.getLogger()
+
+    fmt = logging.Formatter('{asctime} {levelname} {name}: {message}',
+                            datefmt='%b %d %H:%M:%S',
+                            style='{')
+
+    if not any(
+            isinstance(h, logging.StreamHandler) for h in root_logger.handlers):
+        stderr = sys.stderr
+        # XXX: Horrible hack required by the virtual stderr xonsh uses for each entered
+        # command getting closed after the command is run: we need to pull out
+        # the real stderr because this survives across multiple command runs.
+        #
+        # This only applies when running xonsh in interactive mode and importing releng.
+        if isinstance(sys.stderr, xonsh.base_shell._TeeStd):
+            stderr = stderr.std  # type: ignore
+
+        hand = logging.StreamHandler(stream=stderr)
+        hand.set_name('releng root handler')
+        hand.setFormatter(fmt)
+        root_logger.addHandler(hand)
+
+
+setup_logging()
 
-if not any(isinstance(h, logging.StreamHandler) for h in rootLogger.handlers):
-    hand = logging.StreamHandler()
-    hand.setFormatter(fmt)
-    rootLogger.addHandler(hand)
 
 def reload():
     import importlib