CC2652R7: Commissioning for matter device fails

Vivek Bhageria

Part Number: CC2652R7

I have read through the thread "CC2652R7: TI-Matter pump-app not BLE provisioning to the Thread&Matter network(s)".

I have been meaning to ask, is it possible to have the following setup, because I have been failing the commissioning process as well. The current setup is just for testing purposes, but we intend to use TI officially in the product line. But due to these issues, it has really been causing a look of stumbling blocks in testing and we need to move rapidly to the development phase.

Your help will mean very much...

1xCC2652R7 for the Thread network running (RCP)

1xCC2652R7 as a Thread device.(Lock-app example)

1xLinux machine running docker version of OTBR.

Connection to the internet through WIFI.
The Linux machine uses the chip-tool to do commissioning.

Another attempt was to also use the sample mobile matter apk in the Matter repository, but that failed, and it could not even detect the BLE on the Thread device to do the commissioning process.

Steps I followed:
1. Upload the RCP image to the TI board (LP-CC2652R7) (Thread network instance).
2. Start the docker OTBR on the Linux machine, and then form a Thread network on TI board running the RCP image via the webpage.
3. Upload the lock-app firmware on the TI device. Activate BLE advertising on the TI device.
4. On the Linux machine using the chip-tool to do commissioning,
but fails similar to the above thread post I have read through the thread "CC2652R7: TI-Matter pump-app not BLE provisioning to the Thread&Matter network(s)".

Kind regards,

over 2 years ago

0 Ryan Brown1 over 2 years ago

TI__Guru**** 218837 points

Hi Vivek,

Can you provide a log of the specific chip-tool behavior? The aforementioned thread had progressed significantly and it is difficult to know exactly what error you are experiencing. Are you able to use a third-party app such as LightBlue to confirm BLE advertisements from the CC2652R7? It would also be beneficial to provide a lock-app terminal log. Also, can you make sure that your Linux machine has Bluetooth capabilities enabled? It is important that the correct commissioning command is executed, from the chip-tool-guide:

./chip-tool pairing ble-thread <node_id> hex:<operational_dataset> <pin_code> <discriminator>

Regards,
Ryan

0 Logan Becker over 2 years ago

Prodigy 70 points

Hi Ryan,
Here is the Log.
1. It entails starting the OTBR docker and its outputs.
2. Forming the thread network on the webpage.
3. Commission attempt with the chip-tool on the linux machine that runs the docker OTBR.
4. Commission attempt with the chip-tool mobile app.

Notes: No Ethernet connection to the Linux machine running the OTBR, just the using Wifi for that. Could that be the issue?
           The light blue app detects the BLE advertising from the TI device.
           The Router in the house has 1 repeater. At times the mobile phone connects to which ever is closer, but I ensured that
           it remains closer to the 1 the laptop is connected too.
           I have Ethernet access to the Repeater only if that is required.

Command (Terminal 1)

-------------

→ sudo dockerd

Output

---------

INFO[2023-03-15T15:20:30.328866509+02:00] Starting up

INFO[2023-03-15T15:20:30.329881877+02:00] detected 127.0.0.53 nameserver, assuming systemd-resolved, so using resolv.conf: /run/systemd/resolve/resolv.conf

INFO[2023-03-15T15:20:30.330727097+02:00] [core] [Channel #1] Channel created module=grpc

INFO[2023-03-15T15:20:30.330745884+02:00] [core] [Channel #1] original dial target is: "unix:///run/containerd/containerd.sock" module=grpc

INFO[2023-03-15T15:20:30.330772839+02:00] [core] [Channel #1] parsed dial target is: {Scheme:unix Authority: Endpoint:run/containerd/containerd.sock URL:{Scheme:unix Opaque: User: Host: Path:/run/containerd/containerd.sock RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}} module=grpc

INFO[2023-03-15T15:20:30.330786808+02:00] [core] [Channel #1] Channel authority set to "localhost" module=grpc

INFO[2023-03-15T15:20:30.330880484+02:00] [core] [Channel #1] Resolver state updated: {

"Addresses": [

{

"Addr": "/run/containerd/containerd.sock",

"ServerName": "",

"Attributes": {},

"BalancerAttributes": null,

"Type": 0,

"Metadata": null

}

"ServiceConfig": null,

"Attributes": null

} (resolver returned new addresses) module=grpc

INFO[2023-03-15T15:20:30.330948608+02:00] [core] [Channel #1] Channel switches to new LB policy "pick_first" module=grpc

INFO[2023-03-15T15:20:30.331032116+02:00] [core] [Channel #1 SubChannel #2] Subchannel created module=grpc

INFO[2023-03-15T15:20:30.331070162+02:00] [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING module=grpc

INFO[2023-03-15T15:20:30.331094796+02:00] [core] [Channel #1 SubChannel #2] Subchannel picks a new address "/run/containerd/containerd.sock" to connect module=grpc

INFO[2023-03-15T15:20:30.331115378+02:00] [core] [Channel #1] Channel Connectivity change to CONNECTING module=grpc

INFO[2023-03-15T15:20:30.331333896+02:00] [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to READY module=grpc

INFO[2023-03-15T15:20:30.331399001+02:00] [core] [Channel #1] Channel Connectivity change to READY module=grpc

INFO[2023-03-15T15:20:30.332214857+02:00] [core] [Channel #4] Channel created module=grpc

INFO[2023-03-15T15:20:30.332291382+02:00] [core] [Channel #4] original dial target is: "unix:///run/containerd/containerd.sock" module=grpc

INFO[2023-03-15T15:20:30.332356898+02:00] [core] [Channel #4] parsed dial target is: {Scheme:unix Authority: Endpoint:run/containerd/containerd.sock URL:{Scheme:unix Opaque: User: Host: Path:/run/containerd/containerd.sock RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}} module=grpc

INFO[2023-03-15T15:20:30.332414774+02:00] [core] [Channel #4] Channel authority set to "localhost" module=grpc

INFO[2023-03-15T15:20:30.332516490+02:00] [core] [Channel #4] Resolver state updated: {

"Addresses": [

{

"Addr": "/run/containerd/containerd.sock",

"ServerName": "",

"Attributes": {},

"BalancerAttributes": null,

"Type": 0,

"Metadata": null

}

"ServiceConfig": null,

"Attributes": null

} (resolver returned new addresses) module=grpc

INFO[2023-03-15T15:20:30.333092109+02:00] [core] [Channel #4] Channel switches to new LB policy "pick_first" module=grpc

INFO[2023-03-15T15:20:30.333175269+02:00] [core] [Channel #4 SubChannel #5] Subchannel created module=grpc

INFO[2023-03-15T15:20:30.333255764+02:00] [core] [Channel #4 SubChannel #5] Subchannel Connectivity change to CONNECTING module=grpc

INFO[2023-03-15T15:20:30.333398282+02:00] [core] [Channel #4 SubChannel #5] Subchannel picks a new address "/run/containerd/containerd.sock" to connect module=grpc

INFO[2023-03-15T15:20:30.333468706+02:00] [core] [Channel #4] Channel Connectivity change to CONNECTING module=grpc

INFO[2023-03-15T15:20:30.334035609+02:00] [core] [Channel #4 SubChannel #5] Subchannel Connectivity change to READY module=grpc

INFO[2023-03-15T15:20:30.334064474+02:00] [core] [Channel #4] Channel Connectivity change to READY module=grpc

INFO[2023-03-15T15:20:30.361230084+02:00] [graphdriver] using prior storage driver: overlay2

INFO[2023-03-15T15:20:30.364705552+02:00] Loading containers: start.

INFO[2023-03-15T15:20:30.893753429+02:00] Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address

INFO[2023-03-15T15:20:31.022618134+02:00] Loading containers: done.

INFO[2023-03-15T15:20:31.052968931+02:00] Docker daemon commit=bc3805a graphdriver=overlay2 version=23.0.1

INFO[2023-03-15T15:20:31.053180670+02:00] Daemon has completed initialization

INFO[2023-03-15T15:20:31.076772464+02:00] [core] [Server #7] Server created module=grpc

INFO[2023-03-15T15:20:31.080240534+02:00] API listen on /var/run/docker.sock

Command (Terminal 2)

-------------

→ sudo docker run --sysctl "net.ipv6.conf.all.disable_ipv6=0 net.ipv4.conf.all.forwarding=1

net.ipv6.conf.all.forwarding=1" -p 8080:80 --dns=127.0.0.1 -it --volume /dev/ttyACM0:/dev/ttyACM0 --privileged openthread/otbr --radio-url spinel+hdlc+uart:///dev/ttyACM0

Output

---------

WARNING: Localhost DNS setting (--dns=127.0.0.1) may fail in containers.

RADIO_URL: spinel+hdlc+uart:///dev/ttyACM0

TREL_URL:

TUN_INTERFACE_NAME: wpan0

BACKBONE_INTERFACE: eth0

NAT64_PREFIX: 64:ff9b::/96

+++ dirname /app/script/server

++ cd /app/script/..

++ [[ ! -n x ]]

++ echo 'Current platform is ubuntu'

Current platform is ubuntu

++ with BORDER_ROUTING

++ local value

+++ printenv BORDER_ROUTING

++ value=1

++ [[ -z 1 ]]

++ [[ 1 == 1 ]]

++ with DHCPV6_PD

++ local value

+++ printenv DHCPV6_PD

++ value=

++ [[ -z '' ]]

++ [[ -f examples/platforms/ubuntu/default ]]

++ [[ '' == 1 ]]

++ with BORDER_ROUTING

++ local value

+++ printenv BORDER_ROUTING

++ value=1

++ [[ -z 1 ]]

++ [[ 1 == 1 ]]

++ with NETWORK_MANAGER

++ local value

+++ printenv NETWORK_MANAGER

++ value=

++ [[ -z '' ]]

++ [[ -f examples/platforms/ubuntu/default ]]

++ [[ '' == 1 ]]

++ STAGE_DIR=/app/stage

++ BUILD_DIR=/app/build

++ [[ -d /app/stage ]]

++ mkdir -v -p /app/stage

mkdir: created directory '/app/stage'

++ [[ -d /app/build ]]

++ mkdir -v -p /app/build

mkdir: created directory '/app/build'

++ export PATH=/app/stage/usr/bin:/app/stage/usr/sbin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin

++ PATH=/app/stage/usr/bin:/app/stage/usr/sbin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin

+++ basename /app/script/server

++ TASKNAME=server

++ BEFORE_HOOK=examples/platforms/ubuntu/before_server

++ AFTER_HOOK=examples/platforms/ubuntu/after_server

++ [[ ! -f examples/platforms/ubuntu/before_server ]]

++ BEFORE_HOOK=/dev/null

++ [[ ! -f examples/platforms/ubuntu/after_server ]]

++ AFTER_HOOK=/dev/null

+ . script/_nat64

++ NAT64_SERVICE=openthread

++ TAYGA_DEFAULT=/etc/default/tayga

++ TAYGA_CONF=/etc/tayga.conf

++ TAYGA_IPV4_ADDR=192.168.255.1

++ TAYGA_IPV6_ADDR=fdaa:bb:1::1

++ TAYGA_TUN_V6_ADDR=fdaa:bb:1::2

++ NAT64_PREFIX=64:ff9b::/96

++ DYNAMIC_POOL=192.168.255.0/24

++ NAT44_SERVICE=/etc/init.d/otbr-nat44

++ WLAN_IFNAMES=eth0

+ . script/_dns64

++ BIND_CONF_OPTIONS=/etc/bind/named.conf.options

++ NAT64_PREFIX=64:ff9b::/96

++ DNS64_NAMESERVER_ADDR=127.0.0.1

+++ echo 64:ff9b::/96

+++ tr '"/"' '"/"'

++ DNS64_CONF='dns64 64:ff9b::/96 { clients { thread; }; recursive-only yes; };'

++ without NAT64

++ with NAT64

++ local value

+++ printenv NAT64

++ value=1

++ [[ -z 1 ]]

++ [[ 1 == 1 ]]

++ without DNS64

++ with DNS64

++ local value

+++ printenv DNS64

++ value=0

++ [[ -z 0 ]]

++ [[ 0 == 1 ]]

++ '[' ubuntu = raspbian ']'

++ '[' ubuntu = beagleboneblack ']'

++ '[' ubuntu = ubuntu ']'

++ RESOLV_CONF_HEAD=/etc/resolvconf/resolv.conf.d/head

+ . script/_firewall

++ FIREWALL_SERVICE=/etc/init.d/otbr-firewall

++ sudo modprobe ip6table_filter

sudo: modprobe: command not found

++ true

+ main

+ [[ '' == \s\h\u\t\d\o\w\n ]]

+ startup

+ . /dev/null

+ sudo sysctl --system

* Applying /etc/sysctl.d/10-console-messages.conf ...

kernel.printk = 4 4 1 7

* Applying /etc/sysctl.d/10-ipv6-privacy.conf ...

net.ipv6.conf.all.use_tempaddr = 2

net.ipv6.conf.default.use_tempaddr = 2

* Applying /etc/sysctl.d/10-kernel-hardening.conf ...

kernel.kptr_restrict = 1

* Applying /etc/sysctl.d/10-link-restrictions.conf ...

fs.protected_hardlinks = 1

fs.protected_symlinks = 1

* Applying /etc/sysctl.d/10-magic-sysrq.conf ...

kernel.sysrq = 176

* Applying /etc/sysctl.d/10-network-security.conf ...

net.ipv4.conf.default.rp_filter = 1

net.ipv4.conf.all.rp_filter = 1

net.ipv4.tcp_syncookies = 1

* Applying /etc/sysctl.d/10-ptrace.conf ...

kernel.yama.ptrace_scope = 1

* Applying /etc/sysctl.d/10-zeropage.conf ...

vm.mmap_min_addr = 65536

* Applying /etc/sysctl.d/60-otbr-accept-ra.conf ...

net.ipv6.conf.eth0.accept_ra = 2

net.ipv6.conf.eth0.accept_ra_rt_info_max_plen = 64

* Applying /etc/sysctl.d/60-otbr-ip-forward.conf ...

net.ipv6.conf.all.forwarding = 1

net.ipv4.ip_forward = 1

* Applying /etc/sysctl.conf ...

+ nat64_start

+ with NAT64

+ local value

++ printenv NAT64

+ value=1

+ [[ -z 1 ]]

+ [[ 1 == 1 ]]

+ '[' openthread = tayga ']'

+ nat44_start

+ with DOCKER

+ local value

++ printenv DOCKER

+ value=1

+ [[ -z 1 ]]

+ [[ 1 == 1 ]]

+ service otbr-nat44 start

+ dns64_start

+ with NAT64

+ local value

++ printenv NAT64

+ value=1

+ [[ -z 1 ]]

+ [[ 1 == 1 ]]

+ with DNS64

+ local value

++ printenv DNS64

+ value=0

+ [[ -z 0 ]]

+ [[ 0 == 1 ]]

+ return 0

+ firewall_start

+ with DOCKER

+ local value

++ printenv DOCKER

+ value=1

+ [[ -z 1 ]]

+ [[ 1 == 1 ]]

+ service otbr-firewall start

+ case "$1" in

+ firewall_start

+ firewall_stop

+ ip6tables -C FORWARD -o wpan0 -j OTBR_FORWARD_INGRESS

ip6tables v1.6.1: Couldn't load target `OTBR_FORWARD_INGRESS':No such file or directory

Try `ip6tables -h' or 'ip6tables --help' for more information.

+ ip6tables -L OTBR_FORWARD_INGRESS

ip6tables: No chain/target/match by that name.

+ ipset_destroy_if_exist otbr-ingress-deny-src

+ ipset list otbr-ingress-deny-src

ipset v6.34: Kernel support protocol versions 6-7 while userspace supports protocol versions 6-6

The set with the given name does not exist

+ ipset_destroy_if_exist otbr-ingress-deny-src-swap

+ ipset list otbr-ingress-deny-src-swap

ipset v6.34: Kernel support protocol versions 6-7 while userspace supports protocol versions 6-6

The set with the given name does not exist

+ ipset_destroy_if_exist otbr-ingress-allow-dst

+ ipset list otbr-ingress-allow-dst

ipset v6.34: Kernel support protocol versions 6-7 while userspace supports protocol versions 6-6

The set with the given name does not exist

+ ipset_destroy_if_exist otbr-ingress-allow-dst-swap

+ ipset list otbr-ingress-allow-dst-swap

ipset v6.34: Kernel support protocol versions 6-7 while userspace supports protocol versions 6-6

The set with the given name does not exist

+ ipset create -exist otbr-ingress-deny-src hash:net family inet6

+ ipset create -exist otbr-ingress-deny-src-swap hash:net family inet6

+ ipset create -exist otbr-ingress-allow-dst hash:net family inet6

+ ipset create -exist otbr-ingress-allow-dst-swap hash:net family inet6

+ ip6tables -N OTBR_FORWARD_INGRESS

+ ip6tables -I FORWARD 1 -o wpan0 -j OTBR_FORWARD_INGRESS

+ ip6tables -A OTBR_FORWARD_INGRESS -m pkttype --pkt-type unicast -i wpan0 -j DROP

+ ip6tables -A OTBR_FORWARD_INGRESS -m set --match-set otbr-ingress-deny-src src -j DROP

+ ip6tables -A OTBR_FORWARD_INGRESS -m set --match-set otbr-ingress-allow-dst dst -j ACCEPT

+ ip6tables -A OTBR_FORWARD_INGRESS -m pkttype --pkt-type unicast -j DROP

+ ip6tables -A OTBR_FORWARD_INGRESS -j ACCEPT

+ have systemctl

+ command -v systemctl

+ have service

+ command -v service

+ sudo service rsyslog status

* rsyslogd is not running

+ sudo service rsyslog start

* Starting enhanced syslogd rsyslogd [ OK ]

+ sudo service dbus status

* dbus is not running

+ sudo service dbus start

* Starting system message bus dbus [ OK ]

+ sudo service mdns status

Usage: /etc/init.d/mDNS {start|stop|reload|restart}

+ sudo service mdns start

Starting Apple Darwin Multicast DNS / DNS Service Discovery daemon: mdnsd.

+ sudo service avahi-daemon status

Avahi mDNS/DNS-SD Daemon is not running

+ sudo service avahi-daemon start

* Starting Avahi mDNS/DNS-SD Daemon avahi-daemon [ OK ]

+ sudo service otbr-agent status

* otbr-agent is not running

+ sudo service otbr-agent start

* Starting thread border agent otbr-agent [ OK ]

+ without WEB_GUI

+ with WEB_GUI

+ local value

++ printenv WEB_GUI

+ value=1

+ [[ -z 1 ]]

+ [[ 1 == 1 ]]

+ sudo service otbr-web status

* otbr-web is not running

+ sudo service otbr-web start

* Starting thread web interface otbr-web [ OK ]

+ . /dev/null

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: New relevant interface eth0.IPv4 for mDNS.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Joining mDNS multicast group on interface lo.IPv6 with address ::1.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: New relevant interface lo.IPv6 for mDNS.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: New relevant interface lo.IPv4 for mDNS.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Network interface enumeration completed.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Registering new address record for fe80::42:acff:fe11:2 on eth0.*.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Registering new address record for 172.17.0.2 on eth0.IPv4.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Registering new address record for ::1 on lo.*.

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Registering new address record for 127.0.0.1 on lo.IPv4.

Mar 15 13:20:40 22141e5b02de otbr-agent: [NOTE]-AGENT---: Backbone interface: eth0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [NOTE]-AGENT---: Running 0.3.0-8a8b241

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [NOTE]-AGENT---: Thread version: 1.3.0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [NOTE]-AGENT---: Thread interface: wpan0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [NOTE]-AGENT---: Radio URL: spinel+hdlc+uart:///dev/ttyACM0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [NOTE]-ILS-----: Infra link selected: eth0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-NCP-----: OpenThread log level changed to 5

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 53d.07:49:50.475 [I] Platform------: RCP reset: RESET_POWER_ON

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 53d.07:49:50.495 [I] Platform------: Backbone interface is configured to eth0 (14)

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 53d.07:49:50.496 [I] Platform------: [netif] Sent request#1 to set addr_gen_mode to 1

Mar 15 13:20:40 22141e5b02de kernel: [312423.394225] netlink: 'otbr-agent': attribute type 8 has an invalid length.

Mar 15 13:20:40 22141e5b02de kernel: [312423.394229] netlink: 'otbr-agent': attribute type 8 has an invalid length.

Mar 15 13:20:40 22141e5b02de otbr-web[219]: [INFO]-WEB-----: Running 0.3.0-8a8b241

Mar 15 13:20:40 22141e5b02de otbr-web[219]: [INFO]-WEB-----: Border router web started on wpan0

Mar 15 13:20:40 22141e5b02de otbr-web[219]: [ERR ]-WEB-----: OpenThread daemon is not running.

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.031 [I] ChildSupervsn-: Timeout: 0 -> 190

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.032 [I] InfraIf-------: Init infra netif 14

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.032 [N] BorderRouter--: No valid /48 BR ULA prefix found in settings, generating new one

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.036 [I] Settings------: Saved BrUlaPrefix fd4b:96a7:a130::/48

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.036 [N] BorderRouter--: BR ULA prefix: fd4b:96a7:a130::/48 (generated)

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.036 [I] BorderRouter--: Generated OMR prefix: fd4b:96a7:a130:1::/64

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.036 [I] BorderRouter--: Generated local NAT64 prefix: fd4b:96a7:a130:2:0:0::/96

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.036 [N] BorderRouter--: Local on-link prefix: fdde:ad00:beef:cafe::/64

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.036 [I] InfraIf-------: State changed: NOT RUNNING -> RUNNING

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-UTILS---: Set state callback: OK

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.036 [I] Nat64---------: NAT64 translator is now NotRunning

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #C776._meshcop._udp.local.

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-MDNS----: Registering new service OpenThread BorderRouter #C776._meshcop._udp.local, serviceRef = (nil)

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-ADPROXY-: Publish all hosts and services

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-ADPROXY-: Started

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-DPROXY--: Started

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-BA------: Start Thread Border Agent: OK

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.037 [I] BbrLocal------: Add Domain Prefix: ::/0, NotFound

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.037 [I] BbrLocal------: Add BBR Service: seqno (83), delay (5s), timeout (3600s), InvalidState

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-APP-----: Thread Border Router started on AIL eth0.

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.037 [I] Notifier------: StateChanged (0x42038200) [NetData PanId NetName ExtPanId BbrState (unknown)]

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.037 [I] Bbr-----------: Backbone TMF subscribes ff32:40:fdde:ad00:beef:0:0:3: OK

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.038 [I] BbrManager----: Start Backbone TMF agent: OK

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.039 [I] Platform------: Execute command `ipset flush otbr-ingress-allow-dst-swap` = 0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.041 [I] Platform------: Execute command `ipset flush otbr-ingress-deny-src-swap` = 0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.043 [I] Platform------: Execute command `ipset add otbr-ingress-deny-src-swap fdde:ad00:beef:0::/64 -exist` = 0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.044 [I] Platform------: Execute command `ipset swap otbr-ingress-deny-src-swap otbr-ingress-deny-src` = 0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.046 [I] Platform------: Execute command `ipset swap otbr-ingress-allow-dst-swap otbr-ingress-allow-dst` = 0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.046 [I] Platform------: MulticastRoutingManager: Disable: OK

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [INFO]-BA------: Publish meshcop service OpenThread BorderRouter #C776._meshcop._udp.local.

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: [DEBG]-BBA-----: BackboneAgent: HandleBackboneRouterState: state=1, mBackboneRouterState=0

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.046 [I] RouterTable---: Route table

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.050 [I] Platform------: [netif] Host netif is down

Mar 15 13:20:40 22141e5b02de otbr-agent[191]: 00:00:00.050 [I] Platform------: [netif] Succeeded to process request#1

Mar 15 13:20:40 22141e5b02de avahi-daemon[163]: Server startup complete. Host name is 22141e5b02de.local. Local service cookie is 1649091272.

Mar 15 13:20:40 22141e5b02de rsyslogd: rsyslogd's groupid changed to 101

Mar 15 13:20:40 22141e5b02de rsyslogd: rsyslogd's userid changed to 101

Mar 15 13:20:40 22141e5b02de rsyslogd: [origin software="rsyslogd" swVersion="8.32.0" x-pid="96" x-info="http://www.rsyslog.com"] start

Mar 15 13:20:41 22141e5b02de otbr-agent[191]: [INFO]-MDNS----: Received reply for service OpenThread BorderRouter #C776._meshcop._udp., serviceRef = 0x55eb7f36d5c0

Mar 15 13:20:41 22141e5b02de otbr-agent[191]: [INFO]-MDNS----: Successfully registered service OpenThread BorderRouter #C776._meshcop._udp.

Mar 15 13:20:41 22141e5b02de otbr-agent[191]: [INFO]-BA------: Result of publish meshcop service OpenThread BorderRouter #C776._meshcop._udp.local: OK

Mar 15 13:21:20 22141e5b02de kernel: [312463.597117] [UFW BLOCK] IN=wlp2s0 OUT= MAC=01:00:5e:00:00:01:dc:15:c8:7e:c6:48:08:00 SRC=192.168.178.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=41838 DF PROTO=2

Mar 15 13:21:20 22141e5b02de kernel: [312463.597869] [UFW BLOCK] IN=wlp2s0 OUT= MAC=01:00:5e:00:00:01:dc:15:c8:7e:c6:48:08:00 SRC=192.168.178.1 DST=224.0.0.1 LEN=36 TOS=0x00 PREC=0xC0 TTL=1 ID=41838 DF PROTO=2

Matter Commissioning with the CHIP-Tool on android

TI-LockApp Terminal Output

------------------------------------

[15:30:49:148] Enabled BLE Advertisements

[15:31:05:578] CHIPoBLE connection established

[15:31:11:606] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:11:616] Unhandled cluster ID: 48

[15:31:11:619] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:11:625] Unhandled cluster ID: 48

[15:31:11:708] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:11:719] Unhandled cluster ID: 48

[15:31:11:719] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:11:728] Unhandled cluster ID: 48

[15:31:15:523] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:15:532] Unhandled cluster ID: 48

[15:31:15:534] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:15:542] Unhandled cluster ID: 48

[15:31:15:615] ## Service provisioning state change (1,32)

[15:31:15:620] ## Thread stack state change (1100103d)

[15:31:17:258] ## Thread stack state change (10000040)

[15:31:18:460] ## Thread stack state change (30001224)

[15:31:18:467] ## Thread connectivity established...

[15:31:18:469] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:18:477] Unhandled cluster ID: 48

[15:31:18:483] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:18:488] Unhandled cluster ID: 48

[15:31:18:493] ## Operational network enabled

[15:31:42:019] Failsafe timer expired

[15:31:42:026] Commissioning failed (attempt 1): 32

[15:31:42:034] ## Failsafe timer expired...

[15:31:42:038] OpCreds: Got FailSafeTimerExpired

[15:31:42:045] OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!

[15:31:42:053] Reverting pending fabric data for fabric 0x1

[15:31:42:053] Warning: metadata not found during delete of fabric 0x1

[15:31:42:130] Warning: metadata not found during delete of fabric 0x1

[15:31:42:144] OpCreds: failed to delete fabric at index 1: d8

[15:31:42:148] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:42:160] Unhandled cluster ID: 48

[15:31:42:160] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:31:42:174] Unhandled cluster ID: 48

[15:31:42:183] ## Service provisioning state change (1,0)

[15:31:42:187] ## Thread stack state change (11002046)

[15:31:42:192] ## Thread connectivity lost...

[15:31:42:203] HandleChipConnectionReceived failed, err = d

[15:31:42:205] failed handle new chip BLE connection, status = d

[15:31:56:370] no endpoint for unsub recvd

Matter Commissioning with CHIP-TOOL on Linux machine hosting Docker OTBR

Command

-------------

→ sudo ./chip-tool pairing ble-thread 12 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fdc65d4d37343566051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840

Output

--------

[1678887361.005113][1010942:1010942] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs

[1678887361.007482][1010942:1010942] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini

[1678887361.007638][1010942:1010942] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini

[1678887361.007734][1010942:1010942] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini

[1678887361.007965][1010942:1010942] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-hisoAK)

[1678887361.008100][1010942:1010942] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)

[1678887361.008123][1010942:1010942] CHIP:DL: NVS set: chip-counters/reboot-count = 138 (0x8A)

[1678887361.008331][1010942:1010942] CHIP:DL: Got Ethernet interface: enp3s0

[1678887361.008466][1010942:1010942] CHIP:DL: Found the primary Ethernet interface:enp3s0

[1678887361.008611][1010942:1010942] CHIP:DL: Got WiFi interface: wlp2s0

[1678887361.009454][1010942:1010942] CHIP:DL: Found the primary WiFi interface:wlp2s0

[1678887361.009808][1010942:1010942] CHIP:IN: UDP::Init bind&listen port=0

[1678887361.009837][1010942:1010942] CHIP:IN: UDP::Init bound to port=60364

[1678887361.009842][1010942:1010942] CHIP:IN: UDP::Init bind&listen port=0

[1678887361.009876][1010942:1010942] CHIP:IN: UDP::Init bound to port=42662

[1678887361.009880][1010942:1010942] CHIP:IN: BLEBase::Init - setting/overriding transport

[1678887361.009884][1010942:1010942] CHIP:IN: TransportMgr initialized

[1678887361.009928][1010942:1010942] CHIP:FP: Initializing FabricTable from persistent storage

[1678887361.010229][1010942:1010942] CHIP:TS: Last Known Good Time: 2023-03-02T09:12:42

[1678887361.010893][1010942:1010942] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x66A151DC0F37CCD8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1

[1678887361.011627][1010942:1010942] CHIP:ZCL: Using ZAP configuration...

[1678887361.012005][1010942:1010942] CHIP:DL: MDNS failed to join multicast group on enp3s0 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found

[1678887361.012821][1010942:1010942] CHIP:DL: MDNS failed to join multicast group on vethc78f8eb for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found

[1678887361.012910][1010942:1010942] CHIP:CTL: System State Initialized...

[1678887361.012936][1010942:1010942] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1678887361.013335][1010942:1010942] CHIP:CTL: Setting attestation nonce to random value

[1678887361.013345][1010942:1010942] CHIP:CTL: Setting CSR nonce to random value

[1678887361.013363][1010942:1010942] CHIP:IN: UDP::Init bind&listen port=5550

[1678887361.013397][1010942:1010942] CHIP:IN: UDP::Init bound to port=5550

[1678887361.013402][1010942:1010942] CHIP:IN: UDP::Init bind&listen port=5550

[1678887361.013417][1010942:1010942] CHIP:IN: UDP::Init bound to port=5550

[1678887361.013421][1010942:1010942] CHIP:IN: TransportMgr initialized

[1678887361.013548][1010942:1010944] CHIP:DL: CHIP task running

[1678887361.013858][1010942:1010944] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1678887361.013871][1010942:1010944] CHIP:CTL: Setting attestation nonce to random value

[1678887361.013908][1010942:1010944] CHIP:CTL: Setting CSR nonce to random value

[1678887361.014555][1010942:1010944] CHIP:CTL: Generating NOC

[1678887361.015133][1010942:1010944] CHIP:FP: Validating NOC chain

[1678887361.015799][1010942:1010944] CHIP:FP: NOC chain validation successful

[1678887361.015875][1010942:1010944] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669

[1678887361.015884][1010942:1010944] CHIP:TS: Last Known Good Time: 2023-03-02T09:12:42

[1678887361.015890][1010942:1010944] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00

[1678887361.015894][1010942:1010944] CHIP:TS: Retaining current Last Known Good Time

[1678887361.016846][1010942:1010944] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.

[1678887361.017219][1010942:1010944] CHIP:TS: Committing Last Known Good Time to storage: 2023-03-02T09:12:42

[1678887361.017579][1010942:1010944] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 66A151DC0F37CCD8)

[1678887361.017590][1010942:1010944] CHIP:IN: UDP::Init bind&listen port=5550

[1678887361.017632][1010942:1010944] CHIP:IN: UDP::Init bound to port=5550

[1678887361.017639][1010942:1010944] CHIP:IN: UDP::Init bind&listen port=5550

[1678887361.017655][1010942:1010944] CHIP:IN: UDP::Init bound to port=5550

[1678887361.017660][1010942:1010944] CHIP:IN: TransportMgr initialized

[1678887361.019870][1010942:1010944] CHIP:CTL: Setting thread operational dataset from parameters

[1678887361.019877][1010942:1010944] CHIP:CTL: Setting attempt thread scan from parameters

[1678887361.019899][1010942:1010944] CHIP:CTL: Setting attestation nonce to random value

[1678887361.019931][1010942:1010944] CHIP:CTL: Setting CSR nonce to random value

[1678887361.019937][1010942:1010944] CHIP:CTL: Setting PASE-only commissioning from parameters

[1678887361.019954][1010942:1010944] CHIP:CTL: Commission called for node ID 0x000000000000000C

[1678887361.021905][1010942:1010943] CHIP:DL: TRACE: Bus acquired for name C-6cfe

[1678887361.024541][1010942:1010944] CHIP:DL: PlatformBlueZInit init success

[1678887361.026175][1010942:1010943] CHIP:BLE: BLE removing known devices.

[1678887361.026739][1010942:1010943] CHIP:BLE: BLE initiating scan.

[1678887361.145966][1010942:1010944] CHIP:DL: Long dispatch time: 126 ms, for event type 2

[1678887361.268535][1010942:1010943] CHIP:BLE: New device scanned: 79:A0:EC:DE:F3:CA

[1678887361.268573][1010942:1010943] CHIP:BLE: Device discriminator match. Attempting to connect.

[1678887361.273920][1010942:1010943] CHIP:BLE: Scan complete notification without an active scan.

[1678887361.810070][1010942:1010943] CHIP:DL: ConnectDevice complete

[1678887362.914824][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914838][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914846][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914851][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914856][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914860][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914866][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914871][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914876][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914881][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914885][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914889][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914897][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914902][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914909][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914914][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914920][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914926][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914936][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914940][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914946][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914950][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914955][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914960][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914965][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914970][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914975][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914980][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914985][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.914990][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.914995][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.915001][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915007][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.915012][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915017][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.915022][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915027][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service000d

[1678887362.915031][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915038][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915042][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915048][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915052][1010942:1010943] CHIP:DL: Char1 /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA/service0020

[1678887362.915059][1010942:1010943] CHIP:DL: New BLE connection 0x7f3cdc0571e0, device 79:A0:EC:DE:F3:CA, path /org/bluez/hci0/dev_79_A0_EC_DE_F3_CA

[1678887362.915096][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16385

[1678887362.915108][1010942:1010944] CHIP:DIS: Closing all BLE connections

[1678887362.915124][1010942:1010944] CHIP:IN: BleConnectionComplete: endPoint 0x55d9475dfb20

[1678887362.915178][1010942:1010944] CHIP:IN: SecureSession[0x7f3cd4011e00]: Allocated Type:1 LSID:18212

[1678887362.915187][1010942:1010944] CHIP:SC: Assigned local session key ID 18212

[1678887362.915211][1010942:1010944] CHIP:EM: <<< [E:54797i M:214871856] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)

[1678887362.915224][1010942:1010944] CHIP:IN: (U) Sending msg 214871856 to IP address 'BLE'

[1678887362.915233][1010942:1010944] CHIP:IN: Message appended to BLE send queue

[1678887362.915238][1010942:1010944] CHIP:SC: Sent PBKDF param request

[1678887363.305059][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887363.405789][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16388

[1678887363.405825][1010942:1010944] CHIP:BLE: subscribe complete, ep = 0x55d9475dfb20

[1678887363.455456][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887363.455567][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887363.455626][1010942:1010944] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4

[1678887363.455711][1010942:1010944] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.

[1678887363.455744][1010942:1010944] CHIP:BLE: local and remote recv window size = 6

[1678887363.455861][1010942:1010944] CHIP:IN: BLE EndPoint 0x55d9475dfb20 Connection Complete

[1678887363.554971][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887363.608168][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887363.608357][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887363.608456][1010942:1010944] CHIP:EM: >>> [E:54797i M:259579940] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)

[1678887363.608482][1010942:1010944] CHIP:EM: Found matching exchange: 54797i, Delegate: 0x7f3cd400d4c0

[1678887363.608507][1010942:1010944] CHIP:SC: Received PBKDF param response

[1678887363.608536][1010942:1010944] CHIP:SC: Peer assigned session ID 45975

[1678887363.608560][1010942:1010944] CHIP:SC: Found MRP parameters in the message

[1678887363.615960][1010942:1010944] CHIP:EM: <<< [E:54797i M:214871857] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)

[1678887363.615997][1010942:1010944] CHIP:IN: (U) Sending msg 214871857 to IP address 'BLE'

[1678887363.616068][1010942:1010944] CHIP:SC: Sent spake2p msg1

[1678887363.705061][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887368.957697][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887368.957891][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887368.957976][1010942:1010944] CHIP:EM: >>> [E:54797i M:259579941] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)

[1678887368.958001][1010942:1010944] CHIP:EM: Found matching exchange: 54797i, Delegate: 0x7f3cd400d4c0

[1678887368.958026][1010942:1010944] CHIP:SC: Received spake2p msg2

[1678887368.959081][1010942:1010944] CHIP:EM: <<< [E:54797i M:214871858] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)

[1678887368.959120][1010942:1010944] CHIP:IN: (U) Sending msg 214871858 to IP address 'BLE'

[1678887368.959176][1010942:1010944] CHIP:SC: Sent spake2p msg3

[1678887369.054941][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887369.105611][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887369.105723][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887369.105804][1010942:1010944] CHIP:EM: >>> [E:54797i M:259579942] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)

[1678887369.105829][1010942:1010944] CHIP:EM: Found matching exchange: 54797i, Delegate: 0x7f3cd400d4c0

[1678887369.105989][1010942:1010944] CHIP:SC: SecureSession[0x7f3cd4011e00]: Moving from state 'kEstablishing' --> 'kActive'

[1678887369.106010][1010942:1010944] CHIP:IN: SecureSession[0x7f3cd4011e00]: Activated - Type:1 LSID:18212

[1678887369.106024][1010942:1010944] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:18212 PSID:45975!

[1678887369.106080][1010942:1010944] CHIP:CTL: Remote device completed SPAKE2+ handshake

[1678887369.106097][1010942:1010944] CHIP:TOO: Pairing Success

[1678887369.106109][1010942:1010944] CHIP:TOO: PASE establishment successful

[1678887369.106124][1010942:1010944] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'

[1678887369.106140][1010942:1010944] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'

[1678887369.106154][1010942:1010944] CHIP:CTL: Sending request for commissioning information

[1678887369.106202][1010942:1010944] CHIP:DMG: SendReadRequest ReadClient[0x7f3cd401d9e0]: Sending Read Request

[1678887369.106314][1010942:1010944] CHIP:EM: <<< [E:54798i M:64725834] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)

[1678887369.106345][1010942:1010944] CHIP:IN: (S) Sending msg 64725834 on secure session with LSID: 18212

[1678887369.106403][1010942:1010944] CHIP:DMG: MoveToState ReadClient[0x7f3cd401d9e0]: Moving to [AwaitingIn]

[1678887369.204924][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887369.255619][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887369.255813][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887369.361590][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887369.361786][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887369.361896][1010942:1010944] CHIP:EM: >>> [E:54798i M:267170855] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)

[1678887369.361923][1010942:1010944] CHIP:EM: Found matching exchange: 54798i, Delegate: 0x7f3cd401d9f0

[1678887369.362152][1010942:1010944] CHIP:DMG: ReportDataMessage =

[1678887369.362173][1010942:1010944] CHIP:DMG: {

[1678887369.362185][1010942:1010944] CHIP:DMG: AttributeReportIBs =

[1678887369.362205][1010942:1010944] CHIP:DMG: [

[1678887369.362218][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.362245][1010942:1010944] CHIP:DMG: {

[1678887369.362259][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.362275][1010942:1010944] CHIP:DMG: {

[1678887369.362292][1010942:1010944] CHIP:DMG: DataVersion = 0x6d04d601,

[1678887369.362307][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.362330][1010942:1010944] CHIP:DMG: {

[1678887369.362348][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.362367][1010942:1010944] CHIP:DMG: Cluster = 0x31,

[1678887369.362399][1010942:1010944] CHIP:DMG: Attribute = 0x0000_0003,

[1678887369.362418][1010942:1010944] CHIP:DMG: }

[1678887369.362438][1010942:1010944] CHIP:DMG:

[1678887369.362457][1010942:1010944] CHIP:DMG: Data = 20,

[1678887369.362474][1010942:1010944] CHIP:DMG: },

[1678887369.362496][1010942:1010944] CHIP:DMG:

[1678887369.362513][1010942:1010944] CHIP:DMG: },

[1678887369.362541][1010942:1010944] CHIP:DMG:

[1678887369.362590][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.362614][1010942:1010944] CHIP:DMG: {

[1678887369.362630][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.362647][1010942:1010944] CHIP:DMG: {

[1678887369.362664][1010942:1010944] CHIP:DMG: DataVersion = 0x5b531d18,

[1678887369.362680][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.362698][1010942:1010944] CHIP:DMG: {

[1678887369.362715][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.362733][1010942:1010944] CHIP:DMG: Cluster = 0x28,

[1678887369.362766][1010942:1010944] CHIP:DMG: Attribute = 0x0000_0004,

[1678887369.362795][1010942:1010944] CHIP:DMG: }

[1678887369.362821][1010942:1010944] CHIP:DMG:

[1678887369.362840][1010942:1010944] CHIP:DMG: Data = 32778,

[1678887369.362857][1010942:1010944] CHIP:DMG: },

[1678887369.362879][1010942:1010944] CHIP:DMG:

[1678887369.362895][1010942:1010944] CHIP:DMG: },

[1678887369.362921][1010942:1010944] CHIP:DMG:

[1678887369.362936][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.362971][1010942:1010944] CHIP:DMG: {

[1678887369.362987][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.363016][1010942:1010944] CHIP:DMG: {

[1678887369.363044][1010942:1010944] CHIP:DMG: DataVersion = 0x5b531d18,

[1678887369.363060][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.363078][1010942:1010944] CHIP:DMG: {

[1678887369.363094][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.363112][1010942:1010944] CHIP:DMG: Cluster = 0x28,

[1678887369.363130][1010942:1010944] CHIP:DMG: Attribute = 0x0000_0002,

[1678887369.363148][1010942:1010944] CHIP:DMG: }

[1678887369.363169][1010942:1010944] CHIP:DMG:

[1678887369.363187][1010942:1010944] CHIP:DMG: Data = 65521,

[1678887369.363203][1010942:1010944] CHIP:DMG: },

[1678887369.363224][1010942:1010944] CHIP:DMG:

[1678887369.363239][1010942:1010944] CHIP:DMG: },

[1678887369.363266][1010942:1010944] CHIP:DMG:

[1678887369.363282][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.363302][1010942:1010944] CHIP:DMG: {

[1678887369.363318][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.363334][1010942:1010944] CHIP:DMG: {

[1678887369.363351][1010942:1010944] CHIP:DMG: DataVersion = 0xa843cd64,

[1678887369.363367][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.363384][1010942:1010944] CHIP:DMG: {

[1678887369.363401][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.363419][1010942:1010944] CHIP:DMG: Cluster = 0x30,

[1678887369.363436][1010942:1010944] CHIP:DMG: Attribute = 0x0000_0003,

[1678887369.363454][1010942:1010944] CHIP:DMG: }

[1678887369.363475][1010942:1010944] CHIP:DMG:

[1678887369.363492][1010942:1010944] CHIP:DMG: Data = 0,

[1678887369.363509][1010942:1010944] CHIP:DMG: },

[1678887369.363529][1010942:1010944] CHIP:DMG:

[1678887369.363544][1010942:1010944] CHIP:DMG: },

[1678887369.363571][1010942:1010944] CHIP:DMG:

[1678887369.363597][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.363618][1010942:1010944] CHIP:DMG: {

[1678887369.363645][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.363662][1010942:1010944] CHIP:DMG: {

[1678887369.363679][1010942:1010944] CHIP:DMG: DataVersion = 0xa843cd64,

[1678887369.363695][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.363712][1010942:1010944] CHIP:DMG: {

[1678887369.363729][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.363746][1010942:1010944] CHIP:DMG: Cluster = 0x30,

[1678887369.363764][1010942:1010944] CHIP:DMG: Attribute = 0x0000_0002,

[1678887369.363781][1010942:1010944] CHIP:DMG: }

[1678887369.363800][1010942:1010944] CHIP:DMG:

[1678887369.363818][1010942:1010944] CHIP:DMG: Data = 0,

[1678887369.363835][1010942:1010944] CHIP:DMG: },

[1678887369.363855][1010942:1010944] CHIP:DMG:

[1678887369.363884][1010942:1010944] CHIP:DMG: },

[1678887369.363912][1010942:1010944] CHIP:DMG:

[1678887369.363927][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.363955][1010942:1010944] CHIP:DMG: {

[1678887369.363970][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.363987][1010942:1010944] CHIP:DMG: {

[1678887369.364003][1010942:1010944] CHIP:DMG: DataVersion = 0xa843cd64,

[1678887369.364021][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.364040][1010942:1010944] CHIP:DMG: {

[1678887369.364057][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.364079][1010942:1010944] CHIP:DMG: Cluster = 0x30,

[1678887369.364097][1010942:1010944] CHIP:DMG: Attribute = 0x0000_0001,

[1678887369.364115][1010942:1010944] CHIP:DMG: }

[1678887369.364135][1010942:1010944] CHIP:DMG:

[1678887369.364151][1010942:1010944] CHIP:DMG: Data =

[1678887369.364169][1010942:1010944] CHIP:DMG: {

[1678887369.364188][1010942:1010944] CHIP:DMG: 0x0 = 60,

[1678887369.364208][1010942:1010944] CHIP:DMG: 0x1 = 900,

[1678887369.364226][1010942:1010944] CHIP:DMG: },

[1678887369.364243][1010942:1010944] CHIP:DMG: },

[1678887369.364264][1010942:1010944] CHIP:DMG:

[1678887369.364279][1010942:1010944] CHIP:DMG: },

[1678887369.364307][1010942:1010944] CHIP:DMG:

[1678887369.364321][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.364354][1010942:1010944] CHIP:DMG: {

[1678887369.364370][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.364386][1010942:1010944] CHIP:DMG: {

[1678887369.364405][1010942:1010944] CHIP:DMG: DataVersion = 0xa843cd64,

[1678887369.364421][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.364441][1010942:1010944] CHIP:DMG: {

[1678887369.364458][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.364476][1010942:1010944] CHIP:DMG: Cluster = 0x30,

[1678887369.364496][1010942:1010944] CHIP:DMG: Attribute = 0x0000_0000,

[1678887369.364513][1010942:1010944] CHIP:DMG: }

[1678887369.364533][1010942:1010944] CHIP:DMG:

[1678887369.364551][1010942:1010944] CHIP:DMG: Data = 0,

[1678887369.364567][1010942:1010944] CHIP:DMG: },

[1678887369.364587][1010942:1010944] CHIP:DMG:

[1678887369.364603][1010942:1010944] CHIP:DMG: },

[1678887369.364630][1010942:1010944] CHIP:DMG:

[1678887369.364645][1010942:1010944] CHIP:DMG: AttributeReportIB =

[1678887369.364665][1010942:1010944] CHIP:DMG: {

[1678887369.364679][1010942:1010944] CHIP:DMG: AttributeDataIB =

[1678887369.364696][1010942:1010944] CHIP:DMG: {

[1678887369.364711][1010942:1010944] CHIP:DMG: DataVersion = 0x6d04d601,

[1678887369.364732][1010942:1010944] CHIP:DMG: AttributePathIB =

[1678887369.364748][1010942:1010944] CHIP:DMG: {

[1678887369.364766][1010942:1010944] CHIP:DMG: Endpoint = 0x0,

[1678887369.364797][1010942:1010944] CHIP:DMG: Cluster = 0x31,

[1678887369.364818][1010942:1010944] CHIP:DMG: Attribute = 0x0000_FFFC,

[1678887369.364835][1010942:1010944] CHIP:DMG: }

[1678887369.364856][1010942:1010944] CHIP:DMG:

[1678887369.364872][1010942:1010944] CHIP:DMG: Data = 2,

[1678887369.364889][1010942:1010944] CHIP:DMG: },

[1678887369.364908][1010942:1010944] CHIP:DMG:

[1678887369.364923][1010942:1010944] CHIP:DMG: },

[1678887369.364945][1010942:1010944] CHIP:DMG:

[1678887369.364960][1010942:1010944] CHIP:DMG: ],

[1678887369.365016][1010942:1010944] CHIP:DMG:

[1678887369.365032][1010942:1010944] CHIP:DMG: SuppressResponse = true,

[1678887369.365048][1010942:1010944] CHIP:DMG: InteractionModelRevision = 1

[1678887369.365062][1010942:1010944] CHIP:DMG: }

[1678887369.365875][1010942:1010944] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0

[1678887369.365931][1010942:1010944] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'

[1678887369.365952][1010942:1010944] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'

[1678887369.365971][1010942:1010944] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'

[1678887369.365986][1010942:1010944] CHIP:CTL: Arming failsafe (60 seconds)

[1678887369.366031][1010942:1010944] CHIP:DMG: ICR moving to [AddingComm]

[1678887369.366051][1010942:1010944] CHIP:DMG: ICR moving to [AddedComma]

[1678887369.366126][1010942:1010944] CHIP:EM: <<< [E:54799i M:64725835] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1678887369.366156][1010942:1010944] CHIP:IN: (S) Sending msg 64725835 on secure session with LSID: 18212

[1678887369.366215][1010942:1010944] CHIP:DMG: ICR moving to [CommandSen]

[1678887369.454813][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887369.505527][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887369.505793][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887369.506001][1010942:1010944] CHIP:EM: >>> [E:54799i M:267170856] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1678887369.506031][1010942:1010944] CHIP:EM: Found matching exchange: 54799i, Delegate: 0x7f3cdc058ca8

[1678887369.506056][1010942:1010944] CHIP:DMG: ICR moving to [ResponseRe]

[1678887369.506090][1010942:1010944] CHIP:DMG: InvokeResponseMessage =

[1678887369.506104][1010942:1010944] CHIP:DMG: {

[1678887369.506119][1010942:1010944] CHIP:DMG: suppressResponse = false,

[1678887369.506135][1010942:1010944] CHIP:DMG: InvokeResponseIBs =

[1678887369.506177][1010942:1010944] CHIP:DMG: [

[1678887369.506191][1010942:1010944] CHIP:DMG: InvokeResponseIB =

[1678887369.506212][1010942:1010944] CHIP:DMG: {

[1678887369.506227][1010942:1010944] CHIP:DMG: CommandDataIB =

[1678887369.506255][1010942:1010944] CHIP:DMG: {

[1678887369.506270][1010942:1010944] CHIP:DMG: CommandPathIB =

[1678887369.506287][1010942:1010944] CHIP:DMG: {

[1678887369.506304][1010942:1010944] CHIP:DMG: EndpointId = 0x0,

[1678887369.506322][1010942:1010944] CHIP:DMG: ClusterId = 0x30,

[1678887369.506338][1010942:1010944] CHIP:DMG: CommandId = 0x1,

[1678887369.506354][1010942:1010944] CHIP:DMG: },

[1678887369.506371][1010942:1010944] CHIP:DMG:

[1678887369.506386][1010942:1010944] CHIP:DMG: CommandFields =

[1678887369.506415][1010942:1010944] CHIP:DMG: {

[1678887369.506432][1010942:1010944] CHIP:DMG: 0x0 = 0,

[1678887369.506450][1010942:1010944] CHIP:DMG: 0x1 = "" (0 chars),

[1678887369.506467][1010942:1010944] CHIP:DMG: },

[1678887369.506482][1010942:1010944] CHIP:DMG: },

[1678887369.506503][1010942:1010944] CHIP:DMG:

[1678887369.506517][1010942:1010944] CHIP:DMG: },

[1678887369.506537][1010942:1010944] CHIP:DMG:

[1678887369.506551][1010942:1010944] CHIP:DMG: ],

[1678887369.506572][1010942:1010944] CHIP:DMG:

[1678887369.506586][1010942:1010944] CHIP:DMG: InteractionModelRevision = 1

[1678887369.506599][1010942:1010944] CHIP:DMG: },

[1678887369.506649][1010942:1010944] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001

[1678887369.506691][1010942:1010944] CHIP:CTL: Received ArmFailSafe response errorCode=0

[1678887369.506712][1010942:1010944] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'

[1678887369.506726][1010942:1010944] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'

[1678887369.506747][1010942:1010944] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'

[1678887369.506760][1010942:1010944] CHIP:CTL: Setting Regulatory Config

[1678887369.506786][1010942:1010944] CHIP:CTL: Device does not support configurable regulatory location

[1678887369.506830][1010942:1010944] CHIP:DMG: ICR moving to [AddingComm]

[1678887369.506849][1010942:1010944] CHIP:DMG: ICR moving to [AddedComma]

[1678887369.506910][1010942:1010944] CHIP:EM: <<< [E:54800i M:64725836] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1678887369.506937][1010942:1010944] CHIP:IN: (S) Sending msg 64725836 on secure session with LSID: 18212

[1678887369.506996][1010942:1010944] CHIP:DMG: ICR moving to [CommandSen]

[1678887369.507138][1010942:1010944] CHIP:DMG: ICR moving to [AwaitingDe]

[1678887369.604546][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887369.655555][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887369.655722][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887369.655932][1010942:1010944] CHIP:EM: >>> [E:54800i M:267170857] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1678887369.655961][1010942:1010944] CHIP:EM: Found matching exchange: 54800i, Delegate: 0x7f3cdc058f38

[1678887369.655985][1010942:1010944] CHIP:DMG: ICR moving to [ResponseRe]

[1678887369.656025][1010942:1010944] CHIP:DMG: InvokeResponseMessage =

[1678887369.656041][1010942:1010944] CHIP:DMG: {

[1678887369.656054][1010942:1010944] CHIP:DMG: suppressResponse = false,

[1678887369.656070][1010942:1010944] CHIP:DMG: InvokeResponseIBs =

[1678887369.656092][1010942:1010944] CHIP:DMG: [

[1678887369.656107][1010942:1010944] CHIP:DMG: InvokeResponseIB =

[1678887369.656128][1010942:1010944] CHIP:DMG: {

[1678887369.656141][1010942:1010944] CHIP:DMG: CommandDataIB =

[1678887369.656157][1010942:1010944] CHIP:DMG: {

[1678887369.656182][1010942:1010944] CHIP:DMG: CommandPathIB =

[1678887369.656200][1010942:1010944] CHIP:DMG: {

[1678887369.656219][1010942:1010944] CHIP:DMG: EndpointId = 0x0,

[1678887369.656239][1010942:1010944] CHIP:DMG: ClusterId = 0x30,

[1678887369.656257][1010942:1010944] CHIP:DMG: CommandId = 0x3,

[1678887369.656279][1010942:1010944] CHIP:DMG: },

[1678887369.656300][1010942:1010944] CHIP:DMG:

[1678887369.656319][1010942:1010944] CHIP:DMG: CommandFields =

[1678887369.656337][1010942:1010944] CHIP:DMG: {

[1678887369.656360][1010942:1010944] CHIP:DMG: 0x0 = 0,

[1678887369.656381][1010942:1010944] CHIP:DMG: 0x1 = "" (0 chars),

[1678887369.656400][1010942:1010944] CHIP:DMG: },

[1678887369.656417][1010942:1010944] CHIP:DMG: },

[1678887369.656439][1010942:1010944] CHIP:DMG:

[1678887369.656453][1010942:1010944] CHIP:DMG: },

[1678887369.656474][1010942:1010944] CHIP:DMG:

[1678887369.656492][1010942:1010944] CHIP:DMG: ],

[1678887369.656513][1010942:1010944] CHIP:DMG:

[1678887369.656528][1010942:1010944] CHIP:DMG: InteractionModelRevision = 1

[1678887369.656561][1010942:1010944] CHIP:DMG: },

[1678887369.656628][1010942:1010944] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003

[1678887369.656656][1010942:1010944] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0

[1678887369.656675][1010942:1010944] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'

[1678887369.656689][1010942:1010944] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'

[1678887369.656709][1010942:1010944] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'

[1678887369.656724][1010942:1010944] CHIP:CTL: Sending request for PAI certificate

[1678887369.656737][1010942:1010944] CHIP:CTL: Sending Certificate Chain request to 0x7f3cd400d470 device

[1678887369.656780][1010942:1010944] CHIP:DMG: ICR moving to [AddingComm]

[1678887369.656821][1010942:1010944] CHIP:DMG: ICR moving to [AddedComma]

[1678887369.656892][1010942:1010944] CHIP:EM: <<< [E:54801i M:64725837] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1678887369.656920][1010942:1010944] CHIP:IN: (S) Sending msg 64725837 on secure session with LSID: 18212

[1678887369.656985][1010942:1010944] CHIP:DMG: ICR moving to [CommandSen]

[1678887369.657036][1010942:1010944] CHIP:DMG: ICR moving to [AwaitingDe]

[1678887369.754951][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887369.805766][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887369.805893][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887369.911607][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887369.911800][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887370.056239][1010942:1010943] CHIP:DL: Indication received, conn = 0x7f3cdc0571e0

[1678887370.056411][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1678887370.056527][1010942:1010944] CHIP:EM: >>> [E:54801i M:267170858] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1678887370.056554][1010942:1010944] CHIP:EM: Found matching exchange: 54801i, Delegate: 0x7f3cdc058ca8

[1678887370.056581][1010942:1010944] CHIP:DMG: ICR moving to [ResponseRe]

[1678887370.056621][1010942:1010944] CHIP:DMG: InvokeResponseMessage =

[1678887370.056636][1010942:1010944] CHIP:DMG: {

[1678887370.056650][1010942:1010944] CHIP:DMG: suppressResponse = false,

[1678887370.056664][1010942:1010944] CHIP:DMG: InvokeResponseIBs =

[1678887370.056685][1010942:1010944] CHIP:DMG: [

[1678887370.056698][1010942:1010944] CHIP:DMG: InvokeResponseIB =

[1678887370.056720][1010942:1010944] CHIP:DMG: {

[1678887370.056744][1010942:1010944] CHIP:DMG: CommandDataIB =

[1678887370.056767][1010942:1010944] CHIP:DMG: {

[1678887370.056786][1010942:1010944] CHIP:DMG: CommandPathIB =

[1678887370.056806][1010942:1010944] CHIP:DMG: {

[1678887370.056828][1010942:1010944] CHIP:DMG: EndpointId = 0x0,

[1678887370.056846][1010942:1010944] CHIP:DMG: ClusterId = 0x3e,

[1678887370.056864][1010942:1010944] CHIP:DMG: CommandId = 0x3,

[1678887370.056880][1010942:1010944] CHIP:DMG: },

[1678887370.056901][1010942:1010944] CHIP:DMG:

[1678887370.056918][1010942:1010944] CHIP:DMG: CommandFields =

[1678887370.056936][1010942:1010944] CHIP:DMG: {

[1678887370.056957][1010942:1010944] CHIP:DMG: 0x0 = [

[1678887370.057067][1010942:1010944] CHIP:DMG: 0x30, 0x82, 0x01, 0xcb, 0x30, 0x82, 0x01, 0x71, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0x0c, 0x8c, 0x87, 0x6d, 0x03, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x05, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x09, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0x0b, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x

[1678887370.057120][1010942:1010944] CHIP:DMG: ] (463 bytes)

[1678887370.057140][1010942:1010944] CHIP:DMG: },

[1678887370.057156][1010942:1010944] CHIP:DMG: },

[1678887370.057178][1010942:1010944] CHIP:DMG:

[1678887370.057193][1010942:1010944] CHIP:DMG: },

[1678887370.057213][1010942:1010944] CHIP:DMG:

[1678887370.057227][1010942:1010944] CHIP:DMG: ],

[1678887370.057250][1010942:1010944] CHIP:DMG:

[1678887370.057292][1010942:1010944] CHIP:DMG: InteractionModelRevision = 1

[1678887370.057307][1010942:1010944] CHIP:DMG: },

[1678887370.057361][1010942:1010944] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003

[1678887370.057386][1010942:1010944] CHIP:CTL: Received certificate chain from the device

[1678887370.057408][1010942:1010944] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'

[1678887370.057431][1010942:1010944] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'

[1678887370.057450][1010942:1010944] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'

[1678887370.057464][1010942:1010944] CHIP:CTL: Sending request for DAC certificate

[1678887370.057477][1010942:1010944] CHIP:CTL: Sending Certificate Chain request to 0x7f3cd400d470 device

[1678887370.057519][1010942:1010944] CHIP:DMG: ICR moving to [AddingComm]

[1678887370.057538][1010942:1010944] CHIP:DMG: ICR moving to [AddedComma]

[1678887370.057608][1010942:1010944] CHIP:EM: <<< [E:54802i M:64725838] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1678887370.057637][1010942:1010944] CHIP:IN: (S) Sending msg 64725838 on secure session with LSID: 18212

[1678887370.057702][1010942:1010944] CHIP:DMG: ICR moving to [CommandSen]

[1678887370.057748][1010942:1010944] CHIP:DMG: ICR moving to [AwaitingDe]

[1678887370.154909][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1678887385.069340][1010942:1010944] CHIP:BLE: ack recv timeout, closing ep 0x55d9475dfb20

[1678887385.069380][1010942:1010944] CHIP:IN: Clearing BLE pending packets.

[1678887385.071510][1010942:1010944] CHIP:DL: HandlePlatformSpecificBLEEvent 16388

[1678887385.071542][1010942:1010944] CHIP:BLE: Auto-closing end point's BLE connection.

[1678887385.071556][1010942:1010944] CHIP:DL: Closing BLE GATT connection (con 0x7f3cdc0571e0)

[1678887385.071669][1010942:1010943] CHIP:DL: BluezDisconnect peer=79:A0:EC:DE:F3:CA

[1678887387.608962][1010942:1010943] CHIP:DL: Bluez disconnected

[1678887387.608996][1010942:1010943] CHIP:DL: Bluez notify CHIPoBluez connection disconnected

[1678887400.065478][1010942:1010944] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 54802i

[1678887400.065536][1010942:1010944] CHIP:CTL: Device failed to receive the Certificate Chain request Response: ../../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout

[1678887400.065562][1010942:1010944] CHIP:CTL: Error on commissioning step 'SendDACCertificateRequest': '../../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout'

[1678887400.065578][1010942:1010944] CHIP:CTL: Failed to perform commissioning step 6

[1678887400.065598][1010942:1010944] CHIP:CTL: Going from commissioning step 'SendDACCertificateRequest' with lastErr = '../../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout' -> 'Cleanup'

[1678887400.065623][1010942:1010944] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout'

[1678887400.065640][1010942:1010944] CHIP:CTL: Expiring failsafe on proxy 0x7f3cd400d470

[1678887400.065686][1010942:1010944] CHIP:DMG: ICR moving to [AddingComm]

[1678887400.065707][1010942:1010944] CHIP:DMG: ICR moving to [AddedComma]

[1678887400.065797][1010942:1010944] CHIP:EM: <<< [E:54803i M:64725839] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1678887400.065831][1010942:1010944] CHIP:IN: (S) Sending msg 64725839 on secure session with LSID: 18212

[1678887400.065851][1010942:1010944] CHIP:IN: Message appended to BLE send queue

[1678887400.065867][1010942:1010944] CHIP:DMG: ICR moving to [CommandSen]

[1678887400.065899][1010942:1010944] CHIP:DMG: ICR moving to [AwaitingDe]

[1678887417.071420][1010942:1010944] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 54803i

[1678887417.071478][1010942:1010944] CHIP:CTL: Received failure response when disarming failsafe../../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout

[1678887417.071510][1010942:1010944] CHIP:CTL: Successfully finished commissioning step 'Cleanup'

[1678887417.071567][1010942:1010944] CHIP:TOO: Device commissioning Failure: ../../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout

[1678887417.071599][1010942:1010944] CHIP:DIS: Closing all BLE connections

[1678887417.071645][1010942:1010944] CHIP:IN: SecureSession[0x7f3cd4011e00]: MarkForEviction Type:1 LSID:18212

[1678887417.071664][1010942:1010944] CHIP:SC: SecureSession[0x7f3cd4011e00]: Moving from state 'kActive' --> 'kPendingEviction'

[1678887417.071746][1010942:1010944] CHIP:IN: SecureSession[0x7f3cd4011e00]: Released - Type:1 LSID:18212

[1678887417.071779][1010942:1010944] CHIP:DMG: ICR moving to [AwaitingDe]

[1678887417.072074][1010942:1010942] CHIP:CTL: Shutting down the commissioner

[1678887417.072109][1010942:1010942] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1678887417.072182][1010942:1010942] CHIP:CTL: Shutting down the controller

[1678887417.072202][1010942:1010942] CHIP:IN: Expiring all sessions for fabric 0x1!!

[1678887417.072216][1010942:1010942] CHIP:FP: Forgetting fabric 0x1

[1678887417.072238][1010942:1010942] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:12:42

[1678887417.072369][1010942:1010942] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:12:42

[1678887417.072386][1010942:1010942] CHIP:TS: Reverted Last Known Good Time to previous value

[1678887417.072419][1010942:1010942] CHIP:CTL: Shutting down the commissioner

[1678887417.072431][1010942:1010942] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1678887417.072476][1010942:1010942] CHIP:CTL: Shutting down the controller

[1678887417.072490][1010942:1010942] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack

[1678887417.072768][1010942:1010942] CHIP:DMG: IM WH moving to [Uninitialized]

[1678887417.072784][1010942:1010942] CHIP:DMG: IM WH moving to [Uninitialized]

[1678887417.072795][1010942:1010942] CHIP:DMG: IM WH moving to [Uninitialized]

[1678887417.072807][1010942:1010942] CHIP:DMG: IM WH moving to [Uninitialized]

[1678887417.072820][1010942:1010942] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet

[1678887417.072864][1010942:1010942] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.

[1678887417.072890][1010942:1010942] CHIP:FP: Shutting down FabricTable

[1678887417.072906][1010942:1010942] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:12:42

[1678887417.072979][1010942:1010942] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:12:42

[1678887417.072994][1010942:1010942] CHIP:TS: Reverted Last Known Good Time to previous value

[1678887417.073194][1010942:1010942] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Mfciqh)

[1678887417.073622][1010942:1010942] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)

[1678887417.073680][1010942:1010942] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)

[1678887417.073701][1010942:1010942] CHIP:DL: Inet Layer shutdown

[1678887417.073716][1010942:1010942] CHIP:DL: BLE shutdown

[1678887417.075152][1010942:1010942] CHIP:DL: System Layer shutdown

[1678887417.075440][1010942:1010942] CHIP:TOO: Run command failure: ../../examples/chip-tool/third_party/connectedhomeip/src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout

Output from TI Lock-App Terminal

-----------------------------------------------

[15:35:48:377] Enabled BLE Advertisements

[15:36:03:357] CHIPoBLE connection established

[15:36:09:410] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:36:09:419] Unhandled cluster ID: 48

[15:36:09:421] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:36:09:429] Unhandled cluster ID: 48

[15:36:09:562] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:36:09:571] Unhandled cluster ID: 48

[15:36:09:573] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:36:09:582] Unhandled cluster ID: 48

[15:36:27:626] no endpoint for BLE sent data ack

[15:37:11:716] Failsafe timer expired

[15:37:11:727] Commissioning failed (attempt 1): 32

[15:37:11:734] ## Failsafe timer expired...

[15:37:11:734] OpCreds: Got FailSafeTimerExpired

[15:37:11:737] OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!

[15:37:11:749] PreAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:37:11:758] Unhandled cluster ID: 48

[15:37:11:759] PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'

[15:37:11:768] Unhandled cluster ID: 48

0 Ryan Brown1 over 2 years ago in reply to Logan Becker

TI__Guru**** 218837 points

Hello Logan,

Thanks for the detailed logs, they describe an issue that is different from the aforementioned thread. Your setup gets far into the commissioning process before failing. Lock-app can join the OTBR, the chip-tool and lock-app connect over BLE , and PASE establishment is successful. But chip-tool then fails at discovering the LP on the network. It's unclear whether chip-tool and OTBR are on the same Wi-Fi and that could be the main issue. You should try to determine whether IP communication between chip-tool and the OTBR are working. Please refer to this relevant E2E thread (using wlan0 instead of eth0 or whatever your OTBR interface name is).

Regards,
Ryan

0 Logan Becker over 2 years ago in reply to Ryan Brown1

Prodigy 70 points

Hey Ryan,

I hope all is well?
I switched to another house with only 1 router.
It seems PASE session which runs on BLE is constantly having timeouts.
My laptop has BLE version 4.0, and my TI board has version BLE 5.2.
Could speed variation and message capacity be the resulting issue?

I attempted commissioning and only 2/60 attempts passed the PASE session, but failed during the CASE session.
The 1st attempt passing PASE session stopped at commissioning step 15.
The 2nd attemp passing PASE session stopped at commissioning step 18.
The other 58 failures remain from my first error log I post the first time.

I did attempt to connect the Ethernet cable to test if it would resolve step 18. But it just made the same errors from before and stopped at step 5.

Kind regards,
Logan Becker

Here is the logs for the 2nd attempt:

sudo ./chip-tool pairing ble-thread 12345 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fdc65d4d37343566051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840

[1679565456.360983][61500:61500] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1679565456.363060][61500:61500] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1679565456.363133][61500:61500] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1679565456.363189][61500:61500] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1679565456.363340][61500:61500] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-fql7BL)
[1679565456.363586][61500:61500] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1679565456.363609][61500:61500] CHIP:DL: NVS set: chip-counters/reboot-count = 47 (0x2F)
[1679565456.363881][61500:61500] CHIP:DL: Got Ethernet interface: enp3s0
[1679565456.364050][61500:61500] CHIP:DL: Found the primary Ethernet interface:enp3s0
[1679565456.364244][61500:61500] CHIP:DL: Got WiFi interface: wlp2s0
[1679565456.365482][61500:61500] CHIP:DL: Found the primary WiFi interface:wlp2s0
[1679565456.365522][61500:61500] CHIP:IN: UDP::Init bind&listen port=0
[1679565456.365588][61500:61500] CHIP:IN: UDP::Init bound to port=38564
[1679565456.365594][61500:61500] CHIP:IN: UDP::Init bind&listen port=0
[1679565456.365635][61500:61500] CHIP:IN: UDP::Init bound to port=45037
[1679565456.365639][61500:61500] CHIP:IN: BLEBase::Init - setting/overriding transport
[1679565456.365653][61500:61500] CHIP:IN: TransportMgr initialized
[1679565456.365660][61500:61500] CHIP:FP: Initializing FabricTable from persistent storage
[1679565456.365697][61500:61500] CHIP:TS: Last Known Good Time: 2023-03-02T09:12:42
[1679565456.366224][61500:61500] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x0C6F58F310B58F43, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1679565456.366648][61500:61500] CHIP:ZCL: Using ZAP configuration...
[1679565456.367010][61500:61500] CHIP:DL: MDNS failed to join multicast group on enp3s0 for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
[1679565456.367794][61500:61500] CHIP:DL: MDNS failed to join multicast group on veth01558ad for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
[1679565456.367847][61500:61500] CHIP:CTL: System State Initialized...
[1679565456.367871][61500:61500] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1679565456.367888][61500:61500] CHIP:CTL: Setting attestation nonce to random value
[1679565456.367896][61500:61500] CHIP:CTL: Setting CSR nonce to random value
[1679565456.367908][61500:61500] CHIP:IN: UDP::Init bind&listen port=5550
[1679565456.367925][61500:61500] CHIP:IN: UDP::Init bound to port=5550
[1679565456.367929][61500:61500] CHIP:IN: UDP::Init bind&listen port=5550
[1679565456.367943][61500:61500] CHIP:IN: UDP::Init bound to port=5550
[1679565456.367946][61500:61500] CHIP:IN: TransportMgr initialized
[1679565456.368067][61500:61505] CHIP:DL: CHIP task running
[1679565456.368152][61500:61505] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1679565456.368163][61500:61505] CHIP:CTL: Setting attestation nonce to random value
[1679565456.368187][61500:61505] CHIP:CTL: Setting CSR nonce to random value
[1679565456.368537][61500:61505] CHIP:CTL: Generating NOC
[1679565456.368903][61500:61505] CHIP:FP: Validating NOC chain
[1679565456.369374][61500:61505] CHIP:FP: NOC chain validation successful
[1679565456.369450][61500:61505] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1679565456.369456][61500:61505] CHIP:TS: Last Known Good Time: 2023-03-02T09:12:42
[1679565456.369474][61500:61505] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1679565456.369478][61500:61505] CHIP:TS: Retaining current Last Known Good Time
[1679565456.369845][61500:61505] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1679565456.370186][61500:61505] CHIP:TS: Committing Last Known Good Time to storage: 2023-03-02T09:12:42
[1679565456.370581][61500:61505] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1679565456.370590][61500:61505] CHIP:IN: UDP::Init bind&listen port=5550
[1679565456.370611][61500:61505] CHIP:IN: UDP::Init bound to port=5550
[1679565456.370616][61500:61505] CHIP:IN: UDP::Init bind&listen port=5550
[1679565456.370639][61500:61505] CHIP:IN: UDP::Init bound to port=5550
[1679565456.370644][61500:61505] CHIP:IN: TransportMgr initialized
[1679565456.372794][61500:61505] CHIP:IN: SecureSession[0x7f050c00acb0]: Allocated Type:1 LSID:53795
[1679565456.372804][61500:61505] CHIP:SC: Assigned local session key ID 53795
[1679565456.372815][61500:61505] CHIP:SC: Including MRP parameters in PBKDF param request
[1679565456.372830][61500:61505] CHIP:EM: <<< [E:45976i M:188567100] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1679565456.372840][61500:61505] CHIP:IN: (U) Sending msg 188567100 to IP address 'BLE'
[1679565456.372846][61500:61505] CHIP:IN: Message appended to BLE send queue
[1679565456.372850][61500:61505] CHIP:SC: Sent PBKDF param request
[1679565456.372855][61500:61505] CHIP:CTL: Setting thread operational dataset from parameters
[1679565456.372859][61500:61505] CHIP:CTL: Setting attempt thread scan from parameters
[1679565456.372864][61500:61505] CHIP:CTL: Setting attestation nonce to random value
[1679565456.372873][61500:61505] CHIP:CTL: Setting CSR nonce to random value
[1679565456.372879][61500:61505] CHIP:CTL: Commission called for node ID 0x0000000000003039
[1679565456.372939][61500:61506] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1679565456.373008][61500:61503] CHIP:DL: TRACE: Bus acquired for name C-f03c
[1679565456.375368][61500:61505] CHIP:DL: PlatformBlueZInit init success
[1679565456.377386][61500:61503] CHIP:BLE: BLE removing known devices.
[1679565456.377880][61500:61503] CHIP:BLE: BLE initiating scan.
[1679565456.494924][61500:61505] CHIP:DL: Long dispatch time: 122 ms, for event type 2
[1679565456.504200][61500:61503] CHIP:BLE: New device scanned: 49:07:53:EF:D7:10
[1679565456.504232][61500:61503] CHIP:BLE: Device discriminator match. Attempting to connect.
[1679565456.510685][61500:61503] CHIP:BLE: Scan complete notification without an active scan.
[1679565456.646925][61500:61503] CHIP:DL: ConnectDevice complete
[1679565457.754414][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754425][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754430][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754451][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754456][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754460][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754483][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754487][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754493][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754496][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754502][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754506][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754510][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754514][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754518][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754522][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754545][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754549][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754563][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754567][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754571][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754575][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754582][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754586][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754590][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754594][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754598][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754602][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754607][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754611][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754616][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754619][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754624][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service000d
[1679565457.754636][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754649][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754653][61500:61503] CHIP:DL: Char1 /org/bluez/hci0/dev_49_07_53_EF_D7_10/service0020
[1679565457.754659][61500:61503] CHIP:DL: New BLE connection 0x7f05180449e0, device 49:07:53:EF:D7:10, path /org/bluez/hci0/dev_49_07_53_EF_D7_10
[1679565457.754698][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1679565457.754708][61500:61505] CHIP:IN: BleConnectionComplete: endPoint 0x55b3faf90b40
[1679565458.145262][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565458.246019][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1679565458.246055][61500:61505] CHIP:BLE: subscribe complete, ep = 0x55b3faf90b40
[1679565458.296206][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565458.296385][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565458.296424][61500:61505] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1679565458.296442][61500:61505] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1679565458.296455][61500:61505] CHIP:BLE: local and remote recv window size = 6
[1679565458.296550][61500:61505] CHIP:IN: BLE EndPoint 0x55b3faf90b40 Connection Complete
[1679565458.395078][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565458.445526][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565458.445725][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565458.445825][61500:61505] CHIP:EM: >>> [E:45976i M:114745775] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1679565458.445849][61500:61505] CHIP:EM: Found matching exchange: 45976i, Delegate: 0x7f050c00d660
[1679565458.445873][61500:61505] CHIP:SC: Received PBKDF param response
[1679565458.445903][61500:61505] CHIP:SC: Peer assigned session ID 60378
[1679565458.445923][61500:61505] CHIP:SC: Found MRP parameters in the message
[1679565458.452966][61500:61505] CHIP:EM: <<< [E:45976i M:188567101] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1679565458.453016][61500:61505] CHIP:IN: (U) Sending msg 188567101 to IP address 'BLE'
[1679565458.453363][61500:61505] CHIP:SC: Sent spake2p msg1
[1679565458.545058][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565463.796090][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565463.796298][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565463.796400][61500:61505] CHIP:EM: >>> [E:45976i M:114745776] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1679565463.796428][61500:61505] CHIP:EM: Found matching exchange: 45976i, Delegate: 0x7f050c00d660
[1679565463.796453][61500:61505] CHIP:SC: Received spake2p msg2
[1679565463.797477][61500:61505] CHIP:EM: <<< [E:45976i M:188567102] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1679565463.797516][61500:61505] CHIP:IN: (U) Sending msg 188567102 to IP address 'BLE'
[1679565463.797577][61500:61505] CHIP:SC: Sent spake2p msg3
[1679565463.892559][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565463.943523][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565463.943676][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565463.943772][61500:61505] CHIP:EM: >>> [E:45976i M:114745777] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1679565463.943796][61500:61505] CHIP:EM: Found matching exchange: 45976i, Delegate: 0x7f050c00d660
[1679565463.943951][61500:61505] CHIP:SC: SecureSession[0x7f050c00acb0]: Moving from state 'kEstablishing' --> 'kActive'
[1679565463.943977][61500:61505] CHIP:IN: SecureSession[0x7f050c00acb0]: Activated - Type:1 LSID:53795
[1679565463.943993][61500:61505] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:53795 PSID:60378!
[1679565463.944015][61500:61505] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1679565463.944031][61500:61505] CHIP:TOO: Pairing Success
[1679565463.944046][61500:61505] CHIP:TOO: PASE establishment successful
[1679565463.944063][61500:61505] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1679565463.944081][61500:61505] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1679565463.944096][61500:61505] CHIP:CTL: Sending request for commissioning information
[1679565463.944123][61500:61505] CHIP:DMG: SendReadRequest ReadClient[0x7f050c018a70]: Sending Read Request
[1679565463.944225][61500:61505] CHIP:EM: <<< [E:45977i M:54907276] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1679565463.944254][61500:61505] CHIP:IN: (S) Sending msg 54907276 on secure session with LSID: 53795
[1679565463.944312][61500:61505] CHIP:DMG: MoveToState ReadClient[0x7f050c018a70]: Moving to [AwaitingIn]
[1679565464.092375][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565464.143582][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565464.143748][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565464.297899][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565464.298076][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565464.298191][61500:61505] CHIP:EM: >>> [E:45977i M:235583078] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1679565464.298255][61500:61505] CHIP:EM: Found matching exchange: 45977i, Delegate: 0x7f050c018a80
[1679565464.298349][61500:61505] CHIP:DMG: ReportDataMessage =
[1679565464.298366][61500:61505] CHIP:DMG: {
[1679565464.298380][61500:61505] CHIP:DMG: AttributeReportIBs =
[1679565464.298403][61500:61505] CHIP:DMG: [
[1679565464.298418][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.298441][61500:61505] CHIP:DMG: {
[1679565464.298456][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.298474][61500:61505] CHIP:DMG: {
[1679565464.298492][61500:61505] CHIP:DMG: DataVersion = 0x60067a23,
[1679565464.298509][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.298528][61500:61505] CHIP:DMG: {
[1679565464.298545][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.298564][61500:61505] CHIP:DMG: Cluster = 0x31,
[1679565464.298583][61500:61505] CHIP:DMG: Attribute = 0x0000_0003,
[1679565464.298601][61500:61505] CHIP:DMG: }
[1679565464.298622][61500:61505] CHIP:DMG:
[1679565464.298663][61500:61505] CHIP:DMG: Data = 20,
[1679565464.298680][61500:61505] CHIP:DMG: },
[1679565464.298699][61500:61505] CHIP:DMG:
[1679565464.298715][61500:61505] CHIP:DMG: },
[1679565464.298741][61500:61505] CHIP:DMG:
[1679565464.298756][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.298777][61500:61505] CHIP:DMG: {
[1679565464.298792][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.298809][61500:61505] CHIP:DMG: {
[1679565464.298826][61500:61505] CHIP:DMG: DataVersion = 0xa8426781,
[1679565464.298850][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.298867][61500:61505] CHIP:DMG: {
[1679565464.298885][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.298904][61500:61505] CHIP:DMG: Cluster = 0x28,
[1679565464.298922][61500:61505] CHIP:DMG: Attribute = 0x0000_0004,
[1679565464.298941][61500:61505] CHIP:DMG: }
[1679565464.298960][61500:61505] CHIP:DMG:
[1679565464.298979][61500:61505] CHIP:DMG: Data = 32778,
[1679565464.298995][61500:61505] CHIP:DMG: },
[1679565464.299016][61500:61505] CHIP:DMG:
[1679565464.299042][61500:61505] CHIP:DMG: },
[1679565464.299071][61500:61505] CHIP:DMG:
[1679565464.299086][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.299109][61500:61505] CHIP:DMG: {
[1679565464.299123][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.299139][61500:61505] CHIP:DMG: {
[1679565464.299155][61500:61505] CHIP:DMG: DataVersion = 0xa8426781,
[1679565464.299172][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.299190][61500:61505] CHIP:DMG: {
[1679565464.299208][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.299225][61500:61505] CHIP:DMG: Cluster = 0x28,
[1679565464.299243][61500:61505] CHIP:DMG: Attribute = 0x0000_0002,
[1679565464.299261][61500:61505] CHIP:DMG: }
[1679565464.299280][61500:61505] CHIP:DMG:
[1679565464.299297][61500:61505] CHIP:DMG: Data = 65521,
[1679565464.299313][61500:61505] CHIP:DMG: },
[1679565464.299332][61500:61505] CHIP:DMG:
[1679565464.299348][61500:61505] CHIP:DMG: },
[1679565464.299374][61500:61505] CHIP:DMG:
[1679565464.299388][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.299409][61500:61505] CHIP:DMG: {
[1679565464.299424][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.299441][61500:61505] CHIP:DMG: {
[1679565464.299456][61500:61505] CHIP:DMG: DataVersion = 0x460dde53,
[1679565464.299473][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.299489][61500:61505] CHIP:DMG: {
[1679565464.299507][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.299543][61500:61505] CHIP:DMG: Cluster = 0x30,
[1679565464.299565][61500:61505] CHIP:DMG: Attribute = 0x0000_0003,
[1679565464.299582][61500:61505] CHIP:DMG: }
[1679565464.299602][61500:61505] CHIP:DMG:
[1679565464.299621][61500:61505] CHIP:DMG: Data = 0,
[1679565464.299636][61500:61505] CHIP:DMG: },
[1679565464.299657][61500:61505] CHIP:DMG:
[1679565464.299671][61500:61505] CHIP:DMG: },
[1679565464.299696][61500:61505] CHIP:DMG:
[1679565464.299712][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.299732][61500:61505] CHIP:DMG: {
[1679565464.299748][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.299764][61500:61505] CHIP:DMG: {
[1679565464.299780][61500:61505] CHIP:DMG: DataVersion = 0x460dde53,
[1679565464.299797][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.299813][61500:61505] CHIP:DMG: {
[1679565464.299831][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.299849][61500:61505] CHIP:DMG: Cluster = 0x30,
[1679565464.299867][61500:61505] CHIP:DMG: Attribute = 0x0000_0002,
[1679565464.299890][61500:61505] CHIP:DMG: }
[1679565464.299908][61500:61505] CHIP:DMG:
[1679565464.299926][61500:61505] CHIP:DMG: Data = 0,
[1679565464.299943][61500:61505] CHIP:DMG: },
[1679565464.299965][61500:61505] CHIP:DMG:
[1679565464.299981][61500:61505] CHIP:DMG: },
[1679565464.300022][61500:61505] CHIP:DMG:
[1679565464.300037][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.300064][61500:61505] CHIP:DMG: {
[1679565464.300079][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.300098][61500:61505] CHIP:DMG: {
[1679565464.300115][61500:61505] CHIP:DMG: DataVersion = 0x460dde53,
[1679565464.300131][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.300153][61500:61505] CHIP:DMG: {
[1679565464.300171][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.300189][61500:61505] CHIP:DMG: Cluster = 0x30,
[1679565464.300207][61500:61505] CHIP:DMG: Attribute = 0x0000_0001,
[1679565464.300225][61500:61505] CHIP:DMG: }
[1679565464.300244][61500:61505] CHIP:DMG:
[1679565464.300261][61500:61505] CHIP:DMG: Data =
[1679565464.300279][61500:61505] CHIP:DMG: {
[1679565464.300297][61500:61505] CHIP:DMG: 0x0 = 60,
[1679565464.300316][61500:61505] CHIP:DMG: 0x1 = 900,
[1679565464.300348][61500:61505] CHIP:DMG: },
[1679565464.300375][61500:61505] CHIP:DMG: },
[1679565464.300397][61500:61505] CHIP:DMG:
[1679565464.300412][61500:61505] CHIP:DMG: },
[1679565464.300440][61500:61505] CHIP:DMG:
[1679565464.300467][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.300487][61500:61505] CHIP:DMG: {
[1679565464.300501][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.300518][61500:61505] CHIP:DMG: {
[1679565464.300535][61500:61505] CHIP:DMG: DataVersion = 0x460dde53,
[1679565464.300551][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.300580][61500:61505] CHIP:DMG: {
[1679565464.300597][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.300615][61500:61505] CHIP:DMG: Cluster = 0x30,
[1679565464.300644][61500:61505] CHIP:DMG: Attribute = 0x0000_0000,
[1679565464.300660][61500:61505] CHIP:DMG: }
[1679565464.300695][61500:61505] CHIP:DMG:
[1679565464.300713][61500:61505] CHIP:DMG: Data = 0,
[1679565464.300730][61500:61505] CHIP:DMG: },
[1679565464.300754][61500:61505] CHIP:DMG:
[1679565464.300769][61500:61505] CHIP:DMG: },
[1679565464.300795][61500:61505] CHIP:DMG:
[1679565464.300809][61500:61505] CHIP:DMG: AttributeReportIB =
[1679565464.300830][61500:61505] CHIP:DMG: {
[1679565464.300845][61500:61505] CHIP:DMG: AttributeDataIB =
[1679565464.300861][61500:61505] CHIP:DMG: {
[1679565464.300886][61500:61505] CHIP:DMG: DataVersion = 0x60067a23,
[1679565464.300903][61500:61505] CHIP:DMG: AttributePathIB =
[1679565464.300924][61500:61505] CHIP:DMG: {
[1679565464.300943][61500:61505] CHIP:DMG: Endpoint = 0x0,
[1679565464.300961][61500:61505] CHIP:DMG: Cluster = 0x31,
[1679565464.300993][61500:61505] CHIP:DMG: Attribute = 0x0000_FFFC,
[1679565464.301010][61500:61505] CHIP:DMG: }
[1679565464.301030][61500:61505] CHIP:DMG:
[1679565464.301048][61500:61505] CHIP:DMG: Data = 2,
[1679565464.301064][61500:61505] CHIP:DMG: },
[1679565464.301084][61500:61505] CHIP:DMG:
[1679565464.301103][61500:61505] CHIP:DMG: },
[1679565464.301123][61500:61505] CHIP:DMG:
[1679565464.301138][61500:61505] CHIP:DMG: ],
[1679565464.301195][61500:61505] CHIP:DMG:
[1679565464.301210][61500:61505] CHIP:DMG: SuppressResponse = true,
[1679565464.301225][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565464.301239][61500:61505] CHIP:DMG: }
[1679565464.302027][61500:61505] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1679565464.302083][61500:61505] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1679565464.302103][61500:61505] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1679565464.302123][61500:61505] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1679565464.302138][61500:61505] CHIP:CTL: Arming failsafe (60 seconds)
[1679565464.302180][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565464.302199][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565464.302268][61500:61505] CHIP:EM: <<< [E:45978i M:54907277] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565464.302298][61500:61505] CHIP:IN: (S) Sending msg 54907277 on secure session with LSID: 53795
[1679565464.302362][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565464.392236][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565464.448578][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565464.448784][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565464.448908][61500:61505] CHIP:EM: >>> [E:45978i M:235583079] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565464.448938][61500:61505] CHIP:EM: Found matching exchange: 45978i, Delegate: 0x7f0518045c78
[1679565464.449017][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565464.449060][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565464.449099][61500:61505] CHIP:DMG: {
[1679565464.449141][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565464.449199][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565464.449301][61500:61505] CHIP:DMG: [
[1679565464.449316][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565464.449338][61500:61505] CHIP:DMG: {
[1679565464.449352][61500:61505] CHIP:DMG: CommandDataIB =
[1679565464.449368][61500:61505] CHIP:DMG: {
[1679565464.449384][61500:61505] CHIP:DMG: CommandPathIB =
[1679565464.449430][61500:61505] CHIP:DMG: {
[1679565464.449450][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565464.449471][61500:61505] CHIP:DMG: ClusterId = 0x30,
[1679565464.449489][61500:61505] CHIP:DMG: CommandId = 0x1,
[1679565464.449519][61500:61505] CHIP:DMG: },
[1679565464.449551][61500:61505] CHIP:DMG:
[1679565464.449575][61500:61505] CHIP:DMG: CommandFields =
[1679565464.449596][61500:61505] CHIP:DMG: {
[1679565464.449616][61500:61505] CHIP:DMG: 0x0 = 0,
[1679565464.449637][61500:61505] CHIP:DMG: 0x1 = "" (0 chars),
[1679565464.449656][61500:61505] CHIP:DMG: },
[1679565464.449673][61500:61505] CHIP:DMG: },
[1679565464.449695][61500:61505] CHIP:DMG:
[1679565464.449711][61500:61505] CHIP:DMG: },
[1679565464.449733][61500:61505] CHIP:DMG:
[1679565464.449747][61500:61505] CHIP:DMG: ],
[1679565464.449769][61500:61505] CHIP:DMG:
[1679565464.449784][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565464.449799][61500:61505] CHIP:DMG: },
[1679565464.449862][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1679565464.449909][61500:61505] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1679565464.449932][61500:61505] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1679565464.449948][61500:61505] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1679565464.449963][61500:61505] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1679565464.449982][61500:61505] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1679565464.450028][61500:61505] CHIP:CTL: Setting Regulatory Config
[1679565464.450061][61500:61505] CHIP:CTL: Device does not support configurable regulatory location
[1679565464.450138][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565464.450185][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565464.450299][61500:61505] CHIP:EM: <<< [E:45979i M:54907278] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565464.450331][61500:61505] CHIP:IN: (S) Sending msg 54907278 on secure session with LSID: 53795
[1679565464.450419][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565464.450471][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565464.542245][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565464.598376][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565464.598548][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565464.598715][61500:61505] CHIP:EM: >>> [E:45979i M:235583080] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565464.598746][61500:61505] CHIP:EM: Found matching exchange: 45979i, Delegate: 0x7f0518046038
[1679565464.598782][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565464.598827][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565464.598846][61500:61505] CHIP:DMG: {
[1679565464.598865][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565464.598882][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565464.598927][61500:61505] CHIP:DMG: [
[1679565464.598958][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565464.598982][61500:61505] CHIP:DMG: {
[1679565464.598997][61500:61505] CHIP:DMG: CommandDataIB =
[1679565464.599015][61500:61505] CHIP:DMG: {
[1679565464.599044][61500:61505] CHIP:DMG: CommandPathIB =
[1679565464.599062][61500:61505] CHIP:DMG: {
[1679565464.599081][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565464.599101][61500:61505] CHIP:DMG: ClusterId = 0x30,
[1679565464.599119][61500:61505] CHIP:DMG: CommandId = 0x3,
[1679565464.599136][61500:61505] CHIP:DMG: },
[1679565464.599156][61500:61505] CHIP:DMG:
[1679565464.599173][61500:61505] CHIP:DMG: CommandFields =
[1679565464.599191][61500:61505] CHIP:DMG: {
[1679565464.599209][61500:61505] CHIP:DMG: 0x0 = 0,
[1679565464.599230][61500:61505] CHIP:DMG: 0x1 = "" (0 chars),
[1679565464.599249][61500:61505] CHIP:DMG: },
[1679565464.599265][61500:61505] CHIP:DMG: },
[1679565464.599286][61500:61505] CHIP:DMG:
[1679565464.599302][61500:61505] CHIP:DMG: },
[1679565464.599323][61500:61505] CHIP:DMG:
[1679565464.599338][61500:61505] CHIP:DMG: ],
[1679565464.599360][61500:61505] CHIP:DMG:
[1679565464.599375][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565464.599389][61500:61505] CHIP:DMG: },
[1679565464.599444][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1679565464.599471][61500:61505] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1679565464.599493][61500:61505] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1679565464.599508][61500:61505] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1679565464.599528][61500:61505] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1679565464.599542][61500:61505] CHIP:CTL: Sending request for PAI certificate
[1679565464.599556][61500:61505] CHIP:CTL: Sending Certificate Chain request to 0x7f050c00d610 device
[1679565464.599600][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565464.599636][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565464.599704][61500:61505] CHIP:EM: <<< [E:45980i M:54907279] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565464.599732][61500:61505] CHIP:IN: (S) Sending msg 54907279 on secure session with LSID: 53795
[1679565464.599797][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565464.599878][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565464.692839][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565464.742624][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565464.742788][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565464.848757][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565464.848928][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565464.948735][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565464.948957][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565464.949066][61500:61505] CHIP:EM: >>> [E:45980i M:235583081] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565464.949096][61500:61505] CHIP:EM: Found matching exchange: 45980i, Delegate: 0x7f0518045c78
[1679565464.949126][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565464.949167][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565464.949193][61500:61505] CHIP:DMG: {
[1679565464.949212][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565464.949231][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565464.949260][61500:61505] CHIP:DMG: [
[1679565464.949273][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565464.949300][61500:61505] CHIP:DMG: {
[1679565464.949318][61500:61505] CHIP:DMG: CommandDataIB =
[1679565464.949341][61500:61505] CHIP:DMG: {
[1679565464.949359][61500:61505] CHIP:DMG: CommandPathIB =
[1679565464.949383][61500:61505] CHIP:DMG: {
[1679565464.949402][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565464.949420][61500:61505] CHIP:DMG: ClusterId = 0x3e,
[1679565464.949438][61500:61505] CHIP:DMG: CommandId = 0x3,
[1679565464.949455][61500:61505] CHIP:DMG: },
[1679565464.949486][61500:61505] CHIP:DMG:
[1679565464.949503][61500:61505] CHIP:DMG: CommandFields =
[1679565464.949520][61500:61505] CHIP:DMG: {
[1679565464.949539][61500:61505] CHIP:DMG: 0x0 = [
[1679565464.949644][61500:61505] CHIP:DMG: 0x30, 0x82, 0x1, 0xcb, 0x30, 0x82, 0x1, 0x71, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0xf, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0xc, 0x8c, 0x87, 0x6d, 0x3, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x5, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x9, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0xb, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x6, 0x3, 0x55, 0x1d, 0x13, 0x1, 0x1, 0xff, 0x4, 0x8, 0x30, 0x6, 0x1, 0x1, 0xff, 0x2, 0x1,
[1679565464.949706][61500:61505] CHIP:DMG: ] (463 bytes)
[1679565464.949724][61500:61505] CHIP:DMG: },
[1679565464.949740][61500:61505] CHIP:DMG: },
[1679565464.949763][61500:61505] CHIP:DMG:
[1679565464.949778][61500:61505] CHIP:DMG: },
[1679565464.949799][61500:61505] CHIP:DMG:
[1679565464.949813][61500:61505] CHIP:DMG: ],
[1679565464.949840][61500:61505] CHIP:DMG:
[1679565464.949859][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565464.949872][61500:61505] CHIP:DMG: },
[1679565464.949929][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1679565464.949971][61500:61505] CHIP:CTL: Received certificate chain from the device
[1679565464.949993][61500:61505] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1679565464.950011][61500:61505] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1679565464.950063][61500:61505] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1679565464.950089][61500:61505] CHIP:CTL: Sending request for DAC certificate
[1679565464.950103][61500:61505] CHIP:CTL: Sending Certificate Chain request to 0x7f050c00d610 device
[1679565464.950146][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565464.950166][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565464.950232][61500:61505] CHIP:EM: <<< [E:45981i M:54907280] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565464.950260][61500:61505] CHIP:IN: (S) Sending msg 54907280 on secure session with LSID: 53795
[1679565464.950323][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565464.950418][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565465.042020][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565465.093057][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565465.093241][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565465.198781][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565465.198946][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565465.348014][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565465.348174][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565465.348294][61500:61505] CHIP:EM: >>> [E:45981i M:235583082] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565465.348323][61500:61505] CHIP:EM: Found matching exchange: 45981i, Delegate: 0x7f0518046038
[1679565465.348351][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565465.348390][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565465.348411][61500:61505] CHIP:DMG: {
[1679565465.348426][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565465.348442][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565465.348466][61500:61505] CHIP:DMG: [
[1679565465.348480][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565465.348501][61500:61505] CHIP:DMG: {
[1679565465.348517][61500:61505] CHIP:DMG: CommandDataIB =
[1679565465.348536][61500:61505] CHIP:DMG: {
[1679565465.348552][61500:61505] CHIP:DMG: CommandPathIB =
[1679565465.348569][61500:61505] CHIP:DMG: {
[1679565465.348591][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565465.348610][61500:61505] CHIP:DMG: ClusterId = 0x3e,
[1679565465.348627][61500:61505] CHIP:DMG: CommandId = 0x3,
[1679565465.348646][61500:61505] CHIP:DMG: },
[1679565465.348692][61500:61505] CHIP:DMG:
[1679565465.348710][61500:61505] CHIP:DMG: CommandFields =
[1679565465.348728][61500:61505] CHIP:DMG: {
[1679565465.348750][61500:61505] CHIP:DMG: 0x0 = [
[1679565465.348857][61500:61505] CHIP:DMG: 0x30, 0x82, 0x1, 0xe8, 0x30, 0x82, 0x1, 0x8e, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x3d, 0xc4, 0xfb, 0x5c, 0x8e, 0x4d, 0x26, 0x46, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x41, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x2, 0xc, 0x4, 0x38, 0x30, 0x30, 0x41, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x5f, 0x37, 0x84, 0xbd, 0x6c, 0xbf, 0xb9, 0x2c, 0xee, 0xf9, 0xf8, 0x44, 0x35, 0x4e, 0x4a, 0xfe, 0x4, 0xbe, 0x20, 0x7, 0x16, 0x1d, 0x1, 0x46, 0x72, 0xc8, 0x69, 0xa7, 0x21, 0xb8, 0x35, 0xec, 0xf5, 0xd1, 0x15, 0x4d, 0xc7, 0x7b, 0xb9, 0x65, 0xdf, 0x3c, 0xc2, 0x7b, 0x57, 0xb4, 0xbb, 0x5c, 0xe7, 0xd7, 0xde, 0
[1679565465.348917][61500:61505] CHIP:DMG: ] (492 bytes)
[1679565465.348936][61500:61505] CHIP:DMG: },
[1679565465.348952][61500:61505] CHIP:DMG: },
[1679565465.348974][61500:61505] CHIP:DMG:
[1679565465.348990][61500:61505] CHIP:DMG: },
[1679565465.349010][61500:61505] CHIP:DMG:
[1679565465.349024][61500:61505] CHIP:DMG: ],
[1679565465.349046][61500:61505] CHIP:DMG:
[1679565465.349061][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565465.349076][61500:61505] CHIP:DMG: },
[1679565465.349132][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1679565465.349158][61500:61505] CHIP:CTL: Received certificate chain from the device
[1679565465.349179][61500:61505] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1679565465.349199][61500:61505] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1679565465.349218][61500:61505] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1679565465.349233][61500:61505] CHIP:CTL: Sending Attestation Request to the device.
[1679565465.349248][61500:61505] CHIP:CTL: Sending Attestation request to 0x7f050c00d610 device
[1679565465.349292][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565465.349333][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565465.349401][61500:61505] CHIP:EM: <<< [E:45982i M:54907281] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565465.349431][61500:61505] CHIP:IN: (S) Sending msg 54907281 on secure session with LSID: 53795
[1679565465.349494][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565465.349516][61500:61505] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1679565465.349554][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565465.441901][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565465.548619][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565465.548757][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565465.648474][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565465.648667][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565465.748794][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565465.748960][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565465.749080][61500:61505] CHIP:EM: >>> [E:45982i M:235583083] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565465.749108][61500:61505] CHIP:EM: Found matching exchange: 45982i, Delegate: 0x7f0518045c78
[1679565465.749136][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565465.749188][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565465.749205][61500:61505] CHIP:DMG: {
[1679565465.749222][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565465.749292][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565465.749319][61500:61505] CHIP:DMG: [
[1679565465.749334][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565465.749360][61500:61505] CHIP:DMG: {
[1679565465.749376][61500:61505] CHIP:DMG: CommandDataIB =
[1679565465.749392][61500:61505] CHIP:DMG: {
[1679565465.749406][61500:61505] CHIP:DMG: CommandPathIB =
[1679565465.749423][61500:61505] CHIP:DMG: {
[1679565465.749440][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565465.749458][61500:61505] CHIP:DMG: ClusterId = 0x3e,
[1679565465.749477][61500:61505] CHIP:DMG: CommandId = 0x1,
[1679565465.749495][61500:61505] CHIP:DMG: },
[1679565465.749514][61500:61505] CHIP:DMG:
[1679565465.749532][61500:61505] CHIP:DMG: CommandFields =
[1679565465.749550][61500:61505] CHIP:DMG: {
[1679565465.749588][61500:61505] CHIP:DMG: 0x0 = [
[1679565465.749696][61500:61505] CHIP:DMG: 0x15, 0x31, 0x1, 0x1b, 0x2, 0x30, 0x82, 0x2, 0x17, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x2, 0xa0, 0x82, 0x2, 0x8, 0x30, 0x82, 0x2, 0x4, 0x2, 0x1, 0x3, 0x31, 0xd, 0x30, 0xb, 0x6, 0x9, 0x60, 0x86, 0x48, 0x1, 0x65, 0x3, 0x4, 0x2, 0x1, 0x30, 0x82, 0x1, 0x70, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x1, 0xa0, 0x82, 0x1, 0x61, 0x4, 0x82, 0x1, 0x5d, 0x15, 0x24, 0x0, 0x1, 0x25, 0x1, 0xf1, 0xff, 0x36, 0x2, 0x5, 0x0, 0x80, 0x5, 0x1, 0x80, 0x5, 0x2, 0x80, 0x5, 0x3, 0x80, 0x5, 0x4, 0x80, 0x5, 0x5, 0x80, 0x5, 0x6, 0x80, 0x5, 0x7, 0x80, 0x5, 0x8, 0x80, 0x5, 0x9, 0x80, 0x5, 0xa, 0x80, 0x5, 0xb, 0x80, 0x5, 0xc, 0x80, 0x5, 0xd, 0x80, 0x5, 0xe, 0x80, 0x5, 0xf, 0x80, 0x5, 0x10, 0x80, 0x5, 0x11, 0x80, 0x5, 0x12, 0x80, 0x5, 0x13, 0x80, 0x5, 0x14, 0x80, 0x5, 0x15, 0x80, 0x5, 0x16, 0x80, 0x5, 0x17, 0x80, 0x5, 0x18, 0x80, 0x5, 0x19, 0x80, 0x5, 0x1a, 0x80, 0x5, 0x1b, 0x80, 0x5, 0x1c, 0x80, 0x5, 0x1d, 0x80, 0x5, 0x1e, 0x80, 0x5, 0x1f, 0x80, 0x5, 0x20, 0x80, 0x5, 0x21, 0x80, 0x5, 0x22, 0x80, 0x5, 0x23, 0x80, 0x5, 0x24, 0x80, 0x5, 0x25, 0x80, 0x5, 0x26, 0x80, 0x5, 0x27, 0x80, 0x5, 0x28, 0x80, 0x5, 0x29, 0x80, 0x5, 0x2a, 0x80, 0x5, 0x2b, 0x80, 0x5, 0x2c, 0x80, 0x5, 0x2d, 0x80, 0x5, 0x2e, 0x80, 0x5, 0x2f, 0x80, 0x5, 0x30, 0x80, 0x5, 0x31, 0x80, 0x5, 0x32, 0x80, 0x5, 0x33, 0x80, 0x5, 0x34, 0x80, 0x5, 0x35, 0x80, 0x5, 0x36, 0x80, 0x5, 0x37, 0x80, 0x5, 0x38, 0x80, 0x5, 0x39, 0x80, 0x5, 0x3a, 0x80, 0x5, 0x3b, 0x80, 0x5, 0x3c, 0x80, 0x5, 0x3d, 0x80, 0x5, 0x3e, 0x80, 0x5, 0x3f, 0x80, 0x5, 0x40, 0x80, 0x5, 0x41, 0x80, 0x5, 0x42, 0x80, 0x5, 0x43, 0x80, 0x5, 0x44, 0x80, 0x5, 0x45, 0x80, 0x5, 0x46, 0x80, 0x5, 0x47, 0x80, 0x5, 0x48, 0x80, 0x5, 0x49, 0x80, 0x5, 0x4a, 0x80, 0x5, 0
[1679565465.749756][61500:61505] CHIP:DMG: ] (583 bytes)
[1679565465.749774][61500:61505] CHIP:DMG: 0x1 = [
[1679565465.749808][61500:61505] CHIP:DMG: 0x82, 0x3d, 0x2a, 0x32, 0x30, 0x25, 0x1, 0x47, 0x7f, 0x73, 0x43, 0xa1, 0x97, 0xb4, 0xc9, 0x3e, 0xce, 0x87, 0xcf, 0xa, 0xe8, 0xd2, 0xb6, 0xc4, 0x19, 0xcc, 0xbb, 0x9b, 0xa3, 0x5, 0xb5, 0xd, 0xcf, 0x21, 0x8d, 0xa8, 0x1, 0x1d, 0xb0, 0xd5, 0xa4, 0xf5, 0xb6, 0xfe, 0x7f, 0xa5, 0x99, 0x60, 0x32, 0x7a, 0x58, 0x40, 0x88, 0x13, 0x31, 0xa7, 0x5e, 0xcd, 0x9e, 0x5d, 0x25, 0x2, 0x45, 0x73,
[1679565465.749835][61500:61505] CHIP:DMG: ] (64 bytes)
[1679565465.749854][61500:61505] CHIP:DMG: },
[1679565465.749870][61500:61505] CHIP:DMG: },
[1679565465.749893][61500:61505] CHIP:DMG:
[1679565465.749908][61500:61505] CHIP:DMG: },
[1679565465.749931][61500:61505] CHIP:DMG:
[1679565465.749944][61500:61505] CHIP:DMG: ],
[1679565465.749967][61500:61505] CHIP:DMG:
[1679565465.749981][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565465.749996][61500:61505] CHIP:DMG: },
[1679565465.750052][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1679565465.750079][61500:61505] CHIP:CTL: Received Attestation Information from the device
[1679565465.750102][61500:61505] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1679565465.750119][61500:61505] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583
[1679565465.750157][61500:61505] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1679565465.750178][61500:61505] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1679565465.750195][61500:61505] CHIP:CTL: Verifying attestation
[1679565465.771377][61500:61505] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1679565465.771431][61500:61505] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification'
[1679565465.771439][61500:61505] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
[1679565465.771468][61500:61505] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest'
[1679565465.771477][61500:61505] CHIP:CTL: Sending CSR request to 0x7f050c00d610 device
[1679565465.771546][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565465.771567][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565465.771675][61500:61505] CHIP:EM: <<< [E:45983i M:54907282] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565465.771687][61500:61505] CHIP:IN: (S) Sending msg 54907282 on secure session with LSID: 53795
[1679565465.771776][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565465.771809][61500:61505] CHIP:CTL: Sent CSR request, waiting for the CSR
[1679565465.771828][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565465.841795][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565467.097173][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565467.097317][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565467.197813][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565467.198052][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565467.198233][61500:61505] CHIP:EM: >>> [E:45983i M:235583084] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565467.198265][61500:61505] CHIP:EM: Found matching exchange: 45983i, Delegate: 0x7f0518046038
[1679565467.198295][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565467.198338][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565467.198357][61500:61505] CHIP:DMG: {
[1679565467.198372][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565467.198386][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565467.198408][61500:61505] CHIP:DMG: [
[1679565467.198423][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565467.198452][61500:61505] CHIP:DMG: {
[1679565467.198468][61500:61505] CHIP:DMG: CommandDataIB =
[1679565467.198485][61500:61505] CHIP:DMG: {
[1679565467.198500][61500:61505] CHIP:DMG: CommandPathIB =
[1679565467.198519][61500:61505] CHIP:DMG: {
[1679565467.198537][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565467.198558][61500:61505] CHIP:DMG: ClusterId = 0x3e,
[1679565467.198579][61500:61505] CHIP:DMG: CommandId = 0x5,
[1679565467.198616][61500:61505] CHIP:DMG: },
[1679565467.198682][61500:61505] CHIP:DMG:
[1679565467.198700][61500:61505] CHIP:DMG: CommandFields =
[1679565467.198717][61500:61505] CHIP:DMG: {
[1679565467.198736][61500:61505] CHIP:DMG: 0x0 = [
[1679565467.198820][61500:61505] CHIP:DMG: 0x15, 0x30, 0x1, 0xcc, 0x30, 0x81, 0xc9, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0xf2, 0xfc, 0xe9, 0x17, 0x1f, 0x43, 0x62, 0x32, 0xd8, 0xcf, 0x34, 0xf7, 0x89, 0x5f, 0x14, 0x90, 0x94, 0xe1, 0xb1, 0xa4, 0xc3, 0x24, 0xf3, 0x8d, 0xe1, 0x74, 0x7c, 0x47, 0xde, 0x88, 0x66, 0x42, 0x65, 0xf6, 0xbc, 0xb1, 0x18, 0x6e, 0x82, 0x1b, 0xfa, 0xdf, 0xee, 0xa9, 0xbb, 0xe7, 0xd3, 0xaf, 0x91, 0x3f, 0x9a, 0xb9, 0x15, 0x56, 0x2, 0x19, 0x8d, 0x25, 0xca, 0x8b, 0x43, 0x8c, 0x8f, 0xcd, 0xa0, 0x0, 0x30, 0xc, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x5, 0x0, 0x3, 0x47, 0x0, 0x30, 0x44, 0x2, 0x20, 0x64, 0xb8, 0xb8, 0x2f, 0x86, 0x6d, 0x7c, 0x3c, 0x7, 0x9d, 0xe5, 0xd5, 0xd6, 0x35, 0x8, 0xa2, 0x81, 0x65, 0xa3, 0x25, 0x87, 0x43, 0xc8, 0x41, 0xef, 0xc7, 0x7, 0x9f, 0x9f, 0x6b, 0x16, 0xc5, 0x2, 0x20, 0x41, 0xe8, 0x45, 0xe2, 0x59, 0x19, 0x93, 0xf, 0xe1, 0x24, 0x13, 0x6c, 0xe1, 0xb0, 0x7c, 0x1f, 0x3e, 0x50, 0xf2, 0xfd, 0x22, 0x2d, 0x91, 0x89, 0xe3, 0xfa, 0x25, 0xb4, 0x65, 0xf1, 0x7d, 0x52, 0x30, 0x2, 0x20, 0x34, 0xf8, 0xd4, 0x49, 0x8c, 0x3f, 0x7d, 0x6f, 0x6e, 0xe5, 0x85, 0x4e, 0xa6, 0xd6, 0xc1, 0xab, 0x17, 0x8c, 0xa8, 0xc6, 0xa, 0x41, 0x89, 0xa7, 0x7, 0xeb, 0xe4, 0x1a, 0x79, 0xdc, 0x72, 0xce, 0x18,
[1679565467.198873][61500:61505] CHIP:DMG: ] (244 bytes)
[1679565467.198892][61500:61505] CHIP:DMG: 0x1 = [
[1679565467.198926][61500:61505] CHIP:DMG: 0x9a, 0xbf, 0xbf, 0xe6, 0x98, 0xe3, 0x86, 0xf3, 0xb2, 0x3f, 0x9f, 0xd9, 0xba, 0xb8, 0x4a, 0x77, 0xc9, 0x18, 0x5e, 0x4f, 0x9d, 0x9e, 0xfb, 0xf8, 0x36, 0x1b, 0x46, 0xb2, 0x5d, 0x0, 0x86, 0xd6, 0x76, 0xd7, 0x2c, 0xe5, 0x8e, 0x20, 0xe5, 0x90, 0x92, 0xcd, 0xaa, 0xc2, 0xe, 0x2e, 0xb0, 0xf1, 0xb4, 0x47, 0x31, 0x31, 0x3f, 0x4e, 0xee, 0xbf, 0x53, 0xde, 0x52, 0x38, 0x57, 0x82, 0x78, 0x90,
[1679565467.198956][61500:61505] CHIP:DMG: ] (64 bytes)
[1679565467.198974][61500:61505] CHIP:DMG: },
[1679565467.198991][61500:61505] CHIP:DMG: },
[1679565467.199013][61500:61505] CHIP:DMG:
[1679565467.199029][61500:61505] CHIP:DMG: },
[1679565467.199052][61500:61505] CHIP:DMG:
[1679565467.199067][61500:61505] CHIP:DMG: ],
[1679565467.199091][61500:61505] CHIP:DMG:
[1679565467.199106][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565467.199121][61500:61505] CHIP:DMG: },
[1679565467.199191][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1679565467.199219][61500:61505] CHIP:CTL: Received certificate signing request from the device
[1679565467.199242][61500:61505] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
[1679565467.199258][61500:61505] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[1679565467.199278][61500:61505] CHIP:CTL: Performing next commissioning step 'ValidateCSR'
[1679565467.204341][61500:61505] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR'
[1679565467.204369][61500:61505] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[1679565467.204388][61500:61505] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain'
[1679565467.204403][61500:61505] CHIP:CTL: Getting certificate chain for the device from the issuer
[1679565467.208625][61500:61505] CHIP:CTL: Verifying Certificate Signing Request
[1679565467.210905][61500:61505] CHIP:CTL: Generating NOC
[1679565467.211160][61500:61505] CHIP:CTL: Providing certificate chain to the commissioner
[1679565467.211185][61500:61505] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../examples/chip-tool/third_party/connectedhomeip/src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success
[1679565467.211205][61500:61505] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain'
[1679565467.211352][61500:61505] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert'
[1679565467.211368][61500:61505] CHIP:CTL: Sending root certificate to the device
[1679565467.211449][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565467.211471][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565467.211548][61500:61505] CHIP:EM: <<< [E:45984i M:54907283] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565467.211579][61500:61505] CHIP:IN: (S) Sending msg 54907283 on secure session with LSID: 53795
[1679565467.211650][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565467.211680][61500:61505] CHIP:CTL: Sent root certificate to the device
[1679565467.212004][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565467.341153][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565467.441083][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565467.647661][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565467.647862][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565467.648011][61500:61505] CHIP:EM: >>> [E:45984i M:235583085] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565467.648040][61500:61505] CHIP:EM: Found matching exchange: 45984i, Delegate: 0x7f0518045c78
[1679565467.648066][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565467.648104][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565467.648120][61500:61505] CHIP:DMG: {
[1679565467.648134][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565467.648147][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565467.648168][61500:61505] CHIP:DMG: [
[1679565467.648183][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565467.648204][61500:61505] CHIP:DMG: {
[1679565467.648220][61500:61505] CHIP:DMG: CommandStatusIB =
[1679565467.648237][61500:61505] CHIP:DMG: {
[1679565467.648253][61500:61505] CHIP:DMG: CommandPathIB =
[1679565467.648280][61500:61505] CHIP:DMG: {
[1679565467.648300][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565467.648320][61500:61505] CHIP:DMG: ClusterId = 0x3e,
[1679565467.648336][61500:61505] CHIP:DMG: CommandId = 0xb,
[1679565467.648354][61500:61505] CHIP:DMG: },
[1679565467.648377][61500:61505] CHIP:DMG:
[1679565467.648391][61500:61505] CHIP:DMG: StatusIB =
[1679565467.648411][61500:61505] CHIP:DMG: {
[1679565467.648429][61500:61505] CHIP:DMG: status = 0x00 (SUCCESS),
[1679565467.648449][61500:61505] CHIP:DMG: },
[1679565467.648474][61500:61505] CHIP:DMG:
[1679565467.648491][61500:61505] CHIP:DMG: },
[1679565467.648512][61500:61505] CHIP:DMG:
[1679565467.648526][61500:61505] CHIP:DMG: },
[1679565467.648548][61500:61505] CHIP:DMG:
[1679565467.648563][61500:61505] CHIP:DMG: ],
[1679565467.648584][61500:61505] CHIP:DMG:
[1679565467.648599][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565467.648619][61500:61505] CHIP:DMG: },
[1679565467.648671][61500:61505] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1679565467.648692][61500:61505] CHIP:CTL: Device confirmed that it has received the root certificate
[1679565467.648714][61500:61505] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert'
[1679565467.648730][61500:61505] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[1679565467.648749][61500:61505] CHIP:CTL: Performing next commissioning step 'SendNOC'
[1679565467.648802][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565467.648826][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565467.648894][61500:61505] CHIP:EM: <<< [E:45985i M:54907284] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565467.648923][61500:61505] CHIP:IN: (S) Sending msg 54907284 on secure session with LSID: 53795
[1679565467.648985][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565467.649008][61500:61505] CHIP:CTL: Sent operational certificate to the device
[1679565467.649045][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565467.840891][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565467.990858][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565468.090794][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565468.597251][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565468.597404][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565468.597564][61500:61505] CHIP:EM: >>> [E:45985i M:235583086] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565468.597597][61500:61505] CHIP:EM: Found matching exchange: 45985i, Delegate: 0x7f0518046038
[1679565468.597622][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565468.597666][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565468.597683][61500:61505] CHIP:DMG: {
[1679565468.597698][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565468.597711][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565468.597732][61500:61505] CHIP:DMG: [
[1679565468.597747][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565468.597771][61500:61505] CHIP:DMG: {
[1679565468.597785][61500:61505] CHIP:DMG: CommandDataIB =
[1679565468.597801][61500:61505] CHIP:DMG: {
[1679565468.597815][61500:61505] CHIP:DMG: CommandPathIB =
[1679565468.597832][61500:61505] CHIP:DMG: {
[1679565468.597849][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565468.597870][61500:61505] CHIP:DMG: ClusterId = 0x3e,
[1679565468.597892][61500:61505] CHIP:DMG: CommandId = 0x8,
[1679565468.597913][61500:61505] CHIP:DMG: },
[1679565468.597933][61500:61505] CHIP:DMG:
[1679565468.597948][61500:61505] CHIP:DMG: CommandFields =
[1679565468.597965][61500:61505] CHIP:DMG: {
[1679565468.597982][61500:61505] CHIP:DMG: 0x0 = 0,
[1679565468.598000][61500:61505] CHIP:DMG: 0x1 = 1,
[1679565468.598020][61500:61505] CHIP:DMG: },
[1679565468.598036][61500:61505] CHIP:DMG: },
[1679565468.598059][61500:61505] CHIP:DMG:
[1679565468.598074][61500:61505] CHIP:DMG: },
[1679565468.598096][61500:61505] CHIP:DMG:
[1679565468.598110][61500:61505] CHIP:DMG: ],
[1679565468.598133][61500:61505] CHIP:DMG:
[1679565468.598147][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565468.598161][61500:61505] CHIP:DMG: },
[1679565468.598218][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1679565468.598246][61500:61505] CHIP:CTL: Device returned status 0 on receiving the NOC
[1679565468.598262][61500:61505] CHIP:CTL: Operational credentials provisioned on device 0x7f050c00d610
[1679565468.598278][61500:61505] CHIP:TOO: Secure Pairing Success
[1679565468.598291][61500:61505] CHIP:TOO: CASE establishment successful
[1679565468.598312][61500:61505] CHIP:CTL: Successfully finished commissioning step 'SendNOC'
[1679565468.598329][61500:61505] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup'
[1679565468.598349][61500:61505] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup'
[1679565468.598401][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565468.598424][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565468.598490][61500:61505] CHIP:EM: <<< [E:45986i M:54907285] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565468.598520][61500:61505] CHIP:IN: (S) Sending msg 54907285 on secure session with LSID: 53795
[1679565468.598588][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565468.598660][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565468.740420][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565468.790984][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565468.791125][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565468.791300][61500:61505] CHIP:EM: >>> [E:45986i M:235583087] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565468.791332][61500:61505] CHIP:EM: Found matching exchange: 45986i, Delegate: 0x7f0518045c78
[1679565468.791358][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565468.791397][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565468.791415][61500:61505] CHIP:DMG: {
[1679565468.791429][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565468.791443][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565468.791465][61500:61505] CHIP:DMG: [
[1679565468.791480][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565468.791504][61500:61505] CHIP:DMG: {
[1679565468.791597][61500:61505] CHIP:DMG: CommandDataIB =
[1679565468.791631][61500:61505] CHIP:DMG: {
[1679565468.791727][61500:61505] CHIP:DMG: CommandPathIB =
[1679565468.791836][61500:61505] CHIP:DMG: {
[1679565468.791935][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565468.792044][61500:61505] CHIP:DMG: ClusterId = 0x31,
[1679565468.792162][61500:61505] CHIP:DMG: CommandId = 0x5,
[1679565468.792284][61500:61505] CHIP:DMG: },
[1679565468.792371][61500:61505] CHIP:DMG:
[1679565468.792388][61500:61505] CHIP:DMG: CommandFields =
[1679565468.792498][61500:61505] CHIP:DMG: {
[1679565468.792629][61500:61505] CHIP:DMG: 0x0 = 0,
[1679565468.792897][61500:61505] CHIP:DMG: 0x2 = 0,
[1679565468.793151][61500:61505] CHIP:DMG: },
[1679565468.793181][61500:61505] CHIP:DMG: },
[1679565468.793229][61500:61505] CHIP:DMG:
[1679565468.793263][61500:61505] CHIP:DMG: },
[1679565468.793289][61500:61505] CHIP:DMG:
[1679565468.793306][61500:61505] CHIP:DMG: ],
[1679565468.793331][61500:61505] CHIP:DMG:
[1679565468.793349][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565468.793363][61500:61505] CHIP:DMG: },
[1679565468.793433][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1679565468.794070][61500:61505] CHIP:CTL: Received NetworkConfig response, networkingStatus=0
[1679565468.794160][61500:61505] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkSetup'
[1679565468.794179][61500:61505] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'ThreadNetworkEnable'
[1679565468.794203][61500:61505] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable'
[1679565468.794264][61500:61505] CHIP:DMG: ICR moving to [AddingComm]
[1679565468.794288][61500:61505] CHIP:DMG: ICR moving to [AddedComma]
[1679565468.794390][61500:61505] CHIP:EM: <<< [E:45987i M:54907286] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1679565468.794423][61500:61505] CHIP:IN: (S) Sending msg 54907286 on secure session with LSID: 53795
[1679565468.794513][61500:61505] CHIP:DMG: ICR moving to [CommandSen]
[1679565468.794567][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565469.440196][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565470.146855][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565470.147027][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565470.147168][61500:61505] CHIP:EM: >>> [E:45987i M:235583088] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1679565470.147201][61500:61505] CHIP:EM: Found matching exchange: 45987i, Delegate: 0x7f0518046038
[1679565470.147270][61500:61505] CHIP:DMG: ICR moving to [ResponseRe]
[1679565470.147311][61500:61505] CHIP:DMG: InvokeResponseMessage =
[1679565470.147330][61500:61505] CHIP:DMG: {
[1679565470.147345][61500:61505] CHIP:DMG: suppressResponse = false,
[1679565470.147361][61500:61505] CHIP:DMG: InvokeResponseIBs =
[1679565470.147385][61500:61505] CHIP:DMG: [
[1679565470.147401][61500:61505] CHIP:DMG: InvokeResponseIB =
[1679565470.147424][61500:61505] CHIP:DMG: {
[1679565470.147440][61500:61505] CHIP:DMG: CommandDataIB =
[1679565470.147457][61500:61505] CHIP:DMG: {
[1679565470.147474][61500:61505] CHIP:DMG: CommandPathIB =
[1679565470.147492][61500:61505] CHIP:DMG: {
[1679565470.147512][61500:61505] CHIP:DMG: EndpointId = 0x0,
[1679565470.147535][61500:61505] CHIP:DMG: ClusterId = 0x31,
[1679565470.147554][61500:61505] CHIP:DMG: CommandId = 0x7,
[1679565470.147572][61500:61505] CHIP:DMG: },
[1679565470.147590][61500:61505] CHIP:DMG:
[1679565470.147607][61500:61505] CHIP:DMG: CommandFields =
[1679565470.147626][61500:61505] CHIP:DMG: {
[1679565470.147647][61500:61505] CHIP:DMG: 0x0 = 0,
[1679565470.147667][61500:61505] CHIP:DMG: 0x2 = NULL
[1679565470.147685][61500:61505] CHIP:DMG: },
[1679565470.147702][61500:61505] CHIP:DMG: },
[1679565470.147723][61500:61505] CHIP:DMG:
[1679565470.147739][61500:61505] CHIP:DMG: },
[1679565470.147759][61500:61505] CHIP:DMG:
[1679565470.147774][61500:61505] CHIP:DMG: ],
[1679565470.147797][61500:61505] CHIP:DMG:
[1679565470.147813][61500:61505] CHIP:DMG: InteractionModelRevision = 1
[1679565470.147827][61500:61505] CHIP:DMG: },
[1679565470.147882][61500:61505] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1679565470.147909][61500:61505] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1679565470.147931][61500:61505] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable'
[1679565470.147947][61500:61505] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational'
[1679565470.147967][61500:61505] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1679565470.147982][61500:61505] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000003039]
[1679565470.147998][61500:61505] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1679565470.148021][61500:61505] CHIP:CTL: OperationalSessionSetup[1:0000000000003039]: State change 1 --> 2
[1679565470.148242][61500:61505] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp3s0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000063: Cannot assign requested address
[1679565470.148955][61500:61505] CHIP:DIS: mDNS broadcast had only partial success: 9 successes and 1 failures.
[1679565470.149073][61500:61505] CHIP:DMG: ICR moving to [AwaitingDe]
[1679565470.349082][61500:61505] CHIP:DIS: Checking node lookup status after 201 ms
[1679565471.149284][61500:61505] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp3s0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000063: Cannot assign requested address
[1679565471.150177][61500:61505] CHIP:DIS: mDNS broadcast had only partial success: 7 successes and 1 failures.
[1679565473.150370][61500:61505] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp3s0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000063: Cannot assign requested address
[1679565473.151306][61500:61505] CHIP:DIS: mDNS broadcast had only partial success: 7 successes and 1 failures.
[1679565473.788325][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565477.150987][61500:61505] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp3s0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000063: Cannot assign requested address
[1679565477.151981][61500:61505] CHIP:DIS: mDNS broadcast had only partial success: 7 successes and 1 failures.
[1679565477.442364][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565477.442582][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565480.985090][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1679565484.588901][61500:61503] CHIP:DL: Indication received, conn = 0x7f05180449e0
[1679565484.589112][61500:61505] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1679565485.148944][61500:61505] CHIP:DIS: Checking node lookup status after 15001 ms
[1679565485.148999][61500:61505] CHIP:DIS: OperationalSessionSetup[1:0000000000003039]: operational discovery failed: ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
[1679565485.149023][61500:61505] CHIP:CTL: Device connection failed. Error ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
[1679565485.149050][61500:61505] CHIP:CTL: Error on commissioning step 'FindOperational': '../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
[1679565485.149067][61500:61505] CHIP:CTL: Failed to perform commissioning step 18
[1679565485.149085][61500:61505] CHIP:CTL: Going from commissioning step 'FindOperational' with lastErr = '../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
[1679565485.149113][61500:61505] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout'
[1679565485.149131][61500:61505] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1679565485.149152][61500:61505] CHIP:TOO: Device commissioning Failure: ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout
[1679565485.149620][61500:61500] CHIP:CTL: Shutting down the commissioner
[1679565485.149654][61500:61500] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1679565485.149727][61500:61500] CHIP:DIS: Closing all BLE connections
[1679565485.149746][61500:61500] CHIP:IN: Clearing BLE pending packets.
[1679565485.149793][61500:61500] CHIP:BLE: Auto-closing end point's BLE connection.
[1679565485.149808][61500:61500] CHIP:DL: Closing BLE GATT connection (con 0x7f05180449e0)
[1679565485.149837][61500:61500] CHIP:IN: SecureSession[0x7f050c00acb0]: MarkForEviction Type:1 LSID:53795
[1679565485.149852][61500:61500] CHIP:SC: SecureSession[0x7f050c00acb0]: Moving from state 'kActive' --> 'kPendingEviction'
[1679565485.149922][61500:61500] CHIP:IN: SecureSession[0x7f050c00acb0]: Released - Type:1 LSID:53795
[1679565485.149946][61500:61500] CHIP:CTL: Shutting down the controller
[1679565485.149963][61500:61500] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1679565485.149976][61500:61500] CHIP:FP: Forgetting fabric 0x1
[1679565485.149998][61500:61500] CHIP:TS: Pending Last Known Good Time: 2023-03-02T09:12:42
[1679565485.150044][61500:61503] CHIP:DL: BluezDisconnect peer=49:07:53:EF:D7:10
[1679565485.150153][61500:61500] CHIP:TS: Previous Last Known Good Time: 2023-03-02T09:12:42
[1679565485.150182][61500:61500] CHIP:TS: Reverted Last Known Good Time to previous value
[1679565485.150257][61500:61500] CHIP:CTL: Shutting down the commissioner
[1679565485.150734][61500:61500] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1679565485.150818][61500:61500] CHIP:CTL: Shutting down the controller
[1679565485.150855][61500:61500] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1679565485.152242][61500:61500] CHIP:DMG: IM WH moving to [Uninitialized]
[1679565485.152272][61500:61500] CHIP:DMG: IM WH moving to [Uninitialized]
[1679565485.152284][61500:61500] CHIP:DMG: IM WH moving to [Uninitialized]
[1679565485.152296][61500:61500] CHIP:DMG: IM WH moving to [Uninitialized]
[1679565485.152310][61500:61500] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1679565485.152356][61500:61500] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1679565485.152612][61500:61500] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-CnqMrG)
[1679565485.153002][61500:61500] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1679565485.153049][61500:61500] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1679565485.153068][61500:61500] CHIP:DL: Inet Layer shutdown
[1679565485.153083][61500:61500] CHIP:DL: BLE shutdown
[1679565485.153969][61500:61500] CHIP:DL: System Layer shutdown
[1679565485.154033][61500:61500] CHIP:TOO: Run command failure: ../examples/chip-tool/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:174: CHIP Error 0x00000032: Timeout

0 Ryan Brown1 over 2 years ago in reply to Logan Becker

TI__Guru**** 218837 points

Hi Logan,

I am using a BLE 4.0 dongle on my Linux machine and not experiencing similar issues, so I do not believe the variance of BLE Specification is an issue. Have you confirmed that your Linux machine is using the Ethernet connection, instead of defaulting to the pre-existing Wi-Fi interface? Your OpenThread credentials should be correct given that the network has been setup, enabled, and communication with an operational device has begun.

Which matter repo are you using, TI's or connectedhomeip? I would recommend using TI's and pulling from the latest master branch. Using recursive submodules is highly recommended, i.e. "git clone --recurse-submodules https://github.com/TexasInstruments/matter.git"

Here is an online version of the Matter Specification, focusing on Section 2.8. The commissioning process gets pretty far before failing, completing steps 1 through 5. What fails is the second to last step, Security setup with CASE. There is no mention of Sigmas inside your logs like with my setup, which is why I am requesting an update to your repository. You could search for relevant Git issues and perhaps even post a new issue to determine whether there are any existing or unknown issues with the chip-tool, which TI does not maintain.

To enable more logging inside the TI SimpleLink CC13XX/CC26XX application examples, you could modify the args.gni (located at matter\examples\lock-app\cc13x2x7_26x2x7 for example) to select chip_progress_logging=true, however I’m not sure whether it is detailed enough to give you any more insight into this specific issue.

Regards,
Ryan

Zigbee & Thread

Zigbee & Thread forum

CC2652R7: Commissioning for matter device fails