DHCPv4+Debug: add RawData method and improve Logging semantics with configured logger instead of default

2026-08-12 19:03:42 +00:00 · 2026-07-25 11:40:34 -03:00
parent 8873b55e5d
commit a9c9b76de7
4 changed files with 332 additions and 3 deletions
@@ -44,6 +44,9 @@ type Frame struct {
 	buf []byte
 }

+// RawData returns the underlying frame buffer.
+func (frm Frame) RawData() []byte { return frm.buf }
+
 // OptionsPayload returns the options portion of the DHCP frame. May be zero lengthed.
 func (frm Frame) OptionsPayload() []byte {
 	return frm.buf[OptionsOffset:]
@@ -0,0 +1,84 @@
+# espradio AP mode: DHCP server never answers DISCOVER
+
+Diagnosis of `espradio.log` (ESP32 running `espradio` AP + `dhcpv4.Server`).
+
+## Symptom
+
+A client (`e4:c7:67:65:0e:46`) broadcasts DHCP DISCOVER every few seconds and is
+never answered. Log shows only `IN` DHCP frames, never an `OUT` OFFER:
+
+```
+21.866 IN  342 Ethernet ... destination=ff:ff:ff:ff:ff:ff ... | IPv4 ... source=0.0.0.0; destination=255.255.255.255 | UDP ... (Source port)=68; (Destination port)=67 | DHCPv4 op=1 ...
+24.318 IN  342 ... (Transaction ID)=0x65be2ff3 ...
+28.589 IN  342 ... (Transaction ID)=0x503e5f09 ...
+36.971 IN  342 ... (Transaction ID)=0x32b12d21 ...
+53.928 IN  342 ... (Transaction ID)=0x7922b680 ...
+```
+
+Retries with fresh XIDs and growing `secs` (0x0001 → 0x0020) = client never got
+an OFFER, i.e. it is standard client backoff, not a malformed reply.
+
+## Cause: espradio side, not lneto
+
+The DISCOVER is destined to `255.255.255.255`. lneto's IPv4 layer drops packets
+not addressed to the stack unless broadcast acceptance is on
+([internet/stack-ip4.go:109-119](internet/stack-ip4.go#L109-L119)):
+
+```go
+if si4.ip4 != ([4]byte{}) && *dst != si4.ip4 {
+	switch {
+	case si4.acceptMulticast && ipv4.IsMulticast(*dst):
+	case si4.acceptBroadcast && ipv4.IsBroadcast(*dst):
+	default:
+		si4.handlers.debug("ip:not-for-us")
+		return lneto.ErrPacketDrop
+	}
+}
+```
+
+`acceptBroadcast` comes only from `xnet.StackConfig.AcceptIPv4Broadcast`
+([x/xnet/stack-async.go:250](x/xnet/stack-async.go#L250)). espradio's
+`NewStack` builds `xnet.StackConfig` (`espstack.go:59`) and **never sets that
+field**, so the flag is false in AP mode too. The DISCOVER dies at the IPv4
+layer; `dhcpv4.Server.Demux` is never reached, so nothing is ever pending and
+`Encapsulate` emits nothing. The Ethernet layer is not the problem — it accepts
+broadcast destinations unconditionally
+([internet/stack-ethernet.go:148](internet/stack-ethernet.go#L148)).
+
+Everything else in espradio's AP setup is correct:
+`RegisterUDP4(&stack.dhcpSrv, [4]byte{}, dhcpv4.DefaultClientPort)` registers
+local port 67 (`Server.LocalPort()`) with remote port 68 and no source-IP filter.
+
+## lneto-side change
+
+None needed beyond tests: `StackConfig.AcceptIPv4Broadcast` already covers this
+and espradio knows it is starting an AP before it builds the stack. Regression
+tests in [x/xnet/xnet_dhcpserver_test.go](x/xnet/xnet_dhcpserver_test.go):
+
+- `TestDHCPServerAPBroadcastOffer` — broadcast DISCOVER through the full
+  Ethernet/IPv4/UDP demux chain; asserts the egress OFFER is unicast to the
+  client MAC (over the gateway MAC the Ethernet layer wrote), src=server address,
+  dst=offered address, ports 67→68, and both checksums valid despite the server
+  writing addresses inside the IPv4 layer's encapsulation.
+- `TestDHCPServerAPRequiresBroadcastAccept` — pins the failure in this log: with
+  the flag off, `IngressEthernet` returns `ErrPacketDrop` and no reply is produced.
+
+Deliberately not retested here: DORA state machine, address allocation and the
+chaddr/ciaddr lookups — `dhcp/dhcpv4`'s own tests own those.
+
+## Fix in espradio
+
+Plumb it through espradio's own `StackConfig` and set it in the `xnet.StackConfig`
+built by `NewStack` (`espstack.go:59`):
+
+```go
+xcfg := xnet.StackConfig{
+	...
+	AcceptIPv4Broadcast: cfg.AcceptIPv4Broadcast,
+}
+```
+
+AP-ness is already known before that call: `netlink/ap.go` reads
+`params.EnableDHCPServer` to size `udpPorts` a few lines above `NewStack`, so it
+can pass `AcceptIPv4Broadcast: params.EnableDHCPServer` there. Same for
+`examples/ap/main-ap.go`, which registers the DHCP server itself.
@@ -69,6 +69,8 @@ type StackAsync struct {

 	ipv6enabled bool
 	stack6      Stack6
+
+	log *slog.Logger
 }

 type StackConfig struct {
@@ -105,6 +107,9 @@ type StackConfig struct {
 	AcceptMulticast bool
 	// Accept broadcast IPv4 packets. Needed for managing access points and DHCPv4 servers.
 	AcceptIPv4Broadcast bool
+	// Logger receives the stack's Debug and DebugErr output. A nil Logger silences
+	// them; the heap allocation probe still runs so allocation bisection keeps working.
+	Logger *slog.Logger
 }

 func (cfg *StackConfig) id() uint16 {
@@ -202,6 +207,7 @@ func (s *StackAsync) Reset(cfg StackConfig) (err error) {
 	defer s.mu.Unlock()
 	s.prng = uint32(cfg.RandSeed)
 	s.hostname = cfg.Hostname
+	s.log = cfg.Logger
 	// Treat last character of hostname as number.
 	id := cfg.id()
 	linkNodes := 2 // ARP and IPv4 nodes
@@ -843,17 +849,29 @@ func addr4(addr [4]byte, ok bool) netip.Addr {
 }

 // Debug prints debugging and heap information.
+//
+// The heap allocation probe runs unconditionally; only the log line is gated on
+// the configured Logger's level. Building the slog.Attr list allocates, so the
+// gate must come first or the allocation happens even when nothing is logged.
 func (s *StackAsync) Debug(msg string) {
-	internal.LogAttrsAndAllocs(msg, slog.Default(), slog.LevelDebug, "stackasync",
+	internal.LogAllocs(msg)
+	if !internal.LogEnabled(s.log, slog.LevelDebug) {
+		return
+	}
+	internal.LogAttrsAndAllocs(msg, s.log, slog.LevelDebug, "stackasync",
 		slog.String("umsg", msg),
 		slog.Uint64("sent", s.stats.TotalSent),
 		slog.Uint64("recv", s.stats.TotalReceived),
 	)
 }

-// DebugErr prints debugging and heap information.
+// DebugErr prints debugging and heap information with [slog.LevelError] level. See [StackAsync.Debug] on gating.
 func (s *StackAsync) DebugErr(msg, err string) {
-	internal.LogAttrsAndAllocs(msg, slog.Default(), slog.LevelError, "stackasync",
+	internal.LogAllocs(msg)
+	if !internal.LogEnabled(s.log, slog.LevelError) {
+		return
+	}
+	internal.LogAttrsAndAllocs(msg, s.log, slog.LevelError, "stackasync",
 		slog.String("umsg", msg),
 		slog.String("err", err),
 		slog.Uint64("sent", s.stats.TotalSent),
@@ -0,0 +1,224 @@
+package xnet
+
+import (
+	"testing"
+
+	"github.com/soypat/lneto"
+	"github.com/soypat/lneto/dhcp/dhcpv4"
+	"github.com/soypat/lneto/ethernet"
+	"github.com/soypat/lneto/ipv4"
+	"github.com/soypat/lneto/udp"
+)
+
+// Reproduces the AP-mode DHCP server failure observed on hardware (espradio.log):
+// clients broadcast DISCOVER to 255.255.255.255 every few seconds and the AP never
+// answers. Only the stack-level behaviour is tested here; the DORA state machine and
+// address allocation are covered by the dhcpv4 package tests. What those cannot see
+// is a packet that never reaches dhcpv4.Server at all, plus the layer interactions
+// on the way out (Ethernet writes gwmac and IPv4 writes the source address and both
+// checksums around the server's own writes to those same fields).
+
+const (
+	apEthSize  = 14
+	apIPv4Size = 20
+	apUDPSize  = 8
+	apSubnetBi = 24
+)
+
+var (
+	apAddr    = [4]byte{192, 168, 4, 1}
+	apMAC     = [6]byte{0x02, 0x00, 0xde, 0xad, 0xbe, 0xef}
+	apGWMAC   = [6]byte{0x00, 0x00, 0x00, 0x00, 0x00, 0x01} // Dummy AP-mode gateway MAC, as espradio sets.
+	dhcpClMAC = [6]byte{0xe4, 0xc7, 0x67, 0x65, 0x0e, 0x46} // MAC from espradio.log.
+	macBcast  = [6]byte{0xff, 0xff, 0xff, 0xff, 0xff, 0xff}
+	apBufSize = int(ethernet.MaxMTU) + ethernet.MaxOverheadSize
+)
+
+// newAPStack returns a StackAsync configured as an access point with a dhcpv4.Server
+// registered on the DHCP server port.
+func newAPStack(t testing.TB, acceptBroadcast bool) *StackAsync {
+	t.Helper()
+	s := new(StackAsync)
+	err := s.Reset(StackConfig{
+		Hostname:            "apstack",
+		RandSeed:            42,
+		StaticAddress4:      apAddr,
+		HardwareAddress:     apMAC,
+		MTU:                 ethernet.MaxMTU,
+		MaxActiveUDPPorts:   2,
+		AcceptIPv4Broadcast: acceptBroadcast,
+	})
+	if err != nil {
+		t.Fatal(err)
+	}
+	s.SetSubnet4(apAddr, apSubnetBi)
+	// No upstream gateway in AP mode; a non-broadcast dummy still gets written into
+	// the egress Ethernet destination, so the server must overwrite it with chaddr.
+	s.SetGatewayHardwareAddr(apGWMAC)
+	sv := new(dhcpv4.Server)
+	err = sv.Configure(dhcpv4.ServerConfig{
+		ServerAddr: apAddr,
+		Gateway:    apAddr,
+		Subnet:     ipv4.PrefixFrom(apAddr, apSubnetBi),
+	})
+	if err != nil {
+		t.Fatal(err)
+	}
+	// Zero remote address disables the source-IP filter: DHCP clients send from 0.0.0.0.
+	err = s.RegisterUDP4(sv, [4]byte{}, dhcpv4.DefaultClientPort)
+	if err != nil {
+		t.Fatal(err)
+	}
+	return s
+}
+
+// broadcastDiscover builds the DISCOVER of a client with no address: Ethernet and IPv4
+// destinations both broadcast, source 0.0.0.0, with valid checksums.
+func broadcastDiscover(t testing.TB, xid uint32) []byte {
+	t.Helper()
+	var cl dhcpv4.Client
+	err := cl.BeginRequest(xid, dhcpv4.RequestConfig{ClientHardwareAddr: dhcpClMAC})
+	if err != nil {
+		t.Fatal(err)
+	}
+	pkt := make([]byte, apBufSize)
+	efrm, err := ethernet.NewFrame(pkt)
+	if err != nil {
+		t.Fatal(err)
+	}
+	*efrm.DestinationHardwareAddr() = macBcast
+	*efrm.SourceHardwareAddr() = dhcpClMAC
+	efrm.SetEtherType(ethernet.TypeIPv4)
+
+	ifrm, err := ipv4.NewFrame(pkt[apEthSize:])
+	if err != nil {
+		t.Fatal(err)
+	}
+	ifrm.SetVersionAndIHL(4, 5)
+	ifrm.SetToS(0)
+	ifrm.SetFlags(0x4000)
+	ifrm.SetTTL(64)
+	ifrm.SetProtocol(lneto.IPProtoUDP)
+
+	ufrm, err := udp.NewFrame(pkt[apEthSize+apIPv4Size:])
+	if err != nil {
+		t.Fatal(err)
+	}
+	ufrm.SetSourcePort(dhcpv4.DefaultClientPort)
+	ufrm.SetDestinationPort(dhcpv4.DefaultServerPort)
+
+	// Client sets its own IP addresses (0.0.0.0 -> 255.255.255.255).
+	dhcpLen, err := cl.Encapsulate(pkt, apEthSize, apEthSize+apIPv4Size+apUDPSize)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if dhcpLen == 0 {
+		t.Fatal("client produced no DISCOVER")
+	}
+	udpLen := apUDPSize + dhcpLen
+	ifrm.SetTotalLength(uint16(apIPv4Size + udpLen))
+	ufrm.SetLength(uint16(udpLen))
+	ifrm.SetCRC(0)
+	ifrm.SetCRC(ifrm.CalculateHeaderCRC())
+	var crc lneto.CRC791
+	ifrm.CRCWriteUDPPseudo(&crc, uint16(udpLen))
+	ufrm.SetCRC(0)
+	ufrm.SetCRC(lneto.NeverZeroSum(crc.PayloadSum16(ifrm.Payload())))
+	return pkt[:apEthSize+apIPv4Size+udpLen]
+}
+
+// TestDHCPServerAPBroadcastOffer feeds a broadcast DISCOVER through the whole
+// Ethernet/IPv4/UDP demux chain and checks the reply that comes back out of
+// EgressEthernet is a well formed OFFER: unicast to the client's hardware address
+// (over the gateway MAC the Ethernet layer wrote), from the server address to the
+// offered address, ports swapped, and both checksums valid despite the server
+// writing addresses inside the IPv4 layer's encapsulation.
+func TestDHCPServerAPBroadcastOffer(t *testing.T) {
+	ap := newAPStack(t, true)
+	err := ap.IngressEthernet(broadcastDiscover(t, 0xeee8f531))
+	if err != nil {
+		t.Fatalf("ingress discover: %v", err)
+	}
+	buf := make([]byte, apBufSize)
+	n, err := ap.EgressEthernet(buf)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if n == 0 {
+		t.Fatal("AP produced no OFFER for broadcast DISCOVER")
+	}
+
+	efrm, err := ethernet.NewFrame(buf[:n])
+	if err != nil {
+		t.Fatal(err)
+	}
+	if got := *efrm.DestinationHardwareAddr(); got != dhcpClMAC {
+		t.Errorf("OFFER ethernet dst=%v want client MAC %v", got, dhcpClMAC)
+	}
+	ifrm, err := ipv4.NewFrame(efrm.Payload())
+	if err != nil {
+		t.Fatal(err)
+	}
+	if ifrm.CalculateHeaderCRC() != 0 {
+		t.Error("OFFER has invalid IPv4 header checksum")
+	}
+	if got := *ifrm.SourceAddr(); got != apAddr {
+		t.Errorf("OFFER src=%v want server address %v", got, apAddr)
+	}
+	ufrm, err := udp.NewFrame(ifrm.Payload())
+	if err != nil {
+		t.Fatal(err)
+	}
+	var crc lneto.CRC791
+	ifrm.CRCWriteUDPPseudo(&crc, ufrm.Length())
+	if crc.PayloadSum16(ufrm.RawData()[:ufrm.Length()]) != 0 {
+		t.Error("OFFER has invalid UDP checksum")
+	}
+	if got := ufrm.DestinationPort(); got != dhcpv4.DefaultClientPort {
+		t.Errorf("OFFER udp dst port=%d want %d", got, dhcpv4.DefaultClientPort)
+	}
+	if got := ufrm.SourcePort(); got != dhcpv4.DefaultServerPort {
+		t.Errorf("OFFER udp src port=%d want %d", got, dhcpv4.DefaultServerPort)
+	}
+	dfrm, err := dhcpv4.NewFrame(ufrm.Payload())
+	if err != nil {
+		t.Fatal(err)
+	}
+	// The client has no address yet, so the OFFER must be addressed to the address
+	// it is being offered.
+	if got, want := *ifrm.DestinationAddr(), *dfrm.YIAddr(); got != want {
+		t.Errorf("OFFER dst=%v want offered address %v", got, want)
+	}
+	var msgType dhcpv4.MessageType
+	err = dfrm.ForEachOption(func(off int, op dhcpv4.OptNum, data []byte) error {
+		if op == dhcpv4.OptMessageType && len(data) == 1 {
+			msgType = dhcpv4.MessageType(data[0])
+		}
+		return nil
+	})
+	if err != nil {
+		t.Fatal(err)
+	}
+	if msgType != dhcpv4.MsgOffer {
+		t.Errorf("want OFFER, got %s", msgType.String())
+	}
+}
+
+// TestDHCPServerAPRequiresBroadcastAccept pins the espradio.log failure: a stack that
+// does not opt into StackConfig.AcceptIPv4Broadcast drops DISCOVERs at the IPv4 layer,
+// so dhcpv4.Server never sees them and never answers.
+func TestDHCPServerAPRequiresBroadcastAccept(t *testing.T) {
+	ap := newAPStack(t, false)
+	err := ap.IngressEthernet(broadcastDiscover(t, 0x65be2ff3))
+	if err != lneto.ErrPacketDrop {
+		t.Fatalf("want ErrPacketDrop for broadcast DISCOVER without AcceptIPv4Broadcast, got %v", err)
+	}
+	buf := make([]byte, apBufSize)
+	n, err := ap.EgressEthernet(buf)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if n != 0 {
+		t.Fatalf("AP answered a DISCOVER it should have dropped (%d bytes)", n)
+	}
+}