Logging

In Delight, there are four built in logging statements:

log_error("Failed to restore file {}: {}", file, exception)

log_warning("Certificate will expire within 7 days")

log_info("Waiting for connections on port {}", port)

log_trace("x = {}, y = {}", x, y)

The first argument is always a format string. The arguments are formatted using tango.text.convert.Layout. In the simplest case, each {} is replaced by the next argument, converted to a string.

The logging system does not require any configuration to be used. No logger object needs to be declared and nothing needs to be imported. So there's no excuse not to use it.

Configuration

By default, messages logged at the error or warning levels are written to stderr. Messages at the info and trace levels are ignored. You can change this using the LogManager object:

import dlt.log: LogManager, Level

class Main:
	in LogManager logManager

	void main():
		log_info("You won't see this")

		logManager.level = Level.Info

		log_info("Changed logging level")

This prints:

2008-10-06 10:39:57,422 Info  examples.Main - Changed logging level

You can edit the logManager.appenders array to control where the output goes. Every message that is at an acceptable level is passed to every appender in the list.

Why Built-in?

Most languages have logging as a library function. However, this requires a lot of boiler-plate code in every file. e.g. in Java

import org.apache.log4j.Logger;

public class MyApp {
	static Logger logger = Logger.getLogger(MyApp.class);

	void foo() {
		logger.info("Entering foo");
	}
}

The word "logger" appears six times in a class that uses only one log statement! There is then a temptation to use a simpler alternative in many cases (e.g. System.out.println). Making logging built-in makes it as easy to use as a print statement (or easier, since Delight doesn't have a built-in print).

A second problem in Java is the need to specify the source for the logger. MyApp appears twice in the above code, and copy-and-paste errors can cause misleading logging messages [1]. In Delight, the source of a log message is always the code containing the log statement.

A third problem in Java is that there are three different logging APIs in common use: Log4j (shown above), java.util.logging, and Apache Commons Logging. So if you set the log level to show Info and above, you might still not see anything because the class in question is using a different logging system! Also, moving code between projects requires rewriting the logging statements.

It's important that everyone uses the same mechanism for generating log messages, so Delight provides a single way to do it (but you can use whatever reporting mechanisms you like, of course).

A fourth problem is that disabled logging statements still require a function call. Java programs sometimes wrap log statements in if blocks to cache the check about whether the statement will do anything. A built-in allows the compiler to perform this check (although Delight doesn't do anything clever at the moment).

Note that Delight's lack of built-in state isn't the reason for making logging built-in, since the standard library is free from this restriction.

No Global State

The logging system is an exception from the normal rules, since a deeply nested function can cause a message to be displayed to the user.

Delight is designed to make side-effects explicit so you can see, for example, which objects access the file-system or depend on the current time.

I believe that logging should be an exception to this rule, because:

• Logging is pervasive. A good design will limit file-system access to a few classes, but a good program doesn't do all its logging in one place. Therefore, logger objects would have to be distributed to all classes.
• Logging is a kind of debugging, and therefore special.
• Logging is a fairly safe operation. Knowing that a class can produce log messages isn't very interesting.
• Log messages always say where they came from, so there is no difficultly discovering the source of a mysterious message (whereas a program that mysteriously accesses a file on disk can prove a challenge).
• The Main class remains in control. It can disable all logging easily, or only allow logging from certain places.

Good Style

Although it is possible to filter log messages at different levels for different classes, configuration is much simpler if everyone uses the levels consistently. Here are some guidelines:

Error

Use this to log a serious problem which, for some reason, can't be handled by throwing an exception. Typically, this is only used at the top-level of a daemon process, which must continue even if something goes wrong.

Warn

Use this to report a problem that the user should be told about, but where you can't throw an exception for some reason.

Info

Use Info messages to record important events in your program. Reading a configuration file, connecting to a remote server or auto-saving a backup would be appropriate things to log. A user can turn on Info-level logging to get a good idea of what your program is up to.

Trace

Information only useful while debugging.

For quick debugging as a "printf" alternative, use log_error to ensure it will be seen, but then change it to log_trace afterwards, rather than removing it, in case it is needed later.

The golden rule of logging is: don't log an exception that you also throw (or, if you do, do it at Trace level). One exception should result in at most one log entry, and it's the catcher's responsibilty to deal with it.

See also Exception-Handling Antipatterns.