MESH-COP: Security error after finalize action

[OlivierGre]

Hi there,

I'm seeing from time to time a problem during Thread commissioning (about 10% of the times).

Sometimes, the commissioning is seen as OK on the Android phone but a failure is displayed on the Thread device side. This failure happens after the finalize action so that's why the smartphone doesn't see the problem (I can see that the smartphone received the JOIN_FIN.req and sent JOIN_FIN.rsp). In the traces below, you can see that the the firmware of the Thread device indicates "Frame rx failed, error:Security".

Would you have some hints to help me to find where this issue is coming from? I don't know if it is a problem on the Thread device or in the OTBR.

An important info:
The firmware used in the Thread device is based on an openthread library from december 2021.
The commissioning application used in the smartphone is from July 2021.
I have the action to update them but it is not possible right now.

Thanks for your advices!
Regards
Olivier

[0000026529] [MESH_COP]  [INFO]-MESH-CP-: JoinerState: Connecting -> Connected
[0000026530] [MESH_COP]  [INFO]-MESH-CP-: Joiner sent finalize
(0000000 > 0000)        [TXa:x09|00011020|OK|x09,0000]  8a84 -> 25a0    (15)
[0000026540] [MAC]   [INFO]-MAC-----: Sent IPv6 UDP msg, len:117, chksum:794c, to:c61b22f5e1ad25a0, sec:no, prio:normal
[0000026542] [MAC]   [INFO]-MAC-----:     src:[fe80:0:0:0:a4bc:d717:9d0b:8a84]:1000
[0000026544] [MAC]   [INFO]-MAC-----:     dst:[fe80:0:0:0:c41b:22f5:e1ad:25a0]:1000
                        [RX :x07|B0(0/1)|IT:043|143,0]  25a0 -> ffff    (15)
[0000026739] [MAC]   [INFO]-MAC-----: Frame rx failed, error:Security, len:66, seqnum:7, type:Data, src:c61b22f5e1ad25a0, dst:0xffff, sec:yes, ackreq:no
                        [RXa:x08|B0(0/1)|IT:044|143,0]  25a0 -> 8a84    (15)
                        [RXa:x09|B0(0/1)|IT:045|143,0]  25a0 -> 8a84    (15)
[0000026802] [MAC]   [INFO]-MAC-----: Received IPv6 UDP msg, len:159, chksum:5ff2, from:c61b22f5e1ad25a0, sec:yes, prio:net, rss:-56.0
[0000026805] [MAC]   [INFO]-MAC-----:     src:[fe80:0:0:0:c41b:22f5:e1ad:25a0]:61631
[0000026806] [MAC]   [INFO]-MAC-----:     dst:[fe80:0:0:0:a4bc:d717:9d0b:8a84]:61631
[0000026807] [MESH_COP]  [WARN]-MESH-CP-: Error Drop while processing joiner entrust
                        [RX :x0a|B0(0/1)|IT:046|143,0]  25a0 -> ffff    (15)

[jwhui]

The "Frame rx failed, error:Security" line is triggered by a packet sent to the broadcast address (0xffff). As a result, I believe this packet is unrelated to the commissioning flow. Packets sent in the middle of the commissioning flow are unicast packets.

[OlivierGre]

Here is the log recorded during a successful commissioning.

I can see some packets sent to broadcast address 0xffff
(0000000 > 0000) [TX :x7b|00811000|..|x7b,0000] c288 -> ffff (13)
Is it expected?

I can see also the reception of 2 multicast packets:

                        [RX :xa2|B0(0/1)|IT:026|129,0]  3968 -> ffff    (15)
[0000029771] [REGION UNDEF] [I] Mac-----------: Frame rx failed, error:Security, len:121, seqnum:162, type:Data, src:a60b7f5919e03968, dst:0xffff, sec:yes, ackreq:no
                        [RX :xa3|B0(0/1)|IT:027|129,0]  3968 -> ffff    (15)
[0000029806] [REGION UNDEF] [I] Mac-----------: Frame rx failed, error:Security, len:66, seqnum:163, type:Data, src:a60b7f5919e03968, dst:0xffff, sec:yes, ackreq:no

They are failing but the commissioning is successful.

You said that multicast packets are not expected during the commissioning so I'm wondering why I'm getting that. May they be due to our OTBR?

Thank you

commissioning-ok.txt

[jwhui]

The broadcast frames are likely unrelated to Thread Commissioning. Note that Thread devices are operating multiple protocols in parallel during normal operation.

[OlivierGre]

Hi Jonathan,
I'm trying to understand where my multicast messages come from.

In the spec, I'm looking at "8.4.4 Joiner Protocol". There is a description of the Discovery Request (8.4.4.1.1.1) and then a description of the Discovery Response ( 8.4.4.1.1.2). For the Discovery Response, the spec says that the Discovery Response messages are Unicast messages.

What about the Discovery Request messages? Is it Unicast or Multicast?
In my case it looks multicast. Is it what is expected?
In the trace below, I can see that multicast Discovery Request messages are sent. Then we get a unicast Discovery Response but the multicast Discovery Request messages continue and lead to an error.

I have put a breakpoint in MeshForwarder::LogIp6Message() and I can see in the call stack that this message is sent by MeshForwarder::HandleLowpanHC(). It seems related to 6LoWPAN Header Compression.

NB: I will be out of the office in the next 2 weeks so I will see your messages when I come back.

Regards

[0000324064] [REGION UNDEF] [I] Dtls----------: Joiner starting
[0000324066] [PLATFORM] PANID=AE12
[0000324067] [REGION UNDEF] [I] Mle-----------: Send Discovery Request (ff02:0:0:0:0:0:0:2)
[0000324068] [REGION UNDEF] [I] Joiner--------: JoinerState: Idle -> Discover
[00:05:25.163] APP_THREAD_StateNotif 0x1001009
[0000324070] [REGION UNDEF] [I] Notifier------: StateChanged (0x0800800b) [Ip6+ Ip6- LLAddr PanId JoinerState]
[00:05:25.180] APP_THREAD_StateNotif 0x800800b
(0000000 > 0000) [TX :x96|00011000|..|x96,0000] ae12 -> ffff (11)
[0000324089] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000324091] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000324093] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x97|00811000|..|x97,0000] ae12 -> ffff (12)
[0000324399] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000324401] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000324402] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x98|00811000|..|x98,0000] ae12 -> ffff (13)
[0000324708] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000324710] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000324711] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x99|00811000|..|x99,0000] ae12 -> ffff (14)
[0000325017] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000325019] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000325021] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x9a|00811000|..|x9a,0000] ae12 -> ffff (15)
[0000325328] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000325330] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000325331] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
[RXa:x9a|B0(0/1)|IT:000|133,0] 1234 -> face (15)
[0000325493] [REGION UNDEF] [I] MeshForwarder-: Received IPv6 UDP msg, len:108, chksum:d7fd, from:a60b7f5919e03968, sec:no, prio:net, rss:-59.0
[0000325495] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:a40b:7f59:19e0:3968]:19788
[0000325497] [REGION UNDEF] [I] MeshForwarder-: dst:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000325500] [REGION UNDEF] [I] Mle-----------: Receive Discovery Response (fe80:0:0:0:a40b:7f59:19e0:3968)
[0000325502] [REGION UNDEF] [I] Joiner--------: Joiner discover network: a60b7f5919e03968, pan:0x1234, port:1000, chan:15, rssi:-59, allow-any:no
(0000000 > 0000) [TX :x9b|00811000|..|x9b,0000] ae12 -> ffff (16)
[0000325638] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000325640] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000325641] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x9c|00811000|..|x9c,0000] ae12 -> ffff (17)
[0000325950] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000325952] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000325953] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x9d|00811000|..|x9d,0000] ae12 -> ffff (18)
[0000326260] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000326262] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000326263] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x9e|00811000|..|x9e,0000] ae12 -> ffff (19)
[0000326569] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000326571] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000326572] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :x9f|00811000|..|x9f,0000] ae12 -> ffff (20)
[0000326878] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000326880] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000326881] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :xa0|00811000|..|xa0,0000] ae12 -> ffff (21)
[0000327186] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000327188] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000327190] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :xa1|00811000|..|xa1,0000] ae12 -> ffff (22)
[0000327494] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000327496] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000327498] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :xa2|00811000|..|xa2,0000] ae12 -> ffff (23)
[0000327802] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000327804] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000327806] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :xa3|00811000|..|xa3,0000] ae12 -> ffff (24)
[0000328110] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000328112] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000328114] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :xa4|00811000|..|xa4,0000] ae12 -> ffff (25)
[0000328418] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000328420] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000328422] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
(0000000 > 0000) [TX :xa5|00811000|..|xa5,0000] ae12 -> ffff (26)
[0000328728] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 UDP msg, len:56, chksum:f80f, to:0xffff, sec:no, prio:net
[0000328730] [REGION UNDEF] [I] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000328731] [REGION UNDEF] [I] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788
[0000329032] [REGION UNDEF] [N] MeshForwarder-: Failed to send IPv6 UDP msg, len:56, chksum:f80f, to:None, sec:no, error:Abort, prio:net
[0000329035] [REGION UNDEF] [N] MeshForwarder-: src:[fe80:0:0:0:b44c:cffa:1f72:face]:19788
[0000329036] [REGION UNDEF] [N] MeshForwarder-: dst:[ff02:0:0:0:0:0:0:2]:19788

[jwhui]

Thread uses multicast for a number of messages, including MLE Advertisements, MLE Discovery Requests, Address Queries, etc.

In your log above, the multicast messages are MLE Discovery Request messages. They are being sent across different channels, scanning for Thread devices on different channels. Having the MLE Discover Request messages sent across all channels, even after receiving a MLE Discovery Response is expected. This allows the device to discover neighbors on all channels.

The abort error at the end is expected and is how the Discovery Scanner component stops the operation when it has finished scanning across all the channels:

openthread/src/core/thread/discover_scanner.cpp

Lines 187 to 192 in 4e8eecc

	case kStateScanDone:
	// If scan is finished (no more channels to scan), abort the
	// Discovery Request frame tx. The handler callback is invoked &
	// state is cleared from `HandleDiscoveryRequestFrameTxDone()`.
	frame = nullptr;
	break;

[OlivierGre]

Ok thank you Jonathan.