Skip to content

Commit cabed91

Browse files
HectorhammettHectorhammett
authored
feat(BigQuery): Add debug logging to BigQuery (#8790)
1 parent eaad63b commit cabed91

File tree

6 files changed

+246
-7
lines changed

6 files changed

+246
-7
lines changed

‎BigQuery/composer.json‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@
55
"minimum-stability": "stable",
66
"require": {
77
"php": "^8.1",
8-
"google/cloud-core": "^1.64",
8+
"google/cloud-core": "^1.70",
99
"ramsey/uuid": "^3.0|^4.0"
1010
},
1111
"require-dev": {
@@ -16,7 +16,8 @@
1616
"phpdocumentor/reflection-docblock": "^5.3",
1717
"erusev/parsedown": "^1.6",
1818
"google/cloud-storage": "^1.3",
19-
"google/cloud-bigquery-reservation": "^2.0"
19+
"google/cloud-bigquery-reservation": "^2.0",
20+
"nikic/php-parser": "^5.0"
2021
},
2122
"suggest": {
2223
"google/cloud-storage": "Makes it easier to load data from Cloud Storage into BigQuery"

‎BigQuery/src/BigQueryClient.php‎

Lines changed: 63 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,8 @@
1717

1818
namespace Google\Cloud\BigQuery;
1919

20+
use Google\ApiCore\ValidationException;
21+
use Google\Auth\ApplicationDefaultCredentials;
2022
use Google\Auth\FetchAuthTokenInterface;
2123
use Google\Cloud\BigQuery\Connection\ConnectionInterface;
2224
use Google\Cloud\BigQuery\Connection\Rest;
@@ -29,6 +31,8 @@
2931
use Google\Cloud\Core\RetryDeciderTrait;
3032
use Psr\Cache\CacheItemPoolInterface;
3133
use Psr\Http\Message\StreamInterface;
34+
use Psr\Log\LoggerInterface;
35+
use Psr\Log\LogLevel;
3236

3337
/**
3438
* Google Cloud BigQuery allows you to create, manage, share and query data.
@@ -53,7 +57,7 @@ class BigQueryClient
5357
const VERSION = '1.34.7';
5458

5559
const MAX_DELAY_MICROSECONDS = 32000000;
56-
60+
const SERVICE_NAME = 'bigquery';
5761
const SCOPE = 'https://www.googleapis.com/auth/bigquery';
5862
const INSERT_SCOPE = 'https://www.googleapis.com/auth/bigquery.insertdata';
5963

@@ -154,6 +158,9 @@ class BigQueryClient
154158
* fetched over the network it will take precedent over this
155159
* setting (by calling
156160
* {@see Table::reload()}, for example).
161+
* @type false|LoggerInterface $logger
162+
* A PSR-3 compliant logger. If set to false, logging is disabled, ignoring the
163+
* 'GOOGLE_SDK_PHP_LOGGING' environment flag
157164
* }
158165
*/
159166
public function __construct(array $config = [])
@@ -175,10 +182,14 @@ public function __construct(array $config = [])
175182
mt_rand(0, 1000000) + (pow(2, $attempt) * 1000000),
176183
self::MAX_DELAY_MICROSECONDS
177184
);
178-
}
185+
},
179186
//@codeCoverageIgnoreEnd
187+
'logger' => null
180188
];
181189

190+
$config['logger'] = $this->getLogger($config);
191+
$this->logConfiguration($config['logger'], $config);
192+
182193
$this->connection = new Rest($this->configureAuthentication($config));
183194
$this->mapper = new ValueMapper($config['returnInt64AsObject']);
184195
}
@@ -1073,4 +1084,54 @@ public function load(array $options = [])
10731084
$this->location
10741085
);
10751086
}
1087+
1088+
/**
1089+
* Gets the appropriate logger depending on the configuration passed by the user.
1090+
*
1091+
* @param array $config The client configuration
1092+
* @return LoggerInterface|false|null
1093+
* @throws ValidationException
1094+
*/
1095+
private function getLogger(array $config): LoggerInterface|false|null
1096+
{
1097+
$configuration = $config['logger'];
1098+
1099+
if (is_null($configuration)) {
1100+
return ApplicationDefaultCredentials::getDefaultLogger();
1101+
}
1102+
1103+
if ($configuration !== false && !$configuration instanceof LoggerInterface) {
1104+
throw new ValidationException(
1105+
'The "logger" option in the options array should be PSR-3 LoggerInterface compatible.'
1106+
);
1107+
}
1108+
1109+
return $configuration;
1110+
}
1111+
1112+
/**
1113+
* Log the current configuration for the client
1114+
*
1115+
* @param LoggerInterface|false|null $logger The logger to be used.
1116+
* @param array $config The client configuration
1117+
* @return void
1118+
*/
1119+
private function logConfiguration(LoggerInterface|false|null $logger, array $config): void
1120+
{
1121+
if (!$logger) {
1122+
return;
1123+
}
1124+
1125+
$configurationLog = [
1126+
'timestamp' => date(DATE_RFC3339),
1127+
'severity' => strtoupper(LogLevel::DEBUG),
1128+
'processId' => getmypid(),
1129+
'jsonPayload' => [
1130+
'serviceName' => self::SERVICE_NAME,
1131+
'clientConfiguration' => $config,
1132+
]
1133+
];
1134+
1135+
$logger->debug(json_encode($configurationLog));
1136+
}
10761137
}

‎BigQuery/src/Connection/Rest.php‎

Lines changed: 33 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,9 @@
1717

1818
namespace Google\Cloud\BigQuery\Connection;
1919

20+
use Exception;
2021
use Google\Auth\GetUniverseDomainInterface;
22+
use Google\Auth\HttpHandler\HttpHandlerFactory;
2123
use Google\Cloud\BigQuery\BigQueryClient;
2224
use Google\Cloud\Core\RequestBuilder;
2325
use Google\Cloud\Core\RequestWrapper;
@@ -71,6 +73,7 @@ public function __construct(array $config = [])
7173
'serviceDefinitionPath' => __DIR__ . '/ServiceDefinition/bigquery-v2.json',
7274
'componentVersion' => BigQueryClient::VERSION,
7375
'apiEndpoint' => null,
76+
'logger' => null,
7477
// If the user has not supplied a universe domain, use the environment variable if set.
7578
// Otherwise, use the default ("googleapis.com").
7679
'universeDomain' => getenv('GOOGLE_CLOUD_UNIVERSE_DOMAIN')
@@ -79,7 +82,7 @@ public function __construct(array $config = [])
7982

8083
$apiEndpoint = $this->getApiEndpoint(null, $config, self::DEFAULT_API_ENDPOINT_TEMPLATE);
8184

82-
$this->setRequestWrapper(new RequestWrapper($config));
85+
$this->setRequestWrapper($this->getRequestWrapper($config));
8386
$this->setRequestBuilder(new RequestBuilder(
8487
$config['serviceDefinitionPath'],
8588
$apiEndpoint
@@ -419,4 +422,33 @@ public function testTableIamPermissions(array $args = [])
419422
{
420423
return $this->send('tables', 'testIamPermissions', $args);
421424
}
425+
426+
/**
427+
* Creates a request wrapper and sets the HTTP Handler logger to the configured one.
428+
*
429+
* @param array $config
430+
* @return RequestWrapper
431+
*/
432+
private function getRequestWrapper(array $config): RequestWrapper
433+
{
434+
// Because we are setting a logger, we build a handler here instead of using the default
435+
$config['httpHandler'] ??= HttpHandlerFactory::build(logger: $config['logger']);
436+
$config['restRetryListener'] = $this->getRetryListener();
437+
return new RequestWrapper($config);
438+
}
439+
440+
/**
441+
* Returns a function that the RequestWrapper uses between retries. In our listener we modify the call options
442+
* to add the `retryAttempt` field to the call options for our Auth httpHandler logging logic. This way, the logging
443+
* logic has access to the retry attempt.
444+
*
445+
* @return callable
446+
*/
447+
private function getRetryListener(): callable
448+
{
449+
return function (Exception $ex, int $retryAttempt, array &$arguments) {
450+
// The REST calls are [$request, $options]. We need to modify the options.
451+
$arguments[1]['retryAttempt'] = $retryAttempt;
452+
};
453+
}
422454
}

‎BigQuery/tests/Unit/BigQueryClientTest.php‎

Lines changed: 113 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,9 @@
1717

1818
namespace Google\Cloud\BigQuery\Tests\Unit;
1919

20+
use Google\ApiCore\ValidationException;
21+
use Google\Auth\FetchAuthTokenInterface;
22+
use Google\Auth\HttpHandler\Guzzle6HttpHandler;
2023
use Google\Cloud\BigQuery\BigNumeric;
2124
use Google\Cloud\BigQuery\BigQueryClient;
2225
use Google\Cloud\BigQuery\Bytes;
@@ -36,11 +39,20 @@
3639
use Google\Cloud\BigQuery\Time;
3740
use Google\Cloud\BigQuery\Timestamp;
3841
use Google\Cloud\Core\Int64;
42+
use Google\Cloud\Core\Testing\Snippet\Fixtures;
3943
use Google\Cloud\Core\Testing\TestHelpers;
4044
use Google\Cloud\Core\Upload\AbstractUploader;
45+
use GuzzleHttp\Client;
46+
use GuzzleHttp\Handler\MockHandler;
47+
use GuzzleHttp\HandlerStack;
48+
use GuzzleHttp\Psr7\Request;
49+
use GuzzleHttp\Psr7\Response;
50+
use GuzzleHttp\Exception\RequestException;
4151
use PHPUnit\Framework\TestCase;
4252
use Prophecy\Argument;
4353
use Prophecy\PhpUnit\ProphecyTrait;
54+
use Psr\Log\LoggerInterface;
55+
use stdClass;
4456

4557
/**
4658
* @group bigquery
@@ -698,4 +710,105 @@ public function testGetsJson()
698710

699711
$this->assertInstanceOf(Json::class, $json);
700712
}
713+
714+
/**
715+
* @runInSeparateProcess
716+
*/
717+
public function testEnablingLoggerWithFlagLogsToStdOut()
718+
{
719+
putenv('GOOGLE_SDK_PHP_LOGGING=true');
720+
$client = new BigQueryClient([
721+
'projectId' => self::PROJECT_ID,
722+
'keyFilePath' => Fixtures::KEYFILE_STUB_FIXTURE()
723+
]);
724+
725+
$output = $this->getActualOutput();
726+
$parsed = json_decode($output, true);
727+
$this->assertNotFalse($parsed);
728+
$this->assertArrayHasKey('severity', $parsed);
729+
}
730+
731+
/**
732+
* @runInSeparateProcess
733+
*/
734+
public function testDisableLoggerWithOptionsDoesNotLogToStdOut()
735+
{
736+
putenv('GOOGLE_SDK_PHP_LOGGING=true');
737+
$client = new BigQueryClient([
738+
'projectId' => self::PROJECT_ID,
739+
'keyFilePath' => Fixtures::KEYFILE_STUB_FIXTURE(),
740+
'logger' => false
741+
]);
742+
743+
$output = $this->getActualOutput();
744+
$this->assertEmpty($output);
745+
}
746+
747+
public function testPassingTheWrongLoggerRaisesAnException()
748+
{
749+
$this->expectException(ValidationException::class);
750+
751+
$client = new BigQueryClient([
752+
'projectId' => self::PROJECT_ID,
753+
'keyFilePath' => Fixtures::KEYFILE_STUB_FIXTURE(),
754+
'logger' => new stdClass()
755+
]);
756+
}
757+
758+
public function testRetryLogging()
759+
{
760+
$doneJobResponse = $this->jobResponse;
761+
$doneJobResponse['status']['state'] = 'DONE';
762+
763+
$apiMockHandler = new MockHandler([
764+
new RequestException(
765+
'Transient error',
766+
new Request('POST', ''),
767+
new Response(502)
768+
),
769+
new Response(200, [], json_encode($this->jobResponse)),
770+
new Response(200, [], json_encode($doneJobResponse))
771+
]);
772+
773+
$authMockHandler = new MockHandler([
774+
new Response(200, [], json_encode(['access_token' => 'token']))
775+
]);
776+
777+
$retryCallOptionAppeared = false;
778+
$logger = $this->prophesize(LoggerInterface::class);
779+
$logger->debug(
780+
Argument::that(function (string $jsonString) use (&$retryCallOptionAppeared) {
781+
$jsonParsed = json_decode($jsonString, true);
782+
if (isset($jsonParsed['jsonPayload']['retryAttempt'])) {
783+
$retryCallOptionAppeared = true;
784+
}
785+
return true;
786+
})
787+
)->shouldBeCalled();
788+
789+
$credentials = $this->prophesize(FetchAuthTokenInterface::class);
790+
$credentials->fetchAuthToken(Argument::any())
791+
->willReturn(['access_token' => 'foo']);
792+
793+
$apiHandlerStack = HandlerStack::create($apiMockHandler);
794+
$apiHttpClient = new Client(['handler' => $apiHandlerStack]);
795+
796+
$authHandlerStack = HandlerStack::create($authMockHandler);
797+
$authHttpClient = new Client(['handler' => $authHandlerStack]);
798+
799+
$client = new BigQueryClient([
800+
'credentials' => $credentials->reveal(),
801+
'projectId' => self::PROJECT_ID,
802+
'logger' => $logger->reveal(),
803+
'httpHandler' => new Guzzle6HttpHandler($apiHttpClient, $logger->reveal()),
804+
'authHttpHandler' => new Guzzle6HttpHandler($authHttpClient)
805+
]);
806+
807+
$queryConfig = $client->query(
808+
'SELECT * FROM `random_project.random_dataset.random_table`'
809+
);
810+
811+
$client->startQuery($queryConfig);
812+
$this->assertTrue($retryCallOptionAppeared);
813+
}
701814
}

‎Core/src/RequestWrapper.php‎

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -83,6 +83,12 @@ class RequestWrapper
8383
*/
8484
private $retryFunction;
8585

86+
/**
87+
* @var callable|null Lets the user listen for retries and
88+
* modify the next retry arguments
89+
*/
90+
private $retryListener;
91+
8692
/**
8793
* @var callable Executes a delay.
8894
*/
@@ -136,6 +142,8 @@ class RequestWrapper
136142
* determining how long to wait between attempts to retry. Function
137143
* signature should match: `function (int $attempt) : int`.
138144
* @type string $universeDomain The expected universe of the credentials. Defaults to "googleapis.com".
145+
* @type callable $restRetryListener A function to run custom logic between retries. This function can modify
146+
* the next server call arguments for the next retry.
139147
* }
140148
*/
141149
public function __construct(array $config = [])
@@ -151,6 +159,7 @@ public function __construct(array $config = [])
151159
'componentVersion' => null,
152160
'restRetryFunction' => null,
153161
'restDelayFunction' => null,
162+
'restRetryListener' => null,
154163
'restCalcDelayFunction' => null,
155164
'universeDomain' => GetUniverseDomainInterface::DEFAULT_UNIVERSE_DOMAIN,
156165
];
@@ -160,6 +169,7 @@ public function __construct(array $config = [])
160169
$this->restOptions = $config['restOptions'];
161170
$this->shouldSignRequest = $config['shouldSignRequest'];
162171
$this->retryFunction = $config['restRetryFunction'] ?: $this->getRetryFunction();
172+
$this->retryListener = $config['restRetryListener'];
163173
$this->delayFunction = $config['restDelayFunction'] ?: function ($delay) {
164174
usleep($delay);
165175
};
@@ -362,7 +372,7 @@ private function applyHeaders(RequestInterface $request, array $options = [])
362372
*/
363373
private function addAuthHeaders(RequestInterface $request, FetchAuthTokenInterface $fetcher)
364374
{
365-
$backoff = new ExponentialBackoff($this->retries, $this->getRetryFunction());
375+
$backoff = new ExponentialBackoff($this->retries, $this->getRetryFunction(), $this->retryListener);
366376

367377
try {
368378
return $backoff->execute(
@@ -485,7 +495,7 @@ private function getRetryOptions(array $options)
485495
: $this->retryFunction,
486496
'retryListener' => isset($options['restRetryListener'])
487497
? $options['restRetryListener']
488-
: null,
498+
: $this->retryListener,
489499
'delayFunction' => isset($options['restDelayFunction'])
490500
? $options['restDelayFunction']
491501
: $this->delayFunction,

0 commit comments

Comments
 (0)