diff --git a/CHANGELOG.md b/CHANGELOG.md index b5d03aa..153af69 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,16 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [Unreleased] + +### Added + +- Structured logging via [PSR-3](https://www.php-fig.org/psr/psr-3/): `ClientBuilder::logger()` injects any `Psr\Log\LoggerInterface`; no logger is used by default. Emits `client.initialized` (INFO, once), `http.request.sent` / `http.response.received` (DEBUG, per attempt), and `http.request.failed` (ERROR, transport failures only). Query and JSON-body secrets (`api_key`, `api_secret`, `token`, `password`) are always redacted. Request/response bodies are excluded by default; opt in with `ClientBuilder::logBodies(true)`. + +### Changed + +- **Behavior change:** the connection-pool configuration is no longer written to PHP's `error_log()` at client construction. That information is now available only through an injected PSR-3 logger, as the `client.initialized` event. If you relied on the old `error_log` line, inject a logger via `->logger(...)` instead. + ## [9.0.0] - 2026-07-15 OpenAPI regeneration for optional query parameters ([FEEDS-1651](https://linear.app/stream/issue/FEEDS-1651), [#54](https://github.com/GetStream/getstream-php/pull/54)). diff --git a/README.md b/README.md index 4a585d7..5dfa076 100644 --- a/README.md +++ b/README.md @@ -57,6 +57,40 @@ Per-call `curl` overrides replace (do not merge with) the client-level `curl` op **Escape hatch:** Passing your own client via `->httpClient($mine)` skips all 4 knobs; your client is used as-is. +## Logging + +The SDK emits structured events through a [PSR-3](https://www.php-fig.org/psr/psr-3/) `Psr\Log\LoggerInterface`. No logger is injected by default (`Psr\Log\NullLogger`, a no-op); pass your own via `->logger(...)`: + +```php +$client = (new GetStream\ClientBuilder()) + ->apiKey($apiKey) + ->apiSecret($apiSecret) + ->logger($myPsr3Logger) + ->build(); +``` + +Events emitted: + +| Event | Level | When | +|---|---|---| +| `client.initialized` | INFO | Once, at construction | +| `http.request.sent` | DEBUG | Before each HTTP attempt | +| `http.response.received` | DEBUG | After any HTTP response, including 4xx/5xx (status codes are data, not a failure) | +| `http.request.failed` | ERROR | Transport failure only (connection reset, timeout, DNS failure, TLS handshake failure) — no HTTP response was received | + +The SDK never sets the logger's minimum level; that's the caller's responsibility. + +**Bodies are not logged by default.** Enable with `->logBodies(true)`; this emits one WARN at construction and adds (key-redacted) `http.request.body` / `http.response.body` fields to the DEBUG events. Query values for `api_key`, `api_secret`, `token` and top-level JSON body keys `api_secret`, `token`, `password` are always redacted (case-insensitive for query values), whether or not body logging is on. No headers are ever logged. + +```php +$client = (new GetStream\ClientBuilder()) + ->apiKey($apiKey) + ->apiSecret($apiSecret) + ->logger($myPsr3Logger) + ->logBodies(true) + ->build(); +``` + ## Code Generation Generate API methods from OpenAPI spec: diff --git a/composer.json b/composer.json index a5be582..992a3dd 100644 --- a/composer.json +++ b/composer.json @@ -16,6 +16,7 @@ "ext-json": "*", "firebase/php-jwt": "^7.0", "guzzlehttp/guzzle": "^7.0", + "psr/log": "^3.0", "vlucas/phpdotenv": "^5.0" }, "require-dev": { diff --git a/composer.lock b/composer.lock index 836c4d4..45326a5 100644 --- a/composer.lock +++ b/composer.lock @@ -4,7 +4,7 @@ "Read more about it at https://getcomposer.org/doc/01-basic-usage.md#installing-dependencies", "This file is @generated automatically" ], - "content-hash": "191564aa94ee40f4d652a4951de2e3db", + "content-hash": "159185f0345e18ed9c19003d87c1617e", "packages": [ { "name": "firebase/php-jwt", @@ -691,6 +691,56 @@ }, "time": "2023-04-04T09:54:51+00:00" }, + { + "name": "psr/log", + "version": "3.0.2", + "source": { + "type": "git", + "url": "https://github.com/php-fig/log.git", + "reference": "f16e1d5863e37f8d8c2a01719f5b34baa2b714d3" + }, + "dist": { + "type": "zip", + "url": "https://api.github.com/repos/php-fig/log/zipball/f16e1d5863e37f8d8c2a01719f5b34baa2b714d3", + "reference": "f16e1d5863e37f8d8c2a01719f5b34baa2b714d3", + "shasum": "" + }, + "require": { + "php": ">=8.0.0" + }, + "type": "library", + "extra": { + "branch-alias": { + "dev-master": "3.x-dev" + } + }, + "autoload": { + "psr-4": { + "Psr\\Log\\": "src" + } + }, + "notification-url": "https://packagist.org/downloads/", + "license": [ + "MIT" + ], + "authors": [ + { + "name": "PHP-FIG", + "homepage": "https://www.php-fig.org/" + } + ], + "description": "Common interface for logging libraries", + "homepage": "https://github.com/php-fig/log", + "keywords": [ + "log", + "psr", + "psr-3" + ], + "support": { + "source": "https://github.com/php-fig/log/tree/3.0.2" + }, + "time": "2024-09-11T13:17:53+00:00" + }, { "name": "ralouphie/getallheaders", "version": "3.0.3", diff --git a/phpunit.xml b/phpunit.xml index 2714962..a4496a2 100644 --- a/phpunit.xml +++ b/phpunit.xml @@ -17,8 +17,5 @@ src - - - diff --git a/src/ClientBuilder.php b/src/ClientBuilder.php index 647fbe7..4c145ae 100644 --- a/src/ClientBuilder.php +++ b/src/ClientBuilder.php @@ -9,6 +9,8 @@ use GetStream\Http\GuzzleHttpClient; use GetStream\Http\HttpClientInterface; use GetStream\Http\PoolConfig; +use Psr\Log\LoggerInterface; +use Psr\Log\NullLogger; /** * Builder class for creating GetStream clients with environment variable support. @@ -22,6 +24,8 @@ class ClientBuilder private bool $loadEnv = true; private ?string $envPath = null; private PoolConfig $pool; + private ?LoggerInterface $logger = null; + private bool $logBodies = false; public function __construct() { @@ -112,6 +116,30 @@ public function requestTimeout(int $seconds): self return $this; } + /** + * Inject a PSR-3 logger for structured `client.initialized` / `http.request.*` / + * `http.response.*` events. Default when none is set: `Psr\Log\NullLogger` (no-op). + * The SDK never sets the logger's level; that is the caller's responsibility. + */ + public function logger(LoggerInterface $logger): self + { + $this->logger = $logger; + + return $this; + } + + /** + * Include (key-redacted) request/response bodies in the `http.request.sent` / + * `http.response.received` log events. Off by default. Enabling this emits one + * WARN at construction time. + */ + public function logBodies(bool $on): self + { + $this->logBodies = $on; + + return $this; + } + /** * Disable loading from environment variables. */ @@ -265,41 +293,51 @@ private function getEnvVar(string $name): ?string /** * Resolve the HttpClient. * If the user supplied one via httpClient(), return it as-is (escape hatch). - * Otherwise build a GuzzleHttpClient with the configured PoolConfig and emit the INFO log. + * Otherwise build a GuzzleHttpClient with the configured PoolConfig. Either way, + * emit one `client.initialized` INFO event through the injected PSR-3 logger. */ private function resolveHttpClient(): HttpClientInterface { + $logger = $this->logger ?? new NullLogger(); + $user = $this->httpClient; if ($user !== null) { - $this->logInfo( - 'getstream-php connection pool: user_http_client=true (5 knobs not applied)' - ); + $logger->info('client.initialized', $this->clientInitializedContext(userHttpClient: true)); + $this->warnIfLogBodies($logger); return $user; } - $client = new GuzzleHttpClient([], 3, $this->pool); + $client = new GuzzleHttpClient([], 3, $this->pool, $logger, $this->logBodies); - $this->logInfo(sprintf( - 'getstream-php connection pool: max_conns_per_host=%d idle_timeout=%ds connect_timeout=%ds request_timeout=%ds user_http_client=false', - $this->pool->maxConnsPerHost, - $this->pool->idleTimeout, - $this->pool->connectTimeout, - $this->pool->requestTimeout, - )); + $logger->info('client.initialized', $this->clientInitializedContext(userHttpClient: false)); + $this->warnIfLogBodies($logger); return $client; } - /** - * Emit one INFO log line via error_log(). - * Suppressed under PHPUnit to keep test output clean (PHPUNIT_RUNNING constant is set in phpunit.xml). - */ - private function logInfo(string $message): void + private function warnIfLogBodies(LoggerInterface $logger): void { - if (defined('PHPUNIT_RUNNING') && PHPUNIT_RUNNING) { - return; + if ($this->logBodies) { + $logger->warning( + 'HTTP request/response bodies will be logged. Auth headers and known-secret fields are still redacted, but other sensitive data (messages, PII) may appear in logs. Disable for production.' + ); } - error_log('[INFO] ' . $message); + } + + /** @return array */ + private function clientInitializedContext(bool $userHttpClient): array + { + return [ + 'stream.sdk.name' => 'getstream-php', + 'stream.sdk.version' => Constant::VERSION, + 'stream.client.max_conns_per_host' => $this->pool->maxConnsPerHost, + 'stream.client.idle_timeout_seconds' => $this->pool->idleTimeout, + 'stream.client.connect_timeout_seconds' => $this->pool->connectTimeout, + 'stream.client.request_timeout_seconds' => $this->pool->requestTimeout, + 'stream.client.gzip_enabled' => true, + 'stream.client.user_http_client' => $userHttpClient, + 'stream.client.log_bodies' => $this->logBodies, + ]; } } diff --git a/src/Http/GuzzleHttpClient.php b/src/Http/GuzzleHttpClient.php index 4cfefd7..793db7f 100644 --- a/src/Http/GuzzleHttpClient.php +++ b/src/Http/GuzzleHttpClient.php @@ -17,6 +17,8 @@ use GuzzleHttp\Handler\CurlMultiHandler; use GuzzleHttp\HandlerStack; use Psr\Http\Message\ResponseInterface; +use Psr\Log\LoggerInterface; +use Psr\Log\NullLogger; /** * Guzzle HTTP client implementation. @@ -31,16 +33,30 @@ class GuzzleHttpClient implements HttpClientInterface /** @var PoolConfig Effective pool configuration (kept for diagnostics). */ private PoolConfig $pool; + private LoggerInterface $logger; + + /** Whether request/response bodies are included (key-redacted) in log events. */ + private bool $logBodies; + /** * Create a new GuzzleHttpClient. * - * @param array $config Guzzle client configuration (wins over $pool defaults) - * @param int $maxRetries Maximum retries for 429 rate-limit responses (default 3). - * @param PoolConfig|null $pool Connection pool configuration. When null, spec defaults apply. + * @param array $config Guzzle client configuration (wins over $pool defaults) + * @param int $maxRetries Maximum retries for 429 rate-limit responses (default 3). + * @param PoolConfig|null $pool Connection pool configuration. When null, spec defaults apply. + * @param LoggerInterface|null $logger PSR-3 logger for structured request/response events. Defaults to NullLogger. + * @param bool $logBodies When true, include (key-redacted) request/response bodies in log events. */ - public function __construct(array $config = [], int $maxRetries = 3, ?PoolConfig $pool = null) - { + public function __construct( + array $config = [], + int $maxRetries = 3, + ?PoolConfig $pool = null, + ?LoggerInterface $logger = null, + bool $logBodies = false, + ) { $pool = $pool ?? new PoolConfig(); + $this->logger = $logger ?? new NullLogger(); + $this->logBodies = $logBodies; // Persistent multi handle: routes every request (sync and async) through one // libcurl multi handle that holds a connection pool for the lifetime of this @@ -94,6 +110,77 @@ public function getPoolConfig(): PoolConfig return $this->pool; } + private static function elapsedMs(int $startNs): int + { + return (int) ((hrtime(true) - $startNs) / 1e6); + } + + /** Emit the `http.request.sent` DEBUG event for one HTTP attempt. */ + private function emitRequestSent(string $method, string $path, string $query, array $requestOptions): void + { + $context = [ + 'http.request.method' => $method, + 'url.path' => $path, + 'url.query' => LogRedaction::redactQuery($query), + ]; + + if ($this->logBodies && isset($requestOptions['json'])) { + $encoded = json_encode($requestOptions['json']); + if ($encoded !== false) { + $context['http.request.body'] = LogRedaction::redactJsonBody($encoded); + } + } + + $this->logger->debug('http.request.sent', $context); + } + + /** + * Emit the `http.response.received` DEBUG event for one HTTP attempt + * (any status code, including 4xx/5xx: those are data, not a transport + * failure). Reads the response body exactly once and returns it so the + * caller can reuse it instead of consuming the stream a second time. + */ + private function emitResponseReceived(ResponseInterface $response, int $durationMs): string + { + $size = $response->getBody()->getSize(); + $rawBody = (string) $response->getBody(); + + $context = [ + 'http.response.status_code' => $response->getStatusCode(), + 'http.response.body.size' => $size ?? strlen($rawBody), + 'duration_ms' => $durationMs, + ]; + + if ($this->logBodies) { + $contentType = $response->getHeaderLine('Content-Type'); + $context['http.response.body'] = str_contains($contentType, 'application/json') + ? LogRedaction::redactJsonBody($rawBody) + : $rawBody; + } + + $this->logger->debug('http.response.received', $context); + + return $rawBody; + } + + /** Emit the `http.request.failed` ERROR event: transport failure, no HTTP response received. */ + private function emitRequestFailed( + string $method, + string $path, + string $query, + StreamTransportException $transportException, + int $durationMs, + ): void { + $this->logger->error('http.request.failed', [ + 'http.request.method' => $method, + 'url.path' => $path, + 'url.query' => LogRedaction::redactQuery($query), + 'error.type' => $transportException->getErrorType(), + 'error.message' => LogRedaction::redactMessage($transportException->getMessage()), + 'duration_ms' => $durationMs, + ]); + } + /** * Make an HTTP request. * @@ -137,29 +224,48 @@ public function request( } } + $parsedPath = parse_url($url, PHP_URL_PATH); + $path = is_string($parsedPath) ? $parsedPath : $url; + $parsedQuery = parse_url($url, PHP_URL_QUERY); + $query = is_string($parsedQuery) ? $parsedQuery : ''; + // Retry loop for rate-limited (429) responses. for ($attempt = 0;; $attempt++) { + $this->emitRequestSent($method, $path, $query, $requestOptions); + $start = hrtime(true); + try { $response = $this->client->request($method, $url, $requestOptions); } catch (ClientException | ServerException $e) { // Reachable only if a caller flipped `http_errors` back to true. - return $this->createStreamResponse($e->getResponse(), $e); + $durationMs = self::elapsedMs($start); + $rawBody = $this->emitResponseReceived($e->getResponse(), $durationMs); + + return $this->createStreamResponse($e->getResponse(), $e, $rawBody); } catch (ConnectException $e) { - throw new StreamTransportException( + $transportException = new StreamTransportException( $e->getMessage(), self::mapConnectErrorType($e), $e, ); + $this->emitRequestFailed($method, $path, $query, $transportException, self::elapsedMs($start)); + + throw $transportException; } catch (GuzzleException $e) { - throw new StreamTransportException( + $transportException = new StreamTransportException( $e->getMessage(), StreamTransportException::ERROR_TYPE_UNKNOWN, $e, ); + $this->emitRequestFailed($method, $path, $query, $transportException, self::elapsedMs($start)); + + throw $transportException; } + $rawBody = $this->emitResponseReceived($response, self::elapsedMs($start)); + if ($response->getStatusCode() !== 429 || $attempt >= $this->maxRetries) { - return $this->createStreamResponse($response); + return $this->createStreamResponse($response, null, $rawBody); } // Parse Retry-After header or use exponential backoff. Jitter @@ -179,13 +285,16 @@ public function request( * @param \Throwable|null $previous Cause-chain link when the caller already * caught a Guzzle exception that exposed * the response. + * @param string|null $rawBody Body already read by the caller (e.g. for logging). + * The response body stream can only be consumed once; + * pass it through instead of re-reading it here. * * @return StreamResponse */ - private function createStreamResponse(ResponseInterface $response, ?\Throwable $previous = null): StreamResponse + private function createStreamResponse(ResponseInterface $response, ?\Throwable $previous = null, ?string $rawBody = null): StreamResponse { $statusCode = $response->getStatusCode(); - $rawBody = $response->getBody()->getContents(); + $rawBody ??= $response->getBody()->getContents(); // Convert headers to lowercase keys $headers = []; diff --git a/src/Http/LogRedaction.php b/src/Http/LogRedaction.php new file mode 100644 index 0000000..c9da76b --- /dev/null +++ b/src/Http/LogRedaction.php @@ -0,0 +1,69 @@ +'; + private const QUERY_PARAMS = ['api_key', 'api_secret', 'token']; + private const BODY_KEYS = ['api_secret', 'token', 'password']; + + public static function redactQuery(string $query): string + { + if ($query === '') { + return ''; + } + parse_str($query, $params); + foreach ($params as $name => $_value) { + if (in_array(strtolower((string) $name), self::QUERY_PARAMS, true)) { + $params[$name] = self::REDACTED; + } + } + + return urldecode(http_build_query($params)); + } + + public static function redactJsonBody(?string $body): ?string + { + if ($body === null || $body === '') { + return $body; + } + $data = json_decode($body, true); + if (!is_array($data)) { + return $body; + } + $changed = false; + foreach (self::BODY_KEYS as $key) { + if (array_key_exists($key, $data)) { + $data[$key] = self::REDACTED; + $changed = true; + } + } + + if (!$changed) { + return $body; + } + $encoded = json_encode($data); + + return $encoded !== false ? $encoded : $body; + } + + /** + * Redact secret query-parameter values wherever `key=value` appears in a + * free-form string (e.g. a transport exception message that echoes back + * the failed request URL). Value runs up to the next `&`, whitespace, or + * end of string; everything else in the message is left untouched. + */ + public static function redactMessage(string $message): string + { + $keys = implode('|', array_map( + static fn (string $key): string => preg_quote($key, '/'), + self::QUERY_PARAMS, + )); + + return (string) preg_replace('/(' . $keys . ')=[^&\s]*/i', '${1}=' . self::REDACTED, $message); + } +} diff --git a/tests/ClientBuilderTest.php b/tests/ClientBuilderTest.php index 80d1f24..f76a97a 100644 --- a/tests/ClientBuilderTest.php +++ b/tests/ClientBuilderTest.php @@ -8,6 +8,7 @@ use GetStream\Client; use GetStream\ClientBuilder; use GetStream\Http\HttpClientInterface; +use GetStream\Tests\Http\RecordingLogger; use GetStream\VideoClient; use PHPUnit\Framework\MockObject\MockObject; use PHPUnit\Framework\TestCase; @@ -291,4 +292,77 @@ public function userSuppliedHttpClientBypassesBuild(): void // And it is NOT a GuzzleHttpClient (no pool config is applied to it). self::assertNotInstanceOf(\GetStream\Http\GuzzleHttpClient::class, $client->getHttpClient()); } + + /** @test */ + public function loggerReceivesExactlyOneClientInitializedInfoEvent(): void + { + $logger = new RecordingLogger(); + + (new ClientBuilder()) + ->apiKey('k') + ->apiSecret('s') + ->maxConnsPerHost(7) + ->idleTimeout(33) + ->connectTimeout(2) + ->requestTimeout(11) + ->logger($logger) + ->skipEnvLoad() + ->build(); + + $events = $logger->named('client.initialized'); + self::assertCount(1, $events); + self::assertSame('info', $events[0]['level']); + + $context = $events[0]['context']; + self::assertSame('getstream-php', $context['stream.sdk.name']); + self::assertSame(\GetStream\Constant::VERSION, $context['stream.sdk.version']); + self::assertSame(7, $context['stream.client.max_conns_per_host']); + self::assertSame(33, $context['stream.client.idle_timeout_seconds']); + self::assertSame(2, $context['stream.client.connect_timeout_seconds']); + self::assertSame(11, $context['stream.client.request_timeout_seconds']); + self::assertTrue($context['stream.client.gzip_enabled']); + self::assertFalse($context['stream.client.user_http_client']); + self::assertFalse($context['stream.client.log_bodies']); + } + + /** @test */ + public function logBodiesTrueAddsExactlyOneWarnAndFlagsSchema(): void + { + $logger = new RecordingLogger(); + + (new ClientBuilder()) + ->apiKey('k') + ->apiSecret('s') + ->logger($logger) + ->logBodies(true) + ->skipEnvLoad() + ->build(); + + $warnings = array_values(array_filter($logger->records, fn ($r) => $r['level'] === 'warning')); + self::assertCount(1, $warnings); + + $initialized = $logger->named('client.initialized'); + self::assertCount(1, $initialized); + self::assertTrue($initialized[0]['context']['stream.client.log_bodies']); + } + + /** @test */ + public function buildingWithoutLoggerProducesNoErrorLogOutput(): void + { + $tmp = tempnam(sys_get_temp_dir(), 'gs-no-log-'); + $previous = ini_set('error_log', $tmp); + + try { + (new ClientBuilder()) + ->apiKey('k') + ->apiSecret('s') + ->skipEnvLoad() + ->build(); + } finally { + ini_set('error_log', $previous === false ? '' : $previous); + } + + self::assertSame('', file_get_contents($tmp), 'no logger injected: construction must produce zero error_log output'); + @unlink($tmp); + } } diff --git a/tests/Http/LoggingTest.php b/tests/Http/LoggingTest.php new file mode 100644 index 0000000..97dfe80 --- /dev/null +++ b/tests/Http/LoggingTest.php @@ -0,0 +1,141 @@ + $stack], 3, null, $logger, $logBodies); + } + + public function testSentAndReceivedOnSuccess(): void + { + $logger = new RecordingLogger(); + $client = $this->client([new Response(200, ['Content-Type' => 'application/json'], '{"ok":true}')], $logger); + $client->request('GET', 'http://localhost/api/v2/app?api_key=key'); + $this->assertCount(1, $logger->named('http.request.sent')); + $received = $logger->named('http.response.received'); + $this->assertCount(1, $received); + $this->assertSame(200, $received[0]['context']['http.response.status_code']); + $this->assertArrayHasKey('duration_ms', $received[0]['context']); + } + + public function testErrorStatusIsReceivedNotFailed(): void + { + $logger = new RecordingLogger(); + $client = $this->client([new Response(500, ['Content-Type' => 'application/json'], '{"code":1,"message":"boom"}')], $logger); + try { + $client->request('GET', 'http://localhost/api/v2/app'); + $this->fail('expected exception'); + } catch (\GetStream\Exceptions\StreamApiException) { + } + $this->assertCount(1, $logger->named('http.response.received')); + $this->assertCount(0, $logger->named('http.request.failed')); + } + + public function testTransportFailureEmitsFailed(): void + { + $logger = new RecordingLogger(); + $client = $this->client([new ConnectException('reset', new Request('GET', 'http://localhost/x'))], $logger); + try { + $client->request('GET', 'http://localhost/x'); + $this->fail('expected exception'); + } catch (\GetStream\Exceptions\StreamTransportException) { + } + $failed = $logger->named('http.request.failed'); + $this->assertCount(1, $failed); + $this->assertSame('error', $failed[0]['level']); + $this->assertArrayHasKey('error.type', $failed[0]['context']); + } + + public function testTransportFailureRedactsSecretFromMessage(): void + { + // Guzzle builds its ConnectException message by appending the full + // request URL (incl. query string); its own redaction only strips + // HTTP Basic userinfo, not query params. This is the mainline shape + // of that message for a DNS/connect/TLS/timeout failure. + $leakyMessage = 'cURL error 7: Failed to connect to 127.0.0.1 port 1 after 0 ms: ' + . 'Couldn\'t connect to server for http://localhost/api/v2/app?api_key=SUPERSECRETKEY&user_id=123'; + $logger = new RecordingLogger(); + $client = $this->client( + [new ConnectException($leakyMessage, new Request('GET', 'http://localhost/api/v2/app?api_key=SUPERSECRETKEY&user_id=123'))], + $logger, + ); + try { + $client->request('GET', 'http://localhost/api/v2/app?api_key=SUPERSECRETKEY&user_id=123'); + $this->fail('expected exception'); + } catch (\GetStream\Exceptions\StreamTransportException) { + } + $failed = $logger->named('http.request.failed'); + $message = $failed[0]['context']['error.message']; + $this->assertStringContainsString('api_key=', $message); + $this->assertStringNotContainsString('SUPERSECRETKEY', $message); + } + + public function testQueryRedaction(): void + { + $logger = new RecordingLogger(); + $client = $this->client([new Response(200, [], '{}')], $logger); + $client->request('GET', 'http://localhost/api/v2/app?api_key=sekret&x=1'); + $sent = $logger->named('http.request.sent')[0]; + $this->assertStringNotContainsString('sekret', $sent['context']['url.query']); + $this->assertStringContainsString('', $sent['context']['url.query']); + } + + public function testLogBodiesOffByDefaultOnWithRedaction(): void + { + $logger = new RecordingLogger(); + $client = $this->client([new Response(200, ['Content-Type' => 'application/json'], '{"token":"tok","keep":"v"}')], $logger); + $client->request('GET', 'http://localhost/x'); + $this->assertArrayNotHasKey('http.response.body', $logger->named('http.response.received')[0]['context']); + + $logger2 = new RecordingLogger(); + $client2 = $this->client([new Response(200, ['Content-Type' => 'application/json'], '{"token":"tok","keep":"v"}')], $logger2, true); + $client2->request('GET', 'http://localhost/x'); + $body = $logger2->named('http.response.received')[0]['context']['http.response.body']; + // Quoted, not bare: the key name "token" itself contains the substring + // "tok", and redaction preserves key names (only values are redacted). + // Bare assertStringNotContainsString('tok', ...) can never pass while + // the "token" key is present; mirrors the quoted-value check below in + // testRedactionHelpers. + $this->assertStringNotContainsString('"tok"', $body); + $this->assertStringContainsString('keep', $body); + } + + public function testRedactionHelpers(): void + { + $this->assertSame('api_key=&x=1', LogRedaction::redactQuery('api_key=sekret&x=1')); + $out = LogRedaction::redactJsonBody('{"api_secret":"s","password":"p","keep":"v"}'); + $this->assertStringNotContainsString('"s"', $out); + $this->assertStringNotContainsString('"p"', $out); + $this->assertStringContainsString('"keep":"v"', $out); + $this->assertSame('not json', LogRedaction::redactJsonBody('not json')); + + $this->assertSame( + 'api_key=&user_id=123', + LogRedaction::redactMessage('api_key=SUPERSECRETKEY&user_id=123'), + ); + $this->assertSame( + 'api_secret= token=', + LogRedaction::redactMessage('api_secret=shh token=tok'), + ); + $this->assertStringContainsString('user_id=123', LogRedaction::redactMessage('user_id=123')); + } +} diff --git a/tests/Http/RecordingLogger.php b/tests/Http/RecordingLogger.php new file mode 100644 index 0000000..7fec5e3 --- /dev/null +++ b/tests/Http/RecordingLogger.php @@ -0,0 +1,31 @@ + */ + public array $records = []; + + public function log($level, \Stringable|string $message, array $context = []): void + { + $this->records[] = ['level' => (string) $level, 'message' => (string) $message, 'context' => $context]; + } + + /** @return list */ + public function named(string $event): array + { + return array_values(array_filter($this->records, fn ($r) => $r['message'] === $event)); + } +} diff --git a/tests/Integration/ConnectionPoolLogTest.php b/tests/Integration/ConnectionPoolLogTest.php index f954377..88f8146 100644 --- a/tests/Integration/ConnectionPoolLogTest.php +++ b/tests/Integration/ConnectionPoolLogTest.php @@ -4,76 +4,73 @@ namespace GetStream\Tests\Integration; +use GetStream\ClientBuilder; use PHPUnit\Framework\TestCase; +use Psr\Log\AbstractLogger; /** * @group integration */ class ConnectionPoolLogTest extends TestCase { - public function testInfoLogContainsAllKnobs(): void + public function testClientInitializedLogContainsAllKnobs(): void { - $tmp = tempnam(sys_get_temp_dir(), 'gs-cp-log-'); - $autoload = realpath(__DIR__ . '/../../vendor/autoload.php'); - $script = <<apiKey('k')->apiSecret('s') - ->maxConnsPerHost(7)->idleTimeout(33)->connectTimeout(2)->requestTimeout(11) - ->skipEnvLoad() - ->build(); -PHP; - $scriptPath = tempnam(sys_get_temp_dir(), 'gs-cp-script-') . '.php'; - file_put_contents($scriptPath, $script); + $logger = new class extends AbstractLogger { + /** @var list */ + public array $records = []; - $cmd = sprintf('php %s %s 2>&1', escapeshellarg($scriptPath), escapeshellarg($tmp)); - exec($cmd, $out, $code); - self::assertSame(0, $code, implode("\n", $out)); + public function log($level, \Stringable|string $message, array $context = []): void + { + $this->records[] = ['level' => (string) $level, 'message' => (string) $message, 'context' => $context]; + } + }; - $log = file_get_contents($tmp); - self::assertStringContainsString('max_conns_per_host=7', $log); - self::assertStringContainsString('idle_timeout=33s', $log); - self::assertStringContainsString('connect_timeout=2s', $log); - self::assertStringContainsString('request_timeout=11s', $log); - self::assertStringContainsString('user_http_client=false', $log); + (new ClientBuilder()) + ->apiKey('k')->apiSecret('s') + ->maxConnsPerHost(7)->idleTimeout(33)->connectTimeout(2)->requestTimeout(11) + ->logger($logger) + ->skipEnvLoad() + ->build(); - @unlink($tmp); - @unlink($scriptPath); + self::assertCount(1, $logger->records); + $event = $logger->records[0]; + self::assertSame('info', $event['level']); + self::assertSame('client.initialized', $event['message']); + self::assertSame(7, $event['context']['stream.client.max_conns_per_host']); + self::assertSame(33, $event['context']['stream.client.idle_timeout_seconds']); + self::assertSame(2, $event['context']['stream.client.connect_timeout_seconds']); + self::assertSame(11, $event['context']['stream.client.request_timeout_seconds']); + self::assertFalse($event['context']['stream.client.user_http_client']); } - public function testInfoLogIndicatesEscapeHatchUsed(): void + public function testClientInitializedLogIndicatesEscapeHatchUsed(): void { - $tmp = tempnam(sys_get_temp_dir(), 'gs-cp-log-'); - $autoload = realpath(__DIR__ . '/../../vendor/autoload.php'); - $script = <<apiKey('k')->apiSecret('s') - ->httpClient(\$mock) - ->skipEnvLoad() - ->build(); -PHP; - $scriptPath = tempnam(sys_get_temp_dir(), 'gs-cp-script-') . '.php'; - file_put_contents($scriptPath, $script); + $logger = new class extends AbstractLogger { + /** @var list */ + public array $records = []; + + public function log($level, \Stringable|string $message, array $context = []): void + { + $this->records[] = ['level' => (string) $level, 'message' => (string) $message, 'context' => $context]; + } + }; - $cmd = sprintf('php %s %s 2>&1', escapeshellarg($scriptPath), escapeshellarg($tmp)); - exec($cmd, $out, $code); - self::assertSame(0, $code, implode("\n", $out)); + $mock = new class implements \GetStream\Http\HttpClientInterface { + public function request(string $method, string $url, array $headers = [], mixed $body = null, array $options = []): \GetStream\StreamResponse + { + return new \GetStream\StreamResponse(200, [], null, ''); + } + }; - $log = file_get_contents($tmp); - self::assertStringContainsString('user_http_client=true', $log); - self::assertStringContainsString('5 knobs not applied', $log); + (new ClientBuilder()) + ->apiKey('k')->apiSecret('s') + ->httpClient($mock) + ->logger($logger) + ->skipEnvLoad() + ->build(); - @unlink($tmp); - @unlink($scriptPath); + self::assertCount(1, $logger->records); + self::assertSame('client.initialized', $logger->records[0]['message']); + self::assertTrue($logger->records[0]['context']['stream.client.user_http_client']); } }