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
This commit is contained in:
Jade Lovelace 2024-06-13 14:36:32 -07:00
parent 74fb2e8c47
commit e715e5fd31

View file

@ -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