Merge pull request #146 from divergentdave/thread-local-fallback

Thread local fallback

Author: KodrAus

Cargo.toml

@@ -34,6 +34,10 @@ harness = false
 name = "log-in-log"
 harness = false
 
+[[test]]
+name = "log_tls_dtors"
+harness = false
+
 [[test]]
 name = "init-twice-retains-filter"
 harness = false

src/lib.rs

@@ -807,41 +807,49 @@ impl Log for Logger {
                 static FORMATTER: RefCell<Option<Formatter>> = RefCell::new(None);
             }
 
-            FORMATTER.with(|tl_buf| {
-                // It's possible for implementations to sometimes
-                // log-while-logging (e.g. a `std::fmt` implementation logs
-                // internally) but it's super rare. If this happens make sure we
-                // at least don't panic and ship some output to the screen.
-                let mut a;
-                let mut b = None;
-                let tl_buf = match tl_buf.try_borrow_mut() {
-                    Ok(f) => {
-                        a = f;
-                        &mut *a
-                    }
-                    Err(_) => &mut b,
-                };
-
-                // Check the buffer style. If it's different from the logger's
-                // style then drop the buffer and recreate it.
-                match *tl_buf {
-                    Some(ref mut formatter) => {
-                        if formatter.write_style() != self.writer.write_style() {
-                            *formatter = Formatter::new(&self.writer)
-                        }
-                    }
-                    ref mut tl_buf => *tl_buf = Some(Formatter::new(&self.writer)),
-                }
-
-                // The format is guaranteed to be `Some` by this point
-                let mut formatter = tl_buf.as_mut().unwrap();
-
-                let _ = (self.format)(&mut formatter, record)
+            let print = |formatter: &mut Formatter, record: &Record| {
+                let _ = (self.format)(formatter, record)
                     .and_then(|_| formatter.print(&self.writer));
 
                 // Always clear the buffer afterwards
                 formatter.clear();
-            });
+            };
+
+            let printed = FORMATTER.try_with(|tl_buf| {
+                match tl_buf.try_borrow_mut() {
+                    // There are no active borrows of the buffer
+                    Ok(mut tl_buf) => match *tl_buf {
+                        // We have a previously set formatter
+                        Some(ref mut formatter) => {
+                            // Check the buffer style. If it's different from the logger's
+                            // style then drop the buffer and recreate it.
+                            if formatter.write_style() != self.writer.write_style() {
+                                *formatter = Formatter::new(&self.writer);
+                            }
+
+                            print(formatter, record);
+                        }
+                        // We don't have a previously set formatter
+                        None => {
+                            let mut formatter = Formatter::new(&self.writer);
+                            print(&mut formatter, record);
+
+                            *tl_buf = Some(formatter);
+                        }
+                    }
+                    // There's already an active borrow of the buffer (due to re-entrancy)
+                    Err(_) => {
+                        print(&mut Formatter::new(&self.writer), record);
+                    }
+                }
+            }).is_ok();
+
+            if !printed {
+                // The thread-local storage was not available (because its
+                // destructor has already run). Create a new single-use
+                // Formatter on the stack for this call.
+                print(&mut Formatter::new(&self.writer), record);
+            }
         }
     }
 

tests/log_tls_dtors.rs

@@ -0,0 +1,66 @@
+#[macro_use]
+extern crate log;
+extern crate env_logger;
+
+use std::env;
+use std::process;
+use std::str;
+use std::thread;
+
+struct DropMe;
+
+impl Drop for DropMe {
+    fn drop(&mut self) {
+        debug!("Dropping now");
+    }
+}
+
+fn run() {
+    // Use multiple thread local values to increase the chance that our TLS
+    // value will get destroyed after the FORMATTER key in the library
+    thread_local! {
+        static DROP_ME_0: DropMe = DropMe;
+        static DROP_ME_1: DropMe = DropMe;
+        static DROP_ME_2: DropMe = DropMe;
+        static DROP_ME_3: DropMe = DropMe;
+        static DROP_ME_4: DropMe = DropMe;
+        static DROP_ME_5: DropMe = DropMe;
+        static DROP_ME_6: DropMe = DropMe;
+        static DROP_ME_7: DropMe = DropMe;
+        static DROP_ME_8: DropMe = DropMe;
+        static DROP_ME_9: DropMe = DropMe;
+    }
+    DROP_ME_0.with(|_| {});
+    DROP_ME_1.with(|_| {});
+    DROP_ME_2.with(|_| {});
+    DROP_ME_3.with(|_| {});
+    DROP_ME_4.with(|_| {});
+    DROP_ME_5.with(|_| {});
+    DROP_ME_6.with(|_| {});
+    DROP_ME_7.with(|_| {});
+    DROP_ME_8.with(|_| {});
+    DROP_ME_9.with(|_| {});
+}
+
+fn main() {
+    env_logger::init();
+    if env::var("YOU_ARE_TESTING_NOW").is_ok() {
+        // Run on a separate thread because TLS values on the main thread
+        // won't have their destructors run if pthread is used.
+        // https://doc.rust-lang.org/std/thread/struct.LocalKey.html#platform-specific-behavior
+        thread::spawn(run).join().unwrap();
+    } else {
+        let exe = env::current_exe().unwrap();
+        let out = process::Command::new(exe)
+            .env("YOU_ARE_TESTING_NOW", "1")
+            .env("RUST_LOG", "debug")
+            .output()
+            .unwrap_or_else(|e| panic!("Unable to start child process: {}", e));
+        if !out.status.success() {
+            println!("test failed: {}", out.status);
+            println!("--- stdout\n{}", str::from_utf8(&out.stdout).unwrap());
+            println!("--- stderr\n{}", str::from_utf8(&out.stderr).unwrap());
+            process::exit(1);
+        }
+    }
+}