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