ucw/doc/log.txt

   1 Logging
   2 =======
   3
   4 LibUCW contains a powerful system for logging of messages. Depending on your
   5 needs, it can be used either as a very simple logger which writes all messages
   6 to stderr or to a single file, or as a multi-stream logger in which different
   7 messages can be directed to different streams and the streams can be combined
   8 in various ways.
   9
  10 Simple logging
  11 --------------
  12 The basic logging functions are defined in <<basics:logging,lib.h>>.
  13
  14 To log a message, call `msg(L_xxx,@fmt,@args)`, where `L_xxx` is a category of the log
  15 message (`L_INFO`, `L_WARN`, `L_ERR` etc.), @fmt is a format string as for printf,
  16 and @args are additional arguments to be substituted to the format string.
  17 A newline character is automatically appended; the message should not contain
  18 any control characters.
  19
  20 The first argument of `msg` can be OR'ed with additional flags. Most notably, you can
  21 add `L_SIGHANDLER` if you wish to log a message from a signal handler (see below
  22 for discussion on signals and reentrancy in general).
  23
  24 By default, all messages are logged to stderr. If you wish to use a log file,
  25 call `log_file(@name)`. All subsequent logging will use this file and stderr
  26 will be redirected there, too.
  27
  28 Names of log files can contain strftime() escapes, which are expanded on the fly.
  29 This makes it easy to start a new log file every day.
  30
  31 Example
  32 ~~~~~~~
  33         #include <ucw/lib.h>
  34
  35         int main(int argc, char **argv)
  36         {
  37           log_init(argv[0]);
  38           log_file("/var/log/utterances");
  39           msg(L_INFO, "This program does nothing, but successfully.");
  40           return 0;
  41         }
  42
  43 Log streams
  44 -----------
  45 More generally, the logger can use multiple log streams. Each stream can be directed
  46 to a logging back-end (log file, syslog, ...) and equipped with a filter which
  47 selects a subset of the messages received. A stream can also have substreams
  48 attached, which are passed a copy of all log messages sent to the parent stream.
  49
  50 Streams are identified by <<struct_log_stream,struct log_stream>> and also by
  51 their registration number. Messages can be directed to a stream by OR'ing the
  52 registration number to the first argument of msg().
  53
  54 When a log stream receives a message, it is processed as follows:
  55
  56   1. If the log level of the message does not match the set of accepted
  57      levels of the stream (@levels), the message is dropped.
  58   2. The filter hook of the stream is consulted and if it returns a non-zero
  59      value, the message is dropped.
  60   3. The message is passed to all substreams of the stream.
  61   4. The message is formatted according to the formatting flags (@msgfmt) of the stream.
  62   5. The handler hook of the stream is called (if it exists).
  63
  64 When no stream is explicitly selected, msg() uses the default stream, which
  65 has registration number 0 and which is also returned by log_default_stream().
  66 This stream has no explicit destination, but it can have substreams. (When
  67 a program starts, the default stream is connected to stderr. A call to log_file()
  68 establishes a file logging stream and links it as the only substream of the
  69 default stream. If you want to do that with any other log stream, call log_set_default_stream().)
  70
  71 Streams are reference-counted. When a stream is created, it gets reference count 1.
  72 When it is linked as a substream of another stream, its reference count is incremented.
  73 Closing the stream by log_close_stream(), unlinking it or closing a parent stream
  74 (which causes an unlink) decrements the reference count and when it drops to zero,
  75 the stream is removed and all its substreams unlinked.
  76
  77 Example
  78 ~~~~~~~
  79         #include <ucw/lib.h>
  80         #include <ucw/log.h>
  81
  82         int main(int argc, char **argv)
  83         {
  84           log_init(argv[0]);
  85           struct log_stream *ls = log_new_file("/var/log/utterances", 0);
  86           msg(L_INFO | ls->regnum, "Aye captain, we have a log file");
  87           msg(L_INFO, "Alas, stderr still works");
  88           return 0;
  89         }
  90
  91 Message types
  92 -------------
  93 Messages can also have types, which can be used for further filtering inside streams.
  94 By default, there is only the default message type. To obtain an identifier of a new
  95 type (again to be OR'ed to the log level when calling <<msg()>>), use <<log_register_type()>>.
  96 The number of types is currently limited to 32.
  97
  98 If you want non-default types to be visible, enable the `LSFMT_TYPE` format flag.
  99
 100 Processes, threads and signals
 101 ------------------------------
 102 When you fork a new process, it automatically inherits all currently configured log
 103 streams. You should however call <<log_fork()>> to update the logger's notion
 104 of the current PID (at least when you use PID's in your log messages). Also, if you
 105 plan to exec() a process after fork(), do not forget to call <<log_close_all()>>,
 106 so that all file descriptors used for log files (except for stderr) are closed.
 107
 108 The <<basics:msg()>> function itself can be called from multiple threads in parallel
 109 and it is atomic by design. The functions for setting up the logging machinery
 110 are however not reentrant (they follow our general rule about functions that
 111 affect global state).
 112
 113 Logging from signal handlers is problematic, as is doing almost anything in signal
 114 handlers, because almost all libc functions are not signal-safe. Most importantly,
 115 functions for converting time to a human-readable representation aren't safe.
 116 LibUCW therefore offers only limited logging services in such situations and
 117 you must use the `L_SIGHANDLER` flag to request it. Otherwise, deadlocks get
 118 ready to happen.
 119
 120 Messages logged with `L_SIGHANDLER` set are written directly to stderr (which
 121 is usually an alias for the main log file, at least if you use <<log_file()>>)
 122 and they do not carry a timestamp. Logging of sighandler messages to general
 123 log streams or to syslog is therefore not supported.
 124
 125 ucw/log.h
 126 ---------
 127 !!ucw/log.h
 128
 129 Limiting rate: ucw/tbf.h
 130 ------------------------
 131
 132 LibUCW also offers simple means of limiting the rate of log messages (or of any other
 133 events) by means of a so called 'Token Bucket Filter.' The idea behind this filter is
 134 simple: To log a message, we need a token. The available tokens are accumulated in
 135 a bucket which has a fixed 'filling rate' (the number of tokens arriving in the bucket
 136 per second, which may be a fractional number) and fixed 'maximum capacity.' The
 137 bucket receives the tokens continuously with the given rate and when it reaches
 138 the maximum capacity, the extra tokens are dropped on the floor. When a message
 139 has to be sent, we take a single token from the bucket and if there wasn't any,
 140 we drop the message.
 141
 142 The filling rate therefore describes the maximum sustained rate of messages,
 143 while the bucket capacity tells the filter the maximum length of a short burst,
 144 which can temporarily exceed the rate.
 145
 146 A general bucket filter is available in `ucw/tbf.h`. The usual way of using it
 147 to limit logging is to set up a filter hook of a stream which asks the TBF for
 148 every message. (Remember, though, that if your program is multithreaded, the
 149 filter hook can be run in multiple threads in parallel, so it has to guard the
 150 TBF by a lock.) The configuration interface for log streams described above
 151 is able to attach rate limiters to streams per user's request, so you usually
 152 need not take any extra care.
 153
 154 !!ucw/tbf.h