From dc8ff246856abd2017559b4f1a2240b39b8887ec Mon Sep 17 00:00:00 2001 From: Maximilian Hils Date: Sun, 18 Sep 2022 12:44:18 +0200 Subject: [PATCH] don't remove `add_log` but deprecate it. --- CHANGELOG.md | 4 +- docs/scripts/api-events.py | 2 +- docs/src/content/addons-api-changelog.md | 2 +- mitmproxy/addonmanager.py | 19 +++----- mitmproxy/addons/eventstore.py | 11 +---- mitmproxy/addons/termlog.py | 1 + mitmproxy/log.py | 47 +++++++++++++++++++ mitmproxy/master.py | 10 ++-- mitmproxy/tools/main.py | 1 + test/conftest.py | 7 +++ test/mitmproxy/addons/test_proxyserver.py | 8 ++-- test/mitmproxy/addons/test_readfile.py | 2 +- test/mitmproxy/addons/test_script.py | 31 +++++++----- .../data/addonscripts/recorder/recorder.py | 2 +- test/mitmproxy/net/test_udp.py | 2 +- test/mitmproxy/proxy/test_mode_servers.py | 6 +-- test/mitmproxy/test_addonmanager.py | 3 -- 17 files changed, 104 insertions(+), 54 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 451fdbd2c..479d65bb4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -31,9 +31,9 @@ ([#5507](https://github.com/mitmproxy/mitmproxy/pull/5507), @LIU-shuyi) * Add HTTP/3 binary frame content view. ([#5582](https://github.com/mitmproxy/mitmproxy/pull/5582), @mhils) -* Remove `add_log` event hook. Users should use the builtin `logging` module instead. +* Deprecate `add_log` event hook. Users should use the builtin `logging` module instead. ([#5590](https://github.com/mitmproxy/mitmproxy/pull/5590), @mhils) -* Deprecated `mitmproxy.ctx.log` in favor of Python's builtin `logging` module. +* Deprecate `mitmproxy.ctx.log` in favor of Python's builtin `logging` module. ([#5590](https://github.com/mitmproxy/mitmproxy/pull/5590), @mhils) ## 28 June 2022: mitmproxy 8.1.1 diff --git a/docs/scripts/api-events.py b/docs/scripts/api-events.py index 25481366a..7d9971b62 100644 --- a/docs/scripts/api-events.py +++ b/docs/scripts/api-events.py @@ -13,7 +13,7 @@ known = set() def category(name: str, desc: str, hooks: list[type[hooks.Hook]]) -> None: all_params = [ - list(inspect.signature(hook.__init__).parameters.values())[1:] for hook in hooks + list(inspect.signature(hook.__init__, eval_str=True).parameters.values())[1:] for hook in hooks ] # slightly overengineered, but this was fun to write. ¯\_(ツ)_/¯ diff --git a/docs/src/content/addons-api-changelog.md b/docs/src/content/addons-api-changelog.md index 6936d6643..c4dfad60e 100644 --- a/docs/src/content/addons-api-changelog.md +++ b/docs/src/content/addons-api-changelog.md @@ -28,7 +28,7 @@ logging.info("hello world") ``` -Accordingly, the `add_log` event has been removed. Developers who rely on log entries need to register their own +Accordingly, the `add_log` event has been deprecated. Developers who rely on log entries should register their own `logging.Handler` instead. An example for this can be found in the `EventStore` addon. ## mitmproxy 7.0 diff --git a/mitmproxy/addonmanager.py b/mitmproxy/addonmanager.py index bda1090a0..265c81113 100644 --- a/mitmproxy/addonmanager.py +++ b/mitmproxy/addonmanager.py @@ -163,23 +163,18 @@ class AddonManager: """ api_changes = { # mitmproxy 6 -> mitmproxy 7 - "clientconnect": "client_connected", - "clientdisconnect": "client_disconnected", - "serverconnect": "server_connect and server_connected", - "serverdisconnect": "server_disconnected", + "clientconnect": f"The clientconnect event has been removed, use client_connected instead", + "clientdisconnect": f"The clientdisconnect event has been removed, use client_disconnected instead", + "serverconnect": "The serverconnect event has been removed, use server_connect and server_connected instead", + "serverdisconnect": f"The serverdisconnect event has been removed, use server_disconnected instead", # mitmproxy 8 -> mitmproxy 9 - "add_log": None, + "add_log": "The add_log event has been deprecated, use Python's builtin logging module instead", } for a in traverse([addon]): - for old, new in api_changes.items(): + for old, msg in api_changes.items(): if hasattr(a, old): - if new: - msg = f"The {old} event has been removed, use {new} instead. " - else: - msg = f"The {old} event has been removed. " logger.warning( - f"{msg}" - f"For more details, see https://docs.mitmproxy.org/dev/addons-api-changelog/." + f"{msg}. For more details, see https://docs.mitmproxy.org/dev/addons-api-changelog/." ) name = _get_name(a) if name in self.lookup: diff --git a/mitmproxy/addons/eventstore.py b/mitmproxy/addons/eventstore.py index b931b570d..d973842c4 100644 --- a/mitmproxy/addons/eventstore.py +++ b/mitmproxy/addons/eventstore.py @@ -38,15 +38,6 @@ class EventStore: self.sig_refresh.send() -LOGGING_LEVELS_TO_LOGENTRY = { - logging.ERROR: "error", - logging.WARNING: "warn", - logging.INFO: "info", - log.ALERT: "alert", - logging.DEBUG: "debug", -} - - class CallbackLogger(log.MitmLogHandler): def __init__( self, @@ -60,6 +51,6 @@ class CallbackLogger(log.MitmLogHandler): def emit(self, record: logging.LogRecord) -> None: entry = LogEntry( msg=self.format(record), - level=LOGGING_LEVELS_TO_LOGENTRY.get(record.levelno, "error"), + level=log.LOGGING_LEVELS_TO_LOGENTRY.get(record.levelno, "error"), ) self.event_loop.call_soon_threadsafe(self.callback, entry) diff --git a/mitmproxy/addons/termlog.py b/mitmproxy/addons/termlog.py index 2bbe5ea61..331626f36 100644 --- a/mitmproxy/addons/termlog.py +++ b/mitmproxy/addons/termlog.py @@ -1,3 +1,4 @@ +from __future__ import annotations import asyncio import logging from typing import IO diff --git a/mitmproxy/log.py b/mitmproxy/log.py index 9e9b964f9..2e4597372 100644 --- a/mitmproxy/log.py +++ b/mitmproxy/log.py @@ -1,7 +1,10 @@ +from __future__ import annotations import logging import os import warnings +from dataclasses import dataclass +from mitmproxy import hooks, master from mitmproxy.contrib import click as miniclick from mitmproxy.utils import human @@ -180,6 +183,50 @@ class Log: logging.getLogger().log(level=logging.getLevelName(level.upper()), msg=text) +LOGGING_LEVELS_TO_LOGENTRY = { + logging.ERROR: "error", + logging.WARNING: "warn", + logging.INFO: "info", + ALERT: "alert", + logging.DEBUG: "debug", +} + + +class LegacyLogEvents(MitmLogHandler): + """Emit deprecated `add_log` events from stdlib logging.""" + def __init__( + self, + master: master.Master, + ): + super().__init__() + self.master = master + self.formatter = MitmFormatter(colorize=False) + + def emit(self, record: logging.LogRecord) -> None: + entry = LogEntry( + msg=self.format(record), + level=LOGGING_LEVELS_TO_LOGENTRY.get(record.levelno, "error"), + ) + self.master.event_loop.call_soon_threadsafe( + self.master.addons.trigger, + AddLogHook(entry), + ) + + +@dataclass +class AddLogHook(hooks.Hook): + """ + **Deprecated:** Starting with mitmproxy 9, users should use the standard Python logging module instead, for example + by calling `logging.getLogger().addHandler()`. + + Called whenever a new log entry is created through the mitmproxy + context. Be careful not to log from this event, which will cause an + infinite loop! + """ + + entry: LogEntry + + def log_tier(level): """ Comparison method for "old" LogEntry log tiers. diff --git a/mitmproxy/master.py b/mitmproxy/master.py index 322268160..bfb457d34 100644 --- a/mitmproxy/master.py +++ b/mitmproxy/master.py @@ -26,7 +26,10 @@ class Master: self.options: options.Options = opts or options.Options() self.commands = command.CommandManager(self) self.addons = addonmanager.AddonManager(self) - self.log = log.Log(self) + + self.log = log.Log(self) # deprecated, do not use. + self._legacy_log_events = log.LegacyLogEvents(self) + self._legacy_log_events.install() # We expect an active event loop here already because some addons # may want to spawn tasks during the initial configuration phase, @@ -34,10 +37,10 @@ class Master: self.event_loop = event_loop or asyncio.get_running_loop() try: self.should_exit = asyncio.Event() - except RuntimeError: + except RuntimeError: # python 3.9 and below self.should_exit = asyncio.Event(loop=self.event_loop) mitmproxy_ctx.master = self - mitmproxy_ctx.log = self.log + mitmproxy_ctx.log = self.log # deprecated, do not use. mitmproxy_ctx.options = self.options async def run(self) -> None: @@ -74,6 +77,7 @@ class Master: async def done(self) -> None: await self.addons.trigger_event(hooks.DoneHook()) + self._legacy_log_events.uninstall() def _asyncio_exception_handler(self, loop, context): try: diff --git a/mitmproxy/tools/main.py b/mitmproxy/tools/main.py index cf2743d92..c640326aa 100644 --- a/mitmproxy/tools/main.py +++ b/mitmproxy/tools/main.py @@ -52,6 +52,7 @@ def run( async def main() -> T: logging.getLogger().setLevel(logging.DEBUG) logging.getLogger("tornado").setLevel(logging.WARNING) + logging.getLogger("asyncio").setLevel(logging.WARNING) debug.register_info_dumpers() opts = options.Options() diff --git a/test/conftest.py b/test/conftest.py index fb49889b3..89d78c0e9 100644 --- a/test/conftest.py +++ b/test/conftest.py @@ -1,3 +1,4 @@ +from __future__ import annotations import asyncio import os import socket @@ -35,6 +36,9 @@ class AsyncLogCaptureFixture: def __init__(self, caplog: pytest.LogCaptureFixture): self.caplog = caplog + def set_level(self, level: int | str, logger: str | None = None) -> None: + self.caplog.set_level(level, logger) + async def await_log(self, text, timeout=2): await asyncio.sleep(0) for i in range(int(timeout / 0.01)): @@ -44,6 +48,9 @@ class AsyncLogCaptureFixture: await asyncio.sleep(0.01) raise AssertionError(f"Did not find {text!r} in log:\n{self.caplog.text}.") + def clear(self) -> None: + self.caplog.clear() + @pytest.fixture def caplog_async(caplog): diff --git a/test/mitmproxy/addons/test_proxyserver.py b/test/mitmproxy/addons/test_proxyserver.py index b5a278db7..e8eecf80d 100644 --- a/test/mitmproxy/addons/test_proxyserver.py +++ b/test/mitmproxy/addons/test_proxyserver.py @@ -48,7 +48,7 @@ async def tcp_server(handle_conn) -> Address: async def test_start_stop(caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") async def server_handler( reader: asyncio.StreamReader, writer: asyncio.StreamWriter @@ -218,7 +218,7 @@ async def test_startup_err(monkeypatch, caplog) -> None: async def test_shutdown_err(caplog_async) -> None: - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") async def _raise(*_): raise OSError("cannot close") @@ -248,7 +248,7 @@ class DummyResolver: async def test_dns(caplog_async) -> None: - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") ps = Proxyserver() with taddons.context(ps, DummyResolver()) as tctx: tctx.configure( @@ -313,7 +313,7 @@ async def udp_server(handle_conn) -> Address: async def test_dtls(monkeypatch, caplog_async) -> None: - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") def server_handler( transport: asyncio.DatagramTransport, diff --git a/test/mitmproxy/addons/test_readfile.py b/test/mitmproxy/addons/test_readfile.py index 0edd8c831..5c01e95e8 100644 --- a/test/mitmproxy/addons/test_readfile.py +++ b/test/mitmproxy/addons/test_readfile.py @@ -73,7 +73,7 @@ class TestReadFile: with pytest.raises(exceptions.FlowReadException): await rf.load_flows(io.BytesIO(b"qibble")) - caplog_async.caplog.clear() + caplog_async.clear() with pytest.raises(exceptions.FlowReadException): await rf.load_flows(corrupt_data) await caplog_async.await_log("file corrupted") diff --git a/test/mitmproxy/addons/test_script.py b/test/mitmproxy/addons/test_script.py index dc7f09c72..e69065642 100644 --- a/test/mitmproxy/addons/test_script.py +++ b/test/mitmproxy/addons/test_script.py @@ -64,7 +64,7 @@ class TestScript: assert '"' not in s.fullpath async def test_simple(self, tdata, caplog_async): - caplog_async.caplog.set_level("DEBUG") + caplog_async.set_level("DEBUG") sc = script.Script( tdata.path("mitmproxy/data/addonscripts/recorder/recorder.py"), True, @@ -84,21 +84,28 @@ class TestScript: sc.done() async def test_reload(self, tmp_path, caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") with taddons.context() as tctx: f = tmp_path / "foo.py" f.write_text("\n") sc = script.Script(str(f), True) tctx.configure(sc) await caplog_async.await_log("Loading") + caplog_async.clear() - caplog_async.caplog.clear() - f.write_text("\n\n") - await caplog_async.await_log("Loading") + for i in range(20): + # Some filesystems only have second-level granularity, + # so just writing once again is not good enough. + f.write_text("\n") + if "Loading" in caplog_async.caplog.text: + break + await asyncio.sleep(0.1) + else: + raise AssertionError("No reload seen") sc.done() async def test_exception(self, tdata, caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") with taddons.context() as tctx: sc = script.Script( tdata.path("mitmproxy/data/addonscripts/error.py"), @@ -127,7 +134,7 @@ class TestScript: sc.done() async def test_addon(self, tdata, caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") with taddons.context() as tctx: sc = script.Script(tdata.path("mitmproxy/data/addonscripts/addon.py"), True) tctx.master.addons.add(sc) @@ -161,7 +168,7 @@ class TestCutTraceback: class TestScriptLoader: async def test_script_run(self, tdata, caplog_async): - caplog_async.caplog.set_level("DEBUG") + caplog_async.set_level("DEBUG") rp = tdata.path("mitmproxy/data/addonscripts/recorder/recorder.py") sc = script.ScriptLoader() with taddons.context(sc): @@ -204,7 +211,7 @@ class TestScriptLoader: tctx.configure(sc, scripts=["one", "one"]) async def test_script_deletion(self, tdata, caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") tdir = tdata.path("mitmproxy/data/addonscripts/") with open(tdir + "/dummy.py", "w") as f: f.write("\n") @@ -237,7 +244,7 @@ class TestScriptLoader: assert "NoneType" in caplog.text async def test_order(self, tdata, caplog_async): - caplog_async.caplog.set_level("DEBUG") + caplog_async.set_level("DEBUG") rec = tdata.path("mitmproxy/data/addonscripts/recorder") sc = script.ScriptLoader() sc.is_running = True @@ -264,7 +271,7 @@ class TestScriptLoader: "c running", ] - caplog_async.caplog.clear() + caplog_async.clear() tctx.configure( sc, scripts=[ @@ -282,7 +289,7 @@ class TestScriptLoader: "b configure", ] - caplog_async.caplog.clear() + caplog_async.clear() tctx.configure( sc, scripts=[ diff --git a/test/mitmproxy/data/addonscripts/recorder/recorder.py b/test/mitmproxy/data/addonscripts/recorder/recorder.py index d493b13f8..2a01b8cfd 100644 --- a/test/mitmproxy/data/addonscripts/recorder/recorder.py +++ b/test/mitmproxy/data/addonscripts/recorder/recorder.py @@ -10,7 +10,7 @@ class Recorder: self.name = name def __getattr__(self, attr): - if attr in hooks.all_hooks: + if attr in hooks.all_hooks and attr != "add_log": def prox(*args, **kwargs): lg = (self.name, attr, args, kwargs) diff --git a/test/mitmproxy/net/test_udp.py b/test/mitmproxy/net/test_udp.py index c9e9df3f9..6e5a9f623 100644 --- a/test/mitmproxy/net/test_udp.py +++ b/test/mitmproxy/net/test_udp.py @@ -57,7 +57,7 @@ async def test_client_server(): async def test_reader(caplog_async): - caplog_async.caplog.set_level("DEBUG") + caplog_async.set_level("DEBUG") reader = DatagramReader() addr = ("8.8.8.8", 53) reader.feed_data(b"First message", addr) diff --git a/test/mitmproxy/proxy/test_mode_servers.py b/test/mitmproxy/proxy/test_mode_servers.py index a7a55163e..38608595d 100644 --- a/test/mitmproxy/proxy/test_mode_servers.py +++ b/test/mitmproxy/proxy/test_mode_servers.py @@ -53,7 +53,7 @@ async def test_last_exception_and_running(monkeypatch): async def test_tcp_start_stop(caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") manager = MagicMock() with taddons.context(): @@ -76,7 +76,7 @@ async def test_tcp_start_stop(caplog_async): @pytest.mark.parametrize("failure", [True, False]) async def test_transparent(failure, monkeypatch, caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") manager = MagicMock() if failure: @@ -135,7 +135,7 @@ async def test_invalid_protocol(monkeypatch): async def test_udp_start_stop(caplog_async): - caplog_async.caplog.set_level("INFO") + caplog_async.set_level("INFO") manager = MagicMock() manager.connections = {} diff --git a/test/mitmproxy/test_addonmanager.py b/test/mitmproxy/test_addonmanager.py index 90cef76f2..77057d11b 100644 --- a/test/mitmproxy/test_addonmanager.py +++ b/test/mitmproxy/test_addonmanager.py @@ -61,9 +61,6 @@ class AOldAPI: def clientconnect(self): pass - def add_log(self): - pass - def test_command(): with taddons.context() as tctx: