NordicSemiconductor / Android-nRF-Mesh-Library

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

Need help: Reconnection & Configuration after Provisioning #584

Closed ahmadshoh-orc closed 2 months ago

ahmadshoh-orc commented 3 months ago

Edited (28.06.2024)

I am implementing device provisioning and configuration using the NordicMesh library for Android. The project is built with Flutter, utilizing a native Kotlin plugin. While the provisioning process executes correctly, I'm encountering issues during the configuration phase. Specifically, after reconnection, I receive no response for the ConfigAppKeyAdd and ConfigCompositionDataGet messages. The logs indicate that the MeshMessage was processed, but no further messages are received.

Could someone help identify what might be wrong in my code or what I might be missing?

Code

Here is the relevant code for provisioning and configuration:

  fun provision(address: String, callback: (provisionedNode: ProvisionedNode) -> Unit) {
    provisioningService.provisionCallback = { selectedPeripheral, unicastAddress ->
      Log.d("QBleMesh", "Provisioning device with address: $address")

      bleManager.connect(address) {
        Log.d("QBleMesh", "Connected to device with address: $address")
        handler.postDelayed({
          Log.d("QBleMesh", "Starting configuration process.")
          startConfigurationProcess(selectedPeripheral, unicastAddress, callback)
        }, 5000)
      }
    }

    val unprovisionedScanResult = unprovisionedScanResults.firstOrNull { it.device.address == address }
    unprovisionedScanResult?.let { result ->
      bleManager.connect(address) {
        Log.d("QBleMesh", "Connection done was called.")
        provisioningService.startProvisioningProcess(result)
      }
    }
  }

  private fun startConfigurationProcess(
    selectedPeripheral: ScanResult,
    unicastAddress: Int,
    callback: (provisionedNode: ProvisionedNode) -> Unit
  ) {
    val name = selectedPeripheral.device.name ?: "unknown device"
    val address = selectedPeripheral.device.address

    unprovisionedScanResults.removeIf { it.device.address == address }

    val configurationService = ConfigurationService(meshManagerApi)
    configurationService.configurationComplete = { provisionedNode ->
      callback(provisionedNode)
    }

    configurationService.configure(unicastAddress, name, address)
  }
class ConfigurationService(private val meshManagerApi: MeshManagerApi) : ConfigurationServiceMeshStatusCallback() {

  var configurationComplete: (provisionedNode: ProvisionedNode) -> Unit = {}
  private val handler = Handler(Looper.getMainLooper())

  init {
    meshManagerApi.setMeshStatusCallbacks(this)
  }

  fun configure(unicastAddress: Int, name: String, address: String) {
    val provisionedNode = ProvisionedNode(name, address)

    val meshNetwork = meshManagerApi.meshNetwork ?: return
    val node = meshNetwork.getNode(unicastAddress) ?: return
    val appKey = meshNetwork.appKeys.firstOrNull() ?: return
    val netKey = meshNetwork.getNetKey(appKey.boundNetKeyIndex)

    try {
      val configAppKeyAdd = ConfigAppKeyAdd(netKey, appKey)
      Log.d("ConfigurationService", "Sending AppKeyAdd...")
      meshManagerApi.createMeshPdu(node.unicastAddress, configAppKeyAdd)

      compositionDataGetComplete = {
        configurationComplete(provisionedNode)
      }

      handler.postDelayed({
        Log.d("QBleMesh", "Sending ConfigCompositionDataGet...")
        meshManagerApi.createMeshPdu(node.unicastAddress, ConfigCompositionDataGet())
      }, 3000)

    } catch (e: Exception) {
      Log.e("ConfigurationService", "Error configuring node: ${e.message}")
    }
  }
}
open class ConfigurationServiceMeshStatusCallback : MeshStatusCallbacks {
  protected var compositionDataGetComplete: () -> Unit = {}

  override fun onTransactionFailed(dst: Int, hasIncompleteTimerExpired: Boolean) {
    Log.d("ConfigurationService", "Transaction failed -> dst: $dst, hasIncompleteTimerExpired: $hasIncompleteTimerExpired")
  }

  override fun onUnknownPduReceived(src: Int, accessPayload: ByteArray?) {
    Log.d("ConfigurationService", "Unknown PDU received -> src: $src, accessPayload: ${accessPayload?.contentToString()}")
  }

  override fun onBlockAcknowledgementProcessed(dst: Int, message: ControlMessage) {
    Log.d("ConfigurationService", "Block acknowledgement processed -> dst: $dst, message: $message")
  }

  override fun onBlockAcknowledgementReceived(src: Int, message: ControlMessage) {
    Log.d("ConfigurationService", "Block acknowledgement received -> src: $src, message: $message")
  }

  override fun onMeshMessageProcessed(dst: Int, meshMessage: MeshMessage) {
    Log.d("ConfigurationService", "Mesh message processed -> dst: $dst, meshMessage: ${meshMessage.opCode}")
  }

  override fun onMeshMessageReceived(src: Int, meshMessage: MeshMessage) {
    Log.d("ConfigurationService", "Mesh message received -> src: $src, meshMessage: ${meshMessage.opCode}")
    this.compositionDataGetComplete()
  }

  override fun onMessageDecryptionFailed(meshLayer: String?, errorMessage: String?) {
    Log.d("ConfigurationService", "Message decryption failed -> meshLayer: $meshLayer, errorMessage: $errorMessage")
  }
}
class BleMeshManager(appContext: Context) : BleManager(appContext) {

  companion object {
    private const val MTU_SIZE_MAX: Int = 517

    private val MESH_PROVISIONING_DATA_IN: UUID =
      UUID.fromString("00002ADB-0000-1000-8000-00805F9B34FB")

    private val MESH_PROVISIONING_DATA_OUT: UUID =
      UUID.fromString("00002ADC-0000-1000-8000-00805F9B34FB")

    private val MESH_PROXY_DATA_IN = UUID.fromString("00002ADD-0000-1000-8000-00805F9B34FB")

    private val MESH_PROXY_DATA_OUT = UUID.fromString("00002ADE-0000-1000-8000-00805F9B34FB")
  }

  private var gatt: BluetoothGatt? = null
  private var meshProvisioningDataInCharacteristic: BluetoothGattCharacteristic? = null
  private var meshProvisioningDataOutCharacteristic: BluetoothGattCharacteristic? = null
  private var meshProxyDataInCharacteristic: BluetoothGattCharacteristic? = null
  private var meshProxyDataOutCharacteristic: BluetoothGattCharacteristic? = null

  private var dataCallback: MeshDataCallback? = null

  fun setDataCallback(dataCallback: MeshDataCallback) {
    this.dataCallback = dataCallback
  }

  override fun initialize() {
    requestMtu(MTU_SIZE_MAX).enqueue()
    setupProxyListener()
    setupProvisioningListener()
  }

  private fun setupProvisioningListener() {
    meshProvisioningDataOutCharacteristic?.run {
      setNotificationCallback(this).with { device, data ->
        dataCallback?.onDataReceived(device, getMaximumPacketSize(), data.value)
      }
      enableNotifications(this).enqueue()
    }
  }

  private fun setupProxyListener() {
    meshProxyDataOutCharacteristic?.run {
      setNotificationCallback(this).with { device, data ->
        dataCallback?.onDataReceived(device, getMaximumPacketSize(), data.value)
      }
      enableNotifications(this).enqueue()
    }
  }

  fun connect(address: String, successCallback: SuccessCallback) {
    val bluetoothManager: BluetoothManager? = context.getSystemService(Context.BLUETOOTH_SERVICE) as BluetoothManager?
    val device: BluetoothDevice? = bluetoothManager?.adapter?.getRemoteDevice(address)
    device?.run {
      connect(device).done(successCallback).fail { device: BluetoothDevice, status: Int ->
        gatt = null
        Log.d("BleMeshManager", "${device.name} failed with status -> $status")
      }.retry(3, 200).enqueue()
    }
  }

  override fun isRequiredServiceSupported(gatt: BluetoothGatt): Boolean {
    this.gatt = gatt

    try {
      setupProxyCharacteristic()
      Log.d("BleMeshManager", "Proxy characteristics found")
      return meshProxyDataInCharacteristic != null && meshProxyDataOutCharacteristic != null
    } catch (_: Exception) {
      Log.d("BleMeshManager", "Error: Proxy characteristics not found")
    }

    try {
      setupProvisioningCharacteristic()
      return meshProvisioningDataInCharacteristic != null && meshProvisioningDataOutCharacteristic != null
    } catch (_: Exception) {
        Log.d("BleMeshManager", "Error: Provisioning characteristics not found")
    }

    return false
  }

  private fun setupProxyCharacteristic() {
    gatt?.run {
      val meshProxyService: BluetoothGattService = this.getService(MeshManagerApi.MESH_PROXY_UUID)
      if (meshProxyDataInCharacteristic == null) {
        meshProxyDataInCharacteristic = meshProxyService.getCharacteristic(MESH_PROXY_DATA_IN)
      }
      if (meshProxyDataOutCharacteristic == null) {
        meshProxyDataOutCharacteristic = meshProxyService.getCharacteristic(MESH_PROXY_DATA_OUT)
      }
    }
  }

  private fun setupProvisioningCharacteristic() {
    gatt?.run {
      val meshProvisioningService: BluetoothGattService = this.getService(MESH_PROVISIONING_UUID)
      if (meshProvisioningDataInCharacteristic == null) {
        meshProvisioningDataInCharacteristic = meshProvisioningService.getCharacteristic(
          MESH_PROVISIONING_DATA_IN
        )
      }
      if (meshProvisioningDataOutCharacteristic == null) {
        meshProvisioningDataOutCharacteristic =
          meshProvisioningService.getCharacteristic(MESH_PROVISIONING_DATA_OUT)
      }
    }
  }

  fun sendProvisioningPdu(pdu: ByteArray?) {
    writeCharacteristic(
      meshProvisioningDataInCharacteristic,
      pdu,
      BluetoothGattCharacteristic.WRITE_TYPE_NO_RESPONSE
    )
      .split()
      .with { device: BluetoothDevice, data: Data ->
        Log.d("BleMeshManager", "sending ${data.value?.toHex()} to ${device.name}")
        dataCallback?.onDataSent(device, getMaximumPacketSize(), data.value)
      }
      .done { device: BluetoothDevice ->
        Log.d("BleMeshManager", "writing to ${device.name} was successful")
      }
      .fail { device: BluetoothDevice, status: Int ->
        Log.d("BleMeshManager", "failed to send ${device.name} with status $status")
      }
      .enqueue()
  }

  fun createMeshPdu(pdu: ByteArray?) {
    writeCharacteristic(
      meshProxyDataInCharacteristic,
      pdu,
      BluetoothGattCharacteristic.WRITE_TYPE_NO_RESPONSE
    )
      .split()
      .with { device: BluetoothDevice, data: Data ->
        Log.d("BleMeshManager", "sending ${data.value?.toHex()} to ${device.name}")
        dataCallback?.onDataSent(device, getMaximumPacketSize(), data.value)
      }
      .done { device: BluetoothDevice ->
        Log.d("BleMeshManager", "writing to ${device.name} was successful")
      }
      .fail { device: BluetoothDevice, status: Int ->
        Log.d("BleMeshManager", "failed to send ${device.name} with status $status")
      }
      .enqueue()
  }

  fun getMaximumPacketSize(): Int {
    return super.getMtu() - 3
  }
}

Output Logs

Here are the relevant output logs during the provisioning process:

I/ViewRootImpl@d843fa5[MainActivity](13013): ViewPostIme pointer 0
I/ViewRootImpl@d843fa5[MainActivity](13013): ViewPostIme pointer 1
I/BluetoothAdapter(13013): BluetoothAdapter() : com.quimron.bt.worklight_v2
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/CompatibilityChangeReporter(13013): Compat change id reported: 265103382; UID 10420; state: DISABLED
D/BluetoothGatt(13013): connect() - device: 7C:DF:A1:DB:08:92, auto: false
D/BluetoothGatt(13013): registerApp()
D/BluetoothGatt(13013): registerApp() - UUID=0c6d4871-c7fe-491c-a2af-33ba46fce65e
D/BluetoothGatt(13013): onClientRegistered() - status=0 clientIf=6
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothGatt(13013): onClientConnectionState() - status=0 clientIf=6 device=XX:XX:XX:XX:08:92
D/BluetoothGatt(13013): discoverServices() - device: 7C:DF:A1:DB:08:92
D/BluetoothGatt(13013): onConnectionUpdated() - Device=XX:XX:XX:XX:08:92 interval=6 latency=0 timeout=500 status=0
D/BluetoothGatt(13013): onSearchComplete() = Device=XX:XX:XX:XX:08:92 Status=0
D/BleMeshManager(13013): Error: Proxy characteristics not found
D/BluetoothGatt(13013): configureMTU() - device: 7C:DF:A1:DB:08:92 mtu: 517
D/BluetoothGatt(13013): onConfigureMTU() - Device=XX:XX:XX:XX:08:92 mtu=23 status=0
D/BluetoothGatt(13013): setCharacteristicNotification() - uuid: 00002adc-0000-1000-8000-00805f9b34fb enable: true
D/QBleMesh(13013): Connection done was called.
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_INVITE, with data -> 0x030005
D/BleMeshManager(13013): sending 0x030005 to DEMO_2_AC
D/BleMeshManager(13013): Data sent -> mtu: 20, pdu: [3, 0, 5]
V/MeshManagerApi(13013): Provisioning pdu sent: 0x030005
D/BleMeshManager(13013): writing to DEMO_2_AC was successful
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [3, 1, 2, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0]
V/MeshManagerApi(13013): Received provisioning message: 0x03010200010000000000000000
V/ProvisioningCapabilities(13013): Number of elements: 2
V/AlgorithmType(13013): Supported output oob action type: FIPS P-256 Elliptic Curve
V/ProvisioningCapabilities(13013): Public key information available: false
V/ProvisioningCapabilities(13013): Static OOB information available: : false
V/ProvisioningCapabilities(13013): Output OOB size: 0
V/ProvisioningCapabilities(13013): Input OOB size: 0
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_CAPABILITIES, with data -> 0x03010200010000000000000000
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothLeScanner(13013): Start Scan with callback
D/BluetoothLeScanner(13013): onScannerRegistered() - status=0 scannerId=7 mScannerId=0
V/ProvisioningStartState(13013): Provisioning start PDU: 0x03020000000000
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_START, with data -> 0x03020000000000
D/BleMeshManager(13013): sending 0x03020000000000 to DEMO_2_AC
D/BleMeshManager(13013): Data sent -> mtu: 20, pdu: [3, 2, 0, 0, 0, 0, 0]
V/MeshManagerApi(13013): Provisioning pdu sent: 0x03020000000000
D/BluetoothGatt(13013): onConnectionUpdated() - Device=XX:XX:XX:XX:08:92 interval=24 latency=0 timeout=500 status=0
V/ProvisioningPublicKeyState(13013): X: length: 32 257B2B8BE35BAF0E8D1EC07AB766ED5EEF735DC9C08DF7FF412CDB4E1A3F0646
V/ProvisioningPublicKeyState(13013): Y: length: 32 BD11222F2BCE471E011E66344ECE380C59F33F426E6E3A33656EC3D6C43B8B14
V/ProvisioningPublicKeyState(13013): XY: 0x257B2B8BE35BAF0E8D1EC07AB766ED5EEF735DC9C08DF7FF412CDB4E1A3F0646BD11222F2BCE471E011E66344ECE380C59F33F426E6E3A33656EC3D6C43B8B14
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_PUBLIC_KEY_SENT, with data -> 0x0303257B2B8BE35BAF0E8D1EC07AB766ED5EEF735DC9C08DF7FF412CDB4E1A3F0646BD11222F2BCE471E011E66344ECE380C59F33F426E6E3A33656EC3D6C43B8B14
D/BleMeshManager(13013): writing to DEMO_2_AC was successful
D/BleMeshManager(13013): sending 0x4303257B2B8BE35BAF0E8D1EC07AB766ED5EEF73835DC9C08DF7FF412CDB4E1A3F0646BD11222F2B83CE471E011E66344ECE380C59F33F426E6E3A33C3656EC3D6C43B8B14 to DEMO_2_AC
D/BleMeshManager(13013): Data sent -> mtu: 20, pdu: [67, 3, 37, 123, 43, -117, -29, 91, -81, 14, -115, 30, -64, 122, -73, 102, -19, 94, -17, 115, -125, 93, -55, -64, -115, -9, -1, 65, 44, -37, 78, 26, 63, 6, 70, -67, 17, 34, 47, 43, -125, -50, 71, 30, 1, 30, 102, 52, 78, -50, 56, 12, 89, -13, 63, 66, 110, 110, 58, 51, -61, 101, 110, -61, -42, -60, 59, -117, 20]
D/BleMeshManager(13013): writing to DEMO_2_AC was successful
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [67, 3, -40, 34, 25, -22, 11, -103, -17, 99, 40, -101, 103, -42, -42, 6, -96, 39, 83, -23]
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [-125, 31, -34, 68, -18, 30, 90, 119, -87, 85, -83, 15, 85, 61, 9, -96, 101, 50, -128, 94]
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [-125, 58, 44, -3, 36, 58, -76, 94, 78, 127, -36, -60, -115, -93, -67, 95, 18, 20, 105, 59]
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [-61, 78, -24, -29, -46, 16, -30, 102, 11]
V/MeshManagerApi(13013): Received provisioning message: 0x0303D82219EA0B99EF63289B67D6D606A02753E91FDE44EE1E5A77A955AD0F553D09A06532805E3A2CFD243AB45E4E7FDCC48DA3BD5F1214693B4EE8E3D210E2660B
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_PUBLIC_KEY_RECEIVED, with data -> 0xD82219EA0B99EF63289B67D6D606A02753E91FDE44EE1E5A77A955AD0F553D09A06532805E3A2CFD243AB45E4E7FDCC48DA3BD5F1214693B4EE8E3D210E2660B
V/ProvisioningPublicKeyState(13013): Provisionee X: A06532805E3A2CFD243AB45E4E7FDCC48DA3BD5F1214693B4EE8E3D210E2660B
V/ProvisioningPublicKeyState(13013): Provisionee Y: D82219EA0B99EF63289B67D6D606A02753E91FDE44EE1E5A77A955AD0F553D09
V/ProvisioningPublicKeyState(13013): ECDH Secret: E31D93F6D71CD9F221BAADC439BF763725AC419529B26D516C6C3DF4C5121DBD
V/ProvisioningConfirmationState(13013): Confirmation inputs: 0502000100000000000000000000000000257B2B8BE35BAF0E8D1EC07AB766ED5EEF735DC9C08DF7FF412CDB4E1A3F0646BD11222F2BCE471E011E66344ECE380C59F33F426E6E3A33656EC3D6C43B8B14D82219EA0B99EF63289B67D6D606A02753E91FDE44EE1E5A77A955AD0F553D09A06532805E3A2CFD243AB45E4E7FDCC48DA3BD5F1214693B4EE8E3D210E2660B
V/ProvisioningConfirmationState(13013): Confirmation salt: 172B1139E4848FB8A327235B389B74E1
V/ProvisioningConfirmationState(13013): Confirmation key: D2E0B044969A7E1914571D5D2797C299
V/ProvisioningConfirmationState(13013): Provisioner random: D3FDF2C4322053406F5FAB3262E1407B
V/ProvisioningConfirmationState(13013): Authentication value: 00000000000000000000000000000000
V/ProvisioningConfirmationState(13013): Provisioning confirmation: 0305BEF1AD4298DB28DF51609D5C111ECA4C
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_CONFIRMATION_SENT, with data -> 0x0305BEF1AD4298DB28DF51609D5C111ECA4C
D/BleMeshManager(13013): sending 0x0305BEF1AD4298DB28DF51609D5C111ECA4C to DEMO_2_AC
D/BleMeshManager(13013): Data sent -> mtu: 20, pdu: [3, 5, -66, -15, -83, 66, -104, -37, 40, -33, 81, 96, -99, 92, 17, 30, -54, 76]
V/MeshManagerApi(13013): Provisioning pdu sent: 0x0305BEF1AD4298DB28DF51609D5C111ECA4C
D/BleMeshManager(13013): writing to DEMO_2_AC was successful
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [3, 5, -121, 102, -103, 86, 25, 43, -49, -117, 71, 65, -115, 90, -27, 0, -14, 50]
V/MeshManagerApi(13013): Received provisioning message: 0x030587669956192BCF8B47418D5AE500F232
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_CONFIRMATION_RECEIVED, with data -> 0x030587669956192BCF8B47418D5AE500F232
V/ProvisioningRandomConfirmationState(13013): Provisioner random PDU: 0306D3FDF2C4322053406F5FAB3262E1407B
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_CONFIRMATION_SENT, with data -> 0x0306D3FDF2C4322053406F5FAB3262E1407B
D/BleMeshManager(13013): sending 0x0306D3FDF2C4322053406F5FAB3262E1407B to DEMO_2_AC
D/BleMeshManager(13013): Data sent -> mtu: 20, pdu: [3, 6, -45, -3, -14, -60, 50, 32, 83, 64, 111, 95, -85, 50, 98, -31, 64, 123]
V/MeshManagerApi(13013): Provisioning pdu sent: 0x0306D3FDF2C4322053406F5FAB3262E1407B
D/BleMeshManager(13013): writing to DEMO_2_AC was successful
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [3, 6, -24, -103, 76, 33, -65, 99, 39, 79, 51, -28, 26, 116, -23, -53, -104, -58]
V/MeshManagerApi(13013): Received provisioning message: 0x0306E8994C21BF63274F33E41A74E9CB98C6
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_RANDOM_RECEIVED, with data -> 0x0306E8994C21BF63274F33E41A74E9CB98C6
V/ProvisioningRandomConfirmationState(13013): Confirmation inputs: 0502000100000000000000000000000000257B2B8BE35BAF0E8D1EC07AB766ED5EEF735DC9C08DF7FF412CDB4E1A3F0646BD11222F2BCE471E011E66344ECE380C59F33F426E6E3A33656EC3D6C43B8B14D82219EA0B99EF63289B67D6D606A02753E91FDE44EE1E5A77A955AD0F553D09A06532805E3A2CFD243AB45E4E7FDCC48DA3BD5F1214693B4EE8E3D210E2660B
V/ProvisioningRandomConfirmationState(13013): Confirmation salt: 172B1139E4848FB8A327235B389B74E1
V/ProvisioningRandomConfirmationState(13013): Confirmation key: D2E0B044969A7E1914571D5D2797C299
V/ProvisioningRandomConfirmationState(13013): Authentication value: 00000000000000000000000000000000
V/ProvisioningDataState(13013): Provisioning salt: 69669A275FBEFEE82DACB1C3FC5A879D
V/ProvisioningDataState(13013): Session key: 9309B14450DFB273E2778F2F9C87F57C
V/ProvisioningDataState(13013): Session nonce: 4AC1F09E5190DCC24C6F7CCF8A
V/ProvisioningDataState(13013): Device key: FED54C684EE8EF6BF6D914179490ACD6
V/ProvisioningDataState(13013): Network key: 4BE65B5D87E552DDAC430A1D47D63DBB
V/ProvisioningDataState(13013): Key index: 0000
V/ProvisioningDataState(13013): Flags: 00
V/ProvisioningDataState(13013): IV index: 00000000
V/ProvisioningDataState(13013): Unicast address: 0001
V/ProvisioningDataState(13013): Provisioning data: 4BE65B5D87E552DDAC430A1D47D63DBB000000000000000001
V/ProvisioningDataState(13013): Encrypted provisioning data: 2730B4C09029786AE2DF75B32D757505866A8DA5BC24CD5DB35C477CED23E6674E
V/ProvisioningDataState(13013): Prov Data: 03072730B4C09029786AE2DF75B32D757505866A8DA5BC24CD5DB35C477CED23E6674E
D/ProvisioningService(13013): My Node state change to -> PROVISIONING_DATA_SENT, with data -> 0x03072730B4C09029786AE2DF75B32D757505866A8DA5BC24CD5DB35C477CED23E6674E
D/BleMeshManager(13013): sending 0x43072730B4C09029786AE2DF75B32D757505866AC38DA5BC24CD5DB35C477CED23E6674E to DEMO_2_AC
D/BleMeshManager(13013): Data sent -> mtu: 20, pdu: [67, 7, 39, 48, -76, -64, -112, 41, 120, 106, -30, -33, 117, -77, 45, 117, 117, 5, -122, 106, -61, -115, -91, -68, 36, -51, 93, -77, 92, 71, 124, -19, 35, -26, 103, 78]
D/BleMeshManager(13013): writing to DEMO_2_AC was successful
D/BleMeshManager(13013): Data received -> mtu: 20, pdu: [3, 8]
V/MeshManagerApi(13013): Received provisioning message: 0x0308
D/BluetoothGatt(13013): onServiceChanged() - Device=XX:XX:XX:XX:08:92
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothLeScanner(13013): Start Scan with callback
D/BluetoothLeScanner(13013): onScannerRegistered() - status=0 scannerId=8 mScannerId=0
D/BleMeshManager(13013): provisioning is complete. unicast address is -> 1
D/BleMeshManager(13013): we did it.
D/QBleMesh(13013): Provisioning device with address: 7C:DF:A1:DB:08:92
D/BluetoothGatt(13013): discoverServices() - device: 7C:DF:A1:DB:08:92
D/QBleMesh(13013): Connected to device with address: 7C:DF:A1:DB:08:92
D/BluetoothGatt(13013): onConnectionUpdated() - Device=XX:XX:XX:XX:08:92 interval=6 latency=0 timeout=500 status=0
D/BluetoothGatt(13013): onSearchComplete() = Device=XX:XX:XX:XX:08:92 Status=0
D/BleMeshManager(13013): Proxy characteristics found
D/BluetoothGatt(13013): configureMTU() - device: 7C:DF:A1:DB:08:92 mtu: 517
D/BluetoothGatt(13013): onConfigureMTU() - Device=XX:XX:XX:XX:08:92 mtu=23 status=0
D/BluetoothGatt(13013): setCharacteristicNotification() - uuid: 00002ade-0000-1000-8000-00805f9b34fb enable: true
D/BluetoothGatt(13013): setCharacteristicNotification() - uuid: 00002adc-0000-1000-8000-00805f9b34fb enable: true
D/BluetoothGatt(13013): onConnectionUpdated() - Device=XX:XX:XX:XX:08:92 interval=24 latency=0 timeout=500 status=0
D/QBleMesh(13013): Starting configuration process.
V/ConfigAppKeyAdd(13013): NetKeyIndex: 0
V/ConfigAppKeyAdd(13013): AppKeyIndex: 0
D/ConfigurationService(13013): Sending AppKeyAdd...
V/MeshTransport(13013): Src address: 0001
V/MeshTransport(13013): Dst address: 0001
V/MeshTransport(13013): Key: FED54C684EE8EF6BF6D914179490ACD6
V/MeshTransport(13013): akf: 0
V/MeshTransport(13013): aid: 0
V/MeshTransport(13013): aszmic: 0
V/MeshTransport(13013): Sequence number: 1
V/MeshTransport(13013): Access message opcode: 0
V/MeshTransport(13013): Access message parameters: 000000D9541B86A133D2FD2D9AFEE728EF9C1E
V/AccessLayer(13013): Created Access PDU 00000000D9541B86A133D2FD2D9AFEE728EF9C1E
V/UpperTransportLayer(13013): Device nonce: 02000000010001000100000000
V/UpperTransportLayer(13013): Encrypted upper transport pdu: EF2CF5C0965D489B816E5686C26AC2217BA67C1670418F79
V/LowerTransportLayer(13013): Segmented Lower transport access PDU: 80000401EF2CF5C0965D489B816E5686 0 of 2
V/LowerTransportLayer(13013): Segmented Lower transport access PDU: 80000421C26AC2217BA67C1670418F79 1 of 2
V/NetworkLayer(13013): Encryption key: FDD5640CB6047A842AE363EF11E1F19D
V/NetworkLayer(13013): Privacy key: 29A210E8521A7BA6FDE436E21A60412C
V/NetworkLayer(13013): Sequence Number: 000001
V/NetworkLayer(13013): Encrypted Network payload: A6266E1E2891E8DE48DB3D1C16DE46C39F38D290DC40
V/NetworkLayer(13013): Sequence Number: 000002
V/NetworkLayer(13013): Encrypted Network payload: 79255AF10947D1B45898C30D704A972D7A1B22A19E2F
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothLeScanner(13013): Start Scan with callback
D/BluetoothLeScanner(13013): onScannerRegistered() - status=0 scannerId=9 mScannerId=0
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothLeScanner(13013): Start Scan with callback
D/BluetoothLeScanner(13013): onScannerRegistered() - status=0 scannerId=10 mScannerId=0
D/ConfigurationService(13013): Mesh message processed -> dst: 1, meshMessage: 0
D/QBleMesh(13013): Sending ConfigCompositionDataGet...
V/MeshTransport(13013): Src address: 0001
V/MeshTransport(13013): Dst address: 0001
V/MeshTransport(13013): Key: FED54C684EE8EF6BF6D914179490ACD6
V/MeshTransport(13013): akf: 0
V/MeshTransport(13013): aid: 0
V/MeshTransport(13013): aszmic: 0
V/MeshTransport(13013): Sequence number: 3
V/MeshTransport(13013): Access message opcode: 8008
V/MeshTransport(13013): Access message parameters: 00
V/AccessLayer(13013): Created Access PDU 800800
V/UpperTransportLayer(13013): Device nonce: 02000000030001000100000000
V/UpperTransportLayer(13013): Encrypted upper transport pdu: 17556925B56D4C
V/LowerTransportLayer(13013): Unsegmented Lower transport access PDU 0017556925B56D4C
V/NetworkLayer(13013): Encryption key: FDD5640CB6047A842AE363EF11E1F19D
V/NetworkLayer(13013): Privacy key: 29A210E8521A7BA6FDE436E21A60412C
V/NetworkLayer(13013): Sequence Number: 000003
V/NetworkLayer(13013): Encrypted Network payload: 6F2589628BA478C34816A9546311
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothAdapter(13013): semIsBleEnabled(): ON
D/BluetoothAdapter(13013): getBleEnabledArray(): ON
D/BluetoothLeScanner(13013): Start Scan with callback
D/BluetoothLeScanner(13013): onScannerRegistered() - status=0 scannerId=11 mScannerId=0
D/ConfigurationService(13013): Mesh message processed -> dst: 1, meshMessage: 32776
philips77 commented 3 months ago

Hello, We are quite busy with other projects at the moment. We will come back to you as soon as possible. Sorry!

ahmadshoh-orc commented 3 months ago

Hello,

I wanted to share my latest observations and compile all my problems and questions together briefly.

  1. My issue closely resembles this issue: #570.
  2. Provisioning works fine.
  3. After provisioning, I am trying to reconnect to the node to fetch new service data.

QUESTION: Is it correct just call "connect" function from Ble-Library for reconnection?

bleManager.connect(address) {
    Log.d("QBleMesh", "Connected to device with address: $address")
    handler.postDelayed({
        Log.d("QBleMesh", "Starting configuration process.")
        startConfigurationProcess(selectedPeripheral, unicastAddress, callback)
    }, 5000)
}

Details of my attempts:

3.1. I attempted to call the connect function directly. It reconnects to the node, fetches new services and characteristics, and I can send ConfigAppKeyAdd and ConfigCompositionDataGet. Mesh messages are processed, but the problem is that no response messages are received, as seen in the logs.

3.2. I tried manually disconnecting from the provisioned node first and then reconnecting. It reconnects, but the "done" callback is not called, so I cannot start the configuration process.

bleManager.disconnect().enqueue()

bleManager.connect(address) {
  // Configuration
}

I have no ideas at all about what the problem might be and how to solve it. I would appreciate any insights or suggestions on how to resolve it. Thank you!

roshanrajaratnam commented 3 months ago

Hello,

When it comes to connecting to a mesh node we don't use the concept of connecting using a address. Oncea node is provisioned, it belongs to a mesh network and all devices in the network advertises with a certain network id derived using the primary network key that was added during provisioning. When connecting to a provisioned mesh node or the proxy node you have to always filter the devices using their network ID. May be you have this already in place, however an example of how to implement could be found in the sample app.

https://github.com/NordicSemiconductor/Android-nRF-Mesh-Library/blob/162a29e1b9b9de4c15f39f11c9034d51f486b1bd/app/src/main/java/no/nordicsemi/android/nrfmesh/viewmodels/ScannerRepository.java#L74-L99

D/BluetoothGatt(13013): setCharacteristicNotification() - uuid: 00002ade-0000-1000-8000-00805f9b34fb enable: true D/BluetoothGatt(13013): setCharacteristicNotification() - uuid: 00002adc-0000-1000-8000-00805f9b34fb enable: true

According to your logs I see the second characteristic seems to be wrong.

Following are the characteristics for a mesh proxy node with the mesh proxy service. https://github.com/NordicSemiconductor/Android-nRF-Mesh-Library/blob/162a29e1b9b9de4c15f39f11c9034d51f486b1bd/app/src/main/java/no/nordicsemi/android/nrfmesh/ble/BleMeshManager.java#L66-L71

Let me know how this goes.

ahmadshoh-orc commented 2 months ago

Hello Roshanrajaratman,

Thank you for your response. I implemented the reconnection method as you suggested. However, the logs indicate that the correct characteristics are initially set, but then overwritten by the provisioning characteristics. I am unsure why this occurs. I debugged each step, but I do not see any point in the code where the provisioning characteristics are being set after reconnection.

Here are the relevant log entries:

V/MeshManagerApi(18345): Received provisioning message: 0x0308
D/BleMeshManager(18345): provisioning is complete. unicast address is -> 2
D/BleMeshManager(18345): we did it.
D/BluetoothGatt(18345): onServiceChanged() - Device=XX:XX:XX:XX:08:92
D/BluetoothGatt(18345): cancelOpen() - device: 7C:DF:A1:DB:08:92
D/BluetoothGatt(18345): discoverServices() - device: 7C:DF:A1:DB:08:92
D/BluetoothGatt(18345): onClientConnectionState() - status=0 clientIf=6 device=XX:XX:XX:XX:08:92
D/BluetoothGatt(18345): close()
D/BluetoothGatt(18345): unregisterApp() - mClientIf=6
D/BluetoothAdapter(18345): getBleEnabledArray(): ON
D/BluetoothAdapter(18345): getBleEnabledArray(): ON
D/BluetoothAdapter(18345): semIsBleEnabled(): ON
D/BluetoothAdapter(18345): getBleEnabledArray(): ON
D/BluetoothLeScanner(18345): Start Scan with callback
D/BluetoothLeScanner(18345): onScannerRegistered() - status=0 scannerId=9 mScannerId=0
D/BluetoothAdapter(18345): getBleEnabledArray(): ON
D/BluetoothAdapter(18345): getBleEnabledArray(): ON
D/BluetoothLeScanner(18345): Stop Scan with callback
D/BluetoothAdapter(18345): getBleEnabledArray(): ON
D/BluetoothGatt(18345): connect() - device: 7C:DF:A1:DB:08:92, auto: false
D/BluetoothGatt(18345): registerApp()
D/BluetoothGatt(18345): registerApp() - UUID=d2a73192-1369-4fda-ad16-f8a0b2535a85
D/BluetoothGatt(18345): onClientRegistered() - status=0 clientIf=6
D/BluetoothAdapter(18345): getBleEnabledArray(): ON
D/BluetoothGatt(18345): onClientConnectionState() - status=0 clientIf=6 device=XX:XX:XX:XX:08:92
D/BluetoothGatt(18345): discoverServices() - device: 7C:DF:A1:DB:08:92
D/BluetoothGatt(18345): onConnectionUpdated() - Device=XX:XX:XX:XX:08:92 interval=6 latency=0 timeout=500 status=0
D/BluetoothGatt(18345): onSearchComplete() = Device=XX:XX:XX:XX:08:92 Status=0
D/BluetoothGatt(18345): configureMTU() - device: 7C:DF:A1:DB:08:92 mtu: 517
D/BluetoothGatt(18345): onConfigureMTU() - Device=XX:XX:XX:XX:08:92 mtu=23 status=0
D/BluetoothGatt(18345): setCharacteristicNotification() - uuid: 00002ade-0000-1000-8000-00805f9b34fb enable: true
D/BleMeshManager(18345): Data received -> mtu: 20, pdu: [65, 1, 0, -120, -30, -73, 36, 123, -105, -71, 90, 0, 0, 0, 0, 43, 69, 23, 29, -67]
D/BluetoothGatt(18345): setCharacteristicNotification() - uuid: 00002adc-0000-1000-8000-00805f9b34fb enable: true
D/BleMeshManager(18345): Data received -> mtu: 20, pdu: [-63, 110, 69, 122]
D/MeshManagerApi(18345): Received mesh beacon: SecureNetworkBeacon { KeyRefreshActive: false, IV Index: IV Index: 0, IV Update Active: false, Authentication Value: 0x2B45171DBD6E457A}
D/MeshManagerApi(18345): Secure Network Beacon authenticated.
D/MeshManagerApi(18345): Last IV Index: 0
I/MeshManagerApi(18345): Setting IV Update Active to: false
D/BluetoothGatt(18345): onConnectionUpdated() - Device=XX:XX:XX:XX:08:92 interval=24 latency=0 timeout=500 status=0

Below is the implementation of the connection to the provisioned node after provisioning:

fun provision(address: String, callback: (provisionedNode: ProvisionedNode) -> Unit) {
    provisioningService.provisionCallback = { selectedPeripheral, provisionedMeshNodeNode, unicastAddress ->
        val pnScanner = ProvisionedDevicesScanner(activity, meshManagerApi, bleManager)
        pnScanner.provisionedMeshNode = provisionedMeshNodeNode
        pnScanner.connectionCallback = SuccessCallback {
            Log.d("QBleMesh", "Connection callback was called.")
            startConfigurationProcess(selectedPeripheral, unicastAddress, callback)
        }

        bleManager.disconnect().enqueue()

        handler.postDelayed({ pnScanner.open() }, 2000)
    }

    val unprovisionedScanResult = unprovisionedScanResults.firstOrNull { it.device.address == address }
    unprovisionedScanResult?.let { result ->
        bleManager.connect(address) {
            Log.d("QBleMesh", "Connection done was called.")
            provisioningService.startProvisioningProcess(result)
        }
    }
}

Here is the ProvisionedDevicesScanner class:

class ProvisionedDevicesScanner(
    private val activity: Activity,
    private val meshManagerApi: MeshManagerApi,
    private val bleManager: BleMeshManager
) : ScanCallback() {

    private var isStarted: Boolean = false
    var connectionCallback: SuccessCallback? = null

    private var _provisionedMeshNode: ProvisionedMeshNode? = null
    var provisionedMeshNode: ProvisionedMeshNode
        get() = _provisionedMeshNode ?: throw IllegalStateException("ProvisionedMeshNode is not set")
        set(value) {
            _provisionedMeshNode = value
        }

    override fun onScanResult(callbackType: Int, result: ScanResult) {
        result.scanRecord?.getServiceData(ParcelUuid(BleMeshManager.MESH_PROXY_UUID))?.let { serviceData ->
            if (meshManagerApi.isAdvertisedWithNodeIdentity(serviceData) && meshManagerApi.nodeIdentityMatches(provisionedMeshNode, serviceData)) {
                stopScan()
                bleManager.connect(result.device).done(connectionCallback!!).retry(3, 500).enqueue()
            }
        }
    }

    fun open() {
        if (!isStarted) {
            PermissionManager.informAboutPermissionsGranted(activity) {
                startScan()
            }
        }
    }

    private fun startScan(): Boolean {
        if (isStarted) return true

        val scanSettings = ScanSettings.Builder()
            .setScanMode(ScanSettings.SCAN_MODE_LOW_LATENCY)
            .setReportDelay(0)
            .setUseHardwareFilteringIfSupported(false)
            .build()

        val scanFilters = listOf(
            ScanFilter.Builder().setServiceUuid(ParcelUuid(BleMeshManager.MESH_PROXY_UUID)).build()
        )

        return try {
            BluetoothLeScannerCompat.getScanner().startScan(scanFilters, scanSettings, this)
            isStarted = true
            true
        } catch (e: IllegalArgumentException) {
            isStarted = false
            false
        }
    }

    private fun stopScan(): Boolean {
        if (!isStarted) return true

        return try {
            BluetoothLeScannerCompat.getScanner().stopScan(this)
            isStarted = false
            true
        } catch (error: Exception) {
            false
        }
    }
}

Could you please help me understand why the characteristics are being overwritten and how to fix this issue?

Thank you!

ahmadshoh-orc commented 2 months ago

I found the error. After disconnecting, I needed to first clear all characteristics in BleMeshManager and then reconnect to it. After adding this code, everything now works fine.

fun clearCharacteristics() {
  // Clear all cached characteristics and reset GATT instance
  meshProvisioningDataInCharacteristic = null
  meshProvisioningDataOutCharacteristic = null
  meshProxyDataInCharacteristic = null
  meshProxyDataOutCharacteristic = null
  gatt = null
}