Debugging. Don't you just hate it when someone tells you your API isn't working? "I get some internal error", "it says not found", "it says not authorised even when I use the JWT". Yeah, bugs suck, and tracking them down can be a royal pain if you don't have your application setup to deal for it.

Earlier this week, I added request and response logging to a project I'm working on, and it's the best decision I've ever made. First of all, big thanks to Rizqi Djamaluddin, who's working on this project alongside me. It was Rizqi's idea to add this feature, and I'm very happy we did. So what does it do? Well, for every request, we:

1. Generate a UUID to identify the request
2. log all the request data (except for passwords and other possibly sensitive information), attaching the request ID in the log context
3. Log the response data, and attach the request ID to the response's metadata.

After implementing this, the apps that consume this API now receive a response like this:

 1GET /v2/users/dd5e1367-6931-46a9-b89c-35bbcf188db8
 2{
 3  "data": {
 4    "uuid": "dd5e1367-6931-46a9-b89c-35bbcf188db8",
 5    "name": "Leo Sjöberg",
 6    "username": "phroggyy",
 7    "email": "[email protected]"
 8  },
 9  "meta": {
10    "request_id": "69f10339-a860-4dc8-ab8f-b2c6eeadd2bc"
11  }
12}

As a result of this, the frontend developers are now able to make debugging way easier for us! Since they have the request ID as part of the response, they can just submit that as part of a bug report (or in reality, a Slack message), making it way easier for us to determine why something went wrong, much quicker.

So let's look at the implementation. It's about as simple as it can get, it uses a Laravel middleware and Decahedron's Sticky Context monolog processor.

 1class LogRequestAndResponse
 2{
 3    /**
 4     * Handle an incoming request.
 5     *
 6     * @param  \Illuminate\Http\Request $request
 7     * @param  \Closure $next
 8     * @return mixed
 9     */
10    public function handle($request, Closure $next)
11    {
12        StickyContext::add('request_id', $uuid = Uuid::uuid4()->toString());
13        Log::debug('Received request', [
14            'request_data' => $request->except([
15                'password',
16            ]),
17            'request_path' => $request->path(),
18            'request_method' => $request->method(),
19        ]);
20 
21        /** @var \Illuminate\Http\Response $response */
22        $response = $next($request);
23        if ($response instanceof JsonResponse) {
24            $data = $response->getData(true);
25            $data['meta']['request_id'] = $uuid;
26 
27            $response->setData($data);
28            Log::debug('Returning response', ['response_data' => $data]);
29        }
30 
31        return $response;
32    }
33}

What this does first is attach a request ID, which for us is a randomly generated UUID, to the "sticky context", meaning it will automatically be added to every log message under extra.request_id.

Then we proceed to log the received request. Note that we use $request->except() to exclude certain sensitive fields. This is where you'd add any and all fields with sensitive information in your app.

In the last part of this middleware, we check if the response is a JsonResponse, the reason for this is that we can't always be sure that the response is JSON – we might be returning an html view (for example an email confirmation page) instead, in which case there's no good way to add the request ID to the body. If you do want the request ID even on HTML responses, one solution would be to return a custom header (i.e X-YOURAPPNAME-RequestId) with the value.

Last of all, we return the response. That's all there's to it!

Once implemented, you might be delighted to start seeing messages like the one below pop up in your inbox.

Happy debugging!