Skip to content

Commit 63c48db

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

File tree

9 files changed

+87
-61
lines changed

9 files changed

+87
-61
lines changed

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

Lines changed: 4 additions & 0 deletions
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

Lines changed: 30 additions & 17 deletions
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,22 @@
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
4445
*
4546
* @see HttpClientInterface::OPTIONS_DEFAULTS for available options
4647
*/
47-
public function __construct(array $defaultOptions = [], LoggerInterface $logger = null, int $maxHostConnections = 6)
48+
public function __construct(array $defaultOptions = [], int $maxHostConnections = 6)
4849
{
49-
$this->logger = $logger ?? new NullLogger();
50-
5150
if ($defaultOptions) {
5251
[, $this->defaultOptions] = self::prepareRequest(null, null, $defaultOptions, self::OPTIONS_DEFAULTS);
5352
}
@@ -79,8 +78,10 @@ public function __construct(array $defaultOptions = [], LoggerInterface $logger
7978
return;
8079
}
8180

82-
curl_multi_setopt($mh, CURLMOPT_PUSHFUNCTION, static function ($parent, $pushed, array $requestHeaders) use ($multi) {
83-
return self::handlePush($parent, $pushed, $requestHeaders, $multi);
81+
$logger = &$this->logger;
82+
83+
curl_multi_setopt($mh, CURLMOPT_PUSHFUNCTION, static function ($parent, $pushed, array $requestHeaders) use ($multi, &$logger) {
84+
return self::handlePush($parent, $pushed, $requestHeaders, $multi, $logger);
8485
});
8586
}
8687

@@ -91,7 +92,6 @@ public function __construct(array $defaultOptions = [], LoggerInterface $logger
9192
*/
9293
public function request(string $method, string $url, array $options = []): ResponseInterface
9394
{
94-
$this->logger->notice('Making a request', ['url' => $url, 'method' => $method, 'client' => static::class]);
9595
[$url, $options] = self::prepareRequest($method, $url, $options, $this->defaultOptions);
9696
$scheme = $url['scheme'];
9797
$authority = $url['authority'];
@@ -109,14 +109,19 @@ public function request(string $method, string $url, array $options = []): Respo
109109
];
110110

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

116117
return $pushedResponse;
117118
}
119+
120+
$this->logger && $this->logger->info(sprintf('Rejecting pushed response for "%s": authorization headers don\'t match the request', $url));
118121
}
119122

123+
$this->logger && $this->logger->info(sprintf('Request: %s %s', $method, $url));
124+
120125
$curlopts = [
121126
CURLOPT_URL => $url,
122127
CURLOPT_USERAGENT => 'Symfony HttpClient/Curl',
@@ -163,7 +168,7 @@ public function request(string $method, string $url, array $options = []): Respo
163168
// DNS cache removals require curl 7.42 or higher
164169
// On lower versions, we have to create a new multi handle
165170
curl_multi_close($this->multi->handle);
166-
$this->multi->handle = (new self([], $this->logger))->multi->handle;
171+
$this->multi->handle = (new self())->multi->handle;
167172
}
168173

169174
foreach ($options['resolve'] as $host => $ip) {
@@ -262,7 +267,7 @@ public function request(string $method, string $url, array $options = []): Respo
262267
}
263268
}
264269

265-
return new CurlResponse($this->multi, $ch, $options, $method, self::createRedirectResolver($options, $host));
270+
return new CurlResponse($this->multi, $ch, $options, $this->logger, $method, self::createRedirectResolver($options, $host));
266271
}
267272

268273
/**
@@ -289,17 +294,20 @@ public function __destruct()
289294
}
290295
}
291296

292-
private static function handlePush($parent, $pushed, array $requestHeaders, \stdClass $multi): int
297+
private static function handlePush($parent, $pushed, array $requestHeaders, \stdClass $multi, ?LoggerInterface $logger): int
293298
{
294299
$headers = [];
300+
$origin = curl_getinfo($parent, CURLINFO_EFFECTIVE_URL);
295301

296302
foreach ($requestHeaders as $h) {
297303
if (false !== $i = strpos($h, ':', 1)) {
298304
$headers[substr($h, 0, $i)] = substr($h, 1 + $i);
299305
}
300306
}
301307

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

@@ -308,11 +316,16 @@ private static function handlePush($parent, $pushed, array $requestHeaders, \std
308316
// curl before 7.65 doesn't validate the pushed ":authority" header,
309317
// but this is a MUST in the HTTP/2 RFC; let's restrict pushes to the original host,
310318
// 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.'/')) {
319+
if (0 !== strpos($origin, $url.'/')) {
320+
$logger && $logger->info(sprintf('Rejecting pushed response from "%s": server is not authoritative for "%s"', $origin, $url));
321+
312322
return CURL_PUSH_DENY;
313323
}
314324

315-
$multi->pushedResponses[$url.$headers[':path']] = [
325+
$url .= $headers[':path'];
326+
$logger && $logger->info(sprintf('Queueing pushed response: %s', $url));
327+
328+
$multi->pushedResponses[$url] = [
316329
new CurlResponse($multi, $pushed),
317330
[
318331
$headers['authorization'] ?? null,

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

Lines changed: 3 additions & 13 deletions
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
/**
@@ -30,20 +28,12 @@ final class HttpClient
3028
*
3129
* @see HttpClientInterface::OPTIONS_DEFAULTS for available options
3230
*/
33-
public static function create(array $defaultOptions = [], LoggerInterface $logger = null, int $maxHostConnections = 6): HttpClientInterface
31+
public static function create(array $defaultOptions = [], int $maxHostConnections = 6): HttpClientInterface
3432
{
35-
if (null === $logger) {
36-
$logger = new NullLogger();
37-
}
38-
3933
if (\extension_loaded('curl')) {
40-
$logger->debug('Curl extension is enabled. Creating client.', ['client' => CurlHttpClient::class]);
41-
42-
return new CurlHttpClient($defaultOptions, $logger, $maxHostConnections);
34+
return new CurlHttpClient($defaultOptions, $maxHostConnections);
4335
}
4436

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

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

Lines changed: 9 additions & 9 deletions
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

Lines changed: 17 additions & 7 deletions
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

Lines changed: 11 additions & 3 deletions
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)