Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TE7.5 [TC-GC-1.1] VerifyOrDie failure at ../../examples/chip-tool/third_party/connectedhomeip/src/inet/InetLayer.h:121: sEndPointPool.Allocated() == 0 #14472

Closed
Minan-Tuyasmart opened this issue Jan 28, 2022 · 4 comments
Labels
spec Mismatch between spec and implementation V1.0

Comments

@Minan-Tuyasmart
Copy link

Minan-Tuyasmart commented Jan 28, 2022

Problem:
[TC-GC-1.1] VerifyOrDie failure at ../../examples/chip-tool/third_party/connectedhomeip/src/inet/InetLayer.h:121: sEndPointPool.Allocated() == 0
Aborted

platform:
Testing image on RasPi:v1.7.img
Connectedhomeip commitID : b0af6ba
OTBR commitID:72bb3d45684f837e67e7f1ec20a9a8e3ac4a4419
lighting-app run on the EFR32MG24 board base on commitID : b0af6ba

light-log.txt
otbr-log.txt

ubuntu@matter-7-5:~/connectedhomeip/out/standalone$ sudo ./chip-tool generalcommissioning read breadcrumb 12344321 1
[1643274770.425696][5359:5359] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-1yicuE)
[1643274770.426351][5359:5359] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1643274770.426436][5359:5359] CHIP:DL: NVS set: chip-counters/reboot-count = 7 (0x7)
[1643274770.427365][5359:5359] CHIP:DL: Got Ethernet interface: eth0
[1643274770.427966][5359:5359] CHIP:DL: Found the primary Ethernet interface:eth0
[1643274770.428687][5359:5359] CHIP:DL: Got WiFi interface: wlan0
[1643274770.428761][5359:5359] CHIP:DL: Failed to reset WiFi statistic counts
[1643274770.428830][5359:5359] CHIP:IN: UDP::Init bind&listen port=5542
[1643274770.428942][5359:5359] CHIP:IN: UDP::Init bound to port=5542
[1643274770.428970][5359:5359] CHIP:IN: UDP::Init bind&listen port=5542
[1643274770.429064][5359:5359] CHIP:IN: UDP::Init bound to port=5542
[1643274770.429089][5359:5359] CHIP:IN: TransportMgr initialized
[1643274770.429128][5359:5359] CHIP:DIS: Init fabric pairing table with server storage
[1643274770.429415][5359:5359] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-cfYBjG)
[1643274770.430061][5359:5359] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1643274770.430116][5359:5359] CHIP:DL: NVS set: chip-counters/GlobalMCTR = 6000 (0x1770)
[1643274770.430239][5359:5359] CHIP:ZCL: Using ZAP configuration...
[1643274770.433501][5359:5359] CHIP:DL: MDNS failed to join multicast group on wlan0 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1643274770.440824][5359:5359] CHIP:DL: MDNS failed to join multicast group on veth7bb0b90 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1643274770.442726][5359:5359] CHIP:DL: MDNS failed to join multicast group on vethefb2194 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1643274770.444557][5359:5359] CHIP:DL: MDNS failed to join multicast group on veth9fd920d for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1643274770.446326][5359:5359] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:772: Inet Error 0x00000110: Address not found
[1643274770.446866][5359:5359] CHIP:CTL: System State Initialized...
[1643274770.449544][5359:5359] CHIP:CTL: Generating NOC
[1643274770.449858][5359:5359] CHIP:CTL: Generating ICAC
[1643274770.450775][5359:5359] CHIP:DIS: Verifying the received credentials
[1643274770.452529][5359:5359] CHIP:IN: Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000001 and root pubkey
[1643274770.452565][5359:5359] CHIP:IN: 0x04, 0x35, 0xbc, 0x79, 0x0d, 0x81, 0xba, 0x7b,
[1643274770.452590][5359:5359] CHIP:IN: 0x01, 0xfb, 0xb5, 0x3e, 0x39, 0x88, 0x07, 0x21,
[1643274770.452614][5359:5359] CHIP:IN: 0x24, 0x9b, 0xc9, 0xbc, 0x44, 0x0d, 0x31, 0x0a,
[1643274770.452637][5359:5359] CHIP:IN: 0x74, 0x4c, 0xdc, 0x4e, 0x18, 0xb3, 0x14, 0xf5,
[1643274770.452660][5359:5359] CHIP:IN: 0xf4, 0xd4, 0x92, 0x47, 0x5c, 0x88, 0x4b, 0x9d,
[1643274770.452682][5359:5359] CHIP:IN: 0xdc, 0x65, 0x2b, 0xe2, 0xc5, 0xcc, 0xc1, 0x84,
[1643274770.452705][5359:5359] CHIP:IN: 0xe4, 0x4f, 0x08, 0xf7, 0x18, 0x85, 0x73, 0x7c,
[1643274770.452728][5359:5359] CHIP:IN: 0x15, 0x0b, 0xfd, 0xd7, 0x01, 0x88, 0x97, 0x2d,
[1643274770.452748][5359:5359] CHIP:IN: 0xde,
[1643274770.452801][5359:5359] CHIP:IN: Generated compressed fabric ID
[1643274770.452827][5359:5359] CHIP:IN: 0x7b, 0x18, 0xf4, 0x57, 0xe9, 0x2a, 0xda, 0xfd,
[1643274770.452855][5359:5359] CHIP:DIS: Added new fabric at index: 1, Initialized: 1
[1643274770.452878][5359:5359] CHIP:DIS: Assigned compressed fabric ID: 0x7B18F457E92ADAFD, node ID: 0x000000000001B669
[1643274770.452901][5359:5359] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x7B18F457E92ADAFD
[1643274770.452968][5359:5359] CHIP:IN: UDP::Init bind&listen port=5550
[1643274770.453105][5359:5359] CHIP:IN: UDP::Init bound to port=5550
[1643274770.453131][5359:5359] CHIP:IN: UDP::Init bind&listen port=5550
[1643274770.453221][5359:5359] CHIP:IN: UDP::Init bound to port=5550
[1643274770.453246][5359:5359] CHIP:IN: TransportMgr initialized
[1643274770.454079][5359:5359] CHIP:CTL: Generating NOC
[1643274770.454368][5359:5359] CHIP:CTL: Generating ICAC
[1643274770.455144][5359:5359] CHIP:DIS: Verifying the received credentials
[1643274770.456855][5359:5359] CHIP:IN: Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000002 and root pubkey
[1643274770.456891][5359:5359] CHIP:IN: 0x04, 0x35, 0xbc, 0x79, 0x0d, 0x81, 0xba, 0x7b,
[1643274770.456915][5359:5359] CHIP:IN: 0x01, 0xfb, 0xb5, 0x3e, 0x39, 0x88, 0x07, 0x21,
[1643274770.456939][5359:5359] CHIP:IN: 0x24, 0x9b, 0xc9, 0xbc, 0x44, 0x0d, 0x31, 0x0a,
[1643274770.456962][5359:5359] CHIP:IN: 0x74, 0x4c, 0xdc, 0x4e, 0x18, 0xb3, 0x14, 0xf5,
[1643274770.456984][5359:5359] CHIP:IN: 0xf4, 0xd4, 0x92, 0x47, 0x5c, 0x88, 0x4b, 0x9d,
[1643274770.457007][5359:5359] CHIP:IN: 0xdc, 0x65, 0x2b, 0xe2, 0xc5, 0xcc, 0xc1, 0x84,
[1643274770.457030][5359:5359] CHIP:IN: 0xe4, 0x4f, 0x08, 0xf7, 0x18, 0x85, 0x73, 0x7c,
[1643274770.457053][5359:5359] CHIP:IN: 0x15, 0x0b, 0xfd, 0xd7, 0x01, 0x88, 0x97, 0x2d,
[1643274770.457073][5359:5359] CHIP:IN: 0xde,
[1643274770.457124][5359:5359] CHIP:IN: Generated compressed fabric ID
[1643274770.457150][5359:5359] CHIP:IN: 0x7a, 0x82, 0x1f, 0xb2, 0x91, 0xf2, 0xa3, 0xc8,
[1643274770.457179][5359:5359] CHIP:DIS: Added new fabric at index: 2, Initialized: 1
[1643274770.457202][5359:5359] CHIP:DIS: Assigned compressed fabric ID: 0x7A821FB291F2A3C8, node ID: 0x000000000001B669
[1643274770.457225][5359:5359] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x7A821FB291F2A3C8
[1643274770.457287][5359:5359] CHIP:IN: UDP::Init bind&listen port=5550
[1643274770.457413][5359:5359] CHIP:IN: UDP::Init bound to port=5550
[1643274770.457439][5359:5359] CHIP:IN: UDP::Init bind&listen port=5550
[1643274770.457527][5359:5359] CHIP:IN: UDP::Init bound to port=5550
[1643274770.457551][5359:5359] CHIP:IN: TransportMgr initialized
[1643274770.458348][5359:5359] CHIP:CTL: Generating NOC
[1643274770.458815][5359:5359] CHIP:CTL: Generating ICAC
[1643274770.459695][5359:5359] CHIP:DIS: Verifying the received credentials
[1643274770.461573][5359:5359] CHIP:IN: Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000003 and root pubkey
[1643274770.461624][5359:5359] CHIP:IN: 0x04, 0x35, 0xbc, 0x79, 0x0d, 0x81, 0xba, 0x7b,
[1643274770.461648][5359:5359] CHIP:IN: 0x01, 0xfb, 0xb5, 0x3e, 0x39, 0x88, 0x07, 0x21,
[1643274770.461672][5359:5359] CHIP:IN: 0x24, 0x9b, 0xc9, 0xbc, 0x44, 0x0d, 0x31, 0x0a,
[1643274770.461695][5359:5359] CHIP:IN: 0x74, 0x4c, 0xdc, 0x4e, 0x18, 0xb3, 0x14, 0xf5,
[1643274770.461718][5359:5359] CHIP:IN: 0xf4, 0xd4, 0x92, 0x47, 0x5c, 0x88, 0x4b, 0x9d,
[1643274770.461740][5359:5359] CHIP:IN: 0xdc, 0x65, 0x2b, 0xe2, 0xc5, 0xcc, 0xc1, 0x84,
[1643274770.461763][5359:5359] CHIP:IN: 0xe4, 0x4f, 0x08, 0xf7, 0x18, 0x85, 0x73, 0x7c,
[1643274770.461785][5359:5359] CHIP:IN: 0x15, 0x0b, 0xfd, 0xd7, 0x01, 0x88, 0x97, 0x2d,
[1643274770.461805][5359:5359] CHIP:IN: 0xde,
[1643274770.461863][5359:5359] CHIP:IN: Generated compressed fabric ID
[1643274770.461888][5359:5359] CHIP:IN: 0x70, 0x82, 0xe8, 0x37, 0x47, 0x29, 0x5b, 0x21,
[1643274770.461921][5359:5359] CHIP:DIS: Added new fabric at index: 3, Initialized: 1
[1643274770.461944][5359:5359] CHIP:DIS: Assigned compressed fabric ID: 0x7082E83747295B21, node ID: 0x000000000001B669
[1643274770.461966][5359:5359] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x7082E83747295B21
[1643274770.462062][5359:5359] CHIP:IN: UDP::Init bind&listen port=5550
[1643274770.462201][5359:5359] CHIP:IN: UDP::Init bound to port=5550
[1643274770.462227][5359:5359] CHIP:IN: UDP::Init bind&listen port=5550
[1643274770.462317][5359:5359] CHIP:IN: UDP::Init bound to port=5550
[1643274770.462341][5359:5359] CHIP:IN: TransportMgr initialized
[1643274770.462694][5359:5364] CHIP:DL: CHIP task running
[1643274770.462825][5359:5364] CHIP:TOO: Sending command to node 0xbc5c01
[1643274770.463474][5359:5364] CHIP:DIS: Attempt to mDNS broadcast failed:  ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1643274770.463914][5359:5364] CHIP:DIS: Attempt to mDNS broadcast failed:  ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1643274770.464324][5359:5364] CHIP:DIS: Attempt to mDNS broadcast failed:  ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1643274770.464475][5359:5364] CHIP:DIS: Attempt to mDNS broadcast failed:  ../../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable
[1643274770.465314][5359:5364] CHIP:DIS: Node ID resolved for 0x0000000000BC5C01
[1643274770.465366][5359:5364] CHIP:DIS:     Addr 0: [2001:db8::849c:7f62:c927:b009]:5540
[1643274770.465394][5359:5364] CHIP:CTL: OperationalDiscoveryComplete for device ID 0x0000000000BC5C01
[1643274770.466134][5359:5364] CHIP:IN: Generating DestinationID. Fabric ID 0x0000000000000001, Dest node ID 0x0000000000BC5C01, Random data
[1643274770.466179][5359:5364] CHIP:IN: 0x38, 0x70, 0xb4, 0x7e, 0x8b, 0x23, 0x8d, 0xb0,
[1643274770.466203][5359:5364] CHIP:IN: 0x80, 0xde, 0x90, 0xba, 0xc5, 0x83, 0xb4, 0x0d,
[1643274770.466227][5359:5364] CHIP:IN: 0x40, 0xfa, 0x1b, 0x6a, 0xa5, 0x9f, 0x39, 0x69,
[1643274770.466251][5359:5364] CHIP:IN: 0xa0, 0x20, 0x7e, 0xdf, 0x00, 0x5e, 0xc8, 0x15,
[1643274770.466271][5359:5364] CHIP:IN: Root pubkey
[1643274770.466294][5359:5364] CHIP:IN: 0x04, 0x35, 0xbc, 0x79, 0x0d, 0x81, 0xba, 0x7b,
[1643274770.466317][5359:5364] CHIP:IN: 0x01, 0xfb, 0xb5, 0x3e, 0x39, 0x88, 0x07, 0x21,
[1643274770.466340][5359:5364] CHIP:IN: 0x24, 0x9b, 0xc9, 0xbc, 0x44, 0x0d, 0x31, 0x0a,
[1643274770.466363][5359:5364] CHIP:IN: 0x74, 0x4c, 0xdc, 0x4e, 0x18, 0xb3, 0x14, 0xf5,
[1643274770.466385][5359:5364] CHIP:IN: 0xf4, 0xd4, 0x92, 0x47, 0x5c, 0x88, 0x4b, 0x9d,
[1643274770.466436][5359:5364] CHIP:IN: 0xdc, 0x65, 0x2b, 0xe2, 0xc5, 0xcc, 0xc1, 0x84,
[1643274770.466460][5359:5364] CHIP:IN: 0xe4, 0x4f, 0x08, 0xf7, 0x18, 0x85, 0x73, 0x7c,
[1643274770.466483][5359:5364] CHIP:IN: 0x15, 0x0b, 0xfd, 0xd7, 0x01, 0x88, 0x97, 0x2d,
[1643274770.466503][5359:5364] CHIP:IN: 0xde,
[1643274770.466524][5359:5364] CHIP:IN: IPK
[1643274770.466547][5359:5364] CHIP:IN: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
[1643274770.466570][5359:5364] CHIP:IN: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
[1643274770.466606][5359:5364] CHIP:IN: Generated DestinationID output
[1643274770.466631][5359:5364] CHIP:IN: 0x1b, 0x16, 0x3c, 0x82, 0x45, 0x96, 0xd6, 0x2e,
[1643274770.466654][5359:5364] CHIP:IN: 0x9e, 0x6c, 0xd3, 0xf9, 0x26, 0x20, 0xaa, 0x50,
[1643274770.466677][5359:5364] CHIP:IN: 0x69, 0x36, 0xfe, 0x99, 0x62, 0x87, 0x79, 0x7d,
[1643274770.466699][5359:5364] CHIP:IN: 0xe1, 0x6b, 0xfb, 0x08, 0x4f, 0x50, 0xaa, 0xc4,
[1643274770.466723][5359:5364] CHIP:SC: Including MRP parameters
[1643274770.466792][5359:5364] CHIP:IN: Prepared plaintext message 0xaaab016ae8c0 to 0x0000000000000000 (0)  of type 0x30 and protocolId (0, 0) on exchange 18266i with MessageCounter:332976516.
[1643274770.466835][5359:5364] CHIP:IN: Sending plaintext msg 0xaaab016ae8c0 with MessageCounter:332976516 to 0x0000000000000000 at monotonic time: 22084488 msec
[1643274770.466992][5359:5364] CHIP:SC: Sent Sigma1 msg
[1643274770.467027][5359:5364] CHIP:CTL: Address resolved for node: 0x0000000000BC5C01
[1643274770.467356][5359:5364] CHIP:DIS: Discovered node without a pending query
[1643274770.467386][5359:5364] CHIP:DIS: Node ID resolved for 0x0000000000BC5C01
[1643274770.467413][5359:5364] CHIP:DIS:     Addr 0: [2001:db8::849c:7f62:c927:b009]:5540
[1643274770.467435][5359:5364] CHIP:CTL: OperationalDiscoveryComplete for device ID 0x0000000000BC5C01
[1643274770.467463][5359:5364] CHIP:CTL: Address resolved for node: 0x0000000000BC5C01
[1643274770.467612][5359:5364] CHIP:DIS: Discovered node without a pending query
[1643274770.467636][5359:5364] CHIP:DIS: Node ID resolved for 0x0000000000BC5C01
[1643274770.467660][5359:5364] CHIP:DIS:     Addr 0: [2001:db8::849c:7f62:c927:b009]:5540
[1643274770.467681][5359:5364] CHIP:CTL: OperationalDiscoveryComplete for device ID 0x0000000000BC5C01
[1643274770.467706][5359:5364] CHIP:CTL: Address resolved for node: 0x0000000000BC5C01
[1643274770.467851][5359:5364] CHIP:DIS: Discovered node without a pending query
[1643274770.467875][5359:5364] CHIP:DIS: Node ID resolved for 0x0000000000BC5C01
[1643274770.467898][5359:5364] CHIP:DIS:     Addr 0: [2001:db8::849c:7f62:c927:b009]:5540
[1643274770.467919][5359:5364] CHIP:CTL: OperationalDiscoveryComplete for device ID 0x0000000000BC5C01
[1643274770.467943][5359:5364] CHIP:CTL: Address resolved for node: 0x0000000000BC5C01
[1643274770.468086][5359:5364] CHIP:DIS: Discovered node without a pending query
[1643274770.468110][5359:5364] CHIP:DIS: Node ID resolved for 0x0000000000BC5C01
[1643274770.468133][5359:5364] CHIP:DIS:     Addr 0: [2001:db8::849c:7f62:c927:b009]:5540
[1643274770.468154][5359:5364] CHIP:CTL: OperationalDiscoveryComplete for device ID 0x0000000000BC5C01
[1643274770.468178][5359:5364] CHIP:CTL: Address resolved for node: 0x0000000000BC5C01
[1643274772.486384][5359:5364] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:1853389726 on exchange 18266i
[1643274772.486531][5359:5364] CHIP:EM: Found matching exchange: 18266i, Delegate: 0xffffa8214348
[1643274772.486624][5359:5364] CHIP:EM: Rxd Ack; Removing MessageCounter:332976516 from Retrans Table on exchange 18266i
[1643274772.486687][5359:5364] CHIP:EM: Removed CHIP MessageCounter:332976516 from RetransTable on exchange 18266i
[1643274772.486772][5359:5364] CHIP:SC: Received Sigma2 msg
[1643274772.486853][5359:5364] CHIP:SC: Peer assigned session session ID 6
[1643274772.492638][5359:5364] CHIP:IN: Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000001 and root pubkey
[1643274772.492745][5359:5364] CHIP:IN: 0x04, 0x35, 0xbc, 0x79, 0x0d, 0x81, 0xba, 0x7b,
[1643274772.492809][5359:5364] CHIP:IN: 0x01, 0xfb, 0xb5, 0x3e, 0x39, 0x88, 0x07, 0x21,
[1643274772.492871][5359:5364] CHIP:IN: 0x24, 0x9b, 0xc9, 0xbc, 0x44, 0x0d, 0x31, 0x0a,
[1643274772.492930][5359:5364] CHIP:IN: 0x74, 0x4c, 0xdc, 0x4e, 0x18, 0xb3, 0x14, 0xf5,
[1643274772.492990][5359:5364] CHIP:IN: 0xf4, 0xd4, 0x92, 0x47, 0x5c, 0x88, 0x4b, 0x9d,
[1643274772.493053][5359:5364] CHIP:IN: 0xdc, 0x65, 0x2b, 0xe2, 0xc5, 0xcc, 0xc1, 0x84,
[1643274772.493114][5359:5364] CHIP:IN: 0xe4, 0x4f, 0x08, 0xf7, 0x18, 0x85, 0x73, 0x7c,
[1643274772.493174][5359:5364] CHIP:IN: 0x15, 0x0b, 0xfd, 0xd7, 0x01, 0x88, 0x97, 0x2d,
[1643274772.493237][5359:5364] CHIP:IN: 0xde,
[1643274772.493365][5359:5364] CHIP:IN: Generated compressed fabric ID
[1643274772.493438][5359:5364] CHIP:IN: 0x7b, 0x18, 0xf4, 0x57, 0xe9, 0x2a, 0xda, 0xfd,
[1643274772.495633][5359:5364] CHIP:SC: Found MRP parameters in the message
[1643274772.495731][5359:5364] CHIP:SC: Sending Sigma3
[1643274772.496560][5359:5364] CHIP:EM: Piggybacking Ack for MessageCounter:1853389726 on exchange: 18266i
[1643274772.496660][5359:5364] CHIP:IN: Prepared plaintext message 0xaaab016ae8c0 to 0x0000000000000000 (0)  of type 0x32 and protocolId (0, 0) on exchange 18266i with MessageCounter:332976517.
[1643274772.496748][5359:5364] CHIP:IN: Sending plaintext msg 0xaaab016ae8c0 with MessageCounter:332976517 to 0x0000000000000000 at monotonic time: 22086518 msec
[1643274772.497023][5359:5364] CHIP:SC: Sent Sigma3 msg
[1643274773.008254][5359:5364] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:1853389727 on exchange 18266i
[1643274773.008332][5359:5364] CHIP:EM: Found matching exchange: 18266i, Delegate: 0xffffa8214348
[1643274773.008405][5359:5364] CHIP:EM: Rxd Ack; Removing MessageCounter:332976517 from Retrans Table on exchange 18266i
[1643274773.008442][5359:5364] CHIP:EM: Removed CHIP MessageCounter:332976517 from RetransTable on exchange 18266i
[1643274773.008501][5359:5364] CHIP:SC: Success status report received. Session was established
[1643274773.008550][5359:5364] CHIP:IN: New secure session created for device 0x0000000000BC5C01, key 6!!
[1643274773.008724][5359:5364] CHIP:TOO: Sending cluster (0x0030) command (0x00) on endpoint 1
[1643274773.015659][5359:5364] CHIP:DMG: SendReadRequest ReadClient[0xffff90001950]: Sending Read Request
[1643274773.015855][5359:5364] CHIP:IN: Prepared encrypted message 0xaaab016ae8c0 to 0x0000000000BC5C01 (1)  of type 0x2 and protocolId (0, 1) on exchange 18267i with MessageCounter:6773993.
[1643274773.015925][5359:5364] CHIP:IN: Sending encrypted msg 0xaaab016ae8c0 with MessageCounter:6773993 to 0x0000000000BC5C01 (1) at monotonic time: 22087037 msec
[1643274773.016135][5359:5364] CHIP:DMG: MoveToState ReadClient[0xffff90001950]: Moving to [AwaitingIn]
[1643274773.016197][5359:5364] CHIP:CTL: Device connected callback with null pairing delegate. Ignoring
[1643274773.016246][5359:5364] CHIP:EM: Sending Standalone Ack for MessageCounter:1853389727 on exchange 18266i
[1643274773.016301][5359:5364] CHIP:IN: Prepared plaintext message 0xffffa37ed9c8 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 18266i with MessageCounter:332976518.
[1643274773.016360][5359:5364] CHIP:IN: Sending plaintext msg 0xffffa37ed9c8 with MessageCounter:332976518 to 0x0000000000000000 at monotonic time: 22087037 msec
[1643274773.016483][5359:5364] CHIP:EM: Flushed pending ack for MessageCounter:1853389727 on exchange 18266i
[1643274773.135614][5359:5364] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:16127354 on exchange 18267i
[1643274773.135722][5359:5364] CHIP:EM: Found matching exchange: 18267i, Delegate: 0xffff90001950
[1643274773.135808][5359:5364] CHIP:EM: Rxd Ack; Removing MessageCounter:6773993 from Retrans Table on exchange 18267i
[1643274773.135873][5359:5364] CHIP:EM: Removed CHIP MessageCounter:6773993 from RetransTable on exchange 18267i
[1643274773.135991][5359:5364] CHIP:DMG: ReportDataMessage =
[1643274773.136051][5359:5364] CHIP:DMG: {
[1643274773.136097][5359:5364] CHIP:DMG:        AttributeReportIBs =
[1643274773.136168][5359:5364] CHIP:DMG:        [
[1643274773.136331][5359:5364] CHIP:DMG:                AttributeReportIB =
[1643274773.136459][5359:5364] CHIP:DMG:                {
[1643274773.136523][5359:5364] CHIP:DMG:                        AttributeStatusIB =
[1643274773.136588][5359:5364] CHIP:DMG:                        {
[1643274773.136647][5359:5364] CHIP:DMG:                                AttributePathIB =
[1643274773.136712][5359:5364] CHIP:DMG:                                {
[1643274773.136781][5359:5364] CHIP:DMG:                                        Endpoint = 0x1,
[1643274773.136851][5359:5364] CHIP:DMG:                                        Cluster = 0x30,
[1643274773.136928][5359:5364] CHIP:DMG:                                        Attribute = 0x0000_0000,
[1643274773.137051][5359:5364] CHIP:DMG:                                }
[1643274773.137178][5359:5364] CHIP:DMG:
[1643274773.137293][5359:5364] CHIP:DMG:                                StatusIB =
[1643274773.137372][5359:5364] CHIP:DMG:                                {
[1643274773.137487][5359:5364] CHIP:DMG:                                        status = 0x86,
[1643274773.137610][5359:5364] CHIP:DMG:                                },
[1643274773.138218][5359:5364] CHIP:DMG:
[1643274773.138309][5359:5364] CHIP:DMG:                        },
[1643274773.138442][5359:5364] CHIP:DMG:
[1643274773.138523][5359:5364] CHIP:DMG:                },
[1643274773.138609][5359:5364] CHIP:DMG:
[1643274773.138670][5359:5364] CHIP:DMG:        ],
[1643274773.138747][5359:5364] CHIP:DMG:
[1643274773.138807][5359:5364] CHIP:DMG:        SuppressResponse = true,
[1643274773.138863][5359:5364] CHIP:DMG: }
[1643274773.139131][5359:5364] CHIP:TOO: Default Failure Response: 0x86
[1643274773.139282][5359:5364] CHIP:EM: Sending Standalone Ack for MessageCounter:16127354 on exchange 18267i
[1643274773.139427][5359:5364] CHIP:IN: Prepared encrypted message 0xffffa37ed9d8 to 0x0000000000BC5C01 (1)  of type 0x10 and protocolId (0, 0) on exchange 18267i with MessageCounter:6773994.
[1643274773.139522][5359:5364] CHIP:IN: Sending encrypted msg 0xffffa37ed9d8 with MessageCounter:6773994 to 0x0000000000BC5C01 (1) at monotonic time: 22087161 msec
[1643274773.139776][5359:5364] CHIP:EM: Flushed pending ack for MessageCounter:16127354 on exchange 18267i
[1643274773.140159][5359:5359] CHIP:-: ../../examples/chip-tool/third_party/connectedhomeip/zzz_generated/chip-tool/zap-generated/cluster/Commands.h:2502: CHIP Error 0x000000AC: Internal error at ../../examples/chip-tool/commands/common/CHIPCommand.cpp:59
[1643274773.140254][5359:5359] CHIP:TOO: Run command failure: ../../examples/chip-tool/third_party/connectedhomeip/zzz_generated/chip-tool/zap-generated/cluster/Commands.h:2502: CHIP Error 0x000000AC: Internal error
[1643274773.147093][5359:5359] CHIP:SPT: VerifyOrDie failure at ../../examples/chip-tool/third_party/connectedhomeip/src/inet/InetLayer.h:121: sEndPointPool.Allocated() == 0
Aborted
@andy31415
Copy link
Contributor

@nanmu2018 - please follow up with test cases that fail inside this issue instead of creating separate issues for every case. I imagine whoever will end up debugging and fixing this will want to validate all paths as part of a single issue instead of multiple ones.

@jmeg-sfy
Copy link
Contributor

jmeg-sfy commented Feb 3, 2022

Bad endpoint is selected on this logs

I guess we can close this issue

@woody-apple woody-apple added spec Mismatch between spec and implementation and removed looks_critical labels Feb 9, 2022
@bzbarsky-apple
Copy link
Contributor

Resolving: The read is using the wrong endpoint, and on tip (00ccf44) we don't crash in this error scenario.

@justinsignify494
Copy link

Having this same problem!
Any solution as of now?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
spec Mismatch between spec and implementation V1.0
Projects
None yet
Development

No branches or pull requests

6 participants