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:

Field	Notes
duration, view, db	Milliseconds. A 60s query is 60000, not 60.
status	HTTP status code
controller, action, path	Routing info
u_id	User id (null for anonymous)
remote_ip	Forwarded client IP
allocations	Ruby object allocations — high allocations + long duration is a strong signal of a bad query plan
params	Object literal — may contain commas/colons; don't split lines on ,

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.

Pitfalls

• Under rtk, wrap any pipeline that keeps whole lines in rtk proxy sh -c '…'. The hook rewrites rg into a filter that cuts each line at ~300 characters and writes [... omitted end of long line] into the output itself, so a spooled file loses u_id, params and everything after location for good. -o extractions of early fields survive, which hides it.

• Sidekiq job lines are not in the worker log. Searching it for Sidekiq, TID-, Performing, or Enqueued returns nothing — it holds Rails-level output from worker processes, not Sidekiq's own job lifecycle log. Use Sidekiq's web UI or Honeybadger for per-job success/failure.

• Honeybadger throttle warnings mean Honeybadger is under-counting. Unable to report error; reached max queue size of 100 and Error report failed: project is sending too many errors in the worker log mean error reports were dropped client-side. When these are firing, Honeybadger fault counts are a floor, not a total — trust the logs over the dashboard for that window, and treat the onset time of these warnings as the real start of the incident.

• rg | sort | uniq on JSON fragments is fine for counting, but don't awk -F, or cut -d, on a whole line — params:{…} contains commas. Anchor splits to the field name (-F'"duration":').

• rg has no -P — it's Rust regex, so no backreferences or lookaround; none of the patterns here need them.

• The replication-conflict cancel error (PG::TRSerializationFailure: canceling statement due to conflict with recovery) means the replica killed the query because WAL recovery was blocked — it's a symptom of a slow query holding the replica too long, not a bug in the SQL itself. Look for the underlying duration to find the real cause.

• Bots and scanners produce a lot of noise in 4xx and 5xx counts (path-traversal probes, .well-known/* lookups, npm CDN-style 404s). Nearly every request line in the worker log is a bot hitting the host's bare IP — ActionController::RoutingError (No route matches [POST] "/") there is noise, not a routing regression. Eyeball the path before treating an error spike as a real issue.

• The Bash tool truncates long lines it displays with [... omitted end of long line]. The data itself is intact — redirecting to a file or piping onward preserves full lines — but a whole Lograge line printed to the transcript gets clipped at the end (@timestamp, @version, message). So don't eyeball trailing fields off a raw line; extract them with rg -o '<trailing-field>' so the short match is what's displayed.

• One scanner IP can dominate counts. A single bot can rack up tens of thousands of 4xx/5xx and make a real user-facing issue look bigger than it is. Always check "remote_ip" distribution before treating an error spike as a real signal — group by IP first, then re-run analyses excluding the dominant scanner.

• Archives outside the requested window are deleted on each binx_logs run, so binx_cat can't stream a stale day from an earlier pull. If you need more history, re-run with -d N rather than hoarding files.

When jq is and isn't worth it

The web log's lines are JSON, so jq is tempting — but you have to strip the syslog prefix first, and on a full-day log it's noticeably slower than rg/awk. Use jq when you need to group by two or more JSON fields at once, or when params/payload structure matters; otherwise the awk -F'"key":' patterns above are faster. It's rarely useful on the worker log, which is mostly not JSON.

# strip prefix, then jq — only worth it for multi-field aggregations
binx_cat web | sed -E 's/^[^{]+//' \
  | jq -r 'select(.status==500) | "\(.controller)#\(.action)\t\(.duration)"' \
  | sort | uniq -c | sort -rn | head

Honeybadger vs. log files

"What's currently broken in production" and "is exception X happening more this week" are Honeybadger questions — read it with bin/binx_hb (faults, fault, notice, trend, counts), not the MCP. This skill is for requests that didn't raise: slow successful queries, traffic patterns, status-code mix.