[PR #144] [MERGED] [debug-log] Log request outcomes, connection phases and retry attempts #149

New issue

Closed

opened 2026-10-13 19:48:00 +00:00 by bsakaguchi · 0 comments

bsakaguchi commented

2026-10-13 19:48:00 +00:00

Owner

📋 Pull Request Information

Original PR: https://github.com/Glitchy-Sheep/boosty-downloader/pull/144
Author: @Glitchy-Sheep
Created: 8/15/2026
Status: ✅ Merged
Merged: 8/15/2026
Merged by: @Glitchy-Sheep

Base: main ← Head: feat/debug-log-network-phases

📝 Commits (3)

4e57564 feat: Log request outcomes and connection phases in the debug log
9140dd7 feat: Show retry attempt numbers in the debug log
c82f6d1 docs: Note the debug log request tracing in the changelog

📊 Changes

6 files changed (+341 additions, -16 deletions)

View changed files

📝 CHANGELOG.md (+4 -0)
📝 boosty_downloader/src/application/di/app_environment.py (+5 -1)
📝 boosty_downloader/src/infrastructure/loggers/request_tracing.py (+178 -10)
📝 ruff.toml (+2 -1)
📝 test/unit/external_videos_downloader/title_limit_test.py (+3 -3)
📝 test/unit/loggers/request_tracing_test.py (+149 -1)

📄 Description

Summary

The debug log used to record only that a request started. A hang or a killed connection left the log silent - diagnosing the recent network incident took manual raw requests. Now every request logs its outcome, its connection phases and its retry attempt number: the log answers "what happened and where it got stuck" by itself.

Problem

One request start line was the whole trace: no outcome, no timing, no error
Retries were invisible: five failing attempts looked like five identical start lines with silent 13-second gaps
During a hang the log had nothing to say at all - the failing phase (dns / connect / TLS) was anyone's guess

Fix

Every request gets a short id (#N) tying its lines together, an outcome line with status and timing (-> 200 in 0.31s) or the error chain (-> FAIL ClientConnectorError <- ConnectionResetError in 12.1s), and phase timings (dns 0.123s, conn 1.043s; pooled connections say conn reused)
A live connecting... line marks the connection phase: while a connect hangs, it stays the last line of the log
A phase that died mid-way reports how long it lasted - a 12-second tarpit is visible as conn 12.0s on the failed attempt
Requests through the retry client are marked (attempt 2/5); the budget comes from DI, requests outside the retry client get no mark
URLs stay redacted exactly as before - outcome lines carry the request id instead of repeating the URL

Before / After

Before: a killed TLS handshake looks like nothing: the same GET line repeats every ~13 seconds, the log never says why.
After:

#1 GET https://api.boosty.to/v1/blog/author/post/?limit=... (attempt 1/5)
#1 connecting...
#1 -> FAIL ClientConnectorError <- ConnectionResetError in 12.10s (dns 0.011s, conn 12.09s)
#2 GET https://api.boosty.to/v1/blog/author/post/?limit=... (attempt 2/5)

Verification

Live run of --debug check against the real API: start line with (attempt 1/5), live connecting..., outcome -> 200 in 1.64s (dns 0.123s, conn 1.043s) - taken from the actual log file
9 unit tests on the tracing hooks: outcome with phases, error chain of a reset handshake, "last line is connecting" for hangs, pooled connections, shared request id, attempt marks present and absent
Full task ci green: checks, 107 unit tests, 6 live integration tests, build

_{🔄 This issue represents a GitHub Pull Request. It cannot be merged through Gitea due to API limitations.}

## 📋 Pull Request Information **Original PR:** https://github.com/Glitchy-Sheep/boosty-downloader/pull/144 **Author:** [@Glitchy-Sheep](https://github.com/Glitchy-Sheep) **Created:** 8/15/2026 **Status:** ✅ Merged **Merged:** 8/15/2026 **Merged by:** [@Glitchy-Sheep](https://github.com/Glitchy-Sheep) **Base:** `main` ← **Head:** `feat/debug-log-network-phases` --- ### 📝 Commits (3) - [`4e57564`](https://github.com/Glitchy-Sheep/boosty-downloader/commit/4e5756405d21d213e0bc1c52b3e5da0d18add9eb) feat: Log request outcomes and connection phases in the debug log - [`9140dd7`](https://github.com/Glitchy-Sheep/boosty-downloader/commit/9140dd7004fe2734453771132f539427b200125f) feat: Show retry attempt numbers in the debug log - [`c82f6d1`](https://github.com/Glitchy-Sheep/boosty-downloader/commit/c82f6d12685725a17baf73c8e52441230fb534f4) docs: Note the debug log request tracing in the changelog ### 📊 Changes **6 files changed** (+341 additions, -16 deletions) <details> <summary>View changed files</summary> 📝 `CHANGELOG.md` (+4 -0) 📝 `boosty_downloader/src/application/di/app_environment.py` (+5 -1) 📝 `boosty_downloader/src/infrastructure/loggers/request_tracing.py` (+178 -10) 📝 `ruff.toml` (+2 -1) 📝 `test/unit/external_videos_downloader/title_limit_test.py` (+3 -3) 📝 `test/unit/loggers/request_tracing_test.py` (+149 -1) </details> ### 📄 Description ## Summary The debug log used to record only that a request started. A hang or a killed connection left the log silent - diagnosing the recent network incident took manual raw requests. Now every request logs its outcome, its connection phases and its retry attempt number: the log answers "what happened and where it got stuck" by itself. ## Problem - One request start line was the whole trace: no outcome, no timing, no error - Retries were invisible: five failing attempts looked like five identical start lines with silent 13-second gaps - During a hang the log had nothing to say at all - the failing phase (dns / connect / TLS) was anyone's guess ## Fix - Every request gets a short id (`#N`) tying its lines together, an outcome line with status and timing (`-> 200 in 0.31s`) or the error chain (`-> FAIL ClientConnectorError <- ConnectionResetError in 12.1s`), and phase timings (`dns 0.123s, conn 1.043s`; pooled connections say `conn reused`) - A live `connecting...` line marks the connection phase: while a connect hangs, it stays the last line of the log - A phase that died mid-way reports how long it lasted - a 12-second tarpit is visible as `conn 12.0s` on the failed attempt - Requests through the retry client are marked `(attempt 2/5)`; the budget comes from DI, requests outside the retry client get no mark - URLs stay redacted exactly as before - outcome lines carry the request id instead of repeating the URL ## Before / After **Before:** a killed TLS handshake looks like nothing: the same GET line repeats every ~13 seconds, the log never says why. **After:** ``` #1 GET https://api.boosty.to/v1/blog/author/post/?limit=... (attempt 1/5) #1 connecting... #1 -> FAIL ClientConnectorError <- ConnectionResetError in 12.10s (dns 0.011s, conn 12.09s) #2 GET https://api.boosty.to/v1/blog/author/post/?limit=... (attempt 2/5) ``` ## Verification - Live run of `--debug check` against the real API: start line with `(attempt 1/5)`, live `connecting...`, outcome `-> 200 in 1.64s (dns 0.123s, conn 1.043s)` - taken from the actual log file - 9 unit tests on the tracing hooks: outcome with phases, error chain of a reset handshake, "last line is connecting" for hangs, pooled connections, shared request id, attempt marks present and absent - Full `task ci` green: checks, 107 unit tests, 6 live integration tests, build --- <sub>🔄 This issue represents a GitHub Pull Request. It cannot be merged through Gitea due to API limitations.</sub>

bsakaguchi

2026-10-13 19:48:00 +00:00