diff --git a/CHANGES b/CHANGES index 7a691b0cc9..56a383049f 100644 --- a/CHANGES +++ b/CHANGES @@ -45,6 +45,105 @@ $ uvx --from 'libtmux' --prerelease allow python _Notes on the upcoming release will go here._ +### Breaking changes + +#### Query records use the command logger (#748) + +Calls through {func}`~libtmux.neo.fetch_objs` no longer emit the `tmux list +queried` and `tmux list parsed` `DEBUG` records from `libtmux.neo`. They produce +`tmux command dispatched` and `tmux command completed` records from +`libtmux.common` instead. Applications that configure module-specific logging +now select the command logger: + +```python +import logging + +# Before +query_logger = logging.getLogger("libtmux.neo") + +# After +query_logger = logging.getLogger("libtmux.common") +``` + +`libtmux.common` carries every tmux subprocess rather than list queries alone. +Filter a handler on the `tmux_subcommand` field to isolate queries again; +{ref}`logging` shows the filter. + +#### Raised failures stay in the exception channel (#748) + +A failure that libtmux propagates or translates no longer emits an `ERROR` +record first. Applications that consumed those records now log at their own +exception boundary. + +```python +import logging + +from libtmux import exc + +logger = logging.getLogger(__name__) + +# Before +operation() + +# After +try: + operation() +except exc.LibTmuxException: + logger.exception("libtmux operation failed") + raise +``` + +#### Unusable tmux executables share one exception (#748) + +Missing, non-executable, and malformed tmux executables now raise +{exc}`~libtmux.exc.TmuxCommandNotFound` from +{class}`~libtmux.common.tmux_cmd` and +{meth}`Server.raise_if_dead() `. Attempted +launches preserve the operating-system message and cause. Other launch +failures remain native `OSError` values. + +```python +available = True +try: + server.raise_if_dead() +# Before: except (exc.TmuxCommandNotFound, OSError): +# After: +except exc.TmuxCommandNotFound: + available = False +``` + +### What's new + +#### Structured records identify tmux work (#748) + +Command `DEBUG` records add best-effort subcommand and socket fields while +retaining the complete command, exit status, bounded output snapshots, and +line counts. Lifecycle `INFO` records consistently identify affected sockets, +sessions, windows, panes, and targets. + +Applications can route and format these fields independently through +standard-library handlers without modifying the original records. + +#### Handled failures produce one diagnostic (#748) + +{attr}`Server.sessions `, +{attr}`Server.attached_sessions `, and +{attr}`Server.clients ` now emit one `ERROR` record +when they convert a tmux execution failure to an empty result. Expected probes +and failures returned to callers stay quiet. + +Malformed `terminal-features`, `terminal-overrides`, and `command-alias` +entries produce one aggregate `WARNING` per option with the skipped-entry +count. + +### Fixes + +#### Caller-controlled log context stays on one line (#748) + +Command arguments, socket labels, object identities, targets, and failed +lookup paths escape control characters before rendering, so one value cannot +forge additional log lines. + ### Documentation #### Cleaner `from_env` examples (#719) @@ -57,6 +156,12 @@ environment-setup plumbing, so each example leads with the constructor call it demonstrates instead of the socket-path and `$TMUX` boilerplate needed to run it. +#### Logging configuration and record reference (#748) + +{ref}`logging` documents logger ownership, levels, structured fields, failure +routing, payload policy, handler filtering and formatting, and `caplog` +assertions. + ### Development #### CI actions updated to current majors diff --git a/MIGRATION b/MIGRATION index cbcf307f24..2d231f4de7 100644 --- a/MIGRATION +++ b/MIGRATION @@ -113,6 +113,111 @@ sections below for detailed migration examples and code samples. _Detailed migration steps for the next version will be posted here._ +## libtmux 0.63.x: Failure and logging channels (#748) + +### An unusable tmux binary raises `TmuxCommandNotFound` + +{class}`~libtmux.common.tmux_cmd` and +{meth}`Server.raise_if_dead() ` translate a +missing, non-executable, or malformed tmux executable into +{exc}`~libtmux.exc.TmuxCommandNotFound`. That exception subclasses +{exc}`~libtmux.exc.LibTmuxException`, not `OSError`. Through 0.62.0 a +non-executable binary surfaced as `PermissionError` and a malformed one as +`OSError`, so a handler written for either class stops firing. + +**Who is affected:** code catching `OSError` or `PermissionError` around a +tmux launch. Launch failures carrying any other errno still propagate as a +native `OSError`. + +**Before:** + +```python +try: + server.raise_if_dead() +except OSError: + available = False +``` + +**After:** + +```python +from libtmux import exc + +try: + server.raise_if_dead() +except exc.TmuxCommandNotFound: + available = False +``` + +The operating system's diagnostic survives the translation whenever the launch +was attempted: the message carries it and `__cause__` holds the original +`OSError`. A tmux binary absent from `PATH` is never launched, so its +`__cause__` is `None`. + +```python +from libtmux import exc + +try: + server.raise_if_dead() +except exc.TmuxCommandNotFound as error: + errno = getattr(error.__cause__, "errno", None) +``` + +### Raised failures no longer emit an `ERROR` record + +Through 0.62.0 libtmux logged an `ERROR` record before propagating or +translating a failure. A raised failure now reaches the caller through the +exception channel alone. `ERROR` records mark the opposite case, a boundary +that swallowed a failure and returned an empty result: +{attr}`Server.sessions `, +{attr}`Server.attached_sessions `, and +{attr}`Server.clients `. + +**Who is affected:** alerting and log scraping that counted libtmux `ERROR` +records to detect failed operations. Log at your own exception boundary: + +```python +import logging + +from libtmux import exc + +logger = logging.getLogger(__name__) + +try: + operation() +except exc.LibTmuxException: + logger.exception("libtmux operation failed") + raise +``` + +### Query `DEBUG` records come from `libtmux.common` + +{func}`~libtmux.neo.fetch_objs`, the query path behind the object list +accessors, emitted `tmux list queried` and `tmux list parsed` on `libtmux.neo` +through 0.62.0. The shared command producer emits `tmux command dispatched` +and `tmux command completed` on `libtmux.common` in their place. + +**Who is affected:** logging configuration naming `libtmux.neo`, and +assertions on the old message text. `libtmux.common` carries every tmux +subprocess rather than list queries alone; filter a handler on the +`tmux_subcommand` field to isolate queries. See {ref}`logging`. + +**Before:** + +```python +import logging + +logging.getLogger("libtmux.neo").setLevel(logging.DEBUG) +``` + +**After:** + +```python +import logging + +logging.getLogger("libtmux.common").setLevel(logging.DEBUG) +``` + ## libtmux 0.62.0: Query exceptions join the hierarchy (#718) {exc}`~libtmux.exc.ObjectDoesNotExist` and diff --git a/conftest.py b/conftest.py index 88a2656d29..e750cf9330 100644 --- a/conftest.py +++ b/conftest.py @@ -58,6 +58,7 @@ def add_doctest_fixtures( session=session, ) doctest_namespace["monkeypatch"] = request.getfixturevalue("monkeypatch") + doctest_namespace["caplog"] = request.getfixturevalue("caplog") @pytest.fixture(autouse=True) diff --git a/docs/topics/index.md b/docs/topics/index.md index c955e5857e..f81dbfed59 100644 --- a/docs/topics/index.md +++ b/docs/topics/index.md @@ -55,6 +55,13 @@ Create sessions, windows, and panes programmatically. Common patterns for scripting and automation. ::: +:::{grid-item-card} Logging +:link: logging +:link-type: doc +Structured log records, the `tmux_` field schema, and application-owned +handlers. +::: + :::{grid-item-card} Context Managers :link: context_managers :link-type: doc @@ -96,6 +103,7 @@ floating_panes workspace_setup automation_patterns context_managers +logging options_and_hooks clients format-tokens diff --git a/docs/topics/logging.md b/docs/topics/logging.md new file mode 100644 index 0000000000..6fa3758d7e --- /dev/null +++ b/docs/topics/logging.md @@ -0,0 +1,270 @@ +(logging)= + +# Logging + +libtmux emits structured records through Python's {mod}`logging` module. It +does not install an output handler or choose a level. Configure the `libtmux` +logger in your application; `INFO` reports object lifecycle events, while +`DEBUG` adds tmux subprocess boundaries. + +Command records include the complete tmux command. Completion records also +include bounded stdout and stderr snapshots. Applications choose which fields +reach each destination through standard-library handlers and formatters. + +## Enable records + +The `libtmux` logger is the parent of every package logger. A handler attached +there receives records from `libtmux.common`, `libtmux.server`, and the +object modules. + +Use your application's normal logging configuration. For a short script, +`logging.basicConfig(level=logging.INFO)` is enough. To inspect command +metadata without changing other libraries, set only `libtmux.common` to +`DEBUG`. + +```python +>>> import logging +>>> command_logger = logging.getLogger("libtmux.common") +>>> previous_level = command_logger.level +>>> command_logger.setLevel(logging.DEBUG) +>>> command_logger.isEnabledFor(logging.DEBUG) +True +>>> command_logger.setLevel(previous_level) +``` + +## Records by level + +| Level | What libtmux records | +| ----- | -------------------- | +| `DEBUG` | tmux command dispatch and completion; internal lookup details | +| `INFO` | successful server, session, window, and pane lifecycle events | +| `WARNING` | recoverable problems libtmux handled | +| `ERROR` | a failure libtmux intentionally converted to a fallback result | + +The main emitters are: + +| Logger | Records | +| ------ | ------- | +| `libtmux.common` | subprocess dispatch and completion | +| `libtmux.server` | server/session lifecycle and swallowed list failures | +| `libtmux.session` | session/window lifecycle | +| `libtmux.window` | window lifecycle | +| `libtmux.pane` | pane lifecycle | +| `libtmux.options` | aggregated option parsing warnings | +| `libtmux.hooks` | hook parsing warnings | + +## Command records + +Each tmux subprocess can produce two `DEBUG` records: + +- `tmux command dispatched` before execution; +- `tmux command completed` after execution. + +Both carry `tmux_cmd`, a one-line rendering of the complete argv. Printable +values use shell quoting; control characters use escaped representations. The +completion record adds the exit code, the first 100 stdout and stderr lines, +and the total line counts. + +```python +>>> import logging +>>> marker = "caller-payload" +>>> with caplog.at_level(logging.DEBUG, logger="libtmux.common"): +... proc = session.server.cmd("list-sessions", "-F", marker) +>>> marker in proc.stdout +True +>>> command_records = [ +... record for record in caplog.records +... if record.getMessage().startswith("tmux command") +... ] +>>> dispatched, completed = command_records[-2:] +>>> dispatched.tmux_subcommand +'list-sessions' +>>> dispatched.tmux_socket == session.server.socket_name +True +>>> dispatched.tmux_cmd.endswith("list-sessions -F caller-payload") +True +>>> marker in dispatched.tmux_cmd +True +>>> completed.tmux_stdout == proc.stdout +True +>>> completed.tmux_stderr == proc.stderr +True +>>> completed.tmux_stdout_len == len(proc.stdout) +True +``` + +The result object retains every output line. The completion record snapshots +at most 100 lines from each stream and reports the full lengths separately. +`tmux_subcommand` and `tmux_socket` are best-effort conveniences. An unknown +global option leaves uncertain derived fields absent; `tmux_cmd` remains +complete. + +## Failures + +libtmux does not log an error and then raise it. Propagated and translated +failures remain exception data, so callers decide whether and where to log +them. Expected probes such as {meth}`Server.is_alive() +` also stay quiet. + +Missing, non-executable, and malformed tmux executables use +{exc}`~libtmux.exc.TmuxCommandNotFound`. When the operating system attempted +the launch, the exception retains its message and cause. A failed `PATH` +lookup has a factual message without a synthetic cause. Other operating-system +launch errors remain native exceptions at direct APIs. + +Three list-shaped accessors intentionally hide tmux execution failures, +including {exc}`~libtmux.exc.LibTmuxException` and operating-system launch +errors: + +- {attr}`Server.sessions `; +- {attr}`Server.attached_sessions `; +- {attr}`Server.clients `. + +They return an empty collection and emit one `ERROR` record on +`libtmux.server`. The record carries the subcommand, socket, the first 100 lines +of exception text, and the total line count. Use {meth}`Server.raise_if_dead() +` when an unreachable server must be loud. + +A non-zero exit code alone does not produce an `ERROR`; tmux also uses +non-zero status to answer probes with “no.” + +## Structured fields + +Records contain only fields relevant to their event. + +| Field | Type | Meaning | +| ----- | ---- | ------- | +| `tmux_cmd` | `str` | quoted, one-line complete command | +| `tmux_subcommand` | `str` | tmux subcommand | +| `tmux_socket` | `str` | socket name or path | +| `tmux_target` | `str` | target specifier | +| `tmux_session` | `str` | session name | +| `tmux_window` | `str` | window name or index | +| `tmux_pane` | `str` | pane identifier | +| `tmux_exit_code` | `int` | subprocess exit status | +| `tmux_stdout` | `list[str]` | first 100 stdout lines | +| `tmux_stderr` | `list[str]` | first 100 stderr lines | +| `tmux_stdout_len` | `int` | stdout line count | +| `tmux_stderr_len` | `int` | stderr or swallowed-error line count | +| `tmux_option_key` | `str` | option whose entries could not be parsed | +| `tmux_option_skipped` | `int` | entries skipped for that option | + +All identity fields are strings. Unknown identities are omitted rather than +set to `None`. + +## Format records + +Not every record carries every field. A formatter that requires +`%(tmux_cmd)s` drops lifecycle records unless it supplies a default. Python +3.10 and later accept defaults directly: + +```python +>>> import logging +>>> formatter = logging.Formatter( +... "%(levelname)s %(message)s subcommand=%(tmux_subcommand)s exit=%(tmux_exit_code)s", +... defaults={"tmux_subcommand": "-", "tmux_exit_code": "-"}, +... ) +>>> record = logging.LogRecord( +... "libtmux.server", logging.INFO, "server.py", 1, +... "session created", (), None, +... ) +>>> formatter.format(record) +'INFO session created subcommand=- exit=-' +``` + +Use the same defaulting rule in JSON formatters and telemetry exporters. + +### Select fields at the handler + +A handler's filter chooses its records, and its formatter chooses the fields +written to that destination. This Python 3.10-compatible example retains the +payload fields on each record but writes only event names and bounded metadata: + +```python +>>> import io +>>> import logging +>>> stream = io.StringIO() +>>> handler = logging.StreamHandler(stream) +>>> handler.addFilter( +... lambda record: getattr(record, "tmux_subcommand", None) == "display-message" +... ) +>>> handler.setFormatter(logging.Formatter( +... "%(levelname)s %(message)s subcommand=%(tmux_subcommand)s " +... "stdout_lines=%(tmux_stdout_len)s", +... defaults={"tmux_subcommand": "-", "tmux_stdout_len": "-"}, +... )) +>>> package_logger = logging.getLogger("libtmux") +>>> command_logger = logging.getLogger("libtmux.common") +>>> previous_level = command_logger.level +>>> command_logger.setLevel(logging.DEBUG) +>>> package_logger.addHandler(handler) +>>> proc = session.server.cmd("display-message", "-p", "payload-marker") +>>> _ = session.server.cmd("list-sessions") # filtered from this handler +>>> package_logger.removeHandler(handler) +>>> command_logger.setLevel(previous_level) +>>> handler.close() +>>> "payload-marker" in proc.stdout +True +>>> "payload-marker" in stream.getvalue() +False +>>> "list-sessions" in stream.getvalue() +False +>>> stream.getvalue().count("tmux command") +2 +``` + +The standard library documents handler-level +[filters](https://docs.python.org/3/library/logging.html#filter-objects). +Its [Logging Cookbook](https://docs.python.org/3/howto/logging-cookbook.html) +covers contextual fields, routing, handlers, and custom formatting. + +## Assert on records in tests + +Use pytest's `caplog.records` so assertions read structured fields instead of +rendered text: + +```python +>>> import logging +>>> with caplog.at_level(logging.INFO, logger="libtmux.session"): +... logged_window = session.new_window(window_name="logged") +>>> records = [ +... record for record in caplog.records +... if getattr(record, "tmux_subcommand", None) == "new-window" +... ] +>>> len(records) >= 1 +True +>>> records[-1].tmux_socket == session.server.socket_name +True +>>> logged_window.kill() +``` + +Scope capture to the logger under test and filter by message or subcommand; +fixture setup may have emitted earlier records. + +## Warnings are separate + +Deprecations, ignored arguments, and version advisories use +{mod}`warnings`, not logging. Applications that need one stream can route +them through the `py.warnings` logger: + +```python +>>> import logging +>>> logging.captureWarnings(True) +>>> logging.captureWarnings(False) +``` + +libtmux does not duplicate a warning as a log record. + +## Payload size and application policy + +`DEBUG` records contain caller-provided command operands and output lines. +Choose handler destinations, formatting, and retention for the data your +application sends through tmux. libtmux does not redact command or output +payloads; use a handler formatter such as the example above when a destination +needs metadata only. + +When `DEBUG` is disabled, command-context construction is skipped. With it +enabled, `tmux_cmd` grows with argv, and each completion record retains up to +100 lines from each stream. Individual lines are not truncated. libtmux keeps +no shared logging state, so threads and async callers rely on the standard +library's logging guarantees. diff --git a/src/libtmux/AGENTS.md b/src/libtmux/AGENTS.md index 380707c714..921d164e37 100644 --- a/src/libtmux/AGENTS.md +++ b/src/libtmux/AGENTS.md @@ -12,150 +12,110 @@ facts specific to this package. method. - tmux's format-string system (`#{session_id}`, `#{window_name}`, …) is libtmux's query mechanism; format constants live in `formats.py`. -- An object can go stale when tmux state changes externally (another - client kills a window, a session gets renamed). Call `.refresh()` to - reconcile it, or use the `neo` query interface, which always queries - fresh. +- An object can go stale when tmux state changes externally. Call + `.refresh()` to reconcile it, or use the `neo` query interface, + which always queries fresh. ## List-returning accessors: empty by default on tmux errors `Server.sessions`, `Server.clients`, and `Server.attached_sessions` return an empty `QueryList` when tmux's underlying list command fails -for any reason — no running daemon, a missing socket, a permission -error, a subprocess crash. This is a deliberate API contract: -list-shaped accessors are lenient by default. Callers that need to -distinguish "no rows" from "tmux unreachable" use the explicit -`Server.is_alive()` or `Server.raise_if_dead()` primitives. - -When adding a new list-returning accessor, follow this convention. If a -future feature genuinely benefits from loud-failure semantics, expose -it as a scoped opt-in (e.g. a `Server.raise_server_errors()` context -manager) rather than changing the default contract of an existing -accessor or hard-coding raise-on-tmux-error into a new one. -Empty-on-tmux-error stays the default; raise is opt-in. +for any reason. Callers that need to distinguish an empty server from +an unreachable one use `Server.is_alive()` or `Server.raise_if_dead()`. -## Logging - -These rules guide future logging changes; existing code may not yet -conform. - -### Logger setup - -- Use `logging.getLogger(__name__)` in every module. -- Add `NullHandler` in library `__init__.py` files. -- Never configure handlers, levels, or formatters in library code — - that's the application's job. - -### Structured context via `extra` - -Pass structured data on every log call where useful for filtering, -searching, or test assertions. - -**Core keys** (stable, scalar, safe at any log level): - -| Key | Type | Context | -|-----|------|---------| -| `tmux_cmd` | `str` | tmux command line | -| `tmux_subcommand` | `str` | tmux subcommand (e.g. `new-session`) | -| `tmux_target` | `str` | tmux target specifier (e.g. `mysession:1.2`) | -| `tmux_exit_code` | `int` | tmux process exit code | -| `tmux_session` | `str` | session name | -| `tmux_window` | `str` | window name or index | -| `tmux_pane` | `str` | pane identifier | -| `tmux_option_key` | `str` | tmux option name | - -**Heavy/optional keys** (DEBUG only, potentially large): - -| Key | Type | Context | -|-----|------|---------| -| `tmux_stdout` | `list[str]` | tmux stdout lines (truncate or cap; `%(tmux_stdout)s` produces repr) | -| `tmux_stderr` | `list[str]` | tmux stderr lines (same caveats) | -| `tmux_stdout_len` | `int` | number of stdout lines | -| `tmux_stderr_len` | `int` | number of stderr lines | - -Treat established keys as compatibility-sensitive — downstream users -may build dashboards and alerts on them. Change deliberately. - -### Key naming rules - -- `snake_case`, not dotted; `tmux_` prefix. -- Prefer stable scalars; avoid ad-hoc objects. -- Heavy keys (`tmux_stdout`, `tmux_stderr`) are DEBUG-only; consider - companion `tmux_stdout_len` fields or hard truncation (e.g. - `stdout[:100]`). - -### Lazy formatting +Keep list-shaped accessors lenient by default. Add an explicit opt-in +for loud failure rather than changing an existing accessor's contract. -`logger.debug("msg %s", val)` not f-strings. Two rationales: - -- Deferred string interpolation: skipped entirely when level is - filtered. -- Aggregator message template grouping: `"Running %s"` is one signature - grouped ×10,000; f-strings make each line unique. - -When computing `val` itself is expensive, guard with -`if logger.isEnabledFor(logging.DEBUG)`. - -### `stacklevel` for wrappers - -Increment for each wrapper layer so `%(filename)s:%(lineno)d` and OTel -`code.filepath` point to the real caller. Verify whenever call depth -changes. - -### `LoggerAdapter` for persistent context - -For objects with stable identity (Session, Window, Pane), use -`LoggerAdapter` to avoid repeating the same `extra` on every call. Lead -with the portable pattern (override `process()` to merge); -`merge_extra=True` simplifies this on Python 3.13+. - -### Log levels - -| Level | Use for | Examples | -|-------|---------|----------| -| `DEBUG` | Internal mechanics, tmux I/O | tmux command + stdout, format queries | -| `INFO` | Object lifecycle, user-visible operations | Session created, window added | -| `WARNING` | Recoverable issues, deprecation | Deprecated method, missing optional program | -| `ERROR` | Failures that stop an operation | tmux command failed, invalid target | - -### Message style - -- Lowercase, past tense for events: `"session created"`, `"tmux - command failed"`. -- No trailing punctuation. -- Keep messages short; put details in `extra`, not the message string. - -### Exception logging - -- Use `logger.exception()` only inside `except` blocks when you are - **not** re-raising. -- Use `logger.error(..., exc_info=True)` when you need the traceback - outside an `except` block. -- Avoid `logger.exception()` followed by `raise` — this duplicates the - traceback. Either add context via `extra` that would otherwise be - lost, or let the exception propagate. - -### Testing logs +## Logging -Assert on `caplog.records` attributes, not string matching on -`caplog.text`: - -- Scope capture: `caplog.at_level(logging.DEBUG, - logger="libtmux.common")`. -- Filter records rather than index by position: `[r for r in - caplog.records if hasattr(r, "tmux_cmd")]`. -- Assert on schema: `record.tmux_exit_code == 0` not `"exit code 0" in - caplog.text`. -- `caplog.record_tuples` cannot access extra fields — always use - `caplog.records`. - -### Avoid - -- f-strings/`.format()` in log calls. -- Unguarded logging in hot loops (guard with `isEnabledFor()`). -- Catch-log-reraise without adding new context. -- `print()` for diagnostics. -- Logging secret env var values (log key names only). -- Non-scalar ad-hoc objects in `extra`. -- Requiring custom `extra` fields in format strings without safe - defaults (missing keys raise `KeyError`). +### Ownership + +- Use `logging.getLogger(__name__)` only in modules that emit records. +- Keep handlers, levels, and formatters under application control. +- `_internal/log_context.py` owns structured context: + `command_extra(argv)` describes a command and + `object_extra(subcommand, ...)` describes an object operation. +- `tmux_cmd` is the sole producer of subprocess dispatch and + completion records. Do not duplicate them in query or object layers. +- Control mode uses the same command context, then retains it for its + client lifecycle. + +### Command records + +`tmux_cmd` emits `DEBUG` before and after a subprocess. The +`tmux_cmd` field contains a quoted, one-line rendering of the complete argv. +Printable values use shell quoting; control characters use escaped forms. +Completion records retain the first 100 stdout and stderr lines alongside +`tmux_stdout_len` and `tmux_stderr_len`. Keep command-specific redaction, +alias maps, and output classifiers out of the producer; applications select +fields through standard-library handlers and formatters. Treat derived +subcommand and socket fields as best effort and stop parsing unknown options. + +Guard command-context construction with +`logger.isEnabledFor(logging.DEBUG)`. Use lazy interpolation for any +message arguments. + +### Levels and failures + +| Level | Contract | +| ----- | -------- | +| `DEBUG` | Subprocess dispatch/completion and internal lookup details | +| `INFO` | Successful server, session, window, and pane lifecycle events | +| `WARNING` | A recoverable problem libtmux handled, aggregated once per item | +| `ERROR` | A failure libtmux intentionally swallowed | + +Propagated or translated failures stay in their exceptions; do not +catch, log, and re-raise. A non-zero tmux exit is not enough to justify +an `ERROR` because probes use it to answer false. +`Server.is_alive()` stays quiet. + +Normalize executable-launch `ENOENT`, `EACCES`, and `ENOEXEC` errors to +`TmuxCommandNotFound`, preserving the operating-system message and cause. +Keep unrelated `OSError` values native at direct loud APIs. A failed `PATH` +preflight uses a factual message without inventing a cause. + +`Server.sessions` and `Server.clients` log once in +`libtmux.server` when they convert `LibTmuxException` or an OS launch failure +to an empty result. `Server.attached_sessions` inherits that behavior through +`Server.sessions`. The boundary record includes the subcommand, socket, first +100 stderr lines, and total stderr line count. + +Deprecations and ignored arguments use `warnings.warn`, not a second +log record. Applications can route them through +`logging.captureWarnings(True)`. + +### Structured fields + +All fields are optional because each record carries only relevant +context. + +| Field | Type | Meaning | +| ----- | ---- | ------- | +| `tmux_cmd` | `str` | Quoted, one-line complete command | +| `tmux_subcommand` | `str` | tmux subcommand | +| `tmux_socket` | `str` | Socket name or path | +| `tmux_target` | `str` | Target specifier | +| `tmux_session` | `str` | Session name | +| `tmux_window` | `str` | Window name or index | +| `tmux_pane` | `str` | Pane identifier | +| `tmux_exit_code` | `int` | Subprocess exit status | +| `tmux_stdout` | `list[str]` | First 100 stdout lines | +| `tmux_stderr` | `list[str]` | First 100 stderr lines | +| `tmux_stdout_len` | `int` | stdout line count | +| `tmux_stderr_len` | `int` | stderr or error line count | +| `tmux_option_key` | `str` | Option whose entries could not be parsed | +| `tmux_option_skipped` | `int` | Entries skipped for that option | + +Treat field names and types as compatibility-sensitive. Omit unknown +values instead of storing `None`. Keep identity and count fields scalar; +stdout and stderr snapshots are lists of lines. + +### Messages and tests + +- Use short lowercase event messages without trailing punctuation. +- Assert on `caplog.records` fields, not rendered `caplog.text`. +- Scope capture to the emitting logger. +- Pair new record behavior with a deliberate break that proves the + assertion fails. +- Give formatter examples safe `defaults=`; not every record carries + every field. diff --git a/src/libtmux/_internal/control_mode.py b/src/libtmux/_internal/control_mode.py index 05945451eb..c3e90082eb 100644 --- a/src/libtmux/_internal/control_mode.py +++ b/src/libtmux/_internal/control_mode.py @@ -7,10 +7,12 @@ from __future__ import annotations +import logging import os import subprocess import typing as t +from libtmux._internal.log_context import command_extra from libtmux.test.retry import retry_until if t.TYPE_CHECKING: @@ -21,6 +23,10 @@ from libtmux.server import Server from libtmux.session import Session +logger = logging.getLogger(__name__) + +_TERMINATE_TIMEOUT_SECONDS = 5 + class ControlMode: """Context manager that spawns a tmux control-mode client. @@ -80,6 +86,12 @@ def __enter__(self) -> Self: str(self.session.session_id), ] + self._log_extra = { + **command_extra(cmd), + "tmux_subcommand": "attach-session", + "tmux_target": str(self.session.session_id), + } + try: try: self._proc = subprocess.Popen( @@ -98,6 +110,8 @@ def __enter__(self) -> Self: os.close(self._write_fd) raise + logger.debug("control mode client started", extra=self._log_extra) + self.stdout = self._proc.stdout # type: ignore[assignment] client_pid = str(self._proc.pid) @@ -118,12 +132,7 @@ def client_registered() -> bool: retry_until(client_registered, 3, raises=True) except Exception: os.close(self._write_fd) - self._proc.terminate() - try: - self._proc.wait(timeout=5) - except subprocess.TimeoutExpired: - self._proc.kill() - self._proc.wait() + self._terminate() raise return self @@ -138,9 +147,17 @@ def __exit__( # Close write end — causes the control-mode client to exit (EOF on stdin) os.close(self._write_fd) + self._terminate() + + def _terminate(self) -> None: + """Stop the client, escalating to ``SIGKILL`` if it does not exit.""" self._proc.terminate() try: - self._proc.wait(timeout=5) + self._proc.wait(timeout=_TERMINATE_TIMEOUT_SECONDS) except subprocess.TimeoutExpired: + logger.warning( + "control mode client killed after timeout", + extra=self._log_extra, + ) self._proc.kill() self._proc.wait() diff --git a/src/libtmux/_internal/log_context.py b/src/libtmux/_internal/log_context.py new file mode 100644 index 0000000000..f85afe3b1d --- /dev/null +++ b/src/libtmux/_internal/log_context.py @@ -0,0 +1,99 @@ +"""Structured logging context for tmux operations.""" + +from __future__ import annotations + +import os +import shlex +from collections.abc import Sequence + +_VALUE_FLAGS = frozenset("cfLST") +"""tmux global flags that consume a value.""" + +_BOOLEAN_FLAGS = frozenset("2CDdhlNquUvV") +"""tmux global flags that do not consume a value.""" + +LOG_OUTPUT_LINE_LIMIT = 100 +"""Maximum output lines attached to one log record.""" + + +def _safe_scalar(value: str) -> str: + """Keep printable identities readable and escape control characters.""" + return value if value.isprintable() else ascii(value) + + +def _quote(value: str) -> str: + """Quote a printable operation token or escape it as an ASCII literal.""" + return shlex.quote(value) if value.isprintable() else ascii(value) + + +def command_extra(argv: Sequence[str]) -> dict[str, str]: + """Describe a tmux command and derive best-effort structured context.""" + tokens = [str(arg) for arg in argv] + executable = tokens[0] if tokens else "tmux" + subcommand: str | None = None + socket_label: str | None = None + socket_path: str | None = None + + index = 1 + while index < len(tokens): + token = tokens[index] + if token == "--": + index += 1 + if index < len(tokens): + subcommand = tokens[index] + break + if not token.startswith("-") or token == "-": + subcommand = token + break + + known_option = True + takes_next = False + for position, flag in enumerate(token[1:]): + if flag in _BOOLEAN_FLAGS: + continue + if flag not in _VALUE_FLAGS: + known_option = False + break + attached = token[position + 2 :] + value = attached or (tokens[index + 1] if index + 1 < len(tokens) else None) + if flag == "L": + socket_label = value + elif flag == "S": + socket_path = value + takes_next = not attached + break + if not known_option: + break + index += 2 if takes_next else 1 + + socket = socket_path if socket_path is not None else socket_label + extra = {"tmux_cmd": " ".join(_quote(token) for token in (tokens or [executable]))} + if subcommand is not None: + extra["tmux_subcommand"] = _safe_scalar(subcommand) + if socket is not None: + extra["tmux_socket"] = _safe_scalar(socket) + return extra + + +def object_extra( + subcommand: str, + *, + socket: str | os.PathLike[str] | None = None, + session: str | None = None, + window: str | None = None, + pane: str | None = None, + target: str | int | None = None, +) -> dict[str, str]: + """Build structured context for a tmux object lifecycle record.""" + extra = {"tmux_subcommand": subcommand} + if socket is not None: + extra["tmux_socket"] = _safe_scalar(str(socket)) + for key, value in ( + ("tmux_session", session), + ("tmux_window", window), + ("tmux_pane", pane), + ("tmux_target", target), + ): + if value is not None: + extra[key] = _safe_scalar(str(value)) + return extra diff --git a/src/libtmux/_internal/query_list.py b/src/libtmux/_internal/query_list.py index 20aeb407f6..bdc79221c2 100644 --- a/src/libtmux/_internal/query_list.py +++ b/src/libtmux/_internal/query_list.py @@ -102,11 +102,7 @@ def keygetter( dct = getattr(dct, sub_field) except Exception: - logger.debug( - "key lookup failed for path: %s", - path, - exc_info=True, - ) + logger.debug("key lookup failed for path: %r", path) return None return dct @@ -146,11 +142,7 @@ def parse_lookup( if field_name is not None: return keygetter(obj, field_name) except Exception: - logger.debug( - "lookup parsing failed for path: %s", - path, - exc_info=True, - ) + logger.debug("lookup parsing failed for path: %r", path) return None diff --git a/src/libtmux/client.py b/src/libtmux/client.py index 94a19588dd..7283741eb9 100644 --- a/src/libtmux/client.py +++ b/src/libtmux/client.py @@ -8,7 +8,6 @@ from __future__ import annotations import dataclasses -import logging import typing as t from libtmux import exc @@ -21,9 +20,6 @@ from libtmux.window import Window -logger = logging.getLogger(__name__) - - @dataclasses.dataclass() class Client(Obj): """:term:`tmux(1)` :term:`Client` [client_manual]_. diff --git a/src/libtmux/common.py b/src/libtmux/common.py index 2871547700..234be80b75 100644 --- a/src/libtmux/common.py +++ b/src/libtmux/common.py @@ -7,10 +7,10 @@ from __future__ import annotations +import errno import functools import logging import re -import shlex import shutil import subprocess import sys @@ -18,12 +18,14 @@ from . import exc from ._compat import LooseVersion +from ._internal.log_context import LOG_OUTPUT_LINE_LIMIT, command_extra if t.TYPE_CHECKING: from collections.abc import Callable logger = logging.getLogger(__name__) +_UNUSABLE_TMUX_ERRNOS = frozenset({errno.EACCES, errno.ENOENT, errno.ENOEXEC}) #: Minimum version of tmux required to run libtmux TMUX_MIN_VERSION = "3.2a" @@ -37,6 +39,12 @@ PaneDict = dict[str, t.Any] +def _raise_if_unusable_tmux(error: OSError) -> None: + """Translate an unavailable executable while preserving its OS diagnostic.""" + if error.errno in _UNUSABLE_TMUX_ERRNOS: + raise exc.TmuxCommandNotFound(str(error)) from error + + class CmdProtocol(t.Protocol): """Command protocol for tmux command.""" @@ -106,11 +114,6 @@ def set_environment( cmd = self.cmd(*args) if cmd.stderr: - ( - cmd.stderr[0] - if isinstance(cmd.stderr, list) and len(cmd.stderr) == 1 - else cmd.stderr - ) msg = f"tmux set-environment stderr: {cmd.stderr}" raise ValueError(msg) @@ -135,11 +138,6 @@ def unset_environment(self, name: str) -> None: cmd = self.cmd(*args) if cmd.stderr: - ( - cmd.stderr[0] - if isinstance(cmd.stderr, list) and len(cmd.stderr) == 1 - else cmd.stderr - ) msg = f"tmux set-environment stderr: {cmd.stderr}" raise ValueError(msg) @@ -164,11 +162,6 @@ def remove_environment(self, name: str) -> None: cmd = self.cmd(*args) if cmd.stderr: - ( - cmd.stderr[0] - if isinstance(cmd.stderr, list) and len(cmd.stderr) == 1 - else cmd.stderr - ) msg = f"tmux set-environment stderr: {cmd.stderr}" raise ValueError(msg) @@ -303,6 +296,13 @@ class tmux_cmd: $ tmux new-session -s my session + Raises + ------ + :exc:`~libtmux.exc.TmuxCommandNotFound` + When the tmux binary cannot be found or executed. + :class:`OSError` + When the operating system rejects the launch for another reason. + Notes ----- .. versionchanged:: 0.8 @@ -311,21 +311,19 @@ class tmux_cmd: def __init__(self, *args: t.Any, tmux_bin: str | None = None) -> None: resolved = tmux_bin or shutil.which("tmux") - if not resolved: - raise exc.TmuxCommandNotFound - - cmd = [resolved] + cmd = [resolved or "tmux"] cmd += args # add the command arguments to cmd cmd = [str(c) for c in cmd] self.cmd = cmd - if logger.isEnabledFor(logging.DEBUG): - cmd_str = shlex.join(cmd) - logger.debug( - "tmux command dispatched", - extra={"tmux_cmd": cmd_str}, - ) + if not resolved: + msg = "tmux executable not found on PATH" + raise exc.TmuxCommandNotFound(msg) + + log_extra = command_extra(cmd) if logger.isEnabledFor(logging.DEBUG) else None + if log_extra is not None: + logger.debug("tmux command dispatched", extra=log_extra) try: self.process = subprocess.Popen( @@ -336,19 +334,13 @@ def __init__(self, *args: t.Any, tmux_bin: str | None = None) -> None: encoding="utf-8", errors="backslashreplace", ) - stdout, stderr = self.process.communicate() - returncode = self.process.returncode - except FileNotFoundError: - raise exc.TmuxCommandNotFound from None - except Exception: - logger.error( # noqa: TRY400 - "tmux subprocess failed", - extra={ - "tmux_cmd": shlex.join(cmd), - }, - ) + except OSError as error: + _raise_if_unusable_tmux(error) raise + stdout, stderr = self.process.communicate() + returncode = self.process.returncode + self.returncode = returncode stdout_split = stdout.split("\n") @@ -364,14 +356,14 @@ def __init__(self, *args: t.Any, tmux_bin: str | None = None) -> None: else: self.stdout = stdout_split - if logger.isEnabledFor(logging.DEBUG): + if log_extra is not None: logger.debug( "tmux command completed", extra={ - "tmux_cmd": shlex.join(cmd), + **log_extra, "tmux_exit_code": self.returncode, - "tmux_stdout": self.stdout[:100], - "tmux_stderr": self.stderr[:100], + "tmux_stdout": self.stdout[:LOG_OUTPUT_LINE_LIMIT], + "tmux_stderr": self.stderr[:LOG_OUTPUT_LINE_LIMIT], "tmux_stdout_len": len(self.stdout), "tmux_stderr_len": len(self.stderr), }, diff --git a/src/libtmux/exc.py b/src/libtmux/exc.py index 57bb06102f..53947ed8b8 100644 --- a/src/libtmux/exc.py +++ b/src/libtmux/exc.py @@ -96,7 +96,7 @@ class TmuxSessionExists(LibTmuxException): class TmuxCommandNotFound(LibTmuxException): - """Application binary for tmux not found.""" + """Application binary for tmux not found or not executable.""" class NotInsideTmux(LibTmuxException): diff --git a/src/libtmux/hooks.py b/src/libtmux/hooks.py index d9ad24d407..a5c4078759 100644 --- a/src/libtmux/hooks.py +++ b/src/libtmux/hooks.py @@ -312,7 +312,10 @@ def show_hooks( elif len(parts) == 1: key, val = parts[0], None else: - logger.warning("failed to extract hook: %s", item) + logger.warning( + "hook parse failed", + extra={"tmux_subcommand": "show-hooks"}, + ) continue if isinstance(val, str) and val.isdigit(): diff --git a/src/libtmux/neo.py b/src/libtmux/neo.py index 98ece86fa5..9cc7a8eec6 100644 --- a/src/libtmux/neo.py +++ b/src/libtmux/neo.py @@ -4,8 +4,6 @@ import dataclasses import functools -import logging -import shlex import typing as t from collections.abc import Iterable @@ -20,9 +18,6 @@ from libtmux.server import Server -logger = logging.getLogger(__name__) - - OutputRaw = dict[str, t.Any] OutputsRaw = list[OutputRaw] @@ -1118,18 +1113,6 @@ def fetch_objs( tmux_cmds.append(f"-F{format_string}") - cmd_str: str | None = None - - if logger.isEnabledFor(logging.DEBUG): - cmd_str = shlex.join([str(x) for x in tmux_cmds]) - logger.debug( - "tmux list queried", - extra={ - "tmux_subcommand": list_cmd, - "tmux_cmd": cmd_str, - }, - ) - proc = tmux_cmd( *tmux_cmds, tmux_bin=server.tmux_bin, @@ -1137,21 +1120,7 @@ def fetch_objs( raise_if_stderr(proc, list_cmd) - outputs = [parse_output(line, list_cmd, tmux_version) for line in proc.stdout] - - if logger.isEnabledFor(logging.DEBUG): - if cmd_str is None: - cmd_str = shlex.join([str(x) for x in tmux_cmds]) - logger.debug( - "tmux list parsed", - extra={ - "tmux_subcommand": list_cmd, - "tmux_cmd": cmd_str, - "tmux_stdout_len": len(proc.stdout), - }, - ) - - return outputs + return [parse_output(line, list_cmd, tmux_version) for line in proc.stdout] def _is_target_not_found_error(stderr_text: str) -> bool: @@ -1348,10 +1317,7 @@ def fetch_obj( list_extra_args=list_extra_args, ) except exc.LibTmuxException as e: - # A ``-t``-scoped listing pushes the "does it exist?" question down - # into tmux, which answers on stderr rather than with an empty listing. - # Re-raise those as the same TmuxObjectDoesNotExist an unscoped listing - # would have produced; anything else (a dead server) keeps propagating. + # Scoped missing targets arrive on stderr; keep lookup semantics aligned. if not _is_target_not_found_error(str(e)): raise raise exc.TmuxObjectDoesNotExist( diff --git a/src/libtmux/options.py b/src/libtmux/options.py index ff8bb2239d..9bb7a795b5 100644 --- a/src/libtmux/options.py +++ b/src/libtmux/options.py @@ -436,6 +436,15 @@ def explode_arrays( return options +def _warn_skipped(key: str, skipped: int) -> None: + """Report unparseable entries for one option, once rather than per entry.""" + if skipped: + logger.warning( + "tmux options parse failed", + extra={"tmux_option_key": key, "tmux_option_skipped": skipped}, + ) + + def explode_complex( _dict: ExplodedUntypedOptionsDict, ) -> ExplodedComplexUntypedOptionsDict: @@ -510,20 +519,20 @@ def explode_complex( try: if isinstance(val, SparseArray) and key == "terminal-features": new_val: TerminalFeatures = {} + skipped = 0 for item in val.iter_values(): try: term, features = item.split(":", maxsplit=1) new_val[term] = features.split(":") except Exception: # NOQA: PERF203 - logger.warning( - "tmux options parse failed", - extra={"tmux_option_key": key}, - ) + skipped += 1 + _warn_skipped(key, skipped) options[key] = new_val continue if isinstance(val, SparseArray) and key == "terminal-overrides": new_overrides: TerminalOverrides = {} + skipped = 0 for item in val.iter_values(): try: @@ -543,14 +552,13 @@ def explode_complex( elif feature: new_overrides[term][feature] = None except Exception: # NOQA: PERF203 - logger.warning( - "tmux options parse failed", - extra={"tmux_option_key": key}, - ) + skipped += 1 + _warn_skipped(key, skipped) options[key] = new_overrides continue if isinstance(val, SparseArray) and key == "command-alias": new_aliases: CommandAliases = {} + skipped = 0 for item in val.iter_values(): try: @@ -562,10 +570,8 @@ def explode_complex( options[key] = {} new_aliases[alias] = command except Exception: # NOQA: PERF203 - logger.warning( - "tmux options parse failed", - extra={"tmux_option_key": key}, - ) + skipped += 1 + _warn_skipped(key, skipped) options[key] = new_aliases continue options[key] = val diff --git a/src/libtmux/pane.py b/src/libtmux/pane.py index e0c2f59619..be020cc618 100644 --- a/src/libtmux/pane.py +++ b/src/libtmux/pane.py @@ -15,7 +15,13 @@ from libtmux import exc from libtmux._internal.env import pane_id_from_env -from libtmux.common import get_version_str, has_gte_version, raise_if_stderr, tmux_cmd +from libtmux._internal.log_context import object_extra +from libtmux.common import ( + get_version_str, + has_gte_version, + raise_if_stderr, + tmux_cmd, +) from libtmux.constants import ( PANE_DIRECTION_FLAG_MAP, RESIZE_ADJUSTMENT_DIRECTION_FLAG_MAP, @@ -1070,14 +1076,15 @@ def kill( raise_if_stderr(proc, "kill-pane") - extra: dict[str, str] = { - "tmux_subcommand": "kill-pane", - } - if self.pane_id is not None: - extra["tmux_pane"] = str(self.pane_id) - extra["tmux_target"] = str(self.pane_id) - msg = "other panes killed" if all_except else "pane killed" - logger.info(msg, extra=extra) + logger.info( + "other panes killed" if all_except else "pane killed", + extra=object_extra( + "kill-pane", + socket=self.server.socket_path or self.server.socket_name, + pane=self.pane_id, + target=self.pane_id, + ), + ) """ Commands ("climber"-helpers) @@ -1415,18 +1422,17 @@ def split( pane = self.from_pane_id(server=self.server, pane_id=pane_formatters["pane_id"]) - extra: dict[str, str] = { - "tmux_subcommand": "split-window", - "tmux_pane": str(pane.pane_id), - } - if self.session.session_name is not None: - extra["tmux_session"] = str(self.session.session_name) - if self.window.window_name is not None: - extra["tmux_window"] = str(self.window.window_name) - if target is not None: - extra["tmux_target"] = str(target) - - logger.info("pane created", extra=extra) + logger.info( + "pane created", + extra=object_extra( + "split-window", + socket=self.server.socket_path or self.server.socket_name, + session=self.session.session_name, + window=self.window.window_name, + pane=pane.pane_id, + target=target, + ), + ) return pane @@ -1575,18 +1581,17 @@ def new_pane( pane = self.from_pane_id(server=self.server, pane_id=pane_formatters["pane_id"]) - extra: dict[str, str] = { - "tmux_subcommand": "new-pane", - "tmux_pane": str(pane.pane_id), - } - if self.session.session_name is not None: - extra["tmux_session"] = str(self.session.session_name) - if self.window.window_name is not None: - extra["tmux_window"] = str(self.window.window_name) - if target is not None: - extra["tmux_target"] = str(target) - - logger.info("floating pane created", extra=extra) + logger.info( + "floating pane created", + extra=object_extra( + "new-pane", + socket=self.server.socket_path or self.server.socket_name, + session=self.session.session_name, + window=self.window.window_name, + pane=pane.pane_id, + target=target, + ), + ) return pane diff --git a/src/libtmux/pytest_plugin.py b/src/libtmux/pytest_plugin.py index fcc3ce052d..772ae364de 100644 --- a/src/libtmux/pytest_plugin.py +++ b/src/libtmux/pytest_plugin.py @@ -14,6 +14,7 @@ from libtmux import exc from libtmux._internal.control_mode import ControlMode +from libtmux._internal.log_context import object_extra from libtmux.server import Server from libtmux.test.constants import TEST_SESSION_PREFIX from libtmux.test.random import get_test_session_name, namer @@ -286,10 +287,11 @@ def session( server.kill_session(old_test_session) logger.debug( "old test session killed", - extra={ - "tmux_session": old_test_session, - "tmux_subcommand": "kill-session", - }, + extra=object_extra( + "kill-session", + socket=server.socket_path or server.socket_name, + session=old_test_session, + ), ) assert session.session_name == TEST_SESSION_NAME assert TEST_SESSION_NAME != "tmuxp" diff --git a/src/libtmux/server.py b/src/libtmux/server.py index e650557c34..673aeeae21 100644 --- a/src/libtmux/server.py +++ b/src/libtmux/server.py @@ -17,9 +17,16 @@ from libtmux import exc from libtmux._internal.env import socket_path_from_env +from libtmux._internal.log_context import LOG_OUTPUT_LINE_LIMIT, object_extra from libtmux._internal.query_list import QueryList from libtmux.client import Client -from libtmux.common import get_version, has_gte_version, raise_if_stderr, tmux_cmd +from libtmux.common import ( + _raise_if_unusable_tmux, + get_version, + has_gte_version, + raise_if_stderr, + tmux_cmd, +) from libtmux.constants import OptionScope from libtmux.hooks import HooksMixin from libtmux.neo import fetch_objs, get_output_format, parse_output @@ -82,6 +89,27 @@ def _fetch_or_empty( raise +def _log_swallowed_list_error( + server: Server, + list_cmd: str, + error: Exception, +) -> None: + """Record a list failure at the boundary that converts it to empty.""" + stderr = str(error).splitlines() + logger.error( + "tmux command failed", + extra={ + **object_extra( + list_cmd, + socket=server.socket_path or server.socket_name, + ), + "tmux_stderr": stderr[:LOG_OUTPUT_LINE_LIMIT], + "tmux_stderr_len": len(stderr), + }, + stacklevel=2, + ) + + class Server( EnvironmentMixin, OptionsMixin, @@ -306,9 +334,13 @@ def raise_if_dead(self) -> None: ------ :exc:`exc.TmuxCommandNotFound` When the tmux binary cannot be found or executed. + When the operating system attempted the launch, its diagnostic is + available as the exception message and cause. :class:`subprocess.CalledProcessError` When the tmux server is not running (non-zero exit from ``list-sessions``). + :class:`OSError` + When the operating system rejects the launch for another reason. >>> tmux = Server(socket_name="no_exist") >>> try: @@ -319,7 +351,8 @@ def raise_if_dead(self) -> None: """ resolved = self.tmux_bin or shutil.which("tmux") if resolved is None: - raise exc.TmuxCommandNotFound + msg = "tmux executable not found on PATH" + raise exc.TmuxCommandNotFound(msg) cmd_args: list[str] = ["list-sessions"] if self.socket_name: @@ -331,8 +364,9 @@ def raise_if_dead(self) -> None: try: subprocess.check_call([resolved, *cmd_args]) - except FileNotFoundError: - raise exc.TmuxCommandNotFound from None + except OSError as error: + _raise_if_unusable_tmux(error) + raise # # Command @@ -478,7 +512,13 @@ def kill(self) -> None: if _is_daemon_not_up_error(stderr_text): return raise exc.LibTmuxException(proc.stderr) - logger.info("server killed", extra={"tmux_subcommand": "kill-server"}) + logger.info( + "server killed", + extra=object_extra( + "kill-server", + socket=self.socket_path or self.socket_name, + ), + ) def kill_session(self, target_session: str | int) -> Server: """Kill tmux session. @@ -501,6 +541,15 @@ def kill_session(self, target_session: str | int) -> Server: raise_if_stderr(proc, "kill-session") + logger.info( + "session killed", + extra=object_extra( + "kill-session", + socket=self.socket_path or self.socket_name, + target=target_session, + ), + ) + return self def run_shell( @@ -2306,10 +2355,11 @@ def new_session( raise_if_stderr(proc, "kill-session") logger.info( "existing session killed", - extra={ - "tmux_session": session_name, - "tmux_subcommand": "kill-session", - }, + extra=object_extra( + "kill-session", + socket=self.socket_path or self.socket_name, + session=session_name, + ), ) else: msg = f"Session named {session_name} exists" @@ -2317,12 +2367,14 @@ def new_session( msg, ) - extra: dict[str, str] = { - "tmux_subcommand": "new-session", - } - if session_name is not None: - extra["tmux_session"] = str(session_name) - logger.debug("creating session", extra=extra) + logger.debug( + "creating session", + extra=object_extra( + "new-session", + socket=self.socket_path or self.socket_name, + session=session_name, + ), + ) env = os.environ.get("TMUX") @@ -2387,12 +2439,15 @@ def new_session( session = Session(server=self, **session_data) - info_extra: dict[str, str] = { - "tmux_subcommand": "new-session", - } - if session.session_name is not None: - info_extra["tmux_session"] = str(session.session_name) - logger.info("session created", extra=info_extra) + logger.info( + "session created", + extra=object_extra( + "new-session", + socket=self.socket_path or self.socket_name, + session=session.session_name, + target=session.session_id, + ), + ) return session @@ -2411,14 +2466,17 @@ def sessions(self) -> QueryList[Session]: tmux's ``list-sessions`` fails for any reason — no running daemon, a missing socket, a permission error, or a subprocess failure. To distinguish "no sessions" from "tmux unreachable", call - :meth:`Server.is_alive` or :meth:`Server.raise_if_dead`. + :meth:`Server.is_alive` or :meth:`Server.raise_if_dead`. The swallowed + failure is also logged once at ``ERROR`` on ``libtmux.server``; see + :ref:`logging`. """ try: sessions: list[Session] = [ Session(server=self, **obj) for obj in fetch_objs(server=self, list_cmd="list-sessions") ] - except exc.LibTmuxException: + except (exc.LibTmuxException, OSError) as error: + _log_swallowed_list_error(self, "list-sessions", error) return QueryList([]) return QueryList(sessions) @@ -2472,7 +2530,8 @@ def clients(self) -> QueryList[Client]: tmux's ``list-clients`` fails for any reason — no running daemon, a missing socket, a permission error, or a subprocess failure. To distinguish "no clients attached" from "tmux unreachable", call - :meth:`Server.is_alive` or :meth:`Server.raise_if_dead`. + :meth:`Server.is_alive` or :meth:`Server.raise_if_dead`. The swallowed + failure is logged once at ``ERROR`` on ``libtmux.server``. Returns ------- @@ -2490,7 +2549,8 @@ def clients(self) -> QueryList[Client]: Client(server=self, **obj) for obj in fetch_objs(server=self, list_cmd="list-clients") ] - except exc.LibTmuxException: + except (exc.LibTmuxException, OSError) as error: + _log_swallowed_list_error(self, "list-clients", error) return QueryList([]) return QueryList(clients) diff --git a/src/libtmux/session.py b/src/libtmux/session.py index 4277052a37..d69909de31 100644 --- a/src/libtmux/session.py +++ b/src/libtmux/session.py @@ -13,6 +13,7 @@ import typing as t import warnings +from libtmux._internal.log_context import object_extra from libtmux._internal.query_list import QueryList from libtmux.common import has_gte_version, raise_if_stderr, tmux_cmd from libtmux.constants import WINDOW_DIRECTION_FLAG_MAP, OptionScope, WindowDirection @@ -738,15 +739,15 @@ def kill( raise_if_stderr(proc, "kill-session") - msg = "other sessions killed" if all_except else "session killed" - extra: dict[str, str] = { - "tmux_subcommand": "kill-session", - } - if self.session_name is not None: - extra["tmux_session"] = str(self.session_name) - if self.session_id is not None: - extra["tmux_target"] = str(self.session_id) - logger.info(msg, extra=extra) + logger.info( + "other sessions killed" if all_except else "session killed", + extra=object_extra( + "kill-session", + socket=self.server.socket_path or self.server.socket_name, + session=self.session_name, + target=self.session_id, + ), + ) def switch_client(self) -> Session: """Switch client to session. @@ -781,13 +782,15 @@ def rename_session(self, new_name: str) -> Session: self.refresh() - extra: dict[str, str] = { - "tmux_subcommand": "rename-session", - "tmux_session": new_name, - } - if self.session_id is not None: - extra["tmux_target"] = str(self.session_id) - logger.info("session renamed", extra=extra) + logger.info( + "session renamed", + extra=object_extra( + "rename-session", + socket=self.server.socket_path or self.server.socket_name, + session=new_name, + target=self.session_id, + ), + ) return self @@ -942,17 +945,16 @@ def new_window( window_id=window_formatters["window_id"], ) - extra: dict[str, str] = { - "tmux_subcommand": "new-window", - } - if self.session_name is not None: - extra["tmux_session"] = str(self.session_name) - if window.window_name is not None: - extra["tmux_window"] = str(window.window_name) - if target is not None: - extra["tmux_target"] = str(target) - - logger.info("window created", extra=extra) + logger.info( + "window created", + extra=object_extra( + "new-window", + socket=self.server.socket_path or self.server.socket_name, + session=self.session_name, + window=window.window_name, + target=target, + ), + ) return window @@ -983,14 +985,15 @@ def kill_window(self, target_window: str | int | None = None) -> None: raise_if_stderr(proc, "kill-window") - extra: dict[str, str] = { - "tmux_subcommand": "kill-window", - } - if self.session_name is not None: - extra["tmux_session"] = str(self.session_name) - if target is not None: - extra["tmux_target"] = str(target) - logger.info("window killed", extra=extra) + logger.info( + "window killed", + extra=object_extra( + "kill-window", + socket=self.server.socket_path or self.server.socket_name, + session=self.session_name, + target=target, + ), + ) # # Dunder diff --git a/src/libtmux/window.py b/src/libtmux/window.py index b57db99692..aa4a32a7ba 100644 --- a/src/libtmux/window.py +++ b/src/libtmux/window.py @@ -14,6 +14,7 @@ import typing as t import warnings +from libtmux._internal.log_context import object_extra from libtmux._internal.query_list import QueryList from libtmux.common import has_gte_version, raise_if_stderr, tmux_cmd from libtmux.constants import ( @@ -1385,14 +1386,15 @@ def rename_window(self, new_name: str) -> Window: self.window_name = new_name self.refresh() - extra: dict[str, str] = { - "tmux_subcommand": "rename-window", - } - if self.window_name is not None: - extra["tmux_window"] = str(self.window_name) - if self.window_id is not None: - extra["tmux_target"] = str(self.window_id) - logger.info("window renamed", extra=extra) + logger.info( + "window renamed", + extra=object_extra( + "rename-window", + socket=self.server.socket_path or self.server.socket_name, + window=self.window_name, + target=self.window_id, + ), + ) return self @@ -1448,15 +1450,15 @@ def kill( raise_if_stderr(proc, "kill-window") - msg = "other windows killed" if all_except else "window killed" - extra: dict[str, str] = { - "tmux_subcommand": "kill-window", - } - if self.window_name is not None: - extra["tmux_window"] = str(self.window_name) - if self.window_id is not None: - extra["tmux_target"] = str(self.window_id) - logger.info(msg, extra=extra) + logger.info( + "other windows killed" if all_except else "window killed", + extra=object_extra( + "kill-window", + socket=self.server.socket_path or self.server.socket_name, + window=self.window_name, + target=self.window_id, + ), + ) def move_window( self, diff --git a/tests/test_control_mode.py b/tests/test_control_mode.py index f72f68466b..7de2fb1097 100644 --- a/tests/test_control_mode.py +++ b/tests/test_control_mode.py @@ -4,8 +4,10 @@ import locale import os -import select +import queue import sys +import threading +import time import typing as t import pytest @@ -14,9 +16,65 @@ from libtmux.formats import FORMAT_SEPARATOR if t.TYPE_CHECKING: + from collections.abc import Iterator + from libtmux.server import Server +def _read_lines( + stream: t.IO[str], + *, + limit: int, + timeout: float, +) -> Iterator[str]: + """Yield up to *limit* lines from *stream*, giving up after *timeout*. + + A reader thread owns the stream and the caller polls a queue, so the wait + is bounded without anything having to ask the file descriptor whether a + line is available. + + That question has no useful answer here. ``ControlMode`` builds its + subprocess with ``text=True``, so ``stream`` is a ``TextIOWrapper`` over a + ``BufferedReader``: ``select`` would report readiness on the raw + descriptor while ``readline`` serves from the userspace buffer above it. + tmux writes a whole ``%begin``/``%end`` block in one burst, so the first + ``readline`` routinely drains every remaining line off the descriptor -- + leaving ``select`` with nothing to report and the answer already in hand. + """ + lines: queue.Queue[str | BaseException | None] = queue.Queue() + + def pump() -> None: + try: + for line in stream: + lines.put(line) + except BaseException as e: # noqa: BLE001 + # Carry it across the thread boundary. Collapsing it into the + # ``None`` sentinel would report the reader as having reached EOF, + # naming the wrong cause for a decode error this test exists to + # catch. + lines.put(e) + finally: + lines.put(None) + + reader = threading.Thread(target=pump, daemon=True) + reader.start() + + deadline = time.monotonic() + timeout + for _ in range(limit): + remaining = deadline - time.monotonic() + if remaining <= 0: + pytest.fail("timed out waiting for control-mode output") + try: + line = lines.get(timeout=remaining) + except queue.Empty: + pytest.fail("timed out waiting for control-mode output") + if isinstance(line, BaseException): + raise line + if line is None: + pytest.fail("control-mode stream closed before the expected output") + yield line + + def test_control_mode_creates_client( control_mode: t.Callable[[], ControlMode], server: Server, @@ -86,11 +144,7 @@ def test_control_mode_stdout_preserves_non_ascii_output( f"display-message -p '{FORMAT_SEPARATOR}'\n".encode(), ) - for _ in range(20): - ready, _, _ = select.select([ctl.stdout], [], [], 1) - assert ready, "timed out waiting for control-mode output" - - line = ctl.stdout.readline() + for line in _read_lines(ctl.stdout, limit=20, timeout=5): if FORMAT_SEPARATOR in line: break else: diff --git a/tests/test_logging.py b/tests/test_logging.py index ffbdd9a49b..db33318e5b 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,317 +1,851 @@ -"""Tests for libtmux logging standards compliance.""" +"""Tests for libtmux logging contracts.""" from __future__ import annotations +import errno import logging -import types +import os +import pathlib +import shlex +import sys import typing as t +from collections.abc import Callable import pytest if t.TYPE_CHECKING: + from libtmux._internal.control_mode import ControlMode from libtmux.server import Server from libtmux.session import Session -def test_tmux_cmd_debug_logging_schema( - server: Server, +def _capture_info( caplog: pytest.LogCaptureFixture, -) -> None: - """Test that tmux_cmd produces structured log records per AGENTS.md.""" - with caplog.at_level(logging.DEBUG, logger="libtmux.common"): - server.cmd("list-sessions") - records = [r for r in caplog.records if hasattr(r, "tmux_exit_code")] - assert len(records) >= 1 - record = t.cast(t.Any, records[0]) - assert isinstance(record.tmux_cmd, str) - assert isinstance(record.tmux_exit_code, int) + logger_name: str, + message: str, + action: Callable[[], object], +) -> tuple[t.Any, t.Any]: + """Run one action and return its single matching lifecycle record.""" + caplog.clear() + with caplog.at_level(logging.DEBUG, logger=logger_name): + result = action() + + records = [ + record + for record in caplog.records + if record.name == logger_name + and record.levelno == logging.INFO + and record.getMessage() == message + ] + assert len(records) == 1 + return result, t.cast(t.Any, records[0]) -def test_lifecycle_info_logging_schema( +def test_tmux_cmd_debug_logging_schema( session: Session, caplog: pytest.LogCaptureFixture, ) -> None: - """Test that lifecycle operations produce INFO records with str-typed extra.""" - with caplog.at_level(logging.INFO, logger="libtmux.session"): - window = session.new_window(window_name="log_test") + """Command records expose the command and bounded output snapshots.""" + server = session.server + marker = "caller-payload" + + with caplog.at_level(logging.DEBUG, logger="libtmux.common"): + proc = server.cmd("list-sessions", "-F", marker) + assert marker in proc.stdout records = [ - r - for r in caplog.records - if hasattr(r, "tmux_subcommand") and r.levelno == logging.INFO + record + for record in caplog.records + if record.getMessage().startswith("tmux command") + ] + assert [record.getMessage() for record in records] == [ + "tmux command dispatched", + "tmux command completed", ] - assert len(records) >= 1, "expected at least one INFO lifecycle record" - for record in records: rec = t.cast(t.Any, record) - for key in ("tmux_subcommand", "tmux_session", "tmux_window", "tmux_target"): - val = getattr(rec, key, None) - if val is not None: - assert isinstance(val, str), ( - f"extra key {key!r} should be str, got {type(val).__name__}" - ) - - window.kill() - - -def test_server_new_session_info_logging( - server: Server, + assert rec.tmux_subcommand == "list-sessions" + assert rec.tmux_socket == server.socket_name + assert rec.tmux_cmd.endswith(f"list-sessions -F {marker}") + + dispatched = t.cast(t.Any, records[0]) + assert not hasattr(dispatched, "tmux_stdout") + assert not hasattr(dispatched, "tmux_stderr") + completed = t.cast(t.Any, records[-1]) + assert isinstance(completed.tmux_exit_code, int) + assert completed.tmux_stdout == proc.stdout + assert completed.tmux_stderr == proc.stderr + assert completed.tmux_stdout_len == len(proc.stdout) + assert completed.tmux_stderr_len == 0 + + +def test_fetch_objs_emits_one_command_record_pair( + session: Session, caplog: pytest.LogCaptureFixture, ) -> None: - """Test that server.new_session() produces INFO record with str-typed extra.""" - with caplog.at_level(logging.INFO, logger="libtmux.server"): - new_session = server.new_session(session_name="log_test_session") + """A query emits one dispatch/completion pair without duplicate records.""" + from libtmux.neo import fetch_objs + + with caplog.at_level(logging.DEBUG, logger="libtmux"): + fetch_objs(server=session.server, list_cmd="list-sessions") records = [ - r - for r in caplog.records - if hasattr(r, "tmux_subcommand") - and r.levelno == logging.INFO - and getattr(r, "tmux_subcommand", None) == "new-session" + record + for record in caplog.records + if getattr(record, "tmux_subcommand", None) == "list-sessions" + ] + assert [(record.name, record.getMessage()) for record in records] == [ + ("libtmux.common", "tmux command dispatched"), + ("libtmux.common", "tmux command completed"), ] - assert len(records) >= 1, "expected INFO record for session creation" - - rec = t.cast(t.Any, records[0]) - assert isinstance(rec.tmux_subcommand, str) - assert isinstance(rec.tmux_session, str) - - new_session.kill() -def test_server_kill_info_logging( +def test_tmux_cmd_debug_logging_bounds_large_output( caplog: pytest.LogCaptureFixture, ) -> None: - """Test that server.kill() emits a lifecycle INFO record.""" - from libtmux.server import Server - from libtmux.test.random import namer - - with Server(socket_name=f"libtmux_log_{next(namer)}") as temp_server: - temp_server.new_session(session_name=f"log_session_{next(namer)}") - caplog.clear() + """Completion records retain 100 lines and report the full stream lengths.""" + from libtmux.common import tmux_cmd + + stdout_lines = [f"stdout-{index}-π-\x1b[31m" for index in range(150)] + stderr_lines = [f"stderr-{index}-π-\x1b[31m" for index in range(150)] + script = ( + "import sys\n" + "for index in range(150):\n" + " print(f'stdout-{index}-π-\\x1b[31m')\n" + " print(f'stderr-{index}-π-\\x1b[31m', file=sys.stderr)\n" + ) - with caplog.at_level(logging.INFO, logger="libtmux.server"): - temp_server.kill() + with caplog.at_level(logging.DEBUG, logger="libtmux.common"): + proc = tmux_cmd("-c", script, tmux_bin=sys.executable) + + completed = t.cast( + t.Any, + next( + record + for record in caplog.records + if record.getMessage() == "tmux command completed" + ), + ) + assert proc.stdout == stdout_lines + assert proc.stderr == stderr_lines + assert completed.tmux_stdout == stdout_lines[:100] + assert completed.tmux_stderr == stderr_lines[:100] + assert completed.tmux_stdout_len == 150 + assert completed.tmux_stderr_len == 150 - records = [ - r - for r in caplog.records - if getattr(r, "tmux_subcommand", None) == "kill-server" - and r.levelno == logging.INFO - ] - assert len(records) >= 1, "expected INFO record for server kill" - rec = t.cast(t.Any, records[0]) - assert rec.getMessage() == "server killed" - assert isinstance(rec.tmux_subcommand, str) +def test_control_mode_debug_logging_keeps_command_context( + control_mode: Callable[[], ControlMode], + caplog: pytest.LogCaptureFixture, +) -> None: + """Control mode exposes the spawned command and structured target fields.""" + with ( + caplog.at_level(logging.DEBUG, logger="libtmux._internal.control_mode"), + control_mode() as client, + ): + target = str(client.session.session_id) + + record = t.cast( + t.Any, + next( + record + for record in caplog.records + if record.getMessage() == "control mode client started" + ), + ) + assert record.tmux_subcommand == "attach-session" + assert record.tmux_target == target + assert "-C attach-session -t" in record.tmux_cmd + assert shlex.split(record.tmux_cmd)[-1] == target -def test_window_rename_info_logging( - session: Session, +def test_lifecycle_info_logging( + server: Server, caplog: pytest.LogCaptureFixture, ) -> None: - """Test that window.rename_window() produces INFO record with str-typed extra.""" - window = session.active_window - assert window is not None - with caplog.at_level(logging.INFO, logger="libtmux.window"): - window.rename_window("log_renamed") + """Lifecycle call sites emit the shared string-valued context schema.""" + from libtmux._internal.log_context import object_extra + from libtmux.test.random import namer + + session_name = f"log_session_{next(namer)}" + renamed_session = f"log_session_{next(namer)}" + window_name = f"log_window_{next(namer)}" + renamed_window = f"log_window_{next(namer)}" + + session, session_created = _capture_info( + caplog, + "libtmux.server", + "session created", + lambda: server.new_session(session_name=session_name), + ) + session_creating = t.cast( + t.Any, + next( + record + for record in caplog.records + if record.levelno == logging.DEBUG + and record.getMessage() == "creating session" + ), + ) + _, session_renamed = _capture_info( + caplog, + "libtmux.session", + "session renamed", + lambda: session.rename_session(renamed_session), + ) + window, window_created = _capture_info( + caplog, + "libtmux.session", + "window created", + lambda: session.new_window(window_name=window_name), + ) + _, window_renamed = _capture_info( + caplog, + "libtmux.window", + "window renamed", + lambda: window.rename_window(renamed_window), + ) + pane = window.active_pane + assert pane is not None + split_pane, pane_created = _capture_info( + caplog, + "libtmux.pane", + "pane created", + pane.split, + ) + _, pane_killed = _capture_info( + caplog, + "libtmux.pane", + "pane killed", + split_pane.kill, + ) + _, window_killed = _capture_info( + caplog, + "libtmux.session", + "window killed", + lambda: session.kill_window(window.window_id), + ) + doomed_name = f"log_session_{next(namer)}" + doomed, _ = _capture_info( + caplog, + "libtmux.server", + "session created", + lambda: server.new_session(session_name=doomed_name), + ) + _, session_killed = _capture_info( + caplog, + "libtmux.server", + "session killed", + lambda: server.kill_session(doomed_name), + ) + replacement, existing_session_killed = _capture_info( + caplog, + "libtmux.server", + "existing session killed", + lambda: server.new_session(session_name=renamed_session, kill_session=True), + ) + assert replacement.session_name == renamed_session records = [ - r - for r in caplog.records - if hasattr(r, "tmux_subcommand") - and r.levelno == logging.INFO - and getattr(r, "tmux_subcommand", None) == "rename-window" + session_created, + session_renamed, + window_created, + window_renamed, + pane_created, + pane_killed, + window_killed, + session_killed, + existing_session_killed, ] - assert len(records) >= 1, "expected INFO record for window rename" - - rec = t.cast(t.Any, records[0]) - assert isinstance(rec.tmux_subcommand, str) - for key in ("tmux_window", "tmux_target"): - val = getattr(rec, key, None) - if val is not None: - assert isinstance(val, str), ( - f"extra key {key!r} should be str, got {type(val).__name__}" - ) + assert [ + (record.name, record.getMessage(), record.tmux_subcommand) for record in records + ] == [ + ("libtmux.server", "session created", "new-session"), + ("libtmux.session", "session renamed", "rename-session"), + ("libtmux.session", "window created", "new-window"), + ("libtmux.window", "window renamed", "rename-window"), + ("libtmux.pane", "pane created", "split-window"), + ("libtmux.pane", "pane killed", "kill-pane"), + ("libtmux.session", "window killed", "kill-window"), + ("libtmux.server", "session killed", "kill-session"), + ("libtmux.server", "existing session killed", "kill-session"), + ] + for record in records: + assert record.tmux_socket == server.socket_name + for key in ( + "tmux_subcommand", + "tmux_socket", + "tmux_session", + "tmux_window", + "tmux_pane", + "tmux_target", + ): + value = getattr(record, key, None) + assert value is None or isinstance(value, str) + + assert session_created.tmux_session == session_name + assert ( + session_creating.name, + session_creating.tmux_subcommand, + session_creating.tmux_socket, + session_creating.tmux_session, + ) == ("libtmux.server", "new-session", server.socket_name, session_name) + assert session_renamed.tmux_session == renamed_session + assert window_created.tmux_window == window_name + assert window_renamed.tmux_window == renamed_window + assert pane_created.tmux_pane == split_pane.pane_id + assert pane_killed.tmux_pane == split_pane.pane_id + assert window_killed.tmux_target == window.window_id + assert session_killed.tmux_target == doomed.session_name + assert existing_session_killed.tmux_session == renamed_session + assert ( + object_extra("kill-session", target="safe\u2028ERROR forged")["tmux_target"] + == "'safe\\u2028ERROR forged'" + ) -def test_window_kill_all_except_logging( - session: Session, +def test_direct_kill_lifecycle_logging( + server: Server, caplog: pytest.LogCaptureFixture, ) -> None: - """Test that window.kill(all_except=True) identifies the surviving window.""" + """Direct kill branches identify the affected or preserved object.""" from libtmux.test.random import namer - survivor = session.new_window(window_name=f"log_survivor_{next(namer)}") - other_windows = [ - session.new_window(window_name=f"log_other_{next(namer)}"), - session.new_window(window_name=f"log_other_{next(namer)}"), - ] + workspace = server.new_session(session_name=f"log_workspace_{next(namer)}") + window = workspace.new_window(window_name=f"log_window_{next(namer)}") + workspace.new_window(window_name=f"log_other_{next(namer)}") + _, windows_killed = _capture_info( + caplog, + "libtmux.window", + "other windows killed", + lambda: window.kill(all_except=True), + ) + window.resize(height=100, width=100) + pane = window.split() + window.split() + _, panes_killed = _capture_info( + caplog, + "libtmux.pane", + "other panes killed", + lambda: pane.kill(all_except=True), + ) + workspace.new_window(window_name=f"log_spare_{next(namer)}") + _, window_killed = _capture_info( + caplog, + "libtmux.window", + "window killed", + window.kill, + ) - with caplog.at_level(logging.INFO, logger="libtmux.window"): - survivor.kill(all_except=True) + survivor = server.new_session(session_name=f"log_survivor_{next(namer)}") + server.new_session(session_name=f"log_other_{next(namer)}") + _, sessions_killed = _capture_info( + caplog, + "libtmux.session", + "other sessions killed", + lambda: survivor.kill(all_except=True), + ) + server.new_session(session_name=f"log_spare_{next(namer)}") + _, session_killed = _capture_info( + caplog, + "libtmux.session", + "session killed", + survivor.kill, + ) - records = [ - r - for r in caplog.records - if getattr(r, "tmux_subcommand", None) == "kill-window" - and r.levelno == logging.INFO - ] - assert len(records) >= 1, "expected INFO record for all-except window kill" + for record in (windows_killed, window_killed): + assert ( + record.tmux_subcommand, + record.tmux_window, + record.tmux_target, + ) == ("kill-window", window.window_name, window.window_id) + assert ( + panes_killed.tmux_subcommand, + panes_killed.tmux_pane, + panes_killed.tmux_target, + ) == ("kill-pane", pane.pane_id, pane.pane_id) + for record in (sessions_killed, session_killed): + assert ( + record.tmux_subcommand, + record.tmux_session, + record.tmux_target, + ) == ("kill-session", survivor.session_name, survivor.session_id) + + +def test_server_kill_info_logging(caplog: pytest.LogCaptureFixture) -> None: + """Killing a server emits its lifecycle record.""" + from libtmux.server import Server + from libtmux.test.random import namer - rec = t.cast(t.Any, records[0]) - assert rec.getMessage() == "other windows killed" - assert rec.tmux_window == survivor.window_name - assert rec.tmux_target == survivor.window_id - remaining_window_ids = {window.window_id for window in session.windows} - assert survivor.window_id in remaining_window_ids - assert all(window.window_id not in remaining_window_ids for window in other_windows) + with Server(socket_name=f"libtmux_log_{next(namer)}") as server: + server.new_session(session_name=f"log_session_{next(namer)}") + _, record = _capture_info( + caplog, + "libtmux.server", + "server killed", + server.kill, + ) + assert record.tmux_subcommand == "kill-server" + assert record.tmux_socket == server.socket_name -def test_pane_split_info_logging( - session: Session, + +def test_server_new_session_propagates_without_logging( + server: Server, + monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture, ) -> None: - """Test that pane.split() produces INFO record with str-typed extra.""" - window = session.active_window - assert window is not None - pane = window.active_pane - assert pane is not None - with caplog.at_level(logging.INFO, logger="libtmux.pane"): - new_pane = pane.split() + """A propagated tmux failure remains exception data, not a log record.""" + from libtmux import exc - records = [ - r - for r in caplog.records - if hasattr(r, "tmux_subcommand") - and r.levelno == logging.INFO - and getattr(r, "tmux_subcommand", None) == "split-window" - ] - assert len(records) >= 1, "expected INFO record for pane split" + monkeypatch.setattr(server, "has_session", lambda session_name: True) - rec = t.cast(t.Any, records[0]) - assert isinstance(rec.tmux_subcommand, str) - assert isinstance(rec.tmux_pane, str) - for key in ("tmux_session", "tmux_window"): - val = getattr(rec, key, None) - if val is not None: - assert isinstance(val, str), ( - f"extra key {key!r} should be str, got {type(val).__name__}" - ) + with ( + caplog.at_level(logging.ERROR, logger="libtmux.common"), + pytest.raises(exc.LibTmuxException, match="kill-session"), + ): + server.new_session(session_name="no_such_session", kill_session=True) - new_pane.kill() + assert [ + record for record in caplog.records if record.levelno == logging.ERROR + ] == [] -def test_pane_kill_all_except_logging( - session: Session, +def test_environment_failure_propagates_without_logging( + server: Server, caplog: pytest.LogCaptureFixture, ) -> None: - """Test that pane.kill(all_except=True) identifies the surviving pane.""" - window = session.active_window - assert window is not None - window.resize(height=100, width=100) - survivor = window.split() - other_panes = [window.split(), window.split()] + """A translated environment failure remains exception data only.""" + dead = server.new_session(session_name="logging_dead_environment") + dead.kill() - with caplog.at_level(logging.INFO, logger="libtmux.pane"): - survivor.kill(all_except=True) + with ( + caplog.at_level(logging.ERROR, logger="libtmux.common"), + pytest.raises(ValueError), + ): + dead.set_environment("KEY", "value") - records = [ - r - for r in caplog.records - if getattr(r, "tmux_subcommand", None) == "kill-pane" - and r.levelno == logging.INFO - ] - assert len(records) >= 1, "expected INFO record for all-except pane kill" + assert [ + record for record in caplog.records if record.levelno == logging.ERROR + ] == [] - rec = t.cast(t.Any, records[0]) - assert rec.getMessage() == "other panes killed" - assert rec.tmux_pane == survivor.pane_id - assert rec.tmux_target == survivor.pane_id - remaining_pane_ids = {p.pane_id for p in window.panes} - assert survivor.pane_id in remaining_pane_ids - assert all(p.pane_id not in remaining_pane_ids for p in other_panes) +_UNUSABLE_TMUX_CASES = [ + pytest.param("configured-missing", errno.ENOENT, id="configured-missing"), + pytest.param("default-missing", None, id="default-missing"), + pytest.param("not-executable", errno.EACCES, id="not-executable"), + pytest.param("invalid-format", errno.ENOEXEC, id="invalid-format"), +] -def test_session_kill_all_except_logging( - server: Server, + +def _prepare_unusable_tmux_binary( + binary_case: str, + tmp_path: pathlib.Path, + monkeypatch: pytest.MonkeyPatch, +) -> tuple[str | None, pathlib.Path]: + """Build one unusable executable case and return its configured path.""" + tmux_path = tmp_path / "tmux" + if binary_case == "default-missing": + monkeypatch.setenv("PATH", "") + return None, tmux_path + if binary_case in {"not-executable", "invalid-format"}: + tmux_path.write_text("not an executable format\n") + tmux_path.chmod(0o644 if binary_case == "not-executable" else 0o755) + return str(tmux_path), tmux_path + + +@pytest.mark.parametrize("loud_api", ["tmux-cmd", "raise-if-dead"]) +@pytest.mark.parametrize(("binary_case", "expected_errno"), _UNUSABLE_TMUX_CASES) +def test_loud_apis_preserve_unusable_tmux_diagnostics_without_logging( + loud_api: str, + binary_case: str, + expected_errno: int | None, + tmp_path: pathlib.Path, + monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture, ) -> None: - """Test that session.kill(all_except=True) identifies the surviving session.""" - from libtmux.test.random import namer + """Loud APIs preserve available launch facts in one domain exception.""" + from libtmux import exc + from libtmux.common import tmux_cmd + from libtmux.server import Server - survivor = server.new_session(session_name=f"log_survivor_{next(namer)}") - other_sessions = [ - server.new_session(session_name=f"log_other_{next(namer)}"), - server.new_session(session_name=f"log_other_{next(namer)}"), - ] + tmux_bin, tmux_path = _prepare_unusable_tmux_binary( + binary_case, tmp_path, monkeypatch + ) - with caplog.at_level(logging.INFO, logger="libtmux.session"): - survivor.kill(all_except=True) + def run_tmux_cmd() -> object: + return tmux_cmd("list-sessions", tmux_bin=tmux_bin) - records = [ - r - for r in caplog.records - if getattr(r, "tmux_subcommand", None) == "kill-session" - and r.levelno == logging.INFO - ] - assert len(records) >= 1, "expected INFO record for all-except session kill" - - rec = t.cast(t.Any, records[0]) - assert rec.getMessage() == "other sessions killed" - assert rec.tmux_session == survivor.session_name - assert rec.tmux_target == survivor.session_id - remaining_session_ids = {session.session_id for session in server.sessions} - assert survivor.session_id in remaining_session_ids - assert all( - session.session_id not in remaining_session_ids for session in other_sessions + action = ( + run_tmux_cmd + if loud_api == "tmux-cmd" + else Server(tmux_bin=tmux_bin).raise_if_dead + ) + + with ( + caplog.at_level(logging.ERROR, logger="libtmux.common"), + pytest.raises(exc.TmuxCommandNotFound) as exc_info, + ): + action() + + assert [ + record for record in caplog.records if record.levelno == logging.ERROR + ] == [] + if expected_errno is None: + assert str(exc_info.value) == "tmux executable not found on PATH" + assert exc_info.value.__cause__ is None + else: + cause = exc_info.value.__cause__ + assert isinstance(cause, OSError) + assert cause.errno == expected_errno + assert str(exc_info.value) == str(cause) + assert str(tmux_path) in str(exc_info.value) + + +@pytest.mark.parametrize( + ("accessor", "list_cmd"), + [ + ("sessions", "list-sessions"), + ("attached_sessions", "list-sessions"), + ("clients", "list-clients"), + ], +) +@pytest.mark.parametrize(("binary_case", "expected_errno"), _UNUSABLE_TMUX_CASES) +def test_lenient_accessors_log_unusable_tmux_diagnostics( + accessor: str, + list_cmd: str, + binary_case: str, + expected_errno: int | None, + tmp_path: pathlib.Path, + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, +) -> None: + """A swallowed launch failure keeps its diagnostic in the boundary record.""" + from libtmux.server import Server + + tmux_bin, tmux_path = _prepare_unusable_tmux_binary( + binary_case, tmp_path, monkeypatch ) + server = Server(tmux_bin=tmux_bin) + with caplog.at_level(logging.ERROR, logger="libtmux.server"): + assert list(getattr(server, accessor)) == [] -def test_server_new_session_surfaces_kill_session_stderr( + records = [record for record in caplog.records if record.levelno == logging.ERROR] + assert len(records) == 1 + record = t.cast(t.Any, records[0]) + assert record.tmux_subcommand == list_cmd + assert record.tmux_stderr_len == 1 + assert len(record.tmux_stderr) == 1 + diagnostic = record.tmux_stderr[0] + if expected_errno is None: + assert diagnostic == "tmux executable not found on PATH" + else: + assert os.strerror(expected_errno) in diagnostic + assert str(tmux_path) in diagnostic + + +def test_tmux_cmd_unrelated_launch_failure_stays_os_error() -> None: + """A direct launch resource failure retains trunk's native exception.""" + from libtmux import exc + from libtmux.common import tmux_cmd + + with pytest.raises(OSError) as exc_info: + tmux_cmd("set-buffer", "x" * os.sysconf("SC_ARG_MAX")) + + assert not isinstance(exc_info.value, exc.TmuxCommandNotFound) + assert exc_info.value.errno == errno.E2BIG + + +@pytest.mark.parametrize( + ("accessor", "list_cmd"), + [ + ("sessions", "list-sessions"), + ("attached_sessions", "list-sessions"), + ("clients", "list-clients"), + ], +) +def test_lenient_accessors_log_unrelated_launch_failure( + accessor: str, + list_cmd: str, monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, ) -> None: - """Test kill-session stderr propagation using monkeypatch for the failure path. + """Lenient list boundaries still swallow a raw launch resource error.""" + from libtmux.server import Server + + def raise_e2big(*args: object, **kwargs: object) -> None: + raise OSError(errno.E2BIG, os.strerror(errno.E2BIG), "/configured/tmux") + + monkeypatch.setattr("libtmux.common.subprocess.Popen", raise_e2big) + server = Server(tmux_bin="/configured/tmux") + with caplog.at_level(logging.ERROR, logger="libtmux.server"): + assert list(getattr(server, accessor)) == [] - A real tmux fixture is not used here because this path requires forcing a - kill-session command failure before session creation begins. - """ + records = [record for record in caplog.records if record.levelno == logging.ERROR] + assert len(records) == 1 + record = t.cast(t.Any, records[0]) + assert record.tmux_subcommand == list_cmd + assert record.tmux_stderr_len == 1 + assert os.strerror(errno.E2BIG) in record.tmux_stderr[0] + + +def test_raise_if_dead_unrelated_launch_failure_stays_os_error() -> None: + """The loud server probe does not classify resource errors as unavailable.""" from libtmux import exc from libtmux.server import Server - from libtmux.test.random import namer - server = Server(socket_name=f"libtmux_log_{next(namer)}") - monkeypatch.setattr(server, "has_session", lambda session_name: True) - monkeypatch.setattr( - server, - "cmd", - lambda *args, **kwargs: types.SimpleNamespace(stderr=["kill failed"]), + server = Server( + tmux_bin=sys.executable, + config_file="x" * os.sysconf("SC_ARG_MAX"), ) + with pytest.raises(OSError) as exc_info: + server.raise_if_dead() - with pytest.raises(exc.LibTmuxException, match="kill failed"): - server.new_session(session_name="existing_session", kill_session=True) + assert not isinstance(exc_info.value, exc.TmuxCommandNotFound) + assert exc_info.value.errno == errno.E2BIG +@pytest.mark.parametrize( + "binary_case", + ["configured-missing", "default-missing", "not-executable", "invalid-format"], +) +def test_is_alive_unusable_binary_stays_quiet( + binary_case: str, + tmp_path: pathlib.Path, + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, +) -> None: + """A health check converts an unusable executable to a quiet false result.""" + from libtmux.server import Server + + tmux_bin: str | None = str(tmp_path / "missing-tmux") + if binary_case == "default-missing": + tmux_bin = None + monkeypatch.setenv("PATH", "") + elif binary_case in {"not-executable", "invalid-format"}: + invalid_tmux = tmp_path / "invalid-tmux" + invalid_tmux.write_text("not an executable format\n") + invalid_tmux.chmod(0o644 if binary_case == "not-executable" else 0o755) + tmux_bin = str(invalid_tmux) + server = Server(tmux_bin=tmux_bin) + + with caplog.at_level(logging.ERROR, logger="libtmux.common"): + assert not server.is_alive() + + assert [ + record for record in caplog.records if record.levelno == logging.ERROR + ] == [] + + +@pytest.mark.parametrize( + ("option_key", "bad_values"), + [ + ("terminal-features", tuple(range(25))), + ("command-alias", ("split-pane", "server-info", "choose-tree")), + ], +) def test_options_warning_logging_schema( caplog: pytest.LogCaptureFixture, + option_key: str, + bad_values: tuple[str | int, ...], ) -> None: - """Test that options parse warnings produce records with tmux_option_key.""" + """Malformed values produce one aggregate warning without traceback data.""" from libtmux._internal.sparse_array import SparseArray from libtmux.options import explode_complex - # A terminal-features value without ":" triggers a split failure and WARNING - bad_features: SparseArray[str | int | bool | None] = SparseArray() - bad_features[0] = 42 # int, not str — causes .split() to fail + bad_options: SparseArray[str | int] = SparseArray() + for index, bad_value in enumerate(bad_values): + bad_options[index] = bad_value with caplog.at_level(logging.WARNING, logger="libtmux.options"): - explode_complex({"terminal-features": bad_features}) # type: ignore[dict-item] + explode_complex({option_key: bad_options}) # type: ignore[dict-item] records = [ - r - for r in caplog.records - if hasattr(r, "tmux_option_key") and r.levelno == logging.WARNING + record + for record in caplog.records + if getattr(record, "tmux_option_key", None) == option_key ] - assert len(records) >= 1, "expected WARNING record for option parse failure" + assert len(records) == 1 + record = t.cast(t.Any, records[0]) + assert record.tmux_option_skipped == len(bad_values) + assert record.exc_info is None + + +@pytest.mark.parametrize( + ("argv", "expected"), + [ + ( + ["tmux", "-Lsock", "new-session", "-eKEY=secret"], + { + "tmux_cmd": "tmux -Lsock new-session -eKEY=secret", + "tmux_subcommand": "new-session", + "tmux_socket": "sock", + }, + ), + ( + ["tmux", "-S", "/tmp/s", "set-buffer", "secret"], + { + "tmux_cmd": "tmux -S /tmp/s set-buffer secret", + "tmux_subcommand": "set-buffer", + "tmux_socket": "/tmp/s", + }, + ), + ( + ["tmux", "-f", "secret-conf", "run-shell", "secret"], + { + "tmux_cmd": "tmux -f secret-conf run-shell secret", + "tmux_subcommand": "run-shell", + }, + ), + ( + ["tmux", "-2L", "sock", "list-panes"], + { + "tmux_cmd": "tmux -2L sock list-panes", + "tmux_subcommand": "list-panes", + "tmux_socket": "sock", + }, + ), + ( + ["tmux", "-L", "safe\nforged", "future-command", "secret"], + { + "tmux_cmd": "tmux -L 'safe\\nforged' future-command secret", + "tmux_subcommand": "future-command", + "tmux_socket": "'safe\\nforged'", + }, + ), + ( + ["tmux", "-Z", "operand-secret"], + { + "tmux_cmd": "tmux -Z operand-secret", + }, + ), + ( + ["tmux", "--future-option=value", "list-sessions", "payload"], + { + "tmux_cmd": "tmux --future-option=value list-sessions payload", + }, + ), + ( + ["tmux", "--", "future-command", "payload"], + { + "tmux_cmd": "tmux -- future-command payload", + "tmux_subcommand": "future-command", + }, + ), + (["tmux", "-V"], {"tmux_cmd": "tmux -V"}), + ], +) +def test_command_extra_preserves_command_and_extracts_context( + argv: list[str], + expected: dict[str, str], +) -> None: + """Command records retain argv while deriving optional structured fields.""" + from libtmux._internal.log_context import command_extra + + assert command_extra(argv) == expected + + +@pytest.mark.parametrize("flag", tuple("2CDdhlNquUvV")) +def test_command_extra_parses_boolean_global_flags(flag: str) -> None: + """Known boolean flags leave the following token as the subcommand.""" + from libtmux._internal.log_context import command_extra + + result = command_extra(["tmux", f"-{flag}", "list-sessions"]) + + assert result["tmux_subcommand"] == "list-sessions" + + +@pytest.mark.parametrize("flag", tuple("cfLST")) +@pytest.mark.parametrize("attached", [False, True]) +def test_command_extra_parses_value_global_flags( + flag: str, + attached: bool, +) -> None: + """Known value flags accept attached and separate values.""" + from libtmux._internal.log_context import command_extra + + option = f"-{flag}value" if attached else f"-{flag}" + argv = ["tmux", option] + if not attached: + argv.append("value") + argv.append("list-sessions") + + result = command_extra(argv) + + assert result["tmux_subcommand"] == "list-sessions" + if flag in "LS": + assert result["tmux_socket"] == "value" + + +def test_command_extra_preserves_unicode_and_escapes_controls() -> None: + """Printable Unicode remains readable and controls cannot forge log lines.""" + from libtmux._internal.log_context import command_extra + + payload = "snowman ☃ and Ελληνικά" + result = command_extra( + ["tmux", "set-buffer", payload, "line\nERROR forged", "nul\0byte"] + ) + + assert payload in result["tmux_cmd"] + assert "\n" not in result["tmux_cmd"] + assert "\\nERROR forged" in result["tmux_cmd"] + assert "\\x00" in result["tmux_cmd"] + + +def test_command_extra_preserves_large_operand() -> None: + """Command logging does not truncate a large argv operand.""" + from libtmux._internal.log_context import command_extra + + payload = "x" * 1_000_000 + result = command_extra(["tmux", "set-buffer", payload]) + + assert result["tmux_cmd"].endswith(payload) + assert len(result["tmux_cmd"]) == len(payload) + len("tmux set-buffer ") + + +def test_session_fixture_setup_logs_no_errors( + session: Session, + caplog: pytest.LogCaptureFixture, +) -> None: + """The bundled fixture does not inject ERROR records into test reports.""" + assert session.session_name is not None + assert [ + record + for record in caplog.get_records("setup") + if record.levelno >= logging.ERROR + ] == [] + + +def test_lookup_path_cannot_forge_a_log_line( + caplog: pytest.LogCaptureFixture, +) -> None: + """A caller-provided lookup path remains one diagnostic line.""" + from libtmux._internal.query_list import keygetter + + with caplog.at_level(logging.DEBUG, logger="libtmux._internal.query_list"): + keygetter({}, "missing\nERROR libtmux forged") + + record = caplog.records[-1] + assert "\n" not in record.getMessage() + assert "\\nERROR libtmux forged" in record.getMessage() + + +def test_parse_failure_propagates_without_logging( + caplog: pytest.LogCaptureFixture, +) -> None: + """A parser failure remains exception data, not a second error channel.""" + from libtmux.formats import FORMAT_SEPARATOR + from libtmux.neo import parse_output + + row = FORMAT_SEPARATOR.join(["one", "two", "three"]) + FORMAT_SEPARATOR + + with ( + caplog.at_level(logging.ERROR, logger="libtmux.neo"), + pytest.raises(ValueError, match="zip"), + ): + parse_output(row, "list-panes", "3.7") - rec = t.cast(t.Any, records[0]) - assert isinstance(rec.tmux_option_key, str) - assert rec.exc_info is None + assert [ + record for record in caplog.records if record.levelno == logging.ERROR + ] == [] diff --git a/tests/test_pane.py b/tests/test_pane.py index 416032ce62..668503494a 100644 --- a/tests/test_pane.py +++ b/tests/test_pane.py @@ -1802,7 +1802,10 @@ class _NewPaneEmptyValueCase(t.NamedTuple): ) -def test_new_pane_floating(session: Session) -> None: +def test_new_pane_floating( + session: Session, + caplog: pytest.LogCaptureFixture, +) -> None: """Pane.new_pane() creates a floating pane on tmux 3.7+ (else raises).""" window = session.new_window(window_name="floating_pane") window.resize(height=50, width=200) @@ -1810,10 +1813,25 @@ def test_new_pane_floating(session: Session) -> None: assert pane is not None if has_gte_version("3.7"): - floating = pane.new_pane(width=80, height=15, x=5, y=3, shell="sleep 30") + with caplog.at_level(logging.INFO, logger="libtmux.pane"): + floating = pane.new_pane(width=80, height=15, x=5, y=3, shell="sleep 30") assert floating.pane_floating_flag == "1" assert floating.pane_width == "80" assert floating.pane_height == "15" + records = [ + record + for record in caplog.records + if record.name == "libtmux.pane" + and record.getMessage() == "floating pane created" + ] + assert len(records) == 1 + record = t.cast(t.Any, records[0]) + assert record.levelno == logging.INFO + assert record.tmux_subcommand == "new-pane" + assert record.tmux_socket == session.server.socket_name + assert record.tmux_session == session.session_name + assert record.tmux_window == window.window_name + assert record.tmux_pane == floating.pane_id else: with pytest.raises(exc.LibTmuxException, match=r"new_pane .*requires tmux 3.7"): pane.new_pane(width=40, height=10) diff --git a/tests/test_server.py b/tests/test_server.py index 6175a7f9ad..13d73767f1 100644 --- a/tests/test_server.py +++ b/tests/test_server.py @@ -4,7 +4,6 @@ import functools import logging -import os import pathlib import shutil import subprocess @@ -209,7 +208,7 @@ def test_new_session_shell(server: Server) -> None: def test_new_session_shell_env(server: Server) -> None: """Verify ``Server.new_session`` creates valid session running w/ command (#553).""" cmd = "sleep 1m" - env = dict(os.environ) + env = {"LIBTMUX_TEST_ENV": "present"} mysession = server.new_session( "test_new_session_env", window_command=cmd, @@ -220,6 +219,7 @@ def test_new_session_shell_env(server: Server) -> None: pane = window.panes[0] assert mysession.session_name == "test_new_session_env" assert server.has_session("test_new_session_env") + assert mysession.getenv("LIBTMUX_TEST_ENV") == "present" pane_start_command = pane.pane_start_command assert pane_start_command is not None @@ -1399,24 +1399,40 @@ def test_server_search_panes_filter_by_id(server: Server) -> None: assert [p.pane_id for p in matches] == [target.pane_id] -def test_server_clients_returns_empty_on_tmux_error( +@pytest.mark.parametrize( + ("accessor", "list_cmd"), + [ + ("sessions", "list-sessions"), + ("attached_sessions", "list-sessions"), + ("clients", "list-clients"), + ], +) +def test_lenient_list_accessors_log_and_return_empty( server: Server, monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, + accessor: str, + list_cmd: str, ) -> None: - """``Server.clients`` returns an empty QueryList on tmux failure. - - Lenient-by-default contract: ``list-clients`` failing for any reason - yields ``QueryList([])``, matching the historic shape of - :attr:`Server.sessions`. Callers needing a connectivity check should - use :meth:`Server.is_alive` or :meth:`Server.raise_if_dead`. - """ - sentinel = exc.LibTmuxException("simulated list-clients failure") + """Lenient list accessors log once where they swallow a tmux failure.""" + stderr = [f"simulated list failure {index}" for index in range(125)] + sentinel = exc.LibTmuxException("\n".join(stderr)) def _boom(**_: object) -> list[dict[str, str]]: raise sentinel monkeypatch.setattr("libtmux.server.fetch_objs", _boom) - assert list(server.clients) == [] + with caplog.at_level(logging.ERROR, logger="libtmux.server"): + assert list(getattr(server, accessor)) == [] + + records = [record for record in caplog.records if record.levelno == logging.ERROR] + assert len(records) == 1 + record = t.cast(t.Any, records[0]) + assert record.tmux_subcommand == list_cmd + assert record.tmux_socket == server.socket_name + assert record.tmux_stderr_len == len(stderr) + assert record.tmux_stderr == stderr[:100] + assert record.funcName == ("clients" if accessor == "clients" else "sessions") def test_server_search_sessions_propagates_errors( @@ -1439,27 +1455,6 @@ def _boom(**_: object) -> list[dict[str, str]]: server.search_sessions(filter="#{m:keep_*,#{session_name}}") -def test_server_sessions_returns_empty_on_tmux_error( - server: Server, - monkeypatch: pytest.MonkeyPatch, -) -> None: - """``Server.sessions`` returns an empty QueryList on tmux failure. - - Pins the lenient-by-default contract: a ``list-sessions`` failure — - daemon down, missing socket, permission error, subprocess crash — - yields ``QueryList([])`` rather than propagating. Callers that need - to distinguish "no sessions" from "tmux unreachable" should use - :meth:`Server.is_alive` or :meth:`Server.raise_if_dead`. - """ - sentinel = exc.LibTmuxException("simulated list-sessions failure") - - def _boom(**_: object) -> list[dict[str, str]]: - raise sentinel - - monkeypatch.setattr("libtmux.server.fetch_objs", _boom) - assert list(server.sessions) == [] - - def test_server_sessions_missing_socket_returns_empty(tmp_path: pathlib.Path) -> None: """A not-yet-created tmux socket preserves the empty-list contract.""" missing_server = Server(socket_path=tmp_path / "missing.sock")