Skip to content

Commit 6493eae

Browse files
grypezgrypez
committed
feat(kernel): use logger
1 parent 73ee1ad commit 6493eae

File tree

8 files changed

+169
-61
lines changed

8 files changed

+169
-61
lines changed

‎packages/kernel/src/Kernel.ts‎

Lines changed: 34 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -247,7 +247,7 @@ export class Kernel {
247247
await this.#replyToCommand({ method, params: 'pong' });
248248
break;
249249
default:
250-
console.error(
250+
this.#logger.error(
251251
'kernel worker received unexpected command',
252252
// @ts-expect-error Compile-time exhaustiveness check
253253
{ method: method.valueOf(), params },
@@ -341,15 +341,23 @@ export class Kernel {
341341
if (this.#vats.has(vatId)) {
342342
throw new VatAlreadyExistsError(vatId);
343343
}
344-
const commandStream = await this.#vatWorkerService.launch(vatId, vatConfig);
345-
const vat = await VatHandle.make({
346-
kernel: this,
344+
345+
// Create a child logger with the vat's ID
346+
const vatLogger = makeLogger(`[vat ${vatId}]`, this.#logger);
347+
348+
const vatStream = await this.#vatWorkerService.launch(vatId, vatConfig);
349+
350+
this.#vats.set(
347351
vatId,
348-
vatConfig,
349-
vatStream: commandStream,
350-
kernelStore: this.#kernelStore,
351-
});
352-
this.#vats.set(vatId, vat);
352+
await VatHandle.make({
353+
kernel: this,
354+
vatId,
355+
vatConfig,
356+
vatStream,
357+
kernelStore: this.#kernelStore,
358+
logger: vatLogger,
359+
}),
360+
);
353361
}
354362

355363
/**
@@ -515,14 +523,13 @@ export class Kernel {
515523
* @param item - The message/notification to deliver.
516524
*/
517525
async #deliver(item: RunQueueItem): Promise<void> {
518-
const { log } = console;
519526
switch (item.type) {
520527
case 'send': {
521528
const route = this.#routeMessage(item);
522529
if (route) {
523530
const { vatId, target } = route;
524531
const { message } = item;
525-
log(
532+
this.#logger.log(
526533
`@@@@ deliver ${vatId} send ${target}<-${JSON.stringify(message)}`,
527534
);
528535
if (vatId) {
@@ -543,7 +550,9 @@ export class Kernel {
543550
} else {
544551
this.#kernelStore.enqueuePromiseMessage(target, message);
545552
}
546-
log(`@@@@ done ${vatId} send ${target}<-${JSON.stringify(message)}`);
553+
this.#logger.log(
554+
`@@@@ done ${vatId} send ${target}<-${JSON.stringify(message)}`,
555+
);
547556
}
548557
break;
549558
}
@@ -555,7 +564,7 @@ export class Kernel {
555564
context === 'kernel' && isPromise,
556565
`${kpid} is not a kernel promise`,
557566
);
558-
log(`@@@@ deliver ${vatId} notify ${vatId} ${kpid}`);
567+
this.#logger.log(`@@@@ deliver ${vatId} notify ${vatId} ${kpid}`);
559568
const promise = this.#kernelStore.getKernelPromise(kpid);
560569
const { state, value } = promise;
561570
assert(value, `no value for promise ${kpid}`);
@@ -588,39 +597,39 @@ export class Kernel {
588597
}
589598
const vat = this.#getVat(vatId);
590599
await vat.deliverNotify(resolutions);
591-
log(`@@@@ done ${vatId} notify ${vatId} ${kpid}`);
600+
this.#logger.log(`@@@@ done ${vatId} notify ${vatId} ${kpid}`);
592601
break;
593602
}
594603
case 'dropExports': {
595604
const { vatId, krefs } = item;
596-
log(`@@@@ deliver ${vatId} dropExports`, krefs);
605+
this.#logger.log(`@@@@ deliver ${vatId} dropExports`, krefs);
597606
const vat = this.#getVat(vatId);
598607
await vat.deliverDropExports(krefs);
599-
log(`@@@@ done ${vatId} dropExports`, krefs);
608+
this.#logger.log(`@@@@ done ${vatId} dropExports`, krefs);
600609
break;
601610
}
602611
case 'retireExports': {
603612
const { vatId, krefs } = item;
604-
log(`@@@@ deliver ${vatId} retireExports`, krefs);
613+
this.#logger.log(`@@@@ deliver ${vatId} retireExports`, krefs);
605614
const vat = this.#getVat(vatId);
606615
await vat.deliverRetireExports(krefs);
607-
log(`@@@@ done ${vatId} retireExports`, krefs);
616+
this.#logger.log(`@@@@ done ${vatId} retireExports`, krefs);
608617
break;
609618
}
610619
case 'retireImports': {
611620
const { vatId, krefs } = item;
612-
log(`@@@@ deliver ${vatId} retireImports`, krefs);
621+
this.#logger.log(`@@@@ deliver ${vatId} retireImports`, krefs);
613622
const vat = this.#getVat(vatId);
614623
await vat.deliverRetireImports(krefs);
615-
log(`@@@@ done ${vatId} retireImports`, krefs);
624+
this.#logger.log(`@@@@ done ${vatId} retireImports`, krefs);
616625
break;
617626
}
618627
case 'bringOutYourDead': {
619628
const { vatId } = item;
620-
log(`@@@@ deliver ${vatId} bringOutYourDead`);
629+
this.#logger.log(`@@@@ deliver ${vatId} bringOutYourDead`);
621630
const vat = this.#getVat(vatId);
622631
await vat.deliverBringOutYourDead();
623-
log(`@@@@ done ${vatId} bringOutYourDead`);
632+
this.#logger.log(`@@@@ done ${vatId} bringOutYourDead`);
624633
break;
625634
}
626635
default:
@@ -813,7 +822,9 @@ export class Kernel {
813822
throw new VatNotFoundError(vatId);
814823
}
815824
await vat.terminate(terminating);
816-
await this.#vatWorkerService.terminate(vatId).catch(console.error);
825+
await this.#vatWorkerService.terminate(vatId).catch((error) => {
826+
this.#logger.error('Error terminating vat worker:', error);
827+
});
817828
this.#vats.delete(vatId);
818829
}
819830

‎packages/kernel/src/VatHandle.ts‎

Lines changed: 25 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -396,60 +396,74 @@ export class VatHandle {
396396
const kso: VatSyscallObject = this.#translateSyscallVtoK(vso);
397397
const [op] = kso;
398398
const { vatId } = this;
399-
const { log } = console;
399+
400400
switch (op) {
401401
case 'send': {
402402
// [KRef, Message];
403403
const [, target, message] = kso;
404-
log(`@@@@ ${vatId} syscall send ${target}<-${JSON.stringify(message)}`);
404+
this.#logger.log(
405+
`@@@@ ${vatId} syscall send ${target}<-${JSON.stringify(message)}`,
406+
);
405407
this.#handleSyscallSend(target, message);
406408
break;
407409
}
408410
case 'subscribe': {
409411
// [KRef];
410412
const [, promise] = kso;
411-
log(`@@@@ ${vatId} syscall subscribe ${promise}`);
413+
this.#logger.log(`@@@@ ${vatId} syscall subscribe ${promise}`);
412414
this.#handleSyscallSubscribe(promise);
413415
break;
414416
}
415417
case 'resolve': {
416418
// [VatOneResolution[]];
417419
const [, resolutions] = kso;
418-
log(`@@@@ ${vatId} syscall resolve ${JSON.stringify(resolutions)}`);
420+
this.#logger.log(
421+
`@@@@ ${vatId} syscall resolve ${JSON.stringify(resolutions)}`,
422+
);
419423
this.#handleSyscallResolve(resolutions as VatOneResolution[]);
420424
break;
421425
}
422426
case 'exit': {
423427
// [boolean, SwingSetCapData];
424428
const [, fail, info] = kso;
425-
log(`@@@@ ${vatId} syscall exit fail=${fail} ${JSON.stringify(info)}`);
429+
this.#logger.log(
430+
`@@@@ ${vatId} syscall exit fail=${fail} ${JSON.stringify(info)}`,
431+
);
426432
break;
427433
}
428434
case 'dropImports': {
429435
// [KRef[]];
430436
const [, refs] = kso;
431-
log(`@@@@ ${vatId} syscall dropImports ${JSON.stringify(refs)}`);
437+
this.#logger.log(
438+
`@@@@ ${vatId} syscall dropImports ${JSON.stringify(refs)}`,
439+
);
432440
this.#handleSyscallDropImports(refs);
433441
break;
434442
}
435443
case 'retireImports': {
436444
// [KRef[]];
437445
const [, refs] = kso;
438-
log(`@@@@ ${vatId} syscall retireImports ${JSON.stringify(refs)}`);
446+
this.#logger.log(
447+
`@@@@ ${vatId} syscall retireImports ${JSON.stringify(refs)}`,
448+
);
439449
this.#handleSyscallRetireImports(refs);
440450
break;
441451
}
442452
case 'retireExports': {
443453
// [KRef[]];
444454
const [, refs] = kso;
445-
log(`@@@@ ${vatId} syscall retireExports ${JSON.stringify(refs)}`);
455+
this.#logger.log(
456+
`@@@@ ${vatId} syscall retireExports ${JSON.stringify(refs)}`,
457+
);
446458
this.#handleSyscallExportCleanup(refs, true);
447459
break;
448460
}
449461
case 'abandonExports': {
450462
// [KRef[]];
451463
const [, refs] = kso;
452-
log(`@@@@ ${vatId} syscall abandonExports ${JSON.stringify(refs)}`);
464+
this.#logger.log(
465+
`@@@@ ${vatId} syscall abandonExports ${JSON.stringify(refs)}`,
466+
);
453467
this.#handleSyscallExportCleanup(refs, false);
454468
break;
455469
}
@@ -458,13 +472,13 @@ export class VatHandle {
458472
case 'vatstoreGetNextKey':
459473
case 'vatstoreSet':
460474
case 'vatstoreDelete': {
461-
console.warn(`vat ${vatId} issued invalid syscall ${op} `, vso);
475+
this.#logger.warn(`vat ${vatId} issued invalid syscall ${op} `, vso);
462476
break;
463477
}
464478
default:
465479
// Compile-time exhaustiveness check
466480
// eslint-disable-next-line @typescript-eslint/restrict-template-expressions
467-
console.warn(`vat ${vatId} issued unknown syscall ${op} `, vso);
481+
this.#logger.warn(`vat ${vatId} issued unknown syscall ${op} `, vso);
468482
break;
469483
}
470484
}

‎packages/kernel/src/VatSupervisor.test.ts‎

Lines changed: 19 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import '@ocap/test-utils';
22
import { TestDuplexStream } from '@ocap/test-utils/streams';
3-
import { delay } from '@ocap/utils';
3+
import type { Logger } from '@ocap/utils';
4+
import { delay, makeLogger } from '@ocap/utils';
45
import { describe, it, expect, vi } from 'vitest';
56

67
import { VatCommandMethod } from './messages/index.ts';
@@ -27,7 +28,9 @@ const makeVatSupervisor = async (
2728
): Promise<{
2829
supervisor: VatSupervisor;
2930
stream: TestDuplexStream<VatCommand, VatCommandReply>;
31+
logger: Logger;
3032
}> => {
33+
const logger = makeLogger('[test-vat-supervisor]');
3134
const commandStream = await TestDuplexStream.make<
3235
VatCommand,
3336
VatCommandReply
@@ -37,8 +40,10 @@ const makeVatSupervisor = async (
3740
id: 'test-id',
3841
commandStream,
3942
vatPowers: vatPowers ?? {},
43+
logger,
4044
}),
4145
stream: commandStream,
46+
logger,
4247
};
4348
};
4449

@@ -51,32 +56,38 @@ describe('VatSupervisor', () => {
5156
});
5257

5358
it('throws if the stream throws', async () => {
54-
const { supervisor, stream } = await makeVatSupervisor();
55-
const consoleErrorSpy = vi.spyOn(console, 'error');
59+
const { supervisor, stream, logger } = await makeVatSupervisor();
60+
const errorSpy = vi
61+
.spyOn(logger, 'error')
62+
.mockImplementation(() => undefined);
5663
await stream.receiveInput(NaN);
5764
await delay(10);
58-
expect(consoleErrorSpy).toHaveBeenCalledWith(
65+
expect(errorSpy).toHaveBeenCalledWith(
5966
`Unexpected read error from VatSupervisor "${supervisor.id}"`,
6067
expect.any(Error),
6168
);
69+
errorSpy.mockRestore();
6270
});
6371
});
6472

6573
describe('handleMessage', () => {
6674
it('throws if receiving an unexpected message', async () => {
67-
const { supervisor, stream } = await makeVatSupervisor();
75+
const { supervisor, stream, logger } = await makeVatSupervisor();
6876

69-
const consoleErrorSpy = vi.spyOn(console, 'error');
77+
const errorSpy = vi
78+
.spyOn(logger, 'error')
79+
.mockImplementation(() => undefined);
7080
await stream.receiveInput({
7181
channel: 'command',
7282
payload: { method: 'test' },
7383
});
7484
await delay(10);
75-
expect(consoleErrorSpy).toHaveBeenCalledOnce();
76-
expect(consoleErrorSpy).toHaveBeenCalledWith(
85+
expect(errorSpy).toHaveBeenCalledOnce();
86+
expect(errorSpy).toHaveBeenCalledWith(
7787
`Unexpected read error from VatSupervisor "${supervisor.id}"`,
7888
new Error(`VatSupervisor received unexpected command method: "test"`),
7989
);
90+
errorSpy.mockRestore();
8091
});
8192

8293
it('handles Ping messages', async () => {

0 commit comments

Comments
 (0)