diff --git a/Cargo.toml b/Cargo.toml index 0d3b203564b..c26a37b7a4e 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -11,5 +11,6 @@ devices = { path = "devices" } net_util = { path = "net_util" } sys_util = { path = "sys_util" } vmm = { path = "vmm" } +logger = { path = "logger" } [workspace] diff --git a/devices/Cargo.toml b/devices/Cargo.toml index 1cd18cd3567..9029e8b8ef7 100644 --- a/devices/Cargo.toml +++ b/devices/Cargo.toml @@ -14,6 +14,7 @@ sys_util = { path = "../sys_util" } virtio_sys = { path = "../virtio_sys" } vhost_sys = { path = "../vhost_sys" } vhost_backend = { path = "../vhost_backend" } +logger = {path = "../logger"} [dev-dependencies] data_model = { path = "../data_model"} diff --git a/devices/src/lib.rs b/devices/src/lib.rs index 2aaef74971a..5e7e286a5a0 100644 --- a/devices/src/lib.rs +++ b/devices/src/lib.rs @@ -3,14 +3,13 @@ // found in the LICENSE file. //! Emulates virtual and hardware devices. - extern crate byteorder; extern crate epoll; extern crate libc; - +#[macro_use] +extern crate logger; extern crate net_sys; extern crate net_util; -#[macro_use] extern crate sys_util; extern crate vhost_backend; extern crate vhost_sys; diff --git a/kvm/src/lib.rs b/kvm/src/lib.rs index 4e6bcc83d68..741ac8e6a06 100644 --- a/kvm/src/lib.rs +++ b/kvm/src/lib.rs @@ -8,7 +8,6 @@ extern crate libc; extern crate byteorder; extern crate kvm_sys; -#[macro_use] extern crate sys_util; mod cap; @@ -79,12 +78,8 @@ impl Kvm { /// Gets the recommended maximum number of VCPUs per VM. pub fn get_nr_vcpus(&self) -> usize { match self.check_extension_int(Cap::NrVcpus) { - 0 => 4, // according to api.txt x if x > 0 => x as usize, - _ => { - warn!("kernel returned invalid number of VCPUs"); - 4 - } + _ => 4, } } diff --git a/logger/Cargo.toml b/logger/Cargo.toml new file mode 100644 index 00000000000..01d2e0f3ce7 --- /dev/null +++ b/logger/Cargo.toml @@ -0,0 +1,9 @@ +[package] +name = "logger" +version = "0.1.0" +authors = ["Amazon firecracker team "] + +[dependencies] +libc = ">=0.2.39" +log = { version = "0.4", features = ["std"] } + diff --git a/logger/src/error.rs b/logger/src/error.rs new file mode 100644 index 00000000000..4ddab338d9c --- /dev/null +++ b/logger/src/error.rs @@ -0,0 +1,75 @@ +//! Errors returned by the logger. + +use std; +use std::error::Error; +use std::fmt; + +#[derive(Debug)] +pub enum LoggerError { + /// First attempt at initialization failed. + NeverInitialized(String), + /// Initialization has previously failed and can not be retried. + Poisoned(String), + /// Creating log file fails. + CreateLogFile(std::io::Error), + /// Writing to log file fails. + FileLogWrite(std::io::Error), + /// Flushing to disk fails. + FileLogFlush(std::io::Error), + /// Error obtaining lock on mutex. + FileLogLock(String), +} + +impl fmt::Display for LoggerError { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + let printable = match *self { + LoggerError::NeverInitialized(ref e) => e, + LoggerError::Poisoned(ref e) => e, + LoggerError::CreateLogFile(ref e) => e.description(), + LoggerError::FileLogWrite(ref e) => e.description(), + LoggerError::FileLogFlush(ref e) => e.description(), + LoggerError::FileLogLock(ref e) => e, + }; + write!(f, "{}", printable) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::io::ErrorKind; + + #[test] + fn test_formatting() { + assert!( + format!( + "{:?}", + LoggerError::NeverInitialized(String::from("Bad Log Path Provided")) + ).contains("NeverInitialized") + ); + assert!( + format!( + "{:?}", + LoggerError::Poisoned(String::from("Never Initialized")) + ).contains("Poisoned") + ); + assert!( + format!( + "{:?}", + LoggerError::FileLogWrite(std::io::Error::new(ErrorKind::Interrupted, "write")) + ).contains("FileLogWrite") + ); + assert!( + format!( + "{:?}", + LoggerError::FileLogFlush(std::io::Error::new(ErrorKind::Interrupted, "flush")) + ).contains("FileLogFlush") + ); + assert!( + format!( + "{:?}", + LoggerError::FileLogLock(String::from("File log lock")) + ).contains("FileLogLock") + ); + } +} diff --git a/logger/src/lib.rs b/logger/src/lib.rs new file mode 100644 index 00000000000..cb968862367 --- /dev/null +++ b/logger/src/lib.rs @@ -0,0 +1,469 @@ +//! Sends log messages to either stdout, stderr or a file provided as argument to the init. +//! +//! Every function exported by this module is thread-safe. +//! Each function will silently fail until +//! `log::init()` is called and returns `Ok`. +//! +//! # Examples +//! +//! ``` +//! #[macro_use] +//! extern crate log; +//! extern crate logger; +//! use logger::Logger; +//! +//! fn main() { +//! if let Err(e) = Logger::new().init(None) { +//! println!("Could not initialize the log subsystem: {:?}", e); +//! return; +//! } +//! warn!("this is a warning"); +//! error!("this is a error"); +//! } +//! ``` +// workaround to macro_reexport +extern crate log; +pub use log::*; +pub use log::Level::*; + +mod error; +mod writers; + +use error::LoggerError; +use log::{set_boxed_logger, set_max_level, Log, Metadata, Record}; +use std::result; +use std::sync::{Arc, Once, ONCE_INIT}; +use writers::*; + +/// Output sources for the log subsystem. +/// +#[derive(Debug, PartialEq, Clone, Copy)] +enum Destination { + Stderr, + Stdout, + File, +} + +/// Each log level also has a code and a destination output associated with it. +/// +#[derive(Debug)] +pub struct LevelInfo { + code: Level, + writer: Destination, +} + +/// Types used by the Logger. +/// +pub type Result = result::Result; + +/// Values used by the Logger. +/// +pub const IN_PREFIX_SEPARATOR: &str = ":"; +pub const MSG_SEPARATOR: &str = " "; +pub const DEFAULT_LEVEL: Level = Level::Warn; + +/// Synchronization primitives used to run a one-time global initialization. +/// +static INIT: Once = ONCE_INIT; +static mut INIT_RES: Result<()> = Ok(()); + +/// Logger representing the logging subsystem. +/// +#[derive(Debug)] +pub struct Logger { + show_level: bool, + show_file_path: bool, + show_line_numbers: bool, + level_info: LevelInfo, + // used in case we want to log to a file + file: Option>, +} + +/// Auxiliary function to get the default destination for some code level. +/// +fn get_default_destination(level: Level) -> Destination { + match level { + Level::Error => Destination::Stderr, + Level::Warn => Destination::Stderr, + Level::Info => Destination::Stdout, + Level::Debug => Destination::Stdout, + Level::Trace => Destination::Stdout, + } +} + +impl Logger { + /// Creates a new instance of the current logger. + /// + /// The default level is Warning. + /// The default separator between the tag and the log message is " ". + /// The default separator inside the tag is ":". + /// The tag of the log message is the text to the left of the separator. + /// + pub fn new() -> Logger { + Logger { + show_level: true, + show_line_numbers: true, + show_file_path: true, + level_info: LevelInfo { + // DEFAULT_LEVEL is warn so the destination output is stderr + code: DEFAULT_LEVEL, + writer: Destination::Stderr, + }, + file: None, + } + } + + /// Enables or disables including the level in the log message's tag portion. + /// + /// # Example + /// + /// ```rust + /// #[macro_use] + /// extern crate log; + /// extern crate logger; + /// use logger::Logger; + /// + /// fn main() { + /// Logger::new() + /// .set_include_level(true) + /// .init(None) + /// .unwrap(); + /// + /// warn!("This will print 'WARN' surrounded by square brackets followed by log message"); + /// } + /// ``` + pub fn set_include_level(mut self, option: bool) -> Self { + self.show_level = option; + self + } + + /// Enables or disables including the file path and the line numbers in the tag of the log message. + /// + /// # Example + /// + /// ```rust + /// #[macro_use] + /// extern crate log; + /// extern crate logger; + /// use logger::Logger; + /// + /// fn main() { + /// Logger::new() + /// .set_include_origin(true, true) + /// .init(None) + /// .unwrap(); + /// + /// warn!("This will print '[WARN:file_path.rs:155]' followed by log message"); + /// } + /// ``` + pub fn set_include_origin(mut self, file_path: bool, line_numbers: bool) -> Self { + self.show_file_path = file_path; + self.show_line_numbers = line_numbers; + + //buut if the file path is not shown, do not show line numbers either + if !self.show_file_path { + self.show_line_numbers = false; + } + + self + } + + /// Explicitly sets the log level for the Logger. + /// User needs to say the level code(error, warn...) and the output destination will be updated if and only if the + /// logger was not initialized to log to a file. + /// The default level is WARN. So, ERROR and WARN statements will be shown (basically, all that is bigger + /// than the level code). + /// If level is decreased at INFO, ERROR, WARN and INFO statements will be outputted, etc. + /// + /// # Example + /// + /// ```rust + /// #[macro_use] + /// extern crate log; + /// extern crate logger; + /// use logger::Logger; + /// + /// fn main() { + /// Logger::new() + /// .set_level(log::Level::Info) + /// .init(None) + /// .unwrap(); + /// } + /// ``` + pub fn set_level(mut self, level: Level) -> Self { + self.level_info.code = level; + if self.level_info.writer != Destination::File { + self.level_info.writer = get_default_destination(level); + } + self + } + + /// Creates the first portion (to the left of the separator) + /// of the log statement based on the logger settings. + /// + fn create_prefix(&self, record: &Record) -> String { + let level_str = if self.show_level { + record.level().to_string() + } else { + String::new() + }; + + let file_path_str = if self.show_file_path { + let pth = record.file().unwrap_or("unknown"); + if self.show_level { + format!("{}{}", IN_PREFIX_SEPARATOR, pth) + } else { + pth.into() + } + } else { + String::new() + }; + + let line_str = if self.show_line_numbers { + if let Some(l) = record.line() { + format!("{}{}", IN_PREFIX_SEPARATOR, l) + } else { + String::new() + } + } else { + String::new() + }; + + format!("[{}{}{}]", level_str, file_path_str, line_str) + } + + /// Initialize log subsystem (once and only once). + /// Every call made after the first will have no effect besides return `Ok` or `Err` + /// appropriately (read description of error's enum items). + /// + /// # Example + /// + /// ```rust + /// extern crate logger; + /// use logger::Logger; + /// + /// fn main() { + /// Logger::new() + /// .init(None) + /// .unwrap(); + /// } + /// ``` + pub fn init(mut self, log_path: Option) -> Result<()> { + unsafe { + if INIT_RES.is_err() { + INIT_RES = Err(LoggerError::Poisoned(format!( + "{}", + INIT_RES.as_ref().err().unwrap() + ))); + return Err(LoggerError::Poisoned(format!( + "{}", + INIT_RES.as_ref().err().unwrap() + ))); + } + INIT.call_once(|| { + if let Some(path) = log_path.as_ref() { + match FileLogWriter::new(path) { + Ok(t) => { + self.file = Some(Arc::new(t)); + self.level_info.writer = Destination::File; + } + Err(ref e) => { + INIT_RES = Err(LoggerError::NeverInitialized(format!("{}", e))); + } + }; + } + set_max_level(self.level_info.code.to_level_filter()); + + if let Err(e) = set_boxed_logger(Box::new(self)) { + INIT_RES = Err(LoggerError::NeverInitialized(format!("{}", e))) + } + }); + if INIT_RES.is_err() { + return Err(LoggerError::NeverInitialized(format!( + "{}", + INIT_RES.as_ref().err().unwrap() + ))); + } + } + Ok(()) + } +} + +/// Implements trait log from the externally used log crate +/// +impl Log for Logger { + // test whether a log level is enabled for the current module + fn enabled(&self, metadata: &Metadata) -> bool { + metadata.level() <= self.level_info.code + } + + fn log(&self, record: &Record) { + if self.enabled(record.metadata()) { + let mut msg = format!( + "{}{}{}", + self.create_prefix(&record), + MSG_SEPARATOR, + record.args() + ); + + match self.level_info.writer { + Destination::Stderr => { + eprintln!("{}", msg); + } + Destination::Stdout => { + println!("{}", msg); + } + Destination::File => { + if let Some(fw) = self.file.as_ref() { + msg = format!("{}\n", msg); + if let Err(e) = fw.write(&msg) { + eprintln!("logger: Could not write to log file {}", e); + } + self.flush(); + } else { + // if destination of log is a file but no file writer was found, + // should print error + eprintln!("logger: Could not find a file to write to"); + } + } + } + } + } + + fn flush(&self) { + if let Some(fw) = self.file.as_ref() { + if let Err(e) = fw.flush() { + eprintln!("logger: Could not flush log content to disk {}", e); + } + } + // everything else flushes by itself + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::fs::File; + use std::io::BufReader; + use std::io::BufRead; + use std::fs::remove_file; + use log::MetadataBuilder; + + fn validate_logs( + log_path: &str, + expected: &[(&'static str, &'static str, &'static str)], + ) -> bool { + let f = File::open(log_path).unwrap(); + let mut reader = BufReader::new(f); + + let mut line = String::new(); + for tuple in expected { + line.clear(); + reader.read_line(&mut line).unwrap(); + assert!(line.contains(&tuple.0)); + assert!(line.contains(&tuple.1)); + assert!(line.contains(&tuple.2)); + } + false + } + + #[test] + fn test_default_values() { + let l = Logger::new(); + assert_eq!(l.level_info.code, log::Level::Warn); + assert_eq!(l.level_info.writer, Destination::Stderr); + assert_eq!(l.show_line_numbers, true); + assert_eq!(l.show_level, true); + format!("{:?}", l.level_info.code); + format!("{:?}", l.level_info.writer); + format!("{:?}", l.show_line_numbers); + format!("{:?}", l); + } + + #[test] + fn test_init() { + let l = Logger::new().set_include_origin(false, true); + assert_eq!(l.show_line_numbers, false); + + let l = Logger::new() + .set_include_origin(true, true) + .set_include_level(true) + .set_level(log::Level::Info); + assert_eq!(l.show_line_numbers, true); + assert_eq!(l.show_file_path, true); + assert_eq!(l.show_level, true); + + assert!(l.init(Some(String::from("tmp.log"))).is_ok()); + info!("info"); + warn!("warning"); + + let l = Logger::new(); + assert!(l.init(None).is_ok()); + + info!("info"); + warn!("warning"); + error!("error"); + + // here we also test that the second initialization had no effect given that the + // logging system can only be initialized once per program + validate_logs( + "tmp.log", + &[ + ("[INFO", "lib.rs", "info"), + ("[WARN", "lib.rs", "warn"), + ("[INFO", "lib.rs", "info"), + ("[WARN", "lib.rs", "warn"), + ("[ERROR", "lib.rs", "error"), + ], + ); + remove_file("tmp.log").unwrap(); + + let l = Logger::new(); + unsafe { + if let Err(e) = set_boxed_logger(Box::new(l)) { + INIT_RES = Err(LoggerError::NeverInitialized(format!("{}", e))); + } + assert!(format!("{:?}", INIT_RES).contains("NeverInitialized")); + } + let l = Logger::new(); + assert!(l.init(None).is_err()); + unsafe { + assert!(format!("{:?}", INIT_RES).contains("Poisoned")); + } + + let l = Logger::new() + .set_include_level(true) + .set_include_origin(false, false); + let error_metadata = MetadataBuilder::new().level(Level::Error).build(); + let log_record = log::Record::builder().metadata(error_metadata).build(); + Logger::log(&l, &log_record); + let l = Logger::new() + .set_include_level(false) + .set_include_origin(true, true); + Logger::log(&l, &log_record); + } + + #[test] + fn test_get_default_destination() { + assert_eq!( + get_default_destination(log::Level::Error), + Destination::Stderr + ); + assert_eq!( + get_default_destination(log::Level::Warn), + Destination::Stderr + ); + assert_eq!( + get_default_destination(log::Level::Info), + Destination::Stdout + ); + assert_eq!( + get_default_destination(log::Level::Debug), + Destination::Stdout + ); + assert_eq!( + get_default_destination(log::Level::Trace), + Destination::Stdout + ); + } +} diff --git a/logger/src/writers.rs b/logger/src/writers.rs new file mode 100644 index 00000000000..c8653b660b9 --- /dev/null +++ b/logger/src/writers.rs @@ -0,0 +1,89 @@ +use error::LoggerError; +use std::fs::File; +use std::io::{LineWriter, Write}; +use std::path::Path; +use std::result; +use std::sync::{Mutex, MutexGuard}; + +pub type Result = result::Result; + +/// Structure `FileLogWriter` used for writing to a file in a thread-safe way. +#[derive(Debug)] +pub struct FileLogWriter { + line_writer: Mutex>, +} + +impl FileLogWriter { + pub fn new(log_path: &String) -> Result { + let p_file = Path::new(&log_path); + if Path::new(log_path).exists() { + eprintln!( + "Log file {} already exists. Overwriting its contents...", + log_path + ); + } + match File::create(&p_file) { + Ok(t) => Ok(FileLogWriter { + line_writer: Mutex::new(LineWriter::new(t)), + }), + Err(e) => return Err(LoggerError::CreateLogFile(e)), + } + } + + pub fn write(&self, msg: &String) -> Result<()> { + let mut line_writer = self.get_line_writer()?; + line_writer + .write_all(msg.as_bytes()) + .map_err(|e| LoggerError::FileLogWrite(e)) + } + + pub fn flush(&self) -> Result<()> { + let mut line_writer = self.get_line_writer()?; + line_writer + .flush() + .map_err(|e| LoggerError::FileLogFlush(e)) + } + + fn get_line_writer(&self) -> Result<(MutexGuard>)> { + self.line_writer + .lock() + .map_err(|e| LoggerError::FileLogLock(format!("{}", e))) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::fs::remove_file; + + #[test] + fn test_new() { + let mut file: String = "./inexistent/tmp.log".to_string(); + assert!(FileLogWriter::new(&file).is_err()); + format!("{:?}", FileLogWriter::new(&file)); + file = "tmp_writers_new.log".to_string(); + let res = FileLogWriter::new(&file); + format!("{:?}", res); + remove_file(file).unwrap(); + assert!(res.is_ok()) + } + + #[test] + fn test_write() { + let file: String = "tmp_writers_write.log".to_string(); + let fw = FileLogWriter::new(&file).unwrap(); + let msg = String::from("some message"); + let res = fw.write(&msg); + remove_file(file).unwrap(); + assert!(res.is_ok()) + } + + #[test] + fn test_flush() { + let file: String = "tmp_writers_flush.log".to_string(); + let fw = FileLogWriter::new(&file).unwrap(); + let res = fw.flush(); + remove_file(file).unwrap(); + assert!(res.is_ok()) + } +} diff --git a/src/main.rs b/src/main.rs index ac7d7219393..506ff6f363e 100644 --- a/src/main.rs +++ b/src/main.rs @@ -3,6 +3,7 @@ extern crate clap; extern crate api_server; extern crate devices; +extern crate logger; extern crate net_util; extern crate sys_util; extern crate vmm; @@ -18,7 +19,8 @@ use api_server::{ApiRequest, ApiServer}; use api_server::request::instance_info::{InstanceInfo, InstanceState}; use api_server::request::sync::{DeviceState, NetworkInterfaceBody, VsockJsonBody}; use net_util::MacAddr; -use sys_util::{syslog, EventFd, GuestAddress}; +use sys_util::{EventFd, GuestAddress}; +use logger::Logger; use vmm::{CMDLINE_MAX_SIZE, CMDLINE_OFFSET, KERNEL_START_OFFSET}; use vmm::{kernel_cmdline, KernelConfig}; use vmm::device_config::BlockDeviceConfig; @@ -26,11 +28,6 @@ use vmm::device_config::BlockDeviceConfig; const DEFAULT_SUBNET_MASK: &str = "255.255.255.0"; fn main() { - if let Err(e) = syslog::init() { - println!("failed to initialize syslog: {:?}", e); - return; - } - let cmd_arguments = App::new("firecracker") .version(crate_version!()) .author(crate_authors!()) @@ -111,6 +108,13 @@ fn main() { .long("guest-mac") .help("The MAC address of the guest network interface.") .takes_value(true), + ) + .arg( + Arg::with_name("log_file") + .short("l") + .long("log-file") + .help("File to serve as logging output") + .takes_value(true), ), ) .get_matches(); @@ -158,6 +162,27 @@ fn vmm_no_api_handler( from_api, ).expect("cannot create VMM"); + // this is temporary; user will be able to customize logging subsystem through API + if cmd_arguments.is_present("log_file") { + if let Err(e) = Logger::new() + .set_level(logger::Level::Info) + .init(Some(String::from( + cmd_arguments.value_of("log_file").unwrap(), + ))) { + eprintln!( + "main: Failed to initialize logging subsystem: {:?}. Trying without a file", + e + ); + if let Err(e) = Logger::new().set_level(logger::Level::Info).init(None) { + panic!("main: Failed to initialize logging subsystem: {:?}", e); + } + } + } else { + if let Err(e) = Logger::new().set_level(logger::Level::Info).init(None) { + panic!("main: Failed to initialize logging subsystem: {:?}", e); + } + } + // configure virtual machine from command line if cmd_arguments.is_present("vcpu_count") { match cmd_arguments diff --git a/sys_util/src/lib.rs b/sys_util/src/lib.rs index 43ab9de7a8a..c916d08cc80 100644 --- a/sys_util/src/lib.rs +++ b/sys_util/src/lib.rs @@ -10,8 +10,7 @@ extern crate syscall_defines; #[macro_use] pub mod ioctl; -#[macro_use] -pub mod syslog; + mod mmap; mod eventfd; mod errno; @@ -37,16 +36,3 @@ pub use libc_ioctl::*; pub use mmap::Error as MmapError; pub use guest_memory::Error as GuestMemoryError; - -use libc::{c_long, pid_t, syscall}; - -use syscall_defines::linux::LinuxSyscall::SYS_getpid; - -/// This bypasses `libc`'s caching `getpid(2)` wrapper which can be invalid if a raw clone was used -/// elsewhere. -/// TODO(dpopa@): get rid of this when syslog is gone too -#[inline(always)] -pub fn getpid() -> pid_t { - // Safe because this syscall can never fail and we give it a valid syscall number. - unsafe { syscall(SYS_getpid as c_long) as pid_t } -} diff --git a/sys_util/src/syslog.rs b/sys_util/src/syslog.rs deleted file mode 100644 index e37996fa3ba..00000000000 --- a/sys_util/src/syslog.rs +++ /dev/null @@ -1,611 +0,0 @@ -// Copyright 2017 The Chromium OS Authors. All rights reserved. -// Use of this source code is governed by a BSD-style license that can be -// found in the LICENSE file. - -//! Facilities for sending log message to syslog. -//! -//! Every function exported by this module is thread-safe. Each function will silently fail until -//! `syslog::init()` is called and returns `Ok`. -//! -//! # Examples -//! -//! ``` -//! #[macro_use] extern crate sys_util; -//! -//! use sys_util::syslog; -//! -//! fn main() { -//! if let Err(e) = syslog::init() { -//! println!("failed to initiailize syslog: {:?}", e); -//! return; -//! } -//! warn!("this is your {} warning", "final"); -//! error!("something went horribly wrong: {:?}", "out of RAMs"); -//! } -//! ``` - -use std::env; -use std::ffi::{OsStr, OsString}; -use std::fmt; -use std::fs::File; -use std::io::{stderr, Cursor, ErrorKind, Write}; -use std::io; -use std::mem; -use std::os::unix::io::{AsRawFd, FromRawFd, RawFd}; -use std::os::unix::net::UnixDatagram; -use std::path::PathBuf; -use std::ptr::null; -use std::str::from_utf8; -use std::sync::{Mutex, MutexGuard, Once, ONCE_INIT}; - -use libc::{c_char, fcntl, gethostname, localtime_r, openlog, time, time_t, tm, F_GETFD, - LOG_NDELAY, LOG_PERROR, LOG_PID, LOG_USER}; - -use getpid; - -const SYSLOG_PATH: &'static str = "/dev/log"; - -/// The priority (i.e. severity) of a syslog message. -/// -/// See syslog man pages for information on their semantics. -#[derive(Copy, Clone, Debug)] -pub enum Priority { - Emergency = 0, - Alert = 1, - Critical = 2, - Error = 3, - Warning = 4, - Notice = 5, - Info = 6, - Debug = 7, -} - -impl fmt::Display for Priority { - fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - match self { - &Priority::Emergency => write!(f, "{}", "EMERGENCY"), - &Priority::Alert => write!(f, "{}", "ALERT"), - &Priority::Critical => write!(f, "{}", "CRITICAL"), - &Priority::Error => write!(f, "{}", "ERROR"), - &Priority::Warning => write!(f, "{}", "WARNING"), - &Priority::Notice => write!(f, "{}", "NOTICE"), - &Priority::Info => write!(f, "{}", "INFO"), - &Priority::Debug => write!(f, "{}", "DEBUG"), - } - } -} - -/// The facility of a syslog message. -/// -/// See syslog man pages for information on their semantics. -pub enum Facility { - Kernel = 0, - User = 1 << 3, - Mail = 2 << 3, - Daemon = 3 << 3, - Auth = 4 << 3, - Syslog = 5 << 3, - Lpr = 6 << 3, - News = 7 << 3, - Uucp = 8 << 3, - Local0 = 16 << 3, - Local1 = 17 << 3, - Local2 = 18 << 3, - Local3 = 19 << 3, - Local4 = 20 << 3, - Local5 = 21 << 3, - Local6 = 22 << 3, - Local7 = 23 << 3, -} - -/// Errors returned by `syslog::init()`. -#[derive(Debug)] -pub enum Error { - /// Initialization was never attempted. - NeverInitialized, - /// Initialization has previously failed and can not be retried. - Poisoned, - /// Error while creating socket. - Socket(io::Error), - /// Error while attempting to connect socket. - Connect(io::Error), - // There was an error using `open` to get the lowest file descriptor. - GetLowestFd(io::Error), - // The guess of libc's file descriptor for the syslog connection was invalid. - InvalidFd, -} - -fn get_hostname() -> Result { - let mut hostname: [u8; 256] = [b'\0'; 256]; - // Safe because we give a valid pointer to a buffer of the indicated length and check for the - // result. - let ret = unsafe { gethostname(hostname.as_mut_ptr() as *mut c_char, hostname.len()) }; - if ret == -1 { - return Err(()); - } - - let len = hostname.iter().position(|&v| v == b'\0').ok_or(())?; - - Ok(from_utf8(&hostname[..len]).map_err(|_| ())?.to_string()) -} - -fn get_proc_name() -> Option { - env::args_os() - .next() - .map(PathBuf::from) - .and_then(|s| s.file_name().map(OsStr::to_os_string)) - .map(OsString::into_string) - .and_then(Result::ok) -} - -// Uses libc's openlog function to get a socket to the syslogger. By getting the socket this way, as -// opposed to connecting to the syslogger directly, libc's internal state gets initialized for other -// libraries (e.g. minijail) that make use of libc's syslog function. Note that this function -// depends on no other threads or signal handlers being active in this process because they might -// create FDs. -// -// TODO(zachr): Once https://android-review.googlesource.com/470998 lands, there won't be any -// libraries in use that hard depend on libc's syslogger. Remove this and go back to making the -// connection directly once minjail is ready. -fn openlog_and_get_socket() -> Result { - // Ordinarily libc's FD for the syslog connection can't be accessed, but we can guess that the - // FD that openlog will be getting is the lowest unused FD. To guarantee that an FD is opened in - // this function we use the LOG_NDELAY to tell openlog to connect to the syslog now. To get the - // lowest unused FD, we open a dummy file (which the manual says will always return the lowest - // fd), and then close that fd. Voilà, we now know the lowest numbered FD. The call to openlog - // will make use of that FD, and then we just wrap a `UnixDatagram` around it for ease of use. - let fd = File::open("/dev/null") - .map_err(Error::GetLowestFd)? - .as_raw_fd(); - - unsafe { - // Safe because openlog accesses no pointers because `ident` is null, only valid flags are - // used, and it returns no error. - openlog(null(), LOG_NDELAY | LOG_PERROR | LOG_PID, LOG_USER); - // For safety, ensure the fd we guessed is valid. The `fcntl` call itself only reads the - // file descriptor table of the current process, which is trivially safe. - if fcntl(fd, F_GETFD) >= 0 { - Ok(UnixDatagram::from_raw_fd(fd)) - } else { - Err(Error::InvalidFd) - } - } -} - -struct State { - stderr: bool, - socket: Option, - file: Option, - hostname: Option, - proc_name: Option, -} - -impl State { - fn new() -> Result { - let s = openlog_and_get_socket()?; - Ok(State { - stderr: true, - socket: Some(s), - file: None, - hostname: get_hostname().ok(), - proc_name: get_proc_name(), - }) - } -} - -static STATE_ONCE: Once = ONCE_INIT; -static mut STATE: *const Mutex = 0 as *const _; - -fn new_mutex_ptr(inner: T) -> *const Mutex { - Box::into_raw(Box::new(Mutex::new(inner))) -} - -/// Initialize the syslog connection and internal variables. -/// -/// This should only be called once per process before any other threads have been spawned or any -/// signal handlers have been registered. Every call made after the first will have no effect -/// besides return `Ok` or `Err` appropriately. -pub fn init() -> Result<(), Error> { - let mut err = Error::Poisoned; - STATE_ONCE.call_once(|| match State::new() { - // Safe because STATE mutation is guarded by `Once`. - Ok(state) => unsafe { STATE = new_mutex_ptr(state) }, - Err(e) => err = e, - }); - - if unsafe { STATE.is_null() } { - Err(err) - } else { - Ok(()) - } -} - -fn lock() -> Result, Error> { - // Safe because we assume that STATE is always in either a valid or NULL state. - let state_ptr = unsafe { STATE }; - if state_ptr.is_null() { - return Err(Error::NeverInitialized); - } - // Safe because STATE only mutates once and we checked for NULL. - let state = unsafe { &*state_ptr }; - state.lock().map_err(|_| Error::Poisoned) -} - -// Attempts to lock and retrieve the state. Returns from the function silently on failure. -macro_rules! lock { - () => ( - match lock() { - Ok(s) => s, - _ => return, - }; - ) -} - -/// Replaces the hostname reported in each syslog message. -/// -/// The default hostname is whatever `gethostname()` returned when `syslog::init()` was first -/// called. -/// -/// Does nothing if syslog was never initialized. -pub fn set_hostname>(hostname: T) { - let mut state = lock!(); - state.hostname = Some(hostname.into()); -} - -/// Replaces the process name reported in each syslog message. -/// -/// The default process name is the _file name_ of `argv[0]`. For example, if this program was -/// invoked as -/// -/// ```bash -/// $ path/to/app --delete everything -/// ``` -/// -/// the default process name would be _app_. -/// -/// Does nothing if syslog was never initialized. -pub fn set_proc_name>(proc_name: T) { - let mut state = lock!(); - state.proc_name = Some(proc_name.into()); -} - -/// Enables or disables echoing log messages to the syslog. -/// -/// The default behavior is **enabled**. -/// -/// If `enable` goes from `true` to `false`, the syslog connection is closed. The connection is -/// reopened if `enable` is set to `true` after it became `false`. -/// -/// Returns an error if syslog was never initialized or the syslog connection failed to be -/// established. -/// -/// # Arguments -/// * `enable` - `true` to enable echoing to syslog, `false` to disable echoing to syslog. -pub fn echo_syslog(enable: bool) -> Result<(), Error> { - let state_ptr = unsafe { STATE }; - if state_ptr.is_null() { - return Err(Error::NeverInitialized); - } - let mut state = lock().map_err(|_| Error::Poisoned)?; - - match state.socket.take() { - Some(_) if enable => {} - Some(s) => { - // Because `openlog_and_get_socket` actually just "borrows" the syslog FD, this module - // does not own the syslog connection and therefore should not destroy it. - mem::forget(s); - } - None if enable => { - let s = openlog_and_get_socket()?; - state.socket = Some(s); - } - _ => {} - } - Ok(()) -} - -/// Replaces the optional `File` to echo log messages to. -/// -/// The default behavior is to not echo to a file. Passing `None` to this function restores that -/// behavior. -/// -/// Does nothing if syslog was never initialized. -/// -/// # Arguments -/// * `file` - `Some(file)` to echo to `file`, `None` to disable echoing to the file previously -/// passed to `echo_file`. -pub fn echo_file(file: Option) { - let mut state = lock!(); - state.file = file; -} - -/// Enables or disables echoing log messages to the `std::io::stderr()`. -/// -/// The default behavior is **enabled**. -/// -/// Does nothing if syslog was never initialized. -/// -/// # Arguments -/// * `enable` - `true` to enable echoing to stderr, `false` to disable echoing to stderr. -pub fn echo_stderr(enable: bool) { - let mut state = lock!(); - state.stderr = enable; -} - -/// Retrieves the file descriptors owned by the global syslogger. -/// -/// Does nothing if syslog was never initialized. If their are any file descriptors, they will be -/// pushed into `fds`. -/// -/// Note that the `stderr` file descriptor is never added, as it is not owned by syslog. -pub fn push_fds(fds: &mut Vec) { - let state = lock!(); - fds.extend(state.socket.iter().map(|s| s.as_raw_fd())); - fds.extend(state.file.iter().map(|f| f.as_raw_fd())); -} - -/// Should only be called after `init()` was called. -fn send_buf(socket: &UnixDatagram, buf: &[u8]) { - const SEND_RETRY: usize = 2; - - for _ in 0..SEND_RETRY { - match socket.send(&buf[..]) { - Ok(_) => break, - Err(e) => match e.kind() { - ErrorKind::ConnectionRefused - | ErrorKind::ConnectionReset - | ErrorKind::ConnectionAborted - | ErrorKind::NotConnected => { - let res = socket.connect(SYSLOG_PATH); - if res.is_err() { - break; - } - } - _ => {} - }, - } - } -} - -fn get_localtime() -> tm { - unsafe { - // Safe because tm is just a struct of plain data. - let mut tm: tm = mem::zeroed(); - let mut now: time_t = 0; - // Safe because we give time a valid pointer and can never fail. - time(&mut now as *mut _); - // Safe because we give localtime_r valid pointers and can never fail. - localtime_r(&now, &mut tm as *mut _); - tm - } -} - -/// Records a log message with the given details. -/// -/// Note that this will fail silently if syslog was not initialized. -/// -/// # Arguments -/// * `pri` - The `Priority` (i.e. severity) of the log message. -/// * `fac` - The `Facility` of the log message. Usually `Facility::User` should be used. -/// * `file_name` - Name of the file that generated the log. -/// * `line` - Line number within `file_name` that generated the log. -/// * `args` - The log's message to record, in the form of `format_args!()` return value -/// -/// # Examples -/// -/// ``` -/// # #[macro_use] extern crate sys_util; -/// # use sys_util::syslog; -/// # fn main() { -/// # if let Err(e) = syslog::init() { -/// # println!("failed to initiailize syslog: {:?}", e); -/// # return; -/// # } -/// syslog::log(syslog::Priority::Error, -/// syslog::Facility::User, -/// file!(), -/// line!(), -/// format_args!("hello syslog")); -/// # } -/// ``` -pub fn log(pri: Priority, fac: Facility, file_name: &str, line: u32, args: fmt::Arguments) { - const MONTHS: [&'static str; 12] = [ - "Jan", "Feb", "Mar", "Apr", "May", "Jun", "Jul", "Aug", "Sep", "Oct", "Nov", "Dec" - ]; - - let mut state = lock!(); - let mut buf = [0u8; 1024]; - if let Some(ref socket) = state.socket { - let tm = get_localtime(); - let prifac = (pri as u8) | (fac as u8); - let (res, len) = { - let mut buf_cursor = Cursor::new(&mut buf[..]); - ( - write!( - &mut buf_cursor, - "<{}>{} {:02} {:02}:{:02}:{:02} {} {}[{}]: [{}:{}] {}", - prifac, - MONTHS[tm.tm_mon as usize], - tm.tm_mday, - tm.tm_hour, - tm.tm_min, - tm.tm_sec, - state.hostname.as_ref().map(|s| s.as_ref()).unwrap_or("-"), - state.proc_name.as_ref().map(|s| s.as_ref()).unwrap_or("-"), - getpid(), - file_name, - line, - args - ), - buf_cursor.position() as usize, - ) - }; - - if res.is_ok() { - send_buf(&socket, &buf[..len]); - } - } - - let (res, len) = { - let mut buf_cursor = Cursor::new(&mut buf[..]); - ( - write!( - &mut buf_cursor, - "[{}:{}:{}] {}\n", - pri, file_name, line, args - ), - buf_cursor.position() as usize, - ) - }; - if res.is_ok() { - if let Some(ref mut file) = state.file { - let _ = file.write_all(&buf[..len]); - } - if state.stderr { - let _ = stderr().write_all(&buf[..len]); - } - } -} - -/// A macro for logging at an arbitrary priority level. -/// -/// Note that this will fail silently if syslog was not initialized. -#[macro_export] -macro_rules! log { - ($pri:expr, $($args:tt)+) => ({ - $crate::syslog::log( - $pri, $crate::syslog::Facility::User, file!(), line!(), format_args!($($args)+)) - }) -} - -/// A macro for logging an error. -/// -/// Note that this will fail silently if syslog was not initialized. -#[macro_export] -macro_rules! error { - ($($args:tt)+) => (log!($crate::syslog::Priority::Error, $($args)*)) -} - -/// A macro for logging a warning. -/// -/// Note that this will fail silently if syslog was not initialized. -#[macro_export] -macro_rules! warn { - ($($args:tt)+) => (log!($crate::syslog::Priority::Warning, $($args)*)) -} - -/// A macro for logging info. -/// -/// Note that this will fail silently if syslog was not initialized. -#[macro_export] -macro_rules! info { - ($($args:tt)+) => (log!($crate::syslog::Priority::Info, $($args)*)) -} - -/// A macro for logging debug information. -/// -/// Note that this will fail silently if syslog was not initialized. -#[macro_export] -macro_rules! debug { - ($($args:tt)+) => (log!($crate::syslog::Priority::Debug, $($args)*)) -} - -#[cfg(test)] -mod tests { - use super::*; - - use libc::{shm_open, shm_unlink, O_CREAT, O_EXCL, O_RDWR}; - - use std::os::unix::io::FromRawFd; - use std::ffi::CStr; - use std::io::{Read, Seek, SeekFrom}; - - #[test] - fn init_syslog() { - init().unwrap(); - } - - #[test] - fn fds() { - init().unwrap(); - let mut fds = Vec::new(); - push_fds(&mut fds); - assert!(fds.len() >= 1); - for fd in fds { - assert!(fd >= 0); - } - } - - #[test] - fn syslog_log() { - init().unwrap(); - log( - Priority::Error, - Facility::User, - file!(), - line!(), - format_args!("hello syslog"), - ); - } - - #[test] - fn proc_name() { - init().unwrap(); - log( - Priority::Error, - Facility::User, - file!(), - line!(), - format_args!("before proc name"), - ); - set_proc_name("sys_util-test"); - log( - Priority::Error, - Facility::User, - file!(), - line!(), - format_args!("after proc name"), - ); - } - - #[test] - #[ignore] - fn syslog_file() { - init().unwrap(); - let shm_name = CStr::from_bytes_with_nul(b"/crosvm_shm\0").unwrap(); - let mut file = unsafe { - shm_unlink(shm_name.as_ptr()); - let fd = shm_open(shm_name.as_ptr(), O_RDWR | O_CREAT | O_EXCL, 0666); - assert!(fd >= 0, "error creating shared memory;"); - File::from_raw_fd(fd) - }; - - let syslog_file = file.try_clone().expect("error cloning shared memory file"); - echo_file(Some(syslog_file)); - - const TEST_STR: &'static str = "hello shared memory file"; - log( - Priority::Error, - Facility::User, - file!(), - line!(), - format_args!("{}", TEST_STR), - ); - - file.seek(SeekFrom::Start(0)) - .expect("error seeking shared memory file"); - let mut buf = String::new(); - file.read_to_string(&mut buf) - .expect("error reading shared memory file"); - assert!(buf.contains(TEST_STR)); - } - - #[test] - fn macros() { - init().unwrap(); - error!("this is an error {}", 3); - warn!("this is a warning {}", "uh oh"); - info!("this is info {}", true); - debug!("this is debug info {:?}", Some("helpful stuff")); - } -} diff --git a/vmm/Cargo.toml b/vmm/Cargo.toml index 097707660f0..42e55bcce28 100644 --- a/vmm/Cargo.toml +++ b/vmm/Cargo.toml @@ -13,6 +13,7 @@ devices = { path = "../devices" } kernel_loader = { path = "../kernel_loader" } kvm = { path = "../kvm" } kvm_sys = { path = "../kvm_sys" } +logger = { path = "../logger" } net_util = { path = "../net_util"} sys_util = { path = "../sys_util" } x86_64 = { path = "../x86_64" } diff --git a/vmm/src/lib.rs b/vmm/src/lib.rs index e5f15137f26..ae1ee35dafd 100644 --- a/vmm/src/lib.rs +++ b/vmm/src/lib.rs @@ -6,8 +6,9 @@ extern crate devices; extern crate kernel_loader; extern crate kvm; extern crate kvm_sys; -extern crate net_util; #[macro_use] +extern crate logger; +extern crate net_util; extern crate sys_util; extern crate x86_64;