Various files in my CLI application define loggers -- there's a (define-logger users) in the users.rkt file, and a (define-logger files) in files.rkt and so on. I'd like to collect all the log output into a single log file; up until now I've done the standard thing and run it as "... 2>&1 | tee app.log" but this has lead to some issues with multithreading, where messages get overlapped with one another. This is weird; I've never had this issue before and I'm not sure what's causing it, although my best guess is that I've started doing a lot more logging lately and so I've probably just crossed a threshold where I'm getting unlucky.
I'm wondering what the best way to solve this is? I've come up with a few options relating to log receivers and parent loggers but I'm not happy with any of them. I checked the package server but saw nothing that seemed apropos. I googled and likewise came up with nothing solid.
This has to be a common problem so I'm sure I'm missing something. Can anyone point me to the relevant FM section?
(Before anyone asks: I'm aware that racket-mode handles its logging nicely. I need to have multiple instances of the program running simultaneously and want them to be in separate processes so as to better simulate the actual environment.)
There are several ways to deal with logging. The easiest is to set PLTSTDERR (or PLTSTDOUT) in the environment to the appropriate logging topic/levels and use shell redirection to send the data to a file or whatever. I like using this for scripts since it doesn't require any extra configuration in Racket. I can just call logging functions. This also works really well in Docker as it lets you connect the standard out and error to other logging systems.
The next easiest is to explicitly set up a hierarchy in your loggers and set up a receiver on just the root logger.
Alternatively, if you don't define a parent logger it uses (current-logger) and it could be passed to make-log-receiver. Be careful doing it this way though as you may get logs from Racket or third party packages mixed in with all of your other logs.
If it is not possible to create a logger hierarchy then use make-log-receiver on all of the loggers and multiplex them with sync in your logging thread.
I think @SamPhillips's answer covers for what you can do for one process and possibly multiple when you combine logs via the shell redirection he has mentioned.
This prompted me to "log" my thoughts about multi-process in another topic:
One simple way might be a tcp client-server, all processes send their logs to the logging server, it merges them, writes them to one file. (This could make sense if you don't want to use one of the places variants)
In the other topic I also mentioned a few general tools that might be interesting depending on your details.
Lastly there are also a lot of logging services (which may be either interesting or useless depending on what you want and need) and people writing their own logging servers, so that they have something they can run themselves instead of having to use hosted services. Either of those might be useful, if you don't want to write something like a log server yourself.
Any library could potentially change (current-logger) globally when it is required, but in practice, I've never seen a library do that. So both modules should see the same logger.
@SamPhillips Regarding limiting what you see: In my experience it's not necessary to define my own loggers. Instead it's sufficient to make a single log receiver, watching only the desired topics and levels.
Then, as you showed, it's just a matter of calling sync on the log receiver repeatedly, and doing something with the results (writing to stdout, or to a file, or whatever).
@dstorrs As a long as it's a single thread sync-ing a single log receiver and writing to stdout, you should never see "overlapped" log messages.
You might have seen the default log receiver writing to stdout... and also your program is writing other messages there. Those two will definitely get garbled, eventually.
So I think the base/typical case is: A single log receiver per "output resource" (file, stdout, cloud log storage server, whatever). And then everything should be clean.
@SamPhillips Regarding limiting what you see: In my experience it's not necessary to define my own loggers. Instead it's sufficient to make a single log receiver, watching only the desired topics and levels.
Then, as you showed, it's just a matter of calling sync on the log receiver repeatedly, and doing something with the results (writing to stdout, or to a file, or whatever).
@dstorrs As a long as it's a single thread sync-ing a single log receiver and writing to stdout, you should never see "overlapped" log messages.
You might have seen the default log receiver writing to stdout... and also your program is writing other messages there. Those two will definitely get garbled, eventually.
So I think the base/typical case is: A single log receiver per "output resource" (file, stdout, cloud log storage server, whatever). And then everything should be clean.
Nope, these were log messages interwriting one another. Which was distinctly weird and I didn't think Racket's logging system could do that, hence my question. I'm away from my computer but I'll post an example later.
Nope, these were log messages interwriting one another. Which was distinctly weird and I didn't think Racket's logging system could do that, hence my question. I'm away from my computer but I'll post an example later.
Interesting! My guess would be that's a result of multiple log receivers -- maybe one you created as well as the default, both writing to stdout.
Because current-output-port is a very popular resource, anything involving multiple threads writing to it is likely to
the ordering.
have problems with
Does (define-logger foo) have a separate log receiver than the default one?
It does not.
I realize I should clarify something I wrote above:
In my experience it's not necessary to define my own loggers.
@SamPhillips had an example I understood to be about loggers where you're trying to give them parents and make a hierarchy.
What I meant is that I don't do that.
But of course I do use define-logger all the time, which defines log-<topic>-<level> forms.
This way, the log receivers say what topics and levels they care about. This lets the log-<topic>-<level> forms avoid work if no receiver cares, and with that decision deferred until runtime. So that's a pretty flexible and efficient approach. You can "dial up or down" verbosity/focus without recompiling your program. You can even have some UI or API in which you re-create a log receiver, to change the topics/levels, while your program is running.
Although it's also possible to use make-logger to make loggers in a hierarchy, which propagate only some topics and levels to their parent loggers... and although I'm sure there are good use cases for that... I haven't encountered them yet.
That's why I suggested for most people it makes sense just to use define-logger when you want some new distinct logger topic, and then maybe use one or more custom log receivers.
TL;DR: One define-logger per topic. One make-log-receiver per logger output destination.
At least that's my understanding, and as usual I look forward to learning otherwise or more!
I agree 100%. I think the Racket logger is a good API. But it feels like there aren't many published best practices on using it effectively, and many of us have internalized a personal style or cribbed a style from other code we've read.
Additionally, more libraries should document what topics they log to, and it would be nice to see that easily in the docs.
