add logging mechanism

fixes: #247

Signed-off-by: Łukasz Plewa <lukasz.plewa@intel.com>

Author: lplewa

scripts/docs_config/introduction.rst

@@ -95,6 +95,45 @@ the `allocation API`_ as a first argument. There is also a possibility to
 retrieve a memory pool from an existing memory pointer that points to a memory 
 previously allocated by UMF.
 
+Logging
+---------------------
+
+Logging in UMF is handled by logger. There are several levels of logging: *debug*, *info*, *warning*, and *error*.
+The level of logging determines what messages will be printed, ie. the level set to *warning* means all messages at levels *warning* and *error* will be printed.
+
+By default, there is a guarantee that *error* messages are flushed immediately. One can change this behavior to flush on lower-level messages.
+
+Loggers redirect messages to *stdout*, *stderr*, or a file
+
+By default, no messages are printed. To enable logger you have to set **UMF_LOG** environment variable which have following syntax for setting logger options:
+
+  "[level:debug|info|warning|error];[flush:debug|info|warning|error];[output:stdout|stderr|file,<path>];[timestamp:yes|no];[pid:yes|no]"
+
+  * level - a log level, meaning that only messages from this level and above are printed.
+            Possible values, from the lowest level to the highest one: *debug*, *info*, *warning*, *error*,
+  * flush - a flush level, meaning that messages at this level and above are guaranteed to be flushed immediately,
+            possible values are the same as above,
+  * output - indicates where messages should be printed.
+             Possible values are: *stdout*, *stderr* and *file*,
+             when providing a *file* output option, a *<path>* is required
+  * timestamp - add a timestamp to log message
+  * pid - add thread and process ids to log message
+
+  .. note::
+    For output to file, a path to the file has to be provided after a comma, like in the example above. The path has to exist, file will be created if not existing. Path to the file should be no longer than 255 characters long.
+    The output parameter is required, all other logger options are optional. The defaults are set when options are not provided in the environment variable.
+    Options have to be separated with `;`, option names and their values with `:`. Additionally, when providing *file* output, the keyword *file* and a path to a file
+    have to be separated by `'`.
+
+An example of an environment variable for setting up logger with logging level set to *info*, flush level set to *warning*, and output set to
+the ``out.log`` file::
+
+  UMF_LOG="level:info;flush:warning;output:file,out.log"
+
+An example of an environment variable for setting up logger with logging level set to *warning* and output set to stdout::
+
+  UMF_LOGL="level:warning;output:stdout"
+
 .. _UMF: https://github.com/oneapi-src/unified-memory-framework
 .. _README.md: https://github.com/oneapi-src/unified-memory-framework/blob/main/README.md
 .. _allocation API: https://oneapi-src.github.io/unified-memory-framework/api.html#memory-pool

src/libumf_linux.c

@@ -12,10 +12,12 @@
 #include "base_alloc_global.h"
 #include "memspace_host_all_internal.h"
 #include "provider_tracking.h"
+#include "utils_log.h"
 
 umf_memory_tracker_handle_t TRACKER = NULL;
 
 void __attribute__((constructor)) umfCreate(void) {
+    util_log_init();
     TRACKER = umfMemoryTrackerCreate();
 }
 

src/libumf_windows.c

@@ -12,10 +12,14 @@
 
 #include "base_alloc_global.h"
 #include "provider_tracking.h"
+#include "utils_log.h"
 
 umf_memory_tracker_handle_t TRACKER = NULL;
 
-static void umfCreate(void) { TRACKER = umfMemoryTrackerCreate(); }
+static void umfCreate(void) {
+    util_log_init();
+    TRACKER = umfMemoryTrackerCreate();
+}
 
 static void umfDestroy(void) {
     umfMemoryTrackerDestroy(TRACKER);

src/utils/CMakeLists.txt

@@ -1,4 +1,4 @@
-# Copyright (C) 2023 Intel Corporation
+# Copyright (C) 2023-2024 Intel Corporation
 # Under the Apache License v2.0 with LLVM Exceptions. See LICENSE.TXT.
 # SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 
@@ -7,6 +7,7 @@ include(FindThreads)
 
 set(UMF_UTILS_SOURCES_COMMON
     utils_common.c
+    utils_log.c
 )
 
 set(UMF_UTILS_SOURCES_POSIX

src/utils/utils_common.c

@@ -7,8 +7,10 @@
  *
  */
 
-#include "utils_common.h"
+#include <string.h>
+
 #include "utils_assert.h"
+#include "utils_common.h"
 
 // align a pointer and a size
 void util_align_ptr_size(void **ptr, size_t *size, size_t alignment) {
@@ -33,3 +35,34 @@ void util_align_ptr_size(void **ptr, size_t *size, size_t alignment) {
 int util_is_running_in_proxy_lib(void) {
     return util_env_var_has_str("LD_PRELOAD", "libumf_proxy.so");
 }
+
+const char *util_parse_var(const char *var, const char *option,
+                           const char **extraArg) {
+    const char *found = strstr(var, option);
+    // ensure that found string is first on list or it's a separating semicolon
+    if (!found) {
+        return NULL;
+    }
+    // if found string is not at the beginning of var ensure it's preceded by ';'
+    if (found != var && *(found - 1) != ';') {
+        return NULL;
+    }
+
+    const char *endFound = found + strlen(option);
+    if (!extraArg) {
+        // if there is no argument, matched string should end with ';' or '\0'
+        if (*endFound != '\0' && *endFound != ';') {
+            return NULL;
+        }
+        return found;
+    }
+
+    // check if matched string ends with ','
+    if (*endFound != ',') {
+        return NULL;
+    }
+
+    *extraArg = endFound + 1;
+
+    return found;
+}

src/utils/utils_common.h

@@ -43,7 +43,7 @@ extern "C" {
 
 #endif /* _WIN32 */
 
-// util_env_var - populate the given buffer with the value
+// utils_env_var - populate the given buffer with the value
 //                of the given environment variable
 // Return value
 // If the function succeeds, the return value is the number of characters
@@ -61,6 +61,23 @@ int util_env_var(const char *envvar, char *buffer, size_t buffer_size);
 // Check if the environment variable contains the given string.
 int util_env_var_has_str(const char *envvar, const char *str);
 
+// util_parse_var - Parses var for a prefix,
+//                   optionally identifying a following argument.
+// Parameters:
+//   - var: String to parse  in "option1;option2,arg2;..." format, with options
+//          separated by ';' and optional arguments by ','.
+//   - option: Option to search for within var.
+//   - extraArg: If not NULL, function expects an argument after the option and
+//               updates this pointer to the argument's position within var.
+//               If NULL, function expects option without an argument.
+// Return Value:
+// Pointer to option within var if found; NULL otherwise.
+//
+// IMPORTANT: Both extraArg and return values are pointers within var,
+// and are not null-terminated.
+const char *util_parse_var(const char *var, const char *option,
+                           const char **extraArg);
+
 // check if we are running in the proxy library
 int util_is_running_in_proxy_lib(void);
 

src/utils/utils_log.c

@@ -0,0 +1,221 @@
+/*
+ *
+ * Copyright (C) 2024 Intel Corporation
+ *
+ * Under the Apache License v2.0 with LLVM Exceptions. See LICENSE.TXT.
+ * SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+ *
+ */
+
+#ifdef _WIN32
+#include <windows.h>
+#else
+#define _GNU_SOURCE 1
+#include <sys/syscall.h>
+#include <sys/types.h>
+#include <unistd.h>
+#endif
+
+#ifdef __APPLE__
+#include <pthread.h>
+#endif
+
+#include <stdarg.h>
+#include <stdio.h>
+#include <string.h>
+#include <time.h>
+
+#include "utils_assert.h"
+#include "utils_common.h"
+#include "utils_log.h"
+
+#define LOG_MAX 8192
+#define LOG_HEADER 256
+#define MAX_FILE_PATH 256
+#define MAX_ENV_LEN 2048
+
+typedef struct {
+    int timestamp;
+    int pid;
+    util_log_level_t level;
+    util_log_level_t flushLevel;
+    FILE *output;
+} util_log_config_t;
+
+util_log_config_t loggerConfig = {0, 0, LOG_ERROR, LOG_ERROR, NULL};
+
+static const char *level_to_str(util_log_level_t l) {
+    switch (l) {
+    case LOG_DEBUG:
+        return "DEBUG";
+    case LOG_ERROR:
+        return "ERROR";
+    case LOG_INFO:
+        return "INFO";
+    case LOG_WARNING:
+        return "WARN";
+    default:
+        ASSERT(0);
+        return "";
+    }
+}
+
+void util_log(util_log_level_t level, const char *format, ...) {
+    if (!loggerConfig.output) {
+        return; //logger not enabled
+    }
+    if (level < loggerConfig.level) {
+        return;
+    }
+
+#if defined(_WIN32)
+    DWORD pid = GetCurrentProcessId();
+    DWORD tid = GetCurrentThreadId();
+#elif defined(__APPLE__)
+    pid_t pid = getpid();
+    uint64_t tid64;
+    pthread_threadid_np(NULL, &tid64);
+    pid_t tid = (pid_t)tid64;
+#else
+    pid_t pid = getpid();
+    pid_t tid = gettid();
+#endif
+
+    char buffer[LOG_MAX];
+    va_list args;
+    va_start(args, format);
+    int ret = vsnprintf(buffer, sizeof(buffer), format, args);
+    const char *overflow = "";
+    if (ret >= (intptr_t)sizeof(buffer)) {
+        //TODO: alloc bigger buffer with base alloc
+        overflow = "[truncated...]";
+    }
+    va_end(args);
+    char header[LOG_HEADER];
+    char *h_pos = header;
+    memset(header, 0, sizeof(header));
+
+    if (loggerConfig.timestamp) {
+        time_t now = time(NULL);
+        struct tm tm_info;
+#ifdef _WIN32
+        localtime_s(&tm_info, &now);
+#else
+        localtime_r(&now, &tm_info);
+#endif
+
+        ASSERT((intptr_t)sizeof(header) > (h_pos - header));
+        h_pos += strftime(h_pos, sizeof(header) - (h_pos - header),
+                          "%Y-%m-%dT%H:%M:%S ", &tm_info);
+    }
+
+    if (loggerConfig.pid) {
+        ASSERT((intptr_t)sizeof(header) > (h_pos - header));
+        h_pos += snprintf(h_pos, sizeof(header) - (h_pos - header),
+                          "PID:%-6lu TID:%-6lu ", (unsigned long)pid,
+                          (unsigned long)tid);
+    }
+
+    // We take twice header size here to ensure that
+    // we have space for log level and overflow string
+    // otherwise -Wformat-truncation might be thrown by compiler
+    char logLine[LOG_MAX + LOG_HEADER * 2];
+    snprintf(logLine, sizeof(logLine), "[%s%-5s UMF] %s%s\n", header,
+             level_to_str(level), buffer, overflow);
+
+    fputs(logLine, loggerConfig.output);
+
+    if (level >= loggerConfig.flushLevel) {
+        fflush(loggerConfig.output);
+    }
+}
+
+static const char *bool_to_str(int b) { return b ? "yes" : "no"; }
+
+void util_log_init(void) {
+    char envVar[MAX_ENV_LEN];
+
+    if (util_env_var("UMF_LOG", envVar, sizeof(envVar)) <= 0) {
+        return;
+    }
+
+    const char *arg;
+    if (util_parse_var(envVar, "output:stdout", NULL)) {
+        loggerConfig.output = stdout;
+    } else if (util_parse_var(envVar, "output:stderr", NULL)) {
+        loggerConfig.output = stderr;
+    } else if (util_parse_var(envVar, "output:file", &arg)) {
+        loggerConfig.output = NULL;
+        const char *argEnd = strstr(arg, ";");
+        char file[MAX_FILE_PATH + 1];
+        size_t len = 0;
+
+        if (argEnd) {
+            len = argEnd - arg;
+        } else {
+            len = strlen(arg);
+        }
+
+        if (len <= MAX_FILE_PATH) {
+            memcpy(file, arg, len);
+            file[len] = '\0';
+#ifdef _WIN32
+            if (fopen_s(&loggerConfig.output, file, "w")) {
+                loggerConfig.output = NULL;
+            }
+#else
+            loggerConfig.output = fopen(file, "w");
+#endif
+        }
+        if (!loggerConfig.output) {
+            loggerConfig.output = stderr;
+            LOG_ERR("Cannot open output file %s - logging disabled", file);
+            loggerConfig.output = NULL;
+            return;
+        }
+    }
+
+    else {
+        loggerConfig.output = stderr;
+        LOG_ERR("Logging output not set - logging disabled");
+        loggerConfig.output = NULL;
+        return;
+    }
+
+    if (util_parse_var(envVar, "timestamp:yes", NULL)) {
+        loggerConfig.timestamp = 1;
+    } else if (util_parse_var(envVar, "timestamp:no", NULL)) {
+        loggerConfig.timestamp = 0;
+    }
+
+    if (util_parse_var(envVar, "pid:yes", NULL)) {
+        loggerConfig.pid = 1;
+    } else if (util_parse_var(envVar, "pid:no", NULL)) {
+        loggerConfig.pid = 0;
+    }
+
+    if (util_parse_var(envVar, "level:debug", NULL)) {
+        loggerConfig.level = LOG_DEBUG;
+    } else if (util_parse_var(envVar, "level:info", NULL)) {
+        loggerConfig.level = LOG_INFO;
+    } else if (util_parse_var(envVar, "level:warning", NULL)) {
+        loggerConfig.level = LOG_WARNING;
+    } else if (util_parse_var(envVar, "level:error", NULL)) {
+        loggerConfig.level = LOG_ERROR;
+    }
+
+    if (util_parse_var(envVar, "flush:debug", NULL)) {
+        loggerConfig.flushLevel = LOG_DEBUG;
+    } else if (util_parse_var(envVar, "flush:info", NULL)) {
+        loggerConfig.flushLevel = LOG_INFO;
+    } else if (util_parse_var(envVar, "flush:warning", NULL)) {
+        loggerConfig.flushLevel = LOG_WARNING;
+    } else if (util_parse_var(envVar, "flush:error", NULL)) {
+        loggerConfig.flushLevel = LOG_ERROR;
+    }
+
+    LOG_INFO(
+        "Logger enabled (level: %s, flush: %s, pid: %s, timestamp: %s)",
+        level_to_str(loggerConfig.level), level_to_str(loggerConfig.flushLevel),
+        bool_to_str(loggerConfig.pid), bool_to_str(loggerConfig.timestamp));
+}