lvl0/fedi-feed-router

Fork 0

App reports healthy while the database is unreachable and Horizon is dead #164

New issue

Closed

opened 2026-09-26 08:35:05 +02:00 by myrmidex · 1 comment

myrmidex commented

2026-09-26 08:35:05 +02:00

Owner

Incident

The app served HTTP 500 on every authenticated page for ~37 hours. Root cause was infrastructure: the ffr_db MariaDB container was absent from the production stack (docker ps -a showed only ffr_app and ffr_redis; docker inspect ffr_db → no such object; getent hosts db failed 20/20). The mariadb:11 image had to be re-pulled, suggesting the container and its image were removed by a prune while the two running containers were skipped.

Resolved by docker compose up -d db. The ffr_db_data volume survived, data was intact, and migrate:status confirmed all 24 migrations Ran including 000024_fix_belga_feed_offset.

No code change would have prevented the outage. What the code did wrong was hide it for 37 hours, and then fail to recover. This ticket covers the three defects that allowed that.

1. `/up` healthcheck passes while the database is unreachable

Dockerfile:70 runs curl -f http://localhost:8000/up, and bootstrap/app.php:16 configures health: '/up'. Laravel's built-in health endpoint dispatches DiagnosingHealth and returns 200 without touching the database, so a missing DB reads as a healthy app. The container reported healthy for the entire outage — no alert, no restart. The failure was found by loading a page by hand.

Fix: register a DiagnosingHealth listener that verifies DB connectivity (e.g. DB::connection()->getPdo()), so /up fails when the database is unreachable.

Note: a separate /health route at routes/web.php:44 returns a static {"status":"ok"} and is not what the healthcheck uses. Decide whether to converge or remove it.

Tests: /up returns non-200 when the DB connection throws; 200 when healthy.

2. Exception logging writes to the database, so DB outages are recorded nowhere

LogExceptionToDatabase::handle() persists every exception via Log::create(). When the database is the thing that failed, the insert fails identically and the exception is lost. The only surviving output was the wrapper from app/Listeners/LogExceptionToDatabase.php:35:

Failed to log exception to database: SQLSTATE[HY000] [2002] ... (SQL: insert into `logs` ...)

That names the failed insert, not the original error. The real cause — a QueryException from SessionGuard::userFromRecaller() during auth — was only recoverable because the nested exception text happened to embed it. Diagnosis depended on that accident.

The existing comment at line 34 already flags the gap: // Optionally log to file or other non-database destination

Fix: in the catch block, write the original exception through Laravel's file/stderr logger (Log::channel(...)) rather than only error_log() with the wrapper message. Preserve exception class, file, line and trace.

Tests: when Log::create() throws, the original exception's details reach the fallback channel.

3. Container boots with no database, and nothing supervises Horizon

/start-prod.sh (Dockerfile:73-110) waits for the DB in a for i in $(seq 1 30) loop with sleep 2 — 60 seconds — then falls through unconditionally. There is no exit and no failure path. With no db container it waited 60s, then ran config:cache, migrate, db:seed and php artisan horizon & against an unreachable database.

Consequences observed:

horizon:status → Horizon is inactive. The worker died at boot and never recovered when the DB returned 37 hours later — nothing supervises it.
245 pending jobs on the publishing queue. Redis stayed healthy throughout, so the scheduler's Schedule::job() calls all enqueued successfully and reported DONE every 5 minutes while nothing consumed them.
The Articles page "Refresh" button appeared to do nothing, because ArticleDiscoveryJob was enqueued onto a queue with no worker.

The backlog itself is not dangerous — PublishNextArticleJob guards on article_publishing_interval, a daily cap, ShouldBeUnique, and whereDoesntHave(...articlePublications...) — so it drains as mostly early returns.

Fix: fail fast when the DB never becomes reachable so the container exits and the restart policy retries, rather than booting a broken app. Supervise Horizon so a dead worker restarts.

Note: this is a Dockerfile change and cannot be verified by the PHPUnit/Pint/PHPStan gates, which run inside the already-built container. It needs a real image build and deploy to prove.

Common theme

All three let a dead dependency masquerade as a working app. #1 is why nobody was told, #2 is why there was no evidence, #3 is why it never recovered.

## Incident The app served HTTP 500 on every authenticated page for ~37 hours. Root cause was **infrastructure**: the `ffr_db` MariaDB container was absent from the production stack (`docker ps -a` showed only `ffr_app` and `ffr_redis`; `docker inspect ffr_db` → `no such object`; `getent hosts db` failed 20/20). The `mariadb:11` image had to be re-pulled, suggesting the container and its image were removed by a prune while the two running containers were skipped. Resolved by `docker compose up -d db`. The `ffr_db_data` volume survived, data was intact, and `migrate:status` confirmed all 24 migrations `Ran` including `000024_fix_belga_feed_offset`. No code change would have prevented the outage. What the code did wrong was **hide it for 37 hours**, and then fail to recover. This ticket covers the three defects that allowed that. ## 1. `/up` healthcheck passes while the database is unreachable `Dockerfile:70` runs `curl -f http://localhost:8000/up`, and `bootstrap/app.php:16` configures `health: '/up'`. Laravel's built-in health endpoint dispatches `DiagnosingHealth` and returns 200 without touching the database, so a missing DB reads as a healthy app. The container reported `healthy` for the entire outage — no alert, no restart. The failure was found by loading a page by hand. **Fix**: register a `DiagnosingHealth` listener that verifies DB connectivity (e.g. `DB::connection()->getPdo()`), so `/up` fails when the database is unreachable. **Note**: a separate `/health` route at `routes/web.php:44` returns a static `{"status":"ok"}` and is *not* what the healthcheck uses. Decide whether to converge or remove it. **Tests**: `/up` returns non-200 when the DB connection throws; 200 when healthy. ## 2. Exception logging writes to the database, so DB outages are recorded nowhere `LogExceptionToDatabase::handle()` persists every exception via `Log::create()`. When the database is the thing that failed, the insert fails identically and the exception is lost. The only surviving output was the wrapper from `app/Listeners/LogExceptionToDatabase.php:35`: ``` Failed to log exception to database: SQLSTATE[HY000] [2002] ... (SQL: insert into `logs` ...) ``` That names the *failed insert*, not the original error. The real cause — a `QueryException` from `SessionGuard::userFromRecaller()` during auth — was only recoverable because the nested exception text happened to embed it. Diagnosis depended on that accident. The existing comment at line 34 already flags the gap: `// Optionally log to file or other non-database destination` **Fix**: in the catch block, write the original exception through Laravel's file/stderr logger (`Log::channel(...)`) rather than only `error_log()` with the wrapper message. Preserve exception class, file, line and trace. **Tests**: when `Log::create()` throws, the original exception's details reach the fallback channel. ## 3. Container boots with no database, and nothing supervises Horizon `/start-prod.sh` (`Dockerfile:73-110`) waits for the DB in a `for i in $(seq 1 30)` loop with `sleep 2` — 60 seconds — then **falls through unconditionally**. There is no `exit` and no failure path. With no `db` container it waited 60s, then ran `config:cache`, `migrate`, `db:seed` and `php artisan horizon &` against an unreachable database. Consequences observed: - `horizon:status` → **`Horizon is inactive`**. The worker died at boot and never recovered when the DB returned 37 hours later — nothing supervises it. - **245 pending jobs on the `publishing` queue.** Redis stayed healthy throughout, so the scheduler's `Schedule::job()` calls all enqueued successfully and reported `DONE` every 5 minutes while nothing consumed them. - The Articles page "Refresh" button appeared to do nothing, because `ArticleDiscoveryJob` was enqueued onto a queue with no worker. The backlog itself is not dangerous — `PublishNextArticleJob` guards on `article_publishing_interval`, a daily cap, `ShouldBeUnique`, and `whereDoesntHave(...articlePublications...)` — so it drains as mostly early returns. **Fix**: fail fast when the DB never becomes reachable so the container exits and the restart policy retries, rather than booting a broken app. Supervise Horizon so a dead worker restarts. **Note**: this is a Dockerfile change and cannot be verified by the PHPUnit/Pint/PHPStan gates, which run inside the already-built container. It needs a real image build and deploy to prove. ## Common theme All three let a dead dependency masquerade as a working app. #1 is why nobody was told, #2 is why there was no evidence, #3 is why it never recovered.

myrmidex added the

bug

label 2026-09-26 08:35:05 +02:00

myrmidex self-assigned this 2026-09-26 08:35:05 +02:00

myrmidex referenced this issue

2026-09-26 08:53:06 +02:00

/up healthcheck passes while the database is unreachable #165

myrmidex referenced this issue

2026-09-26 08:53:16 +02:00

Exception logging writes to the database, so DB outages are recorded nowhere #166

myrmidex changed title from ~~500 error on server~~ to App reports healthy while the database is unreachable and Horizon is dead

2026-09-26 09:35:52 +02:00

myrmidex added this to the v1.4.3 milestone 2026-09-26 09:35:52 +02:00

myrmidex referenced this issue

2026-09-26 09:36:00 +02:00

/up healthcheck passes while the database is unreachable #165

myrmidex referenced this issue

2026-09-26 09:36:10 +02:00

Exception logging writes to the database, so DB outages are recorded nowhere #166

myrmidex commented

2026-09-26 14:32:15 +02:00

Author

Owner

Fixed in #167, merged to release/v1.4.3:

9247db3 — Log exceptions to a non-database fallback
59d12d6 — Fail the health check when the database is unreachable
2244170 — Exit on database timeout and supervise the workers
b792ee7 — Add the v1.4.3 changelog section and bump the README pin

Each fix was verified red before green: /up returned 200 against a mocked-dead database without the listener, and the log fallback expectation was never called against the original listener. Gates green on all four commits (Pint 361 files, PHPStan clean, 752 Unit + 521 Feature tests), CI runs #106 and #107 success.

One caveat on the startup-script fix (2244170). It cannot be verified by the test gates — those run inside the already-built dev container and never execute /start-prod.sh. What was verified: POSIX syntax via sh -n, and the supervisor restart loop empirically. That second check caught a real bug: under set -e, an unguarded failing command kills the background subshell, so the first version of supervise() ran the command once and the loop died — it would have supervised nothing. Fixed with "$@" || echo ....

The first real execution of the script is the v1.4.3 image build and deploy. If the database-wait exit 1 or the supervisor loop misbehaves, the symptom is a container that will not start; v1.4.2 is the rollback target.

The underlying outage cause is still unexplained. These fixes improve detection and recovery — none of them prevents the ffr_db container from going missing again. journalctl -u docker --since '3 days ago' | grep ffr_db may show what removed it.

Fixed in #167, merged to `release/v1.4.3`: - `9247db3` — Log exceptions to a non-database fallback - `59d12d6` — Fail the health check when the database is unreachable - `2244170` — Exit on database timeout and supervise the workers - `b792ee7` — Add the v1.4.3 changelog section and bump the README pin Each fix was verified red before green: `/up` returned **200** against a mocked-dead database without the listener, and the log fallback expectation was never called against the original listener. Gates green on all four commits (Pint 361 files, PHPStan clean, 752 Unit + 521 Feature tests), CI runs #106 and #107 `success`. **One caveat on the startup-script fix (`2244170`).** It cannot be verified by the test gates — those run inside the already-built dev container and never execute `/start-prod.sh`. What was verified: POSIX syntax via `sh -n`, and the supervisor restart loop empirically. That second check caught a real bug: under `set -e`, an unguarded failing command kills the background subshell, so the first version of `supervise()` ran the command once and the loop died — it would have supervised nothing. Fixed with `"$@" || echo ...`. The first real execution of the script is the `v1.4.3` image build and deploy. If the database-wait `exit 1` or the supervisor loop misbehaves, the symptom is a container that will not start; `v1.4.2` is the rollback target. **The underlying outage cause is still unexplained.** These fixes improve detection and recovery — none of them prevents the `ffr_db` container from going missing again. `journalctl -u docker --since '3 days ago' | grep ffr_db` may show what removed it.

myrmidex closed this issue

2026-09-26 14:32:19 +02:00

myrmidex referenced this issue

2026-09-26 16:07:20 +02:00

Run the test suite against MariaDB instead of SQLite #169

myrmidex referenced this issue

2026-09-26 17:11:33 +02:00

Title rewriting rules per feed and route #155