feature #30537 [HttpClient] logger integration (antonch1989, nicolas-…

…grekas)

This PR was merged into the 4.3-dev branch.

Discussion
----------

[HttpClient] logger integration

| Q             | A
| ------------- | ---
| Branch?       | master
| Bug fix?      | no
| New feature?  | yes
| BC breaks?    | no     <!-- see https://symfony.com/bc -->
| Deprecations? | no
| Tests pass?   | yes    <!-- please add some, will be required by reviewers -->
| Fixed tickets | #30502   <!-- #-prefixed issue number(s), if any -->
| License       | MIT
| Doc PR        |

Commits
-------

26d15c8 [HttpClient] log requests, responses and pushes when they happen
fc6ba7e [HttpClient] logger integration

src/Symfony/Bundle/FrameworkBundle/Resources/config/http_client.xml

@@ -6,9 +6,13 @@
 
     <services>
         <service id="http_client" class="Symfony\Contracts\HttpClient\HttpClientInterface">
+            <tag name="monolog.logger" channel="http_client" />
             <factory class="Symfony\Component\HttpClient\HttpClient" method="create" />
             <argument type="collection" /> <!-- default options -->
             <argument /> <!-- max host connections -->
+            <call method="setLogger">
+                <argument type="service" id="logger" on-invalid="ignore" />
+            </call>
         </service>
         <service id="Symfony\Contracts\HttpClient\HttpClientInterface" alias="http_client" />
 

src/Symfony/Component/HttpClient/CurlHttpClient.php

@@ -11,6 +11,9 @@
 
 namespace Symfony\Component\HttpClient;
 
+use Psr\Log\LoggerAwareInterface;
+use Psr\Log\LoggerAwareTrait;
+use Psr\Log\LoggerInterface;
 use Symfony\Component\HttpClient\Exception\TransportException;
 use Symfony\Component\HttpClient\Response\CurlResponse;
 use Symfony\Component\HttpClient\Response\ResponseStream;
@@ -28,20 +31,22 @@
  *
  * @experimental in 4.3
  */
-final class CurlHttpClient implements HttpClientInterface
+final class CurlHttpClient implements HttpClientInterface, LoggerAwareInterface
 {
     use HttpClientTrait;
+    use LoggerAwareTrait;
 
     private $defaultOptions = self::OPTIONS_DEFAULTS;
     private $multi;
 
     /**
      * @param array $defaultOptions     Default requests' options
      * @param int   $maxHostConnections The maximum number of connections to a single host
+     * @param int   $maxPendingPushes   The maximum number of pushed responses to accept in the queue
      *
      * @see HttpClientInterface::OPTIONS_DEFAULTS for available options
      */
-    public function __construct(array $defaultOptions = [], int $maxHostConnections = 6)
+    public function __construct(array $defaultOptions = [], int $maxHostConnections = 6, int $maxPendingPushes = 50)
     {
         if ($defaultOptions) {
             [, $this->defaultOptions] = self::prepareRequest(null, null, $defaultOptions, self::OPTIONS_DEFAULTS);
@@ -65,7 +70,7 @@ public function __construct(array $defaultOptions = [], int $maxHostConnections
         ];
 
         // Skip configuring HTTP/2 push when it's unsupported or buggy, see https://bugs.php.net/bug.php?id=77535
-        if (\PHP_VERSION_ID < 70217 || (\PHP_VERSION_ID >= 70300 && \PHP_VERSION_ID < 70304)) {
+        if (0 >= $maxPendingPushes || \PHP_VERSION_ID < 70217 || (\PHP_VERSION_ID >= 70300 && \PHP_VERSION_ID < 70304)) {
             return;
         }
 
@@ -74,8 +79,10 @@ public function __construct(array $defaultOptions = [], int $maxHostConnections
             return;
         }
 
-        curl_multi_setopt($mh, CURLMOPT_PUSHFUNCTION, static function ($parent, $pushed, array $requestHeaders) use ($multi) {
-            return self::handlePush($parent, $pushed, $requestHeaders, $multi);
+        $logger = &$this->logger;
+
+        curl_multi_setopt($mh, CURLMOPT_PUSHFUNCTION, static function ($parent, $pushed, array $requestHeaders) use ($multi, $maxPendingPushes, &$logger) {
+            return self::handlePush($parent, $pushed, $requestHeaders, $multi, $maxPendingPushes, $logger);
         });
     }
 
@@ -103,13 +110,19 @@ public function request(string $method, string $url, array $options = []): Respo
             ];
 
             if ('GET' === $method && !$options['body'] && $expectedHeaders === $pushedHeaders) {
+                $this->logger && $this->logger->info(sprintf('Connecting request to pushed response: %s %s', $method, $url));
+
                 // Reinitialize the pushed response with request's options
-                $pushedResponse->__construct($this->multi, $url, $options);
+                $pushedResponse->__construct($this->multi, $url, $options, $this->logger);
 
                 return $pushedResponse;
             }
+
+            $this->logger && $this->logger->info(sprintf('Rejecting pushed response for "%s": authorization headers don\'t match the request', $url));
         }
 
+        $this->logger && $this->logger->info(sprintf('Request: %s %s', $method, $url));
+
         $curlopts = [
             CURLOPT_URL => $url,
             CURLOPT_USERAGENT => 'Symfony HttpClient/Curl',
@@ -255,7 +268,7 @@ public function request(string $method, string $url, array $options = []): Respo
             }
         }
 
-        return new CurlResponse($this->multi, $ch, $options, $method, self::createRedirectResolver($options, $host));
+        return new CurlResponse($this->multi, $ch, $options, $this->logger, $method, self::createRedirectResolver($options, $host));
     }
 
     /**
@@ -282,30 +295,44 @@ public function __destruct()
         }
     }
 
-    private static function handlePush($parent, $pushed, array $requestHeaders, \stdClass $multi): int
+    private static function handlePush($parent, $pushed, array $requestHeaders, \stdClass $multi, int $maxPendingPushes, ?LoggerInterface $logger): int
     {
         $headers = [];
+        $origin = curl_getinfo($parent, CURLINFO_EFFECTIVE_URL);
 
         foreach ($requestHeaders as $h) {
             if (false !== $i = strpos($h, ':', 1)) {
                 $headers[substr($h, 0, $i)] = substr($h, 1 + $i);
             }
         }
 
-        if ('GET' !== $headers[':method'] || isset($headers['range'])) {
+        if (!isset($headers[':method']) || !isset($headers[':scheme']) || !isset($headers[':authority']) || !isset($headers[':path']) || 'GET' !== $headers[':method'] || isset($headers['range'])) {
+            $logger && $logger->info(sprintf('Rejecting pushed response from "%s": pushed headers are invalid', $origin));
+
             return CURL_PUSH_DENY;
         }
 
         $url = $headers[':scheme'].'://'.$headers[':authority'];
 
+        if ($maxPendingPushes <= \count($multi->pushedResponses)) {
+            $logger && $logger->info(sprintf('Rejecting pushed response from "%s" for "%s": the queue is full', $origin, $url));
+
+            return CURL_PUSH_DENY;
+        }
+
         // curl before 7.65 doesn't validate the pushed ":authority" header,
         // but this is a MUST in the HTTP/2 RFC; let's restrict pushes to the original host,
         // ignoring domains mentioned as alt-name in the certificate for now (same as curl).
-        if (0 !== strpos(curl_getinfo($parent, CURLINFO_EFFECTIVE_URL), $url.'/')) {
+        if (0 !== strpos($origin, $url.'/')) {
+            $logger && $logger->info(sprintf('Rejecting pushed response from "%s": server is not authoritative for "%s"', $origin, $url));
+
             return CURL_PUSH_DENY;
         }
 
-        $multi->pushedResponses[$url.$headers[':path']] = [
+        $url .= $headers[':path'];
+        $logger && $logger->info(sprintf('Queueing pushed response: %s', $url));
+
+        $multi->pushedResponses[$url] = [
             new CurlResponse($multi, $pushed),
             [
                 $headers['authorization'] ?? null,

src/Symfony/Component/HttpClient/HttpClient.php

@@ -25,13 +25,14 @@ final class HttpClient
     /**
      * @param array $defaultOptions     Default requests' options
      * @param int   $maxHostConnections The maximum number of connections to a single host
+     * @param int   $maxPendingPushes   The maximum number of pushed responses to accept in the queue
      *
      * @see HttpClientInterface::OPTIONS_DEFAULTS for available options
      */
-    public static function create(array $defaultOptions = [], int $maxHostConnections = 6): HttpClientInterface
+    public static function create(array $defaultOptions = [], int $maxHostConnections = 6, int $maxPendingPushes = 50): HttpClientInterface
     {
         if (\extension_loaded('curl')) {
-            return new CurlHttpClient($defaultOptions, $maxHostConnections);
+            return new CurlHttpClient($defaultOptions, $maxHostConnections, $maxPendingPushes);
         }
 
         return new NativeHttpClient($defaultOptions, $maxHostConnections);

src/Symfony/Component/HttpClient/NativeHttpClient.php

@@ -11,6 +11,8 @@
 
 namespace Symfony\Component\HttpClient;
 
+use Psr\Log\LoggerAwareInterface;
+use Psr\Log\LoggerAwareTrait;
 use Symfony\Component\HttpClient\Exception\TransportException;
 use Symfony\Component\HttpClient\Response\NativeResponse;
 use Symfony\Component\HttpClient\Response\ResponseStream;
@@ -28,9 +30,10 @@
  *
  * @experimental in 4.3
  */
-final class NativeHttpClient implements HttpClientInterface
+final class NativeHttpClient implements HttpClientInterface, LoggerAwareInterface
 {
     use HttpClientTrait;
+    use LoggerAwareTrait;
 
     private $defaultOptions = self::OPTIONS_DEFAULTS;
     private $multi;
@@ -205,7 +208,10 @@ public function request(string $method, string $url, array $options = []): Respo
         $context = stream_context_create($context, ['notification' => $notification]);
         self::configureHeadersAndProxy($context, $host, $options['request_headers'], $proxy, $noProxy);
 
-        return new NativeResponse($this->multi, $context, implode('', $url), $options, $gzipEnabled, $info, $resolveRedirect, $onProgress);
+        $url = implode('', $url);
+        $this->logger && $this->logger->info(sprintf('Request: %s %s', $method, $url));
+
+        return new NativeResponse($this->multi, $context, $url, $options, $gzipEnabled, $info, $resolveRedirect, $onProgress, $this->logger);
     }
 
     /**

src/Symfony/Component/HttpClient/Response/CurlResponse.php

@@ -11,6 +11,7 @@
 
 namespace Symfony\Component\HttpClient\Response;
 
+use Psr\Log\LoggerInterface;
 use Symfony\Component\HttpClient\Chunk\FirstChunk;
 use Symfony\Component\HttpClient\Exception\TransportException;
 use Symfony\Contracts\HttpClient\ResponseInterface;
@@ -29,7 +30,7 @@ final class CurlResponse implements ResponseInterface
     /**
      * @internal
      */
-    public function __construct(\stdClass $multi, $ch, array $options = null, string $method = 'GET', callable $resolveRedirect = null)
+    public function __construct(\stdClass $multi, $ch, array $options = null, LoggerInterface $logger = null, string $method = 'GET', callable $resolveRedirect = null)
     {
         $this->multi = $multi;
 
@@ -41,6 +42,7 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
         }
 
         $this->id = $id = (int) $ch;
+        $this->logger = $logger;
         $this->timeout = $options['timeout'] ?? null;
         $this->info['http_method'] = $method;
         $this->info['user_data'] = $options['user_data'] ?? null;
@@ -64,8 +66,8 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
             $content = ($options['buffer'] ?? true) ? $content : null;
         }
 
-        curl_setopt($ch, CURLOPT_HEADERFUNCTION, static function ($ch, string $data) use (&$info, &$headers, $options, $multi, $id, &$location, $resolveRedirect): int {
-            return self::parseHeaderLine($ch, $data, $info, $headers, $options, $multi, $id, $location, $resolveRedirect);
+        curl_setopt($ch, CURLOPT_HEADERFUNCTION, static function ($ch, string $data) use (&$info, &$headers, $options, $multi, $id, &$location, $resolveRedirect, $logger): int {
+            return self::parseHeaderLine($ch, $data, $info, $headers, $options, $multi, $id, $location, $resolveRedirect, $logger);
         });
 
         if (null === $options) {
@@ -103,7 +105,9 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
                 throw new TransportException($response->info['error']);
             }
 
-            if (\in_array(curl_getinfo($ch = $response->handle, CURLINFO_PRIVATE), ['headers', 'destruct'], true)) {
+            $waitFor = curl_getinfo($ch = $response->handle, CURLINFO_PRIVATE);
+
+            if (\in_array($waitFor, ['headers', 'destruct'], true)) {
                 try {
                     if (\defined('CURLOPT_STREAM_WEIGHT')) {
                         curl_setopt($ch, CURLOPT_STREAM_WEIGHT, 32);
@@ -115,6 +119,8 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
                     $response->close();
                     throw $e;
                 }
+            } elseif ('content' === $waitFor && ($response->multi->handlesActivity[$response->id][0] ?? null) instanceof FirstChunk) {
+                self::stream([$response])->current();
             }
 
             curl_setopt($ch, CURLOPT_HEADERFUNCTION, null);
@@ -156,8 +162,8 @@ public function getInfo(string $type = null)
     public function __destruct()
     {
         try {
-            if (null === $this->timeout || isset($this->info['url'])) {
-                return; // pushed response
+            if (null === $this->timeout) {
+                return; // Unused pushed response
             }
 
             if ('content' === $waitFor = curl_getinfo($this->handle, CURLINFO_PRIVATE)) {
@@ -171,7 +177,13 @@ public function __destruct()
             $this->close();
 
             // Clear local caches when the only remaining handles are about pushed responses
-            if (\count($this->multi->openHandles) === \count($this->multi->pushedResponses)) {
+            if (!$this->multi->openHandles) {
+                if ($this->logger) {
+                    foreach ($this->multi->pushedResponses as $url => $response) {
+                        $this->logger->info(sprintf('Unused pushed response: %s', $url));
+                    }
+                }
+
                 $this->multi->pushedResponses = [];
                 // Schedule DNS cache eviction for the next request
                 $this->multi->dnsCache[2] = $this->multi->dnsCache[2] ?: $this->multi->dnsCache[1];
@@ -249,7 +261,7 @@ protected static function select(\stdClass $multi, float $timeout): int
     /**
      * Parses header lines as curl yields them to us.
      */
-    private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect): int
+    private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect, ?LoggerInterface $logger): int
     {
         if (!\in_array($waitFor = @curl_getinfo($ch, CURLINFO_PRIVATE), ['headers', 'destruct'], true)) {
             return \strlen($data); // Ignore HTTP trailers
@@ -306,6 +318,8 @@ private static function parseHeaderLine($ch, string $data, array &$info, array &
             }
 
             curl_setopt($ch, CURLOPT_PRIVATE, 'content');
+        } elseif (null !== $info['redirect_url'] && $logger) {
+            $logger->info(sprintf('Redirecting: %s %s', $info['http_code'], $info['redirect_url']));
         }
 
         return \strlen($data);

src/Symfony/Component/HttpClient/Response/NativeResponse.php

@@ -11,6 +11,7 @@
 
 namespace Symfony\Component\HttpClient\Response;
 
+use Psr\Log\LoggerInterface;
 use Symfony\Component\HttpClient\Chunk\FirstChunk;
 use Symfony\Component\HttpClient\Exception\TransportException;
 use Symfony\Contracts\HttpClient\ResponseInterface;
@@ -35,12 +36,13 @@ final class NativeResponse implements ResponseInterface
     /**
      * @internal
      */
-    public function __construct(\stdClass $multi, $context, string $url, $options, bool $gzipEnabled, array &$info, callable $resolveRedirect, ?callable $onProgress)
+    public function __construct(\stdClass $multi, $context, string $url, $options, bool $gzipEnabled, array &$info, callable $resolveRedirect, ?callable $onProgress, ?LoggerInterface $logger)
     {
         $this->multi = $multi;
         $this->id = (int) $context;
         $this->context = $context;
         $this->url = $url;
+        $this->logger = $logger;
         $this->timeout = $options['timeout'];
         $this->info = &$info;
         $this->resolveRedirect = $resolveRedirect;
@@ -107,13 +109,19 @@ private function open(): void
             $this->info['start_time'] = microtime(true);
             $url = $this->url;
 
-            do {
+            while (true) {
                 // Send request and follow redirects when needed
                 $this->info['fopen_time'] = microtime(true);
                 $this->handle = $h = fopen($url, 'r', false, $this->context);
                 self::addResponseHeaders($http_response_header, $this->info, $this->headers);
                 $url = ($this->resolveRedirect)($this->multi, $this->headers['location'][0] ?? null, $this->context);
-            } while (null !== $url);
+
+                if (null === $url) {
+                    break;
+                }
+
+                $this->logger && $this->logger->info(sprintf('Redirecting: %s %s', $this->info['http_code'], $url ?? $this->url));
+            }
         } catch (\Throwable $e) {
             $this->close();
             $this->multi->handlesActivity[$this->id][] = null;

src/Symfony/Component/HttpClient/Response/ResponseTrait.php

@@ -30,6 +30,7 @@
  */
 trait ResponseTrait
 {
+    private $logger;
     private $headers = [];
 
     /**
@@ -299,6 +300,9 @@ public static function stream(iterable $responses, float $timeout = null): \Gene
                         } elseif ($chunk instanceof ErrorChunk) {
                             unset($responses[$j]);
                             $isTimeout = true;
+                        } elseif ($chunk instanceof FirstChunk && $response->logger) {
+                            $info = $response->getInfo();
+                            $response->logger->info(sprintf('Response: %s %s', $info['http_code'], $info['url']));
                         }
 
                         yield $response => $chunk;