Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

logger is not able to write to log file after tests complete #6000

Closed
tchaikov opened this issue Apr 10, 2023 · 2 comments · Fixed by #6001
Closed

logger is not able to write to log file after tests complete #6000

tchaikov opened this issue Apr 10, 2023 · 2 comments · Fixed by #6001
Assignees
@tchaikov

Comments

@tchaikov
Copy link
Contributor

tchaikov commented Apr 10, 2023 •
edited
Loading

stop_events_device is registered onto atexit in start_events_device(). see

scylla-cluster-tests/sdcm/sct_events/setup.py

Line 74 in 590b9ef

atexit.register(stop_events_device, _registry=_registry)
. this function writes to the logging object retrieved using logging.getLogger(__name__), see

scylla-cluster-tests/sdcm/sct_events/setup.py

Line 97 in 590b9ef

LOGGER.info("Statistics of sent/received events (by device): %s", json.dumps(events_stat, indent=4))
. while in

scylla-cluster-tests/sdcm/utils/log.py

Lines 11 to 15 in 590b9ef

def setup_stdout_logger(log_level=logging.INFO):
root_logger = logging.getLogger()
root_logger.setLevel(log_level)
root_logger.addHandler(logging.StreamHandler(sys.stdout))
return root_logger
. we point the root logger to stdout.

unforunately, pytest's capsys just closes the stdout when done with tests. there are issues tracking this problem, see pytest-dev/pytest#5577 .

the symptom of this issue is following error message:

22:37:15  unit_tests/provisioner/test_scylla_machine_image_payload.py::test_can_generate_valid_scylla_machine_image_payload_with_minimum_params PASSED [ 99%]
22:37:15  unit_tests/provisioner/test_user_data_builder.py::test_user_data_builder_generates_valid_yaml_from_single_user_data_object PASSED [ 99%]
22:37:15  unit_tests/provisioner/test_user_data_builder.py::test_user_data_can_merge_user_data_objects_yaml PASSED [ 99%]
22:37:15  unit_tests/provisioner/test_user_data_builder.py::test_only_done_runcmd_in_yaml_when_no_user_data_objects PASSED [ 99%]
22:37:15  unit_tests/provisioner/test_user_data_builder.py::test_only_done_runcmd_in_yaml_when_no_applicable_user_data_objects PASSED [ 99%]
22:37:15  unit_tests/rest/test_compaction_manager_client.py::test_compaction_manager_stop_compaction PASSED [100%]
22:37:15  
22:37:15  ============================= slowest 20 durations =============================
22:37:15  11.33s call     test_sct_events_grafana.py::TestGrafana::test_grafana
22:37:15  10.66s call     test_config.py::ConfigurationTests::test_10_mananger_regression
22:37:15  10.61s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_4__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_functional_yaml
22:37:15  10.54s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_7__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_manager_backup_1TB_gce_yaml
22:37:15  10.44s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_3__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_cdc_replication_longevity_yaml
22:37:15  10.24s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_0__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_PR_provision_test_yaml
22:37:15  10.10s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_8__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_rolling_upgrade_yaml
22:37:15  10.08s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_2__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_artifact_amazon2_yaml
22:37:15  10.01s call     test_seed_selector.py::TestSeedSelector::test_reflector_node_not_exists
22:37:15  9.93s call     test_config.py::ConfigurationTests::test_12_scylla_version_ami_case1
22:37:15  9.88s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_5__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_jepsen_yaml
22:37:15  9.84s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_1__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_perf_regression_100threads_30M_keys_yaml
22:37:15  9.64s call     test_scylla_yaml_builders.py::IntegrationTests::test_integration_node_6__tmp_jenkins_workspace_can_scylla_cluster_tests_PR_5993_unit_tests_test_data_test_scylla_yaml_builders_longevity_10gb_3h_yaml
22:37:15  9.56s call     test_config.py::ConfigurationTests::test_16_oracle_scylla_version_us_east_1
22:37:15  8.77s call     test_nemesis_sisyphus.py::test_list_all_available_nemesis
22:37:15  8.74s call     test_profiler.py::TestProfileFactory::test_profile_disabled
22:37:15  8.48s call     test_nemesis.py::test_disabled_monkey
22:37:15  8.01s call     test_sct_events_events_handler.py::TestEventsHandler::test_events_handler
22:37:15  7.61s call     test_profiler.py::TestProfileFactory::test_profile_enabled
22:37:15  7.35s call     test_tester.py::CriticalErrorNotCaughtTest::test
22:37:15  ========== 857 passed, 21 skipped, 49 deselected in 579.91s (0:09:39) ==========
22:37:20  --- Logging error ---
22:37:20  Traceback (most recent call last):
22:37:20    File "/usr/local/lib/python3.10/logging/__init__.py", line 1101, in emit
22:37:20      stream.write(msg + self.terminator)
22:37:20  ValueError: I/O operation on closed file.
22:37:20  Call stack:
22:37:20    File "/tmp/jenkins/workspace/can_scylla-cluster-tests_PR-5993/sdcm/sct_events/setup.py", line 97, in stop_events_device
22:37:20      LOGGER.info("Statistics of sent/received events (by device): %s", json.dumps(events_stat, indent=4))
22:37:20  Message: 'Statistics of sent/received events (by device): %s'
22:37:20  Arguments: ('{\n    "EventsProcessesRegistry[lod_dir=/tmp/tmpf5olv0hw,id=0x7f11e5fcbdf0,default=False][EVENTS_FILE_LOGGER]": 7,\n    "EventsProcessesRegistry[lod_dir=/tmp/tmpf5olv0hw,id=0x7f11e5fcbdf0,default=False][EVENTS_GRAFANA_ANNOTATOR]": 7,\n    "EventsProcessesRegistry[lod_dir=/tmp/tmpf5olv0hw,id=0x7f11e5fcbdf0,default=False][EVENTS_GRAFANA_AGGREGATOR]": 1,\n    "EventsProcessesRegistry[lod_dir=/tmp/tmpf5olv0hw,id=0x7f11e5fcbdf0,default=False][EVENTS_GRAFANA_POSTMAN]": 0,\n    "EventsProcessesRegistry[lod_dir=/tmp/tmpf5olv0hw,id=0x7f11e5fcbdf0,default=False][EVENTS_HANDLER]": 7,\n    "EventsProcessesRegistry[lod_dir=/tmp/tmpf5olv0hw,id=0x7f11e5fcbdf0,default=False][EVENTS_ANALYZER]": 7,\n    "E

see https://jenkins.scylladb.com/job/sct-github-PRs-scan/job/scylla-cluster-tests/job/PR-5993/workflow-stage/
tchaikov added a commit to tchaikov/scylla-cluster-tests that referenced this issue Apr 10, 2023
@tchaikov
fix(unit_test): prevent logging from raising exceptions after tests
949cbdb 
pytest's capsys just closes the stdout when done with tests. there are
issues tracking this problem, see pytest-dev/pytest#5577 .
but we adds a handler which redirect the logging messages to stdout. so,
once pytest finishes testing, exceptions are raised when writing logging
messages, like
```
22:37:20    File "/usr/local/lib/python3.10/logging/__init__.py", line 1101, in emit
22:37:20      stream.write(msg + self.terminator)
22:37:20  ValueError: I/O operation on closed file.
```
so, in this change, `logging.raiseExceptions` is disabled when pytest's
session finishes.

Fixes scylladb#6000

Signed-off-by: Kefu Chai <kefu.chai@scylladb.com>
@tchaikov tchaikov mentioned this issue Apr 10, 2023
Merged
7 tasks
@fruch
Copy link
Contributor

fruch commented Apr 10, 2023

Probably better to point to

pytest-dev/pytest#5502

Where there's ongoing discussion, in our case it's mostly cosmetic, but we can copy the suggestion to disable the loggers

@tchaikov
Copy link
Contributor Author

@fruch i am fine either way. but i'd prefer simpler solutions if possible.

fruch pushed a commit that referenced this issue Apr 10, 2023
@tchaikov @fruch
fix(unit_test): prevent logging from raising exceptions after tests
0435861 
pytest's capsys just closes the stdout when done with tests. there are
issues tracking this problem, see pytest-dev/pytest#5577 .
but we adds a handler which redirect the logging messages to stdout. so,
once pytest finishes testing, exceptions are raised when writing logging
messages, like
```
22:37:20    File "/usr/local/lib/python3.10/logging/__init__.py", line 1101, in emit
22:37:20      stream.write(msg + self.terminator)
22:37:20  ValueError: I/O operation on closed file.
```
so, in this change, `logging.raiseExceptions` is disabled when pytest's
session finishes.

Fixes #6000

Signed-off-by: Kefu Chai <kefu.chai@scylladb.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tchaikov tchaikov

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix(unit_test): prevent logging from raising exceptions after tests tchaikov/scylla-cluster-tests
2 participants
@tchaikov @fruch