Adding sub seconds to logging

[kanjoe24]

Pull request overview

This PR updates the C logging implementation to include sub-second (microsecond) precision timestamps in log output.

Changes:

• Increased the maximum timestamp buffer size (UT_MAX_TIME_STRING) to accommodate fractional seconds.
• Switched from time() to clock_gettime(CLOCK_REALTIME, ...) and appended .%06ld (microseconds) to the formatted timestamp in UT_log() and UT_logPrefix().
• Moved to localtime_r() instead of localtime() as it returns a pointer to a shared static buffer — not thread-safe.

[kanjoe24]

test logs:

2026-08-07 14:23:27.506260, LOG   , ut_console.c,   661 :      Test Complete : 'log active macros smoke test'
2026-08-07 14:23:27.506294, LOG   , ut_console.c,   633 : 

2026-08-07 14:23:27.506329, LOG   , ut_console.c,   639 :      Running Test : 'log macro suppression and arg evaluation'
2026-08-07 14:23:27.506366, LOG   , ut_test_log.c,   147 : test_ut_log_macro_suppression_and_arg_evaluation

2026-08-07 14:23:27.506405, ERROR , ut_test_log.c,   151 : error
2026-08-07 14:23:27.506441, WARN  , ut_test_log.c,   155 : warning
2026-08-07 14:23:27.506476, LOG   , ut_test_log.c,   166 : test_ut_log_macro_suppression_and_arg_evaluation end

2026-08-07 14:23:27.506510, LOG   , ut_console.c,   661 :      Test Complete : 'log macro suppression and arg evaluation'

Run Summary:    Type  Total    Ran Passed Failed Inactive
              suites     18     18    n/a      0        0
               tests    107    107    107      0        0
             asserts    598    598    598      0      n/a

Elapsed time =    3.493 seconds


***************** CUNIT CONSOLE - MAIN MENU ******************************
(R)un  (S)elect  (L)ist  (A)ctivate  (F)ailures  (O)ptions  (H)elp  (Q)uit
Enter command: q

2026-08-07 14:23:30.555323, LOG   , ut_cunit.c,   177 : Logfile:[/tmp/ut-log_2026-08-07_142218.log]
2026-08-07 14:23:30.555455, LOG   , ut_cunit.c,   185 : ---- end of test run ----
-----------------------------------------------------
Suppressions used:
  count      bytes template
   2707     333884 fy_*
-----------------------------------------------------

jpn323@janus ~/workspace/ut-control/tests/build/bin (feature/gh132-add-subsec-to-utlog)$ 

[Copilot]

Pull request overview

This PR updates the C logging implementation to include sub-second (microsecond) precision timestamps in log output.

Changes:

• Increased the maximum timestamp buffer size (UT_MAX_TIME_STRING) to accommodate fractional seconds.
• Switched from time() to clock_gettime(CLOCK_REALTIME, ...) and appended .%06ld (microseconds) to the formatted timestamp in UT_log() and UT_logPrefix().

Suppressed comments (1)

src/ut_log.c:143

• clock_gettime() / localtime() / strftime() results aren’t checked here. On failure, the timestamp string can be incorrect or localtime() can return NULL and be dereferenced by strftime(). Handle failures and fall back to a safe timestamp string.

    clock_gettime(CLOCK_REALTIME, &ts);

    if ( gLogInit == false )
    {
        /* If ut-core has never called to set the log to a fixed location then let's set it */
        UT_log_setLogFilePath(UT_LOG_DEFAULT_PATH);
    }

    /* #FIXME : This will need rework, we shouldn't be opening logs constantly */
    fp = fopen(gLogFileName, "a");
    if (fp == NULL)
    { 
        printf("\nUnable to open file for logging...");
        return;
    }

    tmp = localtime(&ts.tv_sec);
    strftime(time_now, sizeof(time_now), "%Y-%m-%d %H:%M:%S", tmp); // example: 2023-06-19 14:30:45
    snprintf(time_now + strlen(time_now), sizeof(time_now) - strlen(time_now), ".%06ld", ts.tv_nsec / 1000); // example: 2023-06-19 14:30:45.123456

---

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

[Copilot]

Pull request overview

Copilot reviewed 1 out of 1 changed files in this pull request and generated no new comments.

Suppressed comments (6)

src/ut_log.c:79

• clock_gettime(CLOCK_REALTIME, ...) return value is ignored. On failure, ts may contain uninitialized data, and subsequent localtime_r/formatting can crash or log garbage. Add a fallback when clock_gettime fails.

    clock_gettime(CLOCK_REALTIME, &ts);

src/ut_log.c:97

• localtime_r()/strftime() results are not checked before using strlen(time_now) and appending subseconds. If localtime_r returns NULL or strftime returns 0, this can result in undefined behavior or a crash. Guard the formatting and ensure time_now is always NUL-terminated before appending.

    tmp = localtime_r(&ts.tv_sec, &tm_buf);
    strftime(time_now, sizeof(time_now), "%Y-%m-%d %H:%M:%S", tmp); // example: 2023-06-19 14:30:45
    snprintf(time_now + strlen(time_now), sizeof(time_now) - strlen(time_now), ".%06ld", ts.tv_nsec / 1000); // example: 2023-06-19 14:30:45.123456

src/ut_log.c:128

• clock_gettime(CLOCK_REALTIME, ...) return value is ignored. On failure, ts may contain uninitialized data, and subsequent localtime_r/formatting can crash or log garbage. Add a fallback when clock_gettime fails.

    clock_gettime(CLOCK_REALTIME, &ts);

src/ut_log.c:146

• localtime_r()/strftime() results are not checked before using strlen(time_now) and appending subseconds. If localtime_r returns NULL or strftime returns 0, this can result in undefined behavior or a crash. Guard the formatting and ensure time_now is always NUL-terminated before appending.

    tmp = localtime_r(&ts.tv_sec, &tm_buf);
    strftime(time_now, sizeof(time_now), "%Y-%m-%d %H:%M:%S", tmp); // example: 2023-06-19 14:30:45
    snprintf(time_now + strlen(time_now), sizeof(time_now) - strlen(time_now), ".%06ld", ts.tv_nsec / 1000); // example: 2023-06-19 14:30:45.123456

src/ut_log.c:49

• localtime_r()/strftime() results are not checked. If localtime_r returns NULL (or strftime returns 0), this will pass an invalid tm pointer to strftime or leave time_now in an unspecified state, which can lead to crashes or malformed filenames.

This issue also appears in the following locations of the same file:

• line 95
• line 144

    time(&now);
    tmp = localtime_r(&now, &tm_buf);
    strftime(time_now, sizeof(time_now), "%F_%H%M%S", tmp);

src/ut_log.c:97

• Sub-second timestamp formatting is newly introduced here, but there is no automated test asserting the log prefix contains "." followed by exactly 6 digits (and that the overall timestamp remains stable). Adding a small unit/integration test would prevent regressions in log parsing/format expectations.

    strftime(time_now, sizeof(time_now), "%Y-%m-%d %H:%M:%S", tmp); // example: 2023-06-19 14:30:45
    snprintf(time_now + strlen(time_now), sizeof(time_now) - strlen(time_now), ".%06ld", ts.tv_nsec / 1000); // example: 2023-06-19 14:30:45.123456