From 2bf65849a94bb6807e1bcee5294615a10f112b38 Mon Sep 17 00:00:00 2001 From: Muhammad Humza Arain Date: Thu, 29 Jan 2026 00:19:27 +0000 Subject: [PATCH 1/5] Fixed Verbosity issue --- docs/howto/basics/command_line.md | 38 +++++-- procrastinate/cli.py | 46 ++++++-- tests/unit/test_cli.py | 169 ++++++++++++++++++++++++++++++ 3 files changed, 236 insertions(+), 17 deletions(-) diff --git a/docs/howto/basics/command_line.md b/docs/howto/basics/command_line.md index 0c345146d..f1b7d6d58 100644 --- a/docs/howto/basics/command_line.md +++ b/docs/howto/basics/command_line.md @@ -56,21 +56,39 @@ 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. When both environment variable + and CLI flag are used, the flag value is added to the environment variable value + (e.g., `PROCRASTINATE_VERBOSE=1` with `-v` results in verbosity=2, which gives `debug`). + +- **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 b047d5641..0fa332a50 100644 --- a/procrastinate/cli.py +++ b/procrastinate/cli.py @@ -31,8 +31,21 @@ def get_log_level(verbosity: int) -> int: Style = 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: + # Determine which level to use + # log_level takes precedence over verbosity + 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 # Default if neither provided + logging.basicConfig(level=level, format=format, style=style) level_name = logging.getLevelName(level) logger.debug( @@ -176,18 +189,34 @@ 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. """ + log_group = parser.add_argument_group("Logging") + + # Create mutually exclusive group for verbosity control + verbosity_group = log_group.add_mutually_exclusive_group() + + # Use add_argument helper for consistent env var handling add_argument( - parser, + verbosity_group, "-v", "--verbose", default=0, action="count", - help="Use multiple times to increase verbosity", + help="Increase verbosity (0=info, 1+=debug)", envvar="VERBOSE", - envvar_help="set to desired verbosity level", + envvar_help="set to desired verbosity level (0=info, 1+=debug)", envvar_type=int, ) - log_group = parser.add_argument_group("Logging") + + # Use add_argument helper for --log-level too + add_argument( + verbosity_group, + "--log-level", + choices=["debug", "info", "warning", "error", "critical"], + help="Set log level explicitly", + envvar="LOG_LEVEL", + envvar_help="set to desired log level", + ) + add_argument( log_group, "--log-format", @@ -517,8 +546,11 @@ async def cli(args: list[str]): add_cli_features(parser) parsed = vars(parser.parse_args(args)) + # Simple: argparse already handled env vars via add_argument() + # Just pass the values directly configure_logging( - verbosity=parsed.pop("verbose"), + verbosity=parsed.pop("verbose", None), + log_level=parsed.pop("log_level", None), format=parsed.pop("log_format"), style=parsed.pop("log_format_style"), ) diff --git a/tests/unit/test_cli.py b/tests/unit/test_cli.py index 38a03a314..5844efcf2 100644 --- a/tests/unit/test_cli.py +++ b/tests/unit/test_cli.py @@ -34,6 +34,175 @@ 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) + + +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" + + +def test_configure_logging_log_level_takes_precedence(mocker, caplog): + """Test that log_level takes precedence over verbosity.""" + config = mocker.patch("logging.basicConfig") + + caplog.set_level("DEBUG") + + cli.configure_logging(verbosity=1, log_level="warning") + + config.assert_called_once_with( + level=logging.WARNING, 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 == "WARNING" + + +@pytest.mark.parametrize( + "verbose_env, cli_flags, expected", + [ + (None, [], 0), # Default is 0 + ("1", [], 1), # PROCRASTINATE_VERBOSE works + ("0", ["-v"], 1), # CLI flag adds to env=0: 0+1=1 + ("1", ["-v"], 2), # CLI flag adds to env=1: 1+1=2 + (None, ["-v"], 1), # -v gives verbosity 1 + (None, ["-vv"], 2), # -vv gives verbosity 2 + ], +) +async def test_verbose_env_vars(monkeypatch, mocker, verbose_env, cli_flags, expected): + """Test that PROCRASTINATE_VERBOSE works and CLI flags add to env var value.""" + # Clear any existing values + monkeypatch.delenv("PROCRASTINATE_VERBOSE", raising=False) + monkeypatch.delenv("PROCRASTINATE_LOG_LEVEL", 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) + + # This should raise an error because they're mutually exclusive + with pytest.raises(SystemExit): + await cli.cli(["--app=", "-v", "--log-level", "warning", "defer", "test"]) + + def test_main(mocker): mock = mocker.patch("procrastinate.cli.cli", new=mocker.AsyncMock()) cli.main() From fb912a230af1fc8e07d4e12fc6cff6fa5e1e9392 Mon Sep 17 00:00:00 2001 From: Muhammad Humza Arain Date: Fri, 30 Jan 2026 01:06:26 +0000 Subject: [PATCH 2/5] Removed Redundant Tests & Move all decision logic from configure_logging() to get_log_level() --- procrastinate/cli.py | 65 ++++++++++++++++++++++++--------- tests/unit/test_cli.py | 83 +++++++++++------------------------------- 2 files changed, 68 insertions(+), 80 deletions(-) diff --git a/procrastinate/cli.py b/procrastinate/cli.py index 0fa332a50..57c3a856b 100644 --- a/procrastinate/cli.py +++ b/procrastinate/cli.py @@ -20,12 +20,31 @@ ENV_PREFIX = PROGRAM_NAME.upper() -def get_log_level(verbosity: int) -> int: +def get_log_level( + verbosity: int | None = None, + log_level: str | None = None, +) -> int: """ - Given the number of repetitions of the flag -v, - returns the desired log level + Determine the appropriate logging level. + + Args: + verbosity: Number of -v flags (0=INFO, 1+=DEBUG) + log_level: Explicit log level string (debug, info, warning, error, critical) + + Returns: + Logging level constant (e.g., logging.INFO, logging.DEBUG) + + Precedence: log_level > verbosity > default INFO """ - return {0: logging.INFO, 1: logging.DEBUG}.get(min((1, verbosity)), 0) + if log_level is not None: + return getattr(logging, log_level.upper()) + + if verbosity is not None: + return {0: logging.INFO, 1: logging.DEBUG}.get( + min((1, verbosity)), logging.DEBUG + ) + + return logging.INFO Style = Literal["%", "{", "$"] @@ -37,15 +56,11 @@ def configure_logging( format: str = logging.BASIC_FORMAT, style: Style = "%", ) -> None: - # Determine which level to use - # log_level takes precedence over verbosity - 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 # Default if neither provided + """Configure the Python logging system. + This function only performs operations - all logic is in get_log_level(). + """ + level = get_log_level(verbosity=verbosity, log_level=log_level) logging.basicConfig(level=level, format=format, style=style) level_name = logging.getLevelName(level) logger.debug( @@ -201,9 +216,9 @@ def add_cli_features(parser: argparse.ArgumentParser): "--verbose", default=0, action="count", - help="Increase verbosity (0=info, 1+=debug)", + help="Use multiple times to increase verbosity", envvar="VERBOSE", - envvar_help="set to desired verbosity level (0=info, 1+=debug)", + envvar_help="set to desired verbosity level", envvar_type=int, ) @@ -540,14 +555,28 @@ def configure_shell_parser(subparsers: argparse._SubParsersAction[Any]): # pyri shell_parser.set_defaults(func=shell_) -async def cli(args: list[str]): +def parse_args(args: list[str]) -> dict[str, Any]: + """ + Create parser, configure it, and parse arguments. + + Pure function that transforms CLI arguments into a parsed dictionary, + making it testable without mocking execute_command or configure_logging. + + Args: + args: Command-line arguments (e.g., sys.argv[1:]) + + Returns: + Dictionary of parsed arguments + """ parser = create_parser() add_arguments(parser) add_cli_features(parser) - parsed = vars(parser.parse_args(args)) + return vars(parser.parse_args(args)) + + +async def cli(args: list[str]): + parsed = parse_args(args) - # Simple: argparse already handled env vars via add_argument() - # Just pass the values directly configure_logging( verbosity=parsed.pop("verbose", None), log_level=parsed.pop("log_level", None), diff --git a/tests/unit/test_cli.py b/tests/unit/test_cli.py index 5844efcf2..998d5fca3 100644 --- a/tests/unit/test_cli.py +++ b/tests/unit/test_cli.py @@ -13,10 +13,28 @@ @pytest.mark.parametrize( - "verbosity, log_level", [(0, "INFO"), (1, "DEBUG"), (2, "DEBUG")] + "verbosity, log_level, expected", + [ + # Test verbosity alone + (0, None, logging.INFO), + (1, None, logging.DEBUG), + (2, None, logging.DEBUG), + # Test log_level alone + (None, "debug", logging.DEBUG), + (None, "info", logging.INFO), + (None, "warning", logging.WARNING), + (None, "error", logging.ERROR), + (None, "critical", logging.CRITICAL), + # Test precedence: log_level wins + (1, "warning", logging.WARNING), + (0, "debug", logging.DEBUG), + # Test default + (None, None, logging.INFO), + ], ) -def test_get_log_level(verbosity, log_level): - assert cli.get_log_level(verbosity=verbosity) == getattr(logging, log_level) +def test_get_log_level(verbosity, log_level, expected): + """Test get_log_level with various combinations.""" + assert cli.get_log_level(verbosity=verbosity, log_level=log_level) == expected def test_configure_logging(mocker, caplog): @@ -34,65 +52,6 @@ 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) - - -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" - - -def test_configure_logging_log_level_takes_precedence(mocker, caplog): - """Test that log_level takes precedence over verbosity.""" - config = mocker.patch("logging.basicConfig") - - caplog.set_level("DEBUG") - - cli.configure_logging(verbosity=1, log_level="warning") - - config.assert_called_once_with( - level=logging.WARNING, 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 == "WARNING" - - @pytest.mark.parametrize( "verbose_env, cli_flags, expected", [ From 77c12cfa836423bf207f65a58a1532f66301b186 Mon Sep 17 00:00:00 2001 From: Muhammad Humza Arain Date: Fri, 30 Jan 2026 01:54:07 +0000 Subject: [PATCH 3/5] Add deprecation warning for verbosity flag in configure_logging() --- procrastinate/cli.py | 11 +++++++++++ tests/unit/test_cli.py | 30 +++++++++++++++++++++++++++--- 2 files changed, 38 insertions(+), 3 deletions(-) diff --git a/procrastinate/cli.py b/procrastinate/cli.py index 57c3a856b..ed2d5aea4 100644 --- a/procrastinate/cli.py +++ b/procrastinate/cli.py @@ -8,6 +8,7 @@ import os import shlex import sys +import warnings from collections.abc import Awaitable, Callable from typing import Any, Literal @@ -60,6 +61,16 @@ def configure_logging( This function only performs operations - all logic is in get_log_level(). """ + # Issue deprecation warning when -v/--verbose is actively used + if verbosity is not None and verbosity > 0: + warnings.warn( + "The -v/--verbose flag and PROCRASTINATE_VERBOSE environment variable " + "are deprecated and will be removed in a future version. " + "Use --log-level or PROCRASTINATE_LOG_LEVEL instead.", + PendingDeprecationWarning, + stacklevel=2, + ) + level = get_log_level(verbosity=verbosity, log_level=log_level) logging.basicConfig(level=level, format=format, style=style) level_name = logging.getLevelName(level) diff --git a/tests/unit/test_cli.py b/tests/unit/test_cli.py index 998d5fca3..9e3785ff7 100644 --- a/tests/unit/test_cli.py +++ b/tests/unit/test_cli.py @@ -5,6 +5,7 @@ import io import json import logging +import warnings import pytest @@ -42,7 +43,9 @@ def test_configure_logging(mocker, caplog): caplog.set_level("DEBUG") - cli.configure_logging(verbosity=1, format="{message}, yay!", style="{") + # Expect deprecation warning when using verbosity + with pytest.warns(PendingDeprecationWarning): + cli.configure_logging(verbosity=1, format="{message}, yay!", style="{") config.assert_called_once_with( level=logging.DEBUG, format="{message}, yay!", style="{" @@ -52,6 +55,25 @@ def test_configure_logging(mocker, caplog): assert records[0].value == "DEBUG" +def test_configure_logging_deprecation_warning(mocker): + """Test that using -v/--verbose triggers a deprecation warning.""" + mocker.patch("logging.basicConfig") + + # verbosity > 0 should trigger warning + with pytest.warns(PendingDeprecationWarning, match="verbose.*deprecated"): + cli.configure_logging(verbosity=1) + + # verbosity=0 should NOT trigger warning (default level) + with warnings.catch_warnings(): + warnings.simplefilter("error") # Turn warnings into errors + cli.configure_logging(verbosity=0) # Should not raise + + # log_level should NOT trigger warning (new way) + with warnings.catch_warnings(): + warnings.simplefilter("error") + cli.configure_logging(log_level="debug") # Should not raise + + @pytest.mark.parametrize( "verbose_env, cli_flags, expected", [ @@ -85,8 +107,10 @@ async def mock_execute_command(parsed): def mock_configure_logging(**kwargs): nonlocal captured_verbosity captured_verbosity = kwargs.get("verbosity") - # Call original to ensure it works - original_configure_logging(**kwargs) + # Call original to ensure it works, suppressing deprecation warnings + with warnings.catch_warnings(): + warnings.simplefilter("ignore", PendingDeprecationWarning) + original_configure_logging(**kwargs) mocker.patch("procrastinate.cli.execute_command", side_effect=mock_execute_command) mocker.patch( From 50a66b904752bdedee21326df72a45d605d5ac46 Mon Sep 17 00:00:00 2001 From: Muhammad Humza Arain Date: Fri, 30 Jan 2026 14:38:31 +0000 Subject: [PATCH 4/5] Ignore PendingDeprecationWarning in test_cli_logging_configuration --- tests/integration/test_cli.py | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/integration/test_cli.py b/tests/integration/test_cli.py index 9b3cdd991..52ac2cdd4 100644 --- a/tests/integration/test_cli.py +++ b/tests/integration/test_cli.py @@ -52,6 +52,7 @@ async def test_cli(entrypoint): assert result.stderr.startswith("usage:") +@pytest.mark.filterwarnings("ignore::PendingDeprecationWarning") async def test_cli_logging_configuration(entrypoint, cli_app): result = await entrypoint( "--verbose --log-format {message},yay! --log-format-style { healthchecks" From 3bc52d106c48f5a2c8565edf30fd5f6d96599358 Mon Sep 17 00:00:00 2001 From: Muhammad Humza Arain Date: Sun, 1 Feb 2026 11:41:07 +0000 Subject: [PATCH 5/5] Remove implementation detail from configure_logging() docstring --- procrastinate/cli.py | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/procrastinate/cli.py b/procrastinate/cli.py index ed2d5aea4..5b473a883 100644 --- a/procrastinate/cli.py +++ b/procrastinate/cli.py @@ -57,10 +57,7 @@ def configure_logging( format: str = logging.BASIC_FORMAT, style: Style = "%", ) -> None: - """Configure the Python logging system. - - This function only performs operations - all logic is in get_log_level(). - """ + """Configure the Python logging system.""" # Issue deprecation warning when -v/--verbose is actively used if verbosity is not None and verbosity > 0: warnings.warn(