Merge lp:~thomir-deactivatedaccount/autopilot/fix-verbose-log-timestamps into lp:autopilot

[Thomi Richards]

Verbose log now includes timestamps.

Problem:

The verbose log does not contain any timestamps, while the same content in the file log does. These two should be the same.

Solution:

Fix a typo that was preventing the verbose log from showing timestamps.

Tests:

There's a new test suite that covers this new behavior.

[lp:~thomir-deactivatedaccount/autopilot/fix-verbose-log-timestamps]

106. By Thomi Richards on 2012-12-04

Make regex more specific.

[Christopher Lee (veebers)]

review: Approve

=== modified file 'autopilot/testcase.py'
--- autopilot/testcase.py	2012-10-29 11:10:01 +0000
+++ autopilot/testcase.py	2012-12-04 02:28:21 +0000
@@ -99,13 +99,14 @@
         self._log_buffer = StringIO()
         root_logger = logging.getLogger()
         root_logger.setLevel(logging.DEBUG)
+        log_format = "%(asctime)s %(levelname)s %(module)s:%(lineno)d - %(message)s"
+        formatter = MyFormatter(log_format)
         handler = logging.StreamHandler(stream=self._log_buffer)
-        log_format = "%(asctime)s %(levelname)s %(module)s:%(lineno)d - %(message)s"
-        handler.setFormatter(MyFormatter(log_format))
+        handler.setFormatter(formatter)
         root_logger.addHandler(handler)
         if get_log_verbose():
             stderr_handler = logging.StreamHandler(stream=sys.stderr)
-            handler.setFormatter(MyFormatter(log_format))
+            stderr_handler.setFormatter(formatter)
             root_logger.addHandler(stderr_handler)
 
         #Tear down logging in a cleanUp handler, so it's done after all other
 
=== modified file 'autopilot/tests/test_autopilot_functional.py'
--- autopilot/tests/test_autopilot_functional.py	2012-11-14 21:38:12 +0000
+++ autopilot/tests/test_autopilot_functional.py	2012-12-04 02:28:21 +0000
@@ -18,7 +18,7 @@
 from tempfile import mktemp, mkdtemp
 from testtools.content import Content, text_content
 from testtools.content_type import ContentType
-from testtools.matchers import Contains, Equals
+from testtools.matchers import Contains, Equals, MatchesRegex
 from textwrap import dedent
 import re
 
@@ -382,6 +382,24 @@
         self.assertThat(code, Equals(0))
         self.assertThat(error, Contains("Starting test tests.test_simple.SimpleTest.test_simple"))
 
+    def test_verbose_flag_shows_timestamps(self):
+        """Verbose log must include timestamps."""
+        self.create_test_file("test_simple.py", dedent("""\
+
+            from autopilot.testcase import AutopilotTestCase
+
+
+            class SimpleTest(AutopilotTestCase):
+
+                def test_simple(self):
+                    pass
+            """
+            ))
+
+        code, output, error = self.run_autopilot(["run", "-v", "tests"])
+
+        self.assertThat(error, MatchesRegex("^\d\d:\d\d:\d\d\.\d\d\d"))
+
     def test_record_flag_works(self):
         """Must be able to record videos when the -r flag is present."""
         self.create_test_file("test_simple.py", dedent("""\