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