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