diff --git a/handwritten/spanner/src/index.ts b/handwritten/spanner/src/index.ts index 50d393249fe2..7f90f62c9e3d 100644 --- a/handwritten/spanner/src/index.ts +++ b/handwritten/spanner/src/index.ts @@ -89,6 +89,7 @@ import * as v1 from './v1'; import { ObservabilityOptions, ensureInitialContextManagerSet, + isTracingEnabled, } from './instrument'; import { attributeXGoogSpannerRequestIdToActiveSpan, @@ -496,12 +497,14 @@ class Spanner extends GrpcService { this.directedReadOptions = directedReadOptions; this.defaultTransactionOptions = defaultTransactionOptions; this._observabilityOptions = options.observabilityOptions; + if (isTracingEnabled(this._observabilityOptions)) { + ensureInitialContextManagerSet(); + } this.sessionLabels = options.sessionLabels || null; this.commonHeaders_ = getCommonHeaders( this.projectFormattedName_, this._observabilityOptions?.enableEndToEndTracing, ); - ensureInitialContextManagerSet(); this._nthClientId = nextSpannerClientId(); this._universeDomain = universeEndpoint; this.projectId_ = options.projectId; @@ -1721,14 +1724,16 @@ class Spanner extends GrpcService { config.headers[CLOUD_RESOURCE_HEADER], projectId!, ); - // Do context propagation - propagation.inject(context.active(), config.headers, { - set: (carrier, key, value) => { - carrier[key] = value; // Set the span context (trace and span ID) - }, - }); - // Attach the x-goog-spanner-request-id to the currently active span. - attributeXGoogSpannerRequestIdToActiveSpan(config); + if (isTracingEnabled(this._observabilityOptions)) { + // Do context propagation + propagation.inject(context.active(), config.headers, { + set: (carrier, key, value) => { + carrier[key] = value; // Set the span context (trace and span ID) + }, + }); + // Attach the x-goog-spanner-request-id to the currently active span. + attributeXGoogSpannerRequestIdToActiveSpan(config); + } const interceptors: any[] = []; if (this._metricsEnabled) { interceptors.push(MetricInterceptor); diff --git a/handwritten/spanner/src/instrument.ts b/handwritten/spanner/src/instrument.ts index 9537e51efd91..99bfdf9a38e8 100644 --- a/handwritten/spanner/src/instrument.ts +++ b/handwritten/spanner/src/instrument.ts @@ -119,6 +119,67 @@ function ensureInitialContextManagerSet() { export {ensureInitialContextManagerSet}; +let globalTracingEnabled: boolean | undefined = undefined; +let lastCheckTime = 0; +const CACHE_TTL_MS = 10000; // 10 seconds TTL + +/** + * isGlobalTracingEnabled returns true if tracing is enabled globally, + * respecting cached status and active recording spans. + * + * @returns {boolean} True if global tracing is enabled. + */ +function isGlobalTracingEnabled(): boolean { + const now = Date.now(); + if ( + globalTracingEnabled !== undefined && + (globalTracingEnabled || now - lastCheckTime < CACHE_TTL_MS) + ) { + return globalTracingEnabled; + } + + lastCheckTime = now; + const globalProvider = trace.getTracerProvider(); + if (globalProvider) { + let delegate = globalProvider; + if (typeof (globalProvider as any).getDelegate === 'function') { + delegate = (globalProvider as any).getDelegate(); + } + if (delegate) { + const name = delegate.constructor.name; + // Exclude the dummy NoopTracerProvider and uninitialized ProxyTracerProvider + if (name !== 'NoopTracerProvider' && name !== 'ProxyTracerProvider') { + globalTracingEnabled = true; + ensureInitialContextManagerSet(); + return true; + } + } + } + globalTracingEnabled = false; + return false; +} + +/** + * isTracingEnabled returns true if tracing is enabled for the given options + * or globally. + * + * @param {ObservabilityOptions} [opts] The observability options. + * @returns {boolean} True if tracing is enabled. + */ +export function isTracingEnabled(opts?: ObservabilityOptions): boolean { + if (opts?.tracerProvider) { + return true; + } + + return isGlobalTracingEnabled(); +} + +/** Only exported for resetting state in unit tests. */ +export function _resetTracingEnabledForTest(): void { + globalTracingEnabled = undefined; + lastCheckTime = 0; +} + /** * startTrace begins an active span in the current active context * and passes it back to the set callback function. Each span will @@ -132,6 +193,10 @@ export function startTrace( config: traceConfig | undefined, cb: (span: Span) => T, ): T { + if (!isTracingEnabled(config?.opts)) { + return cb(new noopSpan()); + } + if (!config) { config = {} as traceConfig; } diff --git a/handwritten/spanner/src/request_id_header.ts b/handwritten/spanner/src/request_id_header.ts index 99c081de64ca..1926e8f6781b 100644 --- a/handwritten/spanner/src/request_id_header.ts +++ b/handwritten/spanner/src/request_id_header.ts @@ -22,6 +22,8 @@ const randIdForProcess = randomBytes(8) .readUint32LE(0) .toString(16) .padStart(8, '0'); +const REQUEST_HEADER_VERSION = 1; +const PROCESS_PREFIX = `${REQUEST_HEADER_VERSION}.${randIdForProcess}.`; const X_GOOG_SPANNER_REQUEST_ID_HEADER = 'x-goog-spanner-request-id'; class AtomicCounter { @@ -57,15 +59,13 @@ class AtomicCounter { } } -const REQUEST_HEADER_VERSION = 1; - function craftRequestId( nthClientId: number, channelId: number, nthRequest: number, attempt: number, ) { - return `${REQUEST_HEADER_VERSION}.${randIdForProcess}.${nthClientId}.${channelId}.${nthRequest}.${attempt}`; + return `${PROCESS_PREFIX}${nthClientId}.${channelId}.${nthRequest}.${attempt}`; } const nthClientId = new AtomicCounter(); @@ -118,15 +118,6 @@ function injectRequestIDIntoError(config: any, err: Error) { } } -interface withNextNthRequest { - _nextNthRequest: Function; -} - -interface withMetadataWithRequestId { - _nthClientId: number; - _channelId: number; -} - function injectRequestIDIntoHeaders( headers: {[k: string]: string}, session: any, @@ -136,52 +127,31 @@ function injectRequestIDIntoHeaders( if (!session) { return headers; } - + const database = session.parent; if (!nthRequest) { - const database = session.parent as withNextNthRequest; - if (!(database && typeof database._nextNthRequest === 'function')) { + if (!database || typeof database._nextNthRequest !== 'function') { return headers; } nthRequest = database._nextNthRequest(); } + const clientId = database ? database._nthClientId || 1 : 1; + const channelId = database ? database._channelId || 1 : 1; - attempt = attempt || 1; - return _metadataWithRequestId(session, nthRequest!, attempt, headers); -} - -function _metadataWithRequestId( - session: any, - nthRequest: number, - attempt: number, - priorMetadata?: {[k: string]: string}, -): {[k: string]: string} { - if (!priorMetadata) { - priorMetadata = {}; - } - const withReqId = { - ...priorMetadata, - }; - const database = session.parent as withMetadataWithRequestId; - let clientId = 1; - let channelId = 1; - if (database) { - clientId = database._nthClientId || 1; - channelId = database._channelId || 1; - } + const withReqId = {...headers}; withReqId[X_GOOG_SPANNER_REQUEST_ID_HEADER] = craftRequestId( clientId, channelId, - nthRequest, - attempt, + nthRequest || 1, + attempt || 1, ); return withReqId; } function nextNthRequest(database): number { - if (!(database && typeof database._nextNthRequest === 'function')) { - return 1; + if (database && typeof database._nextNthRequest === 'function') { + return database._nextNthRequest(); } - return database._nextNthRequest(); + return 1; } export interface RequestIDError extends grpc.ServiceError { diff --git a/handwritten/spanner/test/spanner.ts b/handwritten/spanner/test/spanner.ts index fc14dff5378d..54e506b9b754 100644 --- a/handwritten/spanner/test/spanner.ts +++ b/handwritten/spanner/test/spanner.ts @@ -91,7 +91,13 @@ const { InMemorySpanExporter, } = require('@opentelemetry/sdk-trace-node'); const {SimpleSpanProcessor} = require('@opentelemetry/sdk-trace-base'); -const {startTrace, ObservabilityOptions} = require('../src/instrument'); +const {trace} = require('@opentelemetry/api'); +const { + startTrace, + ObservabilityOptions, + isTracingEnabled, + _resetTracingEnabledForTest, +} = require('../src/instrument'); function numberToEnglishWord(num: number): string { switch (num) { @@ -7112,6 +7118,7 @@ describe('Spanner with mock server', () => { spanProcessors: [new SimpleSpanProcessor(exporter)], }); provider.register(); + _resetTracingEnabledForTest(); after(async () => { await provider.shutdown(); @@ -7205,6 +7212,7 @@ describe('Spanner with mock server', () => { provider.register(); beforeEach(async () => { + _resetTracingEnabledForTest(); await exporter.forceFlush(); await exporter.reset(); }); @@ -7311,8 +7319,156 @@ describe('Spanner with mock server', () => { }); }); - // TODO(@odeke-em): introduce tests for incremented attempts to verify - // that retries from GAX produce the required results. + }); + + describe('Tracing cache TTL', () => { + const ttlSandbox = sinon.createSandbox(); + let warpOffset: number; + + beforeEach(() => { + _resetTracingEnabledForTest(); + warpOffset = 0; + const originalNow = Date.now; + ttlSandbox.stub(Date, 'now').callsFake(() => originalNow.call(Date) + warpOffset); + }); + + afterEach(() => { + ttlSandbox.restore(); + }); + + it('should respect the 10-second TTL cache for global tracing checks', () => { + // 1. Initially no global tracer is configured, returns false + const getTracerProviderStub = ttlSandbox.stub(trace, 'getTracerProvider'); + getTracerProviderStub.returns({ + constructor: { name: 'ProxyTracerProvider' }, + getDelegate: () => ({ constructor: { name: 'NoopTracerProvider' } }), + getTracer: () => ({ + startActiveSpan: (name, options, cb) => cb({ setAttribute: () => {}, end: () => {} } as any), + }), + } as any); + + assert.strictEqual(isTracingEnabled(), false); + assert.strictEqual(getTracerProviderStub.callCount, 1); + + // 2. Even if OpenTelemetry is registered immediately after, it should hit the cache and return false + getTracerProviderStub.returns({ + constructor: { name: 'ProxyTracerProvider' }, + getDelegate: () => ({ constructor: { name: 'NodeTracerProvider' } }), + getTracer: () => ({ + startActiveSpan: (name, options, cb) => cb({ setAttribute: () => {}, end: () => {} } as any), + }), + } as any); + + assert.strictEqual(isTracingEnabled(), false); + // Call count remains 1 because it was cached! + assert.strictEqual(getTracerProviderStub.callCount, 1); + + // 3. Advance clock by 9.9 seconds (still within 10s TTL) + warpOffset += 9900; + assert.strictEqual(isTracingEnabled(), false); + assert.strictEqual(getTracerProviderStub.callCount, 1); + + // 4. Advance clock past the 10s TTL (e.g., 10.1 seconds total) + warpOffset += 200; // 9.9s + 0.2s = 10.1s + // Cache should be expired now, so it re-checks and auto-detects NodeTracerProvider! + assert.strictEqual(isTracingEnabled(), true); + assert.strictEqual(getTracerProviderStub.callCount, 2); + + // 5. Once enabled, subsequent calls should permanently return true without re-evaluating or checking global provider + assert.strictEqual(isTracingEnabled(), true); + // Call count remains 2! + assert.strictEqual(getTracerProviderStub.callCount, 2); + + // Advance clock by another 1 hour to prove it's permanently cached + warpOffset += 3600000; + assert.strictEqual(isTracingEnabled(), true); + assert.strictEqual(getTracerProviderStub.callCount, 2); + }); + + it('real application flow: should transition from untraced to traced after OTel registration and TTL expiration', async () => { + const exporter = new InMemorySpanExporter(); + const provider = new NodeTracerProvider({ + sampler: new AlwaysOnSampler(), + spanProcessors: [new SimpleSpanProcessor(exporter)], + }); + + const getTracerProviderStub = ttlSandbox.stub(trace, 'getTracerProvider'); + // First phase: global provider is unconfigured (Proxy/Noop) + // We delegate getTracer to provider so that if getTracer is ever called, it works perfectly, + // but name is 'ProxyTracerProvider' so it is detected as unconfigured! + getTracerProviderStub.returns({ + constructor: { name: 'ProxyTracerProvider' }, + getDelegate: () => ({ constructor: { name: 'NoopTracerProvider' } }), + getTracer: (name, version) => provider.getTracer(name, version), + } as any); + + const localDatabase = newTestDatabase(); + + // First call: it shouldn't generate any spans! + const [rows1] = await localDatabase.run({ sql: selectSql }); + assert.strictEqual(rows1.length, 3); + assert.strictEqual(exporter.getFinishedSpans().length, 0); + + // Second call immediately: because 10s TTL cache is still active, it should still NOT trace! + const [rows2] = await localDatabase.run({ sql: selectSql }); + assert.strictEqual(rows2.length, 3); + assert.strictEqual(exporter.getFinishedSpans().length, 0); + + // Register the global provider in our stub + getTracerProviderStub.returns(provider); + + // Advance clock past 10s TTL + warpOffset += 10100; + + // Third call: cache has expired, so it auto-detects OTel and traces successfully! + const [rows3] = await localDatabase.run({ sql: selectSql }); + assert.strictEqual(rows3.length, 3); + + // Verify that we successfully captured spans! + const finishedSpans = exporter.getFinishedSpans(); + const spanNames = finishedSpans.map(s => s.name); + assert.ok(finishedSpans.length > 0); + assert.ok(spanNames.includes('CloudSpanner.Database.run')); + + // Cleanup + await provider.shutdown(); + await localDatabase.close(); + }); + + it('should not cause issues when global OTel is registered before Spanner client (calls ensureInitialContextManagerSet twice)', async () => { + const exporter = new InMemorySpanExporter(); + const provider = new NodeTracerProvider({ + sampler: new AlwaysOnSampler(), + spanProcessors: [new SimpleSpanProcessor(exporter)], + }); + + // Setup trace.getTracerProvider stub to return the registered provider immediately + const getTracerProviderStub = ttlSandbox.stub(trace, 'getTracerProvider'); + getTracerProviderStub.returns(provider); + + // Creating client when global provider is already registered. + // This will invoke ensureInitialContextManagerSet() in isTracingEnabled check AND in constructor block. + const localSpanner = new Spanner({ + servicePath: 'localhost', + port, + sslCreds: grpc.credentials.createInsecure(), + }); + const localInstance = localSpanner.instance('instance'); + const localDatabase = localInstance.database(`database-pre-${dbCounter++}`); + + // Verify the query traces successfully without any issue or crash + const [rows] = await localDatabase.run({ sql: selectSql }); + assert.strictEqual(rows.length, 3); + + const finishedSpans = exporter.getFinishedSpans(); + assert.ok(finishedSpans.length > 0); + const spanNames = finishedSpans.map(s => s.name); + assert.ok(spanNames.includes('CloudSpanner.Database.run')); + + // Cleanup + await provider.shutdown(); + localSpanner.close(); + }); }); });