API Server Logging with Laravel
When you work with APIs it is usually a good idea to log requests and responses. I already covered how to do logging when you are consuming an API. You can read about it in this post. Here we will cover how to do it when building an API service with Laravel. For example, you may want to do request and response logging when a third party is sending your application a shipment notification. Such logging will help you to see if you actually received a notification, what exactly was sent to the application and what your application responded with. Let’s get started.
In routes/api.php file of Laravel create the following route:
Route::middleware('request.logging')->post('/hello', function() {
return response(['message' => 'Hi, how are you?']);
});
This is a post request route that uses request logging middleware. Let’s go ahead and define this middleware in app/Http/Kernel.php at the end of the route middleware array.
protected $routeMiddleware = [
'auth' => \App\Http\Middleware\Authenticate::class,
'auth.basic' => \Illuminate\Auth\Middleware\AuthenticateWithBasicAuth::class,
'bindings' => \Illuminate\Routing\Middleware\SubstituteBindings::class,
'cache.headers' => \Illuminate\Http\Middleware\SetCacheHeaders::class,
'can' => \Illuminate\Auth\Middleware\Authorize::class,
'guest' => \App\Http\Middleware\RedirectIfAuthenticated::class,
'password.confirm' => \Illuminate\Auth\Middleware\RequirePassword::class,
'signed' => \Illuminate\Routing\Middleware\ValidateSignature::class,
'throttle' => \Illuminate\Routing\Middleware\ThrottleRequests::class,
'verified' => \Illuminate\Auth\Middleware\EnsureEmailIsVerified::class,
'request.logging' => \App\Http\Middleware\ApiRequestLogging::class,
];
Now let’s create middleware file /app/Http/Middleware/ApiRequestLogging.php
<?php
namespace App\Http\Middleware;
use Closure;
use Illuminate\Http\Request;
use Illuminate\Http\Response;
use Illuminate\Support\Facades\Log;
class ApiRequestLogging
{
/**
* Handle an incoming request.
*
* @param \Illuminate\Http\Request $request
* @param \Closure $next
* @return mixed
*/
public function handle(Request $request, Closure $next)
{
Log::info('Incoming request:');
Log::info($request);
return $next($request);
}
public function terminate(Request $request, Response $response)
{
Log::info('Outgoing response:');
Log::info($response);
}
}
This is a pretty simple code that logs incoming request and outgoing response. We are able to log request and response because they both implement __toString(). Method terminate() of the middleware will be called by the Laravel framework after sending back request. This is also known as terminable middleware.
Now if you make a post request to /api/hello endpoint you should see something like this in Laravels default log file:
[2020-09-10 23:26:27] acceptance.INFO: Incoming request:
[2020-09-10 23:26:27] acceptance.INFO: array (
'message' => 'Hi!',
)
[2020-09-10 23:26:27] acceptance.INFO: Outgoing response:
[2020-09-10 23:26:27] acceptance.INFO: HTTP/1.1 200 OK
Cache-Control: no-cache, private
Content-Type: application/json
Date: Thu, 10 Sep 2020 23:26:27 GMT
X-Ratelimit-Limit: 60
X-Ratelimit-Remaining: 59
{"message":"Hi, how are you?"}
This basic logging has a few drawbacks. 1) Request and response do not have a unique identifier, so it will be hard to connect them when the application receives a lot of requests. 2) Request data is a bit light. It only has body. It would be great to have more information about the request. 3) Response logging will only work if you are running PHP FastCGI (usually Nginx server). It won’t work if you are using Apache.
To address the first issue let’s create a logger for our API requests and responses that will add a special identifier each time it is logging requests and responses. Below is updated ApiRequestLogging class.
<?php
namespace App\Http\Middleware;
use Closure;
use Illuminate\Http\Request;
use Illuminate\Http\Response;
use Monolog\Formatter\LineFormatter;
use Monolog\Handler\StreamHandler;
use Monolog\Logger;
use Illuminate\Support\Str;
class ApiRequestLogging
{
/** @var Monolog\Logger **/
private $logger;
public function __construct()
{
$this->logger = $this->getLogger();
}
/**
* Handle an incoming request.
*
* @param \Illuminate\Http\Request $request
* @param \Closure $next
* @return mixed
*/
public function handle(Request $request, Closure $next)
{
$this->logger->info('Incoming request:');
$this->logger->info($request);
return $next($request);
}
public function terminate(Request $request, Response $response)
{
$this->logger->info('Outgoing response:');
$this->logger->info($response);
}
private function getLogger()
{
$dateString = now()->format('m_d_Y');
$filePath = 'web_hooks_' . $dateString . '.log';
$dateFormat = "m/d/Y H:i:s";
$output = "[%datetime%] %channel%.%level_name%: %message%\n";
$formatter = new LineFormatter($output, $dateFormat);
$stream = new StreamHandler(storage_path('logs/' . $filePath), Logger::DEBUG);
$stream->setFormatter($formatter);
$processId = Str::random(5);
$logger = new Logger($processId);
$logger->pushHandler($stream);
return $logger;
}
}
We added a __construct() method and a factory method getLogger(). We created our own Monolog logger that will be used to log requests and responses. The logger will be logging in web_hooks_[date].log file. Each log line in the file will have its own process id to identify request – response cycle. Here is the output of the log file:
[09/11/2020 17:54:43] cOv07.INFO: Incoming request:
[09/11/2020 17:54:43] cOv07.INFO: POST /api/hello?query=string HTTP/1.1 Accept: */* Accept-Encoding: gzip, deflate, br Cache-Control: no-cache Connection: keep-alive Content-Length: 26 Content-Type: application/json Host: localhost:8000 Postman-Token: 2e1c590a-e4ea-445d-8e52-ffd7c9bd4270 User-Agent: PostmanRuntime/7.26.5 { "message": "Hi!" }
[09/11/2020 17:54:43] yzyK2.INFO: Outgoing response:
[09/11/2020 17:54:43] yzyK2.INFO: HTTP/1.1 200 OK Cache-Control: no-cache, private Content-Type: application/json Date: Fri, 11 Sep 2020 17:54:43 GMT X-Ratelimit-Limit: 60 X-Ratelimit-Remaining: 59 {"message":"Hi, how are you?"}
Now request log has more information, including headers and query string. It also may be a good idea not to just log request as is, but to parse it and log separate parts. That way you can replace sensitive information like access tokens with generic strings. You can do it something like this:
/**
* Handle an incoming request.
*
* @param \Illuminate\Http\Request $request
* @param \Closure $next
* @return mixed
*/
public function handle(Request $request, Closure $next)
{
$this->logger->info('Incoming request:');
$url = $request->url();
$queryString = $request->getQueryString();
$method = $request->method();
$ip = $request->ip();
$headers = $this->getHeadersFromRequest();
$body = $request->getContent();
$methodUrlString = "$ip $method $url";
if ($queryString) {
$methodUrlString .= "?$queryString";
}
if (array_key_exists('Authorization', $headers)) {
$headers['Authorization'] = 'xxxxxxx';
}
$this->logger->info($methodUrlString);
$this->logger->info(json_encode($headers));
$this->logger->info($body);
return $next($request);
}
private function getHeadersFromRequest()
{
$headers = [];
foreach ($_SERVER as $key => $value) {
if (substr($key, 0, 5) <> 'HTTP_') {
continue;
}
$header = str_replace(' ', '-', ucwords(str_replace('_', ' ', strtolower(substr($key, 5)))));
$headers[$header] = $value;
}
return $headers;
}
From the log file you can also notice that process ids are different for request and response. This is not what we want because we won’t be able to connect them together. This is happening because when calling terminate method Laravel framework is create a new instance of middleware. Therefore a new instance of logger will be created with a new process id. You can fix the issue by telling Laravel’s container to use singleton for your middleware. The solution is described in Laravel’s documentation. However we will use a different approach. This approach will also solve the problem of logging responses when running Apache server.
First we need to add the logger to the request and remove terminate method.
<?php
namespace App\Http\Middleware;
use Closure;
use Illuminate\Http\Request;
use Monolog\Formatter\LineFormatter;
use Monolog\Handler\StreamHandler;
use Monolog\Logger;
use Illuminate\Support\Str;
class ApiRequestLogging
{
/** @var Monolog\Logger **/
private $logger;
public function __construct()
{
$this->logger = $this->getLogger();
}
/**
* Handle an incoming request.
*
* @param \Illuminate\Http\Request $request
* @param \Closure $next
* @return mixed
*/
public function handle(Request $request, Closure $next)
{
$this->logger->info('Incoming request:');
$this->logger->info($request);
$request->hooksLogger = $this->logger;
return $next($request);
}
private function getLogger()
{
$dateString = now()->format('m_d_Y');
$filePath = 'web_hooks_' . $dateString . '.log';
$dateFormat = "m/d/Y H:i:s";
$output = "[%datetime%] %channel%.%level_name%: %message%\n";
$formatter = new LineFormatter($output, $dateFormat);
$stream = new StreamHandler(storage_path('logs/' . $filePath), Logger::DEBUG);
$stream->setFormatter($formatter);
$processId = Str::random(5);
$logger = new Logger($processId);
$logger->pushHandler($stream);
return $logger;
}
}
Next we need to update public/index.php file to log response if hooksLogger exists on the request.
$kernel = $app->make(Illuminate\Contracts\Http\Kernel::class);
$response = $kernel->handle(
$request = Illuminate\Http\Request::capture()
);
if (isset($request->hooksLogger)) {
$request->hooksLogger->info('Outgoing Response:');
$request->hooksLogger->info($response);
}
$response->send();
$kernel->terminate($request, $response);
Right before $response->send() we have a conditional to check if hooksLogger exists on the response instance. If so, we log response the same way we did it in terminate method of the middleware. BTW, $kernel->terminate($request, $response) is the method that calls terminate() on middleware.