TC_RR_1.1 : ERROR Time out! failed to receive write response from Exchange: 18859i (CON-1509) #1240
Comments
github-actions
bot
changed the title
|
can you please look into this as this is a certification blocker for us. |
|
Use the |
|
@VaishaliAvhale getting same issue with --timeout 10000 also attached are fresh logs |
|
There seems to be a small spelling mistake in the timeout parameter. Kindly correct it and try again. |
|
Ah my bad, let me try again. Thanks |
|
@VaishaliAvhale same issue please check |
|
@VaishaliAvhale I reduced the number of endpoints to 3 and now test case is passing but our device has 12 endpoints. Is this something related to NVS size? |
|
@VaishaliAvhale is this something related to this: |
|
@VaishaliAvhale can you please help me with this? |
|
Is this something related to NVS size?
|
|
@VaishaliAvhale I increased NVS but now getting this error on last step: |
|
We are looking into it and will get back to you soon. Thanks! |
Describe the bug
Channel:StandaloneAck)
[MatterTest] 01-12 18:28:44.531 INFO Found an existing secure session to [1:0000000012344321]!
[MatterTest] 01-12 18:28:44.550 INFO <<< [E:18857i S:42526 M:72266529] (S) Msg TX to 1:0000000012344321 [7609] [UDP:[fe80::8265:99ff:fec3:cf64%eth0]:5540] --- Type 0001:06 (IM:WriteRequest)
[MatterTest] 01-12 18:28:44.926 INFO Retransmitting MessageCounter:72266529 on exchange 18857i Send Cnt 1
[MatterTest] 01-12 18:28:45.269 INFO Retransmitting MessageCounter:72266529 on exchange 18857i Send Cnt 2
[MatterTest] 01-12 18:28:45.801 INFO Retransmitting MessageCounter:72266529 on exchange 18857i Send Cnt 3
[MatterTest] 01-12 18:28:46.797 INFO Retransmitting MessageCounter:72266529 on exchange 18857i Send Cnt 4
[MatterTest] 01-12 18:28:48.261 ERROR Failed to Send CHIP MessageCounter:72266529 on exchange 18857i sendCount: 4 max retries: 4
[MatterTest] 01-12 18:28:50.279 INFO >>> [E:18857i S:42526 M:185962603 (Ack:72266529)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0001:07 (IM:WriteResponse)
[MatterTest] 01-12 18:28:50.365 INFO <<< [E:18857i S:42526 M:72266530 (Ack:185962603)] (S) Msg TX to 1:0000000012344321 [7609] [UDP:[fe80::8265:99ff:fec3:cf64%eth0]:5540] --- Type 0001:06 (IM:WriteRequest)
[MatterTest] 01-12 18:28:50.367 INFO >>> [E:18857i S:42526 M:185962604 (Ack:72266529)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:50.368 INFO >>> [E:18857i S:42526 M:185962605 (Ack:72266529)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:50.378 INFO >>> [E:18857i S:42526 M:185962606 (Ack:72266529)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:50.395 INFO >>> [E:18857i S:42526 M:185962607 (Ack:72266529)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:50.742 INFO Retransmitting MessageCounter:72266530 on exchange 18857i Send Cnt 1
[MatterTest] 01-12 18:28:51.109 INFO Retransmitting MessageCounter:72266530 on exchange 18857i Send Cnt 2
[MatterTest] 01-12 18:28:51.723 INFO Retransmitting MessageCounter:72266530 on exchange 18857i Send Cnt 3
[MatterTest] 01-12 18:28:52.049 INFO >>> [E:18857i S:42526 M:185962608 (Ack:72266530)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0001:07 (IM:WriteResponse)
[MatterTest] 01-12 18:28:52.076 INFO <<< [E:18857i S:42526 M:72266531 (Ack:185962608)] (S) Msg TX to 1:0000000012344321 [7609] [UDP:[fe80::8265:99ff:fec3:cf64%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:52.076 INFO Step 14: Setting group key map on fabric 3
[MatterTest] 01-12 18:28:52.078 INFO >>> [E:18857i S:42526 M:185962609 (Ack:72266530)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:52.079 INFO Found an existing secure session to [5:0000000012344321]!
[MatterTest] 01-12 18:28:52.097 INFO <<< [E:18858i S:42528 M:40177813] (S) Msg TX to 5:0000000012344321 [94D6] [UDP:192.168.18.89%eth0:5540] --- Type 0001:06 (IM:WriteRequest)
[MatterTest] 01-12 18:28:52.099 INFO >>> [E:18857i S:42526 M:185962610 (Ack:72266530)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:52.124 INFO >>> [E:18857i S:42526 M:185962611 (Ack:72266530)] (S) Msg RX from 1:0000000012344321 [7609] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:52.785 INFO Retransmitting MessageCounter:40177813 on exchange 18858i Send Cnt 1
[MatterTest] 01-12 18:28:53.471 INFO Retransmitting MessageCounter:40177813 on exchange 18858i Send Cnt 2
[MatterTest] 01-12 18:28:54.408 INFO Retransmitting MessageCounter:40177813 on exchange 18858i Send Cnt 3
[MatterTest] 01-12 18:28:55.905 INFO Retransmitting MessageCounter:40177813 on exchange 18858i Send Cnt 4
[MatterTest] 01-12 18:28:58.566 ERROR Failed to Send CHIP MessageCounter:40177813 on exchange 18858i sendCount: 4 max retries: 4
[MatterTest] 01-12 18:28:59.551 INFO >>> [E:18858i S:42528 M:134177006 (Ack:40177813)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0001:07 (IM:WriteResponse)
[MatterTest] 01-12 18:28:59.638 INFO <<< [E:18858i S:42528 M:40177814 (Ack:134177006)] (S) Msg TX to 5:0000000012344321 [94D6] [UDP:192.168.18.89%eth0:5540] --- Type 0001:06 (IM:WriteRequest)
[MatterTest] 01-12 18:28:59.639 INFO >>> [E:18858i S:42528 M:134177007 (Ack:40177813)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:59.640 INFO >>> [E:18858i S:42528 M:134177008 (Ack:40177813)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:59.643 INFO >>> [E:18858i S:42528 M:134177009 (Ack:40177813)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:59.673 INFO >>> [E:18858i S:42528 M:134177010 (Ack:40177813)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:28:59.978 INFO Retransmitting MessageCounter:40177814 on exchange 18858i Send Cnt 1
[MatterTest] 01-12 18:29:00.355 INFO Retransmitting MessageCounter:40177814 on exchange 18858i Send Cnt 2
[MatterTest] 01-12 18:29:00.890 INFO Retransmitting MessageCounter:40177814 on exchange 18858i Send Cnt 3
[MatterTest] 01-12 18:29:01.749 INFO >>> [E:18858i S:42528 M:134177011 (Ack:40177814)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0001:07 (IM:WriteResponse)
[MatterTest] 01-12 18:29:01.777 INFO <<< [E:18858i S:42528 M:40177815 (Ack:134177011)] (S) Msg TX to 5:0000000012344321 [94D6] [UDP:192.168.18.89%eth0:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:29:01.778 INFO Step 14: Setting group key map on fabric 4
[MatterTest] 01-12 18:29:01.780 INFO Found an existing secure session to [8:0000000012344321]!
[MatterTest] 01-12 18:29:01.787 INFO >>> [E:18858i S:42528 M:134177012 (Ack:40177814)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:29:01.800 INFO <<< [E:18859i S:42529 M:213972027] (S) Msg TX to 8:0000000012344321 [5CA6] [UDP:192.168.18.89%eth0:5540] --- Type 0001:06 (IM:WriteRequest)
[MatterTest] 01-12 18:29:01.813 INFO >>> [E:18858i S:42528 M:134177013 (Ack:40177814)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:29:01.842 INFO >>> [E:18858i S:42528 M:134177014 (Ack:40177814)] (S) Msg RX from 5:0000000012344321 [94D6] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 01-12 18:29:02.468 INFO Retransmitting MessageCounter:213972027 on exchange 18859i Send Cnt 1
[MatterTest] 01-12 18:29:03.100 INFO Retransmitting MessageCounter:213972027 on exchange 18859i Send Cnt 2
[MatterTest] 01-12 18:29:04.187 INFO Retransmitting MessageCounter:213972027 on exchange 18859i Send Cnt 3
[MatterTest] 01-12 18:29:05.819 INFO Retransmitting MessageCounter:213972027 on exchange 18859i Send Cnt 4
[MatterTest] 01-12 18:29:08.584 ERROR Failed to Send CHIP MessageCounter:213972027 on exchange 18859i sendCount: 4 max retries: 4
[MatterTest] 01-12 18:29:10.843 INFO SecureSession[0xffff8c0a07d0, LSID:42529]: State change 'kActive' --> 'kDefunct'
[MatterTest] 01-12 18:29:10.844 ERROR Time out! failed to receive write response from Exchange: 18859i
[MatterTest] 01-12 18:29:10.849 ERROR Exception occurred in test_TC_RR_1_1.
`
Environment
ESP-Matter Commit Id: matter release/1.3
ESP-IDF Commit Id: 5.2.1
SoC (eg: ESP32 or ESP32-C3): esp32-s3
Commissioner app and versions if present: certification tool Version: 2.10.2+spring2024
Device Logs (Please attach the log file):
TC_RR_1.1_log_session_issue.txt
Device logs: (Dropped 1 event from buffer with priority 1 and event number 0x0000000000010033 due to overflow: event priority_level: 1)
I (83996) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010029 due to overflow: event priority_level: 1 I (84036) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001002A due to overflow: event priority_level: 1 I (84046) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001002B due to overflow: event priority_level: 1 I (84096) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001002C due to overflow: event priority_level: 1 I (84136) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001002D due to overflow: event priority_level: 1 I (84146) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001002E due to overflow: event priority_level: 1 I (84156) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001002F due to overflow: event priority_level: 1 I (84176) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010030 due to overflow: event priority_level: 1 I (84186) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010031 due to overflow: event priority_level: 1 I (84196) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010032 due to overflow: event priority_level: 1 I (84216) chip[EM]: <<< [E:18833r S:50127 M:71302490 (Ack:5020272)] (S) Msg TX to 1:000000000001B669 [EE24] [UDP:[FE80::E65F:1FF:FE8E:3CF2%st1]:41695] --- Type 0001:07 (IM:WriteResponse) I (84256) chip[EM]: >>> [E:18833r S:50127 M:5020273 (Ack:71302490)] (S) Msg RX from 1:000000000001B669 [EE24] --- Type 0000:10 (SecureChannel:StandaloneAck) I (84256) chip[EM]: >>> [E:18834r S:50127 M:5020274] (S) Msg RX from 1:000000000001B669 [EE24] --- Type 0001:02 (IM:ReadRequest) I (84276) chip[EM]: <<< [E:18834r S:50127 M:71302491 (Ack:5020274)] (S) Msg TX to 1:000000000001B669 [EE24] [UDP:[FE80::E65F:1FF:FE8E:3CF2%st1]:41695] --- Type 0001:05 (IM:ReportData) I (84326) chip[EM]: >>> [E:18834r S:50127 M:5020275 (Ack:71302491)] (S) Msg RX from 1:000000000001B669 [EE24] --- Type 0000:10 (SecureChannel:StandaloneAck) I (84346) chip[EM]: >>> [E:18835r S:50129 M:37357334] (S) Msg RX from 3:000000000001B669 [C7B8] --- Type 0001:06 (IM:WriteRequest) I (84386) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010033 due to overflow: event priority_level: 1 I (84426) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010034 due to overflow: event priority_level: 1 I (84466) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010035 due to overflow: event priority_level: 1 I (84506) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010036 due to overflow: event priority_level: 1 I (84516) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010037 due to overflow: event priority_level: 1 I (84526) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010038 due to overflow: event priority_level: 1 I (84546) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010039 due to overflow: event priority_level: 1 I (84556) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001003A due to overflow: event priority_level: 1 I (84566) chip[EM]: <<< [E:18835r S:50129 M:197161450 (Ack:37357334)] (S) Msg TX to 3:000000000001B669 [C7B8] [UDP:192.168.18.60:39475] --- Type 0001:07 (IM:WriteResponse) I (84606) chip[EM]: >>> [E:18835r S:50129 M:37357335 (Ack:197161450)] (S) Msg RX from 3:000000000001B669 [C7B8] --- Type 0000:10 (SecureChannel:StandaloneAck) I (84616) chip[EM]: >>> [E:18836r S:50129 M:37357336] (S) Msg RX from 3:000000000001B669 [C7B8] --- Type 0001:02 (IM:ReadRequest) I (84636) chip[EM]: <<< [E:18836r S:50129 M:197161451 (Ack:37357336)] (S) Msg TX to 3:000000000001B669 [C7B8] [UDP:192.168.18.60:39475] --- Type 0001:05 (IM:ReportData) I (84706) chip[EM]: >>> [E:18836r S:50129 M:37357337 (Ack:197161451)] (S) Msg RX from 3:000000000001B669 [C7B8] --- Type 0000:10 (SecureChannel:StandaloneAck) I (84706) chip[EM]: >>> [E:18837r S:50130 M:45770192] (S) Msg RX from 4:000000000001B669 [0CCD] --- Type 0001:06 (IM:WriteRequest) I (84766) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001003B due to overflow: event priority_level: 1 I (84806) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001003C due to overflow: event priority_level: 1 I (84846) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001003D due to overflow: event priority_level: 1 I (84886) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001003E due to overflow: event priority_level: 1 I (84896) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001003F due to overflow: event priority_level: 1 I (84906) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010040 due to overflow: event priority_level: 1 I (84926) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010041 due to overflow: event priority_level: 1 I (84936) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010042 due to overflow: event priority_level: 1 I (84946) chip[EM]: <<< [E:18837r S:50130 M:155746405 (Ack:45770192)] (S) Msg TX to 4:000000000001B669 [0CCD] [UDP:192.168.18.60:39475] --- Type 0001:07 (IM:WriteResponse) I (84986) chip[EM]: >>> [E:18837r S:50130 M:45770193 (Ack:155746405)] (S) Msg RX from 4:000000000001B669 [0CCD] --- Type 0000:10 (SecureChannel:StandaloneAck) I (84996) chip[EM]: >>> [E:18838r S:50130 M:45770194] (S) Msg RX from 4:000000000001B669 [0CCD] --- Type 0001:02 (IM:ReadRequest) I (85016) chip[EM]: <<< [E:18838r S:50130 M:155746406 (Ack:45770194)] (S) Msg TX to 4:000000000001B669 [0CCD] [UDP:192.168.18.60:39475] --- Type 0001:05 (IM:ReportData) I (85076) chip[EM]: >>> [E:18838r S:50130 M:45770195 (Ack:155746406)] (S) Msg RX from 4:000000000001B669 [0CCD] --- Type 0000:10 (SecureChannel:StandaloneAck) I (85096) chip[EM]: >>> [E:18839r S:50131 M:204369712] (S) Msg RX from 5:000000000001B669 [B72D] --- Type 0001:06 (IM:WriteRequest) I (85136) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010043 due to overflow: event priority_level: 1 I (85176) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010044 due to overflow: event priority_level: 1 I (85216) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010045 due to overflow: event priority_level: 1 I (85256) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010046 due to overflow: event priority_level: 1 I (85266) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010047 due to overflow: event priority_level: 1 I (85336) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010048 due to overflow: event priority_level: 1 I (85346) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010049 due to overflow: event priority_level: 1 I (85356) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001004A due to overflow: event priority_level: 1 I (85366) chip[EM]: <<< [E:18839r S:50131 M:71793136 (Ack:204369712)] (S) Msg TX to 5:000000000001B669 [B72D] [UDP:192.168.18.60:39475] --- Type 0001:07 (IM:WriteResponse) I (85406) chip[EM]: >>> [E:18839r S:50131 M:204369713 (Ack:71793136)] (S) Msg RX from 5:000000000001B669 [B72D] --- Type 0000:10 (SecureChannel:StandaloneAck) I (85416) chip[EM]: >>> [E:18840r S:50131 M:204369714] (S) Msg RX from 5:000000000001B669 [B72D] --- Type 0001:02 (IM:ReadRequest) I (85436) chip[EM]: <<< [E:18840r S:50131 M:71793137 (Ack:204369714)] (S) Msg TX to 5:000000000001B669 [B72D] [UDP:192.168.18.60:39475] --- Type 0001:05 (IM:ReportData) I (85506) chip[EM]: >>> [E:18840r S:50131 M:204369715 (Ack:71793137)] (S) Msg RX from 5:000000000001B669 [B72D] --- Type 0000:10 (SecureChannel:StandaloneAck) I (85516) chip[EM]: >>> [E:18841r S:50132 M:108868167] (S) Msg RX from 6:000000000001B669 [7D24] --- Type 0001:06 (IM:WriteRequest) I (85566) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001004B due to overflow: event priority_level: 1 I (85606) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001004C due to overflow: event priority_level: 1 I (85646) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001004D due to overflow: event priority_level: 1 I (85686) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001004E due to overflow: event priority_level: 1 I (85696) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x000000000001004F due to overflow: event priority_level: 1 I (85706) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010050 due to overflow: event priority_level: 1 I (85726) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010051 due to overflow: event priority_level: 1 I (85736) chip[EVL]: Dropped 1 event from buffer with priority 1 and event number 0x0000000000010052 due to overflow: event priority_level: 1This is certification blocker for us.
The text was updated successfully, but these errors were encountered: