Log request/response pairs in the Android driver

[euskadi31]

Why

When the Android driver misbehaves, its log says nothing. A CI run (#31603873289) lost all six scenarios to hierarchy calls that died on the action's context deadline, and the driver log offered exactly 11 lines, all from instrumentation startup:

INSTRUMENTATION_STATUS: class=org.taleslabs.tales.driver.TalesDriverTest
...
s_glBindAttribLocation: bind attrib 0 name position

No request ever appears, so there is no way to tell whether those calls reached the driver at all — and therefore no way to explain why they did not receive the retryable 503 that the 8s snapshot ceiling in Snapshot.kt should have produced. That question is still open.

The Apple driver already does this, and it is what made the iOS root cause readable: the request/response pairs showed a single POST /launch taking 245391ms, which located the failure precisely. Handlers.swift:

[tales-driver] request: POST /launch
[tales-driver] response: POST /launch status=200 elapsed=245391ms

The gap between a request: line and its missing response: is what identifies the call that wedged the driver. Android has no equivalent.

What

Mirror the Apple driver's logging in Router.kt:

• one request: <METHOD> <path> line before dispatch,
• one response: <METHOD> <path> status=<code> elapsed=<ms>ms line after,
• skip GET /health, which Tales polls once a second and which would otherwise bury the log.

Match the [tales-driver] prefix so both platforms grep the same way.

Acceptance

• A failing Android run's build/artifacts/mobile/driver/<target>/driver.log shows the sequence of calls with timings.
• A call that never completes is identifiable as a request: line with no matching response:.
• GET /health does not appear.

Notes

Touching the driver means rebuilding the committed APKs (make build-android-driver, needs JDK 17 + the Android SDK), refreshing the source.sha256 sentinel, and rebuilding the tales binary, which embeds them — an old binary keeps installing the previous driver. make check-android-driver-fresh guards the sentinel in CI.

Context: the ANR that triggered the investigation is handled separately by suppressing system error dialogs on the CI emulator; this issue is only about being able to diagnose the next occurrence.

[euskadi31]

Correction: the logging already exists. It goes to logcat, not to driver.log.

The device log captured in #60 shows the Android driver emitting exactly the pairs this issue asks for, timings included:

16:03:18.240  I tales-driver: [tales-driver] request:  GET /hierarchy
16:03:18.432  I tales-driver: [tales-driver] response: GET /hierarchy status=200 elapsed=192ms
16:03:18.511  I tales-driver: [tales-driver] accepted connection from /127.0.0.1:52813
16:03:18.534  I tales-driver: [tales-driver] response: GET /hierarchy status=503 elapsed=13ms

58 such lines in one 8-second dump. They looked absent because build/artifacts/mobile/driver/<target>/driver.log only captures am instrument stdout, where they never appear.

So the original premise was wrong, and the gap is narrower than described: since #60 attaches an unfiltered logcat dump to every failing step, these lines are now available where they are needed. That was enough to diagnose a real bug on the first occurrence.

What remains worth considering, at much lower priority:

• routing the driver's log lines into driver.log as well, so a driver post-mortem does not depend on a step having failed;
• noting in the docs that the Android driver's trace lives in device.log, not driver.log, which is the confusion that opened this issue.

Retitling or closing this in favour of that narrower scope is fine by me.