Chapter 15: Structured Logging#

1. Stop Using error_log#

error_log("Something happened") works. It also produces an unreadable wall of text in production. Searching for a specific error across 500,000 lines of plain text is painful. Correlating a log line with a request, a user, and a timestamp is manual detective work.

Structured logging writes JSON. Every log entry is a machine-readable object with a timestamp, level, message, and whatever context you attach. Log aggregators (Datadog, Grafana Loki, AWS CloudWatch, Papertrail) can query, filter, and alert on structured logs.

Tina4 provides Tina4\Log for structured logging. Each level has its own method, Log::debug(), Log::info(), Log::warning(), Log::error(), Log::critical(). Output is JSON by default. Zero external packages.

The historical Tina4\Debug::message() API still works as a compatibility shim that forwards to Tina4\Log, use it if you're upgrading from a v3.12.x codebase. New code should use the level-specific Log methods.

2. Log Levels#

Tina4 has five log levels, each with its own Log method:

Method	When to use
`Log::debug($msg, $context)`	Verbose detail for development
`Log::info($msg, $context)`	Normal operations, confirmations
`Log::warning($msg, $context)`	Something unexpected but recoverable
`Log::error($msg, $context)`	A failure that needs attention
`Log::critical($msg, $context)`	System is failing. Immediate action required

The levels rank debug < info < warning < error < critical. critical is the highest severity, it always emits like every other level, and it lands in error.log alongside warning and error. Lower levels are filtered by TINA4_LOG_LEVEL; a higher level is visible whenever it meets that threshold.

3. Basic Logging#

php

<?phpuse Tina4\Log;Log::info("Application started");Log::debug("Cache miss for key: product:42");Log::warning("Payment gateway responded slowly");Log::error("Database query failed");Log::critical("Out of disk space");

Output (JSON format):

json

{"timestamp":"2026-04-02T14:30:01Z","level":"INFO","message":"Application started"}{"timestamp":"2026-04-02T14:30:01Z","level":"DEBUG","message":"Cache miss for key: product:42"}{"timestamp":"2026-04-02T14:30:01Z","level":"WARNING","message":"Payment gateway responded slowly"}{"timestamp":"2026-04-02T14:30:01Z","level":"ERROR","message":"Database query failed"}{"timestamp":"2026-04-02T14:30:01Z","level":"CRITICAL","message":"Out of disk space"}

Each line is a complete JSON object. One per log entry.

4. Log Level Filtering#

Set the minimum log level via environment variable. Only messages at or above that level appear in the output.

bash

# .envTINA4_LOG_LEVEL=WARNING

With this setting:

php

<?phpuse Tina4\Log;Log::debug("Detailed SQL query");        // SuppressedLog::info("User logged in");             // SuppressedLog::warning("Slow query detected");     // AppearsLog::error("Auth service unreachable");  // AppearsLog::critical("Disk full");              // Appears

Recommended levels by environment:

Environment	TINA4LOGLEVEL
Development	`DEBUG`
Staging	`INFO`
Production	`WARNING`

5. Checking the Current Level#

Sometimes you want to skip building an expensive log payload that would never reach the console anyway. Log::isEnabled() answers one question: would a message at this level pass the configured minimum level?

php

<?phpuse Tina4\Log;if (Log::isEnabled('debug')) {    // Only run the costly dump when DEBUG output is actually visible.    Log::debug("Cache snapshot", ['entries' => $cache->dumpAll()]);}

The level is case-insensitive, so Log::isEnabled('DEBUG') and Log::isEnabled('debug') behave the same.

The predicate uses the exact threshold the logger uses to decide what to print, so it can never disagree with real output:

php

<?phpuse Tina4\Log;// With TINA4_LOG_LEVEL=ERROR:Log::isEnabled('info');     // false - info is below the ERROR thresholdLog::isEnabled('warning');  // false - also below ERRORLog::isEnabled('error');    // true  - at the thresholdLog::isEnabled('critical'); // true  - critical outranks error

critical is the highest severity, debug < info < warning < error < critical. It flows through the same ordinary threshold as every other level, so Log::critical() always emits (subject only to TINA4_LOG_LEVEL) and isEnabled('critical') passes at every normal level.

Console visibility only. Log::isEnabled() reflects what reaches stdout. The log file always records every level regardless of the minimum level, so a Log::debug() you guarded out of the console still lands in tina4.log. Use isEnabled() to gate expensive work, not to decide what gets persisted.

6. Logging with Context#

Pass a context array as the second argument. Context values are merged into the JSON log entry.

php

<?phpuse Tina4\Log;Log::info("User login attempt", [    'user_id'    => 42,    'email'      => 'alice@example.com',    'ip'         => '203.0.113.5',    'user_agent' => 'Mozilla/5.0 ...']);

Output:

json

{  "timestamp": "2026-04-02T14:30:01Z",  "level": "INFO",  "message": "User login attempt",  "user_id": 42,  "email": "alice@example.com",  "ip": "203.0.113.5",  "user_agent": "Mozilla/5.0 ..."}

Context makes log lines searchable: level:INFO AND user_id:42 finds every action by that user.

7. Logging in Route Handlers#

Log the lifecycle of an HTTP request. Incoming requests, decisions made, and outcomes:

php

<?phpuse Tina4\Router;use Tina4\Log;Router::post('/api/payments', function ($request, $response) {    $body = $request->body;    Log::info("Payment request received", [        'amount'   => $body['amount'] ?? null,        'currency' => $body['currency'] ?? 'USD',        'ip'       => $request->server['REMOTE_ADDR'] ?? null    ]);    if (empty($body['amount']) || $body['amount'] <= 0) {        Log::warning("Payment rejected: invalid amount", [            'amount' => $body['amount'] ?? 'missing'        ]);        return $response->json(['error' => 'Invalid payment amount'], 400);    }    // Simulate payment processing    $success = true;    $transactionId = 'txn_' . uniqid();    if ($success) {        Log::info("Payment processed successfully", [            'transaction_id' => $transactionId,            'amount'         => $body['amount'],            'currency'       => $body['currency'] ?? 'USD'        ]);        return $response->json(['transaction_id' => $transactionId], 201);    } else {        Log::error("Payment gateway failure", [            'amount'   => $body['amount'],            'gateway'  => 'stripe',            'reason'   => 'Gateway timeout'        ]);        return $response->json(['error' => 'Payment failed'], 502);    }});

8. Logging Exceptions#

Log exceptions with full context. Include the message, file, line, and trace:

php

<?phpuse Tina4\Log;function processOrder(array $order): array {    try {        // Simulate work that might fail        if (empty($order['items'])) {            throw new \InvalidArgumentException("Order must have at least one item");        }        return ['status' => 'processed', 'order_id' => $order['id']];    } catch (\InvalidArgumentException $e) {        Log::warning("Order validation failed", [            'order_id' => $order['id'] ?? null,            'error'    => $e->getMessage()        ]);        throw $e;    } catch (\Throwable $e) {        Log::error("Unexpected error processing order", [            'order_id' => $order['id'] ?? null,            'error'    => $e->getMessage(),            'file'     => $e->getFile(),            'line'     => $e->getLine(),            'trace'    => $e->getTraceAsString()        ]);        throw $e;    }}

9. Request Correlation#

Attach a request ID to every log message within a request. All log lines from the same request share one ID. This lets you filter a full request trace from thousands of concurrent requests.

php

<?phpuse Tina4\Router;use Tina4\Log;Router::any('*', function ($request, $response) {    // Generate a request ID and attach to all logs in this request    $requestId = bin2hex(random_bytes(8));    $GLOBALS['request_id'] = $requestId;    Log::debug("Request started", [        'request_id' => $requestId,        'method'     => $request->method,        'path'       => $request->server['REQUEST_URI'] ?? '/'    ]);    return null; // Pass through to the real handler}, 'next');function logWithRequest(string $level, string $message, array $ctx = []): void {    $merged = array_merge(['request_id' => $GLOBALS['request_id'] ?? 'none'], $ctx);    Log::{$level}($message, $merged);}

With request correlation, a single grep "request_id:a3f8c1d2" finds every log line for one HTTP request.

10. Performance Logging#

Log slow operations automatically. Time your expensive calls:

php

<?phpuse Tina4\Log;function timedQuery(callable $query, string $label, float $warnThresholdMs = 100): mixed {    $start = microtime(true);    $result = $query();    $durationMs = (microtime(true) - $start) * 1000;    $context = [        'label'        => $label,        'duration_ms'  => round($durationMs, 2),        'threshold_ms' => $warnThresholdMs,        'slow'         => $durationMs > $warnThresholdMs,    ];    if ($durationMs > $warnThresholdMs) {        Log::warning("Query timing: {$label}", $context);    } else {        Log::debug("Query timing: {$label}", $context);    }    return $result;}// Usage$products = timedQuery(    fn() => fetchAllProducts(),    'fetchAllProducts',    warnThresholdMs: 50);

Any query slower than 50ms emits a WARNING. All others emit DEBUG and are suppressed in production.

11. Environment Configuration#

bash

# Minimum level to log (DEBUG | INFO | WARNING | ERROR | CRITICAL)TINA4_LOG_LEVEL=WARNING# Log output destination (stdout | file | both)# Unset (the default): stdout is always on; the log FILE is written# ONLY in development (TINA4_DEBUG truthy). Set this to force a file.TINA4_LOG_OUTPUT=both# Log file path - an explicit path forces a file, even in productionTINA4_LOG_FILE=./logs/app.log# Log format (json | text)TINA4_LOG_FORMAT=json

Where do logs go by default?#

When TINA4_LOG_OUTPUT is unset (the default), the destination depends on whether you run in development:

stdout is always on. The built-in server logs to standard output so Docker, Kubernetes, or your shell captures every line, 12-factor wants logs on stdout for the platform to collect.
The log file is written only in development - when TINA4_DEBUG is truthy. A local tail -f logs/tina4.log keeps working.
Production and containers are stdout-only. No tina4.log, no error.log. A log file inside a container just bloats the writable layer and fills the disk, and the platform already captures stdout.

Explicit settings always win. Set TINA4_LOG_OUTPUT=file or TINA4_LOG_OUTPUT=both, or point TINA4_LOG_FILE at a path, and Tina4 writes the file regardless of TINA4_DEBUG.

In development, use DEBUG level with text format for human-readable output. In production, use WARNING or ERROR level with json format for log aggregators.

12. Gotchas#

1. Logging sensitive data#

Problem: User passwords and payment card numbers appear in log files.

Cause: You logged the entire request body without filtering.

Fix: Never log raw $request->body or $_POST. Explicitly list the fields you want to log, excluding sensitive ones:

php

Log::info("User updated", [    'user_id' => $body['id'],    'email'   => $body['email'],    // NOT: 'password' => $body['password']]);

2. Logging too much in production#

Problem: Log volume is enormous. Storage costs spike. Log aggregator rate limits trigger.

Cause: TINA4_LOG_LEVEL=DEBUG in production logs every cache miss, DB query, and template render.

Fix: Set TINA4_LOG_LEVEL=WARNING in production. Use DEBUG only in development.

3. Forgetting to log errors before rethrowing#

Problem: A caught exception is rethrown but never logged. It disappears silently or appears only in a generic error handler with no context.

Fix: Always log before rethrowing. The context (order ID, user ID, inputs) is available inside the catch block. It is gone by the time the exception reaches the top-level handler.