Fix {tid} incorrectly outputting TID of thread pool in AsyncPoolSink

Author: SpriteOvO

clippy.toml

@@ -0,0 +1,2 @@
+# TODO: Remove this in the next minor version (After `RecordOwned` is boxed in `SendToChannelErrorDropped`)
+large-error-threshold = 136

spdlog/src/error.rs

@@ -174,6 +174,7 @@ pub enum SendToChannelError {
 #[non_exhaustive]
 pub enum SendToChannelErrorDropped {
     /// A `log` operation and a record are dropped.
+    // TODO: Box the `RecordOwned` in the next minor version, as it's a bit large.
     Record(RecordOwned),
     /// A `flush` operation is dropped.
     Flush,

spdlog/src/formatter/pattern_formatter/pattern/process_id.rs

@@ -30,6 +30,9 @@ impl Pattern for ProcessId {
     }
 }
 
+// TODO: We can cache the PID someway to improve the performance, but remember
+// to test the case of process forking.
+
 #[cfg(target_family = "unix")]
 #[must_use]
 fn get_current_process_id() -> u64 {

spdlog/src/formatter/pattern_formatter/pattern/thread_id.rs

@@ -23,32 +23,10 @@ pub struct ThreadId;
 impl Pattern for ThreadId {
     fn format(
         &self,
-        _record: &Record,
+        record: &Record,
         dest: &mut StringBuf,
         _ctx: &mut PatternContext,
     ) -> crate::Result<()> {
-        let tid = get_current_thread_id();
-        write!(dest, "{}", tid).map_err(Error::FormatRecord)
+        write!(dest, "{}", record.tid()).map_err(Error::FormatRecord)
     }
 }
-
-#[cfg(target_os = "linux")]
-#[must_use]
-fn get_current_thread_id() -> u64 {
-    let tid = unsafe { libc::gettid() };
-    tid as u64
-}
-
-#[cfg(target_os = "macos")]
-#[must_use]
-fn get_current_thread_id() -> u64 {
-    let tid = unsafe { libc::pthread_self() };
-    tid as u64
-}
-
-#[cfg(target_os = "windows")]
-#[must_use]
-fn get_current_thread_id() -> u64 {
-    let tid = unsafe { winapi::um::processthreadsapi::GetCurrentThreadId() };
-    tid as u64
-}

spdlog/src/record.rs

@@ -2,6 +2,7 @@
 
 use std::{
     borrow::{Borrow, Cow},
+    cell::RefCell,
     time::SystemTime,
 };
 
@@ -33,6 +34,7 @@ struct RecordInner {
     level: Level,
     source_location: Option<SourceLocation>,
     time: SystemTime,
+    tid: u64,
 }
 
 impl<'a> Record<'a> {
@@ -51,6 +53,7 @@ impl<'a> Record<'a> {
                 level,
                 source_location: None,
                 time: SystemTime::now(),
+                tid: get_current_tid(),
             }),
         }
     }
@@ -106,6 +109,13 @@ impl<'a> Record<'a> {
         self.inner.time
     }
 
+    /// Gets the TID when the record was created.
+    // TODO: Public this new method to users in the next minor version
+    #[must_use]
+    pub(crate) fn tid(&self) -> u64 {
+        self.inner.tid
+    }
+
     // When adding more getters, also add to `RecordOwned`
 
     #[cfg(feature = "log")]
@@ -127,6 +137,9 @@ impl<'a> Record<'a> {
                 level: record.level().into(),
                 source_location: SourceLocation::from_log_crate_record(record),
                 time,
+                // For records from `log` crate, they never seem to come from different threads, so
+                // getting the current TID here should be correct
+                tid: get_current_tid(),
             }),
         }
     }
@@ -243,3 +256,32 @@ impl<'a> RecordBuilder<'a> {
         self.record
     }
 }
+
+fn get_current_tid() -> u64 {
+    #[cfg(target_os = "linux")]
+    #[must_use]
+    fn get_current_tid_inner() -> u64 {
+        let tid = unsafe { libc::gettid() };
+        tid as u64
+    }
+
+    #[cfg(target_os = "macos")]
+    #[must_use]
+    fn get_current_tid_inner() -> u64 {
+        let tid = unsafe { libc::pthread_self() };
+        tid as u64
+    }
+
+    #[cfg(target_os = "windows")]
+    #[must_use]
+    fn get_current_tid_inner() -> u64 {
+        let tid = unsafe { winapi::um::processthreadsapi::GetCurrentThreadId() };
+        tid as u64
+    }
+
+    thread_local! {
+        static TID: RefCell<Option<u64>> = RefCell::new(None);
+    }
+
+    TID.with(|tid| *tid.borrow_mut().get_or_insert_with(get_current_tid_inner))
+}

spdlog/tests/pattern.rs

@@ -430,3 +430,40 @@ fn test_builtin_patterns() {
     check(pattern!("{tid}"), None as Option<&str>, vec![OS_ID_RANGE]);
     check(pattern!("{eol}"), Some("{eol}"), vec![]);
 }
+
+#[cfg(feature = "multi-thread")]
+#[test]
+fn test_different_context_thread() {
+    use std::time::Duration;
+
+    use spdlog::{sink::AsyncPoolSink, ThreadPool};
+
+    let formatter = Box::new(PatternFormatter::new(pattern!("{tid}{eol}")));
+    let thread_pool = Arc::new(ThreadPool::builder().build().unwrap());
+    let buffer_sink = Arc::new(
+        WriteSink::builder()
+            .formatter(formatter)
+            .target(Vec::new())
+            .build()
+            .unwrap(),
+    );
+    let sinks: [Arc<dyn Sink>; 2] = [
+        buffer_sink.clone(),
+        Arc::new(
+            AsyncPoolSink::builder()
+                .sink(buffer_sink.clone())
+                .thread_pool(thread_pool)
+                .build()
+                .unwrap(),
+        ),
+    ];
+    let logger = Arc::new(Logger::builder().sinks(sinks).build().unwrap());
+
+    info!(logger: logger, "");
+    std::thread::sleep(Duration::from_millis(200));
+
+    let buffer = String::from_utf8(buffer_sink.clone_target()).unwrap();
+    let buffer = buffer.lines().collect::<Vec<_>>();
+    assert_eq!(buffer.len(), 2);
+    buffer.windows(2).for_each(|w| assert_eq!(w[0], w[1]))
+}