From e86f371b93442d659e01a9bbb1dccddffad64d99 Mon Sep 17 00:00:00 2001
From: David Wilson <dw@botanicus.net>
Date: Sun, 18 Aug 2019 00:59:34 +0100
Subject: [PATCH] issue #621: send ADD_ROUTE earlier and add test for early
 logging.

Logs were broken because ADD_ROUTE was being sent *after* messages
started flowing from the new child. That's an explicit non-goal of the
design, so fix it.
---
 mitogen/parent.py         |  2 +-
 tests/log_handler_test.py | 90 +++++++++++++++++++++++++++++++++++++++
 2 files changed, 91 insertions(+), 1 deletion(-)
 create mode 100644 tests/log_handler_test.py

diff --git a/mitogen/parent.py b/mitogen/parent.py
index 9f93571b..6e99bb66 100644
--- a/mitogen/parent.py
+++ b/mitogen/parent.py
@@ -1546,6 +1546,7 @@ class Connection(object):
                     remote_id=self.context.context_id,
                 )
             )
+            self._router.route_monitor.notice_stream(self.stdio_stream)
         self.latch.put()
 
     def _fail_connection(self, exc):
@@ -2423,7 +2424,6 @@ class Router(mitogen.core.Router):
         except mitogen.core.TimeoutError:
             raise mitogen.core.StreamError(self.connection_timeout_msg)
 
-        self.route_monitor.notice_stream(conn.stdio_stream)
         return context
 
     def connect(self, method_name, name=None, **kwargs):
diff --git a/tests/log_handler_test.py b/tests/log_handler_test.py
new file mode 100644
index 00000000..c5d257a9
--- /dev/null
+++ b/tests/log_handler_test.py
@@ -0,0 +1,90 @@
+
+import logging
+import mock
+
+import unittest2
+import testlib
+import mitogen.core
+import mitogen.master
+import mitogen.parent
+import mitogen.utils
+from mitogen.core import b
+
+
+def ping():
+    pass
+
+
+class BufferingTest(testlib.TestCase):
+    klass = mitogen.core.LogHandler
+
+    def record(self):
+        return logging.LogRecord(
+            name='name',
+            level=99,
+            pathname='pathname',
+            lineno=123,
+            msg='msg',
+            args=(),
+            exc_info=None,
+        )
+
+    def build(self):
+        context = mock.Mock()
+        return context, self.klass(context)
+
+    def test_initially_buffered(self):
+        context, handler = self.build()
+        rec = self.record()
+        handler.emit(rec)
+        self.assertEquals(0, context.send.call_count)
+        self.assertEquals(1, len(handler._buffer))
+
+    def test_uncork(self):
+        context, handler = self.build()
+        rec = self.record()
+        handler.emit(rec)
+        handler.uncork()
+
+        self.assertEquals(1, context.send.call_count)
+        self.assertEquals(None, handler._buffer)
+
+        _, args, _ = context.send.mock_calls[0]
+        msg, = args
+
+        self.assertEquals(mitogen.core.FORWARD_LOG, msg.handle)
+        self.assertEquals(b('name\x0099\x00msg'), msg.data)
+
+
+class StartupTest(testlib.RouterMixin, testlib.TestCase):
+    def test_earliest_messages_logged(self):
+        log = testlib.LogCapturer()
+        log.start()
+
+        c1 = self.router.local()
+        c1.shutdown(wait=True)
+
+        logs = log.stop()
+        self.assertTrue('Python version is' in logs)
+        self.assertTrue('Parent is context 0 (master)' in logs)
+
+    def test_earliest_messages_logged_via(self):
+        c1 = self.router.local(name='c1')
+        # ensure any c1-related msgs are processed before beginning capture.
+        c1.call(ping)
+
+        log = testlib.LogCapturer()
+        log.start()
+
+        c2 = self.router.local(via=c1, name='c2', debug=True)
+        c2.shutdown(wait=True)
+
+        logs = log.stop()
+        self.assertTrue('Python version is' in logs)
+
+        expect = 'Parent is context %s (%s)' % (c1.context_id, 'parent')
+        self.assertTrue(expect in logs)
+
+
+if __name__ == '__main__':
+    unittest2.main()