• State Not Answered
  • Replies 14 replies
  • Subscribers 95 subscribers
  • Views 3134 views
  • Users 0 members are here
Attachments (5) Download All
Nordic Case Info
  • Case ID: 296541
Options

Android CHIPTool - Crash when interacting with clusters (groups & temperatureMeasurement)

jacobbluhm

I am seeing the Android CHIPTool crash when I send certain commands to clusters. I can read attributes from this cluster, and even send the removeAllGroups command.  The issue is with the AddGroup command in the groups cluster - Error output from android:

10-06 15:32:58.361 21352 21352 D AndroidRuntime: Shutting down VM
--------- beginning of crash
10-06 15:32:58.363 21352 21352 E AndroidRuntime: FATAL EXCEPTION: main
10-06 15:32:58.363 21352 21352 E AndroidRuntime: Process: com.google.chip.chiptool, PID: 21352
10-06 15:32:58.363 21352 21352 E AndroidRuntime: java.lang.ClassCastException: java.lang.String cannot be cast to java.lang.Integer
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at chip.devicecontroller.ClusterInfoMapping.lambda$getCommandMap$70(ClusterInfoMapping.java:7709)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at chip.devicecontroller.-$$Lambda$ClusterInfoMapping$cIWpw-xlwNrySAuCbV94O7DtfOY.invokeCommand(Unknown Source:0)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at com.google.chip.chiptool.clusterclient.clusterinteraction.ClusterDetailFragment.setInvokeCommandOnClickListener$lambda-2(ClusterDetailFragment.kt:153)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at com.google.chip.chiptool.clusterclient.clusterinteraction.ClusterDetailFragment.lambda$L3VHqSpfGvBTNuxjIdwuacnYJ6Y(Unknown Source:0)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at com.google.chip.chiptool.clusterclient.clusterinteraction.-$$Lambda$ClusterDetailFragment$L3VHqSpfGvBTNuxjIdwuacnYJ6Y.onClick(Unknown Source:11)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.view.View.performClick(View.java:7288)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.view.View.performClickInternal(View.java:7258)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.view.View.access$4000(View.java:808)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.view.View$PerformClick.run(View.java:28019)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.os.Handler.handleCallback(Handler.java:883)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.os.Handler.dispatchMessage(Handler.java:100)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.os.Looper.loop(Looper.java:214)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at android.app.ActivityThread.main(ActivityThread.java:7615)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at java.lang.reflect.Method.invoke(Native Method)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
10-06 15:32:58.363 21352 21352 E AndroidRuntime: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:964)

It seems that any command that has a parameter will result in a crash.

Unrelated to this issue I've also seen the CHIPTool crash when sending the readTemperatureMeasurementAttribute. It resulted in the same Exception: java.lang.ClassCastException

Im using the latest CHIPTool .apk in this github repo -> https://github.com/nrfconnect/sdk-connectedhomeip/releases/tag/v2.1.0

Using this .apk -> chip-tool-android_armv7l.apk

  • 0 in reply to Jørgen Holmefjord

    Yes I'm using v2.1 for both the CHIP tool and on the end device

    Here is the 802.15.4 sniffer trace which doesn't provide much information. I've confirmed the sniffer is set up correctly by viewing a successful commission with the Android ChipTool. I believe the issue is during the BLE exchange between the chip-tool and end device. I will work on providing you a BLE sniffer trace but I am having trouble filtering the Wireshark output between the end device and the Mac running the chip-tool.

    802.15.4 Sniffer trace.pcapng

    Here is the output from the Mac running the chip-tool:

    Fullscreen chip-tool output.txt Download 
    dw-216:CHIPTOOL jacobbluhm$ sudo  ./chip-tool pairing ble-thread 69 hex:0e080000000000010000000300000d35060004001fffe002082e0659eb06d26c760708fd6f1f279857684e0510738c0eae722d342679a7653dd405ca10030f4f70656e5468726561642d653263370102e2c704107127b08300d7d6789ada05996b2c7f5d0c0402a0f7f8 20202021 3840
[1666020491424] [43599:4426788] CHIP: [DL] KVS will be written to: file:///tmp/chip_kvs
[1666020491436] [43599:4426788] CHIP: [DL] _Init
[1666020491436] [43599:4426788] CHIP: [IN] UDP::Init bind&listen port=0
[1666020491436] [43599:4426788] CHIP: [IN] UDP::Init bound to port=55934
[1666020491436] [43599:4426788] CHIP: [IN] UDP::Init bind&listen port=0
[1666020491436] [43599:4426788] CHIP: [IN] UDP::Init bound to port=52321
[1666020491436] [43599:4426788] CHIP: [IN] BLEBase::Init - setting/overriding transport
[1666020491436] [43599:4426788] CHIP: [IN] TransportMgr initialized
[1666020491436] [43599:4426788] CHIP: [FP] Initializing FabricTable from persistent storage
[1666020491436] [43599:4426788] CHIP: [TS] Last Known Good Time: 2022-10-14T15:10:00
[1666020491437] [43599:4426788] CHIP: [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0F421C8A8895452, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1666020491444] [43599:4426788] CHIP: [ZCL] Using ZAP configuration...
[1666020491444] [43599:4426788] CHIP: [CTL] System State Initialized...
[1666020491444] [43599:4426788] CHIP: [CTL] Stopping commissioning discovery over DNS-SD
[1666020491444] [43599:4426788] CHIP: [CTL] Setting attestation nonce to random value
[1666020491444] [43599:4426788] CHIP: [CTL] Setting CSR nonce to random value
[1666020491444] [43599:4426788] CHIP: [IN] UDP::Init bind&listen port=5550
[1666020491444] [43599:4426788] CHIP: [IN] UDP::Init bound to port=5550
[1666020491444] [43599:4426788] CHIP: [IN] UDP::Init bind&listen port=5550
[1666020491444] [43599:4426788] CHIP: [IN] UDP::Init bound to port=5550
[1666020491444] [43599:4426788] CHIP: [IN] TransportMgr initialized
[1666020491444] [43599:4426790] CHIP: [DL] _OnPlatformEvent
[1666020491444] [43599:4426790] CHIP: [CTL] Stopping commissioning discovery over DNS-SD
[1666020491445] [43599:4426790] CHIP: [CTL] Setting attestation nonce to random value
[1666020491445] [43599:4426790] CHIP: [CTL] Setting CSR nonce to random value
[1666020491445] [43599:4426790] CHIP: [CTL] Generating NOC
[1666020491446] [43599:4426790] CHIP: [FP] Validating NOC chain
[1666020491446] [43599:4426790] CHIP: [FP] NOC chain validation successful
[1666020491446] [43599:4426790] CHIP: [FP] Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1666020491446] [43599:4426790] CHIP: [TS] Last Known Good Time: 2022-10-14T15:10:00
[1666020491446] [43599:4426790] CHIP: [TS] New proposed Last Known Good Time: 2021-01-01T00:00:00
[1666020491446] [43599:4426790] CHIP: [TS] Retaining current Last Known Good Time
[1666020491448] [43599:4426790] CHIP: [FP] Metadata for Fabric 0x1 persisted to storage.
[1666020491449] [43599:4426790] CHIP: [TS] Committing Last Known Good Time to storage: 2022-10-14T15:10:00
[1666020491450] [43599:4426790] CHIP: [CTL] Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1666020491450] [43599:4426790] CHIP: [IN] UDP::Init bind&listen port=5550
[1666020491450] [43599:4426790] CHIP: [IN] UDP::Init bound to port=5550
[1666020491450] [43599:4426790] CHIP: [IN] UDP::Init bind&listen port=5550
[1666020491450] [43599:4426790] CHIP: [IN] UDP::Init bound to port=5550
[1666020491450] [43599:4426790] CHIP: [IN] TransportMgr initialized
[1666020491456] [43599:4426790] CHIP: [BLE] NewConnection
[1666020491456] [43599:4426790] CHIP: [BLE] CancelConnection
[1666020491457] [43599:4426790] CHIP: [IN] SecureSession[0x600000b6c000]: Allocated Type:1 LSID:48673
[1666020491457] [43599:4426790] CHIP: [SC] Assigned local session key ID 48673
[1666020491457] [43599:4426790] CHIP: [SC] Including MRP parameters in PBKDF param request
[1666020491457] [43599:4426790] CHIP: [EM] <<< [E:58956i M:169116149] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1666020491457] [43599:4426790] CHIP: [IN] (U) Sending msg 169116149 to IP address 'BLE'
[1666020491457] [43599:4426790] CHIP: [IN] Message appended to BLE send queue
[1666020491457] [43599:4426790] CHIP: [SC] Sent PBKDF param request
[1666020491457] [43599:4426790] CHIP: [CTL] Setting thread operational dataset from parameters
[1666020491457] [43599:4426790] CHIP: [CTL] Setting attempt thread scan from parameters
[1666020491457] [43599:4426790] CHIP: [CTL] Setting attestation nonce to random value
[1666020491457] [43599:4426790] CHIP: [CTL] Setting CSR nonce to random value
[1666020491457] [43599:4426790] CHIP: [CTL] Commission called for node ID 0x0000000000000045
[1666020491514] [43599:4426791] CHIP: [BLE] CBManagerState: ON
[1666020495627] [43599:4426791] CHIP: [BLE] Connecting to device with discriminator: 3840
[1666020521459] [43599:4426790] CHIP: [SC] PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1666020521459] [43599:4426790] CHIP: [IN] SecureSession[0x600000b6c000]: Released - Type:1 LSID:48673
[1666020521459] [43599:4426790] CHIP: [TOO] Secure Pairing Failed
[1666020521459] [43599:4426790] CHIP: [DIS] Closing all BLE connections
[1666020521459] [43599:4426790] CHIP: [TOO] Pairing Failure: ../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout
[1666020521459] [43599:4426788] CHIP: [CTL] Shutting down the commissioner
[1666020521459] [43599:4426788] CHIP: [CTL] Stopping commissioning discovery over DNS-SD
[1666020521460] [43599:4426788] CHIP: [CTL] Shutting down the controller
[1666020521460] [43599:4426788] CHIP: [IN] Expiring all sessions for fabric 0x1!!
[1666020521460] [43599:4426788] CHIP: [FP] Forgetting fabric 0x1
[1666020521460] [43599:4426788] CHIP: [TS] Pending Last Known Good Time: 2022-10-14T15:10:00
[1666020521460] [43599:4426788] CHIP: [TS] Previous Last Known Good Time: 2022-10-14T15:10:00
[1666020521460] [43599:4426788] CHIP: [TS] Reverted Last Known Good Time to previous value
[1666020521460] [43599:4426788] CHIP: [CTL] Shutting down the commissioner
[1666020521460] [43599:4426788] CHIP: [CTL] Stopping commissioning discovery over DNS-SD
[1666020521460] [43599:4426788] CHIP: [CTL] Shutting down the controller
[1666020521460] [43599:4426788] CHIP: [CTL] Shutting down the System State, this will teardown the CHIP Stack
[1666020521460] [43599:4426788] CHIP: [DMG] IM WH moving to [Uninitialized]
[1666020521460] [43599:4426788] CHIP: [DMG] IM WH moving to [Uninitialized]
[1666020521460] [43599:4426788] CHIP: [DMG] IM WH moving to [Uninitialized]
[1666020521460] [43599:4426788] CHIP: [DMG] IM WH moving to [Uninitialized]
[1666020521460] [43599:4426788] CHIP: [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1666020521460] [43599:4426788] CHIP: [BLE] CancelConnection
[1666020521460] [43599:4426788] CHIP: [DL] Inet Layer shutdown
[1666020521460] [43599:4426788] CHIP: [DL] BLE shutdown
[1666020521460] [43599:4426788] CHIP: [DL] System Layer shutdown
[1666020521460] [43599:4426788] CHIP: [TOO] Run command failure: ../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout

    And lastly here is the end device UART output of the failed commission attempt coming from the chip-tool running on Mac.

    Fullscreen End device output.txt Download 
    I: 596 [DL]Device Configuration:
I: 600 [DL]  Serial Number: 11223344556677889900
I: 605 [DL]  Vendor Id: 65521 (0xFFF1)
I: 608 [DL]  Product Id: 32768 (0x8000)
I: 612 [DL]  Hardware Version: 0
I: 616 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 622 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 629 [DL]  Manufacturing Date: (not set)
I: 633 [DL]  Device Type: 65535 (0xFFFF)
I: 638 [SVR]SetupQRCode: [MT:Y.K9042C00KA0648G00]
I: 642 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 648 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I: 657 [SVR]Manual pairing code: [34970112332]
I: 662 [DL]CHIP task running
I: 668 [DL]CHIPoBLE advertising started
I: 13616 [DL]BLE connection established (ConnId: 0x00)
I: 13621 [DL]Current number of connections: 1/1
I: 13626 [DL]CHIPoBLE advertising stopped
W: Ignoring data for unknown channel ID 0x003a
I: 14135 [DL]BLE GAP connection terminated (reason 0x08)
I: 14140 [DL]Current number of connections: 0/1
I: 14147 [DL]CHIPoBLE advertising started
I: 44150 [DL]CHIPoBLE advertising mode changed to slow

  • 0 in reply to jacobbluhm

    Here is the BLE Sniffer trace when attempting to commission from the chip-tool on Mac, connection starts at line 2253.

    BLE Sinffer from failed commission Mac chip-tool.pcapng

    Here is the BLE Sniffer trace of a successful commission from the Android CHIPTool, connection starts at line 1433

    BLE Sniffer from successful commission Android CHIPTool.pcapng

  • 0 in reply to jacobbluhm

    Hi,

    It looks like the Mac is sending some bad frames, and/or sending the LL_PHY_RSP at the wrong time, causing a conflict. The frames all reports as CRC error and are retransmitted multiple times:

    I will check with our Matter team if they have experienced this before, but if you have a different computer (preferably a Linux PC) that you can test with, that may work better.

  • 0 in reply to Jørgen Holmefjord

    I am working on securing a Linux PC to test. Do you recommend a certain Linux distribution?

    Any word back from the Matter team on this issue?

  • 0 in reply to jacobbluhm

    I believe Ubuntu 22.04 LTS 64-bit would be the best option.

    Our Matter team had not seen this issue before, but it looks like a Bluetooth Host issue and not directly Matter related. I can check with our Bluetooth team if they have some suggestions.

Related
Terms of service