Skip to content

Commit d112eee

Browse files
rustyconoverclaude
andcommitted
Fix review issues from structlog-to-stdlib logging migration
- Fix handler accumulation: clear handlers before adding new ones - Add timestamp (HH:MM:SS) to text log format - Remove vestigial self.log on Worker (zero references) - Move LogLevel/LogFormat to module-level imports, remove globals() hack - Add tests/test_worker_cli.py with 9 tests for configure_worker_logging - Document worker logging options in README and docs/cli.md Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
1 parent 55b4d9a commit d112eee

5 files changed

Lines changed: 191 additions & 9 deletions

File tree

README.md

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -409,6 +409,25 @@ Client Worker
409409

410410
---
411411

412+
## Logging
413+
414+
Workers support `--debug`, `--log-level`, `--log-format`, and `--log-logger` options:
415+
416+
```bash
417+
# Enable debug logging
418+
vgi-example-worker --debug
419+
420+
# JSON-formatted logs for structured pipelines
421+
vgi-example-worker --log-format json
422+
423+
# Target a specific logger
424+
vgi-example-worker --log-level DEBUG --log-logger vgi.worker
425+
```
426+
427+
See [CLI Reference](docs/cli.md#worker-logging) for the full list of loggers and options.
428+
429+
---
430+
412431
## Development
413432

414433
```bash

docs/cli.md

Lines changed: 56 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -493,6 +493,62 @@ vgi-client catalog detach $ATTACH_ID --worker ./worker.py
493493

494494
---
495495

496+
## Worker Logging
497+
498+
All workers that use `Worker.main()` (including `vgi-example-worker`) support
499+
logging options on the command line. Logs are written to stderr.
500+
501+
### Options
502+
503+
| Option | Description |
504+
|--------|-------------|
505+
| `--debug` | Enable DEBUG level on all `vgi` and `vgi_rpc` loggers |
506+
| `--log-level LEVEL` | Set log level: `DEBUG`, `INFO` (default), `WARNING`, `ERROR` |
507+
| `--log-logger NAME` | Target specific logger(s) instead of all defaults (repeatable) |
508+
| `--log-format FORMAT` | Stderr format: `text` (default) or `json` |
509+
| `--quiet` / `-q` | Suppress the interactive-terminal startup warning |
510+
511+
`--debug` overrides `--log-level` when both are provided.
512+
513+
### Examples
514+
515+
```bash
516+
# Enable debug logging
517+
vgi-example-worker --debug
518+
519+
# Set WARNING level only
520+
vgi-example-worker --log-level WARNING
521+
522+
# Target a specific logger at DEBUG
523+
vgi-example-worker --log-level DEBUG --log-logger vgi.worker
524+
525+
# JSON-formatted logs (for structured log pipelines)
526+
vgi-example-worker --log-format json
527+
```
528+
529+
### Available Loggers
530+
531+
| Logger | Description |
532+
|--------|-------------|
533+
| `vgi` | VGI root logger (all VGI messages) |
534+
| `vgi.worker` | Worker lifecycle (startup, shutdown) |
535+
| `vgi.client` | Client operations (spawn, bind, exchange) |
536+
| `vgi.client.cli` | CLI front-end (argument parsing) |
537+
| `vgi.filter_pushdown` | Filter pushdown debug (deserialization/evaluation) |
538+
| `vgi_rpc` | vgi_rpc root logger (all vgi_rpc messages) |
539+
| `vgi_rpc.wire.request` | RPC wire request (serialised request bytes) |
540+
| `vgi_rpc.wire.response` | RPC wire response (serialised response bytes) |
541+
| `vgi_rpc.wire.transport` | Transport layer (pipe/HTTP transport debug) |
542+
543+
### Environment Variables
544+
545+
| Variable | Description |
546+
|----------|-------------|
547+
| `VGI_QUIET=1` | Suppress the interactive-terminal startup warning (same as `--quiet`) |
548+
| `VGI_FILTER_DEBUG=1` | Enable filter pushdown debug logging |
549+
550+
---
551+
496552
## Example Workers
497553

498554
### vgi-example-worker

tests/test_worker_cli.py

Lines changed: 110 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,110 @@
1+
"""Tests for Worker.main() CLI logging options."""
2+
3+
from __future__ import annotations
4+
5+
import logging
6+
from typing import TYPE_CHECKING
7+
8+
import pytest
9+
10+
from vgi.logging_config import (
11+
_KNOWN_LOGGERS,
12+
LogFormat,
13+
LogLevel,
14+
configure_worker_logging,
15+
)
16+
17+
if TYPE_CHECKING:
18+
from collections.abc import Iterator
19+
20+
# All known logger names from the registry
21+
_ALL_LOGGER_NAMES = [name for name, _, _ in _KNOWN_LOGGERS]
22+
23+
24+
@pytest.fixture(autouse=False)
25+
def _reset_loggers() -> Iterator[None]:
26+
"""Save and restore logger handlers and levels after each test."""
27+
saved: dict[str, tuple[int, list[logging.Handler]]] = {}
28+
for name in _ALL_LOGGER_NAMES:
29+
logger = logging.getLogger(name)
30+
saved[name] = (logger.level, list(logger.handlers))
31+
yield
32+
for name in _ALL_LOGGER_NAMES:
33+
logger = logging.getLogger(name)
34+
level, handlers = saved[name]
35+
logger.handlers[:] = handlers
36+
logger.setLevel(level)
37+
38+
39+
class TestConfigureWorkerLogging:
40+
"""Tests for configure_worker_logging() options."""
41+
42+
def test_debug_flag(self, _reset_loggers: None) -> None:
43+
"""``--debug`` sets vgi + vgi_rpc loggers to DEBUG."""
44+
configure_worker_logging(debug=True)
45+
for name in ("vgi", "vgi_rpc"):
46+
logger = logging.getLogger(name)
47+
assert logger.level == logging.DEBUG
48+
assert len(logger.handlers) == 1
49+
50+
def test_log_level_option(self, _reset_loggers: None) -> None:
51+
"""``--log-level WARNING`` sets correct level."""
52+
configure_worker_logging(log_level=LogLevel.WARNING)
53+
for name in ("vgi", "vgi_rpc"):
54+
logger = logging.getLogger(name)
55+
assert logger.level == logging.WARNING
56+
57+
def test_log_logger_targeting(self, _reset_loggers: None) -> None:
58+
"""``--log-logger vgi.worker`` targets only that logger."""
59+
configure_worker_logging(log_level=LogLevel.DEBUG, log_loggers=["vgi.worker"])
60+
target = logging.getLogger("vgi.worker")
61+
assert target.level == logging.DEBUG
62+
assert len(target.handlers) == 1
63+
# Root vgi logger should not have been modified
64+
root = logging.getLogger("vgi")
65+
assert root.handlers == [] or root.level != logging.DEBUG
66+
67+
def test_log_format_json(self, _reset_loggers: None) -> None:
68+
"""``--log-format json`` uses VgiJsonFormatter."""
69+
from vgi_rpc.logging_utils import VgiJsonFormatter
70+
71+
configure_worker_logging(debug=True, log_format=LogFormat.json)
72+
logger = logging.getLogger("vgi")
73+
assert any(isinstance(h.formatter, VgiJsonFormatter) for h in logger.handlers)
74+
75+
def test_debug_overrides_log_level(self, _reset_loggers: None) -> None:
76+
"""``--debug --log-level INFO`` resolves to DEBUG."""
77+
configure_worker_logging(debug=True, log_level=LogLevel.INFO)
78+
logger = logging.getLogger("vgi")
79+
assert logger.level == logging.DEBUG
80+
81+
def test_unknown_logger_warning(self, _reset_loggers: None, capsys: pytest.CaptureFixture[str]) -> None:
82+
"""Unrecognized logger name warns on stderr."""
83+
configure_worker_logging(log_level=LogLevel.DEBUG, log_loggers=["not.a.real.logger"])
84+
captured = capsys.readouterr()
85+
assert "warning: unknown logger 'not.a.real.logger'" in captured.err
86+
87+
def test_configure_idempotent(self, _reset_loggers: None) -> None:
88+
"""Calling configure_worker_logging() twice doesn't duplicate handlers."""
89+
configure_worker_logging(debug=True)
90+
configure_worker_logging(debug=True)
91+
logger = logging.getLogger("vgi")
92+
assert len(logger.handlers) == 1
93+
94+
def test_returns_effective_level(self, _reset_loggers: None) -> None:
95+
"""Return value is the numeric log level."""
96+
level = configure_worker_logging(log_level=LogLevel.WARNING)
97+
assert level == logging.WARNING
98+
99+
level = configure_worker_logging(debug=True, log_level=LogLevel.WARNING)
100+
assert level == logging.DEBUG
101+
102+
def test_text_format_has_timestamp(self, _reset_loggers: None) -> None:
103+
"""Text format includes asctime in the formatter."""
104+
configure_worker_logging(log_format=LogFormat.text)
105+
logger = logging.getLogger("vgi")
106+
assert len(logger.handlers) == 1
107+
fmt = logger.handlers[0].formatter
108+
assert fmt is not None
109+
assert fmt._fmt is not None
110+
assert "asctime" in fmt._fmt

vgi/logging_config.py

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -71,7 +71,9 @@ def configure_worker_logging(
7171

7272
handler.setFormatter(VgiJsonFormatter())
7373
else:
74-
handler.setFormatter(logging.Formatter("%(name)-30s %(levelname)-5s %(message)s"))
74+
handler.setFormatter(
75+
logging.Formatter("%(asctime)s %(name)-30s %(levelname)-5s %(message)s", datefmt="%H:%M:%S")
76+
)
7577

7678
targets = log_loggers if log_loggers else ["vgi", "vgi_rpc"]
7779

@@ -81,6 +83,7 @@ def configure_worker_logging(
8183
# Still configure it — the user may know what they're doing
8284
sys.stderr.write(f"warning: unknown logger {name!r}\n")
8385
logger = logging.getLogger(name)
86+
logger.handlers.clear()
8487
logger.setLevel(effective_level)
8588
logger.addHandler(handler)
8689

vgi/worker.py

Lines changed: 2 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -90,6 +90,7 @@ class MyWorker(Worker):
9090
BindResponse,
9191
GlobalInitResponse,
9292
)
93+
from vgi.logging_config import LogFormat, LogLevel
9394
from vgi.protocol import (
9495
BindRequest,
9596
CatalogAttachRequest,
@@ -402,13 +403,7 @@ def main(cls) -> None:
402403
"""
403404
import typer
404405

405-
from vgi.logging_config import LogFormat, LogLevel, configure_worker_logging
406-
407-
# Inject types into module globals so typer can resolve stringified
408-
# annotations created by ``from __future__ import annotations``.
409-
_mod = globals()
410-
_mod["LogLevel"] = LogLevel
411-
_mod["LogFormat"] = LogFormat
406+
from vgi.logging_config import configure_worker_logging
412407

413408
app = typer.Typer(add_completion=False)
414409

@@ -1387,7 +1382,6 @@ def __init__(self, *, quiet: bool = False, log_level: int = logging.INFO) -> Non
13871382
"""
13881383
self._quiet = quiet or os.environ.get("VGI_QUIET") == "1"
13891384
logging.getLogger("vgi").setLevel(log_level)
1390-
self.log: logging.Logger = _logger
13911385

13921386
def run(self) -> None:
13931387
"""Run the worker, reading from stdin and writing to stdout."""

0 commit comments

Comments
 (0)