From ca56dd06a38f499feffcbc85314c0c3fec1d6cc6 Mon Sep 17 00:00:00 2001 From: Mohamed Belhsan Hmida Date: Wed, 16 Sep 2026 00:37:45 +0100 Subject: [PATCH 1/3] Log one line when the CLI rejects an option value A reporting cron job stopped producing data, and the log file the wrapper script writes held no trace of why. The command had a stray --start, which swallowed the option that followed it as its value, and Click rejected that as a datetime. Click reports such errors on stderr alone, while the script redirected only stdout, so nothing was recorded. FlexMeasures configures a rotating file handler of its own, but an invocation that fails while parsing its options never reaches any code that logs, so that file stays silent too. The same goes for latest_task_runs, which is filled by a decorator around the command body. Add LoggedClickExceptionCommand, which logs one ERROR line naming the command and the message Click would print, and re-raises so that Click's own output and its exit code are unchanged. One line, rather than the usage block, keeps a repeatedly failing cron job from filling the log. Applied to `flexmeasures add report` for now, which is the command this was found on. Signed-off-by: Mohamed Belhsan Hmida --- flexmeasures/cli/data_add.py | 3 +- .../cli/tests/test_data_add_fresh_db.py | 16 ++++++++++ flexmeasures/cli/utils.py | 31 +++++++++++++++++++ 3 files changed, 49 insertions(+), 1 deletion(-) diff --git a/flexmeasures/cli/data_add.py b/flexmeasures/cli/data_add.py index bd832d70e6..314b715f00 100755 --- a/flexmeasures/cli/data_add.py +++ b/flexmeasures/cli/data_add.py @@ -43,6 +43,7 @@ MsgStyle, DeprecatedOption, DeprecatedOptionsCommand, + LoggedClickExceptionCommand, add_cli_options_from_schema, split_commas, ) @@ -2096,7 +2097,7 @@ def add_schedule( # noqa C901 ) -@fm_add_data.command("report") +@fm_add_data.command("report", cls=LoggedClickExceptionCommand) @with_appcontext @click.option( "--config", diff --git a/flexmeasures/cli/tests/test_data_add_fresh_db.py b/flexmeasures/cli/tests/test_data_add_fresh_db.py index 65d2c2b615..b48e02fc84 100644 --- a/flexmeasures/cli/tests/test_data_add_fresh_db.py +++ b/flexmeasures/cli/tests/test_data_add_fresh_db.py @@ -188,6 +188,22 @@ def test_add_forecast_rejects_config_with_existing_source( ) +def test_add_report_logs_click_error_for_invalid_start(app, caplog): + """A Click parameter error is logged once, without the full usage text.""" + runner = app.test_cli_runner() + + with caplog.at_level(logging.ERROR): + result = runner.invoke(args=["add", "report", "--start", ""]) + + assert result.exit_code == 2 + assert "Error: Invalid value for '--start': Not a valid datetime." in result.output + assert ( + "Click error in `flexmeasures add report`: Invalid value for '--start': " + "Not a valid datetime." in caplog.text + ) + assert "Usage: flexmeasures add report [OPTIONS]" not in caplog.text + + def test_add_reporter(app, fresh_db, setup_dummy_data, caplog): """ The reporter aggregates input data from two sensors (both have 200 data points) diff --git a/flexmeasures/cli/utils.py b/flexmeasures/cli/utils.py index ad02f1d680..0aa5d292fa 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 @@ -121,6 +122,36 @@ def process(value, state): return parser +class LoggedClickExceptionCommand(click.Command): + """A command that logs Click usage errors before Click reports them.""" + + def _log_click_exception(self, ctx: click.Context, exc: click.ClickException): + from flask import current_app, has_app_context + + logger = ( + current_app.logger if has_app_context() else logging.getLogger(__name__) + ) + logger.error( + "Click error in `%s`: %s", + 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) + except click.ClickException as exc: + self._log_click_exception(ctx, exc) + raise + + def invoke(self, ctx: click.Context): + try: + return super().invoke(ctx) + except click.ClickException as exc: + self._log_click_exception(ctx, exc) + raise + + class DeprecatedDefaultGroup(DefaultGroup): """Invokes a default subcommand, *and* shows a deprecation message. From 55e89c692ec11982ef2a0bbed69210deef6baf06 Mon Sep 17 00:00:00 2001 From: Mohamed Belhsan Hmida Date: Wed, 16 Sep 2026 00:51:09 +0100 Subject: [PATCH 2/3] Add changelog entry for the CLI option-error log line Signed-off-by: Mohamed Belhsan Hmida --- documentation/changelog.rst | 1 + 1 file changed, 1 insertion(+) diff --git a/documentation/changelog.rst b/documentation/changelog.rst index d3ff854686..8364bacdfb 100644 --- a/documentation/changelog.rst +++ b/documentation/changelog.rst @@ -34,6 +34,7 @@ Infrastructure / Support * Train and predict a forecaster's per-horizon models side by side rather than one after another, which cuts the training time of a long forecast horizon several-fold while leaving the forecasts themselves unchanged [see `PR #2479 `_] * 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 `_] Bugfixes ----------- From 3456e18aa665e488d933016e9160fe975267b1d7 Mon Sep 17 00:00:00 2001 From: Mohamed Belhsan Hmida Date: Wed, 16 Sep 2026 14:16:53 +0100 Subject: [PATCH 3/3] Log a Click error from every CLI group, not just from `add report` `add forecasts`, `add schedule` and `jobs run-automations` are run from cron just as `add report` is, and a per-command `cls` would leave each new command to remember to opt in. Put the logging on the group instead. A command's error passes through its group on the way out, so one class on each of the seven groups covers every command in them, including the ones that pass a `cls` of their own, and it picks up the group's own errors too, such as an unknown subcommand. The context Click attaches to the error names the command that failed, which is what the line reports, so a command's error is still reported against the command rather than against its group. Each exception is logged by the first handler to see it and skipped by the rest, so a failure is logged once. Signed-off-by: Mohamed Belhsan Hmida --- flexmeasures/cli/data_add.py | 6 +- flexmeasures/cli/data_delete.py | 3 +- flexmeasures/cli/data_edit.py | 3 +- flexmeasures/cli/data_show.py | 3 +- flexmeasures/cli/db_ops.py | 4 +- flexmeasures/cli/jobs.py | 4 +- flexmeasures/cli/monitor.py | 4 +- .../cli/tests/test_data_add_fresh_db.py | 16 --- flexmeasures/cli/tests/test_utils.py | 98 ++++++++++++++++++- flexmeasures/cli/utils.py | 82 ++++++++++------ 10 files changed, 164 insertions(+), 59 deletions(-) diff --git a/flexmeasures/cli/data_add.py b/flexmeasures/cli/data_add.py index 550e3d03c5..0c064fecbf 100755 --- a/flexmeasures/cli/data_add.py +++ b/flexmeasures/cli/data_add.py @@ -43,7 +43,7 @@ MsgStyle, DeprecatedOption, DeprecatedOptionsCommand, - LoggedClickExceptionCommand, + LoggedClickExceptionGroup, add_cli_options_from_schema, split_commas, ) @@ -139,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.""" @@ -2124,7 +2124,7 @@ def add_schedule( # noqa C901 ) -@fm_add_data.command("report", cls=LoggedClickExceptionCommand) +@fm_add_data.command("report") @with_appcontext @click.option( "--config", 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_data_add_fresh_db.py b/flexmeasures/cli/tests/test_data_add_fresh_db.py index b48e02fc84..65d2c2b615 100644 --- a/flexmeasures/cli/tests/test_data_add_fresh_db.py +++ b/flexmeasures/cli/tests/test_data_add_fresh_db.py @@ -188,22 +188,6 @@ def test_add_forecast_rejects_config_with_existing_source( ) -def test_add_report_logs_click_error_for_invalid_start(app, caplog): - """A Click parameter error is logged once, without the full usage text.""" - runner = app.test_cli_runner() - - with caplog.at_level(logging.ERROR): - result = runner.invoke(args=["add", "report", "--start", ""]) - - assert result.exit_code == 2 - assert "Error: Invalid value for '--start': Not a valid datetime." in result.output - assert ( - "Click error in `flexmeasures add report`: Invalid value for '--start': " - "Not a valid datetime." in caplog.text - ) - assert "Usage: flexmeasures add report [OPTIONS]" not in caplog.text - - def test_add_reporter(app, fresh_db, setup_dummy_data, caplog): """ The reporter aggregates input data from two sensors (both have 200 data points) 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 0aa5d292fa..982985373c 100644 --- a/flexmeasures/cli/utils.py +++ b/flexmeasures/cli/utils.py @@ -40,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. @@ -122,36 +174,6 @@ def process(value, state): return parser -class LoggedClickExceptionCommand(click.Command): - """A command that logs Click usage errors before Click reports them.""" - - def _log_click_exception(self, ctx: click.Context, exc: click.ClickException): - from flask import current_app, has_app_context - - logger = ( - current_app.logger if has_app_context() else logging.getLogger(__name__) - ) - logger.error( - "Click error in `%s`: %s", - 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) - except click.ClickException as exc: - self._log_click_exception(ctx, exc) - raise - - def invoke(self, ctx: click.Context): - try: - return super().invoke(ctx) - except click.ClickException as exc: - self._log_click_exception(ctx, exc) - raise - - class DeprecatedDefaultGroup(DefaultGroup): """Invokes a default subcommand, *and* shows a deprecation message.