<html xmlns="http://www.w3.org/1999/xhtml"> <head> <title>Foolscap Logging</title> <style src="stylesheet-unprocessed.css"></style> </head> <body> <h1>Logging in Foolscap</h1> <p>Foolscap comes with an advanced event-logging package. This package is used internally to record connection establishment, remote message delivery, and errors. It can also be used by applications built on top of Foolscap for their own needs.</p> <p>This logging package includes a viewer application that processes locally saved log data or data retrieved over a foolscap connection, and displays a selected subset of the events. It also includes code to create a web page inside your application that presents the same kind of log view.</p> <h2>Philosophy</h2> <p>My background is in embedded systems, specifically routers, in which bugs and unexpected operations happen from time to time, causing problems. In this environment, storage space is at a premium (most routers do not have hard drives, and only a limited amount of RAM and non-volatile flash memory), and devices are often deployed at remote sites with no operator at the console. Embedded devices are expected to function properly without human intervention, and crashes or other malfunctions are rare compared to interactive applications.</p> <p>In this environment, when an error occurs, it is a good idea to record as much information as possible, because asking the operator to turn on extra event logging and then try to re-create the failure is only going to make the customer more angry ("my network has already broken once today, you want me to intentionally break it again?"). That one crash is the only chance you have to learn about the cause.</p> <p>In addition, as new features are being developed (or completed ones are being debugged), it is important to have visibility into certain internal state. Extra logging messages are added to illuminate this state, sometimes resulting in hundreds of messages per second. These messages are useful only while the problem is being investigated. Since most log formats involve flat text files, lots of additional log messages tend to obscure important things like unhandled exceptions and assertion failures, so once the messages have outlived their usefulness they are just getting in the way. Each message costs a certain amount of human attention, so we are motiviated to minimize that cost by removing the unhelpful messages.</p> <p>Logging also gets removed because it consumes CPU time, disk IO, disk space, or memory space. Many operations that can be done in linear time can expand to super-linear time if additional work is required to log the actions taking place, or the current state of the program.</p> <p>As a result, many formerly-useful log messages are commented out once they have served their purpose. Having been disabled, the cost to re-enable them if the bug should resurface is fairly high: at the very least it requires modifying the source code and restarting the program, and for some languages requires a complete recompile/rebuild. Even worse, to keep the source code readable, disabled log messages are frequently deleted altogether. After many months it may not be obvious where the log messages should be put back, and developers will need to re-acquaint themselves with the code base to find suitable places for those messages.</p> <p>To balance these costs, developers try to leave enough log messages in place that unexpected events will be captured with enough detail to start debugging, but not so many that it impacts performance or a human's ability to spot problems while scanning the logs. But it would be nice if certain log messages could be disabled or disregarded in a way that didn't abandon all of the work that went into developing and placing them.</p> <h3>Memory-limited, strangeness-triggered log dumping</h3> <p>Each potential log message could be described (to a human) as being useful in a particular set of circumstances. For example, if the program tried to read from a file and got a permission-denied error, it would be useful to know which file it was trying to read from, and how it came to decide upon that particular filename, and what user command was responsible for triggering this action. If a protocol parser which implements a state machine finds itself in an invalid state, it would be useful to know what series of input messages had arrived recently, to work backwards to the place where things started to go awry.</p> <p>Flip this around and you can phrase it as: the filename we compute will be interesting only if we get an error when we finally try to access it. Likewise, the series of input messages <b>would</b> be interesting to know if, at some point in the near future, an invalid protocol state is reached.</p> <p>The thing to note about these patterns is that an event at time T <b>causes</b> events before time T to become interesting. Interesting messages are worth keeping (and storing, and examining). Non-interesting messages are not worth as much, but there are different kinds of costs, and as the message becomes less interesting (or loses the potential to become interesting), we want to lower our costs. Displaying a message to a human is pretty expensive, since it tends to obscure other, more important messages. Storing messages is less expensive, depending upon how long we expect to store them (and how much storage space is available). Generating messages may be expensive or cheap, depending upon their frequency and complexity.</p> <p>Foolscap's logging library seeks to capture this ex-post-facto interestingness by categorizing messages into "severity levels", recording each level into a separate size-limited circular buffer, and provoking a dump of all buffers when an "Incident" occurs. An "Incident Qualifier" is used to classify certain higher-severity events as worthy of triggering the log dump. The idea is that, at any given time, we have a record (in memory) of a lot of low-frequency important things (like program startup, user actions, and unhandled exceptions), and only the most recent high-frequency events (verbose debugging data). But, if something strange happens, we dump everything we've got to disk, because it is likely that some of these noisy high-frequency not-normally-interesting events will be helpful to track down the cause of the unusual event. The viewing tools then rearrange all of these events into a linear order, and make it easy to filter out events by severity level or origin.</p> <p>Each severity level is (roughly) inversely proportional to a message rate. Assertion checks in code are in the "this should never happen" category, and their resulting low expected rate puts them in a high-severity level. Routine actions are expected to happen all the time, which puts them into a low-severity level.</p> <p>(you might think of severity as a separate axis than frequency. Severity would mean "how much damage will this cause". Frequency equals cost, controlling how long we keep the message around in the hopes of it becoming interesting. But things which cause a lot of damage should not be happening very frequently, and things which happen frequently must not cause a lot of damage. So these axes are sufficiently aligned for us to use just a single parameter for now.)</p> <h3>Structured Logging</h3> <p>The usual approach to event logging involves a single file with a sequence of lines of text, new events being continually appended at the end, perhaps with the files being rotated once they become too large or old. Typically the source code is peppered with lines like:</p> <pre class="python"> log.msg(text) Log.Log(source, facility, severity, text) log.log_stacktrace() log.err(failure) </pre> <p>Each such function call adds some more text to the logfile, encoding the various parameters into a new line.</p> <p>Using a text-based file format enables the use of certain unix tools like 'grep' and 'wc' to analyze the log entries, but frequently inhbits the use of more complex tools because they must first parse the human-readable lines back into the structured arguments that were originally passed to the log() call. Frequently, the free-form text portion of the log cannot be reliably distinguished from the stringified metadata (the quoting issue), making analysis tools more difficult to write. In addition, the desire to make both logfiles and the generating source code more greppable is occasionally at odds with clean code structure (putting everything on a single line) or refactoring goals (sending all logging for a given module through a common function).</p> <p>The Foolscap log system uses binary logfiles that accurately and reversibly serialize all the metadata associated with a given event. Tools are provided to turn this data into a human-readable greppable form, but better tools are provided to perform many of the same tasks that 'grep' is typically used for. For example, a log viewer can apply a python expression to each event as a filter, and the expression can do arbitrary comparison of event parameters (e.g. "show me all events related to failing uploads of files larger than 20MB").</p> <p>To accomplish this, all unrecognized keyword arguments to the <code>log.msg</code> call are recorded as additional keys in the log event. To encourage structured usage, the message string be provided as a format specifier instead of a pre-interpolated string, using the keyword args as a formatting dictionary. Any time the string is displayed to a human, the keyword args are interpolated into the format string first.</p> <p>(in compiled languages, it would be useful and cheap to embed the source file and line number of the log() call inside the log event. Unfortunately, in Python, this would require expensive stack crawling, so developers are generally stuck with grepping for the log message in their source tree to backtrack from a log message to the code that generated it)</p> <h3>Remote log aggregation</h3> <p>Code is provided to allow a Foolscap-based application to easily publish a 'logport': an object which providers remote callers with access to that application's accumulated log data. Events are delivered over a secure Foolscap connection, to prevent eavesdroppers from seeing sensitive data inside the log messages themselves. This can be useful for a developer who wants to find out what just happened inside a given application, or who is about to do something to the application and wants to see how it responds from the inside. The <code>flogtool tail</code> tool is provided for this job.</p> <p>Each Tub always activates a logport, and a Tub option makes it possible to use a persistent FURL for remote access.</p> <p>(TODO: really?) The log-viewer application can either read log data from a local log directory, or it can connect to the logport on a remote host.</p> <p>A centralized "log gatherer" program can connect to multiple logports and aggregate all the logs collected from each, similar to the unix 'syslog' facility. This is most useful when the gatherer is configured to store more messages than the applications (perhaps it stores all of them), since it allows the costs to be shifted to a secondary machine with extra disk and fewer CPU-intensive responsibilities.</p> <p>To facilitate this, each Tub can either be given the FURL of a Log Gatherer, or the name of a file that might contain this FURL. This makes deployment easier: just copy the FURL of your central gatherer into this file in each of your application's working directories.</p> <p>A basic log gatherer is created by running <code>flogtool create-gatherer</code> and giving it a storage directory: this emits a gatherer FURL that can be used in the app configuration, and saves all incoming log events to disk.</p> <h3>Causality Tracing</h3> <p>Log messages correspond to events. Events are triggered by other events. Sometimes the relationship between events is visible to the local programmer, sometimes it involves external hosts that can confuse the relationships.</p> <p>For local "application-level" causality, Foolscap's logging system makes it possible to define hierarchies of log events. Each call to <code>log.msg</code> returns an identifier (really just a number). If you pass this same identifier into a later <code>log.msg</code> call as the <code>parent=</code> parameter, that second message is said to be a "child" of the first. This creates multiple trees of log events, in which the tree tops are the parentless messages. For example, a user command like "copy this file" could be a top-level event, while the various steps involved in copying the file (compute source filename, open source file, compute target filename, open target file, read data, write data, close) would be children of that top-level event.</p> <p>The viewer application has a way to hide or expand the nodes of these trees, to make it easy to look at just the messages that are related to a specific action. This lets you prioritize events along both severity (is this a common event?) and relevance (is this event related to the one of interest?)</p> <p>In the future, Foolscap's logging system will be enhanced to offer tools for analyzing causality relationships between multiple systems, taking inspiration from the E <a href="http://www.erights.org/elang/tools/causeway/index.html">Causeway</a> debugger. In this system, when one Tub sends a message to another, enough data is logged to enable a third party (with access to all the logs) to figure out the set of operations that were <b>caused</b> by the first message. Each message send is recorded, with an index that includes the TubID, current event number, and stack trace. Event A on tub 1 triggers event B on tub 2, along with certain operations and log messages. Event B triggers further operations, etc.</p> <p>The viewer application will offer a causality-oriented view in addition to the temporal one.</p> <h2>Using Foolscap Logging</h2> <p>The majority of your application's interaction with the Foolscap logging system will be in the form of calls to its <code>log.msg</code> function. </p> <h3>Logging Messages From Application Code</h3> <p>To emit log messages from application code, just use the <code>foolscap.log.msg</code> function:</p> <pre class="python"> from foolscap.logging import log log.msg("hello world") </pre> <p>You can add arguments that will be lazily evaluated and stringified by treating the log message as a normal format string:</p> <pre class="python"> log.msg("queue depth %d exceeds limit %d", current_depth, limit) </pre> <p>Or you can use keyword arguments instead. The format string can use positional parameters, or keyword arguments, but not both.</p> <pre class="python"> log.msg(format="Danger %(name)s %(surname)s", name="Will", surname="Robinson") </pre> <p>Passing arguments as separate parameters (instead of interpolating them before calling <code>log.msg</code> has the benefit of preserving more information: later, when you view the log messages, you can apply python filter expressions that use these parameters as search criteria.</p> <p>Regardless of how you format the main log message, you can always pass additional keyword arguments, and their values will be serialized into the log event. This will not be automatically stringified into a printed form of the message, but it will be available to other tools (either to filter upon or to display):</p> <pre class="python"> log.msg("state changed", previous=states[now-1], current=stats[now]) </pre> <h4>Modifying Log Messages</h4> <p>There are a number of arguments you can add to the <code>log.msg</code> call that foolscap will treat specially:</p> <pre class="python"> parent = log.msg(facility="app.initialization", level=log.INFREQUENT, msg="hello world", stacktrace=False) log.msg(facility="app.storage", level=log.OPERATIONAL, msg="init storage", stacktrace=False, parent=parent) </pre> <p>The <code>level</code> argument is how you specify a severity level, and takes a constant from the list defined in <code>foolscap/log.py</code>:</p> <ul> <li><code>BAD</code>: something which significantly breaks functionality. Unhandled exceptions and broken invariants fall into this category.</li> <li><code>SCARY</code>: something which is a problem, and shouldn't happen in normal operation, but which causes minimal functional impact, or from which the application can somehow recover.</li> <li><code>WEIRD</code>: not as much of a problem as SCARY, but still not right.</li> <li><code>CURIOUS</code></li> <li><code>INFREQUENT</code>: messages which are emitted as a normal course of operation, but which happen infrequently, perhaps once every ten to one hundred seconds. User actions like triggering an upload or sending a message fall into this category.</li> <li><code>UNUSUAL</code>: messages which indicate events that are not normal, but not particularly fatal. Examples include excessive memory or CPU usage, minor errors which can be corrected by fallback code. </li> <li><code>OPERATIONAL</code>: messages which are emitted as a normal course of operation, like all the steps involved in uploading a file, potentially one to ten per second..</li> <li><code>NOISY</code>: verbose debugging about small operations, potentially emitting tens or hundreds per second</li> </ul> <p>The <code>stacktrace</code> argument controls whether or not a stack trace is recorded along with the rest of the log message.</p> <p>The <code>parent</code> argument allows messages to be related to earlier messages.</p> <h4>Logging Messages Through a Tub</h4> <p>Each Tub offers a log method: this is just like the process-wide <code>log.msg</code> described above, but it adds an additional parameter named <code>tubid</code>. This is convenient during analysis, to identify which messages came from which applications.</p> <pre class="python"> class Example: def __init__(self): self.tub = Tub() ... def query(self, args): self.tub.log("about to send query to server") self.server.callRemote("query", args).addCallback(self._query_done) </pre> <h3>Facilities</h3> <p>Facility names are up to the application: the viewer app will show a list of checkboxes, one for each facility name discovered in the logged data. Facility names should be divided along functional boundaries, so that developers who do not care about, say, UI events can turn all of them off with a single click. Related facilities can be given names separated with dots, for example "ui.internationalization" and "ui.toolkit", and the viewer app may make it easy to enable or disable entire groups at once. Facilities can also be associated with more descriptive strings by calling <code>log.explain_facility</code> at least once:</p> <pre class="python"> log.explain_facility("ui.web", "rendering pages for the web UI") </pre> <h3>"That Was Weird" Buttons</h3> <p>Sometimes it is the user of your application who is in the best position to decide that something weird has taken place. Internal consistency checks are useful, but the user is the final judge of what meets their needs. So if they were expecting one thing to happen and something else happened instead, they should be able to declare that an Incident has taken place, perhaps by pushing a special "That Was Weird" button in your UI.</p> <p>To implement this sort of button for your user, just take the user's reason string and log it in an event at level WEIRD or higher. Since events at this level trigger Incidents by default, Foolscap's normal incident-handling behavior will take care of the rest for you.</p> <pre class="python"> def that_was_weird_button_pushed(reason): log.msg(format="The user said that was weird: %(reason)s", reason=reason, level=log.WEIRD) </pre> <h2>Configuring Logging</h2> <p>Foolscap's logging system is always enabled, but the unconfigured initial state is lacking a number of useful features. By configuring the logging system at application startup, you can enable these features.</p> <h3>Saving Log Events to Disk</h3> <p>The first missing piece is that it does not have a place to save log events in the event of something strange happening, so the short-term circular buffers are the only source of historical log events.</p> <p>To give the logging system some disk space to work with, just give it a logdir. The logging system will dump the circular buffers into this directory any time something strange happens, and both the in-memory buffers and the on-disk records are made available to viewing applications:</p> <pre class="python"> from foolscap.logging import log log.setLogDir("~/saved-log-events") # == log.theLogger.setLogDir </pre> <p>The foolscap logging code does not delete files from this directory. Applications which set up a logdir should arrange to delete old files once storage space becomes a problem. TODO: we could provide a maximum size for the logdir and have Foolscap automatically delete the oldest logfiles to stay under the size limit: this would make the disk-based logdir an extension of the memory-based circular buffers.</p> <h4>Incidents</h4> <p>Foolscap's logging subsystem uses the term "Incident" to describe the "something strange" that causes the buffered log events to be dumped. The logger has an "Incident Qualifier" that controls what counts as an incident. The default qualifier simply fires on events at severity level <code>log.WEIRD</code> or higher. You can override the qualifier by subclassing <code>foolscap.logging.incident.IncidentQualifier</code> and calling <code>log.setIncidentQualifier</code> with an instance of your new class. For example, certain facilities might be more important than others, and you might want to declare an Incident for unusual but relatively low-severity events in those facilities:</p> <pre class="python"> from foolscap.logging import log, incident class BetterQualifier(incident.IncidentQualifier): def check_event(self, ev): if ev.get('facility',"").startswith("lifesupport"): if ev['level'] > log.UNUSUAL: return True return incident.IncidentQualifier.check_event(self, ev) log.setIncidentQualifier(BetterQualifier()) </pre> <p>The qualifier could also keep track of how many events of a given type had occurred, and trigger an incident if too many UNUSUAL events happen in rapid succession, or if too many recoverable errors are observed within a single operation.</p> <p>Once the Incident has been declared, the "Incident Reporter" is responsible for recording the recent events to the file on disk. The default reporter copies everything from the circular buffers into the logfiles, then waits an additional 5 seconds or 100 events (whichever comes first), recording any trailing events into the logfile too. The idea is to capture the application's error-recovery behavior: if the application experiences a problem, it should log something at the <code>log.WEIRD</code> level (or similar), then attempt to fix the problem. The post-trigger trailing event logging code should capture the otherwise-ordinary events performed by this recovery code.</p> <p>Overlapping incidents will be combined: if an incident reporter is already active when the qualifier sees a new triggering event, that event is just added to the existing reporter.</p> <p>The incident reporter can be overridden as well, by calling <code>log.setIncidentReporterFactory</code> with a <b>class</b> that will produce reporter instances. For example, if you wanted to increase the post-trigger event recording to 1000 events or 10 seconds, then you could do something like this:</p> <pre class="python"> from foolscap.logging import log, incident class MoreRecoveryIncidentReporter(incident.IncidentReporter): TRAILING_DELAY = 10.0 TRAILING_EVENT_LIMIT = 1000 log.setIncidentReporterFactory(MoreRecoveryIncidentReporter) </pre> <p>Recorded Incidents will be saved in the logdir with filenames like <code>incident-2008-05-02-011235.flog.bz2</code>, and can be read with tools like <code>flogtool dump</code> and <code>flogtool web-viewer</code>.</p> <h3>Setting up the logport</h3> <p>The <code>logport</code> is a <code>foolscap.Referenceable</code> object which provides access to all available log events. Viewer applications can either retrieve old events (buffered in RAM or on disk), or subscribe to hear about new events that occur later. The logport implements the <code>foolscap.logging.interfaces.RILogPublisher</code> interface, which defines the methods that can be called on it. Each Tub automatically creates and registers a logport: the <code>tub.getLogPort()</code> and <code>tub.getLogPortFURL()</code> methods make it possible to grant access to others:</p> <pre class="python"> t = Tub() ... # usual Tub setup: startService, listenOn, setLocation logport_furl = t.getLogPortFURL() # this is how you learn the logport furl print "please point your log viewer at: %s" % logport_furl logport = t.getLogPort() # a Referenceable you can pass over the wire rref.callRemote("please_use_my_logport", logport) </pre> <p>The default behavior is register the logport object with an ephemeral name, and therefore its FURL will change from one run of the program to the next. This can be an operational nuisance, since the external log viewing program you're running (<code>flogtool tail LOGPORT</code>) would need a new FURL each time the target program is restarted. By giving the logport a place to store its FURL between program runs, the logport gets a persistent name. The <code>logport-furlfile</code> option is used to identify this file. If the file exists, the desired FURL will be read out of it. If it does not, the newly-generated FURL will be written into it.</p> <p>If you use <code>logport-furlfile</code>, it must be set before you call <code>getLogPortFURL</code> (and also before you pass the result of <code>getLogPort</code> over the wire), otherwise an ephemeral name will have already been registered and the persistent one will be ignored. The call to <code>setOption</code> can take place before <code>setLocation</code>, and the logport-furlfile will be created as soon as both the filename and the location hints are known. However, note that the logport will not be available until after <code>setLocation</code> is called: <code>getLogPortFURL</code> and <code>getLogPort</code> will raise exceptions.</p> <pre class="python"> tub.setOption("logport-furlfile", "~/logport.furl") print "please point your log viewer at: %s" % tub.getLogPortFURL() </pre> <p>This <code>logport.furl</code> file can be read directly by other tools if you want to point them at an operating directory rather than the actual logport FURL. For example, the <code>flogtool tail</code> command (described below) can accept either an actual FURL, or the directory in which a file named <code>logport.furl</code> can be located, making it easier to examine the logs of a local application. Note that the <code>logport-furlfile</code> is chmod'ed <code>go-r</code>, since it is a secret: the idea is that only people with access to the application's working directory (and presumeably to the application itself) should get access to the logs.</p> <h3>Configuring a Log Gatherer</h3> <p>The third feature that requires special setup is the log gatherer. You can either tell the Tub a specific gatherer to use, or give it a filename where the FURL of a log gatherer is stored.</p> <p>The <code>tub.setOption("log-gatherer-furl", gatherer_FURL)</code> call can be used to have the Tub automatically connect to the log gatherer and offer its logport. The Tub uses a Reconnector to make sure the gatherer connection is reestablished each time it gets dropped.</p> <pre class="python"> t = Tub() t.setOption("log-gatherer-furl", gatherer_FURL) </pre> <p>Alternatively, you can use the <code>tub.setOption("log-gatherer-furlfile", "~/gatherer.furl")</code> call to tell the Tub about a file where a gatherer FURL might be found. If that file exists, the Tub will read a FURL from it, otherwise the Tub will not use a gatherer. The file can contain multiple log-gatherer FURLs, one per line. This is probably the easiest deployment mode:</p> <pre class="python"> t = Tub() t.setOption("log-gatherer-furlfile", "~/gatherer.furl") </pre> <p>In both cases, the gatherer FURL is expected to point to a remote object which implements the <code>foolscap.logging.RILogGatherer</code> interface (such as the service created by <code>flogtool create-gatherer</code>). The Tub will connect to the gatherer and offer it the logport.</p> <p>The <code>log-gatherer-furl</code> and <code>log-gatherer-furlfile</code> options can be set at any time, however the connection to the gatherer will not be initiated until <code>setLocation</code> is called.</p> <h3>Interacting With Other Logging Systems</h3> <p>There are two other logging systems that the Foolscap logging code knows how to handle: <code>twisted.python.log</code> and the stdlib <code>logging</code> system.</p> <p>First, a brief discussion of the single-instance nature of Foolscap's logging is in order. Each process that uses Foolscap gets a single instance of the Foolscap logging code (named <code>theLogger</code> and defined at module level in <code>foolscap.logging.log</code>). This maintains a single logdir. Each time a process is started it gets a new "incarnation record", which consists of a randomly generated (unique) number, and (if a logdir is available) (TODO) a continuously incrementing sequence number. All log events are tagged with this incarnation record: it is used to distinguish between event#23 in one process versus the same event number from a different process.</p> <p>Each Tub has a distinct TubID, and all log events that go through the Tub (via <code>tub.log</code>) are tagged with this TubID. Each Tub maintains its own logport (specifically there is a single <code>LogPublisher</code> object, but like all Referenceables it can be registered in multiple Tubs and gets a distinct FURL for each one).</p> <h4>twisted.python.log</h4> <p>Twisted's logging mechanism is used by importing <code>twisted.python.log</code> and invoking its <code>log.msg()</code> and <code>log.err</code> methods. This mechanism is used extensively by Twisted itself; the most important messages are those concerning "Unhandled Error in Deferred" and other exceptions in processing received data and timed calls. The normal destination for Twisted log messages depends upon how the application is run: the <code>twistd</code> daemonization tool sends the log messages to a file named <code>twistd.log</code>, the <code>trial</code> unit-test tool puts them in <code>_trial_temp/test.log</code>, and standalone scripts discard these logs by default (unless you use something like <code>log.startLogging(sys.stderr)</code>).</p> <p>To capture these log messages, you need a "bridge", which will add a Twisted log observer and copy each Twisted log message into Foolscap. There can be at most one such bridge per python process. Either you will use a generic bridge (which tags each message with the incarnation record), or you will use a Tub as a bridge (which additionally tags each message with the TubID). Each time you set the twisted log bridge, any previous bridge is discarded.</p> <p>When you have only one Tub in an application, use the Tub bridge. Likewise if you have multiple Tubs but there is one that is long-lived, use that Tub for the bridge. If you have mutiple Tubs with no real primary one, use the generic bridge. Using a Tub bridge adds slightly more information to the log events, and may make it a bit easier to correlate Twisted log messages with actions of your application code, especially when you're combining events from several applications together for analysis.</p> <p>To set up the generic bridge, use the following code:</p> <pre class="python"> from foolcap.logging import log log.bridgeTwistedLogs() </pre> <p>To set up a Tub bridge, use this instead:</p> <pre class="python"> t = Tub() t.setOption("bridge-twisted-logs", True) </pre> <p>Note that for Tub bridges, the Twisted log messages will only be delivered while the Tub is running (specifically from the time its startService() method is until its stopService() method is called). TODO: review this behavior, we want earlier messages to be bridged too.</p> <p>To bridge log events in the other direction (i.e. taking foolscap log messages and copying them into twisted), use the <code>log.bridgeLogsToTwisted()</code> call, or the <code>FLOGTOTWISTED</code> environment variable. This is useful to get foolscap.logging.log.msg() events copied into <code>twistd.log</code>. The default filter only bridges non-noisy events (i.e. those at level OPERATIONAL or higher), and does not bridge foolscal internal events.</p> <p>You might use this if you don't buy into the foolscap logging philosophy and really want log events to be continually written out to disk. You might also use it if you want a long-term record of operationally-significant events, or a record that will survive application crashes which don't get handled by the existing Incident-recording mechanism.</p> <pre class="python"> from foolscap.logging import log log.bridgeLogsToTwisted() </pre> <h4>stdlib 'logging' module</h4> <p>stdlib <code>logging</code> messages must be bridged in the same way. TODO: define and implement the bridge setup</p> <h4>Preferred Logging API</h4> <p>To take advantage of the parent/child causality mechanism, you must use Foolscap's native API. (to be precise, you can pass in <code>parent=</code> to either Twisted's <code>log.msg</code> or stdlib's <code>logging.log</code>, but to get a handle to use as a value to <code>parent=</code> you must use <code>foolscap.log.msg</code>, because neither stdlib's nor Twisted's log calls provide a return value)</p> <h3>Controlling Buffer Sizes</h3> <p>There is a separate circular buffer (with some maximum size) for each combination of level and facility. After each message is added, the size of the buffer is checked and enough old messages are discarded to bring the size back down to the limit. Each facility uses a separate set of buffers, so that e.g. the NOISY messages from the "ui" facility do not evict the NOISY messages from the "upload" facility.</p> <p>The sizes of these buffers can be controlled with the <code>log.set_buffer_size</code> function, which is called with the severity level, the facility name, and the desired buffer size (maximum number of messages). If <code>set_buffer_size</code> is called without a facility name, then it will set the default size that will be used when a log.msg call references an as-yet-unknown facility).</p> <pre class="python"> log.set_buffer_size(log.NOISY, 10000) log.set_buffer_size(level=log.NOISY, facility="upload", size=10000) log.allocate_facility_buffers("web") print log.get_buffer_size(log.NOISY, facility="upload") </pre> <h3>Some Messages Are Not Worth Generating</h3> <p>If the message to be logged is below some threshold, it will not even be generated. This makes it easy to leave the log line in the source code, but not consume CPU time or memory space by actually using it. Such messages must be enabled before use (either through the logport (TODO) or by restarting the application with different log settings(TODO)), but at least developers will not have to re-learn the source code to figure out where it might be useful to add some messages. This threshold can be configured for all facilities at the same time, or on a facility-by-facility basis.</p> <pre class="python"> log.set_generation_threshold(log.NOISY) log.set_generation_threshold(level=log.OPERATIONAL, facility="web") print log.get_generation_threshold() print log.get_generation_threshold(facility="web") </pre> <h2>Viewing Log Messages</h2> <p>There are a variety of ways for humans (and their tools) to read and analyze log messages. The <code>flogtool</code> program, provided with Foolscap, provides access to many of them.</p> <ul> <li><code>flogtool dump</code>: look at the saved log events (in a logdir) and display their contents to stdout. Options are provided to specify the log source, the facilities and severity levels to display, and grep-like filters on the messages to emit. </li> <li><code>flogtool tail</code>: connect to a logport and display new log events to stdout. The <code>--catchup</code> option will also display old events.</li> <li><code>flogtool gtk-viewer</code>: a Gtk-based graphical tool to examine log messages.</li> <li><code>flogtool web-viewer</code>: runs a local web server, through which log events can be examined.</li> </ul> <p>This tool uses a log-viewing API defined in <code>foolscap/logging/interfaces.py</code>. (TODO) Application code can use the same API to get access to log messages from inside a python program.</p> <h3>Log Views</h3> <p>(NOTE: this section is incomplete and has not been implemented)</p> <p>Many of these tools share the concept of "Log Views". This is a particular set of filters which can be applied to the overall log event stream. For example, one view might show all events that are UNUSUAL or worse. Another view might show NOISY messages for the "ui" facility but nothing else.</p> <p>Each view is described by a set of thresholds: each facility gets a severity threshold, and all messages at or above the threshold will be included in the view. While in principle there is a threshold for each facility, this may be expressed as a single generic threshold combined with overrides for a few specific facilities.</p> <h3>Log Observers</h3> <p>A "Log Observer" can be attached to a foolscap-using program (either internally or by subscribing through the flogport). Once attached, this observer will receive a stream of log messages, which the observer is then free to format, store, or ignore as it sees fit.</p> <p>Each log message is a dictionary, as defined in <a href="specifications/logfiles.xhtml">specifications/logfiles</a>.</p> <pre class="python"> def observe(event): print strftime(fmt, event.timestamp) print event["level"] # a number print event.get("facility" # a string like "ui" print event["message"] # a unicode object with the actual event text log.theLogger.addObserver(observe) </pre> <h3>Running a Log Gatherer</h3> <p>A "Log Gatherer" is a python server to which the process under examination sends some or all of its log messages. These messages are saved to a file as they arrive, so they can be examined later. The resulting logfiles can be compressed, and they can be automatically rotated (saved, rename, reopened) on a periodic interval. In addition, sending a SIGHUP to the gatherer will cause it to rotate the logfiles.</p> <p>To create one, choose a new directory for it to live in, and run "<code>flogtool create-gatherer</code>". You can then start it with "twistd", and stop it by using the <code>twistd.pid</code> file:</p> <pre class="shell"> % flogtool create-gatherer lg Gatherer created in directory lg Now run '(cd lg && twistd -y gatherer.tac)' to launch the daemon % cd lg % ls gatherer.tac % twistd -y gatherer.tac % ls from-2008-07-28-133034--to-present.flog log_gatherer.furl twistd.pid gatherer.pem portnum gatherer.tac twistd.log % cat log_gatherer.furl pb://g7yntwfu24w2hhb54oniqowfgizpk73d@192.168.69.172:54611,127.0.0.1:54611/z4ntcdg4jpdg3pnabhmyu3qvi3a7mdp3 % kill `cat twistd.pid` % </pre> <p>The <code>log_gatherer.furl</code> string is the one that should be provided to all applications whose logs should be gathered here. By using <code>tub.setOption("log-gatherer-furlfile", "log_gatherer.furl")</code> in the application, you can just copy this .furl file into the application's working directory.</p> <h3>Running an Incident Gatherer</h3> <p>An "Incident Gatherer" is like a Log Gatherer, but it only gathers weirdness-triggered Incidents. It records these incidents into files on the local disk, and provides access to them through a web server. The Incident Gatherer can also be configured to classify the incidents into various categories (perhaps expressions of a specific bug), to facilitate analysis by separating known problems from new ones.</p> <p>To create one, choose a new directory for it to live in, and run "<code>flogtool create-incident-gatherer</code>", just like the log gatherer:</p> <pre class="shell"> % flogtool create-incident-gatherer ig Gatherer created in directory ig Now run '(cd ig && twistd -y gatherer.tac)' to launch the daemon % cd ig % ls gatherer.tac % twistd -y gatherer.tac % </pre> <h4>Incident Storage</h4> <p>Inside the gatherer's base directory (which we refer to as BASEDIR here), the <code>incidents/</code> directory will contain a subdirectory for each tub that connects to the gatherer. Each subdir will contain the incident files, named <code>incident-TIMESTAMP-UNIQUE.flog.bz2</code>.</p> <p>A simple unix command like <code>find BASEDIR/incidents -name 'incident-*.flog.bz2'</code> will locate all incident files. Each incident file can be examined with a tool like <code>flogtool dump</code>. The format is described in the <a href="specifications/logfiles.xhtml">Logfiles specification</a> docs.</p> <h4>Classification</h4> <p>The Incident Gatherer uses a collection of user-supplied classification functions to analyze each Incident and place it into one or more categories. To add a classification function, create a file with a name like "<code>classify_*.py</code>" (such as <code>classify_foolscap.py</code> or <code>classify_db.py</code>), and define a function in it named "<code>classify_incident()</code>". Place this file in the gatherer's directory. All such files will be loaded and evaluated when the gatherer starts.</p> <p>The <code>classify_incident()</code> function will accept a single triggering event (a regular log Event dictionary, see logfiles.xhtml for details, which can be examined as follows:</p> <pre class="python"> def classify_incident(trigger): m = trigger.get('message', '') if "Tub.connectorFinished:" in m: return 'foolscap-tubconnector' </pre> <p>The function should return a list (or set) of categories, or a single category string, or None. Each incident can wind up in multiple categories. If no function finds a category for the incident, it will be added to the "unknown" category. All incidents are added to the "all" category.</p> <p>The <code>classified/</code> directory will contain a file for each defined classification. This file will contain one line for each incident that falls into that category, containing the BASEDIR-relative pathname of the incident file (i.e. each line will look like <code>incidents/TUBID/incident-TIMESTAMP-UNIQUE.flog.bz2</code>). The <code>classified/all</code> file will contain the same filenames as the <code>find</code> command described earlier.</p> <p>If the <code>classified/</code> directory does not exist when the gatherer is started, all stored Incidents will be re-classified. After modifying or adding classification functions, you should delete the <code>classified/</code> directory and restart the gatherer.</p> <h4>Incident Gatherer Web Server</h4> <p>The Incident Gatherer can run a small webserver, to publish information about the incidents it collects. The plan is to have it publish an RSS feed of incidents by category, and to serve incidents as HTML just like the <code>foolscap web-viewer</code> command. This code is not yet written.</p> <h4>Incident Reports by Email</h4> <p>The Incident Gatherer can also be configured to send email with a description of the incident for various categories. The incident report will be included as an attachment for further analysis. This code is not yet written.</p> <!-- <h2>Python <code>logging</code> module</h2> <p>(NOTE: this section is incomplete and has not been implemented. In addition it may be entirely false and misleading.)</p> <p>The Python stdlib <code>logging</code> module offers portions of the desired functionality. The Foolscap logging framework is built as an extension to the native Python facilities.</p> <p>The <code>logging</code> module provides a tree of facilities, one <code>Logger</code> instance per facility (in which the child path names are joined with periods to form the Logger's name). Each <code>Logger</code> gets a set of <code>Handlers</code> which receive all messages sent to that <code>Logger</code> or below; the <code>Handlers</code> attached to the root <code>Logger</code> see all messages. Each message arrives as a <code>LogRecord</code> instance, and handlers are responsible for formatting them into text or a record on disk or whatever is necessary. Each log message has a severity (from DEBUG at 10 up to CRITICAL at 50), and both <code>Loggers</code> and <code>Handlers</code> have thresholds to discard low-severity messages.</p> <p><code>logging</code></p> Plan of attack: <p> foolscap installs a root Logger handler, with a threshold set very low (0), so it gets everything. The root Logger is set to a low threshold (since it defaults to WARNING=30), to make sure that all events are passed through to its handlers. Foolscap's handler splits the events it receives out by facility (Logger name) and severity level, and appends them to a space-limited buffer (probably a dequeue). </p> <p>That covers all native users of logging.py . Foolscap users deal with foolscap.log.msg(), which massages the arguments before passing them through to logging.log(). In particular, each log message processed by the foolscap handler gets a serial number assigned to it. This number is used as a marker, which can be passed to later msg() calls. The foolscap.log.msg code manages these serial numbers and uses them to construct the call to logging.log(), then the foolscap handler pulls the serial number out of the event and records it.</p> --> </body></html>