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