From 78fc70ecc746fc70926d27737bdd7e34ca7bff48 Mon Sep 17 00:00:00 2001 From: Omry Yadan Date: Sat, 22 Aug 2020 09:51:59 -0700 Subject: [PATCH] Fix to flush logging instead of shutting it down at job end --- hydra/_internal/hydra.py | 7 ++- hydra/core/utils.py | 15 ++++-- hydra/experimental/compose.py | 1 + hydra/extra/pytest_plugin.py | 6 +++ hydra/test_utils/test_utils.py | 24 +++++++--- news/833.bugfix.1 | 1 + news/833.bugfix.2 | 1 + noxfile.py | 52 ++++++++++----------- tests/jupyter/%run_test.ipynb | 8 ++-- tests/test_examples/test_patterns.py | 1 + tests/test_examples/test_tutorials_basic.py | 1 + tests/test_hydra.py | 31 ++++++++++-- 12 files changed, 102 insertions(+), 46 deletions(-) create mode 100644 news/833.bugfix.1 create mode 100644 news/833.bugfix.2 diff --git a/hydra/_internal/hydra.py b/hydra/_internal/hydra.py index 76af35fac8d..6dd67be511e 100644 --- a/hydra/_internal/hydra.py +++ b/hydra/_internal/hydra.py @@ -95,11 +95,12 @@ def run( config_name: Optional[str], task_function: TaskFunction, overrides: List[str], + with_log_configuration: bool = True, ) -> JobReturn: cfg = self.compose_config( config_name=config_name, overrides=overrides, - with_log_configuration=True, + with_log_configuration=with_log_configuration, run_mode=RunMode.RUN, ) HydraConfig.instance().set_config(cfg) @@ -108,6 +109,7 @@ def run( task_function=task_function, job_dir_key="hydra.run.dir", job_subdir_key=None, + configure_logging=with_log_configuration, ) def multirun( @@ -115,13 +117,14 @@ def multirun( config_name: Optional[str], task_function: TaskFunction, overrides: List[str], + with_log_configuration: bool = True, ) -> Any: # Initial config is loaded without strict (individual job configs may have strict). cfg = self.compose_config( config_name=config_name, overrides=overrides, strict=False, - with_log_configuration=True, + with_log_configuration=with_log_configuration, run_mode=RunMode.MULTIRUN, ) HydraConfig.instance().set_config(cfg) diff --git a/hydra/core/utils.py b/hydra/core/utils.py index a84227993a4..a979d7e2f47 100644 --- a/hydra/core/utils.py +++ b/hydra/core/utils.py @@ -83,6 +83,7 @@ def run_job( task_function: TaskFunction, job_dir_key: str, job_subdir_key: Optional[str], + configure_logging: bool = True, ) -> "JobReturn": old_cwd = os.getcwd() working_dir = str(OmegaConf.select(config, job_dir_key)) @@ -108,7 +109,8 @@ def run_job( Path(str(working_dir)).mkdir(parents=True, exist_ok=True) os.chdir(working_dir) - configure_log(config.hydra.job_logging, config.hydra.verbose) + if configure_logging: + configure_log(config.hydra.job_logging, config.hydra.verbose) hydra_cfg = OmegaConf.masked_copy(config, "hydra") assert isinstance(hydra_cfg, DictConfig) @@ -123,9 +125,7 @@ def run_job( ret.return_value = task_function(task_cfg) ret.task_name = JobRuntime.instance().get("name") - # shut down logging to ensure job log files are closed. - # If logging is still required after run_job caller is responsible to re-initialize it. - logging.shutdown() + _flush_loggers() return ret finally: @@ -240,3 +240,10 @@ def env_override(env: Dict[str, str]) -> Any: del os.environ[key] else: os.environ[key] = value + + +def _flush_loggers() -> None: + # Python logging does not have an official API to flush all loggers. + # This will have to do. + for h_weak_ref in logging._handlerList: # type: ignore + h_weak_ref().flush() diff --git a/hydra/experimental/compose.py b/hydra/experimental/compose.py index ebbb3dac3c3..ff20b3f8882 100644 --- a/hydra/experimental/compose.py +++ b/hydra/experimental/compose.py @@ -34,6 +34,7 @@ def compose( run_mode=RunMode.RUN, strict=strict, from_shell=False, + with_log_configuration=False, ) assert isinstance(cfg, DictConfig) diff --git a/hydra/extra/pytest_plugin.py b/hydra/extra/pytest_plugin.py index 273ee306493..8e63392c5ea 100644 --- a/hydra/extra/pytest_plugin.py +++ b/hydra/extra/pytest_plugin.py @@ -34,6 +34,7 @@ def hydra_sweep_runner() -> Callable[ Optional[List[str]], Optional[bool], Optional[Path], + bool, ], SweepTaskFunction, ]: @@ -46,6 +47,7 @@ def _( overrides: Optional[List[str]], strict: Optional[bool] = None, temp_dir: Optional[Path] = None, + configure_logging: bool = False, ) -> SweepTaskFunction: sweep = SweepTaskFunction() sweep.calling_file = calling_file @@ -56,6 +58,7 @@ def _( sweep.strict = strict sweep.overrides = overrides or [] sweep.temp_dir = str(temp_dir) + sweep.configure_logging = configure_logging return sweep return _ @@ -70,6 +73,7 @@ def hydra_task_runner() -> Callable[ Optional[str], Optional[List[str]], Optional[bool], + bool, ], TaskTestFunction, ]: @@ -80,6 +84,7 @@ def _( config_name: Optional[str], overrides: Optional[List[str]] = None, strict: Optional[bool] = None, + configure_logging: bool = False, ) -> TaskTestFunction: task = TaskTestFunction() task.overrides = overrides or [] @@ -88,6 +93,7 @@ def _( task.calling_module = calling_module task.config_path = config_path task.strict = strict + task.configure_logging = configure_logging return task return _ diff --git a/hydra/test_utils/test_utils.py b/hydra/test_utils/test_utils.py index fd1282a0bf9..c259787b17c 100644 --- a/hydra/test_utils/test_utils.py +++ b/hydra/test_utils/test_utils.py @@ -50,6 +50,7 @@ def __init__(self) -> None: self.strict: Optional[bool] = None self.hydra: Optional[Hydra] = None self.job_ret: Optional[JobReturn] = None + self.configure_logging: bool = False def __call__(self, cfg: DictConfig) -> Any: """ @@ -78,17 +79,21 @@ def __enter__(self) -> "TaskTestFunction": assert overrides is not None overrides.append(f"hydra.run.dir={self.temp_dir}") self.job_ret = self.hydra.run( - config_name=config_name, task_function=self, overrides=overrides + config_name=config_name, + task_function=self, + overrides=overrides, + with_log_configuration=self.configure_logging, ) return self finally: GlobalHydra().clear() def __exit__(self, exc_type: Any, exc_val: Any, exc_tb: Any) -> None: - # release log file handles - logging.shutdown() + # release log file handles. + if self.configure_logging: + logging.shutdown() assert self.temp_dir is not None - shutil.rmtree(self.temp_dir) + shutil.rmtree(self.temp_dir, ignore_errors=True) class TTaskRunner(Protocol): @@ -100,6 +105,7 @@ def __call__( config_name: Optional[str], overrides: Optional[List[str]] = None, strict: Optional[bool] = None, + configure_logging: bool = False, ) -> TaskTestFunction: ... @@ -123,6 +129,7 @@ def __init__(self) -> None: self.strict: Optional[bool] = None self.sweeps = None self.returns = None + self.configure_logging: bool = False def __call__(self, cfg: DictConfig) -> Any: """ @@ -156,7 +163,10 @@ def __enter__(self) -> "SweepTaskFunction": ) self.returns = hydra_.multirun( - config_name=config_name, task_function=self, overrides=overrides + config_name=config_name, + task_function=self, + overrides=overrides, + with_log_configuration=self.configure_logging, ) finally: GlobalHydra().clear() @@ -164,8 +174,10 @@ def __enter__(self) -> "SweepTaskFunction": return self def __exit__(self, exc_type: Any, exc_val: Any, exc_tb: Any) -> None: + if self.configure_logging: + logging.shutdown() assert self.temp_dir is not None - shutil.rmtree(self.temp_dir) + shutil.rmtree(self.temp_dir, ignore_errors=True) class TSweepRunner(Protocol): diff --git a/news/833.bugfix.1 b/news/833.bugfix.1 new file mode 100644 index 00000000000..2db7dcd02cc --- /dev/null +++ b/news/833.bugfix.1 @@ -0,0 +1 @@ +Fix to flush logging instead of shutting it down at job end diff --git a/news/833.bugfix.2 b/news/833.bugfix.2 new file mode 100644 index 00000000000..d0bbc9e1b0e --- /dev/null +++ b/news/833.bugfix.2 @@ -0,0 +1 @@ +compose() no longer initialized logging subsystem diff --git a/noxfile.py b/noxfile.py index c95386e303e..b172e84bac3 100644 --- a/noxfile.py +++ b/noxfile.py @@ -274,6 +274,30 @@ def lint_plugins(session): session.run("mypy", ".", "--strict", silent=SILENT) +@nox.session(python=PYTHON_VERSIONS) +def test_tools(session): + install_cmd = ["pip", "install"] + _upgrade_basic(session) + session.install("pytest") + install_hydra(session, install_cmd) + + tools = [ + x + for x in sorted(os.listdir(os.path.join(BASE, "tools"))) + if not os.path.isfile(x) + ] + + for tool in tools: + tool_path = os.path.join("tools", tool) + session.chdir(BASE) + cmd = list(install_cmd) + ["-e", tool_path] + session.run(*cmd, silent=SILENT) + + session.run("pytest", tool_path) + + session.chdir(BASE) + + def _get_standalone_apps_dir(): standalone_apps_dir = Path(f"{BASE}/tests/standalone_apps") apps = [standalone_apps_dir / subdir for subdir in os.listdir(standalone_apps_dir)] @@ -395,9 +419,7 @@ def test_jupyter_notebooks(session): session.skip( f"Not testing Jupyter notebook on Python {session.python}, supports [{','.join(versions)}]" ) - # pyzmq 19.0.1 has installation issues on Windows - # pytest 6.0 makes deprecation warnings wail on errors, breaking nbval due to a deprecated API usage - session.install("jupyter", "nbval", "pyzmq==19.0.0", "pytest==5.4.3") + session.install("jupyter", "nbval") install_hydra(session, ["pip", "install", "-e"]) args = pytest_args( "--nbval", "examples/jupyter_notebooks/compose_configs_in_notebook.ipynb", @@ -413,27 +435,3 @@ def test_jupyter_notebooks(session): args = pytest_args("--nbval", str(notebook)) args = [x for x in args if x != "-Werror"] session.run(*args, silent=SILENT) - - -@nox.session(python=PYTHON_VERSIONS) -def test_tools(session): - install_cmd = ["pip", "install"] - _upgrade_basic(session) - session.install("pytest") - install_hydra(session, install_cmd) - - tools = [ - x - for x in sorted(os.listdir(os.path.join(BASE, "tools"))) - if not os.path.isfile(x) - ] - - for tool in tools: - tool_path = os.path.join("tools", tool) - session.chdir(BASE) - cmd = list(install_cmd) + ["-e", tool_path] - session.run(*cmd, silent=SILENT) - - session.run("pytest", tool_path) - - session.chdir(BASE) diff --git a/tests/jupyter/%run_test.ipynb b/tests/jupyter/%run_test.ipynb index 0d542fabf64..8dbd67a9de6 100644 --- a/tests/jupyter/%run_test.ipynb +++ b/tests/jupyter/%run_test.ipynb @@ -49,8 +49,8 @@ ], "source": [ "import tempfile\n", - "with tempfile.TemporaryDirectory() as tmpdir:\n", - " %run ../../examples/tutorials/basic/your_first_hydra_app/6_composition/my_app.py hydra.run.dir=$tmpdir" + "tmpdir = tempfile.mkdtemp()\n", + "%run ../../examples/tutorials/basic/your_first_hydra_app/6_composition/my_app.py hydra.run.dir=$tmpdir" ] } ], @@ -70,9 +70,9 @@ "name": "python", "nbconvert_exporter": "python", "pygments_lexer": "ipython3", - "version": "3.8.2" + "version": "3.8.0" } }, "nbformat": 4, "nbformat_minor": 4 -} \ No newline at end of file +} diff --git a/tests/test_examples/test_patterns.py b/tests/test_examples/test_patterns.py index ad637eb21ce..bb6975b7f92 100644 --- a/tests/test_examples/test_patterns.py +++ b/tests/test_examples/test_patterns.py @@ -25,6 +25,7 @@ def test_specializing_config_example( config_path="conf", config_name="config.yaml", overrides=["dataset=cifar10"], + configure_logging=True, ) as task: assert task.job_ret is not None and task.job_ret.cfg == dict( dataset=dict(name="cifar10", path="/datasets/cifar10"), diff --git a/tests/test_examples/test_tutorials_basic.py b/tests/test_examples/test_tutorials_basic.py index 411350951f1..732569ccbba 100644 --- a/tests/test_examples/test_tutorials_basic.py +++ b/tests/test_examples/test_tutorials_basic.py @@ -198,6 +198,7 @@ def test_composition_config_example( config_path="conf", config_name="config.yaml", overrides=["schema=school"], + configure_logging=True, ) as task: assert task.job_ret is not None assert task.job_ret.cfg == { diff --git a/tests/test_hydra.py b/tests/test_hydra.py index a2ed2555081..c5ad23a6468 100644 --- a/tests/test_hydra.py +++ b/tests/test_hydra.py @@ -3,6 +3,7 @@ import re import subprocess import sys +from logging import getLogger from pathlib import Path from typing import Any, List, Optional, Set @@ -135,6 +136,7 @@ def test_app_without_config__with_append( config_path="", config_name=None, overrides=["+abc=123", "+a.b=1", "+a.a=2"], + configure_logging=True, ) as task: assert task.job_ret is not None and task.job_ret.cfg == dict( abc=123, a=dict(b=1, a=2) @@ -160,6 +162,7 @@ def test_app_with_config_file__no_overrides( calling_module=calling_module, config_path=None, # Testing legacy mode, both path and named are in config_path config_name="config.yaml", + configure_logging=True, ) with task: assert task.job_ret is not None and task.job_ret.cfg == { @@ -227,6 +230,7 @@ def test_app_with_config_path_backward_compatibility( calling_module=calling_module, config_path="conf/config.yaml", # Testing legacy mode, both path and named are in config_path config_name=None, + configure_logging=True, ) with task: assert task.job_ret is not None and task.job_ret.cfg == { @@ -255,6 +259,7 @@ def test_app_with_config_file__with_overide( config_path=None, config_name="config.yaml", overrides=["dataset.path=/datasets/imagenet2"], + configure_logging=True, ) as task: assert task.job_ret is not None and task.job_ret.cfg == dict( dataset=dict(name="imagenet", path="/datasets/imagenet2") @@ -280,6 +285,7 @@ def test_app_with_split_config( calling_module=calling_module, config_path=None, config_name="config.yaml", + configure_logging=True, ) as task: assert task.job_ret is not None and task.job_ret.cfg == dict( dataset=dict(name="imagenet", path="/datasets/imagenet"), @@ -332,6 +338,7 @@ def test_app_with_config_groups__override_all_configs( config_path="conf", config_name=None, overrides=["+optimizer=adam", "optimizer.lr=10"], + configure_logging=True, ) as task: assert task.job_ret is not None and task.job_ret.cfg == dict( optimizer=dict(type="adam", lr=10, beta=0.01) @@ -804,9 +811,9 @@ def test_config_name_and_path_overrides( @pytest.mark.parametrize( # type: ignore "overrides, expected_files", [ - ([], {"my_app.log", ".hydra"}), - (["hydra.output_subdir=foo"], {"my_app.log", "foo"}), - (["hydra.output_subdir=null"], {"my_app.log"}), + ([], {".hydra"}), + (["hydra.output_subdir=foo"], {"foo"}), + (["hydra.output_subdir=null"], set()), ], ) @pytest.mark.parametrize( # type: ignore @@ -1074,3 +1081,21 @@ def test_defaults_pkg_with_dot(monkeypatch: Any, tmpdir: Path) -> None: assert OmegaConf.create(result) == { "dataset": {"test": {"name": "imagenet", "path": "/datasets/imagenet"}} } + + +class TestTaskRunnerLogging: + def test_1( + self, hydra_restore_singletons: Any, hydra_task_runner: TTaskRunner + ) -> None: + with hydra_task_runner( + calling_file=None, + calling_module="tests.test_apps.app_without_config.my_app", + config_path=None, + config_name=None, + ): + logger = getLogger(__name__) + logger.info("test_1") + + def test_2(self) -> None: + logger = getLogger(__name__) + logger.info("test_2")