michael@0: # This Source Code Form is subject to the terms of the Mozilla Public michael@0: # License, v. 2.0. If a copy of the MPL was not distributed with this file, michael@0: # You can obtain one at http://mozilla.org/MPL/2.0/. michael@0: michael@0: import datetime michael@0: import json michael@0: import socket michael@0: import threading michael@0: import time michael@0: import unittest michael@0: michael@0: import mozfile michael@0: michael@0: import mozlog michael@0: michael@0: class ListHandler(mozlog.Handler): michael@0: """Mock handler appends messages to a list for later inspection.""" michael@0: michael@0: def __init__(self): michael@0: mozlog.Handler.__init__(self) michael@0: self.messages = [] michael@0: michael@0: def emit(self, record): michael@0: self.messages.append(self.format(record)) michael@0: michael@0: class TestLogging(unittest.TestCase): michael@0: """Tests behavior of basic mozlog api.""" michael@0: michael@0: def test_logger_defaults(self): michael@0: """Tests the default logging format and behavior.""" michael@0: michael@0: default_logger = mozlog.getLogger('default.logger') michael@0: self.assertEqual(default_logger.name, 'default.logger') michael@0: self.assertEqual(len(default_logger.handlers), 1) michael@0: self.assertTrue(isinstance(default_logger.handlers[0], michael@0: mozlog.StreamHandler)) michael@0: michael@0: f = mozfile.NamedTemporaryFile() michael@0: list_logger = mozlog.getLogger('file.logger', michael@0: handler=mozlog.FileHandler(f.name)) michael@0: self.assertEqual(len(list_logger.handlers), 1) michael@0: self.assertTrue(isinstance(list_logger.handlers[0], michael@0: mozlog.FileHandler)) michael@0: f.close() michael@0: michael@0: self.assertRaises(ValueError, mozlog.getLogger, michael@0: 'file.logger', handler=ListHandler()) michael@0: michael@0: def test_timestamps(self): michael@0: """Verifies that timestamps are included when asked for.""" michael@0: log_name = 'test' michael@0: handler = ListHandler() michael@0: handler.setFormatter(mozlog.MozFormatter()) michael@0: log = mozlog.getLogger(log_name, handler=handler) michael@0: log.info('no timestamp') michael@0: self.assertTrue(handler.messages[-1].startswith('%s ' % log_name)) michael@0: handler.setFormatter(mozlog.MozFormatter(include_timestamp=True)) michael@0: log.info('timestamp') michael@0: # Just verify that this raises no exceptions. michael@0: datetime.datetime.strptime(handler.messages[-1][:23], michael@0: '%Y-%m-%d %H:%M:%S,%f') michael@0: michael@0: class TestStructuredLogging(unittest.TestCase): michael@0: """Tests structured output in mozlog.""" michael@0: michael@0: def setUp(self): michael@0: self.handler = ListHandler() michael@0: self.handler.setFormatter(mozlog.JSONFormatter()) michael@0: self.logger = mozlog.MozLogger('test.Logger') michael@0: self.logger.addHandler(self.handler) michael@0: self.logger.setLevel(mozlog.DEBUG) michael@0: michael@0: def check_messages(self, expected, actual): michael@0: """Checks actual for equality with corresponding fields in actual. michael@0: The actual message should contain all fields in expected, and michael@0: should be identical, with the exception of the timestamp field. michael@0: The actual message should contain no fields other than the timestamp michael@0: field and those present in expected.""" michael@0: michael@0: self.assertTrue(isinstance(actual['_time'], (int, long))) michael@0: michael@0: for k, v in expected.items(): michael@0: self.assertEqual(v, actual[k]) michael@0: michael@0: for k in actual.keys(): michael@0: if k != '_time': michael@0: self.assertTrue(expected.get(k) is not None) michael@0: michael@0: def test_structured_output(self): michael@0: self.logger.log_structured('test_message', michael@0: {'_level': mozlog.INFO, michael@0: '_message': 'message one'}) michael@0: self.logger.log_structured('test_message', michael@0: {'_level': mozlog.INFO, michael@0: '_message': 'message two'}) michael@0: self.logger.log_structured('error_message', michael@0: {'_level': mozlog.ERROR, michael@0: 'diagnostic': 'unexpected error'}) michael@0: michael@0: message_one_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'INFO', michael@0: '_message': 'message one', michael@0: 'action': 'test_message'} michael@0: message_two_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'INFO', michael@0: '_message': 'message two', michael@0: 'action': 'test_message'} michael@0: message_three_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'ERROR', michael@0: 'diagnostic': 'unexpected error', michael@0: 'action': 'error_message'} michael@0: michael@0: message_one_actual = json.loads(self.handler.messages[0]) michael@0: message_two_actual = json.loads(self.handler.messages[1]) michael@0: message_three_actual = json.loads(self.handler.messages[2]) michael@0: michael@0: self.check_messages(message_one_expected, message_one_actual) michael@0: self.check_messages(message_two_expected, message_two_actual) michael@0: self.check_messages(message_three_expected, message_three_actual) michael@0: michael@0: def test_unstructured_conversion(self): michael@0: """ Tests that logging to a logger with a structured formatter michael@0: via the traditional logging interface works as expected. """ michael@0: self.logger.info('%s %s %d', 'Message', 'number', 1) michael@0: self.logger.error('Message number 2') michael@0: self.logger.debug('Message with %s', 'some extras', michael@0: extra={'params': {'action': 'mozlog_test_output', michael@0: 'is_failure': False}}) michael@0: message_one_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'INFO', michael@0: '_message': 'Message number 1'} michael@0: message_two_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'ERROR', michael@0: '_message': 'Message number 2'} michael@0: message_three_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'DEBUG', michael@0: '_message': 'Message with some extras', michael@0: 'action': 'mozlog_test_output', michael@0: 'is_failure': False} michael@0: michael@0: message_one_actual = json.loads(self.handler.messages[0]) michael@0: message_two_actual = json.loads(self.handler.messages[1]) michael@0: message_three_actual = json.loads(self.handler.messages[2]) michael@0: michael@0: self.check_messages(message_one_expected, message_one_actual) michael@0: self.check_messages(message_two_expected, message_two_actual) michael@0: self.check_messages(message_three_expected, message_three_actual) michael@0: michael@0: def message_callback(self): michael@0: if len(self.handler.messages) == 3: michael@0: message_one_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'DEBUG', michael@0: '_message': 'socket message one', michael@0: 'action': 'test_message'} michael@0: message_two_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'DEBUG', michael@0: '_message': 'socket message two', michael@0: 'action': 'test_message'} michael@0: message_three_expected = {'_namespace': 'test.Logger', michael@0: '_level': 'DEBUG', michael@0: '_message': 'socket message three', michael@0: 'action': 'test_message'} michael@0: michael@0: message_one_actual = json.loads(self.handler.messages[0]) michael@0: michael@0: message_two_actual = json.loads(self.handler.messages[1]) michael@0: michael@0: message_three_actual = json.loads(self.handler.messages[2]) michael@0: michael@0: self.check_messages(message_one_expected, message_one_actual) michael@0: self.check_messages(message_two_expected, message_two_actual) michael@0: self.check_messages(message_three_expected, message_three_actual) michael@0: michael@0: def test_log_listener(self): michael@0: connection = '127.0.0.1', 0 michael@0: self.log_server = mozlog.LogMessageServer(connection, michael@0: self.logger, michael@0: message_callback=self.message_callback, michael@0: timeout=0.5) michael@0: michael@0: message_string_one = json.dumps({'_message': 'socket message one', michael@0: 'action': 'test_message', michael@0: '_level': 'DEBUG'}) michael@0: message_string_two = json.dumps({'_message': 'socket message two', michael@0: 'action': 'test_message', michael@0: '_level': 'DEBUG'}) michael@0: michael@0: message_string_three = json.dumps({'_message': 'socket message three', michael@0: 'action': 'test_message', michael@0: '_level': 'DEBUG'}) michael@0: michael@0: message_string = message_string_one + '\n' + \ michael@0: message_string_two + '\n' + \ michael@0: message_string_three + '\n' michael@0: michael@0: server_thread = threading.Thread(target=self.log_server.handle_request) michael@0: server_thread.start() michael@0: michael@0: host, port = self.log_server.server_address michael@0: michael@0: sock = socket.socket() michael@0: sock.connect((host, port)) michael@0: michael@0: # Sleeps prevent listener from receiving entire message in a single call michael@0: # to recv in order to test reconstruction of partial messages. michael@0: sock.sendall(message_string[:8]) michael@0: time.sleep(.01) michael@0: sock.sendall(message_string[8:32]) michael@0: time.sleep(.01) michael@0: sock.sendall(message_string[32:64]) michael@0: time.sleep(.01) michael@0: sock.sendall(message_string[64:128]) michael@0: time.sleep(.01) michael@0: sock.sendall(message_string[128:]) michael@0: michael@0: server_thread.join() michael@0: michael@0: class Loggable(mozlog.LoggingMixin): michael@0: """Trivial class inheriting from LoggingMixin""" michael@0: pass michael@0: michael@0: class TestLoggingMixin(unittest.TestCase): michael@0: """Tests basic use of LoggingMixin""" michael@0: michael@0: def test_mixin(self): michael@0: loggable = Loggable() michael@0: self.assertTrue(not hasattr(loggable, "_logger")) michael@0: loggable.log(mozlog.INFO, "This will instantiate the logger") michael@0: self.assertTrue(hasattr(loggable, "_logger")) michael@0: self.assertEqual(loggable._logger.name, "test_logger.Loggable") michael@0: michael@0: self.assertRaises(ValueError, loggable.set_logger, michael@0: "not a logger") michael@0: michael@0: logger = mozlog.MozLogger('test.mixin') michael@0: handler = ListHandler() michael@0: logger.addHandler(handler) michael@0: loggable.set_logger(logger) michael@0: self.assertTrue(isinstance(loggable._logger.handlers[0], michael@0: ListHandler)) michael@0: self.assertEqual(loggable._logger.name, "test.mixin") michael@0: michael@0: loggable.log(mozlog.WARN, 'message for "log" method') michael@0: loggable.info('message for "info" method') michael@0: loggable.error('message for "error" method') michael@0: loggable.log_structured('test_message', michael@0: params={'_message': 'message for ' + \ michael@0: '"log_structured" method'}) michael@0: michael@0: expected_messages = ['message for "log" method', michael@0: 'message for "info" method', michael@0: 'message for "error" method', michael@0: 'message for "log_structured" method'] michael@0: michael@0: actual_messages = loggable._logger.handlers[0].messages michael@0: self.assertEqual(expected_messages, actual_messages) michael@0: michael@0: if __name__ == '__main__': michael@0: unittest.main()