Launchpad itself

Merge lp:~wgrant/launchpad/fix-mocklogger-format-string-crash into lp:launchpad

  1. fix-mocklogger-format-string-crash
  2. Merge into devel
Proposed by William Grant
Status: Merged
Merged at revision: not available
Proposed branch: lp:~wgrant/launchpad/fix-mocklogger-format-string-crash
Merge into: lp:launchpad
Diff against target: None lines
To merge this branch: bzr merge lp:~wgrant/launchpad/fix-mocklogger-format-string-crash
Reviewer Review Type Date Requested Status
Jonathan Lange (community) Approve
Review via email: mp+10902@code.launchpad.net

Commit message

[r=jml][ui=none] (wgrant) Fix bug in MockLogger where format strings without args would raise errors. Also add unit tests for MockLogger.

To post a comment you must log in.
Revision history for this message
William Grant (wgrant) wrote :

= Summary =

MockLogger.log crashes when there are unfilled format string tokens in the message, even if there are no arguments. This is rather bad when an exception handler passes in exc_info=True, and the traceback happens to contain a '%s'.

== Tests ==

Nothing fails due to this bug with Python 2.4, but soyuz-set-of-uploads.txt does with 2.5 (2.4 seems to render the first line of each statement in tracebacks, while 2.5 renders the last).

 $ bin/test -t soyuz-set-of-uploads.txt

I will of course add further tests if requested, but I'm not sure there's much point.

Revision history for this message
Jonathan Lange (jml) wrote :

Thanks for chasing this down.

I personally would prefer to see unit tests for this change (and indeed for mocklogger!) but I don't think that should block the patch. If you do want to add tests, I'm happy to help you write them or at least to review them promptly. If not, let me know and I'll land this patch as-is.

In addition, it would be nice to bring some sanity to the world of fake loggers in Launchpad. It's out of scope for this patch, but if you're feeling particularly keen you could file a bug.

review: Approve
Revision history for this message
William Grant (wgrant) wrote :

On Mon, 2009-08-31 at 06:03 +0000, Jonathan Lange wrote:
> Review: Approve
> Thanks for chasing this down.
>
> I personally would prefer to see unit tests for this change (and indeed
> for mocklogger!) but I don't think that should block the patch. If you
> do want to add tests, I'm happy to help you write them or at least to
> review them promptly. If not, let me know and I'll land this patch
> as-is.

Thanks for the review. I've added tests, and cleaned up the code
slightly. See the attached r9265..9268 diff.

r9268.diff
1=== modified file 'lib/canonical/launchpad/ftests/logger.py'
2--- lib/canonical/launchpad/ftests/logger.py 2009-08-31 05:12:01 +0000
3+++ lib/canonical/launchpad/ftests/logger.py 2009-08-31 08:08:27 +0000
4@@ -7,6 +7,7 @@
5 __all__ = ['MockLogger']
6
7 import logging
8+import sys
9
10 # XXX cprov 20071018: This class should be combined with
11 # launchpad.scripts.logger.FakeLogger at some point.
12@@ -15,23 +16,26 @@
13 """Imitates a logger, but prints to standard output."""
14 loglevel = logging.INFO
15
16+ def __init__(self, outfile=None):
17+ if outfile is None:
18+ outfile = sys.stdout
19+ self.outfile = outfile
20+
21 def setLevel(self, loglevel):
22 self.loglevel = loglevel
23
24 def getEffectiveLevel(self):
25 return self.loglevel
26
27- def log(self, *args, **kwargs):
28- # The standard logger takes a template string as the first argument.
29- log_line = args[0]
30-
31- # Only attempt this if we have arguments.
32- # Otherwise logging messages with string formatting sequences
33- # will die.
34- if len(args) > 1:
35- log_line %= args[1:]
36-
37- print "log> ", log_line
38+ def log(self, msg, *args, **kwargs):
39+ # The standard logger takes a template string as the first
40+ # argument, but we must only attempt to use it as one if we have
41+ # arguments. Otherwise logging of messages with string formatting
42+ # sequences will die.
43+ if len(args) > 0:
44+ msg %= args
45+
46+ self.outfile.write("log> %s\n" % msg)
47
48 if "exc_info" in kwargs:
49 import sys
50
51=== added file 'lib/canonical/launchpad/ftests/test_mocklogger.py'
52--- lib/canonical/launchpad/ftests/test_mocklogger.py 1970-01-01 00:00:00 +0000
53+++ lib/canonical/launchpad/ftests/test_mocklogger.py 2009-08-31 07:54:08 +0000
54@@ -0,0 +1,73 @@
55+# Copyright 2009 Canonical Ltd. This software is licensed under the
56+# GNU Affero General Public License version 3 (see the file LICENSE).
57+
58+"""Tests for MockLogger."""
59+
60+__metaclass__ = type
61+
62+import logging
63+import unittest
64+from cStringIO import StringIO
65+
66+from canonical.launchpad.ftests.logger import MockLogger
67+
68+
69+class TestMockLogger(unittest.TestCase):
70+ def setUp(self):
71+ self.logger = MockLogger(StringIO())
72+
73+ def assertOutput(self, expected):
74+ self.logger.outfile.seek(0)
75+ self.assertEqual(self.logger.outfile.read(), expected)
76+
77+ def test_log_literal(self):
78+ # If just a string is given, it is printed out literally.
79+ self.logger.log('foo')
80+ self.assertOutput('log> foo\n')
81+
82+ def test_log_with_arguments(self):
83+ # If a format string and arguments are given, string
84+ # formatting is performed.
85+ self.logger.log('foo %s %d', 'bar', 1)
86+ self.assertOutput('log> foo bar 1\n')
87+
88+ def test_log_format_string_without_arguments(self):
89+ # If a format string is given without arguments, string
90+ # formatting is not performed.
91+ self.logger.log('foo %s %d')
92+ self.assertOutput('log> foo %s %d\n')
93+
94+ def test_log_with_format_string_in_exc_info(self):
95+ # If an exception occurs with '%s' in the backtrace, string
96+ # formatting is not attempted (so a crash is avoided).
97+ try:
98+ 1/0 # %s
99+ except Exception:
100+ self.logger.log('foo', exc_info=True)
101+
102+ self.logger.outfile.seek(0)
103+ output = self.logger.outfile.read()
104+ self.assertTrue(output.endswith(
105+ 'ZeroDivisionError: integer division or modulo by zero\n'))
106+ self.assertTrue('1/0 # %s' in output)
107+
108+ def test_setLevel(self):
109+ # setLevel should alter the value returned by getEffectiveLevel.
110+ self.assertEqual(self.logger.getEffectiveLevel(), logging.INFO)
111+ self.logger.setLevel(logging.ERROR)
112+ self.assertEqual(self.logger.getEffectiveLevel(), logging.ERROR)
113+
114+ def test_info_works_with_default_level(self):
115+ # As the default level is INFO, info() should do something by
116+ # default.
117+ self.logger.info('foobar')
118+ self.assertOutput('log> foobar\n')
119+
120+ def test_info_respects_log_level(self):
121+ # If we set the level to ERROR, info() should do nothing.
122+ self.logger.setLevel(logging.ERROR)
123+ self.logger.info('foobar')
124+ self.assertOutput('')
125+
126+def test_suite():
127+ return unittest.TestLoader().loadTestsFromName(__name__)
Revision history for this message
Jonathan Lange (jml) wrote :

> On Mon, 2009-08-31 at 06:03 +0000, Jonathan Lange wrote:
> > Review: Approve
> > Thanks for chasing this down.
> >
> > I personally would prefer to see unit tests for this change (and indeed
> > for mocklogger!) but I don't think that should block the patch. If you
> > do want to add tests, I'm happy to help you write them or at least to
> > review them promptly. If not, let me know and I'll land this patch
> > as-is.
>
> Thanks for the review. I've added tests, and cleaned up the code
> slightly. See the attached r9265..9268 diff.

Beautiful. As a minor style point, please make sure there are two blank lines before 'def test_suite()'.

Once you do that, ping me and I'll submit your branch.

Thanks for going the extra mile.

jml

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'lib/canonical/launchpad/ftests/logger.py'
2--- lib/canonical/launchpad/ftests/logger.py 2009-06-25 05:30:52 +0000
3+++ lib/canonical/launchpad/ftests/logger.py 2009-08-31 05:12:01 +0000
4@@ -23,7 +23,15 @@
5
6 def log(self, *args, **kwargs):
7 # The standard logger takes a template string as the first argument.
8- print "log>", args[0] % args[1:]
9+ log_line = args[0]
10+
11+ # Only attempt this if we have arguments.
12+ # Otherwise logging messages with string formatting sequences
13+ # will die.
14+ if len(args) > 1:
15+ log_line %= args[1:]
16+
17+ print "log> ", log_line
18
19 if "exc_info" in kwargs:
20 import sys