Skip to content

Commit

Permalink
feat(SwingSet): Echo kernel console output to the slog (#10925)
Browse files Browse the repository at this point in the history
Fixes #10776

## Description
After a lot of refactoring, makes the relatively simple change of endowing the compartment in which the kernel runs with a console whose methods are augmented to write slog entries. Best reviewed by commit.

### Security Considerations
Security posture should not be affected.

### Scaling Considerations
The slog will gain new entries, but kernel logging tends to be reasonably small AFAIK.

### Documentation Considerations
Anything consuming slogfiles (such as for telemetry reporting) should be prepared to encounter entries with type "console" and source "kernel".

### Testing Considerations
Manual confirmation per #10776:

<details><summary>slog excerpts</summary>

```json
{"type":"terminate","vatID":"v12","shouldReject":false,"info":{"body":"#\"payment retrieved\"","slots":[]},"time":1738358161.052329,"monotime":71.14055863702298}
{"type":"console","source":"kernel","args":["kernel terminating vat v12 (failure=false)"],"time":1738358161.052675,"monotime":71.14090518701076}
{"type":"crank-finish","crankNum":407,"crankhash":"38659f7b8b9b1628e74ca7fdd0fef9d8a4706ddf6cd78e8698aae891c558ffb2","activityhash":"b5bb680d4f6641fa9256fb68672d1fd0644462930576b0b08f4f8ba6ed80dcd9","time":1738358161.059831,"monotime":71.14806092399358}
{"type":"crank-start","crankType":"routing","crankNum":408,"message":{"type":"send","target":"ko107","msg":{"methargs":{"body":"#[\"exitAllSeats\",[\"payment retrieved\"]]","slots":[]},"result":"kp140"}},"time":1738358161.06028,"monotime":71.14851041698456}
{"type":"crank-finish","crankNum":408,"crankhash":"994c78a3c5c6cecd51f656cf7202b7ee7e1d594e0c8bf5440b0b5d3d2ddffeb3","activityhash":"12eabf17b96cd47b11554750cc910e01110fbb33e40ba7fa8d63f0d120946ecf","time":1738358161.060456,"monotime":71.1486860319972}
{"type":"crank-start","crankType":"routing","crankNum":409,"message":{"type":"notify","vatID":"v1","kpid":"kp139"},"time":1738358161.060624,"monotime":71.14885371297598}
```
```json
{"type":"crank-finish","crankNum":5051,"crankhash":"c541bb4757bf6a14f5f889d1d1d1864a4aa0c4cc69f64463c10c6827b6a1d7aa","activityhash":"dc641db0486240e2a15f86f88ee8caa9440803b4f818f9b262f4204d763f6594","time":1738358367.758784,"monotime":277.8470162190199}
{"type":"crank-start","crankType":"delivery","crankNum":5052,"message":{"type":"send","target":"ko349","msg":{"methargs":{"body":"#[\"update\",[\"osmosis-1_shido__9008-1\",{\"client_id\":\"07-tendermint-3198\",\"counterparty\":{\"client_id\":\"07-tendermint-0\",\"connection_id\":\"connection-0\"},\"id\":\"connection-2654\",\"state\":3,\"transferChannel\":{\"channelId\":\"channel-73755\",\"counterPartyChannelId\":\"channel-0\",\"counterPartyPortId\":\"transfer\",\"ordering\":0,\"portId\":\"transfer\",\"state\":3,\"version\":\"ics20-1\"}}]]","slots":[]},"result":"kp1257"}},"time":1738358367.7592,"monotime":277.8474297670126}
{"type":"clist","crankNum":5052,"mode":"import","vatID":"v6","kobj":"kp1257","vobj":"p-394","time":1738358367.759473,"monotime":277.84770355999467}
{"type":"deliver","crankNum":5052,"vatID":"v6","deliveryNum":599,"replay":false,"kd":["message","ko349",{"methargs":{"body":"#[\"update\",[\"osmosis-1_shido__9008-1\",{\"client_id\":\"07-tendermint-3198\",\"counterparty\":{\"client_id\":\"07-tendermint-0\",\"connection_id\":\"connection-0\"},\"id\":\"connection-2654\",\"state\":3,\"transferChannel\":{\"channelId\":\"channel-73755\",\"counterPartyChannelId\":\"channel-0\",\"counterPartyPortId\":\"transfer\",\"ordering\":0,\"portId\":\"transfer\",\"state\":3,\"version\":\"ics20-1\"}}]]","slots":[]},"result":"kp1257"}],"vd":["message","o+d10/10:0",{"methargs":{"body":"#[\"update\",[\"osmosis-1_shido__9008-1\",{\"client_id\":\"07-tendermint-3198\",\"counterparty\":{\"client_id\":\"07-tendermint-0\",\"connection_id\":\"connection-0\"},\"id\":\"connection-2654\",\"state\":3,\"transferChannel\":{\"channelId\":\"channel-73755\",\"counterPartyChannelId\":\"channel-0\",\"counterPartyPortId\":\"transfer\",\"ordering\":0,\"portId\":\"transfer\",\"state\":3,\"version\":\"ics20-1\"}}]]","slots":[]},"result":"p-394"}],"time":1738358367.759596,"monotime":277.8478261709809}
{"type":"console","source":"kernel","args":["error in kernel.deliver:",{"name":"ExitSignal","code":"SIGINT"}],"time":1738358367.780067,"monotime":277.86829756200314}
```

</details>

### Upgrade Considerations
This tweaks some typing in packages/swingset-liveslots/src/liveslots.js and adds some utilities to package "internal", but everything else is kernel code that is not subject to and does not affect consensus.

Release verification should look for slog entries like the above (type "console" and source "kernel").
  • Loading branch information
mergify[bot] authored Feb 20, 2025
2 parents dc77e16 + 89c0327 commit 07cb543
Show file tree
Hide file tree
Showing 19 changed files with 283 additions and 244 deletions.
69 changes: 37 additions & 32 deletions packages/SwingSet/src/controller/controller.js
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ import { initSwingStore } from '@agoric/swing-store';
import { mustMatch, M } from '@endo/patterns';
import { checkBundle } from '@endo/check-bundle/lite.js';
import { deepCopyJsonable } from '@agoric/internal/src/js-utils.js';
import { makeLimitedConsole } from '@agoric/internal/src/ses-utils.js';
import engineGC from '@agoric/internal/src/lib-nodejs/engine-gc.js';
import { startSubprocessWorker } from '@agoric/internal/src/lib-nodejs/spawnSubprocessWorker.js';
import { waitUntilQuiescent } from '@agoric/internal/src/lib-nodejs/waitUntilQuiescent.js';
Expand Down Expand Up @@ -56,34 +57,32 @@ export function computeSha512(bytes) {
return hash.digest().toString('hex');
}

/** @param {string | ((args: unknown[]) => string)} tagOrTagCreator */
function makeConsole(tagOrTagCreator) {
/** @type {(level: string) => (args: unknown[]) => void} */
let makeLoggerForLevel;
if (typeof tagOrTagCreator === 'function') {
const tagToLogger = new Map();
makeLoggerForLevel =
level =>
(...args) => {
// Retrieve the logger from cache.
const tag = tagOrTagCreator(args);
let logger = tagToLogger.get(tag);
if (!logger) {
logger = anylogger(tag);
tagToLogger.set(tag, logger);
}
// Actually log the message.
return logger[level](...args);
};
} else {
const logger = anylogger(tagOrTagCreator);
makeLoggerForLevel = level => logger[level];
}
const cons = {};
for (const level of ['debug', 'log', 'info', 'warn', 'error']) {
cons[level] = makeLoggerForLevel(level);
/**
* Make logger functions from either a prefix string or a function that receives
* the first argument of a log-method invocation and returns a replacement that
* provides more detail for source identification.
*
* @param {string | ((originalSource: unknown) => string)} prefixer
*/
function makeConsole(prefixer) {
if (typeof prefixer !== 'function') {
const logger = anylogger(prefixer);
return makeLimitedConsole(level => logger[level]);
}
return harden(cons);

const prefixToLogger = new Map();
return makeLimitedConsole(level => {
return (source, ...args) => {
const prefix = prefixer(source);
let logger = prefixToLogger.get(prefix);
if (!logger) {
logger = anylogger(prefix);
prefixToLogger.set(prefix, logger);
}

return logger[level](...args);
};
});
}

/**
Expand Down Expand Up @@ -213,17 +212,23 @@ export async function makeSwingsetController(
process.on('unhandledRejection', unhandledRejectionHandler);
}

function kernelRequire(what) {
Fail`kernelRequire unprepared to satisfy require(${what})`;
}
const kernelConsole = makeConsole(`${debugPrefix}SwingSet:kernel`);
const sloggingKernelConsole = makeLimitedConsole(level => {
return (...args) => {
kernelConsole[level](...args);
writeSlogObject({ type: 'console', source: 'kernel', args });
};
});
writeSlogObject({ type: 'import-kernel-start' });
const kernelNS = await importBundle(kernelBundle, {
filePrefix: 'kernel/...',
endowments: {
console: makeConsole(`${debugPrefix}SwingSet:kernel`),
console: sloggingKernelConsole,
// See https://github.com/Agoric/agoric-sdk/issues/9515
assert: globalThis.assert,
require: kernelRequire,
require: harden(
what => Fail`kernelRequire unprepared to satisfy require(${what})`,
),
URL: globalThis.Base64, // Unavailable only on XSnap
Base64: globalThis.Base64, // Available only on XSnap
},
Expand Down
10 changes: 4 additions & 6 deletions packages/SwingSet/src/kernel/kernel.js
Original file line number Diff line number Diff line change
Expand Up @@ -110,11 +110,10 @@ export default function buildKernel(
warehousePolicy,
overrideVatManagerOptions = {},
} = kernelRuntimeOptions;
const logStartup = verbose ? console.debug : () => 0;
const logStartup = verbose ? console.debug : () => {};

const vatAdminRootKref = kernelStorage.kvStore.get('vatAdminRootKref');

/** @type { KernelSlog } */
const kernelSlog = writeSlogObject
? makeSlogger(slogCallbacks, writeSlogObject)
: makeDummySlogger(slogCallbacks, makeConsole('disabled slogger'));
Expand Down Expand Up @@ -167,10 +166,9 @@ export default function buildKernel(
harden(testLog);

function makeSourcedConsole(vatID) {
const origConsole = makeConsole(args => {
const source = args.shift();
return `${debugPrefix}SwingSet:${source}:${vatID}`;
});
const origConsole = makeConsole(
source => `${debugPrefix}SwingSet:${source}:${vatID}`,
);
return kernelSlog.vatConsole(vatID, origConsole);
}

Expand Down
Loading

0 comments on commit 07cb543

Please sign in to comment.