8 4. `Working with flogfiles`_
11 1. `Incident Gatherer`_
14 6. `Local twistd.log files`_
15 7. `Adding log messages`_
16 8. `Log Messages During Unit Tests`_
21 Tahoe uses the Foolscap logging mechanism (known as the "flog" subsystem) to
22 record information about what is happening inside the Tahoe node. This is
23 primarily for use by programmers and grid operators who want to find out what
26 The Foolscap logging system is documented at
27 `<http://foolscap.lothar.com/docs/logging.html>`_.
29 The Foolscap distribution includes a utility named "``flogtool``" that is
30 used to get access to many Foolscap logging features. This command only
31 works when foolscap and its dependencies are installed correctly.
32 Tahoe-LAFS v1.10.0 and later include a ``tahoe debug flogtool`` command
33 that can be used even when foolscap is not installed; to use this, prefix
34 all of the example commands below with ``tahoe debug``.
36 For earlier versions since Tahoe-LAFS v1.8.2, installing Foolscap v0.6.1
37 or later and then running ``bin/tahoe @flogtool`` from the root of a
38 Tahoe-LAFS source distribution may work (but only on Unix, not Windows).
44 When you are working on Tahoe code, and want to see what the node is doing,
45 the easiest tool to use is "``flogtool tail``". This connects to the Tahoe
46 node and subscribes to hear about all log events. These events are then
47 displayed to stdout, and optionally saved to a file.
49 "``flogtool tail``" connects to the "logport", for which the FURL is stored
50 in ``BASEDIR/private/logport.furl`` . The following command will connect to
51 this port and start emitting log information::
53 flogtool tail BASEDIR/private/logport.furl
55 The ``--save-to FILENAME`` option will save all received events to a file,
56 where then can be examined later with "``flogtool dump``" or "``flogtool
57 web-viewer``". The ``--catch-up`` option will ask the node to dump all stored
58 events before subscribing to new ones (without ``--catch-up``, you will only
59 hear about events that occur after the tool has connected and subscribed).
64 Foolscap keeps a short list of recent events in memory. When something goes
65 wrong, it writes all the history it has (and everything that gets logged in
66 the next few seconds) into a file called an "incident". These files go into
67 ``BASEDIR/logs/incidents/`` , in a file named
68 "``incident-TIMESTAMP-UNIQUE.flog.bz2``". The default definition of
69 "something goes wrong" is the generation of a log event at the ``log.WEIRD``
70 level or higher, but other criteria could be implemented.
72 The typical "incident report" we've seen in a large Tahoe grid is about 40kB
73 compressed, representing about 1800 recent events.
75 These "flogfiles" have a similar format to the files saved by "``flogtool
76 tail --save-to``". They are simply lists of log events, with a small header
77 to indicate which event triggered the incident.
79 The "``flogtool dump FLOGFILE``" command will take one of these ``.flog.bz2``
80 files and print their contents to stdout, one line per event. The raw event
81 dictionaries can be dumped by using "``flogtool dump --verbose FLOGFILE``".
83 The "``flogtool web-viewer``" command can be used to examine the flogfile in
84 a web browser. It runs a small HTTP server and emits the URL on stdout. This
85 view provides more structure than the output of "``flogtool dump``": the
86 parent/child relationships of log events is displayed in a nested format.
87 "``flogtool web-viewer``" is still fairly immature.
89 Working with flogfiles
90 ======================
92 The "``flogtool filter``" command can be used to take a large flogfile
93 (perhaps one created by the log-gatherer, see below) and copy a subset of
94 events into a second file. This smaller flogfile may be easier to work with
95 than the original. The arguments to "``flogtool filter``" specify filtering
96 criteria: a predicate that each event must match to be copied into the target
97 file. ``--before`` and ``--after`` are used to exclude events outside a given
98 window of time. ``--above`` will retain events above a certain severity
99 level. ``--from`` retains events send by a specific tubid.
100 ``--strip-facility`` removes events that were emitted with a given facility
101 (like ``foolscap.negotiation`` or ``tahoe.upload``).
106 In a deployed Tahoe grid, it is useful to get log information automatically
107 transferred to a central log-gatherer host. This offloads the (admittedly
108 modest) storage requirements to a different host and provides access to
109 logfiles from multiple nodes (web-API, storage, or helper) in a single place.
111 There are two kinds of gatherers: "log gatherer" and "stats gatherer". Each
112 produces a FURL which needs to be placed in the ``NODEDIR/tahoe.cfg`` file of
113 each node that is to publish to the gatherer, under the keys
114 "log_gatherer.furl" and "stats_gatherer.furl" respectively. When the Tahoe
115 node starts, it will connect to the configured gatherers and offer its
116 logport: the gatherer will then use the logport to subscribe to hear about
119 The gatherer will write to files in its working directory, which can then be
120 examined with tools like "``flogtool dump``" as described above.
125 The "incident gatherer" only collects Incidents: records of the log events
126 that occurred just before and slightly after some high-level "trigger event"
127 was recorded. Each incident is classified into a "category": a short string
128 that summarizes what sort of problem took place. These classification
129 functions are written after examining a new/unknown incident. The idea is to
130 recognize when the same problem is happening multiple times.
132 A collection of classification functions that are useful for Tahoe nodes are
133 provided in ``misc/incident-gatherer/support_classifiers.py`` . There is
134 roughly one category for each ``log.WEIRD``-or-higher level event in the
137 The incident gatherer is created with the "``flogtool
138 create-incident-gatherer WORKDIR``" command, and started with "``tahoe
139 start``". The generated "``gatherer.tac``" file should be modified to add
140 classifier functions.
142 The incident gatherer writes incident names (which are simply the relative
143 pathname of the ``incident-\*.flog.bz2`` file) into ``classified/CATEGORY``.
144 For example, the ``classified/mutable-retrieve-uncoordinated-write-error``
145 file contains a list of all incidents which were triggered by an
146 uncoordinated write that was detected during mutable file retrieval (caused
147 when somebody changed the contents of the mutable file in between the node's
148 mapupdate step and the retrieve step). The ``classified/unknown`` file
149 contains a list of all incidents that did not match any of the classification
152 At startup, the incident gatherer will automatically reclassify any incident
153 report which is not mentioned in any of the ``classified/\*`` files. So the
154 usual workflow is to examine the incidents in ``classified/unknown``, add a
155 new classification function, delete ``classified/unknown``, then bound the
156 gatherer with "``tahoe restart WORKDIR``". The incidents which can be
157 classified with the new functions will be added to their own
158 ``classified/FOO`` lists, and the remaining ones will be put in
159 ``classified/unknown``, where the process can be repeated until all events
162 The incident gatherer is still fairly immature: future versions will have a
163 web interface and an RSS feed, so operations personnel can track problems in
166 In our experience, each incident takes about two seconds to transfer from the
167 node that generated it to the gatherer. The gatherer will automatically catch
168 up to any incidents which occurred while it is offline.
173 The "Log Gatherer" subscribes to hear about every single event published by
174 the connected nodes, regardless of severity. This server writes these log
175 events into a large flogfile that is rotated (closed, compressed, and
176 replaced with a new one) on a periodic basis. Each flogfile is named
177 according to the range of time it represents, with names like
178 "``from-2008-08-26-132256--to-2008-08-26-162256.flog.bz2``". The flogfiles
179 contain events from many different sources, making it easier to correlate
180 things that happened on multiple machines (such as comparing a client node
181 making a request with the storage servers that respond to that request).
183 Create the Log Gatherer with the "``flogtool create-gatherer WORKDIR``"
184 command, and start it with "``tahoe start``". Then copy the contents of the
185 ``log_gatherer.furl`` file it creates into the ``BASEDIR/tahoe.cfg`` file
186 (under the key ``log_gatherer.furl`` of the section ``[node]``) of all nodes
187 that should be sending it log events. (See `<configuration.rst>`_.)
189 The "``flogtool filter``" command, described above, is useful to cut down the
190 potentially large flogfiles into a more focussed form.
192 Busy nodes, particularly web-API nodes which are performing recursive
193 deep-size/deep-stats/deep-check operations, can produce a lot of log events.
194 To avoid overwhelming the node (and using an unbounded amount of memory for
195 the outbound TCP queue), publishing nodes will start dropping log events when
196 the outbound queue grows too large. When this occurs, there will be gaps
197 (non-sequential event numbers) in the log-gatherer's flogfiles.
199 Local twistd.log files
200 ======================
202 [TODO: not yet true, requires foolscap-0.3.1 and a change to ``allmydata.node``]
204 In addition to the foolscap-based event logs, certain high-level events will
205 be recorded directly in human-readable text form, in the
206 ``BASEDIR/logs/twistd.log`` file (and its rotated old versions:
207 ``twistd.log.1``, ``twistd.log.2``, etc). This form does not contain as much
208 information as the flogfiles available through the means described
209 previously, but they are immediately available to the curious developer, and
210 are retained until the twistd.log.NN files are explicitly deleted.
212 Only events at the ``log.OPERATIONAL`` level or higher are bridged to
213 ``twistd.log`` (i.e. not the ``log.NOISY`` debugging events). In addition,
214 foolscap internal events (like connection negotiation messages) are not
215 bridged to ``twistd.log``.
220 When adding new code, the Tahoe developer should add a reasonable number of
221 new log events. For details, please see the Foolscap logging documentation,
222 but a few notes are worth stating here:
224 * use a facility prefix of "``tahoe.``", like "``tahoe.mutable.publish``"
226 * assign each severe (``log.WEIRD`` or higher) event a unique message
227 identifier, as the ``umid=`` argument to the ``log.msg()`` call. The
228 ``misc/coding_tools/make_umid`` script may be useful for this purpose.
229 This will make it easier to write a classification function for these
232 * use the ``parent=`` argument whenever the event is causally/temporally
233 clustered with its parent. For example, a download process that involves
234 three sequential hash fetches could announce the send and receipt of those
235 hash-fetch messages with a ``parent=`` argument that ties them to the
236 overall download process. However, each new web-API download request should
239 * use the ``format=`` argument in preference to the ``message=`` argument.
240 E.g. use ``log.msg(format="got %(n)d shares, need %(k)d", n=n, k=k)``
241 instead of ``log.msg("got %d shares, need %d" % (n,k))``. This will allow
242 later tools to analyze the event without needing to scrape/reconstruct the
243 structured data out of the formatted string.
245 * Pass extra information as extra keyword arguments, even if they aren't
246 included in the ``format=`` string. This information will be displayed in
247 the "``flogtool dump --verbose``" output, as well as being available to
248 other tools. The ``umid=`` argument should be passed this way.
250 * use ``log.err`` for the catch-all ``addErrback`` that gets attached to the
251 end of any given Deferred chain. When used in conjunction with
252 ``LOGTOTWISTED=1``, ``log.err()`` will tell Twisted about the error-nature
253 of the log message, causing Trial to flunk the test (with an "ERROR"
254 indication that prints a copy of the Failure, including a traceback).
255 Don't use ``log.err`` for events that are ``BAD`` but handled (like hash
256 failures: since these are often deliberately provoked by test code, they
257 should not cause test failures): use ``log.msg(level=BAD)`` for those
261 Log Messages During Unit Tests
262 ==============================
264 If a test is failing and you aren't sure why, start by enabling
265 ``FLOGTOTWISTED=1`` like this::
267 make test FLOGTOTWISTED=1
269 With ``FLOGTOTWISTED=1``, sufficiently-important log events will be written
270 into ``_trial_temp/test.log``, which may give you more ideas about why the
271 test is failing. Note, however, that ``_trial_temp/log.out`` will not receive
272 messages below the ``level=OPERATIONAL`` threshold, due to this issue:
273 `<http://foolscap.lothar.com/trac/ticket/154>`_
276 If that isn't enough, look at the detailed foolscap logging messages instead,
277 by running the tests like this::
279 make test FLOGFILE=flog.out.bz2 FLOGLEVEL=1 FLOGTOTWISTED=1
281 The first environment variable will cause foolscap log events to be written
282 to ``./flog.out.bz2`` (instead of merely being recorded in the circular
283 buffers for the use of remote subscribers or incident reports). The second
284 will cause all log events to be written out, not just the higher-severity
285 ones. The third will cause twisted log events (like the markers that indicate
286 when each unit test is starting and stopping) to be copied into the flogfile,
287 making it easier to correlate log events with unit tests.
289 Enabling this form of logging appears to roughly double the runtime of the
290 unit tests. The ``flog.out.bz2`` file is approximately 2MB.
292 You can then use "``flogtool dump``" or "``flogtool web-viewer``" on the
293 resulting ``flog.out`` file.
295 ("``flogtool tail``" and the log-gatherer are not useful during unit tests,
296 since there is no single Tub to which all the log messages are published).
298 It is possible for setting these environment variables to cause spurious test
299 failures in tests with race condition bugs. All known instances of this have
300 been fixed as of Tahoe-LAFS v1.7.1.