Problem when doing commissioning + SRP service creation

[OlivierGre]

I'm doing a Commissioning of my Thread device, and then I use SRP to advertize its presence.

I see some errors during SRP activation (see attached log file):

[0000074804] [REGION UNDEF] [I] SrpClient-----: Retry interval 1800 ms
[0000074805] [REGION UNDEF] [I] SrpClient-----: Timed out, no response
[0000074806] [REGION UNDEF] [I] SrpClient-----: State Updating -> ToUpdate
[00:01:15.912] srpClientCallback
[00:01:15.912] Error: Srp Client callback returned 28, 0 was expected
[0000075022] [REGION UNDEF] [I] AddrResolver--: Timed out waiting for address notification for fdde:ad00:beef:0:2e57:e9b6:cde1:feb3, retry: 15
[0000075023] [REGION UNDEF] [N] MeshForwarder-: Dropping IPv6 UDP msg, len:441, chksum:c999, ecn:no, sec:yes, error:AddressQuery, prio:normal
[0000075026] [REGION UNDEF] [N] MeshForwarder-:     src:[fdde:ad00:beef:0:4811:ab9e:809f:86c2]:49154
[0000075028] [REGION UNDEF] [N] MeshForwarder-:     dst:[fdde:ad00:beef:0:2e57:e9b6:cde1:feb3]:53537
[0000075280] [REGION UNDEF] [I] Settings------: Read SrpEcdsaKey
[0000075423] [REGION UNDEF] [I] SrpClient-----: Send update
[0000075424] [REGION UNDEF] [I] SrpClient-----: State ToUpdate -> Updating
[0000075426] [REGION UNDEF] [N] MeshForwarder-: Dropping IPv6 UDP msg, len:441, chksum:724d, ecn:no, sec:yes, error:Drop, prio:normal
[0000075429] [REGION UNDEF] [N] MeshForwarder-:     src:[fdde:ad00:beef:0:4811:ab9e:809f:86c2]:49154
[0000075431] [REGION UNDEF] [N] MeshForwarder-:     dst:[fdde:ad00:beef:0:2e57:e9b6:cde1:feb3]:53537

SRP activation is failing a few times but then it finishes by a success (after a few tries).

During my investigation, I have observed something:

log.txt

If I replace the Commissioning phase by some CLI command to join the OTBR network (based on "dataset set active xxxx" command), and then run the exact same code for SRP activation, then I don"t see the problem anymore. SRP activation is running smoothly.

Do you know what could be wrong? Could it be related to DTLS ?

Thank you

[abtink]

The issue seem unrelated to SRP itself, but from logs it looks like the destination (SRP server) is not initially responding to "address query" .

My guess/theory is that this happening right at start and before all links are established.
My suggestion is to either add delay before starting the registration and/or keep it as is and allow the retries to take care of it.

---

Here address query for fdde:ad00:beef:0:2e57:e9b6:cde1:feb3

0000073010] [REGION UNDEF] [I] AddrResolver--: Cache entry added: fdde:ad00:beef:0:2e57:e9b6:cde1:feb3, 0xfffe - query request

After this we see the router 0xcc00 is trying to establish link:

[0000073829] [REGION UNDEF] [I] Mle-----------: Receive Link Accept and Request (fe80:0:0:0:1032:2851:795:eace,0xcc00)
[0000073833] [REGION UNDEF] [I] Mle-----------: Send Link Accept (fe80:0:0:0:1032:2851:795:eace)

The address query timed out here

[REGION UNDEF] [I] AddrResolver--: Timed out waiting for address notification for fdde:ad00:beef:0:2e57:e9b6:cde1:feb3, retry: 15

So all messages to this destination (inlcuding SPR update is now dropped) - We don't know where to send this:

[0000075023] [REGION UNDEF] [N] MeshForwarder-: Dropping IPv6 UDP msg, len:441, chksum:c999, ecn:no, sec:yes, error:AddressQuery, prio:normal
[0000075026] [REGION UNDEF] [N] MeshForwarder-:     src:[fdde:ad00:beef:0:4811:ab9e:809f:86c2]:49154
[0000075028] [REGION UNDEF] [N] MeshForwarder-:     dst:[fdde:ad00:beef:0:2e57:e9b6:cde1:feb3]:53537

Next address query attempt later succeeds (and we see 0xc00 was the destination):

0000094206] [REGION UNDEF] [I] DuaManager----: Sending address query for fdde:ad00:beef:0:2e57:e9b6:cde1:feb3
(0000000 > 0000)        [TX :x5f|00811000|..|x5f,0000]  8400 -> ffff    (15)
[0000094214] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, to:0xffff, sec:yes, prio:net
[0000094216] [REGION UNDEF] [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:8400]
[0000094217] [REGION UNDEF] [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
(0000000 > 0000)        [TX :x60|00011000|..|x60,0000]  8400 -> ffff    (15)
[0000094225] [REGION UNDEF] [I] MeshForwarder-: Sent IPv6 HopOpts msg, len:86, chksum:0000, ecn:no, to:0xffff, sec:yes, prio:net
[0000094227] [REGION UNDEF] [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:8400]
[0000094228] [REGION UNDEF] [I] MeshForwarder-:     dst:[ff03:0:0:0:0:0:0:2]
                        [RXa:x98|B0(0/1)|IT:049|154,0]  cc00 -> 8400    (15)
[0000094265] [REGION UNDEF] [I] MeshForwarder-: Received IPv6 UDP msg, len:92, chksum:33a3, ecn:no, from:0xcc00, sec:yes, prio:net, rss:-53.0
[0000094267] [REGION UNDEF] [I] MeshForwarder-:     src:[fdde:ad00:beef:0:0:ff:fe00:cc00]:61631
[0000094269] [REGION UNDEF] [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:0:ff:fe00:8400]:61631
[0000094272] [REGION UNDEF] [I] AddrResolver--: Received address notification from 0xcc00 for fdde:ad00:beef:0:2e57:e9b6:cde1:feb3 to 0xcc00
[0000094275] [REGION UNDEF] [I] AddrResolver--: Cache entry updated: fdde:ad00:beef:0:2e57:e9b6:cde1:feb3, 0xcc00 - rx notification
[0000094276] [REGION UNDEF] [I] EnergyScanClnt: Sending address notification acknowledgment

And registration proceeds successfully:

[0000095159] [REGION UNDEF] [I] MeshForwarder-: Received IPv6 UDP msg, len:60, chksum:d50f, ecn:no, from:0xcc00, sec:yes, prio:normal, rss:-53.0
[0000095162] [REGION UNDEF] [I] MeshForwarder-:     src:[fdde:ad00:beef:0:2e57:e9b6:cde1:feb3]:53537
[0000095164] [REGION UNDEF] [I] MeshForwarder-:     dst:[fdde:ad00:beef:0:4811:ab9e:809f:86c2]:49154
[0000095165] [REGION UNDEF] [I] SrpClient-----: Received response
[0000095166] [REGION UNDEF] [I] SrpClient-----: HostInfo Adding -> Registered

[OlivierGre]

@abtink Thank you Abtink

I have captured some new logs (joiner device + RCP log + RPi syslog) and I can see that, when the problem is happening, the RCP doesn't receive anything. So we probably have a problem with RF transmission between the RCP and the Joiner device.