diff --git a/.changeset/blue-eels-warn.md b/.changeset/blue-eels-warn.md new file mode 100644 index 00000000000..1e963c7e68e --- /dev/null +++ b/.changeset/blue-eels-warn.md @@ -0,0 +1,6 @@ +--- +'@firebase/firestore': patch +'firebase': patch +--- + +Improved debug logging of networking abstractions diff --git a/packages/firestore/src/platform/browser/webchannel_connection.ts b/packages/firestore/src/platform/browser/webchannel_connection.ts index 22c45227009..c7eeec0f7f1 100644 --- a/packages/firestore/src/platform/browser/webchannel_connection.ts +++ b/packages/firestore/src/platform/browser/webchannel_connection.ts @@ -41,12 +41,13 @@ import { } from '../../remote/rpc_error'; import { StreamBridge } from '../../remote/stream_bridge'; import { fail, hardAssert } from '../../util/assert'; +import { generateUniqueDebugId } from '../../util/debug_uid'; import { Code, FirestoreError } from '../../util/error'; import { logDebug, logWarn } from '../../util/log'; import { Rejecter, Resolver } from '../../util/promise'; import { StringMap } from '../../util/types'; -const LOG_TAG = 'Connection'; +const LOG_TAG = 'WebChannelConnection'; const RPC_STREAM_SERVICE = 'google.firestore.v1.Firestore'; @@ -70,6 +71,7 @@ export class WebChannelConnection extends RestConnection { headers: StringMap, body: Req ): Promise { + const streamId = generateUniqueDebugId(); return new Promise((resolve: Resolver, reject: Rejecter) => { const xhr = new XhrIo(); xhr.setWithCredentials(true); @@ -78,11 +80,15 @@ export class WebChannelConnection extends RestConnection { switch (xhr.getLastErrorCode()) { case ErrorCode.NO_ERROR: const json = xhr.getResponseJson() as Resp; - logDebug(LOG_TAG, 'XHR received:', JSON.stringify(json)); + logDebug( + LOG_TAG, + `XHR for RPC '${rpcName}' ${streamId} received:`, + JSON.stringify(json) + ); resolve(json); break; case ErrorCode.TIMEOUT: - logDebug(LOG_TAG, 'RPC "' + rpcName + '" timed out'); + logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} timed out`); reject( new FirestoreError(Code.DEADLINE_EXCEEDED, 'Request time out') ); @@ -91,7 +97,7 @@ export class WebChannelConnection extends RestConnection { const status = xhr.getStatus(); logDebug( LOG_TAG, - 'RPC "' + rpcName + '" failed with status:', + `RPC '${rpcName}' ${streamId} failed with status:`, status, 'response text:', xhr.getResponseText() @@ -134,10 +140,8 @@ export class WebChannelConnection extends RestConnection { break; default: fail( - 'RPC "' + - rpcName + - '" failed with unanticipated ' + - 'webchannel error ' + + `RPC '${rpcName}' ${streamId} ` + + 'failed with unanticipated webchannel error: ' + xhr.getLastErrorCode() + ': ' + xhr.getLastError() + @@ -145,11 +149,12 @@ export class WebChannelConnection extends RestConnection { ); } } finally { - logDebug(LOG_TAG, 'RPC "' + rpcName + '" completed.'); + logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} completed.`); } }); const requestString = JSON.stringify(body); + logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} sending request:`, body); xhr.send(url, 'POST', requestString, headers, XHR_TIMEOUT_SECS); }); } @@ -159,6 +164,7 @@ export class WebChannelConnection extends RestConnection { authToken: Token | null, appCheckToken: Token | null ): Stream { + const streamId = generateUniqueDebugId(); const urlParts = [ this.baseUrl, '/', @@ -217,7 +223,11 @@ export class WebChannelConnection extends RestConnection { request.encodeInitMessageHeaders = true; const url = urlParts.join(''); - logDebug(LOG_TAG, 'Creating WebChannel: ' + url, request); + logDebug( + LOG_TAG, + `Creating RPC '${rpcName}' stream ${streamId}: ${url}`, + request + ); const channel = webchannelTransport.createWebChannel(url, request); // WebChannel supports sending the first message with the handshake - saving @@ -236,14 +246,26 @@ export class WebChannelConnection extends RestConnection { sendFn: (msg: Req) => { if (!closed) { if (!opened) { - logDebug(LOG_TAG, 'Opening WebChannel transport.'); + logDebug( + LOG_TAG, + `Opening RPC '${rpcName}' stream ${streamId} transport.` + ); channel.open(); opened = true; } - logDebug(LOG_TAG, 'WebChannel sending:', msg); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} sending:`, + msg + ); channel.send(msg); } else { - logDebug(LOG_TAG, 'Not sending because WebChannel is closed:', msg); + logDebug( + LOG_TAG, + `Not sending because RPC '${rpcName}' stream ${streamId} ` + + 'is closed:', + msg + ); } }, closeFn: () => channel.close() @@ -273,14 +295,20 @@ export class WebChannelConnection extends RestConnection { unguardedEventListen(channel, WebChannel.EventType.OPEN, () => { if (!closed) { - logDebug(LOG_TAG, 'WebChannel transport opened.'); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} transport opened.` + ); } }); unguardedEventListen(channel, WebChannel.EventType.CLOSE, () => { if (!closed) { closed = true; - logDebug(LOG_TAG, 'WebChannel transport closed'); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} transport closed` + ); streamBridge.callOnClose(); } }); @@ -288,7 +316,11 @@ export class WebChannelConnection extends RestConnection { unguardedEventListen(channel, WebChannel.EventType.ERROR, err => { if (!closed) { closed = true; - logWarn(LOG_TAG, 'WebChannel transport errored:', err); + logWarn( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} transport errored:`, + err + ); streamBridge.callOnClose( new FirestoreError( Code.UNAVAILABLE, @@ -322,7 +354,11 @@ export class WebChannelConnection extends RestConnection { msgDataOrError.error || (msgDataOrError as WebChannelError[])[0]?.error; if (error) { - logDebug(LOG_TAG, 'WebChannel received error:', error); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} received error:`, + error + ); // error.status will be a string like 'OK' or 'NOT_FOUND'. const status: string = error.status; let code = mapCodeFromRpcStatus(status); @@ -340,7 +376,11 @@ export class WebChannelConnection extends RestConnection { streamBridge.callOnClose(new FirestoreError(code, message)); channel.close(); } else { - logDebug(LOG_TAG, 'WebChannel received:', msgData); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} received:`, + msgData + ); streamBridge.callOnMessage(msgData); } } @@ -349,9 +389,15 @@ export class WebChannelConnection extends RestConnection { unguardedEventListen(requestStats, Event.STAT_EVENT, event => { if (event.stat === Stat.PROXY) { - logDebug(LOG_TAG, 'Detected buffering proxy'); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} detected buffering proxy` + ); } else if (event.stat === Stat.NOPROXY) { - logDebug(LOG_TAG, 'Detected no buffering proxy'); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} detected no buffering proxy` + ); } }); diff --git a/packages/firestore/src/platform/node/grpc_connection.ts b/packages/firestore/src/platform/node/grpc_connection.ts index b5d77a11bf7..77879c280ad 100644 --- a/packages/firestore/src/platform/node/grpc_connection.ts +++ b/packages/firestore/src/platform/node/grpc_connection.ts @@ -26,6 +26,7 @@ import { Connection, Stream } from '../../remote/connection'; import { mapCodeFromRpcCode } from '../../remote/rpc_error'; import { StreamBridge } from '../../remote/stream_bridge'; import { hardAssert } from '../../util/assert'; +import { generateUniqueDebugId } from '../../util/debug_uid'; import { FirestoreError } from '../../util/error'; import { logError, logDebug, logWarn } from '../../util/log'; import { NodeCallback, nodePromise } from '../../util/node_api'; @@ -35,7 +36,7 @@ import { Deferred } from '../../util/promise'; // when there's a cleaner way to dynamic require JSON in both Node ESM and CJS const grpcVersion = '__GRPC_VERSION__'; -const LOG_TAG = 'Connection'; +const LOG_TAG = 'GrpcConnection'; const X_GOOG_API_CLIENT_VALUE = `gl-node/${process.versions.node} fire/${SDK_VERSION} grpc/${grpcVersion}`; function createMetadata( @@ -118,6 +119,7 @@ export class GrpcConnection implements Connection { authToken: Token | null, appCheckToken: Token | null ): Promise { + const streamId = generateUniqueDebugId(); const stub = this.ensureActiveStub(); const metadata = createMetadata( this.databasePath, @@ -128,13 +130,21 @@ export class GrpcConnection implements Connection { const jsonRequest = { database: this.databasePath, ...request }; return nodePromise((callback: NodeCallback) => { - logDebug(LOG_TAG, `RPC '${rpcName}' invoked with request:`, request); + logDebug( + LOG_TAG, + `RPC '${rpcName}' ${streamId} invoked with request:`, + request + ); return stub[rpcName]( jsonRequest, metadata, (grpcError?: grpc.ServiceError, value?: Resp) => { if (grpcError) { - logDebug(LOG_TAG, `RPC '${rpcName}' failed with error:`, grpcError); + logDebug( + LOG_TAG, + `RPC '${rpcName}' ${streamId} failed with error:`, + grpcError + ); callback( new FirestoreError( mapCodeFromRpcCode(grpcError.code), @@ -144,7 +154,7 @@ export class GrpcConnection implements Connection { } else { logDebug( LOG_TAG, - `RPC '${rpcName}' completed with response:`, + `RPC '${rpcName}' ${streamId} completed with response:`, value ); callback(undefined, value); @@ -162,11 +172,12 @@ export class GrpcConnection implements Connection { appCheckToken: Token | null, expectedResponseCount?: number ): Promise { + const streamId = generateUniqueDebugId(); const results: Resp[] = []; const responseDeferred = new Deferred(); logDebug( LOG_TAG, - `RPC '${rpcName}' invoked (streaming) with request:`, + `RPC '${rpcName}' ${streamId} invoked (streaming) with request:`, request ); const stub = this.ensureActiveStub(); @@ -180,7 +191,11 @@ export class GrpcConnection implements Connection { const stream = stub[rpcName](jsonRequest, metadata); let callbackFired = false; stream.on('data', (response: Resp) => { - logDebug(LOG_TAG, `RPC ${rpcName} received result:`, response); + logDebug( + LOG_TAG, + `RPC ${rpcName} ${streamId} received result:`, + response + ); results.push(response); if ( expectedResponseCount !== undefined && @@ -191,14 +206,18 @@ export class GrpcConnection implements Connection { } }); stream.on('end', () => { - logDebug(LOG_TAG, `RPC '${rpcName}' completed.`); + logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} completed.`); if (!callbackFired) { callbackFired = true; responseDeferred.resolve(results); } }); stream.on('error', (grpcError: grpc.ServiceError) => { - logDebug(LOG_TAG, `RPC '${rpcName}' failed with error:`, grpcError); + logDebug( + LOG_TAG, + `RPC '${rpcName}' ${streamId} failed with error:`, + grpcError + ); const code = mapCodeFromRpcCode(grpcError.code); responseDeferred.reject(new FirestoreError(code, grpcError.message)); }); @@ -212,6 +231,7 @@ export class GrpcConnection implements Connection { authToken: Token | null, appCheckToken: Token | null ): Stream { + const streamId = generateUniqueDebugId(); const stub = this.ensureActiveStub(); const metadata = createMetadata( this.databasePath, @@ -233,7 +253,11 @@ export class GrpcConnection implements Connection { const stream = new StreamBridge({ sendFn: (msg: Req) => { if (!closed) { - logDebug(LOG_TAG, 'GRPC stream sending:', msg); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} sending:`, + msg + ); try { grpcStream.write(msg); } catch (e) { @@ -244,24 +268,32 @@ export class GrpcConnection implements Connection { throw e; } } else { - logDebug(LOG_TAG, 'Not sending because gRPC stream is closed:', msg); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} ` + + 'not sending because gRPC stream is closed:', + msg + ); } }, closeFn: () => { - logDebug(LOG_TAG, 'GRPC stream closed locally via close().'); + logDebug( + LOG_TAG, + `RPC '${rpcName}' stream ${streamId} closed locally via close().` + ); close(); } }); grpcStream.on('data', (msg: Resp) => { if (!closed) { - logDebug(LOG_TAG, 'GRPC stream received:', msg); + logDebug(LOG_TAG, `RPC '${rpcName}' stream ${streamId} received:`, msg); stream.callOnMessage(msg); } }); grpcStream.on('end', () => { - logDebug(LOG_TAG, 'GRPC stream ended.'); + logDebug(LOG_TAG, `RPC '${rpcName}' stream ${streamId} ended.`); close(); }); @@ -269,7 +301,7 @@ export class GrpcConnection implements Connection { if (!closed) { logWarn( LOG_TAG, - 'GRPC stream error. Code:', + `RPC '${rpcName}' stream ${streamId} error. Code:`, grpcError.code, 'Message:', grpcError.message @@ -279,7 +311,11 @@ export class GrpcConnection implements Connection { } }); - logDebug(LOG_TAG, 'Opening GRPC stream'); + logDebug( + LOG_TAG, + `Opening RPC '${rpcName}' stream ${streamId} ` + + `to ${this.databaseInfo.host}` + ); // TODO(dimond): Since grpc has no explicit open status (or does it?) we // simulate an onOpen in the next loop after the stream had it's listeners // registered diff --git a/packages/firestore/src/remote/rest_connection.ts b/packages/firestore/src/remote/rest_connection.ts index 40ab436787a..b49aaaaf695 100644 --- a/packages/firestore/src/remote/rest_connection.ts +++ b/packages/firestore/src/remote/rest_connection.ts @@ -19,6 +19,7 @@ import { SDK_VERSION } from '../../src/core/version'; import { Token } from '../api/credentials'; import { DatabaseId, DatabaseInfo } from '../core/database_info'; import { debugAssert } from '../util/assert'; +import { generateUniqueDebugId } from '../util/debug_uid'; import { FirestoreError } from '../util/error'; import { logDebug, logWarn } from '../util/log'; import { StringMap } from '../util/types'; @@ -80,21 +81,22 @@ export abstract class RestConnection implements Connection { authToken: Token | null, appCheckToken: Token | null ): Promise { + const streamId = generateUniqueDebugId(); const url = this.makeUrl(rpcName, path); - logDebug(LOG_TAG, 'Sending: ', url, req); + logDebug(LOG_TAG, `Sending RPC '${rpcName}' ${streamId}:`, url, req); const headers = {}; this.modifyHeadersForRequest(headers, authToken, appCheckToken); return this.performRPCRequest(rpcName, url, headers, req).then( response => { - logDebug(LOG_TAG, 'Received: ', response); + logDebug(LOG_TAG, `Received RPC '${rpcName}' ${streamId}: `, response); return response; }, (err: FirestoreError) => { logWarn( LOG_TAG, - `${rpcName} failed with error: `, + `RPC '${rpcName}' ${streamId} failed with error: `, err, 'url: ', url, diff --git a/packages/firestore/src/util/debug_uid.ts b/packages/firestore/src/util/debug_uid.ts new file mode 100644 index 00000000000..d5dac6a1343 --- /dev/null +++ b/packages/firestore/src/util/debug_uid.ts @@ -0,0 +1,61 @@ +/** + * @license + * Copyright 2023 Google LLC + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +/** + * The value returned from the most recent invocation of + * `generateUniqueDebugId()`, or null if it has never been invoked. + */ +let lastUniqueDebugId: number | null = null; + +/** + * Generates and returns an initial value for `lastUniqueDebugId`. + * + * The returned value is randomly selected from a range of integers that are + * represented as 8 hexadecimal digits. This means that (within reason) any + * numbers generated by incrementing the returned number by 1 will also be + * represented by 8 hexadecimal digits. This leads to all "IDs" having the same + * length when converted to a hexadecimal string, making reading logs containing + * these IDs easier to follow. And since the return value is randomly selected + * it will help to differentiate between logs from different executions. + */ +function generateInitialUniqueDebugId(): number { + const minResult = 0x10000000; + const maxResult = 0x90000000; + const resultRange = maxResult - minResult; + const resultOffset = Math.round(resultRange * Math.random()); + return minResult + resultOffset; +} + +/** + * Generates and returns a unique ID as a hexadecimal string. + * + * The returned ID is intended to be used in debug logging messages to help + * correlate log messages that may be spatially separated in the logs, but + * logically related. For example, a network connection could include the same + * "debug ID" string in all of its log messages to help trace a specific + * connection over time. + * + * @return the 10-character generated ID (e.g. "0xa1b2c3d4"). + */ +export function generateUniqueDebugId(): string { + if (lastUniqueDebugId === null) { + lastUniqueDebugId = generateInitialUniqueDebugId(); + } else { + lastUniqueDebugId++; + } + return '0x' + lastUniqueDebugId.toString(16); +}