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