sys_util: use libc's openlog to connect to syslog

By using libc's openlog, we can ensure that the internal state of the
libc syslogger is consistent with the syslog module. Minijail will be
able to print to stderr and the syslog in the same way the logging
macros in crosvm do. The FD the syslog module uses is shared with libc
and via `syslog::get_fds`, jailed processes can inherit the needed FDs
to continue logging.

Now that `sys_log::init()` must be called in single threaded process,
this moves its tests to the list of the serially run ones in
build_test.py.

TEST=./build_test
BUG=None

Change-Id: I8dbc8ebf9d97ef670185259eceac5f6d3d6824ea
Reviewed-on: https://chromium-review.googlesource.com/649951
Commit-Ready: Zach Reizner <zachr@chromium.org>
Tested-by: Zach Reizner <zachr@chromium.org>
Reviewed-by: Jason Clinton <jclinton@chromium.org>
Reviewed-by: Dylan Reid <dgreid@chromium.org>

build_test.py

@@ -46,13 +46,15 @@ TEST_MODULES_PARALLEL = [
     'kvm',
     'kvm_sys',
     'net_sys',
-    'sys_util',
     'syscall_defines',
     'virtio_sys',
     'x86_64',
 ]
 
-TEST_MODULES_SERIAL = ['io_jail']
+TEST_MODULES_SERIAL = [
+    'io_jail',
+    'sys_util',
+  ]
 
 # Bright green
 PASS_COLOR = '\033[1;32m'

seccomp/x86_64/block_device.policy

@@ -22,3 +22,4 @@ write: 1
 eventfd2: 1
 dup: 1
 poll: 1
+getpid: 1

seccomp/x86_64/net_device.policy

@@ -20,3 +20,4 @@ sigaltstack: 1
 # arg0 is flags. Because kernel.
 clone: arg0 & 0x00010000
 write: 1
+getpid: 1

seccomp/x86_64/rng_device.policy

@@ -21,3 +21,4 @@ write: 1
 eventfd2: 1
 dup: 1
 poll: 1
+getpid: 1

seccomp/x86_64/vhost_net_device.policy

@@ -37,3 +37,4 @@ sigaltstack: 1
 # arg0 is flags. Because kernel.
 clone: arg0 & 0x00010000
 write: 1
+getpid: 1

src/device_manager.rs

@@ -13,7 +13,7 @@ use libc::STDERR_FILENO;
 
 use io_jail::Minijail;
 use kvm::IoeventAddress;
-use sys_util::GuestMemory;
+use sys_util::{GuestMemory, syslog};
 use sys_util;
 
 use hw;
@@ -94,6 +94,7 @@ impl DeviceManager {
         // List of FDs to keep open in the child after it forks.
         let mut keep_fds: Vec<RawFd> = device.keep_fds();
         keep_fds.push(STDERR_FILENO);
+        syslog::push_fds(&mut keep_fds);
 
         let mmio_device = hw::virtio::MmioDevice::new(self.guest_mem.clone(), device)
             .map_err(Error::CreateMmioDevice)?;

src/main.rs

@@ -230,6 +230,13 @@ fn wait_all_children() -> bool {
 }
 
 fn run_config(cfg: Config) -> Result<()> {
+    if cfg.multiprocess {
+        // Printing something to the syslog before entering minijail so that libc's syslogger has a
+        // chance to open files necessary for its operation, like `/etc/localtime`. After jailing,
+        // access to those files will not be possible.
+        info!("crosvm entering multiprocess mode");
+    }
+
     let kernel_image = File::open(cfg.kernel_path.as_path())
         .map_err(|e| Error::OpenKernel(cfg.kernel_path.clone(), e))?;
 

sys_util/src/syslog.rs

@@ -31,14 +31,15 @@ use std::fs::File;
 use std::io::{Write, Cursor, ErrorKind, stderr};
 use std::io;
 use std::mem;
-use std::os::unix::io::{AsRawFd, RawFd};
+use std::os::unix::io::{AsRawFd, FromRawFd, RawFd};
 use std::os::unix::net::UnixDatagram;
 use std::path::PathBuf;
-use std::result;
+use std::ptr::null;
 use std::str::from_utf8;
 use std::sync::{Mutex, MutexGuard, Once, ONCE_INIT};
 
-use libc::{tm, time, time_t, localtime_r, gethostname, c_char};
+use libc::{tm, time, time_t, localtime_r, gethostname, openlog, fcntl, c_char, LOG_NDELAY,
+           LOG_PERROR, LOG_PID, LOG_USER, F_GETFD};
 
 use getpid;
 
@@ -100,12 +101,18 @@ pub enum Facility {
 /// 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<String, ()> {
@@ -131,9 +138,43 @@ fn get_proc_name() -> Option<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<UnixDatagram, Error> {
+    // 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: UnixDatagram,
+    socket: Option<UnixDatagram>,
     file: Option<File>,
     hostname: Option<String>,
     proc_name: Option<String>,
@@ -141,11 +182,10 @@ struct State {
 
 impl State {
     fn new() -> Result<State, Error> {
-        let s = UnixDatagram::unbound().map_err(Error::Socket)?;
-        s.connect(SYSLOG_PATH).map_err(Error::Connect)?;
+        let s = openlog_and_get_socket()?;
         Ok(State {
                stderr: true,
-               socket: s,
+               socket: Some(s),
                file: None,
                hostname: get_hostname().ok(),
                proc_name: get_proc_name(),
@@ -162,10 +202,10 @@ fn new_mutex_ptr<T>(inner: T) -> *const Mutex<T> {
 
 /// Initialize the syslog connection and internal variables.
 ///
-/// This should only be called once per process, but it is safe to do so from multiple threads more
-/// than once. Every call made after the first will have no effect besides return `Ok` or `Err`
-/// appropriately.
-pub fn init() -> result::Result<(), Error> {
+/// 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`.
@@ -180,15 +220,15 @@ pub fn init() -> result::Result<(), Error> {
     }
 }
 
-fn lock() -> Result<MutexGuard<'static, State>, ()> {
+fn lock() -> Result<MutexGuard<'static, State>, 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(());
+        return Err(Error::NeverInitialized);
     }
     // Safe because STATE only mutates once and we checked for NULL.
     let state = unsafe { &*state_ptr };
-    state.lock().map_err(|_| ())
+    state.lock().map_err(|_| Error::Poisoned)
 }
 
 // Attempts to lock and retrieve the state. Returns from the function silently on failure.
@@ -229,6 +269,41 @@ pub fn set_proc_name<T: Into<String>>(proc_name: T) {
     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
@@ -262,9 +337,9 @@ pub fn echo_stderr(enable: bool) {
 /// pushed into `fds`.
 ///
 /// Note that the `stderr` file descriptor is never added, as it is not owned by syslog.
-pub fn get_fds(fds: &mut Vec<RawFd>) {
+pub fn push_fds(fds: &mut Vec<RawFd>) {
     let state = lock!();
-    fds.push(state.socket.as_raw_fd());
+    fds.extend(state.socket.iter().map(|s| s.as_raw_fd()));
     fds.extend(state.file.iter().map(|f| f.as_raw_fd()));
 }
 
@@ -339,38 +414,40 @@ pub fn log(pri: Priority, fac: Facility, file_name: &str, line: u32, args: fmt::
                                         "Sep", "Oct", "Nov", "Dec"];
 
     let mut state = lock!();
-    let tm = get_localtime();
-    let prifac = (pri as u8) | (fac as u8);
     let mut buf = [0u8; 1024];
-    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 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(&state.socket, &buf[..len]);
+        if res.is_ok() {
+            send_buf(&socket, &buf[..len]);
+        }
     }
 
     let (res, len) = {
@@ -454,7 +531,7 @@ mod tests {
     fn fds() {
         init().unwrap();
         let mut fds = Vec::new();
-        get_fds(&mut fds);
+        push_fds(&mut fds);
         assert!(fds.len() >= 1);
         for fd in fds {
             assert!(fd >= 0);