Skip to content

Commit

Permalink
chore(swingset): add slogging framework
Browse files Browse the repository at this point in the history 
This adds a set of logging hooks which record swingset deliveries (the kernel
sending messages and resolution notifications into vats), syscalls (from the
vat into the kernel), and console messages. All these events can be
correlated by their crank number, vatID, delivery number, and syscall number.

The output function is not yet implemented; my notional plan is to log to
lines of JSON for now, and maybe move to a SQLite based store for later. I've
not written any analysis tools yet either.

I made a few refactorings to make things smoother:

* vats get their console object from `managerOptions.vatConsole`, rather than
  having the manager build it themselves, which makes it easier to provide
  one that writes to both the regular console and the slog
* as a result, all vats get the same basic `vatEndowments` (with the console
  added on later), rather than calling `makeVatEndowments(vatID)`
* in kernel.js, `deliverToVat` and `processNotify` had their common code
  factored out into `deliverAndLogToVat()`, which now writes to the slog
  in addition to actually performing the `manager.deliver`. The names aren't
  great and want to be changed at some point.
* `buildVatSyscallHandler` function was moved out of `addVatManager` to make
  things easier to read. The new function writes syscalls to the slog.
* console messages written by vats in top-level code, or during the execution
  of `buildRootObject`, are slogged in the "startup" phase. All other calls
  to `console.log` and friends are recorded in a "delivery" phase.

The slog is disabled during test-kernel.js and test-vpid-kernel.js, because
these tests make syscalls outside the context of a delivery, which is
normally illegal, and the slog complains bitterly when it happens.

refs #1535
  • Loading branch information
@warner
warner committed Aug 18, 2020
1 parent a4a173f commit 359c6f4
Show file tree
Hide file tree
Showing 9 changed files with 265 additions and 99 deletions.
24 changes: 15 additions & 9 deletions packages/SwingSet/src/controller.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -287,14 +287,12 @@ export async function buildVatController(
// the same is true for the tildot transform
const transformTildot = harden(makeTransform(babelParser, babelGenerate));

function makeVatEndowments(consoleTag) {
return harden({
console: makeConsole(`${debugPrefix}SwingSet:${consoleTag}`),
// re2 is a RegExp work-a-like that disables backtracking expressions for
// safer memory consumption
RegExp: re2,
});
}
// all vats get these in their global scope, plus a vat-specific 'console'
const vatEndowments = harden({
// re2 is a RegExp work-a-like that disables backtracking expressions for
// safer memory consumption
RegExp: re2,
});

const hostStorage = runtimeOptions.hostStorage || initSwingStore().storage;
insistStorageAPI(hostStorage);
Expand All @@ -320,15 +318,23 @@ export async function buildVatController(
return new Worker(supercode);
}

function writeSlogObject(_obj) {
// TODO sqlite
// console.log(`--slog ${JSON.stringify(obj)}`);
}

const kernelEndowments = {
waitUntilQuiescent,
hostStorage,
makeVatEndowments,
debugPrefix,
vatEndowments,
makeConsole,
replaceGlobalMeter,
transformMetering,
transformTildot,
makeNodeWorker,
startSubprocessWorker,
writeSlogObject,
};

const kernel = buildKernel(kernelEndowments);
Expand Down
2 changes: 2 additions & 0 deletions packages/SwingSet/src/kernel/dynamicVat.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ export function makeDynamicVatCreator(stuff) {
allocateUnusedVatID,
vatNameToID,
vatManagerFactory,
makeVatConsole,
addVatManager,
addExport,
queueToExport,
Expand Down Expand Up @@ -108,6 +109,7 @@ export function makeDynamicVatCreator(stuff) {
enableSetup: false,
enableInternalMetering: false,
notifyTermination: metered ? notifyTermination : undefined,
vatConsole: makeVatConsole(vatID),
vatParameters,
};
const manager = await vatManagerFactory(vatID, managerOptions);
Expand Down
157 changes: 92 additions & 65 deletions packages/SwingSet/src/kernel/kernel.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import { insistDeviceID, insistVatID } from './id';
import { makeMessageResult } from './messageResult';
import { makeMeterManager } from './metering';
import { makeKernelSyscallHandler } from './kernelSyscall';
import { makeSlogger, makeDummySlogger } from './slogger';

import { makeDynamicVatCreator } from './dynamicVat';
import { makeVatTranslators } from './vatTranslator';
Expand All @@ -38,19 +39,28 @@ function makeError(s) {
return harden({ body: JSON.stringify(s), slots: [] });
}

export default function buildKernel(kernelEndowments) {
export default function buildKernel(kernelEndowments, kernelOptions = {}) {
const {
waitUntilQuiescent,
hostStorage,
makeVatEndowments,
debugPrefix,
vatEndowments,
makeConsole,
replaceGlobalMeter,
transformMetering,
transformTildot,
makeNodeWorker,
startSubprocessWorker,
writeSlogObject,
} = kernelEndowments;
const { disableSlog = false } = kernelOptions;
insistStorageAPI(hostStorage);
const { enhancedCrankBuffer, commitCrank } = wrapStorage(hostStorage);

const kernelSlog = disableSlog
? makeDummySlogger(makeConsole)
: makeSlogger(writeSlogObject);

const kernelKeeper = makeKernelKeeper(enhancedCrankBuffer);

const meterManager = makeMeterManager(replaceGlobalMeter);
Expand Down Expand Up @@ -81,6 +91,11 @@ export default function buildKernel(kernelEndowments) {
}
harden(testLog);

function makeVatConsole(vatID) {
const origConsole = makeConsole(`${debugPrefix}SwingSet:${vatID}`);
return kernelSlog.vatConsole(vatID, origConsole);
}

// track results of externally-injected messages (queueToExport, bootstrap)
const pendingMessageResults = new Map(); // kpid -> messageResult

Expand Down Expand Up @@ -263,6 +278,29 @@ export default function buildKernel(kernelEndowments) {
}
}

async function deliverAndLogToVat(vatID, kernelDelivery, vatDelivery) {
const vat = ephemeral.vats.get(vatID);
const crankNum = kernelKeeper.getCrankNumber();
const finish = kernelSlog.delivery(
vatID,
crankNum,
kernelDelivery,
vatDelivery,
);
try {
const deliveryResult = await vat.manager.deliver(vatDelivery);
finish(deliveryResult);
// TODO: eventually
// if (deliveryResult === death) {
// vat.notifyTermination(deliveryResult.causeOfDeath);
// }
} catch (e) {
// log so we get a stack trace
console.error(`error in kernel.deliver:`, e);
throw e;
}
}

async function deliverToVat(vatID, target, msg) {
insistMessage(msg);
const vat = ephemeral.vats.get(vatID);
Expand All @@ -274,19 +312,7 @@ export default function buildKernel(kernelEndowments) {
} else {
const kd = harden(['message', target, msg]);
const vd = vat.translators.kernelDeliveryToVatDelivery(kd);
try {
await vat.manager.deliver(vd);
/* // TODO: eventually this will be as follows, once deliver can return a delivery status
const deliveryResult = await vat.manager.deliver(vd);
if (deliveryResult === death) {
vat.notifyTermination(deliveryResult.causeOfDeath);
}
*/
} catch (e) {
// log so we get a stack trace
console.error(`error in kernel.deliver:`, e);
throw e;
}
await deliverAndLogToVat(vatID, kd, vd);
}
}

Expand Down Expand Up @@ -362,19 +388,7 @@ export default function buildKernel(kernelEndowments) {
kernelKeeper.incStat(statNameForNotify(p.state));
const kd = harden(['notify', kpid, p]);
const vd = vat.translators.kernelDeliveryToVatDelivery(kd);
try {
await vat.manager.deliver(vd);
/* // TODO: eventually this will be as follows, once deliver can return a delivery status
const deliveryResult = await vat.manager.deliver(vd);
if (deliveryResult === death) {
vat.notifyTermination(deliveryResult.causeOfDeath);
}
*/
} catch (e) {
// log so we get a stack trace
console.error(`error in kernel.processNotify:`, e);
throw e;
}
await deliverAndLogToVat(vatID, kd, vd);
}
}

Expand Down Expand Up @@ -592,7 +606,7 @@ export default function buildKernel(kernelEndowments) {
const vatManagerFactory = makeVatManagerFactory({
allVatPowers,
kernelKeeper,
makeVatEndowments,
vatEndowments,
meterManager,
testLog,
transformMetering,
Expand All @@ -601,40 +615,7 @@ export default function buildKernel(kernelEndowments) {
startSubprocessWorker,
});

/*
* Take an existing VatManager (which is already configured to talk to a
* VatWorker, loaded with some vat code) and connect it to the rest of the
* kernel. The vat must be ready to go: any initial buildRootObject
* construction should have happened by this point. However the kernel
* might tell the manager to replay the transcript later, if it notices
* we're reloading a saved state vector.
*/
function addVatManager(vatID, manager, managerOptions) {
// addVatManager takes a manager, not a promise for one
assert(
manager.deliver && manager.setVatSyscallHandler,
`manager lacks .deliver, isPromise=${manager instanceof Promise}`,
);

const {
enablePipelining = false,
notifyTermination = () => {},
} = managerOptions;
// This should create the vatKeeper. Other users get it from the
// kernelKeeper, so we don't need a reference ourselves.
kernelKeeper.allocateVatKeeperIfNeeded(vatID);
const translators = makeVatTranslators(vatID, kernelKeeper);

ephemeral.vats.set(
vatID,
harden({
translators,
manager,
notifyTermination,
enablePipelining: Boolean(enablePipelining),
}),
);

function buildVatSyscallHandler(vatID, translators) {
// This handler never throws. The VatSyscallResult it returns is one of:
// * success, no response data: ['ok', null]
// * success, capdata (callNow) ['ok', capdata]
Expand All @@ -661,6 +642,7 @@ export default function buildKernel(kernelEndowments) {
return harden(['error', 'clist violation: prepare to die']);
}

const finish = kernelSlog.syscall(vatID, ksc, vatSyscallObject);
let vres;
try {
// this can fail if kernel or device code is buggy
Expand All @@ -674,6 +656,7 @@ export default function buildKernel(kernelEndowments) {
// capdata.
vres = translators.kernelSyscallResultToVatSyscallResult(kres);
// here, vres is either ['ok', null] or ['ok', capdata]
finish(kres, vres); // TODO call meaningfully on failure too?
} catch (err) {
// kernel/device errors cause a kernel panic
panic(`error during syscall/device.invoke: ${err}`, err);
Expand All @@ -684,6 +667,43 @@ export default function buildKernel(kernelEndowments) {

return vres;
}
return vatSyscallHandler;
}

/*
* Take an existing VatManager (which is already configured to talk to a
* VatWorker, loaded with some vat code) and connect it to the rest of the
* kernel. The vat must be ready to go: any initial buildRootObject
* construction should have happened by this point. However the kernel
* might tell the manager to replay the transcript later, if it notices
* we're reloading a saved state vector.
*/
function addVatManager(vatID, manager, managerOptions) {
// addVatManager takes a manager, not a promise for one
assert(
manager.deliver && manager.setVatSyscallHandler,
`manager lacks .deliver, isPromise=${manager instanceof Promise}`,
);
const {
enablePipelining = false,
notifyTermination = () => {},
} = managerOptions;
// This should create the vatKeeper. Other users get it from the
// kernelKeeper, so we don't need a reference ourselves.
kernelKeeper.allocateVatKeeperIfNeeded(vatID);
const translators = makeVatTranslators(vatID, kernelKeeper);

ephemeral.vats.set(
vatID,
harden({
translators,
manager,
notifyTermination,
enablePipelining: Boolean(enablePipelining),
}),
);

const vatSyscallHandler = buildVatSyscallHandler(vatID, translators);
manager.setVatSyscallHandler(vatSyscallHandler);
}

Expand Down Expand Up @@ -715,6 +735,7 @@ export default function buildKernel(kernelEndowments) {
allocateUnusedVatID: kernelKeeper.allocateUnusedVatID,
vatNameToID,
vatManagerFactory,
makeVatConsole,
addVatManager,
addExport,
queueToExport,
Expand Down Expand Up @@ -783,11 +804,16 @@ export default function buildKernel(kernelEndowments) {

// instantiate all genesis vats
for (const name of genesisVats.keys()) {
const managerOptions = genesisVats.get(name);
const vatID = kernelKeeper.allocateVatIDForNameIfNeeded(name);
console.debug(`Assigned VatID ${vatID} for genesis vat ${name}`);
const managerOptions = harden({
...genesisVats.get(name),
vatConsole: makeVatConsole(vatID),
});
const finish = kernelSlog.startup(vatID);
// eslint-disable-next-line no-await-in-loop
const manager = await vatManagerFactory(vatID, managerOptions);
finish();
addVatManager(vatID, manager, managerOptions);
}

Expand Down Expand Up @@ -833,10 +859,11 @@ export default function buildKernel(kernelEndowments) {
const deviceID = kernelKeeper.allocateDeviceIDForNameIfNeeded(name);
console.debug(`Assigned DeviceID ${deviceID} for genesis device ${name}`);
const { bundle, endowments: devEndowments } = genesisDevices.get(name);
const devConsole = makeConsole(`${debugPrefix}SwingSet:dev-${name}`);
// eslint-disable-next-line no-await-in-loop
const NS = await importBundle(bundle, {
filePrefix: `dev-${name}`,
endowments: makeVatEndowments(`dev-${name}`),
endowments: harden({ ...vatEndowments, console: devConsole }),
});
assert(
typeof NS.buildRootDeviceNode === 'function',
Expand Down
2 changes: 1 addition & 1 deletion packages/SwingSet/src/kernel/kernelSyscall.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -148,7 +148,7 @@ export function makeKernelSyscallHandler(tools) {
}

const kernelSyscallHandler = harden({
send,
send, // TODO remove these individual ones
invoke,
subscribe,
fulfillToPresence,
Expand Down
Loading

0 comments on commit 359c6f4

Please sign in to comment.