1.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
1.2 +++ b/testing/mozbase/mozlog/tests/test_logger.py Wed Dec 31 06:09:35 2014 +0100
1.3 @@ -0,0 +1,259 @@
1.4 +# This Source Code Form is subject to the terms of the Mozilla Public
1.5 +# License, v. 2.0. If a copy of the MPL was not distributed with this file,
1.6 +# You can obtain one at http://mozilla.org/MPL/2.0/.
1.7 +
1.8 +import datetime
1.9 +import json
1.10 +import socket
1.11 +import threading
1.12 +import time
1.13 +import unittest
1.14 +
1.15 +import mozfile
1.16 +
1.17 +import mozlog
1.18 +
1.19 +class ListHandler(mozlog.Handler):
1.20 + """Mock handler appends messages to a list for later inspection."""
1.21 +
1.22 + def __init__(self):
1.23 + mozlog.Handler.__init__(self)
1.24 + self.messages = []
1.25 +
1.26 + def emit(self, record):
1.27 + self.messages.append(self.format(record))
1.28 +
1.29 +class TestLogging(unittest.TestCase):
1.30 + """Tests behavior of basic mozlog api."""
1.31 +
1.32 + def test_logger_defaults(self):
1.33 + """Tests the default logging format and behavior."""
1.34 +
1.35 + default_logger = mozlog.getLogger('default.logger')
1.36 + self.assertEqual(default_logger.name, 'default.logger')
1.37 + self.assertEqual(len(default_logger.handlers), 1)
1.38 + self.assertTrue(isinstance(default_logger.handlers[0],
1.39 + mozlog.StreamHandler))
1.40 +
1.41 + f = mozfile.NamedTemporaryFile()
1.42 + list_logger = mozlog.getLogger('file.logger',
1.43 + handler=mozlog.FileHandler(f.name))
1.44 + self.assertEqual(len(list_logger.handlers), 1)
1.45 + self.assertTrue(isinstance(list_logger.handlers[0],
1.46 + mozlog.FileHandler))
1.47 + f.close()
1.48 +
1.49 + self.assertRaises(ValueError, mozlog.getLogger,
1.50 + 'file.logger', handler=ListHandler())
1.51 +
1.52 + def test_timestamps(self):
1.53 + """Verifies that timestamps are included when asked for."""
1.54 + log_name = 'test'
1.55 + handler = ListHandler()
1.56 + handler.setFormatter(mozlog.MozFormatter())
1.57 + log = mozlog.getLogger(log_name, handler=handler)
1.58 + log.info('no timestamp')
1.59 + self.assertTrue(handler.messages[-1].startswith('%s ' % log_name))
1.60 + handler.setFormatter(mozlog.MozFormatter(include_timestamp=True))
1.61 + log.info('timestamp')
1.62 + # Just verify that this raises no exceptions.
1.63 + datetime.datetime.strptime(handler.messages[-1][:23],
1.64 + '%Y-%m-%d %H:%M:%S,%f')
1.65 +
1.66 +class TestStructuredLogging(unittest.TestCase):
1.67 + """Tests structured output in mozlog."""
1.68 +
1.69 + def setUp(self):
1.70 + self.handler = ListHandler()
1.71 + self.handler.setFormatter(mozlog.JSONFormatter())
1.72 + self.logger = mozlog.MozLogger('test.Logger')
1.73 + self.logger.addHandler(self.handler)
1.74 + self.logger.setLevel(mozlog.DEBUG)
1.75 +
1.76 + def check_messages(self, expected, actual):
1.77 + """Checks actual for equality with corresponding fields in actual.
1.78 + The actual message should contain all fields in expected, and
1.79 + should be identical, with the exception of the timestamp field.
1.80 + The actual message should contain no fields other than the timestamp
1.81 + field and those present in expected."""
1.82 +
1.83 + self.assertTrue(isinstance(actual['_time'], (int, long)))
1.84 +
1.85 + for k, v in expected.items():
1.86 + self.assertEqual(v, actual[k])
1.87 +
1.88 + for k in actual.keys():
1.89 + if k != '_time':
1.90 + self.assertTrue(expected.get(k) is not None)
1.91 +
1.92 + def test_structured_output(self):
1.93 + self.logger.log_structured('test_message',
1.94 + {'_level': mozlog.INFO,
1.95 + '_message': 'message one'})
1.96 + self.logger.log_structured('test_message',
1.97 + {'_level': mozlog.INFO,
1.98 + '_message': 'message two'})
1.99 + self.logger.log_structured('error_message',
1.100 + {'_level': mozlog.ERROR,
1.101 + 'diagnostic': 'unexpected error'})
1.102 +
1.103 + message_one_expected = {'_namespace': 'test.Logger',
1.104 + '_level': 'INFO',
1.105 + '_message': 'message one',
1.106 + 'action': 'test_message'}
1.107 + message_two_expected = {'_namespace': 'test.Logger',
1.108 + '_level': 'INFO',
1.109 + '_message': 'message two',
1.110 + 'action': 'test_message'}
1.111 + message_three_expected = {'_namespace': 'test.Logger',
1.112 + '_level': 'ERROR',
1.113 + 'diagnostic': 'unexpected error',
1.114 + 'action': 'error_message'}
1.115 +
1.116 + message_one_actual = json.loads(self.handler.messages[0])
1.117 + message_two_actual = json.loads(self.handler.messages[1])
1.118 + message_three_actual = json.loads(self.handler.messages[2])
1.119 +
1.120 + self.check_messages(message_one_expected, message_one_actual)
1.121 + self.check_messages(message_two_expected, message_two_actual)
1.122 + self.check_messages(message_three_expected, message_three_actual)
1.123 +
1.124 + def test_unstructured_conversion(self):
1.125 + """ Tests that logging to a logger with a structured formatter
1.126 + via the traditional logging interface works as expected. """
1.127 + self.logger.info('%s %s %d', 'Message', 'number', 1)
1.128 + self.logger.error('Message number 2')
1.129 + self.logger.debug('Message with %s', 'some extras',
1.130 + extra={'params': {'action': 'mozlog_test_output',
1.131 + 'is_failure': False}})
1.132 + message_one_expected = {'_namespace': 'test.Logger',
1.133 + '_level': 'INFO',
1.134 + '_message': 'Message number 1'}
1.135 + message_two_expected = {'_namespace': 'test.Logger',
1.136 + '_level': 'ERROR',
1.137 + '_message': 'Message number 2'}
1.138 + message_three_expected = {'_namespace': 'test.Logger',
1.139 + '_level': 'DEBUG',
1.140 + '_message': 'Message with some extras',
1.141 + 'action': 'mozlog_test_output',
1.142 + 'is_failure': False}
1.143 +
1.144 + message_one_actual = json.loads(self.handler.messages[0])
1.145 + message_two_actual = json.loads(self.handler.messages[1])
1.146 + message_three_actual = json.loads(self.handler.messages[2])
1.147 +
1.148 + self.check_messages(message_one_expected, message_one_actual)
1.149 + self.check_messages(message_two_expected, message_two_actual)
1.150 + self.check_messages(message_three_expected, message_three_actual)
1.151 +
1.152 + def message_callback(self):
1.153 + if len(self.handler.messages) == 3:
1.154 + message_one_expected = {'_namespace': 'test.Logger',
1.155 + '_level': 'DEBUG',
1.156 + '_message': 'socket message one',
1.157 + 'action': 'test_message'}
1.158 + message_two_expected = {'_namespace': 'test.Logger',
1.159 + '_level': 'DEBUG',
1.160 + '_message': 'socket message two',
1.161 + 'action': 'test_message'}
1.162 + message_three_expected = {'_namespace': 'test.Logger',
1.163 + '_level': 'DEBUG',
1.164 + '_message': 'socket message three',
1.165 + 'action': 'test_message'}
1.166 +
1.167 + message_one_actual = json.loads(self.handler.messages[0])
1.168 +
1.169 + message_two_actual = json.loads(self.handler.messages[1])
1.170 +
1.171 + message_three_actual = json.loads(self.handler.messages[2])
1.172 +
1.173 + self.check_messages(message_one_expected, message_one_actual)
1.174 + self.check_messages(message_two_expected, message_two_actual)
1.175 + self.check_messages(message_three_expected, message_three_actual)
1.176 +
1.177 + def test_log_listener(self):
1.178 + connection = '127.0.0.1', 0
1.179 + self.log_server = mozlog.LogMessageServer(connection,
1.180 + self.logger,
1.181 + message_callback=self.message_callback,
1.182 + timeout=0.5)
1.183 +
1.184 + message_string_one = json.dumps({'_message': 'socket message one',
1.185 + 'action': 'test_message',
1.186 + '_level': 'DEBUG'})
1.187 + message_string_two = json.dumps({'_message': 'socket message two',
1.188 + 'action': 'test_message',
1.189 + '_level': 'DEBUG'})
1.190 +
1.191 + message_string_three = json.dumps({'_message': 'socket message three',
1.192 + 'action': 'test_message',
1.193 + '_level': 'DEBUG'})
1.194 +
1.195 + message_string = message_string_one + '\n' + \
1.196 + message_string_two + '\n' + \
1.197 + message_string_three + '\n'
1.198 +
1.199 + server_thread = threading.Thread(target=self.log_server.handle_request)
1.200 + server_thread.start()
1.201 +
1.202 + host, port = self.log_server.server_address
1.203 +
1.204 + sock = socket.socket()
1.205 + sock.connect((host, port))
1.206 +
1.207 + # Sleeps prevent listener from receiving entire message in a single call
1.208 + # to recv in order to test reconstruction of partial messages.
1.209 + sock.sendall(message_string[:8])
1.210 + time.sleep(.01)
1.211 + sock.sendall(message_string[8:32])
1.212 + time.sleep(.01)
1.213 + sock.sendall(message_string[32:64])
1.214 + time.sleep(.01)
1.215 + sock.sendall(message_string[64:128])
1.216 + time.sleep(.01)
1.217 + sock.sendall(message_string[128:])
1.218 +
1.219 + server_thread.join()
1.220 +
1.221 +class Loggable(mozlog.LoggingMixin):
1.222 + """Trivial class inheriting from LoggingMixin"""
1.223 + pass
1.224 +
1.225 +class TestLoggingMixin(unittest.TestCase):
1.226 + """Tests basic use of LoggingMixin"""
1.227 +
1.228 + def test_mixin(self):
1.229 + loggable = Loggable()
1.230 + self.assertTrue(not hasattr(loggable, "_logger"))
1.231 + loggable.log(mozlog.INFO, "This will instantiate the logger")
1.232 + self.assertTrue(hasattr(loggable, "_logger"))
1.233 + self.assertEqual(loggable._logger.name, "test_logger.Loggable")
1.234 +
1.235 + self.assertRaises(ValueError, loggable.set_logger,
1.236 + "not a logger")
1.237 +
1.238 + logger = mozlog.MozLogger('test.mixin')
1.239 + handler = ListHandler()
1.240 + logger.addHandler(handler)
1.241 + loggable.set_logger(logger)
1.242 + self.assertTrue(isinstance(loggable._logger.handlers[0],
1.243 + ListHandler))
1.244 + self.assertEqual(loggable._logger.name, "test.mixin")
1.245 +
1.246 + loggable.log(mozlog.WARN, 'message for "log" method')
1.247 + loggable.info('message for "info" method')
1.248 + loggable.error('message for "error" method')
1.249 + loggable.log_structured('test_message',
1.250 + params={'_message': 'message for ' + \
1.251 + '"log_structured" method'})
1.252 +
1.253 + expected_messages = ['message for "log" method',
1.254 + 'message for "info" method',
1.255 + 'message for "error" method',
1.256 + 'message for "log_structured" method']
1.257 +
1.258 + actual_messages = loggable._logger.handlers[0].messages
1.259 + self.assertEqual(expected_messages, actual_messages)
1.260 +
1.261 +if __name__ == '__main__':
1.262 + unittest.main()
