Logging web server events in Racket to syslog
Logs or it didn’t happen
How do you write to the system log with the Racket web server?
I’m not talking about writing debug output to the console. (I’m not the only one who’s done that, right?) That’s a good start, but it’s ephemeral.
Nor am I talking about
I’m talking about logging events in your sweet Racket web site to the system log. Something that persists after Racket dies. And something that can serve multiple Racket servers on a single server.
Imagine that you’re not actively sitting at your Racket process, manually scanning or perhaps piping output from the console to a file/socket/some other process. Rather, let’s restrict our attention to the system log, what your operating system maintains for you in the background. (On many Unix-y systems, that’s usually stored in places like /var/log/syslog, or something to that effect.) The system log isn’t necessarily for those really low-level programs. Racket can write to the system log, too.
Logging to the system log opens up the possibility of using tools like Papertrail. Being able to keep track of your Racket web app using such a tool is a real boon.
How do you do that?
To get started, let’s keep things very simple. The topic of logging is rich, and Racket’s support for logging goes well beyond what you’ll see here.
How to write to the system log
When Racket starts up, there’s already a logger sitting around. It passes some events to the system log, and some get presented to the console (standard error, in a Unix-y setting).
(There are probably a bunch of variations on that, and I’m afraid I don’t know all of them. I work with Ubuntu Linux often, and that’s the source of my examples here. It may very well be the same for many other Linux-based systems.)
Here’s one of the gotchas that caught me by surprise:
When working on a Unix-based system, the system log, be default, is not used by Racket. Or, more precisely, the facility that would write things to the system log filters out everything given to it.
You can write error messages all day long and they’ll never show up in your system log.
There are two ways to make sure that your log messages get sent to the system log: environment variables, and command line switches.
The environment variable in question is PLTSYSLOG. Invoke Racket like so:
env PLTSYSLOG="info" racket site.rkt
(I’ll explain in a moment what info means.) Or, more or less equivalently, you can export the variable in your shell (or in a shell script) and then invoke Racket:
export PLTSYSLOG="info" racket site.rkt
This will ensure that log events at the info level (or greater) get logged to the system log.
One thing to keep in mind with the environment variable approach is that you can’t tweak the initial logger settings by using
putenv. This won’t work:
(putenv "PLTSYSLOG" "debug")
(log-error "not gonna happen")
The reason, as far as I can make out, is that the initial logger is, well, part of the initial setup. If you’re evaluating Racket code like
putenv calls, you’re trying to ride a horse has already left the barn. Even putting that kind of code in your .racketrc file isn’t going to do the job.
Command line arguments
The -L argument is what you’re looking for. Use it like this:
racket -L "info" site.rkt
This accomplishes the same thing as the environment variable setup a couple paragraphs ago.
(For my fellow loggers: -W is the switch that controls what kinds of logs get dumped to how standard error. I’m afraid I don’t know any good mnemonic…)
Functions to use & log levels
Use these log functions in your code:
The names reflect the following hierarchy of log levels:
The ontology behind this is that log items have a level (aka severity) attached to them. The list above is presented in decreasing order of severity. The idea is that you don’t just a message, all on it’s own. Rather, you log a message at a certain level of severity. What happens to your log item (message+severity) depends on how the logger’s log receivers
(There’s somewhat more to the story than this. We are skipping here the useful notion of log topics.)
By setting the system logger at, say, info—which is what we have done in the examples above—messages that have the severity info, warning, error, and fatal will be logged. Messages that have the severity debug won’t be logged.
Edge cases: setting the debug level to debug means that no log message will be filtered out (in other words, everything will be logged). Setting the log level to fatal means that only truly hard errors will ever show up in the logs.
Here’s an example of logging for our web app. Let’s imagine we’ve set up a fallback error handler called
fallback, defined like this:
;; url? exn? -> response?
(define (fallback url exn) (log-error "~a ~~~~> ~a" (url->string url) (exn-message exn)) (response #:code 500 #:mime TEXT/HTML-MIME-TYPE #:body (include-template "oops.html")))
As long as we’ve set up logging to system log to error (or lower), we’ll see the message.
Here, we’re logging an error before sending out a response (based on oops.html, discussed in another tutorial.).
Disabling all logging
If you would like to disable logging to the system log, you can use the special value none as the level severity. That is:
racket -L none site.rkt
env PLTSYSERROR=none racket site.rkt
export PLTSYSERROR=none racket site.rkt
(Recall that not logging anything to the system log is—as of Racket 6.9, anyway—the default. We are here only making explicit what is implicit.)
What was left out
We’re skipping, for the moment, an important part of logging—topics—that comes out-of-the-box with Racket. For now; the idea is, simply, to record events to the system log.
We also skipped the idea of logger hierarchy (where one logger can be a parent of another). We worked with only one logger, the initial logger.
One rationale for this simple approach is that the Racket and its web server are, for us, essentially indistinguishable from each other. This doesn’t scale well if we are running multiple Racket web sites on a single server. In another lesson, though, we can consider these more advanced needs.