Introduction

In software development, we encounter two types of issues: “known unknowns” (challenges we’re aware of but haven’t fully explored) and “unknown unknowns” (unforeseen problems). Experience can transform unknown unknowns into known unknowns. These issues often arise at the intersection of software, operating systems, hardware, development processes, and external factors. Understanding and addressing both types is key in software development.

Telemetry

Telemetry data is our lifeline for understanding and debugging unknown unknowns in software. It provides automatic insights into our running applications, allowing us to answer questions about the system’s state at any given moment.

The beauty of telemetry is that it lets us ask unforeseen questions. The ultimate aim is to make our applications observable, meaning we can inquire about our environment without needing to predict the questions in advance. Observability is the key to unraveling the mysteries of unknown unknowns.

Logging

Logs are the most common type of telemetry data. It’s being used no matter the tech stack you use. A lot of the time, we use it to debug our program instead of using a proper debugger just because it’s a lot simpler and easy. Logs are like your trusty toolkit when things go wrong. You rely on them to figure out what’s happening, and you really hope they’ve got all the info you need to fix the problem.

Logging in Laravel

Conviently, Laravel provides a built in facade for our logging needs. It uses monolog library under the hood.

As of this writing, here are the available methods:

use Illuminate\Support\Facades\Log;

Log::emergency($message);
Log::alert($message);
Log::critical($message);
Log::error($message);
Log::warning($message);
Log::notice($message);
Log::info($message);
Log::debug($message);

They all have a common purpose: generating log records. However, each of them operates at a distinct log level, as their names suggest. In ascending order of seriousness, we have debug, info, warn, and error. Error-level logs are reserved for critical failures that could potentially affect users, such as mishandled requests or database queries timing out.

Let’s see an example of usage:

<?php

namespace App\Http\Controllers;

use App\Http\Controllers\Controller;
use App\Models\User;
use Illuminate\Support\Facades\Log;
use Illuminate\View\View;

class UserController extends Controller
{
    /**
     * Show the profile for the given user.
     */
    public function show(string $id): View
    {
        Log::info('Showing the user profile for user: {id}', ['id' => $id]);

        $user = User::find($id);

        if(!$user) {
            Log::error('User does not exists!');
            back()->withErrors(['user' => 'User does not exist']);
        }

        return view('user.profile', [
            'user' => $user
        ]);
    }
}

We’re attempting an operation with potential for failure. If it succeeds, we log the outcome at the info level. If it fails, we log it at the error level. Deciding what to log about a specific function’s execution is typically a localized choice. You can usually determine what information is worth including in a log record by examining the function itself. On that note, you should log extensively for any external components in your program. They are more prone to failures and many issues, like network problems, hardware issues, database unavailability; which are beyond your control.

Correlation

Suppose you have the following logs:

local.INFO: Receiving Request in /profile
local.INFO: Receiving Request in /profile
local.INFO: Fetching profile for user-id-1
local.INFO: Fetching profile for user-id-2
local.ERROR: Failed to execute query: connection error
local.INFO: Successfully fetched profile

Analyzing this log, we don’t have a way to determine which request failed and which one pushed through. This is typically solved by assigning a “Request ID” on every log. How do we do that? Luckily, Laravel provides a way to add data on every succeeding requests by calling withContext method under Log face.

We can generate and assign the request ID by creating a Middleware:


<?php
namespace App\Http\Middleware;

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

class AssignRequestId
{
    /**
     * Handle an incoming request.
     *
     * @param  \Closure(\Illuminate\Http\Request): (\Symfony\Component\HttpFoundation\Response)  $next
     */
    public function handle(Request $request, Closure $next): Response
    {
        $requestId = (string) Str::uuid();

        Log::withContext([
            'request-id' => $requestId
        ]);

        $response = $next($request);

        $response->headers->set('Request-Id', $requestId);

        return $response;
    }
}

And then add the middleware in the stack:

// app/Http/kernel.php

class Kernel extends HttpKernel
{

        protected $middleware = [
            \App\Http\Middleware\AssignRequestId::class,
             //.. other middlewares here
        ];
}

After adding the middleware, all your next logs should be like the following:

local.INFO: Receiving Request in /profile {"request-id":"9e527e95-df4f-4a53-99ce-cde5280bd717"}
local.INFO: Receiving Request in /profile {"request-id":"c1c406e9-28ac-41c9-9626-23c1cf8031b9"}
local.INFO: Fetching profile for user-id-1 {"request-id":"9e527e95-df4f-4a53-99ce-cde5280bd717"}
local.INFO: Fetching profile for user-id-2 {"request-id":"c1c406e9-28ac-41c9-9626-23c1cf8031b9"}
local.ERROR: Failed to execute query: connection error {"request-id":"c1c406e9-28ac-41c9-9626-23c1cf8031b9"}
local.INFO: Successfully fetched profile {"request-id":"9e527e95-df4f-4a53-99ce-cde5280bd717"}

Analyzing this log, we can now clearly conclude that the user-id-2 received an error upon viewing his profile by correlating the request-id of the error log.

Do note that you can use withContext method even outside middlewares. You can use it inside controllers, services, etc. One use case is I add the context before calling a function, in doing so, every subsequent logs under that function will have context data in it making it easier to debug the program just by looking at the logs.

Searching the logs

There are variety of tools to search logs, some are uploading it in an elastic search instance and searching the logs in there, but for me, I really like simplicity, for my use cases, using grep is enough, it’s built in unix systems, and really easy to use example using the command line:

grep "26f3b58e-4fe1-413f-b1f5-9ae75daa17b3" laravel.log

this will show all of the logs with request-id 26f3b58e-4fe1-413f-b1f5-9ae75daa17b3 with automatic line splitting, example below:

[2023-10-29 01:57:14] testing.INFO: Requesting to claim {"request-id":"26f3b58e-4fe1-413f-b1f5-9ae75daa17b3","user":{"App\\Models\\User":{"name":"Edythe Rodriguez","email":"[email protected]","email_verified_at":"2023-10-29T01:57:14.000000Z","updated_at":"2023-10-29T01:57:14.000000Z","created_at":"2023-10-29T01:57:14.000000Z","id":19}},"product_key":{"Ramsey\\Uuid\\Lazy\\LazyUuidFromString":"326ba678-fbbd-4dfb-9dde-12461eef9f1d"}}
[2023-10-29 01:57:14] testing.INFO: Successfully claimed product key {"request-id":"26f3b58e-4fe1-413f-b1f5-9ae75daa17b3","user":{"App\\Models\\User":{"name":"Edythe Rodriguez","email":"[email protected]","email_verified_at":"2023-10-29T01:57:14.000000Z","updated_at":"2023-10-29T01:57:14.000000Z","created_at":"2023-10-29T01:57:14.000000Z","id":19}},"product_key":{"Ramsey\\Uuid\\Lazy\\LazyUuidFromString":"326ba678-fbbd-4dfb-9dde-12461eef9f1d"}}

if you find it slow, there is an alternative program called ripgrep which claims to be much faster than grep, for my purposes, grep is more than enough.

Conclusion

Logging is an essential part of your program that should not be ignored. Most of the time it’s looked over when developing software. It can save us a lot of headaches debugging and tracing what went wrong if there are errors in our program. Luckily, Laravel prodives us with tools that makes this very easy.