feat(BigQuery): Add logging functionality to BigQuery

BigQuery/composer.json

@@ -5,7 +5,7 @@
     "minimum-stability": "stable",
     "require": {
         "php": "^8.1",
-        "google/cloud-core": "^1.64",
+        "google/cloud-core": "^1.70",
         "ramsey/uuid": "^3.0|^4.0"
     },
     "require-dev": {
@@ -16,7 +16,8 @@
         "phpdocumentor/reflection-docblock": "^5.3",
         "erusev/parsedown": "^1.6",
         "google/cloud-storage": "^1.3",
-        "google/cloud-bigquery-reservation": "^2.0"
+        "google/cloud-bigquery-reservation": "^2.0",
+        "nikic/php-parser": "^5.0"
     },
     "suggest": {
         "google/cloud-storage": "Makes it easier to load data from Cloud Storage into BigQuery"

BigQuery/src/BigQueryClient.php

@@ -17,6 +17,8 @@
 
 namespace Google\Cloud\BigQuery;
 
+use Google\ApiCore\ValidationException;
+use Google\Auth\ApplicationDefaultCredentials;
 use Google\Auth\FetchAuthTokenInterface;
 use Google\Cloud\BigQuery\Connection\ConnectionInterface;
 use Google\Cloud\BigQuery\Connection\Rest;
@@ -29,6 +31,8 @@
 use Google\Cloud\Core\RetryDeciderTrait;
 use Psr\Cache\CacheItemPoolInterface;
 use Psr\Http\Message\StreamInterface;
+use Psr\Log\LoggerInterface;
+use Psr\Log\LogLevel;
 
 /**
  * Google Cloud BigQuery allows you to create, manage, share and query data.
@@ -53,7 +57,7 @@ class BigQueryClient
     const VERSION = '1.34.7';
 
     const MAX_DELAY_MICROSECONDS = 32000000;
-
+    const SERVICE_NAME = 'bigquery';
     const SCOPE = 'https://www.googleapis.com/auth/bigquery';
     const INSERT_SCOPE = 'https://www.googleapis.com/auth/bigquery.insertdata';
 
@@ -154,6 +158,9 @@ class BigQueryClient
      *           fetched over the network it will take precedent over this
      *           setting (by calling
      *           {@see Table::reload()}, for example).
+     *     @type false|LoggerInterface $logger
+     *           A PSR-3 compliant logger. If set to false, logging is disabled, ignoring the
+     *           'GOOGLE_SDK_PHP_LOGGING' environment flag
      * }
      */
     public function __construct(array $config = [])
@@ -175,10 +182,14 @@ public function __construct(array $config = [])
                     mt_rand(0, 1000000) + (pow(2, $attempt) * 1000000),
                     self::MAX_DELAY_MICROSECONDS
                 );
-            }
+            },
             //@codeCoverageIgnoreEnd
+            'logger' => null
         ];
 
+        $config['logger'] = $this->getLogger($config);
+        $this->logConfiguration($config['logger'], $config);
+
         $this->connection = new Rest($this->configureAuthentication($config));
         $this->mapper = new ValueMapper($config['returnInt64AsObject']);
     }
@@ -1073,4 +1084,54 @@ public function load(array $options = [])
             $this->location
         );
     }
+
+    /**
+     * Gets the appropriate logger depending on the configuration passed by the user.
+     *
+     * @param array $config The client configuration
+     * @return LoggerInterface|false|null
+     * @throws ValidationException
+     */
+    private function getLogger(array $config): LoggerInterface|false|null
+    {
+        $configuration = $config['logger'];
+
+        if (is_null($configuration)) {
+            return ApplicationDefaultCredentials::getDefaultLogger();
+        }
+
+        if ($configuration !== false && !$configuration instanceof LoggerInterface) {
+            throw new ValidationException(
+                'The "logger" option in the options array should be PSR-3 LoggerInterface compatible.'
+            );
+        }
+
+        return $configuration;
+    }
+
+    /**
+     * Log the current configuration for the client
+     *
+     * @param LoggerInterface|false|null $logger The logger to be used.
+     * @param array $config The client configuration
+     * @return void
+     */
+    private function logConfiguration(LoggerInterface|false|null $logger, array $config): void
+    {
+        if (!$logger) {
+            return;
+        }
+
+        $configurationLog = [
+            'timestamp' => date(DATE_RFC3339),
+            'severity' => strtoupper(LogLevel::DEBUG),
+            'processId' => getmypid(),
+            'jsonPayload' => [
+                'serviceName' => self::SERVICE_NAME,
+                'clientConfiguration' => $config,
+            ]
+        ];
+
+        $logger->debug(json_encode($configurationLog));
+    }
 }

BigQuery/src/Connection/Rest.php

@@ -17,7 +17,9 @@
 
 namespace Google\Cloud\BigQuery\Connection;
 
+use Exception;
 use Google\Auth\GetUniverseDomainInterface;
+use Google\Auth\HttpHandler\HttpHandlerFactory;
 use Google\Cloud\BigQuery\BigQueryClient;
 use Google\Cloud\Core\RequestBuilder;
 use Google\Cloud\Core\RequestWrapper;
@@ -71,6 +73,7 @@ public function __construct(array $config = [])
             'serviceDefinitionPath' => __DIR__ . '/ServiceDefinition/bigquery-v2.json',
             'componentVersion' => BigQueryClient::VERSION,
             'apiEndpoint' => null,
+            'logger' => null,
             // If the user has not supplied a universe domain, use the environment variable if set.
             // Otherwise, use the default ("googleapis.com").
             'universeDomain' => getenv('GOOGLE_CLOUD_UNIVERSE_DOMAIN')
@@ -79,7 +82,7 @@ public function __construct(array $config = [])
 
         $apiEndpoint = $this->getApiEndpoint(null, $config, self::DEFAULT_API_ENDPOINT_TEMPLATE);
 
-        $this->setRequestWrapper(new RequestWrapper($config));
+        $this->setRequestWrapper($this->getRequestWrapper($config));
         $this->setRequestBuilder(new RequestBuilder(
             $config['serviceDefinitionPath'],
             $apiEndpoint
@@ -419,4 +422,33 @@ public function testTableIamPermissions(array $args = [])
     {
         return $this->send('tables', 'testIamPermissions', $args);
     }
+
+    /**
+     * Creates a request wrapper and sets the HTTP Handler logger to the configured one.
+     *
+     * @param array $config
+     * @return RequestWrapper
+     */
+    private function getRequestWrapper(array $config): RequestWrapper
+    {
+        // Because we are setting a logger, we build a handler here instead of using the default
+        $config['httpHandler'] ??= HttpHandlerFactory::build(logger: $config['logger']);
+        $config['restRetryListener'] = $this->getRetryListener();
+        return new RequestWrapper($config);
+    }
+
+    /**
+     * Returns a function that the RequestWrapper uses between retries. In our listener we modify the call options
+     * to add the `retryAttempt` field to the call options for our Auth httpHandler logging logic. This way, the logging
+     * logic has access to the retry attempt.
+     *
+     * @return callable
+     */
+    private function getRetryListener(): callable
+    {
+        return function (Exception $ex, int $retryAttempt, array &$arguments) {
+            // The REST calls are [$request, $options]. We need to modify the options.
+            $arguments[1]['retryAttempt'] = $retryAttempt;
+        };
+    }
 }

BigQuery/tests/Unit/BigQueryClientTest.php

@@ -17,6 +17,9 @@
 
 namespace Google\Cloud\BigQuery\Tests\Unit;
 
+use Google\ApiCore\ValidationException;
+use Google\Auth\FetchAuthTokenInterface;
+use Google\Auth\HttpHandler\Guzzle6HttpHandler;
 use Google\Cloud\BigQuery\BigNumeric;
 use Google\Cloud\BigQuery\BigQueryClient;
 use Google\Cloud\BigQuery\Bytes;
@@ -36,11 +39,20 @@
 use Google\Cloud\BigQuery\Time;
 use Google\Cloud\BigQuery\Timestamp;
 use Google\Cloud\Core\Int64;
+use Google\Cloud\Core\Testing\Snippet\Fixtures;
 use Google\Cloud\Core\Testing\TestHelpers;
 use Google\Cloud\Core\Upload\AbstractUploader;
+use GuzzleHttp\Client;
+use GuzzleHttp\Handler\MockHandler;
+use GuzzleHttp\HandlerStack;
+use GuzzleHttp\Psr7\Request;
+use GuzzleHttp\Psr7\Response;
+use GuzzleHttp\Exception\RequestException;
 use PHPUnit\Framework\TestCase;
 use Prophecy\Argument;
 use Prophecy\PhpUnit\ProphecyTrait;
+use Psr\Log\LoggerInterface;
+use stdClass;
 
 /**
  * @group bigquery
@@ -698,4 +710,105 @@ public function testGetsJson()
 
         $this->assertInstanceOf(Json::class, $json);
     }
+
+    /**
+     * @runInSeparateProcess
+     */
+    public function testEnablingLoggerWithFlagLogsToStdOut()
+    {
+        putenv('GOOGLE_SDK_PHP_LOGGING=true');
+        $client = new BigQueryClient([
+            'projectId' => self::PROJECT_ID,
+            'keyFilePath' => Fixtures::KEYFILE_STUB_FIXTURE()
+        ]);
+
+        $output = $this->getActualOutput();
+        $parsed = json_decode($output, true);
+        $this->assertNotFalse($parsed);
+        $this->assertArrayHasKey('severity', $parsed);
+    }
+
+    /**
+     * @runInSeparateProcess
+     */
+    public function testDisableLoggerWithOptionsDoesNotLogToStdOut()
+    {
+        putenv('GOOGLE_SDK_PHP_LOGGING=true');
+        $client = new BigQueryClient([
+            'projectId' => self::PROJECT_ID,
+            'keyFilePath' => Fixtures::KEYFILE_STUB_FIXTURE(),
+            'logger' => false
+        ]);
+
+        $output = $this->getActualOutput();
+        $this->assertEmpty($output);
+    }
+
+    public function testPassingTheWrongLoggerRaisesAnException()
+    {
+        $this->expectException(ValidationException::class);
+
+        $client = new BigQueryClient([
+            'projectId' => self::PROJECT_ID,
+            'keyFilePath' => Fixtures::KEYFILE_STUB_FIXTURE(),
+            'logger' => new stdClass()
+        ]);
+    }
+
+    public function testRetryLogging()
+    {
+        $doneJobResponse = $this->jobResponse;
+        $doneJobResponse['status']['state'] = 'DONE';
+
+        $apiMockHandler = new MockHandler([
+            new RequestException(
+                'Transient error',
+                new Request('POST', ''),
+                new Response(502)
+            ),
+            new Response(200, [], json_encode($this->jobResponse)),
+            new Response(200, [], json_encode($doneJobResponse))
+        ]);
+
+        $authMockHandler = new MockHandler([
+            new Response(200, [], json_encode(['access_token' => 'token']))
+        ]);
+
+        $retryCallOptionAppeared = false;
+        $logger = $this->prophesize(LoggerInterface::class);
+        $logger->debug(
+            Argument::that(function (string $jsonString) use (&$retryCallOptionAppeared) {
+                $jsonParsed = json_decode($jsonString, true);
+                if (isset($jsonParsed['jsonPayload']['retryAttempt'])) {
+                    $retryCallOptionAppeared = true;
+                }
+                return true;
+            })
+        )->shouldBeCalled();
+
+        $credentials = $this->prophesize(FetchAuthTokenInterface::class);
+        $credentials->fetchAuthToken(Argument::any())
+            ->willReturn(['access_token' => 'foo']);
+
+        $apiHandlerStack = HandlerStack::create($apiMockHandler);
+        $apiHttpClient = new Client(['handler' => $apiHandlerStack]);
+
+        $authHandlerStack = HandlerStack::create($authMockHandler);
+        $authHttpClient = new Client(['handler' => $authHandlerStack]);
+
+        $client = new BigQueryClient([
+            'credentials' => $credentials->reveal(),
+            'projectId' => self::PROJECT_ID,
+            'logger' => $logger->reveal(),
+            'httpHandler' => new Guzzle6HttpHandler($apiHttpClient, $logger->reveal()),
+            'authHttpHandler' => new Guzzle6HttpHandler($authHttpClient)
+        ]);
+
+        $queryConfig = $client->query(
+            'SELECT * FROM `random_project.random_dataset.random_table`'
+        );
+
+        $client->startQuery($queryConfig);
+        $this->assertTrue($retryCallOptionAppeared);
+    }
 }

Core/src/RequestWrapper.php

@@ -83,6 +83,12 @@ class RequestWrapper
      */
     private $retryFunction;
 
+    /**
+     * @var callable|null Lets the user listen for retries and
+     * modify the next retry arguments
+     */
+    private $retryListener;
+
     /**
      * @var callable Executes a delay.
      */
@@ -136,6 +142,8 @@ class RequestWrapper
      *           determining how long to wait between attempts to retry. Function
      *           signature should match: `function (int $attempt) : int`.
      *     @type string $universeDomain The expected universe of the credentials. Defaults to "googleapis.com".
+     *     @type callable $restRetryListener A function to run custom logic between retries. This function can modify
+     *           the next server call arguments for the next retry.
      * }
      */
     public function __construct(array $config = [])
@@ -151,6 +159,7 @@ public function __construct(array $config = [])
             'componentVersion' => null,
             'restRetryFunction' => null,
             'restDelayFunction' => null,
+            'restRetryListener' => null,
             'restCalcDelayFunction' => null,
             'universeDomain' => GetUniverseDomainInterface::DEFAULT_UNIVERSE_DOMAIN,
         ];
@@ -160,6 +169,7 @@ public function __construct(array $config = [])
         $this->restOptions = $config['restOptions'];
         $this->shouldSignRequest = $config['shouldSignRequest'];
         $this->retryFunction = $config['restRetryFunction'] ?: $this->getRetryFunction();
+        $this->retryListener = $config['restRetryListener'];
         $this->delayFunction = $config['restDelayFunction'] ?: function ($delay) {
             usleep($delay);
         };
@@ -362,7 +372,7 @@ private function applyHeaders(RequestInterface $request, array $options = [])
      */
     private function addAuthHeaders(RequestInterface $request, FetchAuthTokenInterface $fetcher)
     {
-        $backoff = new ExponentialBackoff($this->retries, $this->getRetryFunction());
+        $backoff = new ExponentialBackoff($this->retries, $this->getRetryFunction(), $this->retryListener);
 
         try {
             return $backoff->execute(
@@ -485,7 +495,7 @@ private function getRetryOptions(array $options)
                 : $this->retryFunction,
             'retryListener' => isset($options['restRetryListener'])
                 ? $options['restRetryListener']
-                : null,
+                : $this->retryListener,
             'delayFunction' => isset($options['restDelayFunction'])
                 ? $options['restDelayFunction']
                 : $this->delayFunction,