Log one line when the CLI rejects an option value

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 <https://www.github.com/FlexMeasures/flexmeasures/pull/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 <https://www.github.com/FlexMeasures/flexmeasures/pull/2435>`_]
 * Add ``FLEXMEASURES_DEPRECATION_AND_SUNSET`` so hosts can configure deprecation and sunset dates and information links per deprecated API version [see `PR #2362 <https://github.com/FlexMeasures/flexmeasures/pull/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 <https://www.github.com/FlexMeasures/flexmeasures/pull/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 <https://www.github.com/FlexMeasures/flexmeasures/pull/2501>`_]
 
 Bugfixes

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."""
 

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."""
 

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."""
 

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."""
 

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."""
 

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."""
 

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."""
 

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

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.