search

openthread / ot-commissioner

OpenThread Commissioner, a Thread commissioner for joining new Thread devices and managing Thread networks.
https://openthread.io/
BSD 3-Clause "New" or "Revised" License
49 stars 36 forks source link

Custom commissioner assertion #193

Closed krbvroc1 closed 3 years ago

krbvroc1 commented 3 years ago

Previously I asked about an example and documentation https://github.com/openthread/ot-commissioner/issues/165 One was provided, but it looks like it was never merged https://github.com/openthread/ot-commissioner/pull/167

This morning, while trying to recreate what I did two months ago, I updated ot-commissioner to the latest commit, rebuilt my custom commissioner application, and it dies with an assertion after I have become active commissioner and I call SetCommissionerDataset();

custom_commissioner: ../src/library/commissioner_impl.cpp:2202: ot::commissioner::Address ot::commissioner::CommissionerImpl::GetAnycastLocator(uint16_t) const: Assertion `condition' failed.

It appears this is new code introduced in https://github.com/openthread/ot-commissioner/pull/185 @wgtdkp @jwhui

Other than backing out these changes, any idea what has broken? I am running my custom commissioner application on the border router (latest commit) and it does have a Mesh Local Prefix. The assert is that there is no Mesh Local Prefix.

ot-ctl dataset active

Mesh Local Prefix: fd03:b099:34cc:6d32::/64

Also the example code, when it gets merged in, may have highlighted this problem earlier?

krbvroc1 commented 3 years ago

FYI: I reverted to commit b151bb5c66c9e54fac64c531cd571e45bb8794a9 and it works fine.

wgtdkp commented 3 years ago

@krbvroc1 Thanks for raising this issue. I can confirm that https://github.com/openthread/ot-commissioner/pull/185 did break backward compatibility. The latest Thread specification requires a commissioner getting Mesh-Local Prefix before sending MGMT_* commands and https://github.com/openthread/ot-commissioner/pull/185 is an implementation for that.

I have submitted another PR https://github.com/openthread/ot-commissioner/pull/188 that resolves the compatibility issue so that caller-side code doesn't need to be changed. Can you cherry-pick https://github.com/openthread/ot-commissioner/pull/188 to see if it works for you?

krbvroc1 commented 3 years ago

@wgtdkp I fetched this and rebuilt my custom commissioner. While it does not segfault, it fails on the petition attempt. To remove my custom code from the picture, I tried the commissioner-cli and got the same result:

> start :: 49191
IO_ERROR: NET - Reading information from the socket failed
[failed]

Am I missing some configuration in the OTBR that is now required for this new method? Is the OTBR supposed to be listening on 49191 and am I missing a build flag when I rebuilt the OTBR? This works prior to the #185 .

wgtdkp commented 3 years ago

Can you confirm if the BR is running? What is the output of command "sudo ot-ctl state"?

krbvroc1 commented 3 years ago

Can you confirm if the BR is running? What is the output of command "sudo ot-ctl state"?

Yes, the OTBR is running ... State is 'router'. However I recently updated the OTBR (on RaspPi) to the latest commit. I just reverted the ot-commissioner to the commit prior to #185 and the commissioner-cli gives the same error. Did something in the latest OTBR build change or break commissioning? Does some option need to be enabled?

I do not see any tasks 'listening' to the UDP 49191 port.

wgtdkp commented 3 years ago

There are integration tests in the OTBR repo and I don't think there are changes that break the commissioning function.

  1. How did you build the OTBR? Can you share the command?
  2. What is the commit ID of the OTBR?
  3. Can you share the OTBR log with cat /var/log/syslog | grep otbr-agent?
krbvroc1 commented 3 years ago

  • How did you build the OTBR? Can you share the command?

    sudo apt-get install git
git clone https://github.com/openthread/ot-br-posix.git
cd ot-br-posix
./script/bootstrap
INFRA_IF_NAME=eth0 ./script/setup
sudo systemctl start tayga
sudo systemctl enable tayga
sudo reboot

  • What is the commit ID of the OTBR? e33021be

  • Can you share the OTBR log with cat /var/log/syslog | grep otbr-agent?

Log

``` Apr 19 03:11:31 thread-br otbr-agent[3823]: Running 0.3.0-e33021be Apr 19 03:11:31 thread-br otbr-agent[3823]: Thread version: 1.2.0 Apr 19 03:11:31 thread-br otbr-agent[3823]: Thread interface: wpan0 Apr 19 03:11:31 thread-br otbr-agent[3823]: Backbone interface: eth0 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: RCP reset: RESET_POWER_ON Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: RCP API Version: 3 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read NetworkInfo {rloc:0x2400, extaddr:0201aa475d1cbcd5, role:Router, mode:0x0f, version:3, keyseq:0x0, ... Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: ... pid:0x47926a85, mlecntr:0x75fc, maccntr:0xd5d2692d, mliid:3d6cf85883250b22} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read ChildInfo {rloc:0x2404, extaddr:c2b93957de84eb6c, timeout:360000, mode:0x04, version:2} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read ChildInfo {rloc:0x240c, extaddr:42947147583c19dc, timeout:360000, mode:0x04, version:2} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read ChildInfo {rloc:0x2405, extaddr:ea9d5e90e2e1a4f0, timeout:360000, mode:0x04, version:2} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read ChildInfo {rloc:0x2402, extaddr:ce792e3c3fd9543e, timeout:360000, mode:0x04, version:2} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read ChildInfo {rloc:0x2401, extaddr:7687cefb7efceb77, timeout:360000, mode:0x04, version:2} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read ChildInfo {rloc:0x2406, extaddr:ba1f1e71951584bd, timeout:360000, mode:0x04, version:2} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Backbone interface is configured to eth0 (2) Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read OMR prefix fd93:11e0:583e:a30c::/64 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read on-link prefix fda1:12a0:69cd:0::/64 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:31 thread-br otbr-agent[3823]: Set state callback: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BBR-----: Add Domain Prefix: ::/0, NotFound Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BBR-----: Add BBR Service: seqno (26), delay (1200s), timeout (3600s), InvalidState Apr 19 03:11:31 thread-br otbr-agent[3823]: stop Thread Border Agent Apr 19 03:11:31 thread-br otbr-agent[3823]: [adproxy] Stopped Apr 19 03:11:31 thread-br otbr-agent[3823]: Initialize OpenThread Border Router Agent: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: Border router agent started. Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x121fc300) [KeySeqCntr NetData Channel PanId NetName ExtPanId MstrKey PSKc SecPolicy ... Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x121fc300) ... BbrState ActDset] Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BBR-----: Backbone TMF subscribes ff32:40:fd09:436c:53d6:768c:0:3: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BBR-----: Start Backbone TMF agent: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: MulticastRoutingManager: Disable: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Host netif is down Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateMulticast: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateMulticast: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateMulticast: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#1 to add fe80::1:aa47:5d1c:bcd5/64 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BBR-----: Remove BBR Service: seqno (26), delay (1200s), timeout (3600s), NotFound Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-MLE-----: Role Disabled -> Detached Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#2 to add fd09:436c:53d6:768c:3d6c:f858:8325:b22/64 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateMulticast: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateMulticast: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BBR-----: Backbone TMF unsubscribes ff32:40:fd09:436c:53d6:768c:0:3: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BBR-----: Backbone TMF subscribes ff32:40:fd09:436c:53d6:768c:0:3: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#3 to add fd09:436c:53d6:768c:0:ff:fe00:2400/64 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-MLE-----: Attempt to become router Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Read NetworkInfo {rloc:0x2400, extaddr:0201aa475d1cbcd5, role:Router, mode:0x0f, version:3, keyseq:0x0, ... Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: ... pid:0x47926a85, mlecntr:0x75fc, maccntr:0xd5d2692d, mliid:3d6cf85883250b22} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Saved NetworkInfo {rloc:0x2400, extaddr:0201aa475d1cbcd5, role:Router, mode:0x0f, version:3, keyseq:0x0, ... Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: ... pid:0x47926a85, mlecntr:0x79e5, maccntr:0xd5d26d15, mliid:3d6cf85883250b22} Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Link Request (ff02:0:0:0:0:0:0:2) Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x0100103d) [Ip6+ Role LLAddr MLAddr Rloc+ Ip6Mult+ NetifState] Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: changing interface state to up. Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateLink: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: Thread is down Apr 19 03:11:31 thread-br otbr-agent[3823]: stop Thread Border Agent Apr 19 03:11:31 thread-br otbr-agent[3823]: [adproxy] Stopped Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fe80::1:aa47:5d1c:bcd5 (already subscribed, ignored) Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#1 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd09:436c:53d6:768c:3d6c:f858:8325:b22 (already subscribed, ignored) Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#2 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd09:436c:53d6:768c:0:ff:fe00:2400 (already subscribed, ignored) Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#3 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-PLAT----: Host netif is up Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:82, chksum:2289, to:0xffff, sec:no, prio:net Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:2]:19788 Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: processTransmit: Drop Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff33:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff32:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::fc Apr 19 03:11:31 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::1 Apr 19 03:11:31 thread-br otbr-agent[3823]: [WARN]-PLAT----: Failed to subscribe multicast address ff02::2: InvalidArgs Apr 19 03:11:31 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00001000) [Ip6Mult+] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:124, chksum:dfa4, from:d2077cdd9b59797e, sec:no, prio:net, rss:-65.0 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:d007:7cdd:9b59:797e]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Receive Link Accept (fe80:0:0:0:d007:7cdd:9b59:797e,0x0000) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#4 to remove fd09:436c:53d6:768c:0:ff:fe00:2400/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#5 to add fd09:436c:53d6:768c:0:ff:fe00:2400/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-MLE-----: Role Detached -> Router Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateMulticast: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: UpdateMulticast: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Data Request (fe80:0:0:0:d007:7cdd:9b59:797e) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x000010e4) [Role Rloc+ Rloc- PartitionId Ip6Mult+] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: Saved NetworkInfo {rloc:0x2400, extaddr:0201aa475d1cbcd5, role:Router, mode:0x0f, version:3, keyseq:0x0, ... Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Non-volatile: ... pid:0x47926a85, mlecntr:0x79e6, maccntr:0xd5d26d15, mliid:3d6cf85883250b22} Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: Border Routing manager started Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: start Router Solicitation, scheduled in 111 milliseconds Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-N-DATA--: Sent server data notification Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-SRP-----: [server] start listening on port 49152 Apr 19 03:11:32 thread-br otbr-agent[3823]: Thread is up Apr 19 03:11:32 thread-br otbr-agent[3823]: stop Thread Border Agent Apr 19 03:11:32 thread-br otbr-agent[3823]: [adproxy] Stopped Apr 19 03:11:32 thread-br otbr-agent[3823]: [adproxy] Started Apr 19 03:11:32 thread-br otbr-agent[3823]: publish meshcop service Thread-TEST._meshcop._udp.local. Apr 19 03:11:32 thread-br otbr-agent[3823]: [mdns] add service: Thread-TEST._meshcop._udp (ref: 0x1e95c90) Apr 19 03:11:32 thread-br otbr-agent[3823]: Start Thread Border Agent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: DEL [U] fd09:436c:53d6:768c:0:ff:fe00:2400 failed (InvalidArgs) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: processNetifAddrEvent: InvalidArgs Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#4 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#5 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd09:436c:53d6:768c:0:ff:fe00:2400 (already subscribed, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:77, chksum:2e2c, to:d2077cdd9b59797e, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fe80:0:0:0:d007:7cdd:9b59:797e]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:73, chksum:a1dd, to:0x0000, sec:yes, prio:normal Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: processTransmit: Drop Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff33:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff32:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::fc Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::16 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:178, chksum:2ae6, from:d2077cdd9b59797e, sec:yes, prio:net, rss:-65.0 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:d007:7cdd:9b59:797e]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Receive Data Response (fe80:0:0:0:d007:7cdd:9b59:797e) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00000200) [NetData] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Delay Data Response (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: PBBR state: Added Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Rloc16: 0x2400, seqno: 57, delay: 1200, timeout 3600 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Add BBR Service: seqno (58), delay (1200s), timeout (3600s), OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Domain Prefix: ::/0, state: None Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#6 to add fd09:436c:53d6:768c:0:ff:fe00:fc10/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#7 to add fd09:436c:53d6:768c:0:ff:fe00:fc11/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-UTIL----: SLAAC: Adding address fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#8 to add fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: start evaluating routing policy, scheduled in 492 milliseconds Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x04000001) [Ip6+ BbrLocal] Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd09:436c:53d6:768c:0:ff:fe00:fc10 (already subscribed, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#6 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd09:436c:53d6:768c:0:ff:fe00:fc11 (already subscribed, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#7 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3 (already subscribed, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#8 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:139, chksum:0059, from:d2077cdd9b59797e, sec:no, prio:net, rss:-65.0 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:d007:7cdd:9b59:797e]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Receive Data Response (fe80:0:0:0:d007:7cdd:9b59:797e) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00000200) [NetData] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Remove Delayed Data Response (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Delay Data Response (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: PBBR state: Removed Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Domain Prefix: ::/0, state: None Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#9 to remove fd09:436c:53d6:768c:0:ff:fe00:fc11/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-UTIL----: SLAAC: Removing address fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#10 to remove fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: start evaluating routing policy, scheduled in 760 milliseconds Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00000002) [Ip6-] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:54, chksum:919c, from:0x0000, sec:yes, prio:net, rss:-65.0 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: DEL [U] fd09:436c:53d6:768c:0:ff:fe00:fc11 (not found, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#9 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-N-DATA--: Sent server data notification Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: DEL [U] fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3 (not found, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#10 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:89, chksum:955d, to:0x0000, sec:yes, prio:normal Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: processTransmit: Drop Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff33:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff32:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::fc Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::16 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:155, chksum:e916, from:d2077cdd9b59797e, sec:yes, prio:net, rss:-64.5 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:d007:7cdd:9b59:797e]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Receive Data Response (fe80:0:0:0:d007:7cdd:9b59:797e) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00000200) [NetData] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Remove Delayed Data Response (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Delay Data Response (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: PBBR state: Added Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Rloc16: 0x2400, seqno: 58, delay: 1200, timeout 3600 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#11 to add fd09:436c:53d6:768c::fc38/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Domain Prefix: ::/0, state: None Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#12 to add fd09:436c:53d6:768c:0:ff:fe00:fc11/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: start evaluating routing policy, scheduled in 361 milliseconds Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x02000001) [Ip6+ BbrState] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Backbone TMF subscribes ff32:40:fd09:436c:53d6:768c:0:3: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Start Backbone TMF agent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: MulticastRoutingManager: Enable: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: publish meshcop service Thread-TEST._meshcop._udp.local. Apr 19 03:11:32 thread-br otbr-agent[3823]: [mdns] update service Thread-TEST._meshcop._udp Apr 19 03:11:32 thread-br otbr-agent[3823]: [adproxy] handle publish service 'Thread-TEST._meshcop._udp' result: 0 Apr 19 03:11:32 thread-br otbr-agent[3823]: BackboneAgent: Backbone Router becomes Primary! Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#11 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#12 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:54, chksum:bff4, from:0x0000, sec:yes, prio:net, rss:-65.0 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd09:436c:53d6:768c::fc38 (already subscribed, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd09:436c:53d6:768c:0:ff:fe00:fc11 (already subscribed, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: processTransmit: Drop Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff33:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff32:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::fc Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::16 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: processTransmit: Drop Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff33:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff32:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::fc Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::16 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: router solicitation times out Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send delayed message (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:155, chksum:80d3, to:0xffff, sec:yes, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: evaluating routing policy Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: EvaluateOmrPrefix: no valid OMR prefixes found in Thread network Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-N-DATA--: Sent server data notification Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: published local OMR prefix fd93:11e0:583e:a30c::/64 in Thread network Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: send OMR prefix fd93:11e0:583e:a30c::/64 in RIO (valid lifetime = 1800 seconds) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: sent Router Advertisement on interface 2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: router advertisement scheduled in 16 seconds Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: received Router Advertisement from fe80:0:0:0:dea6:32ff:fe92:2618 on interface 2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:107, chksum:a608, to:0x0000, sec:yes, prio:normal Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:161, chksum:56c7, from:d2077cdd9b59797e, sec:yes, prio:net, rss:-64.5 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:d007:7cdd:9b59:797e]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Receive Data Response (fe80:0:0:0:d007:7cdd:9b59:797e) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00000200) [NetData] Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Delay Data Response (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: PBBR state: Unchanged Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Rloc16: 0x2400, seqno: 58, delay: 1200, timeout 3600 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BBR-----: Domain Prefix: ::/0, state: None Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-UTIL----: SLAAC: Adding address fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Sent request#13 to add fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3/64 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: start evaluating routing policy, scheduled in 439 milliseconds Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00000001) [Ip6+] Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: ADD [U] fd93:11e0:583e:a30c:2730:bbea:3c2:2bb3 (already subscribed, ignored) Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (6). Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: unexpected address type (8). Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-PLAT----: Succeeded to process request#13 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:54, chksum:e43d, from:0x0000, sec:yes, prio:net, rss:-65.0 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:32 thread-br otbr-agent[3823]: [WARN]-PLAT----: processTransmit: Drop Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff33:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff32:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::fc Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::1 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::16 Apr 19 03:11:32 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::2 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send delayed message (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:161, chksum:9bee, to:0xffff, sec:yes, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Child Update Request to child (fe80:0:0:0:c0b9:3957:de84:eb6c,0x2404) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Child Update Request to child (fe80:0:0:0:4094:7147:583c:19dc,0x240c) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Child Update Request to child (fe80:0:0:0:e89d:5e90:e2e1:a4f0,0x2405) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Child Update Request to child (fe80:0:0:0:cc79:2e3c:3fd9:543e,0x2402) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Child Update Request to child (fe80:0:0:0:7487:cefb:7efc:eb77,0x2401) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Child Update Request to child (fe80:0:0:0:b81f:1e71:9515:84bd,0x2406) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Prepping indir tx IPv6 UDP msg, len:169, chksum:c1aa, to:0x2404, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Prepping indir tx IPv6 UDP msg, len:169, chksum:cdff, to:0x240c, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Prepping indir tx IPv6 UDP msg, len:169, chksum:e394, to:0x2405, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Prepping indir tx IPv6 UDP msg, len:169, chksum:c012, to:0x2402, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Prepping indir tx IPv6 UDP msg, len:169, chksum:00ef, to:0x2401, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Prepping indir tx IPv6 UDP msg, len:169, chksum:bd13, to:0x2406, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1) Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:91, chksum:ec1d, to:0xffff, sec:no, prio:net Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:32 thread-br otbr-agent[3823]: [mdns] received reply for service Thread-TEST._meshcop._udp. Apr 19 03:11:32 thread-br otbr-agent[3823]: [mdns] successfully registered service Thread-TEST._meshcop._udp. Apr 19 03:11:32 thread-br otbr-agent[3823]: [adproxy] handle publish service 'Thread-TEST._meshcop._udp.' result: 0 Apr 19 03:11:33 thread-br otbr-agent[3823]: [INFO]-BR------: evaluating routing policy Apr 19 03:11:33 thread-br otbr-agent[3823]: [INFO]-BR------: send OMR prefix fd93:11e0:583e:a30c::/64 in RIO (valid lifetime = 1800 seconds) Apr 19 03:11:33 thread-br otbr-agent[3823]: [INFO]-BR------: sent Router Advertisement on interface 2 Apr 19 03:11:33 thread-br otbr-agent[3823]: [INFO]-BR------: router advertisement scheduled in 16 seconds Apr 19 03:11:33 thread-br otbr-agent[3823]: [INFO]-BR------: received Router Advertisement from fe80:0:0:0:dea6:32ff:fe92:2618 on interface 2 Apr 19 03:11:33 thread-br otbr-agent[3823]: [WARN]-PLAT----: processTransmit: Drop Apr 19 03:11:33 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::2 Apr 19 03:11:33 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff33:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:33 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff32:40:fd09:436c:53d6:768c:0:1 Apr 19 03:11:33 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::fc Apr 19 03:11:33 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff03::1 Apr 19 03:11:33 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::16 Apr 19 03:11:33 thread-br otbr-agent[3823]: [NOTE]-PLAT----: Will not subscribe duplicate multicast address ff02::2 Apr 19 03:11:34 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1) Apr 19 03:11:34 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:91, chksum:5d21, to:0xffff, sec:no, prio:net Apr 19 03:11:34 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:34 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:36 thread-br otbr-agent[3823]: [INFO]-BR------: router solicitation times out Apr 19 03:11:37 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1) Apr 19 03:11:37 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:91, chksum:4cd9, to:0xffff, sec:no, prio:net Apr 19 03:11:37 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:37 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:40 thread-br otbr-agent[3823]: [INFO]-BR------: router solicitation times out Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: router solicitation times out Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: evaluating routing policy Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-N-DATA--: Sent server data notification Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: added external route fda1:12a0:69cd:0::/64 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: start advertising new on-link prefix fda1:12a0:69cd:0::/64 on interface 2 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: send on-link prefix fda1:12a0:69cd:0::/64 in PIO (valid lifetime = 1800 seconds) Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: send OMR prefix fd93:11e0:583e:a30c::/64 in RIO (valid lifetime = 1800 seconds) Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: sent Router Advertisement on interface 2 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: router advertisement scheduled in 16 seconds Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: received Router Advertisement from fe80:0:0:0:dea6:32ff:fe92:2618 on interface 2 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:124, chksum:a5de, to:0x0000, sec:yes, prio:normal Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:178, chksum:deba, from:d2077cdd9b59797e, sec:yes, prio:net, rss:-65.0 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:d007:7cdd:9b59:797e]:19788 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MLE-----: Receive Data Response (fe80:0:0:0:d007:7cdd:9b59:797e) Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-CORE----: Notifier: StateChanged (0x00000200) [NetData] Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MLE-----: Delay Data Response (ff02:0:0:0:0:0:0:1) Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BBR-----: PBBR state: Unchanged Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BBR-----: Rloc16: 0x2400, seqno: 58, delay: 1200, timeout 3600 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BBR-----: Domain Prefix: ::/0, state: None Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-BR------: start evaluating routing policy, scheduled in 968 milliseconds Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: Received IPv6 UDP msg, len:54, chksum:45e9, from:0x0000, sec:yes, prio:net, rss:-65.0 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fd09:436c:53d6:768c:0:ff:fe00:fc00]:61631 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[fd09:436c:53d6:768c:0:ff:fe00:2400]:61631 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send delayed message (ff02:0:0:0:0:0:0:1) Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:178, chksum:932f, to:0xffff, sec:yes, prio:net Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:41 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-BR------: evaluating routing policy Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-BR------: send on-link prefix fda1:12a0:69cd:0::/64 in PIO (valid lifetime = 1800 seconds) Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-BR------: send OMR prefix fd93:11e0:583e:a30c::/64 in RIO (valid lifetime = 1800 seconds) Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-BR------: sent Router Advertisement on interface 2 Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-BR------: router advertisement scheduled in 220 seconds Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-PLAT----: processNetifAddrEvent: OK Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-BR------: received Router Advertisement from fe80:0:0:0:dea6:32ff:fe92:2618 on interface 2 Apr 19 03:11:42 thread-br otbr-agent[3823]: [INFO]-BR------: infra interface state changed: RUNNING, link-local-addr=fe80:0:0:0:dea6:32ff:fe92:2618 Apr 19 03:11:46 thread-br otbr-agent[3823]: [INFO]-MLE-----: Send Advertisement (ff02:0:0:0:0:0:0:1) Apr 19 03:11:46 thread-br otbr-agent[3823]: [INFO]-MAC-----: Sent IPv6 UDP msg, len:91, chksum:ca85, to:0xffff, sec:no, prio:net Apr 19 03:11:46 thread-br otbr-agent[3823]: [INFO]-MAC-----: src:[fe80:0:0:0:1:aa47:5d1c:bcd5]:19788 Apr 19 03:11:46 thread-br otbr-agent[3823]: [INFO]-MAC-----: dst:[ff02:0:0:0:0:0:0:1]:19788 ```

wgtdkp commented 3 years ago

@krbvroc1 The log looks good to me and I can not reproduce this issue with e33021be for OTBR and https://github.com/openthread/ot-commissioner/pull/188 for ot-commissioner.

Notice that the native commissioner and border agent currently can not co-exist on the OTBR.

  1. did you start the native commissioner? What is the output of sudo ot-ctl commissioner state?
  2. If the command gives Disabled, can you try to re-form the Thread Network with below commands? 
    
sudo ot-ctl factoryreset      
sudo ot-ctl dataset init new
Done
sudo ot-ctl dataset commit active
Done
sudo ot-ctl ifconfig up          
Done
sudo ot-ctl thread start
Done

Do not forget to change the pskc in commissioner config file.

sudo ot-ctl pskc 85e973c014fba5294fcca20910dcf5f1 Done sudo ot-ctl state leader Done

krbvroc1 commented 3 years ago

did you start the native commissioner? What is the output of sudo ot-ctl commissioner state?

I never use it, it returns disabled.

If the command gives Disabled, can you try to re-form the Thread Network with below commands?

factoryreset and reform - caused otbr-agent to start listening on port 49191. I have no idea why it was not listenining on port 49191 or why this was needed. With the exception of factoryreset, I have cleared the dataset and reformed numerous times the past several days during testing.

So now my custom commissioner becomes the active commissioner. Further progress. I am using the cherry picked #188. I tested a device commission and I see OnJoinerRequest() invoked 3 times, OnJoinerFinalize() invoked 1, then OnJoinerRequest() invoked 1 time. Seems like too much traffic for a single join request.

[INFO]-MESH-CP-: DTLS started
[INFO]-MESH-CP-: Commissioner connected
[INFO]-MESH-CP-: Forwarded request to leader on c/lp
[INFO]-MESH-CP-: received petition
[INFO]-MESH-CP-: sent petition response
[INFO]-MESH-CP-: commissioner accepted: session ID=9334, ALOC=fd5a:124b:8603:2051:0:ff:fe00:fc36
[INFO]-MESH-CP-: Sent to commissioner
[INFO]-MESH-CP-: Forwarded request to leader on c/ag
[INFO]-MESH-CP-: sent active dataset get response to fd5a:124b:8603:2051:0:ff:fe00:2400
[INFO]-MESH-CP-: Sent to commissioner
[INFO]-MESH-CP-: Proxy transmit sent to fd5a:124b:8603:2051:0:ff:fe00:fc00
[INFO]-MESH-CP-: sent commissioning dataset set response
[INFO]-MESH-CP-: Sent to commissioner on c/ur
[INFO]-MESH-CP-: Joiner Router: start
[INFO]-MESH-CP-: JoinerRouter::HandleUdpReceive
[INFO]-MESH-CP-: Sent relay rx
[INFO]-MESH-CP-: Sent to commissioner
[INFO]-MESH-CP-: Sent to commissioner on c/rx
[INFO]-MESH-CP-: Sent to joiner router request on c/tx
[INFO]-MESH-CP-: Received relay transmit
[INFO]-MESH-CP-: JoinerRouter::HandleUdpReceive
[INFO]-MESH-CP-: Sent relay rx
[INFO]-MESH-CP-: Sent to commissioner
[INFO]-MESH-CP-: Sent to commissioner on c/rx
[INFO]-MESH-CP-: Sent to joiner router request on c/tx
[INFO]-MESH-CP-: Received relay transmit
[INFO]-MESH-CP-: JoinerRouter::HandleUdpReceive
[INFO]-MESH-CP-: Sent relay rx
[INFO]-MESH-CP-: Sent to commissioner
[INFO]-MESH-CP-: Sent to commissioner on c/rx
[INFO]-MESH-CP-: Sent to joiner router request on c/tx
[INFO]-MESH-CP-: Received relay transmit
[INFO]-MESH-CP-: JoinerRouter::HandleUdpReceive
[INFO]-MESH-CP-: Sent relay rx
[INFO]-MESH-CP-: Sent to commissioner
[INFO]-MESH-CP-: Sent to commissioner on c/rx
[INFO]-MESH-CP-: Sent to joiner router request on c/tx
[INFO]-MESH-CP-: Received relay transmit
[INFO]-MESH-CP-: Received kek
[INFO]-MESH-CP-: JoinerRouter::HandleUdpReceive
[INFO]-MESH-CP-: Sent relay rx
[INFO]-MESH-CP-: Sent to commissioner
[INFO]-MESH-CP-: Sent to commissioner on c/rx
[INFO]-MESH-CP-: Sending JOIN_ENT.ntf
[INFO]-MESH-CP-: Sent joiner entrust length = 157
[INFO]-MESH-CP-: Receive joiner entrust response
wgtdkp commented 3 years ago

I have no idea why it was not listenining on port 49191 or why this was needed

There lacks logging for the Border Agent events, I will create PR for this soon.

I see OnJoinerRequest() invoked 3 times, OnJoinerFinalize() invoked 1

It is better to have the user be notified only once for a new Joiner request and we created https://github.com/openthread/ot-commissioner/pull/196 for this.

Seems like too much traffic for a single join request.

A DTLS connection will be established between the commissioner and joiner device, so it is expected that there will be multiple message exchanges.

krbvroc1 commented 3 years ago

@wgtdkp I must apologize to you for the trouble with 

> start :: 49191
IO_ERROR: NET - Reading information from the socket failed
[failed]

I have now figured out that during my testing of your fix in #188, my custom commissioner was running in the background, having been started by 'systemd' at boot time on the OTBR. I neglected to disable it, so when I tried to run the test of #188 by hand, the port 49191 was not available because it was already in use. That is what triggered the above error. Again, sorry for that waste of your time.

wgtdkp commented 3 years ago

@krbvroc1 No worries!

I neglected to disable it, so when I tried to run the test of #188 by hand, the port 49191 was not available because it was already in use.

Just out of curious, why your custom commissioner damon needs to listen on port 49191? I think current OTBR is listening on port 49191 and it will conflict with your custom commissioner, right?

krbvroc1 commented 3 years ago

Just out of curious, why your custom commissioner damon needs to listen on port 49191? I think current OTBR is listening on port 49191 and it will conflict with your custom commissioner, right?

My custom commissioner connects to the OTBR on port 49191

error = commissioner->Petition(existingCommissionerId, "::", 49191);

However it seems that once the OTBR receives a UDP 'connection' of 49191, it stops listening on that port for other connections. So initially when I thought my custom commissioner was not running, when I used the following Linux command, I expected to see:

/usr/bin/ss -lun
...
UNCONN  0        0                                                    *:49191                                              *:*                                  
...

but I did not. That is because it has already been started by systemd and OTBR was no longer listening on that port.

wgtdkp commented 3 years ago

However it seems that once the OTBR receives a UDP 'connection' of 49191, it stops listening on that port for other connections.

I can confirm that this is true for current implementation.