Matter: Search for device then Can't find device

[Shivam29]

Hello Dear,

                   I created Matter app reference by Matter Sample app using Matter SDK and I created matter virtual device with on/off clusters and it's working well but when I try with the physical device getting issues which is mentioned below -

I tested with 2.4GHz network but still not getting success

Searching for device....

Logcat

 W  Frame time is 0.089496 ms in the future!  Check that graphics HAL is generating vsync timestamps using the correct timebase.

addDeviceButton.setOnClickListener

CommissionDevice: starting 

commissionDeviceStatus.observe: status []

ShareDevice: Success getting the IntentSender: result [IntentSender]

commissionDeviceIntentSender.observe is called with [creatorPackage [com.google.android.gms]]

CommissionDevice: Launch GPS activity to commission device

Recording user engagement, ms: 13103

commissionDeviceIntentSender.observe is called with [null]

Connecting to remote service

Connection attempt already in progress

Activity paused, time: 3750429

onCreate()

intent [Intent commissioning.AppCommissioningService ]

Connected to remote service

Processing queued up service tasks: 2

Local module descriptor class for com.google.android.gms.googlecertificates not found.

Considering local module com.google.android.gms.googlecertificates:0 and remote module com.google.android.gms.googlecertificates:7

Selected remote version of com.google.android.gms.googlecertificates, version >= 7

Dynamite loader version >= 2, using loadModule2NoCrashUtils

Application going to the background

Application backgrounded at: timestamp_millis: 1709277938430

Inactivity, disconnecting from the service

Can't find device

and Some instructions

and also I shared some code snippet when I click on add device 

        _commissionDeviceStatus.postValue(TaskStatus.InProgress)

        val commissionDeviceRequest =
            CommissioningRequest.builder()
                .setCommissioningService(ComponentName(context, AppCommissioningService::class.java))
                .build()

        // The call to commissionDevice() creates the IntentSender that will eventually be launched
        // in the fragment to trigger the commissioning activity in GPS.
        Matter.getCommissioningClient(context)
            .commissionDevice(commissionDeviceRequest)
            .addOnSuccessListener { result ->
                Log.d("", "ShareDevice: Success getting the IntentSender: result [${result}]")
                // Communication with fragment is via livedata
                _commissionDeviceIntentSender.postValue(result)
            }
            .addOnFailureListener { error ->
                Log.d("Error", error.toString())
                Log.d("Numbersss", "18")

                //Timber.e(error)
                _commissionDeviceStatus.postValue(
                    TaskStatus.Failed("Setting up the IntentSender failed", error))
            }

and this is service class

@AndroidEntryPoint
class AppCommissioningService : Service(), CommissioningService.Callback {

    @Inject internal lateinit var devicesRepository: DevicesRepository
    @Inject internal lateinit var devicesStateRepository: DevicesStateRepository
    @Inject internal lateinit var chipClient: ChipClient

    private val serviceJob = Job()
    private val serviceScope = CoroutineScope(Dispatchers.Main + serviceJob)

    private lateinit var commissioningServiceDelegate: CommissioningService

    override fun onCreate() {
        super.onCreate()
        // May be invoked without MainActivity being called to initialize APP_NAME.
        // So do it here as well.
        Log.d("Numbersss", "3")
        APP_NAME = getString(R.string.app_name)
        Log.d("", "onCreate()")
        commissioningServiceDelegate = CommissioningService.Builder(this).setCallback(this).build()
    }

    override fun onBind(intent: Intent?): IBinder? {
        Log.d("Numbersss", "4")

        Log.d("onBind():", " intent [${intent}]")
        return commissioningServiceDelegate.asBinder()
    }

    override fun onStartCommand(intent: Intent?, flags: Int, startId: Int): Int {
        Log.d("Numbersss", "5")

        Log.d("", "onStartCommand(): intent [${intent}] flags [${flags}] startId [${startId}]")
        return super.onStartCommand(intent, flags, startId)
    }

    override fun onDestroy() {
        super.onDestroy()
        Log.d("Numbersss", "6")

        Log.d("", "onDestroy()")
        serviceJob.cancel()
    }

    override fun onCommissioningRequested(metadata: CommissioningRequestMetadata) {
        Log.d("Numbersss", "7")

        Log.d("Requestedddddddd---->",
            "*** onCommissioningRequested ***:\n" +
                    "\tdeviceDescriptor: " +
                    "deviceType [${metadata.deviceDescriptor.deviceType}] " +
                    "vendorId [${metadata.deviceDescriptor.vendorId}] " +
                    "productId [${metadata.deviceDescriptor.productId}]\n" +
                    "\tnetworkLocation: " +
                    "IP address toString() [${metadata.networkLocation.ipAddress}] " +
                    "IP address hostAddress [${metadata.networkLocation.ipAddress.hostAddress}] " +
                    "port [${metadata.networkLocation.port}]\n" +
                    "\tpassCode [${metadata.passcode}]")

        // CODELAB: onCommissioningRequested()
        serviceScope.launch {
            val deviceId = devicesRepository.incrementAndReturnLastDeviceId()
            Log.d("",
                "Commissioning: App fabric -> ChipClient.establishPaseConnection(): deviceId [${deviceId}]")
            chipClient.awaitEstablishPaseConnection(
                deviceId,
                metadata.networkLocation.ipAddress.hostAddress!!,
                metadata.networkLocation.port,
                metadata.deviceDescriptor.vendorId,
                metadata.deviceDescriptor.productId,
                metadata.deviceDescriptor.deviceType,
                metadata.passcode)
            Log.d("", "Commissioning: App fabric -> ChipClient.commissionDevice(): deviceId [${deviceId}]")
            chipClient.awaitCommissionDevice(deviceId, null)

            Log.d("", "Commissioning: Calling commissioningServiceDelegate.sendCommissioningComplete()")
            commissioningServiceDelegate
                .sendCommissioningComplete(
                    CommissioningCompleteMetadata.builder().setToken(deviceId.toString()).build())
                .addOnSuccessListener {
                    Log.d("",
                        "Commissioning: OnSuccess for commissioningServiceDelegate.sendCommissioningComplete()")
                }
                .addOnFailureListener { ex ->
                    Log.e("", "Commissioning: Failed to send commissioning complete.", ex)
                }
        }
        // CODELAB SECTION END
    }
}

[sipriyadarshi · Accepted solution]

Hello @Shivam29 ,

You can try working with the following commands more information about this can be found here. 

adb shell setprop log.tag.gms_svc_id:336 VERBOSE
adb shell setprop log.tag.gms_svc_id:305 VERBOSE
adb shell setprop log.tag.gms_svc_id:168 VERBOSE
adb logcat | grep MatterCommissioner

Also, try to browse BLE or DNS-SD with another tool if it seems the device can't connect .  

[sipriyadarshi · Accepted solution]

Hello @Shivam29 ,

You can try working with the following commands more information about this can be found here. 

adb shell setprop log.tag.gms_svc_id:336 VERBOSE
adb shell setprop log.tag.gms_svc_id:305 VERBOSE
adb shell setprop log.tag.gms_svc_id:168 VERBOSE
adb logcat | grep MatterCommissioner

Also, try to browse BLE or DNS-SD with another tool if it seems the device can't connect .  

[Shivam29 · Accepted solution]

I think getting some timeout. I sharing some logs -

Log 1:

WifiHAL : createRequest: APF set program request

WifiHAL : Success to allocate program of len: 506

RpcRunner: (REDACTED) Retrieving ClientContext and token for %s.

MatterCommissioner: No matching devices discovered. [CONTEXT service_id=336 ]

SetupDeviceViewModel: Commissioning failed with state Failed to discover commissionable device. [CONTEXT service_id=336 ]

SetupDeviceViewModel: m.vxc: Timed out waiting for 60000 ms

SetupDeviceViewModel:  at m.vxd.run(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):56)

SetupDeviceViewModel:  at android.os.Handler.handleCallback(Handler.java:958)

SetupDeviceViewModel:  at android.os.Handler.dispatchMessage(Handler.java:99)

SetupDeviceViewModel:  at android.os.Looper.loopOnce(Looper.java:205)

SetupDeviceViewModel:  at android.os.Looper.loop(Looper.java:294)

SetupDeviceViewModel:  at android.app.ActivityThread.main(ActivityThread.java:8248)

SetupDeviceViewModel:  at java.lang.reflect.Method.invoke(Native Method)

SetupDeviceViewModel:  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:552)

SetupDeviceViewModel:  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:971)

SetupDeviceChimeraActiv: Showing error status. [CONTEXT service_id=336 ]

SetupDeviceChimeraActiv: m.guw: Timed out waiting for 60000 ms

SetupDeviceChimeraActiv: at m.hde.b(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):459)

SetupDeviceChimeraActiv:       at m.hde.a(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):3)

SetupDeviceChimeraActiv:       at m.wae.a(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):60)

SetupDeviceChimeraActiv:       at m.wbo.a(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):84)

SetupDeviceChimeraActiv:       at m.wea.a(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):3)

SetupDeviceChimeraActiv:       at m.wdz.a(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):137)

SetupDeviceChimeraActiv:       at m.etm.b(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):109)

SetupDeviceChimeraActiv:       at m.eta.invokeSuspend(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):11)

SetupDeviceChimeraActiv:       at m.vmn.resumeWith(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):14)

SetupDeviceChimeraActiv:       at m.vuy.a(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):53)

SetupDeviceChimeraActiv:       at m.vth.E(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):89)

SetupDeviceChimeraActiv:       at m.vth.G(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):28)

SetupDeviceChimeraActiv:       at m.vth.A(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):2)

SetupDeviceChimeraActiv:       at m.vth.resumeWith(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):24)

SetupDeviceChimeraActiv:       at m.vwv.b(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):5)

SetupDeviceChimeraActiv:       at m.vwl.j(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):89)

SetupDeviceChimeraActiv:       at m.vwl.y(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):295)

SetupDeviceChimeraActiv:       at m.vwl.C(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):201)

SetupDeviceChimeraActiv:       at m.vwl.B(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):6)

SetupDeviceChimeraActiv:       at m.vst.resumeWith(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):5)

SetupDeviceChimeraActiv:       at m.vmn.resumeWith(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):38)

SetupDeviceChimeraActiv:       at m.vux.run(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):106)

SetupDeviceChimeraActiv:       at android.os.Handler.handleCallback(Handler.java:958)

SetupDeviceChimeraActiv:       at android.os.Handler.dispatchMessage(Handler.java:99)

SetupDeviceChimeraActiv:       at android.os.Looper.loopOnce(Looper.java:205)

SetupDeviceChimeraActiv:       at android.os.Looper.loop(Looper.java:294)

SetupDeviceChimeraActiv:       at android.app.ActivityThread.main(ActivityThread.java:8248)

SetupDeviceChimeraActiv:       at java.lang.reflect.Method.invoke(Native Method)

SetupDeviceChimeraActiv:       at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:552)

SetupDeviceChimeraActiv:       at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:971)

SetupDeviceChimeraActiv: Caused by: m.vxc: Timed out waiting for 60000 ms

SetupDeviceChimeraActiv:       at m.vxd.run(:com.google.android.gms.optional_home@240854042@24.08.54 (100400-0):56)

SetupDeviceChimeraActiv:       ... 8 more

WindowOnBackDispatcher: OnBackInvokedCallback is not enabled for the application.

WindowOnBackDispatcher: Set 'android:enableOnBackInvokedCallback="true"' in the application manifest.

OomAdjuster: Not killing cached processes

WifiHAL : Done!

WifiHAL : Setting DTIM config , halHandle = 0xb400007d4d147850 Multiplier = 2

WifiHAL : Successfully configured dtim multiplier 2

BoundBrokerSvc: onBind: Intent { act=com.google.android.gms.feedback.internal.IFeedbackService dat=chimera-action:/... cmp=com.google.android.gms/.chimera.GmsBoundBrokerService }

BoundBrokerSvc: Loading bound service for intent: Intent { act=com.google.android.gms.feedback.internal.IFeedbackService dat=chimera-action:/... cmp=com.google.android.gms/.chimera.GmsBoundBrokerService }

RpcRunner: (REDACTED) Executing RPC %s

pixel-thermal: neutral_therm:33.976 raw data: neutral_therm:33976 

pixel-thermal: cellular-emergency:34.9063 raw data: VIRTUAL-NEUTRAL:34906.3 VIRTUAL-NEUTRAL-SKIN2:34723.9 VIRTUAL-QUIET-NEUTRAL:33836 cellular-emergency:34906.3 disp_therm:33486 gnss_tcxo_therm:35111 neutral_therm:33976 quiet_therm:33776 skin_therm1:35868 skin_therm2:36469 

pixel-thermal: VIRTUAL-SKIN-CPU:34.9063 raw data: VIRTUAL-NEUTRAL:34906.3 VIRTUAL-NEUTRAL-SKIN2:34723.9 VIRTUAL-QUIET-NEUTRAL:33836 VIRTUAL-SKIN-CPU:34906.3 

pixel-thermal: VIRTUAL-SKIN:34.9063 raw data: VIRTUAL-NEUTRAL:34906.3 VIRTUAL-NEUTRAL-SKIN2:34723.9 VIRTUAL-QUIET-NEUTRAL:33836 VIRTUAL-SKIN:34906.3 

pixel-thermal: VIRTUAL-SKIN-CHARGE:34.9063 raw data: VIRTUAL-NEUTRAL:34906.3 VIRTUAL-NEUTRAL-SKIN2:34723.9 VIRTUAL-QUIET-NEUTRAL:33836 VIRTUAL-SKIN-CHARGE:34906.3 

pixel-thermal: VIRTUAL-SKIN-CPU-GPU:34.9063 raw data: VIRTUAL-NEUTRAL:34906.3 VIRTUAL-NEUTRAL-SKIN2:34723.9 VIRTUAL-QUIET-NEUTRAL:33836 VIRTUAL-SKIN-CPU-GPU:34906.3 

pixel-thermal: VIRTUAL-SKIN-HINT:34.9063 raw data: VIRTUAL-NEUTRAL:34906.3 VIRTUAL-NEUTRAL-SKIN2:34723.9 VIRTUAL-QUIET-NEUTRAL:33836 VIRTUAL-SKIN-HINT:34906.3 

WifiHAL : Creating message to get link statistics; iface = 47

WifiHAL : In GetLinkStatsCommand::handleResponse

ConnectivityService: NetReassign [no changes] [c 2] [a 1] [i 14]

RpcRunner: (REDACTED) RPC %s completed successfully.

NearbyMediums: Found Fast Ble Advertisements :

NearbyMediums: BleAdvertisement { version=2, socketVersion=2, serviceIdHash=null, data=[ 0x23 0x39 0x4a 0x58 0x45 0x11 0x32 0x85 0xa3 0x20 0xd5 0x80 0x50 0x02 0x89 0xc9 0x8c 0x1b 0xbc 0x79 0x19 0xfc 0x0e ], deviceToken=[ 0x05 0xe3 ] } : 2 times.

NearbyMediums: Total 2 fast advertisements.

Log 2 :

adb logcat | grep MatterCommissioner

MatterCommissioner: (REDACTED) Starting commissioning flow for sessionId: and device identifier: .

MatterCommissioner: Retrieved commissioner credentials. [CONTEXT service_id=336 ]

MatterCommissioner: (REDACTED) Looking for device with discriminator %s

MatterCommissioner: Discovery found no devices during scan. [CONTEXT service_id=336 ]

MatterCommissioner: No matching devices discovered. [CONTEXT service_id=336 ]

MatterCommissioner: (REDACTED) Starting commissioning flow for sessionId: %s and device identifier: %s.

MatterCommissioner: Retrieved commissioner credentials. [CONTEXT service_id=336 ]

MatterCommissioner: (REDACTED) Looking for device with discriminator %s

MatterCommissioner: Discovery found no devices during scan. [CONTEXT service_id=336 ]

MatterCommissioner: No matching devices discovered. [CONTEXT service_id=336 ]

Log 3 :

addDeviceButton.setOnClickListener

CommissionDevice: starting

commissionDeviceStatus.observe: status [InProgress]

ShareDevice: Success getting the IntentSender: result [IntentSender]

commissionDeviceIntentSender.observe is called with [creatorPackage [com.google.android.gms]]

CommissionDevice: Launch GPS activity to commission device

Recording user engagement, ms: 132015

commissionDeviceIntentSender.observe is called with [null]

Connecting to remote service

Connection attempt already in progress

Activity paused, time: 89678756

onCreate()

intent [Intent commissioning.AppCommissioningService ]

Connected to remote service

Processing queued up service tasks: 2

Local module descriptor class for com.google.android.gms.googlecertificates not found.

Considering local module com.google.android.gms.googlecertificates:0 and remote module com.google.android.gms.googlecertificates:7

Selected remote version of com.google.android.gms.googlecertificates, version >= 7

Dynamite loader version >= 2, using loadModule2NoCrashUtils

Application going to the background

Application backgrounded at: timestamp_millis: 1709894450761

Inactivity, disconnecting from the service

and also I have 

Tapo Matter L535 with the

Form Factor: A19, E26

Brightness: 1100L

Color Temperature Range:  2500-6500K