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

Proposed by Gavin Panella
Status: Merged
Approved by: Gavin Panella
Approved revision: 5549
Merged at revision: 5573
Proposed branch: lp:~allenap/maas/normalise-logging--bug-1639182--yakkety
Merge into: lp:maas/trunk
Diff against target: 1003 lines (+347/-405)
9 files modified
services/rackd/run (+2/-1)
services/regiond/run (+3/-1)
services/regiond2/run (+3/-1)
src/provisioningserver/logger/__init__.py (+3/-0)
src/provisioningserver/logger/_twisted.py (+103/-125)
src/provisioningserver/logger/testing/__init__.py (+23/-2)
src/provisioningserver/logger/testing/logsomething.py (+5/-2)
src/provisioningserver/logger/tests/test__twisted.py (+201/-252)
src/provisioningserver/logger/tests/test_logger.py (+4/-21)
To merge this branch: bzr merge lp:~allenap/maas/normalise-logging--bug-1639182--yakkety
Reviewer Review Type Date Requested Status
Blake Rouse (community) Approve
Review via email: mp+310330@code.launchpad.net

Commit message

Log consistently on both Xenial and Yakkety.

Twisted is going through a transition and some of the work done in Xenial for Twisted 16.0 does not have the desired effect in Yakkety with Twisted 16.4, and vice-versa.

Description of the change

This must be read with a corresponding packaging change in
lp:~allenap/maas/packaging.normalise-logging--bug-1639182--yakkety.

To post a comment you must log in.
Revision history for this message
Blake Rouse (blake-rouse) wrote :

Looks good.

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

I think we need to backport this to 2.1 too ?

On Mon, Nov 28, 2016 at 9:48 AM, Blake Rouse <email address hidden>
wrote:

> Review: Approve
>
> Looks good.
>
> Diff comments:
>
> >
> > === modified file 'services/regiond2/run'
> > --- services/regiond2/run 2016-06-22 17:03:02 +0000
> > +++ services/regiond2/run 2016-11-08 16:20:29 +0000
> > @@ -33,4 +33,6 @@
> >
> > # Exec the MAAS API and Web UI Server.
> > script="$(readlink -f bin/twistd.region)"
> > -exec "${script}" --nodaemon --pidfile="" maas-regiond
> > +exec "${script}" \
> > + --logger=provisioningserver.logger.EventLogger \
>
> This made it much easier to connect a custom logger. Less monkey patching
> is always good.
>
> > + --nodaemon --pidfile="" maas-regiond
>
>
> --
> https://code.launchpad.net/~allenap/maas/normalise-
> logging--bug-1639182--yakkety/+merge/310330
> Your team MAAS Committers is subscribed to branch lp:maas.
>

--
Andres Rodriguez
Engineering Manager, MAAS
Canonical USA, Inc.

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

Yes.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'services/rackd/run'
2--- services/rackd/run 2016-03-31 23:34:55 +0000
3+++ services/rackd/run 2016-11-08 16:20:29 +0000
4@@ -30,4 +30,5 @@
5 script="$(readlink -f bin/twistd.rack)"
6
7 exec $(command -v authbind && echo --deep) \
8- "${script}" --nodaemon --pidfile="" maas-rackd
9+ "${script}" --logger=provisioningserver.logger.EventLogger \
10+ --nodaemon --pidfile="" maas-rackd
11
12=== modified file 'services/regiond/run'
13--- services/regiond/run 2016-06-22 17:03:02 +0000
14+++ services/regiond/run 2016-11-08 16:20:29 +0000
15@@ -33,4 +33,6 @@
16
17 # Exec the MAAS API and Web UI Server.
18 script="$(readlink -f bin/twistd.region)"
19-exec "${script}" --nodaemon --pidfile="" maas-regiond
20+exec "${script}" \
21+ --logger=provisioningserver.logger.EventLogger \
22+ --nodaemon --pidfile="" maas-regiond
23
24=== modified file 'services/regiond2/run'
25--- services/regiond2/run 2016-06-22 17:03:02 +0000
26+++ services/regiond2/run 2016-11-08 16:20:29 +0000
27@@ -33,4 +33,6 @@
28
29 # Exec the MAAS API and Web UI Server.
30 script="$(readlink -f bin/twistd.region)"
31-exec "${script}" --nodaemon --pidfile="" maas-regiond
32+exec "${script}" \
33+ --logger=provisioningserver.logger.EventLogger \
34+ --nodaemon --pidfile="" maas-regiond
35
36=== modified file 'src/provisioningserver/logger/__init__.py'
37--- src/provisioningserver/logger/__init__.py 2016-11-04 08:58:00 +0000
38+++ src/provisioningserver/logger/__init__.py 2016-11-08 16:20:29 +0000
39@@ -50,6 +50,7 @@
40
41 __all__ = [
42 "configure",
43+ "EventLogger",
44 "get_maas_logger",
45 "LegacyLogger",
46 "LoggingMode",
47@@ -71,6 +72,7 @@
48 from provisioningserver.logger._tftp import configure_tftp_logging
49 from provisioningserver.logger._twisted import (
50 configure_twisted_logging,
51+ EventLogger,
52 LegacyLogger,
53 set_twisted_verbosity,
54 VerbosityOptions,
55@@ -146,6 +148,7 @@
56 for verbosity_setter in verbosity_setters:
57 verbosity_setter(verbosity)
58
59+
60 verbosity_setters = [
61 set_standard_verbosity,
62 set_twisted_verbosity,
63
64=== modified file 'src/provisioningserver/logger/_twisted.py'
65--- src/provisioningserver/logger/_twisted.py 2016-11-07 20:51:43 +0000
66+++ src/provisioningserver/logger/_twisted.py 2016-11-08 16:20:29 +0000
67@@ -5,6 +5,7 @@
68
69 __all__ = [
70 "configure_twisted_logging",
71+ "EventLogger",
72 "LegacyLogger",
73 "VerbosityOptions",
74 ]
75@@ -29,7 +30,6 @@
76 log as twistedLegacy,
77 usage,
78 )
79-from twisted.python.util import untilConcludes
80
81 # Map verbosity numbers to `twisted.logger` levels.
82 DEFAULT_TWISTED_VERBOSITY_LEVELS = {
83@@ -46,18 +46,6 @@
84 "Twisted verbosity map does not match expectations.")
85
86
87-# Those levels for which we should emit log events.
88-_filterByLevels = frozenset()
89-
90-
91-def _filterByLevel(event):
92- """Only log if event's level is in `_filterByLevels`."""
93- if event.get("log_level") in _filterByLevels:
94- return twistedModern.PredicateResult.maybe
95- else:
96- return twistedModern.PredicateResult.no
97-
98-
99 @typed
100 def set_twisted_verbosity(verbosity: int):
101 """Reconfigure verbosity of the standard library's `logging` module."""
102@@ -83,31 +71,9 @@
103 """
104 set_twisted_verbosity(verbosity)
105
106- # A list of markers for noise.
107- noisy = (
108- {"log_system": "-", "log_text": "Log opened."},
109- {"log_system": "-", "log_text": "Main loop terminated."},
110- )
111-
112- def filterByNoise(event, noisy=noisy):
113- """Only log if event is not noisy."""
114- for noise in noisy:
115- if all(key in event and event[key] == noise[key] for key in noise):
116- return twistedModern.PredicateResult.no
117- else:
118- return twistedModern.PredicateResult.maybe
119-
120- predicates = _filterByLevel, filterByNoise
121-
122- # When `twistd` starts the reactor it initialises the legacy logging
123- # system. Intercept this to wrap the observer in a level filter. We can
124- # use this same approach when not running under `twistd` too.
125- def startLoggingWithObserver(observer, setStdout=1):
126- observer = twistedModern.FilteringLogObserver(observer, predicates)
127- reallyStartLoggingWithObserver(observer, setStdout)
128-
129- reallyStartLoggingWithObserver = twistedLegacy.startLoggingWithObserver
130- twistedLegacy.startLoggingWithObserver = startLoggingWithObserver
131+ warn_unless(hasattr(twistedLegacy, "startLoggingWithObserver"), (
132+ "No startLoggingWithObserver function found; please investigate!"))
133+ twistedLegacy.startLoggingWithObserver = _startLoggingWithObserver
134
135 # Customise warnings behaviour. Ensure that nothing else — neither the
136 # standard library's `logging` module nor Django — clobbers this later.
137@@ -120,17 +86,6 @@
138 twistedModern.globalLogBeginner.showwarning = warnings.showwarning
139 twistedLegacy.theLogPublisher.showwarning = warnings.showwarning
140
141- # Globally override Twisted's legacy logging format.
142- warn_unless(hasattr(twistedLegacy, "FileLogObserver"), (
143- "No t.p.log.FileLogObserver attribute found; please investigate!"))
144- LegacyFileLogObserver.install()
145-
146- # Install a wrapper so that log events from `t.logger` are logged with a
147- # namespace and level by the legacy logger in `t.python.log`. This needs
148- # to be injected into the `t.p.log` module in order to process events as
149- # they move from the legacy to the modern systems.
150- LegacyLogObserverWrapper.install()
151-
152 # Prevent `crochet` from initialising Twisted's logging.
153 warn_unless(hasattr(crochet._main, "_startLoggingWithObserver"), (
154 "No _startLoggingWithObserver function found; please investigate!"))
155@@ -155,81 +110,77 @@
156 # the original standard out stream when this process was started. This
157 # bypasses any wrapping or redirection that may have been done elsewhere.
158 if mode == LoggingMode.COMMAND:
159- twistedLegacy.startLogging(sys.__stdout__, setStdout=False)
160-
161-
162-class LegacyFileLogObserver(twistedLegacy.FileLogObserver):
163- """Log legacy/mixed events to a file, formatting the MAAS way."""
164-
165- timeFormat = DEFAULT_LOG_FORMAT_DATE
166- lineFormat = DEFAULT_LOG_FORMAT + "\n"
167-
168- @classmethod
169- def install(cls):
170- """Install this wrapper in place of `log.FileLogObserver`."""
171- twistedLegacy.FileLogObserver = cls
172-
173- def emit(self, event):
174- """Format and write out the given `event`."""
175- text = twistedLegacy.textFromEventDict(event)
176- if text is None:
177- return
178-
179- system = event["system"] if "system" in event else None
180- if system is None and "log_namespace" in event:
181- system = event["log_namespace"]
182- # Logs written directly to `t.p.log.logfile` and `.logerr` get a
183- # namespace of "twisted.python.log". This is not interesting.
184- if system == twistedLegacy.__name__:
185- system = None
186-
187- level = event["log_level"] if "log_level" in event else None
188- if level is None:
189- if "isError" in event and event["isError"]:
190- level = twistedModern.LogLevel.critical
191- else:
192- level = twistedModern.LogLevel.info
193-
194- line = twistedLegacy._safeFormat(self.lineFormat, {
195- "asctime": self.formatTime(event["time"]),
196- "levelname": "-" if level is None else level.name,
197- "message": text.replace("\n", "\n\t"),
198- "name": "-" if system is None else system,
199- })
200-
201- untilConcludes(self.write, line)
202- untilConcludes(self.flush)
203-
204-
205-class LegacyLogObserverWrapper(twistedModern.LegacyLogObserverWrapper):
206- """Ensure that `log_system` is set in the event.
207-
208- A newly populated `log_system` value is seen by `LegacyLogObserverWrapper`
209- (the superclass) and copied into the `system` key, later used when emitting
210- formatted log lines.
211- """
212-
213- @classmethod
214- def install(cls):
215- """Install this wrapper in place of `log.LegacyLogObserverWrapper`.
216-
217- Inject this wrapper into the `t.python.log` module then remove and
218- re-add all the legacy observers so that they're re-wrapped.
219- """
220- twistedLegacy.LegacyLogObserverWrapper = cls
221- for observer in twistedLegacy.theLogPublisher.observers:
222- twistedLegacy.theLogPublisher.removeObserver(observer)
223- twistedLegacy.theLogPublisher.addObserver(observer)
224-
225- def __call__(self, event):
226- # Be defensive: `system` could be missing or could have a value of
227- # None. Same goes for `log_system` and `log_namespace`.
228- if event.get("system") is None and event.get("log_system") is None:
229- namespace = event.get("log_namespace")
230- if namespace is not None:
231- event["log_system"] = namespace
232- # Up-call, which will apply some more transformations.
233- return super().__call__(event)
234+ twistedModern.globalLogBeginner.beginLoggingTo(
235+ [EventLogger()], discardBuffer=False, redirectStandardIO=False)
236+
237+
238+def EventLogger(outFile=sys.__stdout__):
239+ """Factory returning a `t.logger.ILogObserver`.
240+
241+ This logs to the real standard out using MAAS's logging conventions.
242+
243+ Refer to this with `twistd`'s `--logger` argument.
244+ """
245+ return twistedModern.FilteringLogObserver(
246+ twistedModern.FileLogObserver(outFile, _formatModernEvent),
247+ (_filterByLevel, _filterByNoise))
248+
249+
250+def _startLoggingWithObserver(observer, setStdout=1):
251+ """Replacement for `t.p.log.startLoggingWithObserver`.
252+
253+ When `twistd` starts in 16.0 it initialises the legacy logging system.
254+ Intercept this to DTRT with either a modern or legacy observer.
255+
256+ In Xenial (with Twisted 16.0) `observer` is probably a legacy observer,
257+ like twisted.python.log.FileLogObserver, but we should check if it's
258+ modern. In either case we should call through to the `globalLogBeginner`
259+ ourselves. In Yakkety (with Twisted 16.4) this function will not be
260+ called; `t.application.app.AppLogger` does the right thing already.
261+ """
262+ if not twistedModern.ILogObserver.providedBy(observer):
263+ observer = twistedModern.LegacyLogObserverWrapper(observer)
264+ twistedModern.globalLogBeginner.beginLoggingTo(
265+ [observer], discardBuffer=False, redirectStandardIO=bool(setStdout))
266+
267+
268+_timeFormat = DEFAULT_LOG_FORMAT_DATE
269+_lineFormat = DEFAULT_LOG_FORMAT + "\n"
270+
271+
272+def _formatModernEvent(event):
273+ """Format a "modern" event according to MAAS's conventions."""
274+ text = twistedModern.formatEvent(event)
275+ time = event["log_time"] if "log_time" in event else None
276+ level = event["log_level"] if "log_level" in event else None
277+ system = event["log_system"] if "log_system" in event else None
278+ if system is None and "log_namespace" in event:
279+ system = _getSystemName(event["log_namespace"])
280+
281+ return _lineFormat % {
282+ "asctime": twistedModern.formatTime(time, _timeFormat),
283+ "levelname": "-" if level is None else level.name,
284+ "message": "-" if text is None else text.replace("\n", "\n\t"),
285+ "name": "-" if system is None else system,
286+ }
287+
288+
289+def _getSystemName(system):
290+ """Return the "public" parts of `system`.
291+
292+ `system` is a dot-separated name, e.g. a fully-qualified module name. This
293+ returns the leading parts of that name that are not pseudo-private, i.e.
294+ that start with an underscore. For example "a.b._c.d" would be transformed
295+ into "a.b".
296+ """
297+ if system is None:
298+ return None
299+ elif len(system) == 0:
300+ return None
301+ elif system.startswith("_"):
302+ return None
303+ else:
304+ return system.split("._")[0]
305
306
307 class LegacyLogger(twistedModern.Logger):
308@@ -352,6 +303,33 @@
309 pass # We tried.
310
311
312+# Those levels for which we should emit log events.
313+_filterByLevels = frozenset()
314+
315+
316+def _filterByLevel(event):
317+ """Only log if event's level is in `_filterByLevels`."""
318+ if event.get("log_level") in _filterByLevels:
319+ return twistedModern.PredicateResult.maybe
320+ else:
321+ return twistedModern.PredicateResult.no
322+
323+# A list of markers for noise.
324+_filterByNoises = (
325+ {"log_namespace": "log_legacy", "log_text": "Log opened."},
326+ {"log_namespace": "log_legacy", "log_text": "Main loop terminated."},
327+)
328+
329+
330+def _filterByNoise(event):
331+ """Only log if event is not noisy."""
332+ for noise in _filterByNoises:
333+ if all(key in event and event[key] == noise[key] for key in noise):
334+ return twistedModern.PredicateResult.no
335+ else:
336+ return twistedModern.PredicateResult.maybe
337+
338+
339 _observe_twisted_internet_tcp_noise = re.compile(
340 r"^(?:[(].+ Port \d+ Closed[)]|.+ starting on \d+)")
341
342@@ -375,7 +353,7 @@
343
344
345 _observe_twisted_internet_unix_noise = re.compile(
346- r"^(?:[(]Port \d+ Closed[)]|.+ starting on .+)")
347+ r"^(?:[(]Port .+ Closed[)]|.+ starting on .+)")
348
349
350 def observe_twisted_internet_unix(event):
351
352=== modified file 'src/provisioningserver/logger/testing/__init__.py'
353--- src/provisioningserver/logger/testing/__init__.py 2016-10-26 09:12:47 +0000
354+++ src/provisioningserver/logger/testing/__init__.py 2016-11-08 16:20:29 +0000
355@@ -4,6 +4,7 @@
356 """Testing helpers for `provisioningserver.logger`."""
357
358 __all__ = [
359+ "find_log_lines",
360 "make_event",
361 "make_log_text",
362 "pick_log_level",
363@@ -11,20 +12,23 @@
364 ]
365
366 import random
367+import re
368 import time
369
370 from maastesting.factory import factory
371 from twisted.logger import LogLevel
372
373
374-def make_event(log_text=None, log_level=None, log_time=None):
375+def make_event(log_text=None, log_level=None, log_time=None, **other):
376 """Make a minimal event dict for use with Twisted."""
377- return {
378+ event = {
379 "log_format": "{log_text}",
380 "log_level": pick_log_level() if log_level is None else log_level,
381 "log_text": make_log_text() if log_text is None else log_text,
382 "log_time": pick_log_time() if log_time is None else log_time,
383 }
384+ event.update(other)
385+ return event
386
387
388 def make_log_text():
389@@ -43,3 +47,20 @@
390 def pick_log_time(noise=float(60 * 60)):
391 """Pick a random time based on now, but with some noise."""
392 return time.time() + (random.random() * noise) - (noise / 2)
393+
394+
395+# Matches lines like: 2016-10-18 14:23:55 namespace: [level] message
396+find_log_lines_re = re.compile(
397+ r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (.*?): [[](.*)[]] (.*)$",
398+ re.MULTILINE)
399+
400+
401+def find_log_lines(text):
402+ """Find logs in `text` that match `find_log_lines_re`.
403+
404+ Checks for well-formed date/times but throws them away.
405+ """
406+ return [
407+ (ns, level, line) for (ts, ns, level, line) in
408+ find_log_lines_re.findall(text)
409+ ]
410
411=== modified file 'src/provisioningserver/logger/testing/logsomething.py'
412--- src/provisioningserver/logger/testing/logsomething.py 2016-11-04 00:11:06 +0000
413+++ src/provisioningserver/logger/testing/logsomething.py 2016-11-08 16:20:29 +0000
414@@ -46,9 +46,12 @@
415 if options.set_verbosity is not None:
416 provisioningserver.logger.set_verbosity(options.set_verbosity)
417
418-# Simulate what `twistd` does when passed `--logfile=-`.
419+# Simulate what `twistd` does when passed `--logger=...` in Twisted 16.0. In
420+# 16.4 something similar happens, but globalLogBeginner.beginLoggingTo() is
421+# called without going via `twisted.python.log`.
422 if options.mode == modes.TWISTD:
423- twisted.python.log.startLogging(sys.stdout)
424+ emitter = provisioningserver.logger.EventLogger()
425+ twisted.python.log.startLoggingWithObserver(emitter)
426
427 # Twisted, new.
428 twisted.logger.Logger(options.name).debug("From `twisted.logger`.")
429
430=== modified file 'src/provisioningserver/logger/tests/test__twisted.py'
431--- src/provisioningserver/logger/tests/test__twisted.py 2016-11-07 13:37:33 +0000
432+++ src/provisioningserver/logger/tests/test__twisted.py 2016-11-08 16:20:29 +0000
433@@ -5,31 +5,30 @@
434
435 __all__ = []
436
437-from functools import partial
438 import io
439-from unittest.mock import (
440- patch,
441- sentinel,
442-)
443
444 from maastesting.factory import factory
445-from maastesting.matchers import DocTestMatches
446 from maastesting.testcase import MAASTestCase
447 from maastesting.twisted import TwistedLoggerFixture
448+from provisioningserver.logger import _twisted
449+from provisioningserver.logger._common import DEFAULT_LOG_FORMAT_DATE
450 from provisioningserver.logger._twisted import (
451- LegacyFileLogObserver,
452+ _formatModernEvent,
453+ _getSystemName,
454+ EventLogger,
455 LegacyLogger,
456- LegacyLogObserverWrapper,
457 observe_twisted_internet_tcp,
458 observe_twisted_internet_udp,
459 observe_twisted_internet_unix,
460 )
461-from provisioningserver.logger.testing import make_event
462+from provisioningserver.logger.testing import (
463+ find_log_lines,
464+ make_event,
465+ pick_log_time,
466+)
467 from testtools.matchers import (
468 AfterPreprocessing,
469- AllMatch,
470 Contains,
471- ContainsAll,
472 ContainsDict,
473 Equals,
474 HasLength,
475@@ -37,11 +36,8 @@
476 IsInstance,
477 MatchesAll,
478 MatchesDict,
479- MatchesSetwise,
480- Not,
481 )
482 from twisted import logger
483-from twisted.python import log
484 from twisted.python.failure import Failure
485
486
487@@ -50,243 +46,6 @@
488 {key: Equals(value) for key, value in expected.items()})
489
490
491-def setLegacyObservers(observers):
492- """Remove existing legacy log observers, add those given."""
493- for observer in log.theLogPublisher.observers:
494- log.theLogPublisher.removeObserver(observer)
495- for observer in observers:
496- log.theLogPublisher.addObserver(observer)
497-
498-
499-class TestLegacyFileLogObserver(MAASTestCase):
500- """Scenario tests for `LegacyFileLogObserver`."""
501-
502- scenarios = tuple(
503- (log_level.name, dict(log_level=log_level))
504- for log_level in logger.LogLevel.iterconstants()
505- )
506-
507- def test__namespace_and_level_is_printed_in_legacy_log(self):
508- # Restore existing observers at the end. This must be careful with
509- # ordering of clean-ups, hence the use of unittest.mock.patch.object
510- # as a context manager.
511- self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
512- # The global non-legacy `LogBeginner` emits critical messages straight
513- # to stderr, so temporarily put aside its observer to avoid seeing the
514- # critical log messages we're going to generate.
515- self.patch(logger.globalLogPublisher, "_observers", [])
516-
517- logbuffer = io.StringIO()
518- observer = LegacyFileLogObserver(logbuffer)
519- observer.formatTime = lambda when: "<timestamp>"
520-
521- oldlog = log.msg
522- # Deliberately use the default global observer in the new logger
523- # because we want to see how it behaves in a typical environment where
524- # logs are being emitted by the legacy logging infrastructure, for
525- # example running under `twistd`.
526- newlog = partial(logger.Logger().emit, self.log_level)
527-
528- with patch.object(
529- log, "LegacyLogObserverWrapper",
530- log.LegacyLogObserverWrapper):
531- setLegacyObservers([observer.emit])
532- oldlog("Message from legacy", system="legacy")
533- newlog("Message from modern", log_system="modern")
534-
535- self.assertThat(
536- logbuffer.getvalue(), DocTestMatches("""\
537- <timestamp> legacy: [info] Message from legacy
538- <timestamp> modern: [%s] Message from modern
539- """ % self.log_level.name))
540-
541-
542-class TestLegacyFileLogObserver_Other(MAASTestCase):
543- """Other tests for `LegacyFileLogObserver`."""
544-
545- def test__namespace_is_not_emitted_via_logfile_logerr(self):
546- # Restore existing observers at the end. This must be careful with
547- # ordering of clean-ups, hence the use of unittest.mock.patch.object
548- # as a context manager.
549- self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
550- # The global non-legacy `LogBeginner` emits critical messages straight
551- # to stderr, so temporarily put aside its observer to avoid seeing the
552- # critical log messages we're going to generate.
553- self.patch(logger.globalLogPublisher, "_observers", [])
554-
555- logbuffer = io.StringIO()
556- observer = LegacyFileLogObserver(logbuffer)
557- observer.formatTime = lambda when: "<timestamp>"
558-
559- with patch.object(
560- log, "LegacyLogObserverWrapper",
561- log.LegacyLogObserverWrapper):
562- setLegacyObservers([observer.emit])
563- log.logfile.write("Via log.logfile\n")
564- log.logerr.write("Via log.logerr\n")
565-
566- self.assertThat(
567- logbuffer.getvalue(), DocTestMatches("""\
568- <timestamp> -: [info] Via log.logfile
569- <timestamp> -: [error] Via log.logerr
570- """))
571-
572-
573-class TestLegacyLogObserverWrapper(MAASTestCase):
574- """Scenario tests for `LegacyLogObserverWrapper`."""
575-
576- scenarios = tuple(
577- (log_level.name, dict(log_level=log_level))
578- for log_level in logger.LogLevel.iterconstants()
579- )
580-
581- def processEvent(self, event):
582- events = []
583- observer = LegacyLogObserverWrapper(events.append)
584- observer(event)
585- self.assertThat(events, HasLength(1))
586- return events[0]
587-
588- def test__adds_system_to_event(self):
589- self.assertThat(
590- # This is a `twisted.logger` event, not legacy, and requires
591- # values for `log_time` and `log_level` at a minimum.
592- self.processEvent({
593- "log_time": sentinel.log_time,
594- "log_level": self.log_level,
595- }),
596- MatchesAll(
597- Not(Contains("log_system")),
598- ContainsDictByEquality({"system": "-"}),
599- ),
600- )
601-
602- def test__adds_log_system_and_system_to_event_with_namespace(self):
603- log_namespace = factory.make_name("log_namespace")
604- self.assertThat(
605- self.processEvent({
606- "log_time": sentinel.log_time,
607- "log_level": self.log_level,
608- "log_namespace": log_namespace,
609- }),
610- ContainsDictByEquality({
611- "log_system": log_namespace,
612- "system": log_namespace,
613- }),
614- )
615-
616- def test__adds_system_to_legacy_event(self):
617- self.assertThat(
618- # This is a `twisted.python.log` event, i.e. legacy, and requires
619- # values for `time` and `isError` at a minimum.
620- self.processEvent({
621- "time": sentinel.time,
622- "isError": factory.pick_bool(),
623- }),
624- MatchesAll(
625- Not(Contains("log_system")),
626- ContainsDictByEquality({"system": "-"}),
627- ),
628- )
629-
630- def test__preserves_log_system_in_event(self):
631- log_system = factory.make_name("log_system")
632- self.assertThat(
633- self.processEvent({
634- "log_time": sentinel.time,
635- "log_level": self.log_level,
636- "log_system": log_system,
637- }),
638- # `log_system` is not modified; `system` is set to match.
639- ContainsDictByEquality({
640- "log_system": log_system,
641- "system": log_system,
642- }),
643- )
644-
645- def test__preserves_system_in_legacy_event(self):
646- system = factory.make_name("system")
647- self.assertThat(
648- self.processEvent({
649- "time": sentinel.time,
650- "isError": factory.pick_bool(),
651- "system": system,
652- }),
653- MatchesAll(
654- # `log_system` is not added when `system` already exists.
655- Not(Contains("log_system")),
656- ContainsDictByEquality({
657- "system": system,
658- }),
659- ),
660- )
661-
662-
663-class TestLegacyLogObserverWrapper_Installation(MAASTestCase):
664- """Tests for `LegacyLogObserverWrapper`."""
665-
666- def setUp(self):
667- super().setUp()
668- # Restore existing observers at the end. Tests must be careful with
669- # ordering of clean-ups, hence the use of unittest.mock.patch.object
670- # as a context manager in the tests themselves.
671- self.addCleanup(setLegacyObservers, log.theLogPublisher.observers)
672-
673- def test__installs_wrapper_to_log_module(self):
674- with patch.object(log, "LegacyLogObserverWrapper", sentinel.unchanged):
675- self.assertThat(
676- log.LegacyLogObserverWrapper,
677- Is(sentinel.unchanged))
678- LegacyLogObserverWrapper.install()
679- self.assertThat(
680- log.LegacyLogObserverWrapper,
681- Is(LegacyLogObserverWrapper))
682-
683- def test__rewraps_existing_observers(self):
684-
685- class OldWrapper:
686-
687- def __init__(self, observer):
688- self.legacyObserver = observer
689-
690- def __call__(self, event):
691- return self.legacyObserver(event)
692-
693- with patch.object(log, "LegacyLogObserverWrapper", OldWrapper):
694-
695- observers = (lambda event: event), (lambda event: event)
696- setLegacyObservers(observers)
697-
698- # Our legacy observers are all registered.
699- self.assertThat(
700- log.theLogPublisher.observers,
701- MatchesSetwise(*map(Is, observers)))
702- # Behind the scenes they're all wrapped with OldWrapper.
703- self.assertThat(
704- log.theLogPublisher._legacyObservers,
705- AllMatch(IsInstance(OldWrapper)))
706- # They're registered with the new global log publisher too.
707- self.assertThat(
708- logger.globalLogPublisher._observers,
709- ContainsAll(log.theLogPublisher._legacyObservers))
710-
711- # Install!
712- LegacyLogObserverWrapper.install()
713-
714- # Our legacy observers are all still registered.
715- self.assertThat(
716- log.theLogPublisher.observers,
717- MatchesSetwise(*map(Is, observers)))
718- # Behind the scenes they're now all wrapped with our wrapper.
719- self.assertThat(
720- log.theLogPublisher._legacyObservers,
721- AllMatch(IsInstance(LegacyLogObserverWrapper)))
722- # They're registered with the new global log publisher too.
723- self.assertThat(
724- logger.globalLogPublisher._observers,
725- ContainsAll(log.theLogPublisher._legacyObservers))
726-
727-
728 def formatTimeStatic(when):
729 """Just return <when>."""
730 return "<when>"
731@@ -443,7 +202,7 @@
732 """Tests for `observe_twisted_internet_unix`."""
733
734 def test__ignores_port_closed_events(self):
735- event = make_event("(Port %d Closed)" % factory.pick_port())
736+ event = make_event("(Port %r Closed)" % factory.make_name("port"))
737 with TwistedLoggerFixture() as logger:
738 observe_twisted_internet_unix(event)
739 self.assertThat(logger.events, HasLength(0))
740@@ -460,3 +219,193 @@
741 with TwistedLoggerFixture() as logger:
742 observe_twisted_internet_unix(event)
743 self.assertThat(logger.events, Contains(event))
744+
745+
746+class TestGetSystemName(MAASTestCase):
747+ """Tests for `_getSystemName`."""
748+
749+ expectations = {
750+ "foo.bar.baz": "foo.bar.baz",
751+ "f_o.bar.baz": "f_o.bar.baz",
752+ "foo.b_r.baz": "foo.b_r.baz",
753+ "foo.bar.b_z": "foo.bar.b_z",
754+ "foo.bar._az": "foo.bar",
755+ "foo._ar.baz": "foo",
756+ "foo._ar._az": "foo",
757+ "_oo.bar.baz": None,
758+ "_": None,
759+ "": None,
760+ None: None,
761+ }
762+
763+ scenarios = tuple(
764+ ("%s => %s" % (
765+ string_in or repr(string_in),
766+ string_out or repr(string_out)),
767+ {"string_in": string_in, "string_out": string_out})
768+ for string_in, string_out in expectations.items()
769+ )
770+
771+ def test(self):
772+ self.assertThat(
773+ _getSystemName(self.string_in),
774+ Equals(self.string_out))
775+
776+
777+class TestFormatModernEvent(MAASTestCase):
778+ """Tests for `_formatModernEvent`."""
779+
780+ scenarios = tuple(
781+ (level.name, {"log_level": level})
782+ for level in logger.LogLevel.iterconstants()
783+ )
784+
785+ def test_format_basics(self):
786+ thing1 = factory.make_name("thing")
787+ thing2 = factory.make_name("thing")
788+ log_system = factory.make_name("system")
789+ log_format = ">{thing1}< >{thing2}<"
790+ log_time = pick_log_time()
791+ self.assertThat(
792+ _formatModernEvent({
793+ "log_time": log_time,
794+ "log_format": log_format,
795+ "log_system": log_system,
796+ "log_level": self.log_level,
797+ "thing1": thing1,
798+ "thing2": thing2,
799+ }),
800+ Equals(
801+ "%s %s: [%s] >%s< >%s<\n" % (
802+ logger.formatTime(log_time, DEFAULT_LOG_FORMAT_DATE),
803+ log_system, self.log_level.name, thing1, thing2),
804+ ),
805+ )
806+
807+ def test_formats_without_format(self):
808+ self.assertThat(
809+ _formatModernEvent({
810+ "log_level": self.log_level,
811+ }),
812+ Equals("- -: [%s] \n" % self.log_level.name),
813+ )
814+
815+ def test_formats_with_null_format(self):
816+ self.assertThat(
817+ _formatModernEvent({
818+ "log_format": None,
819+ "log_level": self.log_level,
820+ }),
821+ Equals("- -: [%s] \n" % self.log_level.name),
822+ )
823+
824+ def test_formats_without_time(self):
825+ self.assertThat(
826+ _formatModernEvent({
827+ "log_level": self.log_level,
828+ }),
829+ Equals("- -: [%s] \n" % self.log_level.name),
830+ )
831+
832+ def test_formats_with_null_time(self):
833+ self.assertThat(
834+ _formatModernEvent({
835+ "log_time": None,
836+ "log_level": self.log_level,
837+ }),
838+ Equals("- -: [%s] \n" % self.log_level.name),
839+ )
840+
841+ def test_uses_namespace_if_system_missing(self):
842+ log_namespace = factory.make_name("namespace")
843+ self.assertThat(
844+ _formatModernEvent({
845+ "log_level": self.log_level,
846+ "log_namespace": log_namespace,
847+ }),
848+ Equals(
849+ "- %s: [%s] \n" % (
850+ log_namespace, self.log_level.name),
851+ ),
852+ )
853+
854+ def test_uses_namespace_if_system_null(self):
855+ log_namespace = factory.make_name("namespace")
856+ self.assertThat(
857+ _formatModernEvent({
858+ "log_level": self.log_level,
859+ "log_namespace": log_namespace,
860+ "log_system": None,
861+ }),
862+ Equals(
863+ "- %s: [%s] \n" % (
864+ log_namespace, self.log_level.name),
865+ ),
866+ )
867+
868+
869+class TestEventLogger(MAASTestCase):
870+ """Tests for `EventLogger`."""
871+
872+ scenarios = tuple(
873+ (level.name, {"log_level": level})
874+ for level in logger.LogLevel.iterconstants()
875+ )
876+
877+ def setUp(self):
878+ super(TestEventLogger, self).setUp()
879+ self.output = io.StringIO()
880+ self.log = EventLogger(self.output)
881+ self.get_logs = lambda: find_log_lines(self.output.getvalue())
882+
883+ def setLogLevel(self, log_level):
884+ """Set the level at which events will be logged.
885+
886+ This is not a minimum level, it is an absolute level.
887+ """
888+ self.patch(_twisted, "_filterByLevels", {self.log_level})
889+
890+ def test_basics(self):
891+ self.setLogLevel(self.log_level)
892+ event = make_event(log_level=self.log_level)
893+ event["log_system"] = factory.make_name("system")
894+ self.log(event)
895+ self.assertSequenceEqual(
896+ [(event["log_system"], self.log_level.name, event["log_text"])],
897+ self.get_logs(),
898+ )
899+
900+ def test_filters_by_level(self):
901+ self.setLogLevel(self.log_level)
902+ events = {
903+ log_level: make_event(log_level=log_level)
904+ for log_level in logger.LogLevel.iterconstants()
905+ }
906+ for event in events.values():
907+ self.log(event)
908+ # Only the log at the current level will get through.
909+ self.assertSequenceEqual(
910+ [("-", self.log_level.name, events[self.log_level]["log_text"])],
911+ self.get_logs(),
912+ )
913+
914+ def test_filters_by_noise(self):
915+ self.setLogLevel(self.log_level)
916+ common = dict(log_namespace="log_legacy", log_system="-")
917+ noisy = [
918+ make_event("Log opened.", **common),
919+ make_event("Main loop terminated.", **common),
920+ ]
921+ for event in noisy:
922+ self.log(event)
923+ okay = [
924+ make_event(log_level=self.log_level, **common),
925+ ]
926+ for event in okay:
927+ self.log(event)
928+ # Only the `okay` logs will get through.
929+ expected = [
930+ ("-", self.log_level.name, event["log_text"])
931+ for event in okay
932+ ]
933+ self.assertSequenceEqual(expected, self.get_logs())
934
935=== modified file 'src/provisioningserver/logger/tests/test_logger.py'
936--- src/provisioningserver/logger/tests/test_logger.py 2016-11-07 13:37:33 +0000
937+++ src/provisioningserver/logger/tests/test_logger.py 2016-11-08 16:20:29 +0000
938@@ -6,7 +6,6 @@
939 __all__ = []
940
941 import pathlib
942-import re
943 import subprocess
944 import sys
945
946@@ -14,6 +13,7 @@
947 from maastesting.matchers import DocTestMatches
948 from maastesting.testcase import MAASTestCase
949 from provisioningserver.logger import LoggingMode
950+from provisioningserver.logger.testing import find_log_lines
951 from provisioningserver.utils import typed
952 from provisioningserver.utils.shell import select_c_utf8_locale
953 from testtools.content import text_content
954@@ -40,23 +40,6 @@
955 return output.decode("utf-8")
956
957
958-# Matches lines like: 2016-10-18 14:23:55 [namespace#level] message
959-find_log_lines_re = re.compile(
960- r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (.*?): [[](.*)[]] (.*)$",
961- re.MULTILINE)
962-
963-
964-def find_log_lines(text):
965- """Find logs in `text` that match `find_log_lines_re`.
966-
967- Checks for well-formed date/times but throws them away.
968- """
969- return [
970- (ns, level, line) for (ts, ns, level, line) in
971- find_log_lines_re.findall(text)
972- ]
973-
974-
975 class TestLogging(MAASTestCase):
976 """Test logging in MAAS as configured by `p.logger.configure`.
977
978@@ -115,7 +98,7 @@
979 ('maas.' + name, 'error', 'From `get_maas_logger`.'),
980 ('stdout', 'info', 'Printing to stdout.'),
981 ('stderr', 'error', 'Printing to stderr.'),
982- ('__main__', 'warn', 'UserWarning: This is a warning!'),
983+ ('-', 'warn', 'UserWarning: This is a warning!'),
984 ]
985 self.assertSequenceEqual(expected, observed)
986
987@@ -143,7 +126,7 @@
988 ('maas.' + name, 'error', 'From `get_maas_logger`.'),
989 ('stdout', 'info', 'Printing to stdout.'),
990 ('stderr', 'error', 'Printing to stderr.'),
991- ('__main__', 'warn', 'UserWarning: This is a warning!'),
992+ ('-', 'warn', 'UserWarning: This is a warning!'),
993 ]
994 self.assertSequenceEqual(expected, observed)
995
996@@ -163,7 +146,7 @@
997 ('maas.' + name, 'warn', 'From `get_maas_logger`.'),
998 ('maas.' + name, 'error', 'From `get_maas_logger`.'),
999 ('stderr', 'error', 'Printing to stderr.'),
1000- ('__main__', 'warn', 'UserWarning: This is a warning!'),
1001+ ('-', 'warn', 'UserWarning: This is a warning!'),
1002 ]
1003 self.assertSequenceEqual(expected, observed)
1004