Mesh back and forth seems to break connection

[kaushalyasat]

Hi,

We have one customer having two CoAP hosts and some CoAP clients in the form of wireless sensors. The sensors are paired to a single host. The pairing is actually in the app level, where the sensor discovers the network IP of the host in pairing host. All the devices have the same PANID and network key.

Recently we have seen a scenario where some sensors seemingly stopped communication with the paired host. By looking at the RSSI graphs, we thought is this caused by a sensor constantly swinging back and forth between two hosts (one host acting as a router). We dont have access to the CLI interface of the hosts as this is a remote site. We see the Sensor RSSI reported back. This is its RSSI with the router/leader immediately connected to at the time.  

Any ideas?

Cheers,

Kaushalya

[Edvin]

Hello,

Can you please try to capture a sniffer trace using the nRF Sniffer for 802154?

What do you mean by "swinging back and forth between two hosts"? Do you mean that it (an End Device, I assume) keeps changing between two routers?

Does it ever re-enter the network, or does it disconnect completely?

Do the nodes move around (physically)? Or are the nodes more or less stationary?

Best regards,

Edvin

[Christina Holman]

Are nRF Sniffer for 802154 ok? run 3

[kaushalyasat]

Hi Edvin,

Edvin said:

So in theory, if we take out the child sensors, and the two routers send messages back and forth, we could see the same behavior? Do you agree? 

What you mean is like shutdown the child sensor? But if we remove child sensor, we loose the data packet origination. So after that the parent and next routers wouldn't get any data packets anyway. So the behavior is not same isn't it, though the end result is the same? Moreover, in this instant, the child sensor is successfully sending the packets.

Edvin said:

Do you have a state changed callback in your parent's application?

Yes we have, as our application is derived of the same example. This is what we have.

static void on_thread_state_changed(uint32_t flags, void *context)
{
	struct openthread_context *ot_context = context;

	if (flags & OT_CHANGED_THREAD_ROLE) {
		switch (otThreadGetDeviceRole(ot_context->instance)) {
		case OT_DEVICE_ROLE_CHILD:
		case OT_DEVICE_ROLE_ROUTER:
		case OT_DEVICE_ROLE_LEADER:
			dk_set_led_on(OT_CONNECTION_LED);
			break;

		case OT_DEVICE_ROLE_DISABLED:
		case OT_DEVICE_ROLE_DETACHED:
		default:
			dk_set_led_off(OT_CONNECTION_LED);
			deactivate_provisionig();
			break;
		}
	}
}

We don't do anything special here. Also in the production hosts, we dont populate this LED. 

Edvin said:

Does that trigger when the nodes fall out?

I am afraid we don't know. As we only see this issue once it happened. What you suggest is role change from 'router' to 'disabled' kind of? I will check the role of the host once I detect this again. I will populate the LED mentioned above  as well.

I am trying to understand what the MLE does in the following scenario.

1. sensor  -> parent router -> destination router - good

2. sensor -> parent router  -x- destination router - bad

Q1. If both routers support child supervision, does the supervision packet originate from the destination router or the parent router?

Q2. Sensor wouldn't know scenario 2 has happened?

Q3. I guess when scenario 2 happens parent router would try to find another path via MLE? In our case we have about 10 routers all over the lab. One or two may be power cycled or shut down but not all and they are never moved from one place to the other. Also when I shutdown all the other routers, the sensors all connected back to the destination router. That proves there was at least one path to the parent router. (These sensors were about 10-50cm away from the parent router)

Cheers,

Kaushalya

Cheers,

Kaushalya

[Edvin]

kaushalyasat said:

But if we remove child sensor, we loose the data packet origination. So after that the parent and next routers wouldn't get any data packets anyway. So the behavior is not same isn't it, though the end result is the same?

Of course, but I am saying that if you were to generate dummy data at the parent and send it to the destination, in theory we could see the same, because the packets are lost between the parent router and the destination router. I am just thinking of possible ways to easier reproduce the issue.

kaushalyasat said:

We don't do anything special here. Also in the production hosts, we dont populate this LED. 

Is it possible to add some logging here, to see if there is a state change? It doesn't necessarily change to detached, so printing the actual state change can be helpful, if this is the case.

kaushalyasat said:

Q1. If both routers support child supervision, does the supervision packet originate from the destination router or the parent router?

I don't understand this question. And I don't understand how child supervision is relevant if the packet is lost between two nodes that are not children.

Q2: Depends. Is it a message that is supposed to be acknowledged or not? It wouldn't know that the scenario 2 happened, but it can detect a missing acknowledgement. The routers should be able to detect it, though. Because all messages should be acknowledged in the 802.15.4 layer.

Q3: Could it be that the packet path between the source and destination was through a router that was suddenly powered off? I am not 100% sure of the details, but openthread is not known for being very fast at determining that nodes are gone, and enabling new routes. 

Best regards,

Edvin

[kaushalyasat]

Hi Edvin,

Edvin said:

Is it possible to add some logging here, to see if there is a state change? It doesn't necessarily change to detached, so printing the actual state change can be helpful, if this is the case.

Something interesting I saw couple of days ago with a FTD on my desk. Normally when it powers up it connects to the network and change it's state to a router/leader. But this time it stayed on as a child! Now if a router, who is actively routing packets to another router suddenly change state to a child, I guess we can explain the behavior we are discussing here.

I guess a FTD will remain a child as long as no child connects to it, am I correct? But on the other hand I have seen many instances where a router's child table is empty, but it remains as a router. What conditions determine this transition from child-router and vice versa? 

Edvin said:

I don't understand this question. And I don't understand how child supervision is relevant if the packet is lost between two nodes that are not children.

Sorry, what I was trying to get at is, we implemented child supervision to prevent a SED disconnection from a destination router, but may be not a solution here. 

Edvin said:

Is it a message that is supposed to be acknowledged or not?

I can see that in 'coap_send_request (...)' function, it is hard coded to be non-ack type (COAP_TYPE_NON_CON). I dont know if there is a way to request with confirmation using any API. 

Suppose I clone this 'coap_send_request (...)' and modify it to send ACK packet, then I would need to pass a call back with it to know the ack is successful or not?

Edvin said:

Could it be that the packet path between the source and destination was through a router that was suddenly powered off?

This is possible. Our understanding is even it takes time to renegotiate new paths, it should be ok as we are sending temperature info in every 30 sec. Even if the rerout takes couple of minutes, it should be ok. But the issue is once the sensor's (SED)  data is lost, it remains so for days.

Cheers,

Kaushalya

[kaushalyasat]

Hi Edvin,

Dont know if this is relevant for this issue, but today I saw a parent router going into some error state. I was provisioning and un-provisioning an SED from a FTD for a new fw feature and all of a sudden I noticed the prov reply send by the FTD does not reach the SED. When I look into wireshark log, I could see the parent router not sending the reply back. Also when I had a look at TTM, it showed this parent router grayed out and ext address field was empty. After a while it 'auto-healed' by itself and my provisioning packets are now received by the SED. I wonder if this could be the error state the router ends up when we cant get SED data.

What do you think? 

Following is a pcap of when the provisioning was working and stopped. Provisioning router is 0xb000, provisioning SED is 0x9423 and the parent router 0x9400

May-30-prov success and fail.pcapng

I have also created a separate thread to show the TTM findings. An OpenThread router shown as grayed out in TTM  

Cheers,

Kaushalya

[Edvin]

Hello Kaushalya,

kaushalyasat said:

Normally when it powers up it connects to the network and change it's state to a router/leader. But this time it stayed on as a child!

As you can see in the Openthread documentation, the network will strive to keep the number of routers below 15, if it is feasible. This is in order to be able to expand the network in any direction (physically) when needed. Therefore, if there are no devices that need to attach to your new device, and you already have a large amount of routers, there is no need to promote that device to a router. 

kaushalyasat said:

I guess a FTD will remain a child as long as no child connects to it, am I correct?

Yes, as long as there is a decent coverage of routers in the area of the new child. 

kaushalyasat said:

I can see that in 'coap_send_request (...)' function, it is hard coded to be non-ack type (COAP_TYPE_NON_CON). I dont know if there is a way to request with confirmation using any API. 

Suppose I clone this 'coap_send_request (...)' and modify it to send ACK packet, then I would need to pass a call back with it to know the ack is successful or not?

If there are too few routers in the network, it will promote some of them to routers, so that the network is ready to accept new child nodes.

kaushalyasat said:

This is possible. Our understanding is even it takes time to renegotiate new paths, it should be ok as we are sending temperature info in every 30 sec. Even if the rerout takes couple of minutes, it should be ok. But the issue is once the sensor's (SED)  data is lost, it remains so for days.

Child supervision will not prevent nodes from dropping out of the network. It will just make it easier to detect whether it has happened or not.

...

I am surprised that it doesn't take into account whether you provide a callback function or not, and that you could specify whether the coap_send_request() should be acked or not. But you are right, you can clone this function, and tell it to use COAP_TYPE_CON. Then you can also provide a coap_reply_t reply_cb, which will trigger when the callback occurs. I believe the node will automatically retransmit messages that are not acked, but you can use this while debugging.

...

I agree that it shouldn't happen. If the connection to the parent is lost (because it is powered off), then the child should try to reconnect to the network through some other node. 

kaushalyasat said:

After a while it 'auto-healed' by itself and my provisioning packets are now received by the SED.

I would say that this is the expected behavior (from all other than the router that suddenly disconnected), don't you agree? 

You don't happen to have any logs from the router that suddenly greyed out?

Best regards,

Edvin

[kaushalyasat]

Hi Edvin,

Sorry I forgot to attach the pcap log. 

5633.May-30-prov success and fail.pcapng

Edvin said:

Child supervision will not prevent nodes from dropping out of the network. It will just make it easier to detect whether it has happened or not.

From what we have seen, its not the node dropping off. The nodes (SEDs) are sending their data out to the associated parent. I think the issue is the parent gets into some error state all of a sudden and stops sending these packets any further. 

Edvin said:

I would say that this is the expected behavior (from all other than the router that suddenly disconnected), don't you agree?

What puzzles me is how long it took for the problematic router to be healed. Also this 'healing' happened when I connect to the console, so dont know if that had any effect. As this is a rare event, very difficult to deep diagnose.

This is what I saw from the log while I was connecting to router 0x9400.

Fullscreen 7181.0x9400 log.txt Download

uart:~$ ot rloc16
9400
Done
uart:~$ [01:02:20.614,807] <inf> [I] ChildSupervsn-: sec sinse ast sup 3
[01:02:20.614,898] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
[01:02:20.615,020] <inf> [I] ChildSupervsn-: sec sinse ast sup 12
[01:02:21.614,929] <inf> [I] ChildSupervsn-: sec sinse ast sup 4
[01:02:21.615,020] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
[01:02:21.615,142] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
[01:02:20.614,807] <inf> [I] ChildSupervsn-: sec sinse ast sup 3
[01:02:20.614,898] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
[01:02:20.615,020] <inf> [I] ChildSupervsn-: sec sinse ast sup 12
[01:02:21.614,929] <inf> [I] ChildSupervsn-: sec sinse ast sup 4
[01:02:21.615,020] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
[01:02:21.615,142] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
uart:~$ [01:02:22.614,013] <inf> [I] ChildSupervsn-: sec sinse ast sup 5
[01:02:22.614,135] <inf> [I] ChildSupervsn-: sec sinse ast sup 28
[01:02:22.614,227] <inf> [I] ChildSupervsn-: sec sinse ast sup 14
[01:02:23.036,102] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:3b0a, ecn:no, from:b20fec7a52d53c7b, sec:no, prio:net, rss:-36.0
[01:02:23.036,346] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b00f:ec7a:52d5:3c7b]:19788
[01:02:23.036,621] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:22.614,013] <inf> [I] ChildSupervsn-: sec sinse ast sup 5
[01:02:22.614,135] <inf> [I] ChildSupervsn-: sec sinse ast sup 28
[01:02:22.614,227] <inf> [I] ChildSupervsn-: sec sinse ast sup 14
[01:02:23.036,102] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:3b0a, ecn:no, from:b20fec7a52d53c7b, sec:no, prio:net, rss:-36.0
[01:02:23.036,346] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b00f:ec7a:52d5:3c7b]:19788
[01:02:23.036,621] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
uart:~$ [01:02:23.037,536] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:b00f:ec7a:52d5:3c7b,0xa000)
[01:02:23.618,133] <inf> [I] ChildSupervsn-: sec sinse ast sup 6
[01:02:23.618,255] <inf> [I] ChildSupervsn-: sec sinse ast sup 29
[01:02:23.618,347] <inf> [I] ChildSupervsn-: sec sinse ast sup 15
[01:02:23.037,536] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:b00f:ec7a:52d5:3c7b,0xa000)
[01:02:23.618,133] <inf> [I] ChildSupervsn-: sec sinse ast sup 6
[01:02:23.618,255] <inf> [I] ChildSupervsn-: sec sinse ast sup 29
[01:02:23.618,347] <inf> [I] ChildSupervsn-: sec sinse ast sup 15
uart:~$ [01:02:24.182,678] <inf> coap_server: No temp data
[01:02:24.367,675] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:43c7, ecn:no, from:fa6c34f384a1c343, sec:no, prio:net, rss:-55.0
[01:02:24.367,980] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:f86c:34f3:84a1:c343]:19788
[01:02:24.368,255] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:24.369,171] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:f86c:34f3:84a1:c343,0xc000)
[01:02:24.619,262] <inf> [I] Mle-----------: Child timeout expired
[01:02:24.182,678] <inf> coap_server: No temp data
[01:02:24.367,675] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:43c7, ecn:no, from:fa6c34f384a1c343, sec:no, prio:net, rss:-55.0
[01:02:24.367,980] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:f86c:34f3:84a1:c343]:19788
[01:02:24.368,255] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:24.369,171] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:f86c:34f3:84a1:c343,0xc000)
[01:02:24.619,262] <inf> [I] Mle-----------: Child timeout expired
uart:~$ [01:02:24.619,506] <inf> [I] ChildSupervsn-: sec sinse ast sup 7
[01:02:24.619,781] <inf> [I] ChildSupervsn-: Sending supervision message to child 0x9423
[01:02:24.619,903] <inf> [I] ChildSupervsn-: sec sinse ast sup 16
[01:02:24.737,060] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:bc85, ecn:no, from:8a6694118ee9ea9a, sec:no, prio:net, rss:-28.0
[01:02:24.737,304] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:8866:9411:8ee9:ea9a]:19788
[01:02:24.619,506] <inf> [I] ChildSupervsn-: sec sinse ast sup 7
[01:02:24.619,781] <inf> [I] ChildSupervsn-: Sending supervision message to child 0x9423
[01:02:24.619,903] <inf> [I] ChildSupervsn-: sec sinse ast sup 16
[01:02:24.737,060] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:bc85, ecn:no, from:8a6694118ee9ea9a, sec:no, prio:net, rss:-28.0
[01:02:24.737,304] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:8866:9411:8ee9:ea9a]:19788
uart:~$ [01:02:24.737,579] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:24.738,555] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:8866:9411:8ee9:ea9a,0xd400)
[01:02:24.761,047] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:67, chksum:79f8, ecn:no, from:0x3000, sec:yes, prio:net, rss:-69.0
[01:02:24.761,505] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:3000]:61631
[01:02:24.761,749] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:0:ff:fe00:9400]:61631
[01:02:24.737,579] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:24.738,555] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:8866:9411:8ee9:ea9a,0xd400)
[01:02:24.761,047] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:67, chksum:79f8, ecn:no, from:0x3000, sec:yes, prio:net, rss:-69.0
[01:▒鲊ƪ▒▒▒<inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:3000]:61631
[01:02:24.884,674] <▒[01:02:30.194,885] <inf> coap_server: No temp data
[01:02:30.616,546] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
[01:02:30.616,668] <inf> [I] ChildSupervsn-: sec sinse ast sup 6
[01:02:30.616,790] <inf> [I] ChildSupervsn-: sec sinse ast sup 22
[01:02:30.194,885] <inf> coap_server: No temp data
[01:02:30.616,546] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
[01:02:30.616,668] <inf> [I] ChildSupervsn-: sec sinse ast sup 6
[01:02:30.616,790] <inf> [I] ChildSupervsn-: sec sinse ast sup 22
uart:~$ [01:02:31.618,682] <inf> [I] ChildSupervsn-: sec sinse ast sup 14
[01:02:31.618,835] <inf> [I] ChildSupervsn-: sec sinse ast sup 7
[01:02:31.618,927] <inf> [I] ChildSupervsn-: sec sinse ast sup 23
[01:02:32.256,805] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:83, chksum:700a, ecn:no, from:02e3e52c9bcab9d9, sec:yes, prio:net, rss:-61.0
[01:02:32.257,049] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e3:e52c:9bca:b9d9]:19788
[01:02:31.618,682] <inf> [I] ChildSupervsn-: sec sinse ast sup 14
[01:02:31.618,835] <inf> [I] ChildSupervsn-: sec sinse ast sup 7
[01:02:31.618,927] <inf> [I] ChildSupervsn-: sec sinse ast sup 23
[01:02:32.256,805] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:83, chksum:700a, ecn:no, from:02e3e52c9bcab9d9, sec:yes, prio:net, rss:-61.0
[01:02:32.257,049] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e3:e52c:9bca:b9d9]:19788
uart:~$ [01:02:32.257,324] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:32.614,807] <inf> [I] ChildSupervsn-: sec sinse ast sup 15
[01:02:32.614,898] <inf> [I] ChildSupervsn-: sec sinse ast sup 8
[01:02:32.615,020] <inf> [I] ChildSupervsn-: sec sinse ast sup 24
[01:02:32.257,324] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:32.614,807] <inf> [I] ChildSupervsn-: sec sinse ast sup 15
[01:02:32.614,898] <inf> [I] ChildSupervsn-: sec sinse ast sup 8
[01:02:32.615,020] <inf> [I] ChildSupervsn-: sec sinse ast sup 24
uart:~$ [01:02:33.614,959] <inf> [I] ChildSupervsn-: sec sinse ast sup 16
[01:02:33.615,081] <inf> [I] ChildSupervsn-: sec sinse ast sup 9
[01:02:33.615,173] <inf> [I] ChildSupervsn-: sec sinse ast sup 25
[01:02:34.616,088] <inf> [I] ChildSupervsn-: sec sinse ast sup 17
[01:02:34.616,180] <inf> [I] ChildSupervsn-: sec sinse ast sup 10
[01:02:34.616,302] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
[01:02:33.614,959] <inf> [I] ChildSupervsn-: sec sinse ast sup 16
[01:02:33.615,081] <inf> [I] ChildSupervsn-: sec sinse ast sup 9
[01:02:33.615,173] <inf> [I] ChildSupervsn-: sec sinse ast sup 25
[01:02:34.616,088] <inf> [I] ChildSupervsn-: sec sinse ast sup 17
[01:02:34.616,180] <inf> [I] ChildSupervsn-: sec sinse ast sup 10
[01:02:34.616,302] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
uart:~$ ot [01:02:35.619,232] <inf> [I] ChildSupervsn-: sec sinse ast sup 18
[01:02:35.619,354] <inf> [I] ChildSupervsn-: sec sinse ast sup 11
[01:02:35.619,445] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
[01:02:35.914,001] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:e695, ecn:no, from:768ec5ba1e5e09c6, sec:no, prio:net, rss:-56.0
[01:02:35.914,245] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:748e:c5ba:1e5e:9c6]:19788
[01:02:35.914,489] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:35.619,232] <inf> [I] ChildSupervsn-: sec sinse ast sup 18
uart:~$ ot [01:02:35.915,466] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:748e:c5ba:1e5e:9c6,0xc800)
[01:02:35.619,354] <inf> [I] ChildSupervsn-: sec sinse ast sup 11
[01:02:35.619,445] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
uart:~$ ot [01:02:36.206,848] <inf> coap_server: No temp data
[01:02:36.621,368] <inf> [I] ChildSupervsn-: sec sinse ast sup 19
[01:02:35.914,001] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:e695, ecn:no, from:768ec5ba1e5e09c6, sec:no, prio:net, rss:-56.0
uart:~$ ot [01:02:36.621,520] <inf> [I] ChildSupervsn-: sec sinse ast sup 12
[01:02:36.621,612] <inf> [I] ChildSupervsn-: sec sinse ast sup 28
[01:02:35.914,245] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:748e:c5ba:1e5e:9c6]:19788
[01:02:35.914,489] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:35.915,466] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:748e:c5ba:1e5e:9c6,0xc800)
[01:02:36.206,848] <inf> coap_server: No temp data
[01:02:36.621,368] <inf> [I] ChildSupervsn-: sec sinse ast sup 19
[01:02:36.621,520] <inf> [I] ChildSupervsn-: sec sinse ast sup 12
[01:02:36.621,612] <inf> [I] ChildSupervsn-: sec sinse ast sup 28
uart:~$ ot chil[01:02:37.620,513] <inf> [I] ChildSupervsn-: sec sinse ast sup 20
[01:02:37.620,635] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
[01:02:37.620,727] <inf> [I] ChildSupervsn-: sec sinse ast sup 29
[01:02:38.503,753] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:95, chksum:f385, ecn:no, from:0x941a, sec:yes, prio:normal, rss:-47.0
[01:02:38.504,028] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:fbd0:8244:b15b:7c56]:37410
[01:02:37.620,513] <inf> [I] ChildSupervsn-: sec sinse ast sup 20
uart:~$ ot chil[01:02:38.504,302] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:ba0d:8101:b6b1:47f9]:5683
[01:02:37.620,635] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
[01:02:37.620,727] <inf> [I] ChildSupervsn-: sec sinse ast sup 29
uart:~$ ot chil[01:02:38.510,009] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:95, chksum:f385, ecn:no, to:0xc800, sec:yes, prio:normal
[01:02:38.503,753] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:95, chksum:f385, ecn:no, from:0x941a, sec:yes, prio:normal, rss:-47.0
uart:~$ ot chil[01:02:38.510,284] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:fbd0:8244:b15b:7c56]:37410
[01:02:38.510,528] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:ba0d:8101:b6b1:47f9]:5683
[01:02:38.504,028] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:fbd0:8244:b15b:7c56]:37410
uart:~$ ot chil[01:02:38.567,596] <inf> [I] DataPollHandlr: Rx data poll, src:0x941a, qed_msgs:0, rss:-46, ack-fp:0
[01:02:38.504,302] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:ba0d:8101:b6b1:47f9]:5683
uart:~$ ot chil[01:02:38.617,645] <inf> [I] ChildSupervsn-: sec sinse ast sup 21
[01:02:38.510,009] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:95, chksum:f385, ecn:no, to:0xc800, sec:yes, prio:normal
uart:~$ ot chil[01:02:38.617,767] <inf> [I] ChildSupervsn-: sec sinse ast sup 14
[01:02:38.617,980] <inf> [I] ChildSupervsn-: Sending supervision message to child 0x941b
[01:02:38.510,284] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:fbd0:8244:b15b:7c56]:37410
uart:~$ ot chil[01:02:38.756,408] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:67, chksum:dabb, ecn:no, from:0x3000, sec:yes, prio:net, rss:-73.0
[01:02:38.510,528] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:ba0d:8101:b6b1:47f9]:5683
[01:02:38.567,596] <inf> [I] DataPollHandlr: Rx data poll, src:0x941a, qed_msgs:0, rss:-46, ack-fp:0
uart:~$ ot chil[01:02:38.756,652] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:3000]:61631
[01:02:38.617,645] <inf> [I] ChildSupervsn-: sec sinse ast sup 21
uart:~$ ot child[01:02:38.756,927] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:0:ff:fe00:9400]:61631
[01:02:38.617,767] <inf> [I] ChildSupervsn-: sec sinse ast sup 14
uart:~$ ot child[01:02:38.757,354] <inf> [I] NetDiag-------: Received DiagGetRequest from fdde:ad00:beef:0:0:ff:fe00:3000
[01:02:38.617,980] <inf> [I] ChildSupervsn-: Sending supervision message to child 0x941b
[01:02:38.756,408] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:67, chksum:dabb, ecn:no, from:0x3000, sec:yes, prio:net, rss:-73.0
uart:~$ ot child[01:02:38.764,831] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:116, chksum:f6d0, ecn:no, to:0x3000, sec:yes, prio:normal
[01:02:38.756,652] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:3000]:61631
uart:~$ ot child[01:02:38.765,136] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:9400]:61631
[01:02:38.756,927] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:0:ff:fe00:9400]:61631
uart:~$ ot child[01:02:38.765,411] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:0:ff:fe00:3000]:61631
[01:02:38.757,354] <inf> [I] NetDiag-------: Received DiagGetRequest from fdde:ad00:beef:0:0:ff:fe00:3000
uart:~$ ot child[01:02:38.814,727] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:9670, ecn:no, from:c2e03dbce20f9792, sec:no, prio:net, rss:-21.0
[01:02:38.764,831] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:116, chksum:f6d0, ecn:no, to:0x3000, sec:yes, prio:normal
uart:~$ ot child[01:02:38.815,032] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c0e0:3dbc:e20f:9792]:19788
[01:02:38.765,136] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:9400]:61631
uart:~$ ot child[01:02:38.815,277] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:38.816,192] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:c0e0:3dbc:e20f:9792,0x9800)
[01:02:38.765,411] <inf> [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:0:ff:fe00:3000]:61631
[01:02:38.814,727] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:9670, ecn:no, from:c2e03dbce20f9792, sec:no, prio:net, rss:-21.0
uart:~$ ot child[01:02:38.961,761] <inf> [I] DataPollHandlr: Rx data poll, src:0x941b, qed_msgs:1, rss:-65, ack-fp:1
[01:02:38.815,032] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c0e0:3dbc:e20f:9792]:19788
[01:02:38.815,277] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:38.816,192] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:c0e0:3dbc:e20f:9792,0x9800)
[01:02:38.961,761] <inf> [I] DataPollHandlr: Rx data poll, src:0x941b, qed_msgs:1, rss:-65, ack-fp:1
uart:~$ ot child [01:02:39.616,790] <inf> [I] ChildSupervsn-: sec sinse ast sup 22
[01:02:39.616,912] <inf> [I] ChildSupervsn-: sec sinse ast sup 15
[01:02:39.617,004] <inf> [I] ChildSupervsn-: sec sinse ast sup 1
[01:02:40.620,971] <inf> [I] ChildSupervsn-: sec sinse ast sup 23
[01:02:40.621,093] <inf> [I] ChildSupervsn-: sec sinse ast sup 16
[01:02:40.621,185] <inf> [I] ChildSupervsn-: sec sinse ast sup 2
[01:02:39.616,790] <inf> [I] ChildSupervsn-: sec sinse ast sup 22
uart:~$ ot child tab[01:02:41.107,147] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:ec14, ecn:no, from:ca14168e1d0ab00d, sec:no, prio:net, rss:-69.0
[01:02:41.107,513] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c814:168e:1d0a:b00d]:19788
[01:02:41.107,971] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
--- 1 messages dropped ---
[01:02:39.616,912] <inf> [I] ChildSupervsn-: sec sinse ast sup 15
[01:02:39.617,004] <inf> [I] ChildSupervsn-: sec sinse ast sup 1
uart:~$ ot child tab[01:02:41.108,978] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:c814:168e:1d0a:b00d,0x1c00)
[01:02:40.620,971] <inf> [I] ChildSupervsn-: sec sinse ast sup 23
uart:~$ ot child tab[01:02:41.623,107] <inf> [I] ChildSupervsn-: sec sinse ast sup 24
[01:02:40.621,093] <inf> [I] ChildSupervsn-: sec sinse ast sup 16
uart:~$ ot child tab[01:02:41.623,199] <inf> [I] ChildSupervsn-: sec sinse ast sup 17
[01:02:40.621,185] <inf> [I] ChildSupervsn-: sec sinse ast sup 2
uart:~$ ot child tab[01:02:41.623,321] <inf> [I] ChildSupervsn-: sec sinse ast sup 3
[01:02:41.107,513] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c814:168e:1d0a:b00d]:19788
uart:~$ ot child tab[01:02:42.218,536] <inf> coap_server: No temp data
[01:02:41.107,971] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:41.108,978] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:c814:168e:1d0a:b00d,0x1c00)
[01:02:41.623,107] <inf> [I] ChildSupervsn-: sec sinse ast sup 24
[01:02:41.623,199] <inf> [I] ChildSupervsn-: sec sinse ast sup 17
[01:02:41.623,321] <inf> [I] ChildSupervsn-: sec sinse ast sup 3
[01:02:42.218,536] <inf> coap_server: No temp data
uart:~$ ot child table[01:02:42.579,925] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:15a7, ecn:no, from:62521c7deb161193, sec:no, prio:net, rss:-29.0
[01:02:42.580,200] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:6052:1c7d:eb16:1193]:19788
[01:02:42.580,474] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:42.581,634] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:6052:1c7d:eb16:1193,0x2c00)
[01:02:42.579,925] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:15a7, ecn:no, from:62521c7deb161193, sec:no, prio:net, rss:-29.0
uart:~$ ot child table[01:02:42.627,227] <inf> [I] ChildSupervsn-: sec sinse ast sup 25
[01:02:42.627,349] <inf> [I] ChildSupervsn-: sec sinse ast sup 18
[01:02:42.580,200] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:6052:1c7d:eb16:1193]:19788
uart:~$ ot child table[01:02:42.627,441] <inf> [I] ChildSupervsn-: sec sinse ast sup 4
[01:02:43.629,608] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
[01:02:42.580,474] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
uart:~$ ot child table[01:02:43.629,730] <inf> [I] ChildSupervsn-: sec sinse ast sup 19
[01:02:42.581,634] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:6052:1c7d:eb16:1193,0x2c00)
uart:~$ ot child table[01:02:43.629,821] <inf> [I] ChildSupervsn-: sec sinse ast sup 5
[01:02:42.627,227] <inf> [I] ChildSupervsn-: sec sinse ast sup 25
[01:02:42.627,349] <inf> [I] ChildSupervsn-: sec sinse ast sup 18
[01:02:42.627,441] <inf> [I] ChildSupervsn-: sec sinse ast sup 4
[01:02:43.629,608] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
[01:02:43.629,730] <inf> [I] ChildSupervsn-: sec sinse ast sup 19
[01:02:43.629,821] <inf> [I] ChildSupervsn-: sec sinse ast sup 5
uart:~$ ot child table
| ID  | RLOC16 | Timeout    | Age        | LQ In | C_VN |R|D|N|Ver|CSL|QMsgCnt| Extended MAC     |
+-----+--------+------------+------------+-------+------+-+-+-+---+---+-------+------------------+
|  26 | 0x941a |        240 |          5 |     3 |  225 |0|0|0|  4| 0 |     0 | 2646710567a57593 |
|  35 | 0x9423 |        240 |         19 |     3 |  225 |0|0|0|  4| 0 |     0 | 76bcc914f4f0de22 |
|  27 | 0x941b |        240 |          5 |     3 |  225 |0|0|0|  4| 0 |     0 | 664d9a2a076dabbd |

Done
uart:~$ [01:02:44.629,699] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
[01:02:44.629,821] <inf> [I] ChildSupervsn-: sec sinse ast sup 20
[01:02:44.629,943] <inf> [I] ChildSupervsn-: sec sinse ast sup 6
[01:02:45.630,828] <inf> [I] ChildSupervsn-: sec sinse ast sup 28
[01:02:45.630,920] <inf> [I] ChildSupervsn-: sec sinse ast sup 21
[01:02:45.631,042] <inf> [I] ChildSupervsn-: sec sinse ast sup 7
[01:02:44.629,699] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
[01:02:44.629,821] <inf> [I] ChildSupervsn-: sec sinse ast sup 20
[01:02:44.629,943] <inf> [I] ChildSupervsn-: sec sinse ast sup 6
[01:02:45.630,828] <inf> [I] ChildSupervsn-: sec sinse ast sup 28
[01:02:45.630,920] <inf> [I] ChildSupervsn-: sec sinse ast sup 21
[01:02:45.631,042] <inf> [I] ChildSupervsn-: sec sinse ast sup 7
uart:~$ [01:02:46.630,004] <inf> [I] ChildSupervsn-: sec sinse ast sup 29
[01:02:46.630,126] <inf> [I] ChildSupervsn-: sec sinse ast sup 22
[01:02:46.630,218] <inf> [I] ChildSupervsn-: sec sinse ast sup 8
[01:02:47.631,225] <inf> [I] ChildSupervsn-: Sending supervision message to child 0x941a
[01:02:47.631,317] <inf> [I] ChildSupervsn-: sec sinse ast sup 23
[01:02:47.631,408] <inf> [I] ChildSupervsn-: sec sinse ast sup 9
[01:02:46.630,004] <inf> [I] ChildSupervsn-: sec sinse ast sup 29
[01:02:46.630,126] <inf> [I] ChildSupervsn-: sec sinse ast sup 22
[01:02:46.630,218] <inf> [I] ChildSupervsn-: sec sinse ast sup 8
[01:02:47.631,225] <inf> [I] ChildSupervsn-: Sending supervision message to child 0x941a
[01:02:47.631,317] <inf> [I] ChildSupervsn-: sec sinse ast sup 23
[01:02:47.631,408] <inf> [I] ChildSupervsn-: sec sinse ast sup 9
uart:~$ [01:02:48.229,797] <inf> coap_server: No temp data
[01:02:48.571,228] <inf> [I] DataPollHandlr: Rx data poll, src:0x941a, qed_msgs:1, rss:-46, ack-fp:1
[01:02:48.633,331] <inf> [I] ChildSupervsn-: sec sinse ast sup 1
[01:02:48.633,453] <inf> [I] ChildSupervsn-: sec sinse ast sup 24
[01:02:48.633,544] <inf> [I] ChildSupervsn-: sec sinse ast sup 10
[01:02:49.060,882] <inf> [I] Mle-----------: Send Announce on channel 18
[01:02:49.067,108] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:83, chksum:81d4, ecn:no, to:0xffff, sec:yes, prio:net
[01:02:48.229,797] <inf> coap_server: No temp data
[01:02:48.571,228] <inf> [I] DataPollHandlr: Rx data poll, src:0x941a, qed_msgs:1, rss:-46, ack-fp:1
[01:02:48.633,331] <inf> [I] ChildSupervsn-: sec sinse ast sup 1
[01:02:48.633,453] <inf> [I] ChildSupervsn-: sec sinse ast sup 24
[01:02:48.633,544] <inf> [I] ChildSupervsn-: sec sinse ast sup 10
[01:02:49.060,882] <inf> [I] Mle-----------: Send Announce on channel 18
[01:02:49.067,108] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:83, chksum:81d4, ecn:no, to:0xffff, sec:yes, prio:net
uart:~$ [01:02:49.067,413] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:28aa:8ef9:4725:83eb]:19788
[01:02:49.067,657] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:49.067,413] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:28aa:8ef9:4725:83eb]:19788
[01:02:49.067,657] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
uart:~$ [01:02:49.636,566] <inf> [I] ChildSupervsn-: sec sinse ast sup 2
[01:02:49.636,688] <inf> [I] ChildSupervsn-: sec sinse ast sup 25
[01:02:49.636,779] <inf> [I] ChildSupervsn-: sec sinse ast sup 11
[01:02:49.995,086] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:1ae2, ecn:no, from:8a6694118ee9ea9a, sec:no, prio:net, rss:-29.0
[01:02:49.995,330] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:8866:9411:8ee9:ea9a]:19788
[01:02:49.636,566] <inf> [I] ChildSupervsn-: sec sinse ast sup 2
[01:02:49.636,688] <inf> [I] ChildSupervsn-: sec sinse ast sup 25
[01:02:49.636,779] <inf> [I] ChildSupervsn-: sec sinse ast sup 11
[01:02:49.995,086] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:1ae2, ecn:no, from:8a6694118ee9ea9a, sec:no, prio:net, rss:-29.0
[01:02:49.995,330] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:8866:9411:8ee9:ea9a]:19788
uart:~$ [01:02:49.995,574] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:49.996,551] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:8866:9411:8ee9:ea9a,0xd400)
[01:02:50.639,709] <inf> [I] ChildSupervsn-: sec sinse ast sup 3
[01:02:50.639,801] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
[01:02:50.639,923] <inf> [I] ChildSupervsn-: sec sinse ast sup 12
[01:02:49.995,574] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
[01:02:49.996,551] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:8866:9411:8ee9:ea9a,0xd400)
[01:02:50.639,709] <inf> [I] ChildSupervsn-: sec sinse ast sup 3
[01:02:50.639,801] <inf> [I] ChildSupervsn-: sec sinse ast sup 26
[01:02:50.639,923] <inf> [I] ChildSupervsn-: sec sinse ast sup 12
uart:~$ [01:02:51.643,859] <inf> [I] ChildSupervsn-: sec sinse ast sup 4
[01:02:51.644,012] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
[01:02:51.644,104] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
[01:02:52.190,673] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x7400, sec:yes, prio:normal, rss:-18.0
--- 10 messages dropped ---
[01:02:52.233,032] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
--- 29 messages dropped ---
[01:02:52.262,115] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
--- 39 messages dropped ---
[01:02:51.643,859] <inf> [I] ChildSupervsn-: sec sinse ast sup 4
[01:02:51.644,012] <inf> [I] ChildSupervsn-: sec sinse ast sup 27
[01:02:51.644,104] <inf> [I] ChildSupervsn-: sec sinse ast sup 13
[01:02:52.190,673] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x7400, sec:yes, prio:normal, rss:-18.0
[01:02:52.233,032] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.262,115] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
uart:~$ --- 10 messages dropped ---
[01:02:52.279,785] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xc000, sec:yes, prio:normal, rss:-44.0
[01:02:52.280,029] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.280,273] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.282,165] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x2c00, sec:yes, prio:normal, rss:-28.0
--- 10 messages dropped ---
[01:02:52.279,785] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xc000, sec:yes, prio:normal, rss:-44.0
[01:02:52.280,029] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.280,273] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.282,165] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x2c00, sec:yes, prio:normal, rss:-28.0
uart:~$ [01:02:52.282,440] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.282,684] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.286,926] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xb000, sec:yes, prio:normal, rss:-52.0
[01:02:52.287,200] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.287,445] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.282,440] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.282,684] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.286,926] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xb000, sec:yes, prio:normal, rss:-52.0
[01:02:52.287,200] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.287,445] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
uart:~$ [01:02:52.289,855] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x1c00, sec:yes, prio:normal, rss:-68.0
[01:02:52.290,100] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.290,496] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.292,724] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xa000, sec:yes, prio:normal, rss:-35.0
[01:02:52.292,999] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.289,855] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x1c00, sec:yes, prio:normal, rss:-68.0
[01:02:52.290,100] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.290,496] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.292,724] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xa000, sec:yes, prio:normal, rss:-35.0
[01:02:52.292,999] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
uart:~$ [01:02:52.293,273] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.296,020] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x0800, sec:yes, prio:normal, rss:-67.0
[01:02:52.296,264] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.296,539] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.302,520] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xc800, sec:yes, prio:normal, rss:-54.0
[01:02:52.293,273] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.296,020] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x0800, sec:yes, prio:normal, rss:-67.0
[01:02:52.296,264] <inf> [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:7400]
[01:02:52.296,539] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
[01:02:52.302,520] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xc800, sec:yeK▒ɥ▒▒r▒ɵ▒▒▒ rss:-54.0
uart:~$▒▒▒▒▒▒m▒8Duart▒ [01:02:52.302▒▒] ▒▒l:▒▒  ▒▒▒▒

Also, is there a way to detach from a parent and start a renegotiate to connect to a different router? I tried 'ot detach', 'ot thread stop' and 'ot  thread start' from the SED. But I think since the SED is still in the child table of the first parent, all that happens is that I get a new RLOC. I guess if I wait 240 sec timeout, and try thread stop/start, I might get connected to a new router. What do you think?

Cheers,

Kaushalya

[Edvin]

kaushalyasat said:

From what we have seen, its not the node dropping off. The nodes (SEDs) are sending their data out to the associated parent. I think the issue is the parent gets into some error state all of a sudden and stops sending these packets any further. 

But the supervision messages are only between the child and it's parent, so this message is not routed to any other routers than the parent itself. Right?

kaushalyasat said:

What puzzles me is how long it took for the problematic router to be healed. Also this 'healing' happened when I connect to the console, so dont know if that had any effect. As this is a rare event, very difficult to deep diagnose.

How long did it take?

kaushalyasat said:

This is what I saw from the log while I was connecting to router 0x9400.

So this is the log from the router. When did it crash? (timestamp?)

kaushalyasat said:

I guess if I wait 240 sec timeout, and try thread stop/start, I might get connected to a new router. What do you think?

I would assume it does. But I guess the main issue here is that this is not happening at all times, right?

[kaushalyasat]

Hi Edvin,

Sorry about my delay, I was not well past couple of days and only now back in work.

Edvin said:

But the supervision messages are only between the child and it's parent, so this message is not routed to any other routers than the parent itself. Right?

No the message is send to another router. The parent is just routing it through. 

I think we have identified a potential pitfall in openthread networks. That is partitioning. We think our failure mechanism can be explained by that. 

Think of two routers and a set of sensors (SEDs). If both routers are in the same partition, then no issues. But for whatever reason one router lost its connection to the other, then there will be two network partitions. The problem happens when the Sensors can still reach both routers. If a sensor that is sensing data the router1 suddenly lost its connection and connected to router2, the data path will be broken, but the Sensor will happily stay in the current connection until another MLE session decide to connect back to router1. The issue is for the MLE protocol, every router in range is a potential parent, but this may not work for application data.

It looks like we cant constrain the MLE process to limit the parent search to its own partition. We can implement a two way handshake from application level and initiate another MLE session from the Sensor, but there is no guarantee that it may not choose a parent from a different partition.

Edvin said:

So this is the log from the router. When did it crash? (timestamp?)

Sorry Edvin, as this happened when we were not at office, we dont know exactly at what time this happened. So it may be very diff to extract it from the log.

Cheers,

Kaushalya

[Edvin]

Hello Kaushalya,

Interesting. If the parents split into two different networks, then there will exist two different networks with the same credentials, not able to communicate with one another. And it is not possible to connect the two networks using a SED device.

The solution is "simple". You need to make sure that if you struggle with that the two partitions of the network can't reach one another, you need to add another router that can reach both the network partitions (so that they are no longer separate partitions). 

I believe this is where we started this conversation. I remember asking for state changes to see if a router became leader (which it will if part of the network splits out in it's own partition). 

Is it an option to add another router making sure the network doesn't split into two partitions?

Best regards,

Edvin

[kaushalyasat]

Hi Edvin,

The issue we see here is actually not partitioning, but the SEDs cant seem to proactively dislodge from a router and do a MLE reattach to another. There is no guarantee that the SED will not be connected to the same router again. From the Thread standpoint this may be a perfectly valid scenario, but its a killer or non-recoverable error for us. 

Does 'Search for a better parent' feature pick up a new router ?

Now we are implementing two solutions.

1. Make the partitionID available in our dashboard for each router. It the commissioning stage we make sure all routers form a single partition. If not we introduce additional routers until we can get a single partition.

2. Instead of a single big network, we implement networks per router. We have one main router in a installation and if we need to bring in more, we commission them with main router, so that they all have same network credentials as the main router. Similarly the SEDs will be commissioned in. At the point of commissioning we will have a single contagious network per installation. This way, meshing will be limited within that network.

The only other issue this doesn't solve is a one case a test user reported, where he says he didn't have no  more than one router in his system at all times, but he saw his sensors disconnecting. As this is only single case we have reported, we will park this scenario till we have more conclusive data.

What do you think?

Cheers,

Kaushalya