//! 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) {} }