Notechondria

Version: 0.1.47 Build Date: 2026-04-20T08:00

What's Changed

Backend: fix misleading access-log levels + add §1.7-shaped context

User-reported noise in prod logs:

WARNING  401     62.8ms  POST   /api/v1/notes/
WARNING  'Unauthorized: /api/v1/notes/'
INFO     204      0.5ms  OPTIONS /api/v1/notes/
WARNING  200   1569.2ms  GET    /api/v1/front-page/
CRITICAL 200   6475.4ms  GET    /api/v1/front-page/

Three separate problems fixed:

1. Middleware: level picking decoupled from duration

notechondria.middleware.RequestTimingMiddleware previously promoted any 4xx or any 2xx slower than 500 ms to WARNING, and any 5xx or any 2xx slower than 2000 ms to CRITICAL. That's why a slow successful front-page load showed up as CRITICAL 200.

The fix decouples the two signals:

• Log level = failure signal. _level_for(status) returns error for 5xx, info for everything else (including 4xx). A routine 401/403/404 no longer pages on-call.
• Duration = perf signal, colored separately. Duration >= _VERY_SLOW_MS (2000 ms) turns the duration cell red, >= _SLOW_MS (500 ms) turns it yellow, otherwise it inherits the status color. Same information density, no semantic collision.

Concrete before/after for the reported lines:

2. Django's duplicate Unauthorized: log silenced

Django's default django.request logger emits a WARNING 'Unauthorized: /api/v1/notes/' on top of our own access line for every 4xx. That was the second line in the user's sample.

Raised the django.request logger threshold to ERROR in backend/notechondria/settings.py so 4xx/5xx no longer double-log and our own structured access line stays the single source of truth for request outcomes. 5xx crashes still surface at ERROR level because Django logs the traceback at that level before our middleware runs.

3. §1.7-shaped 401/403 context on every DRF-gated endpoint

The note-editor path had zero backend logging, so a 401 on POST /api/v1/notes/ gave the operator no way to tell which auth class failed or which token prefix was rejected.

Added backend/notechondria/drf_exception_handler.py and wired it via REST_FRAMEWORK.EXCEPTION_HANDLER so every DRF auth/permission failure emits one line through the new notechondria.auth logger in the AGENTS.md §1.7 shape:

Request rejected: Backend.Auth/permission_check — 401 on
POST /api/v1/notes/ (token=abc12345…, cause: Invalid token.)

NotAuthenticated, AuthenticationFailed, and PermissionDenied each produce a distinct line so operators can distinguish "no token supplied" from "token signature mismatch" from "403 owner mismatch". The handler logs the first 8 chars of the bearer token (safe — the DB stores SHA-256 hashes, not the plaintext) so ops can correlate with the API-key audit trail. Response bodies are unchanged; we delegate to DRF's default handler after logging.

4. Note-editor path structured success + failure logs

backend/notes/api.py now pulls a module-level logger under notechondria.notes (also a new entry in LOGGING['loggers']) and emits shaped lines for the three note-editor flows the user explicitly called out:

• NoteListCreateApiView.post — logs creator, note_id, client_draft_id, course_id, editor_mode on both create and upsert.
• NoteDetailApiView.patch — logs fields touched on success, WARNING on 403 owner mismatch with requesting vs owner user ids.
• NoteDetailApiView.delete — logs the soft-delete transition into the recycle bin.

All lines follow "<consequence>: Backend.Notes.Notes/<process> — <cause>".

5. Bulk reshape of non-compliant login/OAuth log lines

creators/api.py had 15+ informal-style log calls in the OAuth bind flow ("BindGoogle: user=...", "BindGitHub token exchange failed", etc.). Reshaped every one of them to §1.7 form so the shape is consistent across the codebase — the Flutter side already emits §1.7-shaped SnackBars and logs, so operator tools like grep and Loki queries now match end-to-end:

Account linking {started|in progress|aborted|failed|complete}:
Backend.Creators.Auth/bind.<provider>.<phase> — <cause>

Files Changed

New

• docs/versions/0.1.47.md (this file).
• backend/notechondria/drf_exception_handler.py: DRF-wide shaped-log wrapper around the default exception handler.

Modified

• VERSION: 0.1.46 → 0.1.47.
• backend/notechondria/middleware.py: _level_for(status) split + independent duration coloring.
• backend/notechondria/settings.py: LOGGING.loggers adds django.request at ERROR, adds notechondria.auth + notechondria.notes at INFO; REST_FRAMEWORK.EXCEPTION_HANDLER points at the new handler.
• backend/creators/api.py: 15 OAuth bind log calls reshaped to §1.7.
• backend/notes/api.py: module logger + three shaped lines on the note-editor CRUD paths.

Verification

• python manage.py check (settings_test): 0 issues.
• python manage.py test notes creators mcp: 130 tests pass — unchanged from 0.1.45, no regressions.

Notes / follow-ups

• Signal-not-alert: the fix intentionally does not introduce a new WARNING band between INFO and ERROR for 4xx. If ops later want to alert on a surge of 401s, that's a rate-based alert on the access log, not a per-request level bump. This keeps "severity" aligned with "something broke" semantics.
• Color palette unchanged: yellow is still used on the duration field for 500–2000 ms. Operators who scan by color keep their muscle memory; what changed is that a slow 200 is now a yellow duration on an INFO row, not the whole row labeled WARNING.
• Remaining non-shaped logs live in creators/forms.py and the OAuth login (not bind) path around creators/api.py:1110 / :1241 for Google/GitHub login — those two are shaped now (the OAuth token-exchange entry points), but the non-bind login flow's post-exchange user-lookup calls still use ad-hoc wording. Fold into a later commit; scope of this round was the user-flagged access-log noise + login + note-editor.