diff --git a/devs.md b/devs.md index a9279f14..788d351b 100644 --- a/devs.md +++ b/devs.md @@ -277,6 +277,8 @@ The scenario uses only fixed in-memory inputs. It does not read or write the Vau - Dev mode creates `ls-debug/` folder in `.obsidian/` for debug outputs (e.g., missing translations) - This causes pretty significant performance overhead. +`ModuleLog` owns an `OwnedResource` for its `API.addLog.setHandler` registration and keeps service log input in a per-instance buffer. The host wraps the complete asynchronous `control.onUnload()` in `withOwnedResource`. On successful shutdown, the handler and its global and per-instance observers remain registered through the final database close and final unload log. If `control.onUnload()` rejects, `withOwnedResource` releases them when the operation settles. Do not release it from an `onBeforeUnload` or module `onUnload` handler; both run before the host's complete unload finishes. The import-time global `Logger` bridge and display and report histories remain shared, while service log calls stay with their owning instance. + #### Diagnostic and notice ownership - A Commonlib or service operation should normally record detailed diagnostics at `LOG_LEVEL_VERBOSE` and return a typed result which lets its caller distinguish complete, partial, and failed outcomes. Do not make callers infer an outcome by parsing log text. diff --git a/package.json b/package.json index 84e21ce5..a9efc5aa 100644 --- a/package.json +++ b/package.json @@ -100,6 +100,7 @@ "test:e2e:obsidian:customisation-sync": "tsx test/e2e-obsidian/scripts/customisation-sync.ts", "test:e2e:obsidian:customisation-catalogue-reload": "tsx test/e2e-obsidian/scripts/customisation-catalogue-reload.ts", "test:e2e:obsidian:optional-file-save-completion": "tsx test/e2e-obsidian/scripts/optional-file-save-completion.ts", + "test:e2e:obsidian:log-lifecycle": "tsx test/e2e-obsidian/scripts/log-lifecycle.ts", "test:e2e:obsidian:livesync-batch": "tsx test/e2e-obsidian/scripts/issue1207-livesync-batch.ts", "test:e2e:obsidian:received-change-readiness": "tsx test/e2e-obsidian/scripts/received-change-readiness.ts", "test:e2e:obsidian:remote-feature-change": "tsx test/e2e-obsidian/scripts/remote-feature-change.ts", diff --git a/src/common/ownedRemoteResource.ts b/src/common/ownedRemoteResource.ts index 60483414..19eaa1a3 100644 --- a/src/common/ownedRemoteResource.ts +++ b/src/common/ownedRemoteResource.ts @@ -1,3 +1,5 @@ +import { withOwnedResource, type DisposableResource } from "octagonal-wheels/resource"; + /** * Run a finite operation with a flow-owned remote resource and release it * after either success or failure. @@ -6,13 +8,9 @@ * caller's ownership boundary explicit and prevents finite flows from leaking * a provider-owned resource when their operation rejects. */ -export async function withOwnedRemoteResource }, TResult>( +export function withOwnedRemoteResource }, TResult>( resource: TResource, operation: (ownedResource: TResource) => Promise ): Promise { - try { - return await operation(resource); - } finally { - await resource.dispose(); - } + return withOwnedResource(resource, operation); } diff --git a/src/common/ownedRemoteResource.unit.spec.ts b/src/common/ownedRemoteResource.unit.spec.ts index 840acf7e..2eb042f9 100644 --- a/src/common/ownedRemoteResource.unit.spec.ts +++ b/src/common/ownedRemoteResource.unit.spec.ts @@ -26,3 +26,47 @@ describe("flow-owned remote resources", () => { expect(dispose).toHaveBeenCalledOnce(); }); }); + +describe("owned remote resource completion", () => { + it("waits for cleanup and preserves its receiver", async () => { + let finish!: () => void; + let started!: () => void; + const disposing = new Promise((resolve) => { + started = resolve; + }); + const cleanup = new Promise((resolve) => { + finish = resolve; + }); + const resource = { + dispose: vi.fn(function (this: unknown) { + expect(this).toBe(resource); + started(); + return cleanup; + }), + }; + let settled = false; + const result = withOwnedRemoteResource(resource, async () => "done"); + void result.then(() => { + settled = true; + }); + await disposing; + expect(settled).toBe(false); + finish(); + await expect(result).resolves.toBe("done"); + expect(resource.dispose).toHaveBeenCalledOnce(); + }); + + it("keeps finally precedence when both the operation and cleanup fail", async () => { + const operationError = new Error("operation"); + const disposalError = new Error("cleanup"); + const dispose = vi.fn(async () => { + throw disposalError; + }); + await expect( + withOwnedRemoteResource({ dispose }, async () => { + throw operationError; + }) + ).rejects.toBe(disposalError); + expect(dispose).toHaveBeenCalledOnce(); + }); +}); diff --git a/src/common/replicatorProviders.ts b/src/common/replicatorProviders.ts index 55fa13b0..19b13d38 100644 --- a/src/common/replicatorProviders.ts +++ b/src/common/replicatorProviders.ts @@ -73,7 +73,7 @@ async function runOneShotWithOutcome( // Manual and unattended wrappers share the provider transfer operation, but // keep interaction authority and result presentation explicit at this boundary. -const couchDBUserInitiatedOneShot: UserInitiatedOneShotRunner = async (instance, setting, request) => { +const userInitiatedOneShot: UserInitiatedOneShotRunner = async (instance, setting, request) => { return await runOneShotWithOutcome( instance, setting, @@ -81,20 +81,7 @@ const couchDBUserInitiatedOneShot: UserInitiatedOneShotRunner = async (instance, ); }; -const couchDBUnattendedOneShot: UnattendedOneShotRunner = async (instance, setting, request) => { - if (request.interaction.kind !== NO_INTERACTION.kind) return replicationBlocked("interaction-required"); - return await runOneShotWithOutcome(instance, setting, false); -}; - -const objectStorageUserInitiatedOneShot: UserInitiatedOneShotRunner = async (instance, setting, request) => { - return await runOneShotWithOutcome( - instance, - setting, - request.progressPresentation === REPLICATION_PROGRESS_PRESENTATIONS.NOTICE - ); -}; - -const objectStorageUnattendedOneShot: UnattendedOneShotRunner = async (instance, setting, request) => { +const unattendedOneShot: UnattendedOneShotRunner = async (instance, setting, request) => { if (request.interaction.kind !== NO_INTERACTION.kind) return replicationBlocked("interaction-required"); return await runOneShotWithOutcome(instance, setting, false); }; @@ -136,8 +123,8 @@ export function createCentralReplicatorProviderDefinitions( ), }, centralRemoteAdministration: COUCHDB_CENTRAL_REMOTE_ADMINISTRATION_CAPABILITY, - userInitiatedOneShot: supportedCapability(couchDBUserInitiatedOneShot), - unattendedOneShot: supportedCapability(couchDBUnattendedOneShot), + userInitiatedOneShot: supportedCapability(userInitiatedOneShot), + unattendedOneShot: supportedCapability(unattendedOneShot), continuous: supportedOpenReplicationContinuous(), stopActiveTransfer: supportedStopActiveTransfer(), }, @@ -166,8 +153,8 @@ export function createCentralReplicatorProviderDefinitions( [REMOTE_RESOURCE_KINDS.INITIAL_FETCH_FAST_FORWARD]: CAPABILITY_NOT_APPLICABLE, }, centralRemoteAdministration: OBJECT_STORAGE_CENTRAL_REMOTE_ADMINISTRATION_CAPABILITY, - userInitiatedOneShot: supportedCapability(objectStorageUserInitiatedOneShot), - unattendedOneShot: supportedCapability(objectStorageUnattendedOneShot), + userInitiatedOneShot: supportedCapability(userInitiatedOneShot), + unattendedOneShot: supportedCapability(unattendedOneShot), continuous: CAPABILITY_NOT_APPLICABLE, stopActiveTransfer: supportedStopActiveTransfer(), }, diff --git a/src/common/replicatorProviders.unit.spec.ts b/src/common/replicatorProviders.unit.spec.ts index 0354537d..8bf02b6d 100644 --- a/src/common/replicatorProviders.unit.spec.ts +++ b/src/common/replicatorProviders.unit.spec.ts @@ -209,6 +209,37 @@ describe("central Replicator provider definitions", () => { expect(openOneShotReplicationWithOutcome).toHaveBeenNthCalledWith(2, setting, true); }); + it.each([REMOTE_COUCHDB, REMOTE_MINIO] as const)( + "keeps unattended %s work quiet and rejects interaction before opening replication", + async (remoteType) => { + const definition = createCentralReplicatorProviderDefinitions({} as never).get(remoteType)!; + if (definition.unattendedOneShot.kind !== CAPABILITY_SUPPORT_KINDS.SUPPORTED) { + throw new Error("Unattended OneShot is unavailable"); + } + const setting = Object.assign(createNewVaultSettings(), { remoteType }); + const instance = { + initializeDatabaseForReplication: vi.fn(async () => true), + openReplication: vi.fn(async () => true), + terminateSync: vi.fn(), + closeReplication: vi.fn(), + openOneShotReplicationWithOutcome: vi.fn(async () => REPLICATION_COMPLETED), + }; + const blocked = await definition.unattendedOneShot.run(instance, setting, { + trigger: "resume", + interaction: USER_INITIATED_REPLICATION_AUTHORITY, + } as never); + expect(blocked).toEqual({ status: "blocked", reason: "interaction-required" }); + expect(instance.openOneShotReplicationWithOutcome).not.toHaveBeenCalled(); + await expect( + definition.unattendedOneShot.run(instance, setting, { + trigger: "resume", + interaction: NO_INTERACTION, + }) + ).resolves.toBe(REPLICATION_COMPLETED); + expect(instance.openOneShotReplicationWithOutcome).toHaveBeenCalledExactlyOnceWith(setting, false); + } + ); + it("dispatches central finite work through the declared operation rather than constructor identity", async () => { const definitions = createCentralReplicatorProviderDefinitions({} as never); const couchDB = definitions.get(REMOTE_COUCHDB)!; diff --git a/src/common/replicatorResources/shared.ts b/src/common/replicatorResources/shared.ts index a88f070a..e2b4b8a1 100644 --- a/src/common/replicatorResources/shared.ts +++ b/src/common/replicatorResources/shared.ts @@ -1,3 +1,4 @@ +import { createOwnedResource } from "octagonal-wheels/resource"; import type { RemoteDBSettings } from "@vrtmrz/livesync-commonlib/compat/common/types"; /** @@ -13,13 +14,8 @@ export interface ResourceReplicator { /** Create one idempotent asynchronous disposer for a private Replicator. */ export function createReplicatorDisposer(replicator: ResourceReplicator): () => Promise { - let disposal: Promise | undefined; - return () => { - if (disposal === undefined) { - disposal = Promise.resolve().then(() => replicator.closeReplication()); - } - return disposal; - }; + const resource = createOwnedResource(replicator, (owned) => Promise.resolve().then(() => owned.closeReplication())); + return () => Promise.resolve(resource.dispose()); } /** Fence a finite resource from later edits to its source settings object. */ diff --git a/src/common/replicatorResources/shared.unit.spec.ts b/src/common/replicatorResources/shared.unit.spec.ts new file mode 100644 index 00000000..e2705440 --- /dev/null +++ b/src/common/replicatorResources/shared.unit.spec.ts @@ -0,0 +1,42 @@ +import { describe, expect, it, vi } from "vitest"; +import { createReplicatorDisposer } from "./shared"; + +describe("Replicator disposal", () => { + it("defers closing, preserves the receiver, and retains one completion promise", async () => { + let finish!: () => void; + const closed = new Promise((resolve) => { + finish = resolve; + }); + const replicator = { + closeReplication: vi.fn(function (this: unknown) { + expect(this).toBe(replicator); + return closed; + }), + }; + const dispose = createReplicatorDisposer(replicator); + const pending = dispose(); + expect(replicator.closeReplication).not.toHaveBeenCalled(); + expect(dispose()).toBe(pending); + await Promise.resolve(); + expect(replicator.closeReplication).toHaveBeenCalledOnce(); + finish(); + await pending; + expect(dispose()).toBe(pending); + expect(replicator.closeReplication).toHaveBeenCalledOnce(); + }); + + it("retains synchronous closing failures as one rejected promise", async () => { + const error = new Error("close"); + const replicator = { + closeReplication: vi.fn(() => { + throw error; + }), + }; + const dispose = createReplicatorDisposer(replicator); + const pending = dispose(); + await expect(pending).rejects.toBe(error); + expect(dispose()).toBe(pending); + await expect(dispose()).rejects.toBe(error); + expect(replicator.closeReplication).toHaveBeenCalledOnce(); + }); +}); diff --git a/src/main.onunload.unit.spec.ts b/src/main.onunload.unit.spec.ts new file mode 100644 index 00000000..3ddb9019 --- /dev/null +++ b/src/main.onunload.unit.spec.ts @@ -0,0 +1,114 @@ +import { beforeEach, describe, expect, it, vi } from "vitest"; +import { createOwnedResource } from "octagonal-wheels/resource"; +import { LOG_LEVEL_URGENT } from "octagonal-wheels/common/logger"; +import { bindableFunction } from "@vrtmrz/livesync-commonlib/compat/services/lib/HandlerUtils"; + +const unusedStartupDependencies: readonly [string, readonly string[]][] = [ + ["@/serviceFeatures/useP2PSettingsPreparation", ["useP2PSettingsPreparation"]], + ["@vrtmrz/livesync-commonlib/compat/common/coreEnvFunctions", ["setGetLanguage"]], + ["./features/LiveSyncCommands.ts", ["LiveSyncCommands"]], + ["./features/HiddenFileSync/CmdHiddenFileSync.ts", ["HiddenFileSync"]], + ["./features/ConfigSync/CmdConfigSync.ts", ["ConfigSync"]], + ["./modules/features/ModuleLog.ts", ["ModuleLog"]], + ["./modules/essentialObsidian/ModuleObsidianEvents.ts", ["ModuleObsidianEvents"]], + ["./modules/features/ModuleObsidianSettingTab.ts", ["ModuleObsidianSettingDialogue"]], + ["./modules/features/ModuleObsidianDocumentHistory.ts", ["ModuleObsidianDocumentHistory"]], + ["./modules/features/ModuleGlobalHistory.ts", ["ModuleObsidianGlobalHistory"]], + ["./features/LocalDatabaseMainte/CmdLocalDatabaseMainte.ts", ["LocalDatabaseMaintenance"]], + ["./modules/services/ObsidianServiceHub.ts", ["ObsidianServiceHub"]], + ["@vrtmrz/livesync-commonlib/compat/serviceModules/Rebuilder", ["ServiceRebuilder"]], + ["@/serviceModules/DatabaseFileAccess.ts", ["ServiceDatabaseFileAccess"]], + ["@/serviceModules/ServiceFileAccessImpl.ts", ["ServiceFileAccessObsidian"]], + ["@vrtmrz/livesync-commonlib/compat/managers/StorageProcessingManager", ["StorageAccessManager"]], + ["./serviceModules/FileHandler.ts", ["ServiceFileHandler"]], + ["./serviceModules/FileAccessObsidian.ts", ["FileAccessObsidian"]], + ["./managers/StorageEventManagerObsidian.ts", ["StorageEventManagerObsidian"]], + ["@vrtmrz/livesync-commonlib/compat/mock_and_interop/wrapper", ["setNoticeClass"]], + ["./LiveSyncBaseCore.ts", ["LiveSyncBaseCore"]], + ["./modules/features/ModuleObsidianSettingAsMarkdown.ts", ["ModuleObsidianSettingsAsMarkdown"]], + ["./modules/features/SetupManager.ts", ["SetupManager"]], + ["./serviceFeatures/onLayoutReady/enablei18n.ts", ["enableI18nFeature"]], + ["@vrtmrz/livesync-commonlib/compat/serviceFeatures/offlineScanner", ["useOfflineScanner"]], + ["@vrtmrz/livesync-commonlib/compat/serviceFeatures/remoteConfig", ["useRemoteConfiguration"]], + ["@vrtmrz/livesync-commonlib/compat/serviceFeatures/checkRemoteSize", ["useCheckRemoteSize"]], + ["./serviceFeatures/redFlag.ts", ["useRedFlagFeatures"]], + ["./serviceFeatures/setupObsidian/setupProtocol.ts", ["useSetupProtocolFeature"]], + ["@/serviceFeatures/setupObsidian/qrCode", ["useSetupQRCodeFeature"]], + ["@/serviceFeatures/setupObsidian/setupUri", ["useSetupURIFeature"]], + [ + "./serviceFeatures/setupObsidian/setupManagerHandlers.ts", + ["showOnboardingInvitation", "useSetupManagerHandlersFeature"], + ], + ["@vrtmrz/livesync-commonlib/p2p", ["useP2PReplicatorCommands", "useP2PReplicatorFeature"]], + ["./serviceFeatures/useP2PReplicatorUI.ts", ["useP2PReplicatorUI"]], + ["./serviceFeatures/useReviewHarness.ts", ["useReviewHarness"]], + ["./features/P2PSync/P2PReplicator/P2PReplicationUI.ts", ["createOpenReplicationUI", "createOpenRebuildUI"]], + ["./serviceFeatures/compatibilityReview.ts", ["useCompatibilityReview"]], + ["./serviceFeatures/compatibilityReviewObsidian.ts", ["createObsidianCompatibilityReviewUi"]], + ["./serviceModules/FileReflectionProvenance.ts", ["createFileReflectionProvenance"]], + ["./serviceFeatures/interactiveConflictResolution", ["useInteractiveConflictResolutionFeature"]], + ["./modules/features/InteractiveConflictResolving/ConflictResolveModal.ts", ["ConflictResolveModal"]], + ["./serviceFeatures/obsidianReplicationRibbon.ts", ["useObsidianReplicationRibbonFeature"]], + ["./serviceFeatures/startupLifecycle", ["useStartupLifecycleFeature"]], + ["./serviceFeatures/useJoinedDevices", ["useJoinedDevicesFeature"]], + ["./serviceFeatures/useDatabaseDiagnostics", ["useDatabaseDiagnosticsFeature"]], +]; + +beforeEach(() => { + vi.resetModules(); + vi.doMock("./deps", () => ({ Plugin: class {}, Notice: class {}, getLanguage: () => "en" })); + for (const [specifier, names] of unusedStartupDependencies) { + vi.doMock(specifier, () => Object.fromEntries(names.map((name) => [name, vi.fn()]))); + } +}); + +describe("Obsidian plug-in unload logging", () => { + it.each(["complete", "fail"] as const)( + "retains its log connection through shutdown and retires it afterwards: %s", + async (outcome) => { + const { default: LiveSyncPlugin } = await import("./main.ts"); + const events: string[] = []; + const sink = vi.fn((message: unknown) => events.push(String(message))); + const addLog = bindableFunction<(message: unknown, level?: number, key?: string) => void>("unload log"); + const unregister = addLog.setHandler(sink); + const dispose = vi.fn(() => { + unregister(); + events.push("disposed"); + }); + const logResource = createOwnedResource(sink, dispose); + let finish!: () => void; + let fail!: (reason: Error) => void; + const shutdown = new Promise((resolve, reject) => { + finish = resolve; + fail = reject; + }); + const onUnload = vi.fn(() => shutdown); + const core = { + getModule: vi.fn(() => ({ logResource })), + services: { API: { addLog }, control: { onUnload } }, + }; + + expect(LiveSyncPlugin.prototype.onunload.call({ core } as never)).toBeUndefined(); + expect(onUnload).toHaveBeenCalledTimes(1); + expect(dispose).not.toHaveBeenCalled(); + addLog("during shutdown"); + + const failure = new Error("database close failed"); + if (outcome === "fail") { + fail(failure); + } else { + finish(); + } + await vi.waitFor(() => expect(dispose).toHaveBeenCalledTimes(1)); + + if (outcome === "fail") { + const message = "Failed to unload Self-hosted LiveSync: " + String(failure); + expect(sink).toHaveBeenCalledWith(message, LOG_LEVEL_URGENT, "shutdown"); + expect(events).toEqual(["during shutdown", message, "disposed"]); + } else { + expect(events).toEqual(["during shutdown", "disposed"]); + } + expect(() => addLog("after shutdown")).toThrow("not assigned"); + } + ); +}); diff --git a/src/main.ts b/src/main.ts index d4e7d346..51aba0d1 100644 --- a/src/main.ts +++ b/src/main.ts @@ -9,6 +9,7 @@ import { ConfigSync } from "./features/ConfigSync/CmdConfigSync.ts"; // import { ModuleDev } from "./modules/extras/ModuleDev.ts"; import { ModuleLog } from "./modules/features/ModuleLog.ts"; +import { withOwnedResource } from "octagonal-wheels/resource"; import { ModuleObsidianEvents } from "./modules/essentialObsidian/ModuleObsidianEvents.ts"; import { ModuleObsidianSettingDialogue } from "./modules/features/ModuleObsidianSettingTab.ts"; import { ModuleObsidianDocumentHistory } from "./modules/features/ModuleObsidianDocumentHistory.ts"; @@ -234,12 +235,14 @@ export default class ObsidianLiveSyncPlugin extends Plugin { void this._startUp(); } override onunload(): void { - void this.core.services.control.onUnload().catch((error) => { - this.core.services.API.addLog( - "Failed to unload Self-hosted LiveSync: " + String(error), - LOG_LEVEL_URGENT, - "shutdown" - ); - }); + void withOwnedResource(this.core.getModule(ModuleLog).logResource, () => + this.core.services.control.onUnload().catch((error) => { + this.core.services.API.addLog( + "Failed to unload Self-hosted LiveSync: " + String(error), + LOG_LEVEL_URGENT, + "shutdown" + ); + }) + ); } } diff --git a/src/modules/features/ModuleLog.ts b/src/modules/features/ModuleLog.ts index 0755506b..58f77daf 100644 --- a/src/modules/features/ModuleLog.ts +++ b/src/modules/features/ModuleLog.ts @@ -1,4 +1,10 @@ -import { computed, reactive, reactiveSource, type ReactiveValue } from "octagonal-wheels/dataobject/reactive"; +import { + computed, + reactive, + reactiveSource, + type ReactiveSource, + type ReactiveValue, +} from "octagonal-wheels/dataobject/reactive"; import { LOG_LEVEL_DEBUG, LOG_LEVEL_INFO, @@ -7,6 +13,7 @@ import { type LOG_LEVEL, } from "@vrtmrz/livesync-commonlib/compat/common/types"; import { scheduleTask } from "octagonal-wheels/concurrency/task"; +import { createOwnedResource, type OwnedResource } from "octagonal-wheels/resource"; import { fireAndForget, isDirty, throttle } from "@vrtmrz/livesync-commonlib/compat/common/utils"; import { chunkFetchCounts, @@ -46,7 +53,11 @@ import { isValidFilenameInDarwin, isValidFilenameInWidows, } from "@vrtmrz/livesync-commonlib/compat/string_and_binary/path"; -import { MARK_LOG_NETWORK_ERROR, MARK_LOG_SEPARATOR } from "@vrtmrz/livesync-commonlib/compat/services/lib/logUtils"; +import { + MARK_LOG_NETWORK_ERROR, + MARK_LOG_SEPARATOR, + type LogFunction, +} from "@vrtmrz/livesync-commonlib/compat/services/lib/logUtils"; import { NetworkWarningStyles } from "@vrtmrz/livesync-commonlib/compat/common/models/setting.const"; import { compatGlobal } from "@vrtmrz/livesync-commonlib/compat/common/coreEnvFunctions"; import { generateReport } from "@/common/reportTool.ts"; @@ -57,20 +68,22 @@ import { // This module cannot be a core module because it depends on the Obsidian UI. -// DI the log again. -const recentLogEntries = reactiveSource([]); -const globalLogFunction = (message: unknown, level?: number, key?: string) => { - const messageX = - message instanceof Error - ? new LiveSyncError("[Error Logged]: " + message.message, { cause: message }) - : typeof message === "string" - ? message - : JSON.stringify(message); - const entry = { message: messageX, level, key } as LogEntry; - recentLogEntries.value = [...recentLogEntries.value, entry]; -}; +function createBufferedLog(entries: ReactiveSource) { + return (message: unknown, level?: number, key?: string) => { + const messageX = + message instanceof Error + ? new LiveSyncError("[Error Logged]: " + message.message, { cause: message }) + : typeof message === "string" + ? message + : JSON.stringify(message); + const entry = { message: messageX, level, key } as LogEntry; + entries.value = [...entries.value, entry]; + }; +} -setGlobalLogFunction(globalLogFunction); +// Legacy Logger calls use this shared buffer; service logs use their owner's buffer. +const recentGlobalLogEntries = reactiveSource([]); +setGlobalLogFunction(createBufferedLog(recentGlobalLogEntries)); // Keep the recent logs in memory for display, but also keep a longer history in logForDump for when the user wants to see more logs. // logForDump is not reactive and is only used for dumping logs when requested, while recentLogs is reactive and is used for displaying logs in the UI. const logForDump = [] as string[]; @@ -113,6 +126,16 @@ function redactLog(log: string) { const showDebugLog = false; export const MARK_DONE = "\u{2009}\u{2009}"; export class ModuleLog extends AbstractObsidianModule { + /** The host releases this connection after the complete asynchronous unload. */ + logResource!: OwnedResource; + private readonly recentLogEntries = reactiveSource([]); + private readonly displayLogEntries = () => { + if (this.recentLogEntries.value.length === 0) return; + const entries = [...this.recentLogEntries.value]; + this.recentLogEntries.value = []; + entries.forEach((entry) => this.__addLog(entry.message, entry.level, entry.key)); + }; + statusBar?: HTMLElement; statusDiv?: HTMLElement; @@ -460,12 +483,7 @@ ${stringifyYaml(info)} return Promise.resolve(true); } private _everyOnloadAfterLoadSettings(): Promise { - recentLogEntries.onChanged((entries) => { - if (entries.value.length === 0) return; - const newEntries = [...entries.value]; - recentLogEntries.value = []; - newEntries.forEach((e) => this.__addLog(e.message, e.level, e.key)); - }); + this.recentLogEntries.onChanged(this.displayLogEntries); eventHub.onEvent(EVENT_FILE_RENAMED, (data) => { void this.setFileStatus(); }); @@ -597,7 +615,22 @@ ${stringifyYaml(info)} } } override onBindFunction(core: LiveSyncCore, services: typeof core.services): void { - services.API.addLog.setHandler(globalLogFunction); + const log = createBufferedLog(this.recentLogEntries); + const unregisterLog = services.API.addLog.setHandler(log); + const collectGlobalLogs = () => { + const entries = recentGlobalLogEntries.value; + if (entries.length === 0) return; + recentGlobalLogEntries.value = []; + this.recentLogEntries.value = [...this.recentLogEntries.value, ...entries]; + }; + this.logResource = createOwnedResource(log, () => { + unregisterLog(); + recentGlobalLogEntries.offChanged(collectGlobalLogs); + this.recentLogEntries.offChanged(this.displayLogEntries); + this.recentLogEntries.value = []; + }); + recentGlobalLogEntries.onChanged(collectGlobalLogs); + collectGlobalLogs(); services.appLifecycle.onInitialise.addHandler(this._everyOnloadStart.bind(this)); services.appLifecycle.onSettingLoaded.addHandler(this._everyOnloadAfterLoadSettings.bind(this)); services.appLifecycle.onLoaded.addHandler(this._everyOnload.bind(this)); diff --git a/src/modules/features/ModuleLog.unit.spec.ts b/src/modules/features/ModuleLog.unit.spec.ts new file mode 100644 index 00000000..28f48231 --- /dev/null +++ b/src/modules/features/ModuleLog.unit.spec.ts @@ -0,0 +1,228 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +vi.mock("@/deps.ts", () => ({ + addIcon: vi.fn(), + debounce: (callback: () => void) => callback, + normalizePath: (path: string) => path, + Notice: class {}, + stringifyYaml: vi.fn(), +})); +vi.mock("./Log/LogPaneView.ts", () => ({ LogPaneView: class {}, VIEW_TYPE_LOG: "log" })); +vi.mock("@/common/reportTool.ts", () => ({ generateReport: vi.fn() })); +vi.mock("@/common/utils.ts", () => ({ isValidPath: () => true })); +vi.mock("@/common/translation", () => ({ $msg: (key: string) => key })); +vi.mock("@/common/events.ts", () => ({ + EVENT_FILE_RENAMED: "renamed", + EVENT_LAYOUT_READY: "ready", + EVENT_LEAF_ACTIVE_CHANGED: "active", + EVENT_ON_UNRESOLVED_ERROR: "error", + eventHub: { onEvent: vi.fn() }, +})); +vi.mock("@vrtmrz/livesync-commonlib/compat/replication/trystero/P2PLogCollector", () => ({ + P2PLogCollector: class {}, +})); + +async function createHarness() { + const { ModuleLog } = await import("./ModuleLog.ts"); + const { bindableFunction, allFunction } = + await import("@vrtmrz/livesync-commonlib/compat/services/lib/HandlerUtils"); + const services = { + API: { + addLog: bindableFunction<(message: unknown, level?: number, key?: string) => void>("log"), + addCommand: vi.fn(), + registerWindow: vi.fn(), + addRibbonIcon: vi.fn(), + registerProtocolHandler: vi.fn(), + }, + context: { events: {}, notices: { hide: vi.fn() } }, + appLifecycle: { + onInitialise: allFunction<() => Promise>(), + onSettingLoaded: allFunction<() => Promise>(), + onLoaded: allFunction<() => Promise>(), + onBeforeUnload: allFunction<() => Promise>(), + }, + }; + const core = { services, settings: {} }; + const module = new ModuleLog({ app: {} } as never, core as never); + const sink = vi.spyOn(module, "__addLog").mockImplementation(() => undefined); + vi.spyOn(module, "observeForLogs").mockImplementation(() => undefined); + vi.spyOn(module, "adjustStatusDivPosition").mockImplementation(() => undefined); + module.onBindFunction(core as never, services as never); + const { Logger } = await import("octagonal-wheels/common/logger"); + return { module, services, sink, Logger }; +} + +describe("ModuleLog service connection", () => { + beforeEach(() => { + vi.resetModules(); + vi.stubGlobal("document", { querySelectorAll: () => [] }); + }); + afterEach(() => { + vi.unstubAllGlobals(); + }); + + it("buffers startup logs and preserves global and service call order", async () => { + const { services, sink, Logger } = await createHarness(); + Logger("before-global"); + services.API.addLog("before-service", 32, "startup"); + Logger("between-global"); + expect(sink).not.toHaveBeenCalled(); + await services.appLifecycle.onSettingLoaded(); + const messages = sink.mock.calls.map(([message]) => message); + expect(messages.filter((message) => typeof message === "string" && /^(before|between)-/.test(message))).toEqual( + ["before-global", "before-service", "between-global"] + ); + expect(sink).toHaveBeenCalledWith("before-service", 32, "startup"); + }); + + it("delivers service logs only to their own module", async () => { + const first = await createHarness(); + const second = await createHarness(); + await first.services.appLifecycle.onSettingLoaded(); + await second.services.appLifecycle.onSettingLoaded(); + first.sink.mockClear(); + second.sink.mockClear(); + + first.services.API.addLog("first", 32, "first-key"); + second.services.API.addLog("second", 64, "second-key"); + expect(first.sink.mock.calls).toEqual([["first", 32, "first-key"]]); + expect(second.sink.mock.calls).toEqual([["second", 64, "second-key"]]); + }); + + it("preserves message conversion, levels, keys, and error causes", async () => { + const { services, sink } = await createHarness(); + await services.appLifecycle.onSettingLoaded(); + sink.mockClear(); + const error = new Error("failed"); + services.API.addLog(error, 128, "failure"); + services.API.addLog({ result: "value" }, 32, "object"); + services.API.addLog("plain"); + const converted = sink.mock.calls[0][0] as Error & { cause: unknown }; + expect(converted.message).toBe("[Error Logged]: failed"); + expect(converted.cause).toBe(error); + expect(sink.mock.calls[0].slice(1)).toEqual([128, "failure"]); + expect(sink.mock.calls.slice(1)).toEqual([ + ['{"result":"value"}', 32, "object"], + ["plain", undefined, undefined], + ]); + }); + + it("detaches both service registration and legacy subscription on disposal", async () => { + const first = await createHarness(); + const second = await createHarness(); + await first.services.appLifecycle.onSettingLoaded(); + await second.services.appLifecycle.onSettingLoaded(); + first.sink.mockClear(); + second.sink.mockClear(); + + await first.module.logResource.dispose(); + await first.module.logResource.dispose(); + expect(() => first.services.API.addLog("retired")).toThrow("not assigned"); + second.services.API.addLog("active", 32, "service"); + first.Logger("legacy-after-retirement", 32, "legacy"); + expect(first.sink).not.toHaveBeenCalled(); + expect(second.sink.mock.calls).toEqual([ + ["active", 32, "service"], + ["legacy-after-retirement", 32, "legacy"], + ]); + await second.module.logResource.dispose(); + }); + + it("leaves a replacement service handler registered when the old owner is disposed", async () => { + const { services, module, sink, Logger } = await createHarness(); + await services.appLifecycle.onSettingLoaded(); + const replacement = vi.fn(); + services.API.addLog.setHandler(replacement, true); + sink.mockClear(); + + await module.logResource.dispose(); + await module.logResource.dispose(); + services.API.addLog("replacement", 32, "key"); + Logger("detached-legacy"); + expect(replacement).toHaveBeenCalledExactlyOnceWith("replacement", 32, "key"); + expect(sink).not.toHaveBeenCalled(); + }); + + it("releases a connection which never reached the settings-loaded phase", async () => { + const { services, module, sink, Logger } = await createHarness(); + services.API.addLog("pending"); + await module.logResource.dispose(); + Logger("after-disposal"); + expect(sink).not.toHaveBeenCalled(); + expect(() => services.API.addLog("retired")).toThrow("not assigned"); + + const replacement = await createHarness(); + await replacement.services.appLifecycle.onSettingLoaded(); + const messages = replacement.sink.mock.calls.map(([message]) => message); + expect(messages).toContain("after-disposal"); + expect(messages).not.toContain("pending"); + await replacement.module.logResource.dispose(); + }); + + it.each(["complete", "fail"] as const)( + "keeps logging through asynchronous database shutdown and releases after it: %s", + async (outcome) => { + const { services, module, sink, Logger } = await createHarness(); + await services.appLifecycle.onSettingLoaded(); + sink.mockClear(); + const { ControlService } = await import("@vrtmrz/livesync-commonlib/compat/services/base/ControlService"); + const { ServiceContext } = await import("@vrtmrz/livesync-commonlib/context"); + const { withOwnedResource } = await import("octagonal-wheels/resource"); + let finish!: () => void; + let fail!: (reason: Error) => void; + let started!: () => void; + const closing = new Promise((resolve) => { + started = resolve; + }); + const closed = new Promise((resolve, reject) => { + finish = resolve; + fail = reject; + }); + const control = new ControlService(new ServiceContext({ translate: (key) => key }), { + appLifecycleService: { + ...services.appLifecycle, + onAppUnload: vi.fn(async () => []), + onUnload: vi.fn(async () => { + services.API.addLog("lifecycle-unload"); + return true; + }), + }, + APIService: services.API, + databaseService: { + localDatabaseDirect: { + onunload: vi.fn(() => services.API.addLog("database-unload")), + close: vi.fn(() => { + started(); + return closed; + }), + }, + }, + } as never); + + const unloading = withOwnedResource(module.logResource, () => control.onUnload()); + await closing; + services.API.addLog("during-close"); + expect(sink.mock.calls.map(([message]) => message)).toEqual([ + "lifecycle-unload", + "database-unload", + "during-close", + ]); + if (outcome === "fail") { + const failure = new Error("database close failed"); + const rejected = expect(unloading).rejects.toBe(failure); + fail(failure); + await rejected; + } else { + finish(); + await unloading; + expect(sink.mock.calls[sink.mock.calls.length - 1][0]).toContain( + "moduleLiveSyncMain.logUnloadingPlugin" + ); + } + expect(() => services.API.addLog("retired")).toThrow("not assigned"); + sink.mockClear(); + Logger("after-unload"); + expect(sink).not.toHaveBeenCalled(); + } + ); +}); diff --git a/src/serviceFeatures/useJoinedDevices.ts b/src/serviceFeatures/useJoinedDevices.ts index 53b7dbc9..6baa9529 100644 --- a/src/serviceFeatures/useJoinedDevices.ts +++ b/src/serviceFeatures/useJoinedDevices.ts @@ -9,6 +9,7 @@ import { import { REMOTE_RESOURCE_KINDS, type JoinedDevicesSnapshot } from "@vrtmrz/livesync-commonlib/replication"; import type { ObsidianNoticeGroups } from "@/modules/services/ObsidianNoticeGroups"; import JoinedDevicesDialog from "@/modules/services/LiveSyncUI/dialogues/JoinedDevicesDialog.svelte"; +import { withOwnedRemoteResource } from "@/common/ownedRemoteResource"; import { getCouchDBReplicatorConfigurationIdentity, getObjectStorageReplicatorConfigurationIdentity, @@ -119,9 +120,9 @@ export function useJoinedDevicesFeature(host: JoinedDevicesHost, notices: Obsidi settings ); if (!resource) throw new Error("Joined devices are unavailable"); - try { + return withOwnedRemoteResource(resource, async (ownedResource) => { assertCurrent(); - const snapshot = await resource.read(); + const snapshot = await ownedResource.read(); assertCurrent(); notify(snapshot, id, identity!); return joinedDevicesView(snapshot, { @@ -130,9 +131,7 @@ export function useJoinedDevicesFeature(host: JoinedDevicesHost, notices: Obsidi pluginVersion: services.API.getPluginVersion(), appVersion: services.API.getAppVersion(), }); - } finally { - await resource.dispose(); - } + }); }, forget: async (id) => { if (id === (await ownId())) throw new Error("This device cannot be forgotten"); @@ -141,14 +140,12 @@ export function useJoinedDevicesFeature(host: JoinedDevicesHost, notices: Obsidi settings ); if (!resource) throw new Error("Joined devices are unavailable"); - try { + return withOwnedRemoteResource(resource, async (ownedResource) => { assertCurrent(); - const result = await resource.forget(id); + const result = await ownedResource.forget(id); assertCurrent(); return result; - } finally { - await resource.dispose(); - } + }); }, cancel: () => controller.abort(), }; diff --git a/src/serviceFeatures/useJoinedDevices.unit.spec.ts b/src/serviceFeatures/useJoinedDevices.unit.spec.ts index 188afe5a..0c5670c2 100644 --- a/src/serviceFeatures/useJoinedDevices.unit.spec.ts +++ b/src/serviceFeatures/useJoinedDevices.unit.spec.ts @@ -110,6 +110,67 @@ describe("joined devices service feature", () => { expect(await pending).toEqual({ status: "handled", value: "closed" }); await expect(options.refresh()).rejects.toThrow(); }); + it("propagates a failed refresh after releasing its resource", async () => { + const data = fixture(); + const failure = new Error("joined devices read failed"); + data.read.mockRejectedValueOnce(failure); + const { options, pending } = await open(data); + + await expect(options.refresh()).rejects.toBe(failure); + expect(data.dispose).toHaveBeenCalledOnce(); + data.close(); + await pending; + }); + it.each(["refresh", "forget"] as const)( + "waits for resource disposal after %s", + async (operationName) => { + const data = fixture(); + let finishDisposal!: () => void; + data.dispose.mockImplementationOnce( + () => + new Promise((resolve) => { + finishDisposal = resolve; + }) + ); + const { options, pending } = await open(data); + const operation = operationName === "refresh" ? options.refresh() : options.forget("other"); + let settled = false; + void operation.then( + () => { + settled = true; + }, + () => { + settled = true; + } + ); + + await vi.waitFor(() => expect(data.dispose).toHaveBeenCalledOnce()); + expect(settled).toBe(false); + finishDisposal(); + await expect(operation).resolves.toBeDefined(); + expect(settled).toBe(true); + data.close(); + await pending; + } + ); + it.each(["refresh", "forget"] as const)( + "uses disposal failure precedence when %s also fails", + async (operationName) => { + const data = fixture(); + const operationFailure = new Error("joined devices operation failed"); + const disposalFailure = new Error("joined devices disposal failed"); + if (operationName === "refresh") data.read.mockRejectedValueOnce(operationFailure); + else data.forget.mockRejectedValueOnce(operationFailure); + data.dispose.mockRejectedValueOnce(disposalFailure); + const { options, pending } = await open(data); + const operation = operationName === "refresh" ? options.refresh() : options.forget("other"); + + await expect(operation).rejects.toBe(disposalFailure); + expect(data.dispose).toHaveBeenCalledOnce(); + data.close(); + await pending; + } + ); it("prevents self removal and fences an old dialogue after a remote switch", async () => { const data = fixture(); const { options, pending } = await open(data); diff --git a/test/e2e-obsidian/scripts/log-lifecycle.ts b/test/e2e-obsidian/scripts/log-lifecycle.ts new file mode 100644 index 00000000..a126da2d --- /dev/null +++ b/test/e2e-obsidian/scripts/log-lifecycle.ts @@ -0,0 +1,373 @@ +import { createHash, randomUUID } from "node:crypto"; +import { readFile, writeFile } from "node:fs/promises"; +import { join } from "node:path"; +import { LOG_LEVEL_URGENT } from "octagonal-wheels/common/logger"; +import { evalObsidianJson } from "../runner/cli.ts"; +import { requireObsidianBinary, requireObsidianCli } from "../runner/environment.ts"; +import { + createE2eCouchDbPluginData, + createE2eObsidianDeviceLocalState, + waitForLiveSyncCoreReady, +} from "../runner/liveSyncWorkflow.ts"; +import { startObsidianLiveSyncSession, type ObsidianLiveSyncSession } from "../runner/session.ts"; +import { createTemporaryVault, type TemporaryVault } from "../runner/vault.ts"; + +process.env.E2E_OBSIDIAN_CLI_TIMEOUT_MS ??= "60000"; + +type FixtureLog = { + message: string; + level?: number; + key?: string; +}; + +type ShutdownObservation = { + closeCalls: number; + disposeCalls: number; + disposeCompleted: boolean; + fixtureLogs: FixtureLog[]; + events: string[]; +}; + +async function evaluate(cliBinary: string, session: ObsidianLiveSyncSession, body: string): Promise { + return await evalObsidianJson( + cliBinary, + `(async()=>{ + const require=(condition,message)=>{if(!condition)throw new Error(message);}; + const waitFor=async(predicate,message)=>{ + const until=Date.now()+15000; + while(!predicate()) { + if(Date.now()>until)throw new Error(message); + await new Promise(resolve=>setTimeout(resolve,20)); + } + }; + ${body} + })()`, + session.cliEnv + ); +} + +function createPluginData(dbName: string): Record { + return createE2eCouchDbPluginData( + { uri: "http://127.0.0.1:1", username: "unused", password: "unused", dbName }, + { + syncInternalFiles: true, + usePluginSync: true, + usePluginSyncV2: true, + deviceAndVaultName: "log-lifecycle-device", + autoSweepPlugins: false, + autoSweepPluginsPeriodic: false, + syncInternalFilesInterval: 0, + liveSync: false, + periodicReplication: false, + syncOnStart: false, + syncOnSave: false, + syncOnFileOpen: false, + syncOnEditorSave: false, + syncAfterMerge: false, + showVerboseLog: true, + } + ); +} + +async function startSession( + binary: string, + cliBinary: string, + vault: TemporaryVault +): Promise { + const session = await startObsidianLiveSyncSession({ + binary, + cliBinary, + vault, + pluginData: createPluginData(`log-lifecycle-${vault.name}`), + localStorageEntries: createE2eObsidianDeviceLocalState(vault.name), + lifecycle: { + beforeLaunch: async () => { + const registryPath = join(vault.userDataPath, "obsidian.json"); + const registry = JSON.parse(await readFile(registryPath, "utf8")); + registry.updateDisabled = true; + await writeFile(registryPath, JSON.stringify(registry)); + }, + }, + }); + return session; +} + +function createShutdownScript(options: { + duringMarker: string; + failureMarker: string; + reloadMarker: string; + injectFailure: boolean; + urgentLevel: number; +}): string { + const fixtures = JSON.stringify(options); + return ` + const fixtures=${fixtures}; + const plugin=app.plugins.plugins["obsidian-livesync"]; + const core=plugin?.core; + require(core,"The LiveSync plug-in did not expose its core"); + const module=core.modules.find(candidate=>candidate.constructor.name==="ModuleLog"); + require(module,"The loaded core did not contain ModuleLog"); + const api=core.services.API; + const database=core.services.database.localDatabaseDirect; + require(database,"The loaded core did not expose its local database"); + + let releaseCloseGate; + const closeGate=new Promise(resolve=>{releaseCloseGate=resolve;}); + const state={ + core, + api, + module, + fixtureLogs:[], + events:[], + closeStarted:false, + closeCalls:0, + disposeCalls:0, + disposeCompleted:false, + closeGateReleased:false, + disableError:"", + }; + app.__livesyncLogLifecycleState=state; + + const originalAddLog=module.__addLog; + module.__addLog=function(message,level,key) { + if(typeof message==="string" && [ + fixtures.duringMarker, + fixtures.failureMarker, + fixtures.reloadMarker + ].some(marker=>marker && message.includes(marker))) { + state.fixtureLogs.push({message,level,key}); + const marker=[fixtures.duringMarker,fixtures.failureMarker,fixtures.reloadMarker] + .find(candidate=>candidate && message.includes(candidate)); + state.events.push("log:"+marker); + } + return originalAddLog.apply(this,arguments); + }; + + const resource=module.logResource; + const originalDispose=resource.dispose; + resource.dispose=async function() { + state.disposeCalls++; + state.events.push("dispose-start"); + try { + return await originalDispose.apply(this,arguments); + } finally { + state.disposeCompleted=true; + state.events.push("dispose-complete"); + } + }; + + const originalClose=database.close; + database.close=async function() { + state.closeCalls++; + if(state.closeCalls===1) { + state.closeStarted=true; + state.events.push("close-start"); + await closeGate; + } + const result=await originalClose.apply(this,arguments); + if(state.closeCalls===1) { + state.events.push("close-finished"); + if(fixtures.injectFailure) { + state.events.push("close-failure-injected"); + throw new Error(fixtures.failureMarker); + } + } + return result; + }; + + state.restore=()=>{ + module.__addLog=originalAddLog; + resource.dispose=originalDispose; + database.close=originalClose; + }; + + const run=async()=>{ + state.disablePromise=app.plugins.disablePlugin("obsidian-livesync"); + state.disablePromise.catch(error=>{state.disableError=String(error);}); + await waitFor(()=>state.closeStarted,"The real local database close did not start"); + require(state.disposeCalls===0 && !state.disposeCompleted, + "The log resource was released before database shutdown completed"); + api.addLog(fixtures.duringMarker,undefined,"e2e-log-lifecycle-during-close"); + await waitFor( + ()=>state.fixtureLogs.some(entry=>entry.message.includes(fixtures.duringMarker)), + "ModuleLog did not receive the during-close log" + ); + require(state.disposeCalls===0,"The log resource was released while database close was gated"); + releaseCloseGate(); + state.closeGateReleased=true; + await waitFor(()=>state.disposeCompleted,"The log resource was not released after database close"); + + require(state.closeCalls===1,"The local database close was not observed exactly once"); + require(state.disposeCalls===1,"The log resource was not disposed exactly once"); + require(state.events.indexOf("close-finished")>=0 && + state.events.indexOf("close-finished")entry.message.includes(fixtures.failureMarker)) + : undefined; + if(fixtures.injectFailure) { + require(failedLog,"The injected post-close failure was not logged"); + require(failedLog.key==="shutdown","The shutdown failure log used the wrong key"); + require(failedLog.level===fixtures.urgentLevel,"The shutdown failure log was not urgent"); + require( + state.events.indexOf("close-finished")state.disposeCompleted,"Cleanup timed out waiting for log resource disposal"); + } catch {} + } + } + `; +} + +async function runCase(options: { + binary: string; + cliBinary: string; + caseName: string; + injectFailure: boolean; +}): Promise> { + const vault = await createTemporaryVault(`obsidian-log-lifecycle-${options.caseName}-`); + let session: ObsidianLiveSyncSession | undefined; + const markers = { + duringMarker: `log-lifecycle-${options.caseName}-during-${randomUUID()}`, + failureMarker: options.injectFailure + ? `log-lifecycle-${options.caseName}-injected-close-failure-${randomUUID()}` + : "", + reloadMarker: options.injectFailure ? "" : `log-lifecycle-${options.caseName}-reload-${randomUUID()}`, + injectFailure: options.injectFailure, + urgentLevel: LOG_LEVEL_URGENT, + }; + + try { + session = await startSession(options.binary, options.cliBinary, vault); + await waitForLiveSyncCoreReady(options.cliBinary, session.cliEnv); + const shutdown = await evaluate(options.cliBinary, session, createShutdownScript(markers)); + if (options.injectFailure) { + return { caseName: options.caseName, shutdown }; + } + + await evaluate( + options.cliBinary, + session, + `await app.plugins.enablePlugin("obsidian-livesync"); return JSON.stringify({enabled:true});` + ); + await waitForLiveSyncCoreReady(options.cliBinary, session.cliEnv); + const reload = await evaluate>( + options.cliBinary, + session, + ` + const state=app.__livesyncLogLifecycleState; + require(state,"The old core observation was not retained across plug-in reload"); + const plugin=app.plugins.plugins["obsidian-livesync"]; + const core=plugin?.core; + require(core && core!==state.core,"Enabling the plug-in did not create a new core"); + const module=core.modules.find(candidate=>candidate.constructor.name==="ModuleLog"); + require(module,"The reloaded core did not contain ModuleLog"); + const originalAddLog=module.__addLog; + const observed=[]; + module.__addLog=function(message,level,key) { + if(typeof message==="string" && message.includes(${JSON.stringify(markers.reloadMarker)})) { + observed.push({message,level,key}); + } + return originalAddLog.apply(this,arguments); + }; + try { + core.services.API.addLog(${JSON.stringify(markers.reloadMarker)},undefined,"e2e-log-lifecycle-reload"); + await waitFor(()=>observed.length>0,"The reloaded ModuleLog did not receive its API log"); + require(observed.length===1,"The reloaded ModuleLog received the fixture log more than once"); + require( + !state.fixtureLogs.some(entry=>entry.message.includes(${JSON.stringify(markers.reloadMarker)})), + "The old ModuleLog observer received the reloaded core's fixture log" + ); + let oldHandlerDetached=false; + try { + state.api.addLog("e2e-log-lifecycle-reloaded-old-api"); + } catch(error) { + oldHandlerDetached=String(error).includes("not assigned"); + } + require(oldHandlerDetached,"The old API log handler was reassigned after reload"); + return JSON.stringify({ + coreChanged:core!==state.core, + observedByNewModule:observed.length, + observedByOldModule:state.fixtureLogs.filter( + entry=>entry.message.includes(${JSON.stringify(markers.reloadMarker)}) + ).length + }); + } finally { + module.__addLog=originalAddLog; + state.restore(); + delete app.__livesyncLogLifecycleState; + } + ` + ); + return { caseName: options.caseName, shutdown, reload }; + } finally { + if (session) { + try { + await evaluate( + options.cliBinary, + session, + ` + const state=app.__livesyncLogLifecycleState; + state?.restore?.(); + delete app.__livesyncLogLifecycleState; + return JSON.stringify({cleaned:true}); + ` + ); + } catch {} + try { + await session.app.stop(); + } finally { + await vault.dispose(); + } + } else { + await vault.dispose(); + } + } +} + +async function main(): Promise { + const binary = requireObsidianBinary(); + const cliBinary = requireObsidianCli(); + const bundleHash = createHash("sha256") + .update(new Uint8Array(await readFile("main.js"))) + .digest("hex"); + + const observations = [ + await runCase({ binary, cliBinary, caseName: "normal", injectFailure: false }), + await runCase({ binary, cliBinary, caseName: "controlled-failure", injectFailure: true }), + ]; + console.log(JSON.stringify({ ok: true, bundleHash, observations }, null, 2)); +} + +await main(); diff --git a/test/e2e-obsidian/scripts/run-focused.ts b/test/e2e-obsidian/scripts/run-focused.ts index ffb805ed..adbfcf03 100644 --- a/test/e2e-obsidian/scripts/run-focused.ts +++ b/test/e2e-obsidian/scripts/run-focused.ts @@ -49,6 +49,7 @@ const focusedScenarios = new Set([ "customisation-sync", "customisation-catalogue-reload", "optional-file-save-completion", + "log-lifecycle", "livesync-batch", "received-change-readiness", "internal-metadata-doctor", diff --git a/updates.md b/updates.md index f5551d3b..c217ef94 100644 --- a/updates.md +++ b/updates.md @@ -12,6 +12,11 @@ Earlier releases remain available in the 1.0 release history, the 1.0 preview hi ## Unreleased +### Diagnostics + +- Service log calls stay with the plug-in instance that registered them. Its log connection is released after the full shutdown, so stale instances cannot receive later service messages. + + ## 1.0.42 27th October, 2026