Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(common/es): log error request/response #681

Merged
merged 4 commits into from
Dec 20, 2023
Merged

feat(common/es): log error request/response #681

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
a8d3d06
refactor: clean code and move log logic to logger
Davidmattei Dec 20, 2023
915d70f
refactor: improve test
Davidmattei Dec 20, 2023
d1ce02f
refactor: improve code, remove old logQuery
Davidmattei Dec 20, 2023
f2bd465
feat: show exception in elastic debug profiler
Davidmattei Dec 20, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 14 additions & 8 deletions EMS/common-bundle/src/DataCollector/ElasticaDataCollector.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,8 +12,10 @@

class ElasticaDataCollector extends DataCollector
{
public function __construct(private readonly ElasticaLogger $logger, private readonly ElasticaService $elasticaService)
{
public function __construct(
private readonly ElasticaLogger $logger,
private readonly ElasticaService $elasticaService
) {
}

public function collect(Request $request, Response $response, ?\Throwable $exception = null): void
Expand All @@ -34,18 +36,15 @@ public function getVersion(): string
return $this->data['version'];
}

/**
* @return mixed
*/
public function getQueryCount()
public function getQueryCount(): int
{
return $this->data['nb_queries'];
}

/**
* @return mixed
* @return array<mixed>
*/
public function getQueries()
public function getQueries(): array
{
return $this->data['queries'];
}
Expand All @@ -60,6 +59,13 @@ public function getTime(): int
return $time;
}

public function countErrors(): int
{
$queries = $this->data['queries'] ?? [];

return \count(\array_filter($queries, static fn (array $q) => isset($q['exception'])));
}

public function getExecutionTime(): float
{
$time = 0;
Expand Down
46 changes: 12 additions & 34 deletions EMS/common-bundle/src/Elasticsearch/Client.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,8 +5,8 @@
namespace EMS\CommonBundle\Elasticsearch;

use Elastica\Client as BaseClient;
use Elastica\Connection;
use Elastica\Exception\ClientException;
use Elastica\Exception\ResponseException;
use Elastica\Request;
use Elastica\Response;
use Symfony\Component\Stopwatch\Stopwatch;
Expand All @@ -24,11 +24,14 @@ class Client extends BaseClient
*/
public function request($path, $method = Request::GET, $data = [], array $query = [], $contentType = Request::DEFAULT_CONTENT_TYPE): Response
{
if (null !== $this->stopwatch) {
$this->stopwatch->start('es_request', 'fos_elastica');
}
$this->stopwatch?->start('es_request', 'fos_elastica');

$response = parent::request($path, $method, $data, $query, $contentType);
try {
$response = parent::request($path, $method, $data, $query, $contentType);
} catch (ResponseException $e) {
$this->getLogger()?->logResponse($e->getResponse(), $e->getRequest(), $e);
throw $e;
}
$responseData = $response->getData();

$transportInfo = $response->getTransferInfo();
Expand All @@ -44,11 +47,8 @@ public function request($path, $method = Request::GET, $data = [], array $query
throw new ClientException($message);
}

$this->logQuery($response, $connection, $path, $method, $query, $data);

if ($this->stopwatch) {
$this->stopwatch->stop('es_request');
}
$this->getLogger()?->logResponse($response, $lastRequest);
$this->stopwatch?->stop('es_request');

return $response;
}
Expand All @@ -58,30 +58,8 @@ public function setStopwatch(?Stopwatch $stopwatch = null): void
$this->stopwatch = $stopwatch;
}

/**
* @param array<mixed>|string $data
* @param array<mixed> $query
*/
private function logQuery(Response $elasticaResponse, Connection $connection, string $path, string $method, array $query, array|string $data): void
public function getLogger(): ?ElasticaLogger
{
if (!$this->_logger instanceof ElasticaLogger || !$this->_logger->isEnabled()) {
return;
}

$connectionArray = [
'host' => $connection->getHost(),
'port' => $connection->getPort(),
'transport' => $connection->getTransport(),
'headers' => $connection->hasConfig('headers') ? $connection->getConfig('headers') : [],
];

$responseData = $elasticaResponse->getData();

$queryTime = $elasticaResponse->getQueryTime();
$engineMS = $responseData['took'] ?? 0;

$itemCount = $responseData['hits']['total']['value'] ?? $responseData['hits']['total'] ?? 0;

$this->_logger->logQuery($path, $method, $data, $queryTime, $connectionArray, $query, $engineMS, $itemCount);
return $this->_logger instanceof ElasticaLogger && $this->_logger->isEnabled() ? $this->_logger : null;
}
}
90 changes: 48 additions & 42 deletions EMS/common-bundle/src/Elasticsearch/ElasticaLogger.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,9 @@

namespace EMS\CommonBundle\Elasticsearch;

use Elastica\Exception\ResponseException;
use Elastica\Request;
use Elastica\Response;
use EMS\CommonBundle\Contracts\Elasticsearch\QueryLoggerInterface;
use EMS\Helpers\Standard\Json;
use Psr\Log\AbstractLogger;
Expand All @@ -15,8 +18,10 @@ class ElasticaLogger extends AbstractLogger implements QueryLoggerInterface
private array $queries = [];
private bool $enabled = true;

public function __construct(private readonly ?LoggerInterface $logger = null, private readonly bool $debug = false)
{
public function __construct(
private readonly ?LoggerInterface $logger = null,
private readonly bool $debug = false
) {
}

public function isEnabled(): bool
Expand All @@ -34,70 +39,71 @@ public function enable(): void
$this->enabled = true;
}

public function getNbQueries(): int
{
return \count($this->queries);
}

/**
* @param array<mixed>|string $data Arguments
* @param array<mixed> $connection Host, port, transport, and headers of the query
* @param array<mixed> $query Arguments
* @return array<mixed>
*/
public function logQuery(string $path, string $method, array|string $data, float $queryTime, array $connection = [], array $query = [], int $engineTime = 0, int $itemCount = 0): void
public function getQueries(): array
{
return $this->queries;
}

/**
* @param array<mixed> $context
*/
public function log($level, $message, array $context = []): void
{
if (null !== $this->logger && $this->isEnabled()) {
$this->logger->log($level, $message, $context);
}
}

public function logResponse(Response $response, Request $request, ?ResponseException $responseException = null): void
{
$responseData = $response->getData();
$queryTime = $response->getQueryTime();
$connection = $request->getConnection();
$data = $request->getData();

$executionMS = $queryTime * 1000;

if ($this->debug) {
if (\is_string($data)) {
$jsonStrings = \explode("\n", $data);
$data = [];
foreach ($jsonStrings as $json) {
if ('' != $json) {
$data[] = Json::decode($json);
}
}
$data = \array_filter(\array_map(static fn ($v) => Json::isJson($v) ? Json::decode($v) : null, $jsonStrings));
} else {
$data = [$data];
}

$this->queries[] = [
'path' => $path,
'method' => $method,
'path' => $request->getPath(),
'method' => $request->getMethod(),
'data' => $data,
'executionMS' => $executionMS,
'engineMS' => $engineTime,
'connection' => $connection,
'queryString' => $query,
'itemCount' => $itemCount,
'engineMS' => $responseData['took'] ?? 0,
'exception' => $responseException,
'connection' => [
'host' => $connection->getHost(),
'port' => $connection->getPort(),
'transport' => $connection->getTransport(),
'headers' => $connection->hasConfig('headers') ? $connection->getConfig('headers') : [],
],
'queryString' => $request->getQuery(),
'itemCount' => $responseData['hits']['total']['value'] ?? $responseData['hits']['total'] ?? 0,
'backtrace' => (new \Exception())->getTraceAsString(),
];
}

if (null !== $this->logger) {
$message = \sprintf('%s (%s) %0.2f ms', $path, $method, $executionMS);
$message = \sprintf('%s (%s) %0.2f ms', $request->getPath(), $request->getMethod(), $executionMS);
$this->logger->info($message, (array) $data);
}
}

public function getNbQueries(): int
{
return \count($this->queries);
}

/**
* @return array<mixed>
*/
public function getQueries(): array
{
return $this->queries;
}

/**
* @param array<mixed> $context
*/
public function log($level, $message, array $context = []): void
{
if (null !== $this->logger && $this->isEnabled()) {
$this->logger->log($level, $message, $context);
}
}

public function reset(): void
{
$this->queries = [];
Expand Down
61 changes: 30 additions & 31 deletions EMS/common-bundle/src/Resources/views/DataCollector/elastica.html.twig
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,25 +10,16 @@
{% endblock %}

{% block toolbar %}
{% set profiler_markup_version = profiler_markup_version|default(1) %}

{% set status_color = collector.countErrors > 0 ? 'red' %}
{% set icon %}
{% if profiler_markup_version == 1 %}
<img alt="elastica" src="data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAABYAAAAcCAYAAABlL09dAAAABGdBTUEAALGPC/xhBQAAA/BpQ0NQSUNDIFByb2ZpbGUAACiRjVXdb9tUFD+Jb1ykFj+gsY4OFYuvVVNbuRsarcYGSZOl6UIauc3YKqTJdW4aU9c2ttNtVZ/2Am8M+AOAsgcekHhCGgzE9rLtAbRJU0EV1SSkPXTaQGiT9oKqcK6vU7tdxriRr38553c+79E1QMdXmuOYSRlg3vJdNZ+Rj5+YljtWIQnPQSf0QKeme066XC4CLsaFR9bDXyHB3jcH2uv/c3VWqacDJJ5CbFc9fR7xaYCUqTuuDyDeRvnwKd9B3PE84h0uJohYYXiW4yzDMxwfDzhT6ihilouk17Uq4iXE/TMx+WwM8xyCtSNPLeoausx6UXbtmmHSWLpPUP/PNW82WvF68eny5iaP4ruP1V53x9QQf65ruUnELyO+5vgZJn8V8b3GXCWNeC9A8pmae6TC+ck3FutT7yDeibhq+IWpUL5ozZQmuG1yec4+qoaca7o3ij2DFxHfqtNCkecjQJVmc6xfiHvrjbHQvzDuLUzmWn4W66Ml7kdw39PGy4h7EH/o2uoEz1lYpmZe5f6FK45fDnMQ1i2zVOQ+iUS9oMZA7tenxrgtOeDjIXJbMl0zjhRC/pJjBrOIuZHzbkOthJwbmpvLcz/kPrUqoc/UrqqWZb0dRHwYjiU0oGDDDO46WLABMqiQhwy+HXBRUwMDTJRQ1FKUGImnYQ5l7XnlgMNxxJgNrNeZNUZpz+ER7oQcm3QThezH5yApkkNkmIyATN4kb5HDJIvSEXJw07Yci89i3dn08z400CvjHYPMuZ5GXxTvrHvS0K9/9PcWa/uRnGkrn3gHwMMOtJgD8fqvLv2wK/KxQi68e7Pr6hJMPKm/qdup9dQK7quptYiR+j21hr9VSGNuZpDRPD5GkIcXyyBew2V8fNBw/wN5doy3JWLNOtcTaVgn6AelhyU42x9Jld+UP5UV5QvlvHJ3W5fbdkn4VPhW+FH4Tvhe+Blk4ZJwWfhJuCJ8I1yMndXj52Pz7IN6W9UyTbteUzCljLRbeknKSi9Ir0jFyJ/ULQ1JY9Ie1OzePLd4vHgtBpzAvdXV9rE4r4JaA04FFXhBhy04s23+Q2vSS4ZIYdvUDrNZbjHEnJgV0yCLe8URcUgcZ7iVn7gHdSO457ZMnf6YCmiMFa9zIJg6NqvMeiHQeUB9etpnF+2o7Zxxjdm6L+9TlNflNH6qqFyw9MF+WTNNOVB5sks96i7Q6iCw7yC/oh+owfctsfN6JPPfBjj0F95ZNyLZdAPgaw+g+7VI1od34rOfAVw4oDfchfDOTyR+AfBq+/fxf10ZvJtuNZsP8L7q+ARg4+Nm85/lZnPjS/S/BnDJ/BdZAHF4xCjCQAAAAAlwSFlzAAALEwAACxMBAJqcGAAABWZJREFUSIm1lU9sXFcVxr9773tv/o8n5sWeGQejTIwpoXYlUCQCUiBSRTdRpS5ihLKxiJBASBFVkViwiOpNxCYREixSdimoi0pATAQJEkJIDlWUtK5K4iKc1HatYtfO+N+8PzPvvnMOCzyWxy2BBT2bK7177u9+99N331Uigk+i9CdCBeD8L00TExOmr6/PN8Z83RjzLaXUF40xeQBzxpjfWGt/6/v+BxcvXky6a9R/s+LChQuZKIqe1Vr/SGv9FaVUopRKjTGitTZa64zW+j2l1BXP816/dOnShojIExVPTEyYUqn0nIhcBjDkuu7Dcrm8UC6XN7XWAuBQq9UaDsNwGMDLcRwXJycnfwag/URwqVT6DIApAJ/O5XKzjUbjzVqttt3f30+FQqFQ7is7YRAuz87OBvPz858noheLxeIbAG7vgZVS6sSJE4Ou646naZoS0ZtjY2PnAIx7nvePkZGRuyMjI9uFQgHZbFZXKpXC4ODgEc/z6gMDA+udTuf9hYWFUQAvAbi9l4qTJ09mtdaTzHwFwA8ymcxRpdQLRESVSuXdI0eObBeLReV5nvI8T4hoKwzDOcdxglqtdvj48eM7xpiAmZ8D9sWNiPIATouIEpE/VKtVF8CA1jqsVCrNUqkkruvC8zxorZVSKu10Oh9GUfQ2gG3f97czmUyLiHIHwUpEHBGZ1Vr/rlgspsYY7bqudV03dRwHWmtoreE4DjzPg+M4ipmb1tp3rbUrImKJCD3gbjFzGoahFZEPRMSKSCZN0ywRGWOM6kK76gFEYRgubG5u2iRJvI+AjTEiIujm+tq1a2tJkiwxcyGKouFsNlvNZDL5/aodxwEAabfbvLS0NBAEwSHP8zZ6wMxcIyKfiGg3o4jj+GqSJMna2trxxcXFwU6nUxCR/WtkZ2cHc3Nz/qNHj55SSmWLxeIvgH1XmpmnRMRn5ncAhLvg3wO4wczP37lz5wsbGxtJo9EIqtVqEIYhOp2ONz8/X7t///4zGxsbjVKp9FYul3vlILifiDqppK04iAkAbty4sXnmzJmXHccZbTabY3Ecl5eXl4/29/dvGWMkCILC2tracBzHh/L5/N9c150aHx9/vwdsrf2xiPwcgi87jjMNoA0Ap06dsq1WC4uLi6rVapWTJPlss9l0RUSladoGsGqM+SOAV9M0nTl79iz1gIno70qpx0TkEZEGgNOnTzvHjh37dqFQeMpxHCRJ8ra1dpqEjFHGYebtlZUVLwiCpa2trfcePnyYXL58GQetUAAUM+9Fr16vP9PpdL63tbXlRVG0w8yvlcvlq5wwcqWcevDgQd/CwsJPiei7InKrUqlMAVjqAQdBgFwuh/1gAD9JkqQUxzGCIHij3W7/6ubNm0F3slqtMhH9GcBRpdRXd8dlEeGeC9LNsO/76ty5c5NKqS/FcSxRFK1aa1+9e/fuh/v7V1dXw2azeVVEfikiqYiY7lwPmIhARHz+/PmjtVrtO9baviiK0G63b1trb8nHvwqamYmZsyIy1HXhoGIhIp3L5b4xOjr6ucP+YeW67rq19pV79+49/hgoAKQiMiciLWZ+qVAo9Pd4vKtYMTNmZmbeqdfrfzKOebbRaPzadd2Z/wD9NzlNZXcD0lrzR8Ddf8X169f/Wq/X79dqtemxsbG3pqenoydwDTM/LSKfAjAVRdEWsO8xHRoa8kXkdRF5rJT64crKyj8BqCcp3a2s53kvisg3ReT7aZr+RUR4T3Gr1ZJ8Pp+IyEkRueL7figiB+OH7jdrLUQEROQw89NEJCKSdvv2wMPDw6319fVbAL4G4PnuSbTWezHsWsXMXSiYGUTEAF4D8EhEuMeK/3f9C5VtKG2arhqTAAAAAElFTkSuQmCC" />
<span class="sf-toolbar-status">{{ collector.querycount }}</span>
{% if collector.querycount > 0 %}
<span class="sf-toolbar-info-piece-additional-detail">in {{ '%0.2f'|format(collector.time) }} ms</span>
{% endif %}
{% else %}
{{ include('@EMSCommon/DataCollector/icon.svg') }}
<span class="sf-toolbar-value">{{ collector.querycount }}</span>
{% if collector.querycount > 0 %}
<span class="sf-toolbar-info-piece-additional-detail">
<span class="sf-toolbar-label">in</span>
<span class="sf-toolbar-value">{{ '%0.2f'|format(collector.time) }}</span>
<span class="sf-toolbar-label">ms</span>
</span>
{% endif %}
{{ include('@EMSCommon/DataCollector/icon.svg') }}
<span class="sf-toolbar-value">{{ collector.queryCount }}</span>
{% if collector.queryCount > 0 %}
<span class="sf-toolbar-info-piece-additional-detail">
<span class="sf-toolbar-label">in</span>
<span class="sf-toolbar-value">{{ '%0.2f'|format(collector.time) }}</span>
<span class="sf-toolbar-label">ms</span>
</span>
{% endif %}
{% endset %}
{% set text %}
Expand All @@ -42,7 +33,7 @@
</div>
<div class="sf-toolbar-info-piece">
<b>Queries</b>
<span class="sf-toolbar-status">{{ collector.querycount }}</span>
<span class="sf-toolbar-status">{{ collector.queryCount }}</span>
</div>
<div class="sf-toolbar-info-piece">
<b>Query Time</b>
Expand All @@ -53,19 +44,18 @@
<span>{{ '%0.2f'|format(collector.executionTime) }} ms</span>
</div>
{% endset %}
{% include '@WebProfiler/Profiler/toolbar_item.html.twig' with { 'link': profiler_url } %}
{% include '@WebProfiler/Profiler/toolbar_item.html.twig' with { 'link': profiler_url, status: status_color } %}
{% endblock %}

{% block menu %}
{% set profiler_markup_version = profiler_markup_version|default(1) %}

<span class="label {{ collector.querycount ? '' : 'disabled' }}">
{% if profiler_markup_version == 1 %}
<span class="icon"><img src="data:image/png;base64,iVBORw0KGgoAAAANSUhEUgAAABYAAAAcCAQAAADPJofWAAAAAXNSR0IArs4c6QAAAAJiS0dEAP+Hj8y/AAAACXBIWXMAAAsTAAALEwEAmpwYAAAAB3RJTUUH2woEDg0xnxGaxwAAA51JREFUOMt100ts1FUUx/Hvufc/8x9mOrTTDpbysEVsqTzUqAsRgpqQGIJiIhtZSEJcqNGFJrSiZSPYkKALBUyAiLEuWKjBhdFAaEwwPNQqEAgEaA0FEWh4lE477/+9x0WLsST+Fmf1ycnJvecI/0knW4ENgZkhr5gVMtcEMmB64z1msCOCboR70tlkOuQdQREMBovF7tQt71/mXtzZQo8s89jLycFETiSqKd/v5wSY32VN18Ak3JGiR1d7an+Y3Z/Np7yVeCY/9czU4efF2iPxZ+wLXPgXP7WCTZ7MvvlnZlbqSJnGGbMeam5pk6HTIw9qs7tiH6D9vrbXW9e1Tus/sbhHZ8VOtfU1uZSExCUe1ExLtqayjcPnx4qNssjOs3TQrY9rYdVB2aFRw7HWq2kbJxCjFAsDoY+3hbkbw9ebNBsQ6EJVNlb3yQIDY8lcaAIsBisxiSXGToTNWqi/JUWXMIoabrK/95ymDNYHzmDUYAiwWOImOle+EI2AxyiKVydQGVAIoyneiBUNsAQEWIn+LA2NJqOYw3hUFQV2DFbu+FSuKTk9kRGMBoyPE7m8vza7UhMrmQNlV+NwAlDZXmXkkcHaeNamQBCEiLyeb7w631C71yxfr8/6YT8GUP6ifKlcf3xJX26kWNQyJfL+TvVs3S8rCw31hfRm2/KzL+iGQz8BnLjz8EVd5TPXF9wI/E0ZK/gr6SOLj7+Yz9RRu2bmMXm6y2/0A/rS0f6JL985+prVQAJiKEU8kLid6ezaA8Gh7iVP6BKtHad7njQr+xmSeFELLi2YovwlJ5Nbu07DNoLFoVNVrwBvh6feSMwSDcVuLvWF0y3Brd9mDlRlTsuVweGPCRzI+NOBW2rW3iYv5ZPfbrm7ji2fx1/Vkn7U/OGlivE4HA5Yh+yqUKFAYa3QfXcVf/R7Segy3wDGo4x3Tr3H3LLmqX6mZ5+jC4A5DO7jLR3SmAoYj8eTqx5uMR+UKErp78q2/e7ARNuLgE940bR1E9jpcKx+16MxJUd5+68XJp+a5DnqFxU/yYZG8XiSfJ+awkIW9WW+zLF8sh6NeqJb0cs+biIcKjW8u3T3xj+uZXZ/PbSe3km2nHWbogb3ZlSgPWz/bt71tsf432Qa64bSh5PTIFAU0pqdG3oRIiCgBBgsVTwRpYwmnWgMAlUd1aR+6m+DA4QqBlDKRDgifCqq8WO+CoFW9Ctd7dvBA+NV8DgiognuSv4bbsA/e9y1PQRZggAAAAAASUVORK5CYII=" alt="" /></span>
{% else %}
<span class="icon">{{ include('@EMSCommon/DataCollector/icon.svg') }}</span>
{% endif %}
<span class="label label-status-{{ collector.countErrors > 0 ? 'error' }} {{ collector.queryCount ? '' : 'disabled' }}">
<span class="icon">{{ include('@EMSCommon/DataCollector/icon.svg') }}</span>
<strong>Elastica</strong>
{% if collector.countErrors > 0 %}
<span class="count">
<span>{{ collector.countErrors }}</span>
</span>
{% endif %}
</span>
{% endblock %}

Expand All @@ -82,7 +72,7 @@
<span class="label">Cluster health</span>
</div>
<div class="metric">
<span class="value">{{ collector.querycount }}</span>
<span class="value">{{ collector.queryCount }}</span>
<span class="label">Database Queries</span>
</div>
<div class="metric">
Expand All @@ -97,7 +87,7 @@

<h2>Queries</h2>

{% if not collector.querycount %}
{% if not collector.queryCount %}
<div class="empty">
<p>No queries were performed.</p>
</div>
Expand All @@ -114,11 +104,20 @@
</thead>
<tbody id="queries">
{% for key, query in collector.queries %}
<tr id="queryNo-{{ key }}">
<tr id="queryNo-{{ key }}" class="{{ html_classes({
'log-status-error': query.exception is not null,
'status-error': query.exception is not null,
}) }}">
<td class="nowrap">{{ loop.index }}</td>
<td class="nowrap">{{ '%0.2f'|format(query.executionMS) }}&nbsp;ms</td>
<td class="nowrap">{{ '%0.2f'|format(query.engineMS) }}&nbsp;ms</td>
<td>
{% if query.exception is not null %}
<div>
{{ query.exception.message }}
<hr />
</div>
{% endif %}
<div>
{% for data in query.data %}
<pre>{{ data|json_encode }}</pre>
Expand Down
Loading