fix: send diagnostics to stderr, and keep stdout for what a command produces by mkb79 · Pull Request #306 · mkb79/audible-cli

mkb79 · 2026-08-21T05:41:55Z

Diagnostics went to stdout. ClickHandler.emit called click.echo(msg) without err=True, so every log line of every command landed in the same stream a command uses for its result — audible api library | jq was handed prose instead of JSON, and a caller had no way to tell the two apart.

One rule holds after this: stdout carries the result a command was asked for; stderr carries everything else — narration, diagnostics, and the conversation with the person at the terminal, questions included. The stream is never chosen by log level.

Three mechanisms serve it, each owning one thing:


`_logging`	every record to stderr, subject to `--verbosity` and copied to `--log-file`
`_dialog`	questions and the sentences explaining them, always visible, never in the log file
`progress`	the download dock, on stderr, off when stderr is not a terminal

`_logging` rewritten

The module was 154 lines and private, so it was rewritten rather than patched. Besides the stream:

echo_kwargs — per-level arguments for click.echo, never supplied by any caller — was the hook err=True should have used all along. Gone, with the "exception" style key, which named a level that does not exist.
The level prefix comes from formatMessage instead of format, so a traceback is appended in its own shape rather than the whole record falling back to the verbose file layout.
capture_warnings() was a way of silencing warnings: captureWarnings hands them to the py.warnings logger, which carries a NullHandler and no route anywhere, so not even Python's lastResort saw them. Handing them back restores the propagation it found.
A handler set below its logger never sees the records it was lowered for. Saying so through the logger meant the message was dropped by the very level it reported; it goes through warnings now.
tqdm.external_write_mode() guarded a progress bar nobody builds any more — the dock reserves its rows through the terminal, not through tqdm.
NO_COLOR and FORCE_COLOR are honoured; click only looks at whether the stream is a terminal.
Handlers are attached and dropped by name under a lock, and closed when dropped: configuring twice no longer prints every line twice, a detailed console log replaces the terse one instead of doubling it, and a file handler carries its destination in its name, so a second file adds a handler while the same file twice replaces one.
The file log is UTF-8 rather than whatever the platform prefers.

The conversion finished

The verbosity option came with a conversion of echo calls into log calls, and nine were left behind — on stdout, where -v cannot reach them. manage profile remove shows what happened: its neighbour profile add goes through ConfigFile.add_profile, which logs, while remove deleted the entry itself and kept its echoes, so the save was reported twice, once per stream. It goes through ConfigFile.delete_profile now.

A second pass found four more, plus the mirror-image mistake: "Auth file is encrypted but no/wrong password is provided" was logged, and it sits directly in front of the password prompt it explains — raise the verbosity and the reason disappears while the question remains. That line is what decides the rest: an explanation that precedes a prompt stays with it, a confirmation that follows one is narration.

--version also printed the version without a newline and appended " (up-to-date)" to the same line, so a script reading it had to strip advice off the end.

The conversation

Prompts were the last thing on stdout, and two of the surfaces belong to dependencies: the audible library holds the external-login exchange with print and input, and questionary draws through prompt_toolkit, which renders to stdout unless handed an output. Both turn out to be ours to take — audible-cli passes its own login callbacks anyway, and every questionary call site now hands over an output bound to stderr.

With those two, the rest follows: the quickstart wizard, the captcha and OTP exchanges, the encrypted-auth explanation, and click's own declarative prompt= options through a DialogOption subclass. audible quickstart > file now leaves the file empty and every question on the screen.

Authenticator.from_login takes four callbacks and only two were passed; the other two asked through the library's print/input. All four are ours now, and a test reads the expected set off the library's signature so a fifth one cannot slip through.

`--log-file PATH`

Moving the narration off stdout leaves nothing to redirect for anyone who kept a record with > log.txt. log_helper.set_file_logger already existed with no way to reach it; a global --log-file wires it up, writes the detailed layout with timestamp, module and line, follows --verbosity, appends across runs, and creates a missing parent directory.

It records what a command says about its work, not the conversation — a password or a captcha answer has no business in a file people attach to bug reports.

One habit breaks

audible download … > log.txt collected the progress notes and now collects nothing. It needs 2>, or better, --log-file.

Tests

The logging module had none. It has 28, plus tests/test_output_channels.py for the cases easiest to cross back over — the version split, a broken plugin, the prompt that must keep its explanation, every login callback, and a source scan that no questionary call site draws on stdout. An autouse fixture keeps the suite out of the real config directory. 374 pass, under NO_COLOR=1, FORCE_COLOR=1 and neither.

Every log line went to stdout, because ClickHandler called click.echo without err=True. That put error messages into the same stream a command uses for its result, so `audible api library | jq` was handed prose instead of JSON, and a caller had no way to tell the two apart. The module was small enough to rewrite rather than patch, and the rest of it had collected its own problems: - The echo_kwargs machinery existed to pass per-level arguments to click.echo and was never given any -- it was the hook err=True should have used all along. Gone, along with the "exception" style key, which named a level that does not exist. - A record carrying a traceback skipped the level prefix and fell back to the verbose file layout. Now the prefix belongs to the message and the traceback keeps its own shape, by overriding formatMessage rather than format. - capture_warnings() was a way of silencing warnings rather than of collecting them: captureWarnings hands them to the py.warnings logger, which carries a NullHandler and no route anywhere, so not even Python's lastResort saw them. It gets the console handler now. - A handler set below its logger never sees the records it was lowered for. Saying so through the logger meant the message was dropped by the very level it was reporting; it goes through `warnings` instead. - tqdm.external_write_mode() guarded against a progress bar nobody builds any more; the dock reserves its rows through the terminal, not through tqdm. The import goes with it, and the test that keeps tqdm out of the package tightens by one file. - click.echo strips colour for a pipe but ignores NO_COLOR and FORCE_COLOR. Both are honoured now. - Handlers are attached by name under a lock, so configuring twice no longer prints every line twice and a detailed console log replaces the terse one instead of doubling it. A file handler carries its destination in its name, so naming a second file adds a handler while naming the same file twice replaces one. - The file log is written as UTF-8 rather than whatever the platform happens to prefer. A plugin that fails to import is replaced by BrokenCommand, which printed its warning and traceback to stdout as well. Same rule, same fix. The module had no tests. It has twenty-four now, holding the stream split, the prefixes, the traceback shape, colour under both environment variables, the handler bookkeeping and the two traps above. One habit breaks: `audible download ... > log.txt` collected the progress notes and now collects nothing. It needs 2> or 2>&1.

The verbosity option came with a conversion of echo calls into log calls, and nine of them were left behind. They sit on stdout, where a pipe collects them, and `-v` cannot quiet them. `manage profile remove` shows what happened. Its neighbour `profile add` goes through `ConfigFile.add_profile`, which logs; `remove` deleted the entry from the dictionary itself and kept its echoes. So the two halves of one command group narrated in two different ways, and the save was reported twice -- once by `write_config` through the logger and once by the command through stdout. It now calls `ConfigFile.delete_profile` the way `add` does, with the write held back until the loop is done, and the "profile doesn't exist" message stops being a red line on stdout that no verbosity level could silence. The rest: the two confirmations in `manage auth-file remove`, and `display_counter`, which narrates the end of a download the way the other 38 lines in that command already do. Nothing that a command produces moved. Every result still goes out through echo or into a file: the API response, the title lists, the activation bytes, the profile table, the exports. What moved is the talking about it. Which leaves nowhere to redirect for anyone who wanted to keep a record, so `--log-file PATH` writes the same log to a file, in the detailed layout with timestamp, module and line. It follows --verbosity, and it is a better record than the scraped stdout it replaces.

A second pass over every place the package writes, against one rule: stdout carries what a command produces or asks, stderr carries what is said about the work. Found going the wrong way, out of the package: - `--version` printed the version without a newline and then appended " (up-to-date)" or an update notice to the same line, so a script reading the version had to strip advice off the end -- and an update check that raised left the line unfinished. The version now goes out whole on stdout; the advice goes to stderr. - "Successfully registered DEVICE." confirms a side effect after the login dialogue has ended, and moves to the logger. - Quickstart's "Use existing auth file for new profile." reports the answer just given rather than explaining the next question, and moves with it. The line between those two is what keeps the captcha and OTP explanations on stdout: they precede a prompt, this one follows one. Found going the wrong way, into the package -- the mirror-image mistake: - "Auth file is encrypted but no/wrong password is provided" was logged, and sits directly in front of the password prompt it explains. On stderr with a raised verbosity the reason disappears while the question remains, leaving a bare password prompt. It travels with its prompt now. Right channel, wrong mechanism: - The two --bunch-size deprecation notices wrote to stderr with echo, so neither --verbosity nor --log-file reached them. They are warnings and say so now. - BrokenCommand did the same with a plugin's load failure. It now logs a one-line summary and hands the stored exception to the logger as exc_info, which is what puts a traceback in its own shape rather than stamping "error: " down its left edge. `--log-file` creates a missing parent directory, the way write_config does, instead of failing on a path the user has every reason to expect to work. tests/test_output_channels.py holds the three cases that are easiest to cross back over: the version split, the broken plugin, and the prompt that must keep its explanation.

The interactive dialogue was the last thing left on stdout, and it was there for a reason that did not survive checking: two of the surfaces belong to dependencies, so moving only the parts this package owns would have split a conversation across two streams -- our explanations on one, the library's questions on the other. Both surfaces turn out to be ours to take. `audible.login.default_login_url_callback` holds its exchange with print and input. audible-cli passes its own callback anyway, so it now carries the instructions itself and still tries the browser route first, which has nothing to print. questionary draws through prompt_toolkit, which renders to stdout unless it is handed an output. Every call site hands it one now, and a test checks that at the source rather than trusting the seven call sites to stay that way. With those two, the rest follows: the quickstart wizard, the captcha and OTP exchanges, the encrypted-auth explanation, and the prompts belonging to each of them. `audible quickstart > file` now leaves the file empty and every question on the screen, where before it swallowed half the wizard. The new `_dialog` module is the counterpart to `_logging`: one place that knows which stream a question goes to, so the next person to add a prompt does not have to remember. `say`, `ask` and `confirm` for text, `selection_output()` for questionary. Deliberately not the logger, for any of it. A prompt's explanation must not be suppressible while the question it explains stays on the screen -- which is the same reason the encrypted-auth notice came off the logger in the last commit. It travels with its prompt, and now they travel together to stderr rather than to stdout.

It arrived only through questionary, which allows anything from 2.0 to 4.0 -- a range that includes versions without the entry point this package now calls. What is imported is declared.

`Authenticator.from_login` takes four callbacks and only two were being passed. The other two fell back to the library's, which hold their half of the conversation with print and input: default_cvf_callback input("CVF Code: ") default_approval_alert_callback print("Approval alert detected! ...") input("Please press ENTER ...") So a login that hit a verification code or an approval alert still asked on stdout, and asked without the prompt handling the rest of the wizard gets. Both are ours now, and they say the same thing through `say` and `ask`. The test reads the expectation off the library's own signature rather than listing the callbacks, so a fifth one in a future audible release fails here instead of quietly falling back again.

They are examples, and an example that mixes its narration into the stream carrying its result teaches that as the way to write a plugin. `cmd_decrypt` had ten of them and no logger at all: what it separates, what it skips, how many chapters it found, which file it overwrote, whether the decryption worked. All on stdout, none reachable by `--verbosity`. It has a logger now, named the way the two plugins that already had one name theirs, so the records reach the handler audible-cli configures. `cmd_get-annotations` was the sharpest case, because both halves were on one stream: "No annotations found for asin X" next to the annotations themselves. Piping that command gave you either JSON or a sentence, with nothing to tell them apart. `convert_oa_cred` confirmed a file it had written. What stays on stdout is what these commands produce: the annotations and the image URLs. `cmd_goodreads-transform` and `cmd_listening-stats` already did the right thing -- one logs and writes a file, the other only writes a file. No scanning test for these, unlike the questionary rule in the package itself. They are meant to be copied and changed, and a test holding an allowlist of which lines in an example may print would cost more than it catches.

`@click.option(..., prompt="...")` asks through `Option.prompt_for_value`, which reaches for `click.core.prompt` and `click.core.confirm` and takes no `err` of its own. Eight options in `manage` did that, so audible manage profile add > payload.txt hid "Please enter the profile name" in the file while the process waited for an answer. `DialogOption` binds those two names for the length of one call rather than copying `prompt_for_value` here: that method grows features between click releases and a copy would fall behind quietly. Two more: - A broken plugin went silent at `--verbosity critical`: exit 1, both streams empty, and no explanation of why the command that was typed could not run. It logs at CRITICAL, which is what it is. - `capture_warnings(False)` removed the handler but left `propagate` off, so a later `captureWarnings(True)` by anything else routed every warning into silence. It puts back what it found. `utils/update_chapter_titles.py` is a standalone script rather than part of the package, so it gets `err=True` on its six narrating lines instead of a dependency on audible-cli's logging. The wizard test walks to the closing confirmation, so every question along the way is covered rather than the first two. Each login callback is asked and answered, and the external-login test forces the fallback rather than assuming playwright is absent. README gains the stream contract, `--log-file` and the colour variables.

A pass over every comment and docstring the branch adds, measured against what the repository already does: `progress.py`, `models.py` and `test_progress.py` average 1.9 to 2.3 lines per comment block. This branch was at 2.6 and is now at 2.2. Three said something untrue, which is the expensive kind: - `RECORD_FORMAT` was described as the layout for handlers writing somewhere durable. `set_console_logger` uses it too. - `ColorFormatter` claimed to put the level in front of a record. It does that for the levels in `LEVEL_COLORS`, and INFO is deliberately not one. - A test comment said every module does `getLogger(__name__)`. None do; they all name themselves. Four were history rather than code: what the file handler naming was like before handlers had names, what `manage profile remove` used to report twice, what `> log.txt` used to do, and a note about what was left to review. Two more were imprecise: `click_basic_config` promised that everything lands on stderr "whatever the level", which skips both the argument it takes and the filtering that still applies; and `ClickEchoHandler` said click drops colour escapes off a terminal, which `FORCE_COLOR` overrides. `set_console_logger` now says that its handler writes straight to the stream, so it carries no colour and misses colorama. The rest is length: Args and Returns sections on one-line wrappers in `_dialog`, four-paragraph module docstrings restating a rule that is stated once, and the explanations that ran a line or two past their point. The comments that explain a trap -- the live exception in the except block, propagate after un-capturing, why the two click names are bound rather than the method copied -- all stay.

A test that builds a `Session` without saying where gets the directory the user works in, through `get_app_dir()`. A command that writes its config then writes that one. An autouse fixture points AUDIBLE_CONFIG_DIR and AUDIBLE_PLUGIN_DIR at fresh directories for every test.

A comment between two statements makes the reader stop, switch from code to prose, and find their place again. Four of them said something about the function as a whole and belong in its docstring; `version_option` had none and now has one. Two said what the docstring above them already said, or what the names `say` and `ask` say themselves. What stays inline is the line that looks arbitrary without it: the live exception handed to the logger as exc_info, and CRITICAL rather than ERROR for a plugin that will not load. The stream contract also gains a note that a question goes to stderr, where the platform puts a prompt regardless of what click is told, so `2> log` on an interactive command looks like a hang.

`version_option` wrote its update notice with its own `click.echo(..., err=True)`. It is part of the conversation, not a log record, so it goes through `_dialog` like the rest and the stream is decided in one place. That leaves two: `_dialog` for questions, `_logging` for diagnostics.

Copilot

🟡 Changes recommended

The current --version behavior can exit non-zero on update-check failures (breaking script-friendly expectations), and two handler-removal paths should close removed handlers to avoid leaks.

Once you've addressed the issues Copilot identified, you can request another Copilot review.

Pull request overview

This PR enforces a strict separation of CLI output streams: stdout is reserved for command “products” (payloads) while stderr carries diagnostics, narration, and interactive prompts, and it adds a global --log-file PATH to persist detailed logs without relying on stream redirection.

Changes:

Reworked CLI logging so all log records are emitted to stderr, with improved formatting, color handling (NO_COLOR / FORCE_COLOR), and safer handler installation.
Introduced _dialog helpers to ensure prompts/questions (including questionary) render on stderr rather than polluting stdout.
Added --log-file PATH, updated docs/changelog, and added substantial tests to prevent regressions in output-channel behavior.

File summaries

File	Description
uv.lock	Adds `prompt-toolkit` to the locked dependency set.
pyproject.toml	Declares explicit `prompt_toolkit` dependency and updates exclusions.
utils/update_chapter_titles.py	Moves non-payload messages and confirmations to stderr.
src/audible_cli/_logging.py	Rewrites logging to always target stderr; improves handler management and formatting.
src/audible_cli/_dialog.py	Adds stderr-bound helpers for prompts and `questionary` output routing.
src/audible_cli/decorators.py	Updates `--version` messaging to keep stdout clean; adds `--log-file` option.
src/audible_cli/cli.py	Wires `--log-file` into the top-level CLI and quickstart entrypoint.
src/audible_cli/utils.py	Converts interactive/login messaging to stderr conversation helpers; adds missing callbacks.
src/audible_cli/config.py	Keeps encryption explanation with the password prompt (stderr conversation channel).
src/audible_cli/plugins.py	Logs broken-plugin failures via the logger (stderr), including tracebacks.
src/audible_cli/cmds/cmd_manage.py	Routes profile removal and auth-file removal diagnostics via logging/dialog mechanisms.
src/audible_cli/cmds/cmd_quickstart.py	Moves quickstart interaction text/prompts to stderr via `_dialog`.
src/audible_cli/cmds/cmd_wishlist.py	Forces `questionary` rendering off stdout by providing an explicit output.
src/audible_cli/cmds/cmd_download.py	Routes non-payload “result summary” and `questionary` UI off stdout.
plugin_cmds/convert_oa_cred.py	Sends “wrote file” status through logging (stderr) instead of stdout.
plugin_cmds/cmd_get-annotations.py	Keeps “no annotations found” off stdout (stderr via logger).
plugin_cmds/cmd_decrypt.py	Routes status/progress text through logging (stderr).
tests/conftest.py	Prevents tests from touching a user’s real config/plugin directories.
tests/test_progress.py	Updates expectations now that `_logging.py` no longer references tqdm.
tests/test_output_channels.py	Adds targeted tests ensuring stdout/stderr contracts are upheld.
tests/test_logging.py	Adds comprehensive tests for handler behavior, formatting, color, warnings capture, and `--log-file`.
tests/test_cmd_manage.py	Adds tests ensuring manage/profile removal narrates once and to stderr.
README.md	Documents the stdout/stderr contract and `--log-file` usage.
CHANGELOG.md	Documents behavioral changes and the new `--log-file` option.

Review details

Suppressed comments (1)

src/audible_cli/_logging.py:296

When replacing an existing console handler in click_basic_config, the removed handler is not closed. Closing it avoids leaking resources (and matches the explicit close done in _detach).

        for attached in list(logger.handlers):
            if attached.get_name() == CONSOLE_HANDLER:
                logger.removeHandler(attached)

Files reviewed: 23/24 changed files
Comments generated: 2
Review effort level: Lite

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

+            for handler in list(warnings_logger.handlers):
+                if handler.get_name() == CONSOLE_HANDLER:
+                    warnings_logger.removeHandler(handler)
+


Three places removed a handler by name and one of them closed it, which leaves the other two registered with the logging module. `_detach` takes the logger to work on, so all three go the same way.

The merge wove both versions of the callback together and left the bare `click.echo()` from #309 standing. There it finished a version line written with `nl=False`; here the line already ends, so it put a blank line on the payload stream. The failure notice goes through `say` like the other two, and the tests that came with #309 now expect the version alone on stdout with the notice on stderr.

The note claimed `--log-file` keeps a record where redirecting stderr would hide the questions. It does not: the conversation never reaches the file, and must not -- a password or a captcha answer does not belong in a file people attach to bug reports.

mkb79 added 8 commits August 21, 2026 00:09

docs: note the stream change in the changelog

50fa6ed

docs: note the dialogue move in the changelog

cb4173c

build: declare prompt_toolkit, which _dialog imports

4f7809b

It arrived only through questionary, which allows anything from 2.0 to 4.0 -- a range that includes versions without the entry point this package now calls. What is imported is declared.

test: pin the selection output to the diagnostic stream

0385c23

mkb79 force-pushed the fix/log-to-stderr branch from 309923f to 0e02870 Compare August 21, 2026 10:22

mkb79 added 5 commits August 21, 2026 13:22

mkb79 force-pushed the fix/log-to-stderr branch from 5cfec94 to 8bd8b97 Compare August 21, 2026 18:22

mkb79 added 2 commits August 21, 2026 22:21

mkb79 requested a lite review from Copilot August 24, 2026 07:24

Copilot started reviewing on behalf of mkb79 August 24, 2026 07:25 View session

Copilot AI reviewed Aug 24, 2026

View reviewed changes

Comment thread src/audible_cli/_logging.py Outdated

Comment on lines +262 to +265

for handler in list(warnings_logger.handlers):

if handler.get_name() == CONSOLE_HANDLER:

warnings_logger.removeHandler(handler)

Comment thread src/audible_cli/decorators.py

refactor: close the handlers we detach

f609298

Three places removed a handler by name and one of them closed it, which leaves the other two registered with the logging module. `_detach` takes the logger to work on, so all three go the same way.

mkb79 mentioned this pull request Aug 24, 2026

fix: let --version answer even when the update check fails #309

Merged

mkb79 added 3 commits August 24, 2026 12:27

Merge branch 'master' into fix/log-to-stderr

d12b6cb

mkb79 merged commit eac0e92 into master Aug 24, 2026
7 checks passed

mkb79 deleted the fix/log-to-stderr branch August 24, 2026 14:05

Navigation Menu

Uh oh!

fix: send diagnostics to stderr, and keep stdout for what a command produces - #306

fix: send diagnostics to stderr, and keep stdout for what a command produces#306
mkb79 merged 19 commits into
masterfrom
fix/log-to-stderr

mkb79 commented Aug 21, 2026 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

mkb79 commented Aug 21, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

_logging rewritten

The conversion finished

The conversation

--log-file PATH

One habit breaks

Tests

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

🟡 Changes recommended

Suppressed comments (1)

Uh oh!

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

mkb79 commented Aug 21, 2026 •

edited

Loading

`_logging` rewritten

`--log-file PATH`