Logging

Moments in time

Mutable references

One way to observe our software’s behavior is to write programs that emit a message each time some noteworthy event occurs. Appropriate strategies for logging vary with the needs of a particular application, but our example here represents one possible design. This example also shows how to throw, catch, and log an exception.

logging.hs

We will be using the safe-exceptions and directory libraries in this example.

import Control.Exception.Safe (displayException, tryAny)
import Data.Foldable (fold)
import System.Directory (getPermissions, writable)
import System.Environment (getEnv)
import System.IO (hPutStr, stdout, stderr)

Often we want to distinguish between different categories of noteworthy event. In this example we have two: if something has gone wrong, we’ll call that an error, and everything else we’ll call info.

data Level = Info | Error

An event will consist of a Level plus some message String that we want to see in the log output. We might imagine expanding this type to include additional fields such as a timestamp or some application-specific contextual information.

data Event = Event Level String

A basic log handle need only consist of a function that specifies what action to take to record an event.

data Log = Log { record :: Event -> IO () }

This is a log that writes each message to one of the process’s standard output streams. Info messages go to stdout and error messages go to stderr.

consoleLog = Log $ \(Event level message) ->
    hPutStr (standardStream level) (message <> "\n")

standardStream Info = stdout
standardStream Error = stderr

This is another log that writes each message to a file. The path parameter is a function which specifies the output file path for each log level.

fileLog path = Log $ \(Event level message) ->
    appendFile (path level) (message <> "\n")

Sometimes we want to disable logging altogether. In that case, we would use this log whose record function does nothing.

nullLog = Log (\_ -> return ())

We can write functions to define one log as a variant of another. Here the formattedLog function returns a log which prefixes the message string with additional information, then writes the modified message to the original log.

formattedLog topic log = Log $ \event ->
    record log (formatEvent topic event)

formatEvent topic (Event level msg) = Event level msg'
  where
    msg' = paren (topic ! levelString level) ! msg

We have written a few small functions to assist formatEvent. The paren function encloses a string in parentheses, and the (!) function joins two strings with a space in between.

paren x = "(" <> x <> ")"

x ! y = x <> " " <> y

levelString Info = "info"
levelString Error = "error"

We can also combine multiple logs together. This function constructs a logger that records an event by writing it to each of two other logs.

multiLog log1 log2 = Log $ \event ->
  do
    record log1 event
    record log2 event

The multiLog function is associative, and it forms a monoid with nullLog as its identity. This allows us to conveniently fold a collection of logs into a single log. We will make use of fold later in this program.

In some circumstances, a program may be able to recover from a partial failure. When a program proceeds after an exception instead of crashing, we usually want to write an event to the log to ensure that the problem does not go unnoticed.

instance Semigroup Log where (<>) = multiLog
instance Monoid Log where mempty = nullLog

This recoverFromException function converts an IO a action to an IO (Maybe a) action.

recoverFromException log action =
  do
    result <- tryAny action

    case result of

If action throws an exception, we write an error event to the log and return Nothing.

        Left e ->
          do
            record log (Event Error (displayException e))
            return Nothing

If action returns a result, then we return Just that result.

        Right x ->
            return (Just x)

Our demo program involves two logs.

main =
  do

The first, which we call the “boot” log, is used only while the program is first starting up; it provides a place to record any errors that may occur while setting up the more complicated “app” log.

There are a number of ways that logging to a file can go awry – for example, if filesystem permissions disallow writing to the file.

    let bootLog = formattedLog "Boot" consoleLog

    record bootLog (Event Info "Starting")

initFileLog (defined below) produces a Log. By using recoverFromException, we allow our program to recover if it fails. The type of the fileLog variable is Maybe Log.

    fileLog <- recoverFromException bootLog initFileLog

Now we can assemble the application’s full logging strategy: Each event will be recorded to the console, as well as to the log files (if possible). Both the (<>) and fold functions take advantage of the Log monoid.

    let appLog = formattedLog "App" consoleLog <> fold fileLog

Here we record one event, and the demonstration ends (though we ask you to imagine that the rest of an application continues from here).

    record appLog (Event Info "Application started")

    -- ...

Finally, we must return to the question of setting up the file log.

initFileLog =
  do

Let us say that we expect our program to be run with two environment variables, INFO and ERROR, specifying the desired log file paths.

    infoPath <- envLogPath "INFO"
    errorPath <- envLogPath "ERROR"

    let
        path Info = infoPath
        path Error = errorPath

    return (fileLog path)

envLogPath varName =
  do

The getEnv function obtains the value of an environment variable, throwing an exception if no definition for this variable is present in the process environment.

    path <- getEnv varName
    assertWritable path
    return path

This assertWritable action determines whether there exists a file at the given path, and whether we will be able to write to that file.

assertWritable path =
  do

If the file does not exist, getPermissions throws an exception.

    permissions <- getPermissions path

If the file is not writable, we throw an exception using fail.

    case writable permissions of
        True -> return ()
        False -> fail ("Log path" ! path ! "is not writable")

If we run the example without setting up the log files and environment variables, we see an error in the console log. The message comes from the exception thrown by getEnv.

$ runhaskell logging.hs
(Boot info) Starting
(Boot error) INFO: getEnv: does not exist (no environment variable)
(App info) Application started

To enable file logging for this program, we have to create the two files and run the program in a context with the INFO and ERROR variables.

This time, in addition to the console output, we can also see that the final event has been recorded to the info log file.

$ touch /tmp/info.txt /tmp/error.txt

$ env INFO=/tmp/info.txt ERROR=/tmp/error.txt runhaskell logging.hs
(Boot info) Starting
(App info) Application started

$ cat /tmp/info.txt
Application started

Finally, we will remove write permissions from one of the log files and run the program once more.

This time the error message we see comes from the exception that we induced using fail.

$ chmod -w /tmp/info.txt

$ env INFO=/tmp/info.txt ERROR=/tmp/error.txt runhaskell logging.hs
(Boot info) Starting
(Boot error) user error (Log path /tmp/info.txt is not writable)
(App info) Application started

Next: Mutable references