LibUCW contains a powerful system for logging of messages. Depending on your needs, it can be used either as a very simple logger which writes all messages to stderr or to a single file, or as a multi-stream logger in which different messages can be directed to different streams and the streams can be combined in various ways.
Simple logging
The basic logging functions are defined in lib.h.
To log a message, call msg(L_xxx,@fmt,@args), where L_xxx is a category of the log message (L_INFO, L_WARN, L_ERR etc.), fmt is a format string as for printf, and args are additional arguments to be substituted to the format string. A newline character is automatically appended; the message should not contain any control characters.
The first argument of msg can be OR’ed with additional flags. Most notably, you can add L_SIGHANDLER if you wish to log a message from a signal handler (see below for discussion on signals and reentrancy in general).
By default, all messages are logged to stderr. If you wish to use a log file, call log_file(@name). All subsequent logging will use this file and stderr will be redirected there, too.
Names of log files can contain strftime() escapes, which are expanded on the fly. This makes it easy to start a new log file every day.
Example
#include <ucw/lib.h>
int main(int argc, char **argv)
{
log_init(argv[0]);
log_file("/var/log/utterances");
msg(L_INFO, "This program does nothing, but successfully.");
return 0;
}
Log streams
More generally, the logger can use multiple log streams. Each stream can be directed to a logging back-end (log file, syslog, …) and equipped with a filter which selects a subset of the messages received. A stream can also have substreams attached, which are passed a copy of all log messages sent to the parent stream.
Streams are identified by struct log_stream and also by their registration number. Messages can be directed to a stream by OR’ing the registration number to the first argument of msg().
When a log stream receives a message, it is processed as follows:
-
If the log level of the message does not match the set of accepted levels of the stream (levels), the message is dropped.
-
The filter hook of the stream is consulted and if it returns a non-zero value, the message is dropped.
-
The message is passed to all substreams of the stream.
-
The message is formatted according to the formatting flags (msgfmt) of the stream.
-
The handler hook of the stream is called (if it exists).
When no stream is explicitly selected, msg() uses the default stream, which has registration number 0 and which is also returned by log_default_stream(). This stream has no explicit destination, but it can have substreams. (When a program starts, the default stream is connected to stderr. A call to log_file() establishes a file logging stream and links it as the only substream of the default stream. If you want to do that with any other log stream, call log_set_default_stream().)
Streams are reference-counted. When a stream is created, it gets reference count 1. When it is linked as a substream of another stream, its reference count is incremented. Closing the stream by log_close_stream(), unlinking it or closing a parent stream (which causes an unlink) decrements the reference count and when it drops to zero, the stream is removed and all its substreams unlinked.
Example
#include <ucw/lib.h> #include <ucw/log.h>
int main(int argc, char **argv)
{
log_init(argv[0]);
struct log_stream *ls = log_new_file("/var/log/utterances", 0);
msg(L_INFO | ls->regnum, "Aye captain, we have a log file");
msg(L_INFO, "Alas, stderr still works");
return 0;
}
Message types
Messages can also have types, which can be used for further filtering inside streams. By default, there is only the default message type. To obtain an identifier of a new type (again to be OR’ed to the log level when calling msg()), use log_register_type(). The number of types is currently limited to 32.
If you want non-default types to be visible, enable the LSFMT_TYPE format flag.
Processes, threads and signals
When you fork a new process, it automatically inherits all currently configured log streams. You should however call log_fork() to update the logger’s notion of the current PID (at least when you use PID’s in your log messages). Also, if you plan to exec() a process after fork(), do not forget to call log_close_all(), so that all file descriptors used for log files (except for stderr) are closed.
The msg() function itself can be called from multiple threads in parallel and it is atomic by design. The functions for setting up the logging machinery are however not reentrant (they follow our general rule about functions that affect global state).
Logging from signal handlers is problematic, as is doing almost anything in signal handlers, because almost all libc functions are not signal-safe. Most importantly, functions for converting time to a human-readable representation aren’t safe. LibUCW therefore offers only limited logging services in such situations and you must use the L_SIGHANDLER flag to request it. Otherwise, deadlocks get ready to happen.
Messages logged with L_SIGHANDLER set are written directly to stderr (which is usually an alias for the main log file, at least if you use log_file()) and they do not carry a timestamp. Logging of sighandler messages to general log streams or to syslog is therefore not supported.
ucw/log.h
Messages and streams
struct log_msg {
char *m; // The formatted message itself, ending with \n\0
int m_len; // Length without the \0
struct tm *tm; // Current time
struct timeval *tv;
uint flags; // Category and other flags as passed to msg()
char *raw_msg; // Unformatted parts
char *stime;
char *sutime;
uint depth; // Recursion depth
bool error; // An error has occurred (e.g., an infinite loop in sub-streams)
};
Inside the logging system, a log message is always represented by this structure.
struct log_stream {
char *name; // Optional name, allocated by the user (or constructor)
int regnum; // Stream number, already encoded by LS_SET_STRNUM(); -1 if closed
uint levels; // Bitmask of accepted severity levels (default: all)
uint types; // Bitmask of accepted message types (default: all)
uint msgfmt; // Formatting flags (LSFMT_xxx)
uint use_count; // Number of references to the stream
uint stream_flags; // Various other flags (LSFLAG_xxx)
int (*filter)(struct log_stream* ls, struct log_msg *m); // Filter function, return non-zero to discard the message
clist substreams; // Pass the message to these streams (simple_list of pointers)
int (*handler)(struct log_stream *ls, struct log_msg *m); // Called to commit the message, return 0 for success, errno on error
void (*close)(struct log_stream* ls); // Called upon log_close_stream()
void *user_data; // Not used by the logging system
// Private data of the handler follow
};
Each stream is represented by an instance of this structure.
enum ls_fmt {
LSFMT_LEVEL = 1, // severity level (one letter) */
LSFMT_TIME = 2, // date and time (YYYY-mm-dd HH:MM:SS) */
LSFMT_USEC = 4, // also micro-seconds */
LSFMT_TITLE = 8, // program title (log_title) */
LSFMT_PID = 16, // program PID (log_pid) */
LSFMT_LOGNAME = 32, // name of the log_stream */
LSFMT_TYPE = 64, // message type
};
Formatting flags specifying the format of the message passed to the handler.
#define LSFMT_DEFAULT (LSFMT_LEVEL | LSFMT_TIME | LSFMT_TITLE | LSFMT_PID)
Default format
enum ls_flag {
LSFLAG_ERR_IS_FATAL = 1, // When a logging error occurs, die() immediately
LSFLAG_ERR_REPORTED = 2, // A logging error has been already reported on this stream
};
General stream flags.
Message flags
The flags parameter of msg() is divided to several groups of bits (from the LSB): message severity level (L_xxx), destination stream, message type and control bits (e.g., L_SIGHANDLER).
#define LS_GET_LEVEL(flags) (((flags) & LS_LEVEL_MASK) >> LS_LEVEL_POS)
Extract severity level
#define LS_GET_STRNUM(flags) (((flags) & LS_STRNUM_MASK) >> LS_STRNUM_POS)
Extract stream number
#define LS_GET_TYPE(flags) (((flags) & LS_TYPE_MASK) >> LS_TYPE_POS)
Extract message type
#define LS_GET_CTRL(flags) (((flags) & LS_CTRL_MASK) >> LS_CTRL_POS)
Extract control bits
#define LS_SET_LEVEL(level) ((level) << LS_LEVEL_POS)
Convert severity level to flags
#define LS_SET_STRNUM(strnum) ((strnum) << LS_STRNUM_POS)
Convert stream number to flags
#define LS_SET_TYPE(type) ((type) << LS_TYPE_POS)
Convert message type to flags
#define LS_SET_CTRL(ctrl) ((ctrl) << LS_CTRL_POS)
Convert control bits to flags
int log_register_type(const char *name);
Register a new message type and return the corresponding flag set (encoded by LS_SET_TYPE).
int log_find_type(const char *name);
Find a message type by name and return the corresponding flag set. Returns -1 if no such type found.
char *log_type_name(uint flags);
Given a flag set, extract the message type ID and return its name.
Operations on streams
struct log_stream *log_new_stream(size_t size);
Allocate a new log stream with no handler and an empty substream list. Since struct log_stream is followed by private data, size bytes of memory are allocated for the whole structure. See below for functions creating specific stream types.
int log_close_stream(struct log_stream *ls);
Decrement the use count of a stream. If it becomes zero, close the stream, free its memory, and unlink all its substreams.
static inline struct log_stream *log_ref_stream(struct log_stream *ls);
Get a new reference on an existing stream. For convenience, the return value is equal to the argument ls.
void log_add_substream(struct log_stream *where, struct log_stream *what);
Link a substream to a stream. The substream gains a reference, preventing it from being freed until it is unlinked.
int log_rm_substream(struct log_stream *where, struct log_stream *what);
Unlink all occurrences of a substream what from stream where. Each occurrence loses a reference. If what is NULL, all substreams are unlinked. Returns the number of unlinked substreams.
void log_set_format(struct log_stream *ls, uint mask, uint data);
Set formatting flags of a given stream and all its substreams. The flags are AND’ed with mask and OR’ed with data.
struct log_stream *log_stream_by_flags(uint flags);
Find a stream by its registration number (in the format of logging flags). Returns NULL if there is no such stream.
static inline struct log_stream *log_default_stream(void);
Return a pointer to the default stream (stream #0).
void log_set_default_stream(struct log_stream *ls);
Make the specified stream the default destination.
In fact, it takes the fixed default stream and attaches ls as its only substream. If there were any other substreams, they are removed.
Log streams created by log_file() or log_configured() are made default by calling this function.
void log_close_all(void);
Close all open streams, un-initialize the module, free all memory and reset the logging mechanism to use stderr only.
void log_pass_filtered(struct log_stream *ls, struct log_msg *m);
The filter function of a stream might want to modify the message before passing it to the handler and/or substreams. In this case, the filter should make a local copy of struct log_msg, call log_pass_filtered() on it and return true, so that the original message will not be processed any further.
Logging to files
All log files are open in append mode, which guarantees atomicity of write() even in multi-threaded programs.
struct log_stream *log_new_file(const char *path, uint flags);
Create a stream bound to a log file. See FF_xxx for flags.
struct log_stream *log_new_fd(int fd, uint flags);
Create a stream bound to a file descriptor. See FF_xxx for flags.
enum log_file_flag {
FF_FORMAT_NAME = 1, // Internal: Name contains strftime escapes
FF_CLOSE_FD = 2, // Close the fd with the stream (use with log_new_fd())
FF_FD2_FOLLOWS = 4, // Maintain stderr as a clone of this stream
};
Flags used for file-based logging
void log_switch_disable(void);
When a time-based name of the log file changes, the logger switches to a new log file automatically. This can be sometimes inconvenient, so you can use this function to disable the automatic switches. The calls to this function can be nested.
void log_switch_enable(void);
Negate the effect of log_switch_disable().
int log_switch(void);
Switch log files manually.
void log_drop_stderr(void);
Drop stderr if it is not already redirected to a log file. This is usually needed in daemons to make sure that the original stderr does not stay open (stdin and stdout are dropped by our daemon setup functions automatically). More specifically, it makes stderr a clone of stdout.
Logging to syslog
This log stream uses the libc interface to the system logging daemon (syslogd). This interface has several limitations:
-
Syslog are poorer than our scheme, so they are translated with a slight loss of information (most importantly, the distinction between local and remote messages is lost). If you are interested in details, search the source for syslog_level().
-
Syslog options (especially logging of PID with each message) must be fixed during initialization of the logger
-
Syslog provides its own formatting, so we turn off all formatting flags of the LibUCW logger. You can override this manually by setting the msgfmt field of the log stream, but the result won’t be nice.
-
Syslog does not support timestamps with sub-second precision.
struct log_stream *log_new_syslog(const char *facility, int options);
Create a log stream for logging to a selected syslog facility. The options are passed to openlog(). (Beware, due to limitations of the syslog interface in libc, the options are shared for all syslog streams and they are applied when the first stream is created.)
int log_syslog_facility_exists(const char *facility);
Verify that a facility of the given name exists. Return 1 if it does, 0 otherwise.
Configuring log streams
If you use the LibUCW mechanism for parsing config files, you can let your user configure arbitrary log streams in the Logging section of the config file (see examples in the default config file). LibUCW automatically verifies that the configuration is consistent (this is performed in the commit hook of the config section), but it opens the streams only upon request. The following functions can be used to control that.
struct log_stream *log_new_configured(const char *name);
Open a log stream configured under the specified name and increase its use count.
void log_configured(const char *name);
Open a log stream configured under the specified name and use it as the default destination.
char *log_check_configured(const char *name);
Verify that a stream called name was configured. If it wasn’t, return an error message. This is intended to be used in configuration commit hooks.
Limiting rate: ucw/tbf.h
LibUCW also offers simple means of limiting the rate of log messages (or of any other events) by means of a so called Token Bucket Filter. The idea behind this filter is simple: To log a message, we need a token. The available tokens are accumulated in a bucket which has a fixed filling rate (the number of tokens arriving in the bucket per second, which may be a fractional number) and fixed maximum capacity. The bucket receives the tokens continuously with the given rate and when it reaches the maximum capacity, the extra tokens are dropped on the floor. When a message has to be sent, we take a single token from the bucket and if there wasn’t any, we drop the message.
The filling rate therefore describes the maximum sustained rate of messages, while the bucket capacity tells the filter the maximum length of a short burst, which can temporarily exceed the rate.
A general bucket filter is available in ucw/tbf.h. The usual way of using it to limit logging is to set up a filter hook of a stream which asks the TBF for every message. (Remember, though, that if your program is multithreaded, the filter hook can be run in multiple threads in parallel, so it has to guard the TBF by a lock.) The configuration interface for log streams described above is able to attach rate limiters to streams per user’s request, so you usually need not take any extra care.
struct token_bucket_filter {
double rate; // Number of tokens received per second
uint burst; // Capacity of the bucket
timestamp_t last_hit; // Internal state...
double bucket;
uint drop_count;
};
A data structure describing a single TBF.
void tbf_init(struct token_bucket_filter *f);
Initialize the bucket.
int tbf_limit(struct token_bucket_filter *f, timestamp_t now);
Ask the filter to process a single event. Returns a negative number if the event exceeds the rate (and should be dropped) and a non-negative number if the event passes the filter. The absolute value of the result is the number of dropped events since the last passed event.