diff --git a/packages/cli/src/app.ts b/packages/cli/src/app.ts index f28c54f31..798401532 100755 --- a/packages/cli/src/app.ts +++ b/packages/cli/src/app.ts @@ -1,3 +1,4 @@ +import { makeLogger } from '@ocap/utils'; import path from 'node:path'; import yargs from 'yargs'; import { hideBin } from 'yargs/helpers'; @@ -9,6 +10,8 @@ import { defaultConfig } from './config.ts'; import type { Config } from './config.ts'; import { withTimeout } from './utils.ts'; +const logger = makeLogger('[cli]'); + await yargs(hideBin(process.argv)) .usage('$0 [options]') .demandCommand(1) @@ -55,7 +58,7 @@ await yargs(hideBin(process.argv)) }, dir: resolvedDir, }; - console.info(`starting ${appName} in ${resolvedDir} on ${url}`); + logger.info(`starting ${appName} in ${resolvedDir} on ${url}`); const server = getServer(config); await server.listen(); }, @@ -77,13 +80,13 @@ await yargs(hideBin(process.argv)) ready .then((close) => { handleClose = close; - console.info(`Watching ${args.dir}...`); + logger.info(`Watching ${args.dir}...`); return undefined; }) - .catch(console.error); + .catch((reason) => logger.error(reason)); error.catch(async (reason) => { - console.error(reason); + logger.error(reason); // If watching started, close the watcher. return handleClose ? withTimeout(handleClose(), 400) : undefined; }); @@ -120,7 +123,7 @@ await yargs(hideBin(process.argv)) const { ready: watchReady, error: watchError } = watchDir(resolvedDir); watchError.catch(async (reason) => { - console.error(reason); + logger.error(reason); await handleClose(); }); @@ -136,7 +139,7 @@ await yargs(hideBin(process.argv)) const { close: closeServer, port } = await server.listen(); closeHandlers.push(closeServer); - console.info(`bundling and serving ${resolvedDir} on localhost:${port}`); + logger.info(`bundling and serving ${resolvedDir} on localhost:${port}`); }, ) .help('help') diff --git a/packages/cli/src/commands/bundle.test.ts b/packages/cli/src/commands/bundle.test.ts index 5b91da975..dd5e9d85e 100644 --- a/packages/cli/src/commands/bundle.test.ts +++ b/packages/cli/src/commands/bundle.test.ts @@ -11,6 +11,13 @@ import { fileExists } from '../file.ts'; const mocks = vi.hoisted(() => ({ bundleSource: vi.fn(), + logger: { + log: vi.fn(), + error: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + debug: vi.fn(), + }, })); vi.mock('@endo/bundle-source', () => ({ @@ -19,6 +26,10 @@ vi.mock('@endo/bundle-source', () => ({ vi.mock('@endo/init', () => ({})); +vi.mock('../logger.ts', () => ({ + logger: mocks.logger, +})); + describe('bundle', async () => { const { testBundleRoot, getTestBundleSpecs, globBundles, resolveBundlePath } = await makeTestBundleStage(); @@ -34,6 +45,7 @@ describe('bundle', async () => { beforeEach(async () => { vi.resetModules(); await deleteTestBundles(); + vi.resetAllMocks(); }); describe('createBundleFile', () => { @@ -57,11 +69,10 @@ describe('bundle', async () => { }, ); - it('calls console.error if bundling fails', async () => { - const consoleErrorSpy = vi.spyOn(console, 'error'); + it('calls logger.error if bundling fails', async () => { const badBundle = resolveBundlePath('bad-vat.fails'); await createBundleFile(badBundle); - expect(consoleErrorSpy).toHaveBeenCalledOnce(); + expect(mocks.logger.error).toHaveBeenCalledOnce(); }); }); diff --git a/packages/cli/src/commands/bundle.ts b/packages/cli/src/commands/bundle.ts index ff31e6c9f..98ffb5dd7 100644 --- a/packages/cli/src/commands/bundle.ts +++ b/packages/cli/src/commands/bundle.ts @@ -5,6 +5,7 @@ import { writeFile } from 'node:fs/promises'; import { resolve, join } from 'node:path'; import { isDirectory } from '../file.ts'; +import { logger } from '../logger.ts'; import { resolveBundlePath } from '../path.ts'; /** @@ -25,9 +26,9 @@ export async function createBundleFile( const bundle = await bundleSource(sourceFullPath); const bundleString = JSON.stringify(bundle); await writeFile(bundlePath, bundleString); - console.log(`wrote ${bundlePath}: ${new Blob([bundleString]).size} bytes`); + logger.log(`wrote ${bundlePath}: ${new Blob([bundleString]).size} bytes`); } catch (problem) { - console.error(problem); + logger.error(problem); } } @@ -38,7 +39,7 @@ export async function createBundleFile( * @returns A promise that resolves when the bundles have been written. */ export async function createBundleDir(sourceDir: string): Promise { - console.log('bundling dir', sourceDir); + logger.log('bundling dir', sourceDir); await Promise.all( (await glob(join(sourceDir, '*.js'))).map( async (source) => await createBundleFile(source), diff --git a/packages/cli/src/commands/watch.test.ts b/packages/cli/src/commands/watch.test.ts index 3ce69b2a3..26594821b 100644 --- a/packages/cli/src/commands/watch.test.ts +++ b/packages/cli/src/commands/watch.test.ts @@ -8,6 +8,16 @@ import { describe, it, expect, vi, beforeEach } from 'vitest'; import { createBundleFile } from './bundle.ts'; import { watchDir, makeWatchEvents } from './watch.ts'; +const mocks = vi.hoisted(() => ({ + logger: { + log: vi.fn(), + error: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + debug: vi.fn(), + }, +})); + vi.mock('fs/promises', () => ({ unlink: vi.fn(async () => new Promise(() => undefined)), })); @@ -20,9 +30,13 @@ vi.mock('./bundle.ts', () => ({ createBundleFile: vi.fn(async () => new Promise(() => undefined)), })); +vi.mock('../logger.ts', () => ({ + logger: mocks.logger, +})); + vi.mock('chokidar', () => ({ watch: () => { - console.log('returning watcher...'); + mocks.logger.log('returning watcher...'); const watcher = { on: () => watcher, close: async (): Promise => undefined, @@ -99,26 +113,25 @@ describe('makeWatchEvents', () => { expect(unlink).toHaveBeenLastCalledWith(`resolved:${testPath}`); }); - it('calls console.info on success', async () => { + it('calls logger.info on success', async () => { const promise = Promise.resolve(); vi.mocked(unlink).mockReturnValue(promise); const events = makeWatchEvents(watch('.'), vi.fn(), vi.fn()); const testPath = 'test-path'; - const infoSpy = vi.spyOn(console, 'info'); events.unlink(testPath); // wait for next crank turn await Promise.resolve(); - expect(infoSpy).toHaveBeenCalledTimes(2); - expect(infoSpy).toHaveBeenNthCalledWith( + expect(mocks.logger.info).toHaveBeenCalledTimes(2); + expect(mocks.logger.info).toHaveBeenNthCalledWith( 1, 'Source file removed:', testPath, ); - expect(infoSpy).toHaveBeenNthCalledWith( + expect(mocks.logger.info).toHaveBeenNthCalledWith( 2, `removed resolved:${testPath}`, ); diff --git a/packages/cli/src/commands/watch.ts b/packages/cli/src/commands/watch.ts index 6ab8e86cb..921e7c0f6 100644 --- a/packages/cli/src/commands/watch.ts +++ b/packages/cli/src/commands/watch.ts @@ -5,6 +5,7 @@ import { unlink } from 'fs/promises'; import { resolve } from 'path'; import { createBundleFile } from './bundle.ts'; +import { logger } from '../logger.ts'; import { resolveBundlePath } from '../path.ts'; type CloseWatcher = () => Promise; @@ -27,18 +28,18 @@ export const makeWatchEvents = ( } => ({ ready: () => readyResolve(watcher.close.bind(watcher)), add: (path) => { - console.info(`Source file added:`, path); + logger.info(`Source file added:`, path); createBundleFile(path, resolveBundlePath(path)).catch(throwError); }, change: (path) => { - console.info(`Source file changed:`, path); + logger.info(`Source file changed:`, path); createBundleFile(path, resolveBundlePath(path)).catch(throwError); }, unlink: (path) => { - console.info('Source file removed:', path); + logger.info('Source file removed:', path); const bundlePath = resolveBundlePath(path); unlink(bundlePath) - .then(() => console.info(`removed ${bundlePath}`)) + .then(() => logger.info(`removed ${bundlePath}`)) .catch((reason: unknown) => { if (reason instanceof Error && reason.message.match(/ENOENT/u)) { // If associated bundle does not exist, do nothing. diff --git a/packages/cli/src/logger.test.ts b/packages/cli/src/logger.test.ts new file mode 100644 index 000000000..0d44fb79e --- /dev/null +++ b/packages/cli/src/logger.test.ts @@ -0,0 +1,9 @@ +import { describe, it, expect } from 'vitest'; + +describe('logger', () => { + it('exports a logger', async () => { + const { logger } = await import('./logger.ts'); + expect(logger).toBeDefined(); + expect(logger.label).toMatch(/cli/u); + }); +}); diff --git a/packages/cli/src/logger.ts b/packages/cli/src/logger.ts new file mode 100644 index 000000000..ff3ffe289 --- /dev/null +++ b/packages/cli/src/logger.ts @@ -0,0 +1,6 @@ +import { makeLogger } from '@ocap/utils'; + +/** + * The default CLI logger + */ +export const logger = makeLogger('[ocap cli]'); diff --git a/packages/extension/src/background.ts b/packages/extension/src/background.ts index 31fb08f0f..b167115a5 100644 --- a/packages/extension/src/background.ts +++ b/packages/extension/src/background.ts @@ -2,11 +2,13 @@ import type { Json } from '@metamask/utils'; import { KernelCommandMethod, isKernelCommandReply } from '@ocap/kernel'; import type { KernelCommand } from '@ocap/kernel'; import { ChromeRuntimeDuplexStream } from '@ocap/streams/browser'; -import { delay } from '@ocap/utils'; +import { delay, makeLogger } from '@ocap/utils'; const OFFSCREEN_DOCUMENT_PATH = '/offscreen.html'; -main().catch(console.error); +const logger = makeLogger('[background]'); + +main().catch(logger.error); /** * The main function for the background script. @@ -36,7 +38,7 @@ async function main(): Promise { await offscreenStream.write(command); }; - // globalThis.kernel will exist due to dev-console.js in background-trusted-prelude.js + // globalThis.kernel will exist due to dev-logger.js in background-trusted-prelude.js Object.defineProperties(globalThis.kernel, { ping: { value: async () => @@ -56,22 +58,22 @@ async function main(): Promise { sendClusterCommand({ method: KernelCommandMethod.ping, params: [], - }).catch(console.error); + }).catch(logger.error); }); // Handle replies from the offscreen document for await (const message of offscreenStream) { if (!isKernelCommandReply(message)) { - console.error('Background received unexpected message', message); + logger.error('Background received unexpected message', message); continue; } switch (message.method) { case KernelCommandMethod.ping: - console.log(message.params); + logger.log(message.params); break; default: - console.error( + logger.error( // @ts-expect-error Compile-time exhaustiveness check `Background received unexpected command method: "${message.method.valueOf()}"`, ); diff --git a/packages/extension/src/iframe.ts b/packages/extension/src/iframe.ts index b183233e0..82d5b2e23 100644 --- a/packages/extension/src/iframe.ts +++ b/packages/extension/src/iframe.ts @@ -4,8 +4,11 @@ import { MessagePortDuplexStream, receiveMessagePort, } from '@ocap/streams/browser'; +import { makeLogger } from '@ocap/utils'; -main().catch(console.error); +const logger = makeLogger('[iframe]'); + +main().catch(logger.error); /** * The main function for the iframe. @@ -30,5 +33,5 @@ async function main(): Promise { commandStream, }); - console.log('VatSupervisor initialized with vatId:', vatId); + logger.log('VatSupervisor initialized with vatId:', vatId); } diff --git a/packages/extension/src/kernel-integration/iframe-vat-worker.ts b/packages/extension/src/kernel-integration/iframe-vat-worker.ts index 99595f0eb..39c2178f3 100644 --- a/packages/extension/src/kernel-integration/iframe-vat-worker.ts +++ b/packages/extension/src/kernel-integration/iframe-vat-worker.ts @@ -1,6 +1,8 @@ import { createWindow } from '@metamask/snaps-utils'; import type { VatId, VatConfig } from '@ocap/kernel'; import type { initializeMessageChannel } from '@ocap/streams/browser'; +import { makeLogger } from '@ocap/utils'; +import type { Logger } from '@ocap/utils'; import type { VatWorker } from './VatWorkerServer.ts'; @@ -9,8 +11,10 @@ const IFRAME_URI = 'iframe.html'; export const makeIframeVatWorker = ( id: VatId, getPort: typeof initializeMessageChannel, + parentLogger?: Logger, ): VatWorker => { const vatHtmlId = `ocap-iframe-${id}`; + const logger = makeLogger(`[${vatHtmlId}]`, parentLogger); return { launch: async (_vatConfig: VatConfig) => { const newWindow = await createWindow({ @@ -27,7 +31,7 @@ export const makeIframeVatWorker = ( terminate: async (): Promise => { const iframe = document.getElementById(vatHtmlId); if (iframe === null) { - console.error( + logger.error( `iframe of vat with id "${id}" already removed from DOM (#${vatHtmlId})`, ); return undefined; diff --git a/packages/extension/src/kernel-integration/kernel-worker.ts b/packages/extension/src/kernel-integration/kernel-worker.ts index c09d9f407..17fc7240d 100644 --- a/packages/extension/src/kernel-integration/kernel-worker.ts +++ b/packages/extension/src/kernel-integration/kernel-worker.ts @@ -88,9 +88,9 @@ async function main(): Promise { (async () => { if (launchDefaultSubcluster) { const result = await kernel.launchSubcluster(defaultSubcluster); - console.log(`Subcluster launched: ${JSON.stringify(result)}`); + logger.log(`Subcluster launched: ${JSON.stringify(result)}`); } else { - console.log(`Resuming kernel execution`); + logger.log(`Resuming kernel execution`); } })(), ]); diff --git a/packages/extension/src/offscreen.ts b/packages/extension/src/offscreen.ts index ec86355f2..730f1ba69 100644 --- a/packages/extension/src/offscreen.ts +++ b/packages/extension/src/offscreen.ts @@ -61,7 +61,7 @@ async function makeKernelWorker(): Promise<{ const vatWorkerServer = ExtensionVatWorkerServer.make( worker as PostMessageTarget, - (vatId) => makeIframeVatWorker(vatId, initializeMessageChannel), + (vatId) => makeIframeVatWorker(vatId, initializeMessageChannel, logger), ); return { diff --git a/packages/kernel/src/Kernel.ts b/packages/kernel/src/Kernel.ts index 5a9aeae09..283598487 100644 --- a/packages/kernel/src/Kernel.ts +++ b/packages/kernel/src/Kernel.ts @@ -247,7 +247,7 @@ export class Kernel { await this.#replyToCommand({ method, params: 'pong' }); break; default: - console.error( + this.#logger.error( 'kernel worker received unexpected command', // @ts-expect-error Compile-time exhaustiveness check { method: method.valueOf(), params }, @@ -341,15 +341,23 @@ export class Kernel { if (this.#vats.has(vatId)) { throw new VatAlreadyExistsError(vatId); } - const commandStream = await this.#vatWorkerService.launch(vatId, vatConfig); - const vat = await VatHandle.make({ - kernel: this, + + // Create a child logger with the vat's ID + const vatLogger = makeLogger(`[vat ${vatId}]`, this.#logger); + + const vatStream = await this.#vatWorkerService.launch(vatId, vatConfig); + + this.#vats.set( vatId, - vatConfig, - vatStream: commandStream, - kernelStore: this.#kernelStore, - }); - this.#vats.set(vatId, vat); + await VatHandle.make({ + kernel: this, + vatId, + vatConfig, + vatStream, + kernelStore: this.#kernelStore, + logger: vatLogger, + }), + ); } /** @@ -515,14 +523,13 @@ export class Kernel { * @param item - The message/notification to deliver. */ async #deliver(item: RunQueueItem): Promise { - const { log } = console; switch (item.type) { case 'send': { const route = this.#routeMessage(item); if (route) { const { vatId, target } = route; const { message } = item; - log( + this.#logger.log( `@@@@ deliver ${vatId} send ${target}<-${JSON.stringify(message)}`, ); if (vatId) { @@ -543,7 +550,9 @@ export class Kernel { } else { this.#kernelStore.enqueuePromiseMessage(target, message); } - log(`@@@@ done ${vatId} send ${target}<-${JSON.stringify(message)}`); + this.#logger.log( + `@@@@ done ${vatId} send ${target}<-${JSON.stringify(message)}`, + ); } break; } @@ -555,7 +564,7 @@ export class Kernel { context === 'kernel' && isPromise, `${kpid} is not a kernel promise`, ); - log(`@@@@ deliver ${vatId} notify ${vatId} ${kpid}`); + this.#logger.log(`@@@@ deliver ${vatId} notify ${vatId} ${kpid}`); const promise = this.#kernelStore.getKernelPromise(kpid); const { state, value } = promise; assert(value, `no value for promise ${kpid}`); @@ -588,39 +597,39 @@ export class Kernel { } const vat = this.#getVat(vatId); await vat.deliverNotify(resolutions); - log(`@@@@ done ${vatId} notify ${vatId} ${kpid}`); + this.#logger.log(`@@@@ done ${vatId} notify ${vatId} ${kpid}`); break; } case 'dropExports': { const { vatId, krefs } = item; - log(`@@@@ deliver ${vatId} dropExports`, krefs); + this.#logger.log(`@@@@ deliver ${vatId} dropExports`, krefs); const vat = this.#getVat(vatId); await vat.deliverDropExports(krefs); - log(`@@@@ done ${vatId} dropExports`, krefs); + this.#logger.log(`@@@@ done ${vatId} dropExports`, krefs); break; } case 'retireExports': { const { vatId, krefs } = item; - log(`@@@@ deliver ${vatId} retireExports`, krefs); + this.#logger.log(`@@@@ deliver ${vatId} retireExports`, krefs); const vat = this.#getVat(vatId); await vat.deliverRetireExports(krefs); - log(`@@@@ done ${vatId} retireExports`, krefs); + this.#logger.log(`@@@@ done ${vatId} retireExports`, krefs); break; } case 'retireImports': { const { vatId, krefs } = item; - log(`@@@@ deliver ${vatId} retireImports`, krefs); + this.#logger.log(`@@@@ deliver ${vatId} retireImports`, krefs); const vat = this.#getVat(vatId); await vat.deliverRetireImports(krefs); - log(`@@@@ done ${vatId} retireImports`, krefs); + this.#logger.log(`@@@@ done ${vatId} retireImports`, krefs); break; } case 'bringOutYourDead': { const { vatId } = item; - log(`@@@@ deliver ${vatId} bringOutYourDead`); + this.#logger.log(`@@@@ deliver ${vatId} bringOutYourDead`); const vat = this.#getVat(vatId); await vat.deliverBringOutYourDead(); - log(`@@@@ done ${vatId} bringOutYourDead`); + this.#logger.log(`@@@@ done ${vatId} bringOutYourDead`); break; } default: @@ -813,7 +822,9 @@ export class Kernel { throw new VatNotFoundError(vatId); } await vat.terminate(terminating); - await this.#vatWorkerService.terminate(vatId).catch(console.error); + await this.#vatWorkerService.terminate(vatId).catch((error) => { + this.#logger.error('Error terminating vat worker:', error); + }); this.#vats.delete(vatId); } diff --git a/packages/kernel/src/VatHandle.ts b/packages/kernel/src/VatHandle.ts index 63cc083b6..3e8042289 100644 --- a/packages/kernel/src/VatHandle.ts +++ b/packages/kernel/src/VatHandle.ts @@ -394,60 +394,74 @@ export class VatHandle { const kso: VatSyscallObject = this.#translateSyscallVtoK(vso); const [op] = kso; const { vatId } = this; - const { log } = console; + switch (op) { case 'send': { // [KRef, Message]; const [, target, message] = kso; - log(`@@@@ ${vatId} syscall send ${target}<-${JSON.stringify(message)}`); + this.#logger.log( + `@@@@ ${vatId} syscall send ${target}<-${JSON.stringify(message)}`, + ); this.#handleSyscallSend(target, message); break; } case 'subscribe': { // [KRef]; const [, promise] = kso; - log(`@@@@ ${vatId} syscall subscribe ${promise}`); + this.#logger.log(`@@@@ ${vatId} syscall subscribe ${promise}`); this.#handleSyscallSubscribe(promise); break; } case 'resolve': { // [VatOneResolution[]]; const [, resolutions] = kso; - log(`@@@@ ${vatId} syscall resolve ${JSON.stringify(resolutions)}`); + this.#logger.log( + `@@@@ ${vatId} syscall resolve ${JSON.stringify(resolutions)}`, + ); this.#handleSyscallResolve(resolutions as VatOneResolution[]); break; } case 'exit': { // [boolean, SwingSetCapData]; const [, fail, info] = kso; - log(`@@@@ ${vatId} syscall exit fail=${fail} ${JSON.stringify(info)}`); + this.#logger.log( + `@@@@ ${vatId} syscall exit fail=${fail} ${JSON.stringify(info)}`, + ); break; } case 'dropImports': { // [KRef[]]; const [, refs] = kso; - log(`@@@@ ${vatId} syscall dropImports ${JSON.stringify(refs)}`); + this.#logger.log( + `@@@@ ${vatId} syscall dropImports ${JSON.stringify(refs)}`, + ); this.#handleSyscallDropImports(refs); break; } case 'retireImports': { // [KRef[]]; const [, refs] = kso; - log(`@@@@ ${vatId} syscall retireImports ${JSON.stringify(refs)}`); + this.#logger.log( + `@@@@ ${vatId} syscall retireImports ${JSON.stringify(refs)}`, + ); this.#handleSyscallRetireImports(refs); break; } case 'retireExports': { // [KRef[]]; const [, refs] = kso; - log(`@@@@ ${vatId} syscall retireExports ${JSON.stringify(refs)}`); + this.#logger.log( + `@@@@ ${vatId} syscall retireExports ${JSON.stringify(refs)}`, + ); this.#handleSyscallExportCleanup(refs, true); break; } case 'abandonExports': { // [KRef[]]; const [, refs] = kso; - log(`@@@@ ${vatId} syscall abandonExports ${JSON.stringify(refs)}`); + this.#logger.log( + `@@@@ ${vatId} syscall abandonExports ${JSON.stringify(refs)}`, + ); this.#handleSyscallExportCleanup(refs, false); break; } @@ -456,13 +470,13 @@ export class VatHandle { case 'vatstoreGetNextKey': case 'vatstoreSet': case 'vatstoreDelete': { - console.warn(`vat ${vatId} issued invalid syscall ${op} `, vso); + this.#logger.warn(`vat ${vatId} issued invalid syscall ${op} `, vso); break; } default: // Compile-time exhaustiveness check // eslint-disable-next-line @typescript-eslint/restrict-template-expressions - console.warn(`vat ${vatId} issued unknown syscall ${op} `, vso); + this.#logger.warn(`vat ${vatId} issued unknown syscall ${op} `, vso); break; } } diff --git a/packages/kernel/src/VatSupervisor.test.ts b/packages/kernel/src/VatSupervisor.test.ts index 6a9b1234e..f1fbb13ef 100644 --- a/packages/kernel/src/VatSupervisor.test.ts +++ b/packages/kernel/src/VatSupervisor.test.ts @@ -1,6 +1,7 @@ import '@ocap/test-utils'; import { TestDuplexStream } from '@ocap/test-utils/streams'; -import { delay } from '@ocap/utils'; +import type { Logger } from '@ocap/utils'; +import { delay, makeLogger } from '@ocap/utils'; import { describe, it, expect, vi } from 'vitest'; import { VatCommandMethod } from './messages/index.ts'; @@ -27,7 +28,9 @@ const makeVatSupervisor = async ( ): Promise<{ supervisor: VatSupervisor; stream: TestDuplexStream; + logger: Logger; }> => { + const logger = makeLogger('[test-vat-supervisor]'); const commandStream = await TestDuplexStream.make< VatCommand, VatCommandReply @@ -37,8 +40,10 @@ const makeVatSupervisor = async ( id: 'test-id', commandStream, vatPowers: vatPowers ?? {}, + logger, }), stream: commandStream, + logger, }; }; @@ -51,32 +56,38 @@ describe('VatSupervisor', () => { }); it('throws if the stream throws', async () => { - const { supervisor, stream } = await makeVatSupervisor(); - const consoleErrorSpy = vi.spyOn(console, 'error'); + const { supervisor, stream, logger } = await makeVatSupervisor(); + const errorSpy = vi + .spyOn(logger, 'error') + .mockImplementation(() => undefined); await stream.receiveInput(NaN); await delay(10); - expect(consoleErrorSpy).toHaveBeenCalledWith( + expect(errorSpy).toHaveBeenCalledWith( `Unexpected read error from VatSupervisor "${supervisor.id}"`, expect.any(Error), ); + errorSpy.mockRestore(); }); }); describe('handleMessage', () => { it('throws if receiving an unexpected message', async () => { - const { supervisor, stream } = await makeVatSupervisor(); + const { supervisor, stream, logger } = await makeVatSupervisor(); - const consoleErrorSpy = vi.spyOn(console, 'error'); + const errorSpy = vi + .spyOn(logger, 'error') + .mockImplementation(() => undefined); await stream.receiveInput({ channel: 'command', payload: { method: 'test' }, }); await delay(10); - expect(consoleErrorSpy).toHaveBeenCalledOnce(); - expect(consoleErrorSpy).toHaveBeenCalledWith( + expect(errorSpy).toHaveBeenCalledOnce(); + expect(errorSpy).toHaveBeenCalledWith( `Unexpected read error from VatSupervisor "${supervisor.id}"`, new Error(`VatSupervisor received unexpected command method: "test"`), ); + errorSpy.mockRestore(); }); it('handles Ping messages', async () => { diff --git a/packages/kernel/src/VatSupervisor.ts b/packages/kernel/src/VatSupervisor.ts index e226b0e39..9f557f8d7 100644 --- a/packages/kernel/src/VatSupervisor.ts +++ b/packages/kernel/src/VatSupervisor.ts @@ -9,6 +9,8 @@ import { makeMarshal } from '@endo/marshal'; import type { CapData } from '@endo/marshal'; import { StreamReadError } from '@ocap/errors'; import type { DuplexStream } from '@ocap/streams'; +import type { Logger } from '@ocap/utils'; +import { makeLogger } from '@ocap/utils'; import type { VatCommand, VatCommandReply } from './messages/index.ts'; import { VatCommandMethod } from './messages/index.ts'; @@ -31,6 +33,7 @@ type SupervisorConstructorProps = { commandStream: DuplexStream; vatPowers?: Record | undefined; fetchBlob?: FetchBlob; + logger?: Logger; }; const marshal = makeMarshal(undefined, undefined, { @@ -44,6 +47,9 @@ export class VatSupervisor { /** Communications channel between this vat and the kernel */ readonly #commandStream: DuplexStream; + /** Logger for outputting messages (such as errors) to the console */ + readonly #logger: Logger; + /** Flag that the user code has been loaded */ #loaded: boolean = false; @@ -70,12 +76,14 @@ export class VatSupervisor { * @param params.commandStream - Communications channel connected to the kernel. * @param params.vatPowers - The external capabilities for this vat. * @param params.fetchBlob - Function to fetch the user code bundle for this vat. + * @param params.logger - Logger for outputting messages (such as errors) to the console. */ constructor({ id, commandStream, vatPowers, fetchBlob, + logger, }: SupervisorConstructorProps) { this.id = id; this.#commandStream = commandStream; @@ -84,11 +92,12 @@ export class VatSupervisor { const defaultFetchBlob: FetchBlob = async (bundleURL: string) => await fetch(bundleURL); this.#fetchBlob = fetchBlob ?? defaultFetchBlob; + this.#logger = logger ?? makeLogger(`[vat-supervisor ${id}]`); Promise.all([ this.#commandStream.drain(this.handleMessage.bind(this)), ]).catch(async (error) => { - console.error( + this.#logger.error( `Unexpected read error from VatSupervisor "${this.id}"`, error, ); @@ -116,7 +125,7 @@ export class VatSupervisor { switch (payload.method) { case VatCommandMethod.deliver: { if (!this.#dispatch) { - console.error(`cannot deliver before vat is loaded`); + this.#logger.error(`cannot deliver before vat is loaded`); return; } await this.#dispatch(harden(payload.params) as VatDeliveryObject); @@ -154,7 +163,7 @@ export class VatSupervisor { // only from some kind of internal system problem, so if it happens we // die. const errMsg = `syscall failure ${failure}`; - console.error(errMsg); + this.#logger.error(errMsg); await this.terminate(Error(errMsg)); } break; @@ -221,7 +230,7 @@ export class VatSupervisor { this.#loaded = true; this.#vatKVStore = makeVatKVStore(state); - const syscall = makeSupervisorSyscall(this, this.#vatKVStore); + const syscall = makeSupervisorSyscall(this, this.#vatKVStore, this.#logger); const liveSlotsOptions = {}; // XXX should be something more real const gcTools: GCTools = harden({ @@ -234,7 +243,7 @@ export class VatSupervisor { }); const workerEndowments = { - console, + console: makeLogger(`[vat ${this.id}]`, this.#logger), assert: globalThis.assert, }; @@ -263,7 +272,7 @@ export class VatSupervisor { this.#vatPowers, liveSlotsOptions, gcTools, - console, + this.#logger, buildVatNamespace, ); diff --git a/packages/kernel/src/messages/message-resolver.test.ts b/packages/kernel/src/messages/message-resolver.test.ts index 9f744ab78..59876f0e4 100644 --- a/packages/kernel/src/messages/message-resolver.test.ts +++ b/packages/kernel/src/messages/message-resolver.test.ts @@ -1,3 +1,4 @@ +import { makeLogger } from '@ocap/utils'; import { describe, it, expect, vi } from 'vitest'; import { MessageResolver } from './message-resolver.ts'; @@ -23,21 +24,23 @@ describe('MessageResolver', () => { it('logs an error if handleResponse is called with an unknown messageId', () => { const prefix = 'test'; - const resolver = new MessageResolver(prefix); - const consoleErrorSpy = vi - .spyOn(console, 'error') - .mockImplementation(() => { - // Do nothing - }); + // Create a real logger with mocked methods + const mockLogger = makeLogger('[test-logger]'); + const errorSpy = vi + .spyOn(mockLogger, 'error') + .mockImplementation(() => undefined); + + const resolver = new MessageResolver(prefix, mockLogger); resolver.handleResponse('unknown-id', 'value'); - expect(consoleErrorSpy).toHaveBeenCalledWith( + expect(errorSpy).toHaveBeenCalledOnce(); + expect(errorSpy.mock.lastCall).toContain( 'No unresolved message with id "unknown-id".', ); - consoleErrorSpy.mockRestore(); + errorSpy.mockRestore(); }); it('generates unique message IDs', async () => { @@ -99,4 +102,17 @@ describe('MessageResolver', () => { expect(resolver.unresolvedMessages.size).toBe(0); }); + + it('uses the parent logger when provided', () => { + const parentLogger = makeLogger('[parent]'); + const loggerSpy = vi + .spyOn(parentLogger, 'error') + .mockImplementation(() => undefined); + + const resolver = new MessageResolver('test', parentLogger); + resolver.handleResponse('unknown-id', 'value'); + + expect(loggerSpy).toHaveBeenCalled(); + loggerSpy.mockRestore(); + }); }); diff --git a/packages/kernel/src/messages/message-resolver.ts b/packages/kernel/src/messages/message-resolver.ts index f83531c85..48bb9ad39 100644 --- a/packages/kernel/src/messages/message-resolver.ts +++ b/packages/kernel/src/messages/message-resolver.ts @@ -1,17 +1,21 @@ import { makePromiseKit } from '@endo/promise-kit'; -import { makeCounter } from '@ocap/utils'; +import type { Logger } from '@ocap/utils'; +import { makeLogger, makeCounter } from '@ocap/utils'; import type { PromiseCallbacks } from '../types.ts'; export class MessageResolver { readonly #prefix: string; + readonly #logger: Logger; + readonly unresolvedMessages = new Map(); readonly #messageCounter = makeCounter(); - constructor(prefix: string) { + constructor(prefix: string, parentLogger?: Logger) { this.#prefix = prefix; + this.#logger = makeLogger(`[message-resolver ${prefix}]`, parentLogger); } async createMessage( @@ -25,14 +29,14 @@ export class MessageResolver { reject, }); - sendMessage(messageId).catch(console.error); + sendMessage(messageId).catch((error) => this.#logger.error(error)); return promise; } handleResponse(messageId: string, value: unknown): void { const promiseCallbacks = this.unresolvedMessages.get(messageId); if (promiseCallbacks === undefined) { - console.error(`No unresolved message with id "${messageId}".`); + this.#logger.error(`No unresolved message with id "${messageId}".`); } else { this.unresolvedMessages.delete(messageId); promiseCallbacks.resolve(value); diff --git a/packages/kernel/src/services/syscall.test.ts b/packages/kernel/src/services/syscall.test.ts index cd773e9b6..4a0a7e4af 100644 --- a/packages/kernel/src/services/syscall.test.ts +++ b/packages/kernel/src/services/syscall.test.ts @@ -5,6 +5,7 @@ import type { } from '@agoric/swingset-liveslots'; import type { CapData } from '@endo/marshal'; import type { KVStore } from '@ocap/store'; +import { makeLogger } from '@ocap/utils'; import { describe, it, expect, vi } from 'vitest'; import { makeSupervisorSyscall } from './syscall.ts'; @@ -64,6 +65,43 @@ describe('syscall', () => { expect(syscall).toHaveProperty('vatstoreDelete'); }); + it('uses provided logger for error logging', () => { + const supervisor = createMockSupervisor(); + const kv = createMockKVStore(); + const logger = makeLogger('[test-syscall]'); + const warnSpy = vi + .spyOn(logger, 'warn') + .mockImplementation(() => undefined); + + // Force an error in the syscall + vi.spyOn(supervisor, 'executeSyscall').mockImplementation(() => { + throw new Error('test error'); + }); + + const syscall = makeSupervisorSyscall(supervisor, kv, logger); + + expect(() => syscall.send('target', { body: '', slots: [] })).toThrow( + 'test error', + ); + expect(warnSpy).toHaveBeenCalledWith( + 'supervisor got error during syscall:', + expect.any(Error), + ); + + warnSpy.mockRestore(); + }); + + it('creates a default logger if none provided', () => { + const supervisor = createMockSupervisor(); + const kv = createMockKVStore(); + + // Create a syscall without providing a logger + const syscall = makeSupervisorSyscall(supervisor, kv); + + // Just verify the syscall works - we can't easily test the internal logger creation + expect(syscall).toHaveProperty('send'); + }); + describe('syscall methods', () => { it('handles send syscall', () => { const supervisor = createMockSupervisor(); diff --git a/packages/kernel/src/services/syscall.ts b/packages/kernel/src/services/syscall.ts index ede62bcf8..61ce7d05e 100644 --- a/packages/kernel/src/services/syscall.ts +++ b/packages/kernel/src/services/syscall.ts @@ -8,6 +8,8 @@ import type { } from '@agoric/swingset-liveslots'; import type { CapData } from '@endo/marshal'; import type { KVStore } from '@ocap/store'; +import type { Logger } from '@ocap/utils'; +import { makeLogger } from '@ocap/utils'; import type { Syscall, SyscallResult } from './types.ts'; import type { VatSupervisor } from '../VatSupervisor.ts'; @@ -23,12 +25,14 @@ import type { VatSupervisor } from '../VatSupervisor.ts'; * * @param supervisor - The VatSupervisor for which we're providing syscall services. * @param kv - A key/value store for holding the vat's persistent state. + * @param logger - The logger to use for error and diagnostic output. * * @returns a syscall object suitable for use by liveslots. */ function makeSupervisorSyscall( supervisor: VatSupervisor, kv: KVStore, + logger?: Logger, ): Syscall { /** * Actually perform the syscall operation. @@ -37,12 +41,13 @@ function makeSupervisorSyscall( * @returns the result from performing the syscall. */ function doSyscall(vso: VatSyscallObject): SyscallResult { + const sysLogger = logger ?? makeLogger(`[syscall ${supervisor.id}]`); insistVatSyscallObject(vso); let syscallResult; try { syscallResult = supervisor.executeSyscall(vso); } catch (problem) { - console.warn(`supervisor got error during syscall:`, problem); + sysLogger.warn(`supervisor got error during syscall:`, problem); throw problem; } const vsr = syscallResult; diff --git a/packages/nodejs/src/vat/logger.test.ts b/packages/nodejs/src/vat/logger.test.ts new file mode 100644 index 000000000..6cdc26629 --- /dev/null +++ b/packages/nodejs/src/vat/logger.test.ts @@ -0,0 +1,16 @@ +import { describe, it, expect } from 'vitest'; + +import { makeVatLogger } from './logger.ts'; + +describe('makeVatLogger', () => { + it('should create a logger with the given vatId', () => { + const vatId = '123'; + const logger = makeVatLogger(vatId); + expect(logger.label).toContain(vatId); + }); + + it('should create a logger when no vatId is provided', () => { + const logger = makeVatLogger(); + expect(logger.label).toContain('(unknown)'); + }); +}); diff --git a/packages/nodejs/src/vat/logger.ts b/packages/nodejs/src/vat/logger.ts new file mode 100644 index 000000000..56b30edfd --- /dev/null +++ b/packages/nodejs/src/vat/logger.ts @@ -0,0 +1,6 @@ +import type { VatId } from '@ocap/kernel'; +import type { Logger } from '@ocap/utils'; +import { makeLogger } from '@ocap/utils'; + +export const makeVatLogger = (vatId?: VatId): Logger => + makeLogger(`[vat-worker ${vatId ?? '(unknown)'}]`); diff --git a/packages/nodejs/src/vat/vat-worker.ts b/packages/nodejs/src/vat/vat-worker.ts index 9fa821ef0..9c451ac5c 100644 --- a/packages/nodejs/src/vat/vat-worker.ts +++ b/packages/nodejs/src/vat/vat-worker.ts @@ -2,22 +2,19 @@ import '@ocap/shims/endoify'; import type { VatId } from '@ocap/kernel'; import { VatSupervisor } from '@ocap/kernel'; -import { makeLogger } from '@ocap/utils'; import fs from 'node:fs/promises'; import url from 'node:url'; +import { makeVatLogger } from './logger.ts'; import { makeCommandStream } from './streams.ts'; const vatId = process.env.NODE_VAT_ID as VatId; /* eslint-disable n/no-unsupported-features/node-builtins */ -if (vatId) { - const logger = makeLogger(`[vat-worker (${vatId})]`); - main().catch((error) => logger.error(error)); -} else { - console.log('no vatId set for env variable NODE_VAT_ID'); -} +const logger = makeVatLogger(vatId); + +main(vatId).catch((error) => logger.error(error)); /** * Fetch a blob of bytes from a URL @@ -39,14 +36,20 @@ async function fetchBlob(blobURL: string): Promise { /** * The main function for the iframe. + * + * @param id - The ID of the vat this worker is running. */ -async function main(): Promise { +async function main(id: VatId): Promise { + if (!id) { + throw new Error('no vat ID set for env variable NODE_VAT_ID'); + } const commandStream = makeCommandStream(); await commandStream.synchronize(); // eslint-disable-next-line no-void void new VatSupervisor({ - id: vatId, + id, commandStream, fetchBlob, + logger, }); } diff --git a/packages/streams/src/browser/ChromeRuntimeStream.test.ts b/packages/streams/src/browser/ChromeRuntimeStream.test.ts index 09a39b0ec..a6f2f4a16 100644 --- a/packages/streams/src/browser/ChromeRuntimeStream.test.ts +++ b/packages/streams/src/browser/ChromeRuntimeStream.test.ts @@ -31,6 +31,21 @@ const makeEnvelope = ( const EXTENSION_ID = 'test-extension-id'; +const mocks = vi.hoisted(() => ({ + logger: { + debug: vi.fn(), + warn: vi.fn(), + }, +})); + +vi.mock('@ocap/utils', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + makeLogger: vi.fn(() => mocks.logger), + }; +}); + // This function declares its own return type. // eslint-disable-next-line @typescript-eslint/explicit-function-return-type const makeRuntime = (extensionId: string = EXTENSION_ID) => { @@ -165,11 +180,11 @@ describe('ChromeRuntimeReader', () => { const nextP = reader.next(); - vi.spyOn(console, 'debug'); + const debugSpy = vi.spyOn(mocks.logger, 'debug'); listeners[0]?.({ not: 'an envelope' }, { id: EXTENSION_ID }); - expect(console.debug).toHaveBeenCalledWith( - `ChromeRuntimeReader received unexpected message: ${stringify({ + expect(debugSpy).toHaveBeenCalledWith( + `received unexpected message: ${stringify({ not: 'an envelope', })}`, ); @@ -189,7 +204,7 @@ describe('ChromeRuntimeReader', () => { const nextP = reader.next(); - vi.spyOn(console, 'warn'); + vi.spyOn(mocks.logger, 'warn'); const message1 = { foo: 'bar' }; dispatchRuntimeMessage( message1, diff --git a/packages/streams/src/browser/ChromeRuntimeStream.ts b/packages/streams/src/browser/ChromeRuntimeStream.ts index efe51e6f7..d9455d9ce 100644 --- a/packages/streams/src/browser/ChromeRuntimeStream.ts +++ b/packages/streams/src/browser/ChromeRuntimeStream.ts @@ -15,7 +15,8 @@ */ import type { Json } from '@metamask/utils'; -import { stringify } from '@ocap/utils'; +import { makeLogger, stringify } from '@ocap/utils'; +import type { Logger } from '@ocap/utils'; import type { ChromeRuntime, ChromeMessageSender } from './chrome.d.ts'; import { @@ -67,6 +68,8 @@ export class ChromeRuntimeReader extends BaseReader { readonly #extensionId: string; + readonly #logger: Logger; + constructor( runtime: ChromeRuntime, target: ChromeRuntimeTarget, @@ -91,6 +94,7 @@ export class ChromeRuntimeReader extends BaseReader { this.#target = target; this.#source = source; this.#extensionId = runtime.id; + this.#logger = makeLogger(`[chrome-runtime-reader ${this.#extensionId}]`); messageListener = this.#onMessage.bind(this); // Begin listening for messages from the Chrome runtime. @@ -105,19 +109,15 @@ export class ChromeRuntimeReader extends BaseReader { } if (!isMessageEnvelope(message)) { - console.debug( - `ChromeRuntimeReader received unexpected message: ${stringify( - message, - )}`, - ); + this.#logger.debug(`received unexpected message: ${stringify(message)}`); return; } if (message.target !== this.#target || message.source !== this.#source) { - console.debug( - `ChromeRuntimeReader received message with incorrect target or source: ${stringify(message)}`, - `Expected target: ${this.#target}`, - `Expected source: ${this.#source}`, + this.#logger.debug( + `received message with incorrect target or source: ${stringify(message)}`, + `expected target: ${this.#target}`, + `expected source: ${this.#source}`, ); return; }