Laravel по-русски
Работая с API иногда имеет смысл делать лог запросов, которые приходят на сервер, и ответов, которые сервер отправляет. Я уже написал статью о том, как делать лог, когда работаешь с API клиентом. Ее можно посмотреть здесь. Сейчас давайте рассмотрим как делать лог, когда программируешь API сервис. Например, если система третьей стороны присылает нам уведомления, что заказ отправлен, неплохо было бы сделать лог запросов которые эта система присылает и ответов, которые высылает наша система. Такой лог поможет разрешить спорные ситуации или найти ошибки в работе системы. Итак, начнем.
В routes/api.php файле Laravel создадим следующий маршрут:
Route::middleware('request.logging')->post('/hello', function() {
return response(['message' => 'Hi, how are you?']);
});
Это маршрут запроса, который использует middleware для лога запросов. Давайте продолжим и определим этот middleware в app/Http/Kernel.php в конце массива route middleware.
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,
];
Теперь давайте создадим middleware файл /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);
}
}
Это довольно простой код, который делает лог входящего запроса и исходящего ответа. Метод terminate() middleware будет вызываться платформой Laravel после отправки обратного запроса. Это также известно как terminable middleware. Теперь, если вы сделаете post запрос в конечную точку /api/hello, вы должны увидеть что-то вроде этого в логе Laravel:
[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?"}
Этот простой лог имеет несколько недостатков. 1) запрос и ответ не имеют уникального идентификатора, поэтому их будет сложно связать, когда приложение получает много запросов. 2) лог запроса не имеет много данных. Было бы здорово записать в лог больше информации о запросе. 3) запись ответов будет работать, только если вы используете PHP FastCGI (обычно сервер Nginx). Это не сработает, если вы используете Apache.
Чтобы решить первую проблему, давайте создадим регистратор для запросов и ответов нашего API, который будет добавлять специальный идентификатор каждый раз, когда регистрируются запросы и ответы. Обновлённый класс ApiRequestLogging приводится ниже:
<?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;
}
}
Мы добавили метод __construct() и метод getLogger (). Мы создали собственный логгер Monolog, который будет использоваться для записи запросов и ответов в файле web_hooks_ [дата] .log. Каждая строка в файле будет иметь свой собственный идентификатор процесса для определения цикла запрос-ответ. Вот результат файла журнала:
[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?"}
Теперь лог содержит больше информации, включая заголовки. Также могжно не просто записывать запрос как есть, а анализировать его и записывать по частям. Таким образом, вы можете изменить или удалить конфиденциальную информацию, такую как токены доступаю Сделать это можно примерно так:
/**
* 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;
}
Глядя на файл лога можно заметить, что идентификаторы процессов для запроса и ответа различаются. В этом случае мы не можем узнать, что мы ответили на запрос. Это происходит потому, что при вызове метода terminate() Laravel framework создает новое middleware. Следовательно, будет создан новый логгер с новым идентификатором процесса. Вы можете решить эту проблему, указав контейнеру Laravel использовать синглтон для вашего middleware. Решение описано в документации Laravel. Однако мы воспользуемся другим подходом. Этот подход также решит проблему, обозначенную выше, для Apache сервера. Сначала нам нужно добавить логгер к запросу и удалить метод terminate():
<?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;
}
}
Затем нам нужно обновить файл public/index.php, чтобы он делал лог ответа, если hooksLogger существует на экземпрляре запроса:
$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);
Перед $response->send() мы проверяем существует ли hooksLogger в экземпляре запроса. Если это так, мы делаем лог ответа точно такжеб как мы это делали в методе terminate() в middleware. Кстати, $kernel->terminate($request,$ response) - это метод, который и вызывает terminate() в middleware.