search

meshtastic / firmware

Meshtastic device firmware
https://meshtastic.org
GNU General Public License v3.0
3.67k stars 920 forks source link

[Bug]: Can't communicate via Ethernet #3618

Closed micheljung closed 2 months ago

micheljung commented 7 months ago

Category

Other

Hardware

RAK4631 RAK13800

Firmware Version

2.3.4.ea61808

Description

I wrote a Software that successfully connects via Ethernet and retrieves device information. However, when trying to send a chat message, the device drops the connection.

To make sure the problem is not on my end, I tried the Python CLI and it seems to confirm the issue:

$ meshtastic --version
2.3.4

$ meshtastic --host 192.168.178.47 --info
Error connecting to 192.168.178.47:Timed out waiting for connection completion

Relevant log output

INFO | 10:55:09 23 [ApiServer] Incoming wifi connection
INFO | 10:55:09 23 [ApiServer] Incoming ethernet connection
INFO | 10:55:09 23 [ServerAPI] Client wants config, nonce=1024315206
INFO | 10:55:09 23 [ServerAPI] Starting API client config
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_MY_INFO
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=3, 12 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_METADATA
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=13, 30 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_NODEINFO
INFO | 10:55:09 23 [ServerAPI] nodeinfo: num=0xcdaf65a1, lastseen=1713092109, id=!cdaf65a1, name=KP Hotzenweid
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=4, 95 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_NODEINFO
INFO | 10:55:09 23 [ServerAPI] nodeinfo: num=0xe5e837d0, lastseen=0, id=!e5e837d0, name=T-Echo #1
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=4, 46 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_NODEINFO
INFO | 10:55:09 23 [ServerAPI] Done sending nodeinfos
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 13 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO | 10:55:09 23 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | 10:55:09 23 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO | 10:55:10 23 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | 10:55:10 23 [ServerAPI] encoding toPhone packet to phone variant=5, 9 bytes
INFO | 10:55:10 23 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | 10:55:10 23 [ServerAPI] encoding toPhone packet to phone variant=5, 20 bytes
INFO | 10:55:10 23 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | 10:55:10 23 [ServerAPI] encoding toPhone packet to phone variant=5, 17 bytes
INFO | 10:55:10 23 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | 10:55:10 23 [ServerAPI] encoding toPhone packet to phone variant=5, 22 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=5, 7 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=5, 19 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=5, 12 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 60 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 17 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 13 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 7 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 14 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 8 bytes
INFO | 10:55:10 24 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | 10:55:10 24 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO | 10:55:11 24 [ServerAPI] getFromRadio=STATE_SEND_COMPLETE_ID
DEBUG | 10:55:11 24 [ServerAPI] encoding toPhone packet to phone variant=7, 6 bytes
INFO | 10:55:11 24 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | 10:55:11 24 [ServerAPI] encoding toPhone packet to phone variant=11, 6 bytes
DEBUG | 10:55:11 24 [GPS] Probing for GPS at 115200
WARN | 10:55:12 26 [GPS] Failed to find UBlox & MTK GNSS Module using baudrate 115200
INFO | 10:55:12 26 [ApiServer] Force closing previous TCP connection
INFO | 10:55:13 27 [ApiServer] Incoming wifi connection
INFO | 10:55:13 27 [ApiServer] Incoming ethernet connection
DEBUG | 10:55:13 27 [Power] Battery: usbPower=1, isCharging=1, batMv=4011, batPct=83
INFO | 10:55:13 27 [ServerAPI] Client dropped connection, suspending API service
micheljung commented 7 months ago

This issue does not occur when starting the firmware (2.3.4.ea61808) in a Docker container:

$ meshtastic --host localhost
Connected to radio

Log:

INFO  | ??:??:?? 18 [ApiServer] Incoming wifi connection
INFO  | ??:??:?? 18 [ApiServer] Incoming wifi connection
INFO  | ??:??:?? 18 [ServerAPI] Client wants config, nonce=3585281042
INFO  | ??:??:?? 18 [ServerAPI] Starting API client config
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MY_INFO
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=3, 11 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_METADATA
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=13, 18 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_NODEINFO
INFO  | ??:??:?? 18 [ServerAPI] nodeinfo: num=0x4e1c43b, lastseen=0, id=!20981da7, name=Meshtastic 0001
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=4, 55 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_NODEINFO
INFO  | ??:??:?? 18 [ServerAPI] Done sending nodeinfos
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 13 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CHANNELS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=10, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=5, 11 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=5, 20 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=5, 17 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=5, 20 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=5, 7 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=5, 14 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_CONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=5, 12 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 53 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 13 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 7 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 14 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 8 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_MODULECONFIG
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=9, 4 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_COMPLETE_ID
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=7, 6 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 6 bytes
DEBUG | ??:??:?? 18 [ServerAPI] PACKET FROM PHONE (id=0xb503a549 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [ServerAPI] Enqueued local (id=0xb503a549 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 18 Telling client we have new packets 2
DEBUG | ??:??:?? 18 [Router] Add packet record (id=0xb503a549 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] handleReceived(REMOTE) (id=0xb503a549 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received Admin from=0x0, id=0xb503a549, portnum=6, payloadlen=2
INFO  | ??:??:?? 18 [Router] Client is getting channel 0
INFO  | ??:??:?? 18 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 18 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received routing from=0x0, id=0xb503a549, portnum=6, payloadlen=2
DEBUG | ??:??:?? 18 [Router] Routing sniffing (id=0xb503a549 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] Module 'routing' considered
DEBUG | ??:??:?? 18 [Router] Sending response (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 18 [Router] Enqueued local (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] Rx someone rebroadcasting for us (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] didn't find pending packet
DEBUG | ??:??:?? 18 [Router] Add packet record (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] handleReceived(REMOTE) (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 18 [Router] packet on wrong channel, but can't respond (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received routing from=0x4e1c43b, id=0x36ad4ebf, portnum=6, payloadlen=13
DEBUG | ??:??:?? 18 [Router] Routing sniffing (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] Received an ack for 0xb503a549, stopping retransmissions
DEBUG | ??:??:?? 18 [Router] Delivering rx packet (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 18 [Router] Forwarding to phone (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'routing' considered
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] phone downloaded packet (id=0x36ad4ebf fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a549 priority=70)
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=2, 45 bytes
INFO  | ??:??:?? 18 Telling client we have new packets 4
DEBUG | ??:??:?? 18 [ServerAPI] PACKET FROM PHONE (id=0xb503a54a fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [ServerAPI] Enqueued local (id=0xb503a54a fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 18 Telling client we have new packets 5
DEBUG | ??:??:?? 18 [Router] Add packet record (id=0xb503a54a fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] handleReceived(REMOTE) (id=0xb503a54a fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received Admin from=0x0, id=0xb503a54a, portnum=6, payloadlen=2
INFO  | ??:??:?? 18 [Router] Client is getting channel 1
INFO  | ??:??:?? 18 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 18 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received routing from=0x0, id=0xb503a54a, portnum=6, payloadlen=2
DEBUG | ??:??:?? 18 [Router] Routing sniffing (id=0xb503a54a fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] Module 'routing' considered
DEBUG | ??:??:?? 18 [Router] Sending response (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 18 [Router] Enqueued local (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] Rx someone rebroadcasting for us (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] didn't find pending packet
DEBUG | ??:??:?? 18 [Router] Add packet record (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] handleReceived(REMOTE) (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 18 [Router] packet on wrong channel, but can't respond (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received routing from=0x4e1c43b, id=0x36ad4ec0, portnum=6, payloadlen=6
DEBUG | ??:??:?? 18 [Router] Routing sniffing (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] Received an ack for 0xb503a54a, stopping retransmissions
DEBUG | ??:??:?? 18 [Router] Delivering rx packet (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 18 [Router] Forwarding to phone (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'routing' considered
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] phone downloaded packet (id=0x36ad4ec0 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54a priority=70)
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=2, 38 bytes
INFO  | ??:??:?? 18 Telling client we have new packets 7
DEBUG | ??:??:?? 18 [ServerAPI] PACKET FROM PHONE (id=0xb503a54b fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [ServerAPI] Enqueued local (id=0xb503a54b fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 18 Telling client we have new packets 8
DEBUG | ??:??:?? 18 [Router] Add packet record (id=0xb503a54b fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] handleReceived(REMOTE) (id=0xb503a54b fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received Admin from=0x0, id=0xb503a54b, portnum=6, payloadlen=2
INFO  | ??:??:?? 18 [Router] Client is getting channel 2
INFO  | ??:??:?? 18 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 18 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received routing from=0x0, id=0xb503a54b, portnum=6, payloadlen=2
DEBUG | ??:??:?? 18 [Router] Routing sniffing (id=0xb503a54b fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [Router] Module 'routing' considered
DEBUG | ??:??:?? 18 [Router] Sending response (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 18 [Router] Enqueued local (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] Rx someone rebroadcasting for us (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] didn't find pending packet
DEBUG | ??:??:?? 18 [Router] Add packet record (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] handleReceived(REMOTE) (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 18 [Router] packet on wrong channel, but can't respond (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 18 [Router] Received routing from=0x4e1c43b, id=0x36ad4ec1, portnum=6, payloadlen=6
DEBUG | ??:??:?? 18 [Router] Routing sniffing (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] Received an ack for 0xb503a54b, stopping retransmissions
DEBUG | ??:??:?? 18 [Router] Delivering rx packet (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 18 [Router] Forwarding to phone (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [Router] Module 'routing' considered
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] phone downloaded packet (id=0x36ad4ec1 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54b priority=70)
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=2, 38 bytes
INFO  | ??:??:?? 18 Telling client we have new packets 10
DEBUG | ??:??:?? 18 [ServerAPI] PACKET FROM PHONE (id=0xb503a54c fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 18 [ServerAPI] Enqueued local (id=0xb503a54c fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 18 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 18 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 11
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0xb503a54c fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0xb503a54c fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received Admin from=0x0, id=0xb503a54c, portnum=6, payloadlen=2
INFO  | ??:??:?? 19 [Router] Client is getting channel 3
INFO  | ??:??:?? 19 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x0, id=0xb503a54c, portnum=6, payloadlen=2
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0xb503a54c fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
DEBUG | ??:??:?? 19 [Router] Sending response (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Enqueued local (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] Rx someone rebroadcasting for us (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] didn't find pending packet
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 19 [Router] packet on wrong channel, but can't respond (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x4e1c43b, id=0x36ad4ec2, portnum=6, payloadlen=6
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] Received an ack for 0xb503a54c, stopping retransmissions
DEBUG | ??:??:?? 19 [Router] Delivering rx packet (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Forwarding to phone (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] phone downloaded packet (id=0x36ad4ec2 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54c priority=70)
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=2, 38 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 13
DEBUG | ??:??:?? 19 [ServerAPI] PACKET FROM PHONE (id=0xb503a54d fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [ServerAPI] Enqueued local (id=0xb503a54d fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 14
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0xb503a54d fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0xb503a54d fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received Admin from=0x0, id=0xb503a54d, portnum=6, payloadlen=2
INFO  | ??:??:?? 19 [Router] Client is getting channel 4
INFO  | ??:??:?? 19 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x0, id=0xb503a54d, portnum=6, payloadlen=2
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0xb503a54d fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
DEBUG | ??:??:?? 19 [Router] Sending response (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Enqueued local (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] Rx someone rebroadcasting for us (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] didn't find pending packet
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 19 [Router] packet on wrong channel, but can't respond (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x4e1c43b, id=0x36ad4ec3, portnum=6, payloadlen=6
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] Received an ack for 0xb503a54d, stopping retransmissions
DEBUG | ??:??:?? 19 [Router] Delivering rx packet (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Forwarding to phone (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] phone downloaded packet (id=0x36ad4ec3 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54d priority=70)
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=2, 38 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 16
DEBUG | ??:??:?? 19 [ServerAPI] PACKET FROM PHONE (id=0xb503a54e fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [ServerAPI] Enqueued local (id=0xb503a54e fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 17
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0xb503a54e fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0xb503a54e fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received Admin from=0x0, id=0xb503a54e, portnum=6, payloadlen=2
INFO  | ??:??:?? 19 [Router] Client is getting channel 5
INFO  | ??:??:?? 19 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x0, id=0xb503a54e, portnum=6, payloadlen=2
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0xb503a54e fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
DEBUG | ??:??:?? 19 [Router] Sending response (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Enqueued local (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] Rx someone rebroadcasting for us (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] didn't find pending packet
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 19 [Router] packet on wrong channel, but can't respond (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x4e1c43b, id=0x36ad4ec4, portnum=6, payloadlen=6
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] Received an ack for 0xb503a54e, stopping retransmissions
DEBUG | ??:??:?? 19 [Router] Delivering rx packet (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Forwarding to phone (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] phone downloaded packet (id=0x36ad4ec4 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54e priority=70)
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=2, 38 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 19
DEBUG | ??:??:?? 19 [ServerAPI] PACKET FROM PHONE (id=0xb503a54f fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [ServerAPI] Enqueued local (id=0xb503a54f fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 20
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0xb503a54f fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0xb503a54f fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received Admin from=0x0, id=0xb503a54f, portnum=6, payloadlen=2
INFO  | ??:??:?? 19 [Router] Client is getting channel 6
INFO  | ??:??:?? 19 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x0, id=0xb503a54f, portnum=6, payloadlen=2
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0xb503a54f fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
DEBUG | ??:??:?? 19 [Router] Sending response (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Enqueued local (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] Rx someone rebroadcasting for us (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] didn't find pending packet
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 19 [Router] packet on wrong channel, but can't respond (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x4e1c43b, id=0x36ad4ec5, portnum=6, payloadlen=6
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] Received an ack for 0xb503a54f, stopping retransmissions
DEBUG | ??:??:?? 19 [Router] Delivering rx packet (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Forwarding to phone (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] phone downloaded packet (id=0x36ad4ec5 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a54f priority=70)
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=2, 38 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 22
DEBUG | ??:??:?? 19 [ServerAPI] PACKET FROM PHONE (id=0xb503a550 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [ServerAPI] Enqueued local (id=0xb503a550 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 Telling client we have new packets 23
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0xb503a550 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0xb503a550 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received Admin from=0x0, id=0xb503a550, portnum=6, payloadlen=2
INFO  | ??:??:?? 19 [Router] Client is getting channel 7
INFO  | ??:??:?? 19 [Router] Asked module 'Admin' to send a response
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x0, id=0xb503a550, portnum=6, payloadlen=2
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0xb503a550 fr=0x00 to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 WANTRESP)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
DEBUG | ??:??:?? 19 [Router] Sending response (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Enqueued local (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] Rx someone rebroadcasting for us (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] didn't find pending packet
DEBUG | ??:??:?? 19 [Router] Add packet record (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] handleReceived(REMOTE) (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'Admin' wantsPacket=1
DEBUG | ??:??:?? 19 [Router] packet on wrong channel, but can't respond (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' wantsPacket=1
INFO  | ??:??:?? 19 [Router] Received routing from=0x4e1c43b, id=0x36ad4ec6, portnum=6, payloadlen=6
DEBUG | ??:??:?? 19 [Router] Routing sniffing (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] Received an ack for 0xb503a550, stopping retransmissions
DEBUG | ??:??:?? 19 [Router] Delivering rx packet (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] Update DB node 0x4e1c43b, rx_time=0
DEBUG | ??:??:?? 19 [Router] Forwarding to phone (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [Router] Module 'routing' considered
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | ??:??:?? 19 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | ??:??:?? 19 [ServerAPI] phone downloaded packet (id=0x36ad4ec6 fr=0x3b to=0x3b, WantAck=0, HopLim=3 Ch=0x0 Portnum=6 requestId=b503a550 priority=70)
DEBUG | ??:??:?? 19 [ServerAPI] encoding toPhone packet to phone variant=2, 38 bytes
INFO  | ??:??:?? 20 Telling client we have new packets 25
DEBUG | ??:??:?? 20 [ServerAPI] PACKET FROM PHONE (id=0xb503a551 fr=0x00 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3)
DEBUG | ??:??:?? 20 [ServerAPI] handleReceived(USER) (id=0xb503a551 fr=0x00 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3)
DEBUG | ??:??:?? 20 [ServerAPI] Module 'position' wantsPacket=1
INFO  | ??:??:?? 20 [ServerAPI] Received position from=0x0, id=0xb503a551, portnum=3, payloadlen=5
DEBUG | ??:??:?? 20 [ServerAPI] Incoming update from MYSELF
DEBUG | ??:??:?? 20 [ServerAPI] Setting local position: latitude=0, longitude=0, time=1713098091
INFO  | ??:??:?? 20 [ServerAPI] POSITION node=04e1c43b l=5 latI=0 lonI=0 msl=0 hae=0 geo=0 pdop=0 hdop=0 vdop=0 siv=0 fxq=0 fxt=0 pts=0 time=1713098091
DEBUG | ??:??:?? 20 [ServerAPI] Upgrading time to quality 3
DEBUG | 12:34:51 20 [ServerAPI] Read RTC time as 1713098091
DEBUG | 12:34:51 20 [ServerAPI] updatePosition SPECIAL time setting time=1713098091
DEBUG | 12:34:51 20 [ServerAPI] Node status update: 0 online, 1 total
DEBUG | 12:34:51 20 [ServerAPI] Module 'position' considered
DEBUG | 12:34:51 20 [ServerAPI] Module 'routing' wantsPacket=1
INFO  | 12:34:51 20 [ServerAPI] Received routing from=0x0, id=0xb503a551, portnum=3, payloadlen=5
DEBUG | 12:34:51 20 [ServerAPI] Routing sniffing (id=0xb503a551 fr=0x00 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3)
DEBUG | 12:34:51 20 [ServerAPI] Module 'routing' considered
DEBUG | 12:34:51 20 [ServerAPI] localSend to channel 0
DEBUG | 12:34:51 20 [ServerAPI] Add packet record (id=0xb503a551 fr=0x00 to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3)
DEBUG | 12:34:51 20 [ServerAPI] Expanding short PSK #1
DEBUG | 12:34:51 20 [ServerAPI] Using AES128 key!
DEBUG | 12:34:51 20 [ServerAPI] Installing AES128 key!
DEBUG | 12:34:51 20 [ServerAPI] enqueuing for send (id=0xb503a551 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted hopStart=3)
DEBUG | 12:34:51 20 [ServerAPI] Set random delay before transmitting.
INFO  | 12:34:51 20 [ServerAPI] getFromRadio=STATE_SEND_PACKETS
DEBUG | 12:34:51 20 [ServerAPI] encoding toPhone packet to phone variant=11, 12 bytes
INFO  | 12:34:51 20 [ServerAPI] Lost phone connection
INFO  | 12:34:51 20 [ServerAPI] Client dropped connection, suspending API service
DEBUG | 12:34:51 20 [SimRadio] delay done
DEBUG | 12:34:51 20 [SimRadio] Starting low level send (id=0xb503a551 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted hopStart=3 priority=64)
DEBUG | 12:34:51 20 [SimRadio] Using channel 0 (hash 0x8)
DEBUG | 12:34:51 20 [SimRadio] Expanding short PSK #1
DEBUG | 12:34:51 20 [SimRadio] Using AES128 key!
DEBUG | 12:34:51 20 [SimRadio] Installing AES128 key!
DEBUG | 12:34:51 20 [SimRadio] decoded message (id=0xb503a551 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=3 hopStart=3 priority=64)
DEBUG | 12:34:51 20 [SimRadio] (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=25, time 419 ms
DEBUG | 12:34:51 20 [SimRadio] AirTime - Packet transmitted : 419ms
DEBUG | 12:34:51 20 [SimRadio] Completed sending (id=0xb503a551 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted hopStart=3 priority=64)
INFO  | 12:35:01 30 [NodeInfoModule] Sending our nodeinfo to mesh (wantReplies=1)
INFO  | 12:35:01 30 [NodeInfoModule] sending owner !20981da7/Meshtastic 0001/0001
DEBUG | 12:35:01 30 [NodeInfoModule] Update DB node 0x4e1c43b, rx_time=1713098101
DEBUG | 12:35:01 30 [NodeInfoModule] handleReceived(LOCAL) (id=0x36ad4ec7 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=4 WANTRESP rxtime=1713098101 priority=10)
DEBUG | 12:35:01 30 [NodeInfoModule] No modules interested in portnum=4, src=LOCAL
DEBUG | 12:35:01 30 [NodeInfoModule] localSend to channel 0
DEBUG | 12:35:01 30 [NodeInfoModule] Add packet record (id=0x36ad4ec7 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=4 WANTRESP rxtime=1713098101 priority=10)
DEBUG | 12:35:01 30 [NodeInfoModule] Expanding short PSK #1
DEBUG | 12:35:01 30 [NodeInfoModule] Using AES128 key!
DEBUG | 12:35:01 30 [NodeInfoModule] Installing AES128 key!
DEBUG | 12:35:01 30 [NodeInfoModule] enqueuing for send (id=0x36ad4ec7 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted rxtime=1713098101 hopStart=3 priority=10)
DEBUG | 12:35:01 30 [NodeInfoModule] Set random delay before transmitting.
DEBUG | 12:35:01 30 [SimRadio] delay done
DEBUG | 12:35:01 30 [SimRadio] Starting low level send (id=0x36ad4ec7 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted rxtime=1713098101 hopStart=3 priority=10)
DEBUG | 12:35:01 30 [SimRadio] Using channel 0 (hash 0x8)
DEBUG | 12:35:01 30 [SimRadio] Expanding short PSK #1
DEBUG | 12:35:01 30 [SimRadio] Using AES128 key!
DEBUG | 12:35:01 30 [SimRadio] Installing AES128 key!
DEBUG | 12:35:01 30 [SimRadio] decoded message (id=0x36ad4ec7 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x0 Portnum=4 WANTRESP rxtime=1713098101 hopStart=3 priority=10)
DEBUG | 12:35:01 30 [SimRadio] (bw=250, sf=11, cr=4/5) packet symLen=8 ms, payloadSize=66, time 722 ms
DEBUG | 12:35:01 30 [SimRadio] AirTime - Packet transmitted : 722ms
DEBUG | 12:35:01 30 [SimRadio] Completed sending (id=0x36ad4ec7 fr=0x3b to=0xff, WantAck=0, HopLim=3 Ch=0x8 encrypted rxtime=1713098101 hopStart=3 priority=10)

What stands out is that on the device it says 

INFO | 10:55:09 23 [ApiServer] Incoming wifi connection
INFO | 10:55:09 23 [ApiServer] Incoming ethernet connection
[...]
INFO | 10:55:12 26 [ApiServer] Force closing previous TCP connection
INFO | 10:55:13 27 [ApiServer] Incoming wifi connection
INFO | 10:55:13 27 [ApiServer] Incoming ethernet connection

while when I run the firmware in Docker it says

INFO  | ??:??:?? 18 [ApiServer] Incoming wifi connection
INFO  | ??:??:?? 18 [ApiServer] Incoming wifi connection
[...]
daytonturner commented 7 months ago

OK, Ive spent a couple hours poking at this and I think I've got some answers on why this is happening, but I don't know the best approach for solving it.

Taking a look at how the TCP API loop is implemented here: https://github.com/meshtastic/firmware/blob/master/src/mesh/api/ServerAPI.cpp#L48-L59

My understanding is this:

The issue of course, is a client connected to the TCP API will send a number of requests through the life of the connection, so the receive buffer will have data in it much longer than the 100ms it takes to start the loop over.

When the loop repeats in the next 100ms, Line 48/49 will return true, because there is an established connection, likely with contents in the recv buffer. The connection we made a moment ago. Its about to be killed.

This generally seems like an incomplete way to handle this. I went looking through old git commits and found #608 where the force-closing of the previous TCP connection was introduced. I get that we only want to permit one connection at a time, but outright killing the existing connection isn't a valid route either.

This behavior makes some sense if you only consider long-running connections that have a 0-length receive buffer waiting from the client (such as the Android app idling, some other custom application watching for received messages, etc).

However, if you're using the CLI via the TCP API, queries can take ~3 seconds to fully complete, and given the 100ms loop, there's no chance they'll finish before they get auto-destroyed the next time the loop runs. I've temporarily changed return 100; to return 4000; to allow enough time for the CLI to do its thing, but thats not a proper solution either.

Hoping someone has some other ideas on ways to handle the various edge cases here?

daytonturner commented 7 months ago

Thinking through some high level logic on an appropriate way to handle this, and I have an idea to propose.

When a new connection comes in, the code currently checks to see if there are any existing clients (openAPI) and if so, it destroys them. I feel like the intention here was to only behave this way if the connection is a long-running, currently idle established connection.

Perhaps on line 51, rather than blindly checking for an existing client, we should be evaluating the currently established client a bit further, and checking if its receive buffer is empty or not. If it is, allow it to be killed. This would allow a second long-running client to "take over" the single connection that's allwoed. If there is data in the recv buffer, dont destroy the client, but also dont attempt to create a new one. This would allow an existing client that's still actively asking for data to finish.

I can see how this could be accomplished with the private functions within EthernetServer/EthernetClient, but not entirely sure if the public functions allow for this level of inspection. I'm not a C++ developer, so I'm just taking a shot here.

Another thought of course, is if you have two clients (let's use the android app using IP connections as our example) both trying to connect to the same API, and the server doesn't want to allow more than one.. If you let the server kill an existing connection and give the new client the socket, it seems like this will actually just cause the two clients to fight while they repeatedly attempt to reconnect - ultimately making neither of them function. I dont know how many times they retry, but this doesn't seem viable either. Perhaps closing the existing connection shouldn't happen at all, and we should just reject new connections with an error if one already exists?

daytonturner commented 7 months ago

Interestingly - I've updated to the latest python meshtastic v2.3.8 and noticed that there's a major change in it to use the 'modern' meshtastic protocol init flow. In the PR it mentions timeouts when using the TCP API:

https://github.com/meshtastic/python/pull/560

After this update, the CLI seems to work basically 100% of the time. It makes some sense, given that it can accomplish the task much faster, but its also entirely confusing given how i know the code mentioned above should work, so there must still be something about the TCP API loop that I dont understand.

Will try to get a better understanding of how that loop works, but for now if you update the meshtastic CLI to 2.3.8, i suspect you'll also see that its now working reliably. Curious to hear your results.

micheljung commented 7 months ago

@daytonturner if I understand it correctly, https://github.com/meshtastic/python/pull/560 only eliminates the symptom, not the issue.

Before, the Python CLI did:

  1. Establish a connection (works)
  2. Request Config (works, probably because it's the first message or because less than 100ms have passed)
  3. Request channels (failed, because of this bug)

Because 3. is no longer needed, the Python CLI no longer runs into this issue.

In the client I'm writing, I can also successfully establish a connection and receive the device information. However, as soon as I send another message to the device, the connection is dropped.

daytonturner commented 7 months ago

It makes sense that this behaviour would mask the problem, rather than fixing the root of the problem.

I say this because the main ServerAPI loop checks to see if a new connection is waiting to be served by testing if there’s an established connection with bytes waiting in the receive buffer (ie the client hasn’t sent its request yet).

If the client makes only one request and is simply waiting for response to happen, then it won’t be a problem.

If after 100ms (the loop time) there’s still a client connected with anything in the receive buffer (like a second request) it will close it and open a new one.

Dayton

From: Michel Jung @.> Sent: Sunday, May 5, 2024 1:01:38 AM To: meshtastic/firmware @.> Cc: daytonturner @.>; Mention @.> Subject: Re: [meshtastic/firmware] [Bug]: Can't communicate via Ethernet (Issue #3618)

@daytonturnerhttps://github.com/daytonturner they way I understand it, meshtastic/python#560https://github.com/meshtastic/python/pull/560 only eliminates the symptom, not the issue.

Before, the Python CLI did:

  1. Establish a connection (works)
  2. Request channels (failed, because of this bug)

Now, it only does 1., which works, and 2. is no longer needed.

In the client I'm writing, I can also successfully establish a connection and receive the device information. However, as soon as I send another message to the device, the connection is dropped.

— Reply to this email directly, view it on GitHubhttps://github.com/meshtastic/firmware/issues/3618#issuecomment-2094673902, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ACZEPSNSUDPMJBVBBR45GY3ZAXROFAVCNFSM6AAAAABGGD3OGGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDAOJUGY3TGOJQGI. You are receiving this because you were mentioned.Message ID: @.***>

EmilAndersson-SE commented 2 months ago

I do see the same problem and may be same root cause. RAK4631 and tried 2.4.0.46d7b82, 2.4.3.91d6612, 2.3.15.deb7c27 and even the 2.5.0.33eb07. But still same behaviour not able to connect and use app properly over ethernet (not wifi). I can confirm i see the same errors as mention here. Are we the only ones that run ethernet? I bet there should be more topics about this.

serial output apiserver error 2024-09-04

NetHorizon82 commented 2 months ago

I think that I am having the same issue, but I am not familiar enough to get this far into the weeds yet. I was able to get it to send messages to a private MQTT server so I know that the device is connected to the network. However, if I try to use the web client to connect the devices IP, the client just never fully loads.

garthvh commented 2 months ago

There is no web server on a nrf device you need to use the hosted web client at client.meshtastic.org

NetHorizon82 commented 2 months ago

There is no web server on a nrf device you need to use the hosted web client at client.meshtastic.org

I know that the RAK4631 does not self host the client. I used both the client.meshtastic.org as well as a client I host locally on another device.

In both cases, when I connect to the device using the IP:

  1. All the device info in the upper left corner (short name, long name, battery, firmware ver.) shows up as "UNK"
  2. The messages window says "Messages: Loading..." and never changes.
  3. clicking on config get the basic config screen with all fields blank.

Everything works fine over serial, and I have a RPi/Waveshare node that I access over the same network so I doubt that there is a problem with the web host/network itself.

EmilAndersson-SE commented 2 months ago

How can this be completed? Is the issue fixed and in what firmware?

logikal commented 2 months ago

It looks like https://github.com/meshtastic/firmware/pull/4639 addressed this.

caveman99 commented 2 months ago

as soon as we merge the acoomanying pull request the issue will automatically be closed. that means the fix is included in the next alpha release.

NetHorizon82 commented 2 months ago

I tried the new firmware (v2.5.0.e470619), but am still having the same results when using the web client to connect. Android client (connecting over ethernet) does seem to work now. Is there someone I can work with to pull logs to see if this is still the same issue or if there is something else going on?

zerolint commented 2 months ago

@NetHorizon82 The web client uses a nodes http/s web server, not the port 4403 api server. Currently the web client will not work connecting to a rak4631 with Ethernet since only a port 4403 api server is run.

NetHorizon82 commented 2 months ago

@zerolint Thank you for the info. Is only running the API server and not both API and http/s a hardware limitation or just something that hasn't been implemented due to priorities? Also, if it is a hardware RESOURCE limitation, would it be possible to make it so that someone could choose if they wanted the API or http/s server to be running?

Also, I am new to participating, so please let me know if there is a better place to discus this issue other than a close bug report.

arne182 commented 1 month ago

Just updated to 2.5.5 and found that the ethernet is no longer working. Is there any update about what version still works?