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