fix/164-health-and-logging-resilience #167
8 changed files with 300 additions and 20 deletions
11
CHANGELOG.md
11
CHANGELOG.md
|
|
@ -2,6 +2,17 @@ # Changelog
|
||||||
|
|
||||||
All notable changes to this project will be documented in this file.
|
All notable changes to this project will be documented in this file.
|
||||||
|
|
||||||
|
## [1.4.3] - 2026-09-26
|
||||||
|
|
||||||
|
### Fixed
|
||||||
|
|
||||||
|
- Fix the container reporting itself healthy while its database was unreachable (#164)
|
||||||
|
- The `/up` health check returned 200 without touching the database. When the database container went missing, the container stayed healthy for 37 hours while every page returned a 500, so nothing alerted and nothing restarted. The health check now fails when the database cannot be reached.
|
||||||
|
- Fix exceptions being lost when the database is the thing that failed (#164)
|
||||||
|
- Exceptions were only ever written to the `logs` table, so a database outage discarded the very errors needed to diagnose it. They now fall back to the configured log channel, preserving the original exception rather than only the failed insert.
|
||||||
|
- Fix the container starting up without a database and never recovering (#164)
|
||||||
|
- The startup script waited 60 seconds for the database and then continued regardless, running migrations against an unreachable server and starting an unsupervised queue worker. The worker died at boot and stayed dead, so publish jobs accumulated unconsumed and the Articles page "Refresh" button silently did nothing. The container now exits so the restart policy retries, migration failures are no longer swallowed, and a worker that dies is restarted.
|
||||||
|
|
||||||
## [1.4.2] - 2026-08-16
|
## [1.4.2] - 2026-08-16
|
||||||
|
|
||||||
### Fixed
|
### Fixed
|
||||||
|
|
|
||||||
29
Dockerfile
29
Dockerfile
|
|
@ -67,7 +67,8 @@ EOF
|
||||||
EXPOSE 8000
|
EXPOSE 8000
|
||||||
|
|
||||||
# Health check
|
# Health check
|
||||||
HEALTHCHECK --interval=30s --timeout=3s --start-period=5s --retries=3 \
|
# start-period must outlast the startup script's 60s database wait.
|
||||||
|
HEALTHCHECK --interval=30s --timeout=3s --start-period=75s --retries=3 \
|
||||||
CMD curl -f http://localhost:8000/up || exit 1
|
CMD curl -f http://localhost:8000/up || exit 1
|
||||||
|
|
||||||
# Create startup script for production
|
# Create startup script for production
|
||||||
|
|
@ -77,32 +78,44 @@ set -e
|
||||||
|
|
||||||
# Wait for database to be ready
|
# Wait for database to be ready
|
||||||
echo "Waiting for database..."
|
echo "Waiting for database..."
|
||||||
|
db_ready=0
|
||||||
for i in $(seq 1 30); do
|
for i in $(seq 1 30); do
|
||||||
if mysqladmin ping -h "$DB_HOST" -u "$DB_USERNAME" -p"$DB_PASSWORD" --silent 2>/dev/null; then
|
if mysqladmin ping -h "$DB_HOST" -u "$DB_USERNAME" -p"$DB_PASSWORD" --silent 2>/dev/null; then
|
||||||
echo "Database is ready!"
|
echo "Database is ready!"
|
||||||
|
db_ready=1
|
||||||
break
|
break
|
||||||
fi
|
fi
|
||||||
echo "Waiting for database... ($i/30)"
|
echo "Waiting for database... ($i/30)"
|
||||||
sleep 2
|
sleep 2
|
||||||
done
|
done
|
||||||
|
|
||||||
|
if [ "$db_ready" -ne 1 ]; then
|
||||||
|
echo "Database unreachable at ${DB_HOST} after 60s; exiting so the restart policy retries." >&2
|
||||||
|
exit 1
|
||||||
|
fi
|
||||||
|
|
||||||
# Cache config with runtime env vars
|
# Cache config with runtime env vars
|
||||||
echo "Caching configuration..."
|
echo "Caching configuration..."
|
||||||
php artisan config:cache
|
php artisan config:cache
|
||||||
|
|
||||||
# Run migrations
|
# Run migrations. A partial schema is worse than a container that refuses to start.
|
||||||
echo "Running migrations..."
|
echo "Running migrations..."
|
||||||
php artisan migrate --force || echo "Migrations failed or already up-to-date"
|
php artisan migrate --force
|
||||||
|
|
||||||
# Run seeders (idempotent - uses updateOrInsert)
|
# Run seeders (idempotent - uses updateOrInsert)
|
||||||
echo "Running seeders..."
|
echo "Running seeders..."
|
||||||
php artisan db:seed --force || echo "Seeders failed or already run"
|
php artisan db:seed --force
|
||||||
|
|
||||||
# Start Horizon in the background
|
# Restart a worker that dies instead of leaving the queue unconsumed.
|
||||||
php artisan horizon &
|
supervise() {
|
||||||
|
while true; do
|
||||||
|
"$@" || echo "[supervisor] '$*' exited with $?; restarting in 5s." >&2
|
||||||
|
sleep 5
|
||||||
|
done
|
||||||
|
}
|
||||||
|
|
||||||
# Start the scheduler in the background
|
supervise php artisan horizon &
|
||||||
php artisan schedule:work &
|
supervise php artisan schedule:work &
|
||||||
|
|
||||||
# Start FrankenPHP
|
# Start FrankenPHP
|
||||||
exec frankenphp run --config /etc/caddy/Caddyfile
|
exec frankenphp run --config /etc/caddy/Caddyfile
|
||||||
|
|
|
||||||
|
|
@ -71,7 +71,7 @@ ### docker-compose.yml
|
||||||
```yaml
|
```yaml
|
||||||
services:
|
services:
|
||||||
app:
|
app:
|
||||||
image: forge.lvl0.xyz/lvl0/fedi-feed-router:v1.4.1
|
image: forge.lvl0.xyz/lvl0/fedi-feed-router:v1.4.3
|
||||||
container_name: ffr_app
|
container_name: ffr_app
|
||||||
restart: always
|
restart: always
|
||||||
ports:
|
ports:
|
||||||
|
|
|
||||||
|
|
@ -5,6 +5,8 @@
|
||||||
use App\Events\ExceptionLogged;
|
use App\Events\ExceptionLogged;
|
||||||
use App\Events\ExceptionOccurred;
|
use App\Events\ExceptionOccurred;
|
||||||
use App\Models\Log;
|
use App\Models\Log;
|
||||||
|
use Illuminate\Support\Facades\Log as Logger;
|
||||||
|
use Throwable;
|
||||||
|
|
||||||
class LogExceptionToDatabase
|
class LogExceptionToDatabase
|
||||||
{
|
{
|
||||||
|
|
@ -19,20 +21,51 @@ public function handle(ExceptionOccurred $event): void
|
||||||
$log = Log::create([
|
$log = Log::create([
|
||||||
'level' => $event->level,
|
'level' => $event->level,
|
||||||
'message' => $message,
|
'message' => $message,
|
||||||
'context' => [
|
'context' => $this->buildContext($event),
|
||||||
'exception_class' => get_class($event->exception),
|
|
||||||
'file' => $event->exception->getFile(),
|
|
||||||
'line' => $event->exception->getLine(),
|
|
||||||
'trace' => $event->exception->getTraceAsString(),
|
|
||||||
...$event->context,
|
|
||||||
],
|
|
||||||
]);
|
]);
|
||||||
|
|
||||||
ExceptionLogged::dispatch($log);
|
ExceptionLogged::dispatch($log);
|
||||||
} catch (\Exception $e) {
|
} catch (Throwable $e) {
|
||||||
// Prevent infinite recursion by not logging this exception
|
$this->logToFallback($event, $e);
|
||||||
// Optionally log to file or other non-database destination
|
|
||||||
error_log('Failed to log exception to database: '.$e->getMessage());
|
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/**
|
||||||
|
* The database is the thing that failed, so this must not touch it.
|
||||||
|
*/
|
||||||
|
private function logToFallback(ExceptionOccurred $event, Throwable $storageFailure): void
|
||||||
|
{
|
||||||
|
$context = [
|
||||||
|
...$this->buildContext($event),
|
||||||
|
'storage_failure' => $storageFailure->getMessage(),
|
||||||
|
];
|
||||||
|
|
||||||
|
try {
|
||||||
|
Logger::log($event->level->value, $event->message, $context);
|
||||||
|
} catch (Throwable $loggerFailure) {
|
||||||
|
error_log(sprintf(
|
||||||
|
'%s: %s in %s:%d (database and log channel both unavailable: %s / %s)',
|
||||||
|
get_class($event->exception),
|
||||||
|
$event->message,
|
||||||
|
$event->exception->getFile(),
|
||||||
|
$event->exception->getLine(),
|
||||||
|
$storageFailure->getMessage(),
|
||||||
|
$loggerFailure->getMessage(),
|
||||||
|
));
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
/**
|
||||||
|
* @return array<string, mixed>
|
||||||
|
*/
|
||||||
|
private function buildContext(ExceptionOccurred $event): array
|
||||||
|
{
|
||||||
|
return [
|
||||||
|
'exception_class' => get_class($event->exception),
|
||||||
|
'file' => $event->exception->getFile(),
|
||||||
|
'line' => $event->exception->getLine(),
|
||||||
|
'trace' => $event->exception->getTraceAsString(),
|
||||||
|
...$event->context,
|
||||||
|
];
|
||||||
|
}
|
||||||
}
|
}
|
||||||
|
|
|
||||||
23
app/Listeners/VerifyDatabaseIsReachable.php
Normal file
23
app/Listeners/VerifyDatabaseIsReachable.php
Normal file
|
|
@ -0,0 +1,23 @@
|
||||||
|
<?php
|
||||||
|
|
||||||
|
namespace App\Listeners;
|
||||||
|
|
||||||
|
use Illuminate\Foundation\Events\DiagnosingHealth;
|
||||||
|
use Illuminate\Support\Facades\DB;
|
||||||
|
use RuntimeException;
|
||||||
|
use Throwable;
|
||||||
|
|
||||||
|
class VerifyDatabaseIsReachable
|
||||||
|
{
|
||||||
|
/**
|
||||||
|
* A container whose database is unreachable is not healthy, however well it serves /up.
|
||||||
|
*/
|
||||||
|
public function handle(DiagnosingHealth $event): void
|
||||||
|
{
|
||||||
|
try {
|
||||||
|
DB::connection()->select('select 1');
|
||||||
|
} catch (Throwable $e) {
|
||||||
|
throw new RuntimeException('The database is not reachable: '.$e->getMessage(), previous: $e);
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
@ -9,6 +9,7 @@
|
||||||
use App\Events\RouteActivated;
|
use App\Events\RouteActivated;
|
||||||
use App\Events\RouteArticleApproved;
|
use App\Events\RouteArticleApproved;
|
||||||
use Illuminate\Contracts\Debug\ExceptionHandler;
|
use Illuminate\Contracts\Debug\ExceptionHandler;
|
||||||
|
use Illuminate\Foundation\Events\DiagnosingHealth;
|
||||||
use Illuminate\Support\Facades\Event;
|
use Illuminate\Support\Facades\Event;
|
||||||
use PHPUnit\Framework\Attributes\DataProvider;
|
use PHPUnit\Framework\Attributes\DataProvider;
|
||||||
use RuntimeException;
|
use RuntimeException;
|
||||||
|
|
@ -28,6 +29,7 @@ public static function eventProvider(): array
|
||||||
'NewArticleFetched' => [NewArticleFetched::class],
|
'NewArticleFetched' => [NewArticleFetched::class],
|
||||||
'RouteActivated' => [RouteActivated::class],
|
'RouteActivated' => [RouteActivated::class],
|
||||||
'RouteArticleApproved' => [RouteArticleApproved::class],
|
'RouteArticleApproved' => [RouteArticleApproved::class],
|
||||||
|
'DiagnosingHealth' => [DiagnosingHealth::class],
|
||||||
];
|
];
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|
|
||||||
41
tests/Feature/HealthEndpointTest.php
Normal file
41
tests/Feature/HealthEndpointTest.php
Normal file
|
|
@ -0,0 +1,41 @@
|
||||||
|
<?php
|
||||||
|
|
||||||
|
namespace Tests\Feature;
|
||||||
|
|
||||||
|
use App\Listeners\VerifyDatabaseIsReachable;
|
||||||
|
use Illuminate\Foundation\Events\DiagnosingHealth;
|
||||||
|
use Illuminate\Support\Facades\DB;
|
||||||
|
use RuntimeException;
|
||||||
|
use Tests\TestCase;
|
||||||
|
|
||||||
|
class HealthEndpointTest extends TestCase
|
||||||
|
{
|
||||||
|
public function test_up_returns_ok_when_the_database_is_reachable(): void
|
||||||
|
{
|
||||||
|
$this->get('/up')->assertOk();
|
||||||
|
}
|
||||||
|
|
||||||
|
public function test_up_fails_when_the_database_is_unreachable(): void
|
||||||
|
{
|
||||||
|
DB::shouldReceive('connection')->andThrow(new RuntimeException('getaddrinfo for db failed'));
|
||||||
|
|
||||||
|
$this->get('/up')->assertServerError();
|
||||||
|
}
|
||||||
|
|
||||||
|
public function test_the_listener_throws_when_the_connection_fails(): void
|
||||||
|
{
|
||||||
|
DB::shouldReceive('connection')->andThrow(new RuntimeException('getaddrinfo for db failed'));
|
||||||
|
|
||||||
|
$this->expectException(RuntimeException::class);
|
||||||
|
$this->expectExceptionMessage('The database is not reachable');
|
||||||
|
|
||||||
|
app(VerifyDatabaseIsReachable::class)->handle(new DiagnosingHealth);
|
||||||
|
}
|
||||||
|
|
||||||
|
public function test_the_listener_passes_when_the_connection_works(): void
|
||||||
|
{
|
||||||
|
app(VerifyDatabaseIsReachable::class)->handle(new DiagnosingHealth);
|
||||||
|
|
||||||
|
$this->addToAssertionCount(1);
|
||||||
|
}
|
||||||
|
}
|
||||||
157
tests/Unit/Listeners/LogExceptionToDatabaseTest.php
Normal file
157
tests/Unit/Listeners/LogExceptionToDatabaseTest.php
Normal file
|
|
@ -0,0 +1,157 @@
|
||||||
|
<?php
|
||||||
|
|
||||||
|
namespace Tests\Unit\Listeners;
|
||||||
|
|
||||||
|
use App\Enums\LogLevelEnum;
|
||||||
|
use App\Events\ExceptionOccurred;
|
||||||
|
use App\Listeners\LogExceptionToDatabase;
|
||||||
|
use App\Models\Log;
|
||||||
|
use Illuminate\Foundation\Testing\RefreshDatabase;
|
||||||
|
use Illuminate\Support\Facades\Log as Logger;
|
||||||
|
use PHPUnit\Framework\Attributes\DataProvider;
|
||||||
|
use RuntimeException;
|
||||||
|
use Tests\TestCase;
|
||||||
|
|
||||||
|
class LogExceptionToDatabaseTest extends TestCase
|
||||||
|
{
|
||||||
|
use RefreshDatabase;
|
||||||
|
|
||||||
|
public function test_it_persists_the_exception_to_the_database(): void
|
||||||
|
{
|
||||||
|
$listener = app(LogExceptionToDatabase::class);
|
||||||
|
|
||||||
|
$listener->handle(new ExceptionOccurred(
|
||||||
|
new RuntimeException('boom'),
|
||||||
|
LogLevelEnum::ERROR,
|
||||||
|
'boom',
|
||||||
|
));
|
||||||
|
|
||||||
|
$this->assertDatabaseHas('logs', [
|
||||||
|
'level' => 'error',
|
||||||
|
'message' => 'boom',
|
||||||
|
]);
|
||||||
|
}
|
||||||
|
|
||||||
|
public function test_it_logs_the_original_exception_to_the_fallback_when_the_database_fails(): void
|
||||||
|
{
|
||||||
|
$exception = new RuntimeException('the original failure');
|
||||||
|
|
||||||
|
Logger::shouldReceive('log')->once()->withArgs(
|
||||||
|
function (string $level, string $message, array $context) use ($exception): bool {
|
||||||
|
return $level === 'error'
|
||||||
|
&& $message === 'the original failure'
|
||||||
|
&& $context['exception_class'] === RuntimeException::class
|
||||||
|
&& $context['line'] === $exception->getLine()
|
||||||
|
&& str_contains($context['storage_failure'], 'no such table');
|
||||||
|
}
|
||||||
|
);
|
||||||
|
|
||||||
|
$this->failTheLogsTable();
|
||||||
|
|
||||||
|
app(LogExceptionToDatabase::class)->handle(new ExceptionOccurred(
|
||||||
|
$exception,
|
||||||
|
LogLevelEnum::ERROR,
|
||||||
|
'the original failure',
|
||||||
|
));
|
||||||
|
|
||||||
|
$this->addToAssertionCount(1);
|
||||||
|
}
|
||||||
|
|
||||||
|
public function test_it_preserves_the_event_context_in_the_fallback(): void
|
||||||
|
{
|
||||||
|
Logger::shouldReceive('log')->once()->withArgs(
|
||||||
|
fn (string $level, string $message, array $context): bool => $context['article_id'] === 42
|
||||||
|
);
|
||||||
|
|
||||||
|
$this->failTheLogsTable();
|
||||||
|
|
||||||
|
app(LogExceptionToDatabase::class)->handle(new ExceptionOccurred(
|
||||||
|
new RuntimeException('boom'),
|
||||||
|
LogLevelEnum::ERROR,
|
||||||
|
'boom',
|
||||||
|
['article_id' => 42],
|
||||||
|
));
|
||||||
|
|
||||||
|
$this->addToAssertionCount(1);
|
||||||
|
}
|
||||||
|
|
||||||
|
public function test_it_does_not_truncate_the_message_in_the_fallback(): void
|
||||||
|
{
|
||||||
|
$message = str_repeat('a', 300);
|
||||||
|
|
||||||
|
Logger::shouldReceive('log')->once()->withArgs(
|
||||||
|
fn (string $level, string $logged, array $context): bool => $logged === $message
|
||||||
|
);
|
||||||
|
|
||||||
|
$this->failTheLogsTable();
|
||||||
|
|
||||||
|
app(LogExceptionToDatabase::class)->handle(new ExceptionOccurred(
|
||||||
|
new RuntimeException($message),
|
||||||
|
LogLevelEnum::ERROR,
|
||||||
|
$message,
|
||||||
|
));
|
||||||
|
|
||||||
|
$this->addToAssertionCount(1);
|
||||||
|
}
|
||||||
|
|
||||||
|
public function test_it_swallows_a_failing_fallback_logger(): void
|
||||||
|
{
|
||||||
|
Logger::shouldReceive('log')->once()->andThrow(new RuntimeException('logger is down too'));
|
||||||
|
|
||||||
|
$this->failTheLogsTable();
|
||||||
|
|
||||||
|
app(LogExceptionToDatabase::class)->handle(new ExceptionOccurred(
|
||||||
|
new RuntimeException('boom'),
|
||||||
|
LogLevelEnum::ERROR,
|
||||||
|
'boom',
|
||||||
|
));
|
||||||
|
|
||||||
|
$this->addToAssertionCount(1);
|
||||||
|
}
|
||||||
|
|
||||||
|
/**
|
||||||
|
* @return array<string, array{LogLevelEnum, string}>
|
||||||
|
*/
|
||||||
|
public static function levelProvider(): array
|
||||||
|
{
|
||||||
|
return [
|
||||||
|
'debug' => [LogLevelEnum::DEBUG, 'debug'],
|
||||||
|
'info' => [LogLevelEnum::INFO, 'info'],
|
||||||
|
'warning' => [LogLevelEnum::WARNING, 'warning'],
|
||||||
|
'error' => [LogLevelEnum::ERROR, 'error'],
|
||||||
|
'critical' => [LogLevelEnum::CRITICAL, 'critical'],
|
||||||
|
];
|
||||||
|
}
|
||||||
|
|
||||||
|
#[DataProvider('levelProvider')]
|
||||||
|
public function test_it_maps_every_level_to_a_psr_log_level(LogLevelEnum $level, string $expected): void
|
||||||
|
{
|
||||||
|
Logger::shouldReceive('log')->once()->withArgs(
|
||||||
|
fn (string $logged, string $message, array $context): bool => $logged === $expected
|
||||||
|
);
|
||||||
|
|
||||||
|
$this->failTheLogsTable();
|
||||||
|
|
||||||
|
app(LogExceptionToDatabase::class)->handle(new ExceptionOccurred(
|
||||||
|
new RuntimeException('boom'),
|
||||||
|
$level,
|
||||||
|
'boom',
|
||||||
|
));
|
||||||
|
|
||||||
|
$this->addToAssertionCount(1);
|
||||||
|
}
|
||||||
|
|
||||||
|
protected function tearDown(): void
|
||||||
|
{
|
||||||
|
Log::flushEventListeners();
|
||||||
|
|
||||||
|
parent::tearDown();
|
||||||
|
}
|
||||||
|
|
||||||
|
private function failTheLogsTable(): void
|
||||||
|
{
|
||||||
|
Log::creating(function (): void {
|
||||||
|
throw new RuntimeException('SQLSTATE[HY000]: no such table: logs');
|
||||||
|
});
|
||||||
|
}
|
||||||
|
}
|
||||||
Loading…
Reference in a new issue