Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Custom commissioner assertion #193

Closed
krbvroc1 opened this issue Apr 16, 2021 · 14 comments · Fixed by #188
Closed

Custom commissioner assertion #193

krbvroc1 opened this issue Apr 16, 2021 · 14 comments · Fixed by #188
Assignees

Comments

@krbvroc1
Copy link

krbvroc1 commented Apr 16, 2021

Previously I asked about an example and documentation #165
One was provided, but it looks like it was never merged #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 #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
Copy link
Author

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

@wgtdkp
Copy link
Member

wgtdkp commented Apr 18, 2021

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

I have submitted another PR #188 that resolves the compatibility issue so that caller-side code doesn't need to be changed. Can you cherry-pick #188 to see if it works for you?

@wgtdkp wgtdkp linked a pull request Apr 18, 2021 that will close this issue
@krbvroc1
Copy link
Author

@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
Copy link
Member

wgtdkp commented Apr 19, 2021

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

@krbvroc1
Copy link
Author

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
Copy link
Member

wgtdkp commented Apr 19, 2021

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
Copy link
Author

krbvroc1 commented Apr 19, 2021

  • 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
Copy link
Member

wgtdkp commented Apr 19, 2021

@krbvroc1 The log looks good to me and I can not reproduce this issue with e33021be for OTBR and #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
Copy link
Author

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
Copy link
Member

wgtdkp commented Apr 19, 2021

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 #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
Copy link
Author

@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
Copy link
Member

wgtdkp commented Apr 20, 2021

@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
Copy link
Author

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
Copy link
Member

wgtdkp commented Apr 21, 2021

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.

jwhui pushed a commit to openthread/openthread that referenced this issue Apr 26, 2021
This commit includes several small changes:
- Add logs for Border Agent Start and Stop events to help analysis
  commissioning issues such as openthread/ot-commissioner#193
  (comment).
- Start Border Agent when the native commissioner is stopped.
- Add CLI command ba state to get current Border Agent state.
Abhayakara pushed a commit to Abhayakara/openthread that referenced this issue Oct 6, 2021
This commit includes several small changes:
- Add logs for Border Agent Start and Stop events to help analysis
  commissioning issues such as openthread/ot-commissioner#193
  (comment).
- Start Border Agent when the native commissioner is stopped.
- Add CLI command ba state to get current Border Agent state.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants