1# -*- coding: utf-8 -*-
2
3from __future__ import absolute_import
4
5import argparse
6import json
7import optparse
8import os
9import sys
10import unittest
11from six import StringIO
12
13import mozunit
14
15import mozfile
16from mozlog import (
17    commandline,
18    reader,
19    structuredlog,
20    stdadapter,
21    handlers,
22    formatters,
23)
24import six
25
26
27class TestHandler(object):
28    def __init__(self):
29        self.items = []
30
31    def __call__(self, data):
32        self.items.append(data)
33
34    @property
35    def last_item(self):
36        return self.items[-1]
37
38    @property
39    def empty(self):
40        return not self.items
41
42
43class BaseStructuredTest(unittest.TestCase):
44    def setUp(self):
45        self.logger = structuredlog.StructuredLogger("test")
46        self.handler = TestHandler()
47        self.logger.add_handler(self.handler)
48
49    def pop_last_item(self):
50        return self.handler.items.pop()
51
52    def assert_log_equals(self, expected, actual=None):
53        if actual is None:
54            actual = self.pop_last_item()
55
56        all_expected = {"pid": os.getpid(), "thread": "MainThread", "source": "test"}
57        specials = set(["time"])
58
59        all_expected.update(expected)
60        for key, value in six.iteritems(all_expected):
61            self.assertEqual(actual[key], value)
62
63        self.assertEquals(set(all_expected.keys()) | specials, set(actual.keys()))
64
65
66class TestStatusHandler(BaseStructuredTest):
67    def setUp(self):
68        super(TestStatusHandler, self).setUp()
69        self.handler = handlers.StatusHandler()
70        self.logger.add_handler(self.handler)
71
72    def test_failure_run(self):
73        self.logger.suite_start([])
74        self.logger.test_start("test1")
75        self.logger.test_status("test1", "sub1", status="PASS")
76        self.logger.test_status("test1", "sub2", status="TIMEOUT")
77        self.logger.test_status(
78            "test1", "sub3", status="FAIL", expected="PASS", known_intermittent=["FAIL"]
79        )
80        self.logger.test_end("test1", status="OK")
81        self.logger.suite_end()
82        summary = self.handler.summarize()
83        self.assertIn("TIMEOUT", summary.unexpected_statuses)
84        self.assertEqual(1, summary.unexpected_statuses["TIMEOUT"])
85        self.assertIn("PASS", summary.expected_statuses)
86        self.assertEqual(1, summary.expected_statuses["PASS"])
87        self.assertIn("OK", summary.expected_statuses)
88        self.assertEqual(1, summary.expected_statuses["OK"])
89        self.assertIn("FAIL", summary.expected_statuses)
90        self.assertEqual(1, summary.expected_statuses["FAIL"])
91        self.assertIn("FAIL", summary.known_intermittent_statuses)
92        self.assertEqual(1, summary.known_intermittent_statuses["FAIL"])
93        self.assertEqual(3, summary.action_counts["test_status"])
94        self.assertEqual(1, summary.action_counts["test_end"])
95
96    def test_precondition_failed_run(self):
97        self.logger.suite_start([])
98        self.logger.test_start("test1")
99        self.logger.test_end("test1", status="PRECONDITION_FAILED")
100        self.logger.test_start("test2")
101        self.logger.test_status("test2", "sub1", status="PRECONDITION_FAILED")
102        self.logger.test_end("test2", status="OK")
103        self.logger.suite_end()
104        summary = self.handler.summarize()
105        self.assertEqual(1, summary.expected_statuses["OK"])
106        self.assertEqual(2, summary.unexpected_statuses["PRECONDITION_FAILED"])
107
108    def test_error_run(self):
109        self.logger.suite_start([])
110        self.logger.test_start("test1")
111        self.logger.error("ERRR!")
112        self.logger.test_end("test1", status="OK")
113        self.logger.test_start("test2")
114        self.logger.test_end("test2", status="OK")
115        self.logger.suite_end()
116        summary = self.handler.summarize()
117        self.assertIn("ERROR", summary.log_level_counts)
118        self.assertEqual(1, summary.log_level_counts["ERROR"])
119        self.assertIn("OK", summary.expected_statuses)
120        self.assertEqual(2, summary.expected_statuses["OK"])
121
122
123class TestSummaryHandler(BaseStructuredTest):
124    def setUp(self):
125        super(TestSummaryHandler, self).setUp()
126        self.handler = handlers.SummaryHandler()
127        self.logger.add_handler(self.handler)
128
129    def test_failure_run(self):
130        self.logger.suite_start([])
131        self.logger.test_start("test1")
132        self.logger.test_status("test1", "sub1", status="PASS")
133        self.logger.test_status("test1", "sub2", status="TIMEOUT")
134        self.logger.assertion_count("test1", 5, 1, 10)
135        self.logger.assertion_count("test1", 5, 10, 15)
136        self.logger.test_end("test1", status="OK")
137        self.logger.suite_end()
138
139        counts = self.handler.current["counts"]
140        self.assertIn("timeout", counts["subtest"]["unexpected"])
141        self.assertEqual(1, counts["subtest"]["unexpected"]["timeout"])
142        self.assertIn("pass", counts["subtest"]["expected"])
143        self.assertEqual(1, counts["subtest"]["expected"]["pass"])
144        self.assertIn("ok", counts["test"]["expected"])
145        self.assertEqual(1, counts["test"]["expected"]["ok"])
146        self.assertIn("pass", counts["assert"]["unexpected"])
147        self.assertEqual(1, counts["assert"]["unexpected"]["pass"])
148        self.assertIn("fail", counts["assert"]["expected"])
149        self.assertEqual(1, counts["assert"]["expected"]["fail"])
150
151        logs = self.handler.current["unexpected_logs"]
152        self.assertEqual(1, len(logs))
153        self.assertIn("test1", logs)
154        self.assertEqual(1, len(logs["test1"]))
155        self.assertEqual("sub2", logs["test1"][0]["subtest"])
156
157    def test_precondition_failed_run(self):
158        self.logger.suite_start([])
159        self.logger.test_start("test1")
160        self.logger.test_status("test1", "sub1", status="PASS")
161        self.logger.test_end("test1", status="PRECONDITION_FAILED")
162        self.logger.test_start("test2")
163        self.logger.test_status("test2", "sub1", status="PRECONDITION_FAILED")
164        self.logger.test_status("test2", "sub2", status="PRECONDITION_FAILED")
165        self.logger.test_end("test2", status="OK")
166        self.logger.suite_end()
167
168        counts = self.handler.current["counts"]
169        self.assertIn("precondition_failed", counts["test"]["unexpected"])
170        self.assertEqual(1, counts["test"]["unexpected"]["precondition_failed"])
171        self.assertIn("pass", counts["subtest"]["expected"])
172        self.assertEqual(1, counts["subtest"]["expected"]["pass"])
173        self.assertIn("ok", counts["test"]["expected"])
174        self.assertEqual(1, counts["test"]["expected"]["ok"])
175        self.assertIn("precondition_failed", counts["subtest"]["unexpected"])
176        self.assertEqual(2, counts["subtest"]["unexpected"]["precondition_failed"])
177
178
179class TestStructuredLog(BaseStructuredTest):
180    def test_suite_start(self):
181        self.logger.suite_start(["test"], "logtest")
182        self.assert_log_equals(
183            {"action": "suite_start", "name": "logtest", "tests": {"default": ["test"]}}
184        )
185        self.logger.suite_end()
186
187    def test_suite_end(self):
188        self.logger.suite_start([])
189        self.logger.suite_end()
190        self.assert_log_equals({"action": "suite_end"})
191
192    def test_start(self):
193        self.logger.suite_start([])
194        self.logger.test_start("test1")
195        self.assert_log_equals({"action": "test_start", "test": "test1"})
196
197        self.logger.test_start(("test1", "==", "test1-ref"), path="path/to/test")
198        self.assert_log_equals(
199            {
200                "action": "test_start",
201                "test": ("test1", "==", "test1-ref"),
202                "path": "path/to/test",
203            }
204        )
205        self.logger.suite_end()
206
207    def test_start_inprogress(self):
208        self.logger.suite_start([])
209        self.logger.test_start("test1")
210        self.logger.test_start("test1")
211        self.assert_log_equals(
212            {
213                "action": "log",
214                "message": "test_start for test1 logged while in progress.",
215                "level": "ERROR",
216            }
217        )
218        self.logger.suite_end()
219
220    def test_status(self):
221        self.logger.suite_start([])
222        self.logger.test_start("test1")
223        self.logger.test_status(
224            "test1", "subtest name", "fail", expected="FAIL", message="Test message"
225        )
226        self.assert_log_equals(
227            {
228                "action": "test_status",
229                "subtest": "subtest name",
230                "status": "FAIL",
231                "message": "Test message",
232                "test": "test1",
233            }
234        )
235        self.logger.test_end("test1", "OK")
236        self.logger.suite_end()
237
238    def test_status_1(self):
239        self.logger.suite_start([])
240        self.logger.test_start("test1")
241        self.logger.test_status("test1", "subtest name", "fail")
242        self.assert_log_equals(
243            {
244                "action": "test_status",
245                "subtest": "subtest name",
246                "status": "FAIL",
247                "expected": "PASS",
248                "test": "test1",
249            }
250        )
251        self.logger.test_end("test1", "OK")
252        self.logger.suite_end()
253
254    def test_status_2(self):
255        self.assertRaises(
256            ValueError,
257            self.logger.test_status,
258            "test1",
259            "subtest name",
260            "XXXUNKNOWNXXX",
261        )
262
263    def test_status_extra(self):
264        self.logger.suite_start([])
265        self.logger.test_start("test1")
266        self.logger.test_status(
267            "test1", "subtest name", "FAIL", expected="PASS", extra={"data": 42}
268        )
269        self.assert_log_equals(
270            {
271                "action": "test_status",
272                "subtest": "subtest name",
273                "status": "FAIL",
274                "expected": "PASS",
275                "test": "test1",
276                "extra": {"data": 42},
277            }
278        )
279        self.logger.test_end("test1", "OK")
280        self.logger.suite_end()
281
282    def test_status_stack(self):
283        self.logger.suite_start([])
284        self.logger.test_start("test1")
285        self.logger.test_status(
286            "test1",
287            "subtest name",
288            "FAIL",
289            expected="PASS",
290            stack="many\nlines\nof\nstack",
291        )
292        self.assert_log_equals(
293            {
294                "action": "test_status",
295                "subtest": "subtest name",
296                "status": "FAIL",
297                "expected": "PASS",
298                "test": "test1",
299                "stack": "many\nlines\nof\nstack",
300            }
301        )
302        self.logger.test_end("test1", "OK")
303        self.logger.suite_end()
304
305    def test_status_known_intermittent(self):
306        self.logger.suite_start([])
307        self.logger.test_start("test1")
308        self.logger.test_status(
309            "test1", "subtest name", "fail", known_intermittent=["FAIL"]
310        )
311        self.assert_log_equals(
312            {
313                "action": "test_status",
314                "subtest": "subtest name",
315                "status": "FAIL",
316                "expected": "PASS",
317                "known_intermittent": ["FAIL"],
318                "test": "test1",
319            }
320        )
321        self.logger.test_end("test1", "OK")
322        self.logger.suite_end()
323
324    def test_status_not_started(self):
325        self.logger.test_status("test_UNKNOWN", "subtest", "PASS")
326        self.assertTrue(
327            self.pop_last_item()["message"].startswith(
328                "test_status for test_UNKNOWN logged while not in progress. Logged with data: {"
329            )
330        )
331
332    def test_remove_optional_defaults(self):
333        self.logger.suite_start([])
334        self.logger.test_start("test1")
335        self.logger.test_status(
336            "test1", "subtest name", "fail", message=None, stack=None
337        )
338        self.assert_log_equals(
339            {
340                "action": "test_status",
341                "subtest": "subtest name",
342                "status": "FAIL",
343                "expected": "PASS",
344                "test": "test1",
345            }
346        )
347        self.logger.test_end("test1", "OK")
348        self.logger.suite_end()
349
350    def test_remove_optional_defaults_raw_log(self):
351        self.logger.log_raw({"action": "suite_start", "tests": [1], "name": None})
352        self.assert_log_equals({"action": "suite_start", "tests": {"default": ["1"]}})
353        self.logger.suite_end()
354
355    def test_end(self):
356        self.logger.suite_start([])
357        self.logger.test_start("test1")
358        self.logger.test_end("test1", "fail", message="Test message")
359        self.assert_log_equals(
360            {
361                "action": "test_end",
362                "status": "FAIL",
363                "expected": "OK",
364                "message": "Test message",
365                "test": "test1",
366            }
367        )
368        self.logger.suite_end()
369
370    def test_end_1(self):
371        self.logger.suite_start([])
372        self.logger.test_start("test1")
373        self.logger.test_end("test1", "PASS", expected="PASS", extra={"data": 123})
374        self.assert_log_equals(
375            {
376                "action": "test_end",
377                "status": "PASS",
378                "extra": {"data": 123},
379                "test": "test1",
380            }
381        )
382        self.logger.suite_end()
383
384    def test_end_2(self):
385        self.assertRaises(ValueError, self.logger.test_end, "test1", "XXXUNKNOWNXXX")
386
387    def test_end_stack(self):
388        self.logger.suite_start([])
389        self.logger.test_start("test1")
390        self.logger.test_end(
391            "test1", "PASS", expected="PASS", stack="many\nlines\nof\nstack"
392        )
393        self.assert_log_equals(
394            {
395                "action": "test_end",
396                "status": "PASS",
397                "test": "test1",
398                "stack": "many\nlines\nof\nstack",
399            }
400        )
401        self.logger.suite_end()
402
403    def test_end_no_start(self):
404        self.logger.test_end("test1", "PASS", expected="PASS")
405        self.assertTrue(
406            self.pop_last_item()["message"].startswith(
407                "test_end for test1 logged while not in progress. Logged with data: {"
408            )
409        )
410        self.logger.suite_end()
411
412    def test_end_twice(self):
413        self.logger.suite_start([])
414        self.logger.test_start("test2")
415        self.logger.test_end("test2", "PASS", expected="PASS")
416        self.assert_log_equals(
417            {"action": "test_end", "status": "PASS", "test": "test2"}
418        )
419        self.logger.test_end("test2", "PASS", expected="PASS")
420        last_item = self.pop_last_item()
421        self.assertEquals(last_item["action"], "log")
422        self.assertEquals(last_item["level"], "ERROR")
423        self.assertTrue(
424            last_item["message"].startswith(
425                "test_end for test2 logged while not in progress. Logged with data: {"
426            )
427        )
428        self.logger.suite_end()
429
430    def test_suite_start_twice(self):
431        self.logger.suite_start([])
432        self.assert_log_equals({"action": "suite_start", "tests": {"default": []}})
433        self.logger.suite_start([])
434        last_item = self.pop_last_item()
435        self.assertEquals(last_item["action"], "log")
436        self.assertEquals(last_item["level"], "ERROR")
437        self.logger.suite_end()
438
439    def test_suite_end_no_start(self):
440        self.logger.suite_start([])
441        self.assert_log_equals({"action": "suite_start", "tests": {"default": []}})
442        self.logger.suite_end()
443        self.assert_log_equals({"action": "suite_end"})
444        self.logger.suite_end()
445        last_item = self.pop_last_item()
446        self.assertEquals(last_item["action"], "log")
447        self.assertEquals(last_item["level"], "ERROR")
448
449    def test_multiple_loggers_suite_start(self):
450        logger1 = structuredlog.StructuredLogger("test")
451        self.logger.suite_start([])
452        logger1.suite_start([])
453        last_item = self.pop_last_item()
454        self.assertEquals(last_item["action"], "log")
455        self.assertEquals(last_item["level"], "ERROR")
456
457    def test_multiple_loggers_test_start(self):
458        logger1 = structuredlog.StructuredLogger("test")
459        self.logger.suite_start([])
460        self.logger.test_start("test")
461        logger1.test_start("test")
462        last_item = self.pop_last_item()
463        self.assertEquals(last_item["action"], "log")
464        self.assertEquals(last_item["level"], "ERROR")
465
466    def test_process(self):
467        self.logger.process_output(1234, "test output")
468        self.assert_log_equals(
469            {"action": "process_output", "process": "1234", "data": "test output"}
470        )
471
472    def test_process_start(self):
473        self.logger.process_start(1234)
474        self.assert_log_equals({"action": "process_start", "process": "1234"})
475
476    def test_process_exit(self):
477        self.logger.process_exit(1234, 0)
478        self.assert_log_equals(
479            {"action": "process_exit", "process": "1234", "exitcode": 0}
480        )
481
482    def test_log(self):
483        for level in ["critical", "error", "warning", "info", "debug"]:
484            getattr(self.logger, level)("message")
485            self.assert_log_equals(
486                {"action": "log", "level": level.upper(), "message": "message"}
487            )
488
489    def test_logging_adapter(self):
490        import logging
491
492        logging.basicConfig(level="DEBUG")
493        old_level = logging.root.getEffectiveLevel()
494        logging.root.setLevel("DEBUG")
495
496        std_logger = logging.getLogger("test")
497        std_logger.setLevel("DEBUG")
498
499        logger = stdadapter.std_logging_adapter(std_logger)
500
501        try:
502            for level in ["critical", "error", "warning", "info", "debug"]:
503                getattr(logger, level)("message")
504                self.assert_log_equals(
505                    {"action": "log", "level": level.upper(), "message": "message"}
506                )
507        finally:
508            logging.root.setLevel(old_level)
509
510    def test_add_remove_handlers(self):
511        handler = TestHandler()
512        self.logger.add_handler(handler)
513        self.logger.info("test1")
514
515        self.assert_log_equals({"action": "log", "level": "INFO", "message": "test1"})
516
517        self.assert_log_equals(
518            {"action": "log", "level": "INFO", "message": "test1"},
519            actual=handler.last_item,
520        )
521
522        self.logger.remove_handler(handler)
523        self.logger.info("test2")
524
525        self.assert_log_equals({"action": "log", "level": "INFO", "message": "test2"})
526
527        self.assert_log_equals(
528            {"action": "log", "level": "INFO", "message": "test1"},
529            actual=handler.last_item,
530        )
531
532    def test_wrapper(self):
533        file_like = structuredlog.StructuredLogFileLike(self.logger)
534
535        file_like.write("line 1")
536
537        self.assert_log_equals({"action": "log", "level": "INFO", "message": "line 1"})
538
539        file_like.write("line 2\n")
540
541        self.assert_log_equals({"action": "log", "level": "INFO", "message": "line 2"})
542
543        file_like.write("line 3\r")
544
545        self.assert_log_equals({"action": "log", "level": "INFO", "message": "line 3"})
546
547        file_like.write("line 4\r\n")
548
549        self.assert_log_equals({"action": "log", "level": "INFO", "message": "line 4"})
550
551    def test_shutdown(self):
552        # explicit shutdown
553        log = structuredlog.StructuredLogger("test 1")
554        log.add_handler(self.handler)
555        log.info("line 1")
556        self.assert_log_equals(
557            {"action": "log", "level": "INFO", "message": "line 1", "source": "test 1"}
558        )
559        log.shutdown()
560        self.assert_log_equals({"action": "shutdown", "source": "test 1"})
561        with self.assertRaises(structuredlog.LoggerShutdownError):
562            log.info("bad log")
563        with self.assertRaises(structuredlog.LoggerShutdownError):
564            log.log_raw({"action": "log", "level": "info", "message": "bad log"})
565
566        # shutdown still applies to new instances
567        del log
568        log = structuredlog.StructuredLogger("test 1")
569        with self.assertRaises(structuredlog.LoggerShutdownError):
570            log.info("bad log")
571
572        # context manager shutdown
573        with structuredlog.StructuredLogger("test 2") as log:
574            log.add_handler(self.handler)
575            log.info("line 2")
576            self.assert_log_equals(
577                {
578                    "action": "log",
579                    "level": "INFO",
580                    "message": "line 2",
581                    "source": "test 2",
582                }
583            )
584        self.assert_log_equals({"action": "shutdown", "source": "test 2"})
585
586        # shutdown prevents logging across instances
587        log1 = structuredlog.StructuredLogger("test 3")
588        log2 = structuredlog.StructuredLogger("test 3", component="bar")
589        log1.shutdown()
590        with self.assertRaises(structuredlog.LoggerShutdownError):
591            log2.info("line 3")
592
593
594class TestTypeConversions(BaseStructuredTest):
595    def test_raw(self):
596        self.logger.log_raw({"action": "suite_start", "tests": [1], "time": "1234"})
597        self.assert_log_equals(
598            {"action": "suite_start", "tests": {"default": ["1"]}, "time": 1234}
599        )
600        self.logger.suite_end()
601
602    def test_tuple(self):
603        self.logger.suite_start([])
604        if six.PY3:
605            self.logger.test_start(
606                (
607                    b"\xf0\x90\x8d\x84\xf0\x90\x8c\xb4\xf0\x90"
608                    b"\x8d\x83\xf0\x90\x8d\x84".decode(),
609                    42,
610                    u"\u16a4",
611                )
612            )
613        else:
614            self.logger.test_start(
615                (
616                    "\xf0\x90\x8d\x84\xf0\x90\x8c\xb4\xf0\x90"
617                    "\x8d\x83\xf0\x90\x8d\x84",
618                    42,
619                    u"\u16a4",
620                )
621            )
622        self.assert_log_equals(
623            {
624                "action": "test_start",
625                "test": (u"\U00010344\U00010334\U00010343\U00010344", u"42", u"\u16a4"),
626            }
627        )
628        self.logger.suite_end()
629
630    def test_non_string_messages(self):
631        self.logger.suite_start([])
632        self.logger.info(1)
633        self.assert_log_equals({"action": "log", "message": "1", "level": "INFO"})
634        self.logger.info([1, (2, "3"), "s", "s" + chr(255)])
635        if six.PY3:
636            self.assert_log_equals(
637                {
638                    "action": "log",
639                    "message": "[1, (2, '3'), 's', 's\xff']",
640                    "level": "INFO",
641                }
642            )
643        else:
644            self.assert_log_equals(
645                {
646                    "action": "log",
647                    "message": "[1, (2, '3'), 's', 's\\xff']",
648                    "level": "INFO",
649                }
650            )
651
652        self.logger.suite_end()
653
654    def test_utf8str_write(self):
655        with mozfile.NamedTemporaryFile() as logfile:
656            _fmt = formatters.TbplFormatter()
657            _handler = handlers.StreamHandler(logfile, _fmt)
658            self.logger.add_handler(_handler)
659            self.logger.suite_start([])
660            self.logger.info("☺")
661            logfile.seek(0)
662            data = logfile.readlines()[-1].strip()
663            if six.PY3:
664                self.assertEquals(data.decode(), "☺")
665            else:
666                self.assertEquals(data, "☺")
667            self.logger.suite_end()
668            self.logger.remove_handler(_handler)
669
670    def test_arguments(self):
671        self.logger.info(message="test")
672        self.assert_log_equals({"action": "log", "message": "test", "level": "INFO"})
673
674        self.logger.suite_start([], run_info={})
675        self.assert_log_equals(
676            {"action": "suite_start", "tests": {"default": []}, "run_info": {}}
677        )
678        self.logger.test_start(test="test1")
679        self.logger.test_status("subtest1", "FAIL", test="test1", status="PASS")
680        self.assert_log_equals(
681            {
682                "action": "test_status",
683                "test": "test1",
684                "subtest": "subtest1",
685                "status": "PASS",
686                "expected": "FAIL",
687            }
688        )
689        self.logger.process_output(123, "data", "test")
690        self.assert_log_equals(
691            {
692                "action": "process_output",
693                "process": "123",
694                "command": "test",
695                "data": "data",
696            }
697        )
698        self.assertRaises(
699            TypeError,
700            self.logger.test_status,
701            subtest="subtest2",
702            status="FAIL",
703            expected="PASS",
704        )
705        self.assertRaises(
706            TypeError,
707            self.logger.test_status,
708            "test1",
709            "subtest1",
710            "PASS",
711            "FAIL",
712            "message",
713            "stack",
714            {},
715            [],
716            "unexpected",
717        )
718        self.assertRaises(TypeError, self.logger.test_status, "test1", test="test2")
719        self.logger.suite_end()
720
721
722class TestComponentFilter(BaseStructuredTest):
723    def test_filter_component(self):
724        component_logger = structuredlog.StructuredLogger(
725            self.logger.name, "test_component"
726        )
727        component_logger.component_filter = handlers.LogLevelFilter(lambda x: x, "info")
728
729        self.logger.debug("Test")
730        self.assertFalse(self.handler.empty)
731        self.assert_log_equals({"action": "log", "level": "DEBUG", "message": "Test"})
732        self.assertTrue(self.handler.empty)
733
734        component_logger.info("Test 1")
735        self.assertFalse(self.handler.empty)
736        self.assert_log_equals(
737            {
738                "action": "log",
739                "level": "INFO",
740                "message": "Test 1",
741                "component": "test_component",
742            }
743        )
744
745        component_logger.debug("Test 2")
746        self.assertTrue(self.handler.empty)
747
748        component_logger.component_filter = None
749
750        component_logger.debug("Test 3")
751        self.assertFalse(self.handler.empty)
752        self.assert_log_equals(
753            {
754                "action": "log",
755                "level": "DEBUG",
756                "message": "Test 3",
757                "component": "test_component",
758            }
759        )
760
761    def test_filter_default_component(self):
762        component_logger = structuredlog.StructuredLogger(
763            self.logger.name, "test_component"
764        )
765
766        self.logger.debug("Test")
767        self.assertFalse(self.handler.empty)
768        self.assert_log_equals({"action": "log", "level": "DEBUG", "message": "Test"})
769
770        self.logger.component_filter = handlers.LogLevelFilter(lambda x: x, "info")
771
772        self.logger.debug("Test 1")
773        self.assertTrue(self.handler.empty)
774
775        component_logger.debug("Test 2")
776        self.assertFalse(self.handler.empty)
777        self.assert_log_equals(
778            {
779                "action": "log",
780                "level": "DEBUG",
781                "message": "Test 2",
782                "component": "test_component",
783            }
784        )
785
786        self.logger.component_filter = None
787
788        self.logger.debug("Test 3")
789        self.assertFalse(self.handler.empty)
790        self.assert_log_equals({"action": "log", "level": "DEBUG", "message": "Test 3"})
791
792    def test_filter_message_mutuate(self):
793        def filter_mutate(msg):
794            if msg["action"] == "log":
795                msg["message"] = "FILTERED! %s" % msg["message"]
796            return msg
797
798        self.logger.component_filter = filter_mutate
799        self.logger.debug("Test")
800        self.assert_log_equals(
801            {"action": "log", "level": "DEBUG", "message": "FILTERED! Test"}
802        )
803        self.logger.component_filter = None
804
805
806class TestCommandline(unittest.TestCase):
807    def setUp(self):
808        self.logfile = mozfile.NamedTemporaryFile()
809
810    @property
811    def loglines(self):
812        self.logfile.seek(0)
813        return [line.rstrip() for line in self.logfile.readlines()]
814
815    def test_setup_logging(self):
816        parser = argparse.ArgumentParser()
817        commandline.add_logging_group(parser)
818        args = parser.parse_args(["--log-raw=-"])
819        logger = commandline.setup_logging("test_setup_logging", args, {})
820        self.assertEqual(len(logger.handlers), 1)
821
822    def test_setup_logging_optparse(self):
823        parser = optparse.OptionParser()
824        commandline.add_logging_group(parser)
825        args, _ = parser.parse_args(["--log-raw=-"])
826        logger = commandline.setup_logging("test_optparse", args, {})
827        self.assertEqual(len(logger.handlers), 1)
828        self.assertIsInstance(logger.handlers[0], handlers.StreamHandler)
829
830    def test_limit_formatters(self):
831        parser = argparse.ArgumentParser()
832        commandline.add_logging_group(parser, include_formatters=["raw"])
833        other_formatters = [fmt for fmt in commandline.log_formatters if fmt != "raw"]
834        # check that every formatter except raw is not present
835        for fmt in other_formatters:
836            with self.assertRaises(SystemExit):
837                parser.parse_args(["--log-%s=-" % fmt])
838            with self.assertRaises(SystemExit):
839                parser.parse_args(["--log-%s-level=error" % fmt])
840        # raw is still ok
841        args = parser.parse_args(["--log-raw=-"])
842        logger = commandline.setup_logging("test_setup_logging2", args, {})
843        self.assertEqual(len(logger.handlers), 1)
844
845    def test_setup_logging_optparse_unicode(self):
846        parser = optparse.OptionParser()
847        commandline.add_logging_group(parser)
848        args, _ = parser.parse_args([u"--log-raw=-"])
849        logger = commandline.setup_logging("test_optparse_unicode", args, {})
850        self.assertEqual(len(logger.handlers), 1)
851        self.assertEqual(logger.handlers[0].stream, sys.stdout)
852        self.assertIsInstance(logger.handlers[0], handlers.StreamHandler)
853
854    def test_logging_defaultlevel(self):
855        parser = argparse.ArgumentParser()
856        commandline.add_logging_group(parser)
857
858        args = parser.parse_args(["--log-tbpl=%s" % self.logfile.name])
859        logger = commandline.setup_logging("test_fmtopts", args, {})
860        logger.info("INFO message")
861        logger.debug("DEBUG message")
862        logger.error("ERROR message")
863        # The debug level is not logged by default.
864        self.assertEqual([b"INFO message", b"ERROR message"], self.loglines)
865
866    def test_logging_errorlevel(self):
867        parser = argparse.ArgumentParser()
868        commandline.add_logging_group(parser)
869        args = parser.parse_args(
870            ["--log-tbpl=%s" % self.logfile.name, "--log-tbpl-level=error"]
871        )
872        logger = commandline.setup_logging("test_fmtopts", args, {})
873        logger.info("INFO message")
874        logger.debug("DEBUG message")
875        logger.error("ERROR message")
876
877        # Only the error level and above were requested.
878        self.assertEqual([b"ERROR message"], self.loglines)
879
880    def test_logging_debuglevel(self):
881        parser = argparse.ArgumentParser()
882        commandline.add_logging_group(parser)
883        args = parser.parse_args(
884            ["--log-tbpl=%s" % self.logfile.name, "--log-tbpl-level=debug"]
885        )
886        logger = commandline.setup_logging("test_fmtopts", args, {})
887        logger.info("INFO message")
888        logger.debug("DEBUG message")
889        logger.error("ERROR message")
890        # Requesting a lower log level than default works as expected.
891        self.assertEqual(
892            [b"INFO message", b"DEBUG message", b"ERROR message"], self.loglines
893        )
894
895    def test_unused_options(self):
896        parser = argparse.ArgumentParser()
897        commandline.add_logging_group(parser)
898        args = parser.parse_args(["--log-tbpl-level=error"])
899        self.assertRaises(
900            ValueError, commandline.setup_logging, "test_fmtopts", args, {}
901        )
902
903
904class TestBuffer(BaseStructuredTest):
905    def assert_log_equals(self, expected, actual=None):
906        if actual is None:
907            actual = self.pop_last_item()
908
909        all_expected = {
910            "pid": os.getpid(),
911            "thread": "MainThread",
912            "source": "testBuffer",
913        }
914        specials = set(["time"])
915
916        all_expected.update(expected)
917        for key, value in six.iteritems(all_expected):
918            self.assertEqual(actual[key], value)
919
920        self.assertEquals(set(all_expected.keys()) | specials, set(actual.keys()))
921
922    def setUp(self):
923        self.logger = structuredlog.StructuredLogger("testBuffer")
924        self.handler = handlers.BufferHandler(TestHandler(), message_limit=4)
925        self.logger.add_handler(self.handler)
926
927    def tearDown(self):
928        self.logger.remove_handler(self.handler)
929
930    def pop_last_item(self):
931        return self.handler.inner.items.pop()
932
933    def test_buffer_messages(self):
934        self.logger.suite_start([])
935        self.logger.test_start("test1")
936        self.logger.send_message("buffer", "off")
937        self.logger.test_status("test1", "sub1", status="PASS")
938        # Even for buffered actions, the buffer does not interfere if
939        # buffering is turned off.
940        self.assert_log_equals(
941            {
942                "action": "test_status",
943                "test": "test1",
944                "status": "PASS",
945                "subtest": "sub1",
946            }
947        )
948        self.logger.send_message("buffer", "on")
949        self.logger.test_status("test1", "sub2", status="PASS")
950        self.logger.test_status("test1", "sub3", status="PASS")
951        self.logger.test_status("test1", "sub4", status="PASS")
952        self.logger.test_status("test1", "sub5", status="PASS")
953        self.logger.test_status("test1", "sub6", status="PASS")
954        self.logger.test_status("test1", "sub7", status="PASS")
955        self.logger.test_end("test1", status="OK")
956        self.logger.send_message("buffer", "clear")
957        self.assert_log_equals({"action": "test_end", "test": "test1", "status": "OK"})
958        self.logger.suite_end()
959
960    def test_buffer_size(self):
961        self.logger.suite_start([])
962        self.logger.test_start("test1")
963        self.logger.test_status("test1", "sub1", status="PASS")
964        self.logger.test_status("test1", "sub2", status="PASS")
965        self.logger.test_status("test1", "sub3", status="PASS")
966        self.logger.test_status("test1", "sub4", status="PASS")
967        self.logger.test_status("test1", "sub5", status="PASS")
968        self.logger.test_status("test1", "sub6", status="PASS")
969        self.logger.test_status("test1", "sub7", status="PASS")
970
971        # No test status messages made it to the underlying handler.
972        self.assert_log_equals({"action": "test_start", "test": "test1"})
973
974        # The buffer's actual size never grows beyond the specified limit.
975        self.assertEquals(len(self.handler._buffer), 4)
976
977        self.logger.test_status("test1", "sub8", status="FAIL")
978        # The number of messages deleted comes back in a list.
979        self.assertEquals([4], self.logger.send_message("buffer", "flush"))
980
981        # When the buffer is dumped, the failure is the last thing logged
982        self.assert_log_equals(
983            {
984                "action": "test_status",
985                "test": "test1",
986                "subtest": "sub8",
987                "status": "FAIL",
988                "expected": "PASS",
989            }
990        )
991        # Three additional messages should have been retained for context
992        self.assert_log_equals(
993            {
994                "action": "test_status",
995                "test": "test1",
996                "status": "PASS",
997                "subtest": "sub7",
998            }
999        )
1000        self.assert_log_equals(
1001            {
1002                "action": "test_status",
1003                "test": "test1",
1004                "status": "PASS",
1005                "subtest": "sub6",
1006            }
1007        )
1008        self.assert_log_equals(
1009            {
1010                "action": "test_status",
1011                "test": "test1",
1012                "status": "PASS",
1013                "subtest": "sub5",
1014            }
1015        )
1016        self.assert_log_equals({"action": "suite_start", "tests": {"default": []}})
1017
1018
1019class TestReader(unittest.TestCase):
1020    def to_file_like(self, obj):
1021        data_str = "\n".join(json.dumps(item) for item in obj)
1022        return StringIO(data_str)
1023
1024    def test_read(self):
1025        data = [
1026            {"action": "action_0", "data": "data_0"},
1027            {"action": "action_1", "data": "data_1"},
1028        ]
1029
1030        f = self.to_file_like(data)
1031        self.assertEquals(data, list(reader.read(f)))
1032
1033    def test_imap_log(self):
1034        data = [
1035            {"action": "action_0", "data": "data_0"},
1036            {"action": "action_1", "data": "data_1"},
1037        ]
1038
1039        f = self.to_file_like(data)
1040
1041        def f_action_0(item):
1042            return ("action_0", item["data"])
1043
1044        def f_action_1(item):
1045            return ("action_1", item["data"])
1046
1047        res_iter = reader.imap_log(
1048            reader.read(f), {"action_0": f_action_0, "action_1": f_action_1}
1049        )
1050        self.assertEquals(
1051            [("action_0", "data_0"), ("action_1", "data_1")], list(res_iter)
1052        )
1053
1054    def test_each_log(self):
1055        data = [
1056            {"action": "action_0", "data": "data_0"},
1057            {"action": "action_1", "data": "data_1"},
1058        ]
1059
1060        f = self.to_file_like(data)
1061
1062        count = {"action_0": 0, "action_1": 0}
1063
1064        def f_action_0(item):
1065            count[item["action"]] += 1
1066
1067        def f_action_1(item):
1068            count[item["action"]] += 2
1069
1070        reader.each_log(
1071            reader.read(f), {"action_0": f_action_0, "action_1": f_action_1}
1072        )
1073
1074        self.assertEquals({"action_0": 1, "action_1": 2}, count)
1075
1076    def test_handler(self):
1077        data = [
1078            {"action": "action_0", "data": "data_0"},
1079            {"action": "action_1", "data": "data_1"},
1080        ]
1081
1082        f = self.to_file_like(data)
1083
1084        test = self
1085
1086        class ReaderTestHandler(reader.LogHandler):
1087            def __init__(self):
1088                self.action_0_count = 0
1089                self.action_1_count = 0
1090
1091            def action_0(self, item):
1092                test.assertEquals(item["action"], "action_0")
1093                self.action_0_count += 1
1094
1095            def action_1(self, item):
1096                test.assertEquals(item["action"], "action_1")
1097                self.action_1_count += 1
1098
1099        handler = ReaderTestHandler()
1100        reader.handle_log(reader.read(f), handler)
1101
1102        self.assertEquals(handler.action_0_count, 1)
1103        self.assertEquals(handler.action_1_count, 1)
1104
1105
1106if __name__ == "__main__":
1107    mozunit.main()
1108