(fix)logger use-after-free in ZeLogger during teardown (#483)

Replace the thread_local std::string line/tid buffers with POD
thread_local char buffers, so log calls that arrive during exit
teardown no longer write into freed memory.

Also add stand alone ASan regression test.

Signed-off-by: Russell McGuire <russell.w.mcguire@intel.com>

Author: rwmcguir

source/utils/ze_logger.cpp

@@ -12,6 +12,7 @@
 #include <cerrno>
 #include <chrono>
 #include <cstdio>
+#include <cstring>
 #include <ctime>
 #include <iomanip>
 #include <iostream>
@@ -156,10 +157,13 @@ struct LogSink {
           is_good(true)
     {}
 
-    void write(const std::string &line) {
+    // Raw (data,len) overload — lets callers emit a fixed char buffer without
+    // constructing an intermediate std::string (keeps the log hot path allocation-free).
+    void write(const char *data, std::size_t len) {
         std::lock_guard<std::mutex> lk(mtx);
         if (is_good) {
-            *stream << line << '\n';
+            stream->write(data, static_cast<std::streamsize>(len));
+            stream->put('\n');
             // stream->fail() is a single rdstate() bitmask read — negligible cost.
             // Once a failure is detected, is_good=false so all future calls return
             // immediately at the guard above, paying zero additional cost.
@@ -172,6 +176,8 @@ struct LogSink {
         }
     }
 
+    void write(const std::string &line) { write(line.data(), line.size()); }
+
     void flush() {
         std::lock_guard<std::mutex> lk(mtx);
         if (stream) {
@@ -235,10 +241,13 @@ void ZeLogger::flush() {
 //   %^%l%$                 — level label (with color when tty)
 //   %v                     — message
 //
-// formatLine writes into an existing string (passed by ref) to avoid
-// a return-by-value heap allocation on every log call.
+// formatLine writes into a caller-provided fixed char buffer (snprintf-style)
+// and returns the total length the line needs.  It keeps no owning static state
+// (POD thread_local buffers only), so it is allocation-free on the hot path and
+// safe to call during exit-time teardown.
 // ---------------------------------------------------------------------------
-void ZeLogger::formatLine(LogLevel msg_level, const std::string &msg, std::string &out) {
+std::size_t ZeLogger::formatLine(LogLevel msg_level, const std::string &msg,
+                                 char *out, std::size_t cap) {
     // Build timestamp: YYYY-MM-DD HH:MM:SS.mmm
     auto now   = std::chrono::system_clock::now();
     auto now_t = std::chrono::system_clock::to_time_t(now);
@@ -259,22 +268,50 @@ void ZeLogger::formatLine(LogLevel msg_level, const std::string &msg, std::strin
     std::snprintf(ts_full, sizeof(ts_full), "%s.%03lld", ts,
                   static_cast<long long>(ms.count()));
 
-    // Thread id — computed once per thread, stored in a thread_local local
-    // static inside this non-inline, non-template .cpp function.
-    // This produces STB_LOCAL linkage (not STB_GNU_UNIQUE), so dlclose() is unaffected.
-    static thread_local const std::string tid_str = [](){
+    // Thread id — computed once per thread into a POD thread_local char buffer.
+    // POD storage has a trivial destructor (nothing runs at thread/exit teardown),
+    // so it cannot become a use-after-free when logging happens during process exit;
+    // and as a function-local static in this non-inline, non-template .cpp function
+    // it has STB_LOCAL linkage (not STB_GNU_UNIQUE), so dlclose() is unaffected.
+    static thread_local char   tid_buf[32];
+    static thread_local std::size_t tid_len = 0;
+    if (tid_len == 0) {
         std::ostringstream ss;
         ss << std::this_thread::get_id();
-        return ss.str();
-    }();
+        const std::string s = ss.str();
+        tid_len = s.size() < sizeof(tid_buf) ? s.size() : sizeof(tid_buf);
+        std::memcpy(tid_buf, s.data(), tid_len);
+    }
+
+    char pid_buf[24];
+    int pid_written = std::snprintf(pid_buf, sizeof(pid_buf), "%lld",
+                                    static_cast<long long>(GET_PID()));
+    if (pid_written < 0) pid_written = 0;
+    const std::size_t pid_len =
+        static_cast<std::size_t>(pid_written) < sizeof(pid_buf)
+            ? static_cast<std::size_t>(pid_written)
+            : sizeof(pid_buf) - 1;
 
     const char *label = levelLabel(msg_level);
     const char *color = _sink->color_enabled ? levelColor(msg_level) : "";
     const char *reset = _sink->color_enabled ? AnsiColor::reset()     : "";
 
-    // Write directly into the caller-provided string — no extra allocation.
-    out.clear();
-    out.reserve(_pattern.size() + msg.size() + 64);
+    // Bounded append into the caller buffer. `len` always tracks the TOTAL bytes
+    // the full line needs (so the caller can detect overflow), but we never write
+    // past `cap`. No heap allocation on this path.
+    std::size_t len = 0;
+    auto put = [&](const char *s, std::size_t n) {
+        if (len < cap) {
+            std::size_t avail = cap - len;
+            std::memcpy(out + len, s, n < avail ? n : avail);
+        }
+        len += n;
+    };
+    auto put_cstr = [&](const char *s) { put(s, std::strlen(s)); };
+    auto put_ch   = [&](char c) {
+        if (len < cap) out[len] = c;
+        len += 1;
+    };
 
     bool color_span_open = false;
 
@@ -285,64 +322,77 @@ void ZeLogger::formatLine(LogLevel msg_level, const std::string &msg, std::strin
                 case 'Y': {
                     const char *seq = "%Y-%m-%d %H:%M:%S.%e";
                     if (_pattern.compare(i, 20, seq) == 0) {
-                        out += ts_full;
+                        put_cstr(ts_full);
                         i += 19;
                     } else {
-                        out += '%';
-                        out += tok;
+                        put_ch('%');
+                        put_ch(tok);
                         ++i;
                     }
                     break;
                 }
                 case 't':
-                    out += tid_str;
+                    put(tid_buf, tid_len);
                     ++i;
                     break;
                 case 'P':
-                    out += std::to_string(GET_PID());
+                    put(pid_buf, pid_len);
                     ++i;
                     break;
                 case '^':
-                    out += color;
+                    put_cstr(color);
                     color_span_open = true;
                     ++i;
                     break;
                 case 'l':
-                    out += label;
+                    put_cstr(label);
                     ++i;
                     break;
                 case '$':
-                    out += reset;
+                    put_cstr(reset);
                     color_span_open = false;
                     ++i;
                     break;
                 case 'v':
-                    out += msg;
+                    put(msg.data(), msg.size());
                     ++i;
                     break;
                 default:
-                    out += '%';
+                    put_ch('%');
                     break;
             }
         } else {
-            out += _pattern[i];
+            put_ch(_pattern[i]);
         }
     }
 
     if (color_span_open) {
-        out += reset;
+        put_cstr(reset);
     }
+
+    return len;
 }
 
 void ZeLogger::write(LogLevel msg_level, const std::string &msg) {
     if (!_sink || msg_level < _level) {
         return;
     }
-    // Reuse a thread_local buffer to avoid a heap allocation per log call.
+    // POD thread_local buffer — trivial destructor, freed with the thread, no heap
+    // leak. A log call can arrive during exit-time teardown (e.g. SYCL shutdown →
+    // validation-layer DDI → log) AFTER a non-trivial thread_local (std::string)
+    // would have been destroyed; a POD char buffer is safe to use at any time.
     // STB_LOCAL linkage (non-inline, non-template .cpp function) — safe for dlclose.
-    static thread_local std::string line_buf;
-    formatLine(msg_level, msg, line_buf);
-    _sink->write(line_buf);
+    static thread_local char line_buf[2048];
+    const std::size_t n = formatLine(msg_level, msg, line_buf, sizeof(line_buf));
+    if (n <= sizeof(line_buf)) {
+        _sink->write(line_buf, n);                 // hot path: zero allocation
+    } else {
+        // Rare oversized line: one allocation, same output (no truncation).
+        // Line length is deterministic for a given message, so a single retry fits.
+        std::string big(n, '\0');
+        const std::size_t n2 = formatLine(msg_level, msg, &big[0], big.size());
+        _sink->write(big.data(), n2 < big.size() ? n2 : big.size());
+    }
 }
 
 void ZeLogger::trace(const std::string &msg)    { write(LogLevel::trace,    msg); }

source/utils/ze_logger.h

@@ -89,7 +89,13 @@ class ZeLogger {
 
 private:
     void write(LogLevel msg_level, const std::string &msg);
-    void formatLine(LogLevel msg_level, const std::string &msg, std::string &out);
+    // Formats the log line into a caller-provided fixed buffer (snprintf-style).
+    // Returns the total number of bytes the full line needs; if that exceeds
+    // `cap` the buffer holds a truncated prefix and the caller must retry with a
+    // larger buffer. Uses no owning static state, so it is safe to call during
+    // exit-time teardown (no thread_local std::string to outlive its destructor).
+    std::size_t formatLine(LogLevel msg_level, const std::string &msg,
+                           char *out, std::size_t cap);
 
     LogLevel _level;
     std::string _pattern;

test/CMakeLists.txt

@@ -1159,3 +1159,21 @@ set_property(TEST test_validation_layer_api_tracing_immediate_cmdlist PROPERTY E
 
 add_test(NAME test_validation_layer_api_tracing_command_queue COMMAND tests --gtest_filter=ValidationLayerApiTracing.GivenValidationLayerEnabledWithTraceLevelLoggingWhenCallingCommandQueueApisThenTracingDoesNotCrash)
 set_property(TEST test_validation_layer_api_tracing_command_queue PROPERTY ENVIRONMENT "ZE_ENABLE_VALIDATION_LAYER=1;ZEL_ENABLE_LOADER_LOGGING=1;ZEL_LOADER_LOGGING_LEVEL=trace;ZE_ENABLE_NULL_DRIVER=1")
+
+# -----------------------------------------------------------------------------
+# Standalone unit test for the ZeLogger exit-time / teardown use-after-free fix.
+# Links ONLY level_zero_utils (no loader, drivers, or layers), so it is a true
+# unit test independent of the static/dynamic build model and of any hardware.
+# Built with -DUSE_ASAN=ON it is a deterministic regression detector for the
+# logger UAF; without ASan it still exercises the teardown-time logging path.
+# -----------------------------------------------------------------------------
+add_executable(ze_logger_teardown_unit_tests ze_logger_teardown_unit_tests.cpp)
+target_include_directories(ze_logger_teardown_unit_tests PRIVATE
+  ${PROJECT_SOURCE_DIR}/include
+  ${PROJECT_SOURCE_DIR}/source/inc
+)
+target_link_libraries(ze_logger_teardown_unit_tests PRIVATE GTest::gtest_main level_zero_utils)
+if(UNIX AND NOT APPLE)
+  target_link_libraries(ze_logger_teardown_unit_tests PRIVATE pthread)
+endif()
+add_test(NAME ze_logger_teardown_unit_tests COMMAND ze_logger_teardown_unit_tests)

test/ze_logger_teardown_unit_tests.cpp

@@ -0,0 +1,99 @@
+/*
+ *
+ * Copyright (C) 2026 Intel Corporation
+ *
+ * SPDX-License-Identifier: MIT
+ *
+ */
+
+// Standalone unit test for the exit-time / teardown use-after-free in
+// loader::ZeLogger.  It links ONLY level_zero_utils (the static library that
+// contains ze_logger.cpp) -- no loader, no drivers, no validation/tracing
+// layers, and none of the SYCL / Unified Runtime stack that originally
+// surfaced the bug.
+//
+// Background
+// ----------
+// The production crash was a heap-use-after-free: during process exit, a late
+// destructor (SYCL shutdown -> UR queue dtor -> zeCommandListHostSynchronize ->
+// validation layer) called into ZeLogger AFTER the logger's function-local
+// `thread_local std::string` line/tid buffers had already been destroyed by the
+// thread-local teardown phase.  formatLine() then wrote into the freed buffer.
+//
+// Reproducing it without SYCL/UR
+// ------------------------------
+// thread_local objects are destroyed in REVERSE order of initialization.  If we
+// declare a thread_local object whose destructor logs *before* the first real
+// log call on a worker thread, then on thread exit:
+//   1. ZeLogger's own thread_local buffers (initialized during the first log)
+//      are destroyed first, and
+//   2. our logging destructor runs last -- emitting a log line into buffers
+//      that teardown has already released.
+// With the buggy `thread_local std::string` implementation this is a
+// heap-use-after-free, caught deterministically when built with -DUSE_ASAN=ON.
+// With the POD `thread_local char[]` fix the buffers have trivial destructors
+// (their storage survives until the thread's TLS block is freed, after all
+// thread_local destructors have run), so the late log call is safe.
+
+#include "gtest/gtest.h"
+
+#include "ze_logger.h"
+
+#include <thread>
+
+namespace {
+
+// A thread_local object whose destructor logs through the shared logger.
+struct LogFromThreadLocalDtor {
+    loader::ZeLogger *logger;
+    ~LogFromThreadLocalDtor() {
+        // Runs during the worker thread's thread_local teardown, AFTER the
+        // logger's own thread_local line/tid buffers have been destroyed.
+        logger->trace("ZeLogger invoked from a thread_local destructor during teardown");
+    }
+};
+
+// Runs on a dedicated worker thread so that its thread_local destructors fire
+// deterministically at thread exit (i.e. at join()), independent of process
+// exit ordering.
+void workerLogsDuringTeardown(loader::ZeLogger *logger) {
+    // Initialized FIRST on this thread -> its destructor runs LAST (after the
+    // logger's own thread_local buffers, which are initialized by the warmup
+    // log call below).
+    thread_local LogFromThreadLocalDtor guard{logger};
+
+    // First real log call: initializes ZeLogger's thread_local line/tid buffers
+    // (registered SECOND -> destroyed FIRST).  Exercises every formatLine append
+    // path via the pattern set on the logger.
+    logger->trace("warmup: initialize the logger's thread_local buffers");
+
+    // Returning ends the thread: the line/tid buffers are torn down first, then
+    // `guard`'s destructor logs into them.
+}
+
+} // namespace
+
+// Sanity: the logger formats and writes without crashing on a live thread.
+TEST(ZeLoggerTeardown, BasicLogDoesNotCrash) {
+    loader::ZeLogger logger(/*use_stderr=*/true, loader::LogLevel::trace,
+                            "[%Y-%m-%d %H:%M:%S.%e] [tid:%t pid:%P] [%l] %v");
+    logger.trace("trace message");
+    logger.info("info message");
+    logger.warn("warn message");
+    SUCCEED();
+}
+
+// Regression guard for the exit-time logger UAF.  Builds with -DUSE_ASAN=ON turn
+// this into a deterministic detector: the buggy thread_local-std::string logger
+// aborts here with heap-use-after-free; the POD-buffer fix completes cleanly.
+TEST(ZeLoggerTeardown, LogFromThreadLocalDestructorAfterBufferTeardownIsSafe) {
+    loader::ZeLogger logger(/*use_stderr=*/true, loader::LogLevel::trace,
+                            "[%Y-%m-%d %H:%M:%S.%e] [tid:%t pid:%P] [%l] %v");
+
+    std::thread worker(workerLogsDuringTeardown, &logger);
+    worker.join(); // teardown-time logging happens here
+
+    // Reaching this point without an ASan abort or crash means logging during
+    // the thread_local destruction phase did not touch freed memory.
+    SUCCEED();
+}