1
0
Fork
You've already forked deforester
0
Logging for Janet
  • Janet 100%
Find a file
2026年07月11日 20:41:00 -06:00
bundle Add bundle and project files 2025年09月15日 00:46:41 -04:00
deforester.janet Make :write accept file descriptors 2026年07月11日 19:34:11 -06:00
project.janet Replace old version with smaller yet richer API 2026年07月11日 01:01:06 -06:00
readme.md Document advanced logging techniques with processors 2026年07月11日 20:41:00 -06:00

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/encode set) consumed like jq . log.ndjson etc.

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") write time=2026年07月11日T05:57:20.678Z level=warn msg=cat to log.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"}
    • :write can be a closure (prefered) or a file descriptor likestdout:
(with[f(file/open"app.log":a)](set-logger!{:writef})(log:warn"ok"))
  • with-duration-ctx adds a duration-ms to log calls it wraps
(with-duration-ctx(os/sleep.5)(log:info"fetched":status:ok))
  • with-config is 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-ctx modifies the context in a fiber, including overwriting :time for 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 REPL

Another 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)
    • msg should be an event name; details should go in other fields so jq select(.msg == "fetched") works
    • keys should hold values like :status 429 instead of prose :msg "got status 429"
    • measure :ms duration (besides :time) whenever doing i/o, latency drift's often a first symptom
    • keep set of keys and :msg names 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​ and status.code which can say OK or error
  • ECS has message​, event.duration​ (in nanoseconds), error.message​, log.level​ and event.outcome​ which can be success or failure
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 -v or -vv or v(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:

  • :debug helps investigate an issue (discarded normally)
  • :info describes normal operation (should be short for a healthy system)
  • :warn shows unexpected things handled well (e.g. retry succeeded, fallback, skipped input, approaching quota) (so expected external failures belong here (or maybe :info))
  • :error shows 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.