From e715e5fd31e0f79eac17c02163bd2035ef7c9166 Mon Sep 17 00:00:00 2001 From: Jade Lovelace Date: Thu, 13 Jun 2024 14:36:32 -0700 Subject: [PATCH] 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 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 --- releng/__init__.py | 62 ++++++++++++++++++++++++++++++++++++++-------- 1 file 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