# Threads and modules; how do they interact?

**URL:** <https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286>\
**Category:** Questions & Answers\
**Created:** [November 1, 2024, 11:39am UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286 "2024-11-01T11:39:11Z")\
**Posts on this page:** 13\
**Page:** 1

<div class="post-metadata">

**Author:** ![bakgatviooldoos](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/bakgatviooldoos/32/1381_2.png) [@bakgatviooldoos](https://racket.discourse.group/u/bakgatviooldoos)\
**Post date:** [November 1, 2024, 11:39am UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/1 "2024-11-01T11:39:11Z")

</div>

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.

```scheme
#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.

---

<div class="post-metadata">

**Author:** ![greghendershott](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/greghendershott/32/98_2.png) [@greghendershott](https://racket.discourse.group/u/greghendershott)\
**Post date:** [November 1, 2024, 12:38pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/2 "2024-11-01T12:38:10Z")

</div>

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, 🙂 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.

---

<div class="post-metadata">

**Author:** ![bakgatviooldoos](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/bakgatviooldoos/32/1381_2.png) [@bakgatviooldoos](https://racket.discourse.group/u/bakgatviooldoos)\
**Post date:** [November 1, 2024, 12:46pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/3 "2024-11-01T12:46:19Z")

</div>

Thank you, @greghendershott.

> [@greghendershott](#):
>
> 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.

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.

---

<div class="post-metadata">

**Author:** ![greghendershott](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/greghendershott/32/98_2.png) [@greghendershott](https://racket.discourse.group/u/greghendershott)\
**Post date:** [November 1, 2024, 12:46pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/4 "2024-11-01T12:46:19Z")

</div>

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 `require`d 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.

---

<div class="post-metadata">

**Author:** ![bakgatviooldoos](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/bakgatviooldoos/32/1381_2.png) [@bakgatviooldoos](https://racket.discourse.group/u/bakgatviooldoos)\
**Post date:** [November 1, 2024, 12:47pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/5 "2024-11-01T12:47:03Z")

</div>

Uitstekend, dankie ❤

---

<div class="post-metadata">

**Author:** ![greghendershott](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/greghendershott/32/98_2.png) [@greghendershott](https://racket.discourse.group/u/greghendershott)\
**Post date:** [November 1, 2024, 12:48pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/6 "2024-11-01T12:48:30Z")

</div>

> [@bakgatviooldoos](#):
>
> 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.

Two logger topics is definitely not abuse. 😄

---

<div class="post-metadata">

**Author:** ![bakgatviooldoos](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/bakgatviooldoos/32/1381_2.png) [@bakgatviooldoos](https://racket.discourse.group/u/bakgatviooldoos)\
**Post date:** [November 1, 2024, 12:50pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/7 "2024-11-01T12:50:41Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![bakgatviooldoos](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/bakgatviooldoos/32/1381_2.png) [@bakgatviooldoos](https://racket.discourse.group/u/bakgatviooldoos)\
**Post date:** [November 1, 2024, 1:03pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/8 "2024-11-01T13:03:36Z")

</div>

> [@greghendershott](#):
>
> sometimes you need less than you think

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.

---

<div class="post-metadata">

**Author:** ![greghendershott](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/greghendershott/32/98_2.png) [@greghendershott](https://racket.discourse.group/u/greghendershott)\
**Post date:** [November 1, 2024, 1:05pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/9 "2024-11-01T13:05:47Z")

</div>

> 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. 😄

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.

---

<div class="post-metadata">

**Author:** ![greghendershott](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/greghendershott/32/98_2.png) [@greghendershott](https://racket.discourse.group/u/greghendershott)\
**Post date:** [November 1, 2024, 1:07pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/10 "2024-11-01T13:07:26Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![LiberalArtist](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/liberalartist/32/151_2.png) [@LiberalArtist](https://racket.discourse.group/u/LiberalArtist)\
**Post date:** [November 1, 2024, 2:23pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/11 "2024-11-01T14:23:53Z")

</div>

> [@greghendershott](#):
>
> 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.

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.

---

<div class="post-metadata">

**Author:** ![bakgatviooldoos](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/bakgatviooldoos/32/1381_2.png) [@bakgatviooldoos](https://racket.discourse.group/u/bakgatviooldoos)\
**Post date:** [November 1, 2024, 3:08pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/12 "2024-11-01T15:08:06Z")

</div>

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!"

---

<div class="post-metadata">

**Author:** ![bakgatviooldoos](https://yyz2.discourse-cdn.com/free1/user_avatar/racket.discourse.group/bakgatviooldoos/32/1381_2.png) [@bakgatviooldoos](https://racket.discourse.group/u/bakgatviooldoos)\
**Post date:** [January 6, 2025, 5:59pm UTC](https://racket.discourse.group/t/threads-and-modules-how-do-they-interact/3286/13 "2025-01-06T17:59:05Z")

</div>

My colleague was showing me the improvements he'd made to our internal logging using `Serilog`, and I enjoyed an aspect of the structured logging the library provides, which looks something like this:

```scheme
log("This is a {type} log. It has some {what}." "info" "structure")

```

This exposes the template string and the key-value pairs, i.e., "type: info" and "what: structure" when the log is received.

So, I wanted to see if I could whip up something similar.

Leaning somewhat on the `at-exp` at-lang, the results are quite pleasing for a couple of minutes' work:

```scheme
#lang at-exp racket/base

(require
  (only-in
   racket/format ~a)
  (only-in
   racket/function thunk)
  (only-in
   racket/match match-lambda)

  racket/stxparam
  (for-syntax
   racket/base))

(define key-pairs (make-parameter #false))
(define keys-mark (gensym))
(define tmpl-mark (gensym))

(define (get-pair key)
  (define pair (assoc key {key-pairs}))
  (unless pair
    (error 'log-key "no value found for key: ~a" key))
  pair)

(define-for-syntax log-key
  (syntax-rules ()
    [(_ key)
     ({key-pairs `(,(get-pair 'key) . ,{key-pairs})}
      . and . "~a")]
    
    [(_ key val)
     ({key-pairs `((key . ,val) . ,{key-pairs})}
      . and . "~a")]))

(define-syntax-parameter > #false)

(define-syntax-rule
  (log-keys log . message)
  #;becomes
  (syntax-parameterize ([> log-key])
    (parameterize ([key-pairs null])
      (define ~msg (~a . message))
      (define keys (reverse {key-pairs}))
      (with-continuation-mark tmpl-mark ~msg
        (with-continuation-mark keys-mark keys
          (log (apply format ~msg (map cdr keys))))))))

(define (get-log-keys cms)
  (car (continuation-mark-set->list cms keys-mark)))

(define (get-log-template cms)
  (car (continuation-mark-set->list cms tmpl-mark)))

(define (start-receiver-thread
         #:logger logger
         #:level level
         #:handler handler)
  (define receiver (make-log-receiver logger level))
  (thread
   (thunk (let receiver-loop ()
            (sync
             (handle-evt (thread-receive-evt) void)
             (handle-evt
              receiver
              (match-lambda
                [(vector level message data topic)
                 (handler level message data topic)
                 (receiver-loop)])))))))

(define-logger test)

(define terminal-log-receiver
  (start-receiver-thread
   #:logger test-logger
   #:level 'debug
   #:handler
   (lambda (level message data topic)
     (printf "[~a]\n~a\n\n" level message)
     (printf "keys: ~a\n" (get-log-keys data))
     (printf "tmpl: ~s\n" (get-log-template data)))))

@log-keys[log-test-info]{
 This is a @>[type 'fun] log.
 I am going to post on my @>[where 'terminal] about it.
 Long live @>[who 'Racket]!
 P.S. did I mention this was @>[type]?}

```

```scheme
[info]
test: This is a fun log.
I am going to post on my terminal about it.
Long live Racket!
P.S. did I mention this was fun?

keys: ((type . fun) (where . terminal) (who . Racket) (type . fun))
tmpl: "This is a ~a log.\nI am going to post on my ~a about it.\nLong live ~a!\nP.S. did I mention this was ~a?"

```

Not super rigorous or anything, but it's so pleasing to be able to craft such nice tools so easily.

Happy new year, everybody :racket_heart:.