Skip to content

Commit 0d3acb4

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

File tree

9 files changed

+80
-58
lines changed

9 files changed

+80
-58
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

+30-17
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

+3-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
/**
@@ -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

+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

+19-6
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;
@@ -24,12 +25,13 @@ final class CurlResponse implements ResponseInterface
2425
{
2526
use ResponseTrait;
2627

28+
private $logger;
2729
private static $performing = false;
2830

2931
/**
3032
* @internal
3133
*/
32-
public function __construct(\stdClass $multi, $ch, array $options = null, string $method = 'GET', callable $resolveRedirect = null)
34+
public function __construct(\stdClass $multi, $ch, array $options = null, LoggerInterface $logger = null, string $method = 'GET', callable $resolveRedirect = null)
3335
{
3436
$this->multi = $multi;
3537

@@ -41,6 +43,7 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
4143
}
4244

4345
$this->id = $id = (int) $ch;
46+
$this->logger = $logger;
4447
$this->timeout = $options['timeout'] ?? null;
4548
$this->info['http_method'] = $method;
4649
$this->info['user_data'] = $options['user_data'] ?? null;
@@ -64,8 +67,8 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
6467
$content = ($options['buffer'] ?? true) ? $content : null;
6568
}
6669

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);
70+
curl_setopt($ch, CURLOPT_HEADERFUNCTION, static function ($ch, string $data) use (&$info, &$headers, $options, $multi, $id, &$location, $resolveRedirect, $logger): int {
71+
return self::parseHeaderLine($ch, $data, $info, $headers, $options, $multi, $id, $location, $resolveRedirect, $logger);
6972
});
7073

7174
if (null === $options) {
@@ -156,8 +159,8 @@ public function getInfo(string $type = null)
156159
public function __destruct()
157160
{
158161
try {
159-
if (null === $this->timeout || isset($this->info['url'])) {
160-
return; // pushed response
162+
if (null === $this->timeout) {
163+
return; // Unused pushed response
161164
}
162165

163166
if ('content' === $waitFor = curl_getinfo($this->handle, CURLINFO_PRIVATE)) {
@@ -172,6 +175,12 @@ public function __destruct()
172175

173176
// Clear local caches when the only remaining handles are about pushed responses
174177
if (\count($this->multi->openHandles) === \count($this->multi->pushedResponses)) {
178+
if ($this->logger) {
179+
foreach ($this->multi->pushedResponses as $url => $response) {
180+
$this->logger->info(sprintf('Unused pushed response: %s', $url));
181+
}
182+
}
183+
175184
$this->multi->pushedResponses = [];
176185
// Schedule DNS cache eviction for the next request
177186
$this->multi->dnsCache[2] = $this->multi->dnsCache[2] ?: $this->multi->dnsCache[1];
@@ -249,7 +258,7 @@ protected static function select(\stdClass $multi, float $timeout): int
249258
/**
250259
* Parses header lines as curl yields them to us.
251260
*/
252-
private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect): int
261+
private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect, ?LoggerInterface $logger): int
253262
{
254263
if (!\in_array($waitFor = @curl_getinfo($ch, CURLINFO_PRIVATE), ['headers', 'destruct'], true)) {
255264
return \strlen($data); // Ignore HTTP trailers
@@ -294,6 +303,8 @@ private static function parseHeaderLine($ch, string $data, array &$info, array &
294303
$location = null;
295304

296305
if ($statusCode < 300 || 400 <= $statusCode || curl_getinfo($ch, CURLINFO_REDIRECT_COUNT) === $options['max_redirects']) {
306+
$logger && $logger->info(sprintf('Response: %s %s', $info['http_code'], $info['url'] ?? curl_getinfo($ch, CURLINFO_EFFECTIVE_URL)));
307+
297308
// Headers and redirects completed, time to get the response's body
298309
$multi->handlesActivity[$id] = [new FirstChunk()];
299310

@@ -306,6 +317,8 @@ private static function parseHeaderLine($ch, string $data, array &$info, array &
306317
}
307318

308319
curl_setopt($ch, CURLOPT_PRIVATE, 'content');
320+
} elseif (null !== $info['redirect_url'] && $logger) {
321+
$logger->info(sprintf('Redirecting: %s %s', $info['http_code'], $info['redirect_url']));
309322
}
310323

311324
return \strlen($data);

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

+6-1
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;
@@ -26,6 +27,7 @@ final class NativeResponse implements ResponseInterface
2627

2728
private $context;
2829
private $url;
30+
private $logger;
2931
private $resolveRedirect;
3032
private $onProgress;
3133
private $remaining;
@@ -35,12 +37,13 @@ final class NativeResponse implements ResponseInterface
3537
/**
3638
* @internal
3739
*/
38-
public function __construct(\stdClass $multi, $context, string $url, $options, bool $gzipEnabled, array &$info, callable $resolveRedirect, ?callable $onProgress)
40+
public function __construct(\stdClass $multi, $context, string $url, $options, bool $gzipEnabled, array &$info, callable $resolveRedirect, ?callable $onProgress, ?LoggerInterface $logger)
3941
{
4042
$this->multi = $multi;
4143
$this->id = (int) $context;
4244
$this->context = $context;
4345
$this->url = $url;
46+
$this->logger = $logger;
4447
$this->timeout = $options['timeout'];
4548
$this->info = &$info;
4649
$this->resolveRedirect = $resolveRedirect;
@@ -113,6 +116,8 @@ private function open(): void
113116
$this->handle = $h = fopen($url, 'r', false, $this->context);
114117
self::addResponseHeaders($http_response_header, $this->info, $this->headers);
115118
$url = ($this->resolveRedirect)($this->multi, $this->headers['location'][0] ?? null, $this->context);
119+
120+
$this->logger && $this->logger->info(sprintf('%s: %s %s', null === $url ? 'Response' : 'Redirecting', $this->info['http_code'], $url ?? $this->url));
116121
} while (null !== $url);
117122
} catch (\Throwable $e) {
118123
$this->close();

0 commit comments

Comments
 (0)