|
| 1 | +"""Sending this package's diagnostics to a console, for the entry points. |
| 2 | +
|
| 3 | +A library does not configure logging for its process, so the package's modules |
| 4 | +only ever call ``logger.info``. Something has to turn that into output, and that |
| 5 | +something is whoever owns the process: the CLI, the example scripts, the |
| 6 | +notebook. Before this existed only the CLI did it, so calling |
| 7 | +``evaluate_scenario`` from anywhere else printed nothing at all. |
| 8 | +""" |
| 9 | + |
| 10 | +import logging |
| 11 | +import sys |
| 12 | + |
| 13 | +PACKAGE_LOGGER_NAME = "BalloonPoppingGymEnv" |
| 14 | +# Marks the handler this module owns, so repeat calls replace that one and leave |
| 15 | +# anything the host installed alone. |
| 16 | +CONSOLE_HANDLER_NAME = "BalloonPoppingGymEnv.console" |
| 17 | + |
| 18 | + |
| 19 | +def configure_console_logging(level=logging.INFO, stream=None): |
| 20 | + """Print this package's log records as plain lines, and nothing else's. |
| 21 | +
|
| 22 | + Scoped to the package logger rather than the root one. ``basicConfig`` on the |
| 23 | + root logger opens the same stream to every dependency that propagates a |
| 24 | + record, and RocketPy is in the middle of adding module loggers of its own, so |
| 25 | + a competitor's score would arrive in the middle of the engine's chatter. |
| 26 | +
|
| 27 | + The formatter is bare ``%(message)s`` deliberately. ``basicConfig``'s default |
| 28 | + is ``levelname:name:message``, which turned ``Total reward: 7`` into |
| 29 | + ``INFO:__main__:Total reward: 7``. That line is the visible result of a run |
| 30 | + and is worth keeping the way it was. |
| 31 | +
|
| 32 | + The threshold is set on the handler as well as on the logger, which is not |
| 33 | + redundant. A record is filtered by the level of the logger it was *emitted |
| 34 | + on*; propagation then hands it to every ancestor handler without rechecking |
| 35 | + any ancestor logger's level. So a descendant left at ``DEBUG`` sends debug |
| 36 | + records straight to this handler, and with the handler at ``NOTSET`` they |
| 37 | + reach stdout. Measured: a child at ``DEBUG`` printed its record even with the |
| 38 | + package logger at ``INFO``. |
| 39 | +
|
| 40 | + Only the handler this module installed is replaced, and it is closed on the |
| 41 | + way out. Clearing the logger's handlers outright would also discard a file, |
| 42 | + JSON or audit handler belonging to whatever is embedding the environment. |
| 43 | +
|
| 44 | + Two things this does take over, which is worth saying plainly because |
| 45 | + preserving handlers is not the same as preserving policy. Propagation is |
| 46 | + turned off, so handlers on the root logger stop receiving this package's |
| 47 | + records; that is what keeps a score from being printed twice, and it is a |
| 48 | + reasonable trade for something an entry point calls. And the logger's own |
| 49 | + threshold is lowered to ``level`` if it had none, or left where it is if the |
| 50 | + host had already set one lower, so a host's DEBUG file handler keeps working |
| 51 | + while the console still shows only ``level`` and above. |
| 52 | +
|
| 53 | + ``level=logging.NOTSET`` is the one value that does not mean what the name |
| 54 | + suggests. On a handler it means "handle everything", but the logger gate |
| 55 | + comes first, and ``NOTSET`` on a non-root logger means "ask my ancestors", |
| 56 | + whose default is ``WARNING``. So passing it leaves ``INFO`` records dropped |
| 57 | + before they reach the console. Pass ``logging.DEBUG`` for everything. The |
| 58 | + behaviour is left as ``logging`` defines it for each object rather than |
| 59 | + special-cased here, because a single value where this function disagrees |
| 60 | + with the standard library is the worse surprise. |
| 61 | +
|
| 62 | + Nothing on the logger is touched until the new handler exists and has |
| 63 | + accepted ``level``, so a level ``logging`` rejects raises with the logger |
| 64 | + exactly as it was. |
| 65 | + """ |
| 66 | + package_logger = logging.getLogger(PACKAGE_LOGGER_NAME) |
| 67 | + |
| 68 | + # Built and configured before the logger is touched at all. setLevel is |
| 69 | + # where logging itself decides what a level name means, and it is the call |
| 70 | + # that rejects a bad one; doing it here rather than after the swap is what |
| 71 | + # makes a rejection leave nothing half-done. It also normalises "INFO" to an |
| 72 | + # int, which the arithmetic at the bottom needs. |
| 73 | + # |
| 74 | + # Not named yet, deliberately. set_name is not configuration, it writes to |
| 75 | + # logging's process-wide handler-name registry, and close() deletes whatever |
| 76 | + # that name currently points at without checking it is the handler being |
| 77 | + # closed. Naming this one first meant the second call took the name, then |
| 78 | + # closing the old handler deleted the new one's entry: the handler stayed |
| 79 | + # attached and kept printing, so every output test passed, while |
| 80 | + # getHandlerByName returned None and an incremental dictConfig could no |
| 81 | + # longer find it. Measured. A rejected level had the same effect, which made |
| 82 | + # the atomicity this function claims untrue in the one way the logger's own |
| 83 | + # attributes do not show. |
| 84 | + handler = logging.StreamHandler(sys.stdout if stream is None else stream) |
| 85 | + handler.setFormatter(logging.Formatter("%(message)s")) |
| 86 | + handler.setLevel(level) |
| 87 | + numeric_level = handler.level |
| 88 | + |
| 89 | + # getEffectiveLevel, not .level. NOTSET on a non-root logger does not mean |
| 90 | + # "no threshold", it means "ask my ancestors", so a host that set DEBUG on |
| 91 | + # the root still has an effective DEBUG here. Reading the raw attribute and |
| 92 | + # finding NOTSET, then setting INFO, raised the threshold anyway. |
| 93 | + effective_level = package_logger.getEffectiveLevel() |
| 94 | + |
| 95 | + # Everything from here down mutates the logger, and none of it can fail. |
| 96 | + for existing in list(package_logger.handlers): |
| 97 | + if existing.get_name() == CONSOLE_HANDLER_NAME: |
| 98 | + package_logger.removeHandler(existing) |
| 99 | + existing.close() |
| 100 | + |
| 101 | + # Named only now, once the old owner of the name has let go of it. |
| 102 | + handler.set_name(CONSOLE_HANDLER_NAME) |
| 103 | + package_logger.addHandler(handler) |
| 104 | + |
| 105 | + # Never raise the threshold. A host that arranged for DEBUG here, directly |
| 106 | + # or through an ancestor, did so to feed its own handler, and moving this |
| 107 | + # logger to INFO would silence that handler even though it is left |
| 108 | + # attached. The console threshold is the one on the handler above, so |
| 109 | + # lowering this one costs nothing. |
| 110 | + package_logger.setLevel(min(effective_level, numeric_level)) |
| 111 | + |
| 112 | + package_logger.propagate = False |
| 113 | + return package_logger |
0 commit comments