From 1d1e27fc0011a27157d933de0527d9da833fe5ff Mon Sep 17 00:00:00 2001 From: David mattei Date: Wed, 20 Dec 2023 11:32:46 +0100 Subject: [PATCH] feat(common/es): log error request/response (#681) --- .../DataCollector/ElasticaDataCollector.php | 22 +++-- .../src/Elasticsearch/Client.php | 46 +++------- .../src/Elasticsearch/ElasticaLogger.php | 90 ++++++++++--------- .../views/DataCollector/elastica.html.twig | 61 +++++++------ .../Elasticsearch/ElasticaLoggerAiTest.php | 14 ++- 5 files changed, 115 insertions(+), 118 deletions(-) diff --git a/EMS/common-bundle/src/DataCollector/ElasticaDataCollector.php b/EMS/common-bundle/src/DataCollector/ElasticaDataCollector.php index 0a6539843..0b1c1fe2b 100644 --- a/EMS/common-bundle/src/DataCollector/ElasticaDataCollector.php +++ b/EMS/common-bundle/src/DataCollector/ElasticaDataCollector.php @@ -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 @@ -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 */ - public function getQueries() + public function getQueries(): array { return $this->data['queries']; } @@ -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; diff --git a/EMS/common-bundle/src/Elasticsearch/Client.php b/EMS/common-bundle/src/Elasticsearch/Client.php index 3e53fac6b..0493e62e2 100644 --- a/EMS/common-bundle/src/Elasticsearch/Client.php +++ b/EMS/common-bundle/src/Elasticsearch/Client.php @@ -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; @@ -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(); @@ -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; } @@ -58,30 +58,8 @@ public function setStopwatch(?Stopwatch $stopwatch = null): void $this->stopwatch = $stopwatch; } - /** - * @param array|string $data - * @param array $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; } } diff --git a/EMS/common-bundle/src/Elasticsearch/ElasticaLogger.php b/EMS/common-bundle/src/Elasticsearch/ElasticaLogger.php index 50329a117..ad9a8b2ea 100644 --- a/EMS/common-bundle/src/Elasticsearch/ElasticaLogger.php +++ b/EMS/common-bundle/src/Elasticsearch/ElasticaLogger.php @@ -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; @@ -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 @@ -34,70 +39,71 @@ public function enable(): void $this->enabled = true; } + public function getNbQueries(): int + { + return \count($this->queries); + } + /** - * @param array|string $data Arguments - * @param array $connection Host, port, transport, and headers of the query - * @param array $query Arguments + * @return array */ - 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 $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 - */ - public function getQueries(): array - { - return $this->queries; - } - - /** - * @param array $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 = []; diff --git a/EMS/common-bundle/src/Resources/views/DataCollector/elastica.html.twig b/EMS/common-bundle/src/Resources/views/DataCollector/elastica.html.twig index eb39b936d..d216a123d 100644 --- a/EMS/common-bundle/src/Resources/views/DataCollector/elastica.html.twig +++ b/EMS/common-bundle/src/Resources/views/DataCollector/elastica.html.twig @@ -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 %} - elastica - {{ collector.querycount }} - {% if collector.querycount > 0 %} - in {{ '%0.2f'|format(collector.time) }} ms - {% endif %} - {% else %} - {{ include('@EMSCommon/DataCollector/icon.svg') }} - {{ collector.querycount }} - {% if collector.querycount > 0 %} - - in - {{ '%0.2f'|format(collector.time) }} - ms - - {% endif %} + {{ include('@EMSCommon/DataCollector/icon.svg') }} + {{ collector.queryCount }} + {% if collector.queryCount > 0 %} + + in + {{ '%0.2f'|format(collector.time) }} + ms + {% endif %} {% endset %} {% set text %} @@ -42,7 +33,7 @@
Queries - {{ collector.querycount }} + {{ collector.queryCount }}
Query Time @@ -53,19 +44,18 @@ {{ '%0.2f'|format(collector.executionTime) }} ms
{% 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) %} - - - {% if profiler_markup_version == 1 %} - - {% else %} - {{ include('@EMSCommon/DataCollector/icon.svg') }} - {% endif %} + + {{ include('@EMSCommon/DataCollector/icon.svg') }} Elastica + {% if collector.countErrors > 0 %} + + {{ collector.countErrors }} + + {% endif %} {% endblock %} @@ -82,7 +72,7 @@ Cluster health
- {{ collector.querycount }} + {{ collector.queryCount }} Database Queries
@@ -97,7 +87,7 @@

Queries

- {% if not collector.querycount %} + {% if not collector.queryCount %}

No queries were performed.

@@ -114,11 +104,20 @@ {% for key, query in collector.queries %} - + {{ loop.index }} {{ '%0.2f'|format(query.executionMS) }} ms {{ '%0.2f'|format(query.engineMS) }} ms + {% if query.exception is not null %} +
+ {{ query.exception.message }} +
+
+ {% endif %}
{% for data in query.data %} 
{{ data|json_encode }}
diff --git a/EMS/common-bundle/tests/Unit/Elasticsearch/ElasticaLoggerAiTest.php b/EMS/common-bundle/tests/Unit/Elasticsearch/ElasticaLoggerAiTest.php index 10c5b7205..deff06b5e 100644 --- a/EMS/common-bundle/tests/Unit/Elasticsearch/ElasticaLoggerAiTest.php +++ b/EMS/common-bundle/tests/Unit/Elasticsearch/ElasticaLoggerAiTest.php @@ -4,6 +4,9 @@ namespace EMS\CommonBundle\Tests\Elasticsearch; +use Elastica\Connection; +use Elastica\Request; +use Elastica\Response; use EMS\CommonBundle\Elasticsearch\ElasticaLogger; use PHPUnit\Framework\TestCase; use Psr\Log\LoggerInterface; @@ -33,14 +36,16 @@ public function testLogQuery(): void $path = '/test_path'; $method = 'GET'; $data = ['key' => 'value']; - $queryTime = 0.5; + + $request = new Request($path, $method, $data); + $request->setConnection(new Connection()); $this->logger->expects($this->once())->method('info')->with( $this->stringContains($path), $this->equalTo([$data]) ); - $this->elasticaLogger->logQuery($path, $method, $data, $queryTime); + $this->elasticaLogger->logResponse(new Response(''), $request); $this->assertSame(1, $this->elasticaLogger->getNbQueries()); $queries = $this->elasticaLogger->getQueries(); @@ -51,7 +56,10 @@ public function testLogQuery(): void public function testReset(): void { - $this->elasticaLogger->logQuery('/test_path', 'GET', ['key' => 'value'], 0.5); + $request = new Request('/test_path', 'GET', ['key' => 'value']); + $request->setConnection(new Connection()); + + $this->elasticaLogger->logResponse(new Response(''), $request); $this->assertSame(1, $this->elasticaLogger->getNbQueries()); $this->elasticaLogger->reset();