The Tor Browser: testing/mozbase/mozlog/tests/test

Incorporate requested changes from Mozilla in review:
https://bugzilla.mozilla.org/show_bug.cgi?id=1123480#c6

     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/.

     5 import datetime

     6 import json

     7 import socket

     8 import threading

     9 import time

    10 import unittest

    12 import mozfile

    14 import mozlog

    16 class ListHandler(mozlog.Handler):

    17     """Mock handler appends messages to a list for later inspection."""

    19     def __init__(self):

    20         mozlog.Handler.__init__(self)

    21         self.messages = []

    23     def emit(self, record):

    24         self.messages.append(self.format(record))

    26 class TestLogging(unittest.TestCase):

    27     """Tests behavior of basic mozlog api."""

    29     def test_logger_defaults(self):

    30         """Tests the default logging format and behavior."""

    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))

    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()

    46         self.assertRaises(ValueError, mozlog.getLogger,

    47                           'file.logger', handler=ListHandler())

    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')

    63 class TestStructuredLogging(unittest.TestCase):

    64     """Tests structured output in mozlog."""

    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)

    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."""

    80         self.assertTrue(isinstance(actual['_time'], (int, long)))

    82         for k, v in expected.items():

    83             self.assertEqual(v, actual[k])

    85         for k in actual.keys():

    86             if k != '_time':

    87                 self.assertTrue(expected.get(k) is not None)

    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'})

   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'}

   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])

   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)

   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}

   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])

   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)

   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'}

   164             message_one_actual = json.loads(self.handler.messages[0])

   166             message_two_actual = json.loads(self.handler.messages[1])

   168             message_three_actual = json.loads(self.handler.messages[2])

   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)

   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)

   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'})

   188         message_string_three = json.dumps({'_message': 'socket message three',

   189                                            'action': 'test_message',

   190                                            '_level': 'DEBUG'})

   192         message_string = message_string_one + '\n' + \

   193                          message_string_two + '\n' + \

   194                          message_string_three + '\n'

   196         server_thread = threading.Thread(target=self.log_server.handle_request)

   197         server_thread.start()

   199         host, port = self.log_server.server_address

   201         sock = socket.socket()

   202         sock.connect((host, port))

   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:])

   216         server_thread.join()

   218 class Loggable(mozlog.LoggingMixin):

   219     """Trivial class inheriting from LoggingMixin"""

   220     pass

   222 class TestLoggingMixin(unittest.TestCase):

   223     """Tests basic use of LoggingMixin"""

   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")

   232         self.assertRaises(ValueError, loggable.set_logger,

   233                           "not a logger")

   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")

   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'})

   250         expected_messages = ['message for "log" method',

   251                              'message for "info" method',

   252                              'message for "error" method',

   253                              'message for "log_structured" method']

   255         actual_messages = loggable._logger.handlers[0].messages

   256         self.assertEqual(expected_messages, actual_messages)

   258 if __name__ == '__main__':

   259     unittest.main()

The Tor Browser / file revision

testing/mozbase/mozlog/tests/test_logger.py@b8a032363ba2

testing/mozbase/mozlog/tests/test_logger.py