zephyr-cp: hostnetwork web_workflow tests ReadTimeout on native_sim after zephyr_260803 rebase

[mikeysklar]

Summary

On the rebased zephyr pin (mikeysklar/zephyr@1f5ee1ce1034, PR #40), three tests/test_web_workflow.py hostnetwork tests fail with requests.exceptions.ReadTimeout on native_native_sim. This is a real regression, not flakiness: all five hostnetwork tests in this file passed reliably on the old pin (verified via PR #38, job 92115220994).

Failing:

• test_web_workflow_hostnetwork
• test_web_workflow_version_json_hostnetwork_ip_and_port
• test_web_workflow_write_code_py_remount

Passing (both only grep the boot console log, no HTTP request made):

• test_web_workflow_status_line_hostnetwork_non_default_port
• test_web_workflow_status_line_hostnetwork_default_port

CIRCUITPY_HOSTNETWORK is only 1 on native_sim, so this class of bug is invisible on real siwx917 hardware.

What's confirmed

The client (requests) gets a ReadTimeout, not a ConnectTimeout — the TCP handshake completes, but no HTTP response ever arrives within the 1.0s client timeout.

Diagnostic printk instrumentation was added to socketpool_socket_accept() in ports/zephyr-cp/common-hal/socketpool/Socket.c (now reverted) to test the original hypothesis that SO_RCVTIMEO wasn't taking effect on the listening socket, causing accept() to block forever on Zephyr's NSOS driver default (K_FOREVER, set by upstream commit 109826, already in our pin). CI run: https://github.com/mikeysklar/circuitpython/actions/runs/30969963576/job/92192271374

That hypothesis is refuted. Full "all serial output" for each of the 3 failing tests:

DIAG accept: zsock_accept -> -1 errno=11 elapsed_ms=19
DIAG accept: zsock_accept -> 1 errno=11 elapsed_ms=20
Stopped at 1.106s

Only 2-3 total accept() calls per test, all completing in 19-20ms, setsockopt(SO_RCVTIMEO) never fails, and the connection is always accepted (newsoc >= 0) within tens of milliseconds of boot. accept() is not the bottleneck.

After accept() succeeds, there is total silence in the serial log — no further output at all — until the process is force-killed by the test harness (Stopped at 1.1xxs, matching when the client's 1.0s requests timeout fires). No crash, no traceback, no printk from anywhere else in the request-handling path.

What's ruled out

• Original hypothesis (SO_RCVTIMEO/K_FOREVER blocking accept() forever): refuted by the diagnostic data above.
• "~50 failed polls at 20ms each eat the 1.0s budget" arithmetic: refuted. Only 2-3 accept() calls occur per test, not ~50. The connection is accepted almost immediately.

One confirmed, real (but so far non-explanatory) anomaly

SO_RCVTIMEO is set to 1ms (tv_usec = 1000) before each accept() call, but every observed call takes 19-20ms — a consistent ~19-20x overshoot. CONFIG_SYS_CLOCK_TICKS_PER_SEC=100 on native_sim (10ms/tick) is consistent with a sub-tick timeout rounding up to ~2 ticks. This is real and reproducible (14/14 diagnostic samples), but by itself does not explain the failure, since only 1-2 EAGAIN attempts occur before accept() succeeds in every failing test — nowhere near enough to consume 1 full second.

Whether CONFIG_SYS_CLOCK_TICKS_PER_SEC=100 is itself new on this pin (vs. unchanged from the old pin, in which case this rounding behavior was always present and isn't the regression) has not been checked against the pre-rebase zephyr tree.

Best remaining hypothesis (not yet confirmed)

ports/zephyr-cp/background.c's port_background_task() calls k_busy_wait(100) unconditionally under CONFIG_ARCH_POSIX, with the comment "Make sure time advances in the simulator." This gets called on every RUN_BACKGROUND_TASKS invocation, including the ones inside socketpool_socket_recv_into() (Socket.c line ~509), which itself is called in a tight non-blocking retry loop by _process_request() in supervisor/shared/web_workflow/web_workflow.c — the loop that reads the HTTP request one byte at a time after accept() succeeds.

On native_sim, k_busy_wait() resolves to arch_busy_wait() in boards/native/native_sim/cpu_wait.c, which calls posix_halt_cpu() — this yields to native_sim's separate hardware-model scheduling, which is also what drives progress on the host-bridged NSOS socket layer. If this halt/resume cycle's real-wall-clock cost is inflated on this pin (by a mechanism not yet identified — it uses a raw microsecond nsi_hws_get_time() clock, not the tick-quantized k_timeout_t path that explains the SO_RCVTIMEO overshoot above, so it is likely a different mechanism), a spin that used to cost single-digit milliseconds could now cost most of a second. This ties together the timing symptom and the "accept succeeds fast, then total silence" symptom, but has not been confirmed with direct instrumentation — doing so requires printk inside the recv-retry loop itself, which was not added before this investigation concluded (see below).

Why this issue exists instead of a fix

This needs a Linux environment to reproduce (native_sim/POSIX arch cannot build or run on macOS), so further narrowing requires another instrumented CI round-trip. Given the risk of guessing wrong on native_sim/Zephyr timing internals and the explicit instruction not to band-aid this (raising the client timeout, skipping the tests, or disabling CIRCUITPY_HOSTNETWORK would all hide the regression rather than fix it), filing this writeup with the ruled-out hypotheses and the strongest remaining lead is more useful than a guess.

Suggested next step

Add printk instrumentation inside _process_request()'s recv-retry path (supervisor/shared/web_workflow/web_workflow.c around line 1672-1708, or in socketpool_socket_recv_into() in Socket.c) to log on the first recv attempt after a fresh accept, and periodically during the retry loop, to determine directly whether the loop is spinning (and how many iterations/how long) or stuck elsewhere. That would confirm or refute the k_busy_wait/posix_halt_cpu hypothesis above directly.

Also worth checking: whether CONFIG_SYS_CLOCK_TICKS_PER_SEC changed between adafruit/zephyr@e1dc85052bc (old pin) and this pin, by diffing the relevant Kconfig defaults in both trees (no build required).

🤖 Generated with Claude Code