First an update: Haskell-torrent has downloaded its first torrent file “from the wild”. Unfortunately, this behaviour is not deterministic yet, and sometimes the download fails in spectacular ways.
For a bittorrent client, which is heavily concurrent, we have a few obvious tools at our disposal to ensure correctness. We can use QuickCheck to generate test cases and test properties. This is best done with the parts of the code relating to encoding and decoding of data in the client. Second, and I think this is important, we can pose invariants on the various processes and check that these invariants hold periodically. Third, we can trace the execution.
In order to trace the execution, we need a logging framework. Several exist for Haskell, but none of these really suits our purpose.
Logging
The first thing we have done is to create a process with a channel. This process is the logger and the only task is to drain the channel and send out log messages on stdout. All other processes log by synchronization on an event where a log message is sent to this process.
Log messages have three components: A /name/ of the logging process, a /message/ to log, and a priority:
> data LogPriority = Debug
> | Warn
> | Info
> | Error
> | Fatal
> | None
> deriving (Show, Eq, Ord)
Since the log channel is part of so many process configurations, it is beneficial to create a type class of those configurations which can log:
> class Logging a where
> getLogger :: a -> (String, LogChannel)
For example, the Piece Manager has a configuration
> data PieceMgrCfg = PieceMgrCfg
> { logCh :: LogChannel
> , pieceMgrCh :: PieceMgrChannel
> , fspCh :: FSPChannel
> , chokeCh :: ChokeInfoChannel
> , statusCh :: StatusChan
> }
so to make it possible to log, we instance this
> instance Logging PieceMgrCfg where
> getLogger cf = ("PieceMgrP", logCh cf)
And to formalize what a log message and channel are:
> data LogMsg = Mes LogPriority String String
> type LogChannel = Channel LogMsg
> instance Show LogMsg where
> show (Mes pri name str) = show name ++ "(" ++ show pri ++ "):\t" ++ str
The logging itself is done by a logger function. Here is its type:
> log :: Logging a => LogPriority -> String -> Process a b ()
It designates that it takes a Priority and a Message to log (the String). It then logs in a Process monad where the configuration is of type a and the state is of type b. Note that the configuration must be an instance of the Logging class.
The code itself is rather straightforward, save for the call to the logLevel function:
> log prio msg = do
> (name, logC) <- asks getLogger
> when (prio >= logLevel name)
> (liftIO $ logMsg' logC name prio msg)
> where logMsg' c name pri = sync . transmit c . Mes pri name
For the sake of convenience, we want it simpler for most uses, so without much further ado:
> logInfo, logDebug, logFatal, logWarn, logError :: Logging a => String -> Process a b ()
> logInfo = log Info
> logDebug = log Debug
> logFatal = log Fatal
> logWarn = log Warn
> logError = log Error
Filtering
The missing piece of the puzzle is now the “logLevel” function. In the function above, we only log messages which has a priority higher than the current log-level. The log-level is discriminated by the process name in question that tries to log.
Basically, what we want is a simple way to filter log messages. Rather than log all messages, we want to selectively log only part of these, depending on what we are currently debugging or tracing. A log filter is:
> type LogFilter = String -> LogPriority
That is, given a process name, they return a minimum priority for that name. The log function then filters the message if it is not above this priority. Here are a couple of simple combinators:
> matchP :: String -> LogPriority -> LogFilter
> matchP process prio = \s -> if s == process then prio else None
>
> matchAny :: LogPriority -> LogFilter
> matchAny prio = const prio
The first of those matches a process by name. If there is a match it sets a specific priority. Otherwise it punts by returning the highest priority possible. The second is a simple wrapper for always matching at a given level.
With this down, we get to action. Log priorities are Monoids in the sense that None is the neutral element and composition ignores None by “eating” it:
> instance Monoid LogPriority where
> mempty = None
> mappend None g = g
> mappend f g = f
Since there is already an instance:
> instance Monoid b => Monoid (a -> b) where ...
Log filters are now monoids. So we can write:
> logLevel :: LogFilter
> #ifdef DEBUG
> logLevel = mconcat [matchP "SendQueueP" Fatal,
> matchP "ReceiverP" Fatal,
> matchAny Debug]
> #else
> logLevel = matchAny Info
> #endif
Which means that we do not care much for log messages from the processes “SendQueueP” and “ReceiverP” unless they are fatal. Otherwise we want Debug messages or above. The only restriction is that the first match in the monoid chain is the one that steers the level.
