diff --git a/composer.json b/composer.json index 41a1d0532..33428c5fa 100644 --- a/composer.json +++ b/composer.json @@ -14,7 +14,8 @@ "guzzlehttp/guzzle": "^7.4.5", "guzzlehttp/psr7": "^2.4.5", "psr/http-message": "^1.1||^2.0", - "psr/cache": "^2.0||^3.0" + "psr/cache": "^2.0||^3.0", + "psr/log": "^3.0" }, "require-dev": { "guzzlehttp/promises": "^2.0", diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index 18241670e..39107c790 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -24,12 +24,14 @@ use Google\Auth\Credentials\UserRefreshCredentials; use Google\Auth\HttpHandler\HttpClientCache; use Google\Auth\HttpHandler\HttpHandlerFactory; +use Google\Auth\Logging\StdOutLogger; use Google\Auth\Middleware\AuthTokenMiddleware; use Google\Auth\Middleware\ProxyAuthTokenMiddleware; use Google\Auth\Subscriber\AuthTokenSubscriber; use GuzzleHttp\Client; use InvalidArgumentException; use Psr\Cache\CacheItemPoolInterface; +use Psr\Log\LoggerInterface; /** * ApplicationDefaultCredentials obtains the default credentials for @@ -70,6 +72,8 @@ */ class ApplicationDefaultCredentials { + private const SDK_DEBUG_ENV_VAR = 'GOOGLE_SDK_PHP_LOGGING'; + /** * @deprecated * @@ -146,7 +150,8 @@ public static function getMiddleware( * user-defined scopes exist, expressed either as an Array or as a * space-delimited string. * @param string|null $universeDomain Specifies a universe domain to use for the - * calling client library + * calling client library. + * @param null|false|LoggerInterface $logger A PSR3 compliant LoggerInterface. * * @return FetchAuthTokenInterface * @throws DomainException if no implementation can be obtained. @@ -158,7 +163,8 @@ public static function getCredentials( ?CacheItemPoolInterface $cache = null, $quotaProject = null, $defaultScope = null, - ?string $universeDomain = null + ?string $universeDomain = null, + null|false|LoggerInterface $logger = null, ) { $creds = null; $jsonKey = CredentialsLoader::fromEnv() @@ -171,7 +177,7 @@ public static function getCredentials( HttpClientCache::setHttpClient($client); } - $httpHandler = HttpHandlerFactory::build($client); + $httpHandler = HttpHandlerFactory::build($client, $logger); } if (is_null($quotaProject)) { @@ -318,6 +324,36 @@ public static function getIdTokenCredentials( return $creds; } + /** + * Returns a StdOutLogger instance + * + * @internal + * + * @return null|LoggerInterface + */ + public static function getDefaultLogger(): null|LoggerInterface + { + $loggingFlag = getenv(self::SDK_DEBUG_ENV_VAR); + + // Env var is not set + if (empty($loggingFlag)) { + return null; + } + + $loggingFlag = strtolower($loggingFlag); + + // Env Var is not true + if ($loggingFlag !== 'true') { + if ($loggingFlag !== 'false') { + trigger_error('The ' . self::SDK_DEBUG_ENV_VAR . ' is set, but it is set to another value than false or true. Logging is disabled'); + } + + return null; + } + + return new StdOutLogger(); + } + /** * @return string */ diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 53a8865fd..ee2739eca 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -16,23 +16,35 @@ */ namespace Google\Auth\HttpHandler; +use Google\Auth\Logging\LoggingTrait; +use Google\Auth\Logging\RpcLogEvent; use GuzzleHttp\ClientInterface; use Psr\Http\Message\RequestInterface; use Psr\Http\Message\ResponseInterface; +use Psr\Log\LoggerInterface; class Guzzle6HttpHandler { + use LoggingTrait; + /** * @var ClientInterface */ private $client; + /** + * @var null|LoggerInterface + */ + private $logger; + /** * @param ClientInterface $client + * @param null|LoggerInterface $logger */ - public function __construct(ClientInterface $client) + public function __construct(ClientInterface $client, ?LoggerInterface $logger = null) { $this->client = $client; + $this->logger = $logger; } /** @@ -44,7 +56,19 @@ public function __construct(ClientInterface $client) */ public function __invoke(RequestInterface $request, array $options = []) { - return $this->client->send($request, $options); + $requestEvent = null; + + if ($this->logger) { + $requestEvent = $this->requestLog($request, $options); + } + + $response = $this->client->send($request, $options); + + if ($this->logger) { + $this->responseLog($response, $requestEvent); + } + + return $response; } /** @@ -57,6 +81,60 @@ public function __invoke(RequestInterface $request, array $options = []) */ public function async(RequestInterface $request, array $options = []) { - return $this->client->sendAsync($request, $options); + $requestEvent = null; + + if ($this->logger) { + $requestEvent = $this->requestLog($request, $options); + } + + $promise = $this->client->sendAsync($request, $options); + + if ($this->logger) { + $promise->then(function (ResponseInterface $response) use ($requestEvent) { + $this->responseLog($response, $requestEvent); + return $response; + }); + } + + return $promise; + } + + /** + * @internal + * @param RequestInterface $request + * @param array $options + */ + public function requestLog(RequestInterface $request, array $options): RpcLogEvent + { + $requestEvent = new RpcLogEvent(); + + $requestEvent->method = $request->getMethod(); + $requestEvent->url = (string) $request->getUri(); + $requestEvent->headers = $request->getHeaders(); + $requestEvent->payload = $request->getBody()->getContents(); + $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; + $requestEvent->serviceName = $options['serviceName'] ?? null; + $requestEvent->processId = (int) getmypid(); + $requestEvent->requestId = $options['requestId'] ?? crc32((string) spl_object_id($request) . getmypid()); + + $this->logRequest($requestEvent); + + return $requestEvent; + } + + /** + * @internal + */ + public function responseLog(ResponseInterface $response, RpcLogEvent $requestEvent): void + { + $responseEvent = new RpcLogEvent($requestEvent->milliseconds); + + $responseEvent->headers = $response->getHeaders(); + $responseEvent->payload = $response->getBody()->getContents(); + $responseEvent->status = $response->getStatusCode(); + $responseEvent->processId = $requestEvent->processId; + $responseEvent->requestId = $requestEvent->requestId; + + $this->logResponse($responseEvent); } } diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index 3856022a2..7b1bf045d 100644 --- a/src/HttpHandler/HttpHandlerFactory.php +++ b/src/HttpHandler/HttpHandlerFactory.php @@ -16,11 +16,13 @@ */ namespace Google\Auth\HttpHandler; +use Google\Auth\ApplicationDefaultCredentials; use GuzzleHttp\BodySummarizer; use GuzzleHttp\Client; use GuzzleHttp\ClientInterface; use GuzzleHttp\HandlerStack; use GuzzleHttp\Middleware; +use Psr\Log\LoggerInterface; class HttpHandlerFactory { @@ -28,11 +30,14 @@ class HttpHandlerFactory * Builds out a default http handler for the installed version of guzzle. * * @param ClientInterface|null $client + * @param null|false|LoggerInterface $logger * @return Guzzle6HttpHandler|Guzzle7HttpHandler * @throws \Exception */ - public static function build(?ClientInterface $client = null) - { + public static function build( + ?ClientInterface $client = null, + null|false|LoggerInterface $logger = null, + ) { if (is_null($client)) { $stack = null; if (class_exists(BodySummarizer::class)) { @@ -45,6 +50,10 @@ public static function build(?ClientInterface $client = null) $client = new Client(['handler' => $stack]); } + $logger = ($logger === false) + ? null + : $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); + $version = null; if (defined('GuzzleHttp\ClientInterface::MAJOR_VERSION')) { $version = ClientInterface::MAJOR_VERSION; @@ -54,9 +63,9 @@ public static function build(?ClientInterface $client = null) switch ($version) { case 6: - return new Guzzle6HttpHandler($client); + return new Guzzle6HttpHandler($client, $logger); case 7: - return new Guzzle7HttpHandler($client); + return new Guzzle7HttpHandler($client, $logger); default: throw new \Exception('Version not supported'); } diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php new file mode 100644 index 000000000..2441a9bd7 --- /dev/null +++ b/src/Logging/LoggingTrait.php @@ -0,0 +1,137 @@ + $event->timestamp, + 'severity' => strtoupper(LogLevel::DEBUG), + 'processId' => $event->processId ?? null, + 'requestId' => $event->requestId ?? null, + ]; + + $debugEvent = array_filter($debugEvent, fn ($value) => !is_null($value)); + + $jsonPayload = [ + 'request.method' => $event->method, + 'request.url' => $event->url, + 'request.headers' => $event->headers, + 'request.payload' => $this->truncatePayload($event->payload), + 'request.jwt' => $this->getJwtToken($event->headers ?? []), + 'retryAttempt' => $event->retryAttempt + ]; + + // Remove null values + $debugEvent['jsonPayload'] = array_filter($jsonPayload, fn ($value) => !is_null($value)); + + $stringifiedEvent = json_encode($debugEvent, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE); + + // There was an error stringifying the event, return to not break execution + if ($stringifiedEvent === false) { + return; + } + + $this->logger->debug($stringifiedEvent); + } + + /** + * @param RpcLogEvent $event + */ + private function logResponse(RpcLogEvent $event): void + { + $debugEvent = [ + 'timestamp' => $event->timestamp, + 'severity' => strtoupper(LogLevel::DEBUG), + 'processId' => $event->processId ?? null, + 'requestId' => $event->requestId ?? null, + 'jsonPayload' => [ + 'response.status' => $event->status, + 'response.headers' => $event->headers, + 'response.payload' => $this->truncatePayload($event->payload), + 'latencyMillis' => $event->latency, + ] + ]; + + // Remove null values + $debugEvent = array_filter($debugEvent, fn ($value) => !is_null($value)); + $debugEvent['jsonPayload'] = array_filter( + $debugEvent['jsonPayload'], + fn ($value) => !is_null($value) + ); + + $stringifiedEvent = json_encode($debugEvent, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE); + + // There was an error stringifying the event, return to not break execution + if ($stringifiedEvent !== false) { + $this->logger->debug($stringifiedEvent); + } + } + + /** + * @param array $headers + * @return null|array + */ + private function getJwtToken(array $headers): null|array + { + if (empty($headers)) { + return null; + } + + $tokenHeader = $headers['Authorization'] ?? ''; + $token = str_replace('Bearer ', '', $tokenHeader); + + if (substr_count($token, '.') !== 2) { + return null; + } + + [$header, $token, $_] = explode('.', $token); + + return [ + 'header' => base64_decode($header), + 'token' => base64_decode($token) + ]; + } + + /** + * @param null|string $payload + * @return string + */ + private function truncatePayload(null|string $payload): null|string + { + $maxLength = 500; + + if (is_null($payload) || strlen($payload) <= $maxLength) { + return $payload; + } + + return substr($payload, 0, $maxLength) . '...'; + } +} diff --git a/src/Logging/RpcLogEvent.php b/src/Logging/RpcLogEvent.php new file mode 100644 index 000000000..50e89fe2f --- /dev/null +++ b/src/Logging/RpcLogEvent.php @@ -0,0 +1,136 @@ + + */ + public null|array $headers = null; + + /** + * An array representation of JSON for the response or request + * + * @var null|string + */ + public null|string $payload = null; + + /** + * Status code for REST or gRPC methods + * + * @var null|int|string + */ + public null|int|string $status = null; + + /** + * The latency in milliseconds + * + * @var null|int + */ + public null|int $latency = null; + + /** + * The retry attempt number + * + * @var null|int + */ + public null|int $retryAttempt = null; + + /** + * The name of the gRPC method being called + * + * @var null|string + */ + public null|string $rpcName = null; + + /** + * The Service Name of the gRPC + * + * @var null|string $serviceName + */ + public null|string $serviceName = null; + + /** + * The Process ID for tracing logs + * + * @var null|int $processId + */ + public null|int $processId = null; + + /** + * The Request id for tracing logs + * + * @var null|int $requestId; + */ + public null|int $requestId = null; + + /** + * Creates an object with all the fields required for logging + * Passing a string representation of a timestamp calculates the difference between + * these two times and sets the latency field with the result. + * + * @param null|float $startTime (Optional) Parameter to calculate the latency + */ + public function __construct(null|float $startTime = null) + { + $this->timestamp = date(DATE_RFC3339); + + // Takes the micro time and convets it to millis + $this->milliseconds = round(microtime(true) * 1000); + + if ($startTime) { + $this->latency = (int) round($this->milliseconds - $startTime); + } + } +} diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php new file mode 100644 index 000000000..27b1f0eb3 --- /dev/null +++ b/src/Logging/StdOutLogger.php @@ -0,0 +1,85 @@ + + */ + private array $levelMapping = [ + LogLevel::EMERGENCY => 7, + LogLevel::ALERT => 6, + LogLevel::CRITICAL => 5, + LogLevel::ERROR => 4, + LogLevel::WARNING => 3, + LogLevel::NOTICE => 2, + LogLevel::INFO => 1, + LogLevel::DEBUG => 0, + ]; + private int $level; + + /** + * Constructs a basic PSR-3 logger class that logs into StdOut for GCP Logging + * + * @param string $level The level of the logger instance. + */ + public function __construct(string $level = LogLevel::DEBUG) + { + $this->level = $this->getLevelFromName($level); + } + + /** + * {@inheritdoc} + */ + public function log($level, string|Stringable $message, array $context = []): void + { + if ($this->getLevelFromName($level) < $this->level) { + return; + } + + print($message . "\n"); + } + + /** + * @param string $levelName + * @return int + * @throws InvalidArgumentException + */ + private function getLevelFromName(string $levelName): int + { + if (!array_key_exists($levelName, $this->levelMapping)) { + throw new InvalidArgumentException('The level supplied to the Logger is not valid'); + } + + return $this->levelMapping[$levelName]; + } +} diff --git a/tests/ApplicationDefaultCredentialsTest.php b/tests/ApplicationDefaultCredentialsTest.php index 1e8a378ef..cf6b542d5 100644 --- a/tests/ApplicationDefaultCredentialsTest.php +++ b/tests/ApplicationDefaultCredentialsTest.php @@ -28,9 +28,11 @@ use Google\Auth\CredentialSource; use Google\Auth\FetchAuthTokenCache; use Google\Auth\GCECache; +use Google\Auth\Logging\StdOutLogger; use GuzzleHttp\Psr7; use GuzzleHttp\Psr7\Response; use GuzzleHttp\Psr7\Utils; +use PHPUnit\Framework\Error\Notice; use PHPUnit\Framework\TestCase; use Prophecy\PhpUnit\ProphecyTrait; use Psr\Cache\CacheItemPoolInterface; @@ -47,6 +49,7 @@ class ApplicationDefaultCredentialsTest extends TestCase private $targetAudience = 'a target audience'; private $quotaProject = 'a-quota-project'; private $originalServiceAccount; + private const SDK_DEBUG_ENV_VAR = 'GOOGLE_SDK_PHP_LOGGING'; public function testGetCredentialsFailsIfEnvSpecifiesNonExistentFile() { @@ -772,6 +775,40 @@ public function testExternalAccountCredentials(string $jsonFile, string $expecte $this->assertInstanceOf($expectedCredSource, $subjectTokenFetcher); } + public function testGetDefaultLoggerReturnStdOutLoggerIfEnvVarIsPresent() + { + putenv($this::SDK_DEBUG_ENV_VAR . '=true'); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + $this->assertTrue($logger instanceof StdOutLogger); + } + + public function testGetDefaultLoggerReturnsNullIfNotEnvVar() + { + putenv($this::SDK_DEBUG_ENV_VAR . '=false'); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + + $this->assertNull($logger); + + putenv($this::SDK_DEBUG_ENV_VAR . '=0'); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + + $this->assertNull($logger); + + putenv($this::SDK_DEBUG_ENV_VAR . '='); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + + $this->assertNull($logger); + } + + public function testGetDefaultLoggerRaiseAWarningIfMisconfiguredAndReturnsNull() + { + putenv($this::SDK_DEBUG_ENV_VAR . '=invalid'); + $this->expectException(Notice::class); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + + $this->assertNull($logger); + } + public function provideExternalAccountCredentials() { return [ diff --git a/tests/HttpHandler/Guzzle7HttpHandlerTest.php b/tests/HttpHandler/Guzzle7HttpHandlerTest.php index 375f72cbf..07ce63005 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -18,6 +18,11 @@ namespace Google\Auth\Tests\HttpHandler; use Google\Auth\HttpHandler\Guzzle7HttpHandler; +use Google\Auth\Logging\StdOutLogger; +use GuzzleHttp\Promise\Promise; +use GuzzleHttp\Psr7\Request; +use GuzzleHttp\Psr7\Response; +use Prophecy\Argument; /** * @group http-handler @@ -31,4 +36,45 @@ public function setUp(): void $this->client = $this->prophesize('GuzzleHttp\ClientInterface'); $this->handler = new Guzzle7HttpHandler($this->client->reveal()); } + + public function testLoggerGetsCalledIfLoggerIsPassed() + { + $requestPromise = new Promise(function () use (&$requestPromise) { + $response = new Response(200); + $requestPromise->resolve($response); + }); + + $mockLogger = $this->prophesize(StdOutLogger::class); + $mockLogger->debug(Argument::cetera()) + ->shouldBeCalledTimes(2); + + $this->client->sendAsync(Argument::cetera()) + ->willReturn($requestPromise); + + $request = new Request('GET', 'https://domain.tld'); + $options = ['key' => 'value']; + + $handler = new Guzzle7HttpHandler($this->client->reveal(), $mockLogger->reveal()); + $handler->async($request, $options)->wait(); + } + + public function testLoggerDoesNotGetsCalledIfLoggerIsNotPassed() + { + $requestPromise = new Promise(function () use (&$requestPromise) { + $response = new Response(200); + $requestPromise->resolve($response); + }); + + $this->client->sendAsync(Argument::cetera()) + ->willReturn($requestPromise) + ->shouldBeCalledTimes(1); + + $request = new Request('GET', 'https://domain.tld'); + $options = ['key' => 'value']; + + $handler = new Guzzle7HttpHandler($this->client->reveal()); + $handler->async($request, $options)->wait(); + + $this->expectOutputString(''); + } } diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php new file mode 100644 index 000000000..c6058fee7 --- /dev/null +++ b/tests/Logging/LoggingTraitTest.php @@ -0,0 +1,109 @@ +loggerContainer = new class() { + use LoggingTrait { + logRequest as public; + logResponse as public; + } + + private LoggerInterface $logger; + + public function __construct() + { + $this->logger = new StdOutLogger(); + } + }; + } + + public function testLogRequest() + { + $event = $this->getNewLogEvent(); + $this->loggerContainer->logRequest($event); + + $buffer = $this->getActualOutput(); + $jsonParsed = json_decode($buffer, true); + + $this->assertEquals($event->timestamp, $jsonParsed['timestamp']); + $this->assertEquals($event->processId, $jsonParsed['processId']); + $this->assertEquals($event->method, $jsonParsed['jsonPayload']['request.method']); + $this->assertEquals($event->url, $jsonParsed['jsonPayload']['request.url']); + $this->assertEquals($event->headers, $jsonParsed['jsonPayload']['request.headers']); + $this->assertArrayHasKey('request.jwt', $jsonParsed['jsonPayload']); + } + + public function testRequestWithoutJwtShouldNotPrintAJwt() + { + $event = $this->getNewLogEvent(); + $event->headers = ['no jwt' => true]; + $this->loggerContainer->logRequest($event); + + $buffer = $this->getActualOutput(); + $jsonParsed = json_decode($buffer, true); + + $this->assertArrayNotHasKey('request.jwt', $jsonParsed['jsonPayload']); + } + + public function testLogResponse() + { + $event = $this->getNewLogEvent(); + $event->headers = ['Thisis' => 'a header']; + $this->loggerContainer->logResponse($event); + + $buffer = $this->getActualOutput(); + + $parsedDebugEvent = json_decode($buffer, true); + $this->assertEquals($event->processId, $parsedDebugEvent['processId']); + $this->assertEquals($event->requestId, $parsedDebugEvent['requestId']); + $this->assertEquals($event->headers, $parsedDebugEvent['jsonPayload']['response.headers']); + } + + private function getNewLogEvent(): RpcLogEvent + { + $event = new RpcLogEvent(); + $event->processId = 123; + $event->method = 'get'; + $event->url = 'test.com'; + $event->headers = [ + 'header1' => 'test', + 'Authorization' => 'Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxMjM0NTY3ODkwIiwibmFtZSI6IkpvaG4gRG9lIiwiaWF0IjoxNTE2MjM5MDIyfQ.cThIIoDvwdueQB468K5xDc5633seEFoqwxjF_xSJyQQ' + ]; + $event->payload = json_encode(['param' => 'test']); + $event->status = 200; + $event->retryAttempt = 0; + $event->rpcName = 'Rpc NameTest'; + $event->serviceName = 'Service Name'; + $event->requestId = 321; + $event->latency = 555; + + return $event; + } +} diff --git a/tests/Logging/RpcLogEventTest.php b/tests/Logging/RpcLogEventTest.php new file mode 100644 index 000000000..63a948ef4 --- /dev/null +++ b/tests/Logging/RpcLogEventTest.php @@ -0,0 +1,47 @@ +assertNotNull($item->timestamp); + } + + public function testConstructorWithoutParameterHasNoLatency() + { + $item = new RpcLogEvent(); + $this->assertNull($item->latency); + } + + public function testConstructorWithParameterHasLatencySet() + { + // We sustract 1000 ms to simulate a microtime 1000ms in the past + $previousMicrotimeInMillis = (microtime(true) * 1000) - 1000; + $item = new RpcLogEvent($previousMicrotimeInMillis); + $this->assertNotNull($item->latency); + + // Adding a delta to the test due timing on how this executes + $this->assertEqualsWithDelta(1000, $item->latency, 5); + } +} diff --git a/tests/Logging/StdOutLoggerTest.php b/tests/Logging/StdOutLoggerTest.php new file mode 100644 index 000000000..67b54bd92 --- /dev/null +++ b/tests/Logging/StdOutLoggerTest.php @@ -0,0 +1,59 @@ +expectException(InvalidArgumentException::class); + new StdOutLogger('invalid level'); + } + + public function testLoggingOnSameLevelWritesToStdOut() + { + $expectedString = 'test'; + $this->expectOutputString($expectedString . "\n"); + + $logger = new StdOutLogger(LogLevel::DEBUG); + $logger->debug($expectedString); + } + + public function testLoggingOnHigherLeverWritesToStdOut() + { + $expectedString = 'test'; + $this->expectOutputString($expectedString . "\n"); + + $logger = new StdOutLogger(LogLevel::WARNING); + $logger->error($expectedString); + } + + public function testLoggingOnLowerLeverDoesNotWriteToStdOut() + { + $this->expectOutputString(''); + + $logger = new StdOutLogger(LogLevel::WARNING); + $expectedString = 'test'; + $logger->debug($expectedString); + } +}