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