Skip to content

Commit 441caef

Browse files
nicolas-grekasnicolas-grekas
committed
[HttpClient] log requests, responses and pushes when they happen
1 parent fc6ba7e commit 441caef

File tree

9 files changed

+90
-61
lines changed

9 files changed

+90
-61
lines changed

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

+4
Original file line numberDiff line numberDiff line change
@@ -6,9 +6,13 @@
66

77
<services>
88
<service id="http_client" class="Symfony\Contracts\HttpClient\HttpClientInterface">
9+
<tag name="monolog.logger" channel="http_client" />
910
<factory class="Symfony\Component\HttpClient\HttpClient" method="create" />
1011
<argument type="collection" /> <!-- default options -->
1112
<argument /> <!-- max host connections -->
13+
<call method="setLogger">
14+
<argument type="service" id="logger" on-invalid="ignore" />
15+
</call>
1216
</service>
1317
<service id="Symfony\Contracts\HttpClient\HttpClientInterface" alias="http_client" />
1418

‎src/Symfony/Component/HttpClient/CurlHttpClient.php

+38-18
Original file line numberDiff line numberDiff line change
@@ -11,8 +11,9 @@
1111

1212
namespace Symfony\Component\HttpClient;
1313

14+
use Psr\Log\LoggerAwareInterface;
15+
use Psr\Log\LoggerAwareTrait;
1416
use Psr\Log\LoggerInterface;
15-
use Psr\Log\NullLogger;
1617
use Symfony\Component\HttpClient\Exception\TransportException;
1718
use Symfony\Component\HttpClient\Response\CurlResponse;
1819
use Symfony\Component\HttpClient\Response\ResponseStream;
@@ -30,24 +31,23 @@
3031
*
3132
* @experimental in 4.3
3233
*/
33-
final class CurlHttpClient implements HttpClientInterface
34+
final class CurlHttpClient implements HttpClientInterface, LoggerAwareInterface
3435
{
3536
use HttpClientTrait;
37+
use LoggerAwareTrait;
3638

3739
private $defaultOptions = self::OPTIONS_DEFAULTS;
3840
private $multi;
39-
private $logger;
4041

4142
/**
4243
* @param array $defaultOptions Default requests' options
4344
* @param int $maxHostConnections The maximum number of connections to a single host
45+
* @param int $maxPendingPushes The maximum number of pushed responses to accept in the queue
4446
*
4547
* @see HttpClientInterface::OPTIONS_DEFAULTS for available options
4648
*/
47-
public function __construct(array $defaultOptions = [], LoggerInterface $logger = null, int $maxHostConnections = 6)
49+
public function __construct(array $defaultOptions = [], int $maxHostConnections = 6, int $maxPendingPushes = 50)
4850
{
49-
$this->logger = $logger ?? new NullLogger();
50-
5151
if ($defaultOptions) {
5252
[, $this->defaultOptions] = self::prepareRequest(null, null, $defaultOptions, self::OPTIONS_DEFAULTS);
5353
}
@@ -70,7 +70,7 @@ public function __construct(array $defaultOptions = [], LoggerInterface $logger
7070
];
7171

7272
// Skip configuring HTTP/2 push when it's unsupported or buggy, see https://bugs.php.net/bug.php?id=77535
73-
if (\PHP_VERSION_ID < 70217 || (\PHP_VERSION_ID >= 70300 && \PHP_VERSION_ID < 70304)) {
73+
if (0 >= $maxPendingPushes || \PHP_VERSION_ID < 70217 || (\PHP_VERSION_ID >= 70300 && \PHP_VERSION_ID < 70304)) {
7474
return;
7575
}
7676

@@ -79,8 +79,10 @@ public function __construct(array $defaultOptions = [], LoggerInterface $logger
7979
return;
8080
}
8181

82-
curl_multi_setopt($mh, CURLMOPT_PUSHFUNCTION, static function ($parent, $pushed, array $requestHeaders) use ($multi) {
83-
return self::handlePush($parent, $pushed, $requestHeaders, $multi);
82+
$logger = &$this->logger;
83+
84+
curl_multi_setopt($mh, CURLMOPT_PUSHFUNCTION, static function ($parent, $pushed, array $requestHeaders) use ($multi, $maxPendingPushes, &$logger) {
85+
return self::handlePush($parent, $pushed, $requestHeaders, $multi, $maxPendingPushes, $logger);
8486
});
8587
}
8688

@@ -91,7 +93,6 @@ public function __construct(array $defaultOptions = [], LoggerInterface $logger
9193
*/
9294
public function request(string $method, string $url, array $options = []): ResponseInterface
9395
{
94-
$this->logger->notice('Making a request', ['url' => $url, 'method' => $method, 'client' => static::class]);
9596
[$url, $options] = self::prepareRequest($method, $url, $options, $this->defaultOptions);
9697
$scheme = $url['scheme'];
9798
$authority = $url['authority'];
@@ -109,14 +110,19 @@ public function request(string $method, string $url, array $options = []): Respo
109110
];
110111

111112
if ('GET' === $method && !$options['body'] && $expectedHeaders === $pushedHeaders) {
112-
$this->logger->debug('Creating pushed response');
113+
$this->logger && $this->logger->info(sprintf('Connecting request to pushed response: %s %s', $method, $url));
114+
113115
// Reinitialize the pushed response with request's options
114-
$pushedResponse->__construct($this->multi, $url, $options);
116+
$pushedResponse->__construct($this->multi, $url, $options, $this->logger);
115117

116118
return $pushedResponse;
117119
}
120+
121+
$this->logger && $this->logger->info(sprintf('Rejecting pushed response for "%s": authorization headers don\'t match the request', $url));
118122
}
119123

124+
$this->logger && $this->logger->info(sprintf('Request: %s %s', $method, $url));
125+
120126
$curlopts = [
121127
CURLOPT_URL => $url,
122128
CURLOPT_USERAGENT => 'Symfony HttpClient/Curl',
@@ -163,7 +169,7 @@ public function request(string $method, string $url, array $options = []): Respo
163169
// DNS cache removals require curl 7.42 or higher
164170
// On lower versions, we have to create a new multi handle
165171
curl_multi_close($this->multi->handle);
166-
$this->multi->handle = (new self([], $this->logger))->multi->handle;
172+
$this->multi->handle = (new self())->multi->handle;
167173
}
168174

169175
foreach ($options['resolve'] as $host => $ip) {
@@ -262,7 +268,7 @@ public function request(string $method, string $url, array $options = []): Respo
262268
}
263269
}
264270

265-
return new CurlResponse($this->multi, $ch, $options, $method, self::createRedirectResolver($options, $host));
271+
return new CurlResponse($this->multi, $ch, $options, $this->logger, $method, self::createRedirectResolver($options, $host));
266272
}
267273

268274
/**
@@ -289,30 +295,44 @@ public function __destruct()
289295
}
290296
}
291297

292-
private static function handlePush($parent, $pushed, array $requestHeaders, \stdClass $multi): int
298+
private static function handlePush($parent, $pushed, array $requestHeaders, \stdClass $multi, int $maxPendingPushes, ?LoggerInterface $logger): int
293299
{
294300
$headers = [];
301+
$origin = curl_getinfo($parent, CURLINFO_EFFECTIVE_URL);
295302

296303
foreach ($requestHeaders as $h) {
297304
if (false !== $i = strpos($h, ':', 1)) {
298305
$headers[substr($h, 0, $i)] = substr($h, 1 + $i);
299306
}
300307
}
301308

302-
if ('GET' !== $headers[':method'] || isset($headers['range'])) {
309+
if (!isset($headers[':method']) || !isset($headers[':scheme']) || !isset($headers[':authority']) || !isset($headers[':path']) || 'GET' !== $headers[':method'] || isset($headers['range'])) {
310+
$logger && $logger->info(sprintf('Rejecting pushed response from "%s": pushed headers are invalid', $origin));
311+
303312
return CURL_PUSH_DENY;
304313
}
305314

306315
$url = $headers[':scheme'].'://'.$headers[':authority'];
307316

317+
if ($maxPendingPushes <= \count($multi->pushedResponses)) {
318+
$logger && $logger->info(sprintf('Rejecting pushed response from "%s" for "%s": the queue is full', $origin, $url));
319+
320+
return CURL_PUSH_DENY;
321+
}
322+
308323
// curl before 7.65 doesn't validate the pushed ":authority" header,
309324
// but this is a MUST in the HTTP/2 RFC; let's restrict pushes to the original host,
310325
// ignoring domains mentioned as alt-name in the certificate for now (same as curl).
311-
if (0 !== strpos(curl_getinfo($parent, CURLINFO_EFFECTIVE_URL), $url.'/')) {
326+
if (0 !== strpos($origin, $url.'/')) {
327+
$logger && $logger->info(sprintf('Rejecting pushed response from "%s": server is not authoritative for "%s"', $origin, $url));
328+
312329
return CURL_PUSH_DENY;
313330
}
314331

315-
$multi->pushedResponses[$url.$headers[':path']] = [
332+
$url .= $headers[':path'];
333+
$logger && $logger->info(sprintf('Queueing pushed response: %s', $url));
334+
335+
$multi->pushedResponses[$url] = [
316336
new CurlResponse($multi, $pushed),
317337
[
318338
$headers['authorization'] ?? null,

‎src/Symfony/Component/HttpClient/HttpClient.php

+4-13
Original file line numberDiff line numberDiff line change
@@ -11,8 +11,6 @@
1111

1212
namespace Symfony\Component\HttpClient;
1313

14-
use Psr\Log\LoggerInterface;
15-
use Psr\Log\NullLogger;
1614
use Symfony\Contracts\HttpClient\HttpClientInterface;
1715

1816
/**
@@ -27,23 +25,16 @@ final class HttpClient
2725
/**
2826
* @param array $defaultOptions Default requests' options
2927
* @param int $maxHostConnections The maximum number of connections to a single host
28+
* @param int $maxPendingPushes The maximum number of pushed responses to accept in the queue
3029
*
3130
* @see HttpClientInterface::OPTIONS_DEFAULTS for available options
3231
*/
33-
public static function create(array $defaultOptions = [], LoggerInterface $logger = null, int $maxHostConnections = 6): HttpClientInterface
32+
public static function create(array $defaultOptions = [], int $maxHostConnections = 6, int $maxPendingPushes = 50): HttpClientInterface
3433
{
35-
if (null === $logger) {
36-
$logger = new NullLogger();
37-
}
38-
3934
if (\extension_loaded('curl')) {
40-
$logger->debug('Curl extension is enabled. Creating client.', ['client' => CurlHttpClient::class]);
41-
42-
return new CurlHttpClient($defaultOptions, $logger, $maxHostConnections);
35+
return new CurlHttpClient($defaultOptions, $maxHostConnections, $maxPendingPushes);
4336
}
4437

45-
$logger->debug('Curl extension is disabled. Creating client.', ['client' => NativeHttpClient::class]);
46-
47-
return new NativeHttpClient($defaultOptions, $logger, $maxHostConnections);
38+
return new NativeHttpClient($defaultOptions, $maxHostConnections);
4839
}
4940
}

‎src/Symfony/Component/HttpClient/NativeHttpClient.php

+9-9
Original file line numberDiff line numberDiff line change
@@ -11,8 +11,8 @@
1111

1212
namespace Symfony\Component\HttpClient;
1313

14-
use Psr\Log\LoggerInterface;
15-
use Psr\Log\NullLogger;
14+
use Psr\Log\LoggerAwareInterface;
15+
use Psr\Log\LoggerAwareTrait;
1616
use Symfony\Component\HttpClient\Exception\TransportException;
1717
use Symfony\Component\HttpClient\Response\NativeResponse;
1818
use Symfony\Component\HttpClient\Response\ResponseStream;
@@ -30,24 +30,22 @@
3030
*
3131
* @experimental in 4.3
3232
*/
33-
final class NativeHttpClient implements HttpClientInterface
33+
final class NativeHttpClient implements HttpClientInterface, LoggerAwareInterface
3434
{
3535
use HttpClientTrait;
36+
use LoggerAwareTrait;
3637

3738
private $defaultOptions = self::OPTIONS_DEFAULTS;
3839
private $multi;
39-
private $logger;
4040

4141
/**
4242
* @param array $defaultOptions Default requests' options
4343
* @param int $maxHostConnections The maximum number of connections to open
4444
*
4545
* @see HttpClientInterface::OPTIONS_DEFAULTS for available options
4646
*/
47-
public function __construct(array $defaultOptions = [], LoggerInterface $logger = null, int $maxHostConnections = 6)
47+
public function __construct(array $defaultOptions = [], int $maxHostConnections = 6)
4848
{
49-
$this->logger = $logger ?? new NullLogger();
50-
5149
if ($defaultOptions) {
5250
[, $this->defaultOptions] = self::prepareRequest(null, null, $defaultOptions, self::OPTIONS_DEFAULTS);
5351
}
@@ -73,7 +71,6 @@ public function __construct(array $defaultOptions = [], LoggerInterface $logger
7371
*/
7472
public function request(string $method, string $url, array $options = []): ResponseInterface
7573
{
76-
$this->logger->notice('Making a request', ['url' => $url, 'method' => $method, 'client' => static::class]);
7774
[$url, $options] = self::prepareRequest($method, $url, $options, $this->defaultOptions);
7875

7976
if ($options['bindto'] && file_exists($options['bindto'])) {
@@ -211,7 +208,10 @@ public function request(string $method, string $url, array $options = []): Respo
211208
$context = stream_context_create($context, ['notification' => $notification]);
212209
self::configureHeadersAndProxy($context, $host, $options['request_headers'], $proxy, $noProxy);
213210

214-
return new NativeResponse($this->multi, $context, implode('', $url), $options, $gzipEnabled, $info, $resolveRedirect, $onProgress);
211+
$url = implode('', $url);
212+
$this->logger && $this->logger->info(sprintf('Request: %s %s', $method, $url));
213+
214+
return new NativeResponse($this->multi, $context, $url, $options, $gzipEnabled, $info, $resolveRedirect, $onProgress, $this->logger);
215215
}
216216

217217
/**

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

+17-7
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111

1212
namespace Symfony\Component\HttpClient\Response;
1313

14+
use Psr\Log\LoggerInterface;
1415
use Symfony\Component\HttpClient\Chunk\FirstChunk;
1516
use Symfony\Component\HttpClient\Exception\TransportException;
1617
use Symfony\Contracts\HttpClient\ResponseInterface;
@@ -29,7 +30,7 @@ final class CurlResponse implements ResponseInterface
2930
/**
3031
* @internal
3132
*/
32-
public function __construct(\stdClass $multi, $ch, array $options = null, string $method = 'GET', callable $resolveRedirect = null)
33+
public function __construct(\stdClass $multi, $ch, array $options = null, LoggerInterface $logger = null, string $method = 'GET', callable $resolveRedirect = null)
3334
{
3435
$this->multi = $multi;
3536

@@ -41,6 +42,7 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
4142
}
4243

4344
$this->id = $id = (int) $ch;
45+
$this->logger = $logger;
4446
$this->timeout = $options['timeout'] ?? null;
4547
$this->info['http_method'] = $method;
4648
$this->info['user_data'] = $options['user_data'] ?? null;
@@ -64,8 +66,8 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
6466
$content = ($options['buffer'] ?? true) ? $content : null;
6567
}
6668

67-
curl_setopt($ch, CURLOPT_HEADERFUNCTION, static function ($ch, string $data) use (&$info, &$headers, $options, $multi, $id, &$location, $resolveRedirect): int {
68-
return self::parseHeaderLine($ch, $data, $info, $headers, $options, $multi, $id, $location, $resolveRedirect);
69+
curl_setopt($ch, CURLOPT_HEADERFUNCTION, static function ($ch, string $data) use (&$info, &$headers, $options, $multi, $id, &$location, $resolveRedirect, $logger): int {
70+
return self::parseHeaderLine($ch, $data, $info, $headers, $options, $multi, $id, $location, $resolveRedirect, $logger);
6971
});
7072

7173
if (null === $options) {
@@ -156,8 +158,8 @@ public function getInfo(string $type = null)
156158
public function __destruct()
157159
{
158160
try {
159-
if (null === $this->timeout || isset($this->info['url'])) {
160-
return; // pushed response
161+
if (null === $this->timeout) {
162+
return; // Unused pushed response
161163
}
162164

163165
if ('content' === $waitFor = curl_getinfo($this->handle, CURLINFO_PRIVATE)) {
@@ -171,7 +173,13 @@ public function __destruct()
171173
$this->close();
172174

173175
// Clear local caches when the only remaining handles are about pushed responses
174-
if (\count($this->multi->openHandles) === \count($this->multi->pushedResponses)) {
176+
if (!$this->multi->openHandles) {
177+
if ($this->logger) {
178+
foreach ($this->multi->pushedResponses as $url => $response) {
179+
$this->logger->info(sprintf('Unused pushed response: %s', $url));
180+
}
181+
}
182+
175183
$this->multi->pushedResponses = [];
176184
// Schedule DNS cache eviction for the next request
177185
$this->multi->dnsCache[2] = $this->multi->dnsCache[2] ?: $this->multi->dnsCache[1];
@@ -249,7 +257,7 @@ protected static function select(\stdClass $multi, float $timeout): int
249257
/**
250258
* Parses header lines as curl yields them to us.
251259
*/
252-
private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect): int
260+
private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect, ?LoggerInterface $logger): int
253261
{
254262
if (!\in_array($waitFor = @curl_getinfo($ch, CURLINFO_PRIVATE), ['headers', 'destruct'], true)) {
255263
return \strlen($data); // Ignore HTTP trailers
@@ -306,6 +314,8 @@ private static function parseHeaderLine($ch, string $data, array &$info, array &
306314
}
307315

308316
curl_setopt($ch, CURLOPT_PRIVATE, 'content');
317+
} elseif (null !== $info['redirect_url'] && $logger) {
318+
$logger->info(sprintf('Redirecting: %s %s', $info['http_code'], $info['redirect_url']));
309319
}
310320

311321
return \strlen($data);

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

+11-3
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@
1111

1212
namespace Symfony\Component\HttpClient\Response;
1313

14+
use Psr\Log\LoggerInterface;
1415
use Symfony\Component\HttpClient\Chunk\FirstChunk;
1516
use Symfony\Component\HttpClient\Exception\TransportException;
1617
use Symfony\Contracts\HttpClient\ResponseInterface;
@@ -35,12 +36,13 @@ final class NativeResponse implements ResponseInterface
3536
/**
3637
* @internal
3738
*/
38-
public function __construct(\stdClass $multi, $context, string $url, $options, bool $gzipEnabled, array &$info, callable $resolveRedirect, ?callable $onProgress)
39+
public function __construct(\stdClass $multi, $context, string $url, $options, bool $gzipEnabled, array &$info, callable $resolveRedirect, ?callable $onProgress, ?LoggerInterface $logger)
3940
{
4041
$this->multi = $multi;
4142
$this->id = (int) $context;
4243
$this->context = $context;
4344
$this->url = $url;
45+
$this->logger = $logger;
4446
$this->timeout = $options['timeout'];
4547
$this->info = &$info;
4648
$this->resolveRedirect = $resolveRedirect;
@@ -107,13 +109,19 @@ private function open(): void
107109
$this->info['start_time'] = microtime(true);
108110
$url = $this->url;
109111

110-
do {
112+
while (true) {
111113
// Send request and follow redirects when needed
112114
$this->info['fopen_time'] = microtime(true);
113115
$this->handle = $h = fopen($url, 'r', false, $this->context);
114116
self::addResponseHeaders($http_response_header, $this->info, $this->headers);
115117
$url = ($this->resolveRedirect)($this->multi, $this->headers['location'][0] ?? null, $this->context);
116-
} while (null !== $url);
118+
119+
if (null === $url) {
120+
break;
121+
}
122+
123+
$this->logger && $this->logger->info(sprintf('Redirecting: %s %s', $this->info['http_code'], $url ?? $this->url));
124+
}
117125
} catch (\Throwable $e) {
118126
$this->close();
119127
$this->multi->handlesActivity[$this->id][] = null;

0 commit comments

Comments
 (0)