feat(kernel): standardize logger usage

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 <command> [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')

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();
     });
   });
 

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<void> {
-  console.log('bundling dir', sourceDir);
+  logger.log('bundling dir', sourceDir);
   await Promise.all(
     (await glob(join(sourceDir, '*.js'))).map(
       async (source) => await createBundleFile(source),

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<void>(() => undefined)),
 }));
@@ -20,9 +30,13 @@ vi.mock('./bundle.ts', () => ({
   createBundleFile: vi.fn(async () => new Promise<void>(() => 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<void> => 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}`,
       );

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<void>;
@@ -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.

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);
+  });
+});

packages/cli/src/logger.ts

@@ -0,0 +1,6 @@
+import { makeLogger } from '@ocap/utils';
+
+/**
+ * The default CLI logger
+ */
+export const logger = makeLogger('[ocap cli]');

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<void> {
     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<void> {
     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()}"`,
         );

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<void> {
     commandStream,
   });
 
-  console.log('VatSupervisor initialized with vatId:', vatId);
+  logger.log('VatSupervisor initialized with vatId:', vatId);
 }

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<void> => {
       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;

packages/extension/src/kernel-integration/kernel-worker.ts

@@ -88,9 +88,9 @@ async function main(): Promise<void> {
     (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`);
       }
     })(),
   ]);

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 {