espressif / esp-matter

Espressif's SDK for Matter
Apache License 2.0
686 stars 155 forks source link

Connect matter device to Google Home won't work (CON-1087) #871

Closed FloBer431 closed 1 week ago

FloBer431 commented 7 months ago

Hello there,

I finally got my contact-sensor device generally working. I also already connected it with apple home and it working out fine (except that the default state is open, not closed as i want it to be) But when I tried to connect it with Google Home, following error occured: E (45302) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = 201

maybe somebody can help

Thanks Florian

VaishaliAvhale commented 7 months ago

Please enable debug log as follows Component config → Log output → Default log verbosity -> Debug and retry same thing and attach complete device side logs file.

FHFS commented 7 months ago

I added some breaklines for readability, because I couldnt read this.

I (36161) chip[ZCL]: Received command to open commissioning window 
I (36161) chip[DIS]: Updating services using commissioning mode 2 
I (36171) chip[DIS]: CHIP minimal mDNS started advertising. 
I (36181) chip[DIS]: Advertise operational node 5236AFA001B879D3-00000000B69FF720 
I (36181) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5236AFA001B879D3-00000000B69FF720. 
I (36201) chip[DIS]: mDNS service published: _matter._tcp 
I (36201) chip[DIS]: Advertise commission parameter vendorID=65522 productID=32769 discriminator=4054/15 cm=2 cp=0 
I (36211) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 7E0318A45F6ECB60. 
I (36231) chip[DIS]: mDNS service published: _matterc._udp 
I (36231) chip[ZCL]: Commissioning window is now open 
I (36241) chip[EM]: <<< [E:17196r S:58560 M:121875092 (Ack:140751351)] (S) Msg TX to 1:00000000C2053460 [79D3] [UDP:192.168.178.109%st1:57784] --- Type 0001:09 (IM:InvokeCommandResponse) 
I (36261) logger: [CSystem::matter_event_callback] Commissioning window opened [system.cpp:382] 
I (36261) chip[EM]: >>> [E:17196r S:58560 M:140751352 (Ack:121875092)] (S) Msg RX from 1:00000000C2053460 [79D3] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (36411) chip[EM]: >>> [E:53360r S:0 M:214017046] (U) Msg RX from 0:8E41A27935CD5049 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) 
I (36421) chip[EM]: <<< [E:53360r S:0 M:147602092 (Ack:214017046)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (36441) chip[EM]: <<< [E:53360r S:0 M:147602093 (Ack:214017046)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) 
I (36451) chip[SVR]: Commissioning session establishment step started 
I (36481) chip[EM]: >>> [E:53360r S:0 M:214017047 (Ack:147602093)] (U) Msg RX from 0:8E41A27935CD5049 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) 
I (36481) chip[EM]: <<< [E:53360r S:0 M:147602094 (Ack:214017047)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (37231) chip[EM]: <<< [E:53360r S:0 M:147602095 (Ack:214017047)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0000:23 (SecureChannel:PASE_Pake2) 
E (37241) chip[DL]: Long dispatch time: 763 ms, for event type 3 
I (37271) chip[EM]: >>> [E:53360r S:0 M:214017048 (Ack:147602095)] (U) Msg RX from 0:8E41A27935CD5049 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) 
I (37271) chip[EM]: <<< [E:53360r S:0 M:147602096 (Ack:214017048)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (37291) chip[EM]: <<< [E:53360r S:0 M:147602097 (Ack:214017048)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0000:40 (SecureChannel:StatusReport) 
I (37311) chip[SC]: SecureSession[0x3fc9fe78, LSID:58562]: State change 'kEstablishing' --> 'kActive' 
I (37321) chip[SVR]: Commissioning completed session establishment step 
I (37321) chip[DIS]: Updating services using commissioning mode 0 
I (37331) chip[DIS]: CHIP minimal mDNS started advertising. 
I (37351) chip[DIS]: Advertise operational node 5236AFA001B879D3-00000000B69FF720 
I (37361) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 5236AFA001B879D3-00000000B69FF720. 
I (37371) chip[DIS]: mDNS service published: _matter._tcp 
I (37371) chip[SVR]: Device completed Rendezvous process 
I (37381) logger: [CSystem::matter_event_callback] Commissioning session started [system.cpp:374] 
I (37391) chip[EM]: >>> [E:53360r S:0 M:214017049 (Ack:147602097)] (U) Msg RX from 0:8E41A27935CD5049 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (37401) chip[EM]: >>> [E:53361r S:58562 M:14345287] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
I (37411) logger: [CSystem::matter_event_callback] Commissioning window closed [system.cpp:385] 
I (37421) chip[EM]: <<< [E:53361r S:58562 M:267819773 (Ack:14345287)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (37481) chip[EM]: >>> [E:53361r S:58562 M:14345288 (Ack:267819773)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (37481) chip[EM]: >>> [E:53362r S:58562 M:14345289] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 
I (37501) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x00000030 
I (37511) chip[FS]: GeneralCommissioning: Received ArmFailSaf
E (120s) 
I (37511) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0x00000030's Attribute 0x00000000 is 0 ********** 
I (37531) chip[EM]: <<< [E:53362r S:58562 M:267819774 (Ack:14345289)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:09 (IM:InvokeCommandResponse) 
I (37551) chip[EM]: >>> [E:53362r S:58562 M:14345290 (Ack:267819774)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (38261) ROUTE_HOOK: Received RIO 
I (38261) ROUTE_HOOK: prefix FDD9:AD53:1ECD:: lifetime 1800 
I (38561) chip[EM]: >>> [E:53363r S:58562 M:14345291] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 
I (38561) esp_matter_command: Received command 0x00000000 for endpoint 0x0000's cluster 0x0000003E 
I (38571) chip[ZCL]: OpCreds: Received an AttestationRequest command 
I (38581) chip[EM]: <<< [E:53363r S:58562 M:267819775 (Ack:14345291)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (38671) chip[ZCL]: OpCreds: AttestationRequest successful. 
I (38671) chip[EM]: <<< [E:53363r S:58562 M:267819776 (Ack:14345291)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:09 (IM:InvokeCommandResponse) 
I (38691) chip[EM]: >>> [E:53363r S:58562 M:14345292 (Ack:267819776)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (38701) chip[EM]: >>> [E:53364r S:58562 M:14345293] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 
I (38711) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E 
I (38721) chip[ZCL]: OpCreds: Certificate Chain request received for DAC 
I (38741) chip[EM]: <<< [E:53364r S:58562 M:267819777 (Ack:14345293)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:09 (IM:InvokeCommandResponse) 
I (38781) chip[EM]: >>> [E:53364r S:58562 M:14345294 (Ack:267819777)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (38791) chip[EM]: >>> [E:53365r S:58562 M:14345295] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) 
I (38801) esp_matter_command: Received command 0x00000002 for endpoint 0x0000's cluster 0x0000003E 
I (38811) chip[ZCL]: OpCreds: Certificate Chain request received for PAI 
I (38821) chip[EM]: <<< [E:53365r S:58562 M:267819778 (Ack:14345295)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:09 (IM:InvokeCommandResponse) 
I (38851) chip[EM]: >>> [E:53365r S:58562 M:14345296 (Ack:267819778)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (38861) chip[EM]: >>> [E:53366r S:58562 M:14345297] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
I (38881) chip[EM]: <<< [E:53366r S:58562 M:267819779 (Ack:14345297)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (38911) chip[EM]: >>> [E:53366r S:58562 M:14345298 (Ack:267819779)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (38921) chip[EM]: >>> [E:53367r S:58562 M:14345299] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
I (38941) chip[EM]: <<< [E:53367r S:58562 M:267819780 (Ack:14345299)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (38981) chip[EM]: >>> [E:53367r S:58562 M:14345300 (Ack:267819780)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (38981) chip[EM]: >>> [E:53368r S:58562 M:14345301] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
E (39001) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = 201 
I (39001) chip[EM]: <<< [E:53368r S:58562 M:267819781 (Ack:14345301)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (39041) chip[EM]: >>> [E:53368r S:58562 M:14345302 (Ack:267819781)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (40201) chip[EM]: >>> [E:53369r S:58562 M:14345303] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
I (40201) chip[EM]: <<< [E:53369r S:58562 M:267819782 (Ack:14345303)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (40401) chip[EM]: >>> [E:53369r S:58562 M:14345304 (Ack:267819782)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (40411) chip[EM]: >>> [E:53370r S:58562 M:14345305] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
I (40421) chip[EM]: <<< [E:53370r S:58562 M:267819783 (Ack:14345305)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (40451) chip[EM]: >>> [E:53370r S:58562 M:14345306 (Ack:267819783)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (40451) chip[EM]: >>> [E:53371r S:58562 M:14345307] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
E (40471) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = 201 
I (40471) chip[EM]: <<< [E:53371r S:58562 M:267819784 (Ack:14345307)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (40711) chip[EM]: >>> [E:53371r S:58562 M:14345308 (Ack:267819784)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (41671) chip[EM]: >>> [E:53372r S:58562 M:14345309] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
I (41681) chip[EM]: <<< [E:53372r S:58562 M:267819785 (Ack:14345309)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (41701) chip[EM]: >>> [E:53372r S:58562 M:14345310 (Ack:267819785)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (41711) chip[EM]: >>> [E:53373r S:58562 M:14345311] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
I (41721) chip[EM]: <<< [E:53373r S:58562 M:267819786 (Ack:14345311)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (41751) chip[EM]: >>> [E:53373r S:58562 M:14345312 (Ack:267819786)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (41761) chip[EM]: >>> [E:53374r S:58562 M:14345313] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) 
E (41771) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = 201 
I (41781) chip[EM]: <<< [E:53374r S:58562 M:267819787 (Ack:14345313)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:62859] --- Type 0001:05 (IM:ReportData) 
I (41821) chip[EM]: >>> [E:53374r S:58562 M:14345314 (Ack:267819787)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) 
I (42751) ROUTE_HOOK: Received RIO 
I (42751) ROUTE_HOOK: prefix FDD9:AD53:1ECD:: lifetime 1800 
I (46951) ROUTE_HOOK: Received RIO
VaishaliAvhale commented 7 months ago

The above logs do not indicate that debug log configuration is enabled. The error 201 stands for CHIP_DEVICE_ERROR_CONFIG_NOT_FOUND, indicating that the requested configuration value was not found. The error is encountered for cluster 0x0028, which is the basic information cluster. Please enable the debug log as mentioned above to get the attribute of the cluster for which the config value is not found. Additionally, could you please let me know if you are trying to make any changes to the basic information cluster in your code?

FloBer431 commented 7 months ago

@VaishaliAvhale I tried to enable the debug log as mentioned, but I think it didn't work. I'm working with Visual Studio on Windows via WSL. I enabled the debug log in the VS Extension settings, but this dont effect my log output. Is there another way to enable the log?

I don't think I'm trying to do any changes to the basic information cluster.

FHFS commented 7 months ago

Add CONFIG_LOG_DEFAULT_LEVEL_DEBUG=y to your file sdkconfig.defaults And build using idf.py -D SDKCONFIG_DEFAULTS="sdkconfig.defaults" clean build

You should see CONFIG_LOG_DEFAULT_LEVEL_DEBUG=y in the sdkconfig that was generated during the build.

FloBer431 commented 7 months ago

Okay, I think that worked now, thank you @FHFS.

This is the part from the sdkconfig:

# Log output
#
# CONFIG_LOG_DEFAULT_LEVEL_NONE is not set
# CONFIG_LOG_DEFAULT_LEVEL_ERROR is not set
# CONFIG_LOG_DEFAULT_LEVEL_WARN is not set
# CONFIG_LOG_DEFAULT_LEVEL_INFO is not set
CONFIG_LOG_DEFAULT_LEVEL_DEBUG=y
# CONFIG_LOG_DEFAULT_LEVEL_VERBOSE is not set

Now the log is massive, I hope I copied everything that is necessary:

D (63516) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (63526) chip[EM]: >>> [E:30269r S:55454 M:225728011 (Ack:190411351)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (63536) chip[EM]: Found matching exchange: 30269r, Delegate: 0x0
D (63546) chip[EM]: Rxd Ack; Removing MessageCounter:190411351 from Retrans Table on exchange 30269r
I (63556) chip[EM]: >>> [E:30270r S:55454 M:225728012] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (63566) chip[EM]: Handling via exchange: 30270r, Delegate: 0x3fca5054
D (63576) chip[IM]: Received Read request
D (63576) chip[DMG]: ReadRequestMessage =
D (63586) chip[DMG]: {
D (63586) chip[DMG]:    AttributePathIBs =
D (63586) chip[DMG]:    [
D (63596) chip[DMG]:            AttributePathIB =
D (63596) chip[DMG]:            {
D (63596) chip[DMG]:                    Endpoint = 0x0,
D (63606) chip[DMG]:                    Cluster = 0x28,
D (63606) chip[DMG]:                    Attribute = 0x0000_0003,
D (63606) chip[DMG]:            }
D (63616) chip[DMG]: 
D (63616) chip[DMG]:    ],
D (63616) chip[DMG]: 
D (63626) chip[DMG]:    isFabricFiltered = true, 
D (63626) chip[DMG]:    InteractionModelRevision = 11
D (63626) chip[DMG]: },
D (63636) chip[DMG]: IM RH moving to [CanStartReporting]
D (63636) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
D (63646) chip[DMG]: <RE:Run> Cluster 28, Attribute 3 is dirty
D (63656) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D (63666) nvs: nvs_open_from_partition chip-factory 0
D (63676) nvs: nvs_get_str_or_blob product-name
D (63676) nvs: nvs_close 381
E (63676) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = 201
D (63686) chip[DMG]: <RE> Sending report (payload has 33 bytes)...
I (63696) chip[EM]: <<< [E:30270r S:55454 M:190411352 (Ack:225728012)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:59913] --- Type 0001:05 (IM:ReportData)
D (63716) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (63716) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (63726) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (63726) nvs: nvs_open_from_partition CHIP_KVS 0
D (63736) nvs: nvs_get_str_or_blob g/su/0
D (63736) nvs: nvs_close 382
D (63746) nvs: nvs_open_from_partition CHIP_KVS 0
D (63746) nvs: nvs_get_str_or_blob g/su/1
D (63746) nvs: nvs_close 383
D (63756) nvs: nvs_open_from_partition CHIP_KVS 0
D (63756) nvs: nvs_get_str_or_blob g/su/2
D (63766) nvs: nvs_close 384
D (63766) nvs: nvs_open_from_partition CHIP_KVS 0
D (63766) nvs: nvs_get_str_or_blob g/su/3
D (63776) nvs: nvs_close 385
D (63776) nvs: nvs_open_from_partition CHIP_KVS 0
D (63786) nvs: nvs_get_str_or_blob g/su/4
D (63786) nvs: nvs_close 386
D (63786) nvs: nvs_open_from_partition CHIP_KVS 0
D (63796) nvs: nvs_get_str_or_blob g/su/5
D (63796) nvs: nvs_close 387
D (63796) nvs: nvs_open_from_partition CHIP_KVS 0
D (63806) nvs: nvs_get_str_or_blob g/su/6
D (63806) nvs: nvs_close 388
D (63816) nvs: nvs_open_from_partition CHIP_KVS 0
D (63816) nvs: nvs_get_str_or_blob g/su/7
D (63826) nvs: nvs_close 389
D (63826) nvs: nvs_open_from_partition CHIP_KVS 0
D (63826) nvs: nvs_get_str_or_blob g/su/8
D (63836) nvs: nvs_close 390
D (63836) nvs: nvs_open_from_partition CHIP_KVS 0
D (63846) nvs: nvs_get_str_or_blob g/su/9
D (63846) nvs: nvs_close 391
D (63846) nvs: nvs_open_from_partition CHIP_KVS 0
D (63856) nvs: nvs_get_str_or_blob g/su/a
D (63856) nvs: nvs_close 392
D (63856) nvs: nvs_open_from_partition CHIP_KVS 0
D (63866) nvs: nvs_get_str_or_blob g/su/b
D (63866) nvs: nvs_close 393
D (63876) nvs: nvs_open_from_partition CHIP_KVS 0
D (63876) nvs: nvs_get_str_or_blob g/su/c
D (63876) nvs: nvs_close 394
D (63886) nvs: nvs_open_from_partition CHIP_KVS 0
D (63886) nvs: nvs_get_str_or_blob g/su/d
D (63896) nvs: nvs_close 395
D (63896) nvs: nvs_open_from_partition CHIP_KVS 0
D (63896) nvs: nvs_get_str_or_blob g/su/e
D (63906) nvs: nvs_close 396
D (63906) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (63916) chip[EM]: >>> [E:30270r S:55454 M:225728013 (Ack:190411352)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (63926) chip[EM]: Found matching exchange: 30270r, Delegate: 0x0
D (63936) chip[EM]: Rxd Ack; Removing MessageCounter:190411352 from Retrans Table on exchange 30270r
I (64856) chip[EM]: >>> [E:30271r S:55454 M:225728014] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (64856) chip[EM]: Handling via exchange: 30271r, Delegate: 0x3fca5054
D (64866) chip[IM]: Received Read request
D (64866) chip[DMG]: ReadRequestMessage =
D (64876) chip[DMG]: {
D (64876) chip[DMG]:    AttributePathIBs =
D (64876) chip[DMG]:    [
D (64876) chip[DMG]:            AttributePathIB =
D (64886) chip[DMG]:            {
D (64886) chip[DMG]:                    Endpoint = 0x0,
D (64886) chip[DMG]:                    Cluster = 0x28,
D (64896) chip[DMG]:                    Attribute = 0x0000_0002,
D (64896) chip[DMG]:            }
D (64906) chip[DMG]: 
D (64906) chip[DMG]:    ],
D (64906) chip[DMG]: 
D (64906) chip[DMG]:    isFabricFiltered = true, 
D (64916) chip[DMG]:    InteractionModelRevision = 11
D (64916) chip[DMG]: },
D (64926) chip[DMG]: IM RH moving to [CanStartReporting]
D (64926) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
D (64936) chip[DMG]: <RE:Run> Cluster 28, Attribute 2 is dirty
D (64946) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D (64956) nvs: nvs_open_from_partition chip-factory 0
D (64956) nvs: nvs_get vendor-id 4
D (64966) nvs: nvs_close 397
D (64966) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (64976) chip[EM]: <<< [E:30271r S:55454 M:190411353 (Ack:225728014)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:59913] --- Type 0001:05 (IM:ReportData)
D (64996) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (64996) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (65006) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (65006) nvs: nvs_open_from_partition CHIP_KVS 0
D (65016) nvs: nvs_get_str_or_blob g/su/0
D (65016) nvs: nvs_close 398
D (65026) nvs: nvs_open_from_partition CHIP_KVS 0
D (65026) nvs: nvs_get_str_or_blob g/su/1
D (65026) nvs: nvs_close 399
D (65036) nvs: nvs_open_from_partition CHIP_KVS 0
D (65036) nvs: nvs_get_str_or_blob g/su/2
D (65046) nvs: nvs_close 400
D (65046) nvs: nvs_open_from_partition CHIP_KVS 0
D (65046) nvs: nvs_get_str_or_blob g/su/3
D (65056) nvs: nvs_close 401
D (65056) nvs: nvs_open_from_partition CHIP_KVS 0
D (65066) nvs: nvs_get_str_or_blob g/su/4
D (65066) nvs: nvs_close 402
D (65066) nvs: nvs_open_from_partition CHIP_KVS 0
D (65076) nvs: nvs_get_str_or_blob g/su/5
D (65076) nvs: nvs_close 403
D (65076) nvs: nvs_open_from_partition CHIP_KVS 0
D (65086) nvs: nvs_get_str_or_blob g/su/6
D (65086) nvs: nvs_close 404
D (65096) nvs: nvs_open_from_partition CHIP_KVS 0
D (65096) nvs: nvs_get_str_or_blob g/su/7
D (65106) nvs: nvs_close 405
D (65106) nvs: nvs_open_from_partition CHIP_KVS 0
D (65106) nvs: nvs_get_str_or_blob g/su/8
D (65116) nvs: nvs_close 406
D (65116) nvs: nvs_open_from_partition CHIP_KVS 0
D (65116) nvs: nvs_get_str_or_blob g/su/9
D (65126) nvs: nvs_close 407
D (65126) nvs: nvs_open_from_partition CHIP_KVS 0
D (65136) nvs: nvs_get_str_or_blob g/su/a
D (65136) nvs: nvs_close 408
D (65136) nvs: nvs_open_from_partition CHIP_KVS 0
D (65146) nvs: nvs_get_str_or_blob g/su/b
D (65146) nvs: nvs_close 409
D (65156) nvs: nvs_open_from_partition CHIP_KVS 0
D (65156) nvs: nvs_get_str_or_blob g/su/c
D (65156) nvs: nvs_close 410
D (65166) nvs: nvs_open_from_partition CHIP_KVS 0
D (65166) nvs: nvs_get_str_or_blob g/su/d
D (65176) nvs: nvs_close 411
D (65176) nvs: nvs_open_from_partition CHIP_KVS 0
D (65176) nvs: nvs_get_str_or_blob g/su/e
D (65186) nvs: nvs_close 412
D (65186) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (65196) chip[EM]: >>> [E:30271r S:55454 M:225728015 (Ack:190411353)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (65206) chip[EM]: Found matching exchange: 30271r, Delegate: 0x0
D (65216) chip[EM]: Rxd Ack; Removing MessageCounter:190411353 from Retrans Table on exchange 30271r
I (65226) chip[EM]: >>> [E:30272r S:55454 M:225728016] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (65236) chip[EM]: Handling via exchange: 30272r, Delegate: 0x3fca5054
D (65246) chip[IM]: Received Read request
D (65246) chip[DMG]: ReadRequestMessage =
D (65246) chip[DMG]: {
D (65256) chip[DMG]:    AttributePathIBs =
D (65256) chip[DMG]:    [
D (65256) chip[DMG]:            AttributePathIB =
D (65266) chip[DMG]:            {
D (65266) chip[DMG]:                    Endpoint = 0x0,
D (65266) chip[DMG]:                    Cluster = 0x28,
D (65276) chip[DMG]:                    Attribute = 0x0000_0004,
D (65276) chip[DMG]:            }
D (65286) chip[DMG]: 
D (65286) chip[DMG]:    ],
D (65286) chip[DMG]: 
D (65286) chip[DMG]:    isFabricFiltered = true, 
D (65296) chip[DMG]:    InteractionModelRevision = 11
D (65296) chip[DMG]: },
D (65306) chip[DMG]: IM RH moving to [CanStartReporting]
D (65306) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
D (65316) chip[DMG]: <RE:Run> Cluster 28, Attribute 4 is dirty
D (65326) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D (65336) nvs: nvs_open_from_partition chip-factory 0
D (65336) nvs: nvs_get product-id 4
D (65346) nvs: nvs_close 413
D (65346) chip[DMG]: <RE> Sending report (payload has 37 bytes)...
I (65356) chip[EM]: <<< [E:30272r S:55454 M:190411354 (Ack:225728016)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:59913] --- Type 0001:05 (IM:ReportData)
D (65376) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (65376) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (65386) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (65386) nvs: nvs_open_from_partition CHIP_KVS 0
D (65396) nvs: nvs_get_str_or_blob g/su/0
D (65396) nvs: nvs_close 414
D (65406) nvs: nvs_open_from_partition CHIP_KVS 0
D (65406) nvs: nvs_get_str_or_blob g/su/1
D (65406) nvs: nvs_close 415
D (65416) nvs: nvs_open_from_partition CHIP_KVS 0
D (65416) nvs: nvs_get_str_or_blob g/su/2
D (65426) nvs: nvs_close 416
D (65426) nvs: nvs_open_from_partition CHIP_KVS 0
D (65426) nvs: nvs_get_str_or_blob g/su/3
D (65436) nvs: nvs_close 417
D (65436) nvs: nvs_open_from_partition CHIP_KVS 0
D (65446) nvs: nvs_get_str_or_blob g/su/4
D (65446) nvs: nvs_close 418
D (65446) nvs: nvs_open_from_partition CHIP_KVS 0
D (65456) nvs: nvs_get_str_or_blob g/su/5
D (65456) nvs: nvs_close 419
D (65456) nvs: nvs_open_from_partition CHIP_KVS 0
D (65466) nvs: nvs_get_str_or_blob g/su/6
D (65466) nvs: nvs_close 420
D (65476) nvs: nvs_open_from_partition CHIP_KVS 0
D (65476) nvs: nvs_get_str_or_blob g/su/7
D (65476) nvs: nvs_close 421
D (65486) nvs: nvs_open_from_partition CHIP_KVS 0
D (65486) nvs: nvs_get_str_or_blob g/su/8
D (65496) nvs: nvs_close 422
D (65496) nvs: nvs_open_from_partition CHIP_KVS 0
D (65496) nvs: nvs_get_str_or_blob g/su/9
D (65506) nvs: nvs_close 423
D (65506) nvs: nvs_open_from_partition CHIP_KVS 0
D (65516) nvs: nvs_get_str_or_blob g/su/a
D (65516) nvs: nvs_close 424
D (65516) nvs: nvs_open_from_partition CHIP_KVS 0
D (65526) nvs: nvs_get_str_or_blob g/su/b
D (65526) nvs: nvs_close 425
D (65526) nvs: nvs_open_from_partition CHIP_KVS 0
D (65536) nvs: nvs_get_str_or_blob g/su/c
D (65536) nvs: nvs_close 426
D (65546) nvs: nvs_open_from_partition CHIP_KVS 0
D (65546) nvs: nvs_get_str_or_blob g/su/d
D (65556) nvs: nvs_close 427
D (65556) nvs: nvs_open_from_partition CHIP_KVS 0
D (65556) nvs: nvs_get_str_or_blob g/su/e
D (65566) nvs: nvs_close 428
D (65566) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
I (65576) chip[EM]: >>> [E:30272r S:55454 M:225728017 (Ack:190411354)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (65586) chip[EM]: Found matching exchange: 30272r, Delegate: 0x0
D (65596) chip[EM]: Rxd Ack; Removing MessageCounter:190411354 from Retrans Table on exchange 30272r
I (65606) chip[EM]: >>> [E:30273r S:55454 M:225728018] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (65616) chip[EM]: Handling via exchange: 30273r, Delegate: 0x3fca5054
D (65626) chip[IM]: Received Read request
D (65626) chip[DMG]: ReadRequestMessage =
D (65626) chip[DMG]: {
D (65636) chip[DMG]:    AttributePathIBs =
D (65636) chip[DMG]:    [
D (65636) chip[DMG]:            AttributePathIB =
D (65646) chip[DMG]:            {
D (65646) chip[DMG]:                    Endpoint = 0x0,
D (65646) chip[DMG]:                    Cluster = 0x28,
D (65656) chip[DMG]:                    Attribute = 0x0000_0003,
D (65656) chip[DMG]:            }
D (65666) chip[DMG]: 
D (65666) chip[DMG]:    ],
D (65666) chip[DMG]: 
D (65666) chip[DMG]:    isFabricFiltered = true, 
D (65676) chip[DMG]:    InteractionModelRevision = 11
D (65676) chip[DMG]: },
D (65686) chip[DMG]: IM RH moving to [CanStartReporting]
D (65686) chip[DMG]: Building Reports for ReadHandler with LastReportGeneration = 0x0000000000000000 DirtyGeneration = 0x0000000000000000
D (65696) chip[DMG]: <RE:Run> Cluster 28, Attribute 3 is dirty
D (65706) chip[DMG]: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D (65716) nvs: nvs_open_from_partition chip-factory 0
D (65716) nvs: nvs_get_str_or_blob product-name
D (65726) nvs: nvs_close 429
E (65726) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = 201
D (65736) chip[DMG]: <RE> Sending report (payload has 33 bytes)...
I (65746) chip[EM]: <<< [E:30273r S:55454 M:190411355 (Ack:225728018)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:59913] --- Type 0001:05 (IM:ReportData)
D (65756) chip[DMG]: <RE> OnReportConfirm: NumReports = 0
D (65766) chip[DMG]: <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D (65776) chip[DMG]: IM RH moving to [AwaitingDestruction]
D (65776) nvs: nvs_open_from_partition CHIP_KVS 0
D (65786) nvs: nvs_get_str_or_blob g/su/0
D (65786) nvs: nvs_close 430
D (65786) nvs: nvs_open_from_partition CHIP_KVS 0
D (65796) nvs: nvs_get_str_or_blob g/su/1
D (65796) nvs: nvs_close 431
D (65806) nvs: nvs_open_from_partition CHIP_KVS 0
D (65806) nvs: nvs_get_str_or_blob g/su/2
D (65806) nvs: nvs_close 432
D (65816) nvs: nvs_open_from_partition CHIP_KVS 0
D (65816) nvs: nvs_get_str_or_blob g/su/3
D (65826) nvs: nvs_close 433
D (65826) nvs: nvs_open_from_partition CHIP_KVS 0
D (65826) nvs: nvs_get_str_or_blob g/su/4
D (65836) nvs: nvs_close 434
D (65836) nvs: nvs_open_from_partition CHIP_KVS 0
D (65846) nvs: nvs_get_str_or_blob g/su/5
D (65846) nvs: nvs_close 435
D (65846) nvs: nvs_open_from_partition CHIP_KVS 0
D (65856) nvs: nvs_get_str_or_blob g/su/6
D (65856) nvs: nvs_close 436
D (65856) nvs: nvs_open_from_partition CHIP_KVS 0
D (65866) nvs: nvs_get_str_or_blob g/su/7
D (65866) nvs: nvs_close 437
D (65876) nvs: nvs_open_from_partition CHIP_KVS 0
D (65876) nvs: nvs_get_str_or_blob g/su/8
D (65886) nvs: nvs_close 438
D (65886) nvs: nvs_open_from_partition CHIP_KVS 0
D (65886) nvs: nvs_get_str_or_blob g/su/9
D (65896) nvs: nvs_close 439
D (65896) nvs: nvs_open_from_partition CHIP_KVS 0
D (65896) nvs: nvs_get_str_or_blob g/su/a
D (65906) nvs: nvs_close 440
D (65906) nvs: nvs_open_from_partition CHIP_KVS 0
D (65916) nvs: nvs_get_str_or_blob g/su/b
D (65916) nvs: nvs_close 441
D (65916) nvs: nvs_open_from_partition CHIP_KVS 0
D (65926) nvs: nvs_get_str_or_blob g/su/c
D (65926) nvs: nvs_close 442
D (65936) nvs: nvs_open_from_partition CHIP_KVS 0
D (65936) nvs: nvs_get_str_or_blob g/su/d
D (65936) nvs: nvs_close 443
D (65946) nvs: nvs_open_from_partition CHIP_KVS 0
D (65946) nvs: nvs_get_str_or_blob g/su/e
D (65956) nvs: nvs_close 444
D (65956) chip[DMG]: All ReadHandler-s are clean, clear GlobalDirtySet
D (65966) chip[IN]: Received a duplicate message with MessageCounter:225728018 on exchange 30273r
I (65966) chip[EM]: >>> [E:30273r S:55454 M:225728018] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D (65986) chip[EM]: Found matching exchange: 30273r, Delegate: 0x0
D (65986) chip[EM]: Forcing tx of solitary ack for duplicate MessageCounter:225728018 on exchange 30273r
I (65996) chip[EM]: <<< [E:30273r S:55454 M:190411356 (Ack:225728018)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[FE80::A2:2C39:3B2C:AD67%st1]:59913] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (66016) chip[EM]: >>> [E:30273r S:55454 M:225728019 (Ack:190411355)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D (66036) chip[EM]: Found matching exchange: 30273r, Delegate: 0x0
D (66036) chip[EM]: Rxd Ack; Removing MessageCounter:190411355 from Retrans Table on exchange 30273r
D (74896) wifi:obss scan is disabled
D (74896) wifi:start obss scan: obss scan is stopped
E (82256) chip[SWU]: No suitable OTA Provider candidate found
I (82256) chip[SWU]: No provider available
FloBer431 commented 6 months ago

Nobody who can help me here?

FHFS commented 6 months ago

You could check your partition. Your error shows it was trying to get the product name from the nvs partition chip-factory. Check if there is a valid name there?

D (63666) nvs: nvs_open_from_partition chip-factory 0
D (63676) nvs: nvs_get_str_or_blob product-name
D (63676) nvs: nvs_close 381
E (63676) chip[DMG]: Error retrieving data from clusterId: 0x0000_0028, err = 201

I do know generic_switch example has some factory data you need to flash before running your application. See generic_switch

jadhavrohit924 commented 2 months ago

@FloBer431 Are you still facing the issue?

dhrishi commented 1 week ago

Closing this now. Please re-open if you still see this issue