DHCP not getting IP on TP-Link AC-1750

[scottfeldman]

Running examples/tcpserver/main.go in soypat/cyw43439, I get a Wifi connection to my test router TP-Link AC1750, but no DHCP IP is given.

sfeldma@nuc:~/work/cyw43439$ tinygo flash -target=pico -opt=1 -stack-size=32kb -size=short -monitor  ./examples/tcpserver/
   code    data     bss |   flash     ram
 564232   15676    3916 |  579908   19592
Connected to /dev/ttyACM1. Press Ctrl-C to exit.
starting program
time=1970-01-01T00:00:02.001Z level=DEBUG msg="starting program"

MAC: 28:cd:c1:01:13:7c
dhcp ongoing...
time=1970-01-01T00:00:06.980Z level=DEBUG msg=UDP:send plen=590
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...
time=1970-01-01T00:00:09.070Z level=DEBUG msg=UDP:recv plen=548
time=1970-01-01T00:00:09.071Z level=DEBUG msg=dhcp-rx msgtype=2
time=1970-01-01T00:00:09.072Z level=DEBUG msg=UDP:send plen=590
time=1970-01-01T00:00:09.121Z level=DEBUG msg=UDP:recv plen=548
time=1970-01-01T00:00:09.122Z level=DEBUG msg=dhcp-rx msgtype=6
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...
dhcp ongoing...

[soypat]

Do you have a wireshark capture file of the exchange? The DHCP server seems to have NACKed the request (message type 6)

[soypat]

Try the DHCP example with Debug-level logging on this branch. You should get more verbose output, i.e:

dhcp ongoing...
time=1970-01-01T00:00:13.675Z level=INFO msg=DHCP:tx msg=Discover
time=1970-01-01T00:00:13.675Z level=DEBUG msg=UDP:send plen=590
time=1970-01-01T00:00:13.676Z level=DEBUG msg=tx len=590
time=1970-01-01T00:00:13.725Z level=DEBUG msg=rx len=364 hdr=data
time=1970-01-01T00:00:13.726Z level=DEBUG msg=UDP:recv plen=300
time=1970-01-01T00:00:13.726Z level=DEBUG msg=DHCP:rx opt=MessageType data=2
time=1970-01-01T00:00:13.727Z level=DEBUG msg=DHCP:rx opt=ServerIdentification data=192,168,1,1
time=1970-01-01T00:00:13.727Z level=DEBUG msg=DHCP:rx opt=IPAddressLeaseTime data=0,1,81,128
time=1970-01-01T00:00:13.728Z level=DEBUG msg=DHCP:rx opt=RenewTimeValue data=0,0,168,192
time=1970-01-01T00:00:13.728Z level=DEBUG msg=DHCP:rx opt=RebindingTimeValue data=0,1,39,80
time=1970-01-01T00:00:13.729Z level=DEBUG msg=DHCP:rx opt=SubnetMask data=255,255,255,0
time=1970-01-01T00:00:13.729Z level=DEBUG msg=DHCP:rx opt=BroadcastAddress data=192,168,1,255
time=1970-01-01T00:00:13.730Z level=DEBUG msg=DHCP:rx opt=DNSServers data=192,168,1,1
time=1970-01-01T00:00:13.730Z level=DEBUG msg=DHCP:rx opt=Router data=192,168,1,1
time=1970-01-01T00:00:13.731Z level=INFO msg=DHCP:rx msg=Offer
time=1970-01-01T00:00:13.732Z level=INFO msg=DHCP:tx msg=Request
time=1970-01-01T00:00:13.732Z level=DEBUG msg=UDP:send plen=590
time=1970-01-01T00:00:13.733Z level=DEBUG msg=tx len=590
time=1970-01-01T00:00:13.776Z level=DEBUG msg=rx len=364 hdr=data
time=1970-01-01T00:00:13.777Z level=DEBUG msg=UDP:recv plen=300
time=1970-01-01T00:00:13.777Z level=DEBUG msg=DHCP:rx opt=MessageType data=5
time=1970-01-01T00:00:13.778Z level=DEBUG msg=DHCP:rx opt=ServerIdentification data=192,168,1,1
time=1970-01-01T00:00:13.778Z level=DEBUG msg=DHCP:rx opt=IPAddressLeaseTime data=0,1,81,128
time=1970-01-01T00:00:13.779Z level=DEBUG msg=DHCP:rx opt=RenewTimeValue data=0,0,168,192
time=1970-01-01T00:00:13.779Z level=DEBUG msg=DHCP:rx opt=RebindingTimeValue data=0,1,39,80
time=1970-01-01T00:00:13.780Z level=DEBUG msg=DHCP:rx opt=SubnetMask data=255,255,255,0
time=1970-01-01T00:00:13.780Z level=DEBUG msg=DHCP:rx opt=BroadcastAddress data=192,168,1,255
time=1970-01-01T00:00:13.781Z level=DEBUG msg=DHCP:rx opt=DNSServers data=192,168,1,1
time=1970-01-01T00:00:13.781Z level=DEBUG msg=DHCP:rx opt=OptNum(252) data=10
time=1970-01-01T00:00:13.782Z level=DEBUG msg=DHCP:rx opt=Router data=192,168,1,1
time=1970-01-01T00:00:13.782Z level=INFO msg=DHCP:rx msg=Ack
DHCP complete IP: 192.168.1.145

[scottfeldman]

I've lost my test case after updating my router. I updated to OpenWRT firmware so I could run tcpdump from the router. After this update, the original DHCP issue went away. I updated to the tp-link factory firmware, and DHCP is still working. So I lost my test case for this issue.

[marcofeltmann]

For reference or so: Sometimes I have the same thing with my Speedport 3. The DHCP server in the WiFi router states that everything is fine, but the DHCP client stays in status 1 - whatever that means.

It looks like the following:

• flash the sample
• pico w boots
• DHCP assigns IP
• power off, power on pico w
• DHCP stays in "ongoing" state 1

[marcofeltmann]

Gave the specific branch example a try and kinda modified it later on.

Successful (first) run:

MAC: 28:cd:c1:0b:a3:35
Start DHCP...
0
trying DHCP...
1970/01/01 00:00:06 INFO DHCP:tx msg=Discover
1
trying DHCP...
1970/01/01 00:00:08 ERROR Stack.RecvEth err="unknown IP protocol"
poll error: unknown IP protocol
1970/01/01 00:00:08 INFO DHCP:rx msg=Offer
1970/01/01 00:00:08 INFO DHCP:tx msg=Request
1970/01/01 00:00:08 INFO DHCP:rx msg=Ack
4
DHCP complete IP: 192.168.160.203
1970/01/01 00:00:09 ERROR Stack.RecvEth err="unknown IP protocol"
poll error: unknown IP protocol

Failed (subsequent) run after Power Off, Power On:

MAC: 28:cd:c1:0b:a3:35
Start DHCP...
0
trying DHCP...
1970/01/01 00:00:07 INFO DHCP:tx msg=Discover
1
trying DHCP...
[...]
1970/01/01 00:00:48 ERROR Stack.RecvEth err="unknown IP protocol"
poll error: unknown IP protocol
1970/01/01 00:00:48 ERROR Stack.RecvEth err="unknown IP protocol"
poll error: unknown IP protocol
1
trying DHCP...
1
trying DHCP...
1970/01/01 00:00:50 ERROR Stack.RecvEth err="unknown IP protocol"
poll error: unknown IP protocol
1970/01/01 00:00:50 ERROR Stack.RecvEth err="unknown IP protocol"
poll error: unknown IP protocol
1
trying DHCP...
1970/01/01 00:00:51 ERROR Stack.RecvEth err="unknown IP protocol"
poll error: unknown IP protocol
1
trying DHCP...
[...]
1
tried (another?) 25x...
trying DHCP...
[...]
1
tried (another?) 25x...
trying DHCP...

And keeps this trying without succeeding with sporadically logging the "unknown IP protocol" thing.

[soypat]

Wireshark captures of this in action would help tremendously!