Threads and modules; how do they interact?

Hi, Racket Discourse.

I have a very simple application, with a small set of log-sources (services and schedule), so I have only two loggers provided to the rest of the application, along with the starting-of and shutting-down of the log-receiver threads, which are handled at the entry/exit-point of the application.

At the base, the two loggers are children of a terminal-logger, which receives all the logs to be displayed to the console as the application is running.

This works fine when the application is properly started, but when I am testing individual parts, I would like to obviously see the results of these logs, and I am not a fan of riddling everything with print expressions.

I thought of just unwrapping the procedure for starting the terminal receiver, but because this produces a thread, and the module is required many times over in my application, I am wondering if this is a silly idea. Will this spawn new threads each time?

The other idea I had, was to wrap log-message and have that check whether the application is in development mode, and then dispatch anything to the console when it is, but this also seems yucky, because I have to change all the existing call-sites.

#lang racket

(require "../data.rkt"
         "../helpers/database-helper.rkt")

(provide start-loggers
         schedule-logger
         services-logger)

(define terminal-logger (make-logger 'terminal))
(define schedule-logger (make-logger 'schedule terminal-logger))
(define services-logger (make-logger 'services terminal-logger))

(define logger-custodian (make-custodian))

(define (start-receiver-thread
         #:logger  logger
         #:level   level
         #:handler handler)
  (define receiver (make-log-receiver logger level))
  (parameterize ([current-custodian logger-custodian])
    (thread
     (thunk (let receiver-loop ()
              (sync
               ; end when the thread receives the '(stop) message
               (handle-evt (thread-receive-evt) void)
               ; otherwise, continue
               (handle-evt
                receiver
                (match-lambda
                  [(vector level message data topic)
                   (handler level message data topic)
                   (receiver-loop)]))))))))

(define (start-database-log-receiver logger level)
  (start-receiver-thread
   #:logger logger
   #:level  level
   #:handler
   (lambda (level message data topic)
     (define now (current-seconds))
     (with-db-connection (db:connect)
       ; the `conn` is syntax if that seems weird
       (db:insert-log conn now (~a level) (~a topic) message)))))

;;
;; This is the culprit
;;
(define terminal-log-receiver
  (start-receiver-thread
   #:logger terminal-logger
   #:level  'debug
   #:handler
   (lambda (level message data topic)
     (displayln (format "[~a]\n~a\n" level message)))))

(define (start-schedule-log-receiver)
  (start-database-log-receiver schedule-logger 'debug))

(define (start-services-log-receiver)
  (start-database-log-receiver services-logger 'debug))

(define (start-loggers)
  (define threads `(,terminal-log-receiver
                    ,(start-schedule-log-receiver)
                    ,(start-services-log-receiver)))
  ; return the procedure for stopping all the loggers
  (thunk
   (for ([thd (in-list threads)]) (thread-send thd '(stop)))
   (for-each thread-wait threads)
   (custodian-shutdown-all logger-custodian)))

Is there a more idiomatic/typical way of approaching this, or could I safely do this without worrying about errant threads all over the place?


Edit:
To elaborate what I mean by "spawn new threads", suppose that I have modules "A.rkt" and "B.rkt", and B requires some things from A, causing execution of things in B to also execute things in A. Both of these modules require "logging.rkt", which has, hypothetically, a thread value defined within it.

My intuition is that there may be separate threads being spawned for A and B from their require, but I can't say for sure.

It can be confusing because there is the concept of log topics, plus loggers, plus log receivers, and sometimes you need less than you think.

TL;DR: Probably you should:

  1. Write your own topics to the default logger (don't need make-logger).

  2. The default logger has two default log receivers, for stderr and stdout.

  3. Use the PTLSTDERR environment variable to show more messages to stderr. For example show debug level for your two topics 'schedule and 'services. (Or, run under DrRacket or Racket Mode, which can show log messages in their UIs.)

  4. Optionally you can use define-logger to define handy "log-topic-level" wrappers around log-message. (Although this also defines/uses a logger, which I said not to do, :slight_smile: this is a TL;DR. My point is to think about receivers as controlling what topics/levels get shown, where/how.)


  1. Optional: If that's still not quite what you want, have a look at with-intercepted-logging, or with-logging-to-port. Or, you could even use make-log-receiver to make your own log receiver to write stuff to a port, to a db, to AWS CloudWatch, or wherever.

    All of these will spawn a thread per log receiver (that's how receivers work), but if you put this in one module (like logger.rkt) and require that in others, you should be OK, just one thread overall per process/run.

1 Like

Thank you, @greghendershott.

This answers my question, basically, but I have read some of your other replies around logging and I definitely feel like I have not yet grokked well the interplay of the loggers and receivers and levels and topics (what a bunch, haha).

I abuse? the topics, because there are multiple services and schedules under the banners schedule and services which I use to differentiate them in the DB logs.

I feel cogs turning about the receivers controlling the behaviour, though, thanks for that nugget.

p.s. Because I've found loggers confusing, myself, I replied in XY Problem.

The real TL;DR, to the question you actually asked, is:

A module-level expression is evaluated just once, even when the module is required multiple times.

If some module-level expression creates a thread, then require-ing that module multiple times will not create multiple threads.

It's the same as if the module-level expression were "hello, world". If you require that from multiple modules, you'll see that displayed just once.

Uitstekend, dankie :heart:

Two logger topics is definitely not abuse. :smile:

1 Like

I misspeak, I have loggers which are "banners", but the topics are, for example, blocklist, mailbox, sentinelone, etc. under the services story :sweat_smile:.

1 Like

And now that you surface this, I could probably just get rid of the distinction between services and schedule altogether if I am passing the more specific topics anyway. Barring any behavioral distinctions (of which there aren't any).

Talking to people always helps to clarify the mind.

I definitely feel like I have not yet grokked well the interplay of the loggers and receivers and levels and topics (what a bunch, haha).

Maybe it helps to think of it as

  • a system with "publishers" and "subscribers"
  • a way for subscribers to say they're only interested in certain levels and topics
  • an optimization where publishers can prevent authors from doing any work to write and send stories no one wants to read. :smile:

Subscribers are in control of what gets written in the first place. And once they get stuff, the subscriber controls how/where it gets shown/written. Ergo the focus on log receivers.

I abuse? the topics, because there are multiple services and schedules under the banners schedule and services which I use to differentiate them in the DB logs.

You can use as many topics as you want. The granularity should probably be whatever lets receivers filter as precisely as you might want.

For further subdivisions, it's fine to embed more "categories" in the string message.

Also, note that each log message can have, in addition to the string message, any arbitrary Racket value! Obviously the standard receivers won't know what to do with this, but if you have a receiver writing to a db, the value could be a list of additional columns/values to insert, or whatever.

I'd think of the topic as a "unit of filtering". Additional categorization could go in the string message or the arbitrary Racket value, as I posted while you were posting your message.

1 Like

If you want to have the string message but also pass on extra structured information for cooperating log receivers, you can do so by putting the extra stuff in a continuation mark.

1 Like

Loggers have such a rich API. Thank you for mentioning this, too.

One is tempted to structure an application more tightly around their machinery. "To the lab!"