Commissioner not responding to join request

nrf52840

NCS 1.9.1

We have a Thread project based on the Coap Client and Server example.  The Coap server acts as the Commissioner, and other devices join using a known pskd.  Sometimes this works fine, but after the server has been running a while (overnght) it does not respond to the join request.

A button press on the server allows joining:

static void on_button_changed(uint32_t button_state, uint32_t has_changed)
{
	uint32_t pressed = button_state & has_changed;
	uint32_t released = ~button_state & has_changed;

	// Button 1:  
	if (pressed & DK_BTN1_MSK) 
	{
		k_work_submit(&joining_work);		// calls activate_joining()
	}
}

// Called in workqueue joining_work
static void activate_joining(struct k_work *item)
{
	ARG_UNUSED(item);

	struct openthread_context *ot_context = openthread_get_default_context();
	otError err;

	otInstance *instance = ot_context->instance;

	otCommissionerState state;
	if ((state = otCommissionerGetState(instance)) == OT_COMMISSIONER_STATE_ACTIVE)
	{
		err = otCommissionerAddJoiner(instance, NULL, pskd, JOINER_TIMEOUT); 
		if (err != OT_ERROR_NONE)
		{
			printk("\r\notCommissionerAddJoiner() failed [%d]\r\n", err);
		}
		else
		{
			//k_timer_start(&led_timer, K_MSEC(100), K_MSEC(100));
			g_joining_allowed = true;

			printk("\r\nCommissioner joiner started for %d seconds...\r\n", JOINER_TIMEOUT);
		}
	}
	else
	{
		printk("\r\nCommissioner state = %d. Restarting...", state);

		err = otCommissionerStart(ot_context->instance, commissioner_state_cb, commissioner_joiner_cb, ot_context);
		if (err != OT_ERROR_NONE)
			printk("otCommissionerStart() failed [%d]\r\n", err);
		else
			start_joiner = true;		// trigger AddJoiner when "commissioner active" happens
	}
}

This happens successfully all the time.  I see the message "Commissioner joiner started for 120 seconds..." every time.

The Coap client uses auto joining by setting these configuration parameters.

# Thread Joiner
CONFIG_OPENTHREAD_JOINER=y
CONFIG_OPENTHREAD_JOINER_AUTOSTART=y
CONFIG_OPENTHREAD_JOINER_PSKD="J01NUS"
CONFIG_OPENTHREAD_MANUAL_START=n
On WireShark I can see the Discovery Request with "Joiner Flag: Intending" but there is no response from the Coap Server.  At the same time I have a device that is broadcasting Discovery Requests (without the joining flag set).  The Coap Server responds to these.  And also responds to requests for router information (otThreadGetRouterInfo() ) with this
--- Router fd70:a900:acc1:3d9f:0:ff:fe00:9000 ----

Ext Address: 0xfb58ff0e
Rloc16: 0x9000
IP6 Address List:
- fd70:a900:acc1:3d9f:0:ff:fe00:fc37    Commissioner
- fd70:a900:acc1:3d9f:0:ff:fe00:fc00    Leader
- fd70:a900:acc1:3d9f:0:ff:fe00:9000
- fd70:a900:acc1:3d9f:355e:d60e:5def:e87b    Coap Server
- fe80:0:0:0:cff:58fb:cdf3:6c77

So, the Coap Server is the Commissioner, and joining is allowed.  So, why isn't it responding to the joiner's request?

Why does this work sometimes and but not always?

Where can I look to diagnose this?

Mary

Parents
  • Hi, 

    I am looking into your case and will update it next week. 

    Regards,
    Amanda H.

  • I recompiled with this change to the prf.conf:

    CONFIG_OPENTHREAD_DEBUG=y
    #CONFIG_OPENTHREAD_DEBUG=n
    CONFIG_OPENTHREAD_LOG_LEVEL_NOTE=y
    When a client is trying to join, I saw this message on the Server:
    W: [WARN]-MLE: Failed to process Discovery Request: Security
    I see this message before I press the "Allow Joining" button, and again when it tries to join after I press the button.
    otCommissionerAddJoiner(instance, NULL, pskd, JOINER_TIMEOUT);  is not returning an error, but it doesn't seem like it worked.
    Mry
  • I added the  mutex lock/unlock around the calls to otCommissionerAddJoiner() and any other calls that change something.  

    Some days later, the problem reappeared.  I tested on two units running identical code.  I verified that using nrfjprog --verify.  One unit allowed a device to join, and the other didn't.  I did a factory reset on the one that failed, and then joining succeeded.

    Mary

  • It failed again today.  Here is a log with more debug information.

    CONFIG_OPENTHREAD_LOG_LEVEL_INFO=y

    Joining is allowed at time [01:21:36.502,502], line 44

    A Discovery request is received at time [01:21:53.936,798], line 84

    and again at time [01:22:25.932,647] line 586

    [01:21:12.756,317] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:21:12.781,555] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:eedf:5f07:3d3a:1a2c]:5683
    [01:21:13.883,239] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:13.908,447] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:14.426,025] <inf> [I] ChannelMonitor: 119 [ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ]
    [01:21:16.884,002] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:16.909,149] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:19.883,789] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:19.908,996] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:22.884,887] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:22.910,003] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:23.213,531] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:6e7f, ecn:no, from:0xf400, sec:yes, prio:normal, rss:-41.0
    [01:21:23.242,553] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:eedf:5f07:3d3a:1a2c]:5683
    [01:21:23.267,822] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:21:23.300,109] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:41a1, ecn:no, to:0xf400, sec:yes, prio:normal
    [01:21:23.327,575] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:21:23.352,813] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:eedf:5f07:3d3a:1a2c]:5683
    [01:21:25.885,009] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:25.910,583] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:28.390,106] <inf> [I] Mle-----------: Send Announce on channel 11
    [01:21:28.418,670] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:83, chksum:a0fe, ecn:no, to:0xffff, sec:yes, prio:net
    [01:21:28.446,014] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:28.470,550] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [01:21:28.883,331] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:28.908,538] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:30.417,327] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:91, chksum:31ac, ecn:no, from:ea6b0c896ab806d4, sec:no, prio:net, rss:-40.0
    [01:21:30.446,960] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e86b:c89:6ab8:6d4]:19788
    [01:21:30.471,343] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [01:21:30.495,452] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:e86b:c89:6ab8:6d4,0xf400)
    [01:21:31.135,742] <inf> [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
    [01:21:31.164,886] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:91, chksum:a6dc, ecn:no, to:0xffff, sec:no, prio:net
    [01:21:31.192,016] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:31.216,552] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [01:21:31.882,965] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:31.908,111] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:33.780,548] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:f496, ecn:no, from:0xf400, sec:yes, prio:normal, rss:-40.0
    [01:21:33.809,570] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:eedf:5f07:3d3a:1a2c]:5683
    [01:21:33.834,838] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:21:33.866,577] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:c7b8, ecn:no, to:0xf400, sec:yes, prio:normal
    [01:21:33.894,042] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:21:33.919,281] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:eedf:5f07:3d3a:1a2c]:5683
    [01:21:34.883,087] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:34.908,203] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:36.502,502] <inf> [I] Commissioner--: Sent CommissionerSet to leader
    [01:21:36.525,390] <inf> [I] Commissioner--: Added Joiner (any, J01NUS)
    
    Commissioner joiner started for 120 seconds...
    [01:21:36.568,725] <inf> [I] NetworkData---: sent CommissionerSet response
    [01:21:36.591,674] <inf> [I] Commissioner--: Received CommissionerSet response
    [01:21:36.709,259] <inf> [I] Commissioner--: Sent LeaderKeepAlive
    [01:21:36.731,567] <inf> [I] MeshCoPLeader-: Received LeaderKeepAlive
    [01:21:36.754,394] <inf> [I] MeshCoPLeader-: Sent LeaderKeepAlive response
    [01:21:36.777,343] <inf> [I] Commissioner--: Received LeaderKeepAlive response
    [01:21:37.884,155] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:37.909,759] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:40.883,911] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:40.909,057] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:43.884,338] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:43.909,484] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:44.354,187] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:083c, ecn:no, from:0xf400, sec:yes, prio:normal, rss:-41.0
    [01:21:44.383,270] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:eedf:5f07:3d3a:1a2c]:5683
    [01:21:44.408,477] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:21:44.441,070] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:db5d, ecn:no, to:0xf400, sec:yes, prio:normal
    [01:21:44.468,536] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:21:44.493,804] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:eedf:5f07:3d3a:1a2c]:5683
    [01:21:46.885,131] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:46.910,247] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:49.419,677] <inf> [I] Mle-----------: Send Announce on channel 12
    [01:21:49.447,723] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:83, chksum:1ea4, ecn:no, to:0xffff, sec:yes, prio:net
    [01:21:49.474,975] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:49.499,481] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [01:21:49.885,223] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:49.910,369] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:52.885,314] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:52.911,834] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:52.937,713] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:52.963,348] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:52.988,891] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:53.013,763] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:53.080,841] <inf> [I] ChannelMonitor: 120 [ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ]
    [01:21:53.856,018] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:56, chksum:a373, ecn:no, from:8ad3bda738fb63ae, sec:no, prio:net, rss:-41.0
    [01:21:53.885,681] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:88d3:bda7:38fb:63ae]:19788
    [01:21:53.912,048] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:21:53.936,798] <inf> [I] Mle-----------: Receive Discovery Request (fe80:0:0:0:88d3:bda7:38fb:63ae)
    [01:21:53.963,439] <wrn> [W] Mle-----------: Failed to process Discovery Request: Security
    [01:21:53.989,257] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:54.014,373] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:54.888,031] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:54.914,398] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:54.940,216] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:54.966,064] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:54.991,973] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:55.016,845] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:55.885,498] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:55.911,499] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:55.937,225] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:55.962,982] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:55.988,952] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:56.014,038] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [01:21:56.410,705] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:f225, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-63.0
    [01:21:56.440,704] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:21:56.465,209] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:21:56.489,288] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:21:56.515,258] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:21:56.541,320] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:ee2c, ecn:no, from:16eefb0b0b5f3b76, sec:no, prio:net, rss:-54.0
    [01:21:56.570,831] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:21:56.595,245] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:21:56.619,384] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:21:56.645,294] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:21:56.738,189] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:21:56.770,538] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:b0f9, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:21:56.798,675] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:56.823,211] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:21:56.946,228] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:21:56.977,966] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:02f7, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:21:57.006,072] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:57.030,670] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:21:57.164,459] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:e68f, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-64.0
    [01:21:57.194,610] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:21:57.219,177] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:57.244,598] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:21:57.270,996] <inf> [I] Mle-----------: Child 0x0000 IPv6 address[1]=fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd
    [01:21:57.297,576] <inf> [I] AddrResolver--: Cache entry removed: fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd, 0xf400, list:cached - removing eid
    [01:21:57.326,507] <inf> [I] Mle-----------: Child 0x0000 has 1 registered IPv6 address, 1 address stored
    [01:21:57.460,601] <inf> [I] Settings------: Added ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:21:57.491,058] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:b4fa:c8d9:e14c:4422,0x5401)
    [01:21:57.517,578] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:0108, ecn:no, from:16eefb0b0b5f3b76, sec:no, prio:net, rss:-54.0
    [01:21:57.547,271] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:21:57.572,357] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:57.597,717] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:21:57.623,565] <inf> [I] Mle-----------: Child 0x0000 IPv6 address[1]=fda2:c723:923e:a564:6f7d:4057:9392:83d6
    [01:21:57.650,207] <inf> [I] AddrResolver--: Cache entry removed: fda2:c723:923e:a564:6f7d:4057:9392:83d6, 0xf400, list:cached - removing eid
    [01:21:57.679,962] <inf> [I] Mle-----------: Child 0x0000 has 1 registered IPv6 address, 1 address stored
    [01:21:57.719,177] <inf> [I] Settings------: Read ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:21:57.849,670] <inf> [I] Settings------: Added ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:21:57.879,669] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:14ee:fb0b:b5f:3b76,0x5402)
    [01:21:57.905,944] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-66, ack-fp:0
    [01:21:57.931,640] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:21:57.957,244] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-66, ack-fp:0
    [01:21:57.983,734] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:21:58.009,338] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:21:58.035,125] <inf> [I] Mac-----------: Frame rx failed, error:Duplicated, len:34, seqnum:33, type:Cmd(DataReq), src:16eefb0b0b5f3b76, dst:e219e200dff78436, sec:yes, ack
    [01:21:58.067,718] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-66, ack-fp:0
    [01:21:58.093,292] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-65, ack-fp:0
    [01:21:58.118,865] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:21:58.144,226] <inf> [I] Notifier------: StateChanged (0x00000400) [Child+]
    [01:21:58.167,907] <inf> [I] ChildSupervsn-: Starting Child Supervision
    
    Role changed: 4  flags: 0x400
    [01:21:58.209,197] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:ff2e, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:21:58.238,891] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:09bc, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:21:58.270,507] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:21:58.296,112] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:21:58.321,746] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:21:58.347,351] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:21:58.373,291] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:21:58.398,895] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:21:58.424,530] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:21:58.450,164] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:21:58.475,769] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:21:58.501,342] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:21:58.527,832] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:21:58.553,436] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:21:58.579,040] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:1
    [01:21:58.604,675] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:1
    [01:21:58.630,340] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:1
    [01:21:58.655,975] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:1
    [01:21:58.686,157] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:84, seqnum:49, type:Data, src:e219e200dff78436, dst:b6fac8d9e14c4422, sec:no, ackre
    [01:21:58.718,139] <inf> [I] DataPollHandlr: Indirect tx to child 5401 failed, attempt 1/4
    [01:21:58.743,774] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:3575, ecn:no, from:16eefb0b0b5f3b76, sec:no, prio:net, rss:-54.0
    [01:21:58.773,895] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:21:58.798,339] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:21:58.822,448] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:21:58.847,656] <wrn> [W] Mle-----------: Failed to process Parent Request: Duplicated
    [01:21:58.872,863] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:100, chksum:ff2e, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:21:58.900,970] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:58.925,567] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:21:58.951,354] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:d179, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-65.0
    [01:21:58.981,109] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:21:59.005,645] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:21:59.029,724] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:21:59.055,053] <wrn> [W] Mle-----------: Failed to process Parent Request: Duplicated
    [01:21:59.080,108] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:100, chksum:09bc, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:21:59.108,184] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:21:59.132,812] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:21:59.456,939] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:e864, ecn:no, from:16eefb0b0b5f3b76, sec:no, prio:net, rss:-54.0
    [01:21:59.486,511] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:21:59.511,230] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:21:59.535,369] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:21:59.561,096] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:21:59.586,944] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:7f26, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-64.0
    [01:21:59.616,546] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:21:59.641,082] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:21:59.665,100] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:21:59.690,917] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:00.170,104] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:22:00.202,575] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:cd16, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:22:00.230,895] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:00.255,493] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:22:00.454,986] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:00.487,213] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:cb90, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:00.515,350] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:00.539,978] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:00.710,845] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:8fd6, ecn:no, from:16eefb0b0b5f3b76, sec:no, prio:net, rss:-54.0
    [01:22:00.740,509] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:22:00.765,380] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:00.790,771] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:22:00.816,894] <inf> [I] Mle-----------: Child 0x5402 IPv6 address[1]=fda2:c723:923e:a564:6f7d:4057:9392:83d6
    [01:22:00.843,353] <inf> [I] Mle-----------: Child 0x5402 has 1 registered IPv6 address, 1 address stored
    [01:22:00.869,750] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:00.930,603] <inf> [I] Settings------: Removed ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:00.973,236] <inf> [I] Settings------: Read ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:01.095,550] <inf> [I] Settings------: Added ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:01.125,091] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:14ee:fb0b:b5f:3b76,0x5402)
    [01:22:01.151,733] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:6795, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-64.0
    [01:22:01.181,427] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:01.205,963] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:01.231,750] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:01.258,148] <inf> [I] Mle-----------: Child 0x5401 IPv6 address[1]=fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd
    [01:22:01.284,545] <inf> [I] Mle-----------: Child 0x5401 has 1 registered IPv6 address, 1 address stored
    [01:22:01.310,729] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:01.339,569] <inf> [I] Settings------: Read ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:01.391,448] <inf> [I] Settings------: Removed ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:01.434,234] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:01.542,449] <inf> [I] Settings------: Added ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:01.571,990] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:b4fa:c8d9:e14c:4422,0x5401)
    [01:22:01.598,266] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:01.624,420] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-65, ack-fp:0
    [01:22:01.650,329] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:01.675,933] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-65, ack-fp:0
    [01:22:01.701,538] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:01.727,691] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-65, ack-fp:0
    [01:22:01.753,509] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:01.779,083] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-65, ack-fp:0
    [01:22:01.804,687] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:01.830,322] <inf> [I] Mac-----------: Frame rx failed, error:Failed
    [01:22:01.853,790] <inf> [I] Notifier------: StateChanged (0x00000c00) [Child+ Child-]
    
    Role changed: 4  flags: 0xc00
    [01:22:01.896,392] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:4809, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:22:01.926,483] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:4134, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:01.956,268] <inf> [I] Commissioner--: Sent LeaderKeepAlive
    [01:22:01.978,454] <inf> [I] MeshCoPLeader-: Received LeaderKeepAlive
    [01:22:02.001,220] <inf> [I] MeshCoPLeader-: Sent LeaderKeepAlive response
    [01:22:02.024,261] <inf> [I] Commissioner--: Received LeaderKeepAlive response
    [01:22:02.049,194] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:22:02.074,768] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:02.100,341] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:22:02.125,946] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:02.151,519] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:22:02.177,124] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:22:02.202,789] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-65, ack-fp:0
    [01:22:02.228,424] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:22:02.254,089] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-66, ack-fp:0
    [01:22:02.279,632] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:02.306,121] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-66, ack-fp:0
    [01:22:02.331,787] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:22:02.357,360] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-66, ack-fp:0
    [01:22:02.382,934] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:1
    [01:22:02.408,569] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-66, ack-fp:1
    [01:22:02.438,720] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:84, seqnum:53, type:Data, src:e219e200dff78436, dst:16eefb0b0b5f3b76, sec:no, ackre
    [01:22:02.470,550] <inf> [I] DataPollHandlr: Indirect tx to child 5402 failed, attempt 1/4
    [01:22:02.500,274] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:84, seqnum:54, type:Data, src:e219e200dff78436, dst:b6fac8d9e14c4422, sec:no, ackre
    [01:22:02.532,196] <inf> [I] DataPollHandlr: Indirect tx to child 5401 failed, attempt 1/4
    [01:22:02.569,793] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:9e80, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-65.0
    [01:22:02.599,365] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:02.623,931] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:22:02.648,040] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:02.673,339] <wrn> [W] Mle-----------: Failed to process Parent Request: Duplicated
    [01:22:03.253,051] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:8786, ecn:no, from:16eefb0b0b5f3b76, sec:no, prio:net, rss:-54.0
    [01:22:03.282,562] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:22:03.306,976] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:22:03.331,390] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:22:03.357,177] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:22:03.383,026] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:7eb7, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-66.0
    [01:22:03.412,567] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:03.437,225] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:22:03.461,242] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:03.487,091] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:03.520,996] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:03.553,924] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:7206, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:03.582,031] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:03.606,567] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:03.938,171] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:22:03.970,977] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:717f, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:22:03.999,084] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:04.023,620] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:22:04.505,157] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:cba2, ecn:no, from:16eefb0b0b5f3b76, sec:no, prio:net, rss:-54.0
    [01:22:04.534,851] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:22:04.559,326] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:04.585,113] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:14ee:fb0b:b5f:3b76)
    [01:22:04.611,267] <inf> [I] Mle-----------: Child 0x5402 IPv6 address[1]=fda2:c723:923e:a564:6f7d:4057:9392:83d6
    [01:22:04.637,756] <inf> [I] Mle-----------: Child 0x5402 has 1 registered IPv6 address, 1 address stored
    [01:22:04.663,787] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:04.725,738] <inf> [I] Settings------: Removed ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:04.768,157] <inf> [I] Settings------: Read ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:04.890,686] <inf> [I] Settings------: Added ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:04.920,288] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:14ee:fb0b:b5f:3b76,0x5402)
    [01:22:04.946,746] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:ffb5, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-63.0
    [01:22:04.976,379] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:05.001,312] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:05.027,130] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:05.053,192] <inf> [I] Mle-----------: Child 0x5401 IPv6 address[1]=fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd
    [01:22:05.079,589] <inf> [I] Mle-----------: Child 0x5401 has 1 registered IPv6 address, 1 address stored
    [01:22:05.106,079] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:05.135,009] <inf> [I] Settings------: Read ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:05.179,992] <inf> [I] Settings------: Removed ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:05.223,327] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:05.331,024] <inf> [I] Settings------: Added ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:05.360,137] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:b4fa:c8d9:e14c:4422,0x5401)
    [01:22:05.386,383] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:1
    [01:22:05.412,750] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:1
    [01:22:05.438,507] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:05.464,080] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:1
    [01:22:05.489,685] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:05.515,991] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:1
    [01:22:05.541,656] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:05.567,260] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:1
    [01:22:05.593,109] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:05.619,049] <inf> [I] Notifier------: StateChanged (0x00000c00) [Child+ Child-]
    
    Role changed: 4  flags: 0xc00
    [01:22:05.661,621] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:cc41, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:22:05.691,436] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:de9f, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:05.723,022] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:05.749,053] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:05.774,627] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:05.801,055] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:05.826,629] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:05.852,264] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:05.878,295] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:05.904,296] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:05.929,992] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:05.955,596] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-55, ack-fp:0
    [01:22:05.982,391] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:100, chksum:cc41, ecn:no, to:16eefb0b0b5f3b76, sec:no, prio:net
    [01:22:06.010,498] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:06.035,156] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:14ee:fb0b:b5f:3b76]:19788
    [01:22:06.060,577] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:06.086,700] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:0
    [01:22:06.112,274] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:06.137,908] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-55, ack-fp:1
    [01:22:06.163,940] <inf> [I] MeshForwarder-: Received IPv6 None msg, len:40, chksum:0000, ecn:no, from:0x5402, sec:yes, prio:normal, rss:-55.0
    [01:22:06.193,176] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6f7d:4057:9392:83d6]
    [01:22:06.218,048] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:f400]
    [01:22:06.242,858] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:1
    [01:22:06.269,134] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x5402, sec:yes, prio:normal, rss:-55.0
    [01:22:06.298,919] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6f7d:4057:9392:83d6]
    [01:22:06.323,699] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    Provisioned existing Sensor. id = 0x21
    [01:22:06.366,302] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:06.392,303] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:06.418,151] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:86, chksum:4a66, ecn:no, to:0x5402, sec:yes, prio:normal
    [01:22:06.448,181] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:84, seqnum:54, type:Data, src:e219e200dff78436, dst:b6fac8d9e14c4422, sec:no, ackre
    [01:22:06.480,010] <inf> [I] DataPollHandlr: Indirect tx to child 5401 failed, attempt 2/4
    [01:22:06.505,798] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:22:06.531,860] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:22:06.557,495] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:22:06.583,099] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:0
    [01:22:06.609,100] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:1
    [01:22:06.635,375] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:84, seqnum:54, type:Data, src:e219e200dff78436, dst:b6fac8d9e14c4422, sec:no, ackre
    [01:22:06.667,175] <inf> [I] DataPollHandlr: Indirect tx to child 5401 failed, attempt 3/4
    [01:22:06.692,749] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:1
    [01:22:06.719,024] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:1, rss:-54, ack-fp:1
    [01:22:06.744,689] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:86, chksum:4a66, ecn:no, to:0x5402, sec:yes, prio:normal
    [01:22:06.772,186] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:22:06.797,393] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6f7d:4057:9392:83d6]:5683
    [01:22:06.827,331] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:21, seqnum:58, type:Data, src:0x5400, dst:0x5402, sec:yes, ackreq:yes
    [01:22:06.857,940] <inf> [I] DataPollHandlr: Indirect tx to child 5402 failed, attempt 1/4
    [01:22:06.885,772] <inf> [I] Mac-----------: Frame tx attempt 1/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:06.917,785] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:4adb, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-64.0
    [01:22:06.947,753] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:06.972,259] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:22:06.996,276] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:07.022,155] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:07.047,637] <inf> [I] Mac-----------: Frame tx attempt 2/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.079,467] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:07.109,527] <inf> [I] Mac-----------: Frame tx attempt 3/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.143,981] <inf> [I] Mac-----------: Frame tx attempt 4/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.179,992] <inf> [I] Mac-----------: Frame tx attempt 5/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.219,573] <inf> [I] Mac-----------: Frame tx attempt 6/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.262,390] <inf> [I] Mac-----------: Frame tx attempt 7/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.303,192] <inf> [I] Mac-----------: Frame tx attempt 8/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.344,848] <inf> [I] Mac-----------: Frame tx attempt 9/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.388,061] <inf> [I] Mac-----------: Frame tx attempt 10/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.432,556] <inf> [I] Mac-----------: Frame tx attempt 11/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.472,930] <inf> [I] Mac-----------: Frame tx attempt 12/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.516,113] <inf> [I] Mac-----------: Frame tx attempt 13/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.550,720] <inf> [I] Mac-----------: Frame tx attempt 14/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.594,207] <inf> [I] Mac-----------: Frame tx attempt 15/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.630,096] <inf> [I] Mac-----------: Frame tx attempt 16/16 failed, error:NoAck, len:33, seqnum:59, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:07.661,224] <inf> [N] MeshForwarder-: Failed to send IPv6 None msg, len:40, chksum:0000, ecn:no, to:0xf400, sec:yes, error:NoAck, prio:normal
    [01:22:07.690,856] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:6f7d:4057:9392:83d6]
    [01:22:07.715,637] <inf> [N] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:f400]
    [01:22:07.741,302] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:719a, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-63.0
    [01:22:07.771,331] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:07.795,837] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:22:07.819,885] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:07.845,733] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:07.870,849] <inf> [I] ChannelManager: Auto-triggered channel select
    [01:22:07.893,676] <inf> [I] ChannelManager: Request to select channel (skip quality check: no)
    [01:22:07.918,457] <inf> [I] ChannelManager: CCA-err-rate: 0x0000 < 0x23d6, selecting channel: no
    [01:22:07.944,488] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:07.970,184] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:b700, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:07.998,291] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:08.022,857] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:08.060,333] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:6667, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:08.088,439] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:08.112,976] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:08.137,695] <inf> [N] MeshForwarder-: Dropping (queue mgmt) IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, sec:yes, prio:normal
    [01:22:08.166,137] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:6f7d:4057:9392:83d6]
    [01:22:08.190,887] <inf> [N] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [01:22:08.213,897] <inf> [N] MeshForwarder-: Dropping (queue mgmt) IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, sec:yes, prio:normal
    [01:22:08.242,370] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:6f7d:4057:9392:83d6]
    [01:22:08.267,150] <inf> [N] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [01:22:08.911,285] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:9d40, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-62.0
    [01:22:08.940,979] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:08.965,484] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:08.990,875] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:09.017,303] <inf> [I] Mle-----------: Child 0x5401 IPv6 address[1]=fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd
    [01:22:09.043,701] <inf> [I] Mle-----------: Child 0x5401 has 1 registered IPv6 address, 1 address stored
    [01:22:09.069,702] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:09.098,327] <inf> [I] Settings------: Read ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:09.146,759] <inf> [I] Settings------: Removed ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:09.189,605] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:09.304,138] <inf> [I] Settings------: Added ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:09.333,770] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:b4fa:c8d9:e14c:4422,0x5401)
    [01:22:09.360,076] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:1
    [01:22:09.385,650] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:09.411,437] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:09.437,316] <inf> [I] Notifier------: StateChanged (0x00000c00) [Child+ Child-]
    
    Role changed: 4  flags: 0xc00
    [01:22:09.479,919] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:1d7e, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:09.510,406] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:09.536,682] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:09.562,530] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:84, seqnum:54, type:Data, src:e219e200dff78436, dst:b6fac8d9e14c4422, sec:no, ackre
    [01:22:09.594,360] <inf> [I] DataPollHandlr: Indirect tx to child 5401 failed, attempt 4/4
    [01:22:09.619,018] <inf> [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:100, chksum:1d7e, ecn:no, to:b6fac8d9e14c4422, sec:no, error:NoAck, prio:net
    [01:22:09.649,566] <inf> [N] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:09.674,102] <inf> [N] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:09.699,829] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:1
    [01:22:09.725,769] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:09.751,342] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:09.777,465] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:09.803,497] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:21, seqnum:62, type:Data, src:0x5400, dst:0x5401, sec:yes, ackreq:yes
    [01:22:09.834,320] <inf> [I] DataPollHandlr: Indirect tx to child 5401 failed, attempt 1/4
    [01:22:09.859,375] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:09.921,264] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:10.021,392] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:10.121,826] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    
    -------------------- Zephyr tasks --------------------
    Thread analyze:
     Wiznet              : STACK: unused 4828 usage 3364 / 8192 (41 %); CPU: 9 %
          : Total CPU cycles used: 15938005
     CoapServer          : STACK: unused 2444 usage 1652 / 4096 (40 %); CPU: 0 %
          : Total CPU cycles used: 114265
     mcumgr smp          : STACK: unused 1852 usage 196 / 2048 (9 %); CPU: 0 %
          : Total CPU cycles used: 0
     rx_q[0]             : STACK: unused 1260 usage 276 / 1536 (17 %); CPU: 0 %
          : Total CPU cycles used: 1231
     openthread          : STACK: unused 5916 usage 2276 / 8192 (27 %); CPU: 5 %
          : Total CPU cycles used: 8317999
     ot_radio_workq      : STACK: unused 1532 usage 516 / 2048 (25 %); CPU: 0 %
          : Total CPU cycles used: 7789
     nrf5_rx             : STACK: unused 428 usage 372 / 800 (46 %); CPU: 0 %
          : Total CPU cycles used: 3296
     sysworkq            : STACK: unused 900 usage 1148 / 2048 (56 %); CPU: 0 %
          : Total CPU cycles used: 2472
     MPSL Work           : STACK: unused 516 usage 508 / 1024 (49 %); CPU: 0 %
          : Total CPU cycles used: 352
     idle                : STACK: unused 212 usage 108 / 320 (33 %); CPU: 84 %
          : Total CPU cycles used: 136606102
     main                : STACK: unused 2580 usage 1516 / 4096 (37 %); CPU: 0 %
          : Total CPU cycles used: 207557
     ISR0                : STACK: unused 2980 usage 1116 / 4096 (27 %)
    
    CCA Failure Rate: [0%]
    
    
    Sensor 20:     rssi -41 dBm    lqi 208
    Sensor 21:     rssi -41 dBm    lqi 208
    Sensor 22:     rssi 0 dBm    lqi 0
    Relay 60:      rssi -41 dBm    lqi 208
    PING: 208.67.222.222 cs=0xf435 checksum=0xf435 data=A 32 byte string with this xxxx
    --[01:22:12.239,624] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:0167, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-63.0
    [01:22:12.269,165] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:12.293,731] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:22:12.317,840] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:12.343,658] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    ---[01:22:12.688,964] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:12.840,576] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:12.871,856] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:133, chksum:3dde, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:12.899,993] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:12.924,530] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    -[01:22:12.993,041] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:128, chksum:4dae, ecn:no, from:b6fac8d9e14c4422, sec:no, prio:net, rss:-63.0
    [01:22:13.022,705] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:13.047,271] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:13.072,662] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:b4fa:c8d9:e14c:4422)
    [01:22:13.098,815] <inf> [I] Mle-----------: Child 0x5401 IPv6 address[1]=fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd
    [01:22:13.125,244] <inf> [I] Mle-----------: Child 0x5401 has 1 registered IPv6 address, 1 address stored
    [01:22:13.151,336] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    [01:22:13.179,992] <inf> [I] Settings------: Read ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    -[01:22:13.228,637] <inf> [I] Settings------: Removed ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:13.271,759] <inf> [I] Settings------: Read ChildInfo {rloc:0x5402, extaddr:16eefb0b0b5f3b76, timeout:240, mode:0x04, version:4}
    -[01:22:13.386,047] <inf> [I] Settings------: Added ChildInfo {rloc:0x5401, extaddr:b6fac8d9e14c4422, timeout:240, mode:0x04, version:4}
    [01:22:13.415,588] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:b4fa:c8d9:e14c:4422,0x5401)
    [01:22:13.442,016] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:13.467,620] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:13.493,408] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-64, ack-fp:0
    [01:22:13.518,920] <inf> [I] Notifier------: StateChanged (0x00000c00) [Child+ Child-]
    
    Role changed: 4  flags: 0xc00
    [01:22:13.561,492] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:100, chksum:d506, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:13.591,766] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:13.617,401] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:0
    [01:22:13.642,974] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-64, ack-fp:1
    [01:22:13.673,278] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:100, chksum:d506, ecn:no, to:b6fac8d9e14c4422, sec:no, prio:net
    [01:22:13.701,416] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:13.725,982] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:b4fa:c8d9:e14c:4422]:19788
    [01:22:13.752,044] <inf> [I] MeshForwarder-: Received IPv6 None msg, len:40, chksum:0000, ecn:no, from:0x5401, sec:yes, prio:normal, rss:-64.0
    [01:22:13.781,555] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd]
    [01:22:13.806,335] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:f400]
    [01:22:13.832,641] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:13.859,558] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x5401, sec:yes, prio:normal, rss:-64.0
    [01:22:13.888,916] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd]
    [01:22:13.913,665] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    Provisioned existing Sensor. id = 0x20
    [01:22:13.956,390] <inf> [I] MeshForwarder-: Prepping indir tx IPv6 UDP msg, len:86, chksum:2a34, ecn:no, to:0x5401, sec:yes, prio:normal
    [01:22:13.986,236] <inf> [I] Mac-----------: Frame tx attempt 1/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.017,791] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:0
    [01:22:14.043,762] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.069,610] <inf> [I] Mac-----------: Frame tx attempt 2/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.101,287] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.127,319] <inf> [I] Mac-----------: Frame tx attempt 3/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.161,712] <inf> [I] Mac-----------: Frame tx attempt 4/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.193,878] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.219,818] <inf> [I] Mac-----------: Frame tx attempt 5/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.254,669] <inf> [I] Mac-----------: Frame tx attempt 6/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.286,499] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.315,124] <inf> [I] Mac-----------: Frame tx attempt 7/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    -[01:22:14.355,072] <inf> [I] Mac-----------: Frame tx attempt 8/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.386,779] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.416,381] <inf> [I] Mac-----------: Frame tx attempt 9/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.456,329] <inf> [I] Mac-----------: Frame tx attempt 10/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.487,976] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.516,296] <inf> [I] Mac-----------: Frame tx attempt 11/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    -[01:22:14.555,633] <inf> [I] Mac-----------: Frame tx attempt 12/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.587,280] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.615,539] <inf> [I] Mac-----------: Frame tx attempt 13/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.653,076] <inf> [I] Mac-----------: Frame tx attempt 14/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.684,753] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:14.713,684] <inf> [I] Mac-----------: Frame tx attempt 15/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    -[01:22:14.748,626] <inf> [I] Mac-----------: Frame tx attempt 16/16 failed, error:NoAck, len:33, seqnum:64, type:Data, src:0x5400, dst:0xf400, sec:yes, ackreq:yes
    [01:22:14.779,632] <inf> [N] MeshForwarder-: Failed to send IPv6 None msg, len:40, chksum:0000, ecn:no, to:0xf400, sec:yes, error:NoAck, prio:normal
    [01:22:14.809,661] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd]
    [01:22:14.834,503] <inf> [N] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:f400]
    [01:22:14.859,191] <inf> [N] MeshForwarder-: Dropping (queue mgmt) IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, sec:yes, prio:normal
    [01:22:14.887,542] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd]
    [01:22:14.912,750] <inf> [N] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [01:22:14.935,821] <inf> [N] MeshForwarder-: Dropping (queue mgmt) IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, sec:yes, prio:normal
    [01:22:14.964,172] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd]
    [01:22:14.988,922] <inf> [N] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [01:22:15.013,519] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:15.039,398] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:15.064,971] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:1, rss:-63, ack-fp:1
    [01:22:15.090,606] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:86, chksum:2a34, ecn:no, to:0x5401, sec:yes, prio:normal
    [01:22:15.118,164] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [01:22:15.143,402] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:a3ee:9eb5:dbb8:a9fd]:5683
    [01:22:15.171,997] <inf> [I] Mac-----------: Frame tx attempt 1/1 failed, error:NoAck, len:21, seqnum:66, type:Data, src:0x5400, dst:0x5401, sec:yes, ackreq:yes
    [01:22:15.202,606] <inf> [I] DataPollHandlr: Indirect tx to child 5401 failed, attempt 1/4
    [01:22:15.346,038] <inf> [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
    [01:22:15.374,511] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:91, chksum:bfe9, ecn:no, to:0xffff, sec:no, prio:net
    [01:22:15.401,702] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [01:22:15.426,330] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [01:22:15.687,561] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:17.990,173] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:18.688,476] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:20.989,929] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:21.687,103] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:23.990,692] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:24.688,323] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:25.854,888] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:56, chksum:d385, ecn:no, from:da8edccb92726b45, sec:no, prio:net, rss:-41.0
    [01:22:25.884,460] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:d88e:dccb:9272:6b45]:19788
    [01:22:25.908,966] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [01:22:25.932,647] <inf> [I] Mle-----------: Receive Discovery Request (fe80:0:0:0:d88e:dccb:9272:6b45)
    [01:22:25.958,099] <wrn> [W] Mle-----------: Failed to process Discovery Request: Security
    [01:22:26.990,447] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:27.048,431] <inf> [I] Commissioner--: Sent LeaderKeepAlive
    [01:22:27.070,617] <inf> [I] MeshCoPLeader-: Received LeaderKeepAlive
    [01:22:27.093,505] <inf> [I] MeshCoPLeader-: Sent LeaderKeepAlive response
    [01:22:27.116,455] <inf> [I] Commissioner--: Received LeaderKeepAlive response
    [01:22:27.688,446] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:29.442,047] <inf> [I] ChannelMonitor: 121 [ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ]
    [01:22:29.989,776] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:30.687,866] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:32.991,333] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-62, ack-fp:0
    [01:22:33.686,706] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:35.991,546] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:36.687,713] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:38.991,638] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:39.687,469] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:41.990,295] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-63, ack-fp:0
    [01:22:42.685,455] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    [01:22:44.991,546] <inf> [I] DataPollHandlr: Rx data poll, src:0x5401, qed_msgs:0, rss:-79, ack-fp:0
    [01:22:45.685,363] <inf> [I] DataPollHandlr: Rx data poll, src:0x5402, qed_msgs:0, rss:-54, ack-fp:0
    
    

    Do you see anything helpful?

    Mary

  • Here is another log, when joining succeeded.

    Joining is allowed at time [00:09:06.215,393], line 287

    The Joiner Router is started at time [00:09:06.992,126], line 319.  This event is missing in the failed example above.

    The Discovery Request is at time [00:09:10.185,638, line 335.  And the joining process follows.

    [00:08:30.494,445] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:33.252,166] <inf> [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
    [00:08:33.280,364] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:92, chksum:4f54, ecn:no, to:0xffff, sec:no, prio:net
    [00:08:33.307,495] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:08:33.332,122] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:08:33.357,177] <inf> [I] Mle-----------: Send Announce on channel 14
    [00:08:33.386,627] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:83, chksum:7a0c, ecn:no, to:0xffff, sec:yes, prio:net
    [00:08:33.413,909] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:08:33.438,415] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:08:33.495,971] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:36.494,781] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    
    -------------------- Zephyr tasks --------------------
    Thread analyze:
     Wiznet              : STACK: unused 4828 usage 3364 / 8192 (41 %); CPU: 14 %
          : Total CPU cycles used: 2457696
     CoapServer          : STACK: unused 2444 usage 1652 / 4096 (40 %); CPU: 0 %
          : Total CPU cycles used: 28188
     mcumgr smp          : STACK: unused 1852 usage 196 / 2048 (9 %); CPU: 0 %
          : Total CPU cycles used: 1
     rx_q[0]             : STACK: unused 1252 usage 284 / 1536 (18 %); CPU: 0 %
          : Total CPU cycles used: 546
     openthread          : STACK: unused 6124 usage 2068 / 8192 (25 %); CPU: 15 %
          : Total CPU cycles used: 2688072
     ot_radio_workq      : STACK: unused 1548 usage 500 / 2048 (24 %); CPU: 0 %
          : Total CPU cycles used: 4967
     nrf5_rx             : STACK: unused 452 usage 348 / 800 (43 %); CPU: 0 %
          : Total CPU cycles used: 1327
     sysworkq            : STACK: unused 892 usage 1156 / 2048 (56 %); CPU: 0 %
          : Total CPU cycles used: 2245
     MPSL Work           : STACK: unused 516 usage 508 / 1024 (49 %); CPU: 0 %
          : Total CPU cycles used: 32
     idle                : STACK: unused 212 usage 108 / 320 (33 %); CPU: 68 %
          : Total CPU cycles used: 11614751
     main                : STACK: unused 2580 usage 1516 / 4096 (37 %); CPU: 0 %
          : Total CPU cycles used: 104446
     ISR0                : STACK: unused 2980 usage 1116 / 4096 (27 %)
    
    CCA Failure Rate: [0%]
    
    
    Sensor 20:     rssi 0 dBm    lqi 0
    Relay 60:      rssi -37 dBm    lqi 220
    PING: 1.0.0.1 cs=0x8636 checksum=0x8636 data=A 32 byte string with this xxxx
    [00:08:39.494,781] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:39.721,740] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:83d4, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-54.0
    [00:08:39.750,915] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:39.775,695] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:39.800,445] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:39.822,631] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 12)
    [00:08:39.850,372] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:82d4, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:39.878,021] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:39.902,801] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:40.485,168] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:2c15, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:08:40.514,160] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:08:40.539,367] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:08:40.572,387] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:0336, ecn:no, to:0x2400, sec:yes, prio:normal
    [00:08:40.599,945] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:08:40.625,183] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:08:40.724,639] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:7fe8, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-54.0
    [00:08:40.753,814] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:40.778,686] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:40.803,436] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:40.825,622] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 13)
    [00:08:40.852,416] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:7ee8, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:40.880,065] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:40.904,846] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:40.979,095] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:92, chksum:105b, ecn:no, from:c6197d23b82740b9, sec:no, prio:net, rss:-38.0
    [00:08:41.008,666] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c419:7d23:b827:40b9]:19788
    [00:08:41.033,172] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:08:41.057,373] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:c419:7d23:b827:40b9,0x2400)
    [00:08:41.726,440] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:7bfc, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-54.0
    [00:08:41.755,645] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:41.780,395] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:41.805,175] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:41.827,392] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 14)
    [00:08:41.855,102] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:7afc, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:41.882,751] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:41.907,501] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:42.495,391] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:42.729,339] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:7810, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-54.0
    [00:08:42.758,514] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:42.783,294] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:42.807,983] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:42.830,169] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 15)
    [00:08:42.858,184] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:7710, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:42.885,925] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:42.910,705] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:43.730,957] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:7424, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-55.0
    [00:08:43.760,131] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:43.784,912] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:43.809,661] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:43.831,848] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 16)
    [00:08:43.859,558] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:7324, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:43.887,176] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:43.911,956] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:44.731,231] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:7038, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-65.0
    [00:08:44.760,406] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:44.785,186] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:44.809,906] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:44.832,122] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 17)
    [00:08:44.860,107] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:6f38, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:44.887,756] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:44.912,536] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:45.391,113] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:92, chksum:8903, ecn:no, from:a2b347ed38bef972, sec:no, prio:net, rss:-60.0
    [00:08:45.420,684] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:a0b3:47ed:38be:f972]:19788
    [00:08:45.445,190] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:08:45.469,360] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:a0b3:47ed:38be:f972,0xe800)
    [00:08:45.495,727] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:45.733,978] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:6c4c, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-57.0
    [00:08:45.763,183] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:45.787,963] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:45.812,622] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:45.834,838] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 18)
    [00:08:45.861,602] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:6b4c, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:45.889,251] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:45.914,001] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:46.735,534] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:6860, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-56.0
    [00:08:46.764,709] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:46.789,489] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:46.814,147] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:46.836,334] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 19)
    [00:08:46.864,318] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:6760, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:46.891,967] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:46.916,717] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:47.738,464] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:6474, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-58.0
    [00:08:47.767,669] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:47.792,449] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:47.817,108] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:47.839,294] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 20)
    [00:08:47.867,645] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:6374, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:47.895,263] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:47.920,043] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:48.496,276] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:48.740,081] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:6088, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-59.0
    [00:08:48.769,287] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:48.794,067] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:48.818,695] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:48.840,881] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 21)
    [00:08:48.869,873] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:5f88, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:48.897,521] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:48.922,271] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:49.742,950] <inf> [I] MeshForwarder-: Received IPv6 ICMP6 msg, len:56, chksum:5c9c, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-59.0
    [00:08:49.772,125] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:49.796,905] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:49.821,563] <inf> [I] Icmp6---------: Received Echo Request
    [00:08:49.843,780] <inf> [I] Icmp6---------: Sent Echo Reply (seq = 22)
    [00:08:49.871,459] <inf> [I] MeshForwarder-: Sent IPv6 ICMP6 msg, len:56, chksum:5b9c, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:49.899,108] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]
    [00:08:49.923,889] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:50.745,086] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-59.0
    [00:08:50.774,536] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:50.799,468] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:50.825,378] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:08:50.855,285] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:50.880,035] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:50.903,625] <inf> [I] Mac-----------: Frame tx attempt 1/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:50.936,004] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:08:50.965,576] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:50.990,386] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:51.013,824] <inf> [I] Mac-----------: Frame tx attempt 2/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:51.050,506] <inf> [I] Mac-----------: Frame tx attempt 3/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:51.084,167] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:b995, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:08:51.113,555] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:08:51.138,824] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:08:51.165,039] <inf> [I] Mac-----------: Frame tx attempt 4/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:51.200,836] <inf> [I] Mac-----------: Frame tx attempt 5/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:51.241,851] <inf> [I] Mac-----------: Frame tx attempt 6/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:51.282,073] <inf> [I] Mac-----------: Frame tx attempt 7/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:51.322,326] <inf> [I] Mac-----------: Frame tx attempt 8/16 failed, error:NoAck, len:84, seqnum:87, type:Data, src:0x5400, dst:0xe800, sec:yes, ackreq:yes
    [00:08:51.356,018] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:56, chksum:93c6, ecn:no, from:a2b347ed38bef972, sec:no, prio:net, rss:-59.0
    [00:08:51.385,620] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:a0b3:47ed:38be:f972]:19788
    [00:08:51.410,156] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [00:08:51.433,746] <inf> [I] Mle-----------: Receive Discovery Request (fe80:0:0:0:a0b3:47ed:38be:f972)
    [00:08:51.459,564] <inf> [I] Mle-----------: Delay Discovery Response (fe80:0:0:0:a0b3:47ed:38be:f972)
    [00:08:51.489,837] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:86, chksum:d676, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:51.518,341] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:08:51.543,579] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]:5683
    [00:08:51.574,005] <inf> [N] MeshForwarder-: Dropping (queue mgmt) IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, sec:yes, prio:normal
    [00:08:51.602,478] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:51.627,197] <inf> [N] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:51.650,177] <inf> [N] MeshForwarder-: Dropping (queue mgmt) IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, sec:yes, prio:normal
    [00:08:51.678,527] <inf> [N] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:51.703,338] <inf> [N] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:51.726,379] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:51.751,342] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:a0b3:47ed:38be:f972)
    [00:08:51.782,653] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:90b6, ecn:no, to:0x2400, sec:yes, prio:normal
    [00:08:51.810,180] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:08:51.835,418] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:08:51.867,523] <inf> [I] Mac-----------: Frame tx attempt 1/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:51.904,846] <inf> [I] Mac-----------: Frame tx attempt 2/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:51.941,894] <inf> [I] Mac-----------: Frame tx attempt 3/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:51.979,278] <inf> [I] Mac-----------: Frame tx attempt 4/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:52.017,883] <inf> [I] Mac-----------: Frame tx attempt 5/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:52.055,328] <inf> [I] Mac-----------: Frame tx attempt 6/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:52.100,982] <inf> [I] Mac-----------: Frame tx attempt 7/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:52.143,127] <inf> [I] Mac-----------: Frame tx attempt 8/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:52.188,873] <inf> [I] Mac-----------: Frame tx attempt 9/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ackr
    [00:08:52.230,041] <inf> [I] Mac-----------: Frame tx attempt 10/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ack
    [00:08:52.271,179] <inf> [I] Mac-----------: Frame tx attempt 11/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ack
    [00:08:52.315,277] <inf> [I] Mac-----------: Frame tx attempt 12/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ack
    [00:08:52.358,673] <inf> [I] Mac-----------: Frame tx attempt 13/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ack
    [00:08:52.399,353] <inf> [I] Mac-----------: Frame tx attempt 14/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ack
    [00:08:52.445,983] <inf> [I] Mac-----------: Frame tx attempt 15/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ack
    [00:08:52.489,044] <inf> [I] Mac-----------: Frame tx attempt 16/16 failed, error:NoAck, len:89, seqnum:89, type:Data, src:e219e200dff78436, dst:a2b347ed38bef972, sec:no, ack
    [00:08:52.521,270] <inf> [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:105, chksum:9a41, ecn:no, to:a2b347ed38bef972, sec:no, error:NoAck, prio:net
    [00:08:52.551,452] <inf> [N] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:08:52.575,958] <inf> [N] MeshForwarder-:     dst:[fe80:0:0:0:a0b3:47ed:38be:f972]:19788
    [00:08:54.495,391] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:55.055,175] <inf> [I] Mle-----------: Send Announce on channel 15
    [00:08:55.082,397] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:83, chksum:7864, ecn:no, to:0xffff, sec:yes, prio:net
    [00:08:55.109,619] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:08:55.134,185] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:08:55.617,248] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-59.0
    [00:08:55.648,071] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:55.672,912] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:55.696,105] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:55.723,144] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:66, chksum:6bd0, ecn:no, from:0xe800, sec:yes, prio:net, rss:-59.0
    [00:08:55.752,349] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:0:ff:fe00:e800]:61631
    [00:08:55.777,191] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:5400]:61631
    [00:08:55.802,307] <inf> [I] NetDiag-------: Received DiagGetRequest from fda2:c723:923e:a564:0:ff:fe00:e800
    [00:08:55.829,315] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:86, chksum:d676, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:55.856,872] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:08:55.882,110] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]:5683
    [00:08:55.913,360] <inf> [I] MeshForwarder-: Sent IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, to:0xffff, sec:yes, prio:normal
    [00:08:55.941,192] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:55.966,033] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:55.990,692] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-59.0
    [00:08:56.020,843] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:56.045,593] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:56.069,091] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:121, chksum:657b, ecn:no, to:0xe800, sec:yes, prio:normal
    [00:08:56.096,649] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:0:ff:fe00:5400]:61631
    [00:08:56.121,490] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:e800]:61631
    [00:08:56.148,376] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0xe800, sec:yes, prio:normal, rss:-60.0
    [00:08:56.177,886] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:56.202,697] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:56.225,921] <inf> [I] MeshForwarder-: Sent IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, to:0xffff, sec:yes, prio:normal
    [00:08:56.253,753] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:6346:ac45:ef71:66a3]
    [00:08:56.278,533] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:08:57.496,948] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:08:58.376,617] <inf> [I] Mle-----------: Send Advertisement (ff02:0:0:0:0:0:0:1)
    [00:08:58.404,266] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:92, chksum:162e, ecn:no, to:0xffff, sec:no, prio:net
    [00:08:58.431,396] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:08:58.455,932] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:00.495,666] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:02.258,361] <inf> [I] ChannelManager: Auto-triggered channel select
    [00:09:02.281,555] <inf> [I] ChannelManager: Request to select channel (skip quality check: no)
    [00:09:02.306,335] <inf> [I] ChannelManager: CCA-err-rate: 0x0000 < 0x23d6, selecting channel: no
    [00:09:02.332,855] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:cb26, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:09:02.361,877] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:09:02.387,084] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:09:02.418,304] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:a247, ecn:no, to:0x2400, sec:yes, prio:normal
    [00:09:02.445,739] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:09:02.470,977] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:09:03.496,246] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    
    Commissioner state = 0. Restarting...[00:09:05.618,865] <inf> [I] Commissioner--: Sent LeaderPetition
    [00:09:05.640,838] <inf> [I] Commissioner--: State: disabled -> petition
    
    Commissioner petitioning...
    [00:09:05.681,457] <inf> [I] Commissioner--: start commissioner OpenThread Commissioner
    [00:09:05.705,688] <inf> [I] Notifier------: StateChanged (0x00800000) [CommissionerState]
    
    Role changed: 3  flags: 0x800000
    [00:09:05.753,997] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:85, chksum:4ec5, ecn:no, to:0xe800, sec:yes, prio:net
    [00:09:05.781,890] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:0:ff:fe00:5400]:61631
    [00:09:05.806,823] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:fc00]:61631
    [00:09:05.833,099] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:87, chksum:5506, ecn:no, from:0xe800, sec:yes, prio:net, rss:-52.0
    [00:09:05.861,816] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:0:ff:fe00:fc00]:61631
    [00:09:05.886,718] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:5400]:61631
    [00:09:05.911,499] <inf> [I] Commissioner--: Received LeaderPetition response
    [00:09:05.934,661] <inf> [I] Commissioner--: State: petition -> active
    
    Commissioner active
    [00:09:05.975,067] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:103, chksum:1e58, ecn:no, from:a2b347ed38bef972, sec:no, prio:net, rss:-52.0
    [00:09:06.004,730] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:a0b3:47ed:38be:f972]:19788
    [00:09:06.029,205] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:06.053,375] <inf> [I] Mle-----------: Receive Data Response (fe80:0:0:0:a0b3:47ed:38be:f972)
    [00:09:06.078,796] <inf> [I] Notifier------: StateChanged (0x00800201) [Ip6+ NetData CommissionerState]
    [00:09:06.104,675] <inf> [I] Mle-----------: Delay Data Response (ff02:0:0:0:0:0:0:1)
    [00:09:06.128,479] <inf> [I] BbrLeader-----: PBBR state: None
    [00:09:06.150,146] <inf> [I] BbrLeader-----: Domain Prefix: ::/0, state: None
    
    Role changed: 3  flags: 0x800201
    [00:09:06.192,474] <inf> [I] Commissioner--: Sent CommissionerSet to leader
    [00:09:06.215,393] <inf> [I] Commissioner--: Added Joiner (any, J01NUS)
    
    Commissioner joiner started for 120 seconds...
    [00:09:06.259,643] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:103, chksum:9117, ecn:no, from:c6197d23b82740b9, sec:no, prio:net, rss:-37.0
    [00:09:06.290,435] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c419:7d23:b827:40b9]:19788
    [00:09:06.315,216] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:06.339,355] <inf> [I] Mle-----------: Receive Data Response (fe80:0:0:0:c419:7d23:b827:40b9)
    [00:09:06.364,624] <inf> [I] DuaManager----: PerformNextRegistration: InvalidState
    [00:09:06.389,099] <inf> [I] Mle-----------: Send delayed message (ff02:0:0:0:0:0:0:1)
    [00:09:06.414,001] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:67, chksum:9c59, ecn:no, to:0xe800, sec:yes, prio:net
    [00:09:06.441,162] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:0:ff:fe00:5400]:61631
    [00:09:06.466,033] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:fc00]:61631
    [00:09:06.492,645] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:58, chksum:e0dd, ecn:no, from:0xe800, sec:yes, prio:net, rss:-53.0
    [00:09:06.521,942] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:0:ff:fe00:fc00]:61631
    [00:09:06.546,813] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:0:ff:fe00:5400]:61631
    [00:09:06.571,594] <inf> [I] Commissioner--: Received CommissionerSet response
    [00:09:06.595,428] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:103, chksum:77a0, ecn:no, from:a2b347ed38bef972, sec:no, prio:net, rss:-53.0
    [00:09:06.625,061] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:a0b3:47ed:38be:f972]:19788
    [00:09:06.649,536] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:06.673,645] <inf> [I] Mle-----------: Receive Data Response (fe80:0:0:0:a0b3:47ed:38be:f972)
    [00:09:06.699,493] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:103, chksum:97ac, ecn:no, from:c6197d23b82740b9, sec:no, prio:net, rss:-38.0
    [00:09:06.729,095] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c419:7d23:b827:40b9]:19788
    [00:09:06.753,601] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:06.777,740] <inf> [I] Mle-----------: Receive Data Response (fe80:0:0:0:c419:7d23:b827:40b9)
    [00:09:06.802,978] <inf> [I] Notifier------: StateChanged (0x00000200) [NetData]
    [00:09:06.826,629] <inf> [N] MeshForwarder-: Dropping IPv6 UDP msg, len:103, chksum:27b0, ecn:no, sec:no, prio:net
    [00:09:06.853,240] <inf> [N] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:09:06.877,716] <inf> [N] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:06.901,214] <inf> [I] Mle-----------: Delay Data Response (ff02:0:0:0:0:0:0:1)
    [00:09:06.925,018] <inf> [I] BbrLeader-----: PBBR state: None
    [00:09:06.946,685] <inf> [I] BbrLeader-----: Domain Prefix: ::/0, state: None
    [00:09:06.969,787] <inf> [I] Ip6Filter-----: Added unsecure port 1000
    [00:09:06.992,126] <inf> [I] JoinerRouter--: Joiner Router: start
    
    Role changed: 3  flags: 0x200
    -[00:09:07.038,085] <inf> [I] ChannelMonitor: 14 [ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ]
    [00:09:07.066,406] <inf> [I] Mle-----------: Send delayed message (ff02:0:0:0:0:0:0:1)
    [00:09:07.095,031] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:103, chksum:c7f9, ecn:no, to:0xffff, sec:no, prio:net
    [00:09:07.122,222] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:09:07.146,850] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:08.528,167] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:92, chksum:5cd0, ecn:no, from:c6197d23b82740b9, sec:no, prio:net, rss:-38.0
    [00:09:08.557,769] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c419:7d23:b827:40b9]:19788
    [00:09:08.582,305] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:08.606,475] <inf> [I] Mle-----------: Receive Advertisement (fe80:0:0:0:c419:7d23:b827:40b9,0x2400)
    [00:09:09.497,131] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:10.107,971] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:56, chksum:c454, ecn:no, from:369d75a94f34e8c8, sec:no, prio:net, rss:-60.0
    [00:09:10.137,542] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:349d:75a9:4f34:e8c8]:19788
    [00:09:10.162,109] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [00:09:10.185,638] <inf> [I] Mle-----------: Receive Discovery Request (fe80:0:0:0:349d:75a9:4f34:e8c8)
    [00:09:10.211,486] <inf> [I] Mle-----------: Delay Discovery Response (fe80:0:0:0:349d:75a9:4f34:e8c8)
    [00:09:10.313,751] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:10.339,141] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:349d:75a9:4f34:e8c8)
    [00:09:10.369,567] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:90, chksum:b529, ecn:no, to:369d75a94f34e8c8, sec:no, prio:net
    [00:09:10.397,552] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:09:10.422,058] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:349d:75a9:4f34:e8c8]:19788
    [00:09:12.501,190] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:12.900,512] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:87fd, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:09:12.929,504] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:09:12.954,803] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:09:12.988,159] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:5f1e, ecn:no, to:0x2400, sec:yes, prio:normal
    [00:09:13.015,716] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:09:13.041,015] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:09:14.490,447] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:475, chksum:6991, ecn:no, from:c26ba300abd1a135, sec:no, prio:normal, rss:-59.0
    [00:09:14.520,355] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:14.544,860] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:14.569,366] <inf> [I] JoinerRouter--: JoinerRouter::HandleUdpReceive
    [00:09:14.593,048] <inf> [I] JoinerRouter--: Sent RelayRx
    [00:09:14.614,837] <inf> [I] Commissioner--: Starting new session with Joiner (any, J01NUS)
    
    Commissioner joiner started.
    [00:09:14.657,897] <inf> [I] Commissioner--: Received RelayRx (c06ba300abd1a135, 0x5400)
    [00:09:14.683,746] <inf> [I] Dtls----------: DTLS started
    [00:09:14.818,267] <inf> [I] JoinerRouter--: Received RelayTx
    [00:09:14.846,801] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:108, chksum:b5d2, ecn:no, to:c26ba300abd1a135, sec:no, prio:net
    [00:09:14.876,068] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:14.900,878] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:14.927,276] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:507, chksum:036a, ecn:no, from:c26ba300abd1a135, sec:no, prio:normal, rss:-59.125
    [00:09:14.957,489] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:14.981,872] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:15.006,439] <inf> [I] JoinerRouter--: JoinerRouter::HandleUdpReceive
    [00:09:15.029,968] <inf> [I] JoinerRouter--: Sent RelayRx
    [00:09:15.052,032] <inf> [I] Commissioner--: Received RelayRx (c06ba300abd1a135, 0x5400)
    [00:09:15.355,102] <inf> [I] JoinerRouter--: Received RelayTx
    [00:09:15.429,229] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:708, chksum:2866, ecn:no, to:c26ba300abd1a135, sec:no, prio:net
    [00:09:15.457,397] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:15.481,842] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:15.506,469] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:15.717,315] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:305, chksum:28bf, ecn:no, from:c26ba300abd1a135, sec:no, prio:normal, rss:-59.0
    [00:09:15.747,344] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:15.771,789] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:15.796,203] <inf> [I] JoinerRouter--: JoinerRouter::HandleUdpReceive
    [00:09:15.819,641] <inf> [I] JoinerRouter--: Sent RelayRx
    [00:09:15.841,583] <inf> [I] Commissioner--: Received RelayRx (c06ba300abd1a135, 0x5400)
    
    Commissioner joiner connected
    [00:09:16.007,263] <inf> [I] JoinerRouter--: Received RelayTx
    [00:09:16.035,522] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:115, chksum:6578, ecn:no, to:c26ba300abd1a135, sec:no, prio:net
    [00:09:16.064,025] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:16.088,470] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:16.113,708] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:122, chksum:333f, ecn:no, from:c26ba300abd1a135, sec:no, prio:normal, rss:-60.0
    [00:09:16.143,707] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:16.168,121] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:16.192,443] <inf> [I] JoinerRouter--: JoinerRouter::HandleUdpReceive
    [00:09:16.215,759] <inf> [I] JoinerRouter--: Sent RelayRx
    [00:09:16.237,579] <inf> [I] Commissioner--: Received RelayRx (c06ba300abd1a135, 0x5400)
    [00:09:16.262,512] <inf> [I] Commissioner--: Received JoinerFinalize
    
    Commissioner joiner finalized
    [00:09:16.303,161] <inf> [I] Commissioner--: Sent JoinerFinalize response
    [00:09:16.326,843] <inf> [I] JoinerRouter--: Received RelayTx
    [00:09:16.348,754] <inf> [I] JoinerRouter--: Received kek
    [00:09:16.371,215] <inf> [I] Mle-----------: Send Announce on channel 16
    [00:09:16.399,414] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:85, chksum:90e6, ecn:no, to:c26ba300abd1a135, sec:no, prio:net
    [00:09:16.427,825] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:16.452,331] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:16.486,236] <inf> [I] JoinerRouter--: Sent JoinerEntrust (len= 163)
    [00:09:16.511,352] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:79, chksum:ac7b, ecn:no, from:c26ba300abd1a135, sec:no, prio:normal, rss:-59.0
    [00:09:16.541,290] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:16.565,734] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:16.590,087] <inf> [I] JoinerRouter--: JoinerRouter::HandleUdpReceive
    [00:09:16.613,403] <inf> [I] JoinerRouter--: Sent RelayRx
    [00:09:16.635,162] <inf> [I] Commissioner--: Received RelayRx (c06ba300abd1a135, 0x5400)
    [00:09:16.662,689] <inf> [I] JoinerRouter--: Received RelayTx
    [00:09:16.684,722] <inf> [I] JoinerRouter--: Received RelayTx
    [00:09:16.707,214] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:83, chksum:17f9, ecn:no, to:0xffff, sec:yes, prio:net
    [00:09:16.734,436] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:09:16.758,972] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    -[00:09:16.797,302] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:163, chksum:68f3, ecn:no, to:c26ba300abd1a135, sec:yes, prio:net
    [00:09:16.825,500] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:61631
    [00:09:16.850,097] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:c06b:a300:abd1:a135]:61631
    [00:09:16.878,753] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:79, chksum:423c, ecn:no, to:c26ba300abd1a135, sec:no, prio:net
    [00:09:16.907,135] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:16.931,579] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:16.957,885] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:54, chksum:cbed, ecn:no, from:c26ba300abd1a135, sec:yes, prio:net, rss:-59.0
    [00:09:16.987,762] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c06b:a300:abd1:a135]:61631
    [00:09:17.012,329] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:61631
    [00:09:17.036,926] <inf> [I] JoinerRouter--: Receive JoinerEntrust response
    [00:09:17.060,638] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:79, chksum:b330, ecn:no, to:c26ba300abd1a135, sec:no, prio:net
    [00:09:17.088,653] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:1000
    [00:09:17.113,067] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:c06b:a300:abd1:a135]:1000
    [00:09:17.138,183] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:84, chksum:c602, ecn:no, from:dea195230f2d31d1, sec:no, prio:net, rss:-59.0
    [00:09:17.167,694] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:dca1:9523:f2d:31d1]:19788
    [00:09:17.192,199] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:2]:19788
    [00:09:17.216,247] <inf> [I] Mle-----------: Receive Parent Request (fe80:0:0:0:dca1:9523:f2d:31d1)
    [00:09:17.242,065] <inf> [I] Mle-----------: Delay Parent Response (fe80:0:0:0:dca1:9523:f2d:31d1)
    --[00:09:17.344,421] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:17.370,605] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:17.395,904] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:17.421,600] <inf> [I] Mle-----------: Send delayed message (fe80:0:0:0:dca1:9523:f2d:31d1)
    [00:09:17.453,796] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:129, chksum:7c1d, ecn:no, to:dea195230f2d31d1, sec:no, prio:net
    [00:09:17.481,903] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:09:17.506,408] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:dca1:9523:f2d:31d1]:19788
    --[00:09:17.792,724] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:104, chksum:dfca, ecn:no, from:dea195230f2d31d1, sec:no, prio:net, rss:-53.0
    [00:09:17.822,326] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:dca1:9523:f2d:31d1]:19788
    [00:09:17.846,832] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:09:17.872,100] <inf> [I] Mle-----------: Receive Child ID Request (fe80:0:0:0:dca1:9523:f2d:31d1)
    -[00:09:17.994,354] <inf> [I] Settings------: Added ChildInfo {rloc:0x5401, extaddr:dea195230f2d31d1, timeout:240, mode:0x0f, version:2}
    [00:09:18.024,047] <inf> [I] Mle-----------: Send Child ID Response (fe80:0:0:0:dca1:9523:f2d:31d1,0x5401)
    [00:09:18.049,987] <inf> [I] Notifier------: StateChanged (0x00000400) [Child+]
    [00:09:18.073,272] <inf> [I] ChildSupervsn-: Starting Child Supervision
    
    Role changed: 3  flags: 0x400
    [00:09:18.132,110] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:219, chksum:9ff9, ecn:no, to:dea195230f2d31d1, sec:yes, prio:net
    [00:09:18.160,430] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:e019:e200:dff7:8436]:19788
    [00:09:18.184,906] <inf> [I] MeshForwarder-:     dst:[fe80:0:0:0:dca1:9523:f2d:31d1]:19788
    ---[00:09:18.412,200] <inf> [I] AddrResolver--: Cache entry added: fda2:c723:923e:a564:265b:ed29:88fc:59b6, 0x5401 - snoop
    [00:09:18.439,605] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x5401, sec:yes, prio:normal, rss:-53.0
    [00:09:18.468,963] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:265b:ed29:88fc:59b6]
    [00:09:18.493,713] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:09:18.517,517] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:18.547,180] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:86, chksum:021e, ecn:no, to:0x5401, sec:yes, prio:normal
    [00:09:18.574,707] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:09:18.600,006] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:265b:ed29:88fc:59b6]:5683
    [00:09:18.629,760] <inf> [I] MeshForwarder-: Sent IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, to:0xffff, sec:yes, prio:normal
    [00:09:18.657,714] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:265b:ed29:88fc:59b6]
    [00:09:18.682,617] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    
    Commissioner joiner end
    [00:09:18.725,738] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:09:18.755,310] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:265b:ed29:88fc:59b6]
    [00:09:18.780,059] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:09:18.804,077] <inf> [I] MeshForwarder-: Received IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:09:18.833,435] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:265b:ed29:88fc:59b6]
    [00:09:18.858,276] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:09:18.881,530] <inf> [I] MeshForwarder-: Sent IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, to:0xffff, sec:yes, prio:normal
    [00:09:18.909,362] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:265b:ed29:88fc:59b6]
    [00:09:18.934,112] <inf> [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:1]
    [00:09:21.497,589] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:23.469,329] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:70, chksum:4a67, ecn:no, from:0x2400, sec:yes, prio:normal, rss:-38.0
    [00:09:23.498,352] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:09:23.523,559] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:09:23.555,389] <inf> [I] MeshForwarder-: Sent IPv6 UDP msg, len:96, chksum:2188, ecn:no, to:0x2400, sec:yes, prio:normal
    [00:09:23.582,916] <inf> [I] MeshForwarder-:     src:[fda2:c723:923e:a564:d653:e8fc:7c8a:3f1f]:5683
    [00:09:23.608,215] <inf> [I] MeshForwarder-:     dst:[fda2:c723:923e:a564:515e:3923:7910:f555]:5683
    [00:09:24.205,627] <inf> [I] MeshForwarder-: Received IPv6 UDP msg, len:83, chksum:eff0, ecn:no, from:c6197d23b82740b9, sec:no, prio:net, rss:-37.0
    [00:09:24.235,198] <inf> [I] MeshForwarder-:     src:[fe80:0:0:0:c419:7d23:b827:40b9]:19788
    [00:09:24.259,704] <inf> [I] MeshForwarder-:     dst:[ff02:0:0:0:0:0:0:1]:19788
    [00:09:24.283,721] <inf> [I] Mle-----------: Receive Announce (fe80:0:0:0:c419:7d23:b827:40b9)
    [00:09:24.498,382] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    [00:09:27.496,704] <dbg> [D] Mac-----------: Frame rx failed, error:DestinationAddressFiltered
    
    

    It seems that 

    bool LeaderBase::IsJoiningEnabled(void) const om network_data_leader.cpp is returning false.  I think the steering data is not getting set.  Why would that be?

    Mary

  • I'm trying to look at the Commissioning data (which includes steering data) with this call:

    otNetDataGetCommissioningDataset()
    In prj.conf, I have
    CONFIG_OPENTHREAD_FTD=y
    CONFIG_OPENTHREAD_NETDATA_PUBLISHER=y
    And, in the compiler output I see:
    - OT_NETDATA_PUBLISHER=ON --> OPENTHREAD_CONFIG_NETDATA_PUBLISHER_ENABLE=1
    But, the end result of compilation is this error:
    ../src/coap_server.c:387: undefined reference to `otNetDataGetCommissioningDataset'
    How do I include this function?
    Mary
  • Hi, 

    This function was introduced in Openthread API somewhere around November this year.  Thus this function is not available at NCS 1.9.1. You will have to move to the latest version of NCS. 

    -Amanda H.

Reply Children
  • As noted in my reply on Nov 9, the project was migrated to NCS 2.4.1

    Mary

  • When joining fails, I do not see this line in the log:

    [00:09:06.992,126] <inf> [I] JoinerRouter--: Joiner Router: start

    The code that creates this log message is in

    <sdk>/modules/lib/openthread/src/core/meshcop/joiner_router.cpp, line 67

    void JoinerRouter::Start(void)
    {
        VerifyOrExit(Get<Mle::MleRouter>().IsFullThreadDevice());
    
        if (Get<NetworkData::Leader>().IsJoiningEnabled())
        {
            uint16_t port = GetJoinerUdpPort();
    
            VerifyOrExit(!mSocket.IsBound());
    
            IgnoreError(mSocket.Open(&JoinerRouter::HandleUdpReceive, this));
            IgnoreError(mSocket.Bind(port));
            IgnoreError(Get<Ip6::Filter>().AddUnsecurePort(port));
            LogInfo("Joiner Router: start");
        }
        else
        {
            VerifyOrExit(mSocket.IsBound());
    
            IgnoreError(Get<Ip6::Filter>().RemoveUnsecurePort(mSocket.GetSockName().mPort));
    
            IgnoreError(mSocket.Close());
        }
    
    exit:
        return;
    }

    My main question is why wasn't joining enabled?

    How can I detect and correct this situation?

    Mary

  • It seems that there is a conversation between the Commissioner and the Leader before Joining is fully enabled.  The signal that this has completed is a Thread state change with the OT_CHANGED_THREAD_NETDATA flag set.

    So, I implemented a work around.

    When the commissioner allows joining, start a timer (joinerstart_timer) with a 2 second timeout.

    // Called in workqueue joining_work
    static void activate_joining(struct k_work *item)
    {
    	ARG_UNUSED(item);
    
    	struct openthread_context *ot_context = openthread_get_default_context();
    	otError err;
    
    	otInstance *instance = ot_context->instance;
    
    	otCommissionerState state;
    	if ((state = otCommissionerGetState(instance)) == OT_COMMISSIONER_STATE_ACTIVE)
    	{
    		openthread_api_mutex_lock(ot_context);
    		err = otCommissionerAddJoiner(instance, NULL, pskd, JOINER_TIMEOUT); 
    		openthread_api_mutex_unlock(ot_context);
    		if (err != OT_ERROR_NONE)
    		{
    			printk("\r\notCommissionerAddJoiner() failed [%d]\r\n", err);
    		}
    		else
    		{
    			g_joining_allowed = true;
    
    			printk("\r\nCommissioner joiner started for %d seconds...\r\n", JOINER_TIMEOUT);
    			printk("Commissioner SessionID: [%d]\r\n\n", otCommissionerGetSessionId(instance));
    			k_timer_start(&joinerstart_timer, K_MSEC(2000), K_MSEC(2000));
    		}
    	}
    	else
    	{
    		printk("\r\nCommissioner state = %d. Restarting...", state);
    
    		openthread_api_mutex_lock(ot_context);
    		err = otCommissionerStart(ot_context->instance, commissioner_state_cb, commissioner_joiner_cb, ot_context);
    		openthread_api_mutex_unlock(ot_context);
    		if (err != OT_ERROR_NONE)
    			printk("otCommissionerStart() failed [%d]\r\n", err);
    		else
    			g_start_joiner = true;		// trigger AddJoiner when "commissioner active" happens
    	}
    }

    If the Thread state changes with OT_CHANGED_THREAD_NETDATA, stop the timer.  Everything is ok.

    static void on_thread_state_changed(otChangedFlags flags, struct openthread_context *ot_context, void *user_data)
    {
    	otError err;
    
    	printk("\r\nThread state changed: role: %d  flags: 0x%x\r\n", otThreadGetDeviceRole(ot_context->instance), flags);
    
    	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:
    			ot_is_connected = true;
    
    			if (otCommissionerGetState(ot_context->instance) == OT_COMMISSIONER_STATE_DISABLED)
    			{
    				openthread_api_mutex_lock(ot_context);
    				err = otCommissionerStart(ot_context->instance, commissioner_state_cb, commissioner_joiner_cb, ot_context);
    				openthread_api_mutex_unlock(ot_context);
    				if (err != OT_ERROR_NONE)
    					printk("otCommissionerStart() failed [%d]\r\n", err);
    			}
    			break;
    
    		case OT_DEVICE_ROLE_DISABLED:
    		case OT_DEVICE_ROLE_DETACHED:
    		default:
    			ot_is_connected = false;
    			break;
    
    		} // endswitch: role
    	} // endif: role changed
    
    	if (flags & OT_CHANGED_THREAD_NETDATA)
    	{
    		k_timer_stop(&joinerstart_timer);
    	}
    }

    But, if the timer expires first.  Stop the commissioner.  

    void on_joinerstart_timeout(struct k_work *work)
    {
    	otError err;
    	struct openthread_context *ot_context = openthread_get_default_context();
    
    	printk("\r\nJoiner Start timed out. Restarting commissioner.");
    
    	// Net Data Changed was not received, restart commissioner
    	openthread_api_mutex_lock(ot_context);
    	err = otCommissionerStop(ot_context->instance);
    	openthread_api_mutex_unlock(ot_context);
    
    	if (err != OT_ERROR_NONE)
    		printk("otCommissionerStop() failed [%d]\r\n", err);
    }
    
    K_WORK_DEFINE(joinerstarttimout_work, on_joinerstart_timeout);
    
    void joinerstart_timer_handler(struct k_timer *p_timer)
    {
    	k_timer_stop(&joinerstart_timer);
    	k_work_submit(&joinerstarttimout_work);		// stops commissioner
    }

    The user will have to re-initiate joining (button press in our case), which will restart the Commissioner, then call activate_joining().

    I still don't know why the process fails occasionally, but the workaround has succeeded several times.

    Mary

Related