From 18f34fe88e71cbe17eaacf88e011718fa87bc767 Mon Sep 17 00:00:00 2001
From: Maximilian Hils <git@maximilianhils.com>
Date: Thu, 14 Dec 2017 23:03:52 +0100
Subject: streamline console logging, fix #2667

---
 mitmproxy/addons/eventstore.py           | 10 ++++++++--
 mitmproxy/tools/console/consoleaddons.py | 31 +++++++------------------------
 mitmproxy/tools/console/eventlog.py      | 23 ++++++++++++-----------
 mitmproxy/tools/console/flowview.py      |  5 ++---
 mitmproxy/tools/console/master.py        | 15 +++++++++------
 mitmproxy/tools/console/signals.py       | 14 --------------
 6 files changed, 38 insertions(+), 60 deletions(-)

diff --git a/mitmproxy/addons/eventstore.py b/mitmproxy/addons/eventstore.py
index 4e410c98..ff8429d7 100644
--- a/mitmproxy/addons/eventstore.py
+++ b/mitmproxy/addons/eventstore.py
@@ -1,6 +1,8 @@
 from typing import List  # noqa
 
 import blinker
+
+from mitmproxy import command
 from mitmproxy.log import LogEntry
 
 
@@ -10,10 +12,14 @@ class EventStore:
         self.sig_add = blinker.Signal()
         self.sig_refresh = blinker.Signal()
 
-    def log(self, entry: LogEntry):
+    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)
diff --git a/mitmproxy/tools/console/consoleaddons.py b/mitmproxy/tools/console/consoleaddons.py
index 06ee3341..a10efa51 100644
--- a/mitmproxy/tools/console/consoleaddons.py
+++ b/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")
-        signals.add_log(message.content if isinstance(message.content, str) else strutils.bytes_to_escaped_str(message.content), "debug")
+        ctx.log.info(f.message_info(message))
+        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:
@@ -477,13 +467,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]:
         """
diff --git a/mitmproxy/tools/console/eventlog.py b/mitmproxy/tools/console/eventlog.py
index c3e5dd39..3fc34fa2 100644
--- a/mitmproxy/tools/console/eventlog.py
+++ b/mitmproxy/tools/console/eventlog.py
@@ -1,7 +1,5 @@
 import urwid
-from mitmproxy.tools.console import signals
 from mitmproxy.tools.console import layoutwidget
-from mitmproxy import ctx
 from mitmproxy import log
 
 EVENTLOG_SIZE = 10000
@@ -18,9 +16,10 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
     def __init__(self, master):
         self.walker = LogBufferWalker([])
         self.master = master
-        urwid.ListBox.__init__(self, self.walker)
-        signals.sig_add_log.connect(self.sig_add_log)
-        signals.sig_clear_log.connect(self.sig_clear_log)
+        super().__init__(self.walker)
+        master.events.sig_add.connect(self.add_entry)
+        master.events.sig_refresh.connect(self.refresh_entries)
+        self.refresh_entries(None)
 
     def load(self, loader):
         loader.add_option(
@@ -39,12 +38,12 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
             self.set_focus(0)
         return urwid.ListBox.keypress(self, size, key)
 
-    def sig_add_log(self, sender, e, level):
-        if log.log_tier(ctx.options.verbosity) < log.log_tier(level):
+    def add_entry(self, event_store, entry: log.LogEntry):
+        if log.log_tier(self.master.options.verbosity) < log.log_tier(entry.level):
             return
-        txt = "%s: %s" % (level, str(e))
-        if level in ("error", "warn"):
-            e = urwid.Text((level, txt))
+        txt = "%s: %s" % (entry.level, str(entry.msg))
+        if entry.level in ("error", "warn"):
+            e = urwid.Text((entry.level, txt))
         else:
             e = urwid.Text(txt)
         self.walker.append(e)
@@ -53,5 +52,7 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
         if self.master.options.console_focus_follow:
             self.walker.set_focus(len(self.walker) - 1)
 
-    def sig_clear_log(self, sender):
+    def refresh_entries(self, event_store):
         self.walker[:] = []
+        for event in self.master.events.data:
+            self.add_entry(None, event)
diff --git a/mitmproxy/tools/console/flowview.py b/mitmproxy/tools/console/flowview.py
index 651c4330..89f20875 100644
--- a/mitmproxy/tools/console/flowview.py
+++ b/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)"
diff --git a/mitmproxy/tools/console/master.py b/mitmproxy/tools/console/master.py
index 4c7f9cc1..8c575f9c 100644
--- a/mitmproxy/tools/console/master.py
+++ b/mitmproxy/tools/console/master.py
@@ -16,6 +16,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
@@ -32,6 +33,9 @@ class ConsoleMaster(master.Master):
         super().__init__(opts)
 
         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 +44,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,12 +82,12 @@ class ConsoleMaster(master.Master):
             callback = self.quit,
         )
 
-    def sig_add_log(self, sender, e, level):
-        if log.log_tier(self.options.verbosity) < log.log_tier(level):
+    def sig_add_log(self, event_store, entry: log.LogEntry):
+        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(
-                message = "{}: {}".format(level.title(), e)
+                message="{}: {}".format(entry.level.title(), entry.msg)
             )
 
     def sig_call_in(self, sender, seconds, callback, args=()):
diff --git a/mitmproxy/tools/console/signals.py b/mitmproxy/tools/console/signals.py
index 5d39d96a..9c44b361 100644
--- a/mitmproxy/tools/console/signals.py
+++ b/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()
-- 
cgit v1.2.3


From a5fd4bdb82b0dcb8f49b023216978f2c032d722e Mon Sep 17 00:00:00 2001
From: Maximilian Hils <git@maximilianhils.com>
Date: Thu, 14 Dec 2017 23:22:29 +0100
Subject: console: display errors that happened during startup

---
 mitmproxy/tools/console/master.py | 19 ++++++++++++++++---
 1 file changed, 16 insertions(+), 3 deletions(-)

diff --git a/mitmproxy/tools/console/master.py b/mitmproxy/tools/console/master.py
index 8c575f9c..04c7cc0c 100644
--- a/mitmproxy/tools/console/master.py
+++ b/mitmproxy/tools/console/master.py
@@ -9,6 +9,7 @@ import subprocess
 import sys
 import tempfile
 import traceback
+import typing  # noqa
 
 import urwid
 
@@ -32,6 +33,8 @@ 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)
@@ -86,9 +89,13 @@ class ConsoleMaster(master.Master):
         if log.log_tier(self.options.verbosity) < log.log_tier(entry.level):
             return
         if entry.level in ("error", "warn"):
-            signals.status_message.send(
-                message="{}: {}".format(entry.level.title(), entry.msg)
-            )
+            if self.first_tick:
+                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(*_):
@@ -198,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()
-- 
cgit v1.2.3


From 96ee3d853be68ac7b2852aa8fdf4e0753125f5a7 Mon Sep 17 00:00:00 2001
From: Maximilian Hils <git@maximilianhils.com>
Date: Thu, 14 Dec 2017 23:45:12 +0100
Subject: limit eventstore size

---
 mitmproxy/addons/eventstore.py      | 11 +++++++++++
 mitmproxy/tools/console/eventlog.py |  4 ----
 2 files changed, 11 insertions(+), 4 deletions(-)

diff --git a/mitmproxy/addons/eventstore.py b/mitmproxy/addons/eventstore.py
index ff8429d7..415bd017 100644
--- a/mitmproxy/addons/eventstore.py
+++ b/mitmproxy/addons/eventstore.py
@@ -5,6 +5,8 @@ import blinker
 from mitmproxy import command
 from mitmproxy.log import LogEntry
 
+EVENTLOG_SIZE = 10000
+
 
 class EventStore:
     def __init__(self):
@@ -15,6 +17,15 @@ class EventStore:
     def log(self, entry: LogEntry) -> None:
         self.data.append(entry)
         self.sig_add.send(self, entry=entry)
+        # Instead of removing one log row for every row > EVENTLOG_SIZE we add,
+        # we accept an overhead of 10% and only purge then to simplify the API.
+        if len(self.data) / EVENTLOG_SIZE >= 1.1:
+            self.purge()
+
+    def purge(self):
+        """Purge event store size to EVENTLOG_SIZE"""
+        self.data = self.data[len(self.data) - EVENTLOG_SIZE:]
+        self.sig_refresh.send(self)
 
     @command.command("eventstore.clear")
     def clear(self) -> None:
diff --git a/mitmproxy/tools/console/eventlog.py b/mitmproxy/tools/console/eventlog.py
index 3fc34fa2..49e10dbc 100644
--- a/mitmproxy/tools/console/eventlog.py
+++ b/mitmproxy/tools/console/eventlog.py
@@ -2,8 +2,6 @@ import urwid
 from mitmproxy.tools.console import layoutwidget
 from mitmproxy import log
 
-EVENTLOG_SIZE = 10000
-
 
 class LogBufferWalker(urwid.SimpleListWalker):
     pass
@@ -47,8 +45,6 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
         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)
 
-- 
cgit v1.2.3


From 3ff380054c6627112fc6c0fe0d8e282877fddec9 Mon Sep 17 00:00:00 2001
From: Maximilian Hils <git@maximilianhils.com>
Date: Fri, 15 Dec 2017 01:36:41 +0100
Subject: improve eventstore truncation

---
 mitmproxy/addons/eventstore.py           | 22 ++++++++--------------
 mitmproxy/tools/console/eventlog.py      | 24 +++++++++++++++---------
 test/mitmproxy/addons/test_eventstore.py | 15 +++++++++++++++
 3 files changed, 38 insertions(+), 23 deletions(-)

diff --git a/mitmproxy/addons/eventstore.py b/mitmproxy/addons/eventstore.py
index 415bd017..73ffc70c 100644
--- a/mitmproxy/addons/eventstore.py
+++ b/mitmproxy/addons/eventstore.py
@@ -1,31 +1,25 @@
-from typing import List  # noqa
+import collections
+import typing  # noqa
 
 import blinker
 
 from mitmproxy import command
 from mitmproxy.log import LogEntry
 
-EVENTLOG_SIZE = 10000
-
 
 class EventStore:
-    def __init__(self):
-        self.data = []  # type: List[LogEntry]
+    def __init__(self, size=10000):
+        self.data = collections.deque(maxlen=size)  # type: typing.Deque[LogEntry]
         self.sig_add = blinker.Signal()
         self.sig_refresh = blinker.Signal()
 
+    @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)
-        # Instead of removing one log row for every row > EVENTLOG_SIZE we add,
-        # we accept an overhead of 10% and only purge then to simplify the API.
-        if len(self.data) / EVENTLOG_SIZE >= 1.1:
-            self.purge()
-
-    def purge(self):
-        """Purge event store size to EVENTLOG_SIZE"""
-        self.data = self.data[len(self.data) - EVENTLOG_SIZE:]
-        self.sig_refresh.send(self)
 
     @command.command("eventstore.clear")
     def clear(self) -> None:
diff --git a/mitmproxy/tools/console/eventlog.py b/mitmproxy/tools/console/eventlog.py
index 49e10dbc..a5d058a1 100644
--- a/mitmproxy/tools/console/eventlog.py
+++ b/mitmproxy/tools/console/eventlog.py
@@ -1,3 +1,5 @@
+import collections
+
 import urwid
 from mitmproxy.tools.console import layoutwidget
 from mitmproxy import log
@@ -12,12 +14,16 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
     title = "Events"
 
     def __init__(self, master):
-        self.walker = LogBufferWalker([])
         self.master = master
+        self.walker = LogBufferWalker(
+            collections.deque(maxlen=self.master.events.size)
+        )
+
+        master.events.sig_add.connect(self.add_event)
+        master.events.sig_refresh.connect(self.refresh_events)
+        self.refresh_events()
+
         super().__init__(self.walker)
-        master.events.sig_add.connect(self.add_entry)
-        master.events.sig_refresh.connect(self.refresh_entries)
-        self.refresh_entries(None)
 
     def load(self, loader):
         loader.add_option(
@@ -34,9 +40,9 @@ 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 add_entry(self, event_store, entry: log.LogEntry):
+    def add_event(self, event_store, entry: log.LogEntry):
         if log.log_tier(self.master.options.verbosity) < log.log_tier(entry.level):
             return
         txt = "%s: %s" % (entry.level, str(entry.msg))
@@ -48,7 +54,7 @@ class EventLog(urwid.ListBox, layoutwidget.LayoutWidget):
         if self.master.options.console_focus_follow:
             self.walker.set_focus(len(self.walker) - 1)
 
-    def refresh_entries(self, event_store):
-        self.walker[:] = []
+    def refresh_events(self, event_store=None):
+        self.walker.clear()
         for event in self.master.events.data:
-            self.add_entry(None, event)
+            self.add_event(None, event)
diff --git a/test/mitmproxy/addons/test_eventstore.py b/test/mitmproxy/addons/test_eventstore.py
index f54b9980..8ac26b05 100644
--- a/test/mitmproxy/addons/test_eventstore.py
+++ b/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]
-- 
cgit v1.2.3