test_formatters.py (26647B)
1 # This Source Code Form is subject to the terms of the Mozilla Public 2 # License, v. 2.0. If a copy of the MPL was not distributed with this 3 # file, You can obtain one at http://mozilla.org/MPL/2.0/. 4 5 import os 6 import signal 7 import unittest 8 import xml.etree.ElementTree as ET 9 from io import StringIO 10 from textwrap import dedent 11 12 import mozunit 13 import pytest 14 from mozlog.formatters import ( 15 GroupingFormatter, 16 HTMLFormatter, 17 MachFormatter, 18 TbplFormatter, 19 XUnitFormatter, 20 ) 21 from mozlog.handlers import StreamHandler 22 from mozlog.structuredlog import StructuredLogger 23 24 FORMATS = { 25 # A list of tuples consisting of (name, options, expected string). 26 "PASS": [ 27 ( 28 "mach", 29 {}, 30 dedent( 31 """ 32 0:00.00 SUITE_START: running 3 tests 33 0:00.00 TEST_START: test_foo 34 0:00.00 TEST_END: OK 35 0:00.00 TEST_START: test_bar 36 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0 37 0:00.00 TEST_START: test_baz 38 0:00.00 TEST_END: FAIL 39 0:00.00 SUITE_END 40 41 suite 1 42 ~~~~~~~ 43 Ran 4 checks (1 subtests, 3 tests) 44 Expected results: 4 45 Unexpected results: 0 46 OK 47 """ 48 ).lstrip("\n"), 49 ), 50 ( 51 "mach", 52 {"verbose": True}, 53 dedent( 54 """ 55 0:00.00 SUITE_START: running 3 tests 56 0:00.00 TEST_START: test_foo 57 0:00.00 TEST_END: OK 58 0:00.00 TEST_START: test_bar 59 0:00.00 PASS a subtest 60 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0 61 0:00.00 TEST_START: test_baz 62 0:00.00 TEST_END: FAIL 63 0:00.00 SUITE_END 64 65 suite 1 66 ~~~~~~~ 67 Ran 4 checks (1 subtests, 3 tests) 68 Expected results: 4 69 Unexpected results: 0 70 OK 71 """ 72 ).lstrip("\n"), 73 ), 74 ], 75 "FAIL": [ 76 ( 77 "mach", 78 {}, 79 dedent( 80 """ 81 0:00.00 SUITE_START: running 3 tests 82 0:00.00 TEST_START: test_foo 83 0:00.00 TEST_END: FAIL, expected PASS - expected 0 got 1 84 0:00.00 TEST_START: test_bar 85 0:00.00 TEST_END: Test OK. Subtests passed 0/2. Unexpected 2 86 FAIL a subtest - expected 0 got 1 87 SimpleTest.is@SimpleTest/SimpleTest.js:312:5 88 @caps/tests/mochitest/test_bug246699.html:53:1 89 TIMEOUT another subtest 90 0:00.00 TEST_START: test_baz 91 0:00.00 TEST_END: PASS, expected FAIL 92 0:00.00 SUITE_END 93 94 suite 1 95 ~~~~~~~ 96 Ran 5 checks (2 subtests, 3 tests) 97 Expected results: 1 98 Unexpected results: 4 99 test: 2 (1 fail, 1 pass) 100 subtest: 2 (1 fail, 1 timeout) 101 102 Error Summary 103 ------------- 104 test_foo 105 FAIL test_foo - expected 0 got 1 106 test_bar 107 FAIL a subtest - expected 0 got 1 108 SimpleTest.is@SimpleTest/SimpleTest.js:312:5 109 @caps/tests/mochitest/test_bug246699.html:53:1 110 TIMEOUT another subtest 111 test_baz 112 UNEXPECTED-PASS test_baz 113 """ 114 ).lstrip("\n"), 115 ), 116 ( 117 "mach", 118 {"verbose": True}, 119 dedent( 120 """ 121 0:00.00 SUITE_START: running 3 tests 122 0:00.00 TEST_START: test_foo 123 0:00.00 TEST_END: FAIL, expected PASS - expected 0 got 1 124 0:00.00 TEST_START: test_bar 125 0:00.00 FAIL a subtest - expected 0 got 1 126 SimpleTest.is@SimpleTest/SimpleTest.js:312:5 127 @caps/tests/mochitest/test_bug246699.html:53:1 128 0:00.00 TIMEOUT another subtest 129 0:00.00 TEST_END: Test OK. Subtests passed 0/2. Unexpected 2 130 0:00.00 TEST_START: test_baz 131 0:00.00 TEST_END: PASS, expected FAIL 132 0:00.00 SUITE_END 133 134 suite 1 135 ~~~~~~~ 136 Ran 5 checks (2 subtests, 3 tests) 137 Expected results: 1 138 Unexpected results: 4 139 test: 2 (1 fail, 1 pass) 140 subtest: 2 (1 fail, 1 timeout) 141 142 Error Summary 143 ------------- 144 test_foo 145 FAIL test_foo - expected 0 got 1 146 test_bar 147 FAIL a subtest - expected 0 got 1 148 SimpleTest.is@SimpleTest/SimpleTest.js:312:5 149 @caps/tests/mochitest/test_bug246699.html:53:1 150 TIMEOUT another subtest 151 test_baz 152 UNEXPECTED-PASS test_baz 153 """ 154 ).lstrip("\n"), 155 ), 156 ], 157 "PRECONDITION_FAILED": [ 158 ( 159 "mach", 160 {}, 161 dedent( 162 """ 163 0:00.00 SUITE_START: running 2 tests 164 0:00.00 TEST_START: test_foo 165 0:00.00 TEST_END: PRECONDITION_FAILED, expected OK 166 0:00.00 TEST_START: test_bar 167 0:00.00 TEST_END: Test OK. Subtests passed 1/2. Unexpected 1 168 PRECONDITION_FAILED another subtest 169 0:00.00 SUITE_END 170 171 suite 1 172 ~~~~~~~ 173 Ran 4 checks (2 subtests, 2 tests) 174 Expected results: 2 175 Unexpected results: 2 176 test: 1 (1 precondition_failed) 177 subtest: 1 (1 precondition_failed) 178 179 Error Summary 180 ------------- 181 test_foo 182 PRECONDITION_FAILED test_foo 183 test_bar 184 PRECONDITION_FAILED another subtest 185 """ 186 ).lstrip("\n"), 187 ), 188 ( 189 "mach", 190 {"verbose": True}, 191 dedent( 192 """ 193 0:00.00 SUITE_START: running 2 tests 194 0:00.00 TEST_START: test_foo 195 0:00.00 TEST_END: PRECONDITION_FAILED, expected OK 196 0:00.00 TEST_START: test_bar 197 0:00.00 PASS a subtest 198 0:00.00 PRECONDITION_FAILED another subtest 199 0:00.00 TEST_END: Test OK. Subtests passed 1/2. Unexpected 1 200 0:00.00 SUITE_END 201 202 suite 1 203 ~~~~~~~ 204 Ran 4 checks (2 subtests, 2 tests) 205 Expected results: 2 206 Unexpected results: 2 207 test: 1 (1 precondition_failed) 208 subtest: 1 (1 precondition_failed) 209 210 Error Summary 211 ------------- 212 test_foo 213 PRECONDITION_FAILED test_foo 214 test_bar 215 PRECONDITION_FAILED another subtest 216 """ 217 ).lstrip("\n"), 218 ), 219 ], 220 "KNOWN-INTERMITTENT": [ 221 ( 222 "mach", 223 {}, 224 dedent( 225 """ 226 0:00.00 SUITE_START: running 3 tests 227 0:00.00 TEST_START: test_foo 228 0:00.00 TEST_END: FAIL 229 KNOWN-INTERMITTENT-FAIL test_foo 230 0:00.00 TEST_START: test_bar 231 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0 232 KNOWN-INTERMITTENT-PASS a subtest 233 0:00.00 TEST_START: test_baz 234 0:00.00 TEST_END: FAIL 235 0:00.00 SUITE_END 236 237 suite 1 238 ~~~~~~~ 239 Ran 4 checks (1 subtests, 3 tests) 240 Expected results: 4 (2 known intermittents) 241 Unexpected results: 0 242 243 Known Intermittent Results 244 -------------------------- 245 test_foo 246 KNOWN-INTERMITTENT-FAIL test_foo 247 test_bar 248 KNOWN-INTERMITTENT-PASS a subtest 249 OK 250 """ 251 ).lstrip("\n"), 252 ), 253 ( 254 "mach", 255 {"verbose": True}, 256 dedent( 257 """ 258 0:00.00 SUITE_START: running 3 tests 259 0:00.00 TEST_START: test_foo 260 0:00.00 TEST_END: FAIL 261 KNOWN-INTERMITTENT-FAIL test_foo 262 0:00.00 TEST_START: test_bar 263 0:00.00 KNOWN-INTERMITTENT-PASS a subtest 264 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0 265 KNOWN-INTERMITTENT-PASS a subtest 266 0:00.00 TEST_START: test_baz 267 0:00.00 TEST_END: FAIL 268 0:00.00 SUITE_END 269 270 suite 1 271 ~~~~~~~ 272 Ran 4 checks (1 subtests, 3 tests) 273 Expected results: 4 (2 known intermittents) 274 Unexpected results: 0 275 276 Known Intermittent Results 277 -------------------------- 278 test_foo 279 KNOWN-INTERMITTENT-FAIL test_foo 280 test_bar 281 KNOWN-INTERMITTENT-PASS a subtest 282 OK 283 """ 284 ).lstrip("\n"), 285 ), 286 ], 287 } 288 289 290 def ids(test): 291 ids = [] 292 for value in FORMATS[test]: 293 args = ", ".join([f"{k}={v}" for k, v in value[1].items()]) 294 if args: 295 args = f"-{args}" 296 ids.append(f"{value[0]}{args}") 297 return ids 298 299 300 @pytest.fixture(autouse=True) 301 def timestamp(monkeypatch): 302 def fake_time(*args, **kwargs): 303 return 0 304 305 monkeypatch.setattr(MachFormatter, "_time", fake_time) 306 307 308 @pytest.mark.parametrize("name,opts,expected", FORMATS["PASS"], ids=ids("PASS")) 309 def test_pass(get_logger, name, opts, expected): 310 logger = get_logger(name, **opts) 311 312 logger.suite_start(["test_foo", "test_bar", "test_baz"]) 313 logger.test_start("test_foo") 314 logger.test_end("test_foo", "OK") 315 logger.test_start("test_bar") 316 logger.test_status("test_bar", "a subtest", "PASS") 317 logger.test_end("test_bar", "OK") 318 logger.test_start("test_baz") 319 logger.test_end("test_baz", "FAIL", "FAIL", "expected 0 got 1") 320 logger.suite_end() 321 322 buf = logger.handlers[0].stream 323 result = buf.getvalue() 324 print("Dumping result for copy/paste:") 325 print(result) 326 assert result == expected 327 328 329 @pytest.mark.parametrize("name,opts,expected", FORMATS["FAIL"], ids=ids("FAIL")) 330 def test_fail(get_logger, name, opts, expected): 331 stack = """ 332 SimpleTest.is@SimpleTest/SimpleTest.js:312:5 333 @caps/tests/mochitest/test_bug246699.html:53:1 334 """.strip("\n") 335 336 logger = get_logger(name, **opts) 337 338 logger.suite_start(["test_foo", "test_bar", "test_baz"]) 339 logger.test_start("test_foo") 340 logger.test_end("test_foo", "FAIL", "PASS", "expected 0 got 1") 341 logger.test_start("test_bar") 342 logger.test_status( 343 "test_bar", "a subtest", "FAIL", "PASS", "expected 0 got 1", stack 344 ) 345 logger.test_status("test_bar", "another subtest", "TIMEOUT") 346 logger.test_end("test_bar", "OK") 347 logger.test_start("test_baz") 348 logger.test_end("test_baz", "PASS", "FAIL") 349 logger.suite_end() 350 351 buf = logger.handlers[0].stream 352 result = buf.getvalue() 353 print("Dumping result for copy/paste:") 354 print(result) 355 assert result == expected 356 357 358 @pytest.mark.parametrize( 359 "name,opts,expected", FORMATS["PRECONDITION_FAILED"], ids=ids("PRECONDITION_FAILED") 360 ) 361 def test_precondition_failed(get_logger, name, opts, expected): 362 logger = get_logger(name, **opts) 363 364 logger.suite_start(["test_foo", "test_bar"]) 365 logger.test_start("test_foo") 366 logger.test_end("test_foo", "PRECONDITION_FAILED") 367 logger.test_start("test_bar") 368 logger.test_status("test_bar", "a subtest", "PASS") 369 logger.test_status("test_bar", "another subtest", "PRECONDITION_FAILED") 370 logger.test_end("test_bar", "OK") 371 logger.suite_end() 372 373 buf = logger.handlers[0].stream 374 result = buf.getvalue() 375 print("Dumping result for copy/paste:") 376 print(result) 377 assert result == expected 378 379 380 @pytest.mark.parametrize( 381 "name,opts,expected", FORMATS["KNOWN-INTERMITTENT"], ids=ids("KNOWN-INTERMITTENT") 382 ) 383 def test_known_intermittent(get_logger, name, opts, expected): 384 logger = get_logger(name, **opts) 385 386 logger.suite_start(["test_foo", "test_bar", "test_baz"]) 387 logger.test_start("test_foo") 388 logger.test_end("test_foo", "FAIL", "PASS", known_intermittent=["FAIL"]) 389 logger.test_start("test_bar") 390 logger.test_status( 391 "test_bar", "a subtest", "PASS", "FAIL", known_intermittent=["PASS"] 392 ) 393 logger.test_end("test_bar", "OK") 394 logger.test_start("test_baz") 395 logger.test_end( 396 "test_baz", "FAIL", "FAIL", "expected 0 got 1", known_intermittent=["PASS"] 397 ) 398 logger.suite_end() 399 400 buf = logger.handlers[0].stream 401 result = buf.getvalue() 402 print("Dumping result for copy/paste:") 403 print(result) 404 assert result == expected 405 406 407 class FormatterTest(unittest.TestCase): 408 def setUp(self): 409 self.position = 0 410 self.logger = StructuredLogger("test_%s" % type(self).__name__) 411 self.output_file = StringIO() 412 self.handler = StreamHandler(self.output_file, self.get_formatter()) 413 self.logger.add_handler(self.handler) 414 415 def set_position(self, pos=None): 416 if pos is None: 417 pos = self.output_file.tell() 418 self.position = pos 419 420 def get_formatter(self): 421 raise NotImplementedError( 422 "FormatterTest subclasses must implement get_formatter" 423 ) 424 425 @property 426 def loglines(self): 427 self.output_file.seek(self.position) 428 return [line.rstrip() for line in self.output_file.readlines()] 429 430 431 class TestHTMLFormatter(FormatterTest): 432 def get_formatter(self): 433 return HTMLFormatter() 434 435 def test_base64_string(self): 436 self.logger.suite_start([]) 437 self.logger.test_start("string_test") 438 self.logger.test_end("string_test", "FAIL", extra={"data": "foobar"}) 439 self.logger.suite_end() 440 self.assertIn("data:text/html;charset=utf-8;base64,Zm9vYmFy", self.loglines[-3]) 441 442 def test_base64_unicode(self): 443 self.logger.suite_start([]) 444 self.logger.test_start("unicode_test") 445 self.logger.test_end("unicode_test", "FAIL", extra={"data": chr(0x02A9)}) 446 self.logger.suite_end() 447 self.assertIn("data:text/html;charset=utf-8;base64,yqk=", self.loglines[-3]) 448 449 def test_base64_other(self): 450 self.logger.suite_start([]) 451 self.logger.test_start("int_test") 452 self.logger.test_end("int_test", "FAIL", extra={"data": {"foo": "bar"}}) 453 self.logger.suite_end() 454 self.assertIn( 455 "data:text/html;charset=utf-8;base64,eyJmb28iOiAiYmFyIn0=", 456 self.loglines[-3], 457 ) 458 459 460 class TestTBPLFormatter(FormatterTest): 461 def get_formatter(self): 462 return TbplFormatter() 463 464 def test_unexpected_message(self): 465 self.logger.suite_start([]) 466 self.logger.test_start("timeout_test") 467 self.logger.test_end("timeout_test", "TIMEOUT", message="timed out") 468 self.assertIn( 469 "TEST-UNEXPECTED-TIMEOUT | timeout_test | timed out", self.loglines 470 ) 471 self.logger.suite_end() 472 473 def test_default_unexpected_end_message(self): 474 self.logger.suite_start([]) 475 self.logger.test_start("timeout_test") 476 self.logger.test_end("timeout_test", "TIMEOUT") 477 self.assertIn( 478 "TEST-UNEXPECTED-TIMEOUT | timeout_test | expected OK", self.loglines 479 ) 480 self.logger.suite_end() 481 482 def test_default_unexpected_status_message(self): 483 self.logger.suite_start([]) 484 self.logger.test_start("timeout_test") 485 self.logger.test_status("timeout_test", "subtest", status="TIMEOUT") 486 self.assertIn( 487 "TEST-UNEXPECTED-TIMEOUT | timeout_test | subtest - expected PASS", 488 self.loglines, 489 ) 490 self.logger.test_end("timeout_test", "OK") 491 self.logger.suite_end() 492 493 def test_known_intermittent_end(self): 494 self.logger.suite_start([]) 495 self.logger.test_start("intermittent_test") 496 self.logger.test_end( 497 "intermittent_test", 498 status="FAIL", 499 expected="PASS", 500 known_intermittent=["FAIL"], 501 ) 502 # test_end log format: 503 # "TEST-KNOWN-INTERMITTENT-<STATUS> | <test> | took <duration>ms" 504 # where duration may be different each time 505 self.assertIn( 506 "TEST-KNOWN-INTERMITTENT-FAIL | intermittent_test | took ", self.loglines[2] 507 ) 508 self.assertIn("ms", self.loglines[2]) 509 self.logger.suite_end() 510 511 def test_known_intermittent_status(self): 512 self.logger.suite_start([]) 513 self.logger.test_start("intermittent_test") 514 self.logger.test_status( 515 "intermittent_test", 516 "subtest", 517 status="FAIL", 518 expected="PASS", 519 known_intermittent=["FAIL"], 520 ) 521 self.assertIn( 522 "TEST-KNOWN-INTERMITTENT-FAIL | intermittent_test | subtest", self.loglines 523 ) 524 self.logger.test_end("intermittent_test", "OK") 525 self.logger.suite_end() 526 527 def test_single_newline(self): 528 self.logger.suite_start([]) 529 self.logger.test_start("test1") 530 self.set_position() 531 self.logger.test_status("test1", "subtest", status="PASS", expected="FAIL") 532 self.logger.test_end("test1", "OK") 533 self.logger.suite_end() 534 535 # This sequence should not produce blanklines 536 for line in self.loglines: 537 self.assertNotEqual("", line) 538 539 def test_process_exit(self): 540 self.logger.process_exit(1234, 0) 541 self.assertIn("TEST-INFO | 1234: exit 0", self.loglines) 542 543 @unittest.skipUnless(os.name == "posix", "posix only") 544 def test_process_exit_with_sig(self): 545 # subprocess return code is negative when process 546 # has been killed by signal on posix. 547 self.logger.process_exit(1234, -signal.SIGTERM) 548 self.assertIn("TEST-INFO | 1234: killed by SIGTERM", self.loglines) 549 550 551 class TestTBPLFormatterWithShutdown(FormatterTest): 552 def get_formatter(self): 553 return TbplFormatter(summary_on_shutdown=True) 554 555 def test_suite_summary_on_shutdown(self): 556 self.logger.suite_start([]) 557 self.logger.test_start("summary_test") 558 self.logger.test_status( 559 "summary_test", "subtest", "FAIL", "PASS", known_intermittent=["FAIL"] 560 ) 561 self.logger.test_end("summary_test", "FAIL", "OK", known_intermittent=["FAIL"]) 562 self.logger.suite_end() 563 self.logger.shutdown() 564 565 self.assertIn("suite 1: 2/2 (2 known intermittent tests)", self.loglines) 566 self.assertIn("Known Intermittent tests:", self.loglines) 567 self.assertIn( 568 "TEST-KNOWN-INTERMITTENT-FAIL | summary_test | subtest", self.loglines 569 ) 570 571 572 class TestMachFormatter(FormatterTest): 573 def get_formatter(self): 574 return MachFormatter(disable_colors=True) 575 576 def test_summary(self): 577 self.logger.suite_start([]) 578 579 # Some tests that pass 580 self.logger.test_start("test1") 581 self.logger.test_end("test1", status="PASS", expected="PASS") 582 583 self.logger.test_start("test2") 584 self.logger.test_end("test2", status="PASS", expected="TIMEOUT") 585 586 self.logger.test_start("test3") 587 self.logger.test_end("test3", status="FAIL", expected="PASS") 588 589 self.set_position() 590 self.logger.suite_end() 591 592 self.assertIn("Ran 3 checks (3 tests)", self.loglines) 593 self.assertIn("Expected results: 1", self.loglines) 594 self.assertIn( 595 """ 596 Unexpected results: 2 597 test: 2 (1 fail, 1 pass) 598 """.strip(), 599 "\n".join(self.loglines), 600 ) 601 self.assertNotIn("test1", self.loglines) 602 self.assertIn("UNEXPECTED-PASS test2", self.loglines) 603 self.assertIn("FAIL test3", self.loglines) 604 605 def test_summary_subtests(self): 606 self.logger.suite_start([]) 607 608 self.logger.test_start("test1") 609 self.logger.test_status("test1", "subtest1", status="PASS") 610 self.logger.test_status("test1", "subtest2", status="FAIL") 611 self.logger.test_end("test1", status="OK", expected="OK") 612 613 self.logger.test_start("test2") 614 self.logger.test_status("test2", "subtest1", status="TIMEOUT", expected="PASS") 615 self.logger.test_end("test2", status="TIMEOUT", expected="OK") 616 617 self.set_position() 618 self.logger.suite_end() 619 620 self.assertIn("Ran 5 checks (3 subtests, 2 tests)", self.loglines) 621 self.assertIn("Expected results: 2", self.loglines) 622 self.assertIn( 623 """ 624 Unexpected results: 3 625 test: 1 (1 timeout) 626 subtest: 2 (1 fail, 1 timeout) 627 """.strip(), 628 "\n".join(self.loglines), 629 ) 630 631 def test_summary_ok(self): 632 self.logger.suite_start([]) 633 634 self.logger.test_start("test1") 635 self.logger.test_status("test1", "subtest1", status="PASS") 636 self.logger.test_status("test1", "subtest2", status="PASS") 637 self.logger.test_end("test1", status="OK", expected="OK") 638 639 self.logger.test_start("test2") 640 self.logger.test_status("test2", "subtest1", status="PASS", expected="PASS") 641 self.logger.test_end("test2", status="OK", expected="OK") 642 643 self.set_position() 644 self.logger.suite_end() 645 646 self.assertIn("OK", self.loglines) 647 self.assertIn("Expected results: 5", self.loglines) 648 self.assertIn("Unexpected results: 0", self.loglines) 649 650 def test_process_start(self): 651 self.logger.process_start(1234) 652 self.assertIn("Started process `1234`", self.loglines[0]) 653 654 def test_process_start_with_command(self): 655 self.logger.process_start(1234, command="test cmd") 656 self.assertIn("Started process `1234` (test cmd)", self.loglines[0]) 657 658 def test_process_exit(self): 659 self.logger.process_exit(1234, 0) 660 self.assertIn("1234: exit 0", self.loglines[0]) 661 662 @unittest.skipUnless(os.name == "posix", "posix only") 663 def test_process_exit_with_sig(self): 664 # subprocess return code is negative when process 665 # has been killed by signal on posix. 666 self.logger.process_exit(1234, -signal.SIGTERM) 667 self.assertIn("1234: killed by SIGTERM", self.loglines[0]) 668 669 def test_expected_fail_log_conversion(self): 670 """Test that ERROR TEST-EXPECTED-FAIL messages are converted to TODO""" 671 self.set_position() 672 673 # Test a log message that starts with TEST-EXPECTED-FAIL 674 self.logger.error("TEST-EXPECTED-FAIL | some test failed") 675 676 # Test a regular ERROR message (should not be converted) 677 self.logger.error("Regular error message") 678 679 # Test a message containing but not starting with TEST-EXPECTED-FAIL (should not be converted) 680 self.logger.error("Some prefix TEST-EXPECTED-FAIL suffix") 681 682 # Check that the TEST-EXPECTED-FAIL message was converted to TODO 683 # and the prefix was removed 684 output = "\n".join(self.loglines) 685 self.assertIn("TODO | some test failed", output) 686 687 # Check that regular ERROR messages are unchanged 688 self.assertIn("ERROR Regular error message", output) 689 690 # Check that messages not starting with TEST-EXPECTED-FAIL are unchanged 691 self.assertIn("ERROR Some prefix TEST-EXPECTED-FAIL suffix", output) 692 693 # Ensure the original ERROR TEST-EXPECTED-FAIL format doesn't appear 694 self.assertNotIn("ERROR TEST-EXPECTED-FAIL", output) 695 696 697 class TestGroupingFormatter(FormatterTest): 698 def get_formatter(self): 699 return GroupingFormatter() 700 701 def test_results_total(self): 702 self.logger.suite_start([]) 703 704 self.logger.test_start("test1") 705 self.logger.test_status("test1", "subtest1", status="PASS") 706 self.logger.test_status("test1", "subtest1", status="PASS") 707 self.logger.test_end("test1", status="OK") 708 709 self.logger.test_start("test2") 710 self.logger.test_status( 711 "test2", 712 "subtest2", 713 status="FAIL", 714 expected="PASS", 715 known_intermittent=["FAIL"], 716 ) 717 self.logger.test_end("test2", status="FAIL", expected="OK") 718 719 self.set_position() 720 self.logger.suite_end() 721 722 self.assertIn("Ran 2 tests finished in 0.0 seconds.", self.loglines) 723 self.assertIn(" \u2022 1 ran as expected. 0 tests skipped.", self.loglines) 724 self.assertIn(" \u2022 1 known intermittent results.", self.loglines) 725 self.assertIn(" \u2022 1 tests failed unexpectedly", self.loglines) 726 self.assertIn(" \u25b6 FAIL [expected OK] test2", self.loglines) 727 self.assertIn( 728 " \u25b6 FAIL [expected PASS, known intermittent [FAIL] test2, subtest2", 729 self.loglines, 730 ) 731 732 733 class TestXUnitFormatter(FormatterTest): 734 def get_formatter(self): 735 return XUnitFormatter() 736 737 def log_as_xml(self): 738 return ET.fromstring("\n".join(self.loglines)) 739 740 def test_stacktrace_is_present(self): 741 self.logger.suite_start([]) 742 self.logger.test_start("test1") 743 self.logger.test_end( 744 "test1", "fail", message="Test message", stack="this\nis\na\nstack" 745 ) 746 self.logger.suite_end() 747 748 root = self.log_as_xml() 749 self.assertIn("this\nis\na\nstack", root.find("testcase/failure").text) 750 751 def test_failure_message(self): 752 self.logger.suite_start([]) 753 self.logger.test_start("test1") 754 self.logger.test_end("test1", "fail", message="Test message") 755 self.logger.suite_end() 756 757 root = self.log_as_xml() 758 self.assertEqual( 759 "Expected OK, got FAIL", root.find("testcase/failure").get("message") 760 ) 761 762 def test_suite_attrs(self): 763 self.logger.suite_start([]) 764 self.logger.test_start("test1") 765 self.logger.test_end("test1", "ok", message="Test message") 766 self.logger.suite_end() 767 768 root = self.log_as_xml() 769 self.assertEqual(root.get("skips"), "0") 770 self.assertEqual(root.get("failures"), "0") 771 self.assertEqual(root.get("errors"), "0") 772 self.assertEqual(root.get("tests"), "1") 773 774 def test_time_is_not_rounded(self): 775 # call formatter directly, it is easier here 776 formatter = self.get_formatter() 777 formatter.suite_start(dict(time=55000)) 778 formatter.test_start(dict(time=55100)) 779 formatter.test_end( 780 dict(time=55558, test="id", message="message", status="PASS") 781 ) 782 xml_string = formatter.suite_end(dict(time=55559)) 783 784 root = ET.fromstring(xml_string) 785 self.assertEqual(root.get("time"), "0.56") 786 self.assertEqual(root.find("testcase").get("time"), "0.46") 787 788 789 if __name__ == "__main__": 790 mozunit.main()