Format captured log records immediately to have consistent formatting…

… of mutables.

This is a fix for #561

nose/plugins/logcapture.py

@@ -16,7 +16,7 @@
 """
 
 import logging
-from logging.handlers import BufferingHandler
+from logging import Handler
 import threading
 
 from nose.plugins.base import Plugin
@@ -71,12 +71,15 @@ def _deny(self, record):
         return self._any_match(self.exclusive, record)
 
 
-class MyMemoryHandler(BufferingHandler):
-    def __init__(self, capacity, logformat, logdatefmt, filters):
-        BufferingHandler.__init__(self, capacity)
+class MyMemoryHandler(Handler):
+    def __init__(self, logformat, logdatefmt, filters):
+        Handler.__init__(self)
         fmt = logging.Formatter(logformat, logdatefmt)
         self.setFormatter(fmt)
         self.filterset = FilterSet(filters)
+        self.buffer = []
+    def emit(self, record):
+        self.buffer.append(self.format(record))
     def flush(self):
         pass # do nothing
     def truncate(self):
@@ -200,7 +203,7 @@ def begin(self):
         self.start()
 
     def start(self):
-        self.handler = MyMemoryHandler(1000, self.logformat, self.logdatefmt,
+        self.handler = MyMemoryHandler(self.logformat, self.logdatefmt,
                                        self.filters)
         self.setupLoghandler()
 
@@ -233,8 +236,7 @@ def formatError(self, test, err):
         return (ec, self.addCaptureToErr(ev, records), tb)
 
     def formatLogRecords(self):
-        format = self.handler.format
-        return [safe_str(format(r)) for r in self.handler.buffer]
+        return map(safe_str, self.handler.buffer)
 
     def addCaptureToErr(self, ev, records):
         return '\n'.join([safe_str(ev), ln('>> begin captured logging <<')] + \

unit_tests/test_logcapture_plugin.py

@@ -77,7 +77,24 @@ def test_captures_logging(self):
         log.debug("Hello")
         c.end()
         eq_(1, len(c.handler.buffer))
-        eq_("Hello", c.handler.buffer[0].msg)
+        eq_("foobar.something: DEBUG: Hello", c.handler.buffer[0])
+
+    def test_consistent_mutables(self):
+        c = LogCapture()
+        parser = OptionParser()
+        c.addOptions(parser)
+        c.start()
+        log = logging.getLogger("mutable")
+        mutable = { 'value': 1 }
+        log.debug("%r", mutable)
+        repr_1 = repr(mutable)
+        mutable['value'] = 2
+        log.debug("%r", mutable)
+        repr_2 = repr(mutable)
+        c.end()
+        records = c.formatLogRecords()
+        eq_("mutable: DEBUG: %s" % (repr_1,), records[0])
+        eq_("mutable: DEBUG: %s" % (repr_2,), records[1])
 
     def test_loglevel(self):
         c = LogCapture()
@@ -92,7 +109,7 @@ def test_loglevel(self):
         c.end()
         records = c.formatLogRecords()
         eq_(1, len(c.handler.buffer))
-        eq_("Goodbye", c.handler.buffer[0].msg)
+        eq_("loglevel: INFO: Goodbye", c.handler.buffer[0])
         eq_("loglevel: INFO: Goodbye", records[0])
 
     def test_clears_all_existing_log_handlers(self):