Logging

Structured events with log.debug/info/warn/error, where the lines go, and what a 500 records.

log is a top-level method returning the request’s logger. There is one logger per request and it carries the request id, so lines from one visit can be picked out of the stream.

post "/admin/refresh" do
  log.info "refresh requested", feeds: db.first("SELECT COUNT(*) AS c FROM feeds")["c"].to_s
  refresh_feeds
  redirect "/admin"
end

The four levels

log.debug(message, **fields)
log.info(message, **fields)
log.warn(message, **fields)
log.error(message, **fields)

message is a String. fields are keyword arguments; both keys and values are stringified, so pass what you like and it arrives as text. All four return nil — never use the return value.

log.warn "feed failed", feed: name, error: e.message, status: res.status

Keep fields flat and short. There is no nesting, no JSON value, no object serialisation: a Hash or Array passed as a field arrives as its to_s, which is rarely what you want. Format it yourself first.

There is no log.level=, no per-app filtering and no way to suppress a level — every line is written.

Where the lines go

Under melee dev a line is written to the terminal (stderr) as level key=value …:

info msg="refresh requested" feeds=3
error msg=bad route="GET /boom" method=GET path=/boom class=ArgumentError

Values containing a space, a quote or = are quoted. The dev server also prints one line per request (GET /admin -> 200 (4.2 ms)).

In production the same event is sent to melee-server as a log frame, stored as one NDJSON object per line in the app’s log file, and read back with melee logs:

melee logs              # the last 50 lines
melee logs --tail 200
melee logs -f           # follow

melee logs prints HH:MM:SS msg key=value …. Anything the app writes to stderr directly ($stderr.puts, and any uncaught output from the runtime) is captured too and shown as-is. Use log, not puts: puts goes to stdout, which is buffered and not collected.

The 500 line

When an exception escapes a route, melee logs exactly one error line before your error handler runs:

error msg=<exception message> route="GET /boom" method=GET path=/boom class=ArgumentError

route is the pattern that matched, not the concrete path. That is all there is — a Spinel-compiled app has no backtrace (Exception#backtrace returns []), so the class, the message and the route are the whole story. Two things follow:

• Raise with a message that identifies the place: raise ArgumentError, "feed #{id} has no url" rather than raise ArgumentError.
• Log before the risky call, not only after it. A log.info "fetching", url: url line is often the only way to know how far a request got.

Under melee dev you also get a full trace page in the browser, because CRuby does keep backtraces. Do not rely on it for anything you need in production.

Fields that are already there

The request id is attached to every frame, so melee logs can group a request’s lines without you passing anything. The route is attached to the 500 line only — log.info lines inside a route do not carry it, so include what you need in the message:

log.info "note added", id: db.last_id.to_s, on_date: params.fetch(:on_date)

What is not here

No Logger object to configure, no formatters, no log rotation from the app’s side, no correlation ids you set yourself, no metrics or counters, and no way to read the log back from inside the app.