From 1ddb62ed67e93ca2c265556bb5e504d207a639a8 Mon Sep 17 00:00:00 2001 From: Ehsan Date: Mon, 2 Dec 2024 13:48:18 -0800 Subject: [PATCH] feat: Enable tracing via OpenTelemetry. (#2218) * feat: Enable tracing via OpenTelemetry. * Better comment for the tracerProvider setting. * Address feedback. * Add an event for logical termination and add events to tests. * Address API naming feedback. * Remove the trace event that's currently not in Firestore prod. --- dev/src/index.ts | 3 +- dev/src/reference/query-util.ts | 7 +- dev/src/telemetry/disabled-trace-util.ts | 4 + dev/src/telemetry/enabled-trace-util.ts | 27 +++- dev/src/telemetry/span.ts | 4 + dev/src/telemetry/trace-util.ts | 13 ++ dev/system-test/tracing.ts | 59 ++++++-- dev/test/tracing.ts | 166 ++++++++++++++--------- types/firestore.d.ts | 23 ++++ 9 files changed, 225 insertions(+), 81 deletions(-) diff --git a/dev/src/index.ts b/dev/src/index.ts index 46ad88dfd..5bf9c2217 100644 --- a/dev/src/index.ts +++ b/dev/src/index.ts @@ -792,8 +792,7 @@ export class Firestore implements firestore.Firestore { } private newTraceUtilInstance(settings: firestore.Settings): TraceUtil { - // Take the tracing option from the settings. - let createEnabledInstance = settings.openTelemetryOptions?.enableTracing; + let createEnabledInstance = true; // The environment variable can override options to enable/disable telemetry collection. if ('FIRESTORE_ENABLE_TRACING' in process.env) { diff --git a/dev/src/reference/query-util.ts b/dev/src/reference/query-util.ts index 8aad95888..0ac50f775 100644 --- a/dev/src/reference/query-util.ts +++ b/dev/src/reference/query-util.ts @@ -180,6 +180,7 @@ export class QueryUtil< const tag = requestTag(); const startTime = Date.now(); const isExplain = explainOptions !== undefined; + const methodName = 'runQuery'; let numDocumentsReceived = 0; let lastReceivedDocument: QueryDocumentSnapshot< @@ -245,6 +246,11 @@ export class QueryUtil< if (proto.done) { logger('QueryUtil._stream', tag, 'Trigger Logical Termination.'); + this._firestore._traceUtil + .currentSpan() + .addEvent( + `Firestore.${methodName}: Received RunQueryResponse.Done.` + ); backendStream.unpipe(stream); backendStream.resume(); backendStream.end(); @@ -265,7 +271,6 @@ export class QueryUtil< let streamActive: Deferred; do { streamActive = new Deferred(); - const methodName = 'runQuery'; this._firestore._traceUtil .currentSpan() diff --git a/dev/src/telemetry/disabled-trace-util.ts b/dev/src/telemetry/disabled-trace-util.ts index c4c6cce6a..bd703515a 100644 --- a/dev/src/telemetry/disabled-trace-util.ts +++ b/dev/src/telemetry/disabled-trace-util.ts @@ -16,6 +16,10 @@ import {Attributes, TraceUtil} from './trace-util'; import {Span} from './span'; +/** + * @private + * @internal + */ export class DisabledTraceUtil implements TraceUtil { // eslint-disable-next-line @typescript-eslint/no-unused-vars startSpan(name: string): Span { diff --git a/dev/src/telemetry/enabled-trace-util.ts b/dev/src/telemetry/enabled-trace-util.ts index 0fdbaf582..9b78ee99a 100644 --- a/dev/src/telemetry/enabled-trace-util.ts +++ b/dev/src/telemetry/enabled-trace-util.ts @@ -22,6 +22,7 @@ import { trace, Tracer, Span as OpenTelemetrySpan, + TracerProvider, } from '@opentelemetry/api'; import {Span} from './span'; @@ -33,22 +34,40 @@ import {DEFAULT_DATABASE_ID} from '../path'; import {DEFAULT_MAX_IDLE_CHANNELS} from '../index'; const serviceConfig = interfaces['google.firestore.v1.Firestore']; +/** + * @private + * @internal + */ export class EnabledTraceUtil implements TraceUtil { private tracer: Tracer; private settingsAttributes: Attributes; + // Visible for testing + tracerProvider: TracerProvider; + constructor(settings: Settings) { - let tracerProvider = settings.openTelemetryOptions?.tracerProvider; + let provider: TracerProvider | undefined = + settings.openTelemetry?.tracerProvider; // If a TracerProvider has not been given to us, we try to use the global one. - if (!tracerProvider) { + if (!provider) { const {trace} = require('@opentelemetry/api'); - tracerProvider = trace.getTracerProvider(); + provider = trace.getTracerProvider(); } + // At this point provider is guaranteed to be defined because + // `trace.getTracerProvider()` does not return null or undefined. + this.tracerProvider = provider!; + const libVersion = require('../../../package.json').version; const libName = require('../../../package.json').name; - this.tracer = tracerProvider.getTracer(libName, libVersion); + try { + this.tracer = this.tracerProvider.getTracer(libName, libVersion); + } catch (e) { + throw new Error( + "The object provided for 'tracerProvider' does not conform to the TracerProvider interface." + ); + } this.settingsAttributes = {}; this.settingsAttributes['otel.scope.name'] = libName; diff --git a/dev/src/telemetry/span.ts b/dev/src/telemetry/span.ts index a4ad6e249..c4ed1ed0a 100644 --- a/dev/src/telemetry/span.ts +++ b/dev/src/telemetry/span.ts @@ -17,6 +17,10 @@ import {Span as OpenTelemetrySpan} from '@opentelemetry/api'; import {Attributes} from './trace-util'; +/** + * @private + * @internal + */ export class Span { constructor(private span?: OpenTelemetrySpan) {} diff --git a/dev/src/telemetry/trace-util.ts b/dev/src/telemetry/trace-util.ts index ff5a8b071..a38b614e1 100644 --- a/dev/src/telemetry/trace-util.ts +++ b/dev/src/telemetry/trace-util.ts @@ -16,9 +16,18 @@ import {Span} from './span'; +/** + * @private + * @internal + */ export interface Attributes { [attributeKey: string]: AttributeValue | undefined; } + +/** + * @private + * @internal + */ export declare type AttributeValue = | string | number @@ -67,6 +76,10 @@ export const ATTRIBUTE_KEY_TRANSACTION_TYPE = 'transaction_type'; export const ATTRIBUTE_KEY_ATTEMPTS_ALLOWED = 'attempts_allowed'; export const ATTRIBUTE_KEY_ATTEMPTS_REMAINING = 'attempts_remaining'; +/** + * @private + * @internal + */ export interface TraceUtil { startActiveSpan unknown>( name: string, diff --git a/dev/system-test/tracing.ts b/dev/system-test/tracing.ts index d808447ec..21e7f6368 100644 --- a/dev/system-test/tracing.ts +++ b/dev/system-test/tracing.ts @@ -30,7 +30,7 @@ import { Context as OpenTelemetryContext, } from '@opentelemetry/api'; import {TraceExporter} from '@google-cloud/opentelemetry-cloud-trace-exporter'; -import {Settings} from '@google-cloud/firestore'; +import {FirestoreOpenTelemetryOptions, Settings} from '@google-cloud/firestore'; import { AlwaysOnSampler, BatchSpanProcessor, @@ -96,13 +96,6 @@ setLogFunction((msg: string) => { console.log(`LOG: ${msg}`); }); -// TODO(tracing): This should be moved to firestore.d.ts when we want to -// release the feature. -export interface FirestoreOpenTelemetryOptions { - enableTracing?: boolean; - tracerProvider?: any; -} - interface TestConfig { // In-Memory tests check trace correctness by inspecting traces in memory by // utilizing InMemorySpanExporter. These tests have `e2e` set to `false`. @@ -192,7 +185,6 @@ describe('Tracing Tests', () => { tracerProvider: TracerProvider ): FirestoreOpenTelemetryOptions { const options: FirestoreOpenTelemetryOptions = { - enableTracing: true, tracerProvider: undefined, }; @@ -285,7 +277,7 @@ describe('Tracing Tests', () => { const settings: Settings = { preferRest: testConfig.preferRest, - openTelemetryOptions: getOpenTelemetryOptions(tracerProvider), + openTelemetry: getOpenTelemetryOptions(tracerProvider), }; // Named-database tests use an environment variable to specify the database ID. Add it to the settings. @@ -660,7 +652,7 @@ describe('Tracing Tests', () => { // Expect that the span exists first. const span = getSpanByName(spanName); - expect(span).to.not.be.null; + expect(span, `Could not find the span named ${spanName}`).to.not.be.null; // Assert that the expected attributes are present in the span attributes. // Note that the span attributes may be a superset of the attributes passed @@ -672,6 +664,29 @@ describe('Tracing Tests', () => { } } + // Ensures that the given span exists and has the given attributes. + function expectSpanHasEvents(spanName: string, eventNames: string[]): void { + // The Cloud Trace API does not return span attributes and events. + if (testConfig.e2e) { + return; + } + + // Expect that the span exists first. + const span = getSpanByName(spanName); + expect(span, `Could not find the span named ${spanName}`).to.not.be.null; + + // Assert that the expected attributes are present in the span attributes. + // Note that the span attributes may be a superset of the attributes passed + // to this function. + if (span?.events) { + const numEvents = eventNames.length; + expect(numEvents).to.equal(span.events.length); + for (let i = 0; i < numEvents; ++i) { + expect(span.events[i].name).to.equal(eventNames[i]); + } + } + } + describe(IN_MEMORY_TEST_SUITE_TITLE, () => { describe(NON_GLOBAL_OTEL_TEST_SUITE_TITLE, () => { describe(GRPC_TEST_SUITE_TITLE, () => { @@ -753,6 +768,11 @@ describe('Tracing Tests', () => { SPAN_NAME_DOC_REF_GET, SPAN_NAME_BATCH_GET_DOCUMENTS ); + expectSpanHasEvents(SPAN_NAME_BATCH_GET_DOCUMENTS, [ + 'Firestore.batchGetDocuments: Start', + 'Firestore.batchGetDocuments: First response received', + 'Firestore.batchGetDocuments: Completed', + ]); }); it('document reference create()', async () => { @@ -820,6 +840,11 @@ describe('Tracing Tests', () => { ); await waitForCompletedSpans(2); expectSpanHierarchy(SPAN_NAME_TEST_ROOT, SPAN_NAME_AGGREGATION_QUERY_GET); + expectSpanHasEvents(SPAN_NAME_AGGREGATION_QUERY_GET, [ + 'Firestore.runAggregationQuery: Start', + 'Firestore.runAggregationQuery: First response received', + 'Firestore.runAggregationQuery: Completed', + ]); }); it('collection reference add()', async () => { @@ -852,6 +877,12 @@ describe('Tracing Tests', () => { ); await waitForCompletedSpans(2); expectSpanHierarchy(SPAN_NAME_TEST_ROOT, SPAN_NAME_QUERY_GET); + expectSpanHasEvents(SPAN_NAME_QUERY_GET, [ + 'RunQuery', + 'Firestore.runQuery: Start', + 'Firestore.runQuery: First response received', + 'Firestore.runQuery: Completed', + ]); }); it('firestore getAll()', async () => { @@ -862,6 +893,11 @@ describe('Tracing Tests', () => { ); await waitForCompletedSpans(2); expectSpanHierarchy(SPAN_NAME_TEST_ROOT, SPAN_NAME_BATCH_GET_DOCUMENTS); + expectSpanHasEvents(SPAN_NAME_BATCH_GET_DOCUMENTS, [ + 'Firestore.batchGetDocuments: Start', + 'Firestore.batchGetDocuments: First response received', + 'Firestore.batchGetDocuments: Completed', + ]); }); it('transaction', async () => { @@ -920,6 +956,7 @@ describe('Tracing Tests', () => { await runFirestoreOperationInRootSpan(async () => { const query = firestore.collectionGroup('foo'); let numPartitions = 0; + // eslint-disable-next-line @typescript-eslint/no-unused-vars for await (const partition of query.getPartitions(3)) { numPartitions++; } diff --git a/dev/test/tracing.ts b/dev/test/tracing.ts index d356fc3fd..16104951a 100644 --- a/dev/test/tracing.ts +++ b/dev/test/tracing.ts @@ -17,11 +17,15 @@ import {createInstance} from './util/helpers'; import {expect} from 'chai'; import {DisabledTraceUtil} from '../src/telemetry/disabled-trace-util'; import {EnabledTraceUtil} from '../src/telemetry/enabled-trace-util'; +import {NodeTracerProvider} from '@opentelemetry/sdk-trace-node'; +import {ProxyTracerProvider, trace} from '@opentelemetry/api'; describe('Firestore Tracing Controls', () => { let originalEnvVarValue: string | undefined; beforeEach(() => { + // Remove any prior global OpenTelemetry registrations. + trace.disable(); originalEnvVarValue = process.env.FIRESTORE_ENABLE_TRACING; }); @@ -33,116 +37,152 @@ describe('Firestore Tracing Controls', () => { } }); - it('default firestore settings have tracing disabled', async () => { + it('default firestore settings, no env var', async () => { const firestore = await createInstance(); - expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; - }); - - it('no openTelemetryOptions results in tracing disabled', async () => { - const firestore = await createInstance(undefined, { - openTelemetryOptions: undefined, - }); - expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; - }); - - it('openTelemetryOptions.enableTracing controls the tracing feature', async () => { - let firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: undefined, - }, - }); - expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; - - firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: false, - }, - }); - expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; - - firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: true, - }, - }); expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; }); /// Tests to make sure environment variable can override settings. - it('env var disabled, default firestore settings', async () => { + it('default firestore settings, env var disabled', async () => { process.env.FIRESTORE_ENABLE_TRACING = 'OFF'; const firestore = await createInstance(); expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; }); - it('env var enabled, default firestore settings', async () => { + it('default firestore settings, env var enabled', async () => { process.env.FIRESTORE_ENABLE_TRACING = 'ON'; const firestore = await createInstance(); expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; }); - it('env var disabled, no openTelemetryOptions', async () => { + it('no openTelemetry settings, no env var', async () => { + const firestore = await createInstance(undefined, { + openTelemetry: undefined, + }); + expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; + + const firestore2 = await createInstance(undefined, { + openTelemetry: { + tracerProvider: undefined, + }, + }); + expect(firestore2._traceUtil instanceof EnabledTraceUtil).to.be.true; + }); + + it('no openTelemetry settings, env var disabled', async () => { process.env.FIRESTORE_ENABLE_TRACING = 'OFF'; const firestore = await createInstance(undefined, { - openTelemetryOptions: undefined, + openTelemetry: undefined, }); expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; + + const firestore2 = await createInstance(undefined, { + openTelemetry: { + tracerProvider: undefined, + }, + }); + expect(firestore2._traceUtil instanceof DisabledTraceUtil).to.be.true; }); - it('env var enabled, no openTelemetryOptions', async () => { + it('no openTelemetry settings, env var enabled', async () => { process.env.FIRESTORE_ENABLE_TRACING = 'ON'; const firestore = await createInstance(undefined, { - openTelemetryOptions: undefined, + openTelemetry: undefined, }); expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; - }); - it('env var disabled, with openTelemetryOptions.enableTracing', async () => { - process.env.FIRESTORE_ENABLE_TRACING = 'OFF'; - let firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: undefined, + const firestore2 = await createInstance(undefined, { + openTelemetry: { + tracerProvider: undefined, }, }); - expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; + expect(firestore2._traceUtil instanceof EnabledTraceUtil).to.be.true; + }); - firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: false, + it('valid tracerProvider, no env var', async () => { + const firestore = await createInstance(undefined, { + openTelemetry: { + tracerProvider: new NodeTracerProvider(), }, }); - expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; + expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; + }); - firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: true, + it('valid tracerProvider, env var disabled', async () => { + process.env.FIRESTORE_ENABLE_TRACING = 'OFF'; + const firestore = await createInstance(undefined, { + openTelemetry: { + tracerProvider: new NodeTracerProvider(), }, }); expect(firestore._traceUtil instanceof DisabledTraceUtil).to.be.true; }); - it('env var enabled, with openTelemetryOptions.enableTracing', async () => { + it('valid tracerProvider, env var enabled', async () => { process.env.FIRESTORE_ENABLE_TRACING = 'ON'; - let firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: undefined, + const firestore = await createInstance(undefined, { + openTelemetry: { + tracerProvider: new NodeTracerProvider(), }, }); expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; + }); - firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: false, + it('uses the tracerProvider passed to it', async () => { + const myTracerProvider = new NodeTracerProvider(); + + // Make another tracer provider the global tracer provider. + const globalTracerProvider = new NodeTracerProvider(); + globalTracerProvider.register(); + + const firestore = await createInstance(undefined, { + openTelemetry: { + tracerProvider: myTracerProvider, }, }); + expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; + // Make sure the SDK uses the one that was given to it, not the global one. + expect( + (firestore._traceUtil as EnabledTraceUtil).tracerProvider === + myTracerProvider + ).to.be.true; + expect( + (firestore._traceUtil as EnabledTraceUtil).tracerProvider !== + globalTracerProvider + ).to.be.true; + }); + + it('uses the global tracerProvider if nothing was passed to it', async () => { + // Make another tracer provider the global tracer provider. + const globalTracerProvider = new NodeTracerProvider(); + globalTracerProvider.register(); + + const firestore = await createInstance(); - firestore = await createInstance(undefined, { - openTelemetryOptions: { - enableTracing: true, - }, - }); expect(firestore._traceUtil instanceof EnabledTraceUtil).to.be.true; + const enabledTraceUtil: EnabledTraceUtil = + firestore._traceUtil as EnabledTraceUtil; + // Since a TracerProvider is not provided to the SDK directly, the SDK obtains + // the tracer provider from the global `TraceAPI`. The `TraceAPI` returns a + // `ProxyTracerProvider` instance. To check equality, we need to compare our + // `globalTracerProvider` with the proxy's delegate. + const tracerProviderUsed = enabledTraceUtil.tracerProvider; + const actual = (tracerProviderUsed as ProxyTracerProvider).getDelegate(); + expect(actual === globalTracerProvider).to.be.true; + }); + + it('Generates an error if the given tracerProvider is not valid', async () => { + try { + await createInstance(undefined, { + openTelemetry: {tracerProvider: 123}, + }); + } catch (e) { + expect( + e.toString() === + "The object provided for 'tracerProvider' does not conform to the TracerProvider interface." + ); + } }); }); diff --git a/types/firestore.d.ts b/types/firestore.d.ts index 51113bb1d..cfff47c98 100644 --- a/types/firestore.d.ts +++ b/types/firestore.d.ts @@ -461,9 +461,32 @@ declare namespace FirebaseFirestore { */ preferRest?: boolean; + /** + * Settings related to telemetry collection by this client. + * @beta + */ + openTelemetry?: FirestoreOpenTelemetryOptions; + [key: string]: any; // Accept other properties, such as GRPC settings. } + /** + * Options to configure telemetry collection. + * This is a 'beta' interface and may change in backwards incompatible ways. + * @beta + */ + export interface FirestoreOpenTelemetryOptions { + /** + * The OpenTelemetry TracerProvider instance that the SDK should use to + * create trace spans. If not provided, the SDK will use the Global TracerProvider. + * + * Even if a Global TracerProvider has been registered, users can still + * disable this client's span creation by passing in a "no-op" tracer provider + * here, or by setting the `FIRESTORE_ENABLE_TRACING` environment variable to `OFF` or `FALSE`. + */ + tracerProvider?: any; + } + /** Options to configure a read-only transaction. */ export interface ReadOnlyTransactionOptions { /** Set to true to indicate a read-only transaction. */