Merge lp:~allenap/maas/normalise-logging--bug-1639182 into lp:maas/trunk

Proposed by Gavin Panella
Status: Merged
Approved by: Andres Rodriguez
Approved revision: 5541
Merged at revision: 5541
Proposed branch: lp:~allenap/maas/normalise-logging--bug-1639182
Merge into: lp:maas/trunk
Diff against target: 410 lines (+148/-113)
4 files modified
src/provisioningserver/logger/_common.py (+1/-1)
src/provisioningserver/logger/_twisted.py (+55/-24)
src/provisioningserver/logger/tests/test__twisted.py (+87/-83)
src/provisioningserver/logger/tests/test_logger.py (+5/-5)
To merge this branch: bzr merge lp:~allenap/maas/normalise-logging--bug-1639182
Reviewer Review Type Date Requested Status
Andres Rodriguez (community) Approve
Blake Rouse (community) Needs Information
Review via email: mp+310188@code.launchpad.net

Commit message

Change the logging format to be similar between regiond.log, rackd.log, and maas.log.

To post a comment you must log in.
Revision history for this message
Gavin Panella (allenap) wrote :

This monkey-patches the legacy log emitter to use DEFAULT_LOG_FORMAT, so future changes to logging format will be easier.

Having said that... because we're in a transnational state in Twisted between the legacy and modern systems... this code completely doesn't have the intended effect in Twisted 16.4 (which is found in Yakkety).

Revision history for this message
Blake Rouse (blake-rouse) wrote :

Looks good. I tried to get this to work on Friday and was lost. I really dont think twisted could have made logging any more complicated.

This is good enough for the SRU to Xenial, but we need to get this fixes in yacketty as well. ETA on that, possible to do in the branch. So we can get it done in one pass. We need to release 2.1.1 today.

review: Needs Information
Revision history for this message
Gavin Panella (allenap) wrote :

> Looks good. I tried to get this to work on Friday and was lost. I
> really dont think twisted could have made logging any more
> complicated.

I'm right with you on this. My only hope for this is that it'll get a
lot simpler once t.p.log is gone.

> This is good enough for the SRU to Xenial, but we need to get this
> fixes in yacketty as well. ETA on that, possible to do in the branch.
> So we can get it done in one pass. We need to release 2.1.1 today.

I've been hitting my head against the wall with doing this in Yakkety.
I'll land this but we're just going to have to live with funny log for a
bit longer in Yakkety.

On the other hand, do we need to do this at all? The message format has
not changed through the recent logging changes. Do we actually need to
change it now before we can release?

Revision history for this message
Blake Rouse (blake-rouse) wrote :

Yes we need to get this correct before release of 2.1.1. As we are SRU'ing 2.1.1 to Xenial. Mark wants the SRU finished by the end of this week. So we need to release ASAP. This 2.1.1 will also require an SRU to yakketty so we should make this work in yakketty as well.

Revision history for this message
Andres Rodriguez (andreserl) wrote :

The format has changed between 2.1.0 and what will be 2.1.1. So I'm fine landing this for xenial and we will address it for yakkety afterwards.

We need to have a serious discussion how we can overall improve the logging system.

review: Approve
Revision history for this message
Gavin Panella (allenap) wrote :

> We need to have a serious discussion how we can overall improve the
> logging system.

Let me kick it off.

There has been pain in all parts of the stack: Django, Twisted, and the
standard library all do stupid things that we need to work around. I've
been able to contain the ugliness to the p.logger package.

The logs that Django and `logging` produce and those that Twisted
produce are integrated only when they hit the log file. Logs from one
subsystem are not shipped from `logging` to Twisted or vice-versa. There
is an adapter that can pipe Twisted's logs over to the standard library
but it's too lossy right now, and it's not clear that it'll help much
anyway.

Twisted has just one idea of what a log should look like. It doesn't
care about customising the textual output, though it does provide the
means to write your own log event[1] observer and so emit rot-13 logs to
a thermal printer on a pidgeon. It's neither right nor wrong, just a
different approach to that of the stdlib's `logging` package.

This bug in particular has been painful for a couple of reasons:

1. I'm trying to do it the "wrong" way with Twisted. When invoking a
   plugin via twistd the "right" way to customise logging output is to
   specify an observer via `--logger=fully.qualified.callable`.

2. As I've mentioned before, Twisted is in a transitional state between
   its "legacy" and "modern" logging subsystems. There's a lot of
   complexity behind the scenes to make this work, and significant
   change between Twisted in Xenial and Yakkety.

I've been trying to avoid #1 so far, to keep the details hidden, but no
longer. The changes between Twisted 16.0 (Xenial) and 16.4 (Yakkety)
means this is likely to be the only sane way to achieve what we want,
and this is what I'll work on now.

[1] A log *event* is a dict containing some standard keys and any number
of other pieces of information, passed between log observers. One such
observer might filter events, one might forward events to multiple
observers, one might format the event and write it out to a log file.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'src/provisioningserver/logger/_common.py'
2--- src/provisioningserver/logger/_common.py 2016-10-28 15:58:32 +0000
3+++ src/provisioningserver/logger/_common.py 2016-11-07 14:38:23 +0000
4@@ -21,7 +21,7 @@
5
6 # This format roughly matches Twisted's default, so that combined Twisted and
7 # Django logs are consistent with one another.
8-DEFAULT_LOG_FORMAT = "%(asctime)s [%(name)s#%(levelname)s] %(message)s"
9+DEFAULT_LOG_FORMAT = "%(asctime)s %(name)s: [%(levelname)s] %(message)s"
10 DEFAULT_LOG_FORMAT_DATE = "%Y-%m-%d %H:%M:%S"
11 DEFAULT_LOG_VERBOSITY_LEVELS = {0, 1, 2, 3}
12 DEFAULT_LOG_VERBOSITY = 2
13
14=== modified file 'src/provisioningserver/logger/_twisted.py'
15--- src/provisioningserver/logger/_twisted.py 2016-11-03 21:11:05 +0000
16+++ src/provisioningserver/logger/_twisted.py 2016-11-07 14:38:23 +0000
17@@ -15,6 +15,7 @@
18
19 import crochet
20 from provisioningserver.logger._common import (
21+ DEFAULT_LOG_FORMAT,
22 DEFAULT_LOG_FORMAT_DATE,
23 DEFAULT_LOG_VERBOSITY,
24 DEFAULT_LOG_VERBOSITY_LEVELS,
25@@ -28,6 +29,7 @@
26 log as twistedLegacy,
27 usage,
28 )
29+from twisted.python.util import untilConcludes
30
31 # Map verbosity numbers to `twisted.logger` levels.
32 DEFAULT_TWISTED_VERBOSITY_LEVELS = {
33@@ -117,12 +119,10 @@
34 twistedModern.globalLogBeginner.showwarning = warnings.showwarning
35 twistedLegacy.theLogPublisher.showwarning = warnings.showwarning
36
37- # Globally override Twisted's log date format. It's tricky to get to the
38- # FileLogObserver that twistd installs so that we can modify its config
39- # alone, but we actually do want to make a global change anyway.
40- warn_unless(hasattr(twistedLegacy.FileLogObserver, "timeFormat"), (
41- "No FileLogObserver.timeFormat attribute found; please investigate!"))
42- twistedLegacy.FileLogObserver.timeFormat = DEFAULT_LOG_FORMAT_DATE
43+ # Globally override Twisted's legacy logging format.
44+ warn_unless(hasattr(twistedLegacy, "FileLogObserver"), (
45+ "No t.p.log.FileLogObserver attribute found; please investigate!"))
46+ LegacyFileLogObserver.install()
47
48 # Install a wrapper so that log events from `t.logger` are logged with a
49 # namespace and level by the legacy logger in `t.python.log`. This needs
50@@ -157,18 +157,55 @@
51 twistedLegacy.startLogging(sys.__stdout__, setStdout=False)
52
53
54+class LegacyFileLogObserver(twistedLegacy.FileLogObserver):
55+ """Log legacy/mixed events to a file, formatting the MAAS way."""
56+
57+ timeFormat = DEFAULT_LOG_FORMAT_DATE
58+ lineFormat = DEFAULT_LOG_FORMAT + "\n"
59+
60+ @classmethod
61+ def install(cls):
62+ """Install this wrapper in place of `log.FileLogObserver`."""
63+ twistedLegacy.FileLogObserver = cls
64+
65+ def emit(self, event):
66+ """Format and write out the given `event`."""
67+ text = twistedLegacy.textFromEventDict(event)
68+ if text is None:
69+ return
70+
71+ system = event["system"] if "system" in event else None
72+ if system is None and "log_namespace" in event:
73+ system = event["log_namespace"]
74+ # Logs written directly to `t.p.log.logfile` and `.logerr` get a
75+ # namespace of "twisted.python.log". This is not interesting.
76+ if system == twistedLegacy.__name__:
77+ system = None
78+
79+ level = event["log_level"] if "log_level" in event else None
80+ if level is None:
81+ if "isError" in event and event["isError"]:
82+ level = twistedModern.LogLevel.critical
83+ else:
84+ level = twistedModern.LogLevel.info
85+
86+ line = twistedLegacy._safeFormat(self.lineFormat, {
87+ "asctime": self.formatTime(event["time"]),
88+ "levelname": "-" if level is None else level.name,
89+ "message": text.replace("\n", "\n\t"),
90+ "name": "-" if system is None else system,
91+ })
92+
93+ untilConcludes(self.write, line)
94+ untilConcludes(self.flush)
95+
96+
97 class LegacyLogObserverWrapper(twistedModern.LegacyLogObserverWrapper):
98 """Ensure that `log_system` is set in the event.
99
100- This mimics what `twisted.logger.formatEventAsClassicLogText` does when
101- `log_system` is not set, and constructs it from `log_namespace` and
102- `log_level`.
103-
104- This `log_system` value is then seen by `LegacyLogObserverWrapper` and
105- copied into the `system` key and then printed out in the logs by Twisted's
106- legacy logging (`t.python.log`) machinery. This still used by `twistd`, so
107- the net effect is that the logger's namespace and level are printed to the
108- `twistd` log.
109+ A newly populated `log_system` value is seen by `LegacyLogObserverWrapper`
110+ (the superclass) and copied into the `system` key, later used when emitting
111+ formatted log lines.
112 """
113
114 @classmethod
115@@ -185,17 +222,11 @@
116
117 def __call__(self, event):
118 # Be defensive: `system` could be missing or could have a value of
119- # None. Same goes for `log_system`, `log_namespace`, and `log_level`.
120+ # None. Same goes for `log_system` and `log_namespace`.
121 if event.get("system") is None and event.get("log_system") is None:
122 namespace = event.get("log_namespace")
123- # Logs written directly to `t.p.log.logfile` and `.logerr` get a
124- # namespace of "twisted.python.log". This is not interesting.
125- if namespace == twistedLegacy.__name__:
126- namespace = None
127- level = event.get("log_level")
128- event["log_system"] = "{namespace}#{level}".format(
129- namespace=("-" if namespace is None else namespace),
130- level=("-" if level is None else level.name))
131+ if namespace is not None:
132+ event["log_system"] = namespace
133 # Up-call, which will apply some more transformations.
134 return super().__call__(event)
135
136
137=== modified file 'src/provisioningserver/logger/tests/test__twisted.py'
138--- src/provisioningserver/logger/tests/test__twisted.py 2016-11-02 10:01:16 +0000
139+++ src/provisioningserver/logger/tests/test__twisted.py 2016-11-07 14:38:23 +0000
140@@ -17,6 +17,7 @@
141 from maastesting.testcase import MAASTestCase
142 from maastesting.twisted import TwistedLoggerFixture
143 from provisioningserver.logger._twisted import (
144+ LegacyFileLogObserver,
145 LegacyLogger,
146 LegacyLogObserverWrapper,
147 observe_twisted_internet_tcp,
148@@ -57,6 +58,80 @@
149 log.theLogPublisher.addObserver(observer)
150
151
152+class TestLegacyFileLogObserver(MAASTestCase):
153+ """Scenario tests for `LegacyFileLogObserver`."""
154+
155+ scenarios = tuple(
156+ (log_level.name, dict(log_level=log_level))
157+ for log_level in logger.LogLevel.iterconstants()
158+ )
159+
160+ def test__namespace_and_level_is_printed_in_legacy_log(self):
161+ # Restore existing observers at the end. This must be careful with
162+ # ordering of clean-ups, hence the use of unittest.mock.patch.object
163+ # as a context manager.
164+ self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
165+ # The global non-legacy `LogBeginner` emits critical messages straight
166+ # to stderr, so temporarily put aside its observer to avoid seeing the
167+ # critical log messages we're going to generate.
168+ self.patch(logger.globalLogPublisher, "_observers", [])
169+
170+ logbuffer = io.StringIO()
171+ observer = LegacyFileLogObserver(logbuffer)
172+ observer.formatTime = lambda when: "<timestamp>"
173+
174+ oldlog = log.msg
175+ # Deliberately use the default global observer in the new logger
176+ # because we want to see how it behaves in a typical environment where
177+ # logs are being emitted by the legacy logging infrastructure, for
178+ # example running under `twistd`.
179+ newlog = partial(logger.Logger().emit, self.log_level)
180+
181+ with patch.object(
182+ log, "LegacyLogObserverWrapper",
183+ log.LegacyLogObserverWrapper):
184+ setLegacyObservers([observer.emit])
185+ oldlog("Message from legacy", system="legacy")
186+ newlog("Message from modern", log_system="modern")
187+
188+ self.assertThat(
189+ logbuffer.getvalue(), DocTestMatches("""\
190+ <timestamp> legacy: [info] Message from legacy
191+ <timestamp> modern: [%s] Message from modern
192+ """ % self.log_level.name))
193+
194+
195+class TestLegacyFileLogObserver_Other(MAASTestCase):
196+ """Other tests for `LegacyFileLogObserver`."""
197+
198+ def test__namespace_is_not_emitted_via_logfile_logerr(self):
199+ # Restore existing observers at the end. This must be careful with
200+ # ordering of clean-ups, hence the use of unittest.mock.patch.object
201+ # as a context manager.
202+ self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
203+ # The global non-legacy `LogBeginner` emits critical messages straight
204+ # to stderr, so temporarily put aside its observer to avoid seeing the
205+ # critical log messages we're going to generate.
206+ self.patch(logger.globalLogPublisher, "_observers", [])
207+
208+ logbuffer = io.StringIO()
209+ observer = LegacyFileLogObserver(logbuffer)
210+ observer.formatTime = lambda when: "<timestamp>"
211+
212+ with patch.object(
213+ log, "LegacyLogObserverWrapper",
214+ log.LegacyLogObserverWrapper):
215+ setLegacyObservers([observer.emit])
216+ log.logfile.write("Via log.logfile\n")
217+ log.logerr.write("Via log.logerr\n")
218+
219+ self.assertThat(
220+ logbuffer.getvalue(), DocTestMatches("""\
221+ <timestamp> -: [info] Via log.logfile
222+ <timestamp> -: [error] Via log.logerr
223+ """))
224+
225+
226 class TestLegacyLogObserverWrapper(MAASTestCase):
227 """Scenario tests for `LegacyLogObserverWrapper`."""
228
229@@ -72,7 +147,7 @@
230 self.assertThat(events, HasLength(1))
231 return events[0]
232
233- def test__adds_log_system_and_system_to_event(self):
234+ def test__adds_system_to_event(self):
235 self.assertThat(
236 # This is a `twisted.logger` event, not legacy, and requires
237 # values for `log_time` and `log_level` at a minimum.
238@@ -80,10 +155,10 @@
239 "log_time": sentinel.log_time,
240 "log_level": self.log_level,
241 }),
242- ContainsDictByEquality({
243- "log_system": "-#" + self.log_level.name,
244- "system": "-#" + self.log_level.name,
245- }),
246+ MatchesAll(
247+ Not(Contains("log_system")),
248+ ContainsDictByEquality({"system": "-"}),
249+ ),
250 )
251
252 def test__adds_log_system_and_system_to_event_with_namespace(self):
253@@ -95,12 +170,12 @@
254 "log_namespace": log_namespace,
255 }),
256 ContainsDictByEquality({
257- "log_system": log_namespace + "#" + self.log_level.name,
258- "system": log_namespace + "#" + self.log_level.name,
259+ "log_system": log_namespace,
260+ "system": log_namespace,
261 }),
262 )
263
264- def test__adds_log_system_and_system_to_legacy_event(self):
265+ def test__adds_system_to_legacy_event(self):
266 self.assertThat(
267 # This is a `twisted.python.log` event, i.e. legacy, and requires
268 # values for `time` and `isError` at a minimum.
269@@ -108,10 +183,10 @@
270 "time": sentinel.time,
271 "isError": factory.pick_bool(),
272 }),
273- ContainsDictByEquality({
274- "log_system": "-#-",
275- "system": "-#-",
276- }),
277+ MatchesAll(
278+ Not(Contains("log_system")),
279+ ContainsDictByEquality({"system": "-"}),
280+ ),
281 )
282
283 def test__preserves_log_system_in_event(self):
284@@ -146,77 +221,6 @@
285 ),
286 )
287
288- def test__namespace_and_level_is_printed_in_legacy_log(self):
289- # Restore existing observers at the end. This must be careful with
290- # ordering of clean-ups, hence the use of unittest.mock.patch.object
291- # as a context manager.
292- self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
293- # The global non-legacy `LogBeginner` emits critical messages straight
294- # to stderr, so temporarily put aside its observer to avoid seeing the
295- # critical log messages we're going to generate.
296- self.patch(logger.globalLogPublisher, "_observers", [])
297-
298- logbuffer = io.StringIO()
299- observer = log.FileLogObserver(logbuffer)
300- observer.formatTime = lambda when: "<timestamp>"
301-
302- oldlog = log.msg
303- # Deliberately use the default global observer in the new logger
304- # because we want to see how it behaves in a typical environment where
305- # logs are being emitted by the legacy logging infrastructure, for
306- # example running under `twistd`.
307- newlog = partial(logger.Logger().emit, self.log_level)
308-
309- with patch.object(
310- log, "LegacyLogObserverWrapper",
311- log.LegacyLogObserverWrapper):
312- setLegacyObservers([observer.emit])
313- oldlog("Before (legacy)")
314- newlog("Before (new)")
315- LegacyLogObserverWrapper.install()
316- oldlog("After (legacy)")
317- newlog("After (new)")
318-
319- self.assertThat(
320- logbuffer.getvalue(), DocTestMatches("""\
321- <timestamp> [-] Before (legacy)
322- <timestamp> [-] Before (new)
323- <timestamp> [-] After (legacy)
324- <timestamp> [%s#%s] After (new)
325- """ % (__name__, self.log_level.name)))
326-
327- def test__namespace_and_level_are_elided_via_logfile_logerr(self):
328- # Restore existing observers at the end. This must be careful with
329- # ordering of clean-ups, hence the use of unittest.mock.patch.object
330- # as a context manager.
331- self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
332- # The global non-legacy `LogBeginner` emits critical messages straight
333- # to stderr, so temporarily put aside its observer to avoid seeing the
334- # critical log messages we're going to generate.
335- self.patch(logger.globalLogPublisher, "_observers", [])
336-
337- logbuffer = io.StringIO()
338- observer = log.FileLogObserver(logbuffer)
339- observer.formatTime = lambda when: "<timestamp>"
340-
341- with patch.object(
342- log, "LegacyLogObserverWrapper",
343- log.LegacyLogObserverWrapper):
344- setLegacyObservers([observer.emit])
345- log.logfile.write("Before (via log.logfile)\n")
346- log.logerr.write("Before (via log.logerr)\n")
347- LegacyLogObserverWrapper.install()
348- log.logfile.write("After (via log.logfile)\n")
349- log.logerr.write("After (via log.logerr)\n")
350-
351- self.assertThat(
352- logbuffer.getvalue(), DocTestMatches("""\
353- <timestamp> [-] Before (via log.logfile)
354- <timestamp> [-] Before (via log.logerr)
355- <timestamp> [-#info] After (via log.logfile)
356- <timestamp> [-#error] After (via log.logerr)
357- """))
358-
359
360 class TestLegacyLogObserverWrapper_Installation(MAASTestCase):
361 """Tests for `LegacyLogObserverWrapper`."""
362
363=== modified file 'src/provisioningserver/logger/tests/test_logger.py'
364--- src/provisioningserver/logger/tests/test_logger.py 2016-11-03 21:39:45 +0000
365+++ src/provisioningserver/logger/tests/test_logger.py 2016-11-07 14:38:23 +0000
366@@ -42,7 +42,7 @@
367
368 # Matches lines like: 2016-10-18 14:23:55 [namespace#level] message
369 find_log_lines_re = re.compile(
370- r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) [[](.*?)(?:#(.*))?[]] (.*)$",
371+ r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (.*?): [[](.*)[]] (.*)$",
372 re.MULTILINE)
373
374
375@@ -106,7 +106,7 @@
376 (name, 'info', 'From `twisted.logger`.'),
377 (name, 'warn', 'From `twisted.logger`.'),
378 (name, 'error', 'From `twisted.logger`.'),
379- (name, '', 'From `twisted.python.log`.'),
380+ (name, 'info', 'From `twisted.python.log`.'),
381 (name, 'info', 'From `logging`.'),
382 (name, 'warn', 'From `logging`.'),
383 (name, 'error', 'From `logging`.'),
384@@ -132,7 +132,7 @@
385 (name, 'info', 'From `twisted.logger`.'),
386 (name, 'warn', 'From `twisted.logger`.'),
387 (name, 'error', 'From `twisted.logger`.'),
388- (name, '', 'From `twisted.python.log`.'),
389+ (name, 'info', 'From `twisted.python.log`.'),
390 (name, 'debug', 'From `logging`.'),
391 (name, 'info', 'From `logging`.'),
392 (name, 'warn', 'From `logging`.'),
393@@ -195,7 +195,7 @@
394 (name, 'info', 'From `twisted.logger`.'),
395 (name, 'warn', 'From `twisted.logger`.'),
396 (name, 'error', 'From `twisted.logger`.'),
397- (name, '', 'From `twisted.python.log`.'),
398+ (name, 'info', 'From `twisted.python.log`.'),
399 (name, 'info', 'From `logging`.'),
400 (name, 'warn', 'From `logging`.'),
401 (name, 'error', 'From `logging`.'),
402@@ -224,7 +224,7 @@
403 (name, 'info', 'From `twisted.logger`.'),
404 (name, 'warn', 'From `twisted.logger`.'),
405 (name, 'error', 'From `twisted.logger`.'),
406- (name, '', 'From `twisted.python.log`.'),
407+ (name, 'info', 'From `twisted.python.log`.'),
408 (name, 'debug', 'From `logging`.'),
409 (name, 'info', 'From `logging`.'),
410 (name, 'warn', 'From `logging`.'),