RDKEMW-14300 : Removed Log truncation & added testApp to measure CPU

[karuna2git]

Reason for change:

1. Removed Log split & truncation
2. Configured default buffer size to be 0 as same as Previous Releases
3. Added new log formats as TID & TS_TIDs
4. Added testApp to measure CPU
5. Updated default logging to console instead of recently changes syslog as we see better CPU when console used
6. Added unit test cases to verify the new formats
7. Added unified log function to handle all the log formats
   Test Procedure: Verify huge data
   Risks: Medium

[Copilot]

Pull request overview

This PR updates the RDK logger to remove log splitting/truncation, introduce additional log formats (TID / TS+TID), adjust default log4c configuration (bufsize=0 and console default), and adds a new CPU-measurement test application plus unit tests for the new formats.

Changes:

• Refactors core logging path to rely on log4c formatting (adds new layouts and a unified formatting helper) and removes chunked/split logging.
• Updates log4c configuration files (project and gtest) to define new layout types and change default appenders/buffer size.
• Adds a new rdk_logger_cpu_test app and extends rotation unit tests for the new formats.

Reviewed changes

Copilot reviewed 11 out of 11 changed files in this pull request and generated 10 comments.

Show a summary per file

File	Description
src/rdk_debug_priv.c	Adds new log4c layouts and unified formatter; removes truncation/splitting logic; uses log4c_category_vlog.
src/rdk_debug.c	Adds NULL guards for module/format in public logging APIs.
include/rdk_logger.h	Extends rdk_LogFormat with WITH_TID and WITH_TS_TID and updates format docs.
log4crc	Changes default bufsize to 0, adds new layouts, and switches default category appender to console.
unittests/Gtest_log4crc	Updates gtest log4c layouts/appenders to match new format types.
unittests/rdkLoggerRotationTest.cpp	Adds rotation tests intended to validate new TID/TS_TID/detail-without-TS formats.
unittests/rdkLoggerErrorTest.cpp	Removes an unsafe “very long format string” test case.
test/rdk_logger_cpu_test.c	Adds a new test app to measure CPU impact of logger init and logging at different outputs/levels.
test/Makefile.am	Replaces the previous test binary with rdk_logger_cpu_test.
test/rdk_logger_test_main.c	Deleted (old test program main).
test/rdk_logger_debug_test.c	Deleted (old debug test program).

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[Copilot]

Pull request overview

Copilot reviewed 12 out of 12 changed files in this pull request and generated 7 comments.

Comments suppressed due to low confidence (1)

src/rdk_debug.c:54

• The null pointer checks for module and format are performed in both rdk_logger_msg_printf (line 49) and again in rdk_dbg_priv_log_msg (line 617). While defense in depth is good practice, this creates redundant checks that will be executed on every log call. Consider documenting which layer is responsible for validation, or remove the redundant check in one location for better performance. The same redundancy exists in rdk_dbg_MsgRaw (line 69) and the other wrapper functions.

    if ((format) && (module))
    {
        va_start(args, format);
        rdk_dbg_priv_log_msg(level, module, format, args);
        va_end(args);
    }

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[Copilot]

Pull request overview

Copilot reviewed 12 out of 12 changed files in this pull request and generated 1 comment.

Comments suppressed due to low confidence (8)

unittests/rdkLoggerRotationTest.cpp:566

• The timestamp validation is very weak - checking for ':' and '-' characters can match many patterns that aren't timestamps. For example, "method - Success: value" would pass this check even without any timestamp. A more robust validation would check for the actual timestamp format produced by the logger, such as matching a pattern like YYYY-MM-DD HH:MM:SS or at minimum verifying multiple colons and hyphens in the expected positions.

            while (fgets(line, sizeof(line), logFile)) {
                // Look for timestamp patterns (date/time format)
                // The log message could be having something like `method - Success. value:1234` & could lead to false possitive
                // but since we are the only one printing to this file as part of unit testing & we know what we print, this is fine.
                if (strchr(line, ':') != NULL && strchr(line, '-') != NULL) {
                    foundTimestamp = true;
                }

unittests/rdkLoggerRotationTest.cpp:512

• The test validation for thread ID presence is weak - it simply checks for any occurrence of '[' and ']' characters in the log output. This could lead to false positives if the log message itself contains brackets (which the comment acknowledges but dismisses). A more robust check would verify the format pattern, for example by using regex to match the expected format pattern like \[\d+\] for thread IDs.

            while (fgets(line, sizeof(line), logFile)) {
                // Thread ID format typically appears as [xxxxx] or similar;
                // The log message could be having something like `[foo]`
                // but since we are the only one printing to this file as part of unit testing, this is fine.
                if ((strchr(line, '[') != NULL) && (strchr(line, ']') != NULL)) {
                    foundThreadId = true;
                    break;
                }
            }
            fclose(logFile);
            EXPECT_TRUE(foundThreadId) << "Log should contain thread ID information";

src/rdk_debug_priv.c:618

• The null pointer checks for module and format are now duplicated - they exist both in the public API functions (rdk_logger_msg_printf, rdk_dbg_MsgRaw, etc.) and again in rdk_dbg_priv_log_msg. This creates redundant checks that will be executed twice for every log call. Consider removing the checks from one layer to avoid the performance overhead, especially since these functions are called frequently in logging paths. The checks in rdk_debug.c are sufficient as they catch the issue before va_start is called.

    if ((!module_name) || (!format))
        return;

test/rdk_logger_cpu_test.c:94

• The cpu.txt output file is opened with "a+" mode and written to without any path specification, meaning it will be created in the current working directory. This could lead to:

1. Permission issues if the current directory is not writable
2. Difficulty finding the output file since the location isn't documented
3. Potential conflicts if multiple instances run simultaneously
   Consider using a well-defined output path (e.g., /tmp/rdk_logger_cpu.txt) or accepting the output path as a command-line argument.

    FILE* file = fopen("cpu.txt", "a+");
    if (file == NULL) {
        perror("Error opening cpu.txt");
        exit(EXIT_FAILURE);
    }
    if (pBuf)
    {
        fprintf(file, "%16s : \t", pBuf);
    }
    
    fprintf(file, "Current CPU usage: %.2f%%\n", cpu_usage);
    fclose(file);

include/rdk_logger.h:232

• Similar to RDKLOG_FORMAT_WITH_TS, update documentation to specify that timestamps include microseconds precision, not just milliseconds.

 * - RDKLOG_FORMAT_WITH_TS_TID:          Timestamped layout with priority, TID & message.

unittests/rdkLoggerRotationTest.cpp:562

• Spelling error: "possitive" should be "positive".

                // The log message could be having something like `method - Success. value:1234` & could lead to false possitive

include/rdk_logger.h:230

• The documentation states "Timestamped layout including milliseconds" but the implementation uses microseconds (evt_timestamp.tv_usec with %06ld format). Update the documentation to accurately reflect that timestamps include microseconds, not milliseconds.

 * - RDKLOG_FORMAT_WITH_TS:              Timestamped layout including milliseconds, priority & message.

src/rdk_debug_priv.c:799

• The redundant newline check at line 794 accesses event->evt_buffer.buf_data[n] which should already be '\0' after snprintf, making this check redundant. The actual check should verify that position n-1 and n-2 contain newlines. However, the current logic checks if buf_data[n] == '\0', which should always be true for a successful snprintf. The logic appears correct but the comment could be clearer about why we're checking buf_data[n] when we already know n is the number of characters written (excluding the null terminator).

        /* avoid redundant \n */
        if ((n >= 2) &&
            (n < event->evt_buffer.buf_size) &&
            (event->evt_buffer.buf_data != NULL) &&
            (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';
        }

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[Copilot]

Pull request overview

Copilot reviewed 12 out of 12 changed files in this pull request and generated 3 comments.

Comments suppressed due to low confidence (3)

log4crc:42

• The appender "rdk_syslog" is configured with layout "rdk_with_tid" but the default category appender is "rdk_console" with layout "rdk_detail_without_ts". This is a change from the previous configuration where syslog was the default. According to the PR description, this change is intentional (item 5: "Updated default logging to console instead of recently changes syslog"). However, note that the rdk_syslog appender will include TID but not timestamps, while the rdk_console (default) includes neither timestamp nor TID in its detail format. Verify this matches the intended logging behavior for both outputs.

    <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"/>

    <category name="LOG.RDK" priority="warning" appender="rdk_console"/>

test/rdk_logger_cpu_test.c:94

• The PrintCPUMetric function uses hardcoded filename "cpu.txt" without specifying a directory path. The file will be created in the current working directory, which may vary depending on where the test is executed. This could lead to permission issues or file clutter. Consider using a more explicit path (e.g., "/tmp/cpu.txt") or making the output path configurable. Additionally, the file is opened in "a+" mode for every call, which could result in a very large file if the test runs for extended periods.

    FILE* file = fopen("cpu.txt", "a+");
    if (file == NULL) {
        perror("Error opening cpu.txt");
        exit(EXIT_FAILURE);
    }
    if (pBuf)
    {
        fprintf(file, "%16s : \t", pBuf);
    }
    
    fprintf(file, "Current CPU usage: %.2f%%\n", cpu_usage);
    fclose(file);

unittests/CMakeLists.txt:50

• The include_directories and link_directories calls have been reordered. Previously link_directories was called early (before add_executable), now it's called after include_directories but before the target definitions. While this may work, CMake best practice is to use target-specific commands (target_include_directories, target_link_directories) instead of directory-wide commands. The current approach could affect other targets unexpectedly if this CMakeLists.txt is included in a larger build. Consider using target_include_directories(rdk_logger_gtest PRIVATE ...) instead of the global include_directories calls.

include_directories(${CMAKE_INSTALL_PREFIX}/include)
include_directories(${DEP_LIB_PATH}/../include)
link_directories("${DEP_LIB_PATH}/")

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[dshett549]

Looks good