search

NordicSemiconductor / Android-nRF-Mesh-Library

The Bluetooth Mesh Provisioner and Configurator library.
https://www.nordicsemi.com/
BSD 3-Clause "New" or "Revised" License
414 stars 177 forks source link

Bluetooth mesh terminate before sending app key - Error: (0x13): GATT CONN TERMINATE PEER USER #528

Closed tea000001 closed 2 years ago

tea000001 commented 2 years ago

Describe the bug I want to mesh a device, but it's not successed, I read the log and I think this is happend after provisioning complete and before sending app key, i'm not sure the reason is releated IV index: 00000000 or Key index: 0000,

if everyone know what happen about that, please tell me or share the experience, thanks.

To Reproduce Steps to reproduce the behavior: Mesh device

Platform details:

Logs / Screenshots

2022-08-01 16:45:31.136 11508-11508/  V/MeshManagerApi: Received provisioning message: 0x0306C2A04B2C54A6B5407781626C21171D14
2022-08-01 16:45:31.136 11508-11508/  V/ProvisioningRandomConfirmationState: Confirmation inputs: 0504000100000000000000000000000000C2167189D0D90A74DE358BF6656E06A6909054EBDA92E22A2EFD0AC6E45A78634CC57CB08B715D80E75CF4684E3937F28B447DF3FBCD4E8061C99EECCBA9A103F3D01C0D7EFDFECDEBAFF5278D9039EA394BF95328481C7F3480B6E32EB2083FD364F3D3B2F640E6CDD1AA8F7896949395F2F491D7831821202C9F8462CF043F
2022-08-01 16:45:31.137 11508-11508/  V/ProvisioningRandomConfirmationState: Confirmation salt: 2C7E5D928C700453DB721567F7E55954
2022-08-01 16:45:31.138 11508-11508/  V/ProvisioningRandomConfirmationState: Confirmation key: 9FCD036CDE5F0E4AF285FACFCD0BA6FC
2022-08-01 16:45:31.138 11508-11508/  V/ProvisioningRandomConfirmationState: Authentication value: 00000000000000000000000000000000
2022-08-01 16:45:31.138 11508-11508/  V/ProvisioningRandomConfirmationState: Confirmation values match!!!!: D960504E74F86DA9C2E94B2695892A30
2022-08-01 16:45:31.139 11508-11508/  V/ProvisioningRandomConfirmationState: Provisioning salt: 8B50C1579A597AA263383F9089822371
2022-08-01 16:45:31.139 11508-11508/  V/ProvisioningRandomConfirmationState: Session key: 4B0329E3B8F163D6256E5F0A1DFD0E94
2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: Session nonce: 9154BC3D911C265835CED54A23
2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: Device key: 971D84FB76949904BAB21A01D47259E9
2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: Network key: 4C53425545617379436F6E661E359A35
**2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: Key index: 0000**
2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: Flags: 00
**2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: IV index: 00000000**
2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: Unicast address: 0108
2022-08-01 16:45:31.140 11508-11508/  V/ProvisioningRandomConfirmationState: Provisioning data: 4C53425545617379436F6E661E359A35000000000000000108
2022-08-01 16:45:31.141 11508-11508/  V/ProvisioningRandomConfirmationState: Encrypted provisioning data: C97895CB97CF6FCB8232B702A323D07FEE2C0D69B0F1CEAD2D216680F78CA9B2D0
2022-08-01 16:45:31.141 11508-11508/  V/ProvisioningRandomConfirmationState: Prov Data: 0307C97895CB97CF6FCB8232B702A323D07FEE2C0D69B0F1CEAD2D216680F78CA9B2D0
2022-08-01 16:45:31.143 11508-11508/  E/ScanNodeActivity: ProvisioningLiveDataState:PROVISIONING_DATA_SENT
2022-08-01 16:45:31.146 11508-11508/  I/BleManager: Data written to 00002adb-0000-1000-8000-00805f9b34fb, value: (0x) 03-07-C9-78-95-CB-97-CF-6F-CB-82-32-B7-02-A3-23-D0-7F-EE-2C-0D-69-B0-F1-CE-AD-2D-21-66-80-F7-8C-A9-B2-D0
2022-08-01 16:45:31.148 11508-11508/  E/NrfMeshRepository: NrfMeshRepository-onDataSent:M +
2022-08-01 16:45:31.148 11508-11508/  V/MeshManagerApi: Provisioning pdu sent: 0x0307C97895CB97CF6FCB8232B702A323D07FEE2C0D69B0F1CEAD2D216680F78CA9B2D0
2022-08-01 16:45:31.148 11508-11508/  E/NrfMeshRepository: NrfMeshRepository-onDataSent2
2022-08-01 16:45:31.440 11508-11508/  I/BleManager: Notification received from 00002adc-0000-1000-8000-00805f9b34fb, value: (0x) 03-08
2022-08-01 16:45:31.440 11508-11508/  E/NrfMeshRepository: NrfMeshRepository-onDataReceived
2022-08-01 16:45:31.440 11508-11508/  V/MeshManagerApi: Received provisioning message: 0x0308
2022-08-01 16:45:31.443 11508-11508/  E/tmpCurrentAddress:: 264
2022-08-01 16:45:31.444 11508-11508/  E/addCount:: 4
2022-08-01 16:45:31.444 11508-11508/  E/elementCount:: 4
2022-08-01 16:45:31.444 11508-11508/  E/unicastAddress:: 268
2022-08-01 16:45:31.444 11508-11508/  E/MeshManagerApi: MeshNetworkCallbacks-onMeshNetworkUpdated
2022-08-01 16:45:31.448 11508-11508/  D/BluetoothGatt: cancelOpen() - device: C7:ED:B4:81:CB:0C
2022-08-01 16:45:31.450 11508-11508/  E/LsbuWebServer: provisionedNodes.size():2
2022-08-01 16:45:31.451 11508-11508/  E/LsbuWebServer: check provisionedNodes:
2022-08-01 16:45:31.451 11508-11508/  E/LsbuWebServer: CompanyIdentifier:null
2022-08-01 16:45:31.451 11508-11508/  E/LsbuWebServer: ProductIdentifier:null
2022-08-01 16:45:31.451 11508-11508/  E/LsbuWebServer: VersionIdentifier:null
2022-08-01 16:45:31.452 11508-11508/  E/MeshManagerApi: MeshNetworkCallbacks-onNodeDeleted
2022-08-01 16:45:31.452 11508-11508/  E/LsbuWebServer: updateNodeData.meshNodes.size():1
2022-08-01 16:45:31.453 11508-11524/  D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=C7:ED:B4:81:CB:0C
2022-08-01 16:45:31.453 11508-11508/  E/LsbuWebServer: connectJob
2022-08-01 16:45:31.454 11508-11508/  E/ScanNodeActivity: isReconnecting:true
2022-08-01 16:45:31.454 11508-11508/  V/NrfMeshRepository: Disconnecting...
2022-08-01 16:45:31.455 11508-11508/  E/ScanNodeActivity: ProvisioningLiveDataState:PROVISIONING_COMPLETE
2022-08-01 16:45:31.455 11508-11508/  E/ScanNodeActivity: PROVISIONING_COMPLETE
2022-08-01 16:45:31.455 11508-11508/  E/ScanNodeActivity: showProgressMsg:Progress 50 %
2022-08-01 16:45:31.455 11508-11508/  E/ScanNodeActivity: PROVISIONING_COMPLETE==pMeshNode:M +
2022-08-01 16:45:31.455 11508-11508/  E/LsbuWebServer: updateNodeData.meshNodes.size():1
2022-08-01 16:45:31.456 11508-11508/  E/LsbuWebServer: connectJob
2022-08-01 16:45:31.462 11508-11508/  I/BleManager: Disconnected
2022-08-01 16:45:31.463 11508-11508/  D/BluetoothGatt: refresh() - device: C7:ED:B4:81:CB:0C
2022-08-01 16:45:31.464 11508-11508/  I/BleManager: Cache refreshed
2022-08-01 16:45:31.464 11508-11508/  D/BluetoothGatt: close()
2022-08-01 16:45:31.464 11508-11508/  D/BluetoothGatt: unregisterApp() - mClientIf=9
2022-08-01 16:45:31.465 11508-11508/  E/ScanNodeActivity: 節點配置完成
2022-08-01 16:45:31.465 11508-11508/  E/NrfMeshRepository: onDeviceDisconnected2
2022-08-01 16:45:31.466 11508-11508/  E/LsbuWebServer: isConnectedToProxy:false
2022-08-01 16:45:31.466 11508-11508/  E/LsbuWebServer: setProxyNodeAddress:null
2022-08-01 16:45:32.457 11508-11508/  D/BluetoothAdapter: isLeEnabled(): ON
2022-08-01 16:45:32.469 11508-11861/  D/BluetoothLeScanner: onScannerRegistered() - status=0 scannerId=9 mScannerId=0
2022-08-01 16:45:32.474 11508-11508/  V/NrfMeshRepository: Scan started
2022-08-01 16:45:33.331 11508-11508/  E/NrfMeshRepository: onScanResult-serviceData:[B@5136ad5
2022-08-01 16:45:33.332 11508-11508/  E/NrfMeshRepository: node.getBluetoothDeviceAddress():C7:ED:B4:81:CB:0C
2022-08-01 16:45:33.332 11508-11508/  E/NrfMeshRepository: result.getDevice().getAddress():CB:C1:3A:93:E3:E9
2022-08-01 16:45:33.929 11508-11508/  E/NrfMeshRepository: onScanResult-serviceData:[B@a341c78
2022-08-01 16:45:33.929 11508-11508/  E/NrfMeshRepository: node.getBluetoothDeviceAddress():C7:ED:B4:81:CB:0C
2022-08-01 16:45:33.929 11508-11508/  E/NrfMeshRepository: result.getDevice().getAddress():E9:BE:DA:21:D8:2E
2022-08-01 16:45:34.466 11508-11508/  E/NrfMeshRepository: onScanResult-serviceData:[B@5acdf51
2022-08-01 16:45:34.466 11508-11508/  E/NrfMeshRepository: node.getBluetoothDeviceAddress():C7:ED:B4:81:CB:0C
2022-08-01 16:45:34.468 11508-11508/  E/NrfMeshRepository: result.getDevice().getAddress():EC:37:F4:D7:2A:83
2022-08-01 16:45:34.689 11508-11508/  E/NrfMeshRepository: onScanResult-serviceData:[B@4bf3b6
2022-08-01 16:45:34.689 11508-11508/  E/NrfMeshRepository: node.getBluetoothDeviceAddress():C7:ED:B4:81:CB:0C
2022-08-01 16:45:34.689 11508-11508/  E/NrfMeshRepository: result.getDevice().getAddress():DF:1D:E5:3F:E0:A4
2022-08-01 16:45:36.336 11508-11508/  E/NrfMeshRepository: onScanResult-serviceData:[B@8ca8824
2022-08-01 16:45:36.337 11508-11508/  E/NrfMeshRepository: node.getBluetoothDeviceAddress():C7:ED:B4:81:CB:0C
2022-08-01 16:45:36.337 11508-11508/  E/NrfMeshRepository: result.getDevice().getAddress():E5:EC:BC:D6:17:32
2022-08-01 16:45:36.757 11508-11508/  E/NrfMeshRepository: onScanResult-serviceData:[B@38f1f8d
2022-08-01 16:45:36.757 11508-11508/  E/NrfMeshRepository: node.getBluetoothDeviceAddress():C7:ED:B4:81:CB:0C
2022-08-01 16:45:36.757 11508-11508/  E/NrfMeshRepository: result.getDevice().getAddress():EA:28:D2:6D:0E:96
2022-08-01 16:45:37.206 11508-11508/  E/NrfMeshRepository: onScanResult-serviceData:[B@39b9542
2022-08-01 16:45:37.211 11508-11508/  D/BluetoothAdapter: isLeEnabled(): ON
2022-08-01 16:45:37.214 11508-11508/  E/NrfMeshRepository: onProvisionedDeviceFound
2022-08-01 16:45:37.214 11508-11508/  E/NrfMeshRepository: mProvisionedMeshNode:264
2022-08-01 16:45:37.214 11508-11508/  E/NrfMeshRepository: mProvisionedMeshNode:M +
2022-08-01 16:45:37.215 11508-11508/  E/ScanNodeActivity: 準備與代理節點連線...
2022-08-01 16:45:39.215 11508-11508/  E/NrfMeshRepository: initIsConnectedLiveData
2022-08-01 16:45:39.220 11508-11508/  D/BluetoothGatt: connect() - device: C7:ED:B4:81:CB:0C, auto: false
2022-08-01 16:45:39.220 11508-11508/  D/BluetoothGatt: registerApp()
2022-08-01 16:45:39.220 11508-11508/  D/BluetoothGatt: registerApp() - UUID=a72e55e8-abb9-4813-bd6a-ec4cef059a63
2022-08-01 16:45:39.223 11508-11508/  E/ScanNodeActivity: 連線中...
2022-08-01 16:45:39.223 11508-11508/  E/ScanNodeActivity: 連線中...
2022-08-01 16:45:39.224 11508-11896/  D/BluetoothGatt: onClientRegistered() - status=0 clientIf=9
2022-08-01 16:45:40.381 11508-11524/  D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=9 device=C7:ED:B4:81:CB:0C
2022-08-01 16:45:40.382 11508-11508/  I/BleManager: Connected to C7:ED:B4:81:CB:0C
2022-08-01 16:45:40.384 11508-11508/  E/NrfMeshRepository: onDeviceConnected
2022-08-01 16:45:40.385 11508-11508/  E/ScanNodeActivity: 偵測服務中...
2022-08-01 16:45:40.385 11508-11508/  E/LsbuWebServer: isConnectedToProxy:true
2022-08-01 16:45:40.687 11508-11508/  D/BluetoothGatt: discoverServices() - device: C7:ED:B4:81:CB:0C
2022-08-01 16:45:40.826 11508-11896/  D/BluetoothGatt: onConnectionUpdated() - Device=C7:ED:B4:81:CB:0C interval=6 latency=0 timeout=500 status=0
2022-08-01 16:45:40.832 11508-11508/  I/BleManager: Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
2022-08-01 16:45:41.012 11508-11896/  D/BluetoothGatt: onSearchComplete() = Device=C7:ED:B4:81:CB:0C Status=0
2022-08-01 16:45:41.013 11508-11508/  I/BleManager: Services discovered
2022-08-01 16:45:41.019 11508-11508/  D/BluetoothGatt: configureMTU() - device: C7:ED:B4:81:CB:0C mtu: 517
2022-08-01 16:45:41.037 11508-11529/  D/BluetoothGatt: onConfigureMTU() - Device=C7:ED:B4:81:CB:0C mtu=69 status=0
2022-08-01 16:45:41.037 11508-11508/  I/BleManager: MTU changed to: 69
2022-08-01 16:45:41.038 11508-11508/  D/BluetoothGatt: setCharacteristicNotification() - uuid: 00002ade-0000-1000-8000-00805f9b34fb enable: true
2022-08-01 16:45:41.061 11508-11508/  I/BleManager: Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
2022-08-01 16:45:41.061 11508-11508/  I/BleManager: Notifications enabled
2022-08-01 16:45:41.062 11508-11508/  I/BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-4E-66-49-53-8E-81-F3-A8-00-00-00-00-63-18-B6-09-2D-BF-4D-30
2022-08-01 16:45:41.062 11508-11508/  E/NrfMeshRepository: onDeviceReady
2022-08-01 16:45:41.062 11508-11508/  E/NrfMeshRepository: NrfMeshRepository-onDataReceived
2022-08-01 16:45:41.064 11508-11508/  D/MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 0, IV Update Active: false, Authentication Value: 0x6318B6092DBF4D30}
2022-08-01 16:45:41.066 11508-11508/  D/MeshManagerApi: Secure Network Beacon authenticated.
2022-08-01 16:45:41.134 11508-11508/  D/MeshManagerApi: strIvIndex: {"isIvUpdateActive":false,"ivIndex":0,"ivRecoveryFlag":false,"transitionDate":{"year":2022,"month":7,"dayOfMonth":1,"hourOfDay":16,"minute":44,"second":30}}
2022-08-01 16:45:41.138 11508-11508/  D/MeshManagerApi: Last IV Index: 0
2022-08-01 16:45:41.145 11508-11508/  D/MeshManagerApi: strMeshIvIndex: {"isIvUpdateActive":false,"ivIndex":0,"ivRecoveryFlag":false,"transitionDate":{"year":2022,"month":7,"dayOfMonth":1,"hourOfDay":16,"minute":45,"second":41}}
2022-08-01 16:45:41.189 11508-11529/  D/BluetoothGatt: onConnectionUpdated() - Device=C7:ED:B4:81:CB:0C interval=120 latency=0 timeout=400 status=0
2022-08-01 16:45:41.195 11508-11508/  E/MeshManagerApi: MeshNetworkCallbacks-onMeshNetworkUpdated
2022-08-01 16:45:41.196 11508-11508/  E/LsbuWebServer: BleMeshManager().isDeviceReady():true
2022-08-01 16:45:41.197 11508-11508/  E/ScanNodeActivity: ProvisioningComplete:true
2022-08-01 16:45:41.197 11508-11508/  E/ScanNodeActivity: ProvisioningComplete
2022-08-01 16:45:41.198 11508-11508/  E/LsbuWebServer: isConnectedToProxy:true
2022-08-01 16:45:41.198 11508-11508/  I/BleManager: Connection parameters updated (interval: 150.0ms, latency: 0, timeout: 4000ms)
2022-08-01 16:45:41.199 11508-11508/  E/LsbuWebServer: updateNodeData.meshNodes.size():1
2022-08-01 16:45:41.200 11508-11508/  E/LsbuWebServer: connectJob
2022-08-01 16:45:44.067 11508-11508/  E/NrfMeshRepository: onDeviceReady-ConfigAppKeyAdd
2022-08-01 16:45:44.068 11508-11508/  E/BaseMeshMessageHandler: sendConfigMeshMessage 1
2022-08-01 16:45:44.068 11508-11508/  E/BaseMeshMessageHandler: src:32767
2022-08-01 16:45:44.068 11508-11508/  E/BaseMeshMessageHandler: dst:264
2022-08-01 16:45:44.068 11508-11508/  E/MeshManagerApi: sendMeshMessage-SequenceNumber:3001
2022-08-01 16:45:49.889 11508-11508/  I/BleManager: Notification received from 00002ade-0000-1000-8000-00805f9b34fb, value: (0x) 01-01-00-4E-66-49-53-8E-81-F3-A8-00-00-00-00-63-18-B6-09-2D-BF-4D-30
2022-08-01 16:45:49.890 11508-11508/  E/NrfMeshRepository: NrfMeshRepository-onDataReceived
2022-08-01 16:45:49.892 11508-11508/  D/MeshManagerApi: Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 0, IV Update Active: false, Authentication Value: 0x6318B6092DBF4D30}
2022-08-01 16:45:49.894 11508-11508/  D/MeshManagerApi: Secure Network Beacon authenticated.
2022-08-01 16:45:49.960 11508-11508/  D/MeshManagerApi: strIvIndex: {"isIvUpdateActive":false,"ivIndex":0,"ivRecoveryFlag":false,"transitionDate":{"year":2022,"month":7,"dayOfMonth":1,"hourOfDay":16,"minute":45,"second":41}}
2022-08-01 16:45:49.964 11508-11508/  D/MeshManagerApi: Last IV Index: 0
2022-08-01 16:45:49.968 11508-11508/  D/MeshManagerApi: strMeshIvIndex: {"isIvUpdateActive":false,"ivIndex":0,"ivRecoveryFlag":false,"transitionDate":{"year":2022,"month":7,"dayOfMonth":1,"hourOfDay":16,"minute":45,"second":49}}
2022-08-01 16:45:50.021 11508-11508/  E/MeshManagerApi: MeshNetworkCallbacks-onMeshNetworkUpdated
2022-08-01 16:45:50.023 11508-11508/  E/LsbuWebServer: updateNodeData.meshNodes.size():1
2022-08-01 16:45:50.024 11508-11508/  E/LsbuWebServer: connectJob
2022-08-01 16:46:31.442 11508-11529/  D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=9 device=C7:ED:B4:81:CB:0C
2022-08-01 16:46:31.443 11508-11508/  W/BleManager: Error: (0x13): GATT CONN TERMINATE PEER USER
2022-08-01 16:46:31.443 11508-11508/  I/BleManager: Disconnected
2022-08-01 16:46:31.456 11508-11508/  D/BluetoothGatt: close()
2022-08-01 16:46:31.457 11508-11508/  D/BluetoothGatt: unregisterApp() - mClientIf=9
2022-08-01 16:46:31.459 11508-11508/  E/NrfMeshRepository: onDeviceDisconnected2
2022-08-01 16:46:31.460 11508-11508/  E/ScanNodeActivity: isReconnecting1111
2022-08-01 16:46:31.493 11508-11508/  E/ScanNodeActivity: ProvisioningAppKeyReceivedFinish:false
2022-08-01 16:46:31.493 11508-11508/  E/NrfMeshRepository: ProvisioningFail
roshanrajaratnam commented 2 years ago

Hi never seen this happening. Seems like the firmware dropping the connection here. Are you using our examples or is this happening on your own firmware?

tea000001 commented 2 years ago

Hi,

  1. I use your examples code (Android-nRF-Mesh-Library), but it's old version, the version is 2 or 3 yeaes ago, i'm not sure.
    1. It's not only happaning on our own device.
tea000001 commented 2 years ago

update:

I found the problem is in

private void sendConfigMeshMessage(final int src, final int dst, @NonNull final ConfigMessage configurationMessage) { 
   final ProvisionedMeshNode node = mInternalTransportCallbacks.getProvisionedNode(dst);  
   [...]
}

(BaseMeshMessageHandler.java)

node is null, so it can't send the configAppKeyAddState (dst not null)