Error Adding Matter-enabled Nest Thermostat

wwelles · June 14, 2023, 2:23pm

My Nest got the Matter update finally yesterday. When I tried to add it to Home Assistant from the Google Home app, I get the following in my matter server logs. I’m running HA (2023.6) and the matter server (checked out main as part of my troubleshooting) in Docker using docker compose, snippet below (with stuff removed):

  homeassistant:
    container_name: homeassistant
    image: "ghcr.io/home-assistant/home-assistant:2023.6"
    volumes:
      - /run/dbus:/run/dbus:ro
    restart: unless-stopped
    privileged: true
    network_mode: host
  matter-server:
    build:
      context: ./source/python-matter-server
      dockerfile: Dockerfile.dev
    image: matter-server:latest
    container_name: matter-server
    restart: unless-stopped
    # Required for mDNS to work correctly
    network_mode: host
    security_opt:
      # needed for bluetooth via dbus
      - apparmor:unconfined
    volumes:
      - /run/dbus:/run/dbus:ro

Unfortunately it fails pretty quickly and gives me this in the matter server logs.

2023-06-14 14:16:17 wwelles-laptop chip.CTL[1] INFO Setting attestation nonce to random value
2023-06-14 14:16:17 wwelles-laptop chip.CTL[1] INFO Setting CSR nonce to random value
2023-06-14 14:16:17 wwelles-laptop chip.CTL[1] INFO Starting commissioning discovery over BLE
2023-06-14 14:16:17 wwelles-laptop chip.CTL[1] INFO Starting commissioning discovery over DNS-SD
2023-06-14 14:16:17 wwelles-laptop chip.DL[1] ERROR FAIL: NULL apEndpoint->mpAdapter in bluezObjectsSetup
2023-06-14 14:16:17 wwelles-laptop chip.CTL[1] ERROR Commissioning discovery over BLE failed: ../src/platform/Linux/BLEManagerImpl.cpp:682: CHIP Error 0x00000003: Incorrect state
2023-06-14 14:16:17 wwelles-laptop chip.-[1] ERROR ../src/platform/Linux/BLEManagerImpl.cpp:682: CHIP Error 0x00000003: Incorrect state at ../src/controller/SetUpCodePairer.cpp:299
2023-06-14 14:16:17 wwelles-laptop chip.BLE[1] ERROR No adapter available for new connection establishment
2023-06-14 14:16:18 wwelles-laptop chip.CTL[1] INFO Discovered device to be commissioned over DNS-SD
2023-06-14 14:16:18 wwelles-laptop chip.CTL[1] INFO Attempting PASE connection to UDP:[2604:3d09:485:d300:221f:3bff:fecb:660d]:5540
2023-06-14 14:16:18 wwelles-laptop chip.EM[1] INFO <<< [E:274i M:202492555] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
2023-06-14 14:16:18 wwelles-laptop chip.IN[1] INFO (U) Sending msg 202492555 to IP address 'UDP:[2604:3d09:485:d300:221f:3bff:fecb:660d]:5540'
2023-06-14 14:16:18 wwelles-laptop chip.CTL[1] INFO Commission called for node ID 0x000000000000000A
2023-06-14 14:16:18 wwelles-laptop chip.CTL[1] INFO Discovered device to be commissioned over DNS-SD
2023-06-14 14:16:18 wwelles-laptop chip.CTL[1] INFO Discovered device to be commissioned over DNS-SD
2023-06-14 14:16:19 wwelles-laptop chip.EM[1] INFO >>> [E:274i M:224093679 (Ack:202492555)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:19 wwelles-laptop chip.EM[1] INFO >>> [E:274i M:224093680 (Ack:202492555)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
2023-06-14 14:16:19 wwelles-laptop chip.EM[1] INFO <<< [E:274i M:202492556 (Ack:224093680)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
2023-06-14 14:16:19 wwelles-laptop chip.IN[1] INFO (U) Sending msg 202492556 to IP address 'UDP:[2604:3d09:485:d300:221f:3bff:fecb:660d%enx106530ce2676]:5540'
2023-06-14 14:16:19 wwelles-laptop chip.EM[1] INFO >>> [E:274i M:224093681 (Ack:202492556)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:274i M:224093682 (Ack:202492556)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:274i M:202492557 (Ack:224093682)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (U) Sending msg 202492557 to IP address 'UDP:[2604:3d09:485:d300:221f:3bff:fecb:660d%enx106530ce2676]:5540'
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:274i M:224093683 (Ack:202492557)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:274i M:224093684 (Ack:202492557)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
2023-06-14 14:16:20 wwelles-laptop chip.SC[1] INFO SecureSession[0x7f9254025810]: Moving from state 'kEstablishing' --> 'kActive'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'ReadCommissioningInfo'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Sending request for commissioning information
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:275i M:243008298] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008298 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:274i M:202492558 (Ack:224093684)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (U) Sending msg 202492558 to IP address 'UDP:[2604:3d09:485:d300:221f:3bff:fecb:660d%enx106530ce2676]:5540'
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:275i M:28990554 (Ack:243008298)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Successfully finished commissioning step 'ReadCommissioningInfo'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'ArmFailSafe'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Arming failsafe (60 seconds)
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:276i M:243008299] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008299 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:275i M:243008300 (Ack:28990554)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008300 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:276i M:28990555 (Ack:243008299)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2023-06-14 14:16:20 wwelles-laptop chip.DMG[1] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Received ArmFailSafe response errorCode=0
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Successfully finished commissioning step 'ArmFailSafe'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'ConfigRegulatory'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Setting Regulatory Config
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Device does not support configurable regulatory location
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:277i M:243008301] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008301 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:276i M:243008302 (Ack:28990555)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008302 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:277i M:28990556 (Ack:243008301)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2023-06-14 14:16:20 wwelles-laptop chip.DMG[1] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Received SetRegulatoryConfig response errorCode=0
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Successfully finished commissioning step 'ConfigRegulatory'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'SendPAICertificateRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Sending request for PAI certificate
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:278i M:243008303] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008303 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:277i M:243008304 (Ack:28990556)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008304 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:278i M:28990557 (Ack:243008303)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2023-06-14 14:16:20 wwelles-laptop chip.DMG[1] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Received certificate chain from the device
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Successfully finished commissioning step 'SendPAICertificateRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'SendDACCertificateRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Sending request for DAC certificate
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:279i M:243008305] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008305 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:278i M:243008306 (Ack:28990557)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008306 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:279i M:28990558 (Ack:243008305)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2023-06-14 14:16:20 wwelles-laptop chip.DMG[1] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Received certificate chain from the device
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Successfully finished commissioning step 'SendDACCertificateRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'SendAttestationRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Sending Attestation Request to the device.
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:280i M:243008307] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008307 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO <<< [E:279i M:243008308 (Ack:28990558)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008308 on secure session with LSID: 26855
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:280i M:28990559 (Ack:243008307)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:20 wwelles-laptop chip.EM[1] INFO >>> [E:280i M:28990560 (Ack:243008307)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2023-06-14 14:16:20 wwelles-laptop chip.DMG[1] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Received Attestation Information from the device
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Successfully finished commissioning step 'SendAttestationRequest'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'AttestationVerification'
2023-06-14 14:16:20 wwelles-laptop chip.CTL[1] INFO Verifying attestation
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] ERROR Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] INFO Error on commissioning step 'AttestationVerification': '../src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] ERROR Failed to perform commissioning step 8
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] INFO Going from commissioning step 'AttestationVerification' with lastErr = '../src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] INFO Performing next commissioning step 'Cleanup' with completion status = '../src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] INFO Expiring failsafe on proxy 0x7f9254034a40
2023-06-14 14:16:21 wwelles-laptop chip.EM[1] INFO <<< [E:281i M:243008309] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
2023-06-14 14:16:21 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008309 on secure session with LSID: 26855
2023-06-14 14:16:21 wwelles-laptop chip.EM[1] INFO <<< [E:280i M:243008310 (Ack:28990560)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
2023-06-14 14:16:21 wwelles-laptop chip.IN[1] INFO (S) Sending msg 243008310 on secure session with LSID: 26855
2023-06-14 14:16:21 wwelles-laptop chip.EM[1] INFO >>> [E:281i M:28990561 (Ack:243008309)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2023-06-14 14:16:21 wwelles-laptop chip.DMG[1] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] INFO Failsafe disarmed
2023-06-14 14:16:21 wwelles-laptop chip.CTL[1] INFO Successfully finished commissioning step 'Cleanup'
2023-06-14 14:16:21 wwelles-laptop chip.SC[1] INFO SecureSession[0x7f9254025810]: Moving from state 'kActive' --> 'kPendingEviction'
2023-06-14 14:16:21 wwelles-laptop matter_server.server.client_handler[1] ERROR [140266597523824] Error handling message: CommandMessage(message_id='26df1d23d26a422eae62bef38aa01ffc', command='commission_with_code', args={'code': '14926849096'})
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/matter_server/server/client_handler.py", line 188, in _run_handler
    result = await result
  File "/usr/local/lib/python3.10/site-packages/matter_server/server/device_controller.py", line 133, in commission_with_code
    raise NodeCommissionFailed(
matter_server.common.errors.NodeCommissionFailed: Commission with code failed for node 10
2023-06-14 14:16:21 wwelles-laptop chip.EM[1] ERROR Failed to send Solitary ack for MessageCounter:28990561 on exchange 281i:../src/messaging/ExchangeContext.cpp:144: CHIP Error 0x00000002: Connection aborted

wwelles · June 14, 2023, 4:49pm

Got it working, thought I’d post here in case it helps someone else.

My issue was the matter-server. Although I did pull the new code from the Github repo, I failed to re-build the docker container. Once I did that, it worked!