Timestamped logging macro for elapsed physical time

logging/api/logging_macros.h

@@ -12,6 +12,8 @@
 #define LOGGING_MACROS_H
 #include "logging.h"
 #include <stdbool.h>
+#include "tag.h"
+#include "low_level_platform.h"
 
 /** Default log level. */
 #ifndef LOG_LEVEL
@@ -72,7 +74,7 @@ static const bool _lf_log_level_is_debug = LOG_LEVEL >= LOG_LEVEL_DEBUG;
 #define LF_PRINT_DEBUG(format, ...)                                                                                    \
   do {                                                                                                                 \
     if (_lf_log_level_is_debug) {                                                                                      \
-      lf_print_debug(format, ##__VA_ARGS__);                                                                           \
+      lf_print_debug("["PRINTF_TIME"]"format,lf_time_physical_elapsed(), ##__VA_ARGS__);                               \
     }                                                                                                                  \
   } while (0)
 

test/general/logging_test.c

@@ -0,0 +1,75 @@
+#include "logging_macros.h"
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <assert.h>
+#include <unistd.h>
+#include <regex.h>
+
+#define TIMEED_DEBUG_CHAR_LEN   30
+#define SOME_EXTRA_SPACE        10
+/**
+* @brief unit for LF_PRINT_DEBUG macro
+* must be in LOG_LEVEL LOG_LEVEL_DEBUG
+*/
+void test_logging_macro(const char *expected, int st_len) {
+
+    FILE *tmp = tmpfile();  // auto-deletes when closed
+    char* buffer;
+    char pattern[256];
+    regex_t re;
+    int result;
+
+    // strlen("DEBUG: ") + null character + new line character + some extra space
+    int buffer_size = st_len + TIMEED_DEBUG_CHAR_LEN + SOME_EXTRA_SPACE;
+
+    if (!tmp) {
+        perror("tmpfile");
+        exit(1);
+    }
+
+    // Redirect stdout -> tmp
+    fflush(stdout);
+    int fd = fileno(tmp);
+    if (fd == -1 || dup2(fd, STDOUT_FILENO) == -1) {
+        perror("redirect stdout");
+        exit(1);
+    }
+
+    // Call code under test
+    LF_PRINT_DEBUG("%s",expected);
+
+    fflush(stdout);   // flush so data goes into tmp
+    rewind(tmp);      // reset read position
+
+    // Read back
+    buffer = (char*) malloc(buffer_size);
+    size_t n = fread(buffer, 1, buffer_size -1, tmp);
+    buffer[n] = '\0';
+
+    // Regex to check format: DEBUG: [number]expected\n
+    snprintf(pattern, sizeof(pattern),
+            "^DEBUG: \\[-?[0-9]+\\]%s\\n?$", expected);
+
+    if (regcomp(&re, pattern, REG_EXTENDED | REG_NEWLINE) != 0) {
+        perror("regcomp");
+        exit(1);
+    }
+
+    result = regexec(&re, buffer, 0, NULL, 0);
+    regfree(&re);
+
+    assert(result == 0); // match succeeded
+
+    fclose(tmp); // deletes the file
+    free(buffer);
+}
+
+int main()
+{
+    char* str_test = "Hello World";
+    test_logging_macro(str_test, strlen(str_test));
+    return 0;
+}
+
+