diff --git a/features/load_context.feature b/features/load_context.feature index 6d905b1919..8e3d356386 100644 --- a/features/load_context.feature +++ b/features/load_context.feature @@ -26,13 +26,13 @@ Feature: Custom Kedro project # we have more clarity on the necessity of these logging messages. # And I should get a message including "Registered hooks from 1 installed plugin(s): test-plugin-0.1" - Scenario: Hooks from installed plugins are automatically registered and work with the parallel runner + Scenario: Hooks from installed plugins are automatically registered and work with the parallel runner Given I have installed the test plugin When I execute the kedro command "run --runner=ParallelRunner" Then I should get a successful exit code And I should get a message including "Reached after_catalog_created hook" - # See explanation in test above. - # And I should get a message including "Registered hooks from 1 installed plugin(s): test-plugin-0.1" + # See explanation in test above. + # And I should get a message including "Registered hooks from 1 installed plugin(s): test-plugin-0.1" Scenario: Disable automatically registered plugin hooks Given I have installed the test plugin diff --git a/features/run.feature b/features/run.feature index 79d47e55d2..f49fb0171f 100644 --- a/features/run.feature +++ b/features/run.feature @@ -9,17 +9,17 @@ Feature: Run Project And I have run a non-interactive kedro new with starter When I execute the kedro command "run" Then I should get a successful exit code - And the console log should show that 4 nodes were run + And the logs should show that 4 nodes were run Scenario: Run parallel runner with default python entry point with example code Given I have prepared a config file And I have run a non-interactive kedro new with starter When I execute the kedro command "run --runner=ParallelRunner" Then I should get a successful exit code - And the console log should show that "split_data" was run - And the console log should show that "train_model" was run - And the console log should show that "predict" was run - And the console log should show that "report_accuracy" was run + And the logs should show that "split_data" was run + And the logs should show that "train_model" was run + And the logs should show that "predict" was run + And the logs should show that "report_accuracy" was run Scenario: Run default python entry point without example code Given I have prepared a config file @@ -34,7 +34,7 @@ Feature: Run Project And I have prepared a run_config file with config options When I execute the kedro command "run --config run_config.yml" Then I should get a successful exit code - And the console log should show that 1 nodes were run + And the logs should show that 1 nodes were run Scenario: Run kedro run with config file and override option Given I have prepared a config file @@ -42,11 +42,11 @@ Feature: Run Project And I have prepared a run_config file with config options When I execute the kedro command "run --config run_config.yml --pipeline __default__" Then I should get a successful exit code - And the console log should show that 4 nodes were run + And the logs should show that 4 nodes were run Scenario: Run kedro run with extra parameters Given I have prepared a config file And I have run a non-interactive kedro new with starter When I execute the kedro command "run --params extra1:1,extra2:value2" Then I should get a successful exit code - And the console log should show that 4 nodes were run + And the logs should show that 4 nodes were run diff --git a/features/steps/cli_steps.py b/features/steps/cli_steps.py index 7ab0da2afe..7621a7461c 100644 --- a/features/steps/cli_steps.py +++ b/features/steps/cli_steps.py @@ -451,20 +451,24 @@ def check_pipeline_not_empty(context): assert "pipeline = pipeline([])" not in pipeline_file.read_text("utf-8") -@then("the console log should show that {number} nodes were run") +@then("the logs should show that {number} nodes were run") def check_one_node_run(context, number): expected_log_line = f"Completed {number} out of {number} tasks" + info_log = context.root_project_dir / "logs" / "info.log" assert expected_log_line in context.result.stdout + assert expected_log_line in info_log.read_text() -@then('the console log should show that "{node}" was run') +@then('the logs should show that "{node}" was run') def check_correct_nodes_run(context, node): expected_log_line = f"Running node: {node}" + info_log = context.root_project_dir / "logs" / "info.log" stdout = context.result.stdout assert expected_log_line in stdout, ( "Expected the following message segment to be printed on stdout: " f"{expected_log_line},\nbut got {stdout}" ) + assert expected_log_line in info_log.read_text() @then("I should get a successful exit code") diff --git a/features/steps/test_plugin/plugin.py b/features/steps/test_plugin/plugin.py index 876c40bd69..82b3e73832 100644 --- a/features/steps/test_plugin/plugin.py +++ b/features/steps/test_plugin/plugin.py @@ -3,13 +3,16 @@ from kedro.framework.hooks import hook_impl +logger = logging.getLogger(__name__) +logger.setLevel(logging.INFO) + class MyPluginHook: @hook_impl def after_catalog_created( self, catalog ): # pylint: disable=unused-argument,no-self-use - logging.info("Reached after_catalog_created hook") + logger.info("Reached after_catalog_created hook") hooks = MyPluginHook() diff --git a/features/steps/test_starter/{{ cookiecutter.repo_name }}/conf/base/logging.yml b/features/steps/test_starter/{{ cookiecutter.repo_name }}/conf/base/logging.yml index a4dcad2e08..6dfab05dd4 100644 --- a/features/steps/test_starter/{{ cookiecutter.repo_name }}/conf/base/logging.yml +++ b/features/steps/test_starter/{{ cookiecutter.repo_name }}/conf/base/logging.yml @@ -1,55 +1,44 @@ version: 1 + disable_existing_loggers: False + formatters: - simple: - format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" - json_formatter: - format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" - class: pythonjsonlogger.jsonlogger.JsonFormatter + simple: + format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" handlers: - console: - class: logging.StreamHandler - level: INFO - formatter: simple - stream: ext://sys.stdout - - info_file_handler: - class: logging.handlers.RotatingFileHandler - level: INFO - formatter: simple - filename: logs/info.log - maxBytes: 10485760 # 10MB - backupCount: 20 - encoding: utf8 - delay: True - - error_file_handler: - class: logging.handlers.RotatingFileHandler - level: ERROR - formatter: simple - filename: logs/errors.log - maxBytes: 10485760 # 10MB - backupCount: 20 - encoding: utf8 - delay: True + console: + class: logging.StreamHandler + level: INFO + formatter: simple + stream: ext://sys.stdout -loggers: - anyconfig: - level: WARNING - handlers: [console, info_file_handler, error_file_handler] - propagate: no + info_file_handler: + class: logging.handlers.RotatingFileHandler + level: INFO + formatter: simple + filename: logs/info.log + maxBytes: 10485760 # 10MB + backupCount: 20 + encoding: utf8 + delay: True - kedro.io: - level: INFO - handlers: [console, info_file_handler, error_file_handler] - propagate: no + error_file_handler: + class: logging.handlers.RotatingFileHandler + level: ERROR + formatter: simple + filename: logs/errors.log + maxBytes: 10485760 # 10MB + backupCount: 20 + encoding: utf8 + delay: True - kedro.pipeline: - level: INFO - handlers: [console, info_file_handler, error_file_handler] - propagate: no +loggers: + kedro: + level: INFO -root: + {{ cookiecutter.python_package }}: level: INFO - handlers: [console, info_file_handler, error_file_handler] + +root: + handlers: [console, info_file_handler, error_file_handler] diff --git a/features/steps/util.py b/features/steps/util.py index d5a7c5685f..ee903e0940 100644 --- a/features/steps/util.py +++ b/features/steps/util.py @@ -3,38 +3,11 @@ import os import re -import tempfile from contextlib import contextmanager from pathlib import Path from time import sleep, time from typing import Any, Callable, Iterator, List -import pandas as pd - - -def get_sample_csv_content(): - return """col1, col2, col3 - 1, 2, 3 - 4, 5, 6 - """ - - -def get_sample_data_frame(): - data = {"col1": [1, 2], "col2": [4, 5], "col3": [5, 6]} - return pd.DataFrame(data) - - -def create_temp_csv(): - _, csv_file_path = tempfile.mkstemp(suffix=".csv") - return csv_file_path - - -def create_sample_csv(): - csv_file_path = create_temp_csv() - with open(csv_file_path, mode="w", encoding="utf-8") as output_file: - output_file.write(get_sample_csv_content()) - return csv_file_path - @contextmanager def chdir(path: Path) -> Iterator: @@ -99,55 +72,6 @@ def wait_for( ) -def get_logline_count(logfile: str) -> int: - """Get line count in logfile - - Note: If logfile doesn't exist will return 0 - - Args: - logfile: path to logfile - - Returns: - line count of logfile - """ - try: - with open(logfile, encoding="utf-8") as file_handle: - return sum(1 for i in file_handle) - except FileNotFoundError: - return 0 - - -def get_last_logline(logfile: str) -> str: - """Get last line of logfile - - Args: - logfile: path to logfile - - Returns: - last line of logfile - """ - line = "" - with open(logfile, encoding="utf-8") as file_handle: - for line in file_handle: - pass - - return line - - -def get_logfile_path(proj_dir: Path) -> str: - """ - Helper function to fet full path of `pipeline.log` inside project - - Args: - proj_dir: path to proj_dir - - Returns: - path to `pipeline.log` - """ - log_file = (proj_dir / "logs" / "visualization" / "pipeline.log").absolute() - return str(log_file) - - def parse_csv(text: str) -> List[str]: """Parse comma separated **double quoted** strings in behave steps diff --git a/kedro/config/logging.yml b/kedro/config/logging.yml index 60798308e4..ce9998446a 100644 --- a/kedro/config/logging.yml +++ b/kedro/config/logging.yml @@ -1,44 +1,21 @@ version: 1 + disable_existing_loggers: False + formatters: - simple: - format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + simple: + format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" handlers: - console: - class: logging.StreamHandler - level: INFO - formatter: simple - stream: ext://sys.stdout - - info_file_handler: - class: logging.handlers.RotatingFileHandler - level: INFO - formatter: simple - filename: info.log - maxBytes: 10485760 # 10MB - backupCount: 20 - encoding: utf8 - delay: True - - error_file_handler: - class: logging.handlers.RotatingFileHandler - level: ERROR - formatter: simple - filename: errors.log - maxBytes: 10485760 # 10MB - backupCount: 20 - encoding: utf8 - delay: True + console: + class: logging.StreamHandler + level: INFO + formatter: simple + stream: ext://sys.stdout loggers: - kedro.framework.cli.hooks.manager: - level: INFO - handlers: [console] - propagate: no - - kedro: - level: INFO + kedro: + level: INFO root: - handlers: [console, info_file_handler, error_file_handler] + handlers: [console] diff --git a/kedro/framework/session/session.py b/kedro/framework/session/session.py index 158208f401..25f95cdb01 100644 --- a/kedro/framework/session/session.py +++ b/kedro/framework/session/session.py @@ -13,7 +13,7 @@ import click from kedro import __version__ as kedro_version -from kedro.config import ConfigLoader +from kedro.config import ConfigLoader, MissingConfigException from kedro.framework.context import KedroContext from kedro.framework.context.context import _convert_paths_to_absolute_posix from kedro.framework.hooks import _create_hook_manager @@ -185,8 +185,15 @@ def _get_logging_config(self) -> Dict[str, Any]: def _setup_logging(self) -> None: """Register logging specified in logging directory.""" - conf_logging = self._get_logging_config() - configure_logging(conf_logging) + try: + conf_logging = self._get_logging_config() + except MissingConfigException: + self._logger.debug( + "No project logging configuration loaded; " + "Kedro's default logging configuration will be used." + ) + else: + configure_logging(conf_logging) def _init_store(self) -> BaseSessionStore: store_class = settings.SESSION_STORE_CLASS diff --git a/kedro/runner/parallel_runner.py b/kedro/runner/parallel_runner.py index fca229df73..bd4492485f 100644 --- a/kedro/runner/parallel_runner.py +++ b/kedro/runner/parallel_runner.py @@ -12,7 +12,7 @@ from multiprocessing.managers import BaseProxy, SyncManager # type: ignore from multiprocessing.reduction import ForkingPickler from pickle import PicklingError -from typing import Any, Dict, Iterable, Set +from typing import Any, Dict, Iterable, Optional, Set from pluggy import PluginManager @@ -80,12 +80,15 @@ class ParallelRunnerManager(SyncManager): ) -def _bootstrap_subprocess(package_name: str, conf_logging: Dict[str, Any]): +def _bootstrap_subprocess( + package_name: str, conf_logging: Optional[Dict[str, Any]] = None +): # pylint: disable=import-outside-toplevel,cyclic-import from kedro.framework.project import configure_project configure_project(package_name) - logging.config.dictConfig(conf_logging) + if conf_logging is not None: + logging.config.dictConfig(conf_logging) def _run_node_synchronization( # pylint: disable=too-many-arguments @@ -94,7 +97,7 @@ def _run_node_synchronization( # pylint: disable=too-many-arguments is_async: bool = False, session_id: str = None, package_name: str = None, - conf_logging: Dict[str, Any] = None, + conf_logging: Optional[Dict[str, Any]] = None, ) -> Node: """Run a single `Node` with inputs from and outputs to the `catalog`. A `PluginManager` `hook_manager` instance is created in every subprocess because @@ -114,7 +117,6 @@ def _run_node_synchronization( # pylint: disable=too-many-arguments """ if multiprocessing.get_start_method() == "spawn" and package_name: # type: ignore - conf_logging = conf_logging or {} _bootstrap_subprocess(package_name, conf_logging) hook_manager = _create_hook_manager() diff --git a/kedro/templates/project/{{ cookiecutter.repo_name }}/conf/base/logging.yml b/kedro/templates/project/{{ cookiecutter.repo_name }}/conf/base/logging.yml index a4dcad2e08..6dfab05dd4 100644 --- a/kedro/templates/project/{{ cookiecutter.repo_name }}/conf/base/logging.yml +++ b/kedro/templates/project/{{ cookiecutter.repo_name }}/conf/base/logging.yml @@ -1,55 +1,44 @@ version: 1 + disable_existing_loggers: False + formatters: - simple: - format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" - json_formatter: - format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" - class: pythonjsonlogger.jsonlogger.JsonFormatter + simple: + format: "%(asctime)s - %(name)s - %(levelname)s - %(message)s" handlers: - console: - class: logging.StreamHandler - level: INFO - formatter: simple - stream: ext://sys.stdout - - info_file_handler: - class: logging.handlers.RotatingFileHandler - level: INFO - formatter: simple - filename: logs/info.log - maxBytes: 10485760 # 10MB - backupCount: 20 - encoding: utf8 - delay: True - - error_file_handler: - class: logging.handlers.RotatingFileHandler - level: ERROR - formatter: simple - filename: logs/errors.log - maxBytes: 10485760 # 10MB - backupCount: 20 - encoding: utf8 - delay: True + console: + class: logging.StreamHandler + level: INFO + formatter: simple + stream: ext://sys.stdout -loggers: - anyconfig: - level: WARNING - handlers: [console, info_file_handler, error_file_handler] - propagate: no + info_file_handler: + class: logging.handlers.RotatingFileHandler + level: INFO + formatter: simple + filename: logs/info.log + maxBytes: 10485760 # 10MB + backupCount: 20 + encoding: utf8 + delay: True - kedro.io: - level: INFO - handlers: [console, info_file_handler, error_file_handler] - propagate: no + error_file_handler: + class: logging.handlers.RotatingFileHandler + level: ERROR + formatter: simple + filename: logs/errors.log + maxBytes: 10485760 # 10MB + backupCount: 20 + encoding: utf8 + delay: True - kedro.pipeline: - level: INFO - handlers: [console, info_file_handler, error_file_handler] - propagate: no +loggers: + kedro: + level: INFO -root: + {{ cookiecutter.python_package }}: level: INFO - handlers: [console, info_file_handler, error_file_handler] + +root: + handlers: [console, info_file_handler, error_file_handler] diff --git a/tests/config/test_config.py b/tests/config/test_config.py index f3449bdb33..3c9ed07f3b 100644 --- a/tests/config/test_config.py +++ b/tests/config/test_config.py @@ -14,27 +14,6 @@ _BASE_ENV = "base" -def _get_local_logging_config(): - return { - "version": 1, - "formatters": { - "simple": {"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"} - }, - "root": {"level": "INFO", "handlers": ["console"]}, - "loggers": { - "kedro": {"level": "INFO", "handlers": ["console"], "propagate": False} - }, - "handlers": { - "console": { - "class": "logging.StreamHandler", - "level": "INFO", - "formatter": "simple", - "stream": "ext://sys.stdout", - } - }, - } - - def _write_yaml(filepath: Path, config: Dict): filepath.parent.mkdir(parents=True, exist_ok=True) yaml_str = yaml.dump(config) @@ -86,14 +65,12 @@ def local_config(tmp_path): def create_config_dir(tmp_path, base_config, local_config): proj_catalog = tmp_path / _BASE_ENV / "catalog.yml" local_catalog = tmp_path / _DEFAULT_RUN_ENV / "catalog.yml" - local_logging = tmp_path / _DEFAULT_RUN_ENV / "logging.yml" parameters = tmp_path / _BASE_ENV / "parameters.json" db_config_path = tmp_path / _BASE_ENV / "db.ini" project_parameters = dict(param1=1, param2=2) _write_yaml(proj_catalog, base_config) _write_yaml(local_catalog, local_config) - _write_yaml(local_logging, _get_local_logging_config()) _write_json(parameters, project_parameters) _write_dummy_ini(db_config_path) diff --git a/features/steps/test_starter/{{ cookiecutter.repo_name }}/logs/journals/.gitkeep b/tests/extras/datasets/redis/__init__.py similarity index 100% rename from features/steps/test_starter/{{ cookiecutter.repo_name }}/logs/journals/.gitkeep rename to tests/extras/datasets/redis/__init__.py diff --git a/tests/extras/datasets/spark/__init__.py b/tests/extras/datasets/spark/__init__.py index 6431b34ecf..e69de29bb2 100644 --- a/tests/extras/datasets/spark/__init__.py +++ b/tests/extras/datasets/spark/__init__.py @@ -1,5 +0,0 @@ -"""Unit tests for spark related datasets.""" - -import logging - -logging.getLogger("py4j").setLevel(logging.WARN) diff --git a/tests/extras/extensions/test_ipython.py b/tests/extras/extensions/test_ipython.py index f343538393..a1ffb2d9d1 100644 --- a/tests/extras/extensions/test_ipython.py +++ b/tests/extras/extensions/test_ipython.py @@ -12,13 +12,6 @@ def project_path(mocker, tmp_path): mocker.patch("kedro.extras.extensions.ipython.default_project_path", path) -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - @pytest.fixture(autouse=True) def cleanup_session(): yield @@ -62,7 +55,7 @@ def my_register_pipeline(): ) mocker.patch("kedro.framework.project.settings.configure") mocker.patch("kedro.framework.session.session.validate_settings") - mocker.patch("kedro.framework.session.KedroSession._get_config_loader") + mocker.patch("kedro.framework.session.KedroSession._setup_logging") mocker.patch( "kedro.framework.startup.bootstrap_project", return_value=fake_metadata ) @@ -176,7 +169,7 @@ def my_register_pipeline(): ) mocker.patch("kedro.framework.project.settings.configure") mocker.patch("kedro.framework.session.session.validate_settings") - mocker.patch("kedro.framework.session.KedroSession._get_config_loader") + mocker.patch("kedro.framework.session.KedroSession._setup_logging") mocker.patch( "kedro.framework.startup.bootstrap_project", return_value=fake_metadata ) diff --git a/tests/framework/cli/conftest.py b/tests/framework/cli/conftest.py index 2855d65721..77d33d2560 100644 --- a/tests/framework/cli/conftest.py +++ b/tests/framework/cli/conftest.py @@ -121,6 +121,9 @@ def fake_project_cli( CliRunner().invoke( fake_kedro_cli, ["new", "-c", str(dummy_config), "--starter", str(starter_path)] ) + # Delete the project logging.yml, which leaves behind info.log and error.log files. + # This leaves logging config as the framework default. + (fake_repo_path / "conf" / "base" / "logging.yml").unlink() # NOTE: Here we load a couple of modules, as they would be imported in # the code and tests. @@ -154,8 +157,3 @@ def fake_project_cli( @fixture def chdir_to_dummy_project(fake_repo_path, monkeypatch): monkeypatch.chdir(str(fake_repo_path)) - - -@fixture -def patch_log(mocker): - mocker.patch("logging.config.dictConfig") diff --git a/tests/framework/cli/micropkg/conftest.py b/tests/framework/cli/micropkg/conftest.py index 976939fd3d..ff8348b755 100644 --- a/tests/framework/cli/micropkg/conftest.py +++ b/tests/framework/cli/micropkg/conftest.py @@ -5,13 +5,6 @@ from kedro.framework.project import settings -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - @pytest.fixture(autouse=True) def cleanup_micropackages(fake_repo_path, fake_package_path): packages = {p.name for p in fake_package_path.iterdir() if p.is_dir()} diff --git a/tests/framework/cli/micropkg/test_micropkg_package.py b/tests/framework/cli/micropkg/test_micropkg_package.py index 588bb9ac20..6527af0a5e 100644 --- a/tests/framework/cli/micropkg/test_micropkg_package.py +++ b/tests/framework/cli/micropkg/test_micropkg_package.py @@ -15,7 +15,7 @@ TOO_SHORT_ERROR = "It must be at least 2 characters long." -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log", "cleanup_dist") +@pytest.mark.usefixtures("chdir_to_dummy_project", "cleanup_dist") class TestMicropkgPackageCommand: def assert_sdist_contents_correct( self, sdist_location, package_name=PIPELINE_NAME, version="0.1" @@ -491,7 +491,7 @@ def test_micropkg_package_nested_module( @pytest.mark.usefixtures( - "chdir_to_dummy_project", "patch_log", "cleanup_dist", "cleanup_pyproject_toml" + "chdir_to_dummy_project", "cleanup_dist", "cleanup_pyproject_toml" ) class TestMicropkgPackageFromManifest: def test_micropkg_package_all( # pylint: disable=too-many-locals diff --git a/tests/framework/cli/micropkg/test_micropkg_pull.py b/tests/framework/cli/micropkg/test_micropkg_pull.py index 772f3c7f03..ea84dd3bfd 100644 --- a/tests/framework/cli/micropkg/test_micropkg_pull.py +++ b/tests/framework/cli/micropkg/test_micropkg_pull.py @@ -42,7 +42,7 @@ def call_pipeline_delete(cli, metadata, pipeline_name=PIPELINE_NAME): assert result.exit_code == 0 -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log", "cleanup_dist") +@pytest.mark.usefixtures("chdir_to_dummy_project", "cleanup_dist") class TestMicropkgPullCommand: def assert_package_files_exist(self, source_path): assert {f.name for f in source_path.iterdir()} == { @@ -753,7 +753,7 @@ def test_pull_unsupported_protocol_by_fsspec( @pytest.mark.usefixtures( - "chdir_to_dummy_project", "patch_log", "cleanup_dist", "cleanup_pyproject_toml" + "chdir_to_dummy_project", "cleanup_dist", "cleanup_pyproject_toml" ) class TestMicropkgPullFromManifest: def test_micropkg_pull_all( # pylint: disable=too-many-locals diff --git a/tests/framework/cli/pipeline/conftest.py b/tests/framework/cli/pipeline/conftest.py index 2dc27dd6ce..f934ab6939 100644 --- a/tests/framework/cli/pipeline/conftest.py +++ b/tests/framework/cli/pipeline/conftest.py @@ -5,13 +5,6 @@ from kedro.framework.project import settings -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - @pytest.fixture(autouse=True) def cleanup_micropackages(fake_repo_path, fake_package_path): packages = {p.name for p in fake_package_path.iterdir() if p.is_dir()} diff --git a/tests/framework/cli/pipeline/test_pipeline.py b/tests/framework/cli/pipeline/test_pipeline.py index 130a17c3c2..49ef21c694 100644 --- a/tests/framework/cli/pipeline/test_pipeline.py +++ b/tests/framework/cli/pipeline/test_pipeline.py @@ -41,7 +41,7 @@ def make_pipelines(request, fake_repo_path, fake_package_path, mocker): TOO_SHORT_ERROR = "It must be at least 2 characters long." -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestPipelineCreateCommand: @pytest.mark.parametrize("env", [None, "local"]) def test_create_pipeline( # pylint: disable=too-many-locals @@ -252,7 +252,7 @@ def test_bad_env(self, fake_project_cli, fake_metadata): assert f"Unable to locate environment `{env}`" in result.output -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log", "make_pipelines") +@pytest.mark.usefixtures("chdir_to_dummy_project", "make_pipelines") class TestPipelineDeleteCommand: @pytest.mark.parametrize( "make_pipelines,env,expected_conf", diff --git a/tests/framework/cli/test_catalog.py b/tests/framework/cli/test_catalog.py index 1e17cdc06f..1a558e4eea 100644 --- a/tests/framework/cli/test_catalog.py +++ b/tests/framework/cli/test_catalog.py @@ -17,13 +17,6 @@ def fake_load_context(mocker): ) -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - PIPELINE_NAME = "pipeline" @@ -158,7 +151,7 @@ def identity(data): return data # pragma: no cover -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestCatalogCreateCommand: PIPELINE_NAME = "de" diff --git a/tests/framework/cli/test_cli.py b/tests/framework/cli/test_cli.py index e4c59619a5..4ba04b8a20 100644 --- a/tests/framework/cli/test_cli.py +++ b/tests/framework/cli/test_cli.py @@ -1,3 +1,4 @@ +import logging from collections import namedtuple from itertools import cycle from pathlib import Path @@ -8,6 +9,8 @@ from click.testing import CliRunner from pytest import fixture, mark, raises +# pylint: disable=unused-import +import kedro.config.default_logger # noqa from kedro import __version__ as version from kedro.framework.cli import load_entry_points from kedro.framework.cli.catalog import catalog_cli @@ -71,6 +74,16 @@ def fake_session(mocker): return mocked_session +class TestDefaultLogging: + def test_setup_root_logger(self): + root_logger = logging.getLogger() + assert "console" in {handler.name for handler in root_logger.handlers} + + def test_setup_kedro_logger(self): + kedro_logger = logging.getLogger("kedro") + assert kedro_logger.level == logging.INFO + + class TestCliCommands: def test_cli(self): """Run `kedro` without arguments.""" @@ -435,7 +448,7 @@ def test_kedro_cli_with_project(self, mocker, fake_metadata): assert "Project specific commands from Kedro" in result.output -@mark.usefixtures("chdir_to_dummy_project", "patch_log") +@mark.usefixtures("chdir_to_dummy_project") class TestRunCommand: @staticmethod @fixture(params=["run_config.yml", "run_config.json"]) diff --git a/tests/framework/cli/test_cli_hooks.py b/tests/framework/cli/test_cli_hooks.py index fe39fc14ad..3a4aa063c6 100644 --- a/tests/framework/cli/test_cli_hooks.py +++ b/tests/framework/cli/test_cli_hooks.py @@ -93,10 +93,7 @@ def test_kedro_cli_should_invoke_cli_hooks_from_plugin( fake_metadata, fake_plugin_distribution, ): - # Workaround to ensure that the log messages are picked up by caplog. - # https://github.com/pytest-dev/pytest/issues/3697 - logging.getLogger("kedro.framework.cli.hooks.manager").propagate = True - logging.getLogger("kedro.framework.cli.hooks.manager").setLevel(logging.DEBUG) + caplog.set_level(logging.DEBUG, logger="kedro") Module = namedtuple("Module", ["cli"]) mocker.patch( diff --git a/tests/framework/cli/test_jupyter.py b/tests/framework/cli/test_jupyter.py index 2955ec3102..186fb4fbff 100644 --- a/tests/framework/cli/test_jupyter.py +++ b/tests/framework/cli/test_jupyter.py @@ -15,13 +15,6 @@ from kedro.framework.cli.utils import KedroCliError -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - @pytest.fixture(autouse=True) def python_call_mock(mocker): return mocker.patch("kedro.framework.cli.jupyter.python_call") @@ -33,7 +26,7 @@ def create_kernel_mock(mocker): @pytest.mark.usefixtures( - "chdir_to_dummy_project", "patch_log", "create_kernel_mock", "python_call_mock" + "chdir_to_dummy_project", "create_kernel_mock", "python_call_mock" ) class TestJupyterNotebookCommand: def test_happy_path( @@ -83,7 +76,7 @@ def test_fail_no_jupyter(self, fake_project_cli, mocker): @pytest.mark.usefixtures( - "chdir_to_dummy_project", "patch_log", "create_kernel_mock", "python_call_mock" + "chdir_to_dummy_project", "create_kernel_mock", "python_call_mock" ) class TestJupyterLabCommand: def test_happy_path( @@ -171,7 +164,7 @@ def cleanup_nodes_dir(fake_package_path): shutil.rmtree(str(nodes_dir)) -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log", "cleanup_nodes_dir") +@pytest.mark.usefixtures("chdir_to_dummy_project", "cleanup_nodes_dir") class TestConvertNotebookCommand: @pytest.fixture def fake_export_nodes(self, mocker): diff --git a/tests/framework/cli/test_project.py b/tests/framework/cli/test_project.py index a045a6a385..9f9edfd408 100644 --- a/tests/framework/cli/test_project.py +++ b/tests/framework/cli/test_project.py @@ -9,13 +9,6 @@ from kedro.framework.cli.project import NO_DEPENDENCY_MESSAGE -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - @pytest.fixture(autouse=True) def call_mock(mocker): return mocker.patch("kedro.framework.cli.project.call") @@ -31,7 +24,7 @@ def fake_copyfile(mocker): return mocker.patch("shutil.copyfile") -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestActivateNbstripoutCommand: @staticmethod @pytest.fixture() @@ -112,7 +105,7 @@ def test_no_git_executable( assert "Git executable not found. Install Git first." in result.stdout -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestTestCommand: def test_happy_path(self, fake_project_cli, python_call_mock): result = CliRunner().invoke(fake_project_cli, ["test", "--random-arg", "value"]) @@ -136,7 +129,7 @@ def test_pytest_not_installed( python_call_mock.assert_not_called() -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestLintCommand: @pytest.mark.parametrize("files", [(), ("src",)]) def test_lint( @@ -239,7 +232,7 @@ def test_pythonpath_env_var( assert mocked_environ == {"PYTHONPATH": str(fake_repo_path / "src")} -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestIpythonCommand: def test_happy_path( self, @@ -291,7 +284,7 @@ def test_fail_no_ipython(self, fake_project_cli, mocker): assert error in result.output -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestPackageCommand: def test_happy_path( self, call_mock, fake_project_cli, mocker, fake_repo_path, fake_metadata @@ -328,7 +321,7 @@ def test_happy_path( ) -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestBuildDocsCommand: def test_happy_path( self, @@ -383,7 +376,7 @@ def test_open_docs(self, open_flag, fake_project_cli, mocker, fake_metadata): patched_browser.assert_called_once_with(expected_path) -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log", "fake_copyfile") +@pytest.mark.usefixtures("chdir_to_dummy_project", "fake_copyfile") class TestBuildReqsCommand: def test_compile_from_requirements_file( self, diff --git a/tests/framework/cli/test_registry.py b/tests/framework/cli/test_registry.py index 091b9acc2a..f394bc4d15 100644 --- a/tests/framework/cli/test_registry.py +++ b/tests/framework/cli/test_registry.py @@ -22,7 +22,7 @@ def pipelines_dict(): return pipelines -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") def test_list_registered_pipelines( fake_project_cli, fake_metadata, yaml_dump_mock, pipelines_dict ): @@ -34,7 +34,7 @@ def test_list_registered_pipelines( yaml_dump_mock.assert_called_once_with(sorted(pipelines_dict.keys())) -@pytest.mark.usefixtures("chdir_to_dummy_project", "patch_log") +@pytest.mark.usefixtures("chdir_to_dummy_project") class TestRegistryDescribeCommand: @pytest.mark.parametrize("pipeline_name", ["de", "ds", "dp", "__default__"]) def test_describe_registered_pipeline( diff --git a/tests/framework/context/test_context.py b/tests/framework/context/test_context.py index 941bf77cb0..d3bdc9d862 100644 --- a/tests/framework/context/test_context.py +++ b/tests/framework/context/test_context.py @@ -106,44 +106,22 @@ def local_config(tmp_path): } -@pytest.fixture -def local_logging_config() -> Dict[str, Any]: - return { - "version": 1, - "formatters": { - "simple": {"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"} - }, - "root": {"level": "INFO", "handlers": ["console"]}, - "loggers": {"kedro": {"level": "INFO", "handlers": ["console"]}}, - "handlers": { - "console": { - "class": "logging.StreamHandler", - "level": "INFO", - "formatter": "simple", - "stream": "ext://sys.stdout", - } - }, - } - - @pytest.fixture(params=[None]) def env(request): return request.param @pytest.fixture -def prepare_project_dir(tmp_path, base_config, local_config, local_logging_config, env): +def prepare_project_dir(tmp_path, base_config, local_config, env): env = "local" if env is None else env proj_catalog = tmp_path / "conf" / "base" / "catalog.yml" env_catalog = tmp_path / "conf" / str(env) / "catalog.yml" - logging = tmp_path / "conf" / "local" / "logging.yml" env_credentials = tmp_path / "conf" / str(env) / "credentials.yml" parameters = tmp_path / "conf" / "base" / "parameters.json" db_config_path = tmp_path / "conf" / "base" / "db.ini" project_parameters = {"param1": 1, "param2": 2, "param3": {"param4": 3}} _write_yaml(proj_catalog, base_config) _write_yaml(env_catalog, local_config) - _write_yaml(logging, local_logging_config) _write_yaml(env_credentials, local_config) _write_json(parameters, project_parameters) _write_dummy_ini(db_config_path) @@ -207,13 +185,6 @@ def extra_params(request): return request.param -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - @pytest.fixture def dummy_context( tmp_path, prepare_project_dir, env, extra_params diff --git a/tests/framework/session/conftest.py b/tests/framework/session/conftest.py index 45448bffa5..5d61a842f1 100644 --- a/tests/framework/session/conftest.py +++ b/tests/framework/session/conftest.py @@ -33,15 +33,6 @@ def mock_package_name() -> str: return MOCK_PACKAGE_NAME -@pytest.fixture -def local_logging_config() -> Dict[str, Any]: - return { - "version": 1, - "incremental": True, - "root": {"level": "INFO"}, - } - - def _write_yaml(filepath: Path, config: Dict): filepath.parent.mkdir(parents=True, exist_ok=True) yaml_str = yaml.dump(config) @@ -86,14 +77,12 @@ def local_config(tmp_path): @pytest.fixture(autouse=True) -def config_dir(tmp_path, local_config, local_logging_config): +def config_dir(tmp_path, local_config): catalog = tmp_path / "conf" / "base" / "catalog.yml" credentials = tmp_path / "conf" / "local" / "credentials.yml" - logging = tmp_path / "conf" / "local" / "logging.yml" pyproject_toml = tmp_path / "pyproject.toml" _write_yaml(catalog, local_config) _write_yaml(credentials, {"dev_s3": "foo"}) - _write_yaml(logging, local_logging_config) payload = { "tool": { "kedro": { diff --git a/tests/framework/session/test_session.py b/tests/framework/session/test_session.py index 37b70e00d5..ed2aee6e8e 100644 --- a/tests/framework/session/test_session.py +++ b/tests/framework/session/test_session.py @@ -1,4 +1,3 @@ -import json import logging import re import subprocess @@ -7,6 +6,7 @@ import pytest import toml +import yaml from kedro import __version__ as kedro_version from kedro.config import AbstractConfigLoader, ConfigLoader @@ -37,13 +37,6 @@ class BadConfigLoader: # pylint: disable=too-few-public-methods """ -@pytest.fixture(autouse=True) -def mocked_logging(mocker): - # Disable logging.config.dictConfig in KedroSession._setup_logging as - # it changes logging.config and affects other unit tests - return mocker.patch("logging.config.dictConfig") - - @pytest.fixture def mock_context_class(mocker): return mocker.patch("kedro.framework.session.session.KedroContext", autospec=True) @@ -171,35 +164,7 @@ def fake_session_id(mocker): @pytest.fixture -def local_logging_config(): - return { - "version": 1, - "formatters": { - "simple": {"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"} - }, - "root": {"level": "INFO", "handlers": ["console"]}, - "loggers": { - "kedro": {"level": "INFO", "handlers": ["console"], "propagate": False} - }, - "handlers": { - "console": { - "class": "logging.StreamHandler", - "level": "INFO", - "formatter": "simple", - "stream": "ext://sys.stdout", - } - }, - "info_file_handler": { - "class": "logging.handlers.RotatingFileHandler", - "level": "INFO", - "formatter": "simple", - "filename": "logs/info.log", - }, - } - - -@pytest.fixture -def fake_project(tmp_path, local_logging_config, mock_package_name): +def fake_project(tmp_path, mock_package_name): fake_project_dir = Path(tmp_path) / "fake_project" (fake_project_dir / "src").mkdir(parents=True) @@ -216,9 +181,7 @@ def fake_project(tmp_path, local_logging_config, mock_package_name): toml_str = toml.dumps(payload) pyproject_toml_path.write_text(toml_str, encoding="utf-8") - env_logging = fake_project_dir / "conf" / "base" / "logging.yml" - env_logging.parent.mkdir(parents=True) - env_logging.write_text(json.dumps(local_logging_config), encoding="utf-8") + (fake_project_dir / "conf" / "base").mkdir(parents=True) (fake_project_dir / "conf" / "local").mkdir() return fake_project_dir @@ -256,7 +219,7 @@ def test_create( fake_username, ): mock_click_ctx = mocker.patch("click.get_current_context").return_value - mocker.patch("kedro.framework.session.KedroSession._get_logging_config") + mocker.patch("kedro.framework.session.KedroSession._setup_logging") session = KedroSession.create( mock_package_name, fake_project, env=env, extra_params=extra_params ) @@ -327,6 +290,7 @@ def test_load_context_with_envvar( self, fake_project, monkeypatch, mock_package_name, mocker ): mocker.patch("kedro.config.config.ConfigLoader.get") + mocker.patch("kedro.framework.session.KedroSession._setup_logging") monkeypatch.setenv("KEDRO_ENV", "my_fake_env") session = KedroSession.create(mock_package_name, fake_project) @@ -341,6 +305,7 @@ def test_load_config_loader_with_envvar( self, fake_project, monkeypatch, mock_package_name, mocker ): mocker.patch("kedro.config.config.ConfigLoader.get") + mocker.patch("kedro.framework.session.KedroSession._setup_logging") monkeypatch.setenv("KEDRO_ENV", "my_fake_env") session = KedroSession.create(mock_package_name, fake_project) @@ -380,6 +345,24 @@ def test_broken_config_loader(self, mock_settings_file_bad_config_loader_class): with pytest.raises(ValidationError, match=re.escape(pattern)): assert mock_settings.CONFIG_LOADER_CLASS + def test_no_logging_config(self, fake_project, caplog, mock_package_name, mocker): + caplog.set_level(logging.DEBUG, logger="kedro") + + mocker.patch("subprocess.check_output") + session = KedroSession.create(mock_package_name, fake_project) + session.close() + + expected_log_messages = [ + "No project logging configuration loaded; " + "Kedro's default logging configuration will be used." + ] + actual_log_messages = [ + rec.getMessage() + for rec in caplog.records + if rec.name == SESSION_LOGGER_NAME and rec.levelno == logging.DEBUG + ] + assert actual_log_messages == expected_log_messages + @pytest.mark.usefixtures("mock_settings_context_class") def test_default_store( self, fake_project, fake_session_id, caplog, mock_package_name @@ -500,6 +483,7 @@ def test_git_describe_error( """ caplog.set_level(logging.DEBUG, logger="kedro") + mocker.patch("kedro.framework.session.KedroSession._setup_logging") mocker.patch("subprocess.check_output", side_effect=exception) session = KedroSession.create(mock_package_name, fake_project) assert "git" not in session.store @@ -827,15 +811,29 @@ def test_run_broken_pipeline_multiple_times( # pylint: disable=too-many-locals ) +@pytest.fixture +def fake_project_with_logging_file_handler(fake_project): + logging_config = { + "version": 1, + "handlers": {"info_file_handler": {"filename": "logs/info.log"}}, + } + logging_yml = fake_project / "conf" / "base" / "logging.yml" + logging_yml.write_text(yaml.dump(logging_config)) + return fake_project + + @pytest.mark.usefixtures("mock_settings") def test_setup_logging_using_absolute_path( - fake_project, mocked_logging, mock_package_name + fake_project_with_logging_file_handler, mocker, mock_package_name ): - KedroSession.create(mock_package_name, fake_project) + mocked_logging = mocker.patch("logging.config.dictConfig") + KedroSession.create(mock_package_name, fake_project_with_logging_file_handler) mocked_logging.assert_called_once() call_args = mocked_logging.call_args[0][0] - expected_log_filepath = (fake_project / "logs" / "info.log").as_posix() - actual_log_filepath = call_args["info_file_handler"]["filename"] + expected_log_filepath = ( + fake_project_with_logging_file_handler / "logs" / "info.log" + ).as_posix() + actual_log_filepath = call_args["handlers"]["info_file_handler"]["filename"] assert actual_log_filepath == expected_log_filepath diff --git a/tests/framework/session/test_session_extension_hooks.py b/tests/framework/session/test_session_extension_hooks.py index a2b20a3560..6da3b7d63f 100644 --- a/tests/framework/session/test_session_extension_hooks.py +++ b/tests/framework/session/test_session_extension_hooks.py @@ -29,6 +29,7 @@ ) logger = logging.getLogger("tests.framework.session.conftest") +logger.setLevel(logging.DEBUG) def broken_node(): diff --git a/tests/runner/test_parallel_runner.py b/tests/runner/test_parallel_runner.py index 2513bbcb56..7379b84acd 100644 --- a/tests/runner/test_parallel_runner.py +++ b/tests/runner/test_parallel_runner.py @@ -405,7 +405,8 @@ def test_package_name_provided( node_, catalog, is_async, session_id, package_name=package_name ) mock_run_node.assert_called_once() - mock_logging.assert_called_once_with({}) + # No project-side logging.yml has been provided, so logging should not be re-configured. + mock_logging.assert_not_called() mock_configure_project.assert_called_once_with(package_name) def test_package_name_not_provided( diff --git a/tests/test_cli_logging_setup.py b/tests/test_cli_logging_setup.py deleted file mode 100644 index b1bf184c7d..0000000000 --- a/tests/test_cli_logging_setup.py +++ /dev/null @@ -1,19 +0,0 @@ -"""This module contains unit tests for methods in the Kedro __init__.py -""" - -import logging - -from kedro.config.default_logger import LOGGING_CONFIG - - -def test_cli_logging_setup(): - def to_names(handlers): - return [h.name for h in handlers] - - assert LOGGING_CONFIG is not None - - # Check root logger is set up correctly - root_handler_names = to_names(logging.getLogger().handlers) - all_handlers = ["console", "info_file_handler", "error_file_handler"] - intersection = set(root_handler_names).intersection(all_handlers) - assert len(intersection) == 3