Keyboard shortcuts

Press or to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

When something breaks

There are no backtraces in a deployed app. The log line and the route name have to be enough, so write them as you go.

Three places things go wrong, and they need different tools: the build, the request under melee dev, and the request in production.

The build failed

Every diagnostic is one line: file:line: message, against the file you wrote.

views/broken.erb:2: unexpected end-of-input, assuming it is closing the parent top level context
db/migrations/003_bad.sql:1: near "TABEL": syntax error
app.rb:5: views/index.erb does not declare a local `nots`
app.rb:12: unsupported eval of a runtime string is not supported by AOT compilation (define the code statically)
app.rb:12: unsupported call: node 14591 (CallNode `totally_not_a_method`) recv=-/ty-1 argc=1 arg0ty3

The last one is the compiler’s own voice and the one that reads badly. unsupported call on a name you recognise almost always means one of three things:

You called a method that does not exista typo in a top-level helper, or one you meant to define
The file did not require what it usesadd require "json" to the file that calls JSON.parse
The construct is not compilableeval, send with a computed name, define_method, a Proc out of a Hash

A failed melee push deploys nothing and the previous release keeps serving, so a broken build is never an outage.

If you cannot tell what the compiler is objecting to, cut the file down until it compiles — the smallest program that still fails is usually the answer, and it is also what an upstream bug report needs.

It is wrong under melee dev

This is where the tools are good. A 500 renders a page with the exception class and message, the request, the params, the session and a CRuby backtrace.

Enjoy it, and do not build a habit on it: production has none of that.

GET /admin -> 500 (1.2 ms)

log.info with fields goes to the terminal:

info msg="refresh requested" feeds=3

And remember the dev server runs your code under CRuby, so it will happily run things the compiler rejects and behave differently from the deployed binary in the handful of places the dialect differs. melee check is the cross-check.

It is wrong in production

The visitor gets:

Something went wrong

and you get a line in the log:

undefined method 'qeury' for an instance of Melee::DB class=NoMethodError method=GET path=/ route=GET /

Class, message, HTTP method, path, and the route pattern that matched. No line number and no backtraceException#backtrace and caller return [] in a compiled app, because the binary does not carry them.

So the route name is often all you have to locate the failure, which has three consequences worth building into how you write:

  • Raise with messages that say where you were. raise ArgumentError, "feed #{id} has no url" rather than raise ArgumentError.
  • Log before the risky line, not only after it. A line that says what you were about to do survives the thing that stops you doing it.
  • Keep routes short. A route with one call in it and a log line is a route whose failure you can place.
post "/admin/refresh" do
  log.info "refresh requested", feeds: db.first("SELECT COUNT(*) AS c FROM feeds")["c"].to_s
  Household.get("home").refresh
  redirect "/admin"
rescue Durable::RemoteError => e
  log.error "refresh failed", remote_class: e.remote_class, message: e.message
  halt 502
end

Reading the logs

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

Lines are HH:MM:SS msg key=value …. Three kinds are mixed together:

  • your log.* events, each carrying the request id;
  • anything the app wrote to stderr ($stderr.puts, runtime noise), shown as-is — note that puts goes to stdout and is not collected, so use log;
  • the server’s own events, tagged [melee].

The server’s events are the ones that explain a failure with no application line at all:

[melee] warm process started (pid 91129, 4 slots, sandbox off, cgroup off), release 1789257411211-0000
[melee] worker failed to start: bind .../worker.sock: path must be shorter than SUN_LEN; trying again in 60s
[melee] killing warm process group 91129 (environment changed)
[melee] warm process exited: signal: 9 (SIGKILL)

Reading a status code

CodeWhat happened
403The CSRF check. A form without csrf_field, or a stale session.
404No route matched, or your own halt 404.
500Your code raised. The log line is the only detail there is.
502The request process died without answering — a crash, or the sandbox killing it for a forbidden syscall.
503Every slot busy and the queue full (Retry-After: 1), or fork failed against the process cap.
504The request took longer than 30 seconds; the process group was killed.

A 502 with nothing in the log is the sandbox signature: the process was killed before it could say anything. That means a syscall outside the allow-list, which for app code almost always means trying to do something the platform does not intend — open a listening socket, run a subprocess.

Durable objects

melee objects              # every object: class, id, created, last call, next timer
melee objects Stats        # one class
CLASS                ID                               CREATED        LAST CALL      TIMER
Stats                visits                           0s ago         0s ago         in 23h

The TIMER column is the one to check when scheduled work is not happening: - means nothing is pending, and re-arming only happens if on_timer completes.

Calls are logged individually:

call method=hit ms=0.16 object=Stats/visits ok=true

An exception inside an object surfaces in the caller as Durable::RemoteError, with remote_class naming the original exception — or "Melee::Objects::WorkerError" when the worker could not be reached at all. There is no way to tell those two apart except by that string.

When you suspect the compiler

If CRuby and the deployed binary genuinely disagree, that is a dialect trap, and the project keeps a list of every one found so far in docs/research/spinel.md in the repository. Reduce it to the smallest program that shows the difference, run it under both, and check the list.

See also