diff --git a/packages/runtime/datastore/src/dataStoreRuntime.ts b/packages/runtime/datastore/src/dataStoreRuntime.ts index 0c34a36c6f3e..0e0ccfe3dd88 100644 --- a/packages/runtime/datastore/src/dataStoreRuntime.ts +++ b/packages/runtime/datastore/src/dataStoreRuntime.ts @@ -423,8 +423,9 @@ export class FluidDataStoreRuntime logger: dataStoreContext.baseLogger, namespace: "FluidDataStoreRuntime", properties: { - all: { dataStoreId: uuid(), dataStoreVersion: pkgVersion }, - error: { + all: { + dataStoreVersion: pkgVersion, + ...dataStoreLoadTelemetryProps(dataStoreContext), inStagingMode: () => this.inStagingMode, isDirty: () => this.isDirty, }, @@ -1574,8 +1575,9 @@ export class FluidDataStoreRuntime ...tagCodeArtifacts({ channelType, channelId, - fluidDataStoreId: this.id, - fluidDataStorePackagePath: this.dataStoreContext.packagePath.join("/"), + // Properties renamed in 2.103.0 (present via logger common props): + // fluidDataStoreId -> dataStoreId + // fluidDataStorePackagePath -> dataStorePackagePath }), stack: generateStack(30), }); diff --git a/packages/runtime/datastore/src/localChannelContext.ts b/packages/runtime/datastore/src/localChannelContext.ts index 84df52427725..db3ac43f5076 100644 --- a/packages/runtime/datastore/src/localChannelContext.ts +++ b/packages/runtime/datastore/src/localChannelContext.ts @@ -19,9 +19,12 @@ import type { IRuntimeMessageCollection, IRuntimeStorageService, } from "@fluidframework/runtime-definitions/internal"; +import { dataStoreLoadTelemetryProps } from "@fluidframework/runtime-utils/internal"; import { type TelemetryLoggerExt, DataProcessingError, + createChildLogger, + tagCodeArtifacts, } from "@fluidframework/telemetry-utils/internal"; import { @@ -221,6 +224,19 @@ export class RehydratedLocalChannelContext extends LocalChannelContextBase { private readonly snapshotTree: ISnapshotTree, extraBlob?: Map, ) { + // `channelType` is not known until the LazyPromise body runs `loadChannelFactoryAndAttributes`. + // Pass a getter to `tagCodeArtifacts` so events log the type as soon as it's available. + let channelType: string | undefined; + + const subLogger = createChildLogger({ + logger, + namespace: "RehydratedLocalChannelContext", + properties: { + all: { + ...tagCodeArtifacts({ channelId: id, channelType: () => channelType }), + }, + }, + }); super( id, runtime, @@ -241,7 +257,7 @@ export class RehydratedLocalChannelContext extends LocalChannelContextBase { this.dirtyFn, () => this.isGloballyVisible, storageService, - logger, + subLogger, clonedSnapshotTree, blobMap, ); @@ -254,12 +270,13 @@ export class RehydratedLocalChannelContext extends LocalChannelContextBase { this.id, registry, ); + channelType = attributes.type; const channel = await loadChannel( runtime, attributes, factory, this.services.value, - logger, + subLogger, this.id, ); // Send all pending messages to the channel @@ -268,11 +285,18 @@ export class RehydratedLocalChannelContext extends LocalChannelContextBase { } return channel; } catch (error) { - throw DataProcessingError.wrapIfUnrecognized( + const errorWrapped = DataProcessingError.wrapIfUnrecognized( error, "rehydratedLocalChannelContextFailedToLoadChannel", - undefined, ); + errorWrapped.addTelemetryProperties({ + ...dataStoreLoadTelemetryProps(dataStoreContext), + ...tagCodeArtifacts({ channelId: id, channelType }), + }); + + // "Realize" is another name for instantiating the channel for a context + subLogger.sendErrorEvent({ eventName: "RealizeError" }, errorWrapped); + throw errorWrapped; } }), ); diff --git a/packages/runtime/datastore/src/remoteChannelContext.ts b/packages/runtime/datastore/src/remoteChannelContext.ts index 7d5ebcd7d5d8..38cb80ed6bcd 100644 --- a/packages/runtime/datastore/src/remoteChannelContext.ts +++ b/packages/runtime/datastore/src/remoteChannelContext.ts @@ -23,10 +23,13 @@ import type { IRuntimeMessageCollection, IRuntimeStorageService, } from "@fluidframework/runtime-definitions/internal"; +import { dataStoreLoadTelemetryProps } from "@fluidframework/runtime-utils/internal"; import { + DataProcessingError, type TelemetryLoggerExt, ThresholdCounter, createChildLogger, + tagCodeArtifacts, } from "@fluidframework/telemetry-utils/internal"; import { @@ -71,9 +74,21 @@ export class RemoteChannelContext implements IChannelContext { ) { assert(!this.id.includes("/"), 0x310 /* Channel context ID cannot contain slashes */); + // `channelType` is not known until the LazyPromise body runs `loadChannelFactoryAndAttributes`. + // Pass a getter to `tagCodeArtifacts` so events log the type as soon as it's available. + let channelType: string | undefined; + this.subLogger = createChildLogger({ logger: runtime.logger, namespace: "RemoteChannelContext", + properties: { + all: { + ...tagCodeArtifacts({ + channelId: this.id, + channelType: () => channelType, + }), + }, + }, }); this.services = createChannelServiceEndpoints( @@ -88,44 +103,60 @@ export class RemoteChannelContext implements IChannelContext { ); this.channelP = new LazyPromise(async () => { - const { attributes, factory } = await loadChannelFactoryAndAttributes( - dataStoreContext, - this.services, - this.id, - registry, - attachMessageType, - ); + try { + const { attributes, factory } = await loadChannelFactoryAndAttributes( + dataStoreContext, + this.services, + this.id, + registry, + attachMessageType, + ); + channelType = attributes.type; - const channel = await loadChannel( - runtime, - attributes, - factory, - this.services, - this.subLogger, - this.id, - ); + const channel = await loadChannel( + runtime, + attributes, + factory, + this.services, + this.subLogger, + this.id, + ); - assert( - this.pendingMessagesState !== undefined, - 0xa6c /* pending messages state is undefined */, - ); - for (const messageCollection of this.pendingMessagesState.messageCollections) { - this.services.deltaConnection.processMessages(messageCollection); - } - this.thresholdOpsCounter.send( - "ProcessPendingOps", - this.pendingMessagesState.pendingCount, - ); + assert( + this.pendingMessagesState !== undefined, + 0xa6c /* pending messages state is undefined */, + ); + for (const messageCollection of this.pendingMessagesState.messageCollections) { + this.services.deltaConnection.processMessages(messageCollection); + } + this.thresholdOpsCounter.send( + "ProcessPendingOps", + this.pendingMessagesState.pendingCount, + ); - // Commit changes. - this.channel = channel; - this.pendingMessagesState = undefined; - this.isLoaded = true; + // Commit changes. + this.channel = channel; + this.pendingMessagesState = undefined; + this.isLoaded = true; - // Because have some await between we created the service and here, the connection state might have changed - // and we don't propagate the connection state when we are not loaded. So we have to set it again here. - this.services.deltaConnection.setConnectionState(dataStoreContext.connected); - return this.channel; + // Because have some await between we created the service and here, the connection state might have changed + // and we don't propagate the connection state when we are not loaded. So we have to set it again here. + this.services.deltaConnection.setConnectionState(dataStoreContext.connected); + return this.channel; + } catch (error) { + const errorWrapped = DataProcessingError.wrapIfUnrecognized( + error, + "remoteChannelContextFailedToLoadChannel", + ); + errorWrapped.addTelemetryProperties({ + ...dataStoreLoadTelemetryProps(dataStoreContext), + ...tagCodeArtifacts({ channelId: id, channelType }), + }); + + // "Realize" is another name for instantiating the channel for a context + this.subLogger.sendErrorEvent({ eventName: "RealizeError" }, errorWrapped); + throw errorWrapped; + } }); this.summarizerNode = createSummarizerNode( diff --git a/packages/runtime/datastore/src/test/localChannelContext.spec.ts b/packages/runtime/datastore/src/test/localChannelContext.spec.ts index d81d2468f7ed..53fa769112dc 100644 --- a/packages/runtime/datastore/src/test/localChannelContext.spec.ts +++ b/packages/runtime/datastore/src/test/localChannelContext.spec.ts @@ -5,10 +5,17 @@ import { strict as assert } from "node:assert"; +import { ContainerErrorTypes } from "@fluidframework/container-definitions/internal"; +import type { IErrorBase } from "@fluidframework/core-interfaces"; import type { IChannel } from "@fluidframework/datastore-definitions/internal"; import type { ISnapshotTree } from "@fluidframework/driver-definitions/internal"; import type { IFluidDataStoreContext } from "@fluidframework/runtime-definitions/internal"; -import { extractTelemetryLoggerExt } from "@fluidframework/telemetry-utils/internal"; +import { + extractTelemetryLoggerExt, + isFluidError, + MockLogger, + TelemetryDataTag, +} from "@fluidframework/telemetry-utils/internal"; import { MockFluidDataStoreContext, validateAssertionError, @@ -83,4 +90,60 @@ describe("LocalChannelContext Tests", () => { "Expected exception was not thrown", ); }); + + it("RehydratedLocalChannelContext first await on getChannel() logs ChannelLoadFailure with tagged props when load fails", async () => { + const channelId = "ddsId"; + const mockLogger = new MockLogger(); + const contextWithMockLogger = new MockFluidDataStoreContext( + "testDataStoreId", + false, + mockLogger.toTelemetryLogger(), + ); + contextWithMockLogger.packagePath = ["pkgA", "pkgB"]; + const dataStoreRuntime = loadRuntime(contextWithMockLogger, sharedObjectRegistry); + + // Registry returns undefined so loadChannelFactoryAndAttributes throws + // inside the LazyPromise body. With an empty snapshot tree and no + // attachMessageType, this throws `channelTypeNotAvailable`. + const failingRegistry: ISharedObjectRegistry = { + get: () => undefined, + }; + + const rehydratedChannelContext = new RehydratedLocalChannelContext( + channelId, + failingRegistry, + dataStoreRuntime, + contextWithMockLogger, + contextWithMockLogger.storage, + extractTelemetryLoggerExt(contextWithMockLogger.baseLogger), + () => {}, + () => {}, + { trees: {}, blobs: {} } as unknown as ISnapshotTree, + ); + + await assert.rejects( + async () => rehydratedChannelContext.getChannel(), + (error: IErrorBase) => { + assert.strictEqual( + error.errorType, + ContainerErrorTypes.dataProcessingError, + "thrown error should be a DataProcessingError", + ); + assert(isFluidError(error), "thrown error should be a Fluid error"); + return true; + }, + ); + + mockLogger.assertMatchAny( + [ + { + eventName: "RehydratedLocalChannelContext:RealizeError", + fluidDataStoreId: { value: "testDataStoreId", tag: TelemetryDataTag.CodeArtifact }, + fullPackageName: { value: "pkgA/pkgB", tag: TelemetryDataTag.CodeArtifact }, + channelId: { value: channelId, tag: TelemetryDataTag.CodeArtifact }, + }, + ], + "Expected one RealizeError event with tagged data-store and channel props", + ); + }); }); diff --git a/packages/runtime/datastore/src/test/remoteChannelContext.spec.ts b/packages/runtime/datastore/src/test/remoteChannelContext.spec.ts index 4615f706dcdf..d2aacd9cce08 100644 --- a/packages/runtime/datastore/src/test/remoteChannelContext.spec.ts +++ b/packages/runtime/datastore/src/test/remoteChannelContext.spec.ts @@ -5,12 +5,20 @@ import { strict as assert } from "node:assert"; +import { ContainerErrorTypes } from "@fluidframework/container-definitions/internal"; +import type { IErrorBase } from "@fluidframework/core-interfaces"; import type { ISnapshotTree } from "@fluidframework/driver-definitions/internal"; import type { CreateChildSummarizerNodeFn, IContainerRuntimeBase, IFluidDataStoreContext, + ISummarizerNodeWithGC, } from "@fluidframework/runtime-definitions/internal"; +import { + isFluidError, + MockLogger, + TelemetryDataTag, +} from "@fluidframework/telemetry-utils/internal"; import { MockFluidDataStoreContext, validateAssertionError, @@ -65,4 +73,71 @@ describe("RemoteChannelContext Tests", () => { "Expected exception was not thrown", ); }); + + it("first await on getChannel() logs ChannelLoadFailure with tagged props when load fails", async () => { + const channelId = "ddsId"; + const mockLogger = new MockLogger(); + const contextWithMockLogger = new MockFluidDataStoreContext( + "testDataStoreId", + false, + mockLogger.toTelemetryLogger(), + ); + contextWithMockLogger.containerRuntime = {} as unknown as IContainerRuntimeBase; + contextWithMockLogger.packagePath = ["pkgA", "pkgB"]; + + const dataStoreRuntime = loadRuntime(contextWithMockLogger, sharedObjectRegistry); + + // Registry returns undefined so loadChannelFactoryAndAttributes throws + // `channelFactoryNotRegisteredForGivenType` inside the LazyPromise body. + const failingRegistry: ISharedObjectRegistry = { + get: () => undefined, + }; + + const createSummarizerNode: CreateChildSummarizerNodeFn = () => + ({ + invalidate: () => {}, + summarize: async () => ({ summary: {}, stats: {} }), + getGCData: async () => ({ gcNodes: {} }), + updateUsedRoutes: () => {}, + }) as unknown as ISummarizerNodeWithGC; + + const remoteChannelContext = new RemoteChannelContext( + dataStoreRuntime, + contextWithMockLogger, + contextWithMockLogger.storage, + () => {}, + () => {}, + channelId, + { trees: {}, blobs: {} } as unknown as ISnapshotTree, + failingRegistry, + undefined /* extraBlobs */, + createSummarizerNode, + "SomeAttachMessageType", + ); + + await assert.rejects( + async () => remoteChannelContext.getChannel(), + (error: IErrorBase) => { + assert.strictEqual( + error.errorType, + ContainerErrorTypes.dataProcessingError, + "thrown error should be a DataProcessingError", + ); + assert(isFluidError(error), "thrown error should be a Fluid error"); + return true; + }, + ); + + mockLogger.assertMatchAny( + [ + { + eventName: "RemoteChannelContext:RealizeError", + fluidDataStoreId: { value: "testDataStoreId", tag: TelemetryDataTag.CodeArtifact }, + fullPackageName: { value: "pkgA/pkgB", tag: TelemetryDataTag.CodeArtifact }, + channelId: { value: channelId, tag: TelemetryDataTag.CodeArtifact }, + }, + ], + "Expected one RealizeError event with tagged data-store and channel props", + ); + }); }); diff --git a/packages/runtime/runtime-utils/src/dataStoreHelpers.ts b/packages/runtime/runtime-utils/src/dataStoreHelpers.ts index bbc8f95c7ff6..915a9d721746 100644 --- a/packages/runtime/runtime-utils/src/dataStoreHelpers.ts +++ b/packages/runtime/runtime-utils/src/dataStoreHelpers.ts @@ -155,10 +155,10 @@ export function dataStoreLoadTelemetryProps(props: { packagePath: readonly string[]; }): ITelemetryPropertiesExt { const { id, packagePath } = props; - const fullPackageName = packagePath.length > 0 ? packagePath.join("/") : undefined; + const dataStorePackagePath = packagePath.length > 0 ? packagePath.join("/") : undefined; return tagCodeArtifacts({ - fullPackageName, - fluidDataStoreId: id, + dataStorePackagePath, // aka fullPackageName, before 2.103.0 + dataStoreId: id, // aka fluidDataStoreId, before 2.103.0 }); }