Production Log Inspection

Inspecting production logs

Getting the logs

binx_logs downloads production logs; binx_cat streams them. Both are personal scripts on PATH (~/bin), not repo bin/ entries, and both must be run from the repo root.

binx_logs                        # default: web AND worker, yesterday's archive + today's live log
binx_logs -d 7                   # both servers, past week of archives
binx_logs web                    # web only

binx_cat web | rg '"status":5'   # stream a server's logs, oldest lines first
binx_cat -l worker               # list the files that would be streamed

Both need mise's Ruby ahead of the system one (undefined method 'filter_map' or a syntax error in ~/bin/binx_logs means /usr/bin/ruby 2.6 ran them) — prefix the command with PATH="$(dirname "$(mise which ruby)"):$PATH".

binx_logs refuses to run in a Conductor workspace — it has to download into the base checkout (git worktree list | head -1). If that checkout's tmp/ already holds a recent pull, search its files directly with rg -z -I rather than asking for a fresh download; binx_cat only reads the current checkout's tmp/.

binx_logs leaves the rotated archives gzipped on disk (tmp/<server>-production.log.<date>-<n>.gz) alongside today's still-rotating, uncompressed log (tmp/current-production-<server>.log). Always read them through binx_cat <server> — it decompresses the archives and concatenates everything in chronological order on the fly. Don't glob the files yourself, and don't build your own concatenated copy: a day of web logs is ~630 MB uncompressed, and decompression is cheap next to the search, so streaming is free.

Review both by default. A question framed around requests ("why are we 500ing") usually has half its answer in the worker log: the job that poisoned the cache, the Honeybadger client silently dropping error reports, a worker process crash-looping. Only skip a server when the user explicitly scopes to one.

Use rg, not grep. On a day of web logs rg is roughly 4× faster (a -o aggregation over 1.3M lines: 1.4s vs 5.5s). Flag translation is nearly one-to-one — grep -oE 'x' → rg -o 'x' (rg is always regex, so drop -E), -c/-n/-A/-B are the same, and -F still means literal. rg exits 1 on no matches, same as grep. Pass -M0 when a later step reads the whole line (a JSON parse, a params extraction): ~/.ripgreprc sets --max-columns=300, which cuts every Lograge line to a preview ending [... omitted end of long line].

Rules for both servers:

• Never Read the logs, and never binx_cat without a filter. The web log is routinely several hundred MB. Always pipe into rg/awk/head/tail.
• Synthesize by default; paste at most one short example when it's load-bearing. Lograge lines are long and mostly structural JSON — dumping multiple into a reply is unreadable and burns context. A single representative line for an exception or a slow request is fine; a wall of match output is not.

Line formats

Both servers share a syslog-style header: a severity letter (I/W/E), timestamp, and pid.

Web — Lograge JSON, one line per request, with a request-id prefix:

I, [2026-04-27T04:42:04.467657 #277641]  INFO -- : [0591f694-…] {"method":"GET","path":"/search/registrations","format":"html","controller":"Search::RegistrationsController","action":"index","status":500,"allocations":1073409,"duration":51237.65,"view":0.0,"db":51234.09,"remote_ip":"71.212.12.114","u_id":148942,"params":{…},"@timestamp":"…","@version":"1","message":"…"}

Key fields:

When a request raises, you also get separate, non-JSON lines starting with [<request-id>] at column 0 (no syslog header) containing the exception class, message, and stack trace, followed by another JSON line for /500 (the ErrorsController#server_error render). That secondary /500 line inflates 500 counts — exclude "controller":"ErrorsController" when counting.

Worker — free-form. Only a trickle of Lograge lines (bots hitting the worker host by IP). The bulk is:

• Job/rake output (Requesting page 1, S3 Storage (56.1ms) Deleted files by key prefix: …)
• [SKYLIGHT] … Skylight agent enabled — one per process boot; a high count means workers are restarting a lot
• Honeybadger client chatter (Reporting error id=…, Success ⚡ …, and throttle warnings — see pitfalls)
• Library deprecation warnings (Scoped order is ignored, use :cursor with :order …)
• Exception classes + backtraces, same [<request-id>]-prefixed shape as web

Since there's no fixed schema, search by message text, not by field.

Common queries (web)

Time range covered. binx_cat exits cleanly when head closes the pipe.

binx_cat web | head -1
binx_cat web | tail -1

Status-code distribution.

binx_cat web | rg -o '"status":[0-9]+' | sort | uniq -c | sort -rn

Slow requests over a threshold (in ms). Use awk rather than a regex — durations are floats with arbitrary digit counts and a pattern like "duration":[5-9][0-9]{4} will silently miss values:

binx_cat web | awk -F'"duration":' '$2 != "" {split($2,a,","); if (a[1]+0 > 60000) print}'

Pipe that into rg -o '"path":"[^"]+"' | sort | uniq -c | sort -rn to group by path, or rg -o '"status":[0-9]+' for status mix.

Distribution stats (p50/p90/p99).

binx_cat web | awk -F'"duration":' '$2 != "" {split($2,a,","); print a[1]+0}' \
  | sort -n \
  | awk 'BEGIN{c=0}{v[c++]=$1; s+=$1} END{print "n="c, "p50="v[int(c*.5)], "p90="v[int(c*.9)], "p99="v[int(c*.99)], "max="v[c-1], "mean="s/c}'

Most-hit endpoints.

binx_cat web | rg -o '"controller":"[^"]+","action":"[^"]+"' | sort | uniq -c | sort -rn | head -20

5xx counts by endpoint. Filter to "status":5 first to keep the line set small:

binx_cat web | rg '"status":5' \
  | rg -o '"controller":"[^"]+","action":"[^"]+"' | sort | uniq -c | sort -rn

Several stats at once. Each binx_cat re-reads the whole log, so when you want more than two or three cuts of the same data, spool once and reuse — the win is I/O, not decompression:

binx_cat web | rg '"status":5' > tmp/_5xx.log   # small; delete when done

Common queries (worker)

Severity mix — cheap first pass; E, lines and [-prefixed backtrace lines are where the signal is:

binx_cat worker | awk '{print substr($0,1,1)}' | sort | uniq -c | sort -rn

Cluster the noise. Strip the header and the varying ids, then count — most of the file is a handful of repeated messages:

binx_cat worker \
  | sed -E 's/^[IWE], \[[^]]+\] +[A-Z]+ -- //; s/id=[a-f0-9-]+//g; s/pid=[0-9]+//g' \
  | cut -c1-90 | sort | uniq -c | sort -rn | head -15

Exception classes.

binx_cat worker | rg -o '^\[[a-f0-9-]+\] [A-Z][A-Za-z]*(::[A-Za-z]+)+' \
  | sed -E 's/^\[[a-f0-9-]+\] //' | sort | uniq -c | sort -rn

Hourly rate of any message — turns "this happens a lot" into "this started at 09:00":

binx_cat worker | rg 'reached max queue size' \
  | rg -o '\[2026-[0-9-]+T[0-9]{2}' | sort | uniq -c

Worker restarts (each boot logs the Skylight agent once):

binx_cat worker | rg -c 'Skylight agent enabled'

Finding exception stack traces

Works the same on both servers. The JSON request line tells you a request 500'd but not why. Grab the request id from the JSON line, then search for that id — Rails writes the exception class and backtrace as separate lines with the same [request-id] prefix:

binx_cat web | rg -n '0591f694-49b4-4c9c-b49e-4fef89ae8d7b'

Look for lines starting with E, (ERROR severity) and lines beginning [<id>] ActiveRecord::… / [<id>] ActionView::… / [<id>] Caused by: / [<id>] app/…:NN. The trailing app/… lines are the user-code frames (Rails strips gem frames by default).

To find clusters of the same exception, search for the exception class plus a line of context:

binx_cat worker | rg -A1 'ActionController::RoutingError' | head -40

Searching the files directly (optional fast path)

rg -z reads gzip and plain files alike, so it can search the archives and today's uncompressed log in one shot, in parallel across cores. It's modestly faster than streaming (1.1s vs 1.4s on one day; the gap widens with -d 7, where there are more archives to parallelize over). Two catches, so reach for it only on many-pass aggregations:

rg -z -I -o '"status":[0-9]+' $(binx_cat -l web) | sort | uniq -c | sort -rn

• -I (--no-filename) is mandatory. With more than one file rg prefixes each match with tmp/current-production-web.log:, which corrupts any sort | uniq -c.
• Output order is not chronological. rg searches files in parallel and emits them as they finish — today's log routinely lands before yesterday's archive. Fine for counting; wrong for head -1, tail -1, timelines, or reading a trace in order. Use binx_cat for anything order-sensitive.