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,71 @@
+#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;
+}