Merge pull request #2678 from mhils/console-startup-events

Fix console logging during startup

mitmproxy/addons/eventstore.py

@@ -1,19 +1,30 @@
-from typing import List  # noqa
+import collections
+import typing  # noqa
 
 import blinker
+
+from mitmproxy import command
 from mitmproxy.log import LogEntry
 
 
 class EventStore:
-    def __init__(self):
+    def __init__(self, size=10000):
-        self.data = []  # type: List[LogEntry]
+        self.data = collections.deque(maxlen=size)  # type: typing.Deque[LogEntry]
         self.sig_add = blinker.Signal()
         self.sig_refresh = blinker.Signal()
 
-    def log(self, entry: LogEntry):
+    @property
+    def size(self) -> int:
+        return self.data.maxlen
+
+    def log(self, entry: LogEntry) -> None:
         self.data.append(entry)
         self.sig_add.send(self, entry=entry)
 
-    def clear(self):
+    @command.command("eventstore.clear")
+    def clear(self) -> None:
+        """
+        Clear the event log.
+        """
         self.data.clear()
         self.sig_refresh.send(self)

mitmproxy/tools/console/consoleaddons.py

@@ -32,43 +32,33 @@ console_layouts = [
 ]
 
 
-class Logger:
-    def log(self, evt):
-        signals.add_log(evt.msg, evt.level)
-        if evt.level == "alert":
-            signals.status_message.send(
-                message=str(evt.msg),
-                expire=2
-            )
-
-
 class UnsupportedLog:
     """
         A small addon to dump info on flow types we don't support yet.
     """
     def websocket_message(self, f):
         message = f.messages[-1]
-        signals.add_log(f.message_info(message), "info")
+        ctx.log.info(f.message_info(message))
-        signals.add_log(message.content if isinstance(message.content, str) else strutils.bytes_to_escaped_str(message.content), "debug")
+        ctx.log.debug(message.content if isinstance(message.content, str) else strutils.bytes_to_escaped_str(message.content))
 
     def websocket_end(self, f):
-        signals.add_log("WebSocket connection closed by {}: {} {}, {}".format(
+        ctx.log.info("WebSocket connection closed by {}: {} {}, {}".format(
             f.close_sender,
             f.close_code,
             f.close_message,
-            f.close_reason), "info")
+            f.close_reason))
 
     def tcp_message(self, f):
         message = f.messages[-1]
         direction = "->" if message.from_client else "<-"
-        signals.add_log("{client_host}:{client_port} {direction} tcp {direction} {server_host}:{server_port}".format(
+        ctx.log.info("{client_host}:{client_port} {direction} tcp {direction} {server_host}:{server_port}".format(
             client_host=f.client_conn.address[0],
             client_port=f.client_conn.address[1],
             server_host=f.server_conn.address[0],
             server_port=f.server_conn.address[1],
             direction=direction,
-        ), "info")
+        ))
-        signals.add_log(strutils.bytes_to_escaped_str(message.content), "debug")
+        ctx.log.debug(strutils.bytes_to_escaped_str(message.content))
 
 
 class ConsoleAddon:
@@ -481,13 +471,6 @@ class ConsoleAddon:
             ]
         )
 
-    @command.command("console.eventlog.clear")
-    def eventlog_clear(self) -> None:
-        """
-            Clear the event log.
-        """
-        signals.sig_clear_log.send(self)
-
     @command.command("console.key.contexts")
     def key_contexts(self) -> typing.Sequence[str]:
         """

mitmproxy/tools/console/eventlog.py

@@ -1,10 +1,8 @@
-import urwid
+import collections
-from mitmproxy.tools.console import signals
-from mitmproxy.tools.console import layoutwidget
-from mitmproxy import ctx
-from mitmproxy import log
 
-EVENTLOG_SIZE = 10000
+import urwid
+from mitmproxy.tools.console import layoutwidget
+from mitmproxy import log
 
 
 class LogBufferWalker(urwid.SimpleListWalker):
@@ -16,11 +14,16 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
     title = "Events"
 
     def __init__(self, master):
-        self.walker = LogBufferWalker([])
         self.master = master
-        urwid.ListBox.__init__(self, self.walker)
+        self.walker = LogBufferWalker(
-        signals.sig_add_log.connect(self.sig_add_log)
+            collections.deque(maxlen=self.master.events.size)
-        signals.sig_clear_log.connect(self.sig_clear_log)
+        )
+
+        master.events.sig_add.connect(self.add_event)
+        master.events.sig_refresh.connect(self.refresh_events)
+        self.refresh_events()
+
+        super().__init__(self.walker)
 
     def load(self, loader):
         loader.add_option(
@@ -37,21 +40,21 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
             self.set_focus(len(self.walker) - 1)
         elif key == "m_start":
             self.set_focus(0)
-        return urwid.ListBox.keypress(self, size, key)
+        return super().keypress(size, key)
 
-    def sig_add_log(self, sender, e, level):
+    def add_event(self, event_store, entry: log.LogEntry):
-        if log.log_tier(ctx.options.verbosity) < log.log_tier(level):
+        if log.log_tier(self.master.options.verbosity) < log.log_tier(entry.level):
             return
-        txt = "%s: %s" % (level, str(e))
+        txt = "%s: %s" % (entry.level, str(entry.msg))
-        if level in ("error", "warn"):
+        if entry.level in ("error", "warn"):
-            e = urwid.Text((level, txt))
+            e = urwid.Text((entry.level, txt))
         else:
             e = urwid.Text(txt)
         self.walker.append(e)
-        if len(self.walker) > EVENTLOG_SIZE:
-            self.walker.pop(0)
         if self.master.options.console_focus_follow:
             self.walker.set_focus(len(self.walker) - 1)
 
-    def sig_clear_log(self, sender):
+    def refresh_events(self, event_store=None):
-        self.walker[:] = []
+        self.walker.clear()
+        for event in self.master.events.data:
+            self.add_event(None, event)

mitmproxy/tools/console/flowview.py

@@ -11,9 +11,8 @@ from mitmproxy.tools.console import common
 from mitmproxy.tools.console import layoutwidget
 from mitmproxy.tools.console import flowdetailview
 from mitmproxy.tools.console import searchable
-from mitmproxy.tools.console import signals
 from mitmproxy.tools.console import tabs
-import mitmproxy.tools.console.master # noqa
+import mitmproxy.tools.console.master  # noqa
 
 
 class SearchError(Exception):
@@ -117,7 +116,7 @@ class FlowDetails(tabs.Tabs):
             viewmode, message
         )
         if error:
-            signals.add_log(error, "error")
+            self.master.add_log(error, "error")
         # Give hint that you have to tab for the response.
         if description == "No content" and isinstance(message, http.HTTPRequest):
             description = "No request content (press tab to view response)"

mitmproxy/tools/console/master.py

@@ -9,6 +9,7 @@ import subprocess
 import sys
 import tempfile
 import traceback
+import typing  # noqa
 
 import urwid
 
@@ -16,6 +17,7 @@ from mitmproxy import addons
 from mitmproxy import master
 from mitmproxy import log
 from mitmproxy.addons import intercept
+from mitmproxy.addons import eventstore
 from mitmproxy.addons import readfile
 from mitmproxy.addons import view
 from mitmproxy.tools.console import consoleaddons
@@ -31,7 +33,12 @@ class ConsoleMaster(master.Master):
     def __init__(self, opts):
         super().__init__(opts)
 
+        self.start_err = None  # type: typing.Optional[log.LogEntry]
+
         self.view = view.View()  # type: view.View
+        self.events = eventstore.EventStore()
+        self.events.sig_add.connect(self.sig_add_log)
+
         self.stream_path = None
         self.keymap = keymap.Keymap(self)
         defaultkeys.map(self.keymap)
@@ -40,12 +47,11 @@ class ConsoleMaster(master.Master):
         self.view_stack = []
 
         signals.call_in.connect(self.sig_call_in)
-        signals.sig_add_log.connect(self.sig_add_log)
-        self.addons.add(consoleaddons.Logger())
         self.addons.add(*addons.default_addons())
         self.addons.add(
             intercept.Intercept(),
             self.view,
+            self.events,
             consoleaddons.UnsupportedLog(),
             readfile.ReadFile(),
             consoleaddons.ConsoleAddon(self),
@@ -79,13 +85,17 @@ class ConsoleMaster(master.Master):
             callback = self.quit,
         )
 
-    def sig_add_log(self, sender, e, level):
+    def sig_add_log(self, event_store, entry: log.LogEntry):
-        if log.log_tier(self.options.verbosity) < log.log_tier(level):
+        if log.log_tier(self.options.verbosity) < log.log_tier(entry.level):
             return
-        if level in ("error", "warn"):
+        if entry.level in ("error", "warn"):
-            signals.status_message.send(
+            if self.first_tick:
-                message = "{}: {}".format(level.title(), e)
+                self.start_err = entry
-            )
+            else:
+                signals.status_message.send(
+                    message=(entry.level, "{}: {}".format(entry.level.title(), entry.msg)),
+                    expire=5
+                )
 
     def sig_call_in(self, sender, seconds, callback, args=()):
         def cb(*_):
@@ -195,6 +205,12 @@ class ConsoleMaster(master.Master):
 
         self.loop.set_alarm_in(0.01, self.ticker)
 
+        if self.start_err:
+            def display_err(*_):
+                self.sig_add_log(None, self.start_err)
+                self.start_err = None
+            self.loop.set_alarm_in(0.01, display_err)
+
         self.start()
         try:
             self.loop.run()

mitmproxy/tools/console/signals.py

@@ -1,19 +1,5 @@
 import blinker
 
-# Clear the eventlog
-sig_clear_log = blinker.Signal()
-
-# Add an entry to the eventlog
-sig_add_log = blinker.Signal()
-
-
-def add_log(e, level):
-    sig_add_log.send(
-        None,
-        e=e,
-        level=level
-    )
-
 
 # Show a status message in the action bar
 status_message = blinker.Signal()

test/mitmproxy/addons/test_eventstore.py

@@ -30,3 +30,18 @@ def test_simple():
 
     assert not sig_add.called
     assert sig_refresh.called
+
+
+def test_max_size():
+    store = eventstore.EventStore(3)
+    assert store.size == 3
+    store.log(log.LogEntry("foo", "info"))
+    store.log(log.LogEntry("bar", "info"))
+    store.log(log.LogEntry("baz", "info"))
+    assert len(store.data) == 3
+    assert ["foo", "bar", "baz"] == [x.msg for x in store.data]
+
+    # overflow
+    store.log(log.LogEntry("boo", "info"))
+    assert len(store.data) == 3
+    assert ["bar", "baz", "boo"] == [x.msg for x in store.data]