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
  • 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.

  • 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

Reply
  • 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

Children
  • 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