testing/mozbase/mozlog/tests/test_logger.py@b8a032363ba2 (annotated)
testing/mozbase/mozlog/tests/test_logger.py
Thu, 22 Jan 2015 13:21:57 +0100
- author
- Michael Schloh von Bennewitz <michael@schloh.com>
- date
- Thu, 22 Jan 2015 13:21:57 +0100
- branch
- TOR_BUG_9701
- changeset 15
- b8a032363ba2
- permissions
- -rw-r--r--
Incorporate requested changes from Mozilla in review:
https://bugzilla.mozilla.org/show_bug.cgi?id=1123480#c6
| michael@0 | 1 | # This Source Code Form is subject to the terms of the Mozilla Public |
| michael@0 | 2 | # License, v. 2.0. If a copy of the MPL was not distributed with this file, |
| michael@0 | 3 | # You can obtain one at http://mozilla.org/MPL/2.0/. |
| michael@0 | 4 | |
| michael@0 | 5 | import datetime |
| michael@0 | 6 | import json |
| michael@0 | 7 | import socket |
| michael@0 | 8 | import threading |
| michael@0 | 9 | import time |
| michael@0 | 10 | import unittest |
| michael@0 | 11 | |
| michael@0 | 12 | import mozfile |
| michael@0 | 13 | |
| michael@0 | 14 | import mozlog |
| michael@0 | 15 | |
| michael@0 | 16 | class ListHandler(mozlog.Handler): |
| michael@0 | 17 | """Mock handler appends messages to a list for later inspection.""" |
| michael@0 | 18 | |
| michael@0 | 19 | def __init__(self): |
| michael@0 | 20 | mozlog.Handler.__init__(self) |
| michael@0 | 21 | self.messages = [] |
| michael@0 | 22 | |
| michael@0 | 23 | def emit(self, record): |
| michael@0 | 24 | self.messages.append(self.format(record)) |
| michael@0 | 25 | |
| michael@0 | 26 | class TestLogging(unittest.TestCase): |
| michael@0 | 27 | """Tests behavior of basic mozlog api.""" |
| michael@0 | 28 | |
| michael@0 | 29 | def test_logger_defaults(self): |
| michael@0 | 30 | """Tests the default logging format and behavior.""" |
| michael@0 | 31 | |
| michael@0 | 32 | default_logger = mozlog.getLogger('default.logger') |
| michael@0 | 33 | self.assertEqual(default_logger.name, 'default.logger') |
| michael@0 | 34 | self.assertEqual(len(default_logger.handlers), 1) |
| michael@0 | 35 | self.assertTrue(isinstance(default_logger.handlers[0], |
| michael@0 | 36 | mozlog.StreamHandler)) |
| michael@0 | 37 | |
| michael@0 | 38 | f = mozfile.NamedTemporaryFile() |
| michael@0 | 39 | list_logger = mozlog.getLogger('file.logger', |
| michael@0 | 40 | handler=mozlog.FileHandler(f.name)) |
| michael@0 | 41 | self.assertEqual(len(list_logger.handlers), 1) |
| michael@0 | 42 | self.assertTrue(isinstance(list_logger.handlers[0], |
| michael@0 | 43 | mozlog.FileHandler)) |
| michael@0 | 44 | f.close() |
| michael@0 | 45 | |
| michael@0 | 46 | self.assertRaises(ValueError, mozlog.getLogger, |
| michael@0 | 47 | 'file.logger', handler=ListHandler()) |
| michael@0 | 48 | |
| michael@0 | 49 | def test_timestamps(self): |
| michael@0 | 50 | """Verifies that timestamps are included when asked for.""" |
| michael@0 | 51 | log_name = 'test' |
| michael@0 | 52 | handler = ListHandler() |
| michael@0 | 53 | handler.setFormatter(mozlog.MozFormatter()) |
| michael@0 | 54 | log = mozlog.getLogger(log_name, handler=handler) |
| michael@0 | 55 | log.info('no timestamp') |
| michael@0 | 56 | self.assertTrue(handler.messages[-1].startswith('%s ' % log_name)) |
| michael@0 | 57 | handler.setFormatter(mozlog.MozFormatter(include_timestamp=True)) |
| michael@0 | 58 | log.info('timestamp') |
| michael@0 | 59 | # Just verify that this raises no exceptions. |
| michael@0 | 60 | datetime.datetime.strptime(handler.messages[-1][:23], |
| michael@0 | 61 | '%Y-%m-%d %H:%M:%S,%f') |
| michael@0 | 62 | |
| michael@0 | 63 | class TestStructuredLogging(unittest.TestCase): |
| michael@0 | 64 | """Tests structured output in mozlog.""" |
| michael@0 | 65 | |
| michael@0 | 66 | def setUp(self): |
| michael@0 | 67 | self.handler = ListHandler() |
| michael@0 | 68 | self.handler.setFormatter(mozlog.JSONFormatter()) |
| michael@0 | 69 | self.logger = mozlog.MozLogger('test.Logger') |
| michael@0 | 70 | self.logger.addHandler(self.handler) |
| michael@0 | 71 | self.logger.setLevel(mozlog.DEBUG) |
| michael@0 | 72 | |
| michael@0 | 73 | def check_messages(self, expected, actual): |
| michael@0 | 74 | """Checks actual for equality with corresponding fields in actual. |
| michael@0 | 75 | The actual message should contain all fields in expected, and |
| michael@0 | 76 | should be identical, with the exception of the timestamp field. |
| michael@0 | 77 | The actual message should contain no fields other than the timestamp |
| michael@0 | 78 | field and those present in expected.""" |
| michael@0 | 79 | |
| michael@0 | 80 | self.assertTrue(isinstance(actual['_time'], (int, long))) |
| michael@0 | 81 | |
| michael@0 | 82 | for k, v in expected.items(): |
| michael@0 | 83 | self.assertEqual(v, actual[k]) |
| michael@0 | 84 | |
| michael@0 | 85 | for k in actual.keys(): |
| michael@0 | 86 | if k != '_time': |
| michael@0 | 87 | self.assertTrue(expected.get(k) is not None) |
| michael@0 | 88 | |
| michael@0 | 89 | def test_structured_output(self): |
| michael@0 | 90 | self.logger.log_structured('test_message', |
| michael@0 | 91 | {'_level': mozlog.INFO, |
| michael@0 | 92 | '_message': 'message one'}) |
| michael@0 | 93 | self.logger.log_structured('test_message', |
| michael@0 | 94 | {'_level': mozlog.INFO, |
| michael@0 | 95 | '_message': 'message two'}) |
| michael@0 | 96 | self.logger.log_structured('error_message', |
| michael@0 | 97 | {'_level': mozlog.ERROR, |
| michael@0 | 98 | 'diagnostic': 'unexpected error'}) |
| michael@0 | 99 | |
| michael@0 | 100 | message_one_expected = {'_namespace': 'test.Logger', |
| michael@0 | 101 | '_level': 'INFO', |
| michael@0 | 102 | '_message': 'message one', |
| michael@0 | 103 | 'action': 'test_message'} |
| michael@0 | 104 | message_two_expected = {'_namespace': 'test.Logger', |
| michael@0 | 105 | '_level': 'INFO', |
| michael@0 | 106 | '_message': 'message two', |
| michael@0 | 107 | 'action': 'test_message'} |
| michael@0 | 108 | message_three_expected = {'_namespace': 'test.Logger', |
| michael@0 | 109 | '_level': 'ERROR', |
| michael@0 | 110 | 'diagnostic': 'unexpected error', |
| michael@0 | 111 | 'action': 'error_message'} |
| michael@0 | 112 | |
| michael@0 | 113 | message_one_actual = json.loads(self.handler.messages[0]) |
| michael@0 | 114 | message_two_actual = json.loads(self.handler.messages[1]) |
| michael@0 | 115 | message_three_actual = json.loads(self.handler.messages[2]) |
| michael@0 | 116 | |
| michael@0 | 117 | self.check_messages(message_one_expected, message_one_actual) |
| michael@0 | 118 | self.check_messages(message_two_expected, message_two_actual) |
| michael@0 | 119 | self.check_messages(message_three_expected, message_three_actual) |
| michael@0 | 120 | |
| michael@0 | 121 | def test_unstructured_conversion(self): |
| michael@0 | 122 | """ Tests that logging to a logger with a structured formatter |
| michael@0 | 123 | via the traditional logging interface works as expected. """ |
| michael@0 | 124 | self.logger.info('%s %s %d', 'Message', 'number', 1) |
| michael@0 | 125 | self.logger.error('Message number 2') |
| michael@0 | 126 | self.logger.debug('Message with %s', 'some extras', |
| michael@0 | 127 | extra={'params': {'action': 'mozlog_test_output', |
| michael@0 | 128 | 'is_failure': False}}) |
| michael@0 | 129 | message_one_expected = {'_namespace': 'test.Logger', |
| michael@0 | 130 | '_level': 'INFO', |
| michael@0 | 131 | '_message': 'Message number 1'} |
| michael@0 | 132 | message_two_expected = {'_namespace': 'test.Logger', |
| michael@0 | 133 | '_level': 'ERROR', |
| michael@0 | 134 | '_message': 'Message number 2'} |
| michael@0 | 135 | message_three_expected = {'_namespace': 'test.Logger', |
| michael@0 | 136 | '_level': 'DEBUG', |
| michael@0 | 137 | '_message': 'Message with some extras', |
| michael@0 | 138 | 'action': 'mozlog_test_output', |
| michael@0 | 139 | 'is_failure': False} |
| michael@0 | 140 | |
| michael@0 | 141 | message_one_actual = json.loads(self.handler.messages[0]) |
| michael@0 | 142 | message_two_actual = json.loads(self.handler.messages[1]) |
| michael@0 | 143 | message_three_actual = json.loads(self.handler.messages[2]) |
| michael@0 | 144 | |
| michael@0 | 145 | self.check_messages(message_one_expected, message_one_actual) |
| michael@0 | 146 | self.check_messages(message_two_expected, message_two_actual) |
| michael@0 | 147 | self.check_messages(message_three_expected, message_three_actual) |
| michael@0 | 148 | |
| michael@0 | 149 | def message_callback(self): |
| michael@0 | 150 | if len(self.handler.messages) == 3: |
| michael@0 | 151 | message_one_expected = {'_namespace': 'test.Logger', |
| michael@0 | 152 | '_level': 'DEBUG', |
| michael@0 | 153 | '_message': 'socket message one', |
| michael@0 | 154 | 'action': 'test_message'} |
| michael@0 | 155 | message_two_expected = {'_namespace': 'test.Logger', |
| michael@0 | 156 | '_level': 'DEBUG', |
| michael@0 | 157 | '_message': 'socket message two', |
| michael@0 | 158 | 'action': 'test_message'} |
| michael@0 | 159 | message_three_expected = {'_namespace': 'test.Logger', |
| michael@0 | 160 | '_level': 'DEBUG', |
| michael@0 | 161 | '_message': 'socket message three', |
| michael@0 | 162 | 'action': 'test_message'} |
| michael@0 | 163 | |
| michael@0 | 164 | message_one_actual = json.loads(self.handler.messages[0]) |
| michael@0 | 165 | |
| michael@0 | 166 | message_two_actual = json.loads(self.handler.messages[1]) |
| michael@0 | 167 | |
| michael@0 | 168 | message_three_actual = json.loads(self.handler.messages[2]) |
| michael@0 | 169 | |
| michael@0 | 170 | self.check_messages(message_one_expected, message_one_actual) |
| michael@0 | 171 | self.check_messages(message_two_expected, message_two_actual) |
| michael@0 | 172 | self.check_messages(message_three_expected, message_three_actual) |
| michael@0 | 173 | |
| michael@0 | 174 | def test_log_listener(self): |
| michael@0 | 175 | connection = '127.0.0.1', 0 |
| michael@0 | 176 | self.log_server = mozlog.LogMessageServer(connection, |
| michael@0 | 177 | self.logger, |
| michael@0 | 178 | message_callback=self.message_callback, |
| michael@0 | 179 | timeout=0.5) |
| michael@0 | 180 | |
| michael@0 | 181 | message_string_one = json.dumps({'_message': 'socket message one', |
| michael@0 | 182 | 'action': 'test_message', |
| michael@0 | 183 | '_level': 'DEBUG'}) |
| michael@0 | 184 | message_string_two = json.dumps({'_message': 'socket message two', |
| michael@0 | 185 | 'action': 'test_message', |
| michael@0 | 186 | '_level': 'DEBUG'}) |
| michael@0 | 187 | |
| michael@0 | 188 | message_string_three = json.dumps({'_message': 'socket message three', |
| michael@0 | 189 | 'action': 'test_message', |
| michael@0 | 190 | '_level': 'DEBUG'}) |
| michael@0 | 191 | |
| michael@0 | 192 | message_string = message_string_one + '\n' + \ |
| michael@0 | 193 | message_string_two + '\n' + \ |
| michael@0 | 194 | message_string_three + '\n' |
| michael@0 | 195 | |
| michael@0 | 196 | server_thread = threading.Thread(target=self.log_server.handle_request) |
| michael@0 | 197 | server_thread.start() |
| michael@0 | 198 | |
| michael@0 | 199 | host, port = self.log_server.server_address |
| michael@0 | 200 | |
| michael@0 | 201 | sock = socket.socket() |
| michael@0 | 202 | sock.connect((host, port)) |
| michael@0 | 203 | |
| michael@0 | 204 | # Sleeps prevent listener from receiving entire message in a single call |
| michael@0 | 205 | # to recv in order to test reconstruction of partial messages. |
| michael@0 | 206 | sock.sendall(message_string[:8]) |
| michael@0 | 207 | time.sleep(.01) |
| michael@0 | 208 | sock.sendall(message_string[8:32]) |
| michael@0 | 209 | time.sleep(.01) |
| michael@0 | 210 | sock.sendall(message_string[32:64]) |
| michael@0 | 211 | time.sleep(.01) |
| michael@0 | 212 | sock.sendall(message_string[64:128]) |
| michael@0 | 213 | time.sleep(.01) |
| michael@0 | 214 | sock.sendall(message_string[128:]) |
| michael@0 | 215 | |
| michael@0 | 216 | server_thread.join() |
| michael@0 | 217 | |
| michael@0 | 218 | class Loggable(mozlog.LoggingMixin): |
| michael@0 | 219 | """Trivial class inheriting from LoggingMixin""" |
| michael@0 | 220 | pass |
| michael@0 | 221 | |
| michael@0 | 222 | class TestLoggingMixin(unittest.TestCase): |
| michael@0 | 223 | """Tests basic use of LoggingMixin""" |
| michael@0 | 224 | |
| michael@0 | 225 | def test_mixin(self): |
| michael@0 | 226 | loggable = Loggable() |
| michael@0 | 227 | self.assertTrue(not hasattr(loggable, "_logger")) |
| michael@0 | 228 | loggable.log(mozlog.INFO, "This will instantiate the logger") |
| michael@0 | 229 | self.assertTrue(hasattr(loggable, "_logger")) |
| michael@0 | 230 | self.assertEqual(loggable._logger.name, "test_logger.Loggable") |
| michael@0 | 231 | |
| michael@0 | 232 | self.assertRaises(ValueError, loggable.set_logger, |
| michael@0 | 233 | "not a logger") |
| michael@0 | 234 | |
| michael@0 | 235 | logger = mozlog.MozLogger('test.mixin') |
| michael@0 | 236 | handler = ListHandler() |
| michael@0 | 237 | logger.addHandler(handler) |
| michael@0 | 238 | loggable.set_logger(logger) |
| michael@0 | 239 | self.assertTrue(isinstance(loggable._logger.handlers[0], |
| michael@0 | 240 | ListHandler)) |
| michael@0 | 241 | self.assertEqual(loggable._logger.name, "test.mixin") |
| michael@0 | 242 | |
| michael@0 | 243 | loggable.log(mozlog.WARN, 'message for "log" method') |
| michael@0 | 244 | loggable.info('message for "info" method') |
| michael@0 | 245 | loggable.error('message for "error" method') |
| michael@0 | 246 | loggable.log_structured('test_message', |
| michael@0 | 247 | params={'_message': 'message for ' + \ |
| michael@0 | 248 | '"log_structured" method'}) |
| michael@0 | 249 | |
| michael@0 | 250 | expected_messages = ['message for "log" method', |
| michael@0 | 251 | 'message for "info" method', |
| michael@0 | 252 | 'message for "error" method', |
| michael@0 | 253 | 'message for "log_structured" method'] |
| michael@0 | 254 | |
| michael@0 | 255 | actual_messages = loggable._logger.handlers[0].messages |
| michael@0 | 256 | self.assertEqual(expected_messages, actual_messages) |
| michael@0 | 257 | |
| michael@0 | 258 | if __name__ == '__main__': |
| michael@0 | 259 | unittest.main() |
