diff --git a/src/taskgraph/decision.py b/src/taskgraph/decision.py index 6a37308b..5398bd70 100644 --- a/src/taskgraph/decision.py +++ b/src/taskgraph/decision.py @@ -74,8 +74,28 @@ def taskgraph_decision(options, parameters=None): * generating a set of artifacts to memorialize the graph * calling TaskCluster APIs to create the graph """ + level = logging.INFO if options.get("verbose"): - logging.root.setLevel(logging.DEBUG) + level = logging.DEBUG + + logging.root.setLevel(level) + # Handlers must have an explicit level set for them to properly filter + # messages from child loggers (such as the optimization log a few lines + # down). + for h in logging.root.handlers: + h.setLevel(level) + + if not os.path.isdir(ARTIFACTS_DIR): + os.mkdir(ARTIFACTS_DIR) + + # optimizations are difficult to debug after the fact, so we always + # log them at DEBUG level, and write the log as a separate artifact + opt_log = logging.getLogger("optimization") + opt_log.setLevel(logging.DEBUG) + opt_handler = logging.FileHandler(ARTIFACTS_DIR / "optimizations.log", mode="w") + if logging.root.handlers: + opt_handler.setFormatter(logging.root.handlers[0].formatter) + opt_log.addHandler(opt_handler) parameters = parameters or ( lambda graph_config: get_decision_parameters(graph_config, options) diff --git a/src/taskgraph/optimize/base.py b/src/taskgraph/optimize/base.py index 917ab82a..f914e71a 100644 --- a/src/taskgraph/optimize/base.py +++ b/src/taskgraph/optimize/base.py @@ -24,7 +24,7 @@ from taskgraph.util.python_path import import_sibling_modules from taskgraph.util.taskcluster import find_task_id_batched, status_task_batched -logger = logging.getLogger(__name__) +logger = logging.getLogger("optimization") registry = {} diff --git a/src/taskgraph/optimize/strategies.py b/src/taskgraph/optimize/strategies.py index 621e28aa..2f436c52 100644 --- a/src/taskgraph/optimize/strategies.py +++ b/src/taskgraph/optimize/strategies.py @@ -5,7 +5,7 @@ from taskgraph.util.path import match as match_path from taskgraph.util.taskcluster import find_task_id, status_task -logger = logging.getLogger(__name__) +logger = logging.getLogger("optimization") @register_strategy("index-search") diff --git a/test/test_optimize_strategies.py b/test/test_optimize_strategies.py index 9cd408c3..2203e984 100644 --- a/test/test_optimize_strategies.py +++ b/test/test_optimize_strategies.py @@ -1,6 +1,7 @@ # Any copyright is dedicated to the public domain. # http://creativecommons.org/publicdomain/zero/1.0/ +import logging import os from datetime import datetime from time import mktime @@ -24,27 +25,37 @@ def params(): @pytest.mark.parametrize( - "state,expires,expected", + "state,expires,expected,logs", ( ( "completed", "2021-06-06T14:53:16.937Z", False, + ( + "not replacing {label} with {taskid} because it expires before {deadline}", + ), ), - ("completed", "2021-06-08T14:53:16.937Z", "abc"), + ("completed", "2021-06-08T14:53:16.937Z", "abc", ()), ( "exception", "2021-06-08T14:53:16.937Z", False, + ( + "not replacing {label} with {taskid} because it is in failed or exception state", + ), ), ( "failed", "2021-06-08T14:53:16.937Z", False, + ( + "not replacing {label} with {taskid} because it is in failed or exception state", + ), ), ), ) -def test_index_search(responses, params, state, expires, expected): +def test_index_search(caplog, responses, params, state, expires, expected, logs): + caplog.set_level(logging.DEBUG, "optimization") taskid = "abc" index_path = "foo.bar.latest" @@ -79,13 +90,27 @@ def test_index_search(responses, params, state, expires, expected): deadline = "2021-06-07T19:03:20.482Z" assert ( opt.should_replace_task( - {}, params, deadline, ([index_path], label_to_taskid, taskid_to_status) + {"label": "task-label"}, + params, + deadline, + ([index_path], label_to_taskid, taskid_to_status), ) == expected ) # test the non-batched variant as well assert opt.should_replace_task({}, params, deadline, [index_path]) == expected + if logs: + log_records = [ + ( + "optimization", + logging.DEBUG, + m.format(label="task-label", taskid=taskid, deadline=deadline), + ) + for m in logs + ] + assert caplog.record_tuples == log_records + @pytest.mark.parametrize( "params,file_patterns,should_optimize", @@ -111,8 +136,18 @@ def test_index_search(responses, params, state, expires, expected): ), ), ) -def test_skip_unless_changed(params, file_patterns, should_optimize): +def test_skip_unless_changed(caplog, params, file_patterns, should_optimize): + caplog.set_level(logging.DEBUG, "optimization") task = make_task("task") opt = SkipUnlessChanged() assert opt.should_remove_task(task, params, file_patterns) == should_optimize + + if should_optimize: + assert caplog.record_tuples == [ + ( + "optimization", + logging.DEBUG, + f'no files found matching a pattern in `skip-unless-changed` for "{task.label}"', + ), + ]