Setting a per-call timeout in nodejs-CodePudding

Thanks in advance for any help here.

I am trying to set a per-call timeout in the Spanner nodejs client. I have read through the given Spanner documentation, the best of which is here: https://cloud.google.com/spanner/docs/custom-timeout-and-retry. This documentation leaves out that you need to be supplying gaxOptions. Or I'm misunderstanding, which would not be surprising given that I can't explain the behavior I'm seeing.

I created a small repo to house this reproduction here: https://github.com/brg8/spanner-nodejs-timeout-repro. Code also pasted below.

const PROJECT_ID_HERE = "";
const SPANNER_INSTANCE_ID_HERE = "";
const SPANNER_DATABASE_HERE = "";
const TABLE_NAME_HERE = "";

const { Spanner } = require("@google-cloud/spanner");

let client = null;
client = new Spanner({
    projectId: PROJECT_ID_HERE,
});
const instance = client.instance(SPANNER_INSTANCE_ID_HERE);
const database = instance.database(SPANNER_DATABASE_HERE);

async function runQuery(additionalOptions = {}) {
  const t1 = new Date();
  try {
    console.log("Launching query...");
    await database.run({
      sql: `SELECT * FROM ${TABLE_NAME_HERE} LIMIT 1000;`,
      ...additionalOptions,
    });
    console.log("Everything finished.");
  } catch (err) {
    console.log(err);
    console.log("Timed out after", new Date() - t1);
  }
};

// Query finishes, no timeout (as expected)
runQuery();
/*
Launching query...
Everything finished.
*/

// Query times out (as expected)
// However, it only times out after 7-8 seconds
runQuery({
  gaxOptions: {
    timeout: 1,
  },
});
/*
Launching query...
Error: 4 DEADLINE_EXCEEDED: Deadline exceeded
    at Object.callErrorFromStatus (/Users/benjamingodlove/Developer/spanner-node-repro/node_modules/@grpc/grpc-js/build/src/call.js:31:26)
    at Object.onReceiveStatus (/Users/benjamingodlove/Developer/spanner-node-repro/node_modules/@grpc/grpc-js/build/src/client.js:330:49)
    at /Users/benjamingodlove/Developer/spanner-node-repro/node_modules/@grpc/grpc-js/build/src/call-stream.js:80:35
    at Object.onReceiveStatus (/Users/benjamingodlove/Developer/spanner-node-repro/node_modules/grpc-gcp/build/src/index.js:73:29)
    at InterceptingListenerImpl.onReceiveStatus (/Users/benjamingodlove/Developer/spanner-node-repro/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:23)
    at Object.onReceiveStatus (/Users/benjamingodlove/Developer/spanner-node-repro/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:299:181)
    at /Users/benjamingodlove/Developer/spanner-node-repro/node_modules/@grpc/grpc-js/build/src/call-stream.js:145:78
    at processTicksAndRejections (node:internal/process/task_queues:76:11) {
  code: 4,
  details: 'Deadline exceeded',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}
Timed out after 7238
*/

And my package.json

{
  "name": "spanner-node-repro",
  "version": "1.0.0",
  "description": "Reproducing timeout wonkiness with Spanner.",
  "main": "index.js",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "author": "",
  "license": "ISC",
  "dependencies": {
    "@google-cloud/spanner": "^5.15.2"
  }
}

Any insight is appreciated!

Ben Godlove

CodePudding user response：

TLDR

Add retryRequestOptions: {noResponseRetries: 0}, to your gaxOptions so you get the following options:

const query = {
  sql: 'SELECT ...',
  gaxOptions: {
    timeout: 1,
    retryRequestOptions: {noResponseRetries: 0},
  },
};

Longer Version

What is happening under the hood is the following:

The (streaming) query request is sent and the timeout occurs before the server returns any response.
The default retry settings include a noResponseRetries: 2 option, which means that the request will be retried twice if the client did not receive any response at all.
The retry of the request will only start after a randomized retry delay. This delay also increases for each retry attempt.
After retrying twice (so after sending in total 3 requests) the DEADLINE_EXCEEDED error will be propagated to the client. These retries take approximately 7 seconds because the first retry waits approx 2.5 seconds and the second 4.5 seconds (both values contain a random jitter value of 1 second, so the actual value will always be between 6 and 8 seconds)

Setting noResponseRetries: 0 disables the retries of requests that do not receive a response from the server.

You will also see that if you set the timeout to more 'reasonable' value that you will see that the query times out in a normal way, as the server has a chance to respond. Setting it to something like 1500 (meaning 1500ms, i.e. 1.5 seconds) causes the timeout to work as expected for me using your sample code.