From fb69b2c685893086c539d984d7293dac62acd15a Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 8 Nov 2025 16:53:58 +0000 Subject: [PATCH 1/3] Fix PROCRASTINATE_VERBOSE vs PROCRASTINATE_VERBOSITY inconsistency Fixes #1405 The CLI code was using PROCRASTINATE_VERBOSE as the environment variable, while the documentation incorrectly specified PROCRASTINATE_VERBOSITY. Additionally, the documentation claimed to support 3 log levels (warning, info, debug), but the code only supports 2 levels (info at 0, debug at 1+). Changes: - Fixed documentation to use PROCRASTINATE_VERBOSE (matching the code) - Command line flags (-v, -vv) now properly override environment variables instead of adding to them - Added new --log-level option (mutually exclusive with -v) that allows explicit control over all log levels: debug, info, warning, error, critical - Added PROCRASTINATE_LOG_LEVEL environment variable support - Updated documentation to reflect actual behavior and document new options - Updated help text to clearly show verbosity levels: 0=info, 1+=debug - Added comprehensive tests to verify: * PROCRASTINATE_VERBOSE environment variable works correctly * Command line flags override (not add to) environment variables * --log-level option works with all log levels * --log-level and -v are mutually exclusive * PROCRASTINATE_LOG_LEVEL environment variable works correctly All existing tests pass, and new tests confirm all functionality works as expected. --- docs/howto/basics/command_line.md | 35 +++++--- procrastinate/cli.py | 76 +++++++++++++---- tests/unit/test_cli.py | 132 ++++++++++++++++++++++++++++++ 3 files changed, 219 insertions(+), 24 deletions(-) diff --git a/docs/howto/basics/command_line.md b/docs/howto/basics/command_line.md index 0c345146d..fe1143309 100644 --- a/docs/howto/basics/command_line.md +++ b/docs/howto/basics/command_line.md @@ -56,21 +56,36 @@ In both case, the app you specify must have an asynchronous connector. ## Logging -Three different options allow you to control how the command-line tool should log -events: +Several options allow you to control how the command-line tool should log events: -- Verbosity controls the log level (you'll see message of this level and above): +- **Verbosity** controls the log level (you'll see messages of this level and above): - | Flags | Environment equivalent | Log level | - | ----- | ------------------------- | --------- | - | | PROCRASTINATE_VERBOSITY=0 | `warning` | - | -v | PROCRASTINATE_VERBOSITY=1 | `info` | - | -vv | PROCRASTINATE_VERBOSITY=2 | `debug` | + | Flags | Environment equivalent | Log level | + | -------------- | ----------------------- | --------- | + | | PROCRASTINATE_VERBOSE=0 | `info` | + | -v (or higher) | PROCRASTINATE_VERBOSE=1 | `debug` | -- Log format: `--log-format=` / `PROCRASTINATE_LOG_FORMAT=` lets you control how + Note: Values beyond 1 have no additional effect. + +- **Log level** allows explicit control over the logging level (mutually exclusive with `-v`): + + `--log-level=LEVEL` / `PROCRASTINATE_LOG_LEVEL=LEVEL` where `LEVEL` is one of: + `debug`, `info`, `warning`, `error`, or `critical`. + + This option provides access to log levels not available through `-v` flags, + such as `warning`, `error`, and `critical`. You cannot use `--log-level` and + `-v` together. + + Examples: + ```console + $ procrastinate --log-level=warning worker + $ PROCRASTINATE_LOG_LEVEL=error procrastinate worker + ``` + +- **Log format**: `--log-format=` / `PROCRASTINATE_LOG_FORMAT=` lets you control how the log line will be formatted. It uses `%`-style placeholders by default. -- Log format style: `--log-format-style=` / `PROCRASTINATE_LOG_FORMAT_STYLE=` +- **Log format style**: `--log-format-style=` / `PROCRASTINATE_LOG_FORMAT_STYLE=` lets you choose different styles for the log-format, such as `{` or `$`. For more information on log formats, refer to the [Python documentation](https://docs.python.org/3/library/logging.html?highlight=logging#logrecord-attributes) diff --git a/procrastinate/cli.py b/procrastinate/cli.py index 7fb43364f..6ac4049a2 100644 --- a/procrastinate/cli.py +++ b/procrastinate/cli.py @@ -31,8 +31,19 @@ def get_log_level(verbosity: int) -> int: Style = Union[Literal["%"], Literal["{"], Literal["$"]] -def configure_logging(verbosity: int, format: str, style: Style) -> None: - level = get_log_level(verbosity=verbosity) +def configure_logging( + verbosity: int | None = None, + log_level: str | None = None, + format: str = logging.BASIC_FORMAT, + style: Style = "%", +) -> None: + if log_level is not None: + level = getattr(logging, log_level.upper()) + elif verbosity is not None: + level = get_log_level(verbosity=verbosity) + else: + level = logging.INFO + logging.basicConfig(level=level, format=format, style=style) level_name = logging.getLevelName(level) logger.debug( @@ -176,18 +187,24 @@ def add_cli_features(parser: argparse.ArgumentParser): Add features to the parser to make it more CLI-friendly. This is not necessary when the parser is used as a subparser. """ - add_argument( - parser, + log_group = parser.add_argument_group("Logging") + + # Create mutually exclusive group for verbosity control + verbosity_group = log_group.add_mutually_exclusive_group() + verbosity_group.add_argument( "-v", "--verbose", default=0, action="count", - help="Use multiple times to increase verbosity", - envvar="VERBOSE", - envvar_help="set to desired verbosity level", - envvar_type=int, + help="Increase verbosity (0=info, 1+=debug) " + f"(env: {ENV_PREFIX}_VERBOSE)", + ) + verbosity_group.add_argument( + "--log-level", + choices=["debug", "info", "warning", "error", "critical"], + help="Set log level explicitly " + f"(env: {ENV_PREFIX}_LOG_LEVEL)", ) - log_group = parser.add_argument_group("Logging") add_argument( log_group, "--log-format", @@ -517,11 +534,42 @@ async def cli(args): add_cli_features(parser) parsed = vars(parser.parse_args(args)) - configure_logging( - verbosity=parsed.pop("verbose"), - format=parsed.pop("log_format"), - style=parsed.pop("log_format_style"), - ) + # Determine log level from either --log-level or --verbose (mutually exclusive) + log_level = parsed.pop("log_level", None) + verbosity = parsed.pop("verbose") + + # If --log-level was not specified on command line, check environment variable + if log_level is None: + log_level_env = os.environ.get(f"{ENV_PREFIX}_LOG_LEVEL") + if log_level_env and log_level_env.lower() in [ + "debug", + "info", + "warning", + "error", + "critical", + ]: + log_level = log_level_env.lower() + + # If --log-level is set (from CLI or env), use it; otherwise use --verbose + if log_level is not None: + configure_logging( + log_level=log_level, + format=parsed.pop("log_format"), + style=parsed.pop("log_format_style"), + ) + else: + # If no -v flags were used on command line, check environment variable + if verbosity == 0: + verbose_value = os.environ.get(f"{ENV_PREFIX}_VERBOSE") + if verbose_value and verbose_value != "": + verbosity = int(verbose_value) + + configure_logging( + verbosity=verbosity, + format=parsed.pop("log_format"), + style=parsed.pop("log_format_style"), + ) + await execute_command(parsed) diff --git a/tests/unit/test_cli.py b/tests/unit/test_cli.py index 38a03a314..c322d2ac2 100644 --- a/tests/unit/test_cli.py +++ b/tests/unit/test_cli.py @@ -34,6 +34,138 @@ def test_configure_logging(mocker, caplog): assert records[0].value == "DEBUG" +@pytest.mark.parametrize( + "log_level_name, expected_level", + [ + ("debug", logging.DEBUG), + ("info", logging.INFO), + ("warning", logging.WARNING), + ("error", logging.ERROR), + ("critical", logging.CRITICAL), + ], +) +def test_configure_logging_with_log_level(mocker, caplog, log_level_name, expected_level): + config = mocker.patch("logging.basicConfig") + + caplog.set_level("DEBUG") + + cli.configure_logging(log_level=log_level_name) + + config.assert_called_once_with( + level=expected_level, format=logging.BASIC_FORMAT, style="%" + ) + records = [record for record in caplog.records if record.action == "set_log_level"] + assert len(records) == 1 + assert records[0].value == logging.getLevelName(expected_level) + + +@pytest.mark.parametrize( + "verbose_env, cli_flags, expected", + [ + (None, [], 0), # Default is 0 + ("1", [], 1), # PROCRASTINATE_VERBOSE works + ("0", ["-v"], 1), # CLI flag overrides env=0 + ("2", ["-v"], 1), # CLI flag overrides env=2 + (None, ["-v"], 1), # -v gives verbosity 1 + (None, ["-vv"], 2), # -vv gives verbosity 2 (clamped to debug in get_log_level) + ], +) +async def test_verbose_env_vars( + monkeypatch, mocker, verbose_env, cli_flags, expected +): + """Test that PROCRASTINATE_VERBOSE works and command line flags override environment variables.""" + # Clear any existing values + monkeypatch.delenv("PROCRASTINATE_VERBOSE", raising=False) + + # Set the env var if provided + if verbose_env is not None: + monkeypatch.setenv("PROCRASTINATE_VERBOSE", verbose_env) + + # Mock execute_command to capture the verbosity value + captured_verbosity = None + + async def mock_execute_command(parsed): + # Don't actually execute, just return + pass + + original_configure_logging = cli.configure_logging + + def mock_configure_logging(**kwargs): + nonlocal captured_verbosity + captured_verbosity = kwargs.get("verbosity") + # Call original to ensure it works + original_configure_logging(**kwargs) + + mocker.patch("procrastinate.cli.execute_command", side_effect=mock_execute_command) + mocker.patch("procrastinate.cli.configure_logging", side_effect=mock_configure_logging) + + # Run cli with the provided flags + args = cli_flags + ["--app=", "defer", "test"] + await cli.cli(args) + + assert captured_verbosity == expected + + +@pytest.mark.parametrize( + "log_level_env, cli_flags, expected_level", + [ + (None, ["--log-level", "warning"], "warning"), # CLI --log-level works + (None, ["--log-level", "error"], "error"), # CLI --log-level=error works + (None, ["--log-level", "critical"], "critical"), # CLI --log-level=critical works + ("warning", [], "warning"), # PROCRASTINATE_LOG_LEVEL works + ("error", [], "error"), # PROCRASTINATE_LOG_LEVEL=error works + ("warning", ["--log-level", "error"], "error"), # CLI overrides env + ], +) +async def test_log_level_option( + monkeypatch, mocker, log_level_env, cli_flags, expected_level +): + """Test that --log-level and PROCRASTINATE_LOG_LEVEL work correctly.""" + # Clear any existing values + monkeypatch.delenv("PROCRASTINATE_LOG_LEVEL", raising=False) + monkeypatch.delenv("PROCRASTINATE_VERBOSE", raising=False) + + # Set the env var if provided + if log_level_env is not None: + monkeypatch.setenv("PROCRASTINATE_LOG_LEVEL", log_level_env) + + # Mock execute_command to capture the log level + captured_log_level = None + + async def mock_execute_command(parsed): + pass + + original_configure_logging = cli.configure_logging + + def mock_configure_logging(**kwargs): + nonlocal captured_log_level + captured_log_level = kwargs.get("log_level") + original_configure_logging(**kwargs) + + mocker.patch("procrastinate.cli.execute_command", side_effect=mock_execute_command) + mocker.patch("procrastinate.cli.configure_logging", side_effect=mock_configure_logging) + + # Run cli with the provided flags + args = cli_flags + ["--app=", "defer", "test"] + await cli.cli(args) + + assert captured_log_level == expected_level + + +async def test_log_level_and_verbose_mutually_exclusive(monkeypatch): + """Test that --log-level and --verbose are mutually exclusive.""" + monkeypatch.delenv("PROCRASTINATE_LOG_LEVEL", raising=False) + monkeypatch.delenv("PROCRASTINATE_VERBOSE", raising=False) + + parser = cli.create_parser() + cli.add_arguments(parser) + cli.add_cli_features(parser) + + # This should raise an error because they're mutually exclusive + with pytest.raises(SystemExit): + parser.parse_args(["--app=", "-v", "--log-level", "warning", "defer", "test"]) + + def test_main(mocker): mock = mocker.patch("procrastinate.cli.cli", new=mocker.AsyncMock()) cli.main() From da390e3343baee931b6105c404c8d14963363d69 Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Sat, 8 Nov 2025 18:58:48 +0000 Subject: [PATCH 2/3] [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci --- procrastinate/cli.py | 6 ++---- tests/unit/test_cli.py | 48 ++++++++++++++++++++++++------------------ 2 files changed, 30 insertions(+), 24 deletions(-) diff --git a/procrastinate/cli.py b/procrastinate/cli.py index 6ac4049a2..8fff5cb8e 100644 --- a/procrastinate/cli.py +++ b/procrastinate/cli.py @@ -196,14 +196,12 @@ def add_cli_features(parser: argparse.ArgumentParser): "--verbose", default=0, action="count", - help="Increase verbosity (0=info, 1+=debug) " - f"(env: {ENV_PREFIX}_VERBOSE)", + help=f"Increase verbosity (0=info, 1+=debug) (env: {ENV_PREFIX}_VERBOSE)", ) verbosity_group.add_argument( "--log-level", choices=["debug", "info", "warning", "error", "critical"], - help="Set log level explicitly " - f"(env: {ENV_PREFIX}_LOG_LEVEL)", + help=f"Set log level explicitly (env: {ENV_PREFIX}_LOG_LEVEL)", ) add_argument( log_group, diff --git a/tests/unit/test_cli.py b/tests/unit/test_cli.py index c322d2ac2..933cb426a 100644 --- a/tests/unit/test_cli.py +++ b/tests/unit/test_cli.py @@ -44,7 +44,9 @@ def test_configure_logging(mocker, caplog): ("critical", logging.CRITICAL), ], ) -def test_configure_logging_with_log_level(mocker, caplog, log_level_name, expected_level): +def test_configure_logging_with_log_level( + mocker, caplog, log_level_name, expected_level +): config = mocker.patch("logging.basicConfig") caplog.set_level("DEBUG") @@ -62,17 +64,15 @@ def test_configure_logging_with_log_level(mocker, caplog, log_level_name, expect @pytest.mark.parametrize( "verbose_env, cli_flags, expected", [ - (None, [], 0), # Default is 0 - ("1", [], 1), # PROCRASTINATE_VERBOSE works - ("0", ["-v"], 1), # CLI flag overrides env=0 - ("2", ["-v"], 1), # CLI flag overrides env=2 - (None, ["-v"], 1), # -v gives verbosity 1 - (None, ["-vv"], 2), # -vv gives verbosity 2 (clamped to debug in get_log_level) + (None, [], 0), # Default is 0 + ("1", [], 1), # PROCRASTINATE_VERBOSE works + ("0", ["-v"], 1), # CLI flag overrides env=0 + ("2", ["-v"], 1), # CLI flag overrides env=2 + (None, ["-v"], 1), # -v gives verbosity 1 + (None, ["-vv"], 2), # -vv gives verbosity 2 (clamped to debug in get_log_level) ], ) -async def test_verbose_env_vars( - monkeypatch, mocker, verbose_env, cli_flags, expected -): +async def test_verbose_env_vars(monkeypatch, mocker, verbose_env, cli_flags, expected): """Test that PROCRASTINATE_VERBOSE works and command line flags override environment variables.""" # Clear any existing values monkeypatch.delenv("PROCRASTINATE_VERBOSE", raising=False) @@ -97,10 +97,12 @@ def mock_configure_logging(**kwargs): original_configure_logging(**kwargs) mocker.patch("procrastinate.cli.execute_command", side_effect=mock_execute_command) - mocker.patch("procrastinate.cli.configure_logging", side_effect=mock_configure_logging) + mocker.patch( + "procrastinate.cli.configure_logging", side_effect=mock_configure_logging + ) # Run cli with the provided flags - args = cli_flags + ["--app=", "defer", "test"] + args = [*cli_flags, "--app=", "defer", "test"] await cli.cli(args) assert captured_verbosity == expected @@ -109,12 +111,16 @@ def mock_configure_logging(**kwargs): @pytest.mark.parametrize( "log_level_env, cli_flags, expected_level", [ - (None, ["--log-level", "warning"], "warning"), # CLI --log-level works - (None, ["--log-level", "error"], "error"), # CLI --log-level=error works - (None, ["--log-level", "critical"], "critical"), # CLI --log-level=critical works - ("warning", [], "warning"), # PROCRASTINATE_LOG_LEVEL works - ("error", [], "error"), # PROCRASTINATE_LOG_LEVEL=error works - ("warning", ["--log-level", "error"], "error"), # CLI overrides env + (None, ["--log-level", "warning"], "warning"), # CLI --log-level works + (None, ["--log-level", "error"], "error"), # CLI --log-level=error works + ( + None, + ["--log-level", "critical"], + "critical", + ), # CLI --log-level=critical works + ("warning", [], "warning"), # PROCRASTINATE_LOG_LEVEL works + ("error", [], "error"), # PROCRASTINATE_LOG_LEVEL=error works + ("warning", ["--log-level", "error"], "error"), # CLI overrides env ], ) async def test_log_level_option( @@ -143,10 +149,12 @@ def mock_configure_logging(**kwargs): original_configure_logging(**kwargs) mocker.patch("procrastinate.cli.execute_command", side_effect=mock_execute_command) - mocker.patch("procrastinate.cli.configure_logging", side_effect=mock_configure_logging) + mocker.patch( + "procrastinate.cli.configure_logging", side_effect=mock_configure_logging + ) # Run cli with the provided flags - args = cli_flags + ["--app=", "defer", "test"] + args = [*cli_flags, "--app=", "defer", "test"] await cli.cli(args) assert captured_log_level == expected_level From ffe0ebb45aab5ad1dbddc351399695ba937e0a64 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 8 Nov 2025 19:08:46 +0000 Subject: [PATCH 3/3] Add test for default log level when no options are set Verifies that when configure_logging() is called with no arguments (no verbosity or log_level specified), it defaults to logging.INFO level. --- tests/unit/test_cli.py | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/tests/unit/test_cli.py b/tests/unit/test_cli.py index 933cb426a..5ec5d88e1 100644 --- a/tests/unit/test_cli.py +++ b/tests/unit/test_cli.py @@ -61,6 +61,22 @@ def test_configure_logging_with_log_level( assert records[0].value == logging.getLevelName(expected_level) +def test_configure_logging_default_level(mocker, caplog): + """Test that when no verbosity or log_level is set, default is INFO.""" + config = mocker.patch("logging.basicConfig") + + caplog.set_level("DEBUG") + + cli.configure_logging() + + config.assert_called_once_with( + level=logging.INFO, format=logging.BASIC_FORMAT, style="%" + ) + records = [record for record in caplog.records if record.action == "set_log_level"] + assert len(records) == 1 + assert records[0].value == "INFO" + + @pytest.mark.parametrize( "verbose_env, cli_flags, expected", [