OTBR using invalid IPV6 address

[OlivierGre]

Hi,
I'm working on a Thread commissioning demo where we are doing the following:

• Perform Thread Commissioning (with an Android Commissioner)
• Use SRP to indicate the presence of the Thread device
• Once the smartphone detects the service, it can get the IPV6 address of the device and send it some UDP command (we do a fake Thermostat).

We are seeing a bug for which I would like to request your insights:

The first time that we do the test, everything works fine.
At the end of the test, we reboot the Joiner device without saving any Thread credential so it will start disconnecting from Thread network. We will then be able to demonstrate the commissioning again.
The OTBR is not rebooted.

At the second try, we observe that SRP is working but there is then a blocking period of about 20s where we can't send UDP commands to the device. While looking at the Test 2 TCP log file, we can see lot of errors like this:

(0000000 > 0000)        [TXa:x6f|00111000|..|x6f,0014]  0400 -> 6000    (15)
[0000541709] [REGION UNDEF] [I] LinkRaw-------: Frame tx failed, error:NoAck, retries:0/15, len:62, seqnum:111, type:Data, src:0x0400, dst:0x6000, sec:yes, ackreq:yes
(0000000 > 0000)        [TXa:x6f|00111000|..|x6f,0014]  0400 -> 6000    (15)
[0000541717] [REGION UNDEF] [I] LinkRaw-------: Frame tx failed, error:NoAck, retries:1/15, len:62, seqnum:111, type:Data, src:0x0400, dst:0x6000, sec:yes, ackreq:yes
(0000000 > 0000)        [TXa:x6f|00111000|..|x6f,0014]  0400 -> 6000    (15)
[0000541726] [REGION UNDEF] [I] LinkRaw-------: Frame tx failed, error:NoAck, retries:2/15, len:62, seqnum:111, type:Data, src:0x0400, dst:0x6000, sec:yes, ackreq:yes
(0000000 > 0000)        [TXa:x6f|00111000|..|x6f,0014]  0400 -> 6000    (15)

The OTBR is trying to send some packets to the RLOC 0x6000 but it doesn't exist anymore!

In "test2_nok_joiner_device.txt" there is these traces where Joiner RLOC is switched from 0x6000 to 0x0402:

[0000017080] [REGION UNDEF] [N] Mle-----------: RLOC16 6000 -> fffe
[0000017080] [PLATFORM]   Short_Addr=FFFE
[0000017081] [REGION UNDEF] [I] Mle-----------: AttachState Idle -> Start
[0000017083] [REGION UNDEF] [I] Notifier------: StateChanged (0x10000040) [Rloc- ActDset]
[00:00:17.932] APP_THREAD_StateNotif 0x10000040
[00:00:17.932] OT_CHANGED_THREAD_RLOC_REMOVED
[00:00:17.933] OT_CHANGED_ACTIVE_DATASET
...
[0000018243] [REGION UNDEF] [N] Mle-----------: RLOC16 fffe -> 0402
[0000018243] [PLATFORM]   Short_Addr=402
[0000018244] [REGION UNDEF] [N] Mle-----------: Role detached -> child
[0000018246] [REGION UNDEF] [I] Notifier------: StateChanged (0x300012a4) [Role Rloc+ PartitionId NetData Ip6Mult+ ActDset PndDset]
[0000018247] [REGION UNDEF] [I] BbrLeader-----: PBBR state: Added
[0000018248] [REGION UNDEF] [I] BbrLeader-----: Rloc16: 0x 400, seqno: 62, delay: 5, timeout 3600

Looking at the OTBR syslog, RLOC 0x6000 & RLOC 0x0402 are not linked to same target IPv6:

Oct  6 11:42:52 raspberrypi otbr-agent[809]: 00:08:23.465 [I] MeshForwarder-: Sent IPv6 UDP msg, len:60, chksum:5dd4, ecn:no, to:0x0402, sec:yes, prio:low
Oct  6 11:42:52 raspberrypi otbr-agent[809]: 00:08:23.465 [I] MeshForwarder-:     src:[fdde:ad00:beef:0:dfab:10f4:4333:f5d4]:53540
Oct  6 11:42:52 raspberrypi otbr-agent[809]: 00:08:23.465 [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:7c92:e10c:d993:b249]:49154
Oct  6 11:42:53 raspberrypi otbr-agent[809]: 00:08:23.881 [I] MeshForwarder-: Sent IPv6 UDP msg, len:49, chksum:3cd7, ecn:no, to:0x6000, sec:yes, prio:low
Oct  6 11:42:53 raspberrypi otbr-agent[809]: 00:08:23.881 [I] MeshForwarder-:     src:[2a02:8440:5340:6e97:74c9:b0e:fb38:2384]:52205
Oct  6 11:42:53 raspberrypi otbr-agent[809]: 00:08:23.881 [I] MeshForwarder-:     dst:[fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965]:45000

RLOC 0x0402 corresponds to the address fdde:ad00:beef:0:7c92:e10c:d993:b249 which is indeed used during Test2.
RLOC 0x6000 corresponds to the address fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965 which is from Test1! It is unknown from the Joiner device of test2 since it has been rebooted.

Do you know what we could have missed to update the Border Router tables ?

The attached zip file contains:

• the OTBR syslog
• The RCP and Joiner device logs for Test1
• The RCP and Joiner device logs for Test2
• A file giving the IPV6 addresses of the OTBR and the Android Commissioner

Thank you
Regards
Olivier

logs.zip

[jwhui]

RLOC 0x0402 corresponds to the address fdde:ad00:beef:0:7c92:e10c:d993:b249 which is indeed used during Test2.
RLOC 0x6000 corresponds to the address fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965 which is from Test1! It is unknown from the Joiner device of test2 since it has been rebooted.

Looking at test2_nok_joiner_device.txt, it appears that fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965 is still known to the device. And the SRP Client is still registering with that IPv6 address.

$ grep e965 test2_nok_joiner_device.txt 
[0000018260] [REGION UNDEF] [I] Slaac---------: Adding address fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[00:00:19.129] Addr fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[00:00:19.133] Selected IP Address : fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[0000018284] [REGION UNDEF] [I] SrpClient-----: fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[0000018287] [REGION UNDEF] [I] SrpClient-----: fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[00:00:22.982]  Ip6 Address 0: fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[0000052753] [REGION UNDEF] [I] AddrResolver--: Received address query from 0x0400 for target fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[0000052757] [REGION UNDEF] [I] DuaManager----: Sending address notification for target fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965
[0000052832] [REGION UNDEF] [I] MeshForwarder-:     dst:[fdeb:b4c2:ebb4:1:b0db:57d3:5b26:e965]:45000

When rebooting the Joiner device, are you also clearing non-volatile settings?

[OlivierGre]

Thank you so much Jonathan! It works indeed! I will do more tests on monday but I can see that the blocking period doesn't happen anymore.
I call otInstanceErasePersistentInfo() at each init of the device.
Thanks again for your support.
Regards

[OlivierGre]

@jwhui Jonathan,
May I get your point of view about another problem?
During SRP registration, it happens frequently that we get a timeout like this:

[0000049354] [REGION UNDEF] [I] SrpClient-----: Retry interval 1800 ms
[0000049355] [REGION UNDEF] [I] SrpClient-----: Timed out, no response
[0000049356] [REGION UNDEF] [I] SrpClient-----: State Updating -> ToUpdate
[00:00:50.477] srpClientCallback
[00:00:50.477] Error: Srp Client callback returned 28, 0 was expected

This timeout can happen a few time consecutively and the duration is increased everytimes (1800ms -> 3060 ms -> 5s -> 8s ...etc) so it makes SRP service creation too long.

We would like to understand the root cause of this issue.

Here is a new log that I have recorded.
The attached zip file contains:

• the OTBR syslog
• The RCP and Joiner device logs
• A file giving the IPV6 addresses of the OTBR and the Android Commissioner

At [00:00:23.583] we start the commissioning.
At [00:00:36.758] the commissioning is successful.

Normally we start SRP as soon as the joiner device becomes a child or a leader but here, I'm starting SRP manually by pressing a button at time [00:00:48.359]. I have intentionally let more than 10s after the end of the commissioning to see it fixes the problem but it doesn't help.

As indicated, we have a time out at [0000049355] .
SRP registration is then successful at [00:00:52.159].

We have noticed that Address Query is sent at time [0000047556] but doesn't receive answer:

[0000047556] [REGION UNDEF] [I] DuaManager----: Sending address query for fdde:ad00:beef:0:dfab:10f4:4333:f5d4
[0000047559] [REGION UNDEF] [I] AddrResolver--: Cache entry added: fdde:ad00:beef:0:dfab:10f4:4333:f5d4, 0xfffe - query request

The answer arrives later on:
[0000051507] [REGION UNDEF] [I] AddrResolver--: Received address query from 0x0400 for target fdeb:b4c2:ebb4:1:c8d9:3bfb:3fcb:4b78

Thanks for your advices.

logs_srp_timeout.zip

[jwhui]

Looking at otbr_agent_syslog.txt, it appears that fragments sent from RCP to host are being dropped:

Oct 11 18:45:59 raspberrypi otbr-agent[817]: 00:00:58.724 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:96, src:0x0401, dst:0x0400, tag:33927, offset:216, dglen:441, sec:yes
Oct 11 18:45:59 raspberrypi otbr-agent[817]: 00:00:58.724 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:96, src:0x0401, dst:0x0400, tag:33927, offset:312, dglen:441, sec:yes
Oct 11 18:45:59 raspberrypi otbr-agent[817]: 00:00:58.724 [N] MeshForwarder-: Dropping rx frag frame, error:Drop, len:33, src:0x0401, dst:0x0400, tag:33927, offset:408, dglen:441, sec:yes

The above fragments come from the SRP Update message, which is why the SRP Client needs to retransmit the SRP Update mesage.

Can you provide more information about your RCP setup? What hardware platform are you using? What serial connection between RCP and host are you using?