Improving Logging With Racket

Almost a year ago I wrote about logging with Racket in Logging With Racket. As it happened the end was a bit embarrassing for me 😅 but you live and you learn. Well I decided to code in Racket for another another project and that is a long-running batch process. As part of that I ended up iterating on the solution I put in that blog post so I figured I'd talk about it a little.

When To Log

So the project I'm working on is about finding private data and helping you to mange it. The process can run for a very long time and depending upon what's happening can be both computationally and memory intensive. That means that I'm going to run into all the errors, resource constraint, performance, garbage collection… So I need to setup logging to help me through the various ways that the process can fail.

A bit of an aside

I've found recently there's a bit of lost art within development teams I've worked on regarding logging within server environments. Particularly with APIs and Node.js environments the assumption is that you can poke the server environment with a tool like curl or postman and then connect to the server with a tool (I've seen this most often with VS Code but I know you can get Chrome to do the same thing) and debug the code. Some people do this in production too although that kind of access might well make your security team nervous. There's a heavy parallel with REPL-driven development here where it's realistic and efficient to develop with a running image of the software you're working upon. The effect of which seems to discourage logging. This is bad because unless you catch the software in the act of misbehaviour you have nothing to go on. And who wants to be up at 3AM waiting for something to go wrong? 😃 So log regularly, you'll be grateful later. Make it part of code reviews that you're actively maintaining coherent and effective logs. I'm not saying don't have ways to interact with running systems. But make sure you have logging in place.

If you're new to the topic I would suggest looking at what Charity Majors is saying. Observability is an overarching concept that includes logging so there's a higher goal to build towards. But getting logging humming leads to other good places and don't let people (especially tool vendors) tell you that logging isn't part of observability.

Concepts Of Racket Logging

Logging in racket is quite flexible, but to recap the main concepts as I understand them:

The top level is the racket logger. The need for this is arguable. Certainly Racket comes with a default logger that is wired to STDERR and your system log. Its also set to log at the error level. If all you want to do is send things that go wrong to those two destinations everything is there for you. I don't so I've chosen to have a different logger. You can create a tree of loggers, certainly I've wired my logger underneath the main logger. Which I believe means that for error messages they will flow up the logger tree and arrive in STDERR and the system log as well as in my designated outputs.

The next level is the log receiver. This filters what's coming into the logger. It filters at two levels, the first is the log level. The second is the log topic. Between those two you can create fine-grained events that match your needs. Having the ability to separate these logs is quite neat, you can think about ideas like slow logging and fast logging separately for instance.

The third level is the destination. The logging framework isn't quite as explicit here but the general idea is that you set up an output and then when the log message comes in you write it out to the form of output. It's certainly a bit more on the developer to consider what might be good or bad for a particular destination.

With those three setup you push in the log messages to the logger. The logger then delegates the nitty gritty of outcome to the receivers and designations.

Where I Started

So from Logging With Racket I took the code from step 3 and plonked it into my main.rkt:

  (define-logger agent)
  (define agent-logger-receiver (make-log-receiver agent-logger 'info 'agent))
  (current-logger agent-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 "pii_agent.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)))))

Then I began to drop logging calls into my code like:

(log-info "Run completed.")

But I soon noticed I had an issue. During runs I'd sometimes, not consistently, miss the final log message. I pretty quickly realised I was in trouble. This smells like a classic threading error. I knew the call to to thread inside void effectively span up a thread with no control. The lambda would run as long as the program becuase the intentionally infinite loop wold just keep rolling. But clearly the thread was being killed before it had time to output the last log message. That prompted me to post on the Racket Discourse. Sure enough the reply both confirmed my suspicions and was helpful enough to set me on the right track.

Whare I Ended Up

So firing that thread inside the void needed cleaning up. At this point I decided to pull the code out main.rkt and move it to it's own home logging.rkt:

#lang racket/base
(require racket/function)

(provide log-thread)

(define-logger agent #:parent (current-logger))
(define agent-logger-receiver (make-log-receiver agent-logger 'info 'agent))
(current-logger agent-logger)

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

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

(define log-destinations
  (list (list write-to-file "pii_agent.log")
        (list write-to-port (current-output-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
(define log-thread
  (thread 
   (thunk
    (let loop ()
      (define log-vector (sync agent-logger-receiver))
      (define content (format "[~a] ~a\n"
                              (vector-ref log-vector 0)
                              (vector-ref log-vector 1)))
      (send-log-content content log-destinations)
      (when (thread-try-receive)
        (kill-thread (current-thread)))
      (loop)))))

A few things to note here. First up is that I only provide one form. That being log-thread, this feels wierd becuase of the amount of setup that goes into logging.rkt but I've checked and it functions as expected.

The thread is now defined and returned with a variable name. This means the thread can be communicated with. The thunk form is a lot like lambda it just takes no arguments. Inside the loop is now a when form and that's key to the whole thing.

Threading in Racket

Now I'm not going to pretend that I know the Racket VM well enough to explain all the vagaries of threading in Racket but the keys things I do now know are:

  1. Threads are green threads. Racket is not a truly multithreaded language.
  2. Sync-able events are not enough to stop a thread being killed ☹. That's how I got here.
  3. Threads are controlled by Custodians. I don't fully grok that yet.
  4. Every thread has a Thread Mailbox.

Back To The Solution

The reason 4. is important is becuase initially I moved the the thread to log-thread called that from main.rkt and then called thread-wait as suggested in Racket Discourse:

(thread-wait log-thread)

Of course then I waited… and waited… and realised I was waiting on an infinite loop to terminate 🤦. I needed a way to tell the logging thread to terminate so that it could clean up and then allow main.rkt to complete. Those with a theoretical interest in Computer Science will recognise this as a halting problem and likely have a knowing smirk on their faces 😄

So now the when makes a bit more sense. I use the fact the thread has a mailbox. Once the loop detects the thread mailbox has a message in it it shuts down the thread. This means once the work of the program is complete I can send a message from main.rkt and wait for an orderly shutdown of the thread:

(thread-send logging-thread 'time-to-stop)
(thread-wait logging-thread)

I do the check for the message after the body of the loop has executed. Thereby ensuring I have flushed the last message out of the logger by the time the check is run. That's a hack, put the check at the top of the loop or have multiple messages waiting for the loop to run and I'm hosed. But for today I've fixed my issue.