search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.39k stars 1.98k forks source link

LogEvent with 0x000000000000010D would fail with TLV error during eventReportBuilder.CreateEventData() #13075

Closed yunhanw-google closed 2 years ago

yunhanw-google commented 2 years ago

Problem

in master branch, LogEvent with 0x000000000000010D would fail with error TLV container open during eventReportBuilder.CreateEventData()

./gn_build.sh in macbook, then run ./out/debug/mac_x64_clang/chip-im-responder

wait for EventNumber 0x000000000000010C and 0x000000000000010D, then it would generate the TLV error, later logEvent would be fine.

see the error is generated from eventReportBuilder.CreateEventData() when construct event

this issue is consistently reproduced with 0x10D event number within 8-10 min running with chip-im-responder

[1639642086789] [26310:2478531] CHIP: [EVL] LogEvent event number: 0x0000000000000107 priority: 0, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x2 Sys timestamp: 0x0000000006D573A3 [1639642087789] [26310:2478530] CHIP: [EVL] Dropped 1 event from buffer with priority 0 and event number 0x00000000000000D1 due to overflow: event priority_level: 0 [1639642087789] [26310:2478530] CHIP: [EVL] LogEvent event number: 0x0000000000000108 priority: 2, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x1 Sys timestamp: 0x0000000006D5778B [1639642088790] [26310:2478530] CHIP: [EVL] Copy Event to next buffer with priority 2 [1639642088790] [26310:2478530] CHIP: [EVL] Copy Event to next buffer with priority 1 [1639642088790] [26310:2478530] CHIP: [EVL] LogEvent event number: 0x0000000000000109 priority: 0, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x2 Sys timestamp: 0x0000000006D57B73 [1639642089790] [26310:2478531] CHIP: [EVL] Dropped 1 event from buffer with priority 0 and event number 0x00000000000000D3 due to overflow: event priority_level: 0 [1639642089790] [26310:2478531] CHIP: [EVL] LogEvent event number: 0x000000000000010A priority: 2, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x1 Sys timestamp: 0x0000000006D57F5C [1639642090790] [26310:2478530] CHIP: [EVL] Copy Event to next buffer with priority 2 [1639642090790] [26310:2478530] CHIP: [EVL] Copy Event to next buffer with priority 1 [1639642090791] [26310:2478530] CHIP: [EVL] LogEvent event number: 0x000000000000010B priority: 0, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x2 Sys timestamp: 0x0000000006D58344 [1639642091791] [26310:2478530] CHIP: [EVL] Dropped 1 event from buffer with priority 0 and event number 0x00000000000000D5 due to overflow: event priority_level: 0 [1639642091791] [26310:2478530] CHIP: [EVL] LogEvent event number: 0x000000000000010C priority: 2, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x1 Sys timestamp: 0x0000000006D5872D [1639642092791] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 2 [1639642092792] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 1 [1639642092792] [26310:2478531] CHIP: [EVL] Dropped 1 event from buffer with priority 0 and event number 0x00000000000000D7 due to overflow: event priority_level: 0 [1639642092792] [26310:2478531] CHIP: [EVL] Log event with error ../../src/lib/core/CHIPTLVWriter.cpp:622: CHIP Error 0x00000027: TLV container open [1639642093792] [26310:2478531] CHIP: [EVL] LogEvent event number: 0x000000000000010D priority: 2, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x1 Sys timestamp: 0x0000000006D58EFE [1639642094792] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 2 [1639642094793] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 1 [1639642094793] [26310:2478531] CHIP: [EVL] LogEvent event number: 0x000000000000010E priority: 0, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x2 Sys timestamp: 0x0000000006D592E6 [1639642095793] [26310:2478530] CHIP: [EVL] Dropped 1 event from buffer with priority 0 and event number 0x00000000000000D9 due to overflow: event priority_level: 0 [1639642095793] [26310:2478530] CHIP: [EVL] LogEvent event number: 0x000000000000010F priority: 2, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x1 Sys timestamp: 0x0000000006D596CF [1639642096793] [26310:2478530] CHIP: [EVL] Copy Event to next buffer with priority 2 [1639642096793] [26310:2478530] CHIP: [EVL] Copy Event to next buffer with priority 1 [1639642096793] [26310:2478530] CHIP: [EVL] LogEvent event number: 0x0000000000000110 priority: 0, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x2 Sys timestamp: 0x0000000006D59AB7 [1639642097793] [26310:2478531] CHIP: [EVL] Dropped 1 event from buffer with priority 0 and event number 0x00000000000000DB due to overflow: event priority_level: 0 [1639642097793] [26310:2478531] CHIP: [EVL] LogEvent event number: 0x0000000000000111 priority: 2, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x1 Sys timestamp: 0x0000000006D59E9F [1639642098793] [26310:2478531] CHIP: [EVL] Dropped 1 event from buffer with priority 2 and event number 0x0000000000000000 due to overflow: event priority_level: 2 [1639642098794] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 2 [1639642098794] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 1 [1639642098794] [26310:2478531] CHIP: [EVL] LogEvent event number: 0x0000000000000112 priority: 0, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x2 Sys timestamp: 0x0000000006D5A287 [1639642099794] [26310:2478530] CHIP: [EVL] Dropped 1 event from buffer with priority 0 and event number 0x00000000000000DD due to overflow: event priority_level: 0 [1639642099794] [26310:2478530] CHIP: [EVL] LogEvent event number: 0x0000000000000113 priority: 2, endpoint id: 0x1 cluster id: 0x0000_0006 event id: 0x1 Sys timestamp: 0x0000000006D5A670 [1639642100794] [26310:2478531] CHIP: [EVL] Dropped 1 event from buffer with priority 2 and event number 0x0000000000000002 due to overflow: event priority_level: 2 [1639642100794] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 2 [1639642100794] [26310:2478531] CHIP: [EVL] Copy Event to next buffer with priority 1

turon commented 2 years ago

Should add unit test to verify this strange corner case has been fixed in v1. Removing tag v1_triage_split_4

yunhanw-google commented 2 years ago

when LogEvent has filled up the circular event buffer, https://github.com/project-chip/connectedhomeip/blob/master/src/app/EventManagement.cpp#L495, writer.Init(*mpEventBuffer); would fail where write would initialize circularEventBuffer, which further call CHIPCircularTLVBuffer::OnInit and call GetNewBuffer https://github.com/project-chip/connectedhomeip/blob/master/src/lib/core/CHIPCircularTLVBuffer.cpp#L261, and further fail in https://github.com/project-chip/connectedhomeip/blob/master/src/lib/core/CHIPCircularTLVBuffer.cpp#L202 because of mQueueLength >= mQueueSize, since we have set alwaysFail for mProcessEvictedElement in https://github.com/project-chip/connectedhomeip/blob/master/src/app/EventManagement.cpp#L157, EvictHead would always fail

yunhanw-google commented 2 years ago

we probably skip the error instead of alwaysFail, or mark it as expected. @robszewczyk