8000 [HttpClient] log requests, responses and pushes when they happen · symfony/symfony@4314e82 · GitHub
[go: up one dir, main page]
Skip to content

Commit 4314e82

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

File tree

10 files changed

+144
-62
lines changed

10 files changed

+144
-62
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: 38 additions & 18 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,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

Lines changed: 4 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
/**
@@ -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

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: 22 additions & 8 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) {
@@ -103,7 +105,9 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
103105
throw new TransportException($response->info['error']);
104106
}
105107

106-
if (\in_array(curl_getinfo($ch = $response->handle, CURLINFO_PRIVATE), ['headers', 'destruct'], true)) {
108+
$waitFor = curl_getinfo($ch = $response->handle, CURLINFO_PRIVATE);
109+
110+
if (\in_array($waitFor, ['headers', 'destruct'], true)) {
107111
try {
108112
if (\defined('CURLOPT_STREAM_WEIGHT')) {
109113
curl_setopt($ch, CURLOPT_STREAM_WEIGHT, 32);
@@ -115,6 +119,8 @@ public function __construct(\stdClass $multi, $ch, array $options = null, string
115119
$response->close();
116120
throw $e;
117121
}
122+
} elseif ('content' === $waitFor && ($response->multi->handlesActivity[$response->id][0] ?? null) instanceof FirstChunk) {
123+
self::stream([$response])->current();
118124
}
119125

120126
curl_setopt($ch, CURLOPT_HEADERFUNCTION, null);
@@ -156,8 +1 D7AE 62,8 @@ public function getInfo(string $type = null)
156162
public function __destruct()
157163
{
158164
try {
159-
if (null === $this->timeout || isset($this->info['url'])) {
160-
return; // pushed response
165+
if (null === $this->timeout) {
166+
return; // Unused pushed response
161167
}
162168

163169
if ('content' === $waitFor = curl_getinfo($this->handle, CURLINFO_PRIVATE)) {
@@ -171,7 +177,13 @@ public function __destruct()
171177
$this->close();
172178

173179
// Clear local caches when the only remaining handles are about pushed responses
174-
if (\count($this->multi->openHandles) === \count($this->multi->pushedResponses)) {
180+
if (!$this->multi->openHandles) {
181+
if ($this->logger) {
182+
foreach ($this->multi->pushedResponses as $url => $response) {
183+
$this->logger->info(sprintf('Unused pushed response: %s', $url));
184+
}
185+
}
186+
175187
$this->multi->pushedResponses = [];
176188
// Schedule DNS cache eviction for the next request
177189
$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
249261
/**
250262
* Parses header lines as curl yields them to us.
251263
*/
252-
private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect): int
264+
private static function parseHeaderLine($ch, string $data, array &$info, array &$headers, ?array $options, \stdClass $multi, int $id, ?string &$location, ?callable $resolveRedirect, ?LoggerInterface $logger): int
253265
{
254266
if (!\in_array($waitFor = @curl_getinfo($ch, CURLINFO_PRIVATE), ['headers', 'destruct'], true)) {
255267
return \strlen($data); // Ignore HTTP trailers
@@ -306,6 +318,8 @@ private static function parseHeaderLine($ch, string $data, array &$info, array &
306318
}
307319

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

311325
return \strlen($data);

0 commit comments

Comments
 (0)
0