warner
commented
4 years ago Foolscap
Foolscap (home page and github project) is a remote messaging system I built in 2006, inspired by CapTP/VatTP and ocap principles. It is written in Python, which is a bit too permissive to really support ocap confinement, but of course I found that following the rules anyways led to better partitioning of functionality and code that was easier to read. The networking stack was based on Twisted. The primary customer was the Tahoe-LAFS distributed+encrypted storage system (which I co-authored in 2008), although it was overkill and Tahoe is now moving to a simpler system.
In Foolscap, every remotely-accessible object had a "FURL", the Foolscap URL (SturdyRef-as-data), which was shaped like a web-key: pb://TUBID@CONNECTION-HINTS/SWISSNUM. Foolscap provides arbitrary-object-graph serialization of arguments and return values, TLS-based transport security (the FURL's TUBID is a hash of the expected TLS certificate), and a Promise-like eventual-send mechanism based on Twisted's Deferred (but lacking promise-pipelining). The Foolscap "Tub" was like an E "Vat", and hosted the main APIs. Programs could either connect to a FURL once:
def gotRef(remoteReference):
remoteReference.callRemote("hello", arg1, arg2).addCallback(handleResponse)
tub.getReference(FURL).addCallback(gotRef)or they could use a reconnect-on-failure tub.connectTo(FURL, connectHandler) API to maintain a connection despite interruptions.
Foolscap also includes a logging system with a detailed philosophy document. I wrote this to support several aspects of Tahoe:
- A UI request (like "upload this file") might provoke a hierarchy of lower-level operations, many of which involved messages to remote systems. To upload, we must find active storage servers, query them for available space, encrypt segments of the file, erasure-code the ciphertext, upload the shares to selected servers, confirm arrival, and finally return a cryptographic "filecap" to the caller. I wanted to be able to correlate the lower-level operations and the higher-level requests.
- Tahoe did a lot of work for each file, and didn't transfer as fast as we would have liked. Many operations could be optimized if we knew how long they took. Some of the logged data included runtimes, and the status/results UI could show what speeds the various phases (encrypt, encode, push) of an upload were achieving.
- The code had extensive invariant checks, which were occasionally violated. When something went wrong, we really wanted to know what was the higher-level operation that provoked it. The exception raised was the last page of a tale of woe, and to fix things we needed to know the path which led up to that moment.
- Tahoe-LAFS was an open-source product of a commercial backup startup, and we ran a fleet of managed storage servers (each running the same code an individual user might run). If something funny happened on one of those servers, we wanted to know about it.
- We had some known bugs which occasionally triggered warnings, but were sufficiently low-priority that we didn't get around to fixing them. Part of the logging system could classify these "Incidents" (according to filters that we wrote once we identified the known-bug), and set them aside (with a counter). We could get flagged if any new incidents occurred, or if the rate of the known problem rose above a threshold.
The Logging API
Foolscap's core logging API was a simple function log.msg(format, level, parent, **details), where everything was optional except the format string (**details is Python syntax for a collection of keyword arguments, as a dictionary). On its own, this recorded (format, details) into a JSON-serializable record, so log.msg("uploading %(filename)s to server %(servername)s", filename="foo.txt", servername="a74") saved enough information to be processed by code later (if msg["servername"] == "a74": ..), or (if really necessary) render the message as a string (uploading foo.txt to server a74).
The log.err API could be used as the errback handler in a Deferred chain (like the second argument to promise.then), and did useful things with the Error object and stack trace it received.
Each message had a "facility" (topic) and "severity" (an ordered scale of importance, ranging from NOISY and OPERATIONAL, up to UNUSUAL, INFREQUENT, and CURIOUS, and topping out with WEIRD, SCARY, and BAD). Each facility+severity tuple got its own circular buffer of messages. Foolscap retained a few hundred messages in each such buffer. Each severity level has an associated recommended event rate in the docs: NOISY was expected to be used for things that emit tens or hundreds of messages per second, while BAD might only happen once per process (because it records a fatal error).
If, at any time, a message was logged at level=WEIRD or higher, an "Incident" was declared. The contents of all circular buffers were bundled together into an "incident tarball", and stored to disk for later retrieval. The idea was that the infrequent events (UI requests) happened infrequently enough that the most recent one would still be in the buffer, letting us know what started the tale of woe. The more-frequent events (low-level storage operations) would not be preserved for very long, but we probably only cared about the last few before the problem.
The Tahoe client had a web-based UI. We added a "Report Incident" button to that UI, which simply took a string from the user and logged a WEIRD-level event. Our "how to report a problem" user docs pointed folks at this button, and instructions to locate the incident tarball and email it to us. This helped a lot. We did take some care (although probably not enough) to avoid logging user secrets, with some wrapper classes that knew how to censor their contents when passed to the logger.
Each log event was given a global numerical index (total ordering across the process). This lognum was returned by the API call, and could be passed into other calls (as the parent= argument) to create a parent/child relationship between the two:
event1 = log.msg("starting upload")
log.msg("calculating filesize", parent=event1)A common pattern was to curry the parent into a log function given to a child object. The ShareFinder object used during a download would be created with a log function that had the download log event as its parent. The network messages sent to servers to find those shares were marked as children of the ShareFinder parent. This resulted in a locally-causal hierarchy of log events. Our log viewer had expander triangles to let you drill down into the portions of the log that were useful.
(Incidentally, returning an identifier from log() proved to be the most unusual feature of the Foolscap logging API. Python's stdlib logging library, influenced by Log4J, had plenty of options for customization, but none of them could return values back to the caller. I would have preferred to enhance an existing framework, rather than building my own, but I was unable to build the parent-child-relationship feature in any of the ones that I found.)
We did not have a full Causeway-style causality graph: each log event had at most one parent. We didn't encounter a strong need for it in Tahoe. It wouldn't have been hard to add, however building a viewer for it would have taken more work.
When the logging system started, it logged a special event that included the application version, PID, starting timestamp, and other machine-specific data. Each instance of Foolscap also had an "Instance ID" to help distinguish it from other processes (e.g. to resolve ties on the "who is the leader" network-level negotiation), and to detect multiple connections to the same peer (so we could shut down all but one). This data was used to scope the lognum, so aggregates of events from multiple processes could be teased apart again.
It took a year before a busy server ran long enough for us to discover that our lognum was limited to a 32-bit signed integer (the itertools.count() docs claimed it used a BigInt, but the implementation disagreed).
We established a convention of adding a short random string as a umid= detail argument to each message. We felt it was too expensive to have each log.msg capture the Python stack and include it in the message, so instead we merely stored a random identifier. If we were ever uncertain as to what code emitted the message, we just grepped the source tree for the umid. I had an emacs macro to generate and insert a 6-character string and I never noticed a collision.
log.msg("negotiationFailed: DuplicateConnection", level=NOISY, umid="XRFlRA")Remote Access
A single line of code would enable the "logport": a pub/sub object exposed by the logging system. When a Tahoe client or server was running in a base directory BASEDIR, the file BASEDIR/logport.furl contained the FURL of its log port. A client (named flogtool) could connect to this port (speaking Foolscap) and subscribe to hear about all log messages, or a subset filtered by facility or level. The tool accepted either a FURL or a filename containing one, so flogtool tail ~/tahoe/logport.furl was a quick way to look inside the application and see what was going on. A flogtool --catch-up option would dump the contents of the circular buffers before emitting any new messages. The tool could save an event stream to disk (to a "flogfile"), dump a previously-saved flogfile, launch a web viewer to examine the data, or apply grep-like filters and emit a new (smaller) stream.
The client could also subscribe to Incidents, or retrieve previously stored Incidents.
We built a "log gatherer" service, and configured our fleet of storage servers to tub.connectTo it (via a FURL) at startup. In the most verbose mode, the gatherer would then subscribe to all log events and record them all in a database. The normal mode was for it to retrieve only the Incidents, and pass them to the classification function.
I grew really fond of being able to "plug in" to the logport in a running process and find out what it had been doing for the last few minutes. The logport FURL was persistent (the process read an existing file before generating a new random swissnum), so once I'd cut-and-pasted the flogtool tail FURL command into my local shell, I could re-launch it later with ease. The client reconnected automatically, so I could leave the tool running while I bounced the application it was talking to.
Managing the Attention Budget, Retroactive Interestingness
Foolscap's logging system derives from my experience with embedded systems, where crashes are infrequent and hard to debug. I once worked at a company whose product (a router) crashed in a datacenter in Europe. We asked the customer to install some debug firmware which had more logging enabled, in the hopes of learning enough to diagnose the problem. They were unhappy to hear us suggest that we wanted to make it crash a second time, whatever the reason. As the machine was on a private network in this datacenter, we couldn't log into it directly. We had one engineer on-site reading hexdumps over the phone to a team in the US (and that team was sleeping in a conference room during the day so they could be awake on EU hours). I vowed, never again.
Debuggers are great, if you can use them. But sometimes you can't easily reproduce the problem, or interrupt a system long enough to step through it. In those situations, you want to record enough information to figure things out afterwards.
When we're deep in the debugging process, and we have identified a number of interesting points in the code, where knowing the state of a variable (or merely whether it made it that far or not) is vital information, we have built up a lot of mental context about the system. We've done a lot of careful thinking, and the output is a set of maximally-useful log() calls. Then, once we've solved the problem, those log messages are distracting noise, preventing us from seeing the most useful data for the next problem. We usually then delete those log() calls, or maybe comment them out if we want to save at least some of the work we did.
But that's discarding a lot of work. It would be better to suppress the output, but retain the location and arguments of those calls.
There are a variety of costs which leads us to remove or disable log() statements:
- code readability: excessive logging calls obscure the code that does something useful
- human distraction: too much output to sort through
- performance: CPU time spent generating the message, maybe rendering it into a string
- memory: circular buffers take space
- disk: writing to disk takes time and space
and the amount of detail we retain influences the cost. Recording a full stack trace of an unexpected exception is helpful, especially in a utility function that might be called by dozens of unrelated callers. But many invariants happen in functions which are only ever used for one purpose, so knowing who called it doesn't add very much information. Recording the arguments of each stack frame might be far more valuable, but gets expensive quickly. Foolscap's log.msg() has a stacktrace=True option to enable stack trace capture on specific calls.
Logging systems like Log4J typically have control knobs to set generation/recording thresholds, set through an environment variable or some other API. This allows no-longer-helpful log statements to be retained in the code (saving the programmer effort that was spent in deciding where to put them), and enables them to be re-enabled with a relaunch (without a recompile, and without editing the source to uncomment the log calls), but reduce the costs of human attention, disk space, and some portion of the CPU performance (there is still some cost to deciding to not log an event). But if something goes wrong, you still have to re-run the process (this time with logging enabled), and find a way to reproduce the failure.
It seems useful to having multiple thresholds here. If the main cost is human attention, then simply hiding the messages is sufficient to avoid it. If the messages are recorded in a place where they can be easily retrieved later, then we don't need to be afraid of suppressing their display. If disk is the expensive thing, then storing messages in RAM for a few minutes, and only copying them to disk if something unusual happens afterwards (making them retroactively interesting) can reduce that cost while not entirely losing the data. During early development of a feature, we would record (and maybe display) everything. After deployment, we want to display nothing (leaving the console available for actual UI) and be conscientious in how much we store.
When we're debugging a problem, we have a hunch that some otherwise-boring variable in fact is critically important. In normal operation, we wouldn't bother recording its value. The interestingness of that variable depends upon what happens later. Foolscap's circular buffers formed a nice compromise of storage vs utility. I added intermediate severity levels (CURIOUS, WEIRD) to capture events that maybe didn't indicate an unrecoverable problem, but if something did go off the rails shortly afterwards, they might provide a significant clue as to the cause. In Tahoe we used these to report integrity-hash violations, which usually indicated a malicious/faulty storage server that was feeding us corrupted data. We reacted by looking for a better share elsewhere, but if all shares were corrupted, that indicated a problem in our decoding/decryption logic. By recording the earlier suspicious events, we had more to work on if/when the full download failed.
Chris-Hibbert
michaelfig
dckc
katelynsills
kriskowal
erights
FUDCo
Tartuffo
What is the Problem Being Solved?
Distributed systems make it notoriously difficult to get a picture of what's going on. While debugging one program over here, you'd like to know what's happening to that program over there, and what messages are being exchanged. You'd like to be able to run a debugger against this one component, without pausing the entire world. We add
console.logmessages to trace code we've written, delete it when we're done because the output is too noisy, and then wish we'd left it in place when a similar problem pops up a month later. We want structured logging to record more than mere strings (and use proper analysis tools rather than justgrep). We sometimes want statistical logging, where the time spent in each operation is interesting but we're willing to decimate or average out data if it becomes too large. But much of the time we want complete logging, where every message is important.We've all worked on systems with these sorts of problems, and we've all built or adopted logging systems to address them. I'd like to collect our favorite ideas and tools here, with an eye towards building a Grand Agoric Logging System. Our platform is fairly unique in that we have deterministic execution of inbound messages. So if we log the right things, we should be able to e.g. refer to a message that was delivered on the chain last week, fetch the receiving vat's previous state from a number of chain explorer databases, check that state for accuracy against validator announcements, rebuild a local vat to the exact same JS heap, put it under the control of a debugger, and then re-deliver the message to see what happens. Like time-travelling debugging except better.
This ticket is to colect ideas and systems. Please attach comments with presentation-like writeups of: