From 29d1bd1e017f1a7e823e8ce48bca1cfb8a97d4bd Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Wed, 30 Apr 2025 11:30:05 -0400 Subject: [PATCH 01/26] feat(logger): Add injectStream method --- packages/logger/package.json | 1 + packages/logger/src/index.test.ts | 6 +++- packages/logger/src/index.ts | 1 + packages/logger/src/logger.test.ts | 45 ++++++++++++++++++++++++++ packages/logger/src/logger.ts | 25 ++++++++++++++ packages/logger/src/stream.test.ts | 41 +++++++++++++++++++++++ packages/logger/src/stream.ts | 43 ++++++++++++++++++++++++ packages/logger/src/transports.test.ts | 11 +++++-- packages/logger/src/transports.ts | 10 ++++-- yarn.lock | 1 + 10 files changed, 178 insertions(+), 6 deletions(-) create mode 100644 packages/logger/src/stream.test.ts create mode 100644 packages/logger/src/stream.ts diff --git a/packages/logger/package.json b/packages/logger/package.json index ef20c49d6..433e384a5 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -56,6 +56,7 @@ "test:watch": "vitest --config vitest.config.ts" }, "dependencies": { + "@metamask/kernel-utils": "workspace:^", "@metamask/streams": "workspace:^" }, "devDependencies": { diff --git a/packages/logger/src/index.test.ts b/packages/logger/src/index.test.ts index 2276bb985..f809975e9 100644 --- a/packages/logger/src/index.test.ts +++ b/packages/logger/src/index.test.ts @@ -5,7 +5,11 @@ import * as indexModule from './index.ts'; describe('index', () => { it('has the expected exports', () => { expect(Object.keys(indexModule).sort()).toStrictEqual( - expect.arrayContaining(['Logger']), + expect.arrayContaining([ + 'Logger', + 'consoleTransport', + 'makeStreamTransport', + ]), ); }); }); diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index a44a49f70..b2b7772fc 100644 --- a/packages/logger/src/index.ts +++ b/packages/logger/src/index.ts @@ -1 +1,2 @@ export { Logger } from './logger.ts'; +export { consoleTransport, makeStreamTransport } from './transports.ts'; diff --git a/packages/logger/src/logger.test.ts b/packages/logger/src/logger.test.ts index ea7e8e171..177797dbd 100644 --- a/packages/logger/src/logger.test.ts +++ b/packages/logger/src/logger.test.ts @@ -1,6 +1,10 @@ +import type { DuplexStream } from '@metamask/streams'; +import { delay } from '@ocap/test-utils'; import { describe, it, expect, vi } from 'vitest'; import { Logger } from './logger.ts'; +import { lser } from './stream.ts'; +import type { LogMessage } from './stream.ts'; import { consoleTransport } from './transports.ts'; const consoleMethod = ['log', 'debug', 'info', 'warn', 'error'] as const; @@ -108,4 +112,45 @@ describe('Logger', () => { expect(consoleSpy).toHaveBeenCalledWith(['test', 'sub'], 'foo'); }); }); + + describe('injectStream', () => { + it('calls drain on the provided stream', () => { + const logger = new Logger(); + const stream = { drain: vi.fn().mockResolvedValue(undefined) }; + logger.injectStream(stream as unknown as DuplexStream); + expect(stream.drain).toHaveBeenCalled(); + }); + + it.each` + description | logEntry + ${'message and data'} | ${{ level: 'log', tags: ['test'], message: 'foo', data: ['bar'] }} + ${'message but no data'} | ${{ level: 'log', tags: ['test'], message: 'foo' }} + ${'no message or data'} | ${{ level: 'log', tags: ['test'] }} + `( + 'delivers a logEntry to the logger transport: $description', + ({ logEntry }) => { + const testTransport = vi.fn(); + const logger = new Logger({ transports: [testTransport] }); + const stream = { + drain: vi.fn(async (handler) => handler({ params: lser(logEntry) })), + } as unknown as DuplexStream; + logger.injectStream(stream); + expect(testTransport).toHaveBeenCalledWith( + expect.objectContaining(logEntry), + ); + }, + ); + + it('calls the provided onError if drain fails', async () => { + const testError = new Error('test'); + const onError = vi.fn(); + const stream = { + drain: vi.fn().mockRejectedValue(testError), + } as unknown as DuplexStream; + const logger = new Logger(); + logger.injectStream(stream, onError); + await delay(10); + expect(onError).toHaveBeenCalledWith(testError); + }); + }); }); diff --git a/packages/logger/src/logger.ts b/packages/logger/src/logger.ts index cf5af88ff..0cd9c4800 100644 --- a/packages/logger/src/logger.ts +++ b/packages/logger/src/logger.ts @@ -48,7 +48,11 @@ * ``` */ +import type { DuplexStream } from '@metamask/streams'; + import { parseOptions, mergeOptions } from './options.ts'; +import { lunser } from './stream.ts'; +import type { LogMessage } from './stream.ts'; import type { LogLevel, LogEntry, @@ -123,6 +127,27 @@ export class Logger { ); } + /** + * Injects a stream of log messages into the logger. + * + * @param stream - The stream of log messages to inject. + * @param onError - The function to call if an error occurs while draining + * the stream. If not provided, the error will be lost to the void. + */ + injectStream( + stream: DuplexStream, + onError?: (error: Error) => void, + ): void { + // eslint-disable-next-line no-void + void stream + .drain(({ params }) => { + const { level, tags, message, data } = lunser(params); + const args: LogArgs = message ? [message, ...(data ?? [])] : []; + this.#dispatch({ level, tags }, ...args); + }) + .catch(onError); + } + #dispatch(options: LoggerOptions, ...args: LogArgs): void { const { transports, level, tags } = mergeOptions(this.#options, options); const [message, ...data] = args; diff --git a/packages/logger/src/stream.test.ts b/packages/logger/src/stream.test.ts new file mode 100644 index 000000000..9b1c83657 --- /dev/null +++ b/packages/logger/src/stream.test.ts @@ -0,0 +1,41 @@ +import { describe, it, expect } from 'vitest'; + +import { isLogMessage, lser, lunser } from './stream.ts'; + +describe('serialization', () => { + it.each` + description | logEntry + ${'with message and data'} | ${{ + level: 'info', + tags: ['test'], + message: 'test', + data: ['test'], +}} + ${'with message but no data'} | ${{ + level: 'info', + tags: ['test'], + message: 'test', +}} + ${'with no message or data'} | ${{ + level: 'info', + tags: ['test'], +}} + `('round-trips a log entry $description', ({ logEntry }) => { + const serialized = lser(logEntry); + const deserialized = lunser(serialized); + expect(deserialized).toStrictEqual(logEntry); + }); +}); + +describe('isLogMessage', () => { + const validParams = ['info', ['test'], 'test', ['test']]; + const unserializableParams = [() => undefined]; + it.each` + description | value | expectation + ${'valid params'} | ${{ method: 'log', params: validParams, jsonrpc: '2.0' }} | ${true} + ${'unserializable params'} | ${{ method: 'log', params: unserializableParams, jsonrpc: '2.0' }} | ${false} + ${'invalid method'} | ${{ method: 'ping', params: null, jsonrpc: '2.0' }} | ${false} + `('returns $expectation for $description', ({ value, expectation }) => { + expect(isLogMessage(value)).toBe(expectation); + }); +}); diff --git a/packages/logger/src/stream.ts b/packages/logger/src/stream.ts new file mode 100644 index 000000000..8eede4174 --- /dev/null +++ b/packages/logger/src/stream.ts @@ -0,0 +1,43 @@ +import { isJsonRpcCall, stringify } from '@metamask/kernel-utils'; +import type { JsonRpcCall, JsonRpcMessage } from '@metamask/kernel-utils'; + +import type { LogEntry, LogLevel } from './types.ts'; + +type SerializedLogEntry = [ + /* level */ LogLevel, + /* tags */ string[], + /* message */ string | null, + /* data */ string[] | null, +]; + +export type LogMessage = JsonRpcCall & { + method: 'log'; + params: SerializedLogEntry; +}; + +export const lser = ({ + level, + tags, + message, + data, +}: LogEntry): SerializedLogEntry => [ + level, + tags, + message ?? null, + data?.map(stringify) ?? null, +]; + +export const lunser = (params: SerializedLogEntry): LogEntry => { + const [level, tags, message, data] = params; + const entry: LogEntry = { level, tags }; + if (message !== null) { + entry.message = message; + } + if (data !== null) { + entry.data = data.map((datum) => JSON.parse(datum)); + } + return entry; +}; + +export const isLogMessage = (message: JsonRpcMessage): message is LogMessage => + isJsonRpcCall(message) && message.method === 'log'; diff --git a/packages/logger/src/transports.test.ts b/packages/logger/src/transports.test.ts index 414743205..80704ffe5 100644 --- a/packages/logger/src/transports.test.ts +++ b/packages/logger/src/transports.test.ts @@ -1,3 +1,4 @@ +import type { JsonRpcMessage } from '@metamask/kernel-utils'; import type { DuplexStream } from '@metamask/streams'; import { describe, expect, it, vi } from 'vitest'; @@ -31,9 +32,15 @@ describe('makeStreamTransport', () => { const logEntry = makeLogEntry('info'); const mockStream = { write: vi.fn().mockResolvedValue(undefined), - } as unknown as DuplexStream; + } as unknown as DuplexStream; const streamTransport = makeStreamTransport(mockStream); streamTransport(logEntry); - expect(mockStream.write).toHaveBeenCalledWith(logEntry); + expect(mockStream.write).toHaveBeenCalledWith( + expect.objectContaining({ + method: 'log', + params: expect.any(Array), + jsonrpc: '2.0', + }), + ); }); }); diff --git a/packages/logger/src/transports.ts b/packages/logger/src/transports.ts index e04d68eb8..da86fe65f 100644 --- a/packages/logger/src/transports.ts +++ b/packages/logger/src/transports.ts @@ -1,6 +1,8 @@ +import type { JsonRpcMessage } from '@metamask/kernel-utils'; import type { DuplexStream } from '@metamask/streams'; -import type { Transport, LogEntry } from './types.ts'; +import { lser } from './stream.ts'; +import type { Transport } from './types.ts'; /** * The console transport for the logger. @@ -24,9 +26,11 @@ export const consoleTransport: Transport = (entry) => { * @returns A transport function that writes to the stream. */ export const makeStreamTransport = ( - stream: DuplexStream, + stream: DuplexStream, ): Transport => { return (entry) => { - stream.write(entry).catch(console.debug); + stream + .write({ method: 'log', params: lser(entry), jsonrpc: '2.0' }) + .catch(console.debug); }; }; diff --git a/yarn.lock b/yarn.lock index 7611b8e67..c33f7e059 100644 --- a/yarn.lock +++ b/yarn.lock @@ -2230,6 +2230,7 @@ __metadata: "@metamask/eslint-config": "npm:^14.0.0" "@metamask/eslint-config-nodejs": "npm:^14.0.0" "@metamask/eslint-config-typescript": "npm:^14.0.0" + "@metamask/kernel-utils": "workspace:^" "@metamask/streams": "workspace:^" "@ocap/test-utils": "workspace:^" "@ts-bridge/cli": "npm:^0.6.3" From f24a121634aff9f7c9fad6a6265a428dce8d48a4 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Thu, 1 May 2025 09:43:46 -0400 Subject: [PATCH 02/26] feat(logger): Add stream splitter --- packages/logger/package.json | 3 +- packages/logger/src/index.test.ts | 1 + packages/logger/src/index.ts | 1 + packages/logger/src/stream.test.ts | 64 ++++++++++++++++++++++++++++-- packages/logger/src/stream.ts | 37 +++++++++++++++++ yarn.lock | 1 + 6 files changed, 102 insertions(+), 5 deletions(-) diff --git a/packages/logger/package.json b/packages/logger/package.json index 433e384a5..5f0fe7c2a 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -57,7 +57,8 @@ }, "dependencies": { "@metamask/kernel-utils": "workspace:^", - "@metamask/streams": "workspace:^" + "@metamask/streams": "workspace:^", + "@metamask/utils": "^11.4.0" }, "devDependencies": { "@arethetypeswrong/cli": "^0.17.4", diff --git a/packages/logger/src/index.test.ts b/packages/logger/src/index.test.ts index f809975e9..bf00d47d0 100644 --- a/packages/logger/src/index.test.ts +++ b/packages/logger/src/index.test.ts @@ -9,6 +9,7 @@ describe('index', () => { 'Logger', 'consoleTransport', 'makeStreamTransport', + 'splitLoggerStream', ]), ); }); diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index b2b7772fc..47ede2163 100644 --- a/packages/logger/src/index.ts +++ b/packages/logger/src/index.ts @@ -1,2 +1,3 @@ export { Logger } from './logger.ts'; export { consoleTransport, makeStreamTransport } from './transports.ts'; +export { splitLoggerStream } from './stream.ts'; diff --git a/packages/logger/src/stream.test.ts b/packages/logger/src/stream.test.ts index 9b1c83657..d067126c7 100644 --- a/packages/logger/src/stream.test.ts +++ b/packages/logger/src/stream.test.ts @@ -1,6 +1,23 @@ -import { describe, it, expect } from 'vitest'; +import type { JsonRpcMessage } from '@metamask/kernel-utils'; +import type { DuplexStream } from '@metamask/streams'; +import { vi, describe, it, expect } from 'vitest'; -import { isLogMessage, lser, lunser } from './stream.ts'; +import { + isKernelMessage, + isLogMessage, + isLoggerMessage, + lser, + lunser, + splitLoggerStream, +} from './stream.ts'; + +const mocks = vi.hoisted(() => ({ + split: vi.fn((a) => [a, a]), +})); + +vi.mock('@ocap/streams', () => ({ + split: mocks.split, +})); describe('serialization', () => { it.each` @@ -27,9 +44,10 @@ describe('serialization', () => { }); }); +const validParams = ['info', ['test']]; +const unserializableParams = [() => undefined]; + describe('isLogMessage', () => { - const validParams = ['info', ['test'], 'test', ['test']]; - const unserializableParams = [() => undefined]; it.each` description | value | expectation ${'valid params'} | ${{ method: 'log', params: validParams, jsonrpc: '2.0' }} | ${true} @@ -39,3 +57,41 @@ describe('isLogMessage', () => { expect(isLogMessage(value)).toBe(expectation); }); }); + +describe('isKernelMessage', () => { + it.each` + description | value | expectation + ${'kernel method'} | ${{ method: 'ping', params: null, id: null, jsonrpc: '2.0' }} | ${true} + ${'logger method'} | ${{ method: 'log', params: validParams, id: null, jsonrpc: '2.0' }} | ${false} + `('returns $expectation for $description', ({ value, expectation }) => { + expect(isKernelMessage(value)).toBe(expectation); + }); +}); + +describe('isLoggerMessage', () => { + it.each` + description | value | expectation + ${'valid params'} | ${{ method: 'log', params: validParams, id: null, jsonrpc: '2.0' }} | ${true} + ${'unserializable params'} | ${{ method: 'log', params: unserializableParams, id: null, jsonrpc: '2.0' }} | ${false} + ${'invalid method'} | ${{ method: 'ping', params: null, id: null, jsonrpc: '2.0' }} | ${false} + `('returns $expectation for $description', ({ value, expectation }) => { + expect(isLoggerMessage(value)).toBe(expectation); + }); +}); + +describe('splitLoggerStream', () => { + it('splits a stream into a kernel stream and a logger stream', () => { + const stream = { + [Symbol.iterator]: vi.fn(() => stream), + next: vi.fn(() => ({ done: true, value: undefined })), + } as unknown as DuplexStream; + const { kernelStream, loggerStream } = splitLoggerStream(stream); + expect(mocks.split).toHaveBeenCalledWith( + stream, + expect.any(Function), + expect.any(Function), + ); + expect(kernelStream).toStrictEqual(stream); + expect(loggerStream).toStrictEqual(stream); + }); +}); diff --git a/packages/logger/src/stream.ts b/packages/logger/src/stream.ts index 8eede4174..ede9e62a1 100644 --- a/packages/logger/src/stream.ts +++ b/packages/logger/src/stream.ts @@ -1,5 +1,9 @@ import { isJsonRpcCall, stringify } from '@metamask/kernel-utils'; import type { JsonRpcCall, JsonRpcMessage } from '@metamask/kernel-utils'; +import { split } from '@metamask/streams'; +import type { DuplexStream } from '@metamask/streams'; +import { isJsonRpcRequest } from '@metamask/utils'; +import type { JsonRpcRequest } from '@metamask/utils'; import type { LogEntry, LogLevel } from './types.ts'; @@ -41,3 +45,36 @@ export const lunser = (params: SerializedLogEntry): LogEntry => { export const isLogMessage = (message: JsonRpcMessage): message is LogMessage => isJsonRpcCall(message) && message.method === 'log'; + +export const isLoggerMessage = ( + message: JsonRpcMessage, +): message is JsonRpcRequest & { method: 'log' } => + isJsonRpcRequest(message) && message.method === 'log'; + +export const isKernelMessage = ( + message: JsonRpcMessage, +): message is JsonRpcRequest => !isLoggerMessage(message); + +/** + * Splits a stream into a kernel stream and a logger stream. + * + * @param stream - The stream to split. + * @returns An object containing the kernel stream and the logger stream. + */ + +export const splitLoggerStream = ( + stream: DuplexStream, +): { + kernelStream: DuplexStream; + loggerStream: DuplexStream; +} => { + const [kernelStream, loggerStream] = split( + stream, + isKernelMessage, + isLoggerMessage, + ) as [ + DuplexStream, + DuplexStream, + ]; + return { kernelStream, loggerStream }; +}; diff --git a/yarn.lock b/yarn.lock index c33f7e059..97c1c2491 100644 --- a/yarn.lock +++ b/yarn.lock @@ -2232,6 +2232,7 @@ __metadata: "@metamask/eslint-config-typescript": "npm:^14.0.0" "@metamask/kernel-utils": "workspace:^" "@metamask/streams": "workspace:^" + "@metamask/utils": "npm:^11.4.0" "@ocap/test-utils": "workspace:^" "@ts-bridge/cli": "npm:^0.6.3" "@ts-bridge/shims": "npm:^0.1.1" From 6168b978a2cb677b4bbdf847ad0403388eba79bc Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Thu, 1 May 2025 09:45:25 -0400 Subject: [PATCH 03/26] feat(kernel): VatSupervisor uses logger --- packages/kernel-test/package.json | 1 + packages/kernel-test/src/supervisor.test.ts | 4 +++ .../ocap-kernel/src/VatSupervisor.test.ts | 28 +++++++++++++------ packages/ocap-kernel/src/VatSupervisor.ts | 15 ++++++++-- yarn.lock | 1 + 5 files changed, 37 insertions(+), 12 deletions(-) diff --git a/packages/kernel-test/package.json b/packages/kernel-test/package.json index fc3005538..cf9d516f0 100644 --- a/packages/kernel-test/package.json +++ b/packages/kernel-test/package.json @@ -56,6 +56,7 @@ "@metamask/kernel-shims": "workspace:^", "@metamask/kernel-store": "workspace:^", "@metamask/kernel-utils": "workspace:^", + "@metamask/logger": "workspace:^", "@metamask/ocap-kernel": "workspace:^", "@metamask/streams": "workspace:^", "@metamask/utils": "^11.4.0", diff --git a/packages/kernel-test/src/supervisor.test.ts b/packages/kernel-test/src/supervisor.test.ts index c055f42fc..39f80fdcf 100644 --- a/packages/kernel-test/src/supervisor.test.ts +++ b/packages/kernel-test/src/supervisor.test.ts @@ -1,6 +1,7 @@ import '@metamask/kernel-shims/endoify'; import { delay } from '@metamask/kernel-utils'; import type { JsonRpcMessage } from '@metamask/kernel-utils'; +import { Logger } from '@metamask/logger'; import type { VatConfig } from '@metamask/ocap-kernel'; import { VatSupervisor, kser } from '@metamask/ocap-kernel'; import { readFile } from 'fs/promises'; @@ -10,6 +11,8 @@ import { describe, it, expect } from 'vitest'; import { getBundleSpec } from './utils.ts'; import { TestDuplexStream } from '../../streams/test/stream-mocks.ts'; +const logger = new Logger('test'); + const makeVatSupervisor = async ({ dispatch = () => undefined, vatPowers, @@ -26,6 +29,7 @@ const makeVatSupervisor = async ({ supervisor: new VatSupervisor({ id: 'test-id', kernelStream, + logger, vatPowers, // eslint-disable-next-line n/no-unsupported-features/node-builtins fetchBlob: async (url: string): Promise => { diff --git a/packages/ocap-kernel/src/VatSupervisor.test.ts b/packages/ocap-kernel/src/VatSupervisor.test.ts index 01b3d9067..d01c425bd 100644 --- a/packages/ocap-kernel/src/VatSupervisor.test.ts +++ b/packages/ocap-kernel/src/VatSupervisor.test.ts @@ -1,5 +1,6 @@ import { delay, isJsonRpcMessage } from '@metamask/kernel-utils'; import type { JsonRpcMessage } from '@metamask/kernel-utils'; +import { Logger } from '@metamask/logger'; import { rpcErrors } from '@metamask/rpc-errors'; import '@ocap/test-utils'; import { TestDuplexStream } from '@ocap/test-utils/streams'; @@ -21,10 +22,15 @@ vi.mock('@agoric/swingset-liveslots', () => ({ })), })); -const makeVatSupervisor = async ( - dispatch?: (input: unknown) => void | Promise, - vatPowers?: Record, -): Promise<{ +const makeVatSupervisor = async ({ + dispatch, + logger, + vatPowers, +}: { + dispatch?: (input: unknown) => void | Promise; + logger?: Logger; + vatPowers?: Record; +} = {}): Promise<{ supervisor: VatSupervisor; stream: TestDuplexStream; }> => { @@ -36,6 +42,7 @@ const makeVatSupervisor = async ( supervisor: new VatSupervisor({ id: 'test-id', kernelStream, + logger: logger ?? new Logger(), vatPowers: vatPowers ?? {}, }), stream: kernelStream, @@ -51,11 +58,14 @@ describe('VatSupervisor', () => { }); it('throws if the stream throws', async () => { - const { supervisor, stream } = await makeVatSupervisor(); - const consoleErrorSpy = vi.spyOn(console, 'error'); + const logger = { + error: vi.fn(), + subLogger: vi.fn(() => logger), + } as unknown as Logger; + const { supervisor, stream } = await makeVatSupervisor({ logger }); await stream.receiveInput(NaN); await delay(10); - expect(consoleErrorSpy).toHaveBeenCalledWith( + expect(logger.error).toHaveBeenCalledWith( `Unexpected read error from VatSupervisor "${supervisor.id}"`, expect.any(Error), ); @@ -65,7 +75,7 @@ describe('VatSupervisor', () => { describe('handleMessage', () => { it('responds with an error for unknown methods', async () => { const dispatch = vi.fn(); - const { stream } = await makeVatSupervisor(dispatch); + const { stream } = await makeVatSupervisor({ dispatch }); await stream.receiveInput({ id: 'v0:0', @@ -87,7 +97,7 @@ describe('VatSupervisor', () => { it('handles "ping" requests', async () => { const dispatch = vi.fn(); - const { stream } = await makeVatSupervisor(dispatch); + const { stream } = await makeVatSupervisor({ dispatch }); await stream.receiveInput({ id: 'v0:0', diff --git a/packages/ocap-kernel/src/VatSupervisor.ts b/packages/ocap-kernel/src/VatSupervisor.ts index e65cea95c..06414cadb 100644 --- a/packages/ocap-kernel/src/VatSupervisor.ts +++ b/packages/ocap-kernel/src/VatSupervisor.ts @@ -12,6 +12,7 @@ import { RpcClient, RpcService } from '@metamask/kernel-rpc-methods'; import type { VatKVStore, VatCheckpoint } from '@metamask/kernel-store'; import { waitUntilQuiescent } from '@metamask/kernel-utils'; import type { JsonRpcMessage } from '@metamask/kernel-utils'; +import type { Logger } from '@metamask/logger'; import { serializeError } from '@metamask/rpc-errors'; import type { DuplexStream } from '@metamask/streams'; import { isJsonRpcRequest, isJsonRpcResponse } from '@metamask/utils'; @@ -34,6 +35,7 @@ export type FetchBlob = (bundleURL: string) => Promise; type SupervisorConstructorProps = { id: VatId; kernelStream: DuplexStream; + logger: Logger; vatPowers?: Record | undefined; fetchBlob?: FetchBlob; }; @@ -49,6 +51,9 @@ export class VatSupervisor { /** Communications channel between this vat and the kernel */ readonly #kernelStream: DuplexStream; + /** The logger for this vat */ + readonly #logger: Logger; + /** RPC client for sending syscall requests to the kernel */ readonly #rpcClient: RpcClient; @@ -79,17 +84,20 @@ export class VatSupervisor { * @param params - Named constructor parameters. * @param params.id - The id of the vat being supervised. * @param params.kernelStream - Communications channel connected to the kernel. + * @param params.logger - The logger for this vat. * @param params.vatPowers - The external capabilities for this vat. * @param params.fetchBlob - Function to fetch the user code bundle for this vat. */ constructor({ id, kernelStream, + logger, vatPowers, fetchBlob, }: SupervisorConstructorProps) { this.id = id; this.#kernelStream = kernelStream; + this.#logger = logger; this.#vatPowers = vatPowers ?? {}; this.#dispatch = null; const defaultFetchBlob: FetchBlob = async (bundleURL: string) => @@ -102,6 +110,7 @@ export class VatSupervisor { await this.#kernelStream.write(request); }, `${this.id}:`, + this.#logger.subLogger({ tags: ['rpc-client'] }), ); this.#rpcService = new RpcService(vatHandlers, { @@ -112,7 +121,7 @@ export class VatSupervisor { Promise.all([ this.#kernelStream.drain(this.#handleMessage.bind(this)), ]).catch(async (error) => { - console.error( + this.#logger.error( `Unexpected read error from VatSupervisor "${this.id}"`, error, ); @@ -231,7 +240,7 @@ export class VatSupervisor { }); const workerEndowments = { - console, + console: this.#logger.subLogger({ tags: ['vat-worker'] }), assert: globalThis.assert, }; @@ -260,7 +269,7 @@ export class VatSupervisor { this.#vatPowers, liveSlotsOptions, gcTools, - console, + this.#logger.subLogger({ tags: ['liveslots'] }), buildVatNamespace, ); diff --git a/yarn.lock b/yarn.lock index 97c1c2491..e82902788 100644 --- a/yarn.lock +++ b/yarn.lock @@ -3029,6 +3029,7 @@ __metadata: "@metamask/kernel-shims": "workspace:^" "@metamask/kernel-store": "workspace:^" "@metamask/kernel-utils": "workspace:^" + "@metamask/logger": "workspace:^" "@metamask/ocap-kernel": "workspace:^" "@metamask/streams": "workspace:^" "@metamask/utils": "npm:^11.4.0" From f516c6c24755b275dea86ea423ec3aa3c0a2b3e7 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Tue, 29 Apr 2025 17:31:25 -0400 Subject: [PATCH 04/26] feat(nodejs): Use stream transport in vat worker --- packages/nodejs/src/vat/streams.test.ts | 61 +++++++++++++-------- packages/nodejs/src/vat/streams.ts | 19 +++++-- packages/nodejs/src/vat/vat-worker.ts | 29 +++++----- packages/nodejs/test/workers/stream-sync.js | 7 ++- 4 files changed, 71 insertions(+), 45 deletions(-) diff --git a/packages/nodejs/src/vat/streams.test.ts b/packages/nodejs/src/vat/streams.test.ts index b61fdf83d..689a0150f 100644 --- a/packages/nodejs/src/vat/streams.test.ts +++ b/packages/nodejs/src/vat/streams.test.ts @@ -1,45 +1,60 @@ import '@ocap/test-utils/mock-endoify'; -import { describe, expect, it, vi } from 'vitest'; +import { beforeEach, describe, expect, it, vi } from 'vitest'; + +const mocks = vi.hoisted(() => { + const synchronize = vi.fn().mockResolvedValue(true); + + return { + synchronize, + NodeWorkerDuplexStream: vi.fn(() => ({ synchronize })), + split: vi.fn((a) => [a, a]), + parentPort: {}, + }; +}); const doMockParentPort = (value: unknown): void => { vi.doMock('node:worker_threads', () => ({ parentPort: value, })); - vi.resetModules(); }; vi.mock('@metamask/streams', () => ({ - NodeWorkerDuplexStream: vi.fn(), + NodeWorkerDuplexStream: mocks.NodeWorkerDuplexStream, + split: mocks.split, })); -describe('getPort', () => { - it('returns a port', async () => { - const mockParentPort = {}; - doMockParentPort(mockParentPort); +describe('vat/streams', () => { + beforeEach(vi.resetModules); - const { getPort } = await import('./streams.ts'); - const port = getPort(); + describe('getPort', () => { + it('returns a port', async () => { + doMockParentPort(mocks.parentPort); - expect(port).toStrictEqual(mockParentPort); - }, 4000); // Extra time is needed when running yarn test from monorepo root. + const { getPort } = await import('./streams.ts'); + const port = getPort(); - it('throws if parentPort is not defined', async () => { - doMockParentPort(undefined); + expect(port).toStrictEqual(mocks.parentPort); + }, 4000); // Extra time is needed when running yarn test from monorepo root. - const { getPort } = await import('./streams.ts'); + it('throws if parentPort is not defined', async () => { + doMockParentPort(undefined); - expect(getPort).toThrow(/parentPort/u); + const { getPort } = await import('./streams.ts'); + + expect(getPort).toThrow(/parentPort/u); + }); }); -}); -describe('makeKernelStream', () => { - it('returns a NodeWorkerDuplexStream', async () => { - doMockParentPort(new MessageChannel().port1); + describe('makeStreams', () => { + it('returns two NodeWorkerDuplexStreams', async () => { + doMockParentPort(mocks.parentPort); + + const { makeStreams } = await import('./streams.ts'); + const { kernelStream, loggerStream } = await makeStreams(); - const { NodeWorkerDuplexStream } = await import('@metamask/streams'); - const { makeKernelStream } = await import('./streams.ts'); - const kernelStream = makeKernelStream(); - expect(kernelStream).toBeInstanceOf(NodeWorkerDuplexStream); + expect(kernelStream).toHaveProperty('synchronize', mocks.synchronize); + expect(loggerStream).toHaveProperty('synchronize', mocks.synchronize); + }); }); }); diff --git a/packages/nodejs/src/vat/streams.ts b/packages/nodejs/src/vat/streams.ts index 1bb5ecb51..3ae177c3e 100644 --- a/packages/nodejs/src/vat/streams.ts +++ b/packages/nodejs/src/vat/streams.ts @@ -1,5 +1,6 @@ import { isJsonRpcMessage } from '@metamask/kernel-utils'; import type { JsonRpcMessage } from '@metamask/kernel-utils'; +import { splitLoggerStream } from '@metamask/logger'; import { NodeWorkerDuplexStream } from '@metamask/streams'; import { parentPort } from 'node:worker_threads'; import type { MessagePort as NodePort } from 'node:worker_threads'; @@ -17,18 +18,26 @@ export function getPort(): NodePort { return parentPort; } +type VatWorkerStream = NodeWorkerDuplexStream; + /** * When called from within Node.js worker, returns a DuplexStream which * communicates over the parentPort. * * @returns A NodeWorkerDuplexStream */ -export function makeKernelStream(): NodeWorkerDuplexStream< - JsonRpcMessage, - JsonRpcMessage -> { - return new NodeWorkerDuplexStream( +export async function makeStreams(): Promise<{ + kernelStream: VatWorkerStream; + loggerStream: VatWorkerStream; +}> { + const stream = new NodeWorkerDuplexStream( getPort(), isJsonRpcMessage, ); + + const { kernelStream, loggerStream } = splitLoggerStream(stream); + + await stream.synchronize(); + + return { kernelStream, loggerStream }; } diff --git a/packages/nodejs/src/vat/vat-worker.ts b/packages/nodejs/src/vat/vat-worker.ts index a2bcf730d..5d38c642f 100644 --- a/packages/nodejs/src/vat/vat-worker.ts +++ b/packages/nodejs/src/vat/vat-worker.ts @@ -1,24 +1,18 @@ import '@metamask/kernel-shims/endoify'; -import { Logger } from '@metamask/logger'; +import { Logger, makeStreamTransport } from '@metamask/logger'; import type { VatId } from '@metamask/ocap-kernel'; import { VatSupervisor } from '@metamask/ocap-kernel'; import fs from 'node:fs/promises'; import url from 'node:url'; -import { makeKernelStream } from './streams.ts'; +import { makeStreams } from './streams.ts'; -const vatId = process.env.NODE_VAT_ID as VatId; const processLogger = new Logger('nodejs-vat-worker'); /* eslint-disable n/no-unsupported-features/node-builtins */ -if (vatId) { - const vatLogger = processLogger.subLogger(vatId); - main(vatLogger).catch(vatLogger.error); -} else { - processLogger.error('no vatId set for env variable NODE_VAT_ID'); -} +main().catch(processLogger.error); /** * Fetch a blob of bytes from a URL @@ -40,16 +34,23 @@ async function fetchBlob(blobURL: string): Promise { /** * The main function for the vat worker. - * - * @param _logger - The logger to use for logging. (currently unused) */ -async function main(_logger: Logger): Promise { - const kernelStream = makeKernelStream(); - await kernelStream.synchronize(); +async function main(): Promise { + const vatId = process.env.NODE_VAT_ID as VatId; + if (!vatId) { + throw new Error('no vatId set for env variable NODE_VAT_ID'); + } + const { kernelStream, loggerStream } = await makeStreams(); + const logger = processLogger.subLogger({ + tags: [vatId], + transports: [makeStreamTransport(loggerStream)], + }); // eslint-disable-next-line no-void void new VatSupervisor({ id: vatId, kernelStream, fetchBlob, + // TODO: supervisor should accept a logger argument + vatPowers: { logger }, }); } diff --git a/packages/nodejs/test/workers/stream-sync.js b/packages/nodejs/test/workers/stream-sync.js index 9a8f74e5b..cb2235d06 100644 --- a/packages/nodejs/test/workers/stream-sync.js +++ b/packages/nodejs/test/workers/stream-sync.js @@ -1,5 +1,5 @@ import '../../dist/env/endoify.mjs'; -import { makeKernelStream } from '../../dist/vat/streams.mjs'; +import { makeStreams } from '../../dist/vat/streams.mjs'; main().catch(console.error); @@ -8,6 +8,7 @@ main().catch(console.error); * No supervisor is created, but the stream is synchronized for comms testing. */ async function main() { - const stream = makeKernelStream(); - await stream.synchronize(); + const { kernelStream, loggerStream } = makeStreams(); + await kernelStream.synchronize(); + await loggerStream.synchronize(); } From 8fa4283c0318430d5b133e6ec3884beb84213173 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Thu, 1 May 2025 13:25:17 -0400 Subject: [PATCH 05/26] feat(k,e,n): VatSupervisor uses logger --- packages/extension/src/iframe.ts | 1 + packages/nodejs/src/vat/streams.ts | 11 +++++------ packages/nodejs/src/vat/vat-worker.ts | 3 +-- 3 files changed, 7 insertions(+), 8 deletions(-) diff --git a/packages/extension/src/iframe.ts b/packages/extension/src/iframe.ts index a204057fe..42253dbce 100644 --- a/packages/extension/src/iframe.ts +++ b/packages/extension/src/iframe.ts @@ -32,6 +32,7 @@ async function main(): Promise { new VatSupervisor({ id: vatId, kernelStream, + logger: logger.subLogger(vatId), }); logger.info('VatSupervisor initialized with vatId:', vatId); diff --git a/packages/nodejs/src/vat/streams.ts b/packages/nodejs/src/vat/streams.ts index 3ae177c3e..0a4d5995e 100644 --- a/packages/nodejs/src/vat/streams.ts +++ b/packages/nodejs/src/vat/streams.ts @@ -2,6 +2,7 @@ import { isJsonRpcMessage } from '@metamask/kernel-utils'; import type { JsonRpcMessage } from '@metamask/kernel-utils'; import { splitLoggerStream } from '@metamask/logger'; import { NodeWorkerDuplexStream } from '@metamask/streams'; +import type { DuplexStream } from '@metamask/streams'; import { parentPort } from 'node:worker_threads'; import type { MessagePort as NodePort } from 'node:worker_threads'; @@ -18,19 +19,17 @@ export function getPort(): NodePort { return parentPort; } -type VatWorkerStream = NodeWorkerDuplexStream; - /** * When called from within Node.js worker, returns a DuplexStream which * communicates over the parentPort. * - * @returns A NodeWorkerDuplexStream + * @returns A pair of NodeWorkerDuplexStreams */ export async function makeStreams(): Promise<{ - kernelStream: VatWorkerStream; - loggerStream: VatWorkerStream; + kernelStream: DuplexStream; + loggerStream: DuplexStream; }> { - const stream = new NodeWorkerDuplexStream( + const stream = new NodeWorkerDuplexStream( getPort(), isJsonRpcMessage, ); diff --git a/packages/nodejs/src/vat/vat-worker.ts b/packages/nodejs/src/vat/vat-worker.ts index 5d38c642f..a90b58ba3 100644 --- a/packages/nodejs/src/vat/vat-worker.ts +++ b/packages/nodejs/src/vat/vat-worker.ts @@ -49,8 +49,7 @@ async function main(): Promise { void new VatSupervisor({ id: vatId, kernelStream, + logger, fetchBlob, - // TODO: supervisor should accept a logger argument - vatPowers: { logger }, }); } From 2f4a3ee5ff49c1410c1b31e4f4a36dca8cc4baed Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Thu, 1 May 2025 14:40:56 -0400 Subject: [PATCH 06/26] feat(logger): Add makeArrayTransport --- packages/logger/src/index.test.ts | 1 + packages/logger/src/index.ts | 6 +++++- packages/logger/src/transports.test.ts | 16 +++++++++++++++- packages/logger/src/transports.ts | 8 ++++++++ 4 files changed, 29 insertions(+), 2 deletions(-) diff --git a/packages/logger/src/index.test.ts b/packages/logger/src/index.test.ts index bf00d47d0..e4cfc4d21 100644 --- a/packages/logger/src/index.test.ts +++ b/packages/logger/src/index.test.ts @@ -8,6 +8,7 @@ describe('index', () => { expect.arrayContaining([ 'Logger', 'consoleTransport', + 'makeArrayTransport', 'makeStreamTransport', 'splitLoggerStream', ]), diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index 47ede2163..5f4adda81 100644 --- a/packages/logger/src/index.ts +++ b/packages/logger/src/index.ts @@ -1,3 +1,7 @@ export { Logger } from './logger.ts'; -export { consoleTransport, makeStreamTransport } from './transports.ts'; +export { + consoleTransport, + makeArrayTransport, + makeStreamTransport, +} from './transports.ts'; export { splitLoggerStream } from './stream.ts'; diff --git a/packages/logger/src/transports.test.ts b/packages/logger/src/transports.test.ts index 80704ffe5..373712e2c 100644 --- a/packages/logger/src/transports.test.ts +++ b/packages/logger/src/transports.test.ts @@ -3,7 +3,11 @@ import type { DuplexStream } from '@metamask/streams'; import { describe, expect, it, vi } from 'vitest'; import { logLevels } from './constants.ts'; -import { consoleTransport, makeStreamTransport } from './transports.ts'; +import { + consoleTransport, + makeArrayTransport, + makeStreamTransport, +} from './transports.ts'; import type { LogEntry, LogLevel } from './types.ts'; const makeLogEntry = (level: LogLevel): LogEntry => ({ @@ -44,3 +48,13 @@ describe('makeStreamTransport', () => { ); }); }); + +describe('makeArrayTransport', () => { + it('writes to the array', () => { + const target: LogEntry[] = []; + const arrayTransport = makeArrayTransport(target); + const logEntry = makeLogEntry('info'); + arrayTransport(logEntry); + expect(target).toStrictEqual([logEntry]); + }); +}); diff --git a/packages/logger/src/transports.ts b/packages/logger/src/transports.ts index da86fe65f..020c7c928 100644 --- a/packages/logger/src/transports.ts +++ b/packages/logger/src/transports.ts @@ -34,3 +34,11 @@ export const makeStreamTransport = ( .catch(console.debug); }; }; + +export const makeArrayTransport = ( + target: Parameters[0][], +): Transport => { + return (entry) => { + target.push(entry); + }; +}; From 4a2bfb51967f916431b9d56939a835854ad39e90 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Thu, 1 May 2025 14:42:34 -0400 Subject: [PATCH 07/26] types(logger): Expose LogEntry type --- packages/logger/src/index.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index 5f4adda81..5c045438d 100644 --- a/packages/logger/src/index.ts +++ b/packages/logger/src/index.ts @@ -5,3 +5,4 @@ export { makeStreamTransport, } from './transports.ts'; export { splitLoggerStream } from './stream.ts'; +export type { LogEntry } from './types.ts'; From 284978e7f3a83327036d9ad3ea9e36c95aaa659f Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Thu, 1 May 2025 15:50:23 -0400 Subject: [PATCH 08/26] feat(kernel-test): use array transport --- packages/kernel-test/src/liveslots.test.ts | 25 +++++++++++----------- packages/kernel-test/src/resume.test.ts | 10 ++++++--- packages/kernel-test/src/utils.ts | 20 +++++++++++++++++ packages/kernel-test/src/vatstore.test.ts | 10 +++++++-- 4 files changed, 48 insertions(+), 17 deletions(-) diff --git a/packages/kernel-test/src/liveslots.test.ts b/packages/kernel-test/src/liveslots.test.ts index 38171b58c..e45047db0 100644 --- a/packages/kernel-test/src/liveslots.test.ts +++ b/packages/kernel-test/src/liveslots.test.ts @@ -9,15 +9,8 @@ import { } from 'node:worker_threads'; import { beforeEach, describe, expect, it } from 'vitest'; -import { extractVatLogs, getBundleSpec } from './utils.ts'; - -const origStdoutWrite = process.stdout.write.bind(process.stdout); -let buffered: string = ''; -// @ts-expect-error Some type def used by lint is just wrong (compiler likes it ok, but lint whines) -process.stdout.write = (buffer: string, encoding, callback): void => { - buffered += buffer; - origStdoutWrite(buffer, encoding, callback); -}; +import { getBundleSpec, makeTestLogger } from './utils.ts'; +import type { TestLogger } from './utils.ts'; const makeTestSubcluster = ( testName: string, @@ -49,14 +42,17 @@ const makeTestSubcluster = ( }); describe('liveslots promise handling', () => { + let logger: TestLogger; let kernel: Kernel; beforeEach(async () => { const kernelPort: NodeMessagePort = new NodeMessageChannel().port1; + logger = makeTestLogger(); kernel = await makeKernel({ port: kernelPort, resetStorage: true, dbFilename: ':memory:', + logger, }); }); @@ -72,17 +68,22 @@ describe('liveslots promise handling', () => { bundleName: string, testName: string, ): Promise<[unknown, string[]]> { - buffered = ''; const bundleSpec = getBundleSpec(bundleName); const bootstrapResultRaw = await kernel.launchSubcluster( makeTestSubcluster(testName, bundleSpec), ); await waitUntilQuiescent(1000); - const vatLogs = extractVatLogs(buffered); + const vatLogs = logger.entries.filter((entry) => + entry.message?.includes('::> '), + ); + throw new Error(`vatLogs: ${vatLogs.length}`); if (bootstrapResultRaw === undefined) { throw Error(`this can't happen but eslint is stupid`); } - return [kunser(bootstrapResultRaw), vatLogs]; + return [ + kunser(bootstrapResultRaw), + vatLogs.map((entry) => entry.message ?? ''), + ]; } it('promiseArg1: send promise parameter, resolve after send', async () => { diff --git a/packages/kernel-test/src/resume.test.ts b/packages/kernel-test/src/resume.test.ts index e1d9d149f..72b96618d 100644 --- a/packages/kernel-test/src/resume.test.ts +++ b/packages/kernel-test/src/resume.test.ts @@ -7,6 +7,7 @@ import { extractVatLogs, getBundleSpec, makeKernel, + makeTestLogger, runResume, runTestVats, sortLogs, @@ -112,7 +113,8 @@ describe('restarting vats', async () => { const kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); - const kernel = await makeKernel(kernelDatabase, true); + const logger = makeTestLogger(); + const kernel = await makeKernel(kernelDatabase, true, logger); buffered = ''; const bootstrapResult = await runTestVats(kernel, testSubcluster); expect(bootstrapResult).toBe('bootstrap Alice'); @@ -135,12 +137,14 @@ describe('restarting vats', async () => { const kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); - const kernel1 = await makeKernel(kernelDatabase, true); + const logger1 = makeTestLogger(); + const kernel1 = await makeKernel(kernelDatabase, true, logger1); buffered = ''; const bootstrapResult = await runTestVats(kernel1, testSubcluster); expect(bootstrapResult).toBe('bootstrap Alice'); await waitUntilQuiescent(); - const kernel2 = await makeKernel(kernelDatabase, false); + const logger2 = makeTestLogger(); + const kernel2 = await makeKernel(kernelDatabase, false, logger2); const resumeResultA = await runResume(kernel2, 'ko1'); expect(resumeResultA).toBe('resume Alice'); const resumeResultB = await runResume(kernel2, 'ko2'); diff --git a/packages/kernel-test/src/utils.ts b/packages/kernel-test/src/utils.ts index 46cfb2490..e427a9e47 100644 --- a/packages/kernel-test/src/utils.ts +++ b/packages/kernel-test/src/utils.ts @@ -3,6 +3,7 @@ import type { KernelDatabase } from '@metamask/kernel-store'; import { waitUntilQuiescent } from '@metamask/kernel-utils'; +import { Logger, makeArrayTransport, type LogEntry } from '@metamask/logger'; import { Kernel, kunser } from '@metamask/ocap-kernel'; import type { ClusterConfig } from '@metamask/ocap-kernel'; import { NodeWorkerDuplexStream } from '@metamask/streams'; @@ -65,12 +66,14 @@ export async function runResume( * * @param kernelDatabase - The database that will hold the persistent state. * @param resetStorage - If true, reset the database as part of setting up. + * @param logger - The logger to use for the kernel. * * @returns the new kernel instance. */ export async function makeKernel( kernelDatabase: KernelDatabase, resetStorage: boolean, + logger: Logger, ): Promise { const kernelPort: NodeMessagePort = new NodeMessageChannel().port1; const nodeStream = new NodeWorkerDuplexStream< @@ -84,6 +87,7 @@ export async function makeKernel( kernelDatabase, { resetStorage, + logger, }, ); return kernel; @@ -153,3 +157,19 @@ export function logDatabase(kernelDatabase: KernelDatabase): void { const result = kernelDatabase.executeQuery('SELECT * FROM kv'); console.log(result); } + +export type TestLogger = Logger & { entries: LogEntry[] }; + +/** + * Create a logger that records log entries in an array. + * + * @returns A logger that records log entries in an array. + */ +export const makeTestLogger = (): TestLogger => { + const logEntries: LogEntry[] = []; + const logger = new Logger({ transports: [makeArrayTransport(logEntries)] }); + Object.defineProperty(logger, 'entries', { + get: () => logEntries, + }); + return logger as TestLogger; +}; diff --git a/packages/kernel-test/src/vatstore.test.ts b/packages/kernel-test/src/vatstore.test.ts index 94666a3d2..47c57f3af 100644 --- a/packages/kernel-test/src/vatstore.test.ts +++ b/packages/kernel-test/src/vatstore.test.ts @@ -4,7 +4,12 @@ import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; import type { ClusterConfig } from '@metamask/ocap-kernel'; import { describe, vi, expect, it } from 'vitest'; -import { getBundleSpec, makeKernel, runTestVats } from './utils.ts'; +import { + getBundleSpec, + makeKernel, + makeTestLogger, + runTestVats, +} from './utils.ts'; const makeTestSubcluster = (): ClusterConfig => ({ bootstrap: 'alice', @@ -128,7 +133,8 @@ describe('exercise vatstore', async () => { return result; }, ); - const kernel = await makeKernel(kernelDatabase, true); + const logger = makeTestLogger(); + const kernel = await makeKernel(kernelDatabase, true, logger); await runTestVats(kernel, makeTestSubcluster()); type VSRecord = { key: string; value: string }; const vsContents = kernelDatabase.executeQuery( From 7cbc3f62ed1c89a9f45da2238a45649ead0a9a52 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Thu, 1 May 2025 15:50:53 -0400 Subject: [PATCH 09/26] feat(kernel): thread logger to vat handle --- packages/kernel-test/src/utils.ts | 3 ++- packages/nodejs/src/kernel/make-kernel.ts | 5 +++++ packages/ocap-kernel/src/Kernel.ts | 3 ++- 3 files changed, 9 insertions(+), 2 deletions(-) diff --git a/packages/kernel-test/src/utils.ts b/packages/kernel-test/src/utils.ts index e427a9e47..2d7a9d9aa 100644 --- a/packages/kernel-test/src/utils.ts +++ b/packages/kernel-test/src/utils.ts @@ -3,7 +3,8 @@ import type { KernelDatabase } from '@metamask/kernel-store'; import { waitUntilQuiescent } from '@metamask/kernel-utils'; -import { Logger, makeArrayTransport, type LogEntry } from '@metamask/logger'; +import { Logger, makeArrayTransport } from '@metamask/logger'; +import type { LogEntry } from '@metamask/logger'; import { Kernel, kunser } from '@metamask/ocap-kernel'; import type { ClusterConfig } from '@metamask/ocap-kernel'; import { NodeWorkerDuplexStream } from '@metamask/streams'; diff --git a/packages/nodejs/src/kernel/make-kernel.ts b/packages/nodejs/src/kernel/make-kernel.ts index 20655fbb4..3a7226694 100644 --- a/packages/nodejs/src/kernel/make-kernel.ts +++ b/packages/nodejs/src/kernel/make-kernel.ts @@ -1,4 +1,5 @@ import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; +import { Logger } from '@metamask/logger'; import { Kernel } from '@metamask/ocap-kernel'; import { NodeWorkerDuplexStream } from '@metamask/streams'; import type { JsonRpcRequest, JsonRpcResponse } from '@metamask/utils'; @@ -14,6 +15,7 @@ import { NodejsVatWorkerManager } from './VatWorkerManager.ts'; * @param options.workerFilePath - The path to a file defining each vat worker's routine. * @param options.resetStorage - If true, clear kernel storage as part of setting up the kernel. * @param options.dbFilename - The filename of the SQLite database file. + * @param options.logger - The logger to use for the kernel. * @returns The kernel, initialized. */ export async function makeKernel({ @@ -21,11 +23,13 @@ export async function makeKernel({ workerFilePath, resetStorage = false, dbFilename, + logger, }: { port: NodeMessagePort; workerFilePath?: string; resetStorage?: boolean; dbFilename?: string; + logger?: Logger; }): Promise { const nodeStream = new NodeWorkerDuplexStream< JsonRpcRequest, @@ -43,6 +47,7 @@ export async function makeKernel({ kernelDatabase, { resetStorage, + logger: logger ?? new Logger('ocap-kernel'), }, ); diff --git a/packages/ocap-kernel/src/Kernel.ts b/packages/ocap-kernel/src/Kernel.ts index d970bbd03..ce26453c9 100644 --- a/packages/ocap-kernel/src/Kernel.ts +++ b/packages/ocap-kernel/src/Kernel.ts @@ -83,7 +83,7 @@ export class Kernel { this.#rpcService = new RpcService(kernelHandlers, {}); this.#vats = new Map(); this.#vatWorkerService = vatWorkerService; - this.#logger = options.logger ?? new Logger('[ocap kernel]'); + this.#logger = options.logger ?? new Logger('ocap-kernel'); this.#kernelStore = makeKernelStore(kernelDatabase); if (options.resetStorage) { this.#resetKernelState(); @@ -214,6 +214,7 @@ export class Kernel { vatStream, kernelStore: this.#kernelStore, kernelQueue: this.#kernelQueue, + logger: this.#logger.subLogger(vatId), }); this.#vats.set(vatId, vat); } From adae9c689049376cb5c45f13384c5b5a65fd3900 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Fri, 2 May 2025 10:35:51 -0400 Subject: [PATCH 10/26] feat(kernel): inject split stream to VatHandle logger --- packages/ocap-kernel/src/Kernel.ts | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/packages/ocap-kernel/src/Kernel.ts b/packages/ocap-kernel/src/Kernel.ts index ce26453c9..7ee354d15 100644 --- a/packages/ocap-kernel/src/Kernel.ts +++ b/packages/ocap-kernel/src/Kernel.ts @@ -6,8 +6,9 @@ import { } from '@metamask/kernel-errors'; import { RpcService } from '@metamask/kernel-rpc-methods'; import type { KernelDatabase } from '@metamask/kernel-store'; +import { stringify } from '@metamask/kernel-utils'; import type { JsonRpcCall } from '@metamask/kernel-utils'; -import { Logger } from '@metamask/logger'; +import { Logger, splitLoggerStream } from '@metamask/logger'; import { serializeError } from '@metamask/rpc-errors'; import type { DuplexStream } from '@metamask/streams'; import { hasProperty } from '@metamask/utils'; @@ -207,14 +208,20 @@ export class Kernel { if (this.#vats.has(vatId)) { throw new VatAlreadyExistsError(vatId); } - const vatStream = await this.#vatWorkerService.launch(vatId, vatConfig); + const stream = await this.#vatWorkerService.launch(vatId, vatConfig); + const { kernelStream: vatStream, loggerStream } = splitLoggerStream(stream); + const vatLogger = this.#logger.subLogger(vatId); + vatLogger.injectStream( + loggerStream as unknown as Parameters[0], + (error) => console.error(stringify(error)), + ); const vat = await VatHandle.make({ vatId, vatConfig, vatStream, kernelStore: this.#kernelStore, kernelQueue: this.#kernelQueue, - logger: this.#logger.subLogger(vatId), + logger: vatLogger, }); this.#vats.set(vatId, vat); } From 8b85dfaea8277cb3a15e83705b2dd7a0ed69a5ff Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Fri, 2 May 2025 10:56:47 -0400 Subject: [PATCH 11/26] test(kernel-test): update test setup --- packages/kernel-test/src/exo.test.ts | 32 +++++++------------ .../src/garbage-collection.test.ts | 6 +++- packages/kernel-test/src/liveslots.test.ts | 12 ++----- packages/kernel-test/src/resume.test.ts | 16 +++------- packages/kernel-test/src/utils.ts | 29 +++++++++-------- 5 files changed, 38 insertions(+), 57 deletions(-) diff --git a/packages/kernel-test/src/exo.test.ts b/packages/kernel-test/src/exo.test.ts index b447a9c63..530b9736c 100644 --- a/packages/kernel-test/src/exo.test.ts +++ b/packages/kernel-test/src/exo.test.ts @@ -10,16 +10,10 @@ import { extractVatLogs, getBundleSpec, makeKernel, + makeTestLogger, runTestVats, } from './utils.ts'; - -const origStdoutWrite = process.stdout.write.bind(process.stdout); -let buffered: string = ''; -// @ts-expect-error Some type def used by lint is just wrong (compiler likes it ok, but lint whines) -process.stdout.write = (buffer: string, encoding, callback): void => { - buffered += buffer; - origStdoutWrite(buffer, encoding, callback); -}; +import type { TestLogger } from './utils.ts'; const testSubcluster = { bootstrap: 'exoTest', @@ -38,20 +32,21 @@ describe('virtual objects functionality', async () => { let kernel: Kernel; let kernelDatabase: KernelDatabase; let bootstrapResult: unknown; + let logger: TestLogger; beforeEach(async () => { kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); - kernel = await makeKernel(kernelDatabase, true); - buffered = ''; + logger = makeTestLogger(); + kernel = await makeKernel(kernelDatabase, true, logger); bootstrapResult = await runTestVats(kernel, testSubcluster); await waitUntilQuiescent(100); }); it('successfully creates and uses exo objects and scalar stores', async () => { expect(bootstrapResult).toBe('exo-test-complete'); - const vatLogs = extractVatLogs(buffered); + const vatLogs = extractVatLogs(logger.entries); expect(vatLogs).toStrictEqual([ 'ExoTest: initializing state', 'ExoTest: counter value from baggage: 0', @@ -72,11 +67,10 @@ describe('virtual objects functionality', async () => { }, 30000); it('tests scalar store functionality', async () => { - buffered = ''; const storeResult = await kernel.queueMessage('ko1', 'testScalarStore', []); await waitUntilQuiescent(100); expect(kunser(storeResult)).toBe('scalar-store-tests-complete'); - const vatLogs = extractVatLogs(buffered); + const vatLogs = extractVatLogs(logger.entries); expect(vatLogs).toStrictEqual([ 'ExoTest: Map store size: 3', 'ExoTest: Map store keys: alice, bob, charlie', @@ -87,7 +81,6 @@ describe('virtual objects functionality', async () => { }, 30000); it('can create and use objects through messaging', async () => { - buffered = ''; const counterResult = await kernel.queueMessage('ko1', 'createCounter', [ 42, ]); @@ -123,7 +116,7 @@ describe('virtual objects functionality', async () => { personRef, ]); await waitUntilQuiescent(100); - const vatLogs = extractVatLogs(buffered); + const vatLogs = extractVatLogs(logger.entries); // Verify counter was created and used expect(vatLogs).toStrictEqual([ 'ExoTest: Created new counter with value: 42', @@ -135,11 +128,10 @@ describe('virtual objects functionality', async () => { }, 30000); it('tests exoClass type validation and behavior', async () => { - buffered = ''; const exoClassResult = await kernel.queueMessage('ko1', 'testExoClass', []); await waitUntilQuiescent(100); expect(kunser(exoClassResult)).toBe('exoClass-tests-complete'); - const vatLogs = extractVatLogs(buffered); + const vatLogs = extractVatLogs(logger.entries); expect(vatLogs).toStrictEqual([ 'ExoTest: Counter: 3 + 5 = 8', 'ExoTest: Counter: 8 - 2 = 6', @@ -148,7 +140,6 @@ describe('virtual objects functionality', async () => { }, 30000); it('tests exoClassKit with multiple facets', async () => { - buffered = ''; const exoClassKitResult = await kernel.queueMessage( 'ko1', 'testExoClassKit', @@ -156,7 +147,7 @@ describe('virtual objects functionality', async () => { ); await waitUntilQuiescent(100); expect(kunser(exoClassKitResult)).toBe('exoClassKit-tests-complete'); - const vatLogs = extractVatLogs(buffered); + const vatLogs = extractVatLogs(logger.entries); expect(vatLogs).toStrictEqual([ 'ExoTest: 20°C = 68°F', 'ExoTest: 32°F = 0°C', @@ -165,7 +156,6 @@ describe('virtual objects functionality', async () => { }, 30000); it('tests temperature converter through messaging', async () => { - buffered = ''; // Create a temperature converter starting at 100°C const tempResult = await kernel.queueMessage('ko1', 'createTemperature', [ 100, @@ -204,7 +194,7 @@ describe('virtual objects functionality', async () => { ); expect(kunser(newCelsiusResult)).toBe(0); await waitUntilQuiescent(100); - const vatLogs = extractVatLogs(buffered); + const vatLogs = extractVatLogs(logger.entries); expect(vatLogs).toContain( 'ExoTest: Created temperature converter starting at 100°C', ); diff --git a/packages/kernel-test/src/garbage-collection.test.ts b/packages/kernel-test/src/garbage-collection.test.ts index a70417cfb..37663e62d 100644 --- a/packages/kernel-test/src/garbage-collection.test.ts +++ b/packages/kernel-test/src/garbage-collection.test.ts @@ -14,9 +14,11 @@ import { expect, beforeEach, describe, it } from 'vitest'; import { getBundleSpec, makeKernel, + makeTestLogger, parseReplyBody, runTestVats, } from './utils.ts'; +import type { TestLogger } from './utils.ts'; /** * Make a test subcluster with vats for GC testing @@ -52,13 +54,15 @@ describe('Garbage Collection', () => { let importerKRef: KRef; let exporterVatId: VatId; let importerVatId: VatId; + let logger: TestLogger; beforeEach(async () => { + logger = makeTestLogger(); kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); kernelStore = makeKernelStore(kernelDatabase); - kernel = await makeKernel(kernelDatabase, true); + kernel = await makeKernel(kernelDatabase, true, logger); await runTestVats(kernel, makeTestSubcluster()); const vats = kernel.getVats(); diff --git a/packages/kernel-test/src/liveslots.test.ts b/packages/kernel-test/src/liveslots.test.ts index e45047db0..9da762aa8 100644 --- a/packages/kernel-test/src/liveslots.test.ts +++ b/packages/kernel-test/src/liveslots.test.ts @@ -9,7 +9,7 @@ import { } from 'node:worker_threads'; import { beforeEach, describe, expect, it } from 'vitest'; -import { getBundleSpec, makeTestLogger } from './utils.ts'; +import { extractVatLogs, getBundleSpec, makeTestLogger } from './utils.ts'; import type { TestLogger } from './utils.ts'; const makeTestSubcluster = ( @@ -73,17 +73,11 @@ describe('liveslots promise handling', () => { makeTestSubcluster(testName, bundleSpec), ); await waitUntilQuiescent(1000); - const vatLogs = logger.entries.filter((entry) => - entry.message?.includes('::> '), - ); - throw new Error(`vatLogs: ${vatLogs.length}`); + const vatLogs = extractVatLogs(logger.entries); if (bootstrapResultRaw === undefined) { throw Error(`this can't happen but eslint is stupid`); } - return [ - kunser(bootstrapResultRaw), - vatLogs.map((entry) => entry.message ?? ''), - ]; + return [kunser(bootstrapResultRaw), vatLogs]; } it('promiseArg1: send promise parameter, resolve after send', async () => { diff --git a/packages/kernel-test/src/resume.test.ts b/packages/kernel-test/src/resume.test.ts index 72b96618d..d2f5933a4 100644 --- a/packages/kernel-test/src/resume.test.ts +++ b/packages/kernel-test/src/resume.test.ts @@ -13,14 +13,6 @@ import { sortLogs, } from './utils.ts'; -const origStdoutWrite = process.stdout.write.bind(process.stdout); -let buffered: string = ''; -// @ts-expect-error Some type def used by lint is just wrong (compiler likes it ok, but lint whines) -process.stdout.write = (buffer: string, encoding, callback): void => { - buffered += buffer; - origStdoutWrite(buffer, encoding, callback); -}; - const testSubcluster = { bootstrap: 'alice', forceReset: true, @@ -115,7 +107,6 @@ describe('restarting vats', async () => { }); const logger = makeTestLogger(); const kernel = await makeKernel(kernelDatabase, true, logger); - buffered = ''; const bootstrapResult = await runTestVats(kernel, testSubcluster); expect(bootstrapResult).toBe('bootstrap Alice'); await waitUntilQuiescent(); @@ -129,7 +120,7 @@ describe('restarting vats', async () => { const resumeResultC = await runResume(kernel, 'ko3'); expect(resumeResultC).toBe('resume Carol'); await waitUntilQuiescent(1000); - const vatLogs = extractVatLogs(buffered); + const vatLogs = extractVatLogs(logger.entries); expect(vatLogs).toStrictEqual(reference); }, 30000); @@ -139,7 +130,6 @@ describe('restarting vats', async () => { }); const logger1 = makeTestLogger(); const kernel1 = await makeKernel(kernelDatabase, true, logger1); - buffered = ''; const bootstrapResult = await runTestVats(kernel1, testSubcluster); expect(bootstrapResult).toBe('bootstrap Alice'); await waitUntilQuiescent(); @@ -152,7 +142,9 @@ describe('restarting vats', async () => { const resumeResultC = await runResume(kernel2, 'ko3'); expect(resumeResultC).toBe('resume Carol'); await waitUntilQuiescent(1000); - const vatLogs = extractVatLogs(buffered); + const vatLogs1 = extractVatLogs(logger1.entries); + const vatLogs2 = extractVatLogs(logger2.entries); + const vatLogs = sortLogs([...vatLogs1, ...vatLogs2]); expect(vatLogs).toStrictEqual(reference); }, 30000); }); diff --git a/packages/kernel-test/src/utils.ts b/packages/kernel-test/src/utils.ts index 2d7a9d9aa..1cc5d8d30 100644 --- a/packages/kernel-test/src/utils.ts +++ b/packages/kernel-test/src/utils.ts @@ -120,18 +120,20 @@ export function sortLogs(logs: string[]): string[] { } /** - * Convert a raw output buffer into a list of lines suitable for examination. + * Convert a list of log entries into a list of lines suitable for examination. * - * @param buffer - The raw buffer to convert. + * @param entries - The list of log entries to convert. * - * @returns the relevant contents of `buffer`, massaged for use. + * @returns the relevant contents of `entries`, massaged for use. */ -export function extractVatLogs(buffer: string): string[] { - const result = buffer - .split('\n') - .filter((line: string) => line.startsWith('::> ')) - .map((line: string) => line.slice(4)); - return sortLogs(result); +export function extractVatLogs(entries: LogEntry[]): string[] { + if (entries.length === 0) { + throw new Error('No log entries found'); + } + return entries + .filter((entry) => entry.tags.includes('vat-worker')) + .map((entry) => entry.message ?? '') + .filter(Boolean); } /** @@ -167,10 +169,9 @@ export type TestLogger = Logger & { entries: LogEntry[] }; * @returns A logger that records log entries in an array. */ export const makeTestLogger = (): TestLogger => { - const logEntries: LogEntry[] = []; - const logger = new Logger({ transports: [makeArrayTransport(logEntries)] }); - Object.defineProperty(logger, 'entries', { - get: () => logEntries, + const entries: LogEntry[] = []; + const logger = new Logger({ + transports: [makeArrayTransport(entries)], }); - return logger as TestLogger; + return Object.assign(logger, { entries }); }; From cd6274d46b0c117237053fc87d47d5e0b3abe76b Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Sat, 3 May 2025 12:52:11 -0400 Subject: [PATCH 12/26] feat(logger): Use JsonRpcNotification for streamTransport --- packages/logger/src/logger.test.ts | 4 ++- packages/logger/src/logger.ts | 18 +++++----- packages/logger/src/stream.test.ts | 46 ++++++++++++++------------ packages/logger/src/stream.ts | 19 +++++------ packages/logger/src/transports.test.ts | 13 ++++++-- packages/logger/src/transports.ts | 6 +++- 6 files changed, 60 insertions(+), 46 deletions(-) diff --git a/packages/logger/src/logger.test.ts b/packages/logger/src/logger.test.ts index 177797dbd..b92404654 100644 --- a/packages/logger/src/logger.test.ts +++ b/packages/logger/src/logger.test.ts @@ -132,7 +132,9 @@ describe('Logger', () => { const testTransport = vi.fn(); const logger = new Logger({ transports: [testTransport] }); const stream = { - drain: vi.fn(async (handler) => handler({ params: lser(logEntry) })), + drain: vi.fn(async (handler) => + handler({ params: ['logger', ...lser(logEntry)] }), + ), } as unknown as DuplexStream; logger.injectStream(stream); expect(testTransport).toHaveBeenCalledWith( diff --git a/packages/logger/src/logger.ts b/packages/logger/src/logger.ts index 0cd9c4800..ff71dbec1 100644 --- a/packages/logger/src/logger.ts +++ b/packages/logger/src/logger.ts @@ -52,7 +52,7 @@ import type { DuplexStream } from '@metamask/streams'; import { parseOptions, mergeOptions } from './options.ts'; import { lunser } from './stream.ts'; -import type { LogMessage } from './stream.ts'; +import type { LogMessage, SerializedLogEntry } from './stream.ts'; import type { LogLevel, LogEntry, @@ -136,16 +136,16 @@ export class Logger { */ injectStream( stream: DuplexStream, - onError?: (error: Error) => void, + onError?: (error: unknown) => void, ): void { - // eslint-disable-next-line no-void - void stream - .drain(({ params }) => { - const { level, tags, message, data } = lunser(params); - const args: LogArgs = message ? [message, ...(data ?? [])] : []; - this.#dispatch({ level, tags }, ...args); + stream + .drain(async ({ params }) => { + const [, ...args]: ['logger', ...SerializedLogEntry] = params; + const { level, tags, message, data } = lunser(args); + const logArgs: LogArgs = message ? [message, ...(data ?? [])] : []; + this.#dispatch({ level, tags }, ...logArgs); }) - .catch(onError); + .catch((problem) => onError?.(problem)); } #dispatch(options: LoggerOptions, ...args: LogArgs): void { diff --git a/packages/logger/src/stream.test.ts b/packages/logger/src/stream.test.ts index d067126c7..3b1c4403d 100644 --- a/packages/logger/src/stream.test.ts +++ b/packages/logger/src/stream.test.ts @@ -4,7 +4,6 @@ import { vi, describe, it, expect } from 'vitest'; import { isKernelMessage, - isLogMessage, isLoggerMessage, lser, lunser, @@ -44,38 +43,41 @@ describe('serialization', () => { }); }); -const validParams = ['info', ['test']]; +const validParams = ['logger', 'info', ['test']]; +const invalidParams = ['log', 'test']; const unserializableParams = [() => undefined]; -describe('isLogMessage', () => { - it.each` - description | value | expectation - ${'valid params'} | ${{ method: 'log', params: validParams, jsonrpc: '2.0' }} | ${true} - ${'unserializable params'} | ${{ method: 'log', params: unserializableParams, jsonrpc: '2.0' }} | ${false} - ${'invalid method'} | ${{ method: 'ping', params: null, jsonrpc: '2.0' }} | ${false} - `('returns $expectation for $description', ({ value, expectation }) => { - expect(isLogMessage(value)).toBe(expectation); - }); +const asJsonRpcMethod = (method: string, params: unknown) => ({ + method, + params, + jsonrpc: '2.0', }); -describe('isKernelMessage', () => { +describe('isLoggerMessage', () => { it.each` - description | value | expectation - ${'kernel method'} | ${{ method: 'ping', params: null, id: null, jsonrpc: '2.0' }} | ${true} - ${'logger method'} | ${{ method: 'log', params: validParams, id: null, jsonrpc: '2.0' }} | ${false} + description | value | expectation + ${'valid params'} | ${asJsonRpcMethod('notify', validParams)} | ${true} + ${'invalid params'} | ${asJsonRpcMethod('notify', invalidParams)} | ${false} + ${'unserializable params'} | ${asJsonRpcMethod('notify', unserializableParams)} | ${false} + ${'invalid method'} | ${asJsonRpcMethod('ping', null)} | ${false} `('returns $expectation for $description', ({ value, expectation }) => { - expect(isKernelMessage(value)).toBe(expectation); + expect({ result: isLoggerMessage(value), value }).toStrictEqual({ + result: expectation, + value, + }); }); }); -describe('isLoggerMessage', () => { +describe('isKernelMessage', () => { it.each` - description | value | expectation - ${'valid params'} | ${{ method: 'log', params: validParams, id: null, jsonrpc: '2.0' }} | ${true} - ${'unserializable params'} | ${{ method: 'log', params: unserializableParams, id: null, jsonrpc: '2.0' }} | ${false} - ${'invalid method'} | ${{ method: 'ping', params: null, id: null, jsonrpc: '2.0' }} | ${false} + description | value | expectation + ${'kernel method'} | ${asJsonRpcMethod('ping', null)} | ${true} + ${'logger method'} | ${asJsonRpcMethod('notify', validParams)} | ${false} `('returns $expectation for $description', ({ value, expectation }) => { - expect(isLoggerMessage(value)).toBe(expectation); + expect({ result: isKernelMessage(value), value }).toStrictEqual({ + result: expectation, + value, + }); }); }); diff --git a/packages/logger/src/stream.ts b/packages/logger/src/stream.ts index ede9e62a1..e72284960 100644 --- a/packages/logger/src/stream.ts +++ b/packages/logger/src/stream.ts @@ -1,13 +1,13 @@ -import { isJsonRpcCall, stringify } from '@metamask/kernel-utils'; +import { stringify } from '@metamask/kernel-utils'; import type { JsonRpcCall, JsonRpcMessage } from '@metamask/kernel-utils'; import { split } from '@metamask/streams'; import type { DuplexStream } from '@metamask/streams'; -import { isJsonRpcRequest } from '@metamask/utils'; +import { isJsonRpcNotification } from '@metamask/utils'; import type { JsonRpcRequest } from '@metamask/utils'; import type { LogEntry, LogLevel } from './types.ts'; -type SerializedLogEntry = [ +export type SerializedLogEntry = [ /* level */ LogLevel, /* tags */ string[], /* message */ string | null, @@ -15,8 +15,8 @@ type SerializedLogEntry = [ ]; export type LogMessage = JsonRpcCall & { - method: 'log'; - params: SerializedLogEntry; + method: 'notify'; + params: ['logger', ...SerializedLogEntry]; }; export const lser = ({ @@ -43,13 +43,12 @@ export const lunser = (params: SerializedLogEntry): LogEntry => { return entry; }; -export const isLogMessage = (message: JsonRpcMessage): message is LogMessage => - isJsonRpcCall(message) && message.method === 'log'; - export const isLoggerMessage = ( message: JsonRpcMessage, -): message is JsonRpcRequest & { method: 'log' } => - isJsonRpcRequest(message) && message.method === 'log'; +): message is LogMessage => + isJsonRpcNotification(message) && + (message as { params: { length: number } }).params.length > 0 && + (message as { params: unknown[] }).params[0] === 'logger'; export const isKernelMessage = ( message: JsonRpcMessage, diff --git a/packages/logger/src/transports.test.ts b/packages/logger/src/transports.test.ts index 373712e2c..ae15b9e4b 100644 --- a/packages/logger/src/transports.test.ts +++ b/packages/logger/src/transports.test.ts @@ -33,7 +33,8 @@ describe('consoleTransport', () => { describe('makeStreamTransport', () => { it('writes to the stream', () => { - const logEntry = makeLogEntry('info'); + const logLevel = 'info'; + const logEntry = makeLogEntry(logLevel); const mockStream = { write: vi.fn().mockResolvedValue(undefined), } as unknown as DuplexStream; @@ -41,8 +42,14 @@ describe('makeStreamTransport', () => { streamTransport(logEntry); expect(mockStream.write).toHaveBeenCalledWith( expect.objectContaining({ - method: 'log', - params: expect.any(Array), + method: 'notify', + params: expect.arrayContaining([ + 'logger', + logLevel, + logEntry.tags, + logEntry.message, + null, + ]), jsonrpc: '2.0', }), ); diff --git a/packages/logger/src/transports.ts b/packages/logger/src/transports.ts index 020c7c928..face2c2fb 100644 --- a/packages/logger/src/transports.ts +++ b/packages/logger/src/transports.ts @@ -30,7 +30,11 @@ export const makeStreamTransport = ( ): Transport => { return (entry) => { stream - .write({ method: 'log', params: lser(entry), jsonrpc: '2.0' }) + .write({ + method: 'notify', + params: ['logger', ...lser(entry)], + jsonrpc: '2.0', + }) .catch(console.debug); }; }; From 2e3776526288bf588238c3ae195d07d531a7fe8c Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Sat, 3 May 2025 13:03:37 -0400 Subject: [PATCH 13/26] test(logger): Add IPC test for streamTransport --- eslint.config.mjs | 7 ++- packages/logger/package.json | 1 + packages/logger/test/ipc.test.ts | 64 ++++++++++++++++++++++ packages/logger/test/workers/logger.js | 19 +++++++ packages/logger/test/workers/split.js | 24 ++++++++ packages/logger/test/workers/underlying.js | 17 ++++++ packages/logger/tsconfig.json | 10 +++- yarn.lock | 1 + 8 files changed, 139 insertions(+), 4 deletions(-) create mode 100644 packages/logger/test/ipc.test.ts create mode 100644 packages/logger/test/workers/logger.js create mode 100644 packages/logger/test/workers/split.js create mode 100644 packages/logger/test/workers/underlying.js diff --git a/eslint.config.mjs b/eslint.config.mjs index d1a6b011f..7cf120203 100644 --- a/eslint.config.mjs +++ b/eslint.config.mjs @@ -216,9 +216,12 @@ const config = createConfig([ }, { - files: ['packages/nodejs/test/workers/**/*'], + files: [ + 'packages/nodejs/test/workers/**/*', + 'packages/logger/test/workers/**/*', + ], rules: { - // Test node worker files can resolve these imports, even if eslint cannot. + // Test worker files can resolve these imports, even if eslint cannot. 'import-x/no-unresolved': 'off', }, }, diff --git a/packages/logger/package.json b/packages/logger/package.json index 5f0fe7c2a..0ff95b5b6 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -66,6 +66,7 @@ "@metamask/eslint-config": "^14.0.0", "@metamask/eslint-config-nodejs": "^14.0.0", "@metamask/eslint-config-typescript": "^14.0.0", + "@metamask/kernel-shims": "workspace:^", "@ocap/test-utils": "workspace:^", "@ts-bridge/cli": "^0.6.3", "@ts-bridge/shims": "^0.1.1", diff --git a/packages/logger/test/ipc.test.ts b/packages/logger/test/ipc.test.ts new file mode 100644 index 000000000..e37478f8b --- /dev/null +++ b/packages/logger/test/ipc.test.ts @@ -0,0 +1,64 @@ +import { waitUntilQuiescent } from '@metamask/kernel-utils'; +import type { JsonRpcCall, JsonRpcMessage } from '@metamask/kernel-utils'; +import { NodeWorkerDuplexStream } from '@metamask/streams'; +import type { DuplexStream } from '@metamask/streams'; +import { Worker as NodeWorker } from 'node:worker_threads'; +import { describe, it, expect, vi } from 'vitest'; + +import { Logger } from '../src/logger.ts'; +import { splitLoggerStream } from '../src/stream.ts'; +import type { LogMessage } from '../src/stream.ts'; + +const makeWorker = (name: string) => + new NodeWorker(new URL(`./workers/${name}.js`, import.meta.url)); + +describe('ipc', () => { + it('delivery over the underlying duplex stream', async () => { + const worker = makeWorker('underlying'); + const stream = await NodeWorkerDuplexStream.make(worker); + + const { value } = await stream.next(); + expect(value).toBeDefined(); + + const { method, params } = value as JsonRpcCall; + expect(method).toBe('notify'); + expect(params).toStrictEqual(['Hello, world!']); + }); + + it('delivery over a single stream via streamTransport and injectStream', async () => { + const worker = makeWorker('logger'); + const stream = await NodeWorkerDuplexStream.make(worker); + + const mockTransport = vi.fn(); + const logger = new Logger({ transports: [mockTransport] }); + logger.injectStream(stream as unknown as DuplexStream); + + await waitUntilQuiescent(1000); + expect(mockTransport).toHaveBeenCalledWith({ + level: 'debug', + message: 'Hello, world!', + tags: ['test'], + data: [], + }); + }); + + it('delivery over a split stream via streamTransport and injectStream', async () => { + const worker = makeWorker('split'); + const stream = await NodeWorkerDuplexStream.make(worker); + const { loggerStream } = splitLoggerStream( + stream as DuplexStream, + ); + + const mockTransport = vi.fn(); + const logger = new Logger({ transports: [mockTransport] }); + logger.injectStream(loggerStream as unknown as DuplexStream); + + await waitUntilQuiescent(1000); + expect(mockTransport).toHaveBeenCalledWith({ + level: 'debug', + message: 'Hello, world!', + tags: ['test'], + data: [], + }); + }); +}); diff --git a/packages/logger/test/workers/logger.js b/packages/logger/test/workers/logger.js new file mode 100644 index 000000000..f54167ef0 --- /dev/null +++ b/packages/logger/test/workers/logger.js @@ -0,0 +1,19 @@ +import '@metamask/kernel-shims/endoify'; +import { NodeWorkerDuplexStream } from '@metamask/streams'; +import { parentPort } from 'node:worker_threads'; + +import { Logger, makeStreamTransport } from '../../dist/index.mjs'; + +main().catch(console.error); + +/** + * The main function for the worker. + */ +async function main() { + const stream = await NodeWorkerDuplexStream.make(parentPort); + const logger = new Logger({ + tags: ['test'], + transports: [makeStreamTransport(stream)], + }); + logger.debug('Hello, world!'); +} diff --git a/packages/logger/test/workers/split.js b/packages/logger/test/workers/split.js new file mode 100644 index 000000000..6480409d4 --- /dev/null +++ b/packages/logger/test/workers/split.js @@ -0,0 +1,24 @@ +import '@metamask/kernel-shims/endoify'; +import { NodeWorkerDuplexStream } from '@metamask/streams'; +import { parentPort } from 'node:worker_threads'; + +import { + Logger, + makeStreamTransport, + splitLoggerStream, +} from '../../dist/index.mjs'; + +main().catch(console.error); + +/** + * The main function for the worker. + */ +async function main() { + const stream = await NodeWorkerDuplexStream.make(parentPort); + const { loggerStream } = splitLoggerStream(stream); + const logger = new Logger({ + tags: ['test'], + transports: [makeStreamTransport(loggerStream)], + }); + logger.debug('Hello, world!'); +} diff --git a/packages/logger/test/workers/underlying.js b/packages/logger/test/workers/underlying.js new file mode 100644 index 000000000..450f5fdfa --- /dev/null +++ b/packages/logger/test/workers/underlying.js @@ -0,0 +1,17 @@ +import '@metamask/kernel-shims/endoify'; +import { NodeWorkerDuplexStream } from '@metamask/streams'; +import { parentPort } from 'node:worker_threads'; + +main().catch(console.error); + +/** + * The main function for the worker. + */ +async function main() { + const stream = await NodeWorkerDuplexStream.make(parentPort); + await stream.write({ + jsonrpc: '2.0', + method: 'notify', + params: ['Hello, world!'], + }); +} diff --git a/packages/logger/tsconfig.json b/packages/logger/tsconfig.json index 1c756c17e..11635704a 100644 --- a/packages/logger/tsconfig.json +++ b/packages/logger/tsconfig.json @@ -5,11 +5,17 @@ "lib": ["ES2022"], "types": ["ses", "vitest"] }, - "references": [{ "path": "../test-utils" }, { "path": "../streams" }], + "references": [ + { "path": "../test-utils" }, + { "path": "../streams" }, + { "path": "../kernel-shims" } + ], "include": [ "../../vitest.config.ts", "./src", + "./test", "./vite.config.ts", "./vitest.config.ts" - ] + ], + "exclude": ["./test/workers/*.js"] } diff --git a/yarn.lock b/yarn.lock index e82902788..08ff33018 100644 --- a/yarn.lock +++ b/yarn.lock @@ -2230,6 +2230,7 @@ __metadata: "@metamask/eslint-config": "npm:^14.0.0" "@metamask/eslint-config-nodejs": "npm:^14.0.0" "@metamask/eslint-config-typescript": "npm:^14.0.0" + "@metamask/kernel-shims": "workspace:^" "@metamask/kernel-utils": "workspace:^" "@metamask/streams": "workspace:^" "@metamask/utils": "npm:^11.4.0" From 9211b58d8f3c4939e9d40127ef9061d9d4bf8d16 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Sun, 4 May 2025 11:09:22 -0400 Subject: [PATCH 14/26] feat(nodejs): Tidy logger plumbing --- packages/nodejs/src/kernel/make-kernel.ts | 8 ++++++-- packages/nodejs/src/vat/vat-worker.ts | 12 ++++++++---- 2 files changed, 14 insertions(+), 6 deletions(-) diff --git a/packages/nodejs/src/kernel/make-kernel.ts b/packages/nodejs/src/kernel/make-kernel.ts index 3a7226694..597d25a86 100644 --- a/packages/nodejs/src/kernel/make-kernel.ts +++ b/packages/nodejs/src/kernel/make-kernel.ts @@ -35,7 +35,11 @@ export async function makeKernel({ JsonRpcRequest, JsonRpcResponse >(port); - const vatWorkerClient = new NodejsVatWorkerManager({ workerFilePath }); + const rootLogger = logger ?? new Logger('kernel-worker'); + const vatWorkerClient = new NodejsVatWorkerManager({ + workerFilePath, + logger: rootLogger.subLogger({ tags: ['vwm'] }), + }); // Initialize kernel store. const kernelDatabase = await makeSQLKernelDatabase({ dbFilename }); @@ -47,7 +51,7 @@ export async function makeKernel({ kernelDatabase, { resetStorage, - logger: logger ?? new Logger('ocap-kernel'), + logger: rootLogger.subLogger({ tags: ['kernel'] }), }, ); diff --git a/packages/nodejs/src/vat/vat-worker.ts b/packages/nodejs/src/vat/vat-worker.ts index a90b58ba3..a799a4979 100644 --- a/packages/nodejs/src/vat/vat-worker.ts +++ b/packages/nodejs/src/vat/vat-worker.ts @@ -8,11 +8,13 @@ import url from 'node:url'; import { makeStreams } from './streams.ts'; -const processLogger = new Logger('nodejs-vat-worker'); +const LOG_TAG = 'nodejs-vat-worker'; + +let logger = new Logger(LOG_TAG); /* eslint-disable n/no-unsupported-features/node-builtins */ -main().catch(processLogger.error); +main().catch((reason) => logger.error('main exited with error', reason)); /** * Fetch a blob of bytes from a URL @@ -41,8 +43,8 @@ async function main(): Promise { throw new Error('no vatId set for env variable NODE_VAT_ID'); } const { kernelStream, loggerStream } = await makeStreams(); - const logger = processLogger.subLogger({ - tags: [vatId], + logger = new Logger({ + tags: [LOG_TAG, vatId], transports: [makeStreamTransport(loggerStream)], }); // eslint-disable-next-line no-void @@ -51,5 +53,7 @@ async function main(): Promise { kernelStream, logger, fetchBlob, + vatPowers: { logger }, }); + logger.debug('vat-worker main'); } From 852abbde0312a9cd54067505244bebf344c20c40 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Sun, 4 May 2025 11:09:38 -0400 Subject: [PATCH 15/26] feat(kernel): Tidy logger plumbing --- packages/ocap-kernel/src/Kernel.test.ts | 7 ++++--- packages/ocap-kernel/src/Kernel.ts | 2 +- packages/ocap-kernel/src/VatSupervisor.ts | 2 +- 3 files changed, 6 insertions(+), 5 deletions(-) diff --git a/packages/ocap-kernel/src/Kernel.test.ts b/packages/ocap-kernel/src/Kernel.test.ts index f1fa322ec..a1bebc53e 100644 --- a/packages/ocap-kernel/src/Kernel.test.ts +++ b/packages/ocap-kernel/src/Kernel.test.ts @@ -56,9 +56,10 @@ describe('Kernel', () => { launchWorkerMock = vi .spyOn(mockWorkerService, 'launch') - .mockResolvedValue( - {} as unknown as DuplexStream, - ); + .mockResolvedValue({ end: vi.fn() } as unknown as DuplexStream< + JsonRpcMessage, + JsonRpcMessage + >); terminateWorkerMock = vi .spyOn(mockWorkerService, 'terminate') .mockResolvedValue(undefined); diff --git a/packages/ocap-kernel/src/Kernel.ts b/packages/ocap-kernel/src/Kernel.ts index 7ee354d15..d237d0426 100644 --- a/packages/ocap-kernel/src/Kernel.ts +++ b/packages/ocap-kernel/src/Kernel.ts @@ -210,7 +210,7 @@ export class Kernel { } const stream = await this.#vatWorkerService.launch(vatId, vatConfig); const { kernelStream: vatStream, loggerStream } = splitLoggerStream(stream); - const vatLogger = this.#logger.subLogger(vatId); + const vatLogger = this.#logger.subLogger({ tags: [vatId] }); vatLogger.injectStream( loggerStream as unknown as Parameters[0], (error) => console.error(stringify(error)), diff --git a/packages/ocap-kernel/src/VatSupervisor.ts b/packages/ocap-kernel/src/VatSupervisor.ts index 06414cadb..59a65cc29 100644 --- a/packages/ocap-kernel/src/VatSupervisor.ts +++ b/packages/ocap-kernel/src/VatSupervisor.ts @@ -240,7 +240,7 @@ export class VatSupervisor { }); const workerEndowments = { - console: this.#logger.subLogger({ tags: ['vat-worker'] }), + console: this.#logger.subLogger({ tags: ['console'] }), assert: globalThis.assert, }; From b9fedd29bb270c728ab585464be671f9ff207b20 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Sun, 4 May 2025 13:38:39 -0400 Subject: [PATCH 16/26] feat(kernel-test): Use vat loggers to remove terminal noise --- packages/kernel-test/src/exo.test.ts | 375 +++++++----- .../src/garbage-collection.test.ts | 6 +- packages/kernel-test/src/liveslots.test.ts | 534 +++++++++++------- packages/kernel-test/src/logger.test.ts | 35 ++ packages/kernel-test/src/resume.test.ts | 32 +- packages/kernel-test/src/utils.ts | 33 +- packages/kernel-test/src/vats/exo-vat.js | 21 +- packages/kernel-test/src/vats/logger-vat.js | 21 + .../src/vats/message-to-promise-vat.js | 15 +- .../src/vats/pass-result-promise-vat.js | 15 +- .../kernel-test/src/vats/pass-result-vat.js | 15 +- .../kernel-test/src/vats/promise-arg-vat.js | 15 +- .../kernel-test/src/vats/promise-chain-vat.js | 15 +- .../src/vats/promise-crosswise-vat.js | 15 +- .../kernel-test/src/vats/promise-cycle-vat.js | 15 +- .../src/vats/promise-indirect-vat.js | 15 +- .../src/vats/resolve-pipelined-vat.js | 15 +- packages/kernel-test/src/vats/resume-vat.js | 15 +- packages/kernel-test/src/vatstore.test.ts | 2 +- 19 files changed, 675 insertions(+), 534 deletions(-) create mode 100644 packages/kernel-test/src/logger.test.ts create mode 100644 packages/kernel-test/src/vats/logger-vat.js diff --git a/packages/kernel-test/src/exo.test.ts b/packages/kernel-test/src/exo.test.ts index 530b9736c..4c06f7c79 100644 --- a/packages/kernel-test/src/exo.test.ts +++ b/packages/kernel-test/src/exo.test.ts @@ -1,19 +1,18 @@ import '@metamask/kernel-shims/endoify'; -import type { KernelDatabase } from '@metamask/kernel-store'; import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; import { waitUntilQuiescent } from '@metamask/kernel-utils'; +import type { LogEntry } from '@metamask/logger'; import { Kernel, kunser } from '@metamask/ocap-kernel'; import type { KRef } from '@metamask/ocap-kernel'; import { beforeEach, describe, expect, it } from 'vitest'; import { - extractVatLogs, + extractTestLogs, getBundleSpec, makeKernel, makeTestLogger, runTestVats, } from './utils.ts'; -import type { TestLogger } from './utils.ts'; const testSubcluster = { bootstrap: 'exoTest', @@ -30,173 +29,237 @@ const testSubcluster = { describe('virtual objects functionality', async () => { let kernel: Kernel; - let kernelDatabase: KernelDatabase; + let logEntries: LogEntry[]; let bootstrapResult: unknown; - let logger: TestLogger; + + /** + * Clears the log entries array. + * Used to ignore logs from before a given test checkpoint. + */ + const clearLogEntries = () => { + logEntries.length = 0; + }; beforeEach(async () => { - kernelDatabase = await makeSQLKernelDatabase({ + const kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); - logger = makeTestLogger(); + const { logger, entries } = makeTestLogger(); kernel = await makeKernel(kernelDatabase, true, logger); bootstrapResult = await runTestVats(kernel, testSubcluster); + logEntries = entries; await waitUntilQuiescent(100); }); - it('successfully creates and uses exo objects and scalar stores', async () => { - expect(bootstrapResult).toBe('exo-test-complete'); - const vatLogs = extractVatLogs(logger.entries); - expect(vatLogs).toStrictEqual([ - 'ExoTest: initializing state', - 'ExoTest: counter value from baggage: 0', - 'ExoTest: bootstrap()', - 'ExoTest: Created counter with initial value: 10', - 'ExoTest: Incremented counter by 5 to: 15', - 'ExoTest: ERROR: Increment with negative value should have failed', - 'ExoTest: Alice has 1 friends', - 'ExoTest: Added 2 entries to map store', - 'ExoTest: Added 2 entries to set store', - 'ExoTest: Retrieved Alice from map store', - 'ExoTest: Temperature at 25°C = 77°F', - 'ExoTest: After setting to 68°F, celsius is 20°C', - 'ExoTest: SimpleCounter initial value: 0', - 'ExoTest: SimpleCounter after +7: 7', - 'ExoTest: Updated baggage counter to: 7', - ]); - }, 30000); + it( + 'successfully creates and uses exo objects and scalar stores', + { + timeout: 30_000, + }, + async () => { + expect(bootstrapResult).toBe('exo-test-complete'); + const vatLogs = extractTestLogs(logEntries, 'ExoTest'); + expect(vatLogs).toStrictEqual([ + 'initializing state', + 'counter value from baggage: 0', + 'bootstrap()', + 'Created counter with initial value: 10', + 'Incremented counter by 5 to: 15', + 'ERROR: Increment with negative value should have failed', + 'Alice has 1 friends', + 'Added 2 entries to map store', + 'Added 2 entries to set store', + 'Retrieved Alice from map store', + 'Temperature at 25°C = 77°F', + 'After setting to 68°F, celsius is 20°C', + 'SimpleCounter initial value: 0', + 'SimpleCounter after +7: 7', + 'Updated baggage counter to: 7', + ]); + }, + ); - it('tests scalar store functionality', async () => { - const storeResult = await kernel.queueMessage('ko1', 'testScalarStore', []); - await waitUntilQuiescent(100); - expect(kunser(storeResult)).toBe('scalar-store-tests-complete'); - const vatLogs = extractVatLogs(logger.entries); - expect(vatLogs).toStrictEqual([ - 'ExoTest: Map store size: 3', - 'ExoTest: Map store keys: alice, bob, charlie', - "ExoTest: Map has 'charlie': true", - 'ExoTest: Set store size: 3', - 'ExoTest: Set has Charlie: true', - ]); - }, 30000); + it( + 'tests scalar store functionality', + { + timeout: 30_000, + }, + async () => { + expect(bootstrapResult).toBe('exo-test-complete'); + clearLogEntries(); + const storeResult = await kernel.queueMessage( + 'ko1', + 'testScalarStore', + [], + ); + await waitUntilQuiescent(100); + expect(kunser(storeResult)).toBe('scalar-store-tests-complete'); + const vatLogs = extractTestLogs(logEntries, 'ExoTest'); + expect(vatLogs).toStrictEqual([ + 'Map store size: 3', + 'Map store keys: alice, bob, charlie', + "Map has 'charlie': true", + 'Set store size: 3', + 'Set has Charlie: true', + ]); + }, + ); - it('can create and use objects through messaging', async () => { - const counterResult = await kernel.queueMessage('ko1', 'createCounter', [ - 42, - ]); - await waitUntilQuiescent(); - const counterRef = counterResult.slots[0] as KRef; - const incrementResult = await kernel.queueMessage(counterRef, 'increment', [ - 5, - ]); - // Verify the increment result - expect(kunser(incrementResult)).toBe(47); - await waitUntilQuiescent(); - const personResult = await kernel.queueMessage('ko1', 'createPerson', [ - 'Dave', - 35, - ]); - await waitUntilQuiescent(); - const personRef = personResult.slots[0] as KRef; - await kernel.queueMessage('ko1', 'createOrUpdateInMap', [ - 'dave', - personRef, - ]); - await waitUntilQuiescent(); + it( + 'can create and use objects through messaging', + { + timeout: 30_000, + }, + async () => { + expect(bootstrapResult).toBe('exo-test-complete'); + clearLogEntries(); + const counterResult = await kernel.queueMessage('ko1', 'createCounter', [ + 42, + ]); + await waitUntilQuiescent(); + const counterRef = counterResult.slots[0] as KRef; + const incrementResult = await kernel.queueMessage( + counterRef, + 'increment', + [5], + ); + // Verify the increment result + expect(kunser(incrementResult)).toBe(47); + await waitUntilQuiescent(); + const personResult = await kernel.queueMessage('ko1', 'createPerson', [ + 'Dave', + 35, + ]); + await waitUntilQuiescent(); + const personRef = personResult.slots[0] as KRef; + await kernel.queueMessage('ko1', 'createOrUpdateInMap', [ + 'dave', + personRef, + ]); + await waitUntilQuiescent(); - // Get object from map store - const retrievedPerson = await kernel.queueMessage('ko1', 'getFromMap', [ - 'dave', - ]); - await waitUntilQuiescent(); - // Verify the retrieved person object - expect(kunser(retrievedPerson)).toBe(personRef); - await kernel.queueMessage('ko1', 'createOrUpdateInMap', [ - 'dave', - personRef, - ]); - await waitUntilQuiescent(100); - const vatLogs = extractVatLogs(logger.entries); - // Verify counter was created and used - expect(vatLogs).toStrictEqual([ - 'ExoTest: Created new counter with value: 42', - 'ExoTest: Created person Dave, age 35', - 'ExoTest: Added dave to map, size now: 3', - 'ExoTest: Found dave in map', - 'ExoTest: Updated dave in map', - ]); - }, 30000); + // Get object from map store + const retrievedPerson = await kernel.queueMessage('ko1', 'getFromMap', [ + 'dave', + ]); + await waitUntilQuiescent(); + // Verify the retrieved person object + expect(kunser(retrievedPerson)).toBe(personRef); + await kernel.queueMessage('ko1', 'createOrUpdateInMap', [ + 'dave', + personRef, + ]); + await waitUntilQuiescent(100); + const vatLogs = extractTestLogs(logEntries, 'ExoTest'); + // Verify counter was created and used + expect(vatLogs).toStrictEqual([ + 'Created new counter with value: 42', + 'Created person Dave, age 35', + 'Added dave to map, size now: 3', + 'Found dave in map', + 'Updated dave in map', + ]); + }, + ); - it('tests exoClass type validation and behavior', async () => { - const exoClassResult = await kernel.queueMessage('ko1', 'testExoClass', []); - await waitUntilQuiescent(100); - expect(kunser(exoClassResult)).toBe('exoClass-tests-complete'); - const vatLogs = extractVatLogs(logger.entries); - expect(vatLogs).toStrictEqual([ - 'ExoTest: Counter: 3 + 5 = 8', - 'ExoTest: Counter: 8 - 2 = 6', - 'ExoTest: Successfully caught type error: In "increment" method of (Counter): arg 0: string "foo" - Must be a number', - ]); - }, 30000); + it( + 'tests exoClass type validation and behavior', + { + timeout: 30_000, + }, + async () => { + expect(bootstrapResult).toBe('exo-test-complete'); + clearLogEntries(); + const exoClassResult = await kernel.queueMessage( + 'ko1', + 'testExoClass', + [], + ); + await waitUntilQuiescent(100); + expect(kunser(exoClassResult)).toBe('exoClass-tests-complete'); + const vatLogs = extractTestLogs(logEntries, 'ExoTest'); + expect(vatLogs).toStrictEqual([ + 'Counter: 3 + 5 = 8', + 'Counter: 8 - 2 = 6', + 'Successfully caught type error: In "increment" method of (Counter): arg 0: string "foo" - Must be a number', + ]); + }, + ); - it('tests exoClassKit with multiple facets', async () => { - const exoClassKitResult = await kernel.queueMessage( - 'ko1', - 'testExoClassKit', - [], - ); - await waitUntilQuiescent(100); - expect(kunser(exoClassKitResult)).toBe('exoClassKit-tests-complete'); - const vatLogs = extractVatLogs(logger.entries); - expect(vatLogs).toStrictEqual([ - 'ExoTest: 20°C = 68°F', - 'ExoTest: 32°F = 0°C', - 'ExoTest: Successfully caught cross-facet error: celsius.getFahrenheit is not a function', - ]); - }, 30000); + it( + 'tests exoClassKit with multiple facets', + { + timeout: 30_000, + }, + async () => { + expect(bootstrapResult).toBe('exo-test-complete'); + clearLogEntries(); + const exoClassKitResult = await kernel.queueMessage( + 'ko1', + 'testExoClassKit', + [], + ); + await waitUntilQuiescent(100); + expect(kunser(exoClassKitResult)).toBe('exoClassKit-tests-complete'); + const vatLogs = extractTestLogs(logEntries, 'ExoTest'); + expect(vatLogs).toStrictEqual([ + '20°C = 68°F', + '32°F = 0°C', + 'Successfully caught cross-facet error: celsius.getFahrenheit is not a function', + ]); + }, + ); - it('tests temperature converter through messaging', async () => { - // Create a temperature converter starting at 100°C - const tempResult = await kernel.queueMessage('ko1', 'createTemperature', [ - 100, - ]); - await waitUntilQuiescent(); - // Get both facets from the result - const tempKit = tempResult; - const celsiusRef = tempKit.slots[0] as KRef; - const fahrenheitRef = tempKit.slots[1] as KRef; - // Get the celsius value - const celsiusResult = await kernel.queueMessage( - celsiusRef, - 'getCelsius', - [], - ); - expect(kunser(celsiusResult)).toBe(100); - // Get the fahrenheit value - const fahrenheitResult = await kernel.queueMessage( - fahrenheitRef, - 'getFahrenheit', - [], - ); - expect(kunser(fahrenheitResult)).toBe(212); - // Change the temperature using the fahrenheit facet - const setFahrenheitResult = await kernel.queueMessage( - fahrenheitRef, - 'setFahrenheit', - [32], - ); - expect(kunser(setFahrenheitResult)).toBe(32); - // Verify that the celsius value changed - const newCelsiusResult = await kernel.queueMessage( - celsiusRef, - 'getCelsius', - [], - ); - expect(kunser(newCelsiusResult)).toBe(0); - await waitUntilQuiescent(100); - const vatLogs = extractVatLogs(logger.entries); - expect(vatLogs).toContain( - 'ExoTest: Created temperature converter starting at 100°C', - ); - }, 30000); + it( + 'tests temperature converter through messaging', + { + timeout: 30_000, + }, + async () => { + expect(bootstrapResult).toBe('exo-test-complete'); + clearLogEntries(); + // Create a temperature converter starting at 100°C + const tempResult = await kernel.queueMessage('ko1', 'createTemperature', [ + 100, + ]); + await waitUntilQuiescent(); + // Get both facets from the result + const tempKit = tempResult; + const celsiusRef = tempKit.slots[0] as KRef; + const fahrenheitRef = tempKit.slots[1] as KRef; + // Get the celsius value + const celsiusResult = await kernel.queueMessage( + celsiusRef, + 'getCelsius', + [], + ); + expect(kunser(celsiusResult)).toBe(100); + // Get the fahrenheit value + const fahrenheitResult = await kernel.queueMessage( + fahrenheitRef, + 'getFahrenheit', + [], + ); + expect(kunser(fahrenheitResult)).toBe(212); + // Change the temperature using the fahrenheit facet + const setFahrenheitResult = await kernel.queueMessage( + fahrenheitRef, + 'setFahrenheit', + [32], + ); + expect(kunser(setFahrenheitResult)).toBe(32); + // Verify that the celsius value changed + const newCelsiusResult = await kernel.queueMessage( + celsiusRef, + 'getCelsius', + [], + ); + expect(kunser(newCelsiusResult)).toBe(0); + await waitUntilQuiescent(100); + const vatLogs = extractTestLogs(logEntries, 'ExoTest'); + expect(vatLogs).toContain( + 'Created temperature converter starting at 100°C', + ); + }, + ); }); diff --git a/packages/kernel-test/src/garbage-collection.test.ts b/packages/kernel-test/src/garbage-collection.test.ts index 37663e62d..6f4b97ea7 100644 --- a/packages/kernel-test/src/garbage-collection.test.ts +++ b/packages/kernel-test/src/garbage-collection.test.ts @@ -2,6 +2,7 @@ import '@metamask/kernel-shims/endoify'; import type { KernelDatabase } from '@metamask/kernel-store'; import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; import { waitUntilQuiescent } from '@metamask/kernel-utils'; +import { Logger } from '@metamask/logger'; import { Kernel, kunser, makeKernelStore } from '@metamask/ocap-kernel'; import type { ClusterConfig, @@ -18,7 +19,6 @@ import { parseReplyBody, runTestVats, } from './utils.ts'; -import type { TestLogger } from './utils.ts'; /** * Make a test subcluster with vats for GC testing @@ -54,10 +54,10 @@ describe('Garbage Collection', () => { let importerKRef: KRef; let exporterVatId: VatId; let importerVatId: VatId; - let logger: TestLogger; + let logger: Logger; beforeEach(async () => { - logger = makeTestLogger(); + logger = makeTestLogger().logger; kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); diff --git a/packages/kernel-test/src/liveslots.test.ts b/packages/kernel-test/src/liveslots.test.ts index 9da762aa8..7209bcabd 100644 --- a/packages/kernel-test/src/liveslots.test.ts +++ b/packages/kernel-test/src/liveslots.test.ts @@ -1,16 +1,17 @@ import '@metamask/kernel-shims/endoify'; +import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; import { waitUntilQuiescent } from '@metamask/kernel-utils'; +import type { LogEntry } from '@metamask/logger'; import { Kernel, kunser } from '@metamask/ocap-kernel'; import type { ClusterConfig } from '@metamask/ocap-kernel'; -import { makeKernel } from '@ocap/nodejs'; -import { - MessagePort as NodeMessagePort, - MessageChannel as NodeMessageChannel, -} from 'node:worker_threads'; import { beforeEach, describe, expect, it } from 'vitest'; -import { extractVatLogs, getBundleSpec, makeTestLogger } from './utils.ts'; -import type { TestLogger } from './utils.ts'; +import { + getBundleSpec, + makeTestLogger, + makeKernel, + extractTestLogs, +} from './utils.ts'; const makeTestSubcluster = ( testName: string, @@ -42,18 +43,16 @@ const makeTestSubcluster = ( }); describe('liveslots promise handling', () => { - let logger: TestLogger; let kernel: Kernel; + let entries: LogEntry[]; beforeEach(async () => { - const kernelPort: NodeMessagePort = new NodeMessageChannel().port1; - logger = makeTestLogger(); - kernel = await makeKernel({ - port: kernelPort, - resetStorage: true, + const { logger, entries: testEntries } = makeTestLogger(); + const kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', - logger, }); + kernel = await makeKernel(kernelDatabase, true, logger); + entries = testEntries; }); /** @@ -62,234 +61,331 @@ describe('liveslots promise handling', () => { * @param bundleName - The name of the bundle for the test implementation vat(s). * @param testName - The name of the test to run. * - * @returns a tuple of the bootstrap result and the execution log output. + * @returns the bootstrap result. */ async function runTestVats( bundleName: string, testName: string, - ): Promise<[unknown, string[]]> { + ): Promise { const bundleSpec = getBundleSpec(bundleName); const bootstrapResultRaw = await kernel.launchSubcluster( makeTestSubcluster(testName, bundleSpec), ); await waitUntilQuiescent(1000); - const vatLogs = extractVatLogs(logger.entries); if (bootstrapResultRaw === undefined) { throw Error(`this can't happen but eslint is stupid`); } - return [kunser(bootstrapResultRaw), vatLogs]; + return kunser(bootstrapResultRaw); } - it('promiseArg1: send promise parameter, resolve after send', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-arg-vat', - 'promiseArg1', - ); - expect(bootstrapResult).toBe('bobPSucc'); - const reference = [ - `Alice: running test promiseArg1`, - `Alice: sending the promise to Bob`, - `Alice: resolving the promise that was sent to Bob`, - `Alice: awaiting Bob's response`, - `Alice: Bob's response to hereIsAPromise: 'Bob.hereIsAPromise done'`, - `Bob: the promise parameter resolved to 'Alice said hi after send'`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseArg1: send promise parameter, resolve after send', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-arg-vat', + 'promiseArg1', + ); + expect(bootstrapResult).toBe('bobPSucc'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseArg1`, + `sending the promise to Bob`, + `resolving the promise that was sent to Bob`, + `awaiting Bob's response`, + `Bob's response to hereIsAPromise: 'Bob.hereIsAPromise done'`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `the promise parameter resolved to 'Alice said hi after send'`, + ]); + }, + ); - it('promiseArg2: send promise parameter, resolved before send', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-arg-vat', - 'promiseArg2', - ); - expect(bootstrapResult).toBe('bobPSucc'); - const reference = [ - `Alice: running test promiseArg2`, - `Alice: resolving the promise that will be sent to Bob`, - `Alice: sending the promise to Bob`, - `Alice: awaiting Bob's response`, - `Alice: Bob's response to hereIsAPromise: 'Bob.hereIsAPromise done'`, - `Bob: the promise parameter resolved to 'Alice said hi before send'`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseArg2: send promise parameter, resolved before send', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-arg-vat', + 'promiseArg2', + ); + expect(bootstrapResult).toBe('bobPSucc'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseArg2`, + `resolving the promise that will be sent to Bob`, + `sending the promise to Bob`, + `awaiting Bob's response`, + `Bob's response to hereIsAPromise: 'Bob.hereIsAPromise done'`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `the promise parameter resolved to 'Alice said hi before send'`, + ]); + }, + ); - it('promiseArg3: send promise parameter, resolve after reply to send', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-arg-vat', - 'promiseArg3', - ); - expect(bootstrapResult).toBe('bobPSucc'); - const reference = [ - `Alice: running test promiseArg3`, - `Alice: sending the promise to Bob`, - `Alice: awaiting Bob's response`, - `Alice: Bob's response to hereIsAPromise: 'Bob.hereIsAPromise done'`, - `Alice: resolving the promise that was sent to Bob`, - `Bob: the promise parameter resolved to 'Alice said hi after Bob's reply'`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseArg3: send promise parameter, resolve after reply to send', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-arg-vat', + 'promiseArg3', + ); + expect(bootstrapResult).toBe('bobPSucc'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseArg3`, + `sending the promise to Bob`, + `awaiting Bob's response`, + `Bob's response to hereIsAPromise: 'Bob.hereIsAPromise done'`, + `resolving the promise that was sent to Bob`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `the promise parameter resolved to 'Alice said hi after Bob's reply'`, + ]); + }, + ); - it('promiseChain: resolve a chain of promises', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-chain-vat', - 'promiseChain', - ); - expect(bootstrapResult).toBe('end of chain'); - const reference = [ - `Alice: running test promiseChain`, - `Alice: waitFor start`, - `Alice: count 0 < 3, recurring...`, - `Alice: waitFor start`, - `Alice: count 1 < 3, recurring...`, - `Alice: waitFor start`, - `Alice: count 2 < 3, recurring...`, - `Alice: waitFor start`, - `Alice: finishing chain`, - `Bob: bobGen set value to 1`, - `Bob: bobGen set value to 2`, - `Bob: bobGen set value to 3`, - `Bob: bobGen set value to 4`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseChain: resolve a chain of promises', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-chain-vat', + 'promiseChain', + ); + expect(bootstrapResult).toBe('end of chain'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseChain`, + `waitFor start`, + `count 0 < 3, recurring...`, + `waitFor start`, + `count 1 < 3, recurring...`, + `waitFor start`, + `count 2 < 3, recurring...`, + `waitFor start`, + `finishing chain`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `bobGen set value to 1`, + `bobGen set value to 2`, + `bobGen set value to 3`, + `bobGen set value to 4`, + ]); + }, + ); - it('promiseCycle: mutually referential promise resolutions', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-cycle-vat', - 'promiseCycle', - ); - expect(bootstrapResult).toBe('done'); - const reference = [ - `Alice: running test promiseCycle`, - `Alice: isPromise(resolutionX[0]): true`, - `Alice: isPromise(resolutionY[0]): true`, - `Bob: genPromise1`, - `Bob: genPromise2`, - `Bob: resolveBoth`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseCycle: mutually referential promise resolutions', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-cycle-vat', + 'promiseCycle', + ); + expect(bootstrapResult).toBe('done'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseCycle`, + `isPromise(resolutionX[0]): true`, + `isPromise(resolutionY[0]): true`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `genPromise1`, + `genPromise2`, + `resolveBoth`, + ]); + }, + ); - it('promiseCycleMultiCrank: mutually referential promise resolutions across cranks', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-cycle-vat', - 'promiseCycleMultiCrank', - ); - expect(bootstrapResult).toBe('done'); - const reference = [ - `Alice: running test promiseCycleMultiCrank`, - `Alice: isPromise(resolutionX[0]): true`, - `Alice: isPromise(resolutionY[0]): true`, - `Bob: genPromise1`, - `Bob: genPromise2`, - `Bob: resolve1`, - `Bob: resolve2`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseCycleMultiCrank: mutually referential promise resolutions across cranks', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-cycle-vat', + 'promiseCycleMultiCrank', + ); + expect(bootstrapResult).toBe('done'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseCycleMultiCrank`, + `isPromise(resolutionX[0]): true`, + `isPromise(resolutionY[0]): true`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `genPromise1`, + `genPromise2`, + `resolve1`, + `resolve2`, + ]); + }, + ); - it('promiseCrosswise: mutually referential promise resolutions across cranks', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-crosswise-vat', - 'promiseCrosswise', - ); - expect(bootstrapResult).toBe('done'); - const reference = [ - `Alice: running test promiseCrosswise`, - `Alice: isPromise(resolutionX[0]): true`, - `Alice: isPromise(resolutionY[0]): true`, - `Bob: genPromise`, - `Bob: resolve`, - `Carol: genPromise`, - `Carol: resolve`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseCrosswise: mutually referential promise resolutions across cranks', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-crosswise-vat', + 'promiseCrosswise', + ); + expect(bootstrapResult).toBe('done'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseCrosswise`, + `isPromise(resolutionX[0]): true`, + `isPromise(resolutionY[0]): true`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([`genPromise`, `resolve`]); + const carolLogs = extractTestLogs(entries, 'Carol'); + expect(carolLogs).toStrictEqual([`genPromise`, `resolve`]); + }, + ); - it('promiseIndirect: resolution of a resolution of a promise', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'promise-indirect-vat', - 'promiseIndirect', - ); - expect(bootstrapResult).toBe('done'); - const reference = [ - `Alice: running test promiseIndirect`, - `Alice: resolution == hello`, - `Bob: genPromise1`, - `Bob: genPromise2`, - `Bob: resolve`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'promiseIndirect: resolution of a resolution of a promise', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'promise-indirect-vat', + 'promiseIndirect', + ); + expect(bootstrapResult).toBe('done'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test promiseIndirect`, + `resolution == hello`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([`genPromise1`, `genPromise2`, `resolve`]); + }, + ); - it('passResult: pass a method result as a parameter', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'pass-result-vat', - 'passResult', - ); - expect(bootstrapResult).toStrictEqual(['p1succ', 'p2succ']); - const reference = [ - `Alice: running test passResult`, - `Alice: first result resolved to Bob's first answer`, - `Alice: second result resolved to Bob's second answer`, - `Bob: first`, - `Bob: second`, - `Bob: parameter to second resolved to Bob's first answer`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'passResult: pass a method result as a parameter', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'pass-result-vat', + 'passResult', + ); + expect(bootstrapResult).toStrictEqual(['p1succ', 'p2succ']); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test passResult`, + `first result resolved to Bob's first answer`, + `second result resolved to Bob's second answer`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `first`, + `second`, + `parameter to second resolved to Bob's first answer`, + ]); + }, + ); - it('passResultPromise: pass a method promise as a parameter', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'pass-result-promise-vat', - 'passResultPromise', - ); - expect(bootstrapResult).toStrictEqual(['p1succ', 'p2succ']); - const reference = [ - `Alice: running test passResultPromise`, - `Alice: first result resolved to Bob answers first in second`, - `Alice: second result resolved to Bob's second answer`, - `Bob: first`, - `Bob: second`, - `Bob: parameter to second resolved to Bob answers first in second`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'passResultPromise: pass a method promise as a parameter', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'pass-result-promise-vat', + 'passResultPromise', + ); + expect(bootstrapResult).toStrictEqual(['p1succ', 'p2succ']); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test passResultPromise`, + `first result resolved to Bob answers first in second`, + `second result resolved to Bob's second answer`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `first`, + `second`, + `parameter to second resolved to Bob answers first in second`, + ]); + }, + ); - it('resolvePipeline: send to promise resolution', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'resolve-pipelined-vat', - 'resolvePipelined', - ); - expect(bootstrapResult).toStrictEqual(['p1succ', 'p2succ']); - const reference = [ - `Alice: running test resolvePipelined`, - `Alice: first result resolved to [object Alleged: thing]`, - `Alice: second result resolved to Bob's second answer`, - `Bob: first`, - `Bob: thing.second`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'resolvePipeline: send to promise resolution', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'resolve-pipelined-vat', + 'resolvePipelined', + ); + expect(bootstrapResult).toStrictEqual(['p1succ', 'p2succ']); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test resolvePipelined`, + `first result resolved to [object Alleged: thing]`, + `second result resolved to Bob's second answer`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([`first`, `thing.second`]); + }, + ); - it('messageToPromise: send to promise before resolution', async () => { - const [bootstrapResult, vatLogs] = await runTestVats( - 'message-to-promise-vat', - 'messageToPromise', - ); - expect(bootstrapResult).toBe('p2succ'); - const reference = [ - `Alice: running test messageToPromise`, - `Alice: invoking loopback`, - `Alice: second result resolved to 'deferred something'`, - `Alice: loopback done`, - `Bob: setup`, - `Bob: doResolve`, - `Bob: thing.doSomething`, - `Bob: loopback`, - ]; - expect(vatLogs).toStrictEqual(reference); - }, 30000); + it( + 'messageToPromise: send to promise before resolution', + { + timeout: 30_000, + }, + async () => { + const bootstrapResult = await runTestVats( + 'message-to-promise-vat', + 'messageToPromise', + ); + expect(bootstrapResult).toBe('p2succ'); + const aliceLogs = extractTestLogs(entries, 'Alice'); + expect(aliceLogs).toStrictEqual([ + `running test messageToPromise`, + `invoking loopback`, + `second result resolved to 'deferred something'`, + `loopback done`, + ]); + const bobLogs = extractTestLogs(entries, 'Bob'); + expect(bobLogs).toStrictEqual([ + `setup`, + `doResolve`, + `thing.doSomething`, + `loopback`, + ]); + }, + ); }); diff --git a/packages/kernel-test/src/logger.test.ts b/packages/kernel-test/src/logger.test.ts new file mode 100644 index 000000000..5483317f0 --- /dev/null +++ b/packages/kernel-test/src/logger.test.ts @@ -0,0 +1,35 @@ +import '@metamask/kernel-shims/endoify'; +import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; +import { waitUntilQuiescent } from '@metamask/kernel-utils'; +import type { VatId } from '@metamask/ocap-kernel'; +import { describe, expect, it } from 'vitest'; + +import { + extractTestLogs, + getBundleSpec, + makeKernel, + makeTestLogger, +} from './utils.ts'; + +describe('logger', () => { + it('captures logs from vat', async () => { + const vatId: VatId = 'v1'; + const name = 'Alice'; + const { logger, entries } = makeTestLogger(); + const database = await makeSQLKernelDatabase({}); + const kernel = await makeKernel(database, true, logger); + const vat = await kernel.launchVat({ + bundleSpec: getBundleSpec('logger-vat'), + parameters: { name }, + }); + const vats = kernel.getVatIds(); + expect(vats).toStrictEqual([vatId]); + + await waitUntilQuiescent(); + await kernel.queueMessageFromKernel(vat, 'foo', []); + + await waitUntilQuiescent(); + const vatLogs = extractTestLogs(entries, vatId); + expect(vatLogs).toStrictEqual([`foo: ${name}`]); + }); +}); diff --git a/packages/kernel-test/src/resume.test.ts b/packages/kernel-test/src/resume.test.ts index d2f5933a4..2489e3ec9 100644 --- a/packages/kernel-test/src/resume.test.ts +++ b/packages/kernel-test/src/resume.test.ts @@ -4,13 +4,13 @@ import { waitUntilQuiescent } from '@metamask/kernel-utils'; import { describe, expect, it } from 'vitest'; import { - extractVatLogs, getBundleSpec, makeKernel, makeTestLogger, runResume, runTestVats, sortLogs, + extractTestLogs, } from './utils.ts'; const testSubcluster = { @@ -100,12 +100,12 @@ const reference = sortLogs([ ...carolResumeReference, ]); -describe('restarting vats', async () => { +describe('restarting vats', { timeout: 30_000 }, async () => { it('exercise restart vats individually', async () => { const kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); - const logger = makeTestLogger(); + const { logger, entries } = makeTestLogger(); const kernel = await makeKernel(kernelDatabase, true, logger); const bootstrapResult = await runTestVats(kernel, testSubcluster); expect(bootstrapResult).toBe('bootstrap Alice'); @@ -119,21 +119,22 @@ describe('restarting vats', async () => { expect(resumeResultB).toBe('resume Bob'); const resumeResultC = await runResume(kernel, 'ko3'); expect(resumeResultC).toBe('resume Carol'); + await waitUntilQuiescent(1000); - const vatLogs = extractVatLogs(logger.entries); - expect(vatLogs).toStrictEqual(reference); - }, 30000); + const vatLogs = extractTestLogs(entries, 'v1', 'v2', 'v3'); + expect(sortLogs(vatLogs)).toStrictEqual(reference); + }); - it('exercise restart kernel', async () => { + it('exercise restart kernel', { timeout: 30_000 }, async () => { const kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); - const logger1 = makeTestLogger(); + const { logger: logger1, entries: entries1 } = makeTestLogger(); const kernel1 = await makeKernel(kernelDatabase, true, logger1); const bootstrapResult = await runTestVats(kernel1, testSubcluster); expect(bootstrapResult).toBe('bootstrap Alice'); await waitUntilQuiescent(); - const logger2 = makeTestLogger(); + const { logger: logger2, entries: entries2 } = makeTestLogger(); const kernel2 = await makeKernel(kernelDatabase, false, logger2); const resumeResultA = await runResume(kernel2, 'ko1'); expect(resumeResultA).toBe('resume Alice'); @@ -142,9 +143,12 @@ describe('restarting vats', async () => { const resumeResultC = await runResume(kernel2, 'ko3'); expect(resumeResultC).toBe('resume Carol'); await waitUntilQuiescent(1000); - const vatLogs1 = extractVatLogs(logger1.entries); - const vatLogs2 = extractVatLogs(logger2.entries); - const vatLogs = sortLogs([...vatLogs1, ...vatLogs2]); - expect(vatLogs).toStrictEqual(reference); - }, 30000); + const vatLogs = extractTestLogs( + [...entries1, ...entries2], + 'v1', + 'v2', + 'v3', + ); + expect(sortLogs(vatLogs)).toStrictEqual(reference); + }); }); diff --git a/packages/kernel-test/src/utils.ts b/packages/kernel-test/src/utils.ts index 1cc5d8d30..9e46f5e7f 100644 --- a/packages/kernel-test/src/utils.ts +++ b/packages/kernel-test/src/utils.ts @@ -81,7 +81,9 @@ export async function makeKernel( JsonRpcRequest, JsonRpcResponse >(kernelPort); - const vatWorkerClient = new NodejsVatWorkerManager({}); + const vatWorkerClient = new NodejsVatWorkerManager({ + logger: logger.subLogger({ tags: ['vwm'] }), + }); const kernel = await Kernel.make( nodeStream, vatWorkerClient, @@ -123,17 +125,22 @@ export function sortLogs(logs: string[]): string[] { * Convert a list of log entries into a list of lines suitable for examination. * * @param entries - The list of log entries to convert. + * @param withTags - The tags to filter by. * * @returns the relevant contents of `entries`, massaged for use. */ -export function extractVatLogs(entries: LogEntry[]): string[] { - if (entries.length === 0) { - throw new Error('No log entries found'); - } +export function extractTestLogs( + entries: LogEntry[], + ...withTags: string[] +): string[] { + const hasTag = + withTags.length > 0 + ? (tags: string[]) => withTags.some((tag) => tags.includes(tag)) + : () => true; return entries - .filter((entry) => entry.tags.includes('vat-worker')) - .map((entry) => entry.message ?? '') - .filter(Boolean); + .filter(({ tags }) => tags.includes('test') && hasTag(tags)) + .map(({ message }) => message ?? '') + .filter((message) => message.length > 0); } /** @@ -161,17 +168,13 @@ export function logDatabase(kernelDatabase: KernelDatabase): void { console.log(result); } -export type TestLogger = Logger & { entries: LogEntry[] }; - /** * Create a logger that records log entries in an array. * * @returns A logger that records log entries in an array. */ -export const makeTestLogger = (): TestLogger => { +export const makeTestLogger = (): { logger: Logger; entries: LogEntry[] } => { const entries: LogEntry[] = []; - const logger = new Logger({ - transports: [makeArrayTransport(entries)], - }); - return Object.assign(logger, { entries }); + const logger = new Logger({ transports: [makeArrayTransport(entries)] }); + return { logger, entries }; }; diff --git a/packages/kernel-test/src/vats/exo-vat.js b/packages/kernel-test/src/vats/exo-vat.js index 84e241e78..e8478bb14 100644 --- a/packages/kernel-test/src/vats/exo-vat.js +++ b/packages/kernel-test/src/vats/exo-vat.js @@ -6,13 +6,16 @@ import { M } from '@endo/patterns'; /** * Build function for testing exo objects and liveslots virtual object functionality. * - * @param {unknown} _vatPowers - Special powers granted to this vat (not used here). + * @param {unknown} vatPowers - Special powers granted to this vat (not used here). * @param {unknown} parameters - Initialization parameters from the vat's config object. * @param {unknown} baggage - Root of vat's persistent state (not used here). * @returns {unknown} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, baggage) { +export function buildRootObject(vatPowers, parameters, baggage) { const vatName = parameters?.name ?? 'anonymous'; + const { logger } = vatPowers; + const testLogger = logger.subLogger({ tags: ['test', vatName] }); + const tlog = (...args) => testLogger.log(...args); /** * Print a message to the log. @@ -23,20 +26,6 @@ export function buildRootObject(_vatPowers, parameters, baggage) { console.log(`${vatName}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - * @param {...any} args - Additional arguments to print. - */ - function tlog(message, ...args) { - if (args.length > 0) { - console.log(`::> ${vatName}: ${message}`, ...args); - } else { - console.log(`::> ${vatName}: ${message}`); - } - } - log(`buildRootObject`); // Create stores for testing diff --git a/packages/kernel-test/src/vats/logger-vat.js b/packages/kernel-test/src/vats/logger-vat.js new file mode 100644 index 000000000..385ef7afc --- /dev/null +++ b/packages/kernel-test/src/vats/logger-vat.js @@ -0,0 +1,21 @@ +import { Far } from '@endo/marshal'; + +/** + * Build function for vats that will run various tests. + * + * @param {*} vatPowers - Special powers granted to this vat. + * @param {*} parameters - Initialization parameters from the vat's config object. + * @param {*} _baggage - Root of vat's persistent state (not used here). + * @returns {*} The root object for the new vat. + */ +export function buildRootObject(vatPowers, parameters, _baggage) { + const name = parameters?.name ?? 'anonymous'; + const logger = vatPowers.logger.subLogger({ tags: ['test'] }); + + return Far('root', { + foo() { + logger.log(`foo: ${name}`); + console.log(`bar: ${name}`); + }, + }); +} diff --git a/packages/kernel-test/src/vats/message-to-promise-vat.js b/packages/kernel-test/src/vats/message-to-promise-vat.js index 17801261d..f7e742123 100644 --- a/packages/kernel-test/src/vats/message-to-promise-vat.js +++ b/packages/kernel-test/src/vats/message-to-promise-vat.js @@ -4,14 +4,16 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -22,15 +24,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); log(`configuration parameters: ${JSON.stringify(parameters)}`); diff --git a/packages/kernel-test/src/vats/pass-result-promise-vat.js b/packages/kernel-test/src/vats/pass-result-promise-vat.js index c4f5997fb..792d0cd1d 100644 --- a/packages/kernel-test/src/vats/pass-result-promise-vat.js +++ b/packages/kernel-test/src/vats/pass-result-promise-vat.js @@ -5,14 +5,16 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -23,15 +25,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); log(`configuration parameters: ${JSON.stringify(parameters)}`); diff --git a/packages/kernel-test/src/vats/pass-result-vat.js b/packages/kernel-test/src/vats/pass-result-vat.js index a636db674..9a1c7160b 100644 --- a/packages/kernel-test/src/vats/pass-result-vat.js +++ b/packages/kernel-test/src/vats/pass-result-vat.js @@ -4,14 +4,16 @@ import { Far } from '@endo/marshal'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -22,15 +24,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); log(`configuration parameters: ${JSON.stringify(parameters)}`); diff --git a/packages/kernel-test/src/vats/promise-arg-vat.js b/packages/kernel-test/src/vats/promise-arg-vat.js index aa4ceb43d..c506bd184 100644 --- a/packages/kernel-test/src/vats/promise-arg-vat.js +++ b/packages/kernel-test/src/vats/promise-arg-vat.js @@ -4,14 +4,16 @@ import { Far } from '@endo/marshal'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const testLogger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => testLogger.log(...args); /** * Print a message to the log. @@ -22,15 +24,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); log(`configuration parameters: ${JSON.stringify(parameters)}`); diff --git a/packages/kernel-test/src/vats/promise-chain-vat.js b/packages/kernel-test/src/vats/promise-chain-vat.js index 65c44d461..33d160f1d 100644 --- a/packages/kernel-test/src/vats/promise-chain-vat.js +++ b/packages/kernel-test/src/vats/promise-chain-vat.js @@ -5,15 +5,17 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; const limit = Number(parameters?.limit ?? 3); + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -24,15 +26,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); log(`configuration parameters: ${JSON.stringify(parameters)}`); diff --git a/packages/kernel-test/src/vats/promise-crosswise-vat.js b/packages/kernel-test/src/vats/promise-crosswise-vat.js index b5c45dd70..bd2f456f0 100644 --- a/packages/kernel-test/src/vats/promise-crosswise-vat.js +++ b/packages/kernel-test/src/vats/promise-crosswise-vat.js @@ -5,14 +5,16 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -23,15 +25,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - /** * Test if a value is a promise. * diff --git a/packages/kernel-test/src/vats/promise-cycle-vat.js b/packages/kernel-test/src/vats/promise-cycle-vat.js index 50a8583bb..2587be5ae 100644 --- a/packages/kernel-test/src/vats/promise-cycle-vat.js +++ b/packages/kernel-test/src/vats/promise-cycle-vat.js @@ -5,14 +5,16 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -23,15 +25,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - /** * Test if a value is a promise. * diff --git a/packages/kernel-test/src/vats/promise-indirect-vat.js b/packages/kernel-test/src/vats/promise-indirect-vat.js index 6060c669b..4a764a9f0 100644 --- a/packages/kernel-test/src/vats/promise-indirect-vat.js +++ b/packages/kernel-test/src/vats/promise-indirect-vat.js @@ -5,14 +5,16 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -23,15 +25,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); log(`configuration parameters: ${JSON.stringify(parameters)}`); diff --git a/packages/kernel-test/src/vats/resolve-pipelined-vat.js b/packages/kernel-test/src/vats/resolve-pipelined-vat.js index 96ea299dc..08fb3ee09 100644 --- a/packages/kernel-test/src/vats/resolve-pipelined-vat.js +++ b/packages/kernel-test/src/vats/resolve-pipelined-vat.js @@ -4,14 +4,16 @@ import { Far } from '@endo/marshal'; /** * Build function for vats that will run various tests. * - * @param {*} _vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat (not used here). * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, _baggage) { +export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. @@ -22,15 +24,6 @@ export function buildRootObject(_vatPowers, parameters, _baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); log(`configuration parameters: ${JSON.stringify(parameters)}`); diff --git a/packages/kernel-test/src/vats/resume-vat.js b/packages/kernel-test/src/vats/resume-vat.js index 3e167b3db..252ca984a 100644 --- a/packages/kernel-test/src/vats/resume-vat.js +++ b/packages/kernel-test/src/vats/resume-vat.js @@ -5,13 +5,15 @@ import { Far } from '@endo/marshal'; /** * Build function for generic test vat. * - * @param {unknown} _vatPowers - Special powers granted to this vat (not used here). + * @param {unknown} vatPowers - Special powers granted to this vat (not used here). * @param {unknown} parameters - Initialization parameters from the vat's config object. * @param {unknown} baggage - Root of vat's persistent state (not used here). * @returns {unknown} The root object for the new vat. */ -export function buildRootObject(_vatPowers, parameters, baggage) { +export function buildRootObject(vatPowers, parameters, baggage) { const name = parameters?.name ?? 'anonymous'; + const logger = vatPowers.logger.subLogger({ tags: ['test'] }); + const tlog = (message) => logger.log(`${name}: ${message}`); /** * Print a message to the log. @@ -22,15 +24,6 @@ export function buildRootObject(_vatPowers, parameters, baggage) { console.log(`${name}: ${message}`); } - /** - * Print a message to the log, tagged as part of the test output. - * - * @param {string} message - The message to print. - */ - function tlog(message) { - console.log(`::> ${name}: ${message}`); - } - log(`buildRootObject`); let startCount; diff --git a/packages/kernel-test/src/vatstore.test.ts b/packages/kernel-test/src/vatstore.test.ts index 47c57f3af..6e802c64c 100644 --- a/packages/kernel-test/src/vatstore.test.ts +++ b/packages/kernel-test/src/vatstore.test.ts @@ -133,7 +133,7 @@ describe('exercise vatstore', async () => { return result; }, ); - const logger = makeTestLogger(); + const { logger } = makeTestLogger(); const kernel = await makeKernel(kernelDatabase, true, logger); await runTestVats(kernel, makeTestSubcluster()); type VSRecord = { key: string; value: string }; From a40e0afde092d7d3d390e630e72dd934689e5518 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Tue, 6 May 2025 09:01:41 -0400 Subject: [PATCH 17/26] fix(kernel-test): fix kernel queueMessage method --- packages/kernel-test/src/logger.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/kernel-test/src/logger.test.ts b/packages/kernel-test/src/logger.test.ts index 5483317f0..19f65fa62 100644 --- a/packages/kernel-test/src/logger.test.ts +++ b/packages/kernel-test/src/logger.test.ts @@ -26,7 +26,7 @@ describe('logger', () => { expect(vats).toStrictEqual([vatId]); await waitUntilQuiescent(); - await kernel.queueMessageFromKernel(vat, 'foo', []); + await kernel.queueMessage(vat, 'foo', []); await waitUntilQuiescent(); const vatLogs = extractTestLogs(entries, vatId); From 61250575edf8f160ce51755b2e6b19e8386f83db Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 11:37:40 -0400 Subject: [PATCH 18/26] chore: thresholds --- vitest.config.ts | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/vitest.config.ts b/vitest.config.ts index 163aae7e3..c752cfaea 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -116,22 +116,22 @@ export default defineConfig({ lines: 100, }, 'packages/logger/**': { - statements: 97.29, - functions: 92.3, - branches: 95.45, + statements: 98.43, + functions: 95.83, + branches: 97.29, lines: 100, }, 'packages/nodejs/**': { - statements: 72.91, - functions: 83.33, - branches: 63.63, - lines: 72.91, + statements: 72.22, + functions: 76.92, + branches: 69.23, + lines: 73.58, }, 'packages/ocap-kernel/**': { - statements: 90.47, - functions: 92.51, + statements: 90.51, + functions: 92.54, branches: 80.45, - lines: 90.45, + lines: 90.48, }, 'packages/streams/**': { statements: 100, @@ -142,4 +142,4 @@ export default defineConfig({ }, }, }, -}); +}); \ No newline at end of file From 397cc0fe63b54ccb2b7aaf8b1069b36f113ab5c0 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 12:11:45 -0400 Subject: [PATCH 19/26] feat(kernel-test): Use mock logger where possible --- .../src/garbage-collection.test.ts | 7 ++----- packages/kernel-test/src/supervisor.test.ts | 7 ++----- packages/kernel-test/src/utils.ts | 21 +++++++++++++++++++ packages/kernel-test/src/vatstore.test.ts | 5 ++--- 4 files changed, 27 insertions(+), 13 deletions(-) diff --git a/packages/kernel-test/src/garbage-collection.test.ts b/packages/kernel-test/src/garbage-collection.test.ts index 6f4b97ea7..d6beb1e28 100644 --- a/packages/kernel-test/src/garbage-collection.test.ts +++ b/packages/kernel-test/src/garbage-collection.test.ts @@ -2,7 +2,6 @@ import '@metamask/kernel-shims/endoify'; import type { KernelDatabase } from '@metamask/kernel-store'; import { makeSQLKernelDatabase } from '@metamask/kernel-store/sqlite/nodejs'; import { waitUntilQuiescent } from '@metamask/kernel-utils'; -import { Logger } from '@metamask/logger'; import { Kernel, kunser, makeKernelStore } from '@metamask/ocap-kernel'; import type { ClusterConfig, @@ -15,7 +14,7 @@ import { expect, beforeEach, describe, it } from 'vitest'; import { getBundleSpec, makeKernel, - makeTestLogger, + makeMockLogger, parseReplyBody, runTestVats, } from './utils.ts'; @@ -54,15 +53,13 @@ describe('Garbage Collection', () => { let importerKRef: KRef; let exporterVatId: VatId; let importerVatId: VatId; - let logger: Logger; beforeEach(async () => { - logger = makeTestLogger().logger; kernelDatabase = await makeSQLKernelDatabase({ dbFilename: ':memory:', }); kernelStore = makeKernelStore(kernelDatabase); - kernel = await makeKernel(kernelDatabase, true, logger); + kernel = await makeKernel(kernelDatabase, true, makeMockLogger()); await runTestVats(kernel, makeTestSubcluster()); const vats = kernel.getVats(); diff --git a/packages/kernel-test/src/supervisor.test.ts b/packages/kernel-test/src/supervisor.test.ts index 39f80fdcf..8355b6824 100644 --- a/packages/kernel-test/src/supervisor.test.ts +++ b/packages/kernel-test/src/supervisor.test.ts @@ -1,18 +1,15 @@ import '@metamask/kernel-shims/endoify'; import { delay } from '@metamask/kernel-utils'; import type { JsonRpcMessage } from '@metamask/kernel-utils'; -import { Logger } from '@metamask/logger'; import type { VatConfig } from '@metamask/ocap-kernel'; import { VatSupervisor, kser } from '@metamask/ocap-kernel'; import { readFile } from 'fs/promises'; import { join } from 'path'; import { describe, it, expect } from 'vitest'; -import { getBundleSpec } from './utils.ts'; +import { getBundleSpec, makeMockLogger } from './utils.ts'; import { TestDuplexStream } from '../../streams/test/stream-mocks.ts'; -const logger = new Logger('test'); - const makeVatSupervisor = async ({ dispatch = () => undefined, vatPowers, @@ -29,7 +26,7 @@ const makeVatSupervisor = async ({ supervisor: new VatSupervisor({ id: 'test-id', kernelStream, - logger, + logger: makeMockLogger(), vatPowers, // eslint-disable-next-line n/no-unsupported-features/node-builtins fetchBlob: async (url: string): Promise => { diff --git a/packages/kernel-test/src/utils.ts b/packages/kernel-test/src/utils.ts index 9e46f5e7f..c6be56fff 100644 --- a/packages/kernel-test/src/utils.ts +++ b/packages/kernel-test/src/utils.ts @@ -14,6 +14,7 @@ import { MessagePort as NodeMessagePort, MessageChannel as NodeMessageChannel, } from 'node:worker_threads'; +import { vi } from 'vitest'; /** * Construct a bundle path URL from a bundle name. @@ -178,3 +179,23 @@ export const makeTestLogger = (): { logger: Logger; entries: LogEntry[] } => { const logger = new Logger({ transports: [makeArrayTransport(entries)] }); return { logger, entries }; }; + +/** + * Create a mock logger that can be used to spy on the logger methods. + * Derived sub-loggers will invoke the parent logger methods directly. + * The injectStream method is a no-op. + * + * @returns A mock logger. + */ +export const makeMockLogger = (): Logger => { + const mockLogger = { + log: vi.fn(), + error: vi.fn(), + warn: vi.fn(), + info: vi.fn(), + debug: vi.fn(), + subLogger: vi.fn(() => mockLogger), + injectStream: vi.fn(), + } as unknown as Logger; + return mockLogger; +}; diff --git a/packages/kernel-test/src/vatstore.test.ts b/packages/kernel-test/src/vatstore.test.ts index 6e802c64c..12d4c2dd1 100644 --- a/packages/kernel-test/src/vatstore.test.ts +++ b/packages/kernel-test/src/vatstore.test.ts @@ -7,7 +7,7 @@ import { describe, vi, expect, it } from 'vitest'; import { getBundleSpec, makeKernel, - makeTestLogger, + makeMockLogger, runTestVats, } from './utils.ts'; @@ -133,8 +133,7 @@ describe('exercise vatstore', async () => { return result; }, ); - const { logger } = makeTestLogger(); - const kernel = await makeKernel(kernelDatabase, true, logger); + const kernel = await makeKernel(kernelDatabase, true, makeMockLogger()); await runTestVats(kernel, makeTestSubcluster()); type VSRecord = { key: string; value: string }; const vsContents = kernelDatabase.executeQuery( From 0f82993ef6a5217f3c74a0e5c0db6c26fe9e121f Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 12:53:44 -0400 Subject: [PATCH 20/26] docs(kernel-test): Fix vatPowers param descriptions --- packages/kernel-test/src/vats/message-to-promise-vat.js | 2 +- packages/kernel-test/src/vats/pass-result-promise-vat.js | 2 +- packages/kernel-test/src/vats/pass-result-vat.js | 2 +- packages/kernel-test/src/vats/powers-vat.js | 2 +- packages/kernel-test/src/vats/promise-arg-vat.js | 2 +- packages/kernel-test/src/vats/promise-chain-vat.js | 2 +- packages/kernel-test/src/vats/promise-crosswise-vat.js | 2 +- packages/kernel-test/src/vats/promise-cycle-vat.js | 2 +- packages/kernel-test/src/vats/promise-indirect-vat.js | 2 +- packages/kernel-test/src/vats/resolve-pipelined-vat.js | 2 +- packages/kernel-test/src/vats/resume-vat.js | 2 +- 11 files changed, 11 insertions(+), 11 deletions(-) diff --git a/packages/kernel-test/src/vats/message-to-promise-vat.js b/packages/kernel-test/src/vats/message-to-promise-vat.js index f7e742123..7129c478b 100644 --- a/packages/kernel-test/src/vats/message-to-promise-vat.js +++ b/packages/kernel-test/src/vats/message-to-promise-vat.js @@ -4,7 +4,7 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/pass-result-promise-vat.js b/packages/kernel-test/src/vats/pass-result-promise-vat.js index 792d0cd1d..6c3f7cd25 100644 --- a/packages/kernel-test/src/vats/pass-result-promise-vat.js +++ b/packages/kernel-test/src/vats/pass-result-promise-vat.js @@ -5,7 +5,7 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/pass-result-vat.js b/packages/kernel-test/src/vats/pass-result-vat.js index 9a1c7160b..8afef7357 100644 --- a/packages/kernel-test/src/vats/pass-result-vat.js +++ b/packages/kernel-test/src/vats/pass-result-vat.js @@ -4,7 +4,7 @@ import { Far } from '@endo/marshal'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/powers-vat.js b/packages/kernel-test/src/vats/powers-vat.js index a13c56ad8..7d6db60dd 100644 --- a/packages/kernel-test/src/vats/powers-vat.js +++ b/packages/kernel-test/src/vats/powers-vat.js @@ -3,7 +3,7 @@ import { Far } from '@endo/marshal'; /** * Build function for running a test of the vatstore. * - * @param {unknown} vatPowers - Special powers granted to this vat (not used here). + * @param {unknown} vatPowers - Special powers granted to this vat. * @param {unknown} parameters - Initialization parameters from the vat's config object. * @param {unknown} _baggage - Root of vat's persistent state. * @returns {unknown} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/promise-arg-vat.js b/packages/kernel-test/src/vats/promise-arg-vat.js index c506bd184..5cb2dff16 100644 --- a/packages/kernel-test/src/vats/promise-arg-vat.js +++ b/packages/kernel-test/src/vats/promise-arg-vat.js @@ -4,7 +4,7 @@ import { Far } from '@endo/marshal'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/promise-chain-vat.js b/packages/kernel-test/src/vats/promise-chain-vat.js index 33d160f1d..7b8bcbe43 100644 --- a/packages/kernel-test/src/vats/promise-chain-vat.js +++ b/packages/kernel-test/src/vats/promise-chain-vat.js @@ -5,7 +5,7 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/promise-crosswise-vat.js b/packages/kernel-test/src/vats/promise-crosswise-vat.js index bd2f456f0..ff0970b55 100644 --- a/packages/kernel-test/src/vats/promise-crosswise-vat.js +++ b/packages/kernel-test/src/vats/promise-crosswise-vat.js @@ -5,7 +5,7 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/promise-cycle-vat.js b/packages/kernel-test/src/vats/promise-cycle-vat.js index 2587be5ae..1b88f07d4 100644 --- a/packages/kernel-test/src/vats/promise-cycle-vat.js +++ b/packages/kernel-test/src/vats/promise-cycle-vat.js @@ -5,7 +5,7 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/promise-indirect-vat.js b/packages/kernel-test/src/vats/promise-indirect-vat.js index 4a764a9f0..21e2794f4 100644 --- a/packages/kernel-test/src/vats/promise-indirect-vat.js +++ b/packages/kernel-test/src/vats/promise-indirect-vat.js @@ -5,7 +5,7 @@ import { makePromiseKit } from '@endo/promise-kit'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/resolve-pipelined-vat.js b/packages/kernel-test/src/vats/resolve-pipelined-vat.js index 08fb3ee09..445d0a8fe 100644 --- a/packages/kernel-test/src/vats/resolve-pipelined-vat.js +++ b/packages/kernel-test/src/vats/resolve-pipelined-vat.js @@ -4,7 +4,7 @@ import { Far } from '@endo/marshal'; /** * Build function for vats that will run various tests. * - * @param {*} vatPowers - Special powers granted to this vat (not used here). + * @param {*} vatPowers - Special powers granted to this vat. * @param {*} parameters - Initialization parameters from the vat's config object. * @param {*} _baggage - Root of vat's persistent state (not used here). * @returns {*} The root object for the new vat. diff --git a/packages/kernel-test/src/vats/resume-vat.js b/packages/kernel-test/src/vats/resume-vat.js index 252ca984a..2a7dc3cd6 100644 --- a/packages/kernel-test/src/vats/resume-vat.js +++ b/packages/kernel-test/src/vats/resume-vat.js @@ -5,7 +5,7 @@ import { Far } from '@endo/marshal'; /** * Build function for generic test vat. * - * @param {unknown} vatPowers - Special powers granted to this vat (not used here). + * @param {unknown} vatPowers - Special powers granted to this vat. * @param {unknown} parameters - Initialization parameters from the vat's config object. * @param {unknown} baggage - Root of vat's persistent state (not used here). * @returns {unknown} The root object for the new vat. From 9eb1bd2ba483c41434956c9499679018d830349f Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 12:56:18 -0400 Subject: [PATCH 21/26] chore(kernel-test): Standardize logger name in test vats --- packages/kernel-test/src/vats/exo-vat.js | 5 ++--- packages/kernel-test/src/vats/promise-arg-vat.js | 4 ++-- 2 files changed, 4 insertions(+), 5 deletions(-) diff --git a/packages/kernel-test/src/vats/exo-vat.js b/packages/kernel-test/src/vats/exo-vat.js index e8478bb14..bef658493 100644 --- a/packages/kernel-test/src/vats/exo-vat.js +++ b/packages/kernel-test/src/vats/exo-vat.js @@ -13,9 +13,8 @@ import { M } from '@endo/patterns'; */ export function buildRootObject(vatPowers, parameters, baggage) { const vatName = parameters?.name ?? 'anonymous'; - const { logger } = vatPowers; - const testLogger = logger.subLogger({ tags: ['test', vatName] }); - const tlog = (...args) => testLogger.log(...args); + const logger = vatPowers.logger.subLogger({ tags: ['test', vatName] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. diff --git a/packages/kernel-test/src/vats/promise-arg-vat.js b/packages/kernel-test/src/vats/promise-arg-vat.js index 5cb2dff16..034658f9a 100644 --- a/packages/kernel-test/src/vats/promise-arg-vat.js +++ b/packages/kernel-test/src/vats/promise-arg-vat.js @@ -12,8 +12,8 @@ import { Far } from '@endo/marshal'; export function buildRootObject(vatPowers, parameters, _baggage) { const name = parameters?.name ?? 'anonymous'; const test = parameters?.test ?? 'unspecified'; - const testLogger = vatPowers.logger.subLogger({ tags: ['test', name] }); - const tlog = (...args) => testLogger.log(...args); + const logger = vatPowers.logger.subLogger({ tags: ['test', name] }); + const tlog = (...args) => logger.log(...args); /** * Print a message to the log. From efad9a4c55fca9d7c359865b014b82fe34f3eabf Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 13:15:43 -0400 Subject: [PATCH 22/26] chore: disabbreviate --- packages/kernel-test/src/utils.ts | 2 +- packages/nodejs/src/kernel/make-kernel.ts | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/kernel-test/src/utils.ts b/packages/kernel-test/src/utils.ts index c6be56fff..8bf2b496d 100644 --- a/packages/kernel-test/src/utils.ts +++ b/packages/kernel-test/src/utils.ts @@ -83,7 +83,7 @@ export async function makeKernel( JsonRpcResponse >(kernelPort); const vatWorkerClient = new NodejsVatWorkerManager({ - logger: logger.subLogger({ tags: ['vwm'] }), + logger: logger.subLogger({ tags: ['vat-worker-manager'] }), }); const kernel = await Kernel.make( nodeStream, diff --git a/packages/nodejs/src/kernel/make-kernel.ts b/packages/nodejs/src/kernel/make-kernel.ts index 597d25a86..494aecb9e 100644 --- a/packages/nodejs/src/kernel/make-kernel.ts +++ b/packages/nodejs/src/kernel/make-kernel.ts @@ -38,7 +38,7 @@ export async function makeKernel({ const rootLogger = logger ?? new Logger('kernel-worker'); const vatWorkerClient = new NodejsVatWorkerManager({ workerFilePath, - logger: rootLogger.subLogger({ tags: ['vwm'] }), + logger: rootLogger.subLogger({ tags: ['vat-worker-manager'] }), }); // Initialize kernel store. From d45f0b585f6ca5c0182f3682fb498f00f3cfd281 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 17:22:21 -0400 Subject: [PATCH 23/26] feat(ocap-kernel): Replace lingering console calls with logger --- packages/ocap-kernel/src/Kernel.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/ocap-kernel/src/Kernel.ts b/packages/ocap-kernel/src/Kernel.ts index d237d0426..afc4bec98 100644 --- a/packages/ocap-kernel/src/Kernel.ts +++ b/packages/ocap-kernel/src/Kernel.ts @@ -213,7 +213,7 @@ export class Kernel { const vatLogger = this.#logger.subLogger({ tags: [vatId] }); vatLogger.injectStream( loggerStream as unknown as Parameters[0], - (error) => console.error(stringify(error)), + (error) => this.#logger.error(`Vat ${vatId} error: ${stringify(error)}`), ); const vat = await VatHandle.make({ vatId, @@ -308,7 +308,7 @@ 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(this.#logger.error); this.#vats.delete(vatId); } From e46c9d19ded31fff3fb93ae786cf9c1386a43c7c Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 17:25:00 -0400 Subject: [PATCH 24/26] fix(logger): harden and document exports --- packages/logger/src/stream.ts | 35 ++++++++++++++++++++++++++++++++++- vitest.config.ts | 2 +- 2 files changed, 35 insertions(+), 2 deletions(-) diff --git a/packages/logger/src/stream.ts b/packages/logger/src/stream.ts index e72284960..82ca33b4d 100644 --- a/packages/logger/src/stream.ts +++ b/packages/logger/src/stream.ts @@ -19,6 +19,16 @@ export type LogMessage = JsonRpcCall & { params: ['logger', ...SerializedLogEntry]; }; +/** + * Serializes a log entry. + * + * @param entry - The log entry to serialize. + * @param entry.level - The log level. + * @param entry.tags - The log tags. + * @param entry.message - The log message. + * @param entry.data - The log data. + * @returns The serialized log entry. + */ export const lser = ({ level, tags, @@ -30,7 +40,14 @@ export const lser = ({ message ?? null, data?.map(stringify) ?? null, ]; +harden(lser); +/** + * Deserializes a log entry. + * + * @param params - The serialized log entry to deserialize. + * @returns The deserialized log entry. + */ export const lunser = (params: SerializedLogEntry): LogEntry => { const [level, tags, message, data] = params; const entry: LogEntry = { level, tags }; @@ -42,17 +59,33 @@ export const lunser = (params: SerializedLogEntry): LogEntry => { } return entry; }; +harden(lunser); +/** + * Checks if a message is a logger message. + * + * @param message - The message to check. + * @returns Whether the message is a logger message. + */ export const isLoggerMessage = ( message: JsonRpcMessage, ): message is LogMessage => isJsonRpcNotification(message) && (message as { params: { length: number } }).params.length > 0 && (message as { params: unknown[] }).params[0] === 'logger'; +harden(isLoggerMessage); +/** + * Checks if a message is a kernel message. A kernel message is any message + * which is not a logger message. + * + * @param message - The message to check. + * @returns Whether the message is a kernel message. + */ export const isKernelMessage = ( message: JsonRpcMessage, ): message is JsonRpcRequest => !isLoggerMessage(message); +harden(isKernelMessage); /** * Splits a stream into a kernel stream and a logger stream. @@ -60,7 +93,6 @@ export const isKernelMessage = ( * @param stream - The stream to split. * @returns An object containing the kernel stream and the logger stream. */ - export const splitLoggerStream = ( stream: DuplexStream, ): { @@ -77,3 +109,4 @@ export const splitLoggerStream = ( ]; return { kernelStream, loggerStream }; }; +harden(splitLoggerStream); diff --git a/vitest.config.ts b/vitest.config.ts index c752cfaea..38ee3be75 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -116,7 +116,7 @@ export default defineConfig({ lines: 100, }, 'packages/logger/**': { - statements: 98.43, + statements: 98.55, functions: 95.83, branches: 97.29, lines: 100, From 5282079954c5893a1ef9e6812cb52f6ca6c458bd Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Mon, 5 May 2025 17:31:41 -0400 Subject: [PATCH 25/26] fix(logger): harden bind output --- packages/logger/src/logger.ts | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/packages/logger/src/logger.ts b/packages/logger/src/logger.ts index ff71dbec1..9d35b588e 100644 --- a/packages/logger/src/logger.ts +++ b/packages/logger/src/logger.ts @@ -100,10 +100,12 @@ export class Logger { // Create aliases for the log methods, allowing them to be used in a // manner similar to the console object. const bind = (level: LogLevel): LogMethod => - this.#dispatch.bind(this, { - ...this.#options, - level, - }) as LogMethod; + harden( + this.#dispatch.bind(this, { + ...this.#options, + level, + }), + ) as LogMethod; this.log = bind('log'); this.debug = bind('debug'); this.info = bind('info'); From b01355a842a89cdd8a5acd53ae39de163bf5e137 Mon Sep 17 00:00:00 2001 From: grypez <143971198+grypez@users.noreply.github.com> Date: Tue, 6 May 2025 09:07:38 -0400 Subject: [PATCH 26/26] chore: lint --- vitest.config.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/vitest.config.ts b/vitest.config.ts index 38ee3be75..ca6ad97d7 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -142,4 +142,4 @@ export default defineConfig({ }, }, }, -}); \ No newline at end of file +});