rbrooks/Circa

Watch

Fork 0

No logging or observability anywhere in the backend #89

New issue

Closed

opened 2026-07-28 06:00:31 +00:00 by claude-bot · 1 comment

claude-bot commented

2026-07-28 06:00:31 +00:00

Severity: MEDIUM

The problem

There is no logging import anywhere under backend/app — confirmed by grep. The only
diagnostics are echo=True SQL dumps in development, which are themselves a data-disclosure
problem (they log comment bodies and notes).

When the OAuth callback fails, ingest rejects a file, or the worker dies, there is nothing to read.

The AuditEvent table is a product record of who changed what — it is not an operations log
and should not be pressed into that role.

Fix

Stdlib logging with a module-level logger per package.
Request-context middleware logging method, path, status, duration, and user id.
Log on raise in the exception handler introduced by the error-shape issue.
Structured output (JSON) so logs are greppable once the worker and deployment land.
Configurable level via CIRCA_LOG_LEVEL; drop echo=True in favour of a separate
CIRCA_SQL_ECHO that defaults off.

Done when

Requests, errors, and worker job transitions are logged
Log level is configurable and SQL echo is off by default
A failed OAuth callback leaves a useful server-side record
No user content is logged at default level

References

backend/app/main.py, backend/app/db/session.py:16

Related: #50 (deployment) will consume this.

## Severity: MEDIUM ## The problem There is no `logging` import anywhere under `backend/app` — confirmed by grep. The only diagnostics are `echo=True` SQL dumps in development, which are themselves a data-disclosure problem (they log comment bodies and notes). When the OAuth callback fails, ingest rejects a file, or the worker dies, there is nothing to read. The `AuditEvent` table is a **product** record of who changed what — it is not an operations log and should not be pressed into that role. ## Fix - Stdlib `logging` with a module-level logger per package. - Request-context middleware logging method, path, status, duration, and user id. - Log on raise in the exception handler introduced by the error-shape issue. - Structured output (JSON) so logs are greppable once the worker and deployment land. - Configurable level via `CIRCA_LOG_LEVEL`; drop `echo=True` in favour of a separate `CIRCA_SQL_ECHO` that defaults off. ## Done when - [ ] Requests, errors, and worker job transitions are logged - [ ] Log level is configurable and SQL echo is off by default - [ ] A failed OAuth callback leaves a useful server-side record - [ ] No user content is logged at default level ## References - `backend/app/main.py`, `backend/app/db/session.py:16` Related: #50 (deployment) will consume this.

claude-bot added this to the v0.2.0 milestone

2026-07-28 06:00:31 +00:00

claude-bot added the

backend

infra

labels

2026-07-28 06:00:31 +00:00

claude-bot referenced this issue

2026-08-03 15:16:18 +00:00

Add a development-only login bypass #15

rbrooks referenced this issue from a commit

2026-08-03 16:50:31 +00:00

Give the backend a log, and a rule about what goes in it

rbrooks closed this issue

2026-08-03 16:50:31 +00:00

claude-bot commented

2026-08-03 16:50:58 +00:00

Author

Done in 960e6f0. app/logging_config.py, RequestLogMiddleware, and backend/tests/test_logging.py (20).

What it writes

One line per request: method, path, status, duration, user id, request id. The id also comes back as X-Request-Id, so a reported problem can be found in the log without asking the person what time it was — and it is set as a contextvar, so a warning from deep inside the image sandbox carries the id of the upload that caused it without every function in the chain being handed one.

JSON by default. Not a style preference: a message containing a newline — an exception, an Authlib error payload — silently becomes two entries in a line-oriented text format, and the second one looks like a fresh event with no context. CIRCA_LOG_FORMAT=text for a terminal; CIRCA_LOG_LEVEL for the level.

4xx logs at INFO, 5xx at ERROR. A refused login is ordinary traffic, and shouting about it trains people to ignore the channel that is supposed to mean something.

The worker now installs the same handler instead of its own basicConfig format — they were writing differently-shaped lines to the same place, so anything reading them needed two parsers and a job failure could not be lined up with the request that enqueued it.

What it must never write, which is the actual design

The path, never the query string. There is no diagnostic question status=disputed answers that /api/photos does not — and logging the path alone means a future search parameter cannot quietly start recording what people look for.
The user id, never the email. An id is a handle for correlating lines; an address is a person, in a file that outlives the question it was written for.
Never a request or response body. Notes are what a relative said about a photograph; comments are a conversation between reviewers. A log file is copied to different places, kept for a different length of time, and read by people with different reasons to be looking.

LOGGED_FIELDS is a closed list and test_a_request_line_carries_only_the_declared_fields holds it closed. The failure worth guarding is not somebody logging a note on purpose — it is somebody adding request.query_params or a body because it was convenient, in a change nobody reads as being about privacy. Two more tests write a real note and a real comment through the API and assert the text appears in no record at all.

The ledger stays a product record

test_a_request_writes_no_audit_event asserts requests add nothing to AuditEvent. It is who-changed-what about a photograph, read by reviewers, and immutable at the database level (#67) — so a stack trace in there would be permanent and unremovable, which is the strongest possible reason not to start.

On the SQL echo

Already done in #14, which is where the environment default moved. The setting is CIRCA_SQLITE_ECHO rather than the CIRCA_SQL_ECHO this issue names — same thing, matching the CIRCA_SQLITE_* family already in config. Off by default and not implied by development, because the echoed statements contain exactly the note and comment bodies above.

Done when

Requests, errors, and worker job transitions are logged
Log level is configurable and SQL echo is off by default
A failed OAuth callback leaves a useful server-side record — asserted with the traceback, and asserted that the client still learns only "Authentication failed" (#59)
No user content is logged at default level

One thing found on the way: configure_logging is idempotent and refuses to stack handlers, because create_app() calls it and the test suite builds hundreds of applications in one process — a handler per app would multiply every line by the number ever constructed.

1079 passed, 8 skipped; ruff clean. README and .env.example updated.

Done in 960e6f0. `app/logging_config.py`, `RequestLogMiddleware`, and `backend/tests/test_logging.py` (20). ## What it writes One line per request: method, path, status, duration, user id, request id. The id also comes back as `X-Request-Id`, so a reported problem can be found in the log without asking the person what time it was — and it is set as a **contextvar**, so a warning from deep inside the image sandbox carries the id of the upload that caused it without every function in the chain being handed one. JSON by default. Not a style preference: a message containing a newline — an exception, an Authlib error payload — silently becomes *two* entries in a line-oriented text format, and the second one looks like a fresh event with no context. `CIRCA_LOG_FORMAT=text` for a terminal; `CIRCA_LOG_LEVEL` for the level. 4xx logs at INFO, 5xx at ERROR. A refused login is ordinary traffic, and shouting about it trains people to ignore the channel that is supposed to mean something. The worker now installs the same handler instead of its own `basicConfig` format — they were writing differently-shaped lines to the same place, so anything reading them needed two parsers and a job failure could not be lined up with the request that enqueued it. ## What it must never write, which is the actual design - **The path, never the query string.** There is no diagnostic question `status=disputed` answers that `/api/photos` does not — and logging the path alone means a future search parameter cannot quietly start recording what people look for. - **The user id, never the email.** An id is a handle for correlating lines; an address is a person, in a file that outlives the question it was written for. - **Never a request or response body.** Notes are what a relative said about a photograph; comments are a conversation between reviewers. A log file is copied to different places, kept for a different length of time, and read by people with different reasons to be looking. `LOGGED_FIELDS` is a closed list and `test_a_request_line_carries_only_the_declared_fields` holds it closed. The failure worth guarding is not somebody logging a note on purpose — it is somebody adding `request.query_params` or a body because it was convenient, in a change nobody reads as being about privacy. Two more tests write a real note and a real comment through the API and assert the text appears in no record at all. ## The ledger stays a product record `test_a_request_writes_no_audit_event` asserts requests add nothing to `AuditEvent`. It is who-changed-what about a photograph, read by reviewers, and immutable at the database level (#67) — so a stack trace in there would be permanent and unremovable, which is the strongest possible reason not to start. ## On the SQL echo Already done in #14, which is where the environment default moved. The setting is `CIRCA_SQLITE_ECHO` rather than the `CIRCA_SQL_ECHO` this issue names — same thing, matching the `CIRCA_SQLITE_*` family already in config. Off by default and **not** implied by development, because the echoed statements contain exactly the note and comment bodies above. ## Done when - [x] Requests, errors, and worker job transitions are logged - [x] Log level is configurable and SQL echo is off by default - [x] A failed OAuth callback leaves a useful server-side record — asserted with the traceback, and asserted that the *client* still learns only "Authentication failed" (#59) - [x] No user content is logged at default level One thing found on the way: `configure_logging` is idempotent and refuses to stack handlers, because `create_app()` calls it and the test suite builds hundreds of applications in one process — a handler per app would multiply every line by the number ever constructed. **1079 passed, 8 skipped**; ruff clean. README and `.env.example` updated.

claude-bot referenced this issue

2026-08-03 17:32:00 +00:00

No response compression for API JSON #92

claude-bot referenced this issue

2026-08-04 06:14:16 +00:00

A cancelled thumbnail request is logged as an ERROR with a traceback #139

rbrooks referenced this issue from a commit

2026-08-04 20:21:21 +00:00

Stop shouting about a browser that changed its mind