Keybase RPC Log Analysis

Keybase RPC log analysis

The Go service logs every RPC it serves and every call it makes. That log is the only place the client's real network behaviour is visible — the JS side shows intent, the log shows what actually went out. A quiet minute is ~45 lines; a minute with a flood is 120,000.

Capture a clean run

skill/keybase-rpc-log-analysis/scripts/clean-logs.sh --archive   # dry run without a flag
skill/keybase-rpc-log-analysis/scripts/start-service.sh          # own terminal, foreground
cd shared && yarn desktop:start:hot:e2e                          # another terminal
cd shared && yarn test:e2e:desktop:rpc                           # or drive the app by hand

start-service.sh builds from this checkout, stops the running service, and logs with -d --log-file to /tmp/kb-analysis/service.log. Its own file matters: the default log is shared with everything else and a flood rotates the evidence away in under two minutes.

Use test:e2e:desktop:rpc, not test:e2e:desktop. The full suite is 6.6 minutes over two projects (light and dark), which doubles every count and makes the log rotate. test:e2e:desktop:rpc is the six flows that actually drive team and channel loading, on one project, in 39 seconds. test:e2e:desktop:flows takes file arguments if you need a different set — always pass a single --project (it does), or light and dark each contribute a copy of every call.

--log-file still rotates at 128MB — a full e2e run produces ~135MB and will cross it. Nothing is lost, but the analysis must then include the siblings, so pass them all:

python3 skill/keybase-rpc-log-analysis/scripts/rpc-report.py \
  /tmp/kb-analysis/service.log-* /tmp/kb-analysis/service.log

Rotation is easy to miss: a script that reads only service.log after a long run silently analyses the tail. Check ls -la /tmp/kb-analysis/ before believing a count.

The service forks kbfs from its own bin directory, and a plain go install of the service does not build it. Without kbfs the Files tab is empty and git fails with KBFS client not found, which fails every files-* and git-* e2e test for reasons unrelated to the change under test. start-service.sh warns. Note the installed kbfs keeps the mount when the service is swapped for a local build, so those tests can fail even with a kbfs binary in place — they are not in the test:e2e:desktop:rpc set for that reason.

Ask before stopping the service or launching the app — both are the user's.

Prove a fix

A before/after is only worth reporting if both runs did the same thing. What works:

# after: with the fix in the tree
<reload the renderer>; : > /tmp/kb-analysis/service.log
cd shared && yarn test:e2e:desktop:rpc
cp /tmp/kb-analysis/service.log /tmp/kb-analysis/after.log

# before: revert ONLY the source changes, keeping any new test scripts
git stash push -- <the source files you changed>
<reload the renderer>; : > /tmp/kb-analysis/service.log
cd shared && yarn test:e2e:desktop:rpc
cp /tmp/kb-analysis/service.log /tmp/kb-analysis/before.log
git stash pop

• Stash by path, not wholesale. If the fix added the very npm script the capture runs, a bare git stash takes it with them.
• Hard-reload the renderer between runs (CDP page.reload() on localhost:9222). Module-level caches — the usual subject of these fixes — survive HMR, so without a reload the second run starts warm and reads better than it is.
• The service does not need rebuilding between runs for a JS-only fix. Leave it up; only truncate its log.
• Counting straight out of the log beats rpc-diff.py when you already know which calls you are watching: parse + Server: <Name> / + RemoteClient: chat.1.remote.<name>, and count how many landed within the hook's own staleMs of the previous call for the same subject. That last number is the one that says "this was a cache miss" rather than "this was work".

Read it

Run rpc-cost.py early. Count and cost answer different questions, and the loudest line in the log is usually not the expensive one. In one capture the top line by count was an in-memory map lookup — 15,767 calls for 0.16s total, not worth touching — while the real cost was 469 team loads at 292ms each, 186 seconds, sitting 30th by count.

To prove a loud flood is free rather than just absent from the table, pass --min-mean-ms 0 --top 400: the default threshold hides cheap chatty ops, which is exactly the row you need. AttachmentHTTPSrv: GetURL at 4,848 calls does not appear at all by default, and shows as 0.04s total once it does.

Analysing an already-rotated log is the same — pass ~/Library/Logs/keybase.service.log-<start>-<end> directly. The filename carries its own window, so --start/--end are only for narrowing further.

Read rpc-report.py's sections in order:

• REMOTE — service→server. Only these burn server rate limits. Start here.
• APP — app→service. One of these usually explains a REMOTE row.
• BURSTS — same call and subject, 3+ times in one second. Each row is a missing cache or a remounting component.
• FLOODS — most repeated lines, ids and numbers collapsed.

A BURSTS row with a bare name and no (subject) means the subject could not be resolved: many RPCs log no arguments. Those rows are same-name only — treat them as a lead, not as proof the same conversation was hit twice.

rpc-why.py answers attribution. ROOT (the app RPC that opened the trace) is usually the answer; DRIVERS (nearest preceding call) points at the specific line. BATCHES needs the span that logs the item count, which is normally the local one, not the remote it wraps — match HybridConversationSource: GetMessages, not getMessagesRemote. The script says so when it finds no counts.

What a bug looks like

• Same args, same second, N times → no dedupe, or a keyed component remounting as its props arrive in stages.
• Fires again the instant the previous lands → a feedback loop, not user action. Look for a cache that never records success, or an effect whose deps change on every render.
• Batch sizes almost all 1 → the caller loops where it could fetch once.
• A per-item cost inside a loop → e.g. a gregor state read per emoji.