diff --git a/observability-test/batch-transaction.ts b/observability-test/batch-transaction.ts index 763fb7e36..619f705d7 100644 --- a/observability-test/batch-transaction.ts +++ b/observability-test/batch-transaction.ts @@ -153,68 +153,63 @@ describe('BatchTransaction', () => { }; it('createQueryPartitions', done => { - const REQUEST = sandbox.stub(); - - const res = batchTransaction.createQueryPartitions( - QUERY, - (err, part, resp) => { - assert.ifError(err); - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - assert.strictEqual(spans.length, 2, 'Exactly 2 spans expected'); - - // Sort the spans by duration. - spans.sort((spanA, spanB) => { - spanA.duration < spanB.duration; - }); - - const actualSpanNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - }); - - const expectedSpanNames = [ - 'CloudSpanner.BatchTransaction.createPartitions_', - 'CloudSpanner.BatchTransaction.createQueryPartitions', - ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - - // Ensure that createPartitions_ is a child span of createQueryPartitions. - const spanCreatePartitions_ = spans[0]; - const spanCreateQueryPartitions = spans[1]; - assert.ok( - spanCreateQueryPartitions.spanContext().traceId, - 'Expected that createQueryPartitions has a defined traceId' - ); - assert.ok( - spanCreatePartitions_.spanContext().traceId, - 'Expected that createPartitions_ has a defined traceId' - ); - assert.deepStrictEqual( - spanCreatePartitions_.spanContext().traceId, - spanCreateQueryPartitions.spanContext().traceId, - 'Expected that both spans share a traceId' - ); - assert.ok( - spanCreateQueryPartitions.spanContext().spanId, - 'Expected that createQueryPartitions has a defined spanId' - ); - assert.ok( - spanCreatePartitions_.spanContext().spanId, - 'Expected that createPartitions_ has a defined spanId' - ); - assert.deepStrictEqual( - spanCreatePartitions_.parentSpanId, - spanCreateQueryPartitions.spanContext().spanId, - 'Expected that createQueryPartitions is the parent to createPartitions_' - ); - done(); - } - ); + const res = batchTransaction.createQueryPartitions(QUERY, err => { + assert.ifError(err); + traceExporter.forceFlush(); + const spans = traceExporter.getFinishedSpans(); + assert.strictEqual(spans.length, 2, 'Exactly 2 spans expected'); + + // Sort the spans by duration. + spans.sort((spanA, spanB) => { + spanA.duration < spanB.duration; + }); + + const actualSpanNames: string[] = []; + spans.forEach(span => { + actualSpanNames.push(span.name); + }); + + const expectedSpanNames = [ + 'CloudSpanner.BatchTransaction.createPartitions_', + 'CloudSpanner.BatchTransaction.createQueryPartitions', + ]; + assert.deepStrictEqual( + actualSpanNames, + expectedSpanNames, + `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` + ); + + // Ensure that createPartitions_ is a child span of createQueryPartitions. + const spanCreatePartitions_ = spans[0]; + const spanCreateQueryPartitions = spans[1]; + assert.ok( + spanCreateQueryPartitions.spanContext().traceId, + 'Expected that createQueryPartitions has a defined traceId' + ); + assert.ok( + spanCreatePartitions_.spanContext().traceId, + 'Expected that createPartitions_ has a defined traceId' + ); + assert.deepStrictEqual( + spanCreatePartitions_.spanContext().traceId, + spanCreateQueryPartitions.spanContext().traceId, + 'Expected that both spans share a traceId' + ); + assert.ok( + spanCreateQueryPartitions.spanContext().spanId, + 'Expected that createQueryPartitions has a defined spanId' + ); + assert.ok( + spanCreatePartitions_.spanContext().spanId, + 'Expected that createPartitions_ has a defined spanId' + ); + assert.deepStrictEqual( + spanCreatePartitions_.parentSpanId, + spanCreateQueryPartitions.spanContext().spanId, + 'Expected that createQueryPartitions is the parent to createPartitions_' + ); + done(); + }); }); it('createReadPartitions', done => { @@ -222,34 +217,31 @@ describe('BatchTransaction', () => { const response = {}; REQUEST.callsFake((_, callback) => callback(null, response)); - const res = batchTransaction.createReadPartitions( - QUERY, - (err, part, resp) => { - assert.ifError(err); - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - assert.strictEqual(spans.length, 2, 'Exactly 2 spans expected'); - - // Sort the spans by duration. - spans.sort((spanA, spanB) => { - spanA.duration < spanB.duration; - }); - - const actualSpanNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - }); - const expectedSpanNames = [ - 'CloudSpanner.BatchTransaction.createPartitions_', - 'CloudSpanner.BatchTransaction.createReadPartitions', - ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - done(); - } - ); + const res = batchTransaction.createReadPartitions(QUERY, err => { + assert.ifError(err); + traceExporter.forceFlush(); + const spans = traceExporter.getFinishedSpans(); + assert.strictEqual(spans.length, 2, 'Exactly 2 spans expected'); + + // Sort the spans by duration. + spans.sort((spanA, spanB) => { + spanA.duration < spanB.duration; + }); + + const actualSpanNames: string[] = []; + spans.forEach(span => { + actualSpanNames.push(span.name); + }); + const expectedSpanNames = [ + 'CloudSpanner.BatchTransaction.createPartitions_', + 'CloudSpanner.BatchTransaction.createReadPartitions', + ]; + assert.deepStrictEqual( + actualSpanNames, + expectedSpanNames, + `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` + ); + done(); + }); }); }); diff --git a/observability-test/database.ts b/observability-test/database.ts index 3b6811e8c..7351f5297 100644 --- a/observability-test/database.ts +++ b/observability-test/database.ts @@ -1175,7 +1175,7 @@ describe('Database', () => { it('with error on null mutation should catch thrown error', done => { try { - database.writeAtLeastOnce(null, (err, res) => {}); + database.writeAtLeastOnce(null, () => {}); } catch (err) { // Performing a substring search on the error because // depending on the version of Node.js, the error might be either of: @@ -1320,7 +1320,6 @@ describe('Database', () => { 'Expected an ERROR span status' ); - const errorMessage = firstSpan.status.message; assert.deepStrictEqual( firstSpan.status.message, sessionNotFoundError.message @@ -1658,7 +1657,7 @@ describe('Database', () => { .throws(ourException); assert.rejects(async () => { - const value = await database.runTransactionAsync(async txn => { + await database.runTransactionAsync(async txn => { const result = await txn.run('SELECT 1'); await txn.commit(); return result; diff --git a/observability-test/helper.ts b/observability-test/helper.ts index b6d429d32..591171666 100644 --- a/observability-test/helper.ts +++ b/observability-test/helper.ts @@ -19,6 +19,25 @@ import * as assert from 'assert'; const {ReadableSpan} = require('@opentelemetry/sdk-trace-base'); import {SEMATTRS_DB_NAME} from '@opentelemetry/semantic-conventions'; +export const batchCreateSessionsEvents = [ + 'Requesting 25 sessions', + 'Creating 25 sessions', + 'Requested for 25 sessions returned 25', +]; + +export const waitingSessionsEvents = [ + 'Acquiring session', + 'Waiting for a session to become available', + 'Acquired session', + 'Using Session', +]; + +export const cacheSessionEvents = [ + 'Acquiring session', + 'Cache hit: has usable session', + 'Acquired session', +]; + /** * This utility exists as a test helper because mocha has builtin "context" * and referring to context causes type/value collision errors. @@ -47,3 +66,30 @@ export function generateWithAllSpansHaveDBName(dbName: String): Function { }); }; } + +export async function verifySpansAndEvents( + traceExporter, + expectedSpans, + expectedEvents +) { + await traceExporter.forceFlush(); + const spans = traceExporter.getFinishedSpans(); + const actualEventNames: string[] = []; + const actualSpanNames: string[] = []; + spans.forEach(span => { + actualSpanNames.push(span.name); + span.events.forEach(event => { + actualEventNames.push(event.name); + }); + }); + assert.deepStrictEqual( + actualSpanNames, + expectedSpans, + `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpans}` + ); + assert.deepStrictEqual( + actualEventNames, + expectedEvents, + `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEvents}` + ); +} diff --git a/observability-test/observability.ts b/observability-test/observability.ts index 576005687..224001951 100644 --- a/observability-test/observability.ts +++ b/observability-test/observability.ts @@ -382,7 +382,6 @@ describe('setError', () => { it('a non-empty string should set the message', () => { startTrace('aSpan', {opts: {tracerProvider: provider}}, span => { - const status1 = span.status; const res = setSpanError(span, 'this one'); assert.strictEqual(res, true, 'value was set'); span.end(); @@ -438,7 +437,6 @@ describe('setErrorAndException', () => { it('a non-empty string should set the message', () => { startTrace('aSpan', {opts: {tracerProvider: provider}}, span => { - const status1 = span.status; const res = setSpanErrorAndException(span, 'this one'); assert.strictEqual(res, true, 'value was set'); span.end(); diff --git a/observability-test/session-pool.ts b/observability-test/session-pool.ts index e92b42b0a..77a47a5af 100644 --- a/observability-test/session-pool.ts +++ b/observability-test/session-pool.ts @@ -65,7 +65,7 @@ describe('SessionPool', () => { } as unknown as Database; const sandbox = sinon.createSandbox(); - const shouldNotBeCalled = sandbox.stub().throws('Should not be called.'); + sandbox.stub().throws('Should not be called.'); const createSession = (name = 'id', props?): Session => { props = props || {}; @@ -112,9 +112,7 @@ describe('SessionPool', () => { const OPTIONS = 3; it('on exception from Database.batchCreateSessions', async () => { const ourException = new Error('this fails intentionally'); - const stub = sandbox - .stub(DATABASE, 'batchCreateSessions') - .throws(ourException); + sandbox.stub(DATABASE, 'batchCreateSessions').throws(ourException); const releaseStub = sandbox.stub(sessionPool, 'release'); assert.rejects(async () => { @@ -168,9 +166,7 @@ describe('SessionPool', () => { it('without error', async () => { const RESPONSE = [[{}, {}, {}]]; - const stub = sandbox - .stub(DATABASE, 'batchCreateSessions') - .resolves(RESPONSE); + sandbox.stub(DATABASE, 'batchCreateSessions').resolves(RESPONSE); const releaseStub = sandbox.stub(sessionPool, 'release'); await sessionPool._createSessions(OPTIONS); diff --git a/observability-test/spanner.ts b/observability-test/spanner.ts index c9ce60df2..e94e5bc23 100644 --- a/observability-test/spanner.ts +++ b/observability-test/spanner.ts @@ -33,6 +33,9 @@ const { NodeTracerProvider, InMemorySpanExporter, } = require('@opentelemetry/sdk-trace-node'); +const { + TraceExporter, +} = require('@google-cloud/opentelemetry-cloud-trace-exporter'); // eslint-disable-next-line n/no-extraneous-require const {SimpleSpanProcessor} = require('@opentelemetry/sdk-trace-base'); const {SpanStatusCode} = require('@opentelemetry/api'); @@ -40,6 +43,10 @@ const { disableContextAndManager, generateWithAllSpansHaveDBName, setGlobalContextManager, + verifySpansAndEvents, + batchCreateSessionsEvents, + waitingSessionsEvents, + cacheSessionEvents, } = require('./helper'); const { AsyncHooksContextManager, @@ -125,12 +132,14 @@ async function setup( describe('EndToEnd', async () => { const contextManager = new AsyncHooksContextManager(); + const sleep = ms => new Promise(resolve => setTimeout(resolve, ms)); setGlobalContextManager(contextManager); afterEach(() => { disableContextAndManager(contextManager); }); const traceExporter = new InMemorySpanExporter(); + //const traceExporter = new TraceExporter(); const sampler = new AlwaysOnSampler(); const tracerProvider = new NodeTracerProvider({ sampler: sampler, @@ -156,6 +165,7 @@ describe('EndToEnd', async () => { afterEach(async () => { await tracerProvider.forceFlush(); await traceExporter.reset(); + // await sleep(80000); spannerMock.resetRequests(); }); @@ -174,186 +184,82 @@ describe('EndToEnd', async () => { describe('Database', () => { it('getSessions', async () => { const [rows] = await database.getSessions(); - - const withAllSpansHaveDBName = generateWithAllSpansHaveDBName( - database.formattedName_ - ); - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - assert.strictEqual(spans.length, 1, 'Exactly 1 span expected'); - withAllSpansHaveDBName(spans); - - const actualSpanNames: string[] = []; - const actualEventNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = ['CloudSpanner.Database.getSessions']; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - const expectedEventNames = []; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); }); it('getSnapshot', done => { - const withAllSpansHaveDBName = generateWithAllSpansHaveDBName( - database.formattedName_ - ); - database.getSnapshot((err, transaction) => { assert.ifError(err); transaction!.run('SELECT 1', async (err, rows) => { assert.ifError(err); transaction!.end(); - - await tracerProvider.forceFlush(); - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - withAllSpansHaveDBName(spans); - - const actualSpanNames: string[] = []; - const actualEventNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = [ 'CloudSpanner.Snapshot.begin', 'CloudSpanner.Database.getSnapshot', 'CloudSpanner.Snapshot.runStream', 'CloudSpanner.Snapshot.run', ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - const expectedEventNames = [ 'Begin Transaction', 'Transaction Creation Done', - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, 'Starting stream', ]; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); - done(); }); }); }); it('getTransaction', done => { - const withAllSpansHaveDBName = generateWithAllSpansHaveDBName( - database.formattedName_ - ); database.getTransaction(async (err, transaction) => { assert.ifError(err); assert.ok(transaction); transaction!.end(); transaction!.commit(); - await tracerProvider.forceFlush(); - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - withAllSpansHaveDBName(spans); - - const actualEventNames: string[] = []; - const actualSpanNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = ['CloudSpanner.Database.getTransaction']; - assert.deepStrictEqual( - actualSpanNames, + const expectedEventNames = [...cacheSessionEvents, 'Using Session']; + await verifySpansAndEvents( + traceExporter, expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - - const expectedEventNames = [ - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', - 'Using Session', - ]; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + expectedEventNames ); - done(); }); }); it('runStream', done => { - const withAllSpansHaveDBName = generateWithAllSpansHaveDBName( - database.formattedName_ - ); database .runStream('SELECT 1') .on('data', row => {}) .once('error', assert.ifError) - .on('end', () => { - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - withAllSpansHaveDBName(spans); - - const actualSpanNames: string[] = []; - const actualEventNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - + .on('end', async () => { const expectedSpanNames = [ 'CloudSpanner.Snapshot.runStream', 'CloudSpanner.Database.runStream', ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - const expectedEventNames = [ 'Starting stream', - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, 'Using Session', ]; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); done(); @@ -417,9 +323,7 @@ describe('EndToEnd', async () => { const expectedEventNames = [ 'Starting stream', - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, 'Using Session', ]; assert.deepStrictEqual( @@ -430,186 +334,91 @@ describe('EndToEnd', async () => { }); it('runTransaction', done => { - const withAllSpansHaveDBName = generateWithAllSpansHaveDBName( - database.formattedName_ - ); - database.runTransaction(async (err, transaction) => { assert.ifError(err); await transaction!.run('SELECT 1'); await transaction!.commit(); await transaction!.end(); - await traceExporter.forceFlush(); - - const spans = traceExporter.getFinishedSpans(); - withAllSpansHaveDBName(spans); - - const actualEventNames: string[] = []; - const actualSpanNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = [ 'CloudSpanner.Snapshot.runStream', 'CloudSpanner.Snapshot.run', 'CloudSpanner.Transaction.commit', 'CloudSpanner.Database.runTransaction', ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - const expectedEventNames = [ 'Starting stream', 'Transaction Creation Done', 'Starting Commit', 'Commit Done', - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, ]; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); done(); }); }); it('runTransactionAsync', async () => { - const withAllSpansHaveDBName = generateWithAllSpansHaveDBName( - database.formattedName_ - ); await database.runTransactionAsync(async transaction => { await transaction!.run('SELECT 1'); }); - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - withAllSpansHaveDBName(spans); - - const actualEventNames: string[] = []; - const actualSpanNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = [ 'CloudSpanner.Snapshot.runStream', 'CloudSpanner.Snapshot.run', 'CloudSpanner.Database.runTransactionAsync', ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - const expectedEventNames = [ 'Starting stream', 'Transaction Creation Done', - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, 'Using Session', ]; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); }); it('writeAtLeastOnce', done => { - const withAllSpansHaveDBName = generateWithAllSpansHaveDBName( - database.formattedName_ - ); const blankMutations = new MutationSet(); - database.writeAtLeastOnce(blankMutations, (err, response) => { + database.writeAtLeastOnce(blankMutations, async (err, response) => { assert.ifError(err); assert.ok(response); - - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - withAllSpansHaveDBName(spans); - - const actualEventNames: string[] = []; - const actualSpanNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = [ 'CloudSpanner.Transaction.commit', 'CloudSpanner.Database.writeAtLeastOnce', ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - const expectedEventNames = [ 'Starting Commit', 'Commit Done', - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, 'Using Session', ]; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); - done(); }); }); it('batchCreateSessions', done => { - database.batchCreateSessions(5, (err, sessions) => { + database.batchCreateSessions(5, async (err, sessions) => { assert.ifError(err); - - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - - const actualEventNames: string[] = []; - const actualSpanNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = ['CloudSpanner.Database.batchCreateSessions']; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); - const expectedEventNames = []; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); - done(); }); }); @@ -883,9 +692,7 @@ describe('ObservabilityOptions injection and propagation', async () => { ); const expectedEventNames = [ - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, 'Using Session', 'Starting stream', 'Transaction Creation Done', @@ -994,9 +801,7 @@ describe('ObservabilityOptions injection and propagation', async () => { ); const expectedEventNames = [ - 'Acquiring session', - 'Cache hit: has usable session', - 'Acquired session', + ...cacheSessionEvents, 'Using Session', 'Starting stream', ]; @@ -1162,14 +967,9 @@ describe('ObservabilityOptions injection and propagation', async () => { ); const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', + ...batchCreateSessionsEvents, 'Starting stream', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + ...waitingSessionsEvents, ]; assert.deepStrictEqual( actualEventNames, @@ -1310,14 +1110,9 @@ describe('E2E traces with async/await', async () => { // Finally check for the collective expected event names. const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', + ...batchCreateSessionsEvents, 'Starting stream', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + ...waitingSessionsEvents, ]; assert.deepStrictEqual( actualEventNames, @@ -1548,14 +1343,10 @@ SELECT 1p // Finally check for the collective expected event names. const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', + ...batchCreateSessionsEvents, 'Starting stream', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + 'exception', + ...waitingSessionsEvents, ]; assert.deepStrictEqual( actualEventNames, @@ -1704,10 +1495,9 @@ SELECT 1p // Finally check for the collective expected event names. const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', + ...batchCreateSessionsEvents, 'Starting stream', + 'exception', 'Stream broken. Safe to retry', 'Begin Transaction', 'Transaction Creation Done', @@ -1715,10 +1505,7 @@ SELECT 1p 'Transaction Creation Done', 'Starting Commit', 'Commit Done', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + ...waitingSessionsEvents, 'exception', ]; assert.deepStrictEqual( @@ -2101,14 +1888,10 @@ describe('Traces for ExecuteStream broken stream retries', () => { // Finally check for the collective expected event names. const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', + ...batchCreateSessionsEvents, 'Starting stream', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + 'exception', + ...waitingSessionsEvents, 'Transaction Creation Done', ]; assert.deepStrictEqual( @@ -2172,19 +1955,14 @@ describe('Traces for ExecuteStream broken stream retries', () => { // Finally check for the collective expected event names. const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', + ...batchCreateSessionsEvents, 'Starting stream', 'Re-attempting start stream', 'Resuming stream', 'Resuming stream', 'Resuming stream', 'Resuming stream', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + ...waitingSessionsEvents, ]; assert.deepStrictEqual( actualEventNames, @@ -2243,19 +2021,14 @@ describe('Traces for ExecuteStream broken stream retries', () => { // Finally check for the collective expected event names. const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', + ...batchCreateSessionsEvents, 'Starting stream', 'Re-attempting start stream', 'Begin Transaction', 'Transaction Creation Done', 'Starting Commit', 'Commit Done', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + ...waitingSessionsEvents, ]; assert.deepStrictEqual( actualEventNames, @@ -2298,43 +2071,20 @@ describe('Traces for ExecuteStream broken stream retries', () => { 1, 'runTransactionAsync.attempt must be 1' ); - - traceExporter.forceFlush(); - const spans = traceExporter.getFinishedSpans(); - - const actualSpanNames: string[] = []; - const actualEventNames: string[] = []; - spans.forEach(span => { - actualSpanNames.push(span.name); - span.events.forEach(event => { - actualEventNames.push(event.name); - }); - }); - const expectedSpanNames = [ 'CloudSpanner.Database.batchCreateSessions', 'CloudSpanner.SessionPool.createSessions', 'CloudSpanner.Database.runTransactionAsync', ]; - assert.deepStrictEqual( - actualSpanNames, - expectedSpanNames, - `span names mismatch:\n\tGot: ${actualSpanNames}\n\tWant: ${expectedSpanNames}` - ); const expectedEventNames = [ - 'Requesting 25 sessions', - 'Creating 25 sessions', - 'Requested for 25 sessions returned 25', - 'Acquiring session', - 'Waiting for a session to become available', - 'Acquired session', - 'Using Session', + ...batchCreateSessionsEvents, + ...waitingSessionsEvents, ]; - assert.deepStrictEqual( - actualEventNames, - expectedEventNames, - `Unexpected events:\n\tGot: ${actualEventNames}\n\tWant: ${expectedEventNames}` + await verifySpansAndEvents( + traceExporter, + expectedSpanNames, + expectedEventNames ); }); }); diff --git a/src/partial-result-stream.ts b/src/partial-result-stream.ts index 69439f534..8bf414c7a 100644 --- a/src/partial-result-stream.ts +++ b/src/partial-result-stream.ts @@ -28,6 +28,7 @@ import {DeadlineError, isRetryableInternalError} from './transaction-runner'; import {codec, JSONOptions, Json, Field, Value} from './codec'; import {google} from '../protos/protos'; import * as stream from 'stream'; +import {getActiveOrNoopSpan, setSpanErrorAndException} from './instrument'; export type ResumeToken = string | Uint8Array; @@ -494,6 +495,7 @@ export function partialResultStream( let lastRequestStream: Readable; const startTime = Date.now(); const timeout = options?.gaxOptions?.timeout ?? Infinity; + const span = getActiveOrNoopSpan(); // mergeStream allows multiple streams to be connected into one. This is good; // if we need to retry a request and pipe more data to the user's stream. @@ -568,6 +570,7 @@ export function partialResultStream( // checkpoint stream has queued. After that, we will destroy the // user's stream with the same error. setImmediate(() => batchAndSplitOnTokenStream.destroy(err)); + setSpanErrorAndException(span, err as Error); return; } diff --git a/src/transaction-runner.ts b/src/transaction-runner.ts index 61d979e8c..a99e6bd12 100644 --- a/src/transaction-runner.ts +++ b/src/transaction-runner.ts @@ -25,6 +25,7 @@ import {NormalCallback} from './common'; import {isSessionNotFoundError} from './session-pool'; import {Database} from './database'; import {google} from '../protos/protos'; +import {getActiveOrNoopSpan} from './instrument'; import IRequestOptions = google.spanner.v1.IRequestOptions; // eslint-disable-next-line @typescript-eslint/no-var-requires @@ -226,6 +227,7 @@ export abstract class Runner { const timeout = this.options.timeout!; let lastError: grpc.ServiceError; + const span = getActiveOrNoopSpan(); // The transaction runner should always execute at least one attempt before // timing out. @@ -250,6 +252,7 @@ export abstract class Runner { } this.attempts += 1; + span.addEvent('Retrying transaction'); const delay = this.getNextDelay(lastError); await new Promise(resolve => setTimeout(resolve, delay)); diff --git a/test/partial-result-stream.ts b/test/partial-result-stream.ts index 799d29b00..0154f048c 100644 --- a/test/partial-result-stream.ts +++ b/test/partial-result-stream.ts @@ -335,7 +335,7 @@ describe('PartialResultStream', () => { }); partialResultStream(requestFnStub, {gaxOptions: {timeout: 0}}) - .on('data', row => {}) + .on('data', () => {}) .on('error', err => { assert.strictEqual(err.code, grpc.status.DEADLINE_EXCEEDED); assert.strictEqual(requestFnStub.callCount, 1); diff --git a/test/spanner.ts b/test/spanner.ts index d324ed911..0212f6b92 100644 --- a/test/spanner.ts +++ b/test/spanner.ts @@ -3556,7 +3556,7 @@ describe('Spanner with mock server', () => { requestOptions: {transactionTag: 'transaction-tag'}, }); const transaction = promise[0]; - await transaction.run('SELECT 1').then(results => { + await transaction.run('SELECT 1').then(() => { const request = spannerMock.getRequests().find(val => { return (val as v1.ExecuteSqlRequest).sql; }) as v1.ExecuteSqlRequest;