Example: logging and errors
Three endpoints that show what is logged and what the client sees, in development and in production.
Since 4.0.0
The presenter masks Authorization, Cookie, X-Api-Key, headers like X-Refresh-Token and query parameters like api_key by default, so the logger never sees them. The two setup lines add X-Session and session_id. In 3.6.0 only headers were masked, after setMaskedLogHeaders(). 400, 401 and 429 are not logged. See Logging.
| Request | Development | Production |
|---|---|---|
/api/v1/ping | 200, logged | 200, logged |
/api/v1/fail?kind=crash | 500 with detail, in Tracy log | 500 without detail |
/api/v1/fail?kind=maintenance | 503 from AppErrorHandler | 503 |
/api/v1/fail | 400 with detail, not logged | 400 without detail |
/api/v1/broken | 500, output does not match | 200, not checked |
The services
yaml
application:
mapping:
Api: Tomaj\NetteApi\Presenters\*Presenter
services:
router: App\RouterFactory::create
apiPresenter:
factory: Tomaj\NetteApi\Presenters\ApiPresenter
setup:
# since 4.0.0 the logger gets *** instead of the values of secret headers (Authorization, Cookie,
# X-Api-Key, names containing token, secret or key, ...) and query parameters (api_key, token, ...)
# without any setup; these lines change the defaults one entry at a time
- addMaskedLogHeader(X-Session)
- addMaskedLogQueryParam(session_id)
# error details and output schema validation are on unless APP_ENV=production
- Tomaj\NetteApi\Output\Configurator\EnvConfigurator('APP_ENV', 'production')
# ApiPresenter uses the one autowired ErrorHandlerInterface, AppErrorHandler wraps the default one
defaultErrorHandler:
factory: Tomaj\NetteApi\Error\DefaultErrorHandler
autowired: false
- App\AppErrorHandler(@defaultErrorHandler)
# with an ApiLoggerInterface service every handled request is logged;
# the logger needs an IpDetectorInterface service for the client IP
- App\FileApiLogger(%appDir%/../log/api.log)
- Tomaj\NetteApi\Misc\IpDetector
apiDecider:
factory: Tomaj\NetteApi\ApiDecider
setup:
- addApi(Tomaj\NetteApi\EndpointIdentifier('GET', 1, 'ping'), App\Api\PingHandler(), Tomaj\NetteApi\Authorization\NoAuthorization())
- addApi(Tomaj\NetteApi\EndpointIdentifier('GET', 1, 'fail'), App\Api\FailHandler(), Tomaj\NetteApi\Authorization\NoAuthorization())
- addApi(Tomaj\NetteApi\EndpointIdentifier('GET', 1, 'broken'), App\Api\BrokenOutputHandler(), Tomaj\NetteApi\Authorization\NoAuthorization())The logger
php
<?php
declare(strict_types=1);
namespace App;
use Tomaj\NetteApi\Logger\ApiLoggerInterface;
/**
* Writes one JSON line per API request.
* The headers arrive as "Name: value" lines; secret header and query parameter values are already *** because the presenter masks them.
*/
final class FileApiLogger implements ApiLoggerInterface
{
public function __construct(private string $file)
{
}
public function log(
int $responseCode,
string $requestMethod,
string $requestHeader,
string $requestUri,
string $requestIp,
string $requestAgent,
int $responseTime
): bool {
$headers = [];
foreach (explode(PHP_EOL, trim($requestHeader)) as $line) {
[$name, $value] = array_map('trim', explode(':', $line, 2)) + [1 => ''];
$headers[$name] = $value;
}
$line = json_encode([
'code' => $responseCode,
'method' => $requestMethod,
'uri' => $requestUri,
'ip' => $requestIp,
'agent' => $requestAgent,
'time_ms' => $responseTime,
'headers' => $headers,
], JSON_UNESCAPED_SLASHES);
return file_put_contents($this->file, $line . "\n", FILE_APPEND | LOCK_EX) !== false;
}
}The error handler
php
<?php
declare(strict_types=1);
namespace App;
use Throwable;
use Tomaj\NetteApi\Authorization\ApiAuthorizationInterface;
use Tomaj\NetteApi\EndpointInterface;
use Tomaj\NetteApi\Error\ErrorHandlerInterface;
use Tomaj\NetteApi\RateLimit\RateLimitResponse;
use Tomaj\NetteApi\Response\JsonApiResponse;
use Tomaj\NetteApi\Response\ResponseInterface;
/**
* Answers MaintenanceException with 503 and leaves everything else to DefaultErrorHandler.
*/
final class AppErrorHandler implements ErrorHandlerInterface
{
public function __construct(private ErrorHandlerInterface $inner)
{
}
public function handle(Throwable $exception, array $params): ResponseInterface
{
if ($exception instanceof MaintenanceException) {
return new JsonApiResponse(503, ['status' => 'error', 'message' => 'Down for maintenance, try again later']);
}
return $this->inner->handle($exception, $params);
}
public function handleInputParams(array $errors): ResponseInterface
{
return $this->inner->handleInputParams($errors);
}
public function handleSchema(array $errors, array $params): ResponseInterface
{
return $this->inner->handleSchema($errors, $params);
}
public function handleAuthorization(ApiAuthorizationInterface $auth, array $params): ResponseInterface
{
return $this->inner->handleAuthorization($auth, $params);
}
public function handleAuthorizationException(Throwable $exception, array $params): ResponseInterface
{
return $this->inner->handleAuthorizationException($exception, $params);
}
public function handleNotFound(EndpointInterface $endpoint): ResponseInterface
{
return $this->inner->handleNotFound($endpoint);
}
public function handleRateLimit(RateLimitResponse $rateLimit): ResponseInterface
{
return $this->inner->handleRateLimit($rateLimit);
}
}The failing handler
php
<?php
declare(strict_types=1);
namespace App\Api;
use App\MaintenanceException;
use RuntimeException;
use Tomaj\NetteApi\Handlers\BaseHandler;
use Tomaj\NetteApi\Params\GetInputParam;
use Tomaj\NetteApi\Response\ResponseInterface;
/**
* Always throws, to show what the error handler does with an exception.
*/
final class FailHandler extends BaseHandler
{
public function params(): array
{
return [
(new GetInputParam('kind'))->setAvailableValues(['crash', 'maintenance'])->setRequired(),
];
}
public function handle(array $params): ResponseInterface
{
if ($params['kind'] === 'maintenance') {
throw new MaintenanceException('Database migration is running');
}
throw new RuntimeException('Database connection refused');
}
}The test
bash
#!/usr/bin/env bash
# End-to-end check: request logging, error responses and how APP_ENV=production changes them.
set -euo pipefail
cd "$(dirname "$0")"
[[ -f vendor/autoload.php ]] || { echo "fail: vendor/ is missing, run composer install first" >&2; exit 1; }
source ../ci/lib.sh
rm -f log/api.log log/exception.log log/error.log
# development: APP_ENV is not set
APP_ENV= serve 8086
DEV="$BASE"
request -H 'Authorization: Bearer top-secret' -H 'Cookie: session=cookie-secret' -H 'X-Session: session-secret' -H 'X-Refresh-Token: pattern-secret' -H 'X-Trace: visible-value' -A 'e2e/1.0' "$DEV/api/v1/ping?api_key=query-secret&session_id=sid-secret&page=2"
expect_status 200 "ping"
ok "GET /api/v1/ping works"
grep -qF '"code":200' log/api.log || { echo "fail: log/api.log has no line for the ping" >&2; exit 1; }
grep -qF '"Authorization":"***"' log/api.log || { echo "fail: the Authorization header is not masked" >&2; cat log/api.log >&2; exit 1; }
if grep -qF 'top-secret' log/api.log; then echo "fail: the token leaked into log/api.log" >&2; exit 1; fi
grep -qF '"Cookie":"***"' log/api.log && ! grep -qF 'cookie-secret' log/api.log || { echo "fail: the Cookie header is not masked" >&2; exit 1; }
grep -qF '"X-Session":"***"' log/api.log || { echo "fail: the added X-Session header is not masked" >&2; exit 1; }
grep -qF '"X-Refresh-Token":"***"' log/api.log || { echo "fail: the *token* pattern did not mask X-Refresh-Token" >&2; exit 1; }
grep -qF '"uri":"/api/v1/ping?api_key=***&session_id=***&page=2"' log/api.log || { echo "fail: the query parameters are not masked" >&2; cat log/api.log >&2; exit 1; }
for secret in session-secret pattern-secret query-secret sid-secret; do
if grep -qF "$secret" log/api.log; then echo "fail: $secret leaked into log/api.log" >&2; exit 1; fi
done
grep -qF '"X-Trace":"visible-value"' log/api.log || { echo "fail: a header that is not on the list was masked" >&2; exit 1; }
ok "the request is in log/api.log, secret headers and query parameters masked, other values kept"
request "$DEV/api/v1/fail?kind=crash"
expect_status 500 "exception"
expect_body '"message":"Internal server error"' "exception"
expect_body '"detail":"Database connection refused"' "exception"
[[ -s log/exception.log ]] || { echo "fail: Tracy did not log the exception" >&2; exit 1; }
ok "an exception gives 500 with the detail, Tracy logs it"
request "$DEV/api/v1/fail?kind=maintenance"
expect_status 503 "custom error handler"
expect_body 'Down for maintenance' "custom error handler"
ok "AppErrorHandler turns MaintenanceException into 503"
request "$DEV/api/v1/fail"
expect_status 400 "wrong input"
expect_body '"message":"wrong input","detail":{"kind":["Field is required"]}' "wrong input"
if grep -qF '"code":400' log/api.log; then echo "fail: requests rejected before the handler should not be logged" >&2; exit 1; fi
ok "a missing parameter gives 400 with the detail and is not logged"
request "$DEV/api/v1/broken"
expect_status 500 "output schema"
expect_body '"detail":' "output schema"
ok "a response that breaks its output schema gives 500"
# production: no details and no output schema validation
APP_ENV=production serve 8087
PROD="$BASE"
request "$PROD/api/v1/fail?kind=crash"
expect_status 500 "production exception"
expect_body '{"status":"error","message":"Internal server error"}' "production exception"
ok "with APP_ENV=production the 500 has no detail"
request "$PROD/api/v1/fail"
expect_status 400 "production wrong input"
expect_body '{"status":"error","message":"wrong input"}' "production wrong input"
ok "with APP_ENV=production the 400 has no detail"
request "$PROD/api/v1/broken"
expect_status 200 "production output schema"
expect_body '"count":"three"' "production output schema"
ok "with APP_ENV=production the output schema is not checked"FAQ
How is production switched on?
EnvConfigurator('APP_ENV', 'production') turns details and output checks off when APP_ENV=production. See Outputs.
Where are the headers masked?
In the presenter, by default; common.neon only adds X-Session and session_id. The test sends a token, a cookie, X-Session, X-Refresh-Token, ?api_key= and ?session_id=, and checks that api.log has *** for each, no secret value, and keeps X-Trace and page=2. See Logging.
Why is the 400 not in api.log?
Wrong input returns before the logger in 3.x. See Logging.
Where are the exceptions?
In log/exception.log and Tracy's HTML files, written by DefaultErrorHandler.
Why wrap DefaultErrorHandler instead of extending it?
It is final. See Error handling.