search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.55k stars 2.04k forks source link

[BUG] AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout #27190

Open ngocuong86 opened 1 year ago

ngocuong86 commented 1 year ago

Reproduction steps

I copied the chip-tool build file from my PC to the mini PC. PC: ubuntu 20.04.06, use wifi/eth mini PC: ubuntu 20.04.06, only eth, use USB-BLE (4.0).

When I test chip-tool on the mini PC I get the error Timeout waiting for mDNS resolution. And lead to the error AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout. I see the difference between PC and mini PC in the 2 log snippets below: PC:

[1686534322.709825][15051:15053] CHIP:DMG: InvokeResponseMessage =
[1686534322.709841][15051:15053] CHIP:DMG: {
[1686534322.709856][15051:15053] CHIP:DMG:  suppressResponse = false, 
[1686534322.709871][15051:15053] CHIP:DMG:  InvokeResponseIBs =
[1686534322.709894][15051:15053] CHIP:DMG:  [
[1686534322.709909][15051:15053] CHIP:DMG:      InvokeResponseIB =
[1686534322.709932][15051:15053] CHIP:DMG:      {
[1686534322.709948][15051:15053] CHIP:DMG:          CommandDataIB =
[1686534322.709965][15051:15053] CHIP:DMG:          {
[1686534322.709980][15051:15053] CHIP:DMG:              CommandPathIB =
[1686534322.709998][15051:15053] CHIP:DMG:              {
[1686534322.710016][15051:15053] CHIP:DMG:                  EndpointId = 0x0,
[1686534322.710034][15051:15053] CHIP:DMG:                  ClusterId = 0x31,
[1686534322.710052][15051:15053] CHIP:DMG:                  CommandId = 0x7,
[1686534322.710069][15051:15053] CHIP:DMG:              },
[1686534322.710087][15051:15053] CHIP:DMG:              
[1686534322.710104][15051:15053] CHIP:DMG:              CommandFields = 
[1686534322.710121][15051:15053] CHIP:DMG:              {
[1686534322.710140][15051:15053] CHIP:DMG:                  0x0 = 0, 
[1686534322.710158][15051:15053] CHIP:DMG:                  0x2 = NULL
[1686534322.710175][15051:15053] CHIP:DMG:              },
[1686534322.710191][15051:15053] CHIP:DMG:          },
[1686534322.710212][15051:15053] CHIP:DMG:          
[1686534322.710227][15051:15053] CHIP:DMG:      },
[1686534322.710249][15051:15053] CHIP:DMG:      
[1686534322.710264][15051:15053] CHIP:DMG:  ],
[1686534322.710290][15051:15053] CHIP:DMG:  
[1686534322.710304][15051:15053] CHIP:DMG:  InteractionModelRevision = 1
[1686534322.710318][15051:15053] CHIP:DMG: },
[1686534322.710371][15051:15053] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1686534322.710398][15051:15053] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1686534322.710420][15051:15053] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkEnable'
[1686534322.710437][15051:15053] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational'
[1686534322.710455][15051:15053] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1686534322.710470][15051:15053] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1686534322.710486][15051:15053] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1686534322.710510][15051:15053] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1686534322.710909][15051:15053] CHIP:DMG: ICR moving to [AwaitingDe]
[1686534322.911514][15051:15053] CHIP:DIS: Checking node lookup status after 201 ms
**[1686534323.735763][15051:15053] CHIP:DIS: Lookup clearing interface for non LL address
[1686534323.735855][15051:15053] CHIP:DIS: UDP:10.10.50.29%wlp7s0:5540: new best score: 2**
[1686534323.735880][15051:15053] CHIP:DIS: Checking node lookup status after 1025 ms
[1686534323.735940][15051:15053] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:10.10.50.29:5540 while in state 2
[1686534323.735972][15051:15053] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1686534323.736070][15051:15053] CHIP:IN: SecureSession[0x7fb2e0059360]: Allocated Type:2 LSID:41396
[1686534323.736109][15051:15053] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1686534323.737218][15051:15053] CHIP:ATM: CHIP_ERROR SendMessage
[1686534323.737281][15051:15053] CHIP:EM: <<< [E:33849i S:0 M:55156334] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1686534323.737331][15051:15053] CHIP:IN: (U) Sending msg 55156334 to IP address 'UDP:10.10.50.29:5540'
[1686534323.737488][15051:15053] CHIP:SC: Sent Sigma1 msg
[1686534323.737520][15051:15053] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1686534323.924013][15051:15053] CHIP:ATM: CHIP_ERROR TransportMgrBase::HandleMessageReceived

Mini PC:

[1686536003.257343][1965:1967] CHIP:EM: Found matching exchange: 65376i, Delegate: 0x7f3ea003e808
[1686536003.257382][1965:1967] CHIP:DMG: ICR moving to [ResponseRe]
[1686536003.257436][1965:1967] CHIP:DMG: InvokeResponseMessage =
[1686536003.257461][1965:1967] CHIP:DMG: {
[1686536003.257486][1965:1967] CHIP:DMG:    suppressResponse = false, 
[1686536003.257508][1965:1967] CHIP:DMG:    InvokeResponseIBs =
[1686536003.257543][1965:1967] CHIP:DMG:    [
[1686536003.257565][1965:1967] CHIP:DMG:        InvokeResponseIB =
[1686536003.257599][1965:1967] CHIP:DMG:        {
[1686536003.257621][1965:1967] CHIP:DMG:            CommandDataIB =
[1686536003.257647][1965:1967] CHIP:DMG:            {
[1686536003.257669][1965:1967] CHIP:DMG:                CommandPathIB =
[1686536003.257694][1965:1967] CHIP:DMG:                {
[1686536003.257721][1965:1967] CHIP:DMG:                    EndpointId = 0x0,
[1686536003.257748][1965:1967] CHIP:DMG:                    ClusterId = 0x31,
[1686536003.257774][1965:1967] CHIP:DMG:                    CommandId = 0x7,
[1686536003.257798][1965:1967] CHIP:DMG:                },
[1686536003.257826][1965:1967] CHIP:DMG:                
[1686536003.257850][1965:1967] CHIP:DMG:                CommandFields = 
[1686536003.257876][1965:1967] CHIP:DMG:                {
[1686536003.257904][1965:1967] CHIP:DMG:                    0x0 = 0, 
[1686536003.257931][1965:1967] CHIP:DMG:                    0x2 = NULL
[1686536003.257957][1965:1967] CHIP:DMG:                },
[1686536003.257980][1965:1967] CHIP:DMG:            },
[1686536003.258011][1965:1967] CHIP:DMG:            
[1686536003.258033][1965:1967] CHIP:DMG:        },
[1686536003.258064][1965:1967] CHIP:DMG:        
[1686536003.258084][1965:1967] CHIP:DMG:    ],
[1686536003.258117][1965:1967] CHIP:DMG:    
[1686536003.258140][1965:1967] CHIP:DMG:    InteractionModelRevision = 1
[1686536003.258160][1965:1967] CHIP:DMG: },
[1686536003.258238][1965:1967] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1686536003.258276][1965:1967] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1686536003.258305][1965:1967] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkEnable'
[1686536003.258329][1965:1967] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational'
[1686536003.258355][1965:1967] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1686536003.258376][1965:1967] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000037]
[1686536003.258397][1965:1967] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1686536003.258429][1965:1967] CHIP:DIS: OperationalSessionSetup[1:0000000000000037]: State change 1 --> 2
[1686536003.258882][1965:1967] CHIP:DMG: ICR moving to [AwaitingDe]
[1686536003.459875][1965:1967] CHIP:DIS: Checking node lookup status after 201 ms
[1686536005.204160][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536008.000635][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536008.000914][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536010.653885][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536013.376511][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536013.376794][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536016.004108][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536018.752458][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536018.752712][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536021.403759][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536023.904974][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536023.905227][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536026.653399][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536029.247989][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536029.248215][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536031.854226][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536034.271127][1965:1967] CHIP:DIS: Timeout waiting for mDNS resolution.
[1686536034.625207][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536034.625402][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536037.304500][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536040.000744][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536040.001075][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536042.654183][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536045.376305][1965:1966] CHIP:DL: Indication received, conn = 0x7f3ea80ea0c0
[1686536045.376590][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1686536047.954227][1965:1967] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1686536048.260018][1965:1967] CHIP:DIS: Checking node lookup status after 45001 ms
[1686536048.260084][1965:1967] CHIP:DIS: OperationalSessionSetup[1:0000000000000037]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout
[1686536048.260109][1965:1967] CHIP:DIS: Retrying operational DNS-SD discovery. Attempts remaining: 2
[1686536048.260546][1965:1967] CHIP:CTL: Session establishment failed for <0000000000000037, 1>, error: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:114: CHIP Error 0x00000032: Timeout.  Next retry expected to get a response to Sigma1 or fail within 60 seconds

PC has but mini PC doesn't:

[1686534323.735763][15051:15053] CHIP:DIS: Lookup clearing interface for non LL address [1686534323.735855][15051:15053] CHIP:DIS: UDP:10.10.50.29%wlp7s0:5540: new best score: 2

This error is because I copied the chip-tool file the wrong way or because my mini PC lacks some services. Or is it coming from my USB-BLE?

Bug prevalence

every

GitHub hash of the SDK that was being used

master

Platform

other

Platform Version(s)

No response

Anything else?

No response

bzbarsky-apple commented 1 year ago

The error indicates DNS-SD resolution failed. Are you compiling with minimal mdns, or using avahi? In the latter case, what happens when you try to manually run the relevant avahi commands?

ngocuong86 commented 1 year ago

I check both of these services and they are still working normally.

cuong@cuongMini:~/matter/out$ sudo systemctl status mdns.service 
● mdns.service
     Loaded: loaded (/etc/init.d/mdns; generated)
     Active: active (running) since Mon 2023-06-12 13:46:39 +07; 5min ago
       Docs: man:systemd-sysv-generator(8)
    Process: 783 ExecStart=/etc/init.d/mdns start (code=exited, status=0/SUCCESS)
      Tasks: 1 (limit: 4482)
     Memory: 1.3M
     CGroup: /system.slice/mdns.service
             └─791 /usr/sbin/mdnsd

Thg 6 12 13:47:15 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: ProbeCount 0; restarting probing after 1024-tick pause due to possibly spurious multicast conflict (1/1) via interface 101169790>
Thg 6 12 13:47:16 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: Received from 10.10.60.55:5353   16 cuongMini.local. AAAA fd11:1111:1122:2222:b5c8:f63a:a8ae:a6a9
Thg 6 12 13:47:16 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: ProbeCount 2; restarting probing after 1024-tick pause due to possibly spurious multicast conflict (1/1) via interface 101169790>
Thg 6 12 13:47:17 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: Received from fd11:1111:1122:2222:b5c8:f63a:a8ae:a6a9:5353   16 cuongMini.local. AAAA fd11:1111:1122:2222:b5c8:f63a:a8ae:a6a9
Thg 6 12 13:47:17 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: ProbeCount 0; will deregister   16 cuongMini.local. AAAA fe80::a290:aa28:30d6:fd67 due to multicast conflict via interface 10116>
Thg 6 12 13:47:17 cuongMini mDNSResponder[791]: Default: Local Hostname cuongMini.local already in use; will try cuongMini-2.local instead
Thg 6 12 13:47:18 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: Received from 10.10.60.55:5353   17 55.60.10.10.in-addr.arpa. PTR cuongMini.local.
Thg 6 12 13:47:18 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: Unexpected conflict discarding   19 55.60.10.10.in-addr.arpa. PTR cuongMini-2.local.
Thg 6 12 13:47:18 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: Received from 10.10.60.55:5353   17 7.6.d.f.6.d.0.3.8.2.a.a.0.9.2.a.0.0.0.0.0.0.0.0.0.0.0.0.0.8.e.f.ip6.arpa. PTR cuongMini.loca>
Thg 6 12 13:47:18 cuongMini mDNSResponder[791]: Default: mDNSCoreReceiveResponse: Unexpected conflict discarding   19 7.6.D.F.6.D.0.3.8.2.A.A.0.9.2.A.0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.ip6.arpa. PTR cuongMini-2.lo>
cuong@cuongMini:~/matter/out$ sudo systemctl status avahi-daemon.service 
● avahi-daemon.service - Avahi mDNS/DNS-SD Stack
     Loaded: loaded (/lib/systemd/system/avahi-daemon.service; enabled; vendor preset: enabled)
     Active: active (running) since Mon 2023-06-12 13:46:39 +07; 5min ago
TriggeredBy: ● avahi-daemon.socket
   Main PID: 570 (avahi-daemon)
     Status: "avahi-daemon 0.7 starting up."
      Tasks: 2 (limit: 4482)
     Memory: 1.3M
     CGroup: /system.slice/avahi-daemon.service
             ├─570 avahi-daemon: running [cuongMini.local]
             └─626 avahi-daemon: chroot helper

Thg 6 12 13:46:42 cuongMini avahi-daemon[570]: Joining mDNS multicast group on interface enp1s0.IPv6 with address fe80::a290:aa28:30d6:fd67.
Thg 6 12 13:46:42 cuongMini avahi-daemon[570]: New relevant interface enp1s0.IPv6 for mDNS.
Thg 6 12 13:46:42 cuongMini avahi-daemon[570]: Registering new address record for fe80::a290:aa28:30d6:fd67 on enp1s0.*.
Thg 6 12 13:46:42 cuongMini avahi-daemon[570]: Joining mDNS multicast group on interface enp1s0.IPv4 with address 10.10.60.55.
Thg 6 12 13:46:42 cuongMini avahi-daemon[570]: New relevant interface enp1s0.IPv4 for mDNS.
Thg 6 12 13:46:42 cuongMini avahi-daemon[570]: Registering new address record for 10.10.60.55 on enp1s0.IPv4.
Thg 6 12 13:47:14 cuongMini avahi-daemon[570]: Leaving mDNS multicast group on interface enp1s0.IPv6 with address fe80::a290:aa28:30d6:fd67.
Thg 6 12 13:47:14 cuongMini avahi-daemon[570]: Joining mDNS multicast group on interface enp1s0.IPv6 with address fd11:1111:1122:2222:b5c8:f63a:a8ae:a6a9.
Thg 6 12 13:47:14 cuongMini avahi-daemon[570]: Registering new address record for fd11:1111:1122:2222:b5c8:f63a:a8ae:a6a9 on enp1s0.*.
Thg 6 12 13:47:24 cuongMini avahi-daemon[570]: Withdrawing address record for fe80::a290:aa28:30d6:fd67 on enp1s0.
cuong@cuongMini:~/matter/out$ avahi-browse -a
+ enp1s0 IPv6 9c:65:f9:3e:ea:00                             _lumismarthome._tcp  local
+ enp1s0 IPv4 9c:65:f9:3e:ea:00                             _lumismarthome._tcp  local
+ enp1s0 IPv6 HIKVISION LM-AC270412-BU2/SL - D40861183      _CGI._tcp            local
+ enp1s0 IPv4 HIKVISION LM-AC270412-BU2/SL - D40861183      _CGI._tcp            local
+ enp1s0 IPv6 HIKVISION LM-AC270412-BU2/SL - D40861183      _psia._tcp           local
+ enp1s0 IPv4 HIKVISION LM-AC270412-BU2/SL - D40861183      _psia._tcp           local
+ enp1s0 IPv6 HIKVISION LM-AC270412-BU2/SL - D40861183      Web Site             local
+ enp1s0 IPv4 HIKVISION LM-AC270412-BU2/SL - D40861183      Web Site             local
+ enp1s0 IPv6 OpenThread BorderRouter #5BA7                 _meshcop._udp        local
+ enp1s0 IPv4 OpenThread BorderRouter #5BA7                 _meshcop._udp        local
+ lo IPv4 OpenThread BorderRouter #5BA7                 _meshcop._udp        local
bzbarsky-apple commented 1 year ago

The real question is whether avahi-browse -a shows the operational advertisement that then fails to resolve.

ngocuong86 commented 1 year ago

I check with OTBR then I see mDNS works but when use the chip-tool I don't see log of avahi-browse -a notification device MATTER that uses mDNS like on my PC.

ngocuong86 commented 1 year ago

In my PC:

+ wlp7s0 IPv4 265D4094BAA0FE09                              _matterc._udp        local
+ wlp7s0 IPv6 265D4094BAA0FE09                              _matterc._udp        local

In my Mini PC: cuong@cuongMini:~$ avahi-browse -a

+ enp1s0 IPv6 9c:65:f9:3e:ea:00                             _lumismarthome._tcp  local
+ enp1s0 IPv4 9c:65:f9:3e:ea:00                             _lumismarthome._tcp  local
+ enp1s0 IPv6 HIKVISION LM-AC270412-BU2/SL - D40861183      _CGI._tcp            local
+ enp1s0 IPv4 HIKVISION LM-AC270412-BU2/SL - D40861183      _CGI._tcp            local
+ enp1s0 IPv6 HIKVISION LM-AC270412-BU2/SL - D40861183      _psia._tcp           local
+ enp1s0 IPv4 HIKVISION LM-AC270412-BU2/SL - D40861183      _psia._tcp           local
+ enp1s0 IPv6 HIKVISION LM-AC270412-BU2/SL - D40861183      Web Site             local
+ enp1s0 IPv4 HIKVISION LM-AC270412-BU2/SL - D40861183      Web Site             local
+ enp1s0 IPv6 OpenThread BorderRouter #5BA7                 _meshcop._udp        local
+ enp1s0 IPv4 OpenThread BorderRouter #5BA7                 _meshcop._udp        local
+ enp1s0 IPv6 OpenThread BorderRouter #751F                 _meshcop._udp        local
+ enp1s0 IPv4 OpenThread BorderRouter #751F                 _meshcop._udp        local
- enp1s0 IPv6 OpenThread BorderRouter #5BA7                 _meshcop._udp        local
- enp1s0 IPv4 OpenThread BorderRouter #5BA7                 _meshcop._udp        local
bzbarsky-apple commented 1 year ago

@ngovancuong2735 None of that is showing Matter operational advertisements (which would be of type _matter._tcp).

jacqueshsu commented 1 year ago

@ngocuong86 Did you fix your issue? I got the same problem as your PC.

igor90ns commented 11 months ago

Hi, is there any news regarding this error? I am having same issue. My setup is Chiptool app and ESP32 with latest fw from zerocode When I try to pair device it always fail to find Operational device (but i can see it in router dhcp that is successfully connected)

it stucks here 2023-12-28 08:58:17.809 3717-4001 DIS com.google.chip.chiptool D Checking node lookup status after 45001 ms 2023-12-28 08:58:17.810 3717-4001 DIS com.google.chip.chiptool E OperationalSessionSetup[1:0000000000000010]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout 2023-12-28 08:58:17.810 3717-4001 DIS com.google.chip.chiptool D Retrying operational DNS-SD discovery. Attempts remaining: 2 2023-12-28 08:58:17.810 3717-4001 DIS com.google.chip.chiptool D Resolving EA73487ACEC81C8F:0000000000000010 ... 2023-12-28 08:58:17.811 3717-4001 NsdManager...ceResolver com.google.chip.chiptool D resolve: Starting service resolution for 'EA73487ACEC81C8F-0000000000000010' type '_matter._tcp' 2023-12-28 08:58:17.820 3717-4001 CTL com.google.chip.chiptool E Session establishment failed for <0000000000000010, 1>, error: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout. Next retry expected to get a response to Sigma1 or fail within 60 seconds

Complete logs from chip tool `

2023-12-28 08:56:45.400 3717-3717 CTL com.google.chip.chiptool D JNI_OnLoad() called 2023-12-28 08:56:45.400 3717-3717 CTL com.google.chip.chiptool D Loading Java class references. 2023-12-28 08:56:45.400 3717-3717 CTL com.google.chip.chiptool D Java class references loaded. 2023-12-28 08:56:45.400 3717-3717 DL com.google.chip.chiptool D AndroidChipPlatform JNI_OnLoad() called 2023-12-28 08:56:45.400 3717-3717 SPT com.google.chip.chiptool E JavaVM is already set 2023-12-28 08:56:45.400 3717-3717 DL com.google.chip.chiptool D Loading Java class references. 2023-12-28 08:56:45.400 3717-3717 DL com.google.chip.chiptool D Java class references loaded. 2023-12-28 08:56:45.400 3717-3717 DL com.google.chip.chiptool D BleConnectCallbackJNI_OnLoad 2023-12-28 08:56:45.400 3717-3717 DL com.google.chip.chiptool D Initializing tracing for android 2023-12-28 08:56:45.404 3717-3717 Compatibil...geReporter com.google.chip.chiptool D Compat change id reported: 263076149; UID 10309; state: DISABLED 2023-12-28 08:56:45.409 3717-3717 BluetoothAdapter com.google.chip.chiptool I BluetoothAdapter() : com.google.chip.chiptool 2023-12-28 08:56:45.418 3717-3717 Compatibil...geReporter com.google.chip.chiptool D Compat change id reported: 270306772; UID 10309; state: DISABLED 2023-12-28 08:56:45.420 3717-3717 Compatibil...geReporter com.google.chip.chiptool D Compat change id reported: 235355681; UID 10309; state: ENABLED 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D newDeviceController() called 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D Setting attestation nonce to random value 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D Setting CSR nonce to random value 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D Setting attestation nonce to random value 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D Setting CSR nonce to random value 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D Setting attestation nonce from parameters 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D Setting CSR nonce from parameters 2023-12-28 08:56:45.426 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key AndroidDeviceControllerKey 2023-12-28 08:56:45.426 3717-3717 CTL com.google.chip.chiptool D No existing credentials provided: generating ephemeral local NOC chain with OperationalCredentialsIssuer 2023-12-28 08:56:45.431 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key AndroidCARootCert1 2023-12-28 08:56:45.431 3717-3717 CTL com.google.chip.chiptool D Generating NOC 2023-12-28 08:56:45.437 3717-3717 IN com.google.chip.chiptool D UDP::Init bind&listen port=5541 2023-12-28 08:56:45.437 3717-3717 IN com.google.chip.chiptool D UDP::Init bound to port=5541 2023-12-28 08:56:45.437 3717-3717 IN com.google.chip.chiptool D UDP::Init bind&listen port=5541 2023-12-28 08:56:45.437 3717-3717 IN com.google.chip.chiptool D UDP::Init bound to port=5541 2023-12-28 08:56:45.437 3717-3717 IN com.google.chip.chiptool D BLEBase::Init - setting/overriding transport 2023-12-28 08:56:45.437 3717-3717 IN com.google.chip.chiptool D TransportMgr initialized 2023-12-28 08:56:45.437 3717-3717 FP com.google.chip.chiptool D Initializing FabricTable from persistent storage 2023-12-28 08:56:45.437 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key g/lkgt 2023-12-28 08:56:45.437 3717-3717 TS com.google.chip.chiptool D Last Known Good Time: 2023-09-04T15:59:41 2023-12-28 08:56:45.437 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key g/fidx 2023-12-28 08:56:45.437 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/n 2023-12-28 08:56:45.437 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/r 2023-12-28 08:56:45.437 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/m 2023-12-28 08:56:45.437 3717-3717 FP com.google.chip.chiptool D Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xEA73487ACEC81C8F, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF4 2023-12-28 08:56:45.437 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key g/fs/c 2023-12-28 08:56:45.437 3717-3717 KeyValueStoreManager com.google.chip.chiptool D Key 'g/fs/c' not found in shared preferences 2023-12-28 08:56:45.438 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key g/gcc 2023-12-28 08:56:45.438 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key g/gdc 2023-12-28 08:56:45.438 3717-3717 TOO com.google.chip.chiptool D KVS: Setting key g/gcc 2023-12-28 08:56:45.439 3717-3717 TOO com.google.chip.chiptool D KVS: Setting key g/gdc 2023-12-28 08:56:45.440 3717-3717 ZCL com.google.chip.chiptool D Using ZAP configuration... 2023-12-28 08:56:45.440 3717-3717 CTL com.google.chip.chiptool D System State Initialized... 2023-12-28 08:56:45.440 3717-3717 CTL com.google.chip.chiptool D Intermediate CA is not needed 2023-12-28 08:56:45.440 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/r 2023-12-28 08:56:45.440 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/r 2023-12-28 08:56:45.440 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/n 2023-12-28 08:56:45.440 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/r 2023-12-28 08:56:45.440 3717-3717 FP com.google.chip.chiptool D Validating NOC chain 2023-12-28 08:56:45.450 3717-3717 FP com.google.chip.chiptool D NOC chain validation successful 2023-12-28 08:56:45.450 3717-3717 FP com.google.chip.chiptool D Updated fabric at index: 0x1, Node ID: 0x000000000001B669 2023-12-28 08:56:45.450 3717-3717 TS com.google.chip.chiptool D Last Known Good Time: 2023-09-04T15:59:41 2023-12-28 08:56:45.450 3717-3717 TS com.google.chip.chiptool D New proposed Last Known Good Time: 2021-06-10T00:00:00 2023-12-28 08:56:45.450 3717-3717 TS com.google.chip.chiptool D Retaining current Last Known Good Time 2023-12-28 08:56:45.450 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key g/sri 2023-12-28 08:56:45.450 3717-3717 TOO com.google.chip.chiptool D KVS: Setting key g/fs/c 2023-12-28 08:56:45.450 3717-3717 TOO com.google.chip.chiptool D KVS: Setting key f/1/m 2023-12-28 08:56:45.450 3717-3717 FP com.google.chip.chiptool D Metadata for Fabric 0x1 persisted to storage. 2023-12-28 08:56:45.450 3717-3717 TOO com.google.chip.chiptool D KVS: Setting key f/1/n 2023-12-28 08:56:45.451 3717-3717 TOO com.google.chip.chiptool D KVS: Deleting key f/1/i 2023-12-28 08:56:45.451 3717-3717 TS com.google.chip.chiptool D Committing Last Known Good Time to storage: 2023-09-04T15:59:41 2023-12-28 08:56:45.451 3717-3717 TOO com.google.chip.chiptool D KVS: Setting key g/lkgt 2023-12-28 08:56:45.451 3717-3717 TOO com.google.chip.chiptool D KVS: Deleting key g/fs/c 2023-12-28 08:56:45.451 3717-3717 CTL com.google.chip.chiptool D Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: EA73487ACEC81C8F) 2023-12-28 08:56:45.451 3717-3717 CTL com.google.chip.chiptool D *** Missing DeviceAttestationVerifier configuration at DeviceCommissioner init: using global default, consider passing one in CommissionerInitParams. 2023-12-28 08:56:45.451 3717-3717 CTL com.google.chip.chiptool D Setting up group data for Fabric Index 1 with Compressed Fabric ID: 2023-12-28 08:56:45.451 3717-3717 SPT com.google.chip.chiptool D 0xea, 0x73, 0x48, 0x7a, 0xce, 0xc8, 0x1c, 0x8f, 2023-12-28 08:56:45.451 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/g 2023-12-28 08:56:45.451 3717-3717 TOO com.google.chip.chiptool D KVS: Getting key f/1/k/0 2023-12-28 08:56:45.451 3717-3717 TOO com.google.chip.chiptool D KVS: Setting key f/1/k/0 2023-12-28 08:56:45.452 3717-4001 CTL com.google.chip.chiptool D IO thread starting 2023-12-28 08:56:45.452 3717-4001 DL com.google.chip.chiptool D _OnPlatformEvent 2023-12-28 08:56:45.452 3717-3717 CTL com.google.chip.chiptool D setAttestationTrustStoreDelegate() called 2023-12-28 08:56:45.473 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:56:45.474 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:56:45.477 3717-3717 BluetoothAdapter com.google.chip.chiptool I BluetoothAdapter() : com.google.chip.chiptool 2023-12-28 08:56:45.477 3717-3717 DeviceProv...ngFragment com.google.chip.chiptool I showMessage:Scanning for BLE device 3840 2023-12-28 08:56:45.478 3717-3717 Compatibil...geReporter com.google.chip.chiptool D Compat change id reported: 147798919; UID 10309; state: ENABLED 2023-12-28 08:56:45.481 3717-3717 Toast com.google.chip.chiptool I show: caller = com.google.chip.chiptool.provisioning.DeviceProvisioningFragment.showMessage$lambda$4:245 2023-12-28 08:56:45.482 3717-3717 Toast com.google.chip.chiptool I show: isDexDualMode = false 2023-12-28 08:56:45.482 3717-3717 Toast com.google.chip.chiptool I show: contextDispId = 0 mCustomDisplayId = -1 focusedDisplayId = 0 isActivityContext = true 2023-12-28 08:56:45.487 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:56:45.488 3717-3717 BluetoothAdapter com.google.chip.chiptool I BLE support array set: [true, true, true, true, true, true, true] 2023-12-28 08:56:45.494 3717-3717 chip.BluetoothManager com.google.chip.chiptool I Starting Bluetooth scan 2023-12-28 08:56:45.494 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:56:45.495 3717-3717 BluetoothAdapter com.google.chip.chiptool D semIsBleEnabled(): ON 2023-12-28 08:56:45.496 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:56:45.496 3717-3717 BluetoothLeScanner com.google.chip.chiptool D Start Scan with callback 2023-12-28 08:56:45.501 3717-3738 BluetoothLeScanner com.google.chip.chiptool D onScannerRegistered() - status=0 scannerId=4 mScannerId=0 2023-12-28 08:56:45.515 30673-31051 BtGatt.GattService com.android.bluetooth E [GSIM LOG]: gsimLogHandler, msg: MESSAGE_SCAN_START, appName: com.google.chip.chiptool, scannerId: 4, reportDelayMillis=0 2023-12-28 08:56:45.515 3717-3717 AnimatorSet com.google.chip.chiptool D mReversing is false. Don't call initChildren. 2023-12-28 08:56:45.515 3717-3717 AnimatorSet com.google.chip.chiptool D mReversing is false. Don't call initChildren. 2023-12-28 08:56:45.558 3717-3717 WindowOnBackDispatcher com.google.chip.chiptool W sendCancelIfRunning: isInProgress=falsecallback=ImeCallback=ImeOnBackInvokedCallback@144649536 Callback=android.window.IOnBackInvokedCallback$Stub$Proxy@6c9bed3 2023-12-28 08:56:45.559 3717-3717 ImeTracker com.google.chip.chiptool I com.google.chip.chiptool:37c3f4bb: onRequestHide at ORIGIN_CLIENT_HIDE_SOFT_INPUT reason HIDE_SOFT_INPUT 2023-12-28 08:56:45.559 3717-3717 InputMethodManager_LC com.google.chip.chiptool I closeCurrentInput: IInputMethodManagerGlobalInvoker.hideSoftInput 2023-12-28 08:56:45.568 3717-3717 InsetsController com.google.chip.chiptool I setRequestedVisibleTypes: visible=false, mask=ime, host=com.google.chip.chiptool/com.google.chip.chiptool.CHIPToolActivity, from=android.view.InsetsController.controlAnimationUnchecked:1442 android.view.InsetsController.applyAnimation:2002 android.view.InsetsController.applyAnimation:1965 android.view.InsetsController.hide:1400 android.view.ViewRootImpl$ViewRootHandler.handleMessageImpl:7165 android.view.ViewRootImpl$ViewRootHandler.handleMessage:7091 android.os.Handler.dispatchMessage:106 android.os.Looper.loopOnce:230 android.os.Looper.loop:319 android.app.ActivityThread.main:8913 2023-12-28 08:56:45.568 3717-3717 InsetsController com.google.chip.chiptool I controlAnimationUncheckedInner: Added types=ime, animType=1, host=com.google.chip.chiptool/com.google.chip.chiptool.CHIPToolActivity, from=android.view.InsetsController.controlAnimationUnchecked:1446 android.view.InsetsController.applyAnimation:2002 android.view.InsetsController.applyAnimation:1965 2023-12-28 08:56:45.584 3717-3738 ViewRootIm...lActivity] com.google.chip.chiptool I Resizing android.view.ViewRootImpl@b6beb7: frame = [0,0][2800,1752] reportDraw = false forceLayout = false syncSeqId = -1 2023-12-28 08:56:45.590 3717-3717 ImeBackDispatcher com.google.chip.chiptool E Ime callback not found. Ignoring unregisterReceivedCallback. callbackId: 144649536 2023-12-28 08:56:45.590 3717-3717 RemoteInpu...ectionImpl com.google.chip.chiptool W requestCursorAnchorInfo on inactive InputConnection 2023-12-28 08:56:45.591 3717-3717 InsetsController com.google.chip.chiptool I onStateChanged: host=com.google.chip.chiptool/com.google.chip.chiptool.CHIPToolActivity, from=android.view.ViewRootImpl$ViewRootHandler.handleMessageImpl:7134, state=InsetsState: {mDisplayFrame=Rect(0, 0 - 2800, 1752), mDisplayCutout=DisplayCutout{insets=Rect(0, 0 - 0, 0) waterfall=Insets{left=0, top=0, right=0, bottom=0} boundingRect={Bounds=[Rect(0, 0 - 0, 0), Rect(0, 0 - 0, 0), Rect(0, 0 - 0, 0), Rect(0, 0 - 0, 0)]} cutoutPathParserInfo={CutoutPathParserInfo{displayWidth=0 displayHeight=0 physicalDisplayWidth=0 physicalDisplayHeight=0 density={0.0} cutoutSpec={} rotation={0} scale={0.0} physicalPixelDisplaySizeRatio={0.0}}}}, mRoundedCorners=RoundedCorners{[RoundedCorner{position=TopLeft, radius=24, center=Point(24, 24)}, RoundedCorner{position=TopRight, radius=24, center=Point(2776, 24)}, RoundedCorner{position=BottomRight, radius=24, center=Point(2776, 1728)}, RoundedCorner{position=BottomLeft, radius=24, center=Point(24, 1728)}]} mRoundedCornerFrame=Rect(0, 0 - 2800, 1752), mPrivacyIndicatorBounds=PrivacyIndicatorBounds {static bounds=Rect(2717, 0 - 2800, 45) rotation=1}, mDisplayShape=DisplayShape{ spec=-219591279 displayWidth=1752 displayHeight=2800 physicalPixelDisplaySizeRatio=1.0 rotation=1 offsetX=0 offsetY=0 scale=1.0}, mSources= { InsetsSource: {3 mType=ime mFrame=[0,960][2800,1752] mVisible=false mFlags=[]}, InsetsSource: {13640000 mType=statusBars mFrame=[0,0][2800,45] mVisible=true mFlags=[]}, InsetsSource: {13640005 mType=mandatorySystemGestures mFrame=[0,0][2800,45] mVisible=true mFlags=[]}, InsetsSource: {13640006 mType=tappableElement mFrame=[0,0][2800,45] mVisible=true mFlags=[]}, InsetsSource: {75650001 mType=navigationBars mFrame=[0,1662][2800,1752] mVisible=true mFlags=[]}, InsetsSource: {75650004 mType=systemGestures mFrame=[0,0][0,0] mVisible=true mFlags=[]}, InsetsSource: {75650005 mType=mandatorySystemGestures mFrame=[0,1662][2800,1752] mVisible=true mFlags=[]}, InsetsSource: {75650006 mType=tappableElement mFrame=[0,1662][2800,1752] mVisible=true mFlags=[]}, InsetsSource: {75650024 mType=systemGestures mFrame=[0,0][0,0] mVisible=true mFlags=[]} } 2023-12-28 08:56:45.592 3717-3717 InsetsSourceConsumer com.google.chip.chiptool I applyRequestedVisibilityToControl: visible=true, type=navigationBars, host=com.google.chip.chiptool/com.google.chip.chiptool.CHIPToolActivity 2023-12-28 08:56:45.593 3717-3717 ViewRootIm...lActivity] com.google.chip.chiptool I handleResized, msg = 4 frames=ClientWindowFrames{frame=[0,0][2800,1752] display=[0,0][2800,1752] parentFrame=[0,0][0,0]} forceNextWindowRelayout=false displayId=0 dragResizing=false compatScale=1.0 frameChanged=false attachedFrameChanged=false configChanged=false displayChanged=false compatScaleChanged=false 2023-12-28 08:56:45.897 3717-3717 InsetsController com.google.chip.chiptool I cancelAnimation: types=ime, animType=1, host=com.google.chip.chiptool/com.google.chip.chiptool.CHIPToolActivity, from=android.view.InsetsController.notifyFinished:1745 android.view.InsetsAnimationThreadControlRunner$1.lambda$notifyFinished$0:85 android.view.InsetsAnimationThreadControlRunner$1.$r8$lambda$RAf1SfIREsj9-wH5FOigMy6eLkM:0 2023-12-28 08:56:45.899 3717-3717 ImeTracker com.google.chip.chiptool I com.google.chip.chiptool:30d41575: onRequestHide at ORIGIN_CLIENT_HIDE_SOFT_INPUT reason HIDE_SOFT_INPUT_BY_INSETS_API 2023-12-28 08:56:45.899 3717-3717 InputMethodManager_LC com.google.chip.chiptool I notifyImeHidden: IInputMethodManagerGlobalInvoker.hideSoftInput 2023-12-28 08:56:45.901 3717-3717 ImeTracker com.google.chip.chiptool I com.google.chip.chiptool:37c3f4bb: onHidden 2023-12-28 08:56:46.443 3717-3738 ViewRootIm...lActivity] com.google.chip.chiptool I Resizing android.view.ViewRootImpl@b6beb7: frame = [0,0][2800,1752] reportDraw = false forceLayout = false syncSeqId = -1 2023-12-28 08:56:46.446 3717-3717 InsetsController com.google.chip.chiptool I onStateChanged: host=com.google.chip.chiptool/com.google.chip.chiptool.CHIPToolActivity, from=android.view.ViewRootImpl$ViewRootHandler.handleMessageImpl:7121, state=InsetsState: {mDisplayFrame=Rect(0, 0 - 2800, 1752), mDisplayCutout=DisplayCutout{insets=Rect(0, 0 - 0, 0) waterfall=Insets{left=0, top=0, right=0, bottom=0} boundingRect={Bounds=[Rect(0, 0 - 0, 0), Rect(0, 0 - 0, 0), Rect(0, 0 - 0, 0), Rect(0, 0 - 0, 0)]} cutoutPathParserInfo={CutoutPathParserInfo{displayWidth=0 displayHeight=0 physicalDisplayWidth=0 physicalDisplayHeight=0 density={0.0} cutoutSpec={} rotation={0} scale={0.0} physicalPixelDisplaySizeRatio={0.0}}}}, mRoundedCorners=RoundedCorners{[RoundedCorner{position=TopLeft, radius=24, center=Point(24, 24)}, RoundedCorner{position=TopRight, radius=24, center=Point(2776, 24)}, RoundedCorner{position=BottomRight, radius=24, center=Point(2776, 1728)}, RoundedCorner{position=BottomLeft, radius=24, center=Point(24, 1728)}]} mRoundedCornerFrame=Rect(0, 0 - 2800, 1752), mPrivacyIndicatorBounds=PrivacyIndicatorBounds {static bounds=Rect(2717, 0 - 2800, 45) rotation=1}, mDisplayShape=DisplayShape{ spec=-219591279 displayWidth=1752 displayHeight=2800 physicalPixelDisplaySizeRatio=1.0 rotation=1 offsetX=0 offsetY=0 scale=1.0}, mSources= { InsetsSource: {3 mType=ime mFrame=[0,0][0,0] mVisible=false mFlags=[]}, InsetsSource: {13640000 mType=statusBars mFrame=[0,0][2800,45] mVisible=true mFlags=[]}, InsetsSource: {13640005 mType=mandatorySystemGestures mFrame=[0,0][2800,45] mVisible=true mFlags=[]}, InsetsSource: {13640006 mType=tappableElement mFrame=[0,0][2800,45] mVisible=true mFlags=[]}, InsetsSource: {75650001 mType=navigationBars mFrame=[0,1662][2800,1752] mVisible=true mFlags=[]}, InsetsSource: {75650004 mType=systemGestures mFrame=[0,0][0,0] mVisible=true mFlags=[]}, InsetsSource: {75650005 mType=mandatorySystemGestures mFrame=[0,1662][2800,1752] mVisible=true mFlags=[]}, InsetsSource: {75650006 mType=tappableElement mFrame=[0,1662][2800,1752] mVisible=true mFlags=[]}, InsetsSource: {75650024 mType=systemGestures mFrame=[0,0][0,0] mVisible=true mFlags=[]} } 2023-12-28 08:56:46.448 3717-3717 ViewRootIm...lActivity] com.google.chip.chiptool I handleResized, msg = 4 frames=ClientWindowFrames{frame=[0,0][2800,1752] display=[0,0][2800,1752] parentFrame=[0,0][0,0]} forceNextWindowRelayout=false displayId=0 dragResizing=false compatScale=1.0 frameChanged=false attachedFrameChanged=false configChanged=false displayChanged=false compatScaleChanged=false 2023-12-28 08:56:55.503 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:56:55.503 3717-3717 BluetoothLeScanner com.google.chip.chiptool D Stop Scan with callback 2023-12-28 08:56:55.519 30673-31051 BtGatt.GattService com.android.bluetooth E [GSIM LOG]: gsimLogHandler, msg: MESSAGE_SCAN_STOP, appName: com.google.chip.chiptool, scannerId: 4, reportDelayMillis=0 2023-12-28 08:56:55.547 3717-3717 DeviceProv...ngFragment com.google.chip.chiptool I showMessage:Device not found 2023-12-28 08:56:55.553 3717-3717 Toast com.google.chip.chiptool I show: caller = com.google.chip.chiptool.provisioning.DeviceProvisioningFragment.showMessage$lambda$4:245 2023-12-28 08:56:55.553 3717-3717 Toast com.google.chip.chiptool I show: isDexDualMode = false 2023-12-28 08:56:55.554 3717-3717 Toast com.google.chip.chiptool I show: contextDispId = 0 mCustomDisplayId = -1 focusedDisplayId = 0 isActivityContext = true 2023-12-28 08:57:05.890 3717-3717 ViewRootIm...lActivity] com.google.chip.chiptool I ViewPostIme key 0 2023-12-28 08:57:05.890 3717-3717 Activity com.google.chip.chiptool D onKeyDown(KEYCODE_BACK) 2023-12-28 08:57:05.958 3717-3717 ViewRootIm...lActivity] com.google.chip.chiptool I ViewPostIme key 1 2023-12-28 08:57:05.958 3717-3717 Activity com.google.chip.chiptool D onKeyUp(KEYCODE_BACK) isTracking()=true isCanceled()=false hasCallback=false 2023-12-28 08:57:05.973 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:05.976 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:05.983 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:05.985 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:05.991 3717-3717 AnimatorSet com.google.chip.chiptool D mReversing is false. Don't call initChildren. 2023-12-28 08:57:05.997 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:06.002 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:06.007 3717-3717 CTL com.google.chip.chiptool D setDeviceAttestationDelegate() called 2023-12-28 08:57:24.856 3717-3717 ViewRootIm...lActivity] com.google.chip.chiptool I ViewPostIme pointer 0 2023-12-28 08:57:24.863 3717-3717 AnimatorSet com.google.chip.chiptool D mReversing is false. Don't call initChildren. 2023-12-28 08:57:24.928 3717-3717 ViewRootIm...lActivity] com.google.chip.chiptool I ViewPostIme pointer 1 2023-12-28 08:57:24.931 3717-3717 AnimatorSet com.google.chip.chiptool D mReversing is false. Don't call initChildren. 2023-12-28 08:57:24.949 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:24.950 3717-3717 InputMethodManager com.google.chip.chiptool I invalidateInput 2023-12-28 08:57:24.951 3717-3717 DeviceProv...ngFragment com.google.chip.chiptool I showMessage:Scanning for BLE device 3840 2023-12-28 08:57:24.955 3717-3717 Toast com.google.chip.chiptool I show: caller = com.google.chip.chiptool.provisioning.DeviceProvisioningFragment.showMessage$lambda$4:245 2023-12-28 08:57:24.956 3717-3717 Toast com.google.chip.chiptool I show: isDexDualMode = false 2023-12-28 08:57:24.956 3717-3717 Toast com.google.chip.chiptool I show: contextDispId = 0 mCustomDisplayId = -1 focusedDisplayId = 0 isActivityContext = true 2023-12-28 08:57:24.959 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:57:24.960 3717-3717 chip.BluetoothManager com.google.chip.chiptool I Starting Bluetooth scan 2023-12-28 08:57:24.960 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:57:24.961 3717-3717 BluetoothAdapter com.google.chip.chiptool D semIsBleEnabled(): ON 2023-12-28 08:57:24.961 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:57:24.961 3717-3717 BluetoothLeScanner com.google.chip.chiptool D Start Scan with callback 2023-12-28 08:57:24.968 3717-3739 BluetoothLeScanner com.google.chip.chiptool D onScannerRegistered() - status=0 scannerId=4 mScannerId=0 2023-12-28 08:57:24.975 30673-31051 BtGatt.GattService com.android.bluetooth E [GSIM LOG]: gsimLogHandler, msg: MESSAGE_SCAN_START, appName: com.google.chip.chiptool, scannerId: 4, reportDelayMillis=0 2023-12-28 08:57:24.977 3717-3717 AnimatorSet com.google.chip.chiptool D mReversing is false. Don't call initChildren. 2023-12-28 08:57:24.979 3717-3717 AnimatorSet com.google.chip.chiptool D mReversing is false. Don't call initChildren. 2023-12-28 08:57:25.028 3717-3717 chip.BluetoothManager com.google.chip.chiptool I Bluetooth Device Scanned Addr: C2:33:C7:22:56:56, Name null 2023-12-28 08:57:25.029 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:57:25.029 3717-3717 BluetoothLeScanner com.google.chip.chiptool D Stop Scan with callback 2023-12-28 08:57:25.034 3717-3717 DeviceProv...ngFragment com.google.chip.chiptool I showMessage:Connecting to C2:33:C7:22:56:56 2023-12-28 08:57:25.036 30673-31051 BtGatt.GattService com.android.bluetooth E [GSIM LOG]: gsimLogHandler, msg: MESSAGE_SCAN_STOP, appName: com.google.chip.chiptool, scannerId: 4, reportDelayMillis=0 2023-12-28 08:57:25.038 3717-3717 Toast com.google.chip.chiptool I show: caller = com.google.chip.chiptool.provisioning.DeviceProvisioningFragment.showMessage$lambda$4:245 2023-12-28 08:57:25.039 3717-3717 Toast com.google.chip.chiptool I show: isDexDualMode = false 2023-12-28 08:57:25.039 3717-3717 Toast com.google.chip.chiptool I show: contextDispId = 0 mCustomDisplayId = -1 focusedDisplayId = 0 isActivityContext = true 2023-12-28 08:57:25.044 3717-3717 chip.BluetoothManager com.google.chip.chiptool I Connecting 2023-12-28 08:57:25.044 3717-3717 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:57:25.045 3717-3717 Compatibil...geReporter com.google.chip.chiptool D Compat change id reported: 265103382; UID 10309; state: DISABLED 2023-12-28 08:57:25.045 3717-3717 BluetoothGatt com.google.chip.chiptool D connect() - device: C2:33:C7:22:56:56, auto: false 2023-12-28 08:57:25.045 3717-3717 BluetoothGatt com.google.chip.chiptool D registerApp() 2023-12-28 08:57:25.046 3717-3717 BluetoothGatt com.google.chip.chiptool D registerApp() - UUID=b96b884c-ddfc-41a6-aba7-5af4ec7875d4 2023-12-28 08:57:25.049 3717-3739 BluetoothGatt com.google.chip.chiptool D onClientRegistered() - status=0 clientIf=6 2023-12-28 08:57:25.062 3717-3739 BluetoothAdapter com.google.chip.chiptool D getBleEnabledArray(): ON 2023-12-28 08:57:25.341 3717-3739 BluetoothGatt com.google.chip.chiptool D onClientConnectionState() - status=0 clientIf=6 device=XX:XX:XX:XX:56:56 2023-12-28 08:57:25.346 3717-3739 chip.BluetoothManager com.google.chip.chiptool I null.onConnectionStateChange status = 0, newState=2 2023-12-28 08:57:25.346 3717-3739 chip.Bluet...tateChange com.google.chip.chiptool I Discovering Services... 2023-12-28 08:57:25.347 3717-3739 BluetoothGatt com.google.chip.chiptool D discoverServices() - device: C2:33:C7:22:56:56 2023-12-28 08:57:25.695 3717-3739 BluetoothGatt com.google.chip.chiptool D onConnectionUpdated() - Device=XX:XX:XX:XX:56:56 interval=6 latency=0 timeout=500 status=0 2023-12-28 08:57:25.836 3717-3739 BluetoothGatt com.google.chip.chiptool D onSearchComplete() = Device=XX:XX:XX:XX:56:56 Status=0 2023-12-28 08:57:25.840 3717-3739 chip.BluetoothManager com.google.chip.chiptool D null.onServicesDiscovered status = 0 2023-12-28 08:57:25.840 3717-3739 chip.Bluet...Discovered com.google.chip.chiptool I Services Discovered 2023-12-28 08:57:25.840 3717-3739 BluetoothGatt com.google.chip.chiptool D configureMTU() - device: C2:33:C7:22:56:56 mtu: 247 2023-12-28 08:57:25.863 3717-3739 BluetoothGatt com.google.chip.chiptool D onConfigureMTU() - Device=XX:XX:XX:XX:56:56 mtu=256 status=0 2023-12-28 08:57:25.866 3717-3739 chip.BluetoothManager com.google.chip.chiptool D null.onMtuChanged: connecting to CHIP device 2023-12-28 08:57:25.868 3717-3717 DeviceProv...ngFragment com.google.chip.chiptool I showMessage:Pairing 2023-12-28 08:57:25.880 3717-3717 Toast com.google.chip.chiptool I show: caller = com.google.chip.chiptool.provisioning.DeviceProvisioningFragment.showMessage$lambda$4:245 2023-12-28 08:57:25.881 3717-3717 Toast com.google.chip.chiptool I show: isDexDualMode = false 2023-12-28 08:57:25.882 3717-3717 Toast com.google.chip.chiptool I show: contextDispId = 0 mCustomDisplayId = -1 focusedDisplayId = 0 isActivityContext = true 2023-12-28 08:57:25.893 3717-3717 CTL com.google.chip.chiptool D setDeviceAttestationDelegate() called 2023-12-28 08:57:25.893 3717-3717 ChipDeviceController com.google.chip.chiptool D Bluetooth connection added with ID: 1 2023-12-28 08:57:25.893 3717-3717 ChipDeviceController com.google.chip.chiptool D Pairing device with ID: 16 2023-12-28 08:57:25.893 3717-3717 CTL com.google.chip.chiptool D pairDevice() called with device ID, connection object, and pincode 2023-12-28 08:57:25.893 3717-3717 IN com.google.chip.chiptool D BleConnectionComplete: endPoint 0x706efb64d0 2023-12-28 08:57:25.893 3717-3717 DL com.google.chip.chiptool D Received GetMTU 2023-12-28 08:57:25.894 3717-3717 AndroidBleManager com.google.chip.chiptool D Android Manufacturer: (samsung) 2023-12-28 08:57:25.894 3717-3717 AndroidBleManager com.google.chip.chiptool D Android Model: (SM-X800) 2023-12-28 08:57:25.894 3717-3717 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:25.897 3717-3717 IN com.google.chip.chiptool D SecureSession[0xb4000071aab189b0]: Allocated Type:1 LSID:7680 2023-12-28 08:57:25.897 3717-3717 SC com.google.chip.chiptool D Assigned local session key ID 7680 2023-12-28 08:57:25.897 3717-3717 EM com.google.chip.chiptool D <<< [E:48950i S:0 M:14122677] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) 2023-12-28 08:57:25.897 3717-3717 IN com.google.chip.chiptool D (U) Sending msg 14122677 to IP address 'BLE' 2023-12-28 08:57:25.897 3717-3717 IN com.google.chip.chiptool D Message appended to BLE send queue 2023-12-28 08:57:25.897 3717-3717 SC com.google.chip.chiptool D Sent PBKDF param request 2023-12-28 08:57:25.897 3717-3717 CTL com.google.chip.chiptool D Setting wifi credentials from parameters 2023-12-28 08:57:25.897 3717-3717 CTL com.google.chip.chiptool D Setting attestation nonce from parameters 2023-12-28 08:57:25.897 3717-3717 CTL com.google.chip.chiptool D Setting CSR nonce from parameters 2023-12-28 08:57:25.897 3717-3717 CTL com.google.chip.chiptool D Commission called for node ID 0x0000000000000010 2023-12-28 08:57:25.914 3717-3739 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:25.914 3717-3739 DL com.google.chip.chiptool D Received SubscribeCharacteristic 2023-12-28 08:57:25.915 3717-3739 BluetoothGatt com.google.chip.chiptool D setCharacteristicNotification() - uuid: 18ee2ef5-263d-4559-959f-4f9c429f9d12 enable: true 2023-12-28 08:57:25.927 3717-3739 BluetoothGatt com.google.chip.chiptool D onConnectionUpdated() - Device=XX:XX:XX:XX:56:56 interval=24 latency=0 timeout=500 status=0 2023-12-28 08:57:25.971 3717-3739 chip.BluetoothManager com.google.chip.chiptool D null.onDescriptorWrite: 00002902-0000-1000-8000-00805f9b34fb -> 0 2023-12-28 08:57:25.971 3717-3739 BLE com.google.chip.chiptool D subscribe complete, ep = 0x706efb64d0 2023-12-28 08:57:25.976 3717-3739 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:25.977 3717-3739 BLE com.google.chip.chiptool D peripheral chose BTP version 4; central expected between 4 and 4 2023-12-28 08:57:25.977 3717-3739 BLE com.google.chip.chiptool D using BTP fragment sizes rx 244 / tx 244. 2023-12-28 08:57:25.977 3717-3739 BLE com.google.chip.chiptool D local and remote recv window size = 5 2023-12-28 08:57:25.977 3717-3739 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:25.982 3717-3739 IN com.google.chip.chiptool D BLE EndPoint 0x706efb64d0 Connection Complete 2023-12-28 08:57:26.019 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:26.096 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:26.097 3717-3742 EM com.google.chip.chiptool D >>> [E:48950i S:0 M:160299339] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) 2023-12-28 08:57:26.097 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48950i, Delegate: 0xb4000072aab21fc0 2023-12-28 08:57:26.097 3717-3742 SC com.google.chip.chiptool D Received PBKDF param response 2023-12-28 08:57:26.097 3717-3742 SC com.google.chip.chiptool D Peer assigned session ID 13123 2023-12-28 08:57:26.131 3717-3742 EM com.google.chip.chiptool D <<< [E:48950i S:0 M:14122678] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) 2023-12-28 08:57:26.131 3717-3742 IN com.google.chip.chiptool D (U) Sending msg 14122678 to IP address 'BLE' 2023-12-28 08:57:26.131 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:26.134 3717-3742 SC com.google.chip.chiptool D Sent spake2p msg1 2023-12-28 08:57:26.205 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:27.266 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:27.266 3717-3742 EM com.google.chip.chiptool D >>> [E:48950i S:0 M:160299340] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) 2023-12-28 08:57:27.266 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48950i, Delegate: 0xb4000072aab21fc0 2023-12-28 08:57:27.266 3717-3742 SC com.google.chip.chiptool D Received spake2p msg2 2023-12-28 08:57:27.290 3717-3742 EM com.google.chip.chiptool D <<< [E:48950i S:0 M:14122679] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) 2023-12-28 08:57:27.290 3717-3742 IN com.google.chip.chiptool D (U) Sending msg 14122679 to IP address 'BLE' 2023-12-28 08:57:27.290 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:27.292 3717-3742 SC com.google.chip.chiptool D Sent spake2p msg3 2023-12-28 08:57:27.339 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:27.373 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:27.373 3717-3742 EM com.google.chip.chiptool D >>> [E:48950i S:0 M:160299341] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) 2023-12-28 08:57:27.373 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48950i, Delegate: 0xb4000072aab21fc0 2023-12-28 08:57:27.374 3717-3742 SC com.google.chip.chiptool D SecureSession[0xb4000071aab189b0, LSID:7680]: State change 'kEstablishing' --> 'kActive' 2023-12-28 08:57:27.374 3717-3742 IN com.google.chip.chiptool D SecureSession[0xb4000071aab189b0]: Activated - Type:1 LSID:7680 2023-12-28 08:57:27.374 3717-3742 IN com.google.chip.chiptool D New secure session activated for device <FFFFFFFB00000000, 0>, LSID:7680 PSID:13123! 2023-12-28 08:57:27.374 3717-3742 CTL com.google.chip.chiptool D Remote device completed SPAKE2+ handshake 2023-12-28 08:57:27.374 3717-3742 DeviceProv...ngFragment com.google.chip.chiptool D onPairingComplete: 0 2023-12-28 08:57:27.374 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' 2023-12-28 08:57:27.374 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'ReadCommissioningInfo' 2023-12-28 08:57:27.374 3717-3742 CTL com.google.chip.chiptool D Sending request for commissioning information 2023-12-28 08:57:27.374 3717-3742 DMG com.google.chip.chiptool D SendReadRequest ReadClient[0xb40000726ab1edd0]: Sending Read Request 2023-12-28 08:57:27.374 3717-3742 EM com.google.chip.chiptool D <<< [E:48951i S:7680 M:60681016] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 2023-12-28 08:57:27.375 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681016 on secure session with LSID: 7680 2023-12-28 08:57:27.375 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:27.378 3717-3742 DMG com.google.chip.chiptool D MoveToState ReadClient[0xb40000726ab1edd0]: Moving to [AwaitingIn] 2023-12-28 08:57:27.431 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:27.559 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:27.623 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:27.623 3717-3742 EM com.google.chip.chiptool D >>> [E:48951i S:7680 M:211031580] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) 2023-12-28 08:57:27.623 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48951i, Delegate: 0xb40000726ab1ede0 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D ReportDataMessage = 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D AttributeReportIBs = 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0xdf17f815, 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.623 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x31, 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_0003, 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D Data = 30, 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.624 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0x1d746309, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x28, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_0004, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Data = 32768, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0x1d746309, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x28, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_0002, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Data = 65521, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0x41dcf4d0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x30, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_0003, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Data = 0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0x41dcf4d0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x30, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_0002, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Data = 0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0x41dcf4d0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x30, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_0001, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Data = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D 0x0 = 60, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D 0x1 = 900, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0x41dcf4d0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x30, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_0000, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D Data = 0, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeReportIB = 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.625 3717-3742 DMG com.google.chip.chiptool D AttributeDataIB = 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D DataVersion = 0xdf17f815, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D AttributePathIB = 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D Endpoint = 0x0, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D Cluster = 0x31, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D Attribute = 0x0000_FFFC, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D Data = 1, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D SuppressResponse = true, 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:27.626 3717-3742 DMG com.google.chip.chiptool D } 2023-12-28 08:57:27.626 3717-3742 CTL com.google.chip.chiptool D ----- NetworkCommissioning Features: has WiFi. endpointid = 0 2023-12-28 08:57:27.627 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'ReadCommissioningInfo' 2023-12-28 08:57:27.627 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' 2023-12-28 08:57:27.627 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'ArmFailSafe' 2023-12-28 08:57:27.627 3717-3742 CTL com.google.chip.chiptool D Arming failsafe (30 seconds) 2023-12-28 08:57:27.627 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:27.627 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:27.627 3717-3742 EM com.google.chip.chiptool D <<< [E:48952i S:7680 M:60681017] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:27.627 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681017 on secure session with LSID: 7680 2023-12-28 08:57:27.627 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:27.636 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:27.704 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:27.765 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:27.766 3717-3742 EM com.google.chip.chiptool D >>> [E:48952i S:7680 M:211031581] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:27.766 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48952i, Delegate: 0xb4000071cab21f58 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x30, 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x1, 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.766 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D 0x0 = 0, 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D 0x1 = "" (0 chars), 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 2023-12-28 08:57:27.767 3717-3742 CTL com.google.chip.chiptool D Received ArmFailSafe response errorCode=0 2023-12-28 08:57:27.767 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'ArmFailSafe' 2023-12-28 08:57:27.767 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' 2023-12-28 08:57:27.767 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'ConfigRegulatory' 2023-12-28 08:57:27.767 3717-3742 CTL com.google.chip.chiptool D Setting Regulatory Config 2023-12-28 08:57:27.767 3717-3742 CTL com.google.chip.chiptool D Device does not support configurable regulatory location 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:27.767 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:27.767 3717-3742 EM com.google.chip.chiptool D <<< [E:48953i S:7680 M:60681018] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:27.767 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681018 on secure session with LSID: 7680 2023-12-28 08:57:27.767 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:27.770 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:27.770 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:27.822 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:27.919 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:27.919 3717-3742 EM com.google.chip.chiptool D >>> [E:48953i S:7680 M:211031582] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:27.919 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48953i, Delegate: 0xb4000071cab325f8 2023-12-28 08:57:27.919 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x30, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x3, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D 0x0 = 0, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D 0x1 = "" (0 chars), 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:27.920 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:27.921 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:27.921 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 2023-12-28 08:57:27.921 3717-3742 CTL com.google.chip.chiptool D Received SetRegulatoryConfig response errorCode=0 2023-12-28 08:57:27.921 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'ConfigRegulatory' 2023-12-28 08:57:27.921 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' 2023-12-28 08:57:27.921 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'SendPAICertificateRequest' 2023-12-28 08:57:27.921 3717-3742 CTL com.google.chip.chiptool D Sending request for PAI certificate 2023-12-28 08:57:27.921 3717-3742 CTL com.google.chip.chiptool D Sending Certificate Chain request to 0xb4000072aab21f70 device 2023-12-28 08:57:27.921 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:27.922 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:27.922 3717-3742 EM com.google.chip.chiptool D <<< [E:48954i S:7680 M:60681019] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:27.922 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681019 on secure session with LSID: 7680 2023-12-28 08:57:27.922 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:27.930 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:27.930 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:27.972 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:28.043 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.100 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.155 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.156 3717-3742 EM com.google.chip.chiptool D >>> [E:48954i S:7680 M:211031583] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:28.156 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48954i, Delegate: 0xb4000071cab21f58 2023-12-28 08:57:28.156 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:28.156 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:28.156 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x3e, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x3, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D 0x0 = [ 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D ... (byte string too long) ... 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D ] (463 bytes) 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.157 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:28.158 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.158 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 2023-12-28 08:57:28.158 3717-3742 CTL com.google.chip.chiptool D Received certificate chain from the device 2023-12-28 08:57:28.158 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'SendPAICertificateRequest' 2023-12-28 08:57:28.159 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' 2023-12-28 08:57:28.159 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'SendDACCertificateRequest' 2023-12-28 08:57:28.159 3717-3742 CTL com.google.chip.chiptool D Sending request for DAC certificate 2023-12-28 08:57:28.159 3717-3742 CTL com.google.chip.chiptool D Sending Certificate Chain request to 0xb4000072aab21f70 device 2023-12-28 08:57:28.159 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:28.159 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:28.159 3717-3742 EM com.google.chip.chiptool D <<< [E:48955i S:7680 M:60681020] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:28.159 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681020 on secure session with LSID: 7680 2023-12-28 08:57:28.159 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:28.163 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:28.164 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:28.216 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:28.283 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.340 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.396 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.397 3717-3742 EM com.google.chip.chiptool D >>> [E:48955i S:7680 M:211031584] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:28.397 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48955i, Delegate: 0xb4000071cab325f8 2023-12-28 08:57:28.397 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:28.397 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x3e, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x3, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D 0x0 = [ 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D ... (byte string too long) ... 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D ] (493 bytes) 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.398 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 2023-12-28 08:57:28.398 3717-3742 CTL com.google.chip.chiptool D Received certificate chain from the device 2023-12-28 08:57:28.399 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'SendDACCertificateRequest' 2023-12-28 08:57:28.399 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' 2023-12-28 08:57:28.399 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'SendAttestationRequest' 2023-12-28 08:57:28.399 3717-3742 CTL com.google.chip.chiptool D Sending Attestation Request to the device. 2023-12-28 08:57:28.399 3717-3742 CTL com.google.chip.chiptool D Sending Attestation request to 0xb4000072aab21f70 device 2023-12-28 08:57:28.399 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:28.399 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:28.399 3717-3742 EM com.google.chip.chiptool D <<< [E:48956i S:7680 M:60681021] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:28.400 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681021 on secure session with LSID: 7680 2023-12-28 08:57:28.400 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:28.403 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:28.403 3717-3742 CTL com.google.chip.chiptool D Sent Attestation request, waiting for the Attestation Information 2023-12-28 08:57:28.403 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:28.453 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:28.643 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.699 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.761 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.763 3717-3742 EM com.google.chip.chiptool D >>> [E:48956i S:7680 M:211031585] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:28.763 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48956i, Delegate: 0xb4000071cab21f58 2023-12-28 08:57:28.763 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:28.763 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x3e, 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x1, 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D 0x0 = [ 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D ... (byte string too long) ... 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D ] (583 bytes) 2023-12-28 08:57:28.764 3717-3742 DMG com.google.chip.chiptool D 0x1 = [ 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D 0x14, 0xa7, 0x96, 0x9b, 0x53, 0xfc, 0x6c, 0xc1, 0xa0, 0xeb, 0x08, 0xf7, 0x06, 0x08, 0x67, 0x04, 0x0b, 0xd7, 0x4f, 0xb0, 0x4b, 0x84, 0x02, 0xec, 0xc8, 0x56, 0x4c, 0x0b, 0xbb, 0x17, 0xc6, 0x7f, 0x53, 0xed, 0x18, 0xcf, 0xda, 0x5e, 0xf3, 0x61, 0x0e, 0x 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D ] (64 bytes) 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.765 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 2023-12-28 08:57:28.765 3717-3742 CTL com.google.chip.chiptool D Received Attestation Information from the device 2023-12-28 08:57:28.766 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'SendAttestationRequest' 2023-12-28 08:57:28.766 3717-3742 CTL com.google.chip.chiptool D AutoCommissioner setting attestationElements buffer size 583/583 2023-12-28 08:57:28.766 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' 2023-12-28 08:57:28.766 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'AttestationVerification' 2023-12-28 08:57:28.766 3717-3742 CTL com.google.chip.chiptool D Verifying attestation 2023-12-28 08:57:28.789 3717-3742 CR com.google.chip.chiptool E mbedTLS error: ERROR - Generic error 2023-12-28 08:57:28.817 3717-3742 CTL com.google.chip.chiptool D Changing fail-safe timer to 600 seconds to handle DA failure 2023-12-28 08:57:28.817 3717-3742 CTL com.google.chip.chiptool D Arming failsafe (600 seconds) 2023-12-28 08:57:28.817 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:28.817 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:28.817 3717-3742 EM com.google.chip.chiptool D <<< [E:48957i S:7680 M:60681022] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:28.818 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681022 on secure session with LSID: 7680 2023-12-28 08:57:28.818 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:28.820 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:28.820 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:28.872 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:28.936 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:28.937 3717-3742 EM com.google.chip.chiptool D >>> [E:48957i S:7680 M:211031586] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:28.937 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48957i, Delegate: 0xb4000071cab325f8 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x30, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x1, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D 0x0 = 0, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D 0x1 = "" (0 chars), 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:28.937 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:28.938 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 2023-12-28 08:57:28.938 3717-3742 CTL com.google.chip.chiptool D Device attestation completed, delegating continuation to client 2023-12-28 08:57:28.938 3717-3742 CTL com.google.chip.chiptool D OnDeviceAttestationCompleted with result: 0 2023-12-28 08:57:28.938 3717-3742 DeviceProv...ngFragment com.google.chip.chiptool I Device attestation errorCode: 0, Look at 'src/credentials/attestation_verifier/DeviceAttestationVerifier.h' AttestationVerificationResult enum to understand the errors 2023-12-28 08:57:28.939 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:28.939 3717-3717 CTL com.google.chip.chiptool D continueCommissioning() called. 2023-12-28 08:57:28.939 3717-3717 CTL com.google.chip.chiptool D Continuing commissioning after attestation failure for device ID 0x0000000000000010 2023-12-28 08:57:28.939 3717-3717 CTL com.google.chip.chiptool D Overriding attestation failure per client and continuing commissioning 2023-12-28 08:57:28.939 3717-3717 CTL com.google.chip.chiptool D Successfully finished commissioning step 'AttestationVerification' 2023-12-28 08:57:28.939 3717-3717 CTL com.google.chip.chiptool D Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' 2023-12-28 08:57:28.939 3717-3717 CTL com.google.chip.chiptool D Performing next commissioning step 'SendOpCertSigningRequest' 2023-12-28 08:57:28.939 3717-3717 CTL com.google.chip.chiptool D Sending CSR request to 0xb4000072aab21f70 device 2023-12-28 08:57:28.939 3717-3717 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:28.939 3717-3717 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:28.939 3717-3717 EM com.google.chip.chiptool D <<< [E:48958i S:7680 M:60681023] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:28.939 3717-3717 IN com.google.chip.chiptool D (S) Sending msg 60681023 on secure session with LSID: 7680 2023-12-28 08:57:28.939 3717-3717 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:28.943 3717-3717 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:28.943 3717-3717 CTL com.google.chip.chiptool D Sent CSR request, waiting for the CSR 2023-12-28 08:57:28.992 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:29.334 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:29.386 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:29.386 3717-3742 EM com.google.chip.chiptool D >>> [E:48958i S:7680 M:211031587] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:29.386 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48958i, Delegate: 0xb4000071cab1d3b8 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x3e, 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x5, 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.386 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D 0x0 = [ 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D 0x15, 0x30, 0x01, 0xcc, 0x30, 0x81, 0xc9, 0x30, 0x70, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0a, 0x0c, 0x03, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D ] (244 bytes) 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D 0x1 = [ 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D 0xb4, 0x85, 0xf2, 0xd4, 0x60, 0x24, 0xe9, 0x95, 0xd2, 0x37, 0xe8, 0xa8, 0x8b, 0x74, 0x63, 0x48, 0x82, 0x7f, 0xac, 0x84, 0xfd, 0xe0, 0xd0, 0xea, 0xd2, 0x23, 0x36, 0x5e, 0x78, 0xe6, 0x00, 0x4d, 0x36, 0x25, 0xe8, 0x75, 0x17, 0x8a, 0xf0, 0xba, 0x1c, 0x 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D ] (64 bytes) 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.387 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 2023-12-28 08:57:29.387 3717-3742 CTL com.google.chip.chiptool D Received certificate signing request from the device 2023-12-28 08:57:29.387 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'SendOpCertSigningRequest' 2023-12-28 08:57:29.387 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' 2023-12-28 08:57:29.387 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'ValidateCSR' 2023-12-28 08:57:29.404 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'ValidateCSR' 2023-12-28 08:57:29.404 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' 2023-12-28 08:57:29.404 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'GenerateNOCChain' 2023-12-28 08:57:29.404 3717-3742 CTL com.google.chip.chiptool D Getting certificate chain for the device from the issuer 2023-12-28 08:57:29.415 3717-3742 TOO com.google.chip.chiptool D VerifyCertificateSigningRequest 2023-12-28 08:57:29.415 3717-3742 TOO com.google.chip.chiptool D KVS: Getting key AndroidCARootCert1 2023-12-28 08:57:29.415 3717-3742 CTL com.google.chip.chiptool D Generating NOC 2023-12-28 08:57:29.420 3717-3742 CTL com.google.chip.chiptool D Received callback from the CA for NOC Chain generation. Status src/controller/java/AndroidOperationalCredentialsIssuer.cpp:382: Success 2023-12-28 08:57:29.420 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'GenerateNOCChain' 2023-12-28 08:57:29.420 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'SendTrustedRootCert' 2023-12-28 08:57:29.420 3717-3742 CTL com.google.chip.chiptool D Sending root certificate to the device 2023-12-28 08:57:29.420 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:29.420 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:29.420 3717-3742 EM com.google.chip.chiptool D <<< [E:48959i S:7680 M:60681024] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:29.420 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681024 on secure session with LSID: 7680 2023-12-28 08:57:29.420 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:29.423 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:29.423 3717-3742 CTL com.google.chip.chiptool D Sent root certificate to the device 2023-12-28 08:57:29.423 3717-3742 DeviceProv...ngFragment com.google.chip.chiptool D 0�0��0p??01 0 U CSR0Y0�H�=�H�=B??:D"d���� �o�/���I>^��C���N]��yB�v�5�$��h�+{6݀�>�������??0 �H�=??G??0D !>�7Gh��C�j4|n7�B�|s�������t� � �����pz�}V5�,PDvL)��[�s'0 ����Е�@%�1�f��/�d�&p�WY�CC z 2023-12-28 08:57:29.423 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:29.471 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:29.471 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:29.531 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:29.925 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:29.926 3717-3742 EM com.google.chip.chiptool D >>> [E:48959i S:7680 M:211031588] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:29.926 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48959i, Delegate: 0xb4000071cab325f8 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D CommandStatusIB = 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x3e, 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D CommandId = 0xb, 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D StatusIB = 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D status = 0x00, 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.926 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 2023-12-28 08:57:29.927 3717-3742 CTL com.google.chip.chiptool D Device confirmed that it has received the root certificate 2023-12-28 08:57:29.927 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'SendTrustedRootCert' 2023-12-28 08:57:29.927 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' 2023-12-28 08:57:29.927 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'SendNOC' 2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:29.927 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:29.927 3717-3742 EM com.google.chip.chiptool D <<< [E:48960i S:7680 M:60681025] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:29.927 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681025 on secure session with LSID: 7680 2023-12-28 08:57:29.927 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:29.932 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:29.932 3717-3742 CTL com.google.chip.chiptool D Sent operational certificate to the device 2023-12-28 08:57:29.932 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:29.983 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:29.983 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:30.042 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:30.591 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:30.592 3717-3742 EM com.google.chip.chiptool D >>> [E:48960i S:7680 M:211031589] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:30.592 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48960i, Delegate: 0xb4000071cab1d3b8 2023-12-28 08:57:30.592 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:30.592 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:30.592 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.592 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:30.592 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x3e, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x8, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D 0x0 = 0, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D 0x1 = 1, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.593 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.594 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:30.594 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.594 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:30.594 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.594 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 2023-12-28 08:57:30.594 3717-3742 CTL com.google.chip.chiptool D Device returned status 0 on receiving the NOC 2023-12-28 08:57:30.594 3717-3742 CTL com.google.chip.chiptool D Operational credentials provisioned on device 0xb4000072aab21f70 2023-12-28 08:57:30.595 3717-3742 DeviceProv...ngFragment com.google.chip.chiptool D Pairing status update: 0 2023-12-28 08:57:30.595 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'SendNOC' 2023-12-28 08:57:30.595 3717-3742 CTL com.google.chip.chiptool D No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks 2023-12-28 08:57:30.595 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup' 2023-12-28 08:57:30.595 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'WiFiNetworkSetup' 2023-12-28 08:57:30.595 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:30.595 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:30.595 3717-3742 EM com.google.chip.chiptool D <<< [E:48961i S:7680 M:60681026] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:30.595 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681026 on secure session with LSID: 7680 2023-12-28 08:57:30.595 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:30.599 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:30.600 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:30.641 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:30.706 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:30.706 3717-3742 EM com.google.chip.chiptool D >>> [E:48961i S:7680 M:211031590] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:30.706 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48961i, Delegate: 0xb4000071cab325f8 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x31, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x5, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D 0x0 = 0, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D 0x2 = 0, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:30.707 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 2023-12-28 08:57:30.707 3717-3742 CTL com.google.chip.chiptool D Received NetworkConfig response, networkingStatus=0 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'WiFiNetworkSetup' 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable' 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'FailsafeBeforeWiFiEnable' 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Skipping arming failsafe: new time (36 seconds from now) before old time (598 seconds from now) 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'FailsafeBeforeWiFiEnable' 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable' 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Setting wifi connection time min = 30 2023-12-28 08:57:30.708 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'WiFiNetworkEnable' 2023-12-28 08:57:30.708 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddingComm] 2023-12-28 08:57:30.708 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AddedComma] 2023-12-28 08:57:30.708 3717-3742 EM com.google.chip.chiptool D <<< [E:48962i S:7680 M:60681027] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 2023-12-28 08:57:30.708 3717-3742 IN com.google.chip.chiptool D (S) Sending msg 60681027 on secure session with LSID: 7680 2023-12-28 08:57:30.708 3717-3742 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:30.712 3717-3742 DMG com.google.chip.chiptool D ICR moving to [CommandSen] 2023-12-28 08:57:30.713 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:30.761 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:32.807 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:32.808 3717-3742 EM com.google.chip.chiptool D >>> [E:48962i S:7680 M:211031591] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) 2023-12-28 08:57:32.808 3717-3742 EM com.google.chip.chiptool D Found matching exchange: 48962i, Delegate: 0xb4000071cab1d3b8 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D ICR moving to [ResponseRe] 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D InvokeResponseMessage = 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D suppressResponse = false, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIBs = 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D [ 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D InvokeResponseIB = 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D CommandDataIB = 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D CommandPathIB = 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D EndpointId = 0x0, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D ClusterId = 0x31, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D CommandId = 0x7, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D CommandFields = 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D { 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D 0x0 = 0, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D 0x2 = NULL 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D ], 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D
2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D InteractionModelRevision = 1 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D }, 2023-12-28 08:57:32.808 3717-3742 DMG com.google.chip.chiptool D Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 2023-12-28 08:57:32.808 3717-3742 CTL com.google.chip.chiptool D Received ConnectNetwork response, networkingStatus=0 2023-12-28 08:57:32.809 3717-3742 CTL com.google.chip.chiptool D Successfully finished commissioning step 'WiFiNetworkEnable' 2023-12-28 08:57:32.809 3717-3742 CTL com.google.chip.chiptool D Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational' 2023-12-28 08:57:32.809 3717-3742 CTL com.google.chip.chiptool D Performing next commissioning step 'FindOperational' 2023-12-28 08:57:32.809 3717-3742 CSM com.google.chip.chiptool D FindOrEstablishSession: PeerId = [1:0000000000000010] 2023-12-28 08:57:32.809 3717-3742 CSM com.google.chip.chiptool D FindOrEstablishSession: No existing OperationalSessionSetup instance found 2023-12-28 08:57:32.809 3717-3742 DIS com.google.chip.chiptool D OperationalSessionSetup[1:0000000000000010]: State change 1 --> 2 2023-12-28 08:57:32.809 3717-3742 DIS com.google.chip.chiptool D Resolving EA73487ACEC81C8F:0000000000000010 ... 2023-12-28 08:57:32.810 3717-3742 NsdManager...ceResolver com.google.chip.chiptool D resolve: Starting service resolution for 'EA73487ACEC81C8F-0000000000000010' type '_matter._tcp' 2023-12-28 08:57:32.820 3717-3742 DMG com.google.chip.chiptool D ICR moving to [AwaitingDe] 2023-12-28 08:57:32.823 3717-3998 NsdService...ndResolver com.google.chip.chiptool D Service discovery started. regType: _matter._tcp 2023-12-28 08:57:33.009 3717-4001 DIS com.google.chip.chiptool D Checking node lookup status after 201 ms 2023-12-28 08:57:35.315 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:35.385 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:37.823 3717-4052 NsdService...ndResolver com.google.chip.chiptool D Service discovery timed out after 5000 ms 2023-12-28 08:57:37.836 3717-3998 NsdService...ndResolver com.google.chip.chiptool I Discovery stopped: _matter._tcp 2023-12-28 08:57:37.964 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:40.467 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:40.548 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:43.062 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:45.568 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:45.643 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:48.167 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:50.672 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:50.750 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:53.271 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:57:55.777 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:57:55.853 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:57:58.371 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:58:00.875 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:58:00.952 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:58:02.854 3717-3717 NsdManager...ceResolver com.google.chip.chiptool D resolve: Timing out 2023-12-28 08:58:03.468 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:58:05.972 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:58:06.048 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:58:08.572 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:58:11.078 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:58:11.178 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:58:13.670 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:58:16.174 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:58:16.252 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:58:17.809 3717-4001 DIS com.google.chip.chiptool D Checking node lookup status after 45001 ms 2023-12-28 08:58:17.810 3717-4001 DIS com.google.chip.chiptool E OperationalSessionSetup[1:0000000000000010]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout 2023-12-28 08:58:17.810 3717-4001 DIS com.google.chip.chiptool D Retrying operational DNS-SD discovery. Attempts remaining: 2 2023-12-28 08:58:17.810 3717-4001 DIS com.google.chip.chiptool D Resolving EA73487ACEC81C8F:0000000000000010 ... 2023-12-28 08:58:17.811 3717-4001 NsdManager...ceResolver com.google.chip.chiptool D resolve: Starting service resolution for 'EA73487ACEC81C8F-0000000000000010' type '_matter._tcp' 2023-12-28 08:58:17.820 3717-4001 CTL com.google.chip.chiptool E Session establishment failed for <0000000000000010, 1>, error: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout. Next retry expected to get a response to Sigma1 or fail within 60 seconds 2023-12-28 08:58:17.821 3717-4001 CTL com.google.chip.chiptool D Skipping arming failsafe: new time (120 seconds from now) before old time (550 seconds from now) 2023-12-28 08:58:17.821 3717-3998 NsdService...ndResolver com.google.chip.chiptool D Service discovery started. regType: _matter._tcp 2023-12-28 08:58:18.013 3717-4001 DIS com.google.chip.chiptool D Checking node lookup status after 203 ms 2023-12-28 08:58:18.772 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 2023-12-28 08:58:21.276 3717-4001 DL com.google.chip.chiptool D Received SendWriteRequest 2023-12-28 08:58:21.352 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0 2023-12-28 08:58:22.820 3717-4072 NsdService...ndResolver com.google.chip.chiptool D Service discovery timed out after 5000 ms 2023-12-28 08:58:22.827 3717-3998 NsdService...ndResolver com.google.chip.chiptool I Discovery stopped: _matter._tcp 2023-12-28 08:58:23.899 3717-3742 chip.BluetoothManager com.google.chip.chiptool D null.onCharacteristicChanged: 18ee2ef5-263d-4559-959f-4f9c429f9d12 `

Logs from ESP32 `

Performing factory reset ... Done I (251452) chip[DL]: Performing factory reset

I (251492) wifi:state: run -> init (0) I (251492) wifi:pm stop, total sleep time: 146394478 us / 168577687 us

I (251492) wifi:idx I (251492) wifi:idx I (251502) wifi:new:<4,0>, old:<4,0>, ap:<255,255>, sta:<4,0>, prof:1 I (251542) wifi:flush txq I (251542) wifi:stop sw txq I (251542) wifi:lmac stop hw txq I (251632) chip[DL]: System restarting ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0030,len:6940 ho 0 tail 12 room 4 load:0x40078000,len:15500 load:0x40080400,len:3844 entry 0x4008064c I (29) boot: ESP-IDF v5.0.1 2nd stage bootloader I (29) boot: compile time 10:20:20 I (29) boot: chip revision: v3.1 I (32) boot.esp32: SPI Speed : 40MHz I (37) boot.esp32: SPI Mode : DIO I (41) boot.esp32: SPI Flash Size : 4MB I (46) boot: Enabling RNG early entropy source... I (51) boot: Partition Table: I (55) boot: ## Label Usage Type ST Offset Length I (62) boot: 0 esp_secure_cert unknown 3f 06 0000d000 00002000 I (70) boot: 1 nvs WiFi data 01 02 00010000 00006000 I (77) boot: 2 nvs_keys NVS keys 01 04 00016000 00001000 I (84) boot: 3 otadata OTA data 01 00 00017000 00002000 I (92) boot: 4 phy_init RF data 01 01 00019000 00001000 I (99) boot: 5 ota_0 OTA app 00 10 00020000 001e0000 I (107) boot: 6 ota_1 OTA app 00 11 00200000 001e0000 I (114) boot: 7 fctry WiFi data 01 02 003e0000 00006000 I (122) boot: End of partition table I (126) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=374ech (226540) map I (217) esp_image: segment 1: paddr=00057514 vaddr=3ffbdb60 size=053f4h ( 21492) load I (225) esp_image: segment 2: paddr=0005c910 vaddr=40080000 size=03708h ( 14088) load I (231) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=f4f0ch (1003276) map I (596) esp_image: segment 4: paddr=00154f34 vaddr=40083708 size=1af50h (110416) load I (656) boot: Loaded app from partition at offset 0x20000 I (657) boot: Disabling RNG early entropy source... I (668) cpu_start: Pro cpu up. I (668) cpu_start: Starting app cpu, entry point is 0x4008141c I (654) cpu_start: App cpu up. I (685) cpu_start: Pro cpu start user code I (685) cpu_start: cpu freq: 160000000 Hz I (685) cpu_start: Application information: I (690) cpu_start: Project name: light I (694) cpu_start: App version: v1.0 I (699) cpu_start: Compile time: Nov 8 2023 12:44:22 I (705) cpu_start: ELF file SHA256: 62f667c4ec1e35f2... I (711) cpu_start: ESP-IDF: v5.0.1 I (716) cpu_start: Min chip rev: v0.0 I (721) cpu_start: Max chip rev: v3.99 I (726) cpu_start: Chip rev: v3.1 I (731) heap_init: Initializing. RAM available for dynamic allocation: I (738) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (744) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (750) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (756) heap_init: At 3FFD4D60 len 0000B2A0 (44 KiB): DRAM I (762) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (768) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (775) heap_init: At 4009E658 len 000019A8 (6 KiB): IRAM I (782) spi_flash: detected chip: generic I (786) spi_flash: flash io: dio I (793) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (903) led_driver_gpio: Initializing light driver I (903) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 W (933) esp_matter_core: Command 0x00000047 on cluster 0x00000300 already exists. Not creating again. I (933) app_main: Light created with endpoint_id 1 I (953) wifi:wifi driver task: 3ffdbca8, prio:23, stack:6656, core=0 I (953) system_api: Base MAC address is not set I (953) system_api: read default base MAC address from EFUSE I (983) wifi:wifi firmware version: 17afb16 I (983) wifi:wifi certification version: v7.0 I (983) wifi:config NVS flash: enabled I (983) wifi:config nano formating: disabled I (983) wifi:Init data frame dynamic rx buffer num: 32 I (993) wifi:Init management frame dynamic rx buffer num: 32 I (993) wifi:Init management short buffer num: 32 I (1003) wifi:Init dynamic tx buffer num: 32 I (1003) wifi:Init static rx buffer size: 1600 I (1013) wifi:Init static rx buffer num: 10 I (1013) wifi:Init dynamic rx buffer num: 32 I (1023) wifi_init: rx ba win: 6 I (1023) wifi_init: tcpip mbox: 32 I (1023) wifi_init: udp mbox: 6 I (1033) wifi_init: tcp mbox: 6 I (1033) wifi_init: tcp tx win: 5744 I (1033) wifi_init: tcp rx win: 5744 I (1043) wifi_init: tcp mss: 1440 I (1043) wifi_init: WiFi IRAM OP enabled I (1053) wifi_init: WiFi RX IRAM OP enabled I (1083) chip[DL]: NVS set: chip-counters/reboot-count = 1 (0x1) I (1093) chip[DL]: NVS set: chip-counters/total-hours = 0 (0x0) I (1093) chip[DL]: NVS set: chip-config/unique-id = "5CBE74B369E72D61" I (1093) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC) I (1103) BTDM_INIT: BT controller compile version [60aae55] I (1113) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07 I (1503) CHIP[DL]: BLE host-controller synced I (2013) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable) I (2013) NimBLE: GAP procedure initiated: advertise; I (2023) NimBLE: disc_mode=2 I (2023) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2033) NimBLE:

I (2043) chip[DL]: CHIPoBLE advertising started E (2043) chip[DL]: Long dispatch time: 938 ms, for event type 2 I (2053) chip[DL]: Starting ESP WiFi layer I (2053) wifi:mode : sta (d4:d4:da:0f:dc:88) I (2053) wifi:enable tsf W (2063) wifi:Haven't to connect to a suitable AP now! I (2063) chip[DL]: Done driving station state, nothing else to do... W (2073) wifi:Haven't to connect to a suitable AP now! I (2073) chip[DL]: Done driving station state, nothing else to do... I (2083) chip[SVR]: Initializing subscription resumption storage... I (2093) chip[SVR]: Server initializing... I (2093) chip[TS]: Last Known Good Time: [unknown] I (2103) chip[TS]: Setting Last Known Good Time to firmware build time 2023-11-08T12:45:41 I (2113) chip[DMG]: AccessControl: initializing I (2113) chip[DMG]: Examples::AccessControlDelegate::Init I (2123) chip[DMG]: AccessControl: setting I (2123) chip[DMG]: DefaultAclStorage: initializing I (2133) chip[DMG]: DefaultAclStorage: 0 entries loaded I (2143) chip[ZCL]: Using ZAP configuration... I (2143) esp_matter_cluster: Cluster plugin init common callback I (2153) chip[DMG]: AccessControlCluster: initializing I (2153) chip[ZCL]: 0x3f407964ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported I (2163) chip[ZCL]: Initiating Admin Commissioning cluster. E (2173) chip[ZCL]: Duplicate attribute override registration failed I (2183) chip[DIS]: Updating services using commissioning mode 1 I (2183) chip[DIS]: CHIP minimal mDNS started advertising. I (2193) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 I (2203) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: D0885A163034E1CD. I (2213) chip[DIS]: mDNS service published: _matterc._udp I (2213) chip[IN]: CASE Server enabling CASE session setups I (2223) chip[SVR]: Joining Multicast groups I (2223) chip[SVR]: Server Listening... I (2233) esp_matter_core: Dynamic endpoint 0 added I (2243) esp_matter_attribute: ** W : Endpoint 0x0001's Cluster 0x00000003's Attribute 0x00000001 is 0 ** I (2253) esp_matter_attribute: ** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x00000000 is 128 ** I (2263) esp_matter_attribute: ** W : Endpoint 0x0001's Cluster 0x00000004's Attribute 0x0000FFFC is <invalid type: 0> ** I (2273) esp_matter_attribute: ** W : Endpoint 0x0001's Cluster 0x00000005's Attribute 0x00000000 is 0 ** I (2283) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x0000FFFC is 1 ** I (2293) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00004003 is null ** I (2313) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 1 ** I (2323) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000006's Attribute 0x00000000 is 1 ** I (2333) chip[ZCL]: Endpoint 1 On/off already set to new value I (2343) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000002 is 1 ** I (2353) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000003 is 254 ** I (2363) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x0000FFFC is 3 ** I (2373) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 ** I (2383) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00004000 is 64 ** I (2393) esp_matter_attribute: ** W : Endpoint 0x0001's Cluster 0x00000008's Attribute 0x00000000 is 64 ** I (2413) esp_matter_attribute: ** R : Endpoint 0x0001's Cluster 0x00000300's Attribute 0x00004010 is null ** I (2423) esp_matter_core: Dynamic endpoint 1 added I (2433) chip[DL]: WIFI_EVENT_STA_START W (24[0m I (2453) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable) I (2453) chip[DL]: Device already advertising, stop active advertisement and restart I (2463) NimBLE: GAP procedure initiated: stop advertising.

I (2463) NimBLE: GAP procedure initiated: advertise; I (2473) NimBLE: disc_mode=2 I (2473) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40 I (2493) NimBLE:

I (2493) app_main: Commissioning window opened

I (4673) chip[DL]: BLE GAP connection established (con 0) I (4673) chip[DL]: CHIPoBLE advertising stopped I (5473) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (5483) chip[BLE]: local and remote recv window sizes = 5 I (5483) chip[BLE]: selected BTP version 4 I (5493) chip[BLE]: using BTP fragment sizes rx 244 / tx 244. I (5503) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 1 I (5503) chip[DL]: CHIPoBLE subscribe received I (5503) NimBLE: GATT procedure initiated: indicate; I (5513) NimBLE: att_handle=14

I (5563) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (5563) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (5573) chip[EM]: >>> [E:48950r S:0 M:14122677] (U) Msg RX from 0:226869320A2E5D36 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) I (5593) chip[EM]: <<< [E:48950r S:0 M:160299339] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) I (5593) chip[IN]: (U) Sending msg 160299339 to IP address 'BLE' I (5613) NimBLE: GATT procedure initiated: indicate; I (5613) NimBLE: att_handle=14

I (5713) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (5743) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (5743) chip[EM]: >>> [E:48950r S:0 M:14122678] (U) Msg RX from 0:226869320A2E5D36 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) I (6783) chip[EM]: <<< [E:48950r S:0 M:160299340] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) I (6783) chip[IN]: (U) Sending msg 160299340 to IP address 'BLE' I (6803) NimBLE: GATT procedure initiated: indicate; I (6803) NimBLE: att_handle=14

E (6813) chip[DL]: Long dispatch time: 1073 ms, for event type 7 I (6853) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (6883) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (6883) chip[EM]: >>> [E:48950r S:0 M:14122679] (U) Msg RX from 0:226869320A2E5D36 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) I (6903) chip[EM]: <<< [E:48950r S:0 M:160299341] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) I (6913) chip[IN]: (U) Sending msg 160299341 to IP address 'BLE' I (6913) NimBLE: GATT procedure initiated: indicate; I (6913) NimBLE: att_handle=14

I (6933) chip[SC]: SecureSession[0x3ffc85c8]: Moving from state 'kEstablishing' --> 'kActive' I (6933) chip[SVR]: Commissioning completed session establishment step I (6943) chip[DIS]: Updating services using commissioning mode 0 I (6943) chip[DIS]: CHIP minimal mDNS started advertising. I (6963) chip[SVR]: Device completed Rendezvous process I (6963) app_main: Commissioning session started I (6963) app_main: Commissioning window closed I (6973) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (6973) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (6993) chip[EM]: >>> [E:48951r S:13123 M:60681016] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) I (7013) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) I (7013) esp_matter_attribute: ** R : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 ** I (7033) chip[EM]: <<< [E:48951r S:13123 M:211031580] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) I (7033) chip[IN]: (S) Sending msg 211031580 on secure session with LSID: 13123 I (7043) NimBLE: GATT procedure initiated: indicate; I (7043) NimBLE: att_handle=14

I (7153) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7153) NimBLE: GATT procedure initiated: indicate; I (7163) NimBLE: att_handle=14

I (7213) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7243) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (7243) chip[EM]: >>> [E:48952r S:13123 M:60681017] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (7263) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030 I (7263) chip[FS]: GeneralCommissioning: Received ArmFailSafe (30s) I (7273) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 4 ** I (7293) chip[EM]: <<< [E:48952r S:13123 M:211031581] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (7293) chip[IN]: (S) Sending msg 211031581 on secure session with LSID: 13123 I (7303) NimBLE: GATT procedure initiated: indicate; I (7303) NimBLE: att_handle=14

I (7363) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7363) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (7373) chip[EM]: >>> [E:48953r S:13123 M:60681018] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (7383) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x00000030 I (7393) chip[DL]: NVS set: chip-config/reg-location = 0 (0x0) I (7403) chip[DL]: NVS set: chip-config/country-code = "XX" I (7403) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 5 ** I (7423) chip[EM]: <<< [E:48953r S:13123 M:211031582] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (7433) chip[IN]: (S) Sending msg 211031582 on secure session with LSID: 13123 I (7433) NimBLE: GATT procedure initiated: indicate; I (7453) NimBLE: att_handle=14

I (7513) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7513) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (7533) chip[EM]: >>> [E:48954r S:13123 M:60681019] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (7533) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E I (7543) chip[ZCL]: OpCreds: Certificate Chain request received for PAI I (7563) chip[EM]: <<< [E:48954r S:13123 M:211031583] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (7563) chip[IN]: (S) Sending msg 211031583 on secure session with LSID: 13123 I (7573) NimBLE: GATT procedure initiated: indicate; I (7583) NimBLE: att_handle=14

I (7633) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7633) NimBLE: GATT procedure initiated: indicate; I (7643) NimBLE: att_handle=14

I (7693) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7693) NimBLE: GATT procedure initiated: indicate; I (7703) NimBLE: att_handle=14

I (7753) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7753) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (7763) chip[EM]: >>> [E:48955r S:13123 M:60681020] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (7773) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E I (7783) chip[ZCL]: OpCreds: Certificate Chain request received for DAC I (7803) chip[EM]: <<< [E:48955r S:13123 M:211031584] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (7803) chip[IN]: (S) Sending msg 211031584 on secure session with LSID: 13123 I (7813) NimBLE: GATT procedure initiated: indicate; I (7813) NimBLE: att_handle=14

I (7873) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7873) NimBLE: GATT procedure initiated: indicate; I (7883) NimBLE: att_handle=14

I (7933) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7933) NimBLE: GATT procedure initiated: indicate; I (7943) NimBLE: att_handle=14

I (7993) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (7993) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (8003) chip[EM]: >>> [E:48956r S:13123 M:60681021] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (8013) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003E I (8023) chip[ZCL]: OpCreds: Received an AttestationRequest command I (8133) chip[ZCL]: OpCreds: AttestationRequest successful. I (8133) chip[EM]: <<< [E:48956r S:13123 M:211031585] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (8153) chip[IN]: (S) Sending msg 211031585 on secure session with LSID: 13123 I (8153) NimBLE: GATT procedure initiated: indicate; I (8163) NimBLE: att_handle=14

I (8233) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (8233) NimBLE: GATT procedure initiated: indicate; I (8243) NimBLE: att_handle=14

I (8293) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (8293) NimBLE: GATT procedure initiated: indicate; I (8303) NimBLE: att_handle=14

I (8353) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (8413) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (8413) chip[EM]: >>> [E:48957r S:13123 M:60681022] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (8433) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030 I (8433) chip[FS]: GeneralCommissioning: Received ArmFailSafe (600s) I (8443) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 13 ** I (8463) chip[EM]: <<< [E:48957r S:13123 M:211031586] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (8463) chip[IN]: (S) Sending msg 211031586 on secure session with LSID: 13123 I (8473) NimBLE: GATT procedure initiated: indicate; I (8473) NimBLE: att_handle=14

I (8533) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (8533) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (8543) chip[EM]: >>> [E:48958r S:13123 M:60681023] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (8553) esp_matter_command: Received command 0x00000004 for endpoint 0x0000's cluster 0x0000003E I (8563) chip[ZCL]: OpCreds: Received a CSRRequest command I (8753) chip[ZCL]: OpCreds: AllocatePendingOperationalKey succeeded I (8853) chip[ZCL]: OpCreds: CSRRequest successful. I (8853) chip[EM]: <<< [E:48958r S:13123 M:211031587] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (8873) chip[IN]: (S) Sending msg 211031587 on secure session with LSID: 13123 I (8873) NimBLE: GATT procedure initiated: indicate; I (8883) NimBLE: att_handle=14

I (8923) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (8923) NimBLE: GATT procedure initiated: indicate; I (8933) NimBLE: att_handle=14

I (8983) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (9013) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (9073) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (9073) chip[EM]: >>> [E:48959r S:13123 M:60681024] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (9093) esp_matter_command: Received command 0x0000000B for endpoint 0x0000's cluster 0x0000003E I (9093) chip[ZCL]: OpCreds: Received an AddTrustedRootCertificate command I (9433) chip[ZCL]: OpCreds: AddTrustedRootCertificate successful. I (9443) chip[EM]: <<< [E:48959r S:13123 M:211031588] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) I (9453) chip[IN]: (S) Sending msg 211031588 on secure session with LSID: 13123 I (9453) NimBLE: GATT procedure initiated: indicate; I (9473) NimBLE: att_handle=14

I (9523) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (9523) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (9583) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (9583) chip[EM]: >>> [E:48960r S:13123 M:60681025] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) I (9603) esp_matter_command: Received command 0x00000006 for endpoint 0x0000's cluster 0x0000003E I (9603) chip[ZCL]: OpCreds: Received an AddNOC command I (9623) chip[FP]: Validating NOC chain I (9953) chip[FP]: NOC chain validation successful I (9963) chip[FP]: Added new fabric at index: 0x1 I (9963) chip[FP]: Assigned compressed fabric ID: 0xEA73487ACEC81C8F, node ID: 0x0000000000000010 I (9973) chip[TS]: Last Known Good Time: 2023-11-08T12:45:41 I (9973) chip[TS]: New proposed Last Known Good Time: 2021-06-10T00:00:00 I (9983) chip[TS]: Retaining current Last Known Good Time I (10073) chip[ZCL]: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 I (10073) chip[DIS]: Advertise operational node EA73487ACEC81C8F-0000000000000010 I (10083) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: EA73487ACEC81C8F-0000000000000010. I (10103) chip[DIS]: mDNS service published: _matter._tcp I (10103) chip[ZCL]: OpCreds: successfully created fabric index 0x1 via AddNOC I (10113) chip[EM]: <<< [E:48960r S:13123 M:211031589] (S) Msg TX to 1:FFFFFFFB00000000 [1C8F] --- Type 0001:09 (IM:InvokeCommandResponse) I (10123) chip[IN]: (S) Sending msg 211031589 on secure session with LSID: 13123 I (10133) NimBLE: GATT procedure initiated: indicate; I (10133) NimBLE: att_handle=14

I (10143) app_main: Fabric is updated I (10183) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (10183) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (10203) chip[EM]: >>> [E:48961r S:13123 M:60681026] (S) Msg RX from 1:FFFFFFFB00000000 [1C8F] --- Type 0001:08 (IM:InvokeCommandRequest) I (10203) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 20 ** I (10223) chip[EM]: <<< [E:48961r S:13123 M:211031590] (S) Msg TX to 1:FFFFFFFB00000000 [1C8F] --- Type 0001:09 (IM:InvokeCommandResponse) I (10233) chip[IN]: (S) Sending msg 211031590 on secure session with LSID: 13123 I (10233) NimBLE: GATT procedure initiated: indicate; I (10243) NimBLE: att_handle=14

I (10303) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (10303) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (10313) chip[EM]: >>> [E:48962r S:13123 M:60681027] (S) Msg RX from 1:FFFFFFFB00000000 [1C8F] --- Type 0001:08 (IM:InvokeCommandRequest) I (10323) chip[NP]: ESP NetworkCommissioningDelegate: SSID: ObloMobileNetis W (10333) wifi:Haven't to connect to a suitable AP now! I (10333) chip[DL]: WiFi station mode change: Enabled -> Disabled I (10393) chip[DL]: WiFi station mode change: Disabled -> Enabled W (10393) wifi:Haven't to connect to a suitable AP now! I (10393) chip[DL]: Attempting to connect WiFi station interface I (10413) chip[DL]: WiFi station state change: NotConnected -> Connecting I (10413) chip[DL]: Done driving station state, nothing else to do... W (10423) wifi:Haven't to connect to a suitable AP now! I (10423) chip[DL]: Attempting to connect WiFi station interface E (10423) wifi:sta is connecting, return error E (10443) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN W (10443) wifi:Haven't to connect to a suitable AP now! I (10443) chip[DL]: Attempting to connect WiFi station interface E (10453) wifi:sta is connecting, return error E (10453) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN W (10463) wifi:Haven't to connect to a suitable AP now! E (10473) chip[DL]: Failed to get configured network when updating network status: Error ESP32:0x0500300F I (11393) wifi:new:<5,0>, old:<1,0>, ap:<255,255>, sta:<5,0>, prof:1 I (12143) wifi:state: init -> auth (b0) I (12153) wifi:state: auth -> assoc (0) I (12163) wifi:state: assoc -> run (10) I (12173) wifi:idx:0 (ifx:0, 08:10:77:33:34:03), tid:0, ssn:0, winSize:64 I (12193) wifi:connected with ObloMobileNetis, aid = 6, channel 5, BW20, bssid = 08:10:77:33:34:03 I (12203) wifi:security: WPA2-PSK, phy: bgn, rssi: -45 I (12213) wifi:pm start, type: 1

I (12223) wifi:AP's beacon interval = 102400 us, DTIM period = 3 I (12223) chip[DL]: WIFI_EVENT_STA_CONNECTED I (12223) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded I (12233) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected I (12243) chip[DL]: WiFi station interface connected I (12243) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 24 ** I (12263) chip[EM]: <<< [E:48962r S:13123 M:211031591] (S) Msg TX to 1:FFFFFFFB00000000 [1C8F] --- Type 0001:09 (IM:InvokeCommandResponse) I (12273) chip[IN]: (S) Sending msg 211031591 on secure session with LSID: 13123 I (12283) NimBLE: GATT procedure initiated: indicate; I (12283) NimBLE: att_handle=14

I (12293) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged I (12303) chip[DL]: Done driving station state, nothing else to do... I (12303) chip[DIS]: Advertise operational node EA73487ACEC81C8F-0000000000000010 I (12313) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: EA73487ACEC81C8F-0000000000000010. I (12323) chip[DIS]: mDNS service published: _matter._tcp I (12333) chip[SVR]: Operational advertising enabled I (12333) chip[DL]: Updating advertising data I (12403) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (13943) chip[DL]: IP_EVENT_GOT_IP6 I (13943) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:d6d4:daff:fe0f:dc88 I (13953) app_main: Interface IP Address changed I (13953) chip[DIS]: Updating services using commissioning mode 0 I (13963) chip[DIS]: CHIP minimal mDNS started advertising. I (13983) chip[DIS]: Advertise operational node EA73487ACEC81C8F-0000000000000010 I (13983) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: EA73487ACEC81C8F-0000000000000010. I (13993) chip[DIS]: mDNS service published: _matter._tcp E (14003) chip[SVR]: Server initialization complete I (14003) chip[DIS]: Updating services using commissioning mode 0 I (14013) chip[DIS]: CHIP minimal mDNS started advertising. I (14023) chip[DIS]: Advertise operational node EA73487ACEC81C8F-0000000000000010 I (14023) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: EA73487ACEC81C8F-0000000000000010. I (14043) chip[DIS]: mDNS service published: _matter._tcp I (14053) chip[IM]: No subscriptions to resume I (14723) esp_netif_handlers: sta ip: 192.168.1.118, mask: 255.255.255.0, gw: 192.168.1.2 I (14723) chip[DL]: IP_EVENT_STA_GOT_IP I (14723) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.1.118/255.255.255.0 gateway 192.168.1.2 I (14733) chip[DL]: IPv4 Internet connectivity ESTABLISHED I (14743) app_main: Interface IP Address changed I (14753) chip[DIS]: Updating services using commissioning mode 0 I (14763) chip[DIS]: CHIP minimal mDNS started advertising. I (14773) chip[DIS]: Advertise operational node EA73487ACEC81C8F-0000000000000010 I (14783) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: EA73487ACEC81C8F-0000000000000010. I (14803) chip[DIS]: mDNS service published: _matter._tcp I (14923) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (17423) NimBLE: GATT procedure initiated: indicate; I (17423) NimBLE: att_handle=14

I (17593) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (20083) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (22583) NimBLE: GATT procedure initiated: indicate; I (22583) NimBLE: att_handle=14

I (22663) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (25183) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (27683) NimBLE: GATT procedure initiated: indicate; I (27683) NimBLE: att_handle=14

I (27763) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (30283) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (32783) NimBLE: GATT procedure initiated: indicate; I (32783) NimBLE: att_handle=14

I (32863) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (35383) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (37883) NimBLE: GATT procedure initiated: indicate; I (37883) NimBLE: att_handle=14

I (37963) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (40483) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (42983) NimBLE: GATT procedure initiated: indicate; I (42983) NimBLE: att_handle=14

I (43063) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (45583) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (48083) NimBLE: GATT procedure initiated: indicate; I (48083) NimBLE: att_handle=14

I (48163) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (50683) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (53183) NimBLE: GATT procedure initiated: indicate; I (53183) NimBLE: att_handle=14

I (53263) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (55783) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (58283) NimBLE: GATT procedure initiated: indicate; I (58283) NimBLE: att_handle=14

I (58363) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (60883) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (63383) NimBLE: GATT procedure initiated: indicate; I (63383) NimBLE: att_handle=14

I (63493) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (66013) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (68513) NimBLE: GATT procedure initiated: indicate; I (68513) NimBLE: att_handle=14

I (68623) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (71143) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (73643) NimBLE: GATT procedure initiated: indicate; I (73643) NimBLE: att_handle=14

I (73723) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (76243) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (78743) NimBLE: GATT procedure initiated: indicate; I (78743) NimBLE: att_handle=14

I (78823) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (81343) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (83843) NimBLE: GATT procedure initiated: indicate; I (83843) NimBLE: att_handle=14

I (83923) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (86443) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (88943) NimBLE: GATT procedure initiated: indicate; I (88943) NimBLE: att_handle=14

I (89053) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (91543) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (94043) NimBLE: GATT procedure initiated: indicate; I (94043) NimBLE: att_handle=14

I (94123) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (96643) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (99143) NimBLE: GATT procedure initiated: indicate; I (99143) NimBLE: att_handle=14

I (99223) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (101743) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (104243) NimBLE: GATT procedure initiated: indicate; I (104243) NimBLE: att_handle=14

I (104323) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (106843) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (109343) NimBLE: GATT procedure initiated: indicate; I (109343) NimBLE: att_handle=14

I (109423) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (111943) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (114443) NimBLE: GATT procedure initiated: indicate; I (114443) NimBLE: att_handle=14

I (114553) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (117043) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (119543) NimBLE: GATT procedure initiated: indicate; I (119543) NimBLE: att_handle=14

I (119623) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (122143) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (124643) NimBLE: GATT procedure initiated: indicate; I (124643) NimBLE: att_handle=14

I (124723) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (127243) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12 I (129743) NimBLE: GATT procedure initiated: indicate; I (129743) NimBLE: att_handle=14

I (129823) chip[DL]: Confirm received for CHIPoBLE TX characteristic indication (con 0) status= 14 I (132343) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12`

after that FailSafe will remove fabric from esp32

E (677372) chip[SVR]: Failsafe timer expired I (677372) chip[SC]: SecureSession[0x3ffc85c8]: Moving from state 'kActive' --> 'kPendingEviction' E (677382) chip[SVR]: Commissioning failed (attempt 1): 32 I (677392) chip[BLE]: Releasing end point's BLE connection back to application. I (677402) chip[DIS]: Updating services using commissioning mode 1 I (677402) chip[DIS]: CHIP minimal mDNS started advertising. I (677432) chip[DIS]: Advertise operational node 78C325E2815E1D72-000000000001B669 I (677442) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 78C325E2815E1D72-000000000001B669. I (677462) chip[DIS]: mDNS service published: _matter._tcp I (677462) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 I (677472) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B8D9488A9AA17405. I (677502) chip[DIS]: mDNS service published: _matterc._udp E (677502) chip[ZCL]: OpCreds: Got FailSafeTimerExpired E (677502) chip[ZCL]: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! I (677512) chip[SC]: SecureSession[0x3ffc8680]: Moving from state 'kActive' --> 'kPendingEviction' I (677532) chip[SC]: SecureSession[0x3ffc8738]: Moving from state 'kActive' --> 'kPendingEviction' E (677532) chip[FP]: Reverting pending fabric data for fabric 0x1 E (677562) chip[FP]: Warning: metadata not found during delete of fabric 0x1 I (677632) chip[FP]: Fabric (0x1) deleted. I (677632) chip[ZCL]: OpCreds: Fabric index 0x1 was removed I (677642) chip[DIS]: Updating services using commissioning mode 1 I (677652) chip[DIS]: CHIP minimal mDNS started advertising. I (677692) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1 I (677702) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: B8D9488A9AA17405. I (677722) chip[DIS]: mDNS service published: _matterc._udp I (677932) chip[TS]: Pending Last Known Good Time: 2023-11-08T12:45:41 I (677932) chip[TS]: Previous Last Known Good Time: 2023-11-08T12:45:41 I (677932) chip[TS]: Reverted Last Known Good Time to previous value E (677962) chip[FP]: Warning: metadata not found during delete of fabric 0x1 E (677982) chip[ZCL]: OpCreds: failed to delete fabric at index 1: d8 I (677982) esp_matter_attribute: ** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 ** I (677992) app_main: Commissioning failed, fail safe timer expired I (678002) chip[FS]: Fail-safe cleanly disarmed I (678012) app_main: Commissioning window opened I (678012) app_main: Fabric will be removed I (678012) app_main: Fabric removed successfully I (678022) app_main: Fabric will be removed E (691882) chip[IN]: Data received on an unknown session (LSID=7244). Dropping it! I (692012) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 I (692012) chip[DL]: CHIPoBLE unsubscribe received E (692012) chip[BLE]: no endpoint for unsub recvd I (692032) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable) E (692032) chip[DL]: ble_gap_adv_start() failed: Error CHIP:0x0000000B E (692042) chip[DL]: Start advertising failed: Error CHIP:0x0000000B E (692042) chip[DL]: Disabling CHIPoBLE service due to error: Error CHIP:0x0000000B E (692292) chip[IN]: Data received on an unknown session (LSID=7244). Dropping it! E (692602) chip[IN]: Data received on an unknown session (LSID=7244). Dropping it! I (693152) chip[DL]: BLE GAP connection terminated (con 0 reason 0x213) E (693212) chip[IN]: Data received on an unknown session (LSID=7244). Dropping it! E (694032) chip[IN]: Data received on an unknown session (LSID=7244). Dropping it! I (750882) ROUTE_HOOK: Received RIO I (750882) ROUTE_HOOK: prefix FD08:E2D:3E80:1:: lifetime 1800 I (902152) chip[SVR]: Closing pairing window I (902162) chip[DIS]: Updating services using commissioning mode 0 I (902162) chip[DIS]: CHIP minimal mDNS started advertising. I (902192) app_main: Commissioning window closed I (934982) ROUTE_HOOK: Received RIO I (934982) ROUTE_HOOK: prefix FD08:E2D:3E80:1:: lifetime 1800

suktry commented 10 months ago

Hello, I encountered the same issue as you. Could you please share how you resolved it? Any guidance you can provide would be appreciated. Thank you.

jacqueshsu commented 10 months ago

Which interface for your network? Wifi or Ethernet?

suktry commented 10 months ago

Which interface for your network? Wifi or Ethernet?

wifi

jacqueshsu commented 10 months ago

I think the issue is related to the WiFi driver. Do you have other wifi card? You can use it to confirm the root case.

suktry commented 10 months ago

I think the issue is related to the WiFi driver. Do you have other wifi card? You can use it to confirm the root case.

I sincerely apologize for not expressing my actual scenario clearly. I am using a virtual machine running Ubuntu, configuring the setup through Bluetooth using chip-tool pairing ble-thread. The hardware device utilized is the esp32h2, and the thread border router is developed with the esp32s3 in conjunction with the esp32h2 development kit. The thread border router connects to the local network via WiFi. In this setup, I can achieve pairing and operations using the Chip application on Android, but the issue persists consistently when using Ubuntu.