diff --git a/documentation/changelog.rst b/documentation/changelog.rst index 2eabb94c6b..3ab6dae091 100644 --- a/documentation/changelog.rst +++ b/documentation/changelog.rst @@ -43,6 +43,7 @@ Infrastructure / Support * Speed up ``GET /api/v3_0/assets`` on large catalogs by eager-loading the ``owner``, ``generic_asset_type`` and ``child_assets`` relations alongside the already eager-loaded ``sensors``, instead of lazy-loading each of them once per asset, which made the SQL statement count grow linearly with the number of assets returned [see `PR #2515 `_] * The UI's JavaScript modules can now be tested, by running them in a headless browser from pytest, without adding a Node.js toolchain [see `PR #2435 `_] * Add ``FLEXMEASURES_DEPRECATION_AND_SUNSET`` so hosts can configure deprecation and sunset dates and information links per deprecated API version [see `PR #2362 `_]. +* A CLI command that is called with an invalid option value now logs one error line, so that a cron job which captures only the log file still records why the command failed, where previously Click reported it on stderr alone and nothing was written [see `PR #2544 `_] * Settings that a plugin declares in its ``__settings__`` can now be set as environment variables, next to being set in the config file (which still wins), can declare a ``default`` to fall back to, and are reported as missing with a message that says whether such a default applies or the setting stays unset [see `PR #2501 `_] Bugfixes diff --git a/flexmeasures/cli/data_add.py b/flexmeasures/cli/data_add.py index 4ed0ef0039..0c064fecbf 100755 --- a/flexmeasures/cli/data_add.py +++ b/flexmeasures/cli/data_add.py @@ -43,6 +43,7 @@ MsgStyle, DeprecatedOption, DeprecatedOptionsCommand, + LoggedClickExceptionGroup, add_cli_options_from_schema, split_commas, ) @@ -138,7 +139,7 @@ def _parse_regressor_cli_values(values: tuple | list) -> list: return parsed_values -@click.group("add") +@click.group("add", cls=LoggedClickExceptionGroup) def fm_add_data(): """FlexMeasures: Add data.""" diff --git a/flexmeasures/cli/data_delete.py b/flexmeasures/cli/data_delete.py index 3459f636bd..ac6482e995 100644 --- a/flexmeasures/cli/data_delete.py +++ b/flexmeasures/cli/data_delete.py @@ -35,6 +35,7 @@ from flexmeasures.data.services.users import find_user_by_email, delete_user from flexmeasures.data.services.sensors import delete_sensor as delete_sensor_and_data from flexmeasures.cli.utils import ( + LoggedClickExceptionGroup, abort, done, DeprecatedOption, @@ -75,7 +76,7 @@ def _count_affected_secrets( ) -@click.group("delete") +@click.group("delete", cls=LoggedClickExceptionGroup) def fm_delete_data(): """FlexMeasures: Delete data.""" diff --git a/flexmeasures/cli/data_edit.py b/flexmeasures/cli/data_edit.py index f6dc9892bc..271076c999 100644 --- a/flexmeasures/cli/data_edit.py +++ b/flexmeasures/cli/data_edit.py @@ -30,6 +30,7 @@ from flexmeasures.data.models.time_series import TimedBelief from flexmeasures.data.utils import save_to_db from flexmeasures.cli.utils import ( + LoggedClickExceptionGroup, MsgStyle, DeprecatedOption, DeprecatedOptionsCommand, @@ -56,7 +57,7 @@ def _resolve_secret_path( return secret -@click.group("edit") +@click.group("edit", cls=LoggedClickExceptionGroup) def fm_edit_data(): """FlexMeasures: Edit data.""" diff --git a/flexmeasures/cli/data_show.py b/flexmeasures/cli/data_show.py index 695ac09770..eb7620c076 100644 --- a/flexmeasures/cli/data_show.py +++ b/flexmeasures/cli/data_show.py @@ -37,6 +37,7 @@ server_now, ) from flexmeasures.cli.utils import ( + LoggedClickExceptionGroup, MsgStyle, validate_unique, tabulate_account_assets, @@ -50,7 +51,7 @@ ) -@click.group("show") +@click.group("show", cls=LoggedClickExceptionGroup) def fm_show_data(): """FlexMeasures: Show data.""" diff --git a/flexmeasures/cli/db_ops.py b/flexmeasures/cli/db_ops.py index 21173150ef..c9a15fcde1 100644 --- a/flexmeasures/cli/db_ops.py +++ b/flexmeasures/cli/db_ops.py @@ -8,10 +8,10 @@ import flask_migrate as migrate import click -from flexmeasures.cli.utils import MsgStyle +from flexmeasures.cli.utils import LoggedClickExceptionGroup, MsgStyle -@click.group("db-ops") +@click.group("db-ops", cls=LoggedClickExceptionGroup) def fm_db_ops(): """FlexMeasures: Reset, Dump/Restore or Save/Load the DB data.""" diff --git a/flexmeasures/cli/jobs.py b/flexmeasures/cli/jobs.py index c674267914..8bdb1c4089 100644 --- a/flexmeasures/cli/jobs.py +++ b/flexmeasures/cli/jobs.py @@ -45,7 +45,7 @@ from flexmeasures.data.services.scheduling import handle_scheduling_exception from flexmeasures.data.services.forecasting import handle_forecasting_exception from flexmeasures.utils.job_utils import work_on_rq -from flexmeasures.cli.utils import MsgStyle +from flexmeasures.cli.utils import LoggedClickExceptionGroup, MsgStyle from flexmeasures.utils.flexmeasures_inflection import join_words_into_a_list from flexmeasures.utils.time_utils import server_now from flexmeasures.data.services.utils import failed_job_exc_info, job_status_description @@ -66,7 +66,7 @@ ) -@click.group("jobs") +@click.group("jobs", cls=LoggedClickExceptionGroup) def fm_jobs(): """FlexMeasures: Job queueing.""" diff --git a/flexmeasures/cli/monitor.py b/flexmeasures/cli/monitor.py index 2b521fd97d..2c4edebbe0 100644 --- a/flexmeasures/cli/monitor.py +++ b/flexmeasures/cli/monitor.py @@ -25,10 +25,10 @@ from flexmeasures.data.schemas.account import AccountIdField from flexmeasures.api.common.schemas.users import UserIdField from flexmeasures.utils.time_utils import server_now -from flexmeasures.cli.utils import MsgStyle +from flexmeasures.cli.utils import LoggedClickExceptionGroup, MsgStyle -@click.group("monitor") +@click.group("monitor", cls=LoggedClickExceptionGroup) def fm_monitor(): """FlexMeasures: Monitor tasks.""" diff --git a/flexmeasures/cli/tests/test_utils.py b/flexmeasures/cli/tests/test_utils.py index 250ab93378..a9ce6dcfee 100644 --- a/flexmeasures/cli/tests/test_utils.py +++ b/flexmeasures/cli/tests/test_utils.py @@ -1,3 +1,4 @@ +import logging import sys import pytest import click @@ -6,7 +7,11 @@ from pytz import utc from flexmeasures.cli import is_running as cli_is_running -from flexmeasures.cli.utils import DeprecatedOption, DeprecatedOptionsCommand +from flexmeasures.cli.utils import ( + DeprecatedOption, + DeprecatedOptionsCommand, + LoggedClickExceptionGroup, +) from click.testing import CliRunner @@ -167,3 +172,94 @@ def failing_command(): runner = app.test_cli_runner() runner.invoke(failing_command) + + +@pytest.mark.parametrize( + "args, expected_path, expected_message", + [ + # a plain command, on the group where this was first reported + ( + ["add", "report", "--start", ""], + "flexmeasures add report", + "Invalid value for '--start': Not a valid datetime.", + ), + # a DeprecatedOptionsCommand, which passes its own `cls` and so has to inherit the logging + ( + ["show", "beliefs", "--sensor", "not-an-int"], + "flexmeasures show beliefs", + "Invalid value for '--sensor' / '--sensor-id': Not a valid integer.", + ), + # a command in a third group, to show this is not specific to one of them + ( + ["edit", "attribute", "--asset", "not-an-int"], + "flexmeasures edit attribute", + "Invalid value for '--asset' / '--asset-id': Not a valid integer.", + ), + # the group's own error, rather than one of its commands' + ( + ["jobs", "run-automation-typo"], + "flexmeasures jobs", + "No such command 'run-automation-typo'.", + ), + ], +) +def test_cli_logs_click_error_once(app, caplog, args, expected_path, expected_message): + """A Click error is logged as one line, whichever group it comes from, and Click still reports it itself.""" + runner = app.test_cli_runner() + + with caplog.at_level(logging.ERROR): + result = runner.invoke(args=args) + + assert result.exit_code == 2 + assert f"Click error in `{expected_path}`: {expected_message}" in caplog.text + + # one line per failure, so that a command failing on every cron run does not fill the log + assert caplog.text.count("Click error in") == 1 + + # the usage block belongs on stderr, where Click puts it, and not in the log + assert f"Usage: {expected_path} [OPTIONS]" not in caplog.text + assert "Error: " + expected_message in result.output + + +def test_cli_does_not_log_when_a_command_succeeds(app, caplog): + """Nothing is logged for a command that parses its options fine.""" + runner = app.test_cli_runner() + + with caplog.at_level(logging.ERROR): + result = runner.invoke(args=["add", "report", "--help"]) + + assert result.exit_code == 0 + assert "Click error in" not in caplog.text + + +def test_cli_logs_a_command_body_error_against_that_command(app, caplog): + """An error raised in a command's body, which carries no context of its own, still names the command rather than its group.""" + runner = app.test_cli_runner() + + with caplog.at_level(logging.ERROR): + result = runner.invoke(args=["show", "data-sources", "--show-sensors"]) + + assert result.exit_code == 2 + assert ( + "Click error in `flexmeasures show data-sources`: --show-sensors requires --id." + in caplog.text + ) + assert caplog.text.count("Click error in") == 1 + + +def test_deprecated_options_command_logs_click_errors(caplog): + """A command passing its own `cls` logs too, which is why DeprecatedOptionsCommand inherits the behaviour.""" + + @click.group("group", cls=LoggedClickExceptionGroup) + def group(): + pass + + @group.command("cmd", cls=DeprecatedOptionsCommand) + def cmd(): + raise click.UsageError("something the body objected to") + + with caplog.at_level(logging.ERROR): + result = CliRunner().invoke(group, ["cmd"]) + + assert result.exit_code == 2 + assert "Click error in `group cmd`: something the body objected to" in caplog.text diff --git a/flexmeasures/cli/utils.py b/flexmeasures/cli/utils.py index ad02f1d680..982985373c 100644 --- a/flexmeasures/cli/utils.py +++ b/flexmeasures/cli/utils.py @@ -5,6 +5,7 @@ from __future__ import annotations import ast +import logging from typing import Any from datetime import datetime, timedelta @@ -39,6 +40,58 @@ class MsgStyle(object): ERROR: dict[str, Any] = {"fg": "red"} +class LogsClickExceptions: + """Mixin that logs a Click error before Click reports it on stderr. + + Click writes usage errors to stderr only, so a cron job that captures just the log file records nothing about why a command failed. + A single line goes to the app logger instead, which reaches the handlers the host has configured. + The exception is re-raised untouched, so Click's own output and its exit code are unchanged. + + One line, rather than the usage block Click prints, keeps a command that fails on every run from filling the log. + """ + + def _log_click_exception(self, ctx: click.Context, exc: click.ClickException): + # A command's error passes through its group on the way out, so each exception is logged by the first handler to see it, and skipped by the rest. + if getattr(exc, "_flexmeasures_logged", False): + return + exc._flexmeasures_logged = True # type: ignore[attr-defined] + + from flask import current_app, has_app_context + + logger = ( + current_app.logger if has_app_context() else logging.getLogger(__name__) + ) + # An error raised while resolving a subcommand names that subcommand's context, which is the path worth reporting. + error_ctx = getattr(exc, "ctx", None) or ctx + logger.error( + "Click error in `%s`: %s", + error_ctx.command_path, + exc.format_message(), + ) + + def parse_args(self, ctx: click.Context, args: list[str]) -> list[str]: + try: + return super().parse_args(ctx, args) # type: ignore[misc] + except click.ClickException as exc: + self._log_click_exception(ctx, exc) + raise + + def invoke(self, ctx: click.Context): + try: + return super().invoke(ctx) # type: ignore[misc] + except click.ClickException as exc: + self._log_click_exception(ctx, exc) + raise + + +class LoggedClickExceptionGroup(LogsClickExceptions, click.Group): + """A group whose own errors, and those of every command in it, are logged before Click reports them. + + A command's error passes through its group on the way out, so putting this on the group covers every command in it, + including the ones that pass a ``cls`` of their own, and any group nested inside it. + """ + + class DeprecatedOption(click.Option): """A custom option that can be used to mark an option as deprecated.