BAD_SESSION on retries

[turikhay]

Я использую @ydbjs, чтобы подключаться к serverless БД в облаке Яндекса. Клиентом выступает бот, работающий на Cloud Functions.

Во времена пиковых загрузок я заметил, что функция «зависает» и убивается сервисом по тайм-ауту. При этом в логах Node периодически (не всегда) жалуется на то, что что-то в коде вызывает слишком большой setTimeout.

Скриншот из Cloud Functions

Я так понимаю, это из-за того, что в retryConfig указан budget: Infinity. Но основная проблема, скорее всего, в другом. Дебаг на локальной машине показал то, что это может быть недочётом в @ydbjs/query.

Из логов:

1. ydbjs:driver driver is ready <-- ок
2. ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted <-- так пару раз
3. attempt 3: calling retry function, ydbjs:query creating query client for nodeId: 50150n <-- новая попытка
4. ydbjs:query query part failed, status: 400100 <-- BAD_SESSION
5. ydbjs:retry attempt 3: no delay before next retry, ydbjs:query query part failed, status: 400100 <-- и так по кругу

dev.js

import { getSACredentialsFromJson, IamAuthService } from "ydb-sdk";
import { Driver } from "@ydbjs/core";
import { retry } from '@ydbjs/retry';
import { AccessTokenCredentialsProvider } from "@ydbjs/auth/access-token";
import { query } from "@ydbjs/query";

const saKeyFile = process.env.SA_KEY_FILE;
const saCredentials = getSACredentialsFromJson(saKeyFile);
const authService = new IamAuthService(saCredentials);
const token = (await authService.getAuthMetadata()).get("x-ydb-auth-ticket")[0];
const credentialsProvider = new AccessTokenCredentialsProvider({ token });
const ydb = new Driver(process.env.YDB_CONNECTION_STRING, {
  credentialsProvider,
  "ydb.sdk.ready_timeout_ms": 5000,
  "ydb.sdk.token_timeout_ms": 5000,
  "ydb.sdk.enable_discovery": false,
});
await retry({
  budget: 2,
}, async (signal) => {
  await ydb.ready(signal);
});
await ydb.ready();
const sql = query(ydb);
console.log(await sql`SELECT 1`);

Полные логи

$ DEBUG=ydbjs:* node --trace-warnings dev.js 
  ydbjs:driver Driver(connectionString: grpcs://ydb.serverless.yandexcloud.net:2135/?database=/ru-central1/<...>, options: { credentialsProvider: AccessTokenCredentialsProvider { middleware: [Function: bound middleware] AsyncGeneratorFunction }, 'ydb.sdk.ready_timeout_ms': 5000, 'ydb.sdk.token_timeout_ms': 5000, 'ydb.sdk.enable_discovery': false }) +0ms
  ydbjs:driver:pool creating connection pool +0ms
  ydbjs:driver:conn create channel to node id=-1n address=ydb.serverless.yandexcloud.net:2135 +0ms
  ydbjs:driver discovery disabled, using single endpoint +2ms
  ydbjs:retry attempt 1: calling retry function +0ms
  ydbjs:driver waiting for driver to become ready +0ms
  ydbjs:driver single endpoint ready +104ms
  ydbjs:driver driver is ready +0ms
  ydbjs:retry attempt 1: success +105ms
  ydbjs:driver waiting for driver to become ready +1ms
  ydbjs:driver driver is ready +0ms
  ydbjs:query creating query instance for text: SELECT 1 +0ms
  ydbjs:query starting query execution: SELECT 1 +1ms
  ydbjs:driver waiting for driver to become ready +1ms
  ydbjs:driver driver is ready +0ms
  ydbjs:retry attempt 1: calling retry function +0ms
  ydbjs:query creating query client for nodeId: undefined +0ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService +1ms
  ydbjs:query creating new session +1ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/CreateSession OK +0ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +30ms
  ydbjs:query session ydb://session/3?node_id=50150&id=NDhjMmEzOWEtZWExZDZjNDYtMzU4OWQ1NDAtNTllOWU5OGM= created and attached +53ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted +619ms
  ydbjs:retry attempt 1: waiting 1349 ms before next retry +651ms
  ydbjs:query retrying query, attempt 1, error: ClientError: /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted
  ydbjs:query     at wrapClientError (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/wrapClientError.js:9:16)
  ydbjs:query     at Object.serverStreamingMethod [as next] (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/createServerStreamingMethod.js:41:57)
  ydbjs:query     at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
  ydbjs:query     at async debug (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/core/dist/middleware.js:8:16)
  ydbjs:query     at async AccessTokenCredentialsProvider.middleware (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/auth/dist/index.js:11:16)
  ydbjs:query     at async Object.next (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/createServerStreamingMethod.js:68:40)
  ydbjs:query     at async file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/query/dist/query.js:160:28
  ydbjs:query     at async retry (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/query/node_modules/@ydbjs/retry/dist/index.js:24:26)
  ydbjs:query     at async file:///home/turikhay/projects/o6o2/bot/dev.js:25:13 {
  ydbjs:query   path: '/Ydb.Query.V1.QueryService/ExecuteQuery',
  ydbjs:query   code: 8,
  ydbjs:query   details: 'ResourceExhausted'
  ydbjs:query } +2s
  ydbjs:retry attempt 2: calling retry function +1s
  ydbjs:query creating query client for nodeId: 50150n +1ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +2s
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted +2s
  ydbjs:retry attempt 2: waiting 3601 ms before next retry +399ms
  ydbjs:query retrying query, attempt 2, error: ClientError: /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted
  ydbjs:query     at wrapClientError (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/wrapClientError.js:9:16)
  ydbjs:query     at Object.serverStreamingMethod [as next] (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/createServerStreamingMethod.js:41:57)
  ydbjs:query     at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
  ydbjs:query     at async debug (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/core/dist/middleware.js:8:16)
  ydbjs:query     at async AccessTokenCredentialsProvider.middleware (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/auth/dist/index.js:11:16)
  ydbjs:query     at async Object.next (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/createServerStreamingMethod.js:68:40)
  ydbjs:query     at async file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/query/dist/query.js:160:28
  ydbjs:query     at async retry (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/query/node_modules/@ydbjs/retry/dist/index.js:24:26)
  ydbjs:query     at async file:///home/turikhay/projects/o6o2/bot/dev.js:25:13 {
  ydbjs:query   path: '/Ydb.Query.V1.QueryService/ExecuteQuery',
  ydbjs:query   code: 8,
  ydbjs:query   details: 'ResourceExhausted'
  ydbjs:query } +4s
  ydbjs:retry attempt 3: calling retry function +4s
  ydbjs:query creating query client for nodeId: 50150n +0ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +4s
  ydbjs:query query part failed, status: 400100 +36ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery OK +4s
  ydbjs:retry attempt 3: no delay before next retry +36ms
  ydbjs:retry attempt 4: calling retry function +0ms
  ydbjs:query creating query client for nodeId: 50150n +1ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +37ms
  ydbjs:query query part failed, status: 400100 +22ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery OK +23ms
  ydbjs:retry attempt 4: no delay before next retry +24ms
  ydbjs:retry attempt 5: calling retry function +0ms
  ydbjs:query creating query client for nodeId: 50150n +1ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +23ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted +390ms
  ydbjs:retry attempt 5: waiting 31611 ms before next retry +389ms
  ydbjs:query retrying query, attempt 5, error: ClientError: /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted
  ydbjs:query     at wrapClientError (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/wrapClientError.js:9:16)
  ydbjs:query     at Object.serverStreamingMethod [as next] (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/createServerStreamingMethod.js:41:57)
  ydbjs:query     at process.processTicksAndRejections (node:internal/process/task_queues:105:5)
  ydbjs:query     at async debug (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/core/dist/middleware.js:8:16)
  ydbjs:query     at async AccessTokenCredentialsProvider.middleware (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/auth/dist/index.js:11:16)
  ydbjs:query     at async Object.next (/home/turikhay/projects/o6o2/bot/node_modules/nice-grpc/lib/client/createServerStreamingMethod.js:68:40)
  ydbjs:query     at async file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/query/dist/query.js:160:28
  ydbjs:query     at async retry (file:///home/turikhay/projects/o6o2/bot/node_modules/@ydbjs/query/node_modules/@ydbjs/retry/dist/index.js:24:26)
  ydbjs:query     at async file:///home/turikhay/projects/o6o2/bot/dev.js:25:13 {
  ydbjs:query   path: '/Ydb.Query.V1.QueryService/ExecuteQuery',
  ydbjs:query   code: 8,
  ydbjs:query   details: 'ResourceExhausted'
  ydbjs:query } +35s
  ydbjs:retry attempt 6: calling retry function +34s
  ydbjs:query creating query client for nodeId: 50150n +1ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +35s
  ydbjs:query query part failed, status: 400100 +30ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery OK +34s
  ydbjs:retry attempt 6: no delay before next retry +31ms
  ydbjs:retry attempt 7: calling retry function +0ms
  ydbjs:query creating query client for nodeId: 50150n +1ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +31ms
  ydbjs:query query part failed, status: 400100 +23ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery OK +24ms
  ydbjs:retry attempt 7: no delay before next retry +24ms
  ydbjs:retry attempt 8: calling retry function +0ms
  ydbjs:query creating query client for nodeId: 50150n +1ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +24ms
  ydbjs:query query part failed, status: 400100 +23ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery OK +23ms
  ydbjs:retry attempt 8: no delay before next retry +23ms
  ydbjs:retry attempt 9: calling retry function +0ms
  ydbjs:query creating query client for nodeId: 50150n +0ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +23ms
  ydbjs:query query part failed, status: 400100 +23ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery OK +23ms
  ydbjs:retry attempt 9: no delay before next retry +23ms
  ydbjs:retry attempt 10: calling retry function +0ms
  ydbjs:query creating query client for nodeId: 50150n +0ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +23ms
  ydbjs:query query part failed, status: 400100 +23ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery OK +23ms
  ydbjs:retry attempt 10: no delay before next retry +23ms
  ydbjs:retry attempt 11: calling retry function +0ms
  ydbjs:query creating query client for nodeId: 50150n +0ms
  ydbjs:driver creating client for Ydb.Query.V1.QueryService with preferNodeId: 50150 +23ms
  ydbjs:grpc /Ydb.Query.V1.QueryService/ExecuteQuery RESOURCE_EXHAUSTED: ResourceExhausted +389ms
  ydbjs:retry attempt 11: waiting 2047611 ms before next retry +389ms

[turikhay]

В качестве хотфикса залатал вот эти части:

diff --git a/packages/query/src/query.ts b/packages/query/src/query.ts
index 412625e..f7ff2e2 100644
--- a/packages/query/src/query.ts
+++ b/packages/query/src/query.ts
@@ -118,6 +118,7 @@ export class Query<T extends any[] = unknown[]> extends EventEmitter<QueryEventM
 		let retryConfig: RetryConfig = {
 			...defaultRetryConfig,
 			signal,
+			budget: 10,
 			idempotent: this.#idempotent,
 			onRetry: (retryCtx) => {
 				dbg.log('retrying query, attempt %d, error: %O', retryCtx.attempt, retryCtx.error)
@@ -219,6 +220,12 @@ export class Query<T extends any[] = unknown[]> extends EventEmitter<QueryEventM
 			for await (let part of stream) {
 				signal.throwIfAborted()
 
+				if (part.status === StatusIds_StatusCode.BAD_SESSION) {
+                    dbg.log('invalidating session')
+                    sessionId = undefined
+                    throw new YDBError(part.status, part.issues)
+                }
+
 				if (part.status !== StatusIds_StatusCode.SUCCESS) {
 					dbg.log('query part failed, status: %d', part.status)
 					throw new YDBError(part.status, part.issues)

[polRk]

@turikhay Спасибо большое за issue. Буду разбираться!

[polRk]

@turikhay Хорошая практика это всегда указывать signal при вызове запроса. Например, 1с. Если бд не ответил за 1с - то уже не стоит и дальше его мучать