Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Thread communication with external networks is unstable (TZ-352) #36

Closed
alexyuoouy opened this issue Oct 15, 2023 · 13 comments
Closed

Thread communication with external networks is unstable (TZ-352) #36

alexyuoouy opened this issue Oct 15, 2023 · 13 comments

Comments

@alexyuoouy
Copy link

Hello,I've encountered another issue. I've been continuously pinging a node from my computer, and it intermittently connects and disconnects. When it disconnects, it shows a 'Request Timed Out' message. Here's the current network topology: I have a router to which both my computer and OTBR are connected. The router supports IPv6 and does not use DHCPv6. Both my computer and OTBR have generated IPv6 addresses based on the prefix assigned by my ISP. I also have an ESP32-H2-DevKitM-1, which was added as a node to the Thread network. Initially, it acted as a child node, but later it automatically switched to a router role. Currently, I'm using this router node to ping my computer, and it works sometimes. However, when I try to ping this node from my computer, it occasionally succeeds, but I'm encountering the issue I mentioned earlier. I've set the OTBR log level to 'debug,' and from the logs, it seems that OTBR is constantly switching its routing strategy. This might be due to the presence of two IPv6 prefixes in my network – one assigned by the ISP and another by OTBR. This could lead to continuous switching between active and inactive routes, resulting in the issue mentioned above. Here are some log entries.

The routing strategy has changed, and the source address has been modified:

D(314305) OPENTHREAD:[D] Platform------: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:89, rssi:-12 ...
D(314305) OPENTHREAD:[D] Platform------: ... noise:-128, flags:0x0000, channel:26, lqi:10, timestamp:3737310850, rxerr:0
D(314305) OPENTHREAD:[D] Mac-----------: Received frame from short address 0x4400
D(314305) OPENTHREAD:[D] Mac-----------: Rx security - frame counter 20701
D(314305) OPENTHREAD:[D] Mac-----------: ==============================[RX len=089]==============================
D(314305) OPENTHREAD:[D] Mac-----------: | 69 98 AF 86 FC 00 48 00 | 44 0D DD 50 00 00 01 7B | i./.|.H.D.]P...{
D(314305) OPENTHREAD:[D] Mac-----------: | D0 10 3A C8 7D 86 16 53 | E3 CB B3 FD B5 0B 79 B3 | P.:H}..ScK3}5.y3
D(314305) OPENTHREAD:[D] Mac-----------: | D8 AC 57 C9 C7 74 99 67 | A1 59 28 81 00 78 FA 00 | X,WIGt.g!Y(..xz.
D(314305) OPENTHREAD:[D] Mac-----------: | 01 07 5B 61 62 63 64 65 | 66 67 68 69 6A 6B 6C 6D | ..[abcdefghijklm
D(314305) OPENTHREAD:[D] Mac-----------: | 6E 6F 70 71 72 73 74 75 | 76 77 61 62 63 64 65 66 | nopqrstuvwabcdef
D(314305) OPENTHREAD:[D] Mac-----------: | 67 68 69 BD 12 F7 47 F4 | 0A .. .. .. .. .. .. .. | ghi=.wGt........
D(314305) OPENTHREAD:[D] Mac-----------: ------------------------------------------------------------------------
I(314315) OPENTHREAD:[I] MeshForwarder-: Received IPv6 ICMP6 msg, len:80, chksum:78fa, ecn:no, from:0x4400, sec:yes, prio:normal, rss:-12.0
I(314315) OPENTHREAD:[I] MeshForwarder-:     src:[fdb5:7e4f:e7:1:c87d:8616:53e3:cbb3]
I(314315) OPENTHREAD:[I] MeshForwarder-:     dst:[fdb5:b79:b3d8:ac57:c9c7:7499:67a1:5928]
D(314315) OPENTHREAD:[D] Mac-----------: Idle mode: Radio receiving on channel 26
D (314595) OPENTHREAD: Millisecond timer alarm start running, t0=314591, dt=661
I(314595) OPENTHREAD:[I] RoutingManager: Evaluating routing policy
I(314595) OPENTHREAD:[I] RoutingManager: Found a favored on-link prefix 2408:8215:512a:d6e0::/64
I(314595) OPENTHREAD:[I] RoutingManager: Local on-link prefix state: Advertising -> Deprecating (fdb5:b79:b3d8:ac57::/64)
I(314595) OPENTHREAD:[I] RoutingManager: Evaluating NAT64 prefix
I(314595) OPENTHREAD:[I] RoutingManager: Preparing RA
I(314595) OPENTHREAD:[I] RoutingManager: - PIO fdb5:b79:b3d8:ac57::/64 (valid:1796, preferred:0)
I(314595) OPENTHREAD:[I] RoutingManager: - RIO fdb5:7e4f:e7:1::/64 (lifetime:1800, prf:medium)
I (314595) OPENTHREAD: Received PIO
I(314595) OPENTHREAD:[I] RoutingManager: Sent RA on infra netif 2
D(314595) OPENTHREAD:[D] RoutingManager: =============[[BR-CERT] direction=send | type=RA | len=064]=============
D(314595) OPENTHREAD:[D] RoutingManager: | 86 00 00 00 00 00 00 00 | 00 00 00 00 00 00 00 00 | ................
D(314605) OPENTHREAD:[D] RoutingManager: | 03 04 40 C0 00 00 07 04 | 00 00 00 00 00 00 00 00 | ..@@............
D(314605) OPENTHREAD:[D] RoutingManager: | FD B5 0B 79 B3 D8 AC 57 | 00 00 00 00 00 00 00 00 | }5.y3X,W........
D(314605) OPENTHREAD:[D] RoutingManager: | 18 02 40 00 00 00 07 08 | FD B5 7E 4F 00 E7 00 01 | ..@.....}5~O.g..
D(314605) OPENTHREAD:[D] RoutingManager: ------------------------------------------------------------------------
I(314605) OPENTHREAD:[I] RoutingManager: Will evaluate routing policy in 04:23.327 (263327 msec)
D (314605) OPENTHREAD: Millisecond timer alarm fired
I(314605) OPENTHREAD:[I] RoutingManager: Received RA from fe80:0:0:0:4a27:e2ff:fe14:43c4 on infra netif 2
D(314605) OPENTHREAD:[D] RoutingManager: =============[[BR-CERT] direction=recv | type=RA | len=064]=============
D(314605) OPENTHREAD:[D] RoutingManager: | 86 00 7C E0 00 00 00 00 | 00 00 00 00 00 00 00 00 | ..|`............
D(314605) OPENTHREAD:[D] RoutingManager: | 03 04 40 C0 00 00 07 04 | 00 00 00 00 00 00 00 00 | ..@@............
D(314605) OPENTHREAD:[D] RoutingManager: | FD B5 0B 79 B3 D8 AC 57 | 00 00 00 00 00 00 00 00 | }5.y3X,W........
D(314605) OPENTHREAD:[D] RoutingManager: | 18 02 40 00 00 00 07 08 | FD B5 7E 4F 00 E7 00 01 | ..@.....}5~O.g..
D(314605) OPENTHREAD:[D] RoutingManager: ------------------------------------------------------------------------
I(314605) OPENTHREAD:[I] RoutingManager: - RA Header - default route - lifetime:0
I(314615) OPENTHREAD:[I] RoutingManager: - PIO fdb5:b79:b3d8:ac57::/64 (valid:1796, preferred:0)
D(314615) OPENTHREAD:[D] RoutingManager: Prefix stale timer scheduled in 1799612 ms
D (314725) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
V (314725) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
V (314725) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
D (314725) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
D (314725) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
V (314725) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
V (314725) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
D (314725) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
D (315265) OPENTHREAD: Millisecond timer alarm start running, t0=315261, dt=7547
D (315265) OPENTHREAD: Millisecond timer alarm start running, t0=315262, dt=993
D (315265) OPENTHREAD: Millisecond timer alarm fired
D(315295) OPENTHREAD:[D] Mac-----------: Request to start operation "TransmitDataDirect"
D(315295) OPENTHREAD:[D] Mac-----------: Starting operation "TransmitDataDirect"
D(315295) OPENTHREAD:[D] SubMac--------: RadioState: Receive -> CsmaBackoff
D(315295) OPENTHREAD:[D] SubMac--------: RadioState: CsmaBackoff -> Transmit
D (315295) OPENTHREAD: sent radio frame
D(315295) OPENTHREAD:[D] Platform------: Sent spinel frame, flg:0x2, tid:10, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:90, channel:26, maxbackoffs:4, maxretries:15 ...
D(315295) OPENTHREAD:[D] Platform------: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
D (315315) OPENTHREAD: radio uart read event
D (315315) OPENTHREAD: received hdlc radio frame
D(315315) OPENTHREAD:[D] Platform------: Received spinel frame, flg:0x2, tid:10, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
D(315315) OPENTHREAD:[D] SubMac--------: RadioState: Transmit -> Receive
D(315315) OPENTHREAD:[D] Mac-----------: ==============================[TX len=090]==============================
D(315315) OPENTHREAD:[D] Mac-----------: | 69 98 19 86 FC 00 44 00 | 48 0D 91 B8 00 00 01 78 | i...|.D.H..8...x
D(315315) OPENTHREAD:[D] Mac-----------: | 85 01 3A 7F 24 08 82 15 | 51 2A D6 E0 61 30 8F 80 | ..:.$...Q*V`a0..
D(315325) OPENTHREAD:[D] Mac-----------: | 67 11 08 5E C8 7D 86 16 | 53 E3 CB B3 80 00 B4 3A | g..^H}..ScK3..4:
D(315325) OPENTHREAD:[D] Mac-----------: | 00 01 07 5C 61 62 63 64 | 65 66 67 68 69 6A 6B 6C | ...\abcdefghijkl
D(315325) OPENTHREAD:[D] Mac-----------: | 6D 6E 6F 70 71 72 73 74 | 75 76 77 61 62 63 64 65 | mnopqrstuvwabcde
D(315325) OPENTHREAD:[D] Mac-----------: | 66 67 68 69 45 9E C5 8A | 41 77 .. .. .. .. .. .. | fghiE.E.Aw......
D(315325) OPENTHREAD:[D] Mac-----------: ------------------------------------------------------------------------
D(315325) OPENTHREAD:[D] Mac-----------: Finishing operation "TransmitDataDirect"
I(315325) OPENTHREAD:[I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:80, chksum:b43a, ecn:no, to:0x4400, sec:yes, prio:normal
I(315325) OPENTHREAD:[I] MeshForwarder-:     src:[2408:8215:512a:d6e0:6130:8f80:6711:85e]
I(315325) OPENTHREAD:[I] MeshForwarder-:     dst:[fdb5:7e4f:e7:1:c87d:8616:53e3:cbb3]
D(315325) OPENTHREAD:[D] Mac-----------: Idle mode: Radio receiving on channel 26
D (315345) OPENTHREAD: radio uart read event
D (315345) OPENTHREAD: received hdlc radio frame
D(315345) OPENTHREAD:[D] Platform------: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:89, rssi:-12 ...
D(315345) OPENTHREAD:[D] Platform------: ... noise:-128, flags:0x0000, channel:26, lqi:10, timestamp:3738357395, rxerr:0
D(315345) OPENTHREAD:[D] Mac-----------: Received frame from short address 0x4400
D(315345) OPENTHREAD:[D] Mac-----------: Rx security - frame counter 20702
D(315345) OPENTHREAD:[D] Mac-----------: ==============================[RX len=089]==============================
D(315355) OPENTHREAD:[D] Mac-----------: | 69 98 B0 86 FC 00 48 00 | 44 0D DE 50 00 00 01 7B | i.0.|.H.D.^P...{
D(315355) OPENTHREAD:[D] Mac-----------: | D0 10 3A C8 7D 86 16 53 | E3 CB B3 24 08 82 15 51 | P.:H}..ScK3$...Q
D(315355) OPENTHREAD:[D] Mac-----------: | 2A D6 E0 61 30 8F 80 67 | 11 08 5E 81 00 B3 3A 00 | *V`a0..g..^..3:.
D(315355) OPENTHREAD:[D] Mac-----------: | 01 07 5C 61 62 63 64 65 | 66 67 68 69 6A 6B 6C 6D | ..\abcdefghijklm
D(315355) OPENTHREAD:[D] Mac-----------: | 6E 6F 70 71 72 73 74 75 | 76 77 61 62 63 64 65 66 | nopqrstuvwabcdef
D(315355) OPENTHREAD:[D] Mac-----------: | 67 68 69 AE 74 5A 9C F4 | 0A .. .. .. .. .. .. .. | ghi.tZ.t........
D(315355) OPENTHREAD:[D] Mac-----------: ------------------------------------------------------------------------
I(315355) OPENTHREAD:[I] MeshForwarder-: Received IPv6 ICMP6 msg, len:80, chksum:b33a, ecn:no, from:0x4400, sec:yes, prio:normal, rss:-12.0
I(315355) OPENTHREAD:[I] MeshForwarder-:     src:[fdb5:7e4f:e7:1:c87d:8616:53e3:cbb3]
I(315355) OPENTHREAD:[I] MeshForwarder-:     dst:[2408:8215:512a:d6e0:6130:8f80:6711:85e]
D(315365) OPENTHREAD:[D] Mac-----------: Idle mode: Radio receiving on channel 26
D (316275) OPENTHREAD: Millisecond timer alarm start running, t0=316271, dt=6537
D (316275) OPENTHREAD: Millisecond timer alarm start running, t0=316272, dt=981
D (316275) OPENTHREAD: Millisecond timer alarm fired
D(316285) OPENTHREAD:[D] Mac-----------: Request to start operation "TransmitDataDirect"
D(316295) OPENTHREAD:[D] Mac-----------: Starting operation "TransmitDataDirect"
D(316295) OPENTHREAD:[D] SubMac--------: RadioState: Receive -> CsmaBackoff
D(316295) OPENTHREAD:[D] SubMac--------: RadioState: CsmaBackoff -> Transmit

After running like this for a while, my computer started displaying 'Request Timed Out' messages, and there were no forwarding-related logs:

D (327455) OPENTHREAD: radio uart read event
D (327455) OPENTHREAD: received hdlc radio frame
D(327455) OPENTHREAD:[D] Platform------: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:89, rssi:-12 ...
D(327455) OPENTHREAD:[D] Platform------: ... noise:-128, flags:0x0000, channel:26, lqi:10, timestamp:3750467436, rxerr:0
D(327455) OPENTHREAD:[D] Mac-----------: Received frame from short address 0x4400
D(327455) OPENTHREAD:[D] Mac-----------: Rx security - frame counter 20714
D(327455) OPENTHREAD:[D] Mac-----------: ==============================[RX len=089]==============================
D(327465) OPENTHREAD:[D] Mac-----------: | 69 98 BD 86 FC 00 48 00 | 44 0D EA 50 00 00 01 7B | i.=.|.H.D.jP...{
D(327465) OPENTHREAD:[D] Mac-----------: | D0 10 3A C8 7D 86 16 53 | E3 CB B3 24 08 82 15 51 | P.:H}..ScK3$...Q
D(327465) OPENTHREAD:[D] Mac-----------: | 2A D6 E0 61 30 8F 80 67 | 11 08 5E 81 00 B3 2E 00 | *V`a0..g..^..3..
D(327465) OPENTHREAD:[D] Mac-----------: | 01 07 68 61 62 63 64 65 | 66 67 68 69 6A 6B 6C 6D | ..habcdefghijklm
D(327465) OPENTHREAD:[D] Mac-----------: | 6E 6F 70 71 72 73 74 75 | 76 77 61 62 63 64 65 66 | nopqrstuvwabcdef
D(327465) OPENTHREAD:[D] Mac-----------: | 67 68 69 E9 E6 64 F8 F4 | 0A .. .. .. .. .. .. .. | ghiifdxt........
D(327465) OPENTHREAD:[D] Mac-----------: ------------------------------------------------------------------------
I(327465) OPENTHREAD:[I] MeshForwarder-: Received IPv6 ICMP6 msg, len:80, chksum:b32e, ecn:no, from:0x4400, sec:yes, prio:normal, rss:-12.0
I(327465) OPENTHREAD:[I] MeshForwarder-:     src:[fdb5:7e4f:e7:1:c87d:8616:53e3:cbb3]
I(327465) OPENTHREAD:[I] MeshForwarder-:     dst:[2408:8215:512a:d6e0:6130:8f80:6711:85e]
D(327475) OPENTHREAD:[D] Mac-----------: Idle mode: Radio receiving on channel 26
D (327495) OPENTHREAD: Millisecond timer alarm start running, t0=327491, dt=760
D (327495) OPENTHREAD: Millisecond timer alarm fired
D (328265) OPENTHREAD: Millisecond timer alarm start running, t0=328261, dt=7134
D (328265) OPENTHREAD: Millisecond timer alarm start running, t0=328262, dt=989
D (328265) OPENTHREAD: Millisecond timer alarm fired
D (329265) OPENTHREAD: Millisecond timer alarm start running, t0=329261, dt=6134
D (329265) OPENTHREAD: Millisecond timer alarm start running, t0=329262, dt=987
D (329265) OPENTHREAD: Millisecond timer alarm fired
D (330265) OPENTHREAD: Millisecond timer alarm start running, t0=330261, dt=5134
D (330265) OPENTHREAD: Millisecond timer alarm start running, t0=330262, dt=983
D (330265) OPENTHREAD: Millisecond timer alarm fired
D (331265) OPENTHREAD: Millisecond timer alarm start running, t0=331261, dt=4134
D (331265) OPENTHREAD: Millisecond timer alarm start running, t0=331262, dt=979
D (331265) OPENTHREAD: Millisecond timer alarm fired
D (332255) OPENTHREAD: Millisecond timer alarm start running, t0=332251, dt=3144
D (332255) OPENTHREAD: Millisecond timer alarm start running, t0=332252, dt=988
D (332255) OPENTHREAD: Millisecond timer alarm fired
D (333255) OPENTHREAD: Millisecond timer alarm start running, t0=333251, dt=2144
D (333255) OPENTHREAD: Millisecond timer alarm start running, t0=333252, dt=986

Everything was back to normal until the routing strategy changed again:

I(590595) OPENTHREAD:[I] RoutingManager: Sent Neighbor Solicitation to fe80:0:0:0:0:0:0:1 - attempt:2/5
D (590595) OPENTHREAD: Millisecond timer alarm fired
D (591265) OPENTHREAD: Millisecond timer alarm start running, t0=591261, dt=330
D (591265) OPENTHREAD: Millisecond timer alarm fired
D (591605) OPENTHREAD: Millisecond timer alarm start running, t0=591601, dt=650
I(591605) OPENTHREAD:[I] RoutingManager: Sent Neighbor Solicitation to fe80:0:0:0:0:0:0:1 - attempt:3/5
D (591605) OPENTHREAD: Millisecond timer alarm fired
D (592265) OPENTHREAD: Millisecond timer alarm start running, t0=592261, dt=340
D (592265) OPENTHREAD: Millisecond timer alarm fired
D (592615) OPENTHREAD: Millisecond timer alarm start running, t0=592611, dt=643
I(592615) OPENTHREAD:[I] RoutingManager: Sent Neighbor Solicitation to fe80:0:0:0:0:0:0:1 - attempt:4/5
D (592615) OPENTHREAD: Millisecond timer alarm fired
D (593265) OPENTHREAD: Millisecond timer alarm start running, t0=593261, dt=350
D (593265) OPENTHREAD: Millisecond timer alarm fired
D (593625) OPENTHREAD: Millisecond timer alarm start running, t0=593621, dt=631
I(593625) OPENTHREAD:[I] RoutingManager: Sent Neighbor Solicitation to fe80:0:0:0:0:0:0:1 - attempt:5/5
D (593625) OPENTHREAD: Millisecond timer alarm fired
D (594265) OPENTHREAD: Millisecond timer alarm start running, t0=594261, dt=1360
D (594265) OPENTHREAD: Millisecond timer alarm start running, t0=594262, dt=992
D (594265) OPENTHREAD: Millisecond timer alarm fired
D (595275) OPENTHREAD: Millisecond timer alarm start running, t0=595271, dt=350
D (595275) OPENTHREAD: Millisecond timer alarm fired
D (595635) OPENTHREAD: Millisecond timer alarm start running, t0=595631, dt=625
I(595635) OPENTHREAD:[I] RoutingManager: No response to all Neighbor Solicitations attempts from router fe80:0:0:0:0:0:0:1
D (595635) OPENTHREAD: Millisecond timer alarm fired
D(595635) OPENTHREAD:[D] RoutingManager: Prefix stale timer stopped
I(595635) OPENTHREAD:[I] RoutingManager: Will evaluate routing policy in 00:03.614 (3614 msec)
D (596275) OPENTHREAD: Millisecond timer alarm start running, t0=596271, dt=2976
D (596275) OPENTHREAD: Millisecond timer alarm start running, t0=596272, dt=985
D (596275) OPENTHREAD: Millisecond timer alarm fired
D (597275) OPENTHREAD: Millisecond timer alarm start running, t0=597271, dt=1976
D (597275) OPENTHREAD: Millisecond timer alarm start running, t0=597272, dt=988
D (597275) OPENTHREAD: Millisecond timer alarm fired
D (598275) OPENTHREAD: Millisecond timer alarm start running, t0=598271, dt=976
D (598275) OPENTHREAD: Millisecond timer alarm fired
D (599265) OPENTHREAD: Millisecond timer alarm start running, t0=599261, dt=0
I(599265) OPENTHREAD:[I] RoutingManager: Evaluating routing policy
I(599265) OPENTHREAD:[I] RoutingManager: Local on-link prefix state: Deprecating -> Publishing (fdb5:b79:b3d8:ac57::/64)
D (599265) nvs: nvs_get_str_or_blob OT1003
I(599265) OPENTHREAD:[I] RoutingManager: Local on-link prefix state: Publishing -> Advertising (fdb5:b79:b3d8:ac57::/64)
I(599265) OPENTHREAD:[I] RoutingManager: Evaluating NAT64 prefix
I(599265) OPENTHREAD:[I] RoutingManager: Preparing RA
D (599275) nvs: nvs_get_str_or_blob OT1003
I(599275) OPENTHREAD:[I] RoutingManager: - PIO fdb5:b79:b3d8:ac57::/64 (valid:1800, preferred:1800)
I(599275) OPENTHREAD:[I] RoutingManager: - RIO fdb5:7e4f:e7:1::/64 (lifetime:1800, prf:medium)
I (599275) OPENTHREAD: Received PIO
I(599275) OPENTHREAD:[I] RoutingManager: Sent RA on infra netif 2
D(599275) OPENTHREAD:[D] RoutingManager: =============[[BR-CERT] direction=send | type=RA | len=064]=============
D(599275) OPENTHREAD:[D] RoutingManager: | 86 00 00 00 00 00 00 00 | 00 00 00 00 00 00 00 00 | ................
D(599275) OPENTHREAD:[D] RoutingManager: | 03 04 40 C0 00 00 07 08 | 00 00 07 08 00 00 00 00 | ..@@............
D(599275) OPENTHREAD:[D] RoutingManager: | FD B5 0B 79 B3 D8 AC 57 | 00 00 00 00 00 00 00 00 | }5.y3X,W........
D(599275) OPENTHREAD:[D] RoutingManager: | 18 02 40 00 00 00 07 08 | FD B5 7E 4F 00 E7 00 01 | ..@.....}5~O.g..
D(599285) OPENTHREAD:[D] RoutingManager: ------------------------------------------------------------------------
I(599285) OPENTHREAD:[I] RoutingManager: Will evaluate routing policy in 08:02.465 (482465 msec)
D (599285) OPENTHREAD: Millisecond timer alarm fired
I(599285) OPENTHREAD:[I] RoutingManager: Received RA from fe80:0:0:0:4a27:e2ff:fe14:43c4 on infra netif 2
D(599285) OPENTHREAD:[D] RoutingManager: =============[[BR-CERT] direction=recv | type=RA | len=064]=============
D(599285) OPENTHREAD:[D] RoutingManager: | 86 00 75 D4 00 00 00 00 | 00 00 00 00 00 00 00 00 | ..uT............
D(599285) OPENTHREAD:[D] RoutingManager: | 03 04 40 C0 00 00 07 08 | 00 00 07 08 00 00 00 00 | ..@@............
D(599285) OPENTHREAD:[D] RoutingManager: | FD B5 0B 79 B3 D8 AC 57 | 00 00 00 00 00 00 00 00 | }5.y3X,W........
D(599285) OPENTHREAD:[D] RoutingManager: | 18 02 40 00 00 00 07 08 | FD B5 7E 4F 00 E7 00 01 | ..@.....}5~O.g..
D(599285) OPENTHREAD:[D] RoutingManager: ------------------------------------------------------------------------
I(599285) OPENTHREAD:[I] RoutingManager: - RA Header - default route - lifetime:0
D (599285) OPENTHREAD: Millisecond timer alarm start running, t0=599290, dt=8913
D (599285) OPENTHREAD: Millisecond timer alarm start running, t0=599291, dt=967
D (599295) OPENTHREAD: Millisecond timer alarm fired
D (599395) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
V (599395) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
D (599395) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
V (599395) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
D (599395) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
V (599395) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
V (599395) esp_netif_lwip: esp_netif_get_ip6_linklocal esp-netif:0x3fcbe1ec
D (599395) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcbe1ec
D (600275) OPENTHREAD: Millisecond timer alarm start running, t0=600271, dt=7932
D (600275) OPENTHREAD: Millisecond timer alarm start running, t0=600272, dt=985
D (600275) OPENTHREAD: Millisecond timer alarm fired
D(600335) OPENTHREAD:[D] Mac-----------: Request to start operation "TransmitDataDirect"
D(600335) OPENTHREAD:[D] Mac-----------: Starting operation "TransmitDataDirect"
D(600335) OPENTHREAD:[D] SubMac--------: RadioState: Receive -> CsmaBackoff
D(600335) OPENTHREAD:[D] SubMac--------: RadioState: CsmaBackoff -> Transmit
D (600335) OPENTHREAD: sent radio frame
D(600335) OPENTHREAD:[D] Platform------: Sent spinel frame, flg:0x2, tid:13, cmd:PROP_VALUE_SET, key:STREAM_RAW, len:90, channel:26, maxbackoffs:4, maxretries:15 ...
D(600335) OPENTHREAD:[D] Platform------: ... csmaCaEnabled:1, isHeaderUpdated:0, isARetx:0, skipAes:0, txDelay:0, txDelayBase:0
D (600355) OPENTHREAD: radio uart read event
D (600355) OPENTHREAD: received hdlc radio frame
D(600355) OPENTHREAD:[D] Platform------: Received spinel frame, flg:0x2, tid:13, cmd:PROP_VALUE_IS, key:LAST_STATUS, status:OK
D(600355) OPENTHREAD:[D] SubMac--------: RadioState: Transmit -> Receive
D(600355) OPENTHREAD:[D] Mac-----------: ==============================[TX len=090]==============================
D(600355) OPENTHREAD:[D] Mac-----------: | 69 98 B3 86 FC 00 44 00 | 48 0D 17 B9 00 00 01 78 | i.3.|.D.H..9...x
D(600355) OPENTHREAD:[D] Mac-----------: | 85 01 3A 7F FD B5 0B 79 | B3 D8 AC 57 C9 C7 74 99 | ..:.}5.y3X,WIGt.
D(600355) OPENTHREAD:[D] Mac-----------: | 67 A1 59 28 C8 7D 86 16 | 53 E3 CB B3 80 00 79 5F | g!Y(H}..ScK3..y_
D(600365) OPENTHREAD:[D] Mac-----------: | 00 01 07 F6 61 62 63 64 | 65 66 67 68 69 6A 6B 6C | ...vabcdefghijkl
D(600365) OPENTHREAD:[D] Mac-----------: | 6D 6E 6F 70 71 72 73 74 | 75 76 77 61 62 63 64 65 | mnopqrstuvwabcde
D(600365) OPENTHREAD:[D] Mac-----------: | 66 67 68 69 45 9E C5 8A | 41 77 .. .. .. .. .. .. | fghiE.E.Aw......
D(600365) OPENTHREAD:[D] Mac-----------: ------------------------------------------------------------------------
D(600365) OPENTHREAD:[D] Mac-----------: Finishing operation "TransmitDataDirect"
I(600365) OPENTHREAD:[I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:80, chksum:795f, ecn:no, to:0x4400, sec:yes, prio:normal
I(600365) OPENTHREAD:[I] MeshForwarder-:     src:[fdb5:b79:b3d8:ac57:c9c7:7499:67a1:5928]
I(600365) OPENTHREAD:[I] MeshForwarder-:     dst:[fdb5:7e4f:e7:1:c87d:8616:53e3:cbb3]
D(600365) OPENTHREAD:[D] Mac-----------: Idle mode: Radio receiving on channel 26
D (600375) OPENTHREAD: radio uart read event
D (600375) OPENTHREAD: received hdlc radio frame
D(600375) OPENTHREAD:[D] Platform------: Received spinel frame, flg:0x2, tid:0, cmd:PROP_VALUE_IS, key:STREAM_RAW, len:89, rssi:-12 ...
D(600375) OPENTHREAD:[D] Platform------: ... noise:-128, flags:0x0000, channel:26, lqi:10, timestamp:4023388389, rxerr:0
D(600375) OPENTHREAD:[D] Mac-----------: Received frame from short address 0x4400
D(600375) OPENTHREAD:[D] Mac-----------: Rx security - frame counter 20837
D(600375) OPENTHREAD:[D] Mac-----------: ==============================[RX len=089]==============================
D(600385) OPENTHREAD:[D] Mac-----------: | 69 98 3F 86 FC 00 48 00 | 44 0D 65 51 00 00 01 7B | i.?.|.H.D.eQ...{
D(600385) OPENTHREAD:[D] Mac-----------: | D0 10 3A C8 7D 86 16 53 | E3 CB B3 FD B5 0B 79 B3 | P.:H}..ScK3}5.y3
D(600385) OPENTHREAD:[D] Mac-----------: | D8 AC 57 C9 C7 74 99 67 | A1 59 28 81 00 78 5F 00 | X,WIGt.g!Y(..x_.
D(600385) OPENTHREAD:[D] Mac-----------: | 01 07 F6 61 62 63 64 65 | 66 67 68 69 6A 6B 6C 6D | ..vabcdefghijklm
D(600385) OPENTHREAD:[D] Mac-----------: | 6E 6F 70 71 72 73 74 75 | 76 77 61 62 63 64 65 66 | nopqrstuvwabcdef
D(600385) OPENTHREAD:[D] Mac-----------: | 67 68 69 0C 41 70 8E F4 | 0A .. .. .. .. .. .. .. | ghi.Ap.t........
D(600385) OPENTHREAD:[D] Mac-----------: ------------------------------------------------------------------------
I(600385) OPENTHREAD:[I] MeshForwarder-: Received IPv6 ICMP6 msg, len:80, chksum:785f, ecn:no, from:0x4400, sec:yes, prio:normal, rss:-12.0
I(600385) OPENTHREAD:[I] MeshForwarder-:     src:[fdb5:7e4f:e7:1:c87d:8616:53e3:cbb3]
I(600385) OPENTHREAD:[I] MeshForwarder-:     dst:[fdb5:b79:b3d8:ac57:c9c7:7499:67a1:5928]
D(600395) OPENTHREAD:[D] Mac-----------: Idle mode: Radio receiving on channel 26

I don't know how to configure OTBR or my router to solve this problem.

@github-actions github-actions bot changed the title Thread communication with external networks is unstable Thread communication with external networks is unstable (TZ-352) Oct 15, 2023
@alexyuoouy
Copy link
Author

英语很烂,不知道有没有表达清楚,使用中文说一遍:我使用我的电脑一直在ping 一个node,时而通时而断,断的时候提示请求超时。我现在的网络拓扑是这样,我有一个路由器,我的电脑和otbr都连接到了这个路由器,这个路由器支持ipv6,并且没有使用dhcpv6,我的电脑和otbr都生成了运营商分配的ipv6前缀的地址,我手里还有一个ESP32-H2-DevKitM-1,他作为一个node添加进了thread网络,起初他的角色是child,后来自动切换成了router。现在我是用这个作为router的node去ping我的电脑,可以ping通,使用电脑去ping这个node,有时也能ping通,但是会出现我上面说的现象。我将otbr的日志等级设置到了debug,通过日志我看到了otbr似乎一直在切换它的路由策略,因为我现在的网络中存在了两个ipv6前缀,一个是运营商给我分配的,另一个是otbr的,这可能导致某个有效的路由一直在被弃用和被启用之间切换,从而导致了上面的现象。

@alexyuoouy alexyuoouy closed this as not planned Won't fix, can't repro, duplicate, stale Oct 15, 2023
@alexyuoouy alexyuoouy reopened this Oct 15, 2023
@zwx1995esp
Copy link
Collaborator

问下,你有wireshark可以抓包嘛?可以抓一下 ping 过程中,时而通时而断的时候wireshark的包吗?流程如下,
1.先用电脑连上路由器,然后打印一下电脑的ip地址
2.BR连上路由器
3.Node连上路由器
4.在node上 输入 ipaddr 把结果记录一下
5.在电脑上打印电脑的所有ip地址和ip路由(windows 输入 route)
6.电脑上打开wireshark,监听连接到路由器的interface
7.电脑开始ping node,复现一下时断时续的问题,然后保存一下wireshark抓的包。

@alexyuoouy
Copy link
Author

问下,你有wireshark可以抓包嘛?可以抓一下 ping 过程中,时而通时而断的时候wireshark的包吗?流程如下, 1.先用电脑连上路由器,然后打印一下电脑的ip地址 2.BR连上路由器 3.Node连上路由器 4.在node上 输入 ipaddr 把结果记录一下 5.在电脑上打印电脑的所有ip地址和ip路由(windows 输入 route) 6.电脑上打开wireshark,监听连接到路由器的interface 7.电脑开始ping node,复现一下时断时续的问题,然后保存一下wireshark抓的包。

由于抓包日志里带了太多信息,是否可以提供一个邮箱或者其它联系方式单独发给你。

@zwx1995esp
Copy link
Collaborator

公司邮箱附件大小上限是5M,你可以直接打一个压缩包,上传到github这个上面就可以(把压缩包拖到comment框里面就行)。

@alexyuoouy
Copy link
Author

请阅读压缩包里的readme,只提供了ICMPV6的数据包,如果需要其它请告诉我还需要哪些类型的数据包。
br通信测试.zip

@zwx1995esp
Copy link
Collaborator

zwx1995esp commented Oct 18, 2023

请尝试修改这个代码:
$IDF_PATH/components/lwip/lwip/src/core/ipv6/nd6.c line 549:
https://github.com/espressif/esp-lwip/blob/5c4f899f8e7b58ef53522b6f832fc940e29bf0b9/src/core/ipv6/nd6.c#L549

   nd6_send_na(inp, &target_address, ND6_FLAG_SOLICITED | ND6_FLAG_OVERRIDE);

改为这个:

  nd6_send_na(inp, &target_address, ND6_FLAG_ROUTER | ND6_FLAG_SOLICITED | ND6_FLAG_OVERRIDE);

应该会对你的问题有帮助

@alexyuoouy
Copy link
Author

好的,非常感谢,我会试一下,我还有个问题请教一下,如果node使用了matter(比如esp-matter里的light例程),该怎样连接br和电脑端的chip-tool通信?

@chshu
Copy link
Collaborator

chshu commented Oct 18, 2023

br 不需要做任何改动,只要电脑和 br 能ping 通,chip-tool 就可以和 br 通信。

在用 chip-tool 给 Thread 设备配网时,operationalDataset 是从 BR 读出来的 dataset:

dataset active -x

chip-tool 指令参考
https://docs.espressif.com/projects/esp-matter/en/latest/esp32h2/developing.html#commissioning

@alexyuoouy
Copy link
Author

请尝试修改这个代码: $IDF_PATH/components/lwip/lwip/src/core/ipv6/nd6.c line 549: https://github.com/espressif/esp-lwip/blob/5c4f899f8e7b58ef53522b6f832fc940e29bf0b9/src/core/ipv6/nd6.c#L549

   nd6_send_na(inp, &target_address, ND6_FLAG_SOLICITED | ND6_FLAG_OVERRIDE);

改为这个:

  nd6_send_na(inp, &target_address, ND6_FLAG_ROUTER | ND6_FLAG_SOLICITED | ND6_FLAG_OVERRIDE);

应该会对你的问题有帮助

我连续ping了近一个小时,没有再出现请求超时的情况,这个更改是否考虑提交到esp-idf中?

@alexyuoouy
Copy link
Author

br 不需要做任何改动,只要电脑和 br 能ping 通,chip-tool 就可以和 br 通信。

在用 chip-tool 给 Thread 设备配网时,operationalDataset 是从 BR 读出来的 dataset:

dataset active -x

chip-tool 指令参考 https://docs.espressif.com/projects/esp-matter/en/latest/esp32h2/developing.html#commissioning

这个文档描述的好像是通过ble给节点配网,那是否我的电脑还需要一个ble-dongle,这个ble-dongle有什么要求吗,笔记本电脑带的蓝牙行不行?我可以通过手机给matter over thread的节点配网吗,通过二维,使用哪个app?

@chshu
Copy link
Collaborator

chshu commented Oct 19, 2023

笔记本带的蓝牙是可以的。

chip-tool 是 matter 日常开发用的工具,也可以用几个生态的 手机 APP (Google Home, Apple Homekit, Amazon Alexa),需要搭配生态的音箱作为 BR 才能用。

@zwx1995esp
Copy link
Collaborator

请尝试修改这个代码: $IDF_PATH/components/lwip/lwip/src/core/ipv6/nd6.c line 549: https://github.com/espressif/esp-lwip/blob/5c4f899f8e7b58ef53522b6f832fc940e29bf0b9/src/core/ipv6/nd6.c#L549

   nd6_send_na(inp, &target_address, ND6_FLAG_SOLICITED | ND6_FLAG_OVERRIDE);

改为这个:

  nd6_send_na(inp, &target_address, ND6_FLAG_ROUTER | ND6_FLAG_SOLICITED | ND6_FLAG_OVERRIDE);

应该会对你的问题有帮助

我连续ping了近一个小时,没有再出现请求超时的情况,这个更改是否考虑提交到esp-idf中?

这个我们会改到idf中。

@alexyuoouy
Copy link
Author

感谢各位解答,没有更多问题了。

@chshu chshu closed this as completed Oct 23, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants