Merge commit 'b9ebe41358244caa9334e72ca4e3c8c7a14c86e7'

11 files changed, 786 insertions, 159 deletions

diff --git a/cmd/sbc_harness/config/config.h b/cmd/sbc_harness/config/config.h
index 6d2ea89..daa01dd 100644
--- a/cmd/sbc_harness/config/config.h
+++ b/cmd/sbc_harness/config/config.h
@@ -25,6 +25,8 @@
 #define CONFIG_W5500_LOCAL_PORT_MIN     32768
 #define CONFIG_W5500_LOCAL_PORT_MAX     60999
 
+#define CONFIG_W5500_DEBUG              1 /* bool */
+
 /* 9P *************************************************************************/
 
 #define CONFIG_9P_PORT                564
@@ -62,7 +64,7 @@
 /* DHCP ***********************************************************************/
 
 #define CONFIG_DHCP_CAN_RECV_UNICAST_IP_WITHOUT_IP      0 /* bool */
-#define CONFIG_DHCP_DEBUG                               0 /* bool */
+#define CONFIG_DHCP_DEBUG                               1 /* bool */
 #define CONFIG_DHCP_OPT_SIZE                            312 /* minimum of 312 */
 #define CONFIG_DHCP_SELECTING_NS                        (5*NS_PER_S)
 
diff --git a/cmd/sbc_harness/main.c b/cmd/sbc_harness/main.c
index d665fb3..fb4b696 100644
--- a/cmd/sbc_harness/main.c
+++ b/cmd/sbc_harness/main.c
@@ -111,6 +111,8 @@ COROUTINE init_cr(void *) {
 
 int main() {
 	stdio_uart_init();
+	/* char *hdr = "=" * (80-strlen("info : MAIN: ")); */
+	infof("===================================================================");
 	coroutine_add("init", init_cr, NULL);
 	coroutine_main();
 }
diff --git a/gdb-helpers/libcr.py b/gdb-helpers/libcr.py
index c8addc6..c07b679 100644
--- a/gdb-helpers/libcr.py
+++ b/gdb-helpers/libcr.py
@@ -4,41 +4,55 @@
 # SPDX-License-Identifier: AGPL-3.0-or-later
 
 import contextlib
+import time
 import typing
 
 import gdb
+import gdb.unwinder
 
 # GDB helpers ##################################################################
 
 
-def gdb_argv_to_string(argv: list[str]) -> str:
-    """Reverse of gdb.string_to_argv()"""
-    # TODO: This is wrong
-    return " ".join(argv)
+class _gdb_Locus(typing.Protocol):
+    @property
+    def frame_unwinders(self) -> list["gdb._Unwinder"]: ...
+
 
+def gdb_unregister_unwinder(
+    locus: gdb.Objfile | gdb.Progspace | None, unwinder: "gdb._Unwinder"
+) -> None:
+    _locus: _gdb_Locus = typing.cast(_gdb_Locus, gdb) if locus is None else locus
+    _locus.frame_unwinders.remove(unwinder)
+    gdb.invalidate_cached_frames()
 
-class GdbJmpBuf:
+
+class gdb_JmpBuf:
     """Our own in-Python GDB-specific implementation of `jmp_buf`"""
 
-    frame: gdb.Frame
+    level: int
     registers: dict[str, str]
 
 
-def gdb_setjmp() -> GdbJmpBuf:
+def gdb_setjmp() -> gdb_JmpBuf:
     """Our own in-Python GDB-specific implementation of `setjmp()`"""
-    buf = GdbJmpBuf()
-    buf.frame = gdb.selected_frame()
+    buf = gdb_JmpBuf()
+    buf.level = gdb.selected_frame().level()
+    gdb.execute("select-frame level 0")
     buf.registers = {}
     for line in gdb.execute("info registers", to_string=True).split("\n"):
         words = line.split(maxsplit=2)
         if len(words) < 2:
             continue
         buf.registers[words[0]] = words[1]
+    gdb.execute(f"select-frame level {buf.level}")
     return buf
 
 
-def gdb_longjmp(buf: GdbJmpBuf) -> None:
+def gdb_longjmp(buf: gdb_JmpBuf) -> None:
     """Our own in-Python GDB-specific implementation of `longjmp()`"""
+
+    gdb.execute("select-frame level 0")
+
     if (
         ("sp" in buf.registers)
         and ("msp" in buf.registers)
@@ -52,9 +66,12 @@ def gdb_longjmp(buf: GdbJmpBuf) -> None:
         gdb.execute(f"set $sp = {buf.registers['sp']}", to_string=True)
         gdb.execute(f"set $msp = {buf.registers['msp']}")
         gdb.execute(f"set $psp = {buf.registers['psp']}")
+
     for reg, val in buf.registers.items():
         gdb.execute(f"set ${reg} = {val}")
-    buf.frame.select()
+    gdb.invalidate_cached_frames()
+
+    gdb.execute(f"select-frame level {buf.level}")
 
 
 # Core libcr functionality #####################################################
@@ -62,42 +79,167 @@ def gdb_longjmp(buf: GdbJmpBuf) -> None:
 
 class CrGlobals:
     coroutines: list["CrCoroutine"]
-    breakpoints: list[gdb.Breakpoint]
+    _breakpoint: "CrBreakpoint"
+    _known_threads: set[gdb.InferiorThread]
 
     def __init__(self) -> None:
         num = int(
             gdb.parse_and_eval("sizeof(coroutine_table)/sizeof(coroutine_table[0])")
         )
+
         self.coroutines = [CrCoroutine(self, i + 1) for i in range(num)]
-        self.breakpoints = []
+
+        self._breakpoint = CrBreakpoint()
+        self._breakpoint.enabled = False
+
+        self._known_threads = set()
+
+        gdb.events.cont.connect(self._on_cont)
 
     def delete(self) -> None:
         self.coroutines = []
-        for b in self.breakpoints:
-            b.delete()
-        self.breakpoints = []
+        self._breakpoint.delete()
+        gdb.events.cont.disconnect(self._on_cont)
+
+    def readjmp(self, env_ptr_expr: str) -> gdb_JmpBuf:
+        self._breakpoint.enabled = True
+        gdb.execute(f"call (void)cr_gdb_readjmp({env_ptr_expr})")
+        self._breakpoint.enabled = False
+        gdb.execute("queue-signal SIGWINCH")
+        return self._breakpoint.env
+
+    def _on_cont(self, event: gdb.Event) -> None:
+        cur_threads = set(gdb.selected_inferior().threads())
+        if cur_threads - self._known_threads:
+            # Ignore thread creation events.
+            self._known_threads = cur_threads
+            return
+        if self.coroutine_running:
+            if not self.coroutine_running.is_selected():
+                if True:  # https://sourceware.org/bugzilla/show_bug.cgi?id=32428
+                    print("Must return to running coroutine before continuing.")
+                    print("Hit ^C twice then run:")
+                    print(f"  cr select {self.coroutine_running.id}")
+                    while True:
+                        time.sleep(1)
+                assert self.coroutine_running._cont_env
+                gdb_longjmp(self.coroutine_running._cont_env)
+        for cr in self.coroutines:
+            cr._cont_env = None
 
     def is_valid_cid(self, cid: int) -> bool:
         return 0 < cid and cid <= len(self.coroutines)
 
     @property
-    def coroutine_running(self) -> int:
-        return int(gdb.parse_and_eval("coroutine_running"))
+    def coroutine_running(self) -> "CrCoroutine | None":
+        cid = int(gdb.parse_and_eval("coroutine_running"))
+        if not self.is_valid_cid(cid):
+            return None
+        return self.coroutines[cid - 1]
+
+    @property
+    def coroutine_selected(self) -> "CrCoroutine | None":
+        for cr in self.coroutines:
+            if cr.is_selected():
+                return cr
+        return None
 
     @property
     def CR_NONE(self) -> gdb.Value:
         return gdb.parse_and_eval("CR_NONE")
 
+    @property
+    def CR_RUNNING(self) -> gdb.Value:
+        return gdb.parse_and_eval("CR_RUNNING")
+
+
+class CrBreakpointUnwinder(gdb.unwinder.Unwinder):
+    """Used to temporarily disable unwinding so that
+    gdb/breakpoint.c:check_longjmp_breakpoint_for_call_dummy() doesn't
+    prematurely garbage collect the `call`-dummy-frame.
+
+    """
+
+    def __init__(self) -> None:
+        super().__init__("cr_breakpoint_unwinder")
+
+    # The .pyi is wrong; it says `Frame` instead of `PendingFrame`.
+    def __call__(self, pending_frame: gdb.PendingFrame) -> gdb.UnwindInfo | None:
+        # Stop unwinding with stop_reason=UNWIND_NO_SAVED_PC by
+        # returning an UnwindInfo that doesn't have
+        # `.add_saved_register("pc", ...)`.
+        return pending_frame.create_unwind_info(
+            gdb.unwinder.FrameId(
+                sp=pending_frame.read_register("sp"),
+                pc=pending_frame.read_register("pc"),
+            )
+        )
+
+
+class CrBreakpoint(gdb.Breakpoint):
+    env: gdb_JmpBuf
+    _unwinder_locus: gdb.Objfile
+    _unwinder: CrBreakpointUnwinder
+
+    def __init__(self) -> None:
+        self.env = gdb_JmpBuf()
+
+        self._unwinder = CrBreakpointUnwinder()
+        readjmp_sym = gdb.lookup_global_symbol("cr_gdb_readjmp")
+        assert readjmp_sym
+        self._unwinder_locus = readjmp_sym.symtab.objfile
+        gdb.unwinder.register_unwinder(self._unwinder_locus, self._unwinder, True)
+        self._unwinder.enabled = False
+
+        super().__init__(
+            function="cr_gdb_breakpoint", type=gdb.BP_BREAKPOINT, internal=True
+        )
+
+    @property
+    def enabled(self) -> bool:
+        return super().enabled
+
+    @enabled.setter
+    def enabled(self, value: bool) -> None:
+        self._unwinder.enabled = value
+        gdb.Breakpoint.enabled.__set__(self, value)  # type: ignore
+
+    def stop(self) -> bool:
+        assert self._unwinder.enabled
+        self._unwinder.enabled = False
+        self.env = gdb_setjmp()
+        self._unwinder.enabled = True
+        return False  # don't stop
+
+    def delete(self) -> None:
+        gdb_unregister_unwinder(self._unwinder_locus, self._unwinder)
+        super().delete()
+
+
+def cr_select_top_frame() -> None:
+    gdb.execute("select-frame level 0")
+    base_frame = gdb.selected_frame()
+    while True:
+        fn = gdb.selected_frame().name()
+        if fn and (fn.startswith("cr_") or fn.startswith("_cr_")):
+            older = gdb.selected_frame().older()
+            if not older:
+                base_frame.select()
+                break
+            older.select()
+        else:
+            break
+
 
 class CrCoroutine:
     cr_globals: CrGlobals
     cid: int
-    env: GdbJmpBuf | None
+    _cont_env: gdb_JmpBuf | None
 
     def __init__(self, cr_globals: CrGlobals, cid: int) -> None:
         self.cr_globals = cr_globals
         self.cid = cid
-        self.env = None
+        self._cont_env = None
 
     @property
     def id(self) -> int:
@@ -114,50 +256,39 @@ class CrCoroutine:
             bs[i] = int(gdb.parse_and_eval(f"coroutine_table[{self.cid-1}].name[{i}]"))
         return bytes(bs).decode("UTF-8").split("\x00", maxsplit=1)[0]
 
+    def is_selected(self) -> bool:
+        sp = int(gdb.parse_and_eval("$sp"))
+        lo = int(gdb.parse_and_eval(f"coroutine_table[{self.id-1}].stack"))
+        hi = lo + int(gdb.parse_and_eval(f"coroutine_table[{self.id-1}].stack_size"))
+        return lo <= sp and sp < hi
+
+    def select(self, level: int = -1) -> None:
+        if self.cr_globals.coroutine_selected:
+            self.cr_globals.coroutine_selected._cont_env = gdb_setjmp()
+
+        if self._cont_env:
+            gdb_longjmp(self._cont_env)
+        else:
+            env: gdb_JmpBuf
+            if self == self.cr_globals.coroutine_running:
+                assert False  # self._cont_env should have been set
+            elif self.state == self.cr_globals.CR_RUNNING:
+                env = self.cr_globals.readjmp("&coroutine_add_env")
+            else:
+                env = self.cr_globals.readjmp(f"&coroutine_table[{self.id-1}].env")
+            gdb_longjmp(env)
+            cr_select_top_frame()
+
     @contextlib.contextmanager
-    def active(self) -> typing.Iterator[None]:
+    def with_selected(self) -> typing.Iterator[None]:
         saved_env = gdb_setjmp()
-        cr_env = self.env
-        if self.cid == self.cr_globals.coroutine_running:
-            cr_env = saved_env
-        if not cr_env:
-            raise gdb.GdbError(
-                f"GDB does not have a saved execution environment for coroutine {self.id}.  "
-                + "This can happen if the coroutine has not run for as long as GDB has been attached."
-            )
-
-        gdb_longjmp(cr_env)
+        self.select()
         try:
             yield
         finally:
             gdb_longjmp(saved_env)
 
 
-class CrSetJmpBreakpoint(gdb.Breakpoint):
-    cr_globals: CrGlobals
-
-    def __init__(self, cr_globals: CrGlobals) -> None:
-        self.cr_globals = cr_globals
-        cr_globals.breakpoints += [self]
-        super().__init__(
-            function="_cr_plat_setjmp_pre", type=gdb.BP_BREAKPOINT, internal=True
-        )
-
-    def stop(self) -> bool:
-        if bool(gdb.parse_and_eval("env == &coroutine_add_env")):
-            cid = self.cr_globals.coroutine_running
-        elif bool(gdb.parse_and_eval("env == &coroutine_main_env")):
-            cid = 0
-        else:
-            idx = gdb.parse_and_eval(
-                "( ((char*)env)-((char *)&coroutine_table)) / sizeof(coroutine_table[0])"
-            )
-            cid = int(idx) + 1
-        if self.cr_globals.is_valid_cid(cid):
-            self.cr_globals.coroutines[cid - 1].env = gdb_setjmp()
-        return False
-
-
 # User-facing commands #########################################################
 
 
@@ -176,7 +307,12 @@ class CrCommand(gdb.Command):
 
 class CrListCommand(gdb.Command):
     """List libcr coroutines.
-    Usage: cr list"""
+    Usage: cr list
+
+    In the output:
+    - the 'R' marker indicates the currently-running coroutine
+    - the 'G' marker indicates the coroutine that GDB is viewing; this may be changed with `cr select`
+    """
 
     cr_globals: CrGlobals
 
@@ -189,59 +325,80 @@ class CrListCommand(gdb.Command):
         if len(argv) != 0:
             raise gdb.GdbError(f"Usage: cr list")
 
-        w_marker = 1
-        w_id = max(len("Id"), len(str(len(self.cr_globals.coroutines))))
-        w_name = max(
-            len("Name"), int(gdb.parse_and_eval("sizeof(coroutine_table[0].name)"))
-        )
-        w_state = len("CR_INITIALIZING")
-        print(
-            f"  {'Id'.ljust(w_id)}  {'Name'.ljust(w_name)}  {'State'.ljust(w_state)}  Frame"
-        )
+        rows: list[tuple[str, str, str, str, str]] = [
+            ("", "Id", "Name", "State", "Frame")
+        ]
         for cr in self.cr_globals.coroutines:
             if cr.state == self.cr_globals.CR_NONE:
                 continue
-            v_marker = "*" if cr.id == self.cr_globals.coroutine_running else ""
-            v_id = str(cr.id)
-            v_name = cr.name
-            v_state = str(cr.state)
-            v_frame = self._pretty_frame(cr, from_tty)
-            print(
-                f"{v_marker.ljust(w_marker)} {v_id.ljust(w_id)}  {v_name.ljust(w_name)}  {v_state.ljust(w_state)}  {v_frame}"
-            )
+            rows += [
+                (
+                    "".join(
+                        [
+                            "R" if cr == self.cr_globals.coroutine_running else " ",
+                            "G" if cr.is_selected() else " ",
+                        ]
+                    ),
+                    str(cr.id),
+                    repr(cr.name),
+                    str(cr.state),
+                    self._pretty_frame(cr, from_tty),
+                )
+            ]
+
+        widths: list[int] = [
+            max(len(row[col]) for row in rows) for col in range(len(rows[0]))
+        ]
+
+        def line(row: tuple[str, str, str, str, str]) -> str:
+
+            def cell(col: int) -> str:
+                return row[col].ljust(widths[col])
+
+            return f"{cell(0)} {cell(1)}  {cell(2)}  {cell(3)}  {row[4]}"
+
+        maxline = 0
+        if screenwidth := gdb.parameter("width"):
+            assert isinstance(screenwidth, int)
+            maxline = max(screenwidth, len(line(rows[0])))
+
+        for row in rows:
+            l = line(row)
+            if maxline and len(l) > maxline:
+                l = l[:maxline]
+            print(l)
 
     def _pretty_frame(self, cr: CrCoroutine, from_tty: bool) -> str:
         try:
-            with cr.active():
+            with cr.with_selected():
+                saved_level = gdb.selected_frame().level()
+                cr_select_top_frame()
                 full = gdb.execute("frame", from_tty=from_tty, to_string=True)
+                gdb.execute(f"select-frame level {saved_level}")
         except Exception as e:
-            full = "#1 err: " + str(e)
+            full = "#0 err: " + str(e)
         line = full.split("\n", maxsplit=1)[0]
         return line.split(maxsplit=1)[1]
 
 
-class CrApplyCommand(gdb.Command):
-    """Apply a GDB command to libcr coroutines.
-    Usage: cr apply COROUTINE... -- COMMAND
-    COROUTINE is a space-separated list of coroutine IDs or names."""
+class CrSelectCommand(gdb.Command):
+    """Select the coroutine that GDB is viewing
+    Usage: cr select COROUTINE
+    COROUTINE is either a coroutine ID or coroutine name."""
 
     cr_globals: CrGlobals
 
     def __init__(self, cr_globals: CrGlobals) -> None:
         self.cr_globals = cr_globals
-        gdb.Command.__init__(self, "cr apply", gdb.COMMAND_RUNNING, gdb.COMPLETE_NONE)
+        gdb.Command.__init__(self, "cr select", gdb.COMMAND_RUNNING, gdb.COMPLETE_NONE)
 
     def invoke(self, arg: str, from_tty: bool) -> None:
         argv = gdb.string_to_argv(arg)
-        if "--" not in argv:
-            raise gdb.GdbError("Usage: cr apply COROUTINE... -- COMMAND")
-        sep = argv.index("--")
-        crs = argv[:sep]
-        cmd = argv[sep + 1 :]
-        for spec in crs:
-            cr = self._find(spec)
-            with cr.active():
-                gdb.execute(gdb_argv_to_string(cmd), from_tty=from_tty)
+        if len(argv) != 1:
+            raise gdb.GdbError("Usage: cr select COROUTINE")
+        cr = self._find(argv[0])
+        cr.select()
+        gdb.execute("frame")
 
     def _find(self, name: str) -> CrCoroutine:
         if name.isnumeric():
@@ -266,25 +423,35 @@ class CrApplyCommand(gdb.Command):
 
 # Wire it all in ###############################################################
 
+cr_globals: CrGlobals | None = None
 
-def cr_initialize() -> None:
-    cr_globals = CrGlobals()
-
-    CrSetJmpBreakpoint(cr_globals)
 
+def cr_initialize() -> None:
+    global cr_globals
+    if cr_globals:
+        old = cr_globals
+        new = CrGlobals()
+        for i in range(min(len(old.coroutines), len(new.coroutines))):
+            new.coroutines[i]._cont_env = old.coroutines[i]._cont_env
+        old.delete()
+        cr_globals = new
+    else:
+        cr_globals = CrGlobals()
     CrCommand(cr_globals)
     CrListCommand(cr_globals)
-    CrApplyCommand(cr_globals)
+    CrSelectCommand(cr_globals)
 
 
 def cr_on_new_objfile(event: gdb.Event) -> None:
     if any(
-        objfile.lookup_static_symbol("_cr_plat_setjmp_pre")
-        for objfile in gdb.objfiles()
+        objfile.lookup_global_symbol("cr_gdb_readjmp") for objfile in gdb.objfiles()
     ):
         print("Initializing libcr integration...")
         cr_initialize()
         gdb.events.new_objfile.disconnect(cr_on_new_objfile)
 
 
-gdb.events.new_objfile.connect(cr_on_new_objfile)
+if cr_globals:
+    cr_initialize()
+else:
+    gdb.events.new_objfile.connect(cr_on_new_objfile)
diff --git a/libcr/coroutine.c b/libcr/coroutine.c
index dbeef12..a947ae9 100644
--- a/libcr/coroutine.c
+++ b/libcr/coroutine.c
@@ -128,8 +128,17 @@
  *   no longer exists.
  */
 
-#define ALWAYS_INLINE [[gnu::always_inline]] inline
-#define NEVER_INLINE  [[gnu::noinline]]
+/* preprocessor macros ********************************************************/
+
+/** Return `n` rounded up to the nearest multiple of `d` */
+#define ROUND_UP(n, d)          ( ( ((n)+(d)-1) / (d) ) * (d) )
+#define ARRAY_LEN(arr)          (sizeof(arr)/sizeof((arr)[0]))
+#define NEXT_POWER_OF_2(x)      ((1ULL)<<((sizeof(unsigned long long)*8)-__builtin_clzll(x)))
+
+#define UNUSED(name)
+
+#define ALWAYS_INLINE           [[gnu::always_inline]] inline
+#define NEVER_INLINE            [[gnu::noinline]]
 
 /* platform support ***********************************************************/
 
@@ -151,11 +160,16 @@
 	/* For a signal to be *in* the mask means that the signal is
 	 * *blocked*.  */
 
+	#define _CR_SIG_SENTINEL SIGURG
+	#if CONFIG_COROUTINE_GDB
+	#define _CR_SIG_GDB      SIGWINCH
+	#endif
+
 	bool cr_is_in_intrhandler(void) {
 		sigset_t cur_mask;
 		sigfillset(&cur_mask);
 		sigprocmask(0, NULL, &cur_mask);
-		if (sigismember(&cur_mask, SIGHUP))
+		if (sigismember(&cur_mask, _CR_SIG_SENTINEL))
 			/* Interrupts are disabled, so we cannot be in
 			 * an interrupt handler.  */
 			return false;
@@ -169,7 +183,7 @@
 		sigset_t cur_mask;
 		sigfillset(&cur_mask);
 		sigprocmask(0, NULL, &cur_mask);
-		return !sigismember(&cur_mask, SIGHUP);
+		return !sigismember(&cur_mask, _CR_SIG_SENTINEL);
 	}
 
 	static inline void cr_plat_wait_for_interrupt(void) {
@@ -187,7 +201,7 @@
 		sigset_t all, old;
 		sigfillset(&all);
 		sigprocmask(SIG_SETMASK, &all, &old);
-		return !sigismember(&old, SIGHUP);
+		return !sigismember(&old, _CR_SIG_SENTINEL);
 	}
 	void _cr_plat_enable_interrupts(void) {
 		assert(!cr_is_in_intrhandler());
@@ -196,6 +210,19 @@
 		sigemptyset(&zero);
 		sigprocmask(SIG_SETMASK, &zero, NULL);
 	}
+	#if CONFIG_COROUTINE_GDB
+	static void _cr_gdb_intrhandler(int UNUSED(sig)) {}
+	#endif
+	static void cr_plat_init(void) {
+	#if CONFIG_COROUTINE_GDB
+		int r;
+		struct sigaction action = {
+			.sa_handler = _cr_gdb_intrhandler,
+		};
+		r = sigaction(_CR_SIG_GDB, &action, NULL);
+		assert(r == 0);
+	#endif
+	}
 #elif __ARM_ARCH_6M__ && __ARM_EABI__
 	bool cr_is_in_intrhandler(void) {
 		uint32_t isr_number;
@@ -233,6 +260,7 @@
 		assert(!_cr_plat_are_interrupts_enabled());
 		asm volatile ("cpsie i");
 	}
+	static void cr_plat_init(void) {}
 #else
 	#error unsupported platform (not __unix__, not __ARM_ARCH_6M__ && __ARM_EABI__)
 #endif
@@ -318,18 +346,14 @@
 		uintptr_t                      sp;
 	#endif
 	} cr_plat_jmp_buf;
-	#if CONIG_COROUTINE_GDB
-	NEVER_INLINE
-	#endif
 	static void _cr_plat_setjmp_pre(cr_plat_jmp_buf *env [[gnu::unused]]) {
-	#if CONIG_COROUTINE_GDB
-		/* Prevent the call from being optimized away. */
-		asm ("");
-	#endif
 	#if CONFIG_COROUTINE_MEASURE_STACK
 		env->sp = cr_plat_get_sp();
 	#endif
 	}
+	#if CONFIG_COROUTINE_MEASURE_STACK
+	static uintptr_t cr_plat_setjmp_get_sp(cr_plat_jmp_buf *env) { return env->sp; }
+	#endif
 	/* cr_plat_setjmp *NEEDS* to be a preprocessor macro rather
 	 * than a real function, because [[gnu::returns_twice]]
 	 * doesn't work.
@@ -355,13 +379,6 @@
 }
 #endif
 
-/* preprocessor macros ********************************************************/
-
-/** Return `n` rounded up to the nearest multiple of `d` */
-#define ROUND_UP(n, d)          ( ( ((n)+(d)-1) / (d) ) * (d) )
-#define ARRAY_LEN(arr)          (sizeof(arr)/sizeof((arr)[0]))
-#define NEXT_POWER_OF_2(x)      ((1ULL)<<((sizeof(unsigned long long)*8)-__builtin_clzll(x)))
-
 /* types **********************************************************************/
 
 enum coroutine_state {
@@ -410,8 +427,12 @@ static const uint8_t stack_pattern[] = {
 
 /* global variables ***********************************************************/
 
+static bool            coroutine_initialized = false;
 static cr_plat_jmp_buf coroutine_add_env;
 static cr_plat_jmp_buf coroutine_main_env;
+#if CONFIG_COROUTINE_GDB
+static cr_plat_jmp_buf coroutine_gdb_env;
+#endif
 
 /*
  * Invariants (and non-invariants):
@@ -466,6 +487,28 @@ static inline cid_t coroutine_ringbuf_pop(void) {
 	return coroutine_ringbuf.buf[coroutine_ringbuf.tail++ % ARRAY_LEN(coroutine_ringbuf.buf)];
 }
 
+#if CONFIG_COROUTINE_GDB
+NEVER_INLINE void cr_gdb_breakpoint(void) {
+	/* Prevent the call from being optimized away. */
+	asm ("");
+}
+NEVER_INLINE void cr_gdb_readjmp(cr_plat_jmp_buf *env) {
+	if (!cr_plat_setjmp(&coroutine_gdb_env))
+		cr_plat_longjmp(env, 2);
+}
+#define cr_setjmp(env) ({                                               \
+			int val = cr_plat_setjmp(env);                  \
+			if (val == 2) {                                 \
+				cr_gdb_breakpoint();                    \
+				cr_plat_longjmp(&coroutine_gdb_env, 1); \
+			}                                               \
+			val;                                            \
+		})
+#else
+#define cr_setjmp(env)  cr_plat_setjmp(env)
+#endif
+#define cr_longjmp(env) cr_plat_longjmp(env, 1)
+
 static inline void assert_cid(cid_t cid) {
 	assert(cid > 0);
 	assert(cid <= CONFIG_COROUTINE_NUM);
@@ -503,6 +546,11 @@ cid_t coroutine_add_with_stack_size(size_t stack_size,
 	debugf("coroutine_add_with_stack_size(%zu, \"%s\", %p, %p)...",
 	       stack_size, name, fn, args);
 
+	if (!coroutine_initialized) {
+		cr_plat_init();
+		coroutine_initialized = true;
+	}
+
 	cid_t child;
 	{
 		size_t base = last_created;
@@ -524,8 +572,10 @@ cid_t coroutine_add_with_stack_size(size_t stack_size,
 		memset(coroutine_table[child-1].name, 0, sizeof(coroutine_table[child-1].name));
 
 	coroutine_table[child-1].stack_size = stack_size;
+	infof("allocing \"%s\" stack with size %zu", name, stack_size);
 	coroutine_table[child-1].stack =
 		aligned_alloc(CR_PLAT_STACK_ALIGNMENT, stack_size);
+	infof("...done");
 #if CONFIG_COROUTINE_MEASURE_STACK || CONFIG_COROUTINE_PROTECT_STACK
 	for (size_t i = 0; i < stack_size; i++)
 		((uint8_t *)coroutine_table[child-1].stack)[i] =
@@ -540,7 +590,7 @@ cid_t coroutine_add_with_stack_size(size_t stack_size,
 	coroutine_running = child;
 	coroutine_table[child-1].state = CR_INITIALIZING;
 	coroutine_cnt++;
-	if (!cr_plat_setjmp(&coroutine_add_env)) { /* point=a */
+	if (!cr_setjmp(&coroutine_add_env)) { /* point=a */
 		void *stack_base = coroutine_table[child-1].stack
 #if CR_PLAT_STACK_GROWS_DOWNWARD
 			+ stack_size
@@ -577,6 +627,10 @@ cid_t coroutine_add(const char *name, cr_fn_t fn, void *args) {
 
 void coroutine_main(void) {
 	debugf("coroutine_main()");
+	if (!coroutine_initialized) {
+		cr_plat_init();
+		coroutine_initialized = true;
+	}
 	bool saved = cr_save_and_disable_interrupts();
 	assert(saved);
 	assert(!cr_is_in_intrhandler());
@@ -589,10 +643,10 @@ void coroutine_main(void) {
 			cr_plat_wait_for_interrupt();
 		}
 
-		if (!cr_plat_setjmp(&coroutine_main_env)) { /* point=b */
+		if (!cr_setjmp(&coroutine_main_env)) { /* point=b */
 			coroutine_running = next;
 			coroutine_table[coroutine_running-1].state = CR_RUNNING;
-			cr_plat_longjmp(&coroutine_table[coroutine_running-1].env, 1); /* jump to point=c */
+			cr_longjmp(&coroutine_table[coroutine_running-1].env); /* jump to point=c */
 		}
 		/* This is where we jump to from cr_exit(), and from
 		 * nowhere else.  */
@@ -616,8 +670,8 @@ void cr_begin(void) {
 	bool saved = cr_save_and_disable_interrupts();
 	coroutine_table[coroutine_running-1].state = CR_RUNNABLE;
 	coroutine_ringbuf_push(coroutine_running);
-	if (!cr_plat_setjmp(&coroutine_table[coroutine_running-1].env)) /* point=c1 */
-		cr_plat_longjmp(&coroutine_add_env, 1); /* jump to point=a */
+	if (!cr_setjmp(&coroutine_table[coroutine_running-1].env)) /* point=c1 */
+		cr_longjmp(&coroutine_add_env); /* jump to point=a */
 	cr_restore_interrupts(saved);
 }
 
@@ -634,10 +688,10 @@ static inline void _cr_yield() {
 		return;
 	}
 
-	if (!cr_plat_setjmp(&coroutine_table[coroutine_running-1].env)) { /* point=c2 */
+	if (!cr_setjmp(&coroutine_table[coroutine_running-1].env)) { /* point=c2 */
 		coroutine_running = next;
 		coroutine_table[coroutine_running-1].state = CR_RUNNING;
-		cr_plat_longjmp(&coroutine_table[coroutine_running-1].env, 1); /* jump to point=c */
+		cr_longjmp(&coroutine_table[coroutine_running-1].env); /* jump to point=c */
 	}
 }
 
@@ -671,7 +725,7 @@ void cr_pause_and_yield(void) {
 
 	(void)cr_save_and_disable_interrupts();
 	coroutine_table[coroutine_running-1].state = CR_NONE;
-	cr_plat_longjmp(&coroutine_main_env, 1); /* jump to point=b */
+	cr_longjmp(&coroutine_main_env); /* jump to point=b */
 }
 
 static void _cr_unpause(cid_t cid) {
@@ -737,9 +791,9 @@ void cr_cid_info(cid_t cid, struct cr_cid_info *ret) {
 	if (cid == coroutine_running)
 		sp = cr_plat_get_sp();
 	else if (coroutine_table[cid-1].state == CR_RUNNING)
-		sp = coroutine_add_env.sp;
+		sp = cr_plat_setjmp_get_sp(&coroutine_add_env);
 	else
-		sp = coroutine_table[cid-1].env.sp;
+		sp = cr_plat_setjmp_get_sp(&coroutine_table[cid-1].env);
 	assert(sp);
 	uintptr_t sb = (uintptr_t)coroutine_table[cid-1].stack;
 #if CR_PLAT_STACK_GROWS_DOWNWARD
diff --git a/libcr_ipc/include/libcr_ipc/sema.h b/libcr_ipc/include/libcr_ipc/sema.h
index 157c196..db840fe 100644
--- a/libcr_ipc/include/libcr_ipc/sema.h
+++ b/libcr_ipc/include/libcr_ipc/sema.h
@@ -39,7 +39,6 @@ static inline void cr_sema_signal(cr_sema_t *sema) {
 	bool saved = cr_save_and_disable_interrupts();
 	sema->cnt++;
 	if (sema->waiters.front) {
-		sema->cnt--;
 		cr_unpause(
 			_cr_ipc_sll_node_cast(struct _cr_sema_waiter, sema->waiters.front)->cid);
 		_cr_ipc_sll_pop_from_front(&sema->waiters);
@@ -57,7 +56,6 @@ static inline void cr_sema_signal_from_intrhandler(cr_sema_t *sema)  {
 
 	sema->cnt++;
 	if (sema->waiters.front) {
-		sema->cnt--;
 		cr_unpause_from_intrhandler(
 			_cr_ipc_sll_node_cast(struct _cr_sema_waiter, sema->waiters.front)->cid);
 		_cr_ipc_sll_pop_from_front(&sema->waiters);
@@ -75,15 +73,15 @@ static inline void cr_sema_wait(cr_sema_t *sema) {
 	assert(sema);
 
 	bool saved = cr_save_and_disable_interrupts();
-	if (sema->cnt) { /* non-blocking */
-		sema->cnt--;
-	} else { /* blocking */
+	if (!sema->cnt) {
 		struct _cr_sema_waiter self = {
 			.cid    = cr_getcid(),
 		};
 		_cr_ipc_sll_push_to_rear(&sema->waiters, &self);
 		cr_pause_and_yield();
 	}
+	assert(sema->cnt);
+	sema->cnt--;
 	cr_restore_interrupts(saved);
 }
 
diff --git a/libdhcp/dhcp_client.c b/libdhcp/dhcp_client.c
index f526190..ea6ed28 100644
--- a/libdhcp/dhcp_client.c
+++ b/libdhcp/dhcp_client.c
@@ -167,6 +167,18 @@ struct dhcp_client {
 
 };
 
+static const char *state_strs[] = {
+	[STATE_INIT]        = "INIT",
+	[STATE_SELECTING]   = "SELECTING",
+	[STATE_REQUESTING]  = "REQUESTING",
+	[STATE_BOUND]       = "BOUND",
+	[STATE_RENEWING]    = "RENEWING",
+	[STATE_REBINDING]   = "REBINDING",
+
+	[STATE_INIT_REBOOT] = "INIT_REBOOT",
+	[STATE_REBOOTING]   = "REBOOTING",
+};
+
 /**
  * For convenience in switch blocks, a list of the states that, when
  * msgtyp==DHCP_MSGTYP_REQUEST, dhcp_client_send() has assert()ed the state is
@@ -449,6 +461,7 @@ static bool dhcp_client_send(struct dhcp_client *client, uint8_t msgtyp, const c
 	/**********************************************************************\
 	 * Send                                                               *
 	\**********************************************************************/
+	debugf("state %s: sending DHCP %s", state_strs[client->state], dhcp_msgtyp_str(msgtyp));
 	ssize_t r = VCALL(client->sock, sendto, scratch_msg, DHCP_MSG_BASE_SIZE + optlen,
 	                  client_broadcasts ? net_ip4_addr_broadcast : client->lease_server_id, DHCP_PORT_SERVER);
 	if (r < 0) {
@@ -692,6 +705,7 @@ static ssize_t dhcp_client_recv(struct dhcp_client *client, struct dhcp_recv_msg
 static bool dhcp_check_conflict(implements_net_packet_conn *sock, struct net_ip4_addr addr) {
 	assert(sock);
 	ssize_t v = VCALL(sock, sendto, "CHECK_IP_CONFLICT", 17, addr, 5000);
+	debugf("check_ip_conflict => %zd", v);
 	return v != -NET_EARP_TIMEOUT;
 }
 
@@ -726,12 +740,17 @@ static void dhcp_client_take_lease(struct dhcp_client *client, struct dhcp_recv_
 	client->lease_time_ns_t2  = (dur_ns_t2  == DHCP_INFINITY * NS_PER_S) ? 0 : client->time_ns_init + dur_ns_t2;
 	client->lease_time_ns_end = (dur_ns_end == DHCP_INFINITY * NS_PER_S) ? 0 : client->time_ns_init + dur_ns_end;
 
-	if (ifup)
+	if (ifup) {
+		infof("applying configuration to "PRI_net_eth_addr, ARG_net_eth_addr(client->self_eth_addr));
+		infof(":: addr         = "PRI_net_ip4_addr, ARG_net_ip4_addr(client->lease_client_addr));
+		infof(":: gateway_addr = "PRI_net_ip4_addr, ARG_net_ip4_addr(client->lease_auxdata.gateway_addr));
+		infof(":: subnet_mask  = "PRI_net_ip4_addr, ARG_net_ip4_addr(client->lease_auxdata.subnet_mask));
 		VCALL(client->iface, ifup, (struct net_iface_config){
 				.addr         = client->lease_client_addr,
 				.gateway_addr = client->lease_auxdata.gateway_addr,
 				.subnet_mask  = client->lease_auxdata.subnet_mask,
 			});
+	}
 }
 
 static void dhcp_client_setstate(struct dhcp_client *client,
@@ -749,6 +768,7 @@ static void dhcp_client_setstate(struct dhcp_client *client,
 
 	/* State transition diagram: https://datatracker.ietf.org/doc/html/rfc2131#page-35 */
 	for (;;) {
+		debugf("loop: state=%s", state_strs[client->state]);
 		switch (client->state) {
 		case STATE_INIT:
 			client->xid = rand_uint63n(UINT32_MAX);
@@ -787,6 +807,8 @@ static void dhcp_client_setstate(struct dhcp_client *client,
 					break;
 				case DHCP_MSGTYP_ACK:
 					if (dhcp_check_conflict(client->sock, client->lease_client_addr)) {
+						debugf("IP "PRI_net_ip4_addr" is already in use",
+						       ARG_net_ip4_addr(client->lease_client_addr));
 						dhcp_client_setstate(client, STATE_INIT, DHCP_MSGTYP_DECLINE, "IP is already in use", scratch_msg);
 					} else {
 						dhcp_client_take_lease(client, scratch_msg, true);
diff --git a/libdhcp/dhcp_common.h b/libdhcp/dhcp_common.h
index b265df3..5b51ce2 100644
--- a/libdhcp/dhcp_common.h
+++ b/libdhcp/dhcp_common.h
@@ -68,6 +68,7 @@
 #define _LIBDHCP_DHCP_COMMON_H_
 
 #include <libmisc/endian.h>
+#include <libmisc/log.h> /* for const_byte_str() */
 
 /* Config *********************************************************************/
 
@@ -302,4 +303,18 @@ static inline bool dhcp_opt_length_is_valid(uint8_t opt, uint16_t len) {
 #define DHCP_MSGTYP_RELEASE             ((uint8_t)  7) /* RFC2132, client->server */
 #define DHCP_MSGTYP_INFORM              ((uint8_t)  8) /* RFC2132, client->server */
 
+static const char *dhcp_msgtyp_str(uint8_t typ) {
+	switch (typ) {
+	case DHCP_MSGTYP_DISCOVER: return "DHCP_MSGTYP_DISCOVER";
+	case DHCP_MSGTYP_OFFER:    return "DHCP_MSGTYP_OFFER";
+	case DHCP_MSGTYP_REQUEST:  return "DHCP_MSGTYP_REQUEST";
+	case DHCP_MSGTYP_DECLINE:  return "DHCP_MSGTYP_DECLINE";
+	case DHCP_MSGTYP_ACK:      return "DHCP_MSGTYP_ACK";
+	case DHCP_MSGTYP_NAK:      return "DHCP_MSGTYP_NAK";
+	case DHCP_MSGTYP_RELEASE:  return "DHCP_MSGTYP_RELEASE";
+	case DHCP_MSGTYP_INFORM:   return "DHCP_MSGTYP_INFORM";
+	default:                   return const_byte_str(typ);
+	}
+}
+
 #endif /* _LIBDHCP_DHCP_COMMON_H_ */
diff --git a/libhw/w5500.c b/libhw/w5500.c
index c1607f1..e675ae9 100644
--- a/libhw/w5500.c
+++ b/libhw/w5500.c
@@ -67,6 +67,8 @@
  * SPDX-License-Identifier: MIT
  */
 
+#include <inttypes.h> /* for PRIu{n} */
+
 /* TODO: Write a <libhw/generic/gpio.h> to avoid w5500.c being
  * pico-sdk-specific.  */
 #include <hardware/gpio.h> /* pico-sdk:hardware_gpio */
@@ -77,7 +79,7 @@
 #include <libhw/generic/alarmclock.h> /* for sleep_*() */
 
 #define LOG_NAME W5500
-#include <libmisc/log.h> /* for errorf() */
+#include <libmisc/log.h> /* for errorf(), debugf(), const_byte_str() */
 
 #define IMPLEMENTATION_FOR_LIBHW_W5500_H YES
 #include <libhw/w5500.h>
@@ -88,26 +90,43 @@
 
 #include "config.h"
 
-/* These are the default values of the Linux kernel's
- * net.ipv4.ip_local_port_range, so I figure they're probably good
- * values to use.  */
 #ifndef CONFIG_W5500_LOCAL_PORT_MIN
 	#error config.h must define CONFIG_W5500_LOCAL_PORT_MIN
 #endif
-
 #ifndef CONFIG_W5500_LOCAL_PORT_MAX
 	#error config.h must define CONFIG_W5500_LOCAL_PORT_MAX
 #endif
-
 #ifndef CONFIG_W5500_NUM
 	#error config.h must define CONFIG_W5500_NUM
 #endif
+#ifndef CONFIG_W5500_DEBUG
+	#error config.h must define CONFIG_W5500_DEBUG
+#endif
 
 /* C language *****************************************************************/
 
 #define UNUSED(name)
 #define ARRAY_LEN(ary) (sizeof(ary)/sizeof((ary)[0]))
 
+static const char *w5500_state_str(uint8_t state) {
+	switch (state) {
+	case STATE_CLOSED:          return "STATE_CLOSED";
+	case STATE_TCP_INIT:        return "STATE_TCP_INIT";
+	case STATE_TCP_LISTEN:      return "STATE_TCP_LISTEN";
+	case STATE_TCP_SYNSENT:     return "STATE_TCP_SYNSENT";
+	case STATE_TCP_SYNRECV:     return "STATE_TCP_SYNRECV";
+	case STATE_TCP_ESTABLISHED: return "STATE_TCP_ESTABLISHED";
+	case STATE_TCP_FIN_WAIT:    return "STATE_TCP_FIN_WAIT";
+	case STATE_TCP_CLOSING:     return "STATE_TCP_CLOSING";
+	case STATE_TCP_TIME_WAIT:   return "STATE_TCP_TIME_WAIT";
+	case STATE_TCP_CLOSE_WAIT:  return "STATE_TCP_CLOSE_WAIT";
+	case STATE_TCP_LAST_ACK:    return "STATE_TCP_LAST_ACK";
+	case STATE_UDP:             return "STATE_UDP";
+	case STATE_MACRAW:          return "STATE_MACRAW";
+	default:                    return const_byte_str(state);
+	}
+}
+
 /* vtables ********************************************************************/
 
 /* iface */
@@ -207,7 +226,10 @@ static COROUTINE w5500_irq_cr(void *_chip) {
 
 	for (;;) {
 		while (!gpio_get(chip->pin_intr)) {
-			if (w5500ll_read_common_reg(chip->spidev, chip_interrupt))
+			debugf("w5500_irq_cr(): gpio low");
+
+			uint8_t chipintr = w5500ll_read_common_reg(chip->spidev, chip_interrupt);
+			if (chipintr)
 				w5500ll_write_common_reg(chip->spidev, chip_interrupt, 0xFF);
 
 			uint8_t sockmask = w5500ll_read_common_reg(chip->spidev, sock_interrupt);
@@ -226,12 +248,18 @@ static COROUTINE w5500_irq_cr(void *_chip) {
 						send_bits   = sockintr & (SOCKINTR_SEND_OK|SOCKINTR_SEND_TIMEOUT),
 						recv_bits   = sockintr & (SOCKINTR_RECV_DAT|SOCKINTR_RECV_FIN);
 
-					if (listen_bits)
+					if (listen_bits) {
+						debugf("w5500_irq_cr(): signal sock[%"PRIu8"]->listen_sema", socknum);
 						cr_sema_signal(&socket->listen_sema);
-					if (recv_bits)
+					}
+					if (recv_bits) {
+						debugf("w5500_irq_cr(): signal sock[%"PRIu8"]->read_sema", socknum);
 						cr_sema_signal(&socket->read_sema);
-					if (send_bits)
+					}
+					if (send_bits) {
+						debugf("w5500_irq_cr(): signal sock[%"PRIu8"]->write_ch", socknum);
 						_w5500_sockintr_ch_send(&socket->write_ch, send_bits);
+					}
 					break;
 				}
 
@@ -239,6 +267,7 @@ static COROUTINE w5500_irq_cr(void *_chip) {
 			}
 		}
 		cr_sema_wait(&chip->intr);
+		debugf("w5500_irq_cr(): sema signalled");
 	}
 
 	cr_end();
@@ -296,6 +325,7 @@ static inline void w5500_socket_close(struct _w5500_socket *socket) {
 static struct w5500 *w5500_chips[CONFIG_W5500_NUM] = {0};
 
 static void w5500_intrhandler(uint gpio, uint32_t UNUSED(event_mask)) {
+	debugf("w5500_intrhandler(): interrupt on pin %u", gpio);
 	for (size_t i = 0; i < ARRAY_LEN(w5500_chips); i++)
 		if (w5500_chips[i] && w5500_chips[i]->pin_intr == gpio)
 			cr_sema_signal_from_intrhandler(&w5500_chips[i]->intr);
@@ -328,8 +358,8 @@ void _w5500_init(struct w5500 *chip,
 			.socknum = i,
 			/* mutable */
 			.next_free = (i + 1 < 8) ? &chip->sockets[i+1] : NULL,
-			/* the rest of the mutable members get
-			 * initialized to the zero values */
+			/* The rest of the mutable members get
+			 * initialized to the zero values.  */
 		};
 	}
 
@@ -361,7 +391,7 @@ void _w5500_init(struct w5500 *chip,
 
 /* chip methods ***************************************************************/
 
-static inline void w5500_post_reset(struct w5500 *chip) {
+static void w5500_post_reset(struct w5500 *chip) {
 	/* The W5500 does not have a built-in MAC address, we must
 	 * provide one.  */
 	w5500ll_write_common_reg(chip->spidev, eth_addr, chip->hwaddr);
@@ -426,7 +456,7 @@ static struct net_eth_addr w5500_if_hwaddr(implements_net_iface *_chip) {
 	return chip->hwaddr;
 }
 
-static void w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg) {
+static void _w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg) {
 	struct w5500 *chip = VCALL_SELF(struct w5500, implements_net_iface, _chip);
 	assert(chip);
 
@@ -435,8 +465,17 @@ static void w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg
 	w5500ll_write_common_reg(chip->spidev, ip_addr, cfg.addr);
 }
 
+static void w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg) {
+	debugf("if_up()");
+	debugf(":: addr         = "PRI_net_ip4_addr, ARG_net_ip4_addr(cfg.addr));
+	debugf(":: gateway_addr = "PRI_net_ip4_addr, ARG_net_ip4_addr(cfg.gateway_addr));
+	debugf(":: subnet_mask  = "PRI_net_ip4_addr, ARG_net_ip4_addr(cfg.subnet_mask));
+	_w5500_if_up(_chip, cfg);
+}
+
 static void w5500_if_down(implements_net_iface *_chip) {
-	w5500_if_up(_chip, (struct net_iface_config){0});
+	debugf("if_down()");
+	_w5500_if_up(_chip, (struct net_iface_config){0});
 }
 
 static implements_net_stream_listener *w5500_if_tcp_listen(implements_net_iface *_chip, uint16_t local_port) {
@@ -444,8 +483,11 @@ static implements_net_stream_listener *w5500_if_tcp_listen(implements_net_iface
 	assert(chip);
 
 	struct _w5500_socket *sock = w5500_alloc_socket(chip);
-	if (!sock)
+	if (!sock) {
+		debugf("tcp_listen() => no sock");
 		return NULL;
+	}
+	debugf("tcp_listen() => sock[%"PRIu8"]", sock->socknum);
 
 	if (!local_port)
 		local_port = w5500_alloc_local_port(chip);
@@ -468,9 +510,12 @@ static implements_net_stream_conn *w5500_if_tcp_dial(implements_net_iface *_chip
 	assert(port);
 
 	struct _w5500_socket *socket = w5500_alloc_socket(chip);
-	if (!socket)
+	if (!socket) {
+		debugf("tcp_dial() => no sock");
 		return NULL;
+	}
 	uint8_t socknum = socket->socknum;
+	debugf("tcp_dial() => sock[%"PRIu8"]", socknum);
 
 	uint16_t local_port = w5500_alloc_local_port(chip);
 
@@ -495,6 +540,7 @@ static implements_net_stream_conn *w5500_if_tcp_dial(implements_net_iface *_chip
 	w5500_socket_cmd(socket, CMD_CONNECT);
 	for (;;) {
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
+		debugf("tcp_dial(): state=%s", w5500_state_str(state));
 		switch (state) {
 		case STATE_TCP_SYNSENT:
 			cr_yield();
@@ -507,14 +553,17 @@ static implements_net_stream_conn *w5500_if_tcp_dial(implements_net_iface *_chip
 	}
 }
 
-implements_net_packet_conn *w5500_if_udp_conn(implements_net_iface *_chip, uint16_t local_port) {
+static implements_net_packet_conn *w5500_if_udp_conn(implements_net_iface *_chip, uint16_t local_port) {
 	struct w5500 *chip = VCALL_SELF(struct w5500, implements_net_iface, _chip);
 	assert(chip);
 
 	struct _w5500_socket *socket = w5500_alloc_socket(chip);
-	if (!socket)
+	if (!socket) {
+		debugf("udp_conn() => no sock");
 		return NULL;
+	}
 	uint8_t socknum = socket->socknum;
+	debugf("udp_conn() => sock[%"PRIu8"]", socknum);
 
 	if (!local_port)
 		local_port = w5500_alloc_local_port(chip);
@@ -541,8 +590,10 @@ static implements_net_stream_conn *w5500_tcplist_accept(implements_net_stream_li
 	ASSERT_SELF(stream_listener, TCP);
 
  restart:
-	if (!socket->list_open)
+	if (!socket->list_open) {
+		debugf("tcp_listener.accept() => already closed");
 		return NULL;
+	}
 
 	/* Mimics socket.c:socket().  */
 	w5500_socket_close(socket);
@@ -556,6 +607,7 @@ static implements_net_stream_conn *w5500_tcplist_accept(implements_net_stream_li
 	w5500_socket_cmd(socket, CMD_LISTEN);
 	for (;;) {
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
+		debugf("tcp_listener.accept() => state=%s", w5500_state_str(state));
 		switch (state) {
 		case STATE_TCP_LISTEN:
 		case STATE_TCP_SYNRECV:
@@ -574,6 +626,7 @@ static implements_net_stream_conn *w5500_tcplist_accept(implements_net_stream_li
 }
 
 static int w5500_tcplist_close(implements_net_stream_listener *_socket) {
+	debugf("tcp_listener.close()");
 	ASSERT_SELF(stream_listener, TCP);
 
 	socket->list_open = false;
@@ -584,6 +637,7 @@ static int w5500_tcplist_close(implements_net_stream_listener *_socket) {
 /* tcp_conn methods ***********************************************************/
 
 static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, size_t count) {
+	debugf("tcp_conn.write(%zu)", count);
 	ASSERT_SELF(stream_conn, TCP);
 	assert(buf);
 	assert(count);
@@ -610,11 +664,15 @@ static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, s
 
 	size_t done = 0;
 	while (done < count) {
-		if (!socket->write_open)
+		if (!socket->write_open) {
+			debugf(" => soft closed");
 			return -NET_ECLOSED;
+		}
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
-		if (state != STATE_TCP_ESTABLISHED && state != STATE_TCP_CLOSE_WAIT)
+		if (state != STATE_TCP_ESTABLISHED && state != STATE_TCP_CLOSE_WAIT) {
+			debugf(" => hard closed");
 			return -NET_ECLOSED;
+		}
 
 		uint16_t freesize = uint16be_unmarshal(w5500ll_read_sock_reg(chip->spidev, socknum, tx_free_size));
 		if (freesize < count-done && freesize < min_free_space) {
@@ -634,9 +692,11 @@ static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, s
 		w5500_socket_cmd(socket, CMD_SEND);
 		switch (_w5500_sockintr_ch_recv(&socket->write_ch)) {
 		case SOCKINTR_SEND_OK:
+			debugf(" => sent %zu", freesize);
 			done += freesize;
 			break;
 		case SOCKINTR_SEND_TIMEOUT:
+			debugf(" => ACK timeout");
 			return -NET_EACK_TIMEOUT;
 		case SOCKINTR_SEND_OK|SOCKINTR_SEND_TIMEOUT:
 			assert_notreached("send both OK and timed out?");
@@ -644,10 +704,12 @@ static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, s
 			assert_notreached("invalid write_ch bits");
 		}
 	}
+	debugf(" => send finished");
 	return done;
 }
 
 static void w5500_tcp_set_read_deadline(implements_net_stream_conn *_socket, uint64_t ns) {
+	debugf("tcp_conn.set_read_deadline(%"PRIu64")", ns);
 	ASSERT_SELF(stream_conn, TCP);
 	socket->read_deadline_ns = ns;
 }
@@ -658,6 +720,7 @@ static void w5500_tcp_alarm_handler(void *_arg) {
 }
 
 static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, size_t count) {
+	debugf("tcp_conn.read()");
 	ASSERT_SELF(stream_conn, TCP);
 	assert(buf);
 	assert(count);
@@ -674,10 +737,12 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 	for (;;) {
 		if (!socket->read_open) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => soft closed");
 			return -NET_ECLOSED;
 		}
 		if (socket->read_deadline_ns && socket->read_deadline_ns <= VCALL(bootclock, get_time_ns)) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => recv timeout");
 			return -NET_ERECV_TIMEOUT;
 		}
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
@@ -688,6 +753,7 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 			break; /* OK */
 		default:
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => hard closed");
 			return -NET_ECLOSED;
 		}
 
@@ -697,12 +763,14 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 			break;
 		if (state == STATE_TCP_CLOSE_WAIT) {
 			VCALL(bootclock, del_trigger, &trigger);
-			return 0; /* EOF */
+			debugf(" => EOF");
+			return 0;
 		}
 
 		cr_sema_wait(&socket->read_sema);
 	}
 	assert(avail);
+	debugf(" => received %"PRIu16" bytes", avail);
 	uint16_t ptr = uint16be_unmarshal(w5500ll_read_sock_reg(chip->spidev, socknum, rx_read_pointer));
 	/* Read the data.  */
 	if ((size_t)avail > count)
@@ -717,6 +785,7 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 }
 
 static int w5500_tcp_close(implements_net_stream_conn *_socket, bool rd, bool wr) {
+	debugf("tcp_conn.close(rd=%s, wr=%s)", rd ? "true" : "false", wr ? "true" : "false");
 	ASSERT_SELF(stream_conn, TCP);
 
 	if (rd)
@@ -748,18 +817,23 @@ static int w5500_tcp_close(implements_net_stream_conn *_socket, bool rd, bool wr
 
 static ssize_t w5500_udp_sendto(implements_net_packet_conn *_socket, void *buf, size_t count,
                                 struct net_ip4_addr node, uint16_t port) {
+	debugf("udp_conn.sendto()");
 	ASSERT_SELF(packet_conn, UDP);
 	assert(buf);
 	assert(count);
 
 	uint16_t bufsize = ((uint16_t)w5500ll_read_sock_reg(chip->spidev, socknum, tx_buf_size))*1024;
-	if (count > bufsize)
+	if (count > bufsize) {
+		debugf(" => msg too large");
 		return -NET_EMSGSIZE;
+	}
 
 	for (;;) {
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
-		if (state != STATE_UDP)
+		if (state != STATE_UDP) {
+			debugf(" => closed");
 			return -NET_ECLOSED;
+		}
 
 		uint16_t freesize = uint16be_unmarshal(w5500ll_read_sock_reg(chip->spidev, socknum, tx_free_size));
 		if (freesize >= count)
@@ -782,8 +856,10 @@ static ssize_t w5500_udp_sendto(implements_net_packet_conn *_socket, void *buf,
 
 	switch (_w5500_sockintr_ch_recv(&socket->write_ch)) {
 	case SOCKINTR_SEND_OK:
+		debugf(" => sent");
 		return count;
 	case SOCKINTR_SEND_TIMEOUT:
+		debugf(" => ARP timeout");
 		return -NET_EARP_TIMEOUT;
 	case SOCKINTR_SEND_OK|SOCKINTR_SEND_TIMEOUT:
 		assert_notreached("send both OK and timed out?");
@@ -793,6 +869,7 @@ static ssize_t w5500_udp_sendto(implements_net_packet_conn *_socket, void *buf,
 }
 
 static void w5500_udp_set_read_deadline(implements_net_packet_conn *_socket, uint64_t ns) {
+	debugf("udp_conn.set_read_deadline(%"PRIu64")", ns);
 	ASSERT_SELF(packet_conn, UDP);
 	socket->read_deadline_ns = ns;
 }
@@ -804,6 +881,7 @@ static void w5500_udp_alarm_handler(void *_arg) {
 
 static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf, size_t count,
                                   struct net_ip4_addr *ret_node, uint16_t *ret_port) {
+	debugf("udp_conn.recvfrom()");
 	ASSERT_SELF(packet_conn, UDP);
 	assert(buf);
 	assert(count);
@@ -820,11 +898,13 @@ static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf
 	for (;;) {
 		if (socket->read_deadline_ns && socket->read_deadline_ns <= VCALL(bootclock, get_time_ns)) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => recv timeout");
 			return -NET_ERECV_TIMEOUT;
 		}
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
 		if (state != STATE_UDP) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => hard closed");
 			return -NET_ECLOSED;
 		}
 
@@ -851,6 +931,7 @@ static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf
 	if (ret_port)
 		*ret_port = uint16be_decode(&hdr[4]);
 	uint16_t len = uint16be_decode(&hdr[6]);
+	debugf(" => received %"PRIu16" bytes%s", len, len < avail-8 ? " (plus more messages)" : "");
 	/* Now read the actual data.  */
 	if (count > len)
 		count = len;
@@ -864,6 +945,7 @@ static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf
 }
 
 static int w5500_udp_close(implements_net_packet_conn *_socket) {
+	debugf("udp_conn.close()");
 	ASSERT_SELF(packet_conn, UDP);
 
 	w5500_socket_close(socket);
diff --git a/libhw_generic/include/libhw/generic/net.h b/libhw_generic/include/libhw/generic/net.h
index 150d199..a016d51 100644
--- a/libhw_generic/include/libhw/generic/net.h
+++ b/libhw_generic/include/libhw/generic/net.h
@@ -7,6 +7,7 @@
 #ifndef _LIBHW_GENERIC_NET_H_
 #define _LIBHW_GENERIC_NET_H_
 
+#include <inttypes.h>  /* for PRI{u,x}{n} */
 #include <stdbool.h>   /* for bool */
 #include <stddef.h>    /* for size_t */
 #include <stdint.h>    /* for uint{n}_t} */
@@ -31,10 +32,24 @@ struct net_ip4_addr {
 static const struct net_ip4_addr net_ip4_addr_broadcast = {{255, 255, 255, 255}};
 static const struct net_ip4_addr net_ip4_addr_zero      = {{0, 0, 0, 0}};
 
+#define PRI_net_ip4_addr       "%"PRIu8".%"PRIu8".%"PRIu8".%"PRIu8
+#define ARG_net_ip4_addr(addr) (addr).octets[0], \
+                               (addr).octets[1], \
+                               (addr).octets[2], \
+                               (addr).octets[3]
+
 struct net_eth_addr {
 	unsigned char   octets[6];
 };
 
+#define PRI_net_eth_addr       "%02"PRIx8":%02"PRIx8":%02"PRIx8":%02"PRIx8":%02"PRIx8":%02"PRIx8
+#define ARG_net_eth_addr(addr) (addr).octets[0], \
+                               (addr).octets[1], \
+                               (addr).octets[2], \
+                               (addr).octets[3], \
+                               (addr).octets[4], \
+                               (addr).octets[5]
+
 /* Streams (e.g. TCP) *********************************************************/
 
 struct net_stream_listener_vtable;
diff --git a/libmisc/include/libmisc/log.h b/libmisc/include/libmisc/log.h
index 37da20b..c1e4a05 100644
--- a/libmisc/include/libmisc/log.h
+++ b/libmisc/include/libmisc/log.h
@@ -7,6 +7,8 @@
 #ifndef _LIBMISC_LOG_H_
 #define _LIBMISC_LOG_H_
 
+#include <stdint.h> /* for uint8_t */
+
 #ifndef LOG_NAME
 	#error "each compilation unit that includes <libmisc/log.h> must define LOG_NAME"
 #endif
@@ -28,4 +30,6 @@
 #define debugf(fmt, ...) do { if (_LOG_CAT3(CONFIG_, LOG_NAME, _DEBUG) && !_LOG_NDEBUG) \
                               _log_printf("debug: " _LOG_STR(LOG_NAME) ": " fmt "\n" __VA_OPT__(,) __VA_ARGS__); } while (0)
 
+const char *const_byte_str(uint8_t b);
+
 #endif /* _LIBMISC_LOG_H_ */
diff --git a/libmisc/log.c b/libmisc/log.c
index a1ec10f..9bf5366 100644
--- a/libmisc/log.c
+++ b/libmisc/log.c
@@ -7,6 +7,8 @@
 #include <stdio.h>  /* for vprintf() */
 #include <stdarg.h> /* for va_list, va_start(), va_end() */
 
+#include <libmisc/assert.h>
+
 #define LOG_NAME
 #include <libmisc/log.h>
 
@@ -17,3 +19,267 @@ int _log_printf(const char *format, ...) {
 	va_end(va);
 	return ret;
 }
+
+static const char *byte_strs[] = {
+	"0x00",
+	"0x01",
+	"0x02",
+	"0x03",
+	"0x04",
+	"0x05",
+	"0x06",
+	"0x07",
+	"0x08",
+	"0x09",
+	"0x0A",
+	"0x0B",
+	"0x0C",
+	"0x0D",
+	"0x0E",
+	"0x0F",
+	"0x10",
+	"0x11",
+	"0x12",
+	"0x13",
+	"0x14",
+	"0x15",
+	"0x16",
+	"0x17",
+	"0x18",
+	"0x19",
+	"0x1A",
+	"0x1B",
+	"0x1C",
+	"0x1D",
+	"0x1E",
+	"0x1F",
+	"0x20",
+	"0x21",
+	"0x22",
+	"0x23",
+	"0x24",
+	"0x25",
+	"0x26",
+	"0x27",
+	"0x28",
+	"0x29",
+	"0x2A",
+	"0x2B",
+	"0x2C",
+	"0x2D",
+	"0x2E",
+	"0x2F",
+	"0x30",
+	"0x31",
+	"0x32",
+	"0x33",
+	"0x34",
+	"0x35",
+	"0x36",
+	"0x37",
+	"0x38",
+	"0x39",
+	"0x3A",
+	"0x3B",
+	"0x3C",
+	"0x3D",
+	"0x3E",
+	"0x3F",
+	"0x40",
+	"0x41",
+	"0x42",
+	"0x43",
+	"0x44",
+	"0x45",
+	"0x46",
+	"0x47",
+	"0x48",
+	"0x49",
+	"0x4A",
+	"0x4B",
+	"0x4C",
+	"0x4D",
+	"0x4E",
+	"0x4F",
+	"0x50",
+	"0x51",
+	"0x52",
+	"0x53",
+	"0x54",
+	"0x55",
+	"0x56",
+	"0x57",
+	"0x58",
+	"0x59",
+	"0x5A",
+	"0x5B",
+	"0x5C",
+	"0x5D",
+	"0x5E",
+	"0x5F",
+	"0x60",
+	"0x61",
+	"0x62",
+	"0x63",
+	"0x64",
+	"0x65",
+	"0x66",
+	"0x67",
+	"0x68",
+	"0x69",
+	"0x6A",
+	"0x6B",
+	"0x6C",
+	"0x6D",
+	"0x6E",
+	"0x6F",
+	"0x70",
+	"0x71",
+	"0x72",
+	"0x73",
+	"0x74",
+	"0x75",
+	"0x76",
+	"0x77",
+	"0x78",
+	"0x79",
+	"0x7A",
+	"0x7B",
+	"0x7C",
+	"0x7D",
+	"0x7E",
+	"0x7F",
+	"0x80",
+	"0x81",
+	"0x82",
+	"0x83",
+	"0x84",
+	"0x85",
+	"0x86",
+	"0x87",
+	"0x88",
+	"0x89",
+	"0x8A",
+	"0x8B",
+	"0x8C",
+	"0x8D",
+	"0x8E",
+	"0x8F",
+	"0x90",
+	"0x91",
+	"0x92",
+	"0x93",
+	"0x94",
+	"0x95",
+	"0x96",
+	"0x97",
+	"0x98",
+	"0x99",
+	"0x9A",
+	"0x9B",
+	"0x9C",
+	"0x9D",
+	"0x9E",
+	"0x9F",
+	"0xA0",
+	"0xA1",
+	"0xA2",
+	"0xA3",
+	"0xA4",
+	"0xA5",
+	"0xA6",
+	"0xA7",
+	"0xA8",
+	"0xA9",
+	"0xAA",
+	"0xAB",
+	"0xAC",
+	"0xAD",
+	"0xAE",
+	"0xAF",
+	"0xB0",
+	"0xB1",
+	"0xB2",
+	"0xB3",
+	"0xB4",
+	"0xB5",
+	"0xB6",
+	"0xB7",
+	"0xB8",
+	"0xB9",
+	"0xBA",
+	"0xBB",
+	"0xBC",
+	"0xBD",
+	"0xBE",
+	"0xBF",
+	"0xC0",
+	"0xC1",
+	"0xC2",
+	"0xC3",
+	"0xC4",
+	"0xC5",
+	"0xC6",
+	"0xC7",
+	"0xC8",
+	"0xC9",
+	"0xCA",
+	"0xCB",
+	"0xCC",
+	"0xCD",
+	"0xCE",
+	"0xCF",
+	"0xD0",
+	"0xD1",
+	"0xD2",
+	"0xD3",
+	"0xD4",
+	"0xD5",
+	"0xD6",
+	"0xD7",
+	"0xD8",
+	"0xD9",
+	"0xDA",
+	"0xDB",
+	"0xDC",
+	"0xDD",
+	"0xDE",
+	"0xDF",
+	"0xE0",
+	"0xE1",
+	"0xE2",
+	"0xE3",
+	"0xE4",
+	"0xE5",
+	"0xE6",
+	"0xE7",
+	"0xE8",
+	"0xE9",
+	"0xEA",
+	"0xEB",
+	"0xEC",
+	"0xED",
+	"0xEE",
+	"0xEF",
+	"0xF0",
+	"0xF1",
+	"0xF2",
+	"0xF3",
+	"0xF4",
+	"0xF5",
+	"0xF6",
+	"0xF7",
+	"0xF8",
+	"0xF9",
+	"0xFA",
+	"0xFB",
+	"0xFC",
+	"0xFD",
+	"0xFE",
+	"0xFF",
+};
+static_assert(sizeof(byte_strs)/sizeof(byte_strs[0]) == 0x100);
+
+const char *const_byte_str(uint8_t b) {
+	return byte_strs[b];
+}