1import io 2import os 3import re 4from typing import cast 5 6import pytest 7from _pytest.capture import CaptureManager 8from _pytest.config import ExitCode 9from _pytest.pytester import Testdir 10from _pytest.terminal import TerminalReporter 11 12 13def test_nothing_logged(testdir): 14 testdir.makepyfile( 15 """ 16 import sys 17 18 def test_foo(): 19 sys.stdout.write('text going to stdout') 20 sys.stderr.write('text going to stderr') 21 assert False 22 """ 23 ) 24 result = testdir.runpytest() 25 assert result.ret == 1 26 result.stdout.fnmatch_lines(["*- Captured stdout call -*", "text going to stdout"]) 27 result.stdout.fnmatch_lines(["*- Captured stderr call -*", "text going to stderr"]) 28 with pytest.raises(pytest.fail.Exception): 29 result.stdout.fnmatch_lines(["*- Captured *log call -*"]) 30 31 32def test_messages_logged(testdir): 33 testdir.makepyfile( 34 """ 35 import sys 36 import logging 37 38 logger = logging.getLogger(__name__) 39 40 def test_foo(): 41 sys.stdout.write('text going to stdout') 42 sys.stderr.write('text going to stderr') 43 logger.info('text going to logger') 44 assert False 45 """ 46 ) 47 result = testdir.runpytest("--log-level=INFO") 48 assert result.ret == 1 49 result.stdout.fnmatch_lines(["*- Captured *log call -*", "*text going to logger*"]) 50 result.stdout.fnmatch_lines(["*- Captured stdout call -*", "text going to stdout"]) 51 result.stdout.fnmatch_lines(["*- Captured stderr call -*", "text going to stderr"]) 52 53 54def test_root_logger_affected(testdir): 55 testdir.makepyfile( 56 """ 57 import logging 58 logger = logging.getLogger() 59 60 def test_foo(): 61 logger.info('info text ' + 'going to logger') 62 logger.warning('warning text ' + 'going to logger') 63 logger.error('error text ' + 'going to logger') 64 65 assert 0 66 """ 67 ) 68 log_file = testdir.tmpdir.join("pytest.log").strpath 69 result = testdir.runpytest("--log-level=ERROR", "--log-file=pytest.log") 70 assert result.ret == 1 71 72 # The capture log calls in the stdout section only contain the 73 # logger.error msg, because of --log-level=ERROR. 74 result.stdout.fnmatch_lines(["*error text going to logger*"]) 75 stdout = result.stdout.str() 76 assert "warning text going to logger" not in stdout 77 assert "info text going to logger" not in stdout 78 79 # The log file should contain the warning and the error log messages and 80 # not the info one, because the default level of the root logger is 81 # WARNING. 82 assert os.path.isfile(log_file) 83 with open(log_file) as rfh: 84 contents = rfh.read() 85 assert "info text going to logger" not in contents 86 assert "warning text going to logger" in contents 87 assert "error text going to logger" in contents 88 89 90def test_log_cli_level_log_level_interaction(testdir): 91 testdir.makepyfile( 92 """ 93 import logging 94 logger = logging.getLogger() 95 96 def test_foo(): 97 logger.debug('debug text ' + 'going to logger') 98 logger.info('info text ' + 'going to logger') 99 logger.warning('warning text ' + 'going to logger') 100 logger.error('error text ' + 'going to logger') 101 assert 0 102 """ 103 ) 104 105 result = testdir.runpytest("--log-cli-level=INFO", "--log-level=ERROR") 106 assert result.ret == 1 107 108 result.stdout.fnmatch_lines( 109 [ 110 "*-- live log call --*", 111 "*INFO*info text going to logger", 112 "*WARNING*warning text going to logger", 113 "*ERROR*error text going to logger", 114 "=* 1 failed in *=", 115 ] 116 ) 117 result.stdout.no_re_match_line("DEBUG") 118 119 120def test_setup_logging(testdir): 121 testdir.makepyfile( 122 """ 123 import logging 124 125 logger = logging.getLogger(__name__) 126 127 def setup_function(function): 128 logger.info('text going to logger from setup') 129 130 def test_foo(): 131 logger.info('text going to logger from call') 132 assert False 133 """ 134 ) 135 result = testdir.runpytest("--log-level=INFO") 136 assert result.ret == 1 137 result.stdout.fnmatch_lines( 138 [ 139 "*- Captured *log setup -*", 140 "*text going to logger from setup*", 141 "*- Captured *log call -*", 142 "*text going to logger from call*", 143 ] 144 ) 145 146 147def test_teardown_logging(testdir): 148 testdir.makepyfile( 149 """ 150 import logging 151 152 logger = logging.getLogger(__name__) 153 154 def test_foo(): 155 logger.info('text going to logger from call') 156 157 def teardown_function(function): 158 logger.info('text going to logger from teardown') 159 assert False 160 """ 161 ) 162 result = testdir.runpytest("--log-level=INFO") 163 assert result.ret == 1 164 result.stdout.fnmatch_lines( 165 [ 166 "*- Captured *log call -*", 167 "*text going to logger from call*", 168 "*- Captured *log teardown -*", 169 "*text going to logger from teardown*", 170 ] 171 ) 172 173 174@pytest.mark.parametrize("enabled", [True, False]) 175def test_log_cli_enabled_disabled(testdir, enabled): 176 msg = "critical message logged by test" 177 testdir.makepyfile( 178 """ 179 import logging 180 def test_log_cli(): 181 logging.critical("{}") 182 """.format( 183 msg 184 ) 185 ) 186 if enabled: 187 testdir.makeini( 188 """ 189 [pytest] 190 log_cli=true 191 """ 192 ) 193 result = testdir.runpytest() 194 if enabled: 195 result.stdout.fnmatch_lines( 196 [ 197 "test_log_cli_enabled_disabled.py::test_log_cli ", 198 "*-- live log call --*", 199 "CRITICAL *test_log_cli_enabled_disabled.py* critical message logged by test", 200 "PASSED*", 201 ] 202 ) 203 else: 204 assert msg not in result.stdout.str() 205 206 207def test_log_cli_default_level(testdir): 208 # Default log file level 209 testdir.makepyfile( 210 """ 211 import pytest 212 import logging 213 def test_log_cli(request): 214 plugin = request.config.pluginmanager.getplugin('logging-plugin') 215 assert plugin.log_cli_handler.level == logging.NOTSET 216 logging.getLogger('catchlog').info("INFO message won't be shown") 217 logging.getLogger('catchlog').warning("WARNING message will be shown") 218 """ 219 ) 220 testdir.makeini( 221 """ 222 [pytest] 223 log_cli=true 224 """ 225 ) 226 227 result = testdir.runpytest() 228 229 # fnmatch_lines does an assertion internally 230 result.stdout.fnmatch_lines( 231 [ 232 "test_log_cli_default_level.py::test_log_cli ", 233 "WARNING*test_log_cli_default_level.py* message will be shown*", 234 ] 235 ) 236 result.stdout.no_fnmatch_line("*INFO message won't be shown*") 237 # make sure that that we get a '0' exit code for the testsuite 238 assert result.ret == 0 239 240 241def test_log_cli_default_level_multiple_tests(testdir, request): 242 """Ensure we reset the first newline added by the live logger between tests""" 243 filename = request.node.name + ".py" 244 testdir.makepyfile( 245 """ 246 import logging 247 248 def test_log_1(): 249 logging.warning("log message from test_log_1") 250 251 def test_log_2(): 252 logging.warning("log message from test_log_2") 253 """ 254 ) 255 testdir.makeini( 256 """ 257 [pytest] 258 log_cli=true 259 """ 260 ) 261 262 result = testdir.runpytest() 263 result.stdout.fnmatch_lines( 264 [ 265 "{}::test_log_1 ".format(filename), 266 "*WARNING*log message from test_log_1*", 267 "PASSED *50%*", 268 "{}::test_log_2 ".format(filename), 269 "*WARNING*log message from test_log_2*", 270 "PASSED *100%*", 271 "=* 2 passed in *=", 272 ] 273 ) 274 275 276def test_log_cli_default_level_sections(testdir, request): 277 """Check that with live logging enable we are printing the correct headers during 278 start/setup/call/teardown/finish.""" 279 filename = request.node.name + ".py" 280 testdir.makeconftest( 281 """ 282 import pytest 283 import logging 284 285 def pytest_runtest_logstart(): 286 logging.warning('>>>>> START >>>>>') 287 288 def pytest_runtest_logfinish(): 289 logging.warning('<<<<< END <<<<<<<') 290 """ 291 ) 292 293 testdir.makepyfile( 294 """ 295 import pytest 296 import logging 297 298 @pytest.fixture 299 def fix(request): 300 logging.warning("log message from setup of {}".format(request.node.name)) 301 yield 302 logging.warning("log message from teardown of {}".format(request.node.name)) 303 304 def test_log_1(fix): 305 logging.warning("log message from test_log_1") 306 307 def test_log_2(fix): 308 logging.warning("log message from test_log_2") 309 """ 310 ) 311 testdir.makeini( 312 """ 313 [pytest] 314 log_cli=true 315 """ 316 ) 317 318 result = testdir.runpytest() 319 result.stdout.fnmatch_lines( 320 [ 321 "{}::test_log_1 ".format(filename), 322 "*-- live log start --*", 323 "*WARNING* >>>>> START >>>>>*", 324 "*-- live log setup --*", 325 "*WARNING*log message from setup of test_log_1*", 326 "*-- live log call --*", 327 "*WARNING*log message from test_log_1*", 328 "PASSED *50%*", 329 "*-- live log teardown --*", 330 "*WARNING*log message from teardown of test_log_1*", 331 "*-- live log finish --*", 332 "*WARNING* <<<<< END <<<<<<<*", 333 "{}::test_log_2 ".format(filename), 334 "*-- live log start --*", 335 "*WARNING* >>>>> START >>>>>*", 336 "*-- live log setup --*", 337 "*WARNING*log message from setup of test_log_2*", 338 "*-- live log call --*", 339 "*WARNING*log message from test_log_2*", 340 "PASSED *100%*", 341 "*-- live log teardown --*", 342 "*WARNING*log message from teardown of test_log_2*", 343 "*-- live log finish --*", 344 "*WARNING* <<<<< END <<<<<<<*", 345 "=* 2 passed in *=", 346 ] 347 ) 348 349 350def test_live_logs_unknown_sections(testdir, request): 351 """Check that with live logging enable we are printing the correct headers during 352 start/setup/call/teardown/finish.""" 353 filename = request.node.name + ".py" 354 testdir.makeconftest( 355 """ 356 import pytest 357 import logging 358 359 def pytest_runtest_protocol(item, nextitem): 360 logging.warning('Unknown Section!') 361 362 def pytest_runtest_logstart(): 363 logging.warning('>>>>> START >>>>>') 364 365 def pytest_runtest_logfinish(): 366 logging.warning('<<<<< END <<<<<<<') 367 """ 368 ) 369 370 testdir.makepyfile( 371 """ 372 import pytest 373 import logging 374 375 @pytest.fixture 376 def fix(request): 377 logging.warning("log message from setup of {}".format(request.node.name)) 378 yield 379 logging.warning("log message from teardown of {}".format(request.node.name)) 380 381 def test_log_1(fix): 382 logging.warning("log message from test_log_1") 383 384 """ 385 ) 386 testdir.makeini( 387 """ 388 [pytest] 389 log_cli=true 390 """ 391 ) 392 393 result = testdir.runpytest() 394 result.stdout.fnmatch_lines( 395 [ 396 "*WARNING*Unknown Section*", 397 "{}::test_log_1 ".format(filename), 398 "*WARNING* >>>>> START >>>>>*", 399 "*-- live log setup --*", 400 "*WARNING*log message from setup of test_log_1*", 401 "*-- live log call --*", 402 "*WARNING*log message from test_log_1*", 403 "PASSED *100%*", 404 "*-- live log teardown --*", 405 "*WARNING*log message from teardown of test_log_1*", 406 "*WARNING* <<<<< END <<<<<<<*", 407 "=* 1 passed in *=", 408 ] 409 ) 410 411 412def test_sections_single_new_line_after_test_outcome(testdir, request): 413 """Check that only a single new line is written between log messages during 414 teardown/finish.""" 415 filename = request.node.name + ".py" 416 testdir.makeconftest( 417 """ 418 import pytest 419 import logging 420 421 def pytest_runtest_logstart(): 422 logging.warning('>>>>> START >>>>>') 423 424 def pytest_runtest_logfinish(): 425 logging.warning('<<<<< END <<<<<<<') 426 logging.warning('<<<<< END <<<<<<<') 427 """ 428 ) 429 430 testdir.makepyfile( 431 """ 432 import pytest 433 import logging 434 435 @pytest.fixture 436 def fix(request): 437 logging.warning("log message from setup of {}".format(request.node.name)) 438 yield 439 logging.warning("log message from teardown of {}".format(request.node.name)) 440 logging.warning("log message from teardown of {}".format(request.node.name)) 441 442 def test_log_1(fix): 443 logging.warning("log message from test_log_1") 444 """ 445 ) 446 testdir.makeini( 447 """ 448 [pytest] 449 log_cli=true 450 """ 451 ) 452 453 result = testdir.runpytest() 454 result.stdout.fnmatch_lines( 455 [ 456 "{}::test_log_1 ".format(filename), 457 "*-- live log start --*", 458 "*WARNING* >>>>> START >>>>>*", 459 "*-- live log setup --*", 460 "*WARNING*log message from setup of test_log_1*", 461 "*-- live log call --*", 462 "*WARNING*log message from test_log_1*", 463 "PASSED *100%*", 464 "*-- live log teardown --*", 465 "*WARNING*log message from teardown of test_log_1*", 466 "*-- live log finish --*", 467 "*WARNING* <<<<< END <<<<<<<*", 468 "*WARNING* <<<<< END <<<<<<<*", 469 "=* 1 passed in *=", 470 ] 471 ) 472 assert ( 473 re.search( 474 r"(.+)live log teardown(.+)\nWARNING(.+)\nWARNING(.+)", 475 result.stdout.str(), 476 re.MULTILINE, 477 ) 478 is not None 479 ) 480 assert ( 481 re.search( 482 r"(.+)live log finish(.+)\nWARNING(.+)\nWARNING(.+)", 483 result.stdout.str(), 484 re.MULTILINE, 485 ) 486 is not None 487 ) 488 489 490def test_log_cli_level(testdir): 491 # Default log file level 492 testdir.makepyfile( 493 """ 494 import pytest 495 import logging 496 def test_log_cli(request): 497 plugin = request.config.pluginmanager.getplugin('logging-plugin') 498 assert plugin.log_cli_handler.level == logging.INFO 499 logging.getLogger('catchlog').debug("This log message won't be shown") 500 logging.getLogger('catchlog').info("This log message will be shown") 501 print('PASSED') 502 """ 503 ) 504 testdir.makeini( 505 """ 506 [pytest] 507 log_cli=true 508 """ 509 ) 510 511 result = testdir.runpytest("-s", "--log-cli-level=INFO") 512 513 # fnmatch_lines does an assertion internally 514 result.stdout.fnmatch_lines( 515 [ 516 "*test_log_cli_level.py*This log message will be shown", 517 "PASSED", # 'PASSED' on its own line because the log message prints a new line 518 ] 519 ) 520 result.stdout.no_fnmatch_line("*This log message won't be shown*") 521 522 # make sure that that we get a '0' exit code for the testsuite 523 assert result.ret == 0 524 525 result = testdir.runpytest("-s", "--log-level=INFO") 526 527 # fnmatch_lines does an assertion internally 528 result.stdout.fnmatch_lines( 529 [ 530 "*test_log_cli_level.py* This log message will be shown", 531 "PASSED", # 'PASSED' on its own line because the log message prints a new line 532 ] 533 ) 534 result.stdout.no_fnmatch_line("*This log message won't be shown*") 535 536 # make sure that that we get a '0' exit code for the testsuite 537 assert result.ret == 0 538 539 540def test_log_cli_ini_level(testdir): 541 testdir.makeini( 542 """ 543 [pytest] 544 log_cli=true 545 log_cli_level = INFO 546 """ 547 ) 548 testdir.makepyfile( 549 """ 550 import pytest 551 import logging 552 def test_log_cli(request): 553 plugin = request.config.pluginmanager.getplugin('logging-plugin') 554 assert plugin.log_cli_handler.level == logging.INFO 555 logging.getLogger('catchlog').debug("This log message won't be shown") 556 logging.getLogger('catchlog').info("This log message will be shown") 557 print('PASSED') 558 """ 559 ) 560 561 result = testdir.runpytest("-s") 562 563 # fnmatch_lines does an assertion internally 564 result.stdout.fnmatch_lines( 565 [ 566 "*test_log_cli_ini_level.py* This log message will be shown", 567 "PASSED", # 'PASSED' on its own line because the log message prints a new line 568 ] 569 ) 570 result.stdout.no_fnmatch_line("*This log message won't be shown*") 571 572 # make sure that that we get a '0' exit code for the testsuite 573 assert result.ret == 0 574 575 576@pytest.mark.parametrize( 577 "cli_args", 578 ["", "--log-level=WARNING", "--log-file-level=WARNING", "--log-cli-level=WARNING"], 579) 580def test_log_cli_auto_enable(testdir, cli_args): 581 """Check that live logs are enabled if --log-level or --log-cli-level is passed on the CLI. 582 It should not be auto enabled if the same configs are set on the INI file. 583 """ 584 testdir.makepyfile( 585 """ 586 import logging 587 588 def test_log_1(): 589 logging.info("log message from test_log_1 not to be shown") 590 logging.warning("log message from test_log_1") 591 592 """ 593 ) 594 testdir.makeini( 595 """ 596 [pytest] 597 log_level=INFO 598 log_cli_level=INFO 599 """ 600 ) 601 602 result = testdir.runpytest(cli_args) 603 stdout = result.stdout.str() 604 if cli_args == "--log-cli-level=WARNING": 605 result.stdout.fnmatch_lines( 606 [ 607 "*::test_log_1 ", 608 "*-- live log call --*", 609 "*WARNING*log message from test_log_1*", 610 "PASSED *100%*", 611 "=* 1 passed in *=", 612 ] 613 ) 614 assert "INFO" not in stdout 615 else: 616 result.stdout.fnmatch_lines( 617 ["*test_log_cli_auto_enable*100%*", "=* 1 passed in *="] 618 ) 619 assert "INFO" not in stdout 620 assert "WARNING" not in stdout 621 622 623def test_log_file_cli(testdir): 624 # Default log file level 625 testdir.makepyfile( 626 """ 627 import pytest 628 import logging 629 def test_log_file(request): 630 plugin = request.config.pluginmanager.getplugin('logging-plugin') 631 assert plugin.log_file_handler.level == logging.WARNING 632 logging.getLogger('catchlog').info("This log message won't be shown") 633 logging.getLogger('catchlog').warning("This log message will be shown") 634 print('PASSED') 635 """ 636 ) 637 638 log_file = testdir.tmpdir.join("pytest.log").strpath 639 640 result = testdir.runpytest( 641 "-s", "--log-file={}".format(log_file), "--log-file-level=WARNING" 642 ) 643 644 # fnmatch_lines does an assertion internally 645 result.stdout.fnmatch_lines(["test_log_file_cli.py PASSED"]) 646 647 # make sure that that we get a '0' exit code for the testsuite 648 assert result.ret == 0 649 assert os.path.isfile(log_file) 650 with open(log_file) as rfh: 651 contents = rfh.read() 652 assert "This log message will be shown" in contents 653 assert "This log message won't be shown" not in contents 654 655 656def test_log_file_cli_level(testdir): 657 # Default log file level 658 testdir.makepyfile( 659 """ 660 import pytest 661 import logging 662 def test_log_file(request): 663 plugin = request.config.pluginmanager.getplugin('logging-plugin') 664 assert plugin.log_file_handler.level == logging.INFO 665 logging.getLogger('catchlog').debug("This log message won't be shown") 666 logging.getLogger('catchlog').info("This log message will be shown") 667 print('PASSED') 668 """ 669 ) 670 671 log_file = testdir.tmpdir.join("pytest.log").strpath 672 673 result = testdir.runpytest( 674 "-s", "--log-file={}".format(log_file), "--log-file-level=INFO" 675 ) 676 677 # fnmatch_lines does an assertion internally 678 result.stdout.fnmatch_lines(["test_log_file_cli_level.py PASSED"]) 679 680 # make sure that that we get a '0' exit code for the testsuite 681 assert result.ret == 0 682 assert os.path.isfile(log_file) 683 with open(log_file) as rfh: 684 contents = rfh.read() 685 assert "This log message will be shown" in contents 686 assert "This log message won't be shown" not in contents 687 688 689def test_log_level_not_changed_by_default(testdir): 690 testdir.makepyfile( 691 """ 692 import logging 693 def test_log_file(): 694 assert logging.getLogger().level == logging.WARNING 695 """ 696 ) 697 result = testdir.runpytest("-s") 698 result.stdout.fnmatch_lines(["* 1 passed in *"]) 699 700 701def test_log_file_ini(testdir): 702 log_file = testdir.tmpdir.join("pytest.log").strpath 703 704 testdir.makeini( 705 """ 706 [pytest] 707 log_file={} 708 log_file_level=WARNING 709 """.format( 710 log_file 711 ) 712 ) 713 testdir.makepyfile( 714 """ 715 import pytest 716 import logging 717 def test_log_file(request): 718 plugin = request.config.pluginmanager.getplugin('logging-plugin') 719 assert plugin.log_file_handler.level == logging.WARNING 720 logging.getLogger('catchlog').info("This log message won't be shown") 721 logging.getLogger('catchlog').warning("This log message will be shown") 722 print('PASSED') 723 """ 724 ) 725 726 result = testdir.runpytest("-s") 727 728 # fnmatch_lines does an assertion internally 729 result.stdout.fnmatch_lines(["test_log_file_ini.py PASSED"]) 730 731 # make sure that that we get a '0' exit code for the testsuite 732 assert result.ret == 0 733 assert os.path.isfile(log_file) 734 with open(log_file) as rfh: 735 contents = rfh.read() 736 assert "This log message will be shown" in contents 737 assert "This log message won't be shown" not in contents 738 739 740def test_log_file_ini_level(testdir): 741 log_file = testdir.tmpdir.join("pytest.log").strpath 742 743 testdir.makeini( 744 """ 745 [pytest] 746 log_file={} 747 log_file_level = INFO 748 """.format( 749 log_file 750 ) 751 ) 752 testdir.makepyfile( 753 """ 754 import pytest 755 import logging 756 def test_log_file(request): 757 plugin = request.config.pluginmanager.getplugin('logging-plugin') 758 assert plugin.log_file_handler.level == logging.INFO 759 logging.getLogger('catchlog').debug("This log message won't be shown") 760 logging.getLogger('catchlog').info("This log message will be shown") 761 print('PASSED') 762 """ 763 ) 764 765 result = testdir.runpytest("-s") 766 767 # fnmatch_lines does an assertion internally 768 result.stdout.fnmatch_lines(["test_log_file_ini_level.py PASSED"]) 769 770 # make sure that that we get a '0' exit code for the testsuite 771 assert result.ret == 0 772 assert os.path.isfile(log_file) 773 with open(log_file) as rfh: 774 contents = rfh.read() 775 assert "This log message will be shown" in contents 776 assert "This log message won't be shown" not in contents 777 778 779def test_log_file_unicode(testdir): 780 log_file = testdir.tmpdir.join("pytest.log").strpath 781 782 testdir.makeini( 783 """ 784 [pytest] 785 log_file={} 786 log_file_level = INFO 787 """.format( 788 log_file 789 ) 790 ) 791 testdir.makepyfile( 792 """\ 793 import logging 794 795 def test_log_file(): 796 logging.getLogger('catchlog').info("Normal message") 797 logging.getLogger('catchlog').info("├") 798 logging.getLogger('catchlog').info("Another normal message") 799 """ 800 ) 801 802 result = testdir.runpytest() 803 804 # make sure that that we get a '0' exit code for the testsuite 805 assert result.ret == 0 806 assert os.path.isfile(log_file) 807 with open(log_file, encoding="utf-8") as rfh: 808 contents = rfh.read() 809 assert "Normal message" in contents 810 assert "├" in contents 811 assert "Another normal message" in contents 812 813 814@pytest.mark.parametrize("has_capture_manager", [True, False]) 815def test_live_logging_suspends_capture(has_capture_manager: bool, request) -> None: 816 """Test that capture manager is suspended when we emitting messages for live logging. 817 818 This tests the implementation calls instead of behavior because it is difficult/impossible to do it using 819 ``testdir`` facilities because they do their own capturing. 820 821 We parametrize the test to also make sure _LiveLoggingStreamHandler works correctly if no capture manager plugin 822 is installed. 823 """ 824 import logging 825 import contextlib 826 from functools import partial 827 from _pytest.logging import _LiveLoggingStreamHandler 828 829 class MockCaptureManager: 830 calls = [] 831 832 @contextlib.contextmanager 833 def global_and_fixture_disabled(self): 834 self.calls.append("enter disabled") 835 yield 836 self.calls.append("exit disabled") 837 838 class DummyTerminal(io.StringIO): 839 def section(self, *args, **kwargs): 840 pass 841 842 out_file = cast(TerminalReporter, DummyTerminal()) 843 capture_manager = ( 844 cast(CaptureManager, MockCaptureManager()) if has_capture_manager else None 845 ) 846 handler = _LiveLoggingStreamHandler(out_file, capture_manager) 847 handler.set_when("call") 848 849 logger = logging.getLogger(__name__ + ".test_live_logging_suspends_capture") 850 logger.addHandler(handler) 851 request.addfinalizer(partial(logger.removeHandler, handler)) 852 853 logger.critical("some message") 854 if has_capture_manager: 855 assert MockCaptureManager.calls == ["enter disabled", "exit disabled"] 856 else: 857 assert MockCaptureManager.calls == [] 858 assert cast(io.StringIO, out_file).getvalue() == "\nsome message\n" 859 860 861def test_collection_live_logging(testdir): 862 testdir.makepyfile( 863 """ 864 import logging 865 866 logging.getLogger().info("Normal message") 867 """ 868 ) 869 870 result = testdir.runpytest("--log-cli-level=INFO") 871 result.stdout.fnmatch_lines( 872 ["*--- live log collection ---*", "*Normal message*", "collected 0 items"] 873 ) 874 875 876@pytest.mark.parametrize("verbose", ["", "-q", "-qq"]) 877def test_collection_collect_only_live_logging(testdir, verbose): 878 testdir.makepyfile( 879 """ 880 def test_simple(): 881 pass 882 """ 883 ) 884 885 result = testdir.runpytest("--collect-only", "--log-cli-level=INFO", verbose) 886 887 expected_lines = [] 888 889 if not verbose: 890 expected_lines.extend( 891 [ 892 "*collected 1 item*", 893 "*<Module test_collection_collect_only_live_logging.py>*", 894 "*no tests ran*", 895 ] 896 ) 897 elif verbose == "-q": 898 result.stdout.no_fnmatch_line("*collected 1 item**") 899 expected_lines.extend( 900 [ 901 "*test_collection_collect_only_live_logging.py::test_simple*", 902 "no tests ran in [0-9].[0-9][0-9]s", 903 ] 904 ) 905 elif verbose == "-qq": 906 result.stdout.no_fnmatch_line("*collected 1 item**") 907 expected_lines.extend(["*test_collection_collect_only_live_logging.py: 1*"]) 908 909 result.stdout.fnmatch_lines(expected_lines) 910 911 912def test_collection_logging_to_file(testdir): 913 log_file = testdir.tmpdir.join("pytest.log").strpath 914 915 testdir.makeini( 916 """ 917 [pytest] 918 log_file={} 919 log_file_level = INFO 920 """.format( 921 log_file 922 ) 923 ) 924 925 testdir.makepyfile( 926 """ 927 import logging 928 929 logging.getLogger().info("Normal message") 930 931 def test_simple(): 932 logging.getLogger().debug("debug message in test_simple") 933 logging.getLogger().info("info message in test_simple") 934 """ 935 ) 936 937 result = testdir.runpytest() 938 939 result.stdout.no_fnmatch_line("*--- live log collection ---*") 940 941 assert result.ret == 0 942 assert os.path.isfile(log_file) 943 with open(log_file, encoding="utf-8") as rfh: 944 contents = rfh.read() 945 assert "Normal message" in contents 946 assert "debug message in test_simple" not in contents 947 assert "info message in test_simple" in contents 948 949 950def test_log_in_hooks(testdir): 951 log_file = testdir.tmpdir.join("pytest.log").strpath 952 953 testdir.makeini( 954 """ 955 [pytest] 956 log_file={} 957 log_file_level = INFO 958 log_cli=true 959 """.format( 960 log_file 961 ) 962 ) 963 testdir.makeconftest( 964 """ 965 import logging 966 967 def pytest_runtestloop(session): 968 logging.info('runtestloop') 969 970 def pytest_sessionstart(session): 971 logging.info('sessionstart') 972 973 def pytest_sessionfinish(session, exitstatus): 974 logging.info('sessionfinish') 975 """ 976 ) 977 result = testdir.runpytest() 978 result.stdout.fnmatch_lines(["*sessionstart*", "*runtestloop*", "*sessionfinish*"]) 979 with open(log_file) as rfh: 980 contents = rfh.read() 981 assert "sessionstart" in contents 982 assert "runtestloop" in contents 983 assert "sessionfinish" in contents 984 985 986def test_log_in_runtest_logreport(testdir): 987 log_file = testdir.tmpdir.join("pytest.log").strpath 988 989 testdir.makeini( 990 """ 991 [pytest] 992 log_file={} 993 log_file_level = INFO 994 log_cli=true 995 """.format( 996 log_file 997 ) 998 ) 999 testdir.makeconftest( 1000 """ 1001 import logging 1002 logger = logging.getLogger(__name__) 1003 1004 def pytest_runtest_logreport(report): 1005 logger.info("logreport") 1006 """ 1007 ) 1008 testdir.makepyfile( 1009 """ 1010 def test_first(): 1011 assert True 1012 """ 1013 ) 1014 testdir.runpytest() 1015 with open(log_file) as rfh: 1016 contents = rfh.read() 1017 assert contents.count("logreport") == 3 1018 1019 1020def test_log_set_path(testdir): 1021 report_dir_base = testdir.tmpdir.strpath 1022 1023 testdir.makeini( 1024 """ 1025 [pytest] 1026 log_file_level = DEBUG 1027 log_cli=true 1028 """ 1029 ) 1030 testdir.makeconftest( 1031 """ 1032 import os 1033 import pytest 1034 @pytest.hookimpl(hookwrapper=True, tryfirst=True) 1035 def pytest_runtest_setup(item): 1036 config = item.config 1037 logging_plugin = config.pluginmanager.get_plugin("logging-plugin") 1038 report_file = os.path.join({}, item._request.node.name) 1039 logging_plugin.set_log_path(report_file) 1040 yield 1041 """.format( 1042 repr(report_dir_base) 1043 ) 1044 ) 1045 testdir.makepyfile( 1046 """ 1047 import logging 1048 logger = logging.getLogger("testcase-logger") 1049 def test_first(): 1050 logger.info("message from test 1") 1051 assert True 1052 1053 def test_second(): 1054 logger.debug("message from test 2") 1055 assert True 1056 """ 1057 ) 1058 testdir.runpytest() 1059 with open(os.path.join(report_dir_base, "test_first")) as rfh: 1060 content = rfh.read() 1061 assert "message from test 1" in content 1062 1063 with open(os.path.join(report_dir_base, "test_second")) as rfh: 1064 content = rfh.read() 1065 assert "message from test 2" in content 1066 1067 1068def test_colored_captured_log(testdir): 1069 """Test that the level names of captured log messages of a failing test 1070 are colored.""" 1071 testdir.makepyfile( 1072 """ 1073 import logging 1074 1075 logger = logging.getLogger(__name__) 1076 1077 def test_foo(): 1078 logger.info('text going to logger from call') 1079 assert False 1080 """ 1081 ) 1082 result = testdir.runpytest("--log-level=INFO", "--color=yes") 1083 assert result.ret == 1 1084 result.stdout.fnmatch_lines( 1085 [ 1086 "*-- Captured log call --*", 1087 "\x1b[32mINFO \x1b[0m*text going to logger from call", 1088 ] 1089 ) 1090 1091 1092def test_colored_ansi_esc_caplogtext(testdir): 1093 """Make sure that caplog.text does not contain ANSI escape sequences.""" 1094 testdir.makepyfile( 1095 """ 1096 import logging 1097 1098 logger = logging.getLogger(__name__) 1099 1100 def test_foo(caplog): 1101 logger.info('text going to logger from call') 1102 assert '\x1b' not in caplog.text 1103 """ 1104 ) 1105 result = testdir.runpytest("--log-level=INFO", "--color=yes") 1106 assert result.ret == 0 1107 1108 1109def test_logging_emit_error(testdir: Testdir) -> None: 1110 """An exception raised during emit() should fail the test. 1111 1112 The default behavior of logging is to print "Logging error" 1113 to stderr with the call stack and some extra details. 1114 1115 pytest overrides this behavior to propagate the exception. 1116 """ 1117 testdir.makepyfile( 1118 """ 1119 import logging 1120 1121 def test_bad_log(): 1122 logging.warning('oops', 'first', 2) 1123 """ 1124 ) 1125 result = testdir.runpytest() 1126 result.assert_outcomes(failed=1) 1127 result.stdout.fnmatch_lines( 1128 [ 1129 "====* FAILURES *====", 1130 "*not all arguments converted during string formatting*", 1131 ] 1132 ) 1133 1134 1135def test_logging_emit_error_supressed(testdir: Testdir) -> None: 1136 """If logging is configured to silently ignore errors, pytest 1137 doesn't propagate errors either.""" 1138 testdir.makepyfile( 1139 """ 1140 import logging 1141 1142 def test_bad_log(monkeypatch): 1143 monkeypatch.setattr(logging, 'raiseExceptions', False) 1144 logging.warning('oops', 'first', 2) 1145 """ 1146 ) 1147 result = testdir.runpytest() 1148 result.assert_outcomes(passed=1) 1149 1150 1151def test_log_file_cli_subdirectories_are_successfully_created(testdir): 1152 path = testdir.makepyfile(""" def test_logger(): pass """) 1153 expected = os.path.join(os.path.dirname(str(path)), "foo", "bar") 1154 result = testdir.runpytest("--log-file=foo/bar/logf.log") 1155 assert "logf.log" in os.listdir(expected) 1156 assert result.ret == ExitCode.OK 1157