Open benpicco opened 4 years ago
Since the netif-esp-now
thread is the running thread it is most likely the culprit. I usually use a patch like this to dig deeper:
diff --git a/core/include/mutex.h b/core/include/mutex.h
index 24129f8929..ff7dcca1f7 100644
--- a/core/include/mutex.h
+++ b/core/include/mutex.h
@@ -123,7 +123,12 @@ static inline void mutex_lock(mutex_t *mutex)
*
* @param[in] mutex Mutex object to unlock, must not be NULL.
*/
-void mutex_unlock(mutex_t *mutex);
+void _mutex_unlock(mutex_t *mutex);
+
+#include <stdio.h>
+#define mutex_unlock(mutex) \
+ printf("%s:%d: unlock %p\n", __FILE__, __LINE__, (void *)mutex); \
+ _mutex_unlock(mutex);
/**
* @brief Unlocks the mutex and sends the current thread to sleep
diff --git a/core/mutex.c b/core/mutex.c
index 0a52e72a9b..2412155e5f 100644
--- a/core/mutex.c
+++ b/core/mutex.c
@@ -70,7 +70,7 @@ int _mutex_lock(mutex_t *mutex, volatile uint8_t *blocking)
}
}
-void mutex_unlock(mutex_t *mutex)
+void _mutex_unlock(mutex_t *mutex)
{
unsigned irqstate = irq_disable();
It seems like the client node is crucial for this bug to occur. With the second node disconnected, the border router did not crash.
This also speaks for esp_now
:-/
2020-08-02 20:41:10,868 # scandone 2020-08-02 20:41:14,377 # LmacRxBlk:0 2020-08-02 20:41:15,378 # LmacRxBlk:0 2020-08-02 20:41:16,379 # LmacRxBlk:0 2020-08-02 20:41:17,380 # LmacRxBlk:0 2020-08-02 20:41:18,381 # LmacRxBlk:0 2020-08-02 20:41:19,162 # bcn_timout,ap_probe_send_start 2020-08-02 20:41:19,382 # LmacRxBlk:0 2020-08-02 20:41:20,383 # LmacRxBlk:0 2020-08-02 20:41:21,384 # LmacRxBlk:0
This indicates that MAC layer buffer is running out of memory for any reason. Therefore, the status is reset to disassociated
and it gets a beacon timeout afterwards.
2020-08-02 20:41:21,666 # ap_probe_send_over, rest wifi status to disassoc 2020-08-02 20:41:21,669 # state: 5 -> 0 (100) 2020-08-02 20:41:21,669 # rm 0 2020-08-02 20:41:21,675 # WiFi disconnected from ssid beersperminute, reason 200 (BEACON_TIMEOUT)
I have seen this already sporadically. Unfortunatly I wasn't able to figure out the reason because it is something that happens deep inside closed and completely undocumented code of ESP8266 libraries and the OCD capabilities are pretty poor for ESP8266.
Since the
netif-esp-now
thread is the running thread it is most likely the culprit.
Indeed, but the error message LmacRxBlk:0
might indicate the initial problem. esp-now
and esp-wifi
are using the same WiFi interface.
The cause LoadStoreAlignment
usually means that an attempt is made to access the memory at an address that is not 32-bit-word-aligned in a memory segment that supports only 32-bit-word-aligned access. But, there is nothing in core/mutex.c:75
https://github.com/RIOT-OS/RIOT/blob/763924bcaa71a5af91b4a2cb9c55369e16b86981/core/mutex.c#L75 that could cause an unaligned access. So, I would guess the exception happens at another place.
@benpicco The output of the register set could be helpful here. Normally, it should be in the output of the exception handling like the process listing.
Unfortunately a second panic happened when it attempted to print that. Can the esp8266 be debugged with a J-Link device?
Since the
netif-esp-now
thread is the running thread it is most likely the culprit. I usually use a patch like this to dig deeper:
I tried that, but it would produce new, unrelated crashes.
Theoretically yes, see here. But it doesn't work reliable. After having it working 2 or 3 times two years ago, I wasn't able to get it working anymore. I was using the ICprog OpenOCD JTAG Adapter. Maybe, it works more reliable with a J-Link device.
Unfortunately I can't support you for the next three days because I have exams all day and don't have the hardware at hand.
Can the esp8266 be debugged with a J-Link device?
@benpicco I have a working OpenOCD with a J-Link adapter, but I can't set up the appropriate test environment because my Speedport router doesn't support prefix delegation.
Even if I set a global unicast address manually for the esp_now
interface of the border router with
ifconfig 10 add 2001:db8::1/64
it doens't advertise the prefix although the esp_now
client node sends router solicitations and the RTR_ADV
attribute is set.
> ifconfig 10
Iface 10 HWaddr: 5E:CF:7F:80:3F:08 Channel: 8
L2-PDU:249 MTU:1280 HL:64 RTR
RTR_ADV 6LO Source address length: 6
Link type: wireless
inet6 addr: fe80::5ccf:7fff:fe80:3f08 scope: link VAL
inet6 addr: 2001:db8::1 scope: global VAL
...
Even if I set also the global unicast address manually for the esp_now
client node, it doesn't work.
ifconfig 11 add 2001:db8::2/64
Both nodes then have the corresponding route entry in the NIB, but can't reach each other via this global unicast address. After a short look with airmon-ng
it seems that both nodes send a Neighbor Solicitation for the respective global unicast address. The initiating node sends a Neighbor Solicitation, but doesn't get a reply. Instead, the solicited node itself sends a Neighbor Solicitation and doesn't get a reply.
I don't know what I am doing wrong now. Due to lack of time I was not able to look at it in more detail. So I can't reproduce the problem to try to debug it.
@miri64 Do you have any idea what the reason could be why Router Solicitation messages from the esp_now
node are not answered by the border router? Perhaps it is the same reason why Neighbor Discovery does not work on the esp_now
link. A Neighbor Solicitation message is answered by the solicited node with a Neighbor Solicitation message for the initiating node.
Because of the traffic and the resulting large number of debugging messages for the WiFi interface of the border router, I have only the debugging output on the esp_now
node for the Neighbor Discovery at hand:
Mh... my first thought was that maybe something is wrong with multicast on esp_now
, but your logs don't agree with that if I interpret them correctly.
For the following analysis I assume, esp_now
is not using 6Lo-ND, as I remember that we decided that in the past.
For the router solicitation it looks like the receiving node is just not configured to send router advertisements (is the RTR_ADV
bit set?), for the neighbor solicitation the receiving node seems to try to also start a neighbor solicitation process, this shouldn't happen however as the received neighbor solicitation should create a STALE neighbor cache entry. Is the address-resolution state-machine of the NIB compiled in?
Mh... my first thought was that maybe something is wrong with multicast on
esp_now
, but your logs don't agree with that if I interpret them correctly.
You interpret them correctly. Although esp_now
does not support MAC multicast but only MAC broadcast, IPv6 multicast works because IPv6 multicast packets are always sent via MAC Broadcast. For example, the Router Solicitation message which is sent by the esp_now
node with MAC address 1a:fe:34:e5:ef:04
to the all-router multicast address ff02::2
is received by the border router. ND also works for link local addresses.
For the following analysis I assume,
esp_now
is not using 6Lo-ND, as I remember that we decided that in the past.
Exactly, since you introduced the distinction between the so-called 6LN
nodes, which use 6Lo-ND, and the so-called 6Lo
nodes, which use 6Lo only for fragmentation, esp_now
no longer uses 6Lo-ND. If I remember correctly, the reason why esp_now
can't use 6Lo-ND is the lack of a real EUI, but I don't remember exactly.
For the router solicitation it looks like the receiving node is just not configured to send router advertisements (is the
RTR_ADV
bit set?),
RTR_ADV
seems to be set, at least according to the output for the esp_now
interface on the border router:
> ifconfig 10
Iface 10 HWaddr: 5E:CF:7F:80:3F:08 Channel: 8
L2-PDU:249 MTU:1280 HL:64 RTR
RTR_ADV 6LO Source address length: 6
Link type: wireless
inet6 addr: fe80::5ccf:7fff:fe80:3f08 scope: link VAL
inet6 addr: 2001:db8::1 scope: global VAL
for the neighbor solicitation the receiving node seems to try to also start a neighbor solicitation process, this shouldn't happen however
This is what I thought too.
as the received neighbor solicitation should create a STALE neighbor cache entry. Is the address-resolution state-machine of the NIB compiled in?
How can I figure out whether it is compiled in? It is activated by default and info-debug-variable-CLFAGS
doesn't contain a setting for it. On the border router it seems to be compiled in, at least I get an output for the WiFi interface:
> nib neigh
fe80::1 dev #11 lladdr 20:A6:80:56:A4:7B router STALE GC
On the esp_now
node the nib neigh
command gives no results.
Just to be sure, I set the global unicast address 2001:db8::1/64
manually since my Speedport Router doesn't support prefix delegation.
How can I figure out whether it is compiled in? It is activated by default and
info-debug-variable-CLFAGS
doesn't contain a setting for it. On the border router it seems to be compiled in, at least I get an output for the WiFi interface:> nib neigh fe80::1 dev #11 lladdr 20:A6:80:56:A4:7B router STALE GC
On the
esp_now
node thenib neigh
command gives no results.
Then it should be compiled in. Curious however, that the AR state is also printed (GC
== garbarge-collectible, so a "normal" NC entry, not one used for address registration according to 6Lo-ND). Since you are not using 6Lo-ND, it shouldn't be there. Is maybe some conflict between a compiled-in 6LN
NIB config but acting as a non-6LN causing the problem :thinking:?
For the border router, I just use @benpicco's example with RPL compiled in
USEMODULE='gnrc_rpl' make -C examples/gnrc_border_router BOARD=esp8266-esp-12x UPLINK=wifi WIFI_SSID='...' WIFI_PASS='...' flash
and on esp-now
node
CFLAGS='-DESP_NOW_CHANNEL=8' make -C examples/gnrc_networking BOARD=esp8266-esp-12x flash
For the following analysis I assume,
esp_now
is not using 6Lo-ND, as I remember that we decided that in the past. […]esp_now
no longer uses 6Lo-ND.
I hope I'm not waking any sleeping dogs, but esp_now
is marked as GNRC_NETIF_FLAGS_6LN
If I remember correctly, the reason why
esp_now
can't use 6Lo-ND is the lack of a real EUI,
That would be a very weak argument. Our 802.15.4 radios don't use a "real EUI" either, the use one generated by luid too.
Our 802.15.4 radios don't use a "real EUI" either, the use one generated by luid too.
They don't use the same addresses as IEEE 802.15.4 though. But if we assume that the 48-bit addresses of esp_now
are unique as we do with the the luid-based EUI-64s we could indeed use them to generate an EUI-64 as we do for Ethernet.
They don't use the same addresses as IEEE 802.15.4 though. But if we assume that the 48-bit addresses of
esp_now
are unique as we do with the the luid-based EUI-64s we could indeed use them to generate an EUI-64 as we do for Ethernet.
Declaring esp_now
as 6LN
node was introduced with PR #13561. At that time, we had a discussion after the PR was already merged whether esp_now
could be considered as a 6LN
node (https://github.com/RIOT-OS/RIOT/pull/13561#issuecomment-595276512). If I'm right, this discussion ended without result.
The initial discussion whether esp_now
could act as a 6LN
and use 6Lo-ND, multihop prefix dissemination a.s.o. started in PR #10524 with https://github.com/RIOT-OS/RIOT/pull/10524#issuecomment-451620006 when esp_now
was not working in border router any more. As I remember, issue #10723 and PR #10817 were results of this discussion.
But yes, the 48-bit address of esp-now
is a MAC address and therefore unique.
I hope I'm not waking any sleeping dogs, but
esp_now
is marked asGNRC_NETIF_FLAGS_6LN
Ok, if we suppose esp_now
to act as a 6LN node, would that explain why Router Solicitation is not answered because 6Lo-ND is used for prefixes dissemination? As I remember, DHCPv6 is used in @benpicco's test environment to get the prefix on esp_now
nodes.
As I remember, DHCPv6 is used in @benpicco's test environment to get the prefix on
esp_now
nodes.
DHCPv6 is only used to configure the 6LoWPAN border router's (6LBR's) prefix, for the WPAN's nodes prefix dissemation is used. A node configured as 6LoWPAN router (6LR) only starts sending router advertisements—i.e. replying to router solicitations—when it itself has its prefix configured (i.e. received a router advertisement from an upstream router or in the 6LBR's case got the prefix configured). A non-6LR 6LN (6LoWPAN node) does reply to router solicitations as it is not a router.
ping?
Description
When operating as a border router with an
esp_now
client, the border router will crash after a while with what seems like a disconnect event that is not handled correctly.Steps to reproduce the issue
Follow the steps described in https://github.com/RIOT-OS/Release-Specs/pull/185:
flash the border router
make -C examples/gnrc_border_router BOARD=esp8266-esp-12x UPLINK=wifi WIFI_SSID='your_ssd' WIFI_PASS='your_password' PORT=/dev/ttyUSB0 flash term
flash the
esp_now
clientIt seems like the client node is crucial for this bug to occur. With the second node disconnected, the border router did not crash.
Expected results
The border router keeps operating continuously.
Actual results
After a while (~10 Minutes) the border router crashes and reboots.
0x40228c38
points tocore/mutex.c:75
which is not very enlightening.Versions
RIOT master