Making a Web Application with Racket

I've been an admirer of Racket for a while now. It's a language that has a lot of potential and I love the documentation focus. So I decided to write the back end of a webapp in it. In the beginning I thought maybe I'll go for a web framework but then I realised I mostly wanted to write an API. So why not submit to the curse of LISP and see how I go writing my app without a framework? Even better I found Server Racket by Jesse Alama. It's a guide to making a server using Racket and certainly pulls together an example application in a pretty appealing way.

However, as always happens :smiley: as I was delving into the log chapter it became clear that me that it wasn't quite what I wanted. In Server Racket the logs are piped to the syslog. Which is a great place to put the logs on a lot of systems. However, it doesn't always play nicely with development (especially when you're thinking about pulling the app in a container). What I want is something like:

<timestamp> <url> <status code>

Which should be feel familiar if you've seen the logs from Apache or Nginx.

It might be nice if I can optionally turn on the request details (HTTP methods, header, MIME details, elapsed request time and the like). But let's worry about the basic info right now.

Server Racket uses the syslog by pointing the default racket logger at it. I'm a little more cautious so I'm going to point the log to a file and get it right there, then think about making it funky.

Step 1 - Get A Log Out of Racket

So really this is me getting to understand Racket a bit better. There's a logging framework built into Racket, all I have to do is use it. So I started at the official reference. OK so far so good. Now as you'd expect I'm going to be throwing the main pieces into the log system at info level. It's more than debug information but expected behaviour so not a warning. So the reference points out that the default configuration of a running racket instance will log to STDERR but at the error level. So anything I put out at the info level is going to be discarded before appearing on STDERR. No worries, I'll get the initial log out to a file. From there I can get the output tweaked to my liking and then return to STDERR at my leisure.

At this point I've got the idea I could find an example and twiddle that. Sure enough I found this Gist from Metaxal, which was pretty much all I needed. Now if I read the concurrency documentation page correctly you get a green thread with the call to thread:

Threads run concurrently in the sense that one thread can preempt another without its cooperation, but threads do not run in parallel in the sense of using multiple hardware processors. See Parallelism for information on parallelism in Racket.

That's not a real problem to me because I'm likely going to be either on my machine or a docker container. So:

(define-logger fl)
(define fl-receiver (make-log-receiver fl-logger 'info))
(current-logger fl-logger)
(define logfile "web.log")

; Listen for events on the log-receiver
(void 
 (thread 
  (λ()(let loop ()
	(define log-vector (sync fl-receiver))
	(with-output-to-file logfile
	  (λ ()
	   (displayln 
	    (format "[~a] ~a\n"
		    (vector-ref log-vector 0)
		    (vector-ref log-vector 1)
		    (vector-ref log-vector 2)
		    (vector-ref log-vector 3))))
	  #:mode 'text #:exists 'append)
	(loop)))))

Now it should also be noted here that I'm mimicking Metaxal's use of void which is effectively kicking the logger off and setting it aside on the assumption I have no further interest in controlling it.

Let's check what happens:

(log-info "test")

Produces:

[info] fl: test - #<continuation-mark-set> # fl

Those last two elements of that vector I receive from the log message don't look interesting in my use case. I'll just back up a little and use the first two elements of the vector. So I get:

(void 
 (thread 
  (λ()(let loop ()
	(define log-vector (sync fl-receiver))
	(with-output-to-file logfile
	  (λ ()
	   (displayln 
	    (format "[~a] ~a\n"
		    (vector-ref log-vector 0)
		    (vector-ref log-vector 1))))
	  #:mode 'text #:exists 'append)
	(loop)))))

Now to tune that second vector element to record what I want.

Step 2 - Format to Taste

2.1 Get the URL

First up I want to see what I can get out of the racket web server, with an example of that I can strip that back to the key pieces. So I set up a very simple servelet and then I'll use that to get me a request object.

(define (hello req)
  (println req)
  (response/output
   (λ (out)
     (displayln "Hello world!" out))))

(serve/servlet
 hello
 #:listen-ip "127.0.0.1"
 #:port 8000das
 #:command-line? #t
 #:servlet-path ""
 #:servlet-regexp #rx"")

Sure enough, I poke it with Firefox and get a promising result:

(request #"GET" (url #f #f #f #f #t (list (path/param "" '())) '() #f) (list (header #"Host" #"localhost:8000") (header #"User-Agent" #"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.16; rv:85.0) Gecko/20100101 Firefox/85.0") (header #"Accept" #"text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8") (header #"Accept-Language" #"en-US,en;q=0.5") (header #"Accept-Encoding" #"gzip, deflate") (header #"Connection" #"keep-alive") (header #"Upgrade-Insecure-Requests" #"1") (header #"If-Modified-Since" #"Sat, 20 Feb 2021 05:16:13 GMT")) #<promise:bindings-GET> #f "127.0.0.1" 8000 "127.0.0.1")

Now if I'm going to need that second argument to request. Interesting point worth noting here. The fact the request struct that you get back is in fact everything you need to simulate the request is lovely. You can pretty much generate a test right off the back of this. If I was really smart I'd make a sampler that used a subset of my requests and fed them into some end to end tests to see what the user experience of my application feels like.

At this point something pretty embarrassing happened but it's a spoiler so with that warning if you wish to skip the logging bit to focus on the webapp bit please feel free to check out Step 1a - RTFM. The clue is in the title :grimacing:

Now just throwing that request struct at the logger is going to induce a type error. So let's take the approach of having a function to get the useful pieces from request. Passing in the request struct was my first thought but the wrinkle in that is the #<promise:bindings-GET> which I think is the runtime reference to the connection you're feeding the response back to. So instead I'm going to pass in the url.

And a quick test to make sure it's OK:

(require "log.rkt"
	 rackunit 
	 net/url)

(define example-url (url #f #f #f #f #t (list (path/param "" '())) '() #f)) 

(test-case
    "gets the url out of the request"
  (check-regexp-match "/" (extract-request-details example-url "")))
(require net/url)

(define (extract-request-details url)
  (url->string url))

(provide extract-request-details)

That yields a passing test.

2.2 Get a good date

As every developer will tell you, once you see how computers handle dates and time it really punctures the idea of computers as universal tool. Sure enough Racket has a few different approaches that you need to weave together to get what you want. Pinching from the Apache log approach:

127.0.0.1 - frank [10/Oct/2000:13:55:36 -0700] "GET /apache_pb.gif HTTP/1.0" 200 2326

I want a date followed by a time and a timezone.

Racket has a base library, a library called Gregor and what I think is a Scheme compatibility library SRFI 19. So to get a representation of the current time you have to emit this perfectly natural looking incantation:

(seconds->date (current-seconds))

Add to that a format and in order to return a string to the user:

> (require racket/date)
> (define now (seconds->date (current-seconds)))
> (date->string now)
"Saturday, February 27th, 2021"
> (date-display-format 'rfc2822)
> (date->string now)
"Sat, 27 Feb 2021"
> (date-display-format 'german)
> (date->string now)
"27. Februar 2021"
> (date-display-format 'irish)
> (date->string now)
"Saturday, 27th February 2021"
> (date-display-format 'julian)
> (date->string now)
"JD 2 459 273"
> (date-display-format 'iso-8601)
> (date->string now)
"2021-02-27"
> (date-display-format 'chinese)
> (date->string now)
"2021/2/27 星期六"
> (date-display-format 'indian)
> (date->string now)
"27-2-2021"

Well not a single one of those seems appropriate. Gregor turned out to be a lot closer to what I was looking for. Gregor has two things that are useful to me, moments and ~t. Once I worked out they were what I needed the rest dropped out pretty quickly. First up, a test case.

(test-case
    "gets a formatted timestamp"
    (let ([example-timestamp (parse-moment "2015-03-15T03:02:11-04:00" "yyyy-MM-dd'T'HH:mm:ssxxx")])
      (check-equal? (logging-timestamp example-timestamp) "2015/03/15 03:02:11 -04:00")))

And then an implementation that provides a green test:

(define (logging-timestamp [timestamp (now/moment)] )
  (~t timestamp "YYYY/MM/dd HH:mm:ss ZZZZZ"))

Note, I'm also defaulting the argument to the timestamp function so during testing I can pass in a deterministic value.

So my log.rkt looks like:

#lang racket/base

(require net/url
	 gregor)

(define (extract-request-details url)
  (url->string url))

(define (logging-timestamp [timestamp (now/moment)] )
  (~t timestamp "YYYY/MM/dd HH:mm:ss ZZZZZ"))

(provide extract-request-details
	 logging-timestamp)

And my main.rkt is now:

   #lang racket/base

(require web-server/servlet
	 web-server/servlet-env
	 "log.rkt")

(define-logger fl)
(define fl-receiver (make-log-receiver fl-logger 'info))
(current-logger fl-logger)
(define logfile "web.log")

; Listen for events on the log-receiver
(void 
 (thread 
  (λ()(let loop ()
	(define log-vector (sync fl-receiver))
	(with-output-to-file logfile
	  (λ ()
	   (displayln 
	    (format "[~a] ~a\n"
		    (vector-ref log-vector 0)
		    (vector-ref log-vector 1))))
	  #:mode 'text #:exists 'append)
	(loop)))))

(define (hello req)
  (define log-url (extract-request-details (request-uri req)))
  (log-info (string-append (logging-timestamp) " " log-url))
  (response/output
   (λ (out)
     (displayln "Hello world!" out))))

(serve/servlet
 hello
 #:listen-ip "127.0.0.1"
 #:port 8000
 #:command-line? #t
 #:servlet-path ""
 #:servlet-regexp #rx"")

That should be enough to get me to logging both to file and STDERR.

Step 3 - Log to Both File and STDERR

Given what I now know, this should be a matter of defining two log receivers and setting them to each destination. In my first implementation I set up a logger called fl (well fl-logger after the macro works its magic) and a receiver called fl-receiver. Then I formatted the output and wrote a line of output. In reality I'm going to do the same thing but rename the logger and the receivers so that they point to where the log messages are going to go to.

If I understand the philosophy here what we're trying to do with a logger is say here's something that will deal with logging events. Receivers are ways of scoping the log events to the events relevant to that output channel. Topics fall further into that bucket of selectivity for things to be cared about. For example I might push debug level events out through STDERR but only log info level events to file to stop my log files gobbling up the disk. Which is fine as far as it goes but what would be really nice would be if I could delegate the thread management to the logger. Then put some kind of callback into the log receiver. As a kind of consolation prize I'll define a list of destinations and go off that. As a side note, hat tip to the kind souls on Stack Overflow who answered my question about the workings of lists.

  (define-logger web)
(define web-logger-receiver (make-log-receiver web-logger 'info))
(current-logger web-logger)

(define (write-to-file destination content)
      (with-output-to-file destination
	  (λ ()
	   (displayln 
	    content))
	#:mode 'text #:exists 'append))

(define (write-to-port destination content)
  (displayln content destination))

(define log-destinations
  (list (list write-to-file "web.log")
	(list write-to-port (current-error-port))))

(define (send-log-content content destinations)
  (unless (null? destinations)
    (let ([ destination (car destinations)])
      ((car destination) (cadr destination) content)) 
    (send-log-content content (cdr destinations))))

; Listen for events on the log-receiver
(void 
 (thread 
  (λ()(let loop ()
	(define log-vector (sync web-logger-receiver))
	(define content (format "[~a] ~a\n"
				(vector-ref log-vector 0)
				(vector-ref log-vector 1)))

	(send-log-content content log-destinations)
	(loop)))))

There are a few obvious refactors that present themselves. The first is that the list of lists defined as log destinations is ungainly. I'd make that contain metadata suitable for understanding the contents so it feels less arbitary (when I write cadr I know I'm being cheeky). Secondly, I'm fairly sure my separation of port and file is overly arbitary and I could make it cleaner by making a file a port and treating both identically. I suspect that would also clear up the duplicate displayln forms. Finally, I'd rejig the loop in the thread to become closer to send-log-content. The gist that inspired the code was dealing with multiple loggers, I've made one logger log to multiple destinations.

At this point all that's required is to wire it into the servelet and we're done…

Step 1a - RTFM

I read through servelet/serve and stopped for a second, surely, some mistake? No, no mistake there's a logger built into servelet/serve. It even does Apache-style logging by default. There is no emoji that adequately conveys that mix of horror and fascination that comes from discovering a few hours of work being obviated because you didn't read carefully enough. But that's what happened.

So all that stuff above? You don't need it. Merely add a keyword argument called #:log-file. Set #:log-file to your stderr usually (current-error-port) and you're off. So main.rkt now looks like:

 (serve/servlet
hello
#:listen-ip "127.0.0.1"
#:port 8000
#:command-line? #t
#:servlet-path ""
#:servlet-regexp #rx""
#:log-file (current-error-port))

Conclusion

All of this could have been avoided if I'd had the patience to read the documentation for the servlet/serve form properly. But I didn't and so here we are. Having said that I've learnt a chunk about how to generate logs in racket and if that comes in handy then overall I've won. I think :smiley: Hopefully for you this has saved you some time and answered questions about generating logs for racket applications. And perhaps acted as a salutary tale of hubris.