Errors, logging and context

Pathshala’s fee sync failed one evening, and the 500 page a parent saw showed the database password, while the log could not say which of that hour’s requests had failed. Laravel handles errors in two steps: it reports each exception to the logs and renders a response for the visitor. Its logging writes lines to channels, and context adds fields such as a request id to every line of a request.

You will run one failing route with debug mode on and off, and write log lines that carry their request id. Later parts control how your own exceptions are reported and rendered, and keep logs searchable with no secrets in them, into queued jobs too.

Laravel reports errors, then renders a response

Every exception that leaves your code reaches Laravel’s exception handlerexception handler: The part of Laravel that receives every exception that leaves your code. It reports the exception, usually to the log, then renders the response the visitor gets. Its rules live in the withExceptions callback of bootstrap/app.php., which deals with it in two separate steps. Reportingexception reporting: Recording an exception for the team, by default as a log line with its message and stack trace. It happens the same way whether debug mode is on or off. records the exception, by default as a log line with its message and its stack trace. Renderingexception rendering: Turning an exception into the response a visitor receives: an HTML page, or JSON for a client that asks for it. Debug mode decides how much of the exception the response shows. turns it into the response the visitor receives: an HTML page, or JSON for a client that asks for one. Both steps are set up in the withExceptions() callback of bootstrap/app.php, and a new project has one rule there, which picks JSON for paths under api/ and for requests that ask for JSON:

<?php

use Illuminate\Foundation\Application;
use Illuminate\Foundation\Configuration\Exceptions;
use Illuminate\Foundation\Configuration\Middleware;
use Illuminate\Http\Request;

return Application::configure(basePath: dirname(__DIR__))
    ->withRouting(
        web: __DIR__.'/../routes/web.php',
        commands: __DIR__.'/../routes/console.php',
        health: '/up',
    )
    ->withMiddleware(function (Middleware $middleware): void {
        //
    })
    ->withExceptions(function (Exceptions $exceptions): void {
        $exceptions->shouldRenderJsonWhen(
            fn (Request $request) => $request->is('api/*') || $request->expectsJson(),
        );
    })->create();

Follow the exception that Pathshala’s fee sync route throws:

The same callback holds the rules that handle errors you expect. With dontReport(), a kind of exception is rendered but never logged. With throttle(), only some reports of a noisy exception are kept. An exception class can also carry report() and render() methods of its own, which the handler calls instead of its defaults.

Debug mode decides how much of the errors a visitor sees

Debug mode follows APP_DEBUG, which a new project’s .env sets to true. The session sends one failing request with debug on and off, as a browser and as a JSON client, and the route’s message holds an invented password:

<?php

use Illuminate\Support\Facades\Route;

Route::get('/', function () {
    return view('welcome');
});

// A sync job written in a hurry: its error message includes the database password (an invented one).
// The lesson uses it to show where such a message ends up; never put a secret into an exception message.
Route::get('/fees/sync', function () {
    throw new RuntimeException('Could not reach the fee database: DB password is hunter2');
});

<?php

namespace Tests\Feature;

use Illuminate\Support\Facades\Route;
use RuntimeException;
use Tests\TestCase;

// Run it in the pipeline with the production settings: it fails the build whenever a 500 shows exception details.
class ErrorPagesTest extends TestCase
{
    public function test_a_server_error_shows_no_exception_details(): void
    {
        Route::get('/boom', fn () => throw new RuntimeException('Could not reach the fee database: DB password is hunter2'));

        $page = $this->get('/boom')->assertStatus(500)->getContent();
        $this->assertFalse(str_contains($page, 'hunter2'), 'The 500 page shows the exception message.');

        $json = $this->getJson('/boom')->assertStatus(500);
        $this->assertSame('Server Error', $json->json('message'), 'The JSON error shows the exception message.');
    }
}

"""Debug mode and what a visitor sees: the same failing route with APP_DEBUG=true and APP_DEBUG=false, for a browser
and for a JSON client, then a test that fails while debug is on and passes once it is off. The password in the
message is invented. Files: the folder debug/ next to this file."""

from session import run

run(
    """
    export COLLISION_IGNORE_DURATION=true
    export APP_DEBUG=true
    php debug_probe.php
    !php artisan test --filter=ErrorPagesTest
    export APP_DEBUG=false
    php debug_probe.php
    php artisan test --filter=ErrorPagesTest
    """,
    app=True,
    overlay=("debug",),
)

$ export COLLISION_IGNORE_DURATION=true
$ export APP_DEBUG=true
$ php debug_probe.php
APP_DEBUG=true
browser:     status 500, page shows the password: yes, page title: Laravel
JSON client: status 500, body keys: message, exception, file, line, trace
             message: "Could not reach the fee database: DB password is hunter2"
log file:    local.ERROR: Could not reach the fee database: DB password is hunter2 (the stack trace follows)
$ php artisan test --filter=ErrorPagesTest
   FAIL  Tests\Feature\ErrorPagesTest
  ⨯ a server error shows no exception details
  ────────────────────────────────────────────────────────────────────────────
   FAILED  Tests\Feature\ErrorPagesTest > a server error shows no exception…
  The 500 page shows the exception message.
Failed asserting that true is false.

  at tests/Feature/ErrorPagesTest.php:17
     13▕     {
     14▕         Route::get('/boom', fn () => throw new RuntimeException('Could not reach the fee database: DB password is hunter2'));
     15▕
     16▕         $page = $this->get('/boom')->assertStatus(500)->getContent();
  ➜  17▕         $this->assertFalse(str_contains($page, 'hunter2'), 'The 500 page shows the exception message.');
     18▕
     19▕         $json = $this->getJson('/boom')->assertStatus(500);
     20▕         $this->assertSame('Server Error', $json->json('message'), 'The JSON error shows the exception message.');
     21▕     }

  1   tests/Feature/ErrorPagesTest.php:17


  Tests:    1 failed (2 assertions)
  Duration: …s
[exit status 1]
$ export APP_DEBUG=false
$ php debug_probe.php
APP_DEBUG=false
browser:     status 500, page shows the password: no, page title: Server Error
JSON client: status 500, body keys: message
             message: "Server Error"
log file:    local.ERROR: Could not reach the fee database: DB password is hunter2 (the stack trace follows)
$ php artisan test --filter=ErrorPagesTest
   PASS  Tests\Feature\ErrorPagesTest
  ✓ a server error shows no exception details

  Tests:    1 passed (4 assertions)
  Duration: …s

With debug on, the page showed the password, and the JSON body had five keys, message, exception, file, line and trace, which name your application’s files. With debug off, the page was the generic Server Error page and the body held only that message. The log line kept the full message in both runs, because reporting does not depend on debug mode. The Laravel documentation requires debug off in production.

The test turns that rule into a check: it failed while debug was on and passed once it was off. Run it with your production settings in the pipeline, and a deploy that would show details fails first.

Pages for the statuses you expect, such as 403 or 404, are Blade views in resources/views/errors/.

Logging and context: one line per event, with its request

Logging in Laravel sends every line to a log channellog channel: A named destination for log lines in config/logging.php, such as single (one file), daily (a file per day), stderr or stack, which forwards each line to a list of other channels., set up in config/logging.php. A new project’s stack channel forwards each line to the channels that LOG_STACK lists, here only single, the file storage/logs/laravel.log. The log levellog level: The severity of a log line, from debug up to emergency. A channel writes only lines at or above its level, which Laravel reads from LOG_LEVEL. in LOG_LEVEL is the lowest level a channel writes, from debug up to emergency.

Context makes logging useful across a request. The Context facade stores values for the current request, and Laravel adds them to every log line written while it runs. This middleware stores a request idrequest id: A unique value given to one request and written on every log line it produces, and often returned in a response header, so that all the lines of that request can be found with one search., keeping the one a proxy sent when it looks valid:

<?php

namespace App\Http\Middleware;

use Closure;
use Illuminate\Http\Request;
use Illuminate\Support\Facades\Context;
use Illuminate\Support\Str;
use Symfony\Component\HttpFoundation\Response;

// Gives every request an id, adds it to the context so that every log line of the request carries it, and returns it
// in a header so a support message can quote it. An id from the proxy is kept only if it looks like one.
class AssignRequestId
{
    public function handle(Request $request, Closure $next): Response
    {
        $given = (string) $request->header('X-Request-Id');
        $id = preg_match('/^[A-Za-z0-9-]{8,64}$/', $given) ? $given : (string) Str::uuid();

        Context::add('request_id', $id);

        $response = $next($request);
        $response->headers->set('X-Request-Id', $id);

        return $response;
    }
}

<?php

use Illuminate\Support\Facades\Log;
use Illuminate\Support\Facades\Route;

Route::get('/', function () {
    return view('welcome');
});

// A receipt page that writes two log lines: a detail for debugging, and the event itself.
Route::get('/instalments/{id}/receipt', function (string $id) {
    Log::debug('Receipt total computed', ['instalment' => (int) $id, 'paise' => 118000]);
    Log::info('Receipt viewed', ['instalment' => (int) $id]);

    return response('Receipt for instalment '.$id);
});

<?php

use App\Http\Middleware\AssignRequestId;
use Illuminate\Foundation\Application;
use Illuminate\Foundation\Configuration\Exceptions;
use Illuminate\Foundation\Configuration\Middleware;
use Illuminate\Http\Request;

return Application::configure(basePath: dirname(__DIR__))
    ->withRouting(
        web: __DIR__.'/../routes/web.php',
        commands: __DIR__.'/../routes/console.php',
        health: '/up',
    )
    ->withMiddleware(function (Middleware $middleware): void {
        $middleware->append(AssignRequestId::class); // global: every request gets an id first
    })
    ->withExceptions(function (Exceptions $exceptions): void {
        $exceptions->shouldRenderJsonWhen(
            fn (Request $request) => $request->is('api/*') || $request->expectsJson(),
        );
    })->create();

"""Logging with context: a global middleware adds the request id to the context, so every log line of the request
carries it; the same requests are sent again with LOG_LEVEL=info, which drops the debug line. The time at the start of
each log line is left out. Files: the folder context/ next to this file."""

from session import run

run(
    """
    php context_probe.php
    export LOG_LEVEL=info
    php context_probe.php
    """,
    app=True,
    overlay=("context",),
)

$ php context_probe.php
GET /instalments/42/receipt -> 200, X-Request-Id: req-1001-asha
GET /instalments/43/receipt -> 200, X-Request-Id: req-1002-kabir
storage/logs/laravel.log (LOG_LEVEL=debug):
  local.DEBUG: Receipt total computed {"instalment":42,"paise":118000} {"request_id":"req-1001-asha"}
  local.INFO: Receipt viewed {"instalment":42} {"request_id":"req-1001-asha"}
  local.DEBUG: Receipt total computed {"instalment":43,"paise":118000} {"request_id":"req-1002-kabir"}
  local.INFO: Receipt viewed {"instalment":43} {"request_id":"req-1002-kabir"}
$ export LOG_LEVEL=info
$ php context_probe.php
GET /instalments/42/receipt -> 200, X-Request-Id: req-1001-asha
GET /instalments/43/receipt -> 200, X-Request-Id: req-1002-kabir
storage/logs/laravel.log (LOG_LEVEL=info):
  local.INFO: Receipt viewed {"instalment":42} {"request_id":"req-1001-asha"}
  local.INFO: Receipt viewed {"instalment":43} {"request_id":"req-1002-kabir"}

Every line ended with its request’s id, although no logging call mentioned one, so one search finds all that a request did. With LOG_LEVEL=info the debug lines were gone.

For servers and containers, the daily channel keeps a file per day and the stderr channel can write each line as JSON. A log processorlog processor: A function that Monolog runs on every log record before it is written. It can add fields to the record or change them, for example to mask a phone number. can mask phone numbers and tokens before a line is written. Values stored as hidden contexthidden context: Values stored with Context::addHidden(). Code can read them with Context::getHidden(), but Laravel leaves them out of the log lines that carry the rest of the context. stay available to code and never appear in log lines.

Exception classes that report and render themselves, throttled and critical errors, error pages and tests with Exceptions::fake() Pro: opens with a Pro, Premium or Ultimate pass

Channels for each environment, a processor that masks secrets with a failing test, and one request id from the web request into a queued job Pro: opens with a Pro, Premium or Ultimate pass

Practise

Try both halves in your own Pathshala project:

1. Add the AssignRequestId middleware with $middleware->append(...) in bootstrap/app.php, request a page, and find the id in the X-Request-Id header and on its log lines.
2. Set APP_DEBUG=false, request a route that throws, and compare the page and the JSON body.
3. Add ErrorPagesTest to your tests and run it with debug on and with debug off.

Then take the self-check:

Interview questions

Warm-up: in Laravel, what is the difference between reporting an exception and rendering it?

Reporting records the exception for the team, by default as a log line with its message and stack trace, and it happens whatever the visitor sees. Rendering builds the response the visitor gets, an HTML page or JSON, and debug mode decides how much detail it shows. Both are configured in the withExceptions callback of bootstrap/app.php.

Three longer questions follow:

Key takeaways

• Laravel handles every exception in two steps: reporting writes it to the logs, rendering builds the page or the JSON the visitor receives.
• With APP_DEBUG=true a 500 shows the message and your files to anyone, so production runs with debug off, and a test that searches the 500 response keeps it so.
• Logging writes each line to a channel at a level, and the Context facade adds fields such as a request id to every line of a request.