docs/logging.rst

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