From 5de2301b891dec50d1351ad38165276e402612e0 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 4 Sep 2024 21:42:11 +0000 Subject: [PATCH 01/51] Add the StdOutLogger and Logging Trait --- composer.json | 3 +- src/Logging/LogEvent.php | 121 +++++++++++++++++++++++++ src/Logging/LoggingTrait.php | 94 ++++++++++++++++++++ src/Logging/StdOutLogger.php | 107 +++++++++++++++++++++++ tests/Logging/LogEventTest.php | 42 +++++++++ tests/Logging/LoggingTraitTest.php | 136 +++++++++++++++++++++++++++++ tests/Logging/StdOutLoggerTest.php | 74 ++++++++++++++++ 7 files changed, 576 insertions(+), 1 deletion(-) create mode 100644 src/Logging/LogEvent.php create mode 100644 src/Logging/LoggingTrait.php create mode 100644 src/Logging/StdOutLogger.php create mode 100644 tests/Logging/LogEventTest.php create mode 100644 tests/Logging/LoggingTraitTest.php create mode 100644 tests/Logging/StdOutLoggerTest.php diff --git a/composer.json b/composer.json index 72673f1f2..2dfb740d7 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/Logging/LogEvent.php b/src/Logging/LogEvent.php new file mode 100644 index 000000000..38697f2c6 --- /dev/null +++ b/src/Logging/LogEvent.php @@ -0,0 +1,121 @@ + + */ + public null|array $headers = null; + + /** + * An array representation of JSON for the response or request + * + * @var null|string|array + */ + public null|string|array $payload = null; + + /** + * Status code for REST or gRPC methods + * + * @var null|int|string + */ + public null|int|string $status = null; + + /** + * The latency in miliseconds + * + * @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; + + /** + * The Client Id for easy trace + * + * @var int $clientId + */ + public int $clientId; + + /** + * The Request id for easy trace + * + * @var in $requestId; + */ + public int $requestId; + + /** + * 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|string $startTime (Optional) Parameter to calculate the latency + */ + public function __construct(null|string $startTime = null) + { + $this->timestamp = date(DATE_RFC3339); + + if ($startTime) { + $this->latency = (int) strtotime($this->timestamp) - strtotime($startTime); + } + } +} diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php new file mode 100644 index 000000000..664726bc8 --- /dev/null +++ b/src/Logging/LoggingTrait.php @@ -0,0 +1,94 @@ + $event->timestamp, + 'severity' => strtoupper(LogLevel::DEBUG), + 'clientId' => $event->clientId, + 'requestId' => $event->requestId, + ]; + + $jsonPayload = [ + 'request.method' => $event->method, + 'request.url' => $event->url, + 'request.headers' => $event->headers, + 'request.payload' => $event->payload, + 'request.jwt' => $this->getJwtToken($event->headers), + 'retryAttempt' => $event->retryAttempt + ]; + + // Filter out the falsey values + $jsonPayload = array_filter($jsonPayload); + $debugEvent['jsonPayload'] = $jsonPayload; + + $this->logger->debug((string) json_encode($debugEvent)); + } + + private function logResponse(LogEvent $event): void + { + $debugEvent = [ + 'timestamp' => $event->timestamp, + 'severity' => strtoupper(LogLevel::DEBUG), + 'clientId' => $event->clientId, + 'requestId' => $event->requestId, + 'jsonPayload' => [ + 'response.headers' => $event->headers, + 'response.payload' => $event->payload, + 'latency' => $event->latency, + ] + ]; + + $this->logger->debug((string) json_encode($debugEvent)); + + $infoEvent = [ + 'timestamp' => $event->timestamp, + 'severity' => LogLevel::INFO, + 'clientId' => $event->clientId, + 'requestId' => $event->requestId, + 'jsonPayload' => [ + 'response.status' => $event->status + ] + ]; + + $this->logger->info((string) json_encode($infoEvent)); + } + + private function getJwtToken(array $headers): null|array + { + $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) + ]; + } +} diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php new file mode 100644 index 000000000..eeae3fec3 --- /dev/null +++ b/src/Logging/StdOutLogger.php @@ -0,0 +1,107 @@ + + */ + 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; + + public function __construct(string $level = LogLevel::DEBUG) + { + $this->level = $this->getLevelMap($level); + } + + public function emergency(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::EMERGENCY, $message); + } + + public function alert(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::ALERT, $message); + } + + public function critical(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::CRITICAL, $message); + } + + public function error(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::ERROR, $message); + } + + public function warning(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::WARNING, $message); + } + + public function notice(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::NOTICE, $message); + } + + public function info(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::INFO, $message); + } + + public function debug(string|Stringable $message, array $context = []): void + { + $this->log(LogLevel::DEBUG, $message); + } + + public function log($level, string|Stringable $message, array $context = []): void + { + if ($this->getLevelMap($level) < $this->level) { + return; + } + + print($message . "\n"); + } + + private function getLevelMap(string $levelName): int + { + if (!array_key_exists($levelName, $this->levelMapping)) { + throw new Exception('The level supplied to the Logger is not valid'); + } + + return $this->levelMapping[$levelName]; + } +} diff --git a/tests/Logging/LogEventTest.php b/tests/Logging/LogEventTest.php new file mode 100644 index 000000000..5b29b7eb0 --- /dev/null +++ b/tests/Logging/LogEventTest.php @@ -0,0 +1,42 @@ +assertNotNull($item->timestamp); + } + + public function testConstructorWithoutParameterHasNoLatency() + { + $item = new LogEvent(); + $this->assertNull($item->latency); + } + + public function testConstructorWithParameterHasLatencySet() + { + $item = new LogEvent(date(DATE_RFC3339)); + $this->assertNotNull($item->latency); + } +} diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php new file mode 100644 index 000000000..f162b4760 --- /dev/null +++ b/tests/Logging/LoggingTraitTest.php @@ -0,0 +1,136 @@ +loggerContainer = new MockClassWithLogger(); + } + + public function testLogRequest() + { + ob_start(); + + $event = $this->getNewLogEvent(); + $this->loggerContainer->logRequestEvent($event); + + $buffer = ob_get_contents(); + ob_end_clean(); + $jsonParsed = json_decode($buffer, true); + + $this->assertEquals($event->timestamp, $jsonParsed['timestamp']); + $this->assertEquals($event->clientId, $jsonParsed['clientId']); + $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() + { + ob_start(); + + $event = $this->getNewLogEvent(); + $event->headers = ['no jwt' => true]; + $this->loggerContainer->logRequestEvent($event); + + $buffer = ob_get_contents(); + ob_end_clean(); + $jsonParsed = json_decode($buffer, true); + + $this->assertArrayNotHasKey('request.jwt', $jsonParsed['jsonPayload']); + } + + public function testLogResponse() + { + ob_start(); + + $event = $this->getNewLogEvent(); + $this->loggerContainer->logResponseEvent($event); + + $buffer = ob_get_contents(); + ob_end_clean(); + + $buffer = str_replace("\n", '', $buffer); + + // The LogResponse method logs two evnets, one for info and one for debug. + [$debugEvent, $infoEvent] = explode('}{', $buffer); + $debugEvent .= '}'; + $infoEvent = '{' . $infoEvent; + + $parsedDebugEvent = json_decode($debugEvent, true); + $this->assertEquals($event->clientId, $parsedDebugEvent['clientId']); + $this->assertEquals($event->requestId, $parsedDebugEvent['requestId']); + $this->assertEquals($event->headers, $parsedDebugEvent['jsonPayload']['response.headers']); + + $parsedInfoEvent = json_decode($infoEvent, true); + $this->assertEquals($event->status, $parsedInfoEvent['jsonPayload']['response.status']); + } + + private function getNewLogEvent(): LogEvent + { + $event = new LogEvent(); + $event->clientId = 123; + $event->method = 'get'; + $event->url = 'test.com'; + $event->headers = [ + 'header1' => 'test', + 'Authorization' => 'Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxMjM0NTY3ODkwIiwibmFtZSI6IkpvaG4gRG9lIiwiaWF0IjoxNTE2MjM5MDIyfQ.cThIIoDvwdueQB468K5xDc5633seEFoqwxjF_xSJyQQ' + ]; + $event->payload = ['param' => 'test']; + $event->status = 200; + $event->retryAttempt = 0; + $event->rpcName = 'Rpc NameTest'; + $event->serviceName = 'Service Name'; + $event->requestId = 321; + $event->latency = 555; + + return $event; + } +} + +class MockClassWithLogger +{ + use LoggingTrait; + private LoggerInterface $logger; + + public function __construct() + { + $this->logger = new StdOutLogger(); + } + + public function logRequestEvent(LogEvent $event): void + { + $this->logRequest($event); + } + + public function logResponseEvent(LogEvent $event): void + { + $this->logResponse($event); + } +} diff --git a/tests/Logging/StdOutLoggerTest.php b/tests/Logging/StdOutLoggerTest.php new file mode 100644 index 000000000..a58cecad2 --- /dev/null +++ b/tests/Logging/StdOutLoggerTest.php @@ -0,0 +1,74 @@ +expectException(Exception::class); + new StdOutLogger('invalid level'); + } + + public function testLoggingOnSameLevelWritesToStdOut() + { + ob_start(); + + $logger = new StdOutLogger(LogLevel::DEBUG); + $expectedString = 'test'; + $logger->debug($expectedString); + $buffer = ob_get_contents(); + + $this->assertEquals($expectedString . "\n", $buffer); + + ob_end_clean(); + } + + public function testLoggingOnHigherLeverWritesToStdOut() + { + ob_start(); + + $logger = new StdOutLogger(LogLevel::WARNING); + $expectedString = 'test'; + $logger->error($expectedString); + $buffer = ob_get_contents(); + + $this->assertEquals($expectedString . "\n", $buffer); + + ob_end_clean(); + } + + public function testLoggingOnLowerLeverDoesNotWriteToStdOut() + { + ob_start(); + + $logger = new StdOutLogger(LogLevel::WARNING); + $expectedString = 'test'; + $logger->debug($expectedString); + $buffer = ob_get_contents(); + + $this->assertEmpty($buffer); + + ob_end_clean(); + } +} From f3931577a3e3d6b0c6fca0d2b16d2c9b934ff135 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 4 Sep 2024 21:55:05 +0000 Subject: [PATCH 02/51] Fix types and style --- src/Logging/LogEvent.php | 4 ++-- src/Logging/StdOutLogger.php | 5 +++++ 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/src/Logging/LogEvent.php b/src/Logging/LogEvent.php index 38697f2c6..e34da0616 100644 --- a/src/Logging/LogEvent.php +++ b/src/Logging/LogEvent.php @@ -50,7 +50,7 @@ class LogEvent /** * An array representation of JSON for the response or request * - * @var null|string|array + * @var null|string|array */ public null|string|array $payload = null; @@ -99,7 +99,7 @@ class LogEvent /** * The Request id for easy trace * - * @var in $requestId; + * @var int $requestId; */ public int $requestId; diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php index eeae3fec3..224c9388e 100644 --- a/src/Logging/StdOutLogger.php +++ b/src/Logging/StdOutLogger.php @@ -42,6 +42,11 @@ class StdOutLogger implements LoggerInterface ]; 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->getLevelMap($level); From e5540f64cf17049446ec1d1f68d2356f2c08f259 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Thu, 5 Sep 2024 21:49:24 +0000 Subject: [PATCH 03/51] fix typing for PSR-3 logger interface --- src/Logging/StdOutLogger.php | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php index 224c9388e..df5b90417 100644 --- a/src/Logging/StdOutLogger.php +++ b/src/Logging/StdOutLogger.php @@ -92,6 +92,11 @@ public function debug(string|Stringable $message, array $context = []): void $this->log(LogLevel::DEBUG, $message); } + /** + * @param string $level + * @param string|Stringable $message + * @param array $context + */ public function log($level, string|Stringable $message, array $context = []): void { if ($this->getLevelMap($level) < $this->level) { From ff21a95cd6fcc21f335ec984f934a8ecf85f3c6b Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 9 Sep 2024 20:02:41 +0000 Subject: [PATCH 04/51] Add logging to the Guzzle6HttpHandler --- src/ApplicationDefaultCredentials.php | 26 ++++++++++ src/HttpHandler/Guzzle6HttpHandler.php | 50 +++++++++++++++++- src/HttpHandler/HttpHandlerFactory.php | 10 ++-- tests/ApplicationDefaultCredentialsTest.php | 36 +++++++++++++ tests/HttpHandler/Guzzle7HttpHandlerTest.php | 53 ++++++++++++++++++++ 5 files changed, 170 insertions(+), 5 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index 18241670e..04a8418de 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -24,12 +24,15 @@ 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 PHPUnit\TextUI\XmlConfiguration\Logging\Logging; use Psr\Cache\CacheItemPoolInterface; +use Psr\Log\LoggerInterface; /** * ApplicationDefaultCredentials obtains the default credentials for @@ -70,6 +73,8 @@ */ class ApplicationDefaultCredentials { + private const SDK_DEBUG_FLAG = 'GOOGLE_SDK_DEBUG_LOGGING'; + /** * @deprecated * @@ -318,6 +323,27 @@ public static function getIdTokenCredentials( return $creds; } + /** + * Returns a StdOutLogger instance + */ + public static function getDefaultLogger(): null|LoggerInterface + { + $loggingFlag = getenv(self::SDK_DEBUG_FLAG); + if ($loggingFlag instanceof string) { + $loggingFlag = strtolower($loggingFlag); + } + + if ($loggingFlag === false || $loggingFlag !== 'true' && $loggingFlag !== '1') { + if (strtolower($loggingFlag) !== 'false' && strtolower($loggingFlag) !== '0') { + trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false, true or 0. Logging is disabled'); + } + + return null; + } + + return new StdOutLogger(); + } + /** * @return string */ diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 53a8865fd..2c35325ab 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -16,23 +16,34 @@ */ namespace Google\Auth\HttpHandler; +use Google\Auth\Logging\LogEvent; +use Google\Auth\Logging\LoggingTrait; 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 LoggerInterface + */ + private $logger; + /** * @param ClientInterface $client */ - public function __construct(ClientInterface $client) + public function __construct(ClientInterface $client, LoggerInterface $logger = null) { $this->client = $client; + $this->logger = $logger; } /** @@ -57,6 +68,41 @@ 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 = new LogEvent(); + + $requestEvent->method = $request->getMethod(); + $requestEvent->url = $request->getUri()->__toString(); + $requestEvent->headers = $request->getHeaders(); + $requestEvent->payload = $request->getBody()->getContents(); + $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; + $requestEvent->serviceName = $options['serviceName'] ?? null; + $requestEvent->clientId = spl_object_id($this->client); + $requestEvent->requestId = spl_object_id($request); + + $this->logRequest($requestEvent); + } + + $promise = $this->client->sendAsync($request, $options); + + if ($this->logger) { + $promise->then(function (ResponseInterface $response) use ($requestEvent) { + $responseEvent = new LogEvent($requestEvent->timestamp); + + $responseEvent->headers = $response->getHeaders(); + $responseEvent->payload = $response->getBody()->getContents(); + $responseEvent->status = $response->getStatusCode(); + $responseEvent->clientId = $requestEvent->clientId; + $responseEvent->requestId = $requestEvent->requestId; + + $this->logResponse($responseEvent); + + return $response; + }); + } + + return $promise; } } diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index 3856022a2..e8080304b 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 { @@ -31,7 +33,7 @@ class HttpHandlerFactory * @return Guzzle6HttpHandler|Guzzle7HttpHandler * @throws \Exception */ - public static function build(?ClientInterface $client = null) + public static function build(?ClientInterface $client = null, LoggerInterface $logger = null) { if (is_null($client)) { $stack = null; @@ -45,6 +47,8 @@ public static function build(?ClientInterface $client = null) $client = new Client(['handler' => $stack]); } + $logger = $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); + $version = null; if (defined('GuzzleHttp\ClientInterface::MAJOR_VERSION')) { $version = ClientInterface::MAJOR_VERSION; @@ -54,9 +58,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/tests/ApplicationDefaultCredentialsTest.php b/tests/ApplicationDefaultCredentialsTest.php index 1e8a378ef..1bcca47b1 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_FLAG = 'GOOGLE_SDK_DEBUG_LOGGING'; public function testGetCredentialsFailsIfEnvSpecifiesNonExistentFile() { @@ -772,6 +775,39 @@ public function testExternalAccountCredentials(string $jsonFile, string $expecte $this->assertInstanceOf($expectedCredSource, $subjectTokenFetcher); } + public function testGetDefaultLoggerReturnStdOutLoggerIfEnvVarIsPresent() + { + putenv($this::SDK_DEBUG_FLAG . '=true'); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + $this->assertTrue($logger instanceof StdOutLogger); + + putenv($this::SDK_DEBUG_FLAG . '=1'); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + $this->assertTrue($logger instanceof StdOutLogger); + } + + public function testGetDefaultLoggerReturnsNullIfNotEnvVar() + { + putenv($this::SDK_DEBUG_FLAG . '=false'); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + + $this->assertNull($logger); + + putenv($this::SDK_DEBUG_FLAG . '=0'); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + + $this->assertNull($logger); + } + + public function testGetDefaultLoggerRaiseAWarningIfMisconfiguredAndReturnsNull() + { + putenv($this::SDK_DEBUG_FLAG . '=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..3d1204929 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -18,6 +18,14 @@ namespace Google\Auth\Tests\HttpHandler; use Google\Auth\HttpHandler\Guzzle7HttpHandler; +use Google\Auth\Logging\StdOutLogger; +use GuzzleHttp\ClientInterface; +use GuzzleHttp\Promise\Promise; +use GuzzleHttp\Psr7\Request; +use GuzzleHttp\Psr7\Response; +use Prophecy\Argument; +use Prophecy\Promise\ReturnPromise; +use Psr\Log\LoggerInterface; /** * @group http-handler @@ -31,4 +39,49 @@ 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); + $mockLogger->info(Argument::cetera()) + ->shouldBeCalledTimes(1); + + $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']; + + /** + * @var LoggerInterface $mockLogger + * @var ClientInterface $mockClient + */ + $handler = new Guzzle7HttpHandler($this->client->reveal()); + $handler->async($request, $options)->wait(); + } } From 0c65a32c2cf55ab432d8af2b63f57271e8e5175c Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 9 Sep 2024 21:40:16 +0000 Subject: [PATCH 05/51] Change logic for getDefaultLogger --- src/ApplicationDefaultCredentials.php | 22 +++++++++++++++----- tests/HttpHandler/Guzzle7HttpHandlerTest.php | 1 - 2 files changed, 17 insertions(+), 6 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index 04a8418de..35c66044c 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -329,18 +329,30 @@ public static function getIdTokenCredentials( public static function getDefaultLogger(): null|LoggerInterface { $loggingFlag = getenv(self::SDK_DEBUG_FLAG); - if ($loggingFlag instanceof string) { - $loggingFlag = strtolower($loggingFlag); + + // Env var is not set + if (!is_string($loggingFlag)) { + if (is_array($loggingFlag)) { + trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false, true, 0 or 1. Logging is disabled'); + return null; + } + + return null; } - if ($loggingFlag === false || $loggingFlag !== 'true' && $loggingFlag !== '1') { - if (strtolower($loggingFlag) !== 'false' && strtolower($loggingFlag) !== '0') { - trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false, true or 0. Logging is disabled'); + $loggingFlag = strtolower($loggingFlag); + + // Env Var is not true + if ($loggingFlag !== 'true' && $loggingFlag !== '1') { + // Env var is set to a non valid value + if ($loggingFlag !== 'false' && $loggingFlag !== '0') { + trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false, true, 0 or 1. Logging is disabled'); } return null; } + return new StdOutLogger(); } diff --git a/tests/HttpHandler/Guzzle7HttpHandlerTest.php b/tests/HttpHandler/Guzzle7HttpHandlerTest.php index 3d1204929..221b4d39e 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -24,7 +24,6 @@ use GuzzleHttp\Psr7\Request; use GuzzleHttp\Psr7\Response; use Prophecy\Argument; -use Prophecy\Promise\ReturnPromise; use Psr\Log\LoggerInterface; /** From 8c7c1018615e8a98595e0b2183a9657499418e96 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 9 Sep 2024 21:56:15 +0000 Subject: [PATCH 06/51] Fix style issues --- src/ApplicationDefaultCredentials.php | 1 - tests/HttpHandler/Guzzle7HttpHandlerTest.php | 2 +- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index 35c66044c..0de49019b 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -352,7 +352,6 @@ public static function getDefaultLogger(): null|LoggerInterface return null; } - return new StdOutLogger(); } diff --git a/tests/HttpHandler/Guzzle7HttpHandlerTest.php b/tests/HttpHandler/Guzzle7HttpHandlerTest.php index 221b4d39e..732583be3 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -64,7 +64,7 @@ public function testLoggerGetsCalledIfLoggerIsPassed() public function testLoggerDoesNotGetsCalledIfLoggerIsNotPassed() { - $requestPromise = new Promise(function() use (&$requestPromise) { + $requestPromise = new Promise(function () use (&$requestPromise) { $response = new Response(200); $requestPromise->resolve($response); }); From 301d28e52effaa236426f544fd593a04c639d606 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 9 Sep 2024 21:58:57 +0000 Subject: [PATCH 07/51] Fix phpstan typing for getJwtToken --- src/Logging/LoggingTrait.php | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 664726bc8..248be9451 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -75,6 +75,9 @@ private function logResponse(LogEvent $event): void $this->logger->info((string) json_encode($infoEvent)); } + /** + * @param array $headers + */ private function getJwtToken(array $headers): null|array { $tokenHeader = $headers['Authorization'] ?? ''; From 5ae7c1ead8e1c999d39f35ebeed529716955c6ee Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Fri, 13 Sep 2024 21:06:54 +0000 Subject: [PATCH 08/51] Add a flag for disabling logger --- src/HttpHandler/HttpHandlerFactory.php | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index e8080304b..6d5d1385f 100644 --- a/src/HttpHandler/HttpHandlerFactory.php +++ b/src/HttpHandler/HttpHandlerFactory.php @@ -30,10 +30,15 @@ class HttpHandlerFactory * Builds out a default http handler for the installed version of guzzle. * * @param ClientInterface|null $client + * @param LoggerInterface $logger + * @param bool $loggerDisabled * @return Guzzle6HttpHandler|Guzzle7HttpHandler * @throws \Exception */ - public static function build(?ClientInterface $client = null, LoggerInterface $logger = null) + public static function build( + ?ClientInterface $client = null, + LoggerInterface $logger = null, + bool $loggerDisabled = false) { if (is_null($client)) { $stack = null; @@ -47,7 +52,9 @@ public static function build(?ClientInterface $client = null, LoggerInterface $l $client = new Client(['handler' => $stack]); } - $logger = $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); + if (!$loggerDisabled) { + $logger = $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); + } $version = null; if (defined('GuzzleHttp\ClientInterface::MAJOR_VERSION')) { From 7aa7ee2f004e8c0856c4da8f2ef0064d3b7273ac Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 16 Sep 2024 19:31:19 +0000 Subject: [PATCH 09/51] Add logging to the invoke method for apiary support --- src/HttpHandler/Guzzle6HttpHandler.php | 33 +++++++++++++++++++++++++- 1 file changed, 32 insertions(+), 1 deletion(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 2c35325ab..62fb96781 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -55,7 +55,38 @@ public function __construct(ClientInterface $client, LoggerInterface $logger = n */ public function __invoke(RequestInterface $request, array $options = []) { - return $this->client->send($request, $options); + $requestEvent = null; + + if ($this->logger) { + $requestEvent = new LogEvent(); + + $requestEvent->method = $request->getMethod(); + $requestEvent->url = $request->getUri()->__toString(); + $requestEvent->headers = $request->getHeaders(); + $requestEvent->payload = $request->getBody()->getContents(); + $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; + $requestEvent->serviceName = $options['serviceName'] ?? null; + $requestEvent->clientId = spl_object_id($this->client); + $requestEvent->requestId = spl_object_id($request); + + $this->logRequest($requestEvent); + } + + $response = $this->client->send($request, $options); + + if ($this->logger) { + $responseEvent = new LogEvent($requestEvent->timestamp); + + $responseEvent->headers = $response->getHeaders(); + $responseEvent->payload = $response->getBody()->getContents(); + $responseEvent->status = $response->getStatusCode(); + $responseEvent->clientId = $requestEvent->clientId; + $responseEvent->requestId = $requestEvent->requestId; + + $this->logResponse($responseEvent); + } + + return $response; } /** From 331e97cd1dc7ee6dd7c46e7086bdfbc04169ec27 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 16 Sep 2024 20:00:56 +0000 Subject: [PATCH 10/51] Fix style issue on build method --- src/HttpHandler/HttpHandlerFactory.php | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index 6d5d1385f..5a9583f16 100644 --- a/src/HttpHandler/HttpHandlerFactory.php +++ b/src/HttpHandler/HttpHandlerFactory.php @@ -38,7 +38,8 @@ class HttpHandlerFactory public static function build( ?ClientInterface $client = null, LoggerInterface $logger = null, - bool $loggerDisabled = false) + bool $loggerDisabled = false + ) { if (is_null($client)) { $stack = null; From 35f8dde54f6f89ecf7b36a4eb0c82f48e5fbc96a Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Fri, 20 Sep 2024 18:21:00 +0000 Subject: [PATCH 11/51] Change logic for disabling logging --- src/HttpHandler/HttpHandlerFactory.php | 8 +++----- src/Logging/LoggingTrait.php | 18 +++++++++++------- 2 files changed, 14 insertions(+), 12 deletions(-) diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index 5a9583f16..d51380df9 100644 --- a/src/HttpHandler/HttpHandlerFactory.php +++ b/src/HttpHandler/HttpHandlerFactory.php @@ -30,15 +30,13 @@ class HttpHandlerFactory * Builds out a default http handler for the installed version of guzzle. * * @param ClientInterface|null $client - * @param LoggerInterface $logger - * @param bool $loggerDisabled + * @param null|false|LoggerInterface $logger * @return Guzzle6HttpHandler|Guzzle7HttpHandler * @throws \Exception */ public static function build( ?ClientInterface $client = null, - LoggerInterface $logger = null, - bool $loggerDisabled = false + null|false|LoggerInterface $logger = null, ) { if (is_null($client)) { @@ -53,7 +51,7 @@ public static function build( $client = new Client(['handler' => $stack]); } - if (!$loggerDisabled) { + if ($logger !== false) { $logger = $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); } diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 248be9451..a7e9bfbf6 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -27,7 +27,7 @@ private function logRequest(LogEvent $event): void 'timestamp' => $event->timestamp, 'severity' => strtoupper(LogLevel::DEBUG), 'clientId' => $event->clientId, - 'requestId' => $event->requestId, + 'requestId' => $event->requestId ?? null, ]; $jsonPayload = [ @@ -35,13 +35,11 @@ private function logRequest(LogEvent $event): void 'request.url' => $event->url, 'request.headers' => $event->headers, 'request.payload' => $event->payload, - 'request.jwt' => $this->getJwtToken($event->headers), + 'request.jwt' => $this->getJwtToken($event->headers ?? []), 'retryAttempt' => $event->retryAttempt ]; - // Filter out the falsey values - $jsonPayload = array_filter($jsonPayload); - $debugEvent['jsonPayload'] = $jsonPayload; + $debugEvent['jsonPayload'] = array_filter($jsonPayload); $this->logger->debug((string) json_encode($debugEvent)); } @@ -52,7 +50,7 @@ private function logResponse(LogEvent $event): void 'timestamp' => $event->timestamp, 'severity' => strtoupper(LogLevel::DEBUG), 'clientId' => $event->clientId, - 'requestId' => $event->requestId, + 'requestId' => $event->requestId ?? null, 'jsonPayload' => [ 'response.headers' => $event->headers, 'response.payload' => $event->payload, @@ -60,18 +58,20 @@ private function logResponse(LogEvent $event): void ] ]; + $debugEvent['jsonPayload'] = array_filter($debugEvent['jsonPayload']); $this->logger->debug((string) json_encode($debugEvent)); $infoEvent = [ 'timestamp' => $event->timestamp, 'severity' => LogLevel::INFO, 'clientId' => $event->clientId, - 'requestId' => $event->requestId, + 'requestId' => $event->requestId ?? null, 'jsonPayload' => [ 'response.status' => $event->status ] ]; + $infoEvent['jsonPayload'] = array_filter($infoEvent['jsonPayload']); $this->logger->info((string) json_encode($infoEvent)); } @@ -80,6 +80,10 @@ private function logResponse(LogEvent $event): void */ private function getJwtToken(array $headers): null|array { + if (empty($headers)) { + return null; + } + $tokenHeader = $headers['Authorization'] ?? ''; $token = str_replace('Bearer ', '', $tokenHeader); From 36fd1ac0e64b4ad98b996dba2b931ff728c2cd1e Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Fri, 20 Sep 2024 18:30:06 +0000 Subject: [PATCH 12/51] Fix logic for disabling logging --- src/HttpHandler/Guzzle6HttpHandler.php | 2 +- src/HttpHandler/HttpHandlerFactory.php | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 62fb96781..58d415aee 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -33,7 +33,7 @@ class Guzzle6HttpHandler private $client; /** - * @var LoggerInterface + * @var null|LoggerInterface */ private $logger; diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index d51380df9..32d3e460a 100644 --- a/src/HttpHandler/HttpHandlerFactory.php +++ b/src/HttpHandler/HttpHandlerFactory.php @@ -51,7 +51,9 @@ public static function build( $client = new Client(['handler' => $stack]); } - if ($logger !== false) { + if ($logger === false) { + $logger = null; + } else { $logger = $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); } From 2ff7d1aafa722d240a3bf3a9296f574c7c70c9df Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 25 Sep 2024 20:50:57 +0000 Subject: [PATCH 13/51] Add a function to log a gRPC status only --- src/Logging/LogEvent.php | 10 +++--- src/Logging/LoggingTrait.php | 60 ++++++++++++++++++++++++++++++++++-- 2 files changed, 62 insertions(+), 8 deletions(-) diff --git a/src/Logging/LogEvent.php b/src/Logging/LogEvent.php index e34da0616..3007ce2e4 100644 --- a/src/Logging/LogEvent.php +++ b/src/Logging/LogEvent.php @@ -87,21 +87,21 @@ class LogEvent * * @var null|string $serviceName */ - public null|string $serviceName; + public null|string $serviceName = null; /** * The Client Id for easy trace * - * @var int $clientId + * @var null|int $clientId */ - public int $clientId; + public null|int $clientId = null; /** * The Request id for easy trace * - * @var int $requestId; + * @var null|int $requestId; */ - public int $requestId; + public null|int $requestId = null; /** * Creates an object with all the fields required for logging diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index a7e9bfbf6..14d6a3227 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -30,6 +30,8 @@ private function logRequest(LogEvent $event): void 'requestId' => $event->requestId ?? null, ]; + $debugEvent = array_filter($debugEvent, fn($value) => !is_null($value)); + $jsonPayload = [ 'request.method' => $event->method, 'request.url' => $event->url, @@ -39,7 +41,7 @@ private function logRequest(LogEvent $event): void 'retryAttempt' => $event->retryAttempt ]; - $debugEvent['jsonPayload'] = array_filter($jsonPayload); + $debugEvent['jsonPayload'] = array_filter($jsonPayload, fn($value) => !is_null($value)); $this->logger->debug((string) json_encode($debugEvent)); } @@ -58,7 +60,11 @@ private function logResponse(LogEvent $event): void ] ]; - $debugEvent['jsonPayload'] = array_filter($debugEvent['jsonPayload']); + $debugEvent = array_filter($debugEvent, fn($value) => !is_null($value)); + $debugEvent['jsonPayload'] = array_filter( + $debugEvent['jsonPayload'], + fn($value) => !is_null($value) + ); $this->logger->debug((string) json_encode($debugEvent)); $infoEvent = [ @@ -71,7 +77,36 @@ private function logResponse(LogEvent $event): void ] ]; - $infoEvent['jsonPayload'] = array_filter($infoEvent['jsonPayload']); + $infoEvent = array_filter($infoEvent, fn($value) => !is_null($value)); + $infoEvent['jsonPayload'] = array_filter( + $infoEvent['jsonPayload'], + fn($value) => !is_null($value) + ); + + $this->logger->info((string) json_encode($infoEvent)); + } + + /** + * @param LogEvent $status + */ + private function logStatus(LogEvent $event): void + { + $infoEvent = [ + 'timestamp' => $event->timestamp, + 'severity' => LogLevel::INFO, + 'clientId' => $event->clientId, + 'requestId' => $event->requestId ?? null, + 'jsonPayload' => [ + 'response.status' => $event->status + ] + ]; + + $infoEvent = array_filter($infoEvent, fn($value) => !is_null($value)); + $infoEvent['jsonPayload'] = array_filter( + $infoEvent['jsonPayload'], + fn($value) => !is_null($value) + ); + $this->logger->info((string) json_encode($infoEvent)); } @@ -98,4 +133,23 @@ private function getJwtToken(array $headers): null|array 'token' => base64_decode($token) ]; } + + /** + * @param array $arr + * @return array + */ + private function removeNullsFromLog(array $arr): array + { + $result = []; + + foreach ($arr as $key => $value) { + if (is_null($value)) { + continue; + } + + if (is_array($value)) { + + } + } + } } From dbfb61c78edbd1ab81b2e985d0edd4e0caf1708b Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 25 Sep 2024 20:51:39 +0000 Subject: [PATCH 14/51] Removed unused method --- src/Logging/LoggingTrait.php | 19 ------------------- 1 file changed, 19 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 14d6a3227..8760a0ac3 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -133,23 +133,4 @@ private function getJwtToken(array $headers): null|array 'token' => base64_decode($token) ]; } - - /** - * @param array $arr - * @return array - */ - private function removeNullsFromLog(array $arr): array - { - $result = []; - - foreach ($arr as $key => $value) { - if (is_null($value)) { - continue; - } - - if (is_array($value)) { - - } - } - } } From 2f8763625435553ed06b82c8b2cafbc13d818f26 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 25 Sep 2024 21:45:06 +0000 Subject: [PATCH 15/51] Fix style for LoggingTrait --- src/Logging/LoggingTrait.php | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 8760a0ac3..f041aaf42 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -30,7 +30,7 @@ private function logRequest(LogEvent $event): void 'requestId' => $event->requestId ?? null, ]; - $debugEvent = array_filter($debugEvent, fn($value) => !is_null($value)); + $debugEvent = array_filter($debugEvent, fn ($value) => !is_null($value)); $jsonPayload = [ 'request.method' => $event->method, @@ -41,7 +41,7 @@ private function logRequest(LogEvent $event): void 'retryAttempt' => $event->retryAttempt ]; - $debugEvent['jsonPayload'] = array_filter($jsonPayload, fn($value) => !is_null($value)); + $debugEvent['jsonPayload'] = array_filter($jsonPayload, fn ($value) => !is_null($value)); $this->logger->debug((string) json_encode($debugEvent)); } @@ -60,10 +60,10 @@ private function logResponse(LogEvent $event): void ] ]; - $debugEvent = array_filter($debugEvent, fn($value) => !is_null($value)); + $debugEvent = array_filter($debugEvent, fn ($value) => !is_null($value)); $debugEvent['jsonPayload'] = array_filter( $debugEvent['jsonPayload'], - fn($value) => !is_null($value) + fn ($value) => !is_null($value) ); $this->logger->debug((string) json_encode($debugEvent)); @@ -77,10 +77,10 @@ private function logResponse(LogEvent $event): void ] ]; - $infoEvent = array_filter($infoEvent, fn($value) => !is_null($value)); + $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); $infoEvent['jsonPayload'] = array_filter( $infoEvent['jsonPayload'], - fn($value) => !is_null($value) + fn ($value) => !is_null($value) ); $this->logger->info((string) json_encode($infoEvent)); @@ -101,10 +101,10 @@ private function logStatus(LogEvent $event): void ] ]; - $infoEvent = array_filter($infoEvent, fn($value) => !is_null($value)); + $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); $infoEvent['jsonPayload'] = array_filter( $infoEvent['jsonPayload'], - fn($value) => !is_null($value) + fn ($value) => !is_null($value) ); $this->logger->info((string) json_encode($infoEvent)); From 0cb0c27b3bb052d8a65d7198d56279b2e47e06a8 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 25 Sep 2024 21:49:47 +0000 Subject: [PATCH 16/51] Fix typing --- src/Logging/LoggingTrait.php | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index f041aaf42..d6d96a97e 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -87,7 +87,7 @@ private function logResponse(LogEvent $event): void } /** - * @param LogEvent $status + * @param LogEvent $event */ private function logStatus(LogEvent $event): void { @@ -112,6 +112,7 @@ private function logStatus(LogEvent $event): void /** * @param array $headers + * @return null|array */ private function getJwtToken(array $headers): null|array { From 8e4a7e5c7e67f67b8886c30420659e536d464e72 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 25 Sep 2024 22:00:26 +0000 Subject: [PATCH 17/51] Updated type annotations --- src/ApplicationDefaultCredentials.php | 2 ++ src/HttpHandler/Guzzle6HttpHandler.php | 1 + src/Logging/LoggingTrait.php | 6 +++++ src/Logging/StdOutLogger.php | 37 ++++++++++++++++++++++---- tests/Logging/StdOutLoggerTest.php | 4 +-- 5 files changed, 43 insertions(+), 7 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index 0de49019b..a74fe4921 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -325,6 +325,8 @@ public static function getIdTokenCredentials( /** * Returns a StdOutLogger instance + * + * @return null|LoggerInterface */ public static function getDefaultLogger(): null|LoggerInterface { diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 58d415aee..644d94b08 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -39,6 +39,7 @@ class Guzzle6HttpHandler /** * @param ClientInterface $client + * @param null|LoggerInterface $logger */ public function __construct(ClientInterface $client, LoggerInterface $logger = null) { diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index d6d96a97e..fb4f202b7 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -21,6 +21,9 @@ trait LoggingTrait { + /** + * @param LogEvent $event + */ private function logRequest(LogEvent $event): void { $debugEvent = [ @@ -46,6 +49,9 @@ private function logRequest(LogEvent $event): void $this->logger->debug((string) json_encode($debugEvent)); } + /** + * @param LogEvent $event + */ private function logResponse(LogEvent $event): void { $debugEvent = [ diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php index df5b90417..220136757 100644 --- a/src/Logging/StdOutLogger.php +++ b/src/Logging/StdOutLogger.php @@ -17,7 +17,7 @@ namespace Google\Auth\Logging; -use Exception; +use InvalidArgumentException; use Psr\Log\LoggerInterface; use Psr\Log\LogLevel; use Stringable; @@ -52,50 +52,72 @@ public function __construct(string $level = LogLevel::DEBUG) $this->level = $this->getLevelMap($level); } + /** + * {@inheritdoc} + */ public function emergency(string|Stringable $message, array $context = []): void { $this->log(LogLevel::EMERGENCY, $message); } + /** + * {@inheritdoc} + */ public function alert(string|Stringable $message, array $context = []): void { $this->log(LogLevel::ALERT, $message); } + /** + * {@inheritdoc} + */ public function critical(string|Stringable $message, array $context = []): void { $this->log(LogLevel::CRITICAL, $message); } + /** + * {@inheritdoc} + */ public function error(string|Stringable $message, array $context = []): void { $this->log(LogLevel::ERROR, $message); } + /** + * {@inheritdoc} + */ public function warning(string|Stringable $message, array $context = []): void { $this->log(LogLevel::WARNING, $message); } + /** + * {@inheritdoc} + */ public function notice(string|Stringable $message, array $context = []): void { $this->log(LogLevel::NOTICE, $message); } + /** + * {@inheritdoc} + */ public function info(string|Stringable $message, array $context = []): void { $this->log(LogLevel::INFO, $message); } + /** + * {@inheritdoc} + */ public function debug(string|Stringable $message, array $context = []): void { $this->log(LogLevel::DEBUG, $message); } /** - * @param string $level - * @param string|Stringable $message - * @param array $context + * {@inheritdoc} */ public function log($level, string|Stringable $message, array $context = []): void { @@ -106,10 +128,15 @@ public function log($level, string|Stringable $message, array $context = []): vo print($message . "\n"); } + /** + * @param string $levelName + * @return int + * @throws InvalidArgumentException + */ private function getLevelMap(string $levelName): int { if (!array_key_exists($levelName, $this->levelMapping)) { - throw new Exception('The level supplied to the Logger is not valid'); + throw new InvalidArgumentException('The level supplied to the Logger is not valid'); } return $this->levelMapping[$levelName]; diff --git a/tests/Logging/StdOutLoggerTest.php b/tests/Logging/StdOutLoggerTest.php index a58cecad2..f5f603313 100644 --- a/tests/Logging/StdOutLoggerTest.php +++ b/tests/Logging/StdOutLoggerTest.php @@ -17,16 +17,16 @@ namespace Google\Auth\Tests\Logging; -use Exception; use Google\Auth\Logging\StdOutLogger; use Google\Auth\Tests\BaseTest; +use InvalidArgumentException; use Psr\Log\LogLevel; class StdOutLoggerTest extends BaseTest { public function testConstructsWithAnIncorrectLevelThrowsException() { - $this->expectException(Exception::class); + $this->expectException(InvalidArgumentException::class); new StdOutLogger('invalid level'); } From 6ca6bc7cfeb00c86749d2f15e46c212e2cf6d9dc Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Fri, 27 Sep 2024 19:06:47 +0000 Subject: [PATCH 18/51] Change logic for logging responses to exclude the info log --- src/Logging/LoggingTrait.php | 36 +++++++++++++++++++----------------- 1 file changed, 19 insertions(+), 17 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index fb4f202b7..f76c4bf5f 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -73,23 +73,25 @@ private function logResponse(LogEvent $event): void ); $this->logger->debug((string) json_encode($debugEvent)); - $infoEvent = [ - 'timestamp' => $event->timestamp, - 'severity' => LogLevel::INFO, - 'clientId' => $event->clientId, - 'requestId' => $event->requestId ?? null, - 'jsonPayload' => [ - 'response.status' => $event->status - ] - ]; - - $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); - $infoEvent['jsonPayload'] = array_filter( - $infoEvent['jsonPayload'], - fn ($value) => !is_null($value) - ); - - $this->logger->info((string) json_encode($infoEvent)); + if ($event->status) { + $infoEvent = [ + 'timestamp' => $event->timestamp, + 'severity' => LogLevel::INFO, + 'clientId' => $event->clientId, + 'requestId' => $event->requestId ?? null, + 'jsonPayload' => [ + 'response.status' => $event->status + ] + ]; + + $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); + $infoEvent['jsonPayload'] = array_filter( + $infoEvent['jsonPayload'], + fn ($value) => !is_null($value) + ); + + $this->logger->info((string) json_encode($infoEvent)); + } } /** From 16d93724076ad7cdb1daa92221db043cb5e762f8 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Fri, 27 Sep 2024 19:27:19 +0000 Subject: [PATCH 19/51] Change logic for logResponse --- src/Logging/LoggingTrait.php | 4 ---- 1 file changed, 4 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index f76c4bf5f..0cc258c88 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -85,10 +85,6 @@ private function logResponse(LogEvent $event): void ]; $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); - $infoEvent['jsonPayload'] = array_filter( - $infoEvent['jsonPayload'], - fn ($value) => !is_null($value) - ); $this->logger->info((string) json_encode($infoEvent)); } From b1ff50351b431114e6e3400edaf201f3f3c057dd Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Tue, 8 Oct 2024 19:21:55 +0000 Subject: [PATCH 20/51] Handle false for the case when json_encode returns false --- src/Logging/LoggingTrait.php | 31 ++++++++++++++++++++++++++++--- 1 file changed, 28 insertions(+), 3 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 0cc258c88..db416e867 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -44,9 +44,17 @@ private function logRequest(LogEvent $event): void 'retryAttempt' => $event->retryAttempt ]; + // Remove null values $debugEvent['jsonPayload'] = array_filter($jsonPayload, fn ($value) => !is_null($value)); - $this->logger->debug((string) json_encode($debugEvent)); + $stringifiedEvent = json_encode($debugEvent); + + // There was an error stringifying the event, return to not break execution + if ($stringifiedEvent === false) { + return; + } + + $this->logger->debug($stringifiedEvent); } /** @@ -66,12 +74,21 @@ private function logResponse(LogEvent $event): void ] ]; + // Remove null values $debugEvent = array_filter($debugEvent, fn ($value) => !is_null($value)); $debugEvent['jsonPayload'] = array_filter( $debugEvent['jsonPayload'], fn ($value) => !is_null($value) ); - $this->logger->debug((string) json_encode($debugEvent)); + + $stringifiedEvent = json_encode($debugEvent); + + // There was an error stringifying the event, return to not break execution + if ($stringifiedEvent === false) { + return; + } + + $this->logger->debug($stringifiedEvent); if ($event->status) { $infoEvent = [ @@ -84,9 +101,17 @@ private function logResponse(LogEvent $event): void ] ]; + // Remove null values $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); - $this->logger->info((string) json_encode($infoEvent)); + $stringifiedEvent = json_encode($debugEvent); + + // There was an error stringifying the event, return to not break execution + if ($stringifiedEvent === false) { + return; + } + + $this->logger->info($stringifiedEvent); } } From b9fb81755a9c916472e3d19091976781e9582d1a Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 16 Oct 2024 21:29:43 +0000 Subject: [PATCH 21/51] Fix serialization bug --- src/Logging/LoggingTrait.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index db416e867..f0198c35a 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -104,7 +104,7 @@ private function logResponse(LogEvent $event): void // Remove null values $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); - $stringifiedEvent = json_encode($debugEvent); + $stringifiedEvent = json_encode($infoEvent); // There was an error stringifying the event, return to not break execution if ($stringifiedEvent === false) { From 33c156a0618723576a5a0ee769ba1ff246ac5064 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Fri, 18 Oct 2024 22:03:03 +0000 Subject: [PATCH 22/51] Add support for logger in --- src/ApplicationDefaultCredentials.php | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index a74fe4921..a51506ea5 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -151,7 +151,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. @@ -163,7 +164,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() @@ -176,7 +178,7 @@ public static function getCredentials( HttpClientCache::setHttpClient($client); } - $httpHandler = HttpHandlerFactory::build($client); + $httpHandler = HttpHandlerFactory::build($client, $logger); } if (is_null($quotaProject)) { From 2a8f88069984d2d56ff27c0a0c9f818c0f9f2ba0 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 11 Nov 2024 20:01:50 +0000 Subject: [PATCH 23/51] Update the StdOutLogger to use Psr the LoggerTrait --- src/Logging/StdOutLogger.php | 67 ++---------------------------------- 1 file changed, 3 insertions(+), 64 deletions(-) diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php index 220136757..01aabaf2e 100644 --- a/src/Logging/StdOutLogger.php +++ b/src/Logging/StdOutLogger.php @@ -19,6 +19,7 @@ use InvalidArgumentException; use Psr\Log\LoggerInterface; +use Psr\Log\LoggerTrait; use Psr\Log\LogLevel; use Stringable; @@ -27,6 +28,8 @@ */ class StdOutLogger implements LoggerInterface { + use LoggerTrait; + /** * @var array */ @@ -52,70 +55,6 @@ public function __construct(string $level = LogLevel::DEBUG) $this->level = $this->getLevelMap($level); } - /** - * {@inheritdoc} - */ - public function emergency(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::EMERGENCY, $message); - } - - /** - * {@inheritdoc} - */ - public function alert(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::ALERT, $message); - } - - /** - * {@inheritdoc} - */ - public function critical(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::CRITICAL, $message); - } - - /** - * {@inheritdoc} - */ - public function error(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::ERROR, $message); - } - - /** - * {@inheritdoc} - */ - public function warning(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::WARNING, $message); - } - - /** - * {@inheritdoc} - */ - public function notice(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::NOTICE, $message); - } - - /** - * {@inheritdoc} - */ - public function info(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::INFO, $message); - } - - /** - * {@inheritdoc} - */ - public function debug(string|Stringable $message, array $context = []): void - { - $this->log(LogLevel::DEBUG, $message); - } - /** * {@inheritdoc} */ From 13c516e49d3d44ebc93be76ae3ed0c79942819a6 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 11 Nov 2024 21:45:50 +0000 Subject: [PATCH 24/51] Fix style and improved readability --- src/ApplicationDefaultCredentials.php | 15 ++++--------- src/HttpHandler/Guzzle6HttpHandler.php | 2 +- src/HttpHandler/HttpHandlerFactory.php | 8 +++---- src/Logging/LoggingTrait.php | 17 +++++++++----- src/Logging/StdOutLogger.php | 6 ++--- tests/ApplicationDefaultCredentialsTest.php | 4 ---- tests/Logging/StdOutLoggerTest.php | 25 +++++---------------- 7 files changed, 27 insertions(+), 50 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index a51506ea5..f587a83fc 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -30,7 +30,6 @@ use Google\Auth\Subscriber\AuthTokenSubscriber; use GuzzleHttp\Client; use InvalidArgumentException; -use PHPUnit\TextUI\XmlConfiguration\Logging\Logging; use Psr\Cache\CacheItemPoolInterface; use Psr\Log\LoggerInterface; @@ -335,22 +334,16 @@ public static function getDefaultLogger(): null|LoggerInterface $loggingFlag = getenv(self::SDK_DEBUG_FLAG); // Env var is not set - if (!is_string($loggingFlag)) { - if (is_array($loggingFlag)) { - trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false, true, 0 or 1. Logging is disabled'); - return null; - } - + if (!$loggingFlag) { return null; } $loggingFlag = strtolower($loggingFlag); // Env Var is not true - if ($loggingFlag !== 'true' && $loggingFlag !== '1') { - // Env var is set to a non valid value - if ($loggingFlag !== 'false' && $loggingFlag !== '0') { - trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false, true, 0 or 1. Logging is disabled'); + if ($loggingFlag !== 'true') { + if ($loggingFlag !== 'false') { + trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false or true. Logging is disabled'); } return null; diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 644d94b08..80a79ef86 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -106,7 +106,7 @@ public function async(RequestInterface $request, array $options = []) $requestEvent = new LogEvent(); $requestEvent->method = $request->getMethod(); - $requestEvent->url = $request->getUri()->__toString(); + $requestEvent->url = (string) $request->getUri(); $requestEvent->headers = $request->getHeaders(); $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index 32d3e460a..0601efc6c 100644 --- a/src/HttpHandler/HttpHandlerFactory.php +++ b/src/HttpHandler/HttpHandlerFactory.php @@ -51,11 +51,9 @@ public static function build( $client = new Client(['handler' => $stack]); } - if ($logger === false) { - $logger = null; - } else { - $logger = $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); - } + $logger = ($logger === false) + ? null + : $logger ?? ApplicationDefaultCredentials::getDefaultLogger(); $version = null; if (defined('GuzzleHttp\ClientInterface::MAJOR_VERSION')) { diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index f0198c35a..7d4460eeb 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -84,12 +84,10 @@ private function logResponse(LogEvent $event): void $stringifiedEvent = json_encode($debugEvent); // There was an error stringifying the event, return to not break execution - if ($stringifiedEvent === false) { - return; + if ($stringifiedEvent !== false) { + $this->logger->debug($stringifiedEvent); } - $this->logger->debug($stringifiedEvent); - if ($event->status) { $infoEvent = [ 'timestamp' => $event->timestamp, @@ -136,12 +134,19 @@ private function logStatus(LogEvent $event): void fn ($value) => !is_null($value) ); - $this->logger->info((string) json_encode($infoEvent)); + $stringifiedEvent = json_encode($infoEvent); + + // There was an error stringifying the event, return to not break execution + if ($stringifiedEvent === false) { + return; + } + + $this->logger->info($stringifiedEvent); } /** * @param array $headers - * @return null|array + * @return null|array */ private function getJwtToken(array $headers): null|array { diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php index 01aabaf2e..db4185a18 100644 --- a/src/Logging/StdOutLogger.php +++ b/src/Logging/StdOutLogger.php @@ -52,7 +52,7 @@ class StdOutLogger implements LoggerInterface */ public function __construct(string $level = LogLevel::DEBUG) { - $this->level = $this->getLevelMap($level); + $this->level = $this->getLevelFromName($level); } /** @@ -60,7 +60,7 @@ public function __construct(string $level = LogLevel::DEBUG) */ public function log($level, string|Stringable $message, array $context = []): void { - if ($this->getLevelMap($level) < $this->level) { + if ($this->getLevelFromName($level) < $this->level) { return; } @@ -72,7 +72,7 @@ public function log($level, string|Stringable $message, array $context = []): vo * @return int * @throws InvalidArgumentException */ - private function getLevelMap(string $levelName): int + 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'); diff --git a/tests/ApplicationDefaultCredentialsTest.php b/tests/ApplicationDefaultCredentialsTest.php index 1bcca47b1..6d6851f9a 100644 --- a/tests/ApplicationDefaultCredentialsTest.php +++ b/tests/ApplicationDefaultCredentialsTest.php @@ -780,10 +780,6 @@ public function testGetDefaultLoggerReturnStdOutLoggerIfEnvVarIsPresent() putenv($this::SDK_DEBUG_FLAG . '=true'); $logger = ApplicationDefaultCredentials::getDefaultLogger(); $this->assertTrue($logger instanceof StdOutLogger); - - putenv($this::SDK_DEBUG_FLAG . '=1'); - $logger = ApplicationDefaultCredentials::getDefaultLogger(); - $this->assertTrue($logger instanceof StdOutLogger); } public function testGetDefaultLoggerReturnsNullIfNotEnvVar() diff --git a/tests/Logging/StdOutLoggerTest.php b/tests/Logging/StdOutLoggerTest.php index f5f603313..a561adb28 100644 --- a/tests/Logging/StdOutLoggerTest.php +++ b/tests/Logging/StdOutLoggerTest.php @@ -32,43 +32,28 @@ public function testConstructsWithAnIncorrectLevelThrowsException() public function testLoggingOnSameLevelWritesToStdOut() { - ob_start(); + $expectedString = 'test'; + $this->expectOutputString($expectedString . "\n"); $logger = new StdOutLogger(LogLevel::DEBUG); - $expectedString = 'test'; $logger->debug($expectedString); - $buffer = ob_get_contents(); - - $this->assertEquals($expectedString . "\n", $buffer); - - ob_end_clean(); } public function testLoggingOnHigherLeverWritesToStdOut() { - ob_start(); + $expectedString = 'test'; + $this->expectOutputString($expectedString. "\n"); $logger = new StdOutLogger(LogLevel::WARNING); - $expectedString = 'test'; $logger->error($expectedString); - $buffer = ob_get_contents(); - - $this->assertEquals($expectedString . "\n", $buffer); - - ob_end_clean(); } public function testLoggingOnLowerLeverDoesNotWriteToStdOut() { - ob_start(); + $this->expectOutputString(''); $logger = new StdOutLogger(LogLevel::WARNING); $expectedString = 'test'; $logger->debug($expectedString); - $buffer = ob_get_contents(); - - $this->assertEmpty($buffer); - - ob_end_clean(); } } From e5ff048323d1381137cf8d7af575d650636a4f76 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 11 Nov 2024 23:08:08 +0000 Subject: [PATCH 25/51] Fix style issues --- src/HttpHandler/HttpHandlerFactory.php | 3 +-- tests/HttpHandler/Guzzle7HttpHandlerTest.php | 2 +- tests/Logging/StdOutLoggerTest.php | 2 +- 3 files changed, 3 insertions(+), 4 deletions(-) diff --git a/src/HttpHandler/HttpHandlerFactory.php b/src/HttpHandler/HttpHandlerFactory.php index 0601efc6c..7b1bf045d 100644 --- a/src/HttpHandler/HttpHandlerFactory.php +++ b/src/HttpHandler/HttpHandlerFactory.php @@ -37,8 +37,7 @@ class HttpHandlerFactory public static function build( ?ClientInterface $client = null, null|false|LoggerInterface $logger = null, - ) - { + ) { if (is_null($client)) { $stack = null; if (class_exists(BodySummarizer::class)) { diff --git a/tests/HttpHandler/Guzzle7HttpHandlerTest.php b/tests/HttpHandler/Guzzle7HttpHandlerTest.php index 732583be3..fe77a49b0 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -41,7 +41,7 @@ public function setUp(): void public function testLoggerGetsCalledIfLoggerIsPassed() { - $requestPromise = new Promise(function() use (&$requestPromise) { + $requestPromise = new Promise(function () use (&$requestPromise) { $response = new Response(200); $requestPromise->resolve($response); }); diff --git a/tests/Logging/StdOutLoggerTest.php b/tests/Logging/StdOutLoggerTest.php index a561adb28..67b54bd92 100644 --- a/tests/Logging/StdOutLoggerTest.php +++ b/tests/Logging/StdOutLoggerTest.php @@ -42,7 +42,7 @@ public function testLoggingOnSameLevelWritesToStdOut() public function testLoggingOnHigherLeverWritesToStdOut() { $expectedString = 'test'; - $this->expectOutputString($expectedString. "\n"); + $this->expectOutputString($expectedString . "\n"); $logger = new StdOutLogger(LogLevel::WARNING); $logger->error($expectedString); From 374c8590b9864d4e27a090b7f14ea8e6d010bbd3 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 18 Nov 2024 22:19:54 +0000 Subject: [PATCH 26/51] Add milliseconds via microtime to the LogEvent class for latency calculations --- src/HttpHandler/Guzzle6HttpHandler.php | 4 ++-- src/Logging/LogEvent.php | 20 ++++++++++++++------ 2 files changed, 16 insertions(+), 8 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 80a79ef86..575f092c5 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -76,7 +76,7 @@ public function __invoke(RequestInterface $request, array $options = []) $response = $this->client->send($request, $options); if ($this->logger) { - $responseEvent = new LogEvent($requestEvent->timestamp); + $responseEvent = new LogEvent($requestEvent->milliseconds); $responseEvent->headers = $response->getHeaders(); $responseEvent->payload = $response->getBody()->getContents(); @@ -121,7 +121,7 @@ public function async(RequestInterface $request, array $options = []) if ($this->logger) { $promise->then(function (ResponseInterface $response) use ($requestEvent) { - $responseEvent = new LogEvent($requestEvent->timestamp); + $responseEvent = new LogEvent($requestEvent->milliseconds); $responseEvent->headers = $response->getHeaders(); $responseEvent->payload = $response->getBody()->getContents(); diff --git a/src/Logging/LogEvent.php b/src/Logging/LogEvent.php index 3007ce2e4..b65550748 100644 --- a/src/Logging/LogEvent.php +++ b/src/Logging/LogEvent.php @@ -22,9 +22,16 @@ class LogEvent /** * Timestamp in format RFC3339 representing when this event ocurred * - * @var null|string + * @var string + */ + public readonly string $timestamp; + + /** + * The time in milliseconds at time on creation for calculating latency + * + * @var float */ - public null|string $timestamp = null; + public readonly float $milliseconds; /** * Rest method type @@ -90,14 +97,14 @@ class LogEvent public null|string $serviceName = null; /** - * The Client Id for easy trace + * The Client Id for tracing * * @var null|int $clientId */ public null|int $clientId = null; /** - * The Request id for easy trace + * The Request id for tracing * * @var null|int $requestId; */ @@ -110,12 +117,13 @@ class LogEvent * * @param null|string $startTime (Optional) Parameter to calculate the latency */ - public function __construct(null|string $startTime = null) + public function __construct(null|float $startTime = null) { $this->timestamp = date(DATE_RFC3339); + $this->milliseconds = round(microtime(true) * 1000); if ($startTime) { - $this->latency = (int) strtotime($this->timestamp) - strtotime($startTime); + $this->latency = (int) $this->milliseconds - $startTime; } } } From 6655bd653035661d80f73aff03b8c09281ea599d Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 18 Nov 2024 22:29:54 +0000 Subject: [PATCH 27/51] Fix unit testing for latency --- tests/Logging/LogEventTest.php | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tests/Logging/LogEventTest.php b/tests/Logging/LogEventTest.php index 5b29b7eb0..d25fc04be 100644 --- a/tests/Logging/LogEventTest.php +++ b/tests/Logging/LogEventTest.php @@ -36,7 +36,8 @@ public function testConstructorWithoutParameterHasNoLatency() public function testConstructorWithParameterHasLatencySet() { - $item = new LogEvent(date(DATE_RFC3339)); + $currentMicrotimeInMillis = microtime(true) * 1000; + $item = new LogEvent($currentMicrotimeInMillis); $this->assertNotNull($item->latency); } } From 5bdbc7db7529b98d5257c057dae84deaf0493590 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Tue, 19 Nov 2024 00:36:51 +0000 Subject: [PATCH 28/51] Update LoggingTrait to check fo is_null instead of falsey --- src/Logging/LoggingTrait.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 7d4460eeb..b0860e9e4 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -88,7 +88,7 @@ private function logResponse(LogEvent $event): void $this->logger->debug($stringifiedEvent); } - if ($event->status) { + if (!is_null($event->status)) { $infoEvent = [ 'timestamp' => $event->timestamp, 'severity' => LogLevel::INFO, From 7aea4e945965219b798c5bd626d84fb436aa4b87 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Thu, 21 Nov 2024 22:00:44 +0000 Subject: [PATCH 29/51] Use the passed requestId option inside the options array --- src/HttpHandler/Guzzle6HttpHandler.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 575f092c5..3f86c60d2 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -68,7 +68,7 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; $requestEvent->clientId = spl_object_id($this->client); - $requestEvent->requestId = spl_object_id($request); + $requestEvent->requestId = $options['requestId'] ?? spl_object_id($request); $this->logRequest($requestEvent); } From 7e2df5c2b96bd48841a059c22d755a4dc043a029 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Fri, 22 Nov 2024 16:56:01 +0000 Subject: [PATCH 30/51] Change LogEvent name to RpcLogEvent --- src/HttpHandler/Guzzle6HttpHandler.php | 10 +++++----- src/Logging/LoggingTrait.php | 6 +++--- src/Logging/{LogEvent.php => RpcLogEvent.php} | 4 +++- tests/Logging/LoggingTraitTest.php | 10 +++++----- 4 files changed, 16 insertions(+), 14 deletions(-) rename src/Logging/{LogEvent.php => RpcLogEvent.php} (97%) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 3f86c60d2..0563aa91d 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -16,8 +16,8 @@ */ namespace Google\Auth\HttpHandler; -use Google\Auth\Logging\LogEvent; use Google\Auth\Logging\LoggingTrait; +use Google\Auth\Logging\RpcLogEvent; use GuzzleHttp\ClientInterface; use Psr\Http\Message\RequestInterface; use Psr\Http\Message\ResponseInterface; @@ -59,7 +59,7 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent = null; if ($this->logger) { - $requestEvent = new LogEvent(); + $requestEvent = new RpcLogEvent(); $requestEvent->method = $request->getMethod(); $requestEvent->url = $request->getUri()->__toString(); @@ -76,7 +76,7 @@ public function __invoke(RequestInterface $request, array $options = []) $response = $this->client->send($request, $options); if ($this->logger) { - $responseEvent = new LogEvent($requestEvent->milliseconds); + $responseEvent = new RpcLogEvent($requestEvent->milliseconds); $responseEvent->headers = $response->getHeaders(); $responseEvent->payload = $response->getBody()->getContents(); @@ -103,7 +103,7 @@ public function async(RequestInterface $request, array $options = []) $requestEvent = null; if ($this->logger) { - $requestEvent = new LogEvent(); + $requestEvent = new RpcLogEvent(); $requestEvent->method = $request->getMethod(); $requestEvent->url = (string) $request->getUri(); @@ -121,7 +121,7 @@ public function async(RequestInterface $request, array $options = []) if ($this->logger) { $promise->then(function (ResponseInterface $response) use ($requestEvent) { - $responseEvent = new LogEvent($requestEvent->milliseconds); + $responseEvent = new RpcLogEvent($requestEvent->milliseconds); $responseEvent->headers = $response->getHeaders(); $responseEvent->payload = $response->getBody()->getContents(); diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index b0860e9e4..41c6304ae 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -24,7 +24,7 @@ trait LoggingTrait /** * @param LogEvent $event */ - private function logRequest(LogEvent $event): void + private function logRequest(RpcLogEvent $event): void { $debugEvent = [ 'timestamp' => $event->timestamp, @@ -60,7 +60,7 @@ private function logRequest(LogEvent $event): void /** * @param LogEvent $event */ - private function logResponse(LogEvent $event): void + private function logResponse(RpcLogEvent $event): void { $debugEvent = [ 'timestamp' => $event->timestamp, @@ -116,7 +116,7 @@ private function logResponse(LogEvent $event): void /** * @param LogEvent $event */ - private function logStatus(LogEvent $event): void + private function logStatus(RpcLogEvent $event): void { $infoEvent = [ 'timestamp' => $event->timestamp, diff --git a/src/Logging/LogEvent.php b/src/Logging/RpcLogEvent.php similarity index 97% rename from src/Logging/LogEvent.php rename to src/Logging/RpcLogEvent.php index b65550748..5adc691a3 100644 --- a/src/Logging/LogEvent.php +++ b/src/Logging/RpcLogEvent.php @@ -17,7 +17,7 @@ namespace Google\Auth\Logging; -class LogEvent +class RpcLogEvent { /** * Timestamp in format RFC3339 representing when this event ocurred @@ -120,6 +120,8 @@ class LogEvent 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) { diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php index f162b4760..41dd56af0 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -17,8 +17,8 @@ namespace Google\Auth\Tests\Logging; -use Google\Auth\Logging\LogEvent; use Google\Auth\Logging\LoggingTrait; +use Google\Auth\Logging\RpcLogEvent; use Google\Auth\Logging\StdOutLogger; use Google\Auth\Tests\BaseTest; use Psr\Log\LoggerInterface; @@ -92,9 +92,9 @@ public function testLogResponse() $this->assertEquals($event->status, $parsedInfoEvent['jsonPayload']['response.status']); } - private function getNewLogEvent(): LogEvent + private function getNewLogEvent(): RpcLogEvent { - $event = new LogEvent(); + $event = new RpcLogEvent(); $event->clientId = 123; $event->method = 'get'; $event->url = 'test.com'; @@ -124,12 +124,12 @@ public function __construct() $this->logger = new StdOutLogger(); } - public function logRequestEvent(LogEvent $event): void + public function logRequestEvent(RpcLogEvent $event): void { $this->logRequest($event); } - public function logResponseEvent(LogEvent $event): void + public function logResponseEvent(RpcLogEvent $event): void { $this->logResponse($event); } From 1591d5960f2b0a2ec9799eac5977efa9bdeb3c4c Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 25 Nov 2024 21:53:30 +0000 Subject: [PATCH 31/51] Use the round method to store miliseconds on RPCLogEvent --- src/Logging/RpcLogEvent.php | 2 +- .../{LogEventTest.php => RpcLogEventTest.php} | 16 ++++++++++------ 2 files changed, 11 insertions(+), 7 deletions(-) rename tests/Logging/{LogEventTest.php => RpcLogEventTest.php} (68%) diff --git a/src/Logging/RpcLogEvent.php b/src/Logging/RpcLogEvent.php index 5adc691a3..684fca35c 100644 --- a/src/Logging/RpcLogEvent.php +++ b/src/Logging/RpcLogEvent.php @@ -125,7 +125,7 @@ public function __construct(null|float $startTime = null) $this->milliseconds = round(microtime(true) * 1000); if ($startTime) { - $this->latency = (int) $this->milliseconds - $startTime; + $this->latency = (int) round($this->milliseconds - $startTime); } } } diff --git a/tests/Logging/LogEventTest.php b/tests/Logging/RpcLogEventTest.php similarity index 68% rename from tests/Logging/LogEventTest.php rename to tests/Logging/RpcLogEventTest.php index d25fc04be..63a948ef4 100644 --- a/tests/Logging/LogEventTest.php +++ b/tests/Logging/RpcLogEventTest.php @@ -17,27 +17,31 @@ namespace Google\Auth\Tests\Logging; -use Google\Auth\Logging\LogEvent; +use Google\Auth\Logging\RpcLogEvent; use Google\Auth\Tests\BaseTest; -class LogEventTest extends BaseTest +class RpcLogEventTest extends BaseTest { public function testInstanceAddsTimestamp() { - $item = new LogEvent(); + $item = new RpcLogEvent(); $this->assertNotNull($item->timestamp); } public function testConstructorWithoutParameterHasNoLatency() { - $item = new LogEvent(); + $item = new RpcLogEvent(); $this->assertNull($item->latency); } public function testConstructorWithParameterHasLatencySet() { - $currentMicrotimeInMillis = microtime(true) * 1000; - $item = new LogEvent($currentMicrotimeInMillis); + // 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); } } From 53ce7fa054085a55079791526b4a99efb7dc76ab Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 25 Nov 2024 22:19:09 +0000 Subject: [PATCH 32/51] Change the array type of payload to string --- src/Logging/LoggingTrait.php | 45 +++++++++++++----------------- src/Logging/RpcLogEvent.php | 4 +-- tests/Logging/LoggingTraitTest.php | 2 +- 3 files changed, 22 insertions(+), 29 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 41c6304ae..3575e489b 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -22,7 +22,7 @@ trait LoggingTrait { /** - * @param LogEvent $event + * @param RpcLogEvent $event */ private function logRequest(RpcLogEvent $event): void { @@ -39,7 +39,7 @@ private function logRequest(RpcLogEvent $event): void 'request.method' => $event->method, 'request.url' => $event->url, 'request.headers' => $event->headers, - 'request.payload' => $event->payload, + 'request.payload' => $this->truncatePayload($event->payload), 'request.jwt' => $this->getJwtToken($event->headers ?? []), 'retryAttempt' => $event->retryAttempt ]; @@ -58,7 +58,7 @@ private function logRequest(RpcLogEvent $event): void } /** - * @param LogEvent $event + * @param RpcLogEvent $event */ private function logResponse(RpcLogEvent $event): void { @@ -69,7 +69,7 @@ private function logResponse(RpcLogEvent $event): void 'requestId' => $event->requestId ?? null, 'jsonPayload' => [ 'response.headers' => $event->headers, - 'response.payload' => $event->payload, + 'response.payload' => $this->truncatePayload($event->payload), 'latency' => $event->latency, ] ]; @@ -89,32 +89,12 @@ private function logResponse(RpcLogEvent $event): void } if (!is_null($event->status)) { - $infoEvent = [ - 'timestamp' => $event->timestamp, - 'severity' => LogLevel::INFO, - 'clientId' => $event->clientId, - 'requestId' => $event->requestId ?? null, - 'jsonPayload' => [ - 'response.status' => $event->status - ] - ]; - - // Remove null values - $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); - - $stringifiedEvent = json_encode($infoEvent); - - // There was an error stringifying the event, return to not break execution - if ($stringifiedEvent === false) { - return; - } - - $this->logger->info($stringifiedEvent); + $this->logStatus($event); } } /** - * @param LogEvent $event + * @param RpcLogEvent $event */ private function logStatus(RpcLogEvent $event): void { @@ -168,4 +148,17 @@ private function getJwtToken(array $headers): null|array 'token' => base64_decode($token) ]; } + + /** + * @param string $payload + * @return string + */ + private function truncatePayload(string $payload): string + { + if (strlen($payload) <= 500) { + return $payload; + } + + return substr($payload, 0, 500) . '...'; + } } diff --git a/src/Logging/RpcLogEvent.php b/src/Logging/RpcLogEvent.php index 684fca35c..7080f5b78 100644 --- a/src/Logging/RpcLogEvent.php +++ b/src/Logging/RpcLogEvent.php @@ -57,9 +57,9 @@ class RpcLogEvent /** * An array representation of JSON for the response or request * - * @var null|string|array + * @var null|string */ - public null|string|array $payload = null; + public null|string $payload = null; /** * Status code for REST or gRPC methods diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php index 41dd56af0..3fd215b0e 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -102,7 +102,7 @@ private function getNewLogEvent(): RpcLogEvent 'header1' => 'test', 'Authorization' => 'Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiIxMjM0NTY3ODkwIiwibmFtZSI6IkpvaG4gRG9lIiwiaWF0IjoxNTE2MjM5MDIyfQ.cThIIoDvwdueQB468K5xDc5633seEFoqwxjF_xSJyQQ' ]; - $event->payload = ['param' => 'test']; + $event->payload = json_encode(['param' => 'test']); $event->status = 200; $event->retryAttempt = 0; $event->rpcName = 'Rpc NameTest'; From b05fd6314ac2bfce6403c426696b2aad7ab3e4e7 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 25 Nov 2024 22:25:16 +0000 Subject: [PATCH 33/51] Fix null payload bug on the truncatePayload method --- src/Logging/LoggingTrait.php | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 3575e489b..236431a3f 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -150,12 +150,12 @@ private function getJwtToken(array $headers): null|array } /** - * @param string $payload + * @param null|string $payload * @return string */ - private function truncatePayload(string $payload): string + private function truncatePayload(null|string $payload): null|string { - if (strlen($payload) <= 500) { + if (is_null($payload) || strlen($payload) <= 500) { return $payload; } From a897b0bf651173b420e91d9fafb46b89f0328a83 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Tue, 26 Nov 2024 21:27:50 +0000 Subject: [PATCH 34/51] Change the debug flag to GOOGLE_SDK_PHP_LOGGING --- src/ApplicationDefaultCredentials.php | 2 +- tests/ApplicationDefaultCredentialsTest.php | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index f587a83fc..b94923936 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -72,7 +72,7 @@ */ class ApplicationDefaultCredentials { - private const SDK_DEBUG_FLAG = 'GOOGLE_SDK_DEBUG_LOGGING'; + private const SDK_DEBUG_FLAG = 'GOOGLE_SDK_PHP_LOGGING'; /** * @deprecated diff --git a/tests/ApplicationDefaultCredentialsTest.php b/tests/ApplicationDefaultCredentialsTest.php index 6d6851f9a..5c1936b53 100644 --- a/tests/ApplicationDefaultCredentialsTest.php +++ b/tests/ApplicationDefaultCredentialsTest.php @@ -49,7 +49,7 @@ class ApplicationDefaultCredentialsTest extends TestCase private $targetAudience = 'a target audience'; private $quotaProject = 'a-quota-project'; private $originalServiceAccount; - private const SDK_DEBUG_FLAG = 'GOOGLE_SDK_DEBUG_LOGGING'; + private const SDK_DEBUG_FLAG = 'GOOGLE_SDK_PHP_LOGGING'; public function testGetCredentialsFailsIfEnvSpecifiesNonExistentFile() { From 027096e047295de02a0a05fa199ba25d955f8a12 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Sat, 30 Nov 2024 00:08:53 +0000 Subject: [PATCH 35/51] Cast a response url to String --- src/HttpHandler/Guzzle6HttpHandler.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 0563aa91d..428758ed3 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -62,7 +62,7 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent = new RpcLogEvent(); $requestEvent->method = $request->getMethod(); - $requestEvent->url = $request->getUri()->__toString(); + $requestEvent->url = (string) $request->getUri(); $requestEvent->headers = $request->getHeaders(); $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; From db765ecbe3626b6c00ebb166b39830c1949025fb Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Mon, 2 Dec 2024 18:59:02 +0000 Subject: [PATCH 36/51] Fix type notation on phpDoc --- src/Logging/RpcLogEvent.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Logging/RpcLogEvent.php b/src/Logging/RpcLogEvent.php index 7080f5b78..029cae313 100644 --- a/src/Logging/RpcLogEvent.php +++ b/src/Logging/RpcLogEvent.php @@ -115,7 +115,7 @@ class RpcLogEvent * Passing a string representation of a timestamp calculates the difference between * these two times and sets the latency field with the result. * - * @param null|string $startTime (Optional) Parameter to calculate the latency + * @param null|float $startTime (Optional) Parameter to calculate the latency */ public function __construct(null|float $startTime = null) { From f35e295f6869a2a2034844dfd6f31d5973dbbb04 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Tue, 3 Dec 2024 20:19:07 +0000 Subject: [PATCH 37/51] Add the internal tag to internal classes --- src/Logging/LoggingTrait.php | 13 +++++++++---- src/Logging/RpcLogEvent.php | 5 +++++ src/Logging/StdOutLogger.php | 4 +++- 3 files changed, 17 insertions(+), 5 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 236431a3f..9c2d48567 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -19,6 +19,11 @@ use Psr\Log\LogLevel; +/** + * A trait used to call a PSR-3 logging interface. + * + * @internal + */ trait LoggingTrait { /** @@ -47,7 +52,7 @@ private function logRequest(RpcLogEvent $event): void // Remove null values $debugEvent['jsonPayload'] = array_filter($jsonPayload, fn ($value) => !is_null($value)); - $stringifiedEvent = json_encode($debugEvent); + $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) { @@ -70,7 +75,7 @@ private function logResponse(RpcLogEvent $event): void 'jsonPayload' => [ 'response.headers' => $event->headers, 'response.payload' => $this->truncatePayload($event->payload), - 'latency' => $event->latency, + 'latencyMillis' => $event->latency, ] ]; @@ -81,7 +86,7 @@ private function logResponse(RpcLogEvent $event): void fn ($value) => !is_null($value) ); - $stringifiedEvent = json_encode($debugEvent); + $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) { @@ -114,7 +119,7 @@ private function logStatus(RpcLogEvent $event): void fn ($value) => !is_null($value) ); - $stringifiedEvent = json_encode($infoEvent); + $stringifiedEvent = json_encode($infoEvent, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE); // There was an error stringifying the event, return to not break execution if ($stringifiedEvent === false) { diff --git a/src/Logging/RpcLogEvent.php b/src/Logging/RpcLogEvent.php index 029cae313..3095eabcf 100644 --- a/src/Logging/RpcLogEvent.php +++ b/src/Logging/RpcLogEvent.php @@ -17,6 +17,11 @@ namespace Google\Auth\Logging; +/** + * A class that contains all the required information for logging. + * + * @internal + */ class RpcLogEvent { /** diff --git a/src/Logging/StdOutLogger.php b/src/Logging/StdOutLogger.php index db4185a18..27b1f0eb3 100644 --- a/src/Logging/StdOutLogger.php +++ b/src/Logging/StdOutLogger.php @@ -24,7 +24,9 @@ use Stringable; /** - * A basic logger class to log into stdOut for GCP logging + * A basic logger class to log into stdOut for GCP logging. + * + * @internal */ class StdOutLogger implements LoggerInterface { From 636f650167d40e1b6646e1a5f3c43f4961205b16 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Wed, 4 Dec 2024 23:26:20 +0000 Subject: [PATCH 38/51] Swap logic to log the info level log --- src/Logging/LoggingTrait.php | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 9c2d48567..567909a61 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -67,6 +67,10 @@ private function logRequest(RpcLogEvent $event): void */ private function logResponse(RpcLogEvent $event): void { + if (!is_null($event->status)) { + $this->logStatus($event); + } + $debugEvent = [ 'timestamp' => $event->timestamp, 'severity' => strtoupper(LogLevel::DEBUG), @@ -92,10 +96,6 @@ private function logResponse(RpcLogEvent $event): void if ($stringifiedEvent !== false) { $this->logger->debug($stringifiedEvent); } - - if (!is_null($event->status)) { - $this->logStatus($event); - } } /** @@ -105,7 +105,7 @@ private function logStatus(RpcLogEvent $event): void { $infoEvent = [ 'timestamp' => $event->timestamp, - 'severity' => LogLevel::INFO, + 'severity' => strtoupper(LogLevel::INFO), 'clientId' => $event->clientId, 'requestId' => $event->requestId ?? null, 'jsonPayload' => [ From 3bbac24e8352a4fbc3846af4c7dd30bf01ac29c6 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Thu, 5 Dec 2024 00:12:51 +0000 Subject: [PATCH 39/51] Fix the LoggingTrait test --- tests/Logging/LoggingTraitTest.php | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php index 3fd215b0e..de15b2549 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -68,20 +68,18 @@ public function testRequestWithoutJwtShouldNotPrintAJwt() public function testLogResponse() { - ob_start(); - $event = $this->getNewLogEvent(); + $event->headers = ['Thisis' => "a header"]; $this->loggerContainer->logResponseEvent($event); - $buffer = ob_get_contents(); - ob_end_clean(); + $buffer = $this->getActualOutput(); $buffer = str_replace("\n", '', $buffer); - // The LogResponse method logs two evnets, one for info and one for debug. - [$debugEvent, $infoEvent] = explode('}{', $buffer); - $debugEvent .= '}'; - $infoEvent = '{' . $infoEvent; + // The LogResponse method logs two events, one for info and one for debug. + [$infoEvent, $debugEvent] = explode('}{', $buffer); + $infoEvent .= '}'; + $debugEvent = '{' . $debugEvent; $parsedDebugEvent = json_decode($debugEvent, true); $this->assertEquals($event->clientId, $parsedDebugEvent['clientId']); From 1a7523b751c50fe41a6c8f0db90b99cb4a4985f7 Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Thu, 5 Dec 2024 00:20:40 +0000 Subject: [PATCH 40/51] Fix Style --- src/HttpHandler/Guzzle6HttpHandler.php | 2 +- tests/Logging/LoggingTraitTest.php | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 428758ed3..0357c6eea 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -41,7 +41,7 @@ class Guzzle6HttpHandler * @param ClientInterface $client * @param null|LoggerInterface $logger */ - public function __construct(ClientInterface $client, LoggerInterface $logger = null) + public function __construct(ClientInterface $client, ?LoggerInterface $logger = null) { $this->client = $client; $this->logger = $logger; diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php index de15b2549..a3f515d71 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -69,7 +69,7 @@ public function testRequestWithoutJwtShouldNotPrintAJwt() public function testLogResponse() { $event = $this->getNewLogEvent(); - $event->headers = ['Thisis' => "a header"]; + $event->headers = ['Thisis' => 'a header']; $this->loggerContainer->logResponseEvent($event); $buffer = $this->getActualOutput(); From 876f14ac69ee19259ebb3bec1b90ff040451b11e Mon Sep 17 00:00:00 2001 From: Hector Mendoza Jacobo Date: Thu, 5 Dec 2024 23:42:25 +0000 Subject: [PATCH 41/51] Change the client ID field to represent a Gapic Client --- src/ApplicationDefaultCredentials.php | 2 ++ src/HttpHandler/Guzzle6HttpHandler.php | 6 +++--- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index b94923936..05b3e73de 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -327,6 +327,8 @@ public static function getIdTokenCredentials( /** * Returns a StdOutLogger instance * + * @internal + * * @return null|LoggerInterface */ public static function getDefaultLogger(): null|LoggerInterface diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 0357c6eea..356c8cca8 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -67,7 +67,7 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; - $requestEvent->clientId = spl_object_id($this->client); + $requestEvent->clientId = $options['clientId']; $requestEvent->requestId = $options['requestId'] ?? spl_object_id($request); $this->logRequest($requestEvent); @@ -111,8 +111,8 @@ public function async(RequestInterface $request, array $options = []) $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; - $requestEvent->clientId = spl_object_id($this->client); - $requestEvent->requestId = spl_object_id($request); + $requestEvent->clientId = $options['clientId']; + $requestEvent->requestId = $options['requestId'] ?? spl_object_id($request); $this->logRequest($requestEvent); } From 7869f8c8b8c5183ce31c57443d0d23e60df2789c Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Mon, 9 Dec 2024 20:29:45 +0000 Subject: [PATCH 42/51] Change clientId for processId in rpcLogEvent --- src/HttpHandler/Guzzle6HttpHandler.php | 8 ++++---- src/Logging/LoggingTrait.php | 6 +++--- src/Logging/RpcLogEvent.php | 10 +++++----- tests/Logging/LoggingTraitTest.php | 16 +++++----------- 4 files changed, 17 insertions(+), 23 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 356c8cca8..89f3bbf71 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -67,7 +67,7 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; - $requestEvent->clientId = $options['clientId']; + $requestEvent->processId = getmypid(); $requestEvent->requestId = $options['requestId'] ?? spl_object_id($request); $this->logRequest($requestEvent); @@ -81,7 +81,7 @@ public function __invoke(RequestInterface $request, array $options = []) $responseEvent->headers = $response->getHeaders(); $responseEvent->payload = $response->getBody()->getContents(); $responseEvent->status = $response->getStatusCode(); - $responseEvent->clientId = $requestEvent->clientId; + $responseEvent->processId = $requestEvent->processId; $responseEvent->requestId = $requestEvent->requestId; $this->logResponse($responseEvent); @@ -111,7 +111,7 @@ public function async(RequestInterface $request, array $options = []) $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; - $requestEvent->clientId = $options['clientId']; + $requestEvent->processId = getmypid(); $requestEvent->requestId = $options['requestId'] ?? spl_object_id($request); $this->logRequest($requestEvent); @@ -126,7 +126,7 @@ public function async(RequestInterface $request, array $options = []) $responseEvent->headers = $response->getHeaders(); $responseEvent->payload = $response->getBody()->getContents(); $responseEvent->status = $response->getStatusCode(); - $responseEvent->clientId = $requestEvent->clientId; + $responseEvent->processId = $requestEvent->processId; $responseEvent->requestId = $requestEvent->requestId; $this->logResponse($responseEvent); diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 567909a61..d6d0422a4 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -34,7 +34,7 @@ private function logRequest(RpcLogEvent $event): void $debugEvent = [ 'timestamp' => $event->timestamp, 'severity' => strtoupper(LogLevel::DEBUG), - 'clientId' => $event->clientId, + 'processId' => $event->processId ?? null, 'requestId' => $event->requestId ?? null, ]; @@ -74,7 +74,7 @@ private function logResponse(RpcLogEvent $event): void $debugEvent = [ 'timestamp' => $event->timestamp, 'severity' => strtoupper(LogLevel::DEBUG), - 'clientId' => $event->clientId, + 'processId' => $event->processId, 'requestId' => $event->requestId ?? null, 'jsonPayload' => [ 'response.headers' => $event->headers, @@ -106,7 +106,7 @@ private function logStatus(RpcLogEvent $event): void $infoEvent = [ 'timestamp' => $event->timestamp, 'severity' => strtoupper(LogLevel::INFO), - 'clientId' => $event->clientId, + 'processId' => $event->processId, 'requestId' => $event->requestId ?? null, 'jsonPayload' => [ 'response.status' => $event->status diff --git a/src/Logging/RpcLogEvent.php b/src/Logging/RpcLogEvent.php index 3095eabcf..6f6171b2d 100644 --- a/src/Logging/RpcLogEvent.php +++ b/src/Logging/RpcLogEvent.php @@ -74,7 +74,7 @@ class RpcLogEvent public null|int|string $status = null; /** - * The latency in miliseconds + * The latency in milliseconds * * @var null|int */ @@ -102,14 +102,14 @@ class RpcLogEvent public null|string $serviceName = null; /** - * The Client Id for tracing + * The Process ID for tracing logs * - * @var null|int $clientId + * @var null|int $processId */ - public null|int $clientId = null; + public null|int $processId = null; /** - * The Request id for tracing + * The Request id for tracing logs * * @var null|int $requestId; */ diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php index a3f515d71..620e21489 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -34,17 +34,14 @@ public function setUp(): void public function testLogRequest() { - ob_start(); - $event = $this->getNewLogEvent(); $this->loggerContainer->logRequestEvent($event); - $buffer = ob_get_contents(); - ob_end_clean(); + $buffer = $this->getActualOutput(); $jsonParsed = json_decode($buffer, true); $this->assertEquals($event->timestamp, $jsonParsed['timestamp']); - $this->assertEquals($event->clientId, $jsonParsed['clientId']); + $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']); @@ -53,14 +50,11 @@ public function testLogRequest() public function testRequestWithoutJwtShouldNotPrintAJwt() { - ob_start(); - $event = $this->getNewLogEvent(); $event->headers = ['no jwt' => true]; $this->loggerContainer->logRequestEvent($event); - $buffer = ob_get_contents(); - ob_end_clean(); + $buffer = $this->getActualOutput(); $jsonParsed = json_decode($buffer, true); $this->assertArrayNotHasKey('request.jwt', $jsonParsed['jsonPayload']); @@ -82,7 +76,7 @@ public function testLogResponse() $debugEvent = '{' . $debugEvent; $parsedDebugEvent = json_decode($debugEvent, true); - $this->assertEquals($event->clientId, $parsedDebugEvent['clientId']); + $this->assertEquals($event->processId, $parsedDebugEvent['processId']); $this->assertEquals($event->requestId, $parsedDebugEvent['requestId']); $this->assertEquals($event->headers, $parsedDebugEvent['jsonPayload']['response.headers']); @@ -93,7 +87,7 @@ public function testLogResponse() private function getNewLogEvent(): RpcLogEvent { $event = new RpcLogEvent(); - $event->clientId = 123; + $event->processId = 123; $event->method = 'get'; $event->url = 'test.com'; $event->headers = [ From 7d3a494da9c1121d64c2ddb8847893a7e8df8875 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Tue, 10 Dec 2024 00:32:19 +0000 Subject: [PATCH 43/51] Change the httpHandler requestId fallback to a hash --- src/HttpHandler/Guzzle6HttpHandler.php | 4 ++-- src/Logging/LoggingTrait.php | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 89f3bbf71..95926d3a5 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -68,7 +68,7 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; $requestEvent->processId = getmypid(); - $requestEvent->requestId = $options['requestId'] ?? spl_object_id($request); + $requestEvent->requestId = $options['requestId'] ?? crc32((string) spl_object_id($request) . getmypid()); $this->logRequest($requestEvent); } @@ -112,7 +112,7 @@ public function async(RequestInterface $request, array $options = []) $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; $requestEvent->processId = getmypid(); - $requestEvent->requestId = $options['requestId'] ?? spl_object_id($request); + $requestEvent->requestId = $options['requestId'] ?? crc32((string) spl_object_id($request) . getmypid()); $this->logRequest($requestEvent); } diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index d6d0422a4..f42dd8daa 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -74,7 +74,7 @@ private function logResponse(RpcLogEvent $event): void $debugEvent = [ 'timestamp' => $event->timestamp, 'severity' => strtoupper(LogLevel::DEBUG), - 'processId' => $event->processId, + 'processId' => $event->processId ?? null, 'requestId' => $event->requestId ?? null, 'jsonPayload' => [ 'response.headers' => $event->headers, From 8d9ade78e75727283882a47c861473e22a085300 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Tue, 10 Dec 2024 01:07:14 +0000 Subject: [PATCH 44/51] Handle the getmypid false case --- src/HttpHandler/Guzzle6HttpHandler.php | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 95926d3a5..f8fbcf7dd 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -67,7 +67,7 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; - $requestEvent->processId = getmypid(); + $requestEvent->processId = (int) getmypid(); $requestEvent->requestId = $options['requestId'] ?? crc32((string) spl_object_id($request) . getmypid()); $this->logRequest($requestEvent); @@ -111,7 +111,7 @@ public function async(RequestInterface $request, array $options = []) $requestEvent->payload = $request->getBody()->getContents(); $requestEvent->retryAttempt = $options['retryAttempt'] ?? null; $requestEvent->serviceName = $options['serviceName'] ?? null; - $requestEvent->processId = getmypid(); + $requestEvent->processId = (int) getmypid(); $requestEvent->requestId = $options['requestId'] ?? crc32((string) spl_object_id($request) . getmypid()); $this->logRequest($requestEvent); From ffaff38dffd486d6ef93f76bb5a9a1142dc9d827 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Tue, 10 Dec 2024 22:29:59 +0000 Subject: [PATCH 45/51] Remove the INFO level log --- src/Logging/LoggingTrait.php | 36 +------------------- tests/HttpHandler/Guzzle7HttpHandlerTest.php | 2 -- tests/Logging/LoggingTraitTest.php | 12 +------ 3 files changed, 2 insertions(+), 48 deletions(-) diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index f42dd8daa..97c51368a 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -67,16 +67,13 @@ private function logRequest(RpcLogEvent $event): void */ private function logResponse(RpcLogEvent $event): void { - if (!is_null($event->status)) { - $this->logStatus($event); - } - $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, @@ -98,37 +95,6 @@ private function logResponse(RpcLogEvent $event): void } } - /** - * @param RpcLogEvent $event - */ - private function logStatus(RpcLogEvent $event): void - { - $infoEvent = [ - 'timestamp' => $event->timestamp, - 'severity' => strtoupper(LogLevel::INFO), - 'processId' => $event->processId, - 'requestId' => $event->requestId ?? null, - 'jsonPayload' => [ - 'response.status' => $event->status - ] - ]; - - $infoEvent = array_filter($infoEvent, fn ($value) => !is_null($value)); - $infoEvent['jsonPayload'] = array_filter( - $infoEvent['jsonPayload'], - fn ($value) => !is_null($value) - ); - - $stringifiedEvent = json_encode($infoEvent, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE); - - // There was an error stringifying the event, return to not break execution - if ($stringifiedEvent === false) { - return; - } - - $this->logger->info($stringifiedEvent); - } - /** * @param array $headers * @return null|array diff --git a/tests/HttpHandler/Guzzle7HttpHandlerTest.php b/tests/HttpHandler/Guzzle7HttpHandlerTest.php index fe77a49b0..97cb8688d 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -49,8 +49,6 @@ public function testLoggerGetsCalledIfLoggerIsPassed() $mockLogger = $this->prophesize(StdOutLogger::class); $mockLogger->debug(Argument::cetera()) ->shouldBeCalledTimes(2); - $mockLogger->info(Argument::cetera()) - ->shouldBeCalledTimes(1); $this->client->sendAsync(Argument::cetera()) ->willReturn($requestPromise); diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php index 620e21489..edc85b5bd 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -68,20 +68,10 @@ public function testLogResponse() $buffer = $this->getActualOutput(); - $buffer = str_replace("\n", '', $buffer); - - // The LogResponse method logs two events, one for info and one for debug. - [$infoEvent, $debugEvent] = explode('}{', $buffer); - $infoEvent .= '}'; - $debugEvent = '{' . $debugEvent; - - $parsedDebugEvent = json_decode($debugEvent, true); + $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']); - - $parsedInfoEvent = json_decode($infoEvent, true); - $this->assertEquals($event->status, $parsedInfoEvent['jsonPayload']['response.status']); } private function getNewLogEvent(): RpcLogEvent From 6aaf4de1a014e5d72b5ff70d7f349df8e84c4db8 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Wed, 11 Dec 2024 00:15:18 +0000 Subject: [PATCH 46/51] Move logging logic of guzzle logging to private methods --- src/ApplicationDefaultCredentials.php | 8 +- src/HttpHandler/Guzzle6HttpHandler.php | 81 ++++++++++----------- tests/ApplicationDefaultCredentialsTest.php | 10 +-- 3 files changed, 47 insertions(+), 52 deletions(-) diff --git a/src/ApplicationDefaultCredentials.php b/src/ApplicationDefaultCredentials.php index 05b3e73de..39107c790 100644 --- a/src/ApplicationDefaultCredentials.php +++ b/src/ApplicationDefaultCredentials.php @@ -72,7 +72,7 @@ */ class ApplicationDefaultCredentials { - private const SDK_DEBUG_FLAG = 'GOOGLE_SDK_PHP_LOGGING'; + private const SDK_DEBUG_ENV_VAR = 'GOOGLE_SDK_PHP_LOGGING'; /** * @deprecated @@ -333,10 +333,10 @@ public static function getIdTokenCredentials( */ public static function getDefaultLogger(): null|LoggerInterface { - $loggingFlag = getenv(self::SDK_DEBUG_FLAG); + $loggingFlag = getenv(self::SDK_DEBUG_ENV_VAR); // Env var is not set - if (!$loggingFlag) { + if (empty($loggingFlag)) { return null; } @@ -345,7 +345,7 @@ public static function getDefaultLogger(): null|LoggerInterface // Env Var is not true if ($loggingFlag !== 'true') { if ($loggingFlag !== 'false') { - trigger_error('The ' . self::SDK_DEBUG_FLAG . ' is set, but it is set to another value than false or true. Logging is disabled'); + 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; diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index f8fbcf7dd..012d34388 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -59,32 +59,13 @@ public function __invoke(RequestInterface $request, array $options = []) $requestEvent = null; if ($this->logger) { - $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); + $requestEvent = $this->requestLog($request, $options); } $response = $this->client->send($request, $options); if ($this->logger) { - $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); + $this->responseLog($response, $requestEvent); } return $response; @@ -103,38 +84,52 @@ public function async(RequestInterface $request, array $options = []) $requestEvent = null; if ($this->logger) { - $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); + $requestEvent = $this->requestLog($request, $options); } $promise = $this->client->sendAsync($request, $options); if ($this->logger) { $promise->then(function (ResponseInterface $response) use ($requestEvent) { - $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); - + $this->responseLog($response, $requestEvent); return $response; }); } return $promise; } + + /** + * @internal + */ + 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; + } + + 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/tests/ApplicationDefaultCredentialsTest.php b/tests/ApplicationDefaultCredentialsTest.php index 5c1936b53..89a4afafa 100644 --- a/tests/ApplicationDefaultCredentialsTest.php +++ b/tests/ApplicationDefaultCredentialsTest.php @@ -49,7 +49,7 @@ class ApplicationDefaultCredentialsTest extends TestCase private $targetAudience = 'a target audience'; private $quotaProject = 'a-quota-project'; private $originalServiceAccount; - private const SDK_DEBUG_FLAG = 'GOOGLE_SDK_PHP_LOGGING'; + private const SDK_DEBUG_ENV_VAR = 'GOOGLE_SDK_PHP_LOGGING'; public function testGetCredentialsFailsIfEnvSpecifiesNonExistentFile() { @@ -777,19 +777,19 @@ public function testExternalAccountCredentials(string $jsonFile, string $expecte public function testGetDefaultLoggerReturnStdOutLoggerIfEnvVarIsPresent() { - putenv($this::SDK_DEBUG_FLAG . '=true'); + putenv($this::SDK_DEBUG_ENV_VAR . '=true'); $logger = ApplicationDefaultCredentials::getDefaultLogger(); $this->assertTrue($logger instanceof StdOutLogger); } public function testGetDefaultLoggerReturnsNullIfNotEnvVar() { - putenv($this::SDK_DEBUG_FLAG . '=false'); + putenv($this::SDK_DEBUG_ENV_VAR . '=false'); $logger = ApplicationDefaultCredentials::getDefaultLogger(); $this->assertNull($logger); - putenv($this::SDK_DEBUG_FLAG . '=0'); + putenv($this::SDK_DEBUG_ENV_VAR . '=0'); $logger = ApplicationDefaultCredentials::getDefaultLogger(); $this->assertNull($logger); @@ -797,7 +797,7 @@ public function testGetDefaultLoggerReturnsNullIfNotEnvVar() public function testGetDefaultLoggerRaiseAWarningIfMisconfiguredAndReturnsNull() { - putenv($this::SDK_DEBUG_FLAG . '=invalid'); + putenv($this::SDK_DEBUG_ENV_VAR . '=invalid'); $this->expectException(Notice::class); $logger = ApplicationDefaultCredentials::getDefaultLogger(); From d611f8e75e56aa345abf8cdddf11cad59a44a9a2 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Wed, 11 Dec 2024 00:34:57 +0000 Subject: [PATCH 47/51] Update max lenght to be in a variable --- src/HttpHandler/Guzzle6HttpHandler.php | 7 ++++++- src/Logging/LoggingTrait.php | 6 ++++-- tests/ApplicationDefaultCredentialsTest.php | 5 +++++ tests/HttpHandler/Guzzle7HttpHandlerTest.php | 6 ++---- tests/Logging/LoggingTraitTest.php | 16 ++++++++++++++-- 5 files changed, 31 insertions(+), 9 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index 012d34388..cfdbcb183 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -65,7 +65,7 @@ public function __invoke(RequestInterface $request, array $options = []) $response = $this->client->send($request, $options); if ($this->logger) { - $this->responseLog($response, $requestEvent); + $this->responseLog($response, $requestEvent); } return $response; @@ -120,6 +120,11 @@ public function requestLog(RequestInterface $request, array $options): RpcLogEve return $requestEvent; } + /** + * @internal + * @param RequestInterface $request + * @param array $options + */ public function responseLog(ResponseInterface $response, RpcLogEvent $requestEvent): void { $responseEvent = new RpcLogEvent($requestEvent->milliseconds); diff --git a/src/Logging/LoggingTrait.php b/src/Logging/LoggingTrait.php index 97c51368a..2441a9bd7 100644 --- a/src/Logging/LoggingTrait.php +++ b/src/Logging/LoggingTrait.php @@ -126,10 +126,12 @@ private function getJwtToken(array $headers): null|array */ private function truncatePayload(null|string $payload): null|string { - if (is_null($payload) || strlen($payload) <= 500) { + $maxLength = 500; + + if (is_null($payload) || strlen($payload) <= $maxLength) { return $payload; } - return substr($payload, 0, 500) . '...'; + return substr($payload, 0, $maxLength) . '...'; } } diff --git a/tests/ApplicationDefaultCredentialsTest.php b/tests/ApplicationDefaultCredentialsTest.php index 89a4afafa..cf6b542d5 100644 --- a/tests/ApplicationDefaultCredentialsTest.php +++ b/tests/ApplicationDefaultCredentialsTest.php @@ -793,6 +793,11 @@ public function testGetDefaultLoggerReturnsNullIfNotEnvVar() $logger = ApplicationDefaultCredentials::getDefaultLogger(); $this->assertNull($logger); + + putenv($this::SDK_DEBUG_ENV_VAR . '='); + $logger = ApplicationDefaultCredentials::getDefaultLogger(); + + $this->assertNull($logger); } public function testGetDefaultLoggerRaiseAWarningIfMisconfiguredAndReturnsNull() diff --git a/tests/HttpHandler/Guzzle7HttpHandlerTest.php b/tests/HttpHandler/Guzzle7HttpHandlerTest.php index 97cb8688d..53147be3a 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -74,11 +74,9 @@ public function testLoggerDoesNotGetsCalledIfLoggerIsNotPassed() $request = new Request('GET', 'https://domain.tld'); $options = ['key' => 'value']; - /** - * @var LoggerInterface $mockLogger - * @var ClientInterface $mockClient - */ $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 index edc85b5bd..211fc4d0f 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -25,11 +25,23 @@ class LoggingTraitTest extends BaseTest { - private MockClassWithLogger $loggerContainer; + private $loggerContainer; public function setUp(): void { - $this->loggerContainer = new MockClassWithLogger(); + $this->loggerContainer = new class() { + use LoggingTrait { + logRequest as public; + logResponse as public; + } + + private LoggerInterface $logger; + + public function __construct() + { + $this->logger = new StdOutLogger(); + } + }; } public function testLogRequest() From 1df9dec6d66b6be99823f7f5431a37cc3fe127a2 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Wed, 11 Dec 2024 00:37:06 +0000 Subject: [PATCH 48/51] Update type doc for requestLog --- src/HttpHandler/Guzzle6HttpHandler.php | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/HttpHandler/Guzzle6HttpHandler.php b/src/HttpHandler/Guzzle6HttpHandler.php index cfdbcb183..ee2739eca 100644 --- a/src/HttpHandler/Guzzle6HttpHandler.php +++ b/src/HttpHandler/Guzzle6HttpHandler.php @@ -101,6 +101,8 @@ public function async(RequestInterface $request, array $options = []) /** * @internal + * @param RequestInterface $request + * @param array $options */ public function requestLog(RequestInterface $request, array $options): RpcLogEvent { @@ -122,8 +124,6 @@ public function requestLog(RequestInterface $request, array $options): RpcLogEve /** * @internal - * @param RequestInterface $request - * @param array $options */ public function responseLog(ResponseInterface $response, RpcLogEvent $requestEvent): void { From 561d198b6bfc21195d1defff28ce26aa8c8f90c6 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Wed, 11 Dec 2024 00:42:25 +0000 Subject: [PATCH 49/51] Remove unused mock class --- tests/Logging/LoggingTraitTest.php | 27 +++------------------------ 1 file changed, 3 insertions(+), 24 deletions(-) diff --git a/tests/Logging/LoggingTraitTest.php b/tests/Logging/LoggingTraitTest.php index 211fc4d0f..c6058fee7 100644 --- a/tests/Logging/LoggingTraitTest.php +++ b/tests/Logging/LoggingTraitTest.php @@ -47,7 +47,7 @@ public function __construct() public function testLogRequest() { $event = $this->getNewLogEvent(); - $this->loggerContainer->logRequestEvent($event); + $this->loggerContainer->logRequest($event); $buffer = $this->getActualOutput(); $jsonParsed = json_decode($buffer, true); @@ -64,7 +64,7 @@ public function testRequestWithoutJwtShouldNotPrintAJwt() { $event = $this->getNewLogEvent(); $event->headers = ['no jwt' => true]; - $this->loggerContainer->logRequestEvent($event); + $this->loggerContainer->logRequest($event); $buffer = $this->getActualOutput(); $jsonParsed = json_decode($buffer, true); @@ -76,7 +76,7 @@ public function testLogResponse() { $event = $this->getNewLogEvent(); $event->headers = ['Thisis' => 'a header']; - $this->loggerContainer->logResponseEvent($event); + $this->loggerContainer->logResponse($event); $buffer = $this->getActualOutput(); @@ -107,24 +107,3 @@ private function getNewLogEvent(): RpcLogEvent return $event; } } - -class MockClassWithLogger -{ - use LoggingTrait; - private LoggerInterface $logger; - - public function __construct() - { - $this->logger = new StdOutLogger(); - } - - public function logRequestEvent(RpcLogEvent $event): void - { - $this->logRequest($event); - } - - public function logResponseEvent(RpcLogEvent $event): void - { - $this->logResponse($event); - } -} From 79fbf1bdc696036bade58e9d51a1df0ccac3bb38 Mon Sep 17 00:00:00 2001 From: Brent Shaffer Date: Tue, 10 Dec 2024 16:44:49 -0800 Subject: [PATCH 50/51] Apply suggestions from code review --- tests/HttpHandler/Guzzle7HttpHandlerTest.php | 2 -- 1 file changed, 2 deletions(-) diff --git a/tests/HttpHandler/Guzzle7HttpHandlerTest.php b/tests/HttpHandler/Guzzle7HttpHandlerTest.php index 53147be3a..07ce63005 100644 --- a/tests/HttpHandler/Guzzle7HttpHandlerTest.php +++ b/tests/HttpHandler/Guzzle7HttpHandlerTest.php @@ -19,12 +19,10 @@ use Google\Auth\HttpHandler\Guzzle7HttpHandler; use Google\Auth\Logging\StdOutLogger; -use GuzzleHttp\ClientInterface; use GuzzleHttp\Promise\Promise; use GuzzleHttp\Psr7\Request; use GuzzleHttp\Psr7\Response; use Prophecy\Argument; -use Psr\Log\LoggerInterface; /** * @group http-handler From 679f1bdd7b3cce0b701991ae06bcb46296f08594 Mon Sep 17 00:00:00 2001 From: hectorhammett Date: Wed, 11 Dec 2024 00:47:44 +0000 Subject: [PATCH 51/51] Remove readonly properties --- src/Logging/RpcLogEvent.php | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Logging/RpcLogEvent.php b/src/Logging/RpcLogEvent.php index 6f6171b2d..50e89fe2f 100644 --- a/src/Logging/RpcLogEvent.php +++ b/src/Logging/RpcLogEvent.php @@ -29,14 +29,14 @@ class RpcLogEvent * * @var string */ - public readonly string $timestamp; + public string $timestamp; /** * The time in milliseconds at time on creation for calculating latency * * @var float */ - public readonly float $milliseconds; + public float $milliseconds; /** * Rest method type