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