- Janet 100%
|
|
||
|---|---|---|
| bundle | Add bundle and project files | |
| deforester.janet | Make :write accept file descriptors | |
| project.janet | Replace old version with smaller yet richer API | |
| readme.md | Document advanced logging techniques with processors | |
Deforester
# A program should set the logger towards the beginning:(deforester/set-logger!{:writeeprint# actually defaults to these:formatjson/encode})(defndouble[x](try(do(defnew-x(+xx))(deforester/log:debug"doubling"# :level and :msg are positional args:inputx:resultnew-x:outcome:success)new-x)([err](deforester/log:error"doubling":outcome:failure:inputx:error(describeerr)))))(double"cat")# {"level":"error","time":"2026年07月11日T18:18:31.040Z","input":"cat","msg":"doubling","outcome":"failure","error":"\"could not find method :+ for \\\"cat\\\" or :r+ for \\\"cat\\\"\""}Deforester:
- follows the modern, production approach goes from event (table) to processors to formating (table->string) to writing
- falls back to stderr so logging fail won't crash
- filters levels before evaluating args
- outputs NDJSON (if
json/encodeset) consumed likejq . log.ndjsonetc.
In web prod, most things print unbuffered event streams with the orchestrator aggregating them. However, for human scale personal computing or random programs run locally, logging to a file is often more handy, so Deforester offers file-writer:
(deforester/set-logger!{:write(file-writer"log.txt"):formatdeforester/text-format})(defncheck-price[itemurl](defresp(http/geturl))# a la Joy(defprice(parse-price(resp:body)))(when(<price20)(deforester/log:info"price drop":itemitem:priceprice))price)Usage
Deforester exposes the following bindings: log, set-logger!, with-log-ctx, with-duration-logged, with-config, log* along with config helpers text-format and file-writer and key-renamer:
(log :warn "cat")takes level and message as position arguments, by default returning:{"msg":"cat","level":"warn","time":"2026年07月11日T05:44:28.553Z"}(set-logger! {:format text-format :write (file-writer "l.txt")})makes(log :warn "cat")writetime=2026年07月11日T05:57:20.678Z level=warn msg=cattolog.txt(set-logger! {:processors [(key-renamer {:time "@timestamp" :msg "message"})]})makes(log :warn "cat")emit:{"@timestamp":"2026年07月11日T08:14:16.968Z","level":"warn","message":"cat"}:writecan be a closure (prefered) or a file descriptor likestdout:
(with[f(file/open"app.log":a)](set-logger!{:writef})(log:warn"ok"))with-duration-ctxadds aduration-mstologcalls it wraps
(with-duration-ctx(os/sleep.5)(log:info"fetched":status:ok))with-configis very useful for tests:
(defcaptured@[])(with-config{:write|(array/pushcaptured$)}# capture logs in a buffer(log:info"caught"))(ppcaptured)or even overwrite the :msg or :time for stable snapshot test results:
(deflines@[])(with-config{:formattext-format:write|(array/pushlines$):processors[|(put$:time"T")]}(log:info"user login":id7)(log:debug"noise")(with-config{:min-level:warn}(log:info"suppressed")))(assert(deep=lines@["time=T level=info msg=user login id=7""time=T level=debug msg=noise"]))with-log-ctxmodifies the context in a fiber, including overwriting:timefor tests:
(deftickers["WAL""EQX""SODI"])(with-log-ctx{:job-id5}# small example(defdone(ev/chan))(eachtickertickers(ev/spawn(with-log-ctx{:tickerticker}(log:info"fetching":len(lengthticker)))(ev/givedoneticker)))(repeat(lengthtickers)(ev/takedone)))### bigger example(defnfetch-quote[ticker](ev/sleep(*0.01(math/random)))# simulate work(if(>(math/random)0.8)(error"connection reset")(math/floor(*100(math/random)))))(with-log-ctx{:job-id5}(defdone(ev/chan))(deftickers["WAL""EQX""SODI"])(eachtickertickers(ev/spawn(with-log-ctx{:tickerticker}(def[okr](protect(fetch-quoteticker)))(ifok(log:info"quote":pricer)(log:errorr))(ev/givedoneok))))(defoks(seq[_:range[0(lengthtickers)]](ev/takedone)))(log:info"job":total(lengthtickers):failed(countnotoks)))Here is an example processor emulating Go's Zap, checking events/logs and forward some to a special location:
(defnreporter`Make processor sending events pred accepts via report-fn (e.g. a sentry client),
passing the event through unchanged. Reporting failures never break logging:
* (set-logger! {:processors [(reporter |(= ($ :level) :error) send-to-sentry)]})`[predreport-fn](fn[e](when(prede)(try(report-fn(table/to-structe))([_]nil)))e))(defnsend-to-sentry[package](spit"bla.txt"(string/format"%j\n"package):a))(defq(ev/chan1024))(ev/spawn(forever(send-to-sentry(ev/takeq))))(set-logger!{:processors[(reporter|(=($:level):error)|(ev/giveq$))]})(log:error:ok)(log:error:ok)(ev/sleep0.1)# to let the blocked calls go through in REPLAnother useful processor:
(defnsampler`Make processor keeping only every n-th event per [level msg] pair:
* (set-logger! {:processors [(sampler 100)]})`[n](defseen@{})(fn[e](defk[(e:level)(e:msg)])(putseenk(inc(getseenk0)))(if(=1(mod(seenk)n))e)))How to Log
A logging library can only make it easy to emit good events, but the consumer's taxonomy design of what events exist, how they're named, with what fields etc. is where all the benefit comes from. Writing useful events demands much discipline.
For personal stuff, just toss :time, :level, :msg and domain info in a file after filtering.
- log wide events with outcomes not actions - show a full unit of work showing what happened (not starting, doing, finishing x)
- events should answer what happened to what and why with what result (if the site lacks all such context, the log should be emited higher up the chain)
- if a unit of work somehow spans multiple events, include a single id to rejoin them together (hence
with-log-ctx)
- log decisions with reasons - if something different happens (retry, skip) explain why
:reason :already-present - use consistent key names (with a glossary in the readme)
msgshould be an event name; details should go in other fields sojq select(.msg == "fetched")works- keys should hold values like
:status 429instead of prose:msg "got status 429" - measure
:msduration (besides:time) whenever doing i/o, latency drift's often a first symptom - keep set of keys and
:msgnames small, their values should exhibit variation
- relevant metrics create business value; queries over good logs are metrics
- include success too (to have a denominator to calculate rates and generate business metrics like duration and customer quotas)
- guard with expectation/plausibility checks so
200's with garbage don't pass through
- if code should act on something, it belongs in a table/file and logs should just show the point of discovery. Log observations, keep facts in "state" (don't make the logs into a db)
People disagree on what keys to use:
- zerolog:
time,level,msg - zap:
ts,level,msg - elastic common schema:
@timestamp,log.level,message - OpenTelemetry specifies
TimeStamp,SeverityText,Body,Attributes
Or durations:
with-duration-logged currently has :error (message), :duration-ms and :outcome which can be :success or :failure
- OTEL handles this via spans with
exception.message andstatus.codewhich can sayOKorerror - ECS has
message,event.duration (in nanoseconds),error.message,log.levelandevent.outcome which can besuccessorfailure
On levels
Levels conflate how much attention something deserves with a value to filter on. Alternatives to level systems mostly exist to try to deal with this:
- verbosity
-vor-vvorv(3)but what does verbosity 3 even mean? - tag sets like
{:anomaly :external :retryable}are very expressive but lead to taxonomic explosion and turn filters into queries - no levels at all (event streams etc.) leave everything to the reader - storage prices can add up but useful with good queries and metric collectors, bad for personal stuff
- OTEL or syslog severity numbers and named aliases adhering to specific interop
My suggested levels focus on attention and audience:
:debughelps investigate an issue (discarded normally):infodescribes normal operation (should be short for a healthy system):warnshows unexpected things handled well (e.g. retry succeeded, fallback, skipped input, approaching quota) (so expected external failures belong here (or maybe:info)):errorshows unrecovered failures (which a person should look at)
When you want to add more levels, perhaps do e.g. :topic :audit to keep category distinct from attention. :topic is a useful field.