diff options
| -rw-r--r-- | mullvad-daemon/src/logging.rs | 128 | ||||
| -rw-r--r-- | mullvad-daemon/src/main.rs | 32 | ||||
| -rw-r--r-- | mullvad-daemon/src/system_service.rs | 97 | ||||
| -rw-r--r-- | mullvad-jni/src/lib.rs | 10 |
4 files changed, 148 insertions, 119 deletions
diff --git a/mullvad-daemon/src/logging.rs b/mullvad-daemon/src/logging.rs index 80c0f6eafc..adf8757e56 100644 --- a/mullvad-daemon/src/logging.rs +++ b/mullvad-daemon/src/logging.rs @@ -2,10 +2,7 @@ use mullvad_logging::{EnvFilter, LevelFilter, silence_crates}; use std::{ io, path::PathBuf, - sync::{ - Arc, - atomic::{AtomicBool, Ordering}, - }, + sync::atomic::{AtomicBool, Ordering}, }; use talpid_core::logging::rotate_log; use tracing_appender::non_blocking; @@ -32,10 +29,66 @@ pub enum Error { } /// A [`MakeWriter`] that wraps an [`OptionalWriter`]. -struct OptionalMakeWriter<T>(Option<T>); +#[derive(Clone)] +pub struct LogFileWriter(Option<non_blocking::NonBlocking>); + +impl LogFileWriter { + /// Creates a [`MakeWriter`] that writes logs to the given file. + /// + /// If a valid path is passed, the logs are rotated and a writer for the + /// new file are returned. If `None` is passed, the writer will be a noop. + /// + /// The writer will flush remaining logs when the tokio runtime is shut down. + /// NOTE: calling e.g. `std::process::exit` will prevent flushing and might + /// result in lost logs. + /// + /// On Android, the logs will not flush automatically on shutdown, instead + /// one should call `LogFileWriter::get_flusher` to receive channel for + /// manually flushing. + fn new(log_location: Option<LogLocation>) -> Result<Self, Error> { + // Disable logging if log_location is None + let Some(log_location) = log_location else { + return Ok(Self(None)); + }; -impl<'a, T: Clone + io::Write> MakeWriter<'a> for OptionalMakeWriter<T> { - type Writer = OptionalWriter<T>; + // NOTE: Make sure to rotate log file *before* initializing any kind of logger. + rotate_log(&log_location.log_path()).map_err(Error::RotateLog)?; + let file_appender = + tracing_appender::rolling::never(&log_location.directory, &log_location.filename); + let (file_writer, guard) = non_blocking(file_appender); + + // When the guard is dropped, logs will no longer be written to the file, so we need to keep it + // alive until the program exits. + // On desktop, the Tokio runtime lives from the entire program, so we can keep the guard alive + // using a task. + // On Android, the runtime is not running at this point, and will be restarted multiple times + // during the application's lifecycle. Instead, we simply call `mem::forget` to never drop the guard. + // Instead, one should call `LogFileWriter::get_flusher`, to receive channel for manually flushing + if cfg!(target_os = "android") { + core::mem::forget(guard); + } else { + tokio::spawn(async { + std::future::pending::<()>().await; + drop(guard); + }); + } + Ok(Self(Some(file_writer))) + } + + /// Flush any buffered logs to file + #[cfg(target_os = "android")] + pub fn flush(&mut self) -> io::Result<()> { + use std::io::Write; + if let Some(writer) = &mut self.0 { + writer.flush() + } else { + Ok(()) + } + } +} + +impl<'a> MakeWriter<'a> for LogFileWriter { + type Writer = OptionalWriter<non_blocking::NonBlocking>; fn make_writer(&'a self) -> Self::Writer { match &self.0 { @@ -56,11 +109,34 @@ pub fn is_enabled() -> bool { LOG_ENABLED.load(Ordering::SeqCst) } +/// Handle to interact with the logs. Use it to change the log level at runtime or +/// to receive a stream of logs. #[derive(Clone)] pub struct LogHandle { env_filter: Handle<EnvFilter, Registry>, log_stream: LogStreamer, - _file_appender_guard: Option<Arc<non_blocking::WorkerGuard>>, + /// A copy of the logfile writer used to manual flushing of buffered logs + #[cfg(target_os = "android")] + pub logfile_writer: LogFileWriter, +} + +impl LogHandle { + /// Adjust the log level. + /// + /// - `level_filter`: A `RUST_LOG` string. See `env_logger` for more information: + /// https://docs.rs/env_logger/latest/env_logger/ + pub fn set_log_filter( + &self, + level_filter: impl AsRef<str>, + ) -> Result<(), tracing_subscriber::reload::Error> { + let new = silence_crates(EnvFilter::new(level_filter)); + self.env_filter.modify(|env_filter| *env_filter = new) + } + + /// Subscribe to new log events. + pub fn get_log_stream(&self) -> tokio::sync::broadcast::Receiver<String> { + self.log_stream.tx.subscribe() + } } /// A location to put logs. @@ -115,25 +191,6 @@ impl io::Write for LogStreamer { } } -impl LogHandle { - /// Adjust the log level. - /// - /// - `level_filter`: A `RUST_LOG` string. See `env_logger` for more information: - /// https://docs.rs/env_logger/latest/env_logger/ - pub fn set_log_filter( - &self, - level_filter: impl AsRef<str>, - ) -> Result<(), tracing_subscriber::reload::Error> { - let new = silence_crates(EnvFilter::new(level_filter)); - self.env_filter.modify(|env_filter| *env_filter = new) - } - - /// Subscribe to new log events. - pub fn get_log_stream(&self) -> tokio::sync::broadcast::Receiver<String> { - self.log_stream.tx.subscribe() - } -} - /// Initialize a global logger. /// /// * log_level: Base log level, used if `RUST_LOG` is not set. @@ -159,17 +216,7 @@ pub fn init_logger( let default_filter = silence_crates(env_filter); // TODO: Switch this to a rolling appender, likely daily or hourly - let (_file_appender_guard, non_blocking_file_appender) = - if let Some(log_location) = log_location.as_ref() { - // NOTE: Make sure to rotate log file *before* initializing any kind of logger. - rotate_log(&log_location.log_path()).map_err(Error::RotateLog)?; - let file_appender = - tracing_appender::rolling::never(&log_location.directory, &log_location.filename); - let (appender, guard) = non_blocking(file_appender); - (Some(Arc::new(guard)), OptionalMakeWriter(Some(appender))) - } else { - (None, OptionalMakeWriter(None)) - }; + let file_writer = LogFileWriter::new(log_location)?; let (tx, _) = tokio::sync::broadcast::channel(128); let log_stream = LogStreamer { tx }; @@ -178,7 +225,8 @@ pub fn init_logger( let reload_handle = LogHandle { env_filter: reload_handle, log_stream: log_stream.clone(), - _file_appender_guard, + #[cfg(target_os = "android")] + logfile_writer: file_writer.clone(), }; let reg = tracing_subscriber::registry().with(user_filter); @@ -199,7 +247,7 @@ pub fn init_logger( let file_formatter = tracing_subscriber::fmt::layer() .with_ansi(false) - .with_writer(non_blocking_file_appender); + .with_writer(file_writer); let reg = reg .with( diff --git a/mullvad-daemon/src/main.rs b/mullvad-daemon/src/main.rs index bbc99ca7ee..88079f48aa 100644 --- a/mullvad-daemon/src/main.rs +++ b/mullvad-daemon/src/main.rs @@ -35,7 +35,8 @@ fn main() { } }; - log::debug!("Process exiting with code {}", exit_code); + log::debug!("Process exiting with code {exit_code}"); + runtime.shutdown_timeout(Duration::from_millis(100)); std::process::exit(exit_code); } @@ -57,14 +58,14 @@ async fn run() -> Result<(), String> { match config.command { cli::Command::Daemon => { - // uniqueness check must happen before logging initializaton, + // uniqueness check must happen before logging initialization, // as initializing logs will rotate any existing log file. assert_unique().await?; - let (log_location, reload_handle) = init_daemon_logging(config)?; + let (log_location, log_handle) = init_daemon_logging(config)?; log::trace!("Using configuration: {:?}", config); let log_dir = log_location.map(|l| l.directory); - run_standalone(log_dir, reload_handle).await + run_standalone(log_dir, log_handle).await } #[cfg(target_os = "linux")] @@ -118,18 +119,18 @@ fn init_daemon_logging( filename: PathBuf::from("daemon.log"), }); - let reload_handle = init_logger(config, log_location.clone())?; + let log_handle = init_logger(config, log_location.clone())?; if let Some(log_location) = log_location.as_ref() { log::info!("Logging to {}", log_location.log_path().display()); } - Ok((log_location, reload_handle)) + Ok((log_location, log_handle)) } -/// Initialize logging to stder and to the [`EARLY_BOOT_LOG_FILENAME`] +/// Initialize logging to stderr and to the [`EARLY_BOOT_LOG_FILENAME`] #[cfg(target_os = "linux")] -fn init_early_boot_logging(config: &cli::Config) { - let logging = get_log_dir(config) +fn init_early_boot_logging(config: &cli::Config) -> Option<logging::LogHandle> { + let log_file_location = get_log_dir(config) .ok() .flatten() .map(|log_dir| LogLocation { @@ -139,9 +140,12 @@ fn init_early_boot_logging(config: &cli::Config) { // If it's possible to log to the filesystem - attempt to do so, but failing that mustn't stop // the daemon from starting here. - if init_logger(config, logging).is_err() { - let _ = init_logger(config, None); - }; + init_logger(config, log_file_location) + .or_else(|e| { + eprintln!("Failed to initialize early-boot logging to file: '{e}'"); + init_logger(config, None) + }) + .ok() } /// Initialize logging to stderr and to file (if provided). @@ -163,12 +167,12 @@ fn init_logger( exception_logging::enable(); - let reload_handle = + let log_handle = logging::init_logger(config.log_level, log_location, config.log_stdout_timestamps) .map_err(|e| e.display_chain_with_msg("Unable to initialize logger"))?; log_panics::init(); version::log_version(); - Ok(reload_handle) + Ok(log_handle) } fn get_log_dir(config: &cli::Config) -> Result<Option<PathBuf>, String> { diff --git a/mullvad-daemon/src/system_service.rs b/mullvad-daemon/src/system_service.rs index 6425779d6f..ee0d7ba4b3 100644 --- a/mullvad-daemon/src/system_service.rs +++ b/mullvad-daemon/src/system_service.rs @@ -61,11 +61,7 @@ pub fn run() -> Result<(), String> { windows_service::define_windows_service!(service_main, handle_service_main); pub fn handle_service_main(_arguments: Vec<OsString>) { - let config = cli::get_config(); - let (log_location, reload_handle) = - init_daemon_logging(config).expect("Failed to initialize logging"); - log::info!("Service started."); - + let runtime = new_multi_thread().build().expect("Starting runtime"); let (event_tx, event_rx) = mpsc::channel(); // Register service event handler @@ -86,79 +82,52 @@ pub fn handle_service_main(_arguments: Vec<OsString>) { _ => ServiceControlHandlerResult::NotImplemented, } }; - let status_handle = match service_control_handler::register(SERVICE_NAME, event_handler) { - Ok(handle) => handle, - Err(error) => { - log::error!( - "{}", - error.display_chain_with_msg("Failed to register a service control handler") - ); - return; - } - }; + + let status_handle = service_control_handler::register(SERVICE_NAME, event_handler) + .expect("Failed to register a service control handler"); let mut persistent_service_status = PersistentServiceStatus::new(status_handle); persistent_service_status .set_pending_start(Duration::from_secs(1)) .unwrap(); - let should_restart = Arc::new(AtomicBool::new(true)); - - let runtime = new_multi_thread().build(); - let runtime = match runtime { - Err(error) => { - log::error!("{}", error.display_chain()); - persistent_service_status - .set_stopped(ServiceExitCode::ServiceSpecific(1)) - .unwrap(); - return; - } - Ok(runtime) => runtime, - }; - - let result = runtime.block_on(crate::create_daemon( - log_location.map(|l| l.directory), - reload_handle, - )); - let result = if let Ok(daemon) = result { - let shutdown_handle = daemon.shutdown_handle(); - - // Register monitor that translates `ServiceControl` to Daemon events - start_event_monitor( - persistent_service_status.clone(), - shutdown_handle, - event_rx, - should_restart.clone(), - ); - - persistent_service_status.set_running().unwrap(); - - runtime - .block_on(daemon.run()) - .map_err(|e| e.display_chain()) - } else { - result.map(|_| ()) - }; - + let result = runtime.block_on(run_daemon(event_rx, &mut persistent_service_status)); let exit_code = match result { - Ok(()) => { - log::info!("Stopping service"); - // check if shutdown signal was sent from the system - if !should_restart.load(Ordering::Acquire) { - ServiceExitCode::default() - } else { - // otherwise return a non-zero code so that the daemon gets restarted - ServiceExitCode::ServiceSpecific(1) - } - } + Ok(should_restart) if !should_restart => ServiceExitCode::default(), + Ok(_should_restart) => ServiceExitCode::ServiceSpecific(1), Err(error) => { log::error!("{}", error); ServiceExitCode::ServiceSpecific(1) } }; - persistent_service_status.set_stopped(exit_code).unwrap(); } +async fn run_daemon( + event_rx: mpsc::Receiver<ServiceControl>, + persistent_service_status: &mut PersistentServiceStatus, +) -> Result<bool, String> { + let config = cli::get_config(); + let (log_location, log_handle) = + init_daemon_logging(config).expect("Failed to initialize logging"); + + let daemon = crate::create_daemon(log_location.map(|l| l.directory), log_handle).await?; + + let shutdown_handle = daemon.shutdown_handle(); + let should_restart = Arc::new(AtomicBool::new(true)); + start_event_monitor( + persistent_service_status.clone(), + shutdown_handle, + event_rx, + should_restart.clone(), + ); + log::info!("Service started."); + persistent_service_status.set_running().unwrap(); + daemon.run().await.map_err(|e| e.display_chain())?; + log::info!("Stopping service"); + // check if shutdown signal was sent from the system + Ok(should_restart.load(Ordering::Acquire)) +} + /// Start event monitor thread that polls for `ServiceControl` and translates them into calls to /// Daemon. fn start_event_monitor( diff --git a/mullvad-jni/src/lib.rs b/mullvad-jni/src/lib.rs index 2930fff3d0..705f98f5b8 100644 --- a/mullvad-jni/src/lib.rs +++ b/mullvad-jni/src/lib.rs @@ -32,6 +32,7 @@ use talpid_types::{ErrorExt, android::AndroidContext}; /// Mullvad daemon instance. It must be initialized and destroyed by `MullvadDaemon.initialize` and /// `MullvadDaemon.shutdown`, respectively. static DAEMON_CONTEXT: Mutex<Option<DaemonContext>> = Mutex::new(None); +static LOG_HANDLE: OnceLock<LogHandle> = OnceLock::new(); static LOAD_CLASSES: Once = Once::new(); @@ -97,7 +98,6 @@ pub extern "system" fn Java_net_mullvad_mullvadvpn_service_MullvadDaemon_initial // In some cases, this function may be called multiple times for the same daemon process. // Since the tracing dispatcher can only be initialized once, we use a OnceLock to // reuse the existing log handle - static LOG_HANDLE: OnceLock<LogHandle> = OnceLock::new(); let log_handle = LOG_HANDLE .get_or_init(|| { start_logging(&files_dir) @@ -151,6 +151,14 @@ pub extern "system" fn Java_net_mullvad_mullvadvpn_service_MullvadDaemon_shutdow // Dropping the tokio runtime will block if there are any tasks in flight. // That is, until all async tasks yield *and* all blocking threads have stopped. } + + // Flush any remaining logs to file + _ = LOG_HANDLE + .get() + .expect("Log handle has been initialized") + .logfile_writer + .clone() // clone the inner Arcs + .flush(); } fn start( |