search

dresden-elektronik / openthread-r21

OpenThread Border Router for R21 based ConBee II and RaspBee II
BSD 3-Clause "New" or "Revised" License
38 stars 0 forks source link

Common issue with ConBee II thread/matter firmware in HA #5

Open mariuszpreiss opened 2 months ago

mariuszpreiss commented 2 months ago

I am having issues with ConBee II with the newest thread firmware ot-rcp-cb2_0x01010700.GCF when adding a matter over thread device (Aqara U200) to HA and I see I'm not alone - check here and here

I'm having the same - I followed guide from phoscon and I was trying to comission device using android phone, directly from HA (via matter ui) - nothing. It always timeouts when waiting for device to connect to thread device with an error "No connection to Thread network ha-thread-..."

HA is running on a VM, USB shared from the host with Bluetooth and ConBee II itself (it was working well while managing my zigbee network). I verfied and tried everyting I could find on the internet including this great post about matter troubleshooting.

Logs below are when I used local USB BT stick to comission directly from matter UI, providing dataset and pin for matter. It's the most verbose I could get

I'm happy to provide more info if required.

2024-08-30 20:18:47.121 (Dummy-2) CHIP_DETAIL [chip.native.DMG]                     0x1 = "" (0 chars), 
2024-08-30 20:18:47.121 (Dummy-2) CHIP_DETAIL [chip.native.DMG]                 },
2024-08-30 20:18:47.121 (Dummy-2) CHIP_DETAIL [chip.native.DMG]             },
2024-08-30 20:18:47.122 (Dummy-2) CHIP_DETAIL [chip.native.DMG]             
2024-08-30 20:18:47.122 (Dummy-2) CHIP_DETAIL [chip.native.DMG]         },
2024-08-30 20:18:47.122 (Dummy-2) CHIP_DETAIL [chip.native.DMG]         
2024-08-30 20:18:47.122 (Dummy-2) CHIP_DETAIL [chip.native.DMG]     ],
2024-08-30 20:18:47.122 (Dummy-2) CHIP_DETAIL [chip.native.DMG]     
2024-08-30 20:18:47.123 (Dummy-2) CHIP_DETAIL [chip.native.DMG]     InteractionModelRevision = 11
2024-08-30 20:18:47.123 (Dummy-2) CHIP_DETAIL [chip.native.DMG] },
2024-08-30 20:18:47.123 (Dummy-2) CHIP_PROGRESS [chip.native.DMG] Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
2024-08-30 20:18:47.123 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Received ArmFailSafe response errorCode=0
2024-08-30 20:18:47.123 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Successfully finished commissioning step 'FailsafeBeforeThreadEnable'
2024-08-30 20:18:47.123 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Commissioning stage next step: 'FailsafeBeforeThreadEnable' -> 'ThreadNetworkEnable'
2024-08-30 20:18:47.124 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Performing next commissioning step 'ThreadNetworkEnable'
2024-08-30 20:18:47.124 (Dummy-2) CHIP_DETAIL [chip.native.DMG] ICR moving to [AddingComm]
2024-08-30 20:18:47.124 (Dummy-2) CHIP_DETAIL [chip.native.DMG] ICR moving to [AddedComma]
2024-08-30 20:18:47.125 (Dummy-2) CHIP_PROGRESS [chip.native.EM] <<< [E:1162i S:6832 M:55680032] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
2024-08-30 20:18:47.126 (Dummy-2) CHIP_DETAIL [chip.native.DMG] ICR moving to [AwaitingRe]
2024-08-30 20:18:47.127 (Dummy-2) CHIP_DETAIL [chip.native.DMG] ICR moving to [AwaitingDe]
2024-08-30 20:18:47.198 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:18:49.674 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:18:49.675 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:18:52.239 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:18:54.714 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:18:54.715 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:18:57.278 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:18:59.753 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:18:59.754 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:02.320 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:04.795 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:04.796 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:07.358 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:09.834 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:09.835 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:12.399 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:14.875 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:14.876 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:17.439 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:19.915 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:19.916 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:22.125 (Dummy-2) CHIP_PROGRESS [chip.native.DMG] Time out! failed to receive invoke command response from Exchange: 1162i with Node: <FFFFFFFB00000000, 0>
2024-08-30 20:19:22.125 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Received failure response src/app/CommandSender.cpp:328: CHIP Error 0x00000032: Timeout

2024-08-30 20:19:22.125 (Dummy-2) CHIP_ERROR [chip.native.CTL] Error on commissioning step 'ThreadNetworkEnable': 'src/app/CommandSender.cpp:328: CHIP Error 0x00000032: Timeout'
2024-08-30 20:19:22.126 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Going from commissioning step 'ThreadNetworkEnable' with lastErr = 'src/app/CommandSender.cpp:328: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
2024-08-30 20:19:22.126 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Performing next commissioning step 'Cleanup' with completion status = 'src/app/CommandSender.cpp:328: CHIP Error 0x00000032: Timeout'
2024-08-30 20:19:22.126 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Successfully finished commissioning step 'Cleanup'
2024-08-30 20:19:22.126 (Dummy-2) CHIP_PROGRESS [chip.native.CTL] Commissioning complete for node ID 0x000000000000000B: src/app/CommandSender.cpp:328: CHIP Error 0x00000032: Timeout
2024-08-30 20:19:22.127 (Dummy-2) WARNING [chip.ChipDeviceCtrl] Failed to commission: src/app/CommandSender.cpp:328: CHIP Error 0x00000032: Timeout
2024-08-30 20:19:22.127 (Dummy-2) CHIP_DETAIL [chip.native.DMG] ICR moving to [AwaitingDe]
2024-08-30 20:19:22.128 (MainThread) ERROR [matter_server.server.client_handler] [140578575743504] Error while handling: commission_with_code: Commission with code failed for node 11.
2024-08-30 20:19:22.479 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:24.955 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:24.955 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:27.519 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:29.994 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:29.994 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:32.559 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:35.080 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:35.080 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:37.646 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:40.119 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:40.120 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:42.683 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:45.160 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:45.161 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:47.724 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:50.200 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:50.200 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:52.763 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:19:55.240 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:19:55.240 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:19:57.803 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:20:00.283 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:20:00.284 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:20:02.845 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:20:05.322 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:20:05.323 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:20:07.883 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:20:10.361 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:20:10.364 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:20:12.924 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:20:15.398 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:20:15.399 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:20:17.965 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:20:20.439 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:20:20.440 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:20:23.004 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:20:25.479 (Dummy-3) CHIP_DETAIL [chip.native.DL] Indication received, conn = 0x7fdae4048720
2024-08-30 20:20:25.479 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16389
2024-08-30 20:20:28.043 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16387
2024-08-30 20:20:42.987 (Dummy-2) CHIP_ERROR [chip.native.BLE] ack recv timeout, closing ep 0x7fdb03ec9be0
2024-08-30 20:20:42.988 (Dummy-2) CHIP_DETAIL [chip.native.IN] Clearing BLE pending packets.
2024-08-30 20:20:42.990 (Dummy-2) CHIP_DETAIL [chip.native.DL] HandlePlatformSpecificBLEEvent 16388
2024-08-30 20:20:42.990 (Dummy-2) CHIP_PROGRESS [chip.native.BLE] Auto-closing end point's BLE connection.
2024-08-30 20:20:42.991 (Dummy-2) CHIP_PROGRESS [chip.native.DL] Closing BLE GATT connection (con 0x7fdae4048720)
2024-08-30 20:20:42.991 (Dummy-3) CHIP_DETAIL [chip.native.DL] BluezDisconnect peer=0C:AE:5F:99:C4:45
2024-08-30 20:20:45.595 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 2605 ms, for event type 16388
2024-08-30 20:20:45.596 (Dummy-3) CHIP_DETAIL [chip.native.DL] Bluez disconnected
2024-08-30 20:20:45.596 (Dummy-3) CHIP_PROGRESS [chip.native.DL] Bluez notify CHIPoBluez connection disconnected
b0l0k commented 2 months ago

Tested yesterday, same here.