add "slog": swingset logging for replay-based debugging

[warner]

What is the Problem Being Solved?

One feature described in our #1318 survey is the ability to fetch historical turn data from one swingset (i.e. the chain) and rebuild one vat locally, where regular JS debugging tools can be applied. The same data can be used to simply visualize the sequence of operations in a swingset kernel. I'm currently working on new message-pattern tests (for #1404 and #1534) which trigger a dozen-ish vat messages across two kernels, and it would be tremendously useful if I could run one command and dump the sequence of events, with some support for tracing a single object/promise reference across the various vats and comms layers involved.

Description of the Design

My working title is the slog (short for Swingset Log, but of course it also describes the debugging process you're probably going through). The core is an append-only ordered set of records, notionally stored in a SQLite database (but I haven't really committed to anything on the IO end yet).

Each crank gets a pair of records, describing the start (was it a delivery or a notify? which vat was the recipient? message target, method name, arguments, result promise ID) and end (delivery consequences: was the vat killed? metering fault?) of the crank. Within the crank, each syscall made by the vat gets a pair of records (syscall name, arguments, result). Also within the crank, any calls to console.log will have their contents recorded.

All of these records are correlated, so an interactive display tool can tell you which delivery caused the vat to emit a given console.log message. Or it can show you all the deliveries that arrived at a given vat, and then expand that into a list of syscalls and log messages. Also, a message sent by one vat in a syscall can be correlated with the delivery made to the target vat on some later crank.

I also plan to correlate the object/promise IDs across the different vats, and the kernel. If you mouse over o+3 in one vat, any kernel log which mentions the matching ko21 should be highlighted, as well as any other vat deliveries that include it, along with the recipient vat-local o-7 which the c-list matches.

The kernel will have an object named kernelSlog to which the deliveries can be added. This will return a vatDeliverySlog object, which will be added to the vatManager.deliver call (making it vatManager.deliver(vatDeliveryObject, vatDeliverySlog), as well as a finish() function that the kernel should call with the delivery results. The vatDeliverySlog will have methods for recording syscalls, as well as console log messages. Each vatManager needs to arrange for the console endowment they provide to vats to send a copy of their messages to this slog function, as well as to the normal console.

Security Considerations

For now I plan to just write these log records to a local file, so any attacker in a position to read the swingset's secrets would also be able to just read the entire kernelDB. This is irrelevant for a transparent public chain, but private swingsets should be able to keep secrets, and the slog should not present a vector for confidentiality loss.

But in the future, I want a way to point a tool at a running process and extract the records remotely. Back in Tahoe-LAFS I used Foolscap and a webkey-style cap-as-password URL for this. I think I'll need to develop a new networking layer for our purposes, maybe just websockets with an access token for now (only safe when run over the loopback/localhost interface). But eventually I'd like to do the crypto properly, and that might overlap a lot with the encrypted protocol we use for solo-to-solo VatTP communication.

Test Plan

I don't intend to add a lot of unit tests for this right now. As the benefit is for debugging, I'll be content with knowing that the new code doesn't make anything crash. Later I'll add some basic tests to run a simple vat and make sure the emitted events contain the data I expect.

I'll probably put the analysis/dumping tools in a misc/ directory to start, but then they'll move to a separate package. I'm planning on a web-based UI for the cross-vat tracing, which might eventually want some modern web frameworks (D3 might be useful/appropriate), and I wouldn't want to add those dependencies to swingset itself. I'll probably do the bare minimum of automated testing on these tools (partially because I don't have a lot of experience with those sorts of tests).

[FUDCo]

The debugging pattern described here is more or less the same process I go through manually now, running the kernel in verbose mode and capturing the results to a log file, then massaging the log file in emacs to boil out the information that's relevant to the problem I'm trying to diagnose. In more extreme cases, taking a series of dumps of the kernel database (particularly the transcript) has been helpful, particularly when I was working on the retirement of settled promises. However, the fact that I've been able to do this at all suggests that a lot of the underlying machinery we need for this is already in place, and that much of the work will be in systematizing and codifying things (and, of course, probably a lot of effort on the UI side). Having more automation here would be a tremendous time savings. This seems a like a very good application of the "observe what you already do the hard way, then automate that" principle.

[Tartuffo]

@warner Is this done or still relevant? Let's close if not needed.

[dckc]

this is pretty clearly done