chore: add more debug logging messages (#63)

ryanking13 · web-flow · commit 76b41241d7a3 · 2026-02-02T13:33:35.000+09:00
* chore: enable more debug logging

* chore: fix logging when proxied to wrangler

* chore: put back comment
diff --git a/.gitignore b/.gitignore
@@ -62,3 +62,5 @@ docs/_build/
 # OS specific
 .DS_Store
 Thumbs.db
+
+tests/test_workspace
diff --git a/src/pywrangler/cli.py b/src/pywrangler/cli.py
@@ -11,6 +11,7 @@
     WRANGLER_COMMAND,
     WRANGLER_CREATE_COMMAND,
     check_wrangler_version,
+    log_startup_info,
     setup_logging,
     write_success,
 )
@@ -56,6 +57,8 @@ def get_command(self, ctx: click.Context, cmd_name: str) -> click.Command:
         command = super().get_command(ctx, cmd_name)
 
         if command is None:
+            log_startup_info()
+
             try:
                 cmd_index = sys.argv.index(cmd_name)
                 remaining_args = sys.argv[cmd_index + 1 :]
@@ -106,6 +109,8 @@ def app(debug: bool = False) -> None:
     if debug:
         logger.setLevel(logging.DEBUG)
 
+    log_startup_info()
+
 
 @app.command("types")
 @click.option(
@@ -135,6 +140,7 @@ def sync_command(force: bool = False) -> None:
 
     Also creates a virtual env for Workers that you can use for testing.
     """
+
     sync(force, directly_requested=True)
     write_success("Sync process completed successfully.")
 
diff --git a/src/pywrangler/sync.py b/src/pywrangler/sync.py
@@ -147,6 +147,9 @@ def parse_requirements() -> list[str]:
     dependencies = pyproject_data.get("project", {}).get("dependencies", [])
 
     logger.info(f"Found {len(dependencies)} dependencies.")
+    if dependencies:
+        for dep in dependencies:
+            logger.debug(f"  - {dep}")
     return dependencies
 
 
@@ -215,6 +218,9 @@ def _install_requirements_to_vendor(requirements: list[str]) -> None:
                     "Installation of packages into the Python Worker failed. Possibly because these packages are not currently supported. See above for details."
                 )
             raise click.exceptions.Exit(code=result.returncode)
+
+        _log_installed_packages(get_pyodide_venv_path())
+
         pyv = get_python_version()
         shutil.rmtree(vendor_path)
         shutil.copytree(
@@ -231,6 +237,20 @@ def _install_requirements_to_vendor(requirements: list[str]) -> None:
     )
 
 
+def _log_installed_packages(venv_path: Path) -> None:
+    result = run_command(
+        ["uv", "pip", "list", "--format=freeze"],
+        env=os.environ | {"VIRTUAL_ENV": venv_path},
+        capture_output=True,
+        check=False,
+    )
+    if result.returncode == 0 and result.stdout.strip():
+        logger.debug("Installed packages:")
+        for line in result.stdout.strip().split("\n"):
+            if line.strip():
+                logger.debug(f"  {line.strip()}")
+
+
 def _install_requirements_to_venv(requirements: list[str]) -> None:
     # Create a requirements file for .venv-workers that includes pyodide-py
     venv_workers_path = get_venv_workers_path()
@@ -312,12 +332,15 @@ def sync(force: bool = False, directly_requested: bool = False) -> None:
     # Check if sync is needed based on file timestamps
     sync_needed = force or is_sync_needed()
     if not sync_needed:
+        logger.debug("Sync not needed - no changes detected")
         if directly_requested:
             logger.warning(
                 "pyproject.toml hasn't changed since last sync, use --force to ignore timestamp check"
             )
         return
 
+    logger.debug("Sync needed - proceeding with installation")
+
     # Check to make sure a wrangler config file exists.
     check_wrangler_config()
 
diff --git a/src/pywrangler/utils.py b/src/pywrangler/utils.py
@@ -1,6 +1,9 @@
 import logging
+import os
+import platform
 import re
 import subprocess
+import sys
 import tomllib
 from datetime import datetime
 from functools import cache
@@ -20,12 +23,47 @@
 
 logger = logging.getLogger(__name__)
 
-SUCCESS_LEVEL = 100
-RUNNING_LEVEL = 15
-OUTPUT_LEVEL = 16
+SUCCESS_LEVEL = logging.CRITICAL + 50
+RUNNING_LEVEL = logging.DEBUG + 5
+OUTPUT_LEVEL = logging.DEBUG + 6
 
+# Valid log levels for PYWRANGLER_LOG environment variable
+_LOG_LEVEL_MAP = {
+    "debug": logging.DEBUG,
+    "info": logging.INFO,
+    "warning": logging.WARNING,
+    "warn": logging.WARNING,  # alias
+    "error": logging.ERROR,
+}
+
+
+def setup_logging() -> int:
+    """
+    Configure logging with Rich handler.
+
+    Reads PYWRANGLER_LOG environment variable to set log level.
+    Valid values: debug, info, warning, warn, error (case-insensitive).
+    Defaults to INFO if not set or invalid.
+
+    Returns:
+        The configured logging level (e.g., logging.DEBUG, logging.INFO).
+    """
+    # Determine log level from environment variable
+    env_level = os.environ.get("PYWRANGLER_LOG", "").lower().strip()
+    if env_level and env_level not in _LOG_LEVEL_MAP:
+        # Print warning to stderr for invalid value (before logging is configured)
+        print(
+            f"Warning: Invalid PYWRANGLER_LOG value '{env_level}'. "
+            f"Valid values: {', '.join(sorted(set(_LOG_LEVEL_MAP.keys())))}. "
+            "Defaulting to 'info'.",
+            file=sys.stderr,
+        )
+        log_level = logging.INFO
+    elif env_level:
+        log_level = _LOG_LEVEL_MAP[env_level]
+    else:
+        log_level = logging.INFO
 
-def setup_logging() -> None:
     console = Console(
         theme=Theme(
             {
@@ -39,7 +77,7 @@ def setup_logging() -> None:
 
     # Configure Rich logger
     logging.basicConfig(
-        level=logging.INFO,
+        level=log_level,
         format="%(message)s",
         force=True,  # Ensure this configuration is applied
         handlers=[
@@ -52,6 +90,28 @@ def setup_logging() -> None:
     logging.addLevelName(RUNNING_LEVEL, "RUNNING")
     logging.addLevelName(OUTPUT_LEVEL, "OUTPUT")
 
+    return log_level
+
+
+def _get_pywrangler_version() -> str:
+    """Get the version of pywrangler."""
+    try:
+        from importlib.metadata import version
+
+        return version("workers-py")
+    except Exception:
+        return "unknown"
+
+
+def log_startup_info() -> None:
+    """
+    Log startup information for debugging.
+    """
+    logger.debug(f"pywrangler version: {_get_pywrangler_version()}")
+    logger.debug(f"Python: {platform.python_version()}")
+    logger.debug(f"Platform: {sys.platform}")
+    logger.debug(f"Working directory: {Path.cwd()}")
+
 
 def write_success(msg: str) -> None:
     logging.log(SUCCESS_LEVEL, msg)
diff --git a/tests/test_cli.py b/tests/test_cli.py
@@ -542,3 +542,114 @@ def test_check_wrangler_version_insufficient(mock_run_command):
 
     with pytest.raises(click.exceptions.Exit):
         check_wrangler_version()
+
+
+# Tests for PYWRANGLER_LOG environment variable
+
+
+def test_env_var_debug_level(test_dir, monkeypatch, caplog):
+    monkeypatch.setenv("PYWRANGLER_LOG", "debug")
+    create_test_pyproject(test_dir)
+    create_test_wrangler_jsonc(test_dir)
+
+    # Need to reimport to pick up env var change
+    import importlib
+
+    import pywrangler.utils
+
+    importlib.reload(pywrangler.utils)
+
+    from pywrangler.utils import setup_logging
+
+    level = setup_logging()
+    assert level == logging.DEBUG
+
+
+def test_env_var_error_level(test_dir, monkeypatch):
+    """Test that PYWRANGLER_LOG=error sets ERROR level."""
+    monkeypatch.setenv("PYWRANGLER_LOG", "error")
+
+    import importlib
+
+    import pywrangler.utils
+
+    importlib.reload(pywrangler.utils)
+
+    from pywrangler.utils import setup_logging
+
+    level = setup_logging()
+    assert level == logging.ERROR
+
+
+def test_env_var_case_insensitive(test_dir, monkeypatch):
+    """Test that PYWRANGLER_LOG is case-insensitive."""
+    monkeypatch.setenv("PYWRANGLER_LOG", "DEBUG")
+
+    import importlib
+
+    import pywrangler.utils
+
+    importlib.reload(pywrangler.utils)
+
+    from pywrangler.utils import setup_logging
+
+    level = setup_logging()
+    assert level == logging.DEBUG
+
+
+def test_debug_flag_overrides_env(test_dir, monkeypatch, caplog):
+    """Test that --debug flag overrides PYWRANGLER_LOG=error."""
+    monkeypatch.setenv("PYWRANGLER_LOG", "error")
+    create_test_pyproject(test_dir)
+    create_test_wrangler_jsonc(test_dir)
+
+    runner = CliRunner()
+    runner.invoke(app, ["--debug", "sync"])
+
+    debug_logs = [
+        record for record in caplog.records if record.levelno == logging.DEBUG
+    ]
+    assert len(debug_logs) > 0, "--debug flag should override PYWRANGLER_LOG=error"
+
+
+def test_env_var_invalid(test_dir, monkeypatch, capsys):
+    """Test that invalid PYWRANGLER_LOG value produces warning."""
+    monkeypatch.setenv("PYWRANGLER_LOG", "invalid_value")
+
+    import importlib
+
+    import pywrangler.utils
+
+    importlib.reload(pywrangler.utils)
+
+    from pywrangler.utils import setup_logging
+
+    level = setup_logging()
+
+    captured = capsys.readouterr()
+    assert "Warning" in captured.err
+    assert "invalid_value" in captured.err
+    assert level == logging.INFO
+
+
+def test_startup_banner(test_dir, monkeypatch):
+    """Test that debug output contains version, platform, and working directory."""
+    monkeypatch.setenv("PYWRANGLER_LOG", "debug")
+    create_test_pyproject(test_dir)
+    create_test_wrangler_jsonc(test_dir)
+
+    import importlib
+
+    import pywrangler.utils
+
+    importlib.reload(pywrangler.utils)
+
+    from pywrangler.utils import _get_pywrangler_version, log_startup_info
+
+    # Verify the functions exist and return expected content
+    version = _get_pywrangler_version()
+    assert version is not None
+
+    # Verify log_startup_info can be called without error
+    # The actual logging is tested via integration in test_debug_flag
+    log_startup_info()
