RDKEMW-14300 : Removed Log truncation & added testApp to measure CPU#49
RDKEMW-14300 : Removed Log truncation & added testApp to measure CPU#49karuna2git wants to merge 8 commits intodevelopfrom
Conversation
There was a problem hiding this comment.
Pull request overview
This pull request removes log message truncation logic and adds a CPU performance test application to measure the impact of logging operations. The changes transition from a fixed-size buffer approach (980 bytes) to dynamic buffer allocation, allowing arbitrarily large log messages without truncation.
Changes:
- Removed manual log truncation logic that split large messages into chunks, replacing it with log4c's built-in
log4c_category_vlogfunction - Refactored format handlers into a unified
rdk_format_logfunction that dynamically reallocates buffers when needed - Added a new
RDKLOG_FORMAT_WITH_TS_TIDlog format that includes timestamp and thread ID - Replaced old test files with a new CPU performance test that measures logging overhead
Reviewed changes
Copilot reviewed 7 out of 7 changed files in this pull request and generated 20 comments.
Show a summary per file
| File | Description |
|---|---|
| test/rdk_logger_test_main.c | Removed old test main file |
| test/rdk_logger_debug_test.c | Removed old debug test file |
| test/rdk_logger_cpu_test.c | Added new CPU performance measurement test with 4 test scenarios |
| test/Makefile.am | Updated to build new CPU test instead of old test program |
| src/rdk_debug_priv.c | Removed truncation logic, refactored format handlers, added dynamic buffer reallocation, and implemented new format with thread ID |
| log4crc | Changed buffer size from 1024 to 0 for dynamic allocation, added new layout configuration |
| include/rdk_logger.h | Added RDKLOG_FORMAT_WITH_TS_TID enum value |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
test/rdk_logger_cpu_test.c
Outdated
| usleep(10000); | ||
|
|
||
| // Test 4: Print INFO where INFO is enabled. | ||
| // CPU taken to print the log messagge |
There was a problem hiding this comment.
There is a typo in the comment. "messagge" should be "message".
There was a problem hiding this comment.
@copilot open a new pull request to apply changes based on this feedback
src/rdk_debug_priv.c
Outdated
| /**************************************************************** | ||
| * With TimeStamp format with no ending carriage return / line feed |
There was a problem hiding this comment.
The comment is outdated and misleading. The function now adds a newline character via rdk_format_log (see line 731 where "\n" is appended), so it does have an ending line feed. The comment should be updated to reflect the current behavior.
Reason for change: Removed Log truncation & added testApp to measure CPU Test Procedure: Verify huge data Risks: Low Signed-off-by: Karunakaran A <karunakaran_amirthalingam@cable.comcast.com>
62e00cf to
1c54cb4
Compare
|
@karuna2git I've opened a new pull request, #50, to work on those changes. Once the pull request is ready, I'll request review from you. |
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 7 out of 7 changed files in this pull request and generated 4 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
|
@karuna2git I've opened a new pull request, #51, to work on those changes. Once the pull request is ready, I'll request review from you. |
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
|
@karuna2git I've opened a new pull request, #52, to work on those changes. Once the pull request is ready, I'll request review from you. |
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 7 out of 7 changed files in this pull request and generated 3 comments.
Comments suppressed due to low confidence (1)
src/rdk_debug_priv.c:683
- getModuleName() casts event->evt_category to char* even though it is treated as read-only. This can trigger warnings (cast discards const) depending on log4c’s definition of evt_category. Prefer using const char* throughout (and avoid casting away const) since the function does not modify the category string.
static const char* getModuleName(log4c_logging_event_t* event)
{
/** Get the last part of the cagetory as "module" */
char *p= (char *)(event->evt_category);
if (NULL == p)
{
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
|
I have read the CLA Document and I hereby sign the CLA You can retrigger this bot by commenting recheck in this Pull Request. Posted by the CLA Assistant Lite bot. |
d26306d to
3d11802
Compare
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 8 out of 8 changed files in this pull request and generated 6 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| // Read and verify log content contains both timestamp and thread ID | ||
| FILE* logFile = fopen(logFilePath, "r"); | ||
| ASSERT_NE(logFile, nullptr) << "Failed to open log file for validation"; | ||
|
|
||
| char line[1024]; | ||
| bool foundModuleName = false; | ||
| if (fgets(line, sizeof(line), logFile)) { | ||
| // Check for full module name (LOG.RDK.ROTATION) which should be in detailed format | ||
| if (strstr(line, "LOG.RDK.ROTATION") != NULL) { | ||
| foundModuleName = true; | ||
| } | ||
| } | ||
| fclose(logFile); | ||
| EXPECT_TRUE(foundModuleName) << "Log should contain module name in detailed format"; |
There was a problem hiding this comment.
The detailed formats now print only the last segment of the category via getModuleName(...) (e.g., ROTATION), not the full LOG.RDK.ROTATION. As written, this assertion will likely fail even when the format is correct. Update the expectation to match the actual detailed layout (or change the layout to include the full category if that’s the intent).
| // Read and verify log content contains both timestamp and thread ID | |
| FILE* logFile = fopen(logFilePath, "r"); | |
| ASSERT_NE(logFile, nullptr) << "Failed to open log file for validation"; | |
| char line[1024]; | |
| bool foundModuleName = false; | |
| if (fgets(line, sizeof(line), logFile)) { | |
| // Check for full module name (LOG.RDK.ROTATION) which should be in detailed format | |
| if (strstr(line, "LOG.RDK.ROTATION") != NULL) { | |
| foundModuleName = true; | |
| } | |
| } | |
| fclose(logFile); | |
| EXPECT_TRUE(foundModuleName) << "Log should contain module name in detailed format"; | |
| // Read and verify log content contains the module name in detailed format (short module name) | |
| FILE* logFile = fopen(logFilePath, "r"); | |
| ASSERT_NE(logFile, nullptr) << "Failed to open log file for validation"; | |
| char line[1024]; | |
| bool foundModuleName = false; | |
| if (fgets(line, sizeof(line), logFile)) { | |
| // Check for module name as printed by detailed format (last segment of category) | |
| if (strstr(line, "ROTATION") != NULL) { | |
| foundModuleName = true; | |
| } | |
| } | |
| fclose(logFile); | |
| EXPECT_TRUE(foundModuleName) << "Log should contain short module name in detailed format"; |
| struct tm tm; | ||
| char timeBuff[COMCAST_DATAED_BUFF_SIZE] = {0}; | ||
|
|
||
| /** Get the last part of the cagetory as "module" */ |
There was a problem hiding this comment.
Typo in comment: "cagetory" should be "category".
| /** Get the last part of the cagetory as "module" */ | |
| /** Get the last part of the category as "module" */ |
| <appender name="rdk_console" type="to_console" layout="rdk_detail_without_ts"/> | ||
| <appender name="rdk_syslog" type="to_syslog" layout="rdk_with_tid"/> | ||
| <appender name="rdk_journal" type="to_journal" layout="rdk_plaintext"/> | ||
| <appender name="rdk_printf" type="to_console" layout="rdk_detail_with_ts"/> | ||
|
|
There was a problem hiding this comment.
These changes modify default logging behavior (root category now uses rdk_console instead of rdk_syslog; console/syslog layouts changed). This is potentially breaking for consumers relying on previous defaults, and it isn’t mentioned in the PR description. Please confirm it’s intended and document the behavior change (or preserve existing defaults).
| FILE* file = fopen("cpu.txt", "a+"); | ||
| if (file == NULL) { | ||
| perror("Error opening cpu.txt"); |
There was a problem hiding this comment.
This tool writes CPU metrics to a relative path (cpu.txt) and exits on failure. If the program is run from a non-writable working directory (common on embedded/rootfs setups), it will fail immediately. Consider writing to a known-writable location like /tmp by default, or allow the output path to be configured via argv/env.
| FILE* file = fopen("cpu.txt", "a+"); | |
| if (file == NULL) { | |
| perror("Error opening cpu.txt"); | |
| const char *cpuPath = getenv("RDK_LOGGER_CPU_FILE"); | |
| if (cpuPath == NULL || cpuPath[0] == '\0') { | |
| cpuPath = "/tmp/cpu.txt"; | |
| } | |
| FILE* file = fopen(cpuPath, "a+"); | |
| if (file == NULL) { | |
| fprintf(stderr, "Error opening CPU metrics file at '%s'\n", cpuPath); | |
| perror("fopen"); |
| while (fgets(line, sizeof(line), logFile)) { | ||
| // Thread ID format typically appears as [TID:xxxxx] or similar | ||
| if (strstr(line, "TID") != NULL || strchr(line, '[') != NULL) { | ||
| foundThreadId = true; | ||
| break; |
There was a problem hiding this comment.
The thread-ID assertion is too permissive: strchr(line, '[') will be true for any log line because the level is always wrapped in brackets (e.g., [INFO ]). This means the test can pass even if the TID is not present. Please assert on a more specific pattern (e.g., a bracketed numeric token after the level, or a regex like \[[0-9]+\]).
| } | ||
| // Look for thread ID | ||
| if (strstr(line, "TID") != NULL || strchr(line, '[') != NULL) { | ||
| foundThreadId = true; | ||
| } |
There was a problem hiding this comment.
Same issue as above: the thread-ID check will pass for any line that contains '[' (the log level), so this test may pass even if RDKLOG_FORMAT_WITH_TS_TID doesn't include the TID. Please assert specifically for the TID token (e.g., bracketed digits) rather than a generic '['/"TID" substring.
3d11802 to
17bcdcd
Compare
17bcdcd to
4df6aa7
Compare
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 9 out of 9 changed files in this pull request and generated 9 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| // Look for timestamp patterns (date/time format) | ||
| if (strchr(line, ':') != NULL && strchr(line, '-') != NULL) { | ||
| foundTimestamp = true; | ||
| } |
There was a problem hiding this comment.
The timestamp validation is too broad. Checking for ':' and '-' characters could match unrelated content in the log message itself, not just the timestamp format. The actual timestamp format from line 742 in src/rdk_debug_priv.c is "%s.%06ld [%-5s] [%ld] %s\n" where the timestamp contains microseconds. Consider using a more specific pattern to validate the actual timestamp format.
| struct stat st; | ||
| EXPECT_EQ(stat(logFilePath, &st), 0) << "Log file should exist"; | ||
|
|
||
| // Read and verify log content contains both timestamp and thread ID |
There was a problem hiding this comment.
The comment states "Read and verify log content contains both timestamp and thread ID" but the test is for RDKLOG_FORMAT_DETAIL_WITHOUT_TS format which should not contain a timestamp according to line 587. The actual test only checks for module name. Either the comment is incorrect or the test logic is incomplete.
| // Read and verify log content contains both timestamp and thread ID | |
| // Read and verify log content contains the module name in detailed format (without timestamp) |
unittests/rdkLoggerRotationTest.cpp
Outdated
| testPolicy.fileLocation, testPolicy.fileName); | ||
| printf("logFilePath = %s\n", logFilePath); | ||
| struct stat st; | ||
| EXPECT_EQ(lstat(logFilePath, &st), 0) << "Log file should exist"; |
There was a problem hiding this comment.
The test uses lstat instead of stat, which is inconsistent with the other format tests (FormatWithTSTID at line 547 and FormatDetailWithoutTS at line 606) that use stat. Since the test is checking for a regular log file and not a symbolic link, stat should be used for consistency.
| EXPECT_EQ(lstat(logFilePath, &st), 0) << "Log file should exist"; | |
| EXPECT_EQ(stat(logFilePath, &st), 0) << "Log file should exist"; |
unittests/rdkLoggerRotationTest.cpp
Outdated
| char logFilePath[512]; | ||
| snprintf(logFilePath, sizeof(logFilePath), "%s/%s", | ||
| testPolicy.fileLocation, testPolicy.fileName); | ||
| printf("logFilePath = %s\n", logFilePath); |
There was a problem hiding this comment.
The line uses tabs instead of spaces for indentation, which is inconsistent with the rest of the file that uses spaces. This creates visual inconsistency and may cause issues with code formatting tools.
| while (fgets(line, sizeof(line), logFile)) { | ||
| // Thread ID format typically appears as [TID:xxxxx] or similar | ||
| if (strstr(line, "TID") != NULL || strchr(line, '[') != NULL) { | ||
| foundThreadId = true; | ||
| break; | ||
| } |
There was a problem hiding this comment.
The validation logic is too broad and may produce false positives. The test searches for any line containing "TID" or '[' characters, which could match unrelated content. The actual format should be "[%ld]" for thread ID according to line 762 in src/rdk_debug_priv.c. Consider using a more specific pattern or regex to validate the actual thread ID format.
| // Look for thread ID | ||
| if (strstr(line, "TID") != NULL || strchr(line, '[') != NULL) { | ||
| foundThreadId = true; | ||
| } |
There was a problem hiding this comment.
The thread ID validation is too broad and may produce false positives. The test searches for any line containing "TID" or '[' characters, which could match unrelated content. The actual format should be "[%ld]" for thread ID according to line 746 in src/rdk_debug_priv.c. Consider using a more specific pattern or regex to validate the actual thread ID format.
| fprintf(stderr, "Failed to parse CPU statistics from /proc/stat (parsed %d fields)\n", parsed); | ||
| fclose(file); | ||
| exit(EXIT_FAILURE); | ||
| } |
There was a problem hiding this comment.
If fgets returns NULL (e.g., due to an empty file or read error), the function exits normally but leaves the times structure zeroed out. This could lead to incorrect CPU usage calculations. Consider adding an error check or exit when fgets fails to read the first line.
| } | |
| } | |
| } else { | |
| if (feof(file)) { | |
| fprintf(stderr, "Unexpected end of file while reading /proc/stat\n"); | |
| } else { | |
| perror("Error reading /proc/stat"); | |
| } | |
| fclose(file); | |
| exit(EXIT_FAILURE); |
| /* avoid redundant \n */ | ||
| if ((n >= 2) && | ||
| (n < event->evt_buffer.buf_size) && | ||
| (event->evt_buffer.buf_data[n] == '\0') && | ||
| (event->evt_buffer.buf_data[n - 1] == '\n') && | ||
| (event->evt_buffer.buf_data[n - 2] == '\n')) | ||
| { | ||
| event->evt_buffer.buf_data[n - 1] = '\0'; | ||
| } |
There was a problem hiding this comment.
The logic for detecting redundant newlines appears incorrect. Line 785 checks if buf_data[n] equals '\0', but n represents the number of characters written (excluding null terminator). The check should be for buf_data[n-1] and buf_data[n-2] only. Additionally, when n >= buf_size (truncation case), this check accesses beyond the valid buffer range.
unittests/rdkLoggerRotationTest.cpp
Outdated
| rdk_Error ret = rdk_logger_ext_init(&config); | ||
| ASSERT_EQ(ret, RDK_SUCCESS) << "Extended initialization with RDKLOG_FORMAT_WITH_TID should succeed"; | ||
|
|
||
| system("mkdir -p /tmp/rdk_logger_rotation_test"); |
There was a problem hiding this comment.
The line uses tabs instead of spaces for indentation, which is inconsistent with the rest of the file that uses spaces. This creates visual inconsistency and may cause issues with code formatting tools.
| system("mkdir -p /tmp/rdk_logger_rotation_test"); | |
| system("mkdir -p /tmp/rdk_logger_rotation_test"); |
4df6aa7 to
394f064
Compare
Reason for change: Removed Log truncation & added testApp to measure CPU Test Procedure: Verify huge data Risks: Low Co-authored-by: karuna2git <48997923+karuna2git@users.noreply.github.com> Signed-off-by: Karunakaran A <karunakaran_amirthalingam@cable.comcast.com>
394f064 to
a3d3a69
Compare
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 10 out of 10 changed files in this pull request and generated 6 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| if ((!format) && (!module)) | ||
| { | ||
| va_start(args, format); | ||
| rdk_dbg_priv_log_msg(level, module, format, args); | ||
| va_end(args); | ||
| } |
There was a problem hiding this comment.
The null pointer check logic is inverted. The condition uses AND (&&) when it should use OR (||). Currently, the function only logs when BOTH format AND module are NULL, which is incorrect. It should log when EITHER format OR module is NOT NULL. Change the condition to if (format || module) to correctly allow logging when at least one of these parameters is valid.
| if ((!format) && (!module)) | ||
| { | ||
| va_start(args, format); | ||
| rdk_dbg_priv_log_msg(level, module, format, args); | ||
| va_end(args); | ||
| } |
There was a problem hiding this comment.
The null pointer check logic is inverted. The condition uses AND (&&) when it should use OR (||). Currently, the function only logs when BOTH format AND module are NULL, which is incorrect. It should log when EITHER format OR module is NOT NULL. Change the condition to if (format || module) to correctly allow logging when at least one of these parameters is valid.
| if ((!format) && (!module)) | ||
| rdk_dbg_priv_log_msg(level, module, format, args); |
There was a problem hiding this comment.
The null pointer check logic is inverted. The condition uses AND (&&) when it should use OR (||). Currently, the function only logs when BOTH format AND module are NULL, which is incorrect. It should log when EITHER format OR module is NOT NULL. Change the condition to if (format || module) to correctly allow logging when at least one of these parameters is valid.
| while (fgets(line, sizeof(line), logFile)) { | ||
| // Look for timestamp patterns (date/time format) | ||
| if (strchr(line, ':') != NULL && strchr(line, '-') != NULL) { | ||
| foundTimestamp = true; | ||
| } | ||
| // Look for thread ID | ||
| if (strstr(line, "TID") != NULL || strchr(line, '[') != NULL) { | ||
| foundThreadId = true; | ||
| } | ||
| if (foundTimestamp && foundThreadId) break; |
There was a problem hiding this comment.
The validation logic for detecting thread ID and timestamp is too broad. The condition strchr(line, '[') != NULL will match any line containing a square bracket, including the priority field (e.g., "[INFO]"), and the timestamp check strchr(line, ':') != NULL && strchr(line, '-') != NULL could match the colon in the microsecond timestamp or other unrelated content. This makes the test less reliable. Consider making the checks more specific by looking for actual thread ID patterns or timestamp formats.
|
|
||
| <config> | ||
| <bufsize>1024</bufsize> | ||
| <bufsize>0</bufsize> |
There was a problem hiding this comment.
Setting bufsize to 0 in the log4c configuration means the buffer will dynamically grow as needed via realloc. However, there's a critical bug in the realloc implementation at src/rdk_debug_priv.c:778 where the return value is not checked for NULL. This configuration change makes the memory allocation failure path more likely to be hit with large log messages. The realloc bug must be fixed before this configuration change can be safely deployed.
| <bufsize>0</bufsize> | |
| <bufsize>2048</bufsize> |
| if ((!format) && (!module)) | ||
| rdk_dbg_priv_log_msg(level, module, format, args); |
There was a problem hiding this comment.
The null pointer check logic is inverted. The condition uses AND (&&) when it should use OR (||). Currently, the function only logs when BOTH format AND module are NULL, which is incorrect. It should log when EITHER format OR module is NOT NULL. Change the condition to if (format || module) to correctly allow logging when at least one of these parameters is valid.
Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>
Reason for change: Removed Log truncation & added testApp to measure CPU
Test Procedure: Verify huge data
Risks: Low