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
use 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):

{"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.

# .env
TINA4_LOG_LEVEL=WARNING

With this setting:

<?php
use Tina4\Log;

Log::debug("Detailed SQL query");        // Suppressed
Log::info("User logged in");             // Suppressed
Log::warning("Slow query detected");     // Appears
Log::error("Auth service unreachable");  // Appears
Log::critical("Disk full");              // Appears

Recommended levels by environment:

Environment	TINA4_LOG_LEVEL
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
use 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
use Tina4\Log;

// With TINA4_LOG_LEVEL=ERROR:
Log::isEnabled('info');     // false - info is below the ERROR threshold
Log::isEnabled('warning');  // false - also below ERROR
Log::isEnabled('error');    // true  - at the threshold
Log::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
use 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:

{
  "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
use 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
use 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
use 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
use 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

# 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 production
TINA4_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:

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.