diff options
Diffstat (limited to 'examples/http.zig')
| -rw-r--r-- | examples/http.zig | 922 |
1 files changed, 922 insertions, 0 deletions
diff --git a/examples/http.zig b/examples/http.zig new file mode 100644 index 0000000..03d89c1 --- /dev/null +++ b/examples/http.zig @@ -0,0 +1,922 @@ +//! The data path, end to end: associate, take a DHCP lease, answer a ping, fetch a URL. +//! +//! examples/radio.zig proved the control path - SDIO up, RPC in both directions, a scan, an +//! association event from the C6. What it did not do is move a single Ethernet frame, and the +//! symptom was ESP-Hosted logging `task still writing Rx data to queue!` once associated: the AP's +//! traffic arriving with nobody registered to consume it. +//! +//! This file registers that consumer (src/net/link.zig) and puts src/net/ip.zig behind it. Nothing +//! from lwIP, esp_netif or the IDF network stack is linked; the IPv4, ARP, ICMP, UDP, DHCP, TCP and +//! HTTP are all this project's, in one 3.4 KB struct that allocates nothing and reads no clock. +//! +//! Run: +//! zig build -Dhosted -Dapp=examples/http.zig \ +//! -Dssid=YOUR_SSID -Dpsk-file=/path/to/psk run +//! +//! What it prints, in order, and what each line means. Every wait below is bounded and every +//! bound prints why it gave up, because a silent wait on this board is indistinguishable from a +//! dead scheduler. +//! +//! MARK HTTP_START cpu=... the image booted; the CPU clock, from two independent counters +//! MARK HTTP_WDT ... the bootloader's RTC watchdog was found armed and disarmed +//! MARK HTTP_TICK ... heartbeat during bring-up: scheduler alive, C making progress +//! MARK HTTP_RADIO_UP after N ms the C6 answered and the transport reached its active state +//! bad case: MARK HTTP_FAIL radio ... - the transport never came up. Nothing below can run. +//! MARK HTTP_WIFI_START rc=0 the first RPC round trip after bring-up +//! bad case: rc!=0, or spun>0 meaning the RPC threads never left their not-ready loop +//! MARK HTTP_LINK mac=... foot=N the station channel is registered; `mac` is the C6's radio's +//! own address and is what ARP will answer for. From this line on, +//! station frames reach src/net/ip.zig instead of being discarded. +//! bad case: MARK HTTP_FAIL link=MacUnavailable (asked before the radio was started) or +//! =ChannelRegisterFailed (transport_drv_add_channel refused; wrong if_type) +//! MARK HTTP_JOIN ssid=... psk_len=N the association request went out. The passphrase is never +//! printed; only its length, which distinguishes a missing +//! -Dpsk-file from a wrong one. +//! MARK HTTP_ASSOC after N ms by=X rx=N associated. `by=event` means WIFI_EVENT_STA_CONNECTED +//! (id 4) arrived; `by=traffic` means station frames arrived, +//! which an AP does not send to an unassociated station and which +//! is what happens when the C6 was already on this SSID. +//! bad case: MARK HTTP_FAIL assoc timeout ... - the radio never associated. Wrong passphrase, +//! wrong band, or out of range. Any RADIO_EVENT id=5 line before it is a disconnect +//! and carries the reason in its length. +//! MARK HTTP_DHCP_TX ... DISCOVER sent. This is the first frame this project has ever +//! put on a real network. +//! MARK HTTP_DHCP_WAIT ... progress, every second: DHCP state and the frame counters. If +//! `rx=0` stays zero the receive callback is not being called at +//! all; if `rx` climbs while `drop` climbs with it, frames are +//! arriving and being rejected - which is what a frame shifted by +//! a header looks like, so `csum` and `drop` are printed too. +//! MARK HTTP_IP ip=... mask=... a real lease from the real DHCP server +//! MARK HTTP_ROUTE gw=... dns=... in N ms and the route it came with +//! bad case: MARK HTTP_FAIL dhcp state=selecting - DISCOVERs went out, no OFFER came back +//! (frames leaving but not arriving), or state=requesting - an OFFER arrived and the +//! ACK did not. The state is the diagnosis, which is why it is printed rather than +//! just "timeout". +//! MARK HTTP_PING_OPEN ip=... for N ms ping the board from the workstation NOW +//! MARK HTTP_PING n=N arp_rx=... arp_tx=... one line per echo request answered. The ARP +//! counters beside it are what prove the exchange was two-way: +//! the workstation had to ARP for this address and be answered +//! before it could send the echo at all. +//! bad case: no such line for the whole window. If `HTTP_PING_IDLE` shows rx climbing, frames +//! arrive and the board is not recognising them as ICMP for its own address. +//! MARK HTTP_GET host=... port=... path=... the request begins +//! MARK HTTP_STATUS code=... len=N tcp=... the response's status line was parsed +//! MARK HTTP_BODY ... the first bytes of the body, non-printables as '.' +//! bad case: MARK HTTP_FAIL get=HostUnreachable (no ARP answer for the peer), +//! =TimedOut (SYN or data unacknowledged), =ConnectionReset (nothing listening on +//! that port), =WouldBlock (our own deadline, printed with the TCP state) +//! MARK HTTP_LIVE ... still running and still answering ICMP, once a second + +const std = @import("std"); +const hal = @import("hal"); +const soc = @import("soc"); +const net = @import("net"); +const p4 = @import("io"); +const config = @import("config"); + +/// Required by any application implementing `std.Io.VTable` on this target, and it must be in the +/// ROOT module: std reads `std.options` from `@import("root")`. +pub const std_options: std.Options = .{ .page_size_min = 4096 }; + +pub const panic = std.debug.FullPanic(struct { + fn call(msg: []const u8, _: ?usize) noreturn { + soc.rom.print("MARK HTTP_PANIC %s\r\n", .{msg.ptr}); + while (true) {} + } +}.call); + +// =============================================================================== the target +// +// The HTTP peer. A host on this workstation's own /24 rather than the gateway's web UI, so the +// expected response bytes are known in advance and a wrong answer means this stack is wrong rather +// than that a router's firmware is unusual. +// +// Serve it with, from the directory holding the file to be fetched: +// python3 -m http.server 8080 --bind 192.168.1.181 +// A `Content-Length` is what that sends, so the body's end is framed by the header rather than by +// the peer's FIN - which exercises the more interesting of ip.zig's two termination paths. +const http_host: [4]u8 = .{ 192, 168, 1, 181 }; +const http_port: u16 = 8080; +const http_path = "/"; + +/// How long the board stays quietly pingable before it makes the HTTP request. Long enough for a +/// person to run `ping` after reading the line that says to. +const ping_window_ms: u64 = 30_000; + +// ================================================================================== budgets +// +// Every one of these is a bound on a wait that would otherwise be a hang, and each is generous +// against the thing it is waiting for rather than round. + +/// The C6 boots in well under a second; examples/radio.zig saw the transport up at 1,890 ms. +const radio_deadline_ms: u64 = 10_000; +/// A 2.4 GHz association with WPA2 is a second or two. Twenty allows for a scan and a retry. +const assoc_deadline_ms: u64 = 60_000; + +/// How many association attempts before giving up. +/// +/// Ten, because this link is genuinely marginal and the failure is not ours. Measured on this board: +/// the same SSID and passphrase associate on some attempts and are refused on others with reason=4 +/// ASSOC_EXPIRE at about -68 dBm, and one run exhausted four attempts in a row. Reason 15 would mean +/// a wrong passphrase; 4 means the AP expired the association, and the only cure is to ask again. +/// +/// Ten attempts against a 45 s deadline is roughly one every 4.5 s, which is slower than the AP's own +/// timeout and so does not pile requests on top of each other. +const assoc_attempts: u32 = 6; + +/// Pause between association attempts. See the comment at the retry itself: hammering the AP is what +/// turns a marginal link into a refused one. +const assoc_backoff_ms: u64 = 3_000; +/// DHCP's own first retransmission is at 4 s and ip.zig retries with backoff; fifteen seconds is +/// three or four DISCOVERs, which is enough to distinguish "no server" from "one lost frame". +const dhcp_deadline_ms: u64 = 15_000; +/// ARP, a SYN, a request and a response, with TCP's initial RTO at 1 s and six retries available. +const http_deadline_ms: u64 = 20_000; + +// ================================================================================ resources + +/// Twelve task slots. Sizing this too small does NOT fail loudly: `io.async` with no free slot runs +/// the body eagerly instead of returning an error, so a reader task that should loop forever runs +/// once at spawn and is never seen again. ESP-Hosted spawns seven for the transport plus RPC's. +var pool: p4.Static(12, 2048) = .{}; + +/// ESP-Hosted's heap. examples/radio.zig measured the transport and RPC at well under 32 KiB with +/// the SDIO queues at 4/4; the station channel adds one 1,536-byte aligned transmit buffer in +/// flight per queued frame, and each received frame is a `payload_len` allocation freed by +/// `link.onRxFrame` before the next is dispatched. HTTP_HEAP prints what was really used. +var heap_backing: [70 * 1024]u8 align(8) = undefined; + +// ==================================================================================== state + +var associated: bool = false; +var disconnects: u32 = 0; +var bringup_result: ?anyerror = null; +var bringup_done: bool = false; + +/// ESP-Hosted's Wi-Fi RPC, through the C shim in src/net/hosted/wifi_shim.c. The structs stay in C +/// on purpose; see that file's header. +extern fn hosted_wifi_sta_start() c_int; +extern fn hosted_wifi_connect(ssid: [*:0]const u8, psk: [*:0]const u8) c_int; + +/// NUL-terminated credential copies for the C ABI, sized to the maxima `wifi_config_t` itself uses. +/// File scope rather than local because the retry loop below re-issues the request and must pass the +/// same bytes; the passphrase is never printed and never written anywhere else. +var ssid_buf: [33]u8 = @splat(0); +var psk_buf: [65]u8 = @splat(0); + +/// `WIFI_EVENT_STA_CONNECTED`. The C6 reported this as `base=wifi id=4` on the run that proved +/// association; `id=5` beside it is `WIFI_EVENT_STA_DISCONNECTED`. +const wifi_event_sta_connected: i32 = 4; +const wifi_event_sta_disconnected: i32 = 5; + +fn bringUp(ctx: struct { io: std.Io, gpa: std.mem.Allocator }) void { + net.init(ctx.io, ctx.gpa) catch |err| { + bringup_result = err; + bringup_done = true; + return; + }; + bringup_done = true; +} + +fn onEvent(ev: net.port.Event) void { + const base_name: [*:0]const u8 = switch (ev.base) { + .wifi => "wifi", + .named => |n| n, + }; + soc.rom.print("MARK HTTP_EVENT base=%s id=%d len=%u\r\n", .{ + base_name, + ev.id, + @as(u32, @intCast(if (ev.data) |d| d.len else 0)), + }); + if (ev.base == .wifi) { + if (ev.id == wifi_event_sta_connected) associated = true; + // A disconnect after association is worth counting rather than acting on: the C6 retries on + // its own, and a stack that tore itself down on every roam would be less useful than one + // that says how many times it happened. + if (ev.id == wifi_event_sta_disconnected) { + disconnects += 1; + // The reason code is the whole diagnostic value of this event: without it a refused + // association is indistinguishable from an access point that was never there. Layout is + // `wifi_event_sta_disconnected_t` - ssid[32], ssid_len, bssid[6], reason, rssi - so 41 + // bytes with reason at offset 39. Length-checked rather than assumed, because another + // IDF version would move it. + if (ev.data) |d| { + if (d.len >= 41) { + const reason = d[39]; + const rssi: i8 = @bitCast(d[40]); + soc.rom.print("MARK HTTP_DISCONNECT reason=%u rssi=%d %s\r\n", .{ + @as(u32, reason), + @as(i32, rssi), + reasonName(reason), + }); + } else { + soc.rom.print("MARK HTTP_DISCONNECT payload=%u B, expected 41\r\n", .{ + @as(u32, @intCast(d.len)), + }); + } + } + } + } +} + +/// The disconnect reasons that actually occur during bring-up, named. From `wifi_err_reason_t` +/// (esp_wifi_types_generic.h). Anything else prints its number, which is more useful than a wrong +/// guess at a name. +fn reasonName(reason: u8) [*:0]const u8 { + return switch (reason) { + 2 => "AUTH_EXPIRE", + 4 => "ASSOC_EXPIRE", + 15 => "4WAY_HANDSHAKE_TIMEOUT - almost always a wrong passphrase", + 23 => "802_1X_AUTH_FAILED", + 200 => "BEACON_TIMEOUT", + 201 => "NO_AP_FOUND - wrong SSID, or not on a channel the C6 can see", + 202 => "AUTH_FAIL", + 203 => "ASSOC_FAIL", + 204 => "HANDSHAKE_TIMEOUT", + 205 => "CONNECTION_FAIL", + else => "see wifi_err_reason_t", + }; +} + +/// Reset entry. The bootloader hands over with an unspecified stack pointer and the FPU off, so: +/// enable the F extension (mstatus.FS = Initial), establish the stack, clear .bss, then enter Zig. +export fn _start() linksection(".text.entry") callconv(.naked) noreturn { + asm volatile ( + \\ li t0, 1 << 13 + \\ csrs mstatus, t0 + \\ la sp, __stack_top + \\ mv fp, sp + \\ la t0, __bss_start + \\ la t1, __bss_end + \\ bgeu t0, t1, 2f + \\1: + \\ sw zero, 0(t0) + \\ addi t0, t0, 4 + \\ bltu t0, t1, 1b + \\2: + \\ j zig_main + ); +} + +export fn zig_main() noreturn { + // The bootloader leaves the RTC watchdog armed and expects the application to take it over. + // Nothing here feeds it, and this program deliberately runs for minutes. + const wdt_was_armed = hal.rwdt.armed(); + const wdt_off = hal.rwdt.disable(); + soc.rom.print("MARK HTTP_WDT armed_at_entry=%u disabled=%u\r\n", .{ + @as(u32, @intFromBool(wdt_was_armed)), + @as(u32, @intFromBool(wdt_off)), + }); + + // Two independent clocks over one interval: the systimer is a fixed 16 MHz, so the CPU + // frequency falls out of the ratio. Everything above assumes the bootloader's 90 MHz. + const t0 = hal.systimer.read(.unit0) orelse 0; + const c0 = soc.cycles(); + soc.rom.ets_delay_us(10_000); + const t1 = hal.systimer.read(.unit0) orelse 0; + const c1 = soc.cycles(); + const cpu_khz: u64 = if (t1 > t0) ((c1 - c0) * (hal.systimer.hz / 1000)) / (t1 - t0) else 0; + soc.rom.print("\r\nMARK HTTP_START cpu=%u kHz\r\n", .{@as(u32, @truncate(cpu_khz))}); + + const runtime = pool.init(.{}); + const io = runtime.io(); + + var backing = net.heap.Heap.init(&heap_backing); + const gpa = backing.allocator(); + + net.port.setEventHandler(&onEvent); + + // Bring-up runs on its own task: `transport_drv_reconfigure` blocks in a 200 ms retry loop + // waiting for the slave, so a main task inside it could not print. With it elsewhere, the + // heartbeat below distinguishes "the transport is stuck" from "the scheduler is stuck". + var bringup = io.async(bringUp, .{.{ .io = io, .gpa = gpa }}); + soc.rom.print("MARK HTTP_SETUP dispatched\r\n", .{}); + + radioUp(runtime); + bringup.cancel(io); + + // The station channel, and the IP stack behind it. Before the association request rather than + // after, so there is never a window in which the AP's traffic arrives with nothing to consume + // it - that window is exactly what produced `task still writing Rx data to queue!`. + wifiStart(); + linkUp(); + join(runtime); + dhcp(runtime); + pingWindow(runtime); + httpGet(runtime); + internetGet(runtime); + live(runtime); +} + +// ============================================================================= 1. the radio + +fn radioUp(runtime: *p4.Runtime) void { + const started = nowMs(); + var last_report: u64 = 0; + while (!net.isUp()) { + runtime.yield(); + const elapsed = nowMs() - started; + if (elapsed - last_report >= 1000) { + last_report = elapsed; + const s = net.port.stats(); + soc.rom.print("MARK HTTP_TICK t=%u ms heap=%u B blocks=%u stubs=%u done=%u\r\n", .{ + @as(u32, @intCast(elapsed)), + @as(u32, @intCast(s.bytes_live)), + @as(u32, @intCast(s.blocks_live)), + s.stub_calls, + @as(u32, @intFromBool(bringup_done)), + }); + } + if (bringup_done) { + if (bringup_result) |err| fail("radio", @errorName(err)); + } + if (elapsed > radio_deadline_ms) { + soc.rom.print("MARK HTTP_FAIL radio timeout after %u ms (slave never answered)\r\n", .{ + @as(u32, @intCast(elapsed)), + }); + park(); + } + } + soc.rom.print("MARK HTTP_RADIO_UP after %u ms\r\n", .{@as(u32, @intCast(nowMs() - started))}); +} + +// ========================================================================== 2. the station + +fn wifiStart() void { + // `spun` counts ESP-Hosted's RPC not-ready spins across the call. Both `rpc_rx_thread` and + // `rpc_tx_thread` open their loop with `if (!is_rpc_lib_ready()) _h_sleep(1)` + // (rpc_core.c:482-485, :543-547) and those are the only `_h_sleep` callers linked here, so a + // non-zero value means the request was enqueued and never transmitted - a completely different + // failure from the coprocessor refusing it. + const before = net.port.stats().hosted_sleep_calls; + const rc = hosted_wifi_sta_start(); + const after = net.port.stats().hosted_sleep_calls; + soc.rom.print("MARK HTTP_WIFI_START rc=%d spun=%u\r\n", .{ rc, @as(u32, after - before) }); + if (rc != 0) fail("wifi_start", "rpc_wifi_start refused"); +} + +fn linkUp() void { + net.link.open() catch |err| fail("link", @errorName(err)); + const m = net.link.mac(); + soc.rom.print("MARK HTTP_LINK mac=%02x:%02x:%02x:%02x:%02x:%02x foot=%u B\r\n", .{ + @as(u32, m[0]), @as(u32, m[1]), @as(u32, m[2]), + @as(u32, m[3]), @as(u32, m[4]), @as(u32, m[5]), + @as(u32, net.link.footprint), + }); +} + +fn join(runtime: *p4.Runtime) void { + if (config.wifi_ssid.len == 0) { + soc.rom.print("MARK HTTP_FAIL join: no -Dssid given, nothing to associate with\r\n", .{}); + park(); + } + if (config.wifi_ssid.len > 32 or config.wifi_psk.len > 64) { + soc.rom.print("MARK HTTP_FAIL join: ssid or psk longer than 802.11 allows\r\n", .{}); + park(); + } + // NUL-terminated copies for the C ABI, sized to the maxima `wifi_config_t` itself uses. + @memcpy(ssid_buf[0..config.wifi_ssid.len], config.wifi_ssid); + @memcpy(psk_buf[0..config.wifi_psk.len], config.wifi_psk); + + // The SSID is printed; the passphrase is not, and only its length is - enough to tell a missing + // -Dpsk-file from a wrong one without putting the secret on a serial line. + soc.rom.print("MARK HTTP_JOIN ssid=%s psk_len=%u\r\n", .{ + @as([*:0]const u8, @ptrCast(&ssid_buf)), + @as(u32, @intCast(config.wifi_psk.len)), + }); + + // Already associated? The C6 keeps its association across a host reset, and radio.zig may have + // left one behind. Asking again is harmless and is what makes this file runnable twice. + const rc = hosted_wifi_connect(@ptrCast(&ssid_buf), @ptrCast(&psk_buf)); + soc.rom.print("MARK HTTP_CONNECT rc=%d\r\n", .{rc}); + if (rc != 0) fail("connect", "rpc_wifi_connect refused"); + + // Association is asynchronous: the request is answered at once and the outcome arrives as an + // event. Keep the scheduler running and bound the wait. + // + // Two conditions end this wait, not one. The event is the direct evidence. Received station + // traffic is the *indirect* evidence and it is just as conclusive: an AP does not forward + // broadcasts to a station that is not associated with it. The second condition exists because + // the C6 keeps its association across a host reset - examples/radio.zig may have left one + // behind - and a `connect` request that finds the radio already on this SSID need not produce + // a fresh id=4. Without it, the commonest happy case would time out with a misleading reason. + const started = nowMs(); + var why: [*:0]const u8 = "event"; + // Retry, because a single refusal is normal on a real network rather than a failure. + // + // Measured on this board: the same passphrase and SSID associate on some attempts and are + // refused on others with reason=4 ASSOC_EXPIRE at about -68 dBm. That is the AP expiring the + // association, not a credential problem - reason 15 would say wrong passphrase - and giving up + // on the first one made a working stack look broken half the time. Re-issuing the request is + // what any supplicant does. + var attempts: u32 = 1; + var seen_disconnects = disconnects; + while (!associated) { + drive(runtime); + if (net.link.ipCounters().rx_frames > 0) { + why = "traffic"; + break; + } + + // A new disconnect while still unassociated means this attempt is over; start another + // rather than waiting out a deadline that cannot now be met. + if (disconnects != seen_disconnects) { + seen_disconnects = disconnects; + if (attempts < assoc_attempts) { + attempts += 1; + // Back off before asking again, and this matters more than the attempt count. + // + // Retrying immediately made things worse, not better: ten back-to-back attempts + // produced an alternating run of reason=205 CONNECTION_FAIL at rssi=-128 and + // reason=15 4WAY_HANDSHAKE_TIMEOUT at rssi=-58 - a strong signal and a failed + // handshake, with a passphrase that had associated successfully minutes earlier. + // That pattern is an access point refusing a client that is hammering it, not a + // credential problem: reason 15 would otherwise mean a wrong passphrase, and + // psk_len proves the bytes are unchanged. + // + // Three seconds is longer than the AP's own handshake timeout, so each attempt is a + // fresh one rather than a collision with the last. + const backoff_started = nowMs(); + while (nowMs() - backoff_started < assoc_backoff_ms) drive(runtime); + soc.rom.print("MARK HTTP_RETRY attempt %u of %u after %u ms backoff\r\n", .{ + attempts, + assoc_attempts, + @as(u32, @intCast(assoc_backoff_ms)), + }); + if (hosted_wifi_connect(@ptrCast(&ssid_buf), @ptrCast(&psk_buf)) != 0) { + fail("connect", "rpc_wifi_connect refused on retry"); + } + } + } + + const elapsed = nowMs() - started; + if (elapsed > assoc_deadline_ms) { + soc.rom.print( + "MARK HTTP_FAIL assoc timeout after %u ms (attempts=%u, disconnects=%u, no id=4, no frames)\r\n", + .{ @as(u32, @intCast(elapsed)), attempts, disconnects }, + ); + park(); + } + } + soc.rom.print("MARK HTTP_ASSOC after %u ms by=%s rx=%u\r\n", .{ + @as(u32, @intCast(nowMs() - started)), + why, + net.link.ipCounters().rx_frames, + }); +} + +// ================================================================================== 3. DHCP + +fn dhcp(runtime: *p4.Runtime) void { + // `dhcpStart` stamps the acquisition's start from the stack's idea of now, and only `tick` + // sets that. One tick first, therefore, or every DHCP deadline is measured from zero. + _ = net.link.tick(nowMs()); + if (!net.link.dhcpStart()) fail("dhcp", "stack busy at dhcpStart, which cannot happen here"); + soc.rom.print("MARK HTTP_DHCP_TX discover sent\r\n", .{}); + + const started = nowMs(); + var last_report: u64 = 0; + while (net.link.address() == null) { + drive(runtime); + const elapsed = nowMs() - started; + if (elapsed - last_report >= 1000) { + last_report = elapsed; + const c = net.link.ipCounters(); + const l = net.link.stats(); + soc.rom.print( + "MARK HTTP_DHCP_WAIT t=%u state=%s rx=%u drop=%u csum=%u tx=%u dhcp_rx=%u re=%u\r\n", + .{ + @as(u32, @intCast(elapsed)), + @tagName(net.link.dhcpState()).ptr, + c.rx_frames, + c.rx_dropped, + c.checksum_bad, + c.tx_frames, + c.dhcp_rx, + l.rx_reentrant, + }, + ); + } + if (elapsed > dhcp_deadline_ms) { + const c = net.link.ipCounters(); + soc.rom.print( + "MARK HTTP_FAIL dhcp timeout after %u ms state=%s sent=%u got=%u rx=%u drop=%u\r\n", + .{ + @as(u32, @intCast(elapsed)), + @tagName(net.link.dhcpState()).ptr, + c.dhcp_tx, + c.dhcp_rx, + c.rx_frames, + c.rx_dropped, + }, + ); + park(); + } + } + + const a = net.link.address().?; + const m = net.link.netmask(); + const g = net.link.gateway(); + const d = net.link.dnsServer() orelse @as([4]u8, @splat(0)); + // Two lines rather than one seventeen-argument line. `ets_printf` is the mask ROM's, taking + // its arguments the ordinary variadic way - eight in registers and the rest on the stack - and + // there is no reason to be the first caller in this repo to find out where its limit is. + soc.rom.print("MARK HTTP_IP ip=%u.%u.%u.%u mask=%u.%u.%u.%u\r\n", .{ + @as(u32, a[0]), @as(u32, a[1]), @as(u32, a[2]), @as(u32, a[3]), + @as(u32, m[0]), @as(u32, m[1]), @as(u32, m[2]), @as(u32, m[3]), + }); + soc.rom.print("MARK HTTP_ROUTE gw=%u.%u.%u.%u dns=%u.%u.%u.%u in %u ms\r\n", .{ + @as(u32, g[0]), @as(u32, g[1]), @as(u32, g[2]), @as(u32, g[3]), + @as(u32, d[0]), @as(u32, d[1]), @as(u32, d[2]), @as(u32, d[3]), + @as(u32, @intCast(nowMs() - started)), + }); + heapReport(); +} + +// ================================================================================== 4. ICMP + +/// Yield, and tick the IP stack at most every `tick_interval_ms`. +/// +/// The rate limit is the whole point. `link.tick` holds the stack's re-entrancy guard for its +/// duration, and a frame that arrives while the guard is held is dropped - ESP-Hosted's receive task +/// and this one are different tasks, so they genuinely collide. A loop of the obvious shape, +/// +/// while (...) { runtime.yield(); _ = net.link.tick(nowMs()); } +/// +/// ticks thousands of times a second, holds the guard for most of the elapsed time, and drops much +/// of the traffic it is waiting for. Measured on the board: 40 dropped frames out of 113 received, +/// and ping answered at about 40%, even though every reply that was attempted did arrive. +/// +/// Five milliseconds is far finer than anything ip.zig needs - its timers are absolute deadlines, so +/// a late tick is late rather than lost - and it leaves the guard clear almost all the time. +fn drive(runtime: *p4.Runtime) void { + runtime.yield(); + const now = nowMs(); + if (now - last_tick_ms >= tick_interval_ms) { + last_tick_ms = now; + _ = net.link.tick(now); + } +} + +const tick_interval_ms: u64 = 5; +var last_tick_ms: u64 = 0; + +fn pingWindow(runtime: *p4.Runtime) void { + const a = net.link.address().?; + soc.rom.print( + "MARK HTTP_PING_OPEN ip=%u.%u.%u.%u for %u ms - ping it now\r\n", + .{ + @as(u32, a[0]), + @as(u32, a[1]), + @as(u32, a[2]), + @as(u32, a[3]), + @as(u32, @intCast(ping_window_ms)), + }, + ); + + const started = nowMs(); + var seen: u32 = net.link.ipCounters().icmp_echo; + var last_report: u64 = 0; + while (true) { + drive(runtime); + const c = net.link.ipCounters(); + if (c.icmp_echo != seen) { + seen = c.icmp_echo; + // One line per echo answered. `arp` beside it is what proves the exchange was two-way: + // the workstation had to ARP for this address and get an answer before it could send + // the echo at all. + soc.rom.print("MARK HTTP_PING n=%u arp_rx=%u arp_tx=%u\r\n", .{ + seen, + c.arp_rx, + c.arp_tx, + }); + } + const elapsed = nowMs() - started; + if (elapsed - last_report >= 5000) { + last_report = elapsed; + // Heap included deliberately. The board reported "mempool OOM start (RX)" at ~13 s in a + // previous run: with the pool off, ESP-Hosted allocates every received frame from our + // heap via `_h_malloc_align(1536, 64)`, and when that fails the receive path simply + // stops delivering. `live` climbing while `rx` is static means a leak; `live` pinned + // near the heap size with `rx` frozen means a heap too small for the queue depths. + // Without both numbers side by side those two are indistinguishable. + const h = net.port.stats(); + soc.rom.print( + "MARK HTTP_PING_IDLE t=%u echo=%u rx=%u drop=%u tx=%u live=%u B blocks=%u fails=%u\r\n", + .{ + @as(u32, @intCast(elapsed)), + c.icmp_echo, + c.rx_frames, + c.rx_dropped, + c.tx_frames, + @as(u32, @intCast(h.bytes_live)), + @as(u32, @intCast(h.blocks_live)), + @as(u32, @intCast(h.alloc_failures)), + }, + ); + } + if (elapsed > ping_window_ms) break; + } + soc.rom.print("MARK HTTP_PING_DONE echoes=%u\r\n", .{net.link.ipCounters().icmp_echo}); +} + +// ================================================================================== 5. HTTP + +/// The response body. Static rather than on the stack because `httpGet` borrows it for the whole +/// request - the body is written into it from inside the receive callback, on a different task - +/// and a task stack is 4 KiB. +var body: [2048]u8 = undefined; + +fn httpGet(runtime: *p4.Runtime) void { + soc.rom.print("MARK HTTP_GET host=%u.%u.%u.%u port=%u path=%s\r\n", .{ + @as(u32, http_host[0]), @as(u32, http_host[1]), + @as(u32, http_host[2]), @as(u32, http_host[3]), + @as(u32, http_port), @as([*:0]const u8, http_path), + }); + + const started = nowMs(); + var last_report: u64 = 0; + const got: usize = while (true) { + drive(runtime); + // Identical arguments every call, and `body` never moves: that is the whole of the + // WouldBlock protocol. Different arguments mid-flight would return error.Busy instead. + if (net.link.httpGet(http_host, http_port, http_path, &body)) |n| { + break n; + } else |err| switch (err) { + error.WouldBlock => {}, + else => { + soc.rom.print("MARK HTTP_FAIL get=%s tcp=%s after %u ms\r\n", .{ + @errorName(err).ptr, + @tagName(net.link.tcpState()).ptr, + @as(u32, @intCast(nowMs() - started)), + }); + park(); + }, + } + const elapsed = nowMs() - started; + if (elapsed - last_report >= 2000) { + last_report = elapsed; + const c = net.link.ipCounters(); + soc.rom.print("MARK HTTP_WAIT t=%u tcp=%s tx=%u retx=%u rx=%u rst=%u\r\n", .{ + @as(u32, @intCast(elapsed)), + @tagName(net.link.tcpState()).ptr, + c.tcp_tx, + c.tcp_retx, + c.tcp_rx, + c.tcp_rst_rx, + }); + } + if (elapsed > http_deadline_ms) { + const c = net.link.ipCounters(); + soc.rom.print( + "MARK HTTP_FAIL get timeout after %u ms tcp=%s arp_tx=%u tcp_tx=%u tcp_rx=%u\r\n", + .{ + @as(u32, @intCast(elapsed)), + @tagName(net.link.tcpState()).ptr, + c.arp_tx, + c.tcp_tx, + c.tcp_rx, + }, + ); + park(); + } + }; + + soc.rom.print("MARK HTTP_STATUS code=%u len=%u in %u ms\r\n", .{ + @as(u32, net.link.httpStatus()), + @as(u32, @intCast(got)), + @as(u32, @intCast(nowMs() - started)), + }); + printBody(body[0..got]); + heapReport(); +} + +/// The first bytes of the body, on one line, with anything that is not printable ASCII shown as +/// '.'. A response body is arbitrary bytes and this is a serial console: a stray 0x0d would split +/// the line and a 0x00 would truncate it, and either would look like a short read. +fn printBody(bytes: []const u8) void { + const preview_max = 120; + var buf: [preview_max + 1]u8 = undefined; + const n = @min(bytes.len, preview_max); + for (bytes[0..n], 0..) |b, i| buf[i] = if (b >= 0x20 and b < 0x7f) b else '.'; + buf[n] = 0; + soc.rom.print("MARK HTTP_BODY %u/%u |%s|\r\n", .{ + @as(u32, @intCast(n)), + @as(u32, @intCast(bytes.len)), + @as([*:0]const u8, @ptrCast(&buf)), + }); +} + +// ============================================================================== 6. stay live + +/// Keep running. The transport's threads must keep being scheduled, the stack keeps answering ICMP, +/// and leaving the board in a live state is what lets the next experiment start from here. +/// A real host on the real internet: resolve a name, then fetch it. +/// +/// A strictly harder test than the GET against this workstation, and every extra thing it exercises +/// is one the local test could not: +/// +/// * DNS. The name is resolved over UDP against the server DHCP handed us - on this network the +/// gateway - so the resolver, the wire format and its name-compression handling are all in play. +/// * Off-subnet routing. 0x4200.cafe is not on 192.168.1.0/24, so the stack has to ARP for the +/// GATEWAY and send to its MAC while the IP header addresses the far host. The local test never +/// leaves the subnet and so never proved that. +/// * Name-based virtual hosting. The site is behind Cloudflare, which serves it only for a request +/// carrying `Host: 0x4200.cafe`. `Host: 104.21.46.8` gets someone else's error page - which is +/// the entire reason `httpGetHost` exists. +/// * Chunked transfer encoding. Measured from a workstation the response is +/// `Transfer-Encoding: chunked` with no Content-Length, so the body arrives in framed pieces +/// whose boundaries fall wherever TCP puts them. +/// +/// The lines, and what each means: +/// +/// MARK NET_DNS name -> a.b.c.d in N ms the resolver worked end to end +/// bad: failed=Timeout no reply from the DHCP-supplied server inside the bound +/// failed=NoAddress no A record (the name does have AAAA; this stack is IPv4) +/// failed=Malformed a reply arrived and was rejected +/// MARK NET_GET host=... via gw=... the request begins, naming the next hop +/// MARK NET_STATUS code=200 len=N in M ms a real page came back +/// bad: get=HttpChunkMalformed chunked framing rejected +/// get=StreamTooLong the page is bigger than the buffer here - not a stack bug; it +/// means this buffer is small, and this says so rather than truncating +/// MARK NET_BODY n/N |...| first bytes, non-printables as '.' +const internet_name = "0x4200.cafe"; + +/// 2 KiB, which is what the target resource needs and no more. +/// +/// The site's root page is 132,932 bytes decoded - larger than this board's entire 128 KB of L2MEM, +/// so it cannot be buffered whole by anything running here and `StreamTooLong` is the correct answer +/// for asking. Fetching it would need a streaming API that hands the caller each chunk as it arrives +/// and keeps none of it, which this stack does not have. That is a real limitation and it is stated +/// rather than hidden. +/// +/// `/robots.txt` on the same host is 1,248 bytes and exercises everything the root page would about +/// the path being tested here: the name is resolved by DNS, the destination is off-subnet so the +/// frame goes to the gateway's MAC, and the response only comes back at all because the request +/// carries `Host: 0x4200.cafe`. +var net_body: [2048]u8 = undefined; + +/// The path fetched. See `net_body` for why it is not `/`. +const internet_path = "/robots.txt"; + +fn internetGet(runtime: *p4.Runtime) void { + // 1. Resolve. Same WouldBlock protocol as httpGet: identical argument every call, drive between. + const dns_started = nowMs(); + const addr: [4]u8 = while (true) { + drive(runtime); + if (net.link.resolve(internet_name)) |a| { + break a; + } else |err| switch (err) { + error.WouldBlock => {}, + else => { + soc.rom.print("MARK NET_DNS %s failed=%s after %u ms\r\n", .{ + internet_name.ptr, + @errorName(err).ptr, + @as(u32, @intCast(nowMs() - dns_started)), + }); + return; + }, + } + if (nowMs() - dns_started > 15_000) { + soc.rom.print("MARK NET_DNS %s gave up after %u ms\r\n", .{ + internet_name.ptr, + @as(u32, @intCast(nowMs() - dns_started)), + }); + return; + } + }; + soc.rom.print("MARK NET_DNS %s -> %u.%u.%u.%u in %u ms\r\n", .{ + internet_name.ptr, + @as(u32, addr[0]), + @as(u32, addr[1]), + @as(u32, addr[2]), + @as(u32, addr[3]), + @as(u32, @intCast(nowMs() - dns_started)), + }); + + // The gateway is printed because it is the thing under test here: for an off-subnet destination + // the Ethernet frame goes to the gateway's MAC while the IP header addresses the far host, and a + // stack that got that wrong would look like a dead internet rather than a routing bug. + const gw = net.link.gateway(); + soc.rom.print("MARK NET_GET host=%s%s via gw=%u.%u.%u.%u\r\n", .{ + internet_name.ptr, + internet_path.ptr, + @as(u32, gw[0]), + @as(u32, gw[1]), + @as(u32, gw[2]), + @as(u32, gw[3]), + }); + + // 2. Fetch, with the NAME in the Host header rather than the address. + const started = nowMs(); + var last_report: u64 = 0; + const got: usize = while (true) { + drive(runtime); + if (net.link.httpGetHost(addr, internet_name, 80, internet_path, &net_body)) |n| { + break n; + } else |err| switch (err) { + error.WouldBlock => {}, + else => { + soc.rom.print("MARK NET_FAIL get=%s tcp=%s after %u ms\r\n", .{ + @errorName(err).ptr, + @tagName(net.link.tcpState()).ptr, + @as(u32, @intCast(nowMs() - started)), + }); + return; + }, + } + const elapsed = nowMs() - started; + if (elapsed - last_report >= 2000) { + last_report = elapsed; + soc.rom.print("MARK NET_WAIT t=%u tcp=%s\r\n", .{ + @as(u32, @intCast(elapsed)), + @tagName(net.link.tcpState()).ptr, + }); + } + if (elapsed > 30_000) { + soc.rom.print("MARK NET_FAIL timeout tcp=%s\r\n", .{@tagName(net.link.tcpState()).ptr}); + return; + } + }; + + soc.rom.print("MARK NET_STATUS code=%u len=%u in %u ms\r\n", .{ + @as(u32, net.link.httpStatus()), + @as(u32, @intCast(got)), + @as(u32, @intCast(nowMs() - started)), + }); + // First bytes only, printable-filtered: this is a serial line and an HTML page is not a log. + var shown: [96]u8 = undefined; + const n = @min(got, shown.len - 1); + for (0..n) |i| { + const c = net_body[i]; + shown[i] = if (c >= 0x20 and c < 0x7f) c else '.'; + } + shown[n] = 0; + soc.rom.print("MARK NET_BODY %u/%u |%s|\r\n", .{ + @as(u32, @intCast(n)), + @as(u32, @intCast(got)), + @as([*:0]const u8, @ptrCast(&shown)), + }); +} + +fn live(runtime: *p4.Runtime) noreturn { + var last: u64 = 0; + var last_echo: u32 = 0; + while (true) { + drive(runtime); + const t = nowMs(); + if (t - last >= 1000) { + last = t; + const c = net.link.ipCounters(); + const l = net.link.stats(); + soc.rom.print( + "MARK HTTP_LIVE t=%u echo=%u(+%u) rx=%u drop=%u tx=%u txfail=%u re=%u skip=%u\r\n", + .{ + @as(u32, @intCast(t / 1000)), + c.icmp_echo, + c.icmp_echo - last_echo, + c.rx_frames, + c.rx_dropped, + l.tx_frames, + l.tx_failed, + l.rx_reentrant, + l.tick_skipped, + }, + ); + last_echo = c.icmp_echo; + } + } +} + +// =================================================================================== shared + +fn heapReport() void { + const s = net.port.stats(); + soc.rom.print("MARK HTTP_HEAP live=%u B reserved=%u B peak=%u B blocks=%u fails=%u\r\n", .{ + @as(u32, @intCast(s.bytes_live)), + @as(u32, @intCast(s.bytes_reserved)), + @as(u32, @intCast(s.peak_reserved)), + @as(u32, @intCast(s.blocks_live)), + @as(u32, @intCast(s.alloc_failures)), + }); +} + +fn fail(comptime what: []const u8, why: [*:0]const u8) noreturn { + soc.rom.print("MARK HTTP_FAIL " ++ what ++ "=%s\r\n", .{why}); + park(); +} + +fn nowMs() u64 { + // The systimer is a fixed 16 MHz and the only trustworthy timebase here: the CPU runs at the + // bootloader's 90 MHz and nothing in this image reconfigures the PLL. A failed snapshot read + // yields 0, which makes an elapsed calculation conservative rather than wrong. + const ticks = hal.systimer.read(.unit0) orelse return 0; + return ticks / 16_000; +} + +/// `while (true) {}` rather than a reset, so the last message stays on screen instead of scrolling +/// past in a reboot loop. Note that this stops the scheduler too: nothing here is recoverable. +fn park() noreturn { + soc.rom.print("MARK HTTP_DONE parked\r\n", .{}); + while (true) {} +} |