*: flush log before exit (tikv#3594)

Signed-off-by: Neil Shen <overvenus@gmail.com>

components/test_util/Cargo.toml

@@ -11,3 +11,4 @@ tikv = { path = "../../" }
 time = "0.1"
 rand = "0.3"
 slog = "2.3"
+slog-scope = "4.0"

components/test_util/lib.rs

@@ -14,6 +14,7 @@
 extern crate rand;
 #[macro_use]
 extern crate slog;
+extern crate slog_scope;
 extern crate time;
 
 extern crate tikv;
@@ -29,12 +30,17 @@ pub use logging::*;
 pub use security::*;
 
 pub fn setup_for_ci() {
-    if env::var("CI").is_ok() && env::var("LOG_FILE").is_ok() {
-        logging::init_log();
-    }
+    let guard = if env::var("CI").is_ok() && env::var("LOG_FILE").is_ok() {
+        Some(logging::init_log())
+    } else {
+        None
+    };
     if env::var("PANIC_ABORT").is_ok() {
         // Panics as aborts, it's helpful for debugging,
         // but also stops tests immediately.
-        tikv::util::panic_hook::set_exit_hook(true);
+        tikv::util::panic_hook::set_exit_hook(true, guard);
+    } else if let Some(guard) = guard {
+        // Do not reset the global logger.
+        guard.cancel_reset();
     }
 }

components/test_util/logging.rs

@@ -18,6 +18,7 @@ use std::io::prelude::*;
 use std::sync::Mutex;
 
 use slog::{self, Drain, OwnedKVList, Record};
+use slog_scope::GlobalLoggerGuard;
 use time;
 
 use tikv;
@@ -66,7 +67,7 @@ impl Drop for CaseTraceLogger {
 }
 
 // A help function to initial logger.
-pub fn init_log() {
+pub fn init_log() -> GlobalLoggerGuard {
     let output = env::var("LOG_FILE").ok();
     let level = tikv::util::logger::get_level_by_string(
         &env::var("LOG_LEVEL").unwrap_or_else(|_| "debug".to_owned()),
@@ -83,5 +84,5 @@ pub fn init_log() {
     //
     // let drain = slog_async::Async::new(drain).build().fuse();
     let logger = slog::Logger::root_typed(drain, slog_o!());
-    let _ = tikv::util::logger::init_log_for_tikv_only(logger, level);
+    tikv::util::logger::init_log_for_tikv_only(logger, level).unwrap()
 }

src/bin/tikv-importer.rs

@@ -36,6 +36,7 @@ extern crate slog_async;
 extern crate slog_scope;
 extern crate slog_stdlog;
 extern crate slog_term;
+#[macro_use]
 extern crate tikv;
 extern crate toml;
 
@@ -100,11 +101,11 @@ fn main() {
         .get_matches();
 
     let config = setup_config(&matches);
-    init_log(&config);
-    initial_metric(&config.metric, None);
+    let guard = init_log(&config);
+    panic_hook::set_exit_hook(false, Some(guard));
 
+    initial_metric(&config.metric, None);
     util::print_tikv_info();
-    panic_hook::set_exit_hook(false);
     check_environment_variables();
 
     run_import_server(&config);

src/bin/tikv-server.rs

@@ -36,6 +36,7 @@ extern crate slog_async;
 extern crate slog_scope;
 extern crate slog_stdlog;
 extern crate slog_term;
+#[macro_use]
 extern crate tikv;
 extern crate toml;
 
@@ -378,13 +379,12 @@ fn main() {
     // Sets the global logger ASAP.
     // It is okay to use the config w/o `validata()`,
     // because `init_log()` handles various conditions.
-    init_log(&config);
+    let guard = init_log(&config);
+    panic_hook::set_exit_hook(false, Some(guard));
 
     // Print version information.
     util::print_tikv_info();
 
-    panic_hook::set_exit_hook(false);
-
     config.compatible_adjust();
     if let Err(e) = config.validate() {
         fatal!("invalid configuration: {:?}", e);

src/bin/util/setup.rs

@@ -11,16 +11,17 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-use slog::{Drain, Logger};
-use slog_async::{Async, OverflowStrategy};
-use slog_term::{PlainDecorator, TermDecorator};
 use std::env;
 use std::io::BufWriter;
 use std::process;
 use std::sync::atomic::{AtomicBool, Ordering, ATOMIC_BOOL_INIT};
 
 use chrono;
 use clap::ArgMatches;
+use slog::{Drain, Logger};
+use slog_async::{Async, OverflowStrategy};
+use slog_scope::GlobalLoggerGuard;
+use slog_term::{PlainDecorator, TermDecorator};
 
 use tikv::config::{MetricConfig, TiKvConfig};
 use tikv::util;
@@ -48,22 +49,23 @@ macro_rules! fatal {
     })
 }
 
-pub fn init_log(config: &TiKvConfig) {
+pub fn init_log(config: &TiKvConfig) -> GlobalLoggerGuard {
     let log_rotation_timespan = chrono::Duration::from_std(
         config.log_rotation_timespan.clone().into(),
     ).expect("config.log_rotation_timespan is an invalid duration.");
-    if config.log_file.is_empty() {
+    let guard = if config.log_file.is_empty() {
         let decorator = TermDecorator::new().build();
         let drain = logger::TikvFormat::new(decorator).fuse();
         let drain = Async::new(drain)
             .chan_size(SLOG_CHANNEL_SIZE)
             .overflow_strategy(SLOG_CHANNEL_OVERFLOW_STRATEGY)
+            .thread_name(thd_name!("term-slogger"))
             .build()
             .fuse();
         let logger = Logger::root_typed(drain, slog_o!());
         logger::init_log(logger, config.log_level).unwrap_or_else(|e| {
             fatal!("failed to initialize log: {:?}", e);
-        });
+        })
     } else {
         let logger = BufWriter::new(
             RotatingFileLogger::new(&config.log_file, log_rotation_timespan).unwrap_or_else(|e| {
@@ -76,13 +78,17 @@ pub fn init_log(config: &TiKvConfig) {
         );
         let decorator = PlainDecorator::new(logger);
         let drain = logger::TikvFormat::new(decorator).fuse();
-        let drain = Async::new(drain).build().fuse();
+        let drain = Async::new(drain)
+            .thread_name(thd_name!("file-slogger"))
+            .build()
+            .fuse();
         let logger = Logger::root_typed(drain, slog_o!());
         logger::init_log(logger, config.log_level).unwrap_or_else(|e| {
             fatal!("failed to initialize log: {:?}", e);
-        });
-    }
+        })
+    };
     LOG_INITIALIZED.store(true, Ordering::SeqCst);
+    guard
 }
 
 pub fn initial_metric(cfg: &MetricConfig, node_id: Option<u64>) {

src/util/logger.rs

@@ -21,7 +21,7 @@ use grpc;
 use log;
 use log::SetLoggerError;
 use slog::{self, Drain, Key, OwnedKVList, Record, KV};
-use slog_scope;
+use slog_scope::{self, GlobalLoggerGuard};
 use slog_stdlog;
 use slog_term::{Decorator, RecordDecorator};
 
@@ -37,7 +37,7 @@ const ENABLED_TARGETS: &[&str] = &[
     "raft::",
 ];
 
-pub fn init_log<D>(drain: D, level: Level) -> Result<(), SetLoggerError>
+pub fn init_log<D>(drain: D, level: Level) -> Result<GlobalLoggerGuard, SetLoggerError>
 where
     D: Drain + Send + Sync + 'static + RefUnwindSafe + UnwindSafe,
     <D as slog::Drain>::Err: ::std::fmt::Debug,
@@ -48,11 +48,15 @@ where
 
     let logger = slog::Logger::root(drain, slog_o!());
 
-    slog_scope::set_global_logger(logger).cancel_reset();
-    slog_stdlog::init_with_level(convert_slog_level_to_log_level(level))
+    let guard = slog_scope::set_global_logger(logger);
+    slog_stdlog::init_with_level(convert_slog_level_to_log_level(level))?;
+    Ok(guard)
 }
 
-pub fn init_log_for_tikv_only<D>(drain: D, level: Level) -> Result<(), SetLoggerError>
+pub fn init_log_for_tikv_only<D>(
+    drain: D,
+    level: Level,
+) -> Result<GlobalLoggerGuard, SetLoggerError>
 where
     D: Drain + Send + Sync + 'static + RefUnwindSafe + UnwindSafe,
     <D as slog::Drain>::Err: ::std::fmt::Debug,

src/util/panic_hook.rs

@@ -13,11 +13,12 @@
 
 use std::cell::RefCell;
 use std::panic::{self, PanicInfo};
-use std::sync::{Once, ONCE_INIT};
+use std::sync::{Mutex, Once, ONCE_INIT};
 use std::{process, thread};
 
 use backtrace::Backtrace;
 use log::LogLevel;
+use slog_scope::GlobalLoggerGuard;
 
 /// A simple panic hook that allows skiping printing stacktrace conditionaly.
 
@@ -63,7 +64,7 @@ fn track_hook(p: &PanicInfo) {
 }
 
 /// Exit the whole process when panic.
-pub fn set_exit_hook(panic_abort: bool) {
+pub fn set_exit_hook(panic_abort: bool, guard: Option<GlobalLoggerGuard>) {
     // HACK! New a backtrace ahead for caching necessary elf sections of this
     // tikv-server, in case it can not open more files during panicking
     // which leads to no stack info (0x5648bdfe4ff2 - <no info>).
@@ -79,6 +80,9 @@ pub fn set_exit_hook(panic_abort: bool) {
         .spawn(Backtrace::new)
         .unwrap();
 
+    // Hold the guard.
+    let log_guard = Mutex::new(guard);
+
     let orig_hook = panic::take_hook();
     panic::set_hook(box move |info: &PanicInfo| {
         if log_enabled!(LogLevel::Error) {
@@ -105,6 +109,10 @@ pub fn set_exit_hook(panic_abort: bool) {
         } else {
             orig_hook(info);
         }
+
+        // To collect remaining logs, drop the guard before exit.
+        drop(log_guard.lock().unwrap().take());
+
         if panic_abort {
             process::abort();
         } else {