diff --git a/garnet/bin/logger/src/klogger.rs b/garnet/bin/logger/src/klogger.rs
index c617ea54d3ece3618ba42d7b05656363a1974b39..3b24b457bed2e810f76e27b33cd3f059b18d0c57 100644
--- a/garnet/bin/logger/src/klogger.rs
+++ b/garnet/bin/logger/src/klogger.rs
@@ -9,72 +9,52 @@ use byteorder::{ByteOrder, LittleEndian};
use fidl_fuchsia_logger::{self, LogMessage};
use fuchsia_async as fasync;
use fuchsia_zircon as zx;
-use fuchsia_zircon::sys::zx_handle_t;
-use fuchsia_zircon::{AsHandleRef, Signals};
use futures::{future, stream, TryFutureExt, TryStreamExt};
-const ZX_LOG_FLAG_READABLE: u32 = 0x40000000;
-const ZX_LOG_RECORD_MAX: usize = 256;
-
pub fn add_listener<F>(callback: F) -> Result<(), zx::Status>
where
F: 'static + Send + Fn(LogMessage, usize) + Sync,
{
- let mut handle: zx_handle_t = 0;
- let handle_ptr = &mut handle as *mut _ as *mut u32;
-
- unsafe {
- zx::ok(zx::sys::zx_debuglog_create(
- zx::sys::ZX_HANDLE_INVALID,
- ZX_LOG_FLAG_READABLE,
- handle_ptr,
- ))?;
- }
- let h = unsafe { zx::Handle::from_raw(handle) };
+ let debuglog = zx::DebugLog::create(zx::DebugLogOpts::READABLE)?;
let f = stream::repeat(Ok(()))
- .try_fold((callback, h), |(callback, handle), ()| {
+ .try_fold((callback, debuglog), |(callback, debuglog), ()| {
// TODO: change OnSignals to wrap this so that is is not created again and again.
- fasync::OnSignals::new(&handle, Signals::LOG_READABLE).and_then(|_| {
+ fasync::OnSignals::new(&debuglog, zx::Signals::LOG_READABLE).and_then(|_| {
+ let mut buf = Vec::with_capacity(zx::sys::ZX_LOG_RECORD_MAX);
loop {
- let mut buf = [0; ZX_LOG_RECORD_MAX as usize];
- let status = unsafe {
- zx::sys::zx_debuglog_read(
- handle.raw_handle(),
- 0,
- buf.as_mut_ptr(),
- ZX_LOG_RECORD_MAX,
- )
- };
-
- if status == zx::sys::ZX_ERR_SHOULD_WAIT {
- return future::ready(Ok((callback, handle)));
- }
- if status < 0 {
- return future::ready(Err(zx::Status::from_raw(status)));
- }
- let mut l = LogMessage {
- time: LittleEndian::read_i64(&buf[8..16]),
- pid: LittleEndian::read_u64(&buf[16..24]),
- tid: LittleEndian::read_u64(&buf[24..32]),
- severity: fidl_fuchsia_logger::LogLevelFilter::Info as i32,
- dropped_logs: 0,
- tags: vec!["klog".to_string()],
- msg: String::new(),
- };
- let data_len = LittleEndian::read_u16(&buf[4..8]) as usize;
- l.msg = match String::from_utf8(buf[32..(32 + data_len)].to_vec()) {
- Err(e) => {
- eprintln!("logger: invalid log record: {:?}", e);
- continue;
+ match debuglog.read(&mut buf) {
+ Err(status) if status == zx::Status::SHOULD_WAIT => {
+ return future::ready(Ok((callback, debuglog)));
+ }
+ Err(status) => {
+ return future::ready(Err(status));
+ }
+ Ok(()) => {
+ let mut l = LogMessage {
+ time: LittleEndian::read_i64(&buf[8..16]),
+ pid: LittleEndian::read_u64(&buf[16..24]),
+ tid: LittleEndian::read_u64(&buf[24..32]),
+ severity: fidl_fuchsia_logger::LogLevelFilter::Info as i32,
+ dropped_logs: 0,
+ tags: vec!["klog".to_string()],
+ msg: String::new(),
+ };
+ let data_len = LittleEndian::read_u16(&buf[4..6]) as usize;
+ l.msg = match String::from_utf8(buf[32..(32 + data_len)].to_vec()) {
+ Err(e) => {
+ eprintln!("logger: invalid log record: {:?}", e);
+ continue;
+ }
+ Ok(s) => s,
+ };
+ if let Some(b'\n') = l.msg.bytes().last() {
+ l.msg.pop();
+ }
+ let size = logger::METADATA_SIZE + 5/*tag*/ + l.msg.len() + 1;
+ callback(l, size);
}
- Ok(s) => s,
- };
- if l.msg.len() > 0 && l.msg.as_bytes()[l.msg.len() - 1] == '\n' as u8 {
- l.msg.pop();
}
- let size = logger::METADATA_SIZE + 5/*tag*/ + l.msg.len() + 1;
- callback(l, size);
}
})
})
diff --git a/garnet/bin/logger/tests/rust/BUILD.gn b/garnet/bin/logger/tests/rust/BUILD.gn
index 7b6776dca4aab1d4df4fdf94fdd76bf863bac077..f29adf697e81b91738ba95001f9177497c3eb8f2 100644
--- a/garnet/bin/logger/tests/rust/BUILD.gn
+++ b/garnet/bin/logger/tests/rust/BUILD.gn
@@ -22,6 +22,7 @@ rustc_binary("bin") {
"//garnet/public/rust/fuchsia-syslog",
"//garnet/public/rust/fuchsia-syslog-listener",
"//garnet/public/rust/fuchsia-zircon",
+ "//third_party/rust_crates:failure",
"//third_party/rust_crates:futures-preview",
"//third_party/rust_crates:log",
"//third_party/rust_crates:parking_lot",
diff --git a/garnet/bin/logger/tests/rust/src/main.rs b/garnet/bin/logger/tests/rust/src/main.rs
index ab8fc590fbf73071f4b9b55717d7e7bb4959cba3..25b20eddef5a710b73d176bb96c7747801299142 100644
--- a/garnet/bin/logger/tests/rust/src/main.rs
+++ b/garnet/bin/logger/tests/rust/src/main.rs
@@ -11,11 +11,12 @@ fn main() {}
#[cfg(test)]
mod tests {
+ use failure::Error;
use fidl_fuchsia_logger::{LogFilterOptions, LogLevelFilter, LogMessage};
use fuchsia_async as fasync;
use fuchsia_syslog::{self as syslog, fx_log_info};
use fuchsia_syslog_listener::{self as syslog_listener, LogProcessor};
- use fuchsia_zircon::DurationNum;
+ use fuchsia_zircon::{self as zx, DurationNum};
use log::warn;
use parking_lot::Mutex;
@@ -62,7 +63,7 @@ mod tests {
}
#[test]
- fn test_full_stack() {
+ fn test_listen_for_syslog() {
let mut executor = fasync::Executor::new().unwrap();
let random = rand::random::<u16>();
let tag = "logger_integration_rust".to_string() + &random.to_string();
@@ -89,4 +90,31 @@ mod tests {
assert_eq!(logs[1].severity, LogLevelFilter::Warn as i32);
assert_eq!(logs[1].msg, "log crate: 20");
}
+
+ #[test]
+ fn test_listen_for_klog() -> Result<(), Error> {
+ let mut executor = fasync::Executor::new()?;
+ let logs = run_listener("klog".to_string());
+
+ let random = rand::random::<u64>();
+ let msg = format!("logger_integration_rust test_klog {}", random);
+
+ let debuglog = zx::DebugLog::create(zx::DebugLogOpts::empty())?;
+ debuglog.write(msg.as_bytes())?;
+
+ let tries = 50;
+ for _ in 0..tries {
+ let logs = logs.lock();
+ if logs.iter().find(|&m| m.msg == msg).is_some() {
+ return Ok(());
+ }
+ // Must release lock so the log listener started above with fasync::spawn can
+ // mutate it.
+ std::mem::drop(logs);
+
+ let timeout = fasync::Timer::new(100.millis().after_now());
+ executor.run_singlethreaded(timeout);
+ }
+ panic!("Failed to find klog");
+ }
}
diff --git a/garnet/public/rust/fuchsia-zircon/fuchsia-zircon-sys/src/lib.rs b/garnet/public/rust/fuchsia-zircon/fuchsia-zircon-sys/src/lib.rs
index 23888a4046e4927d2bde09fcd753b940c6c94944..84c701ab162e4087a0b969c76289e8780e3f1416 100644
--- a/garnet/public/rust/fuchsia-zircon/fuchsia-zircon-sys/src/lib.rs
+++ b/garnet/public/rust/fuchsia-zircon/fuchsia-zircon-sys/src/lib.rs
@@ -582,4 +582,10 @@ multiconst!(zx_guest_trap_t, [
ZX_GUEST_TRAP_IO = 2;
]);
+pub const ZX_LOG_RECORD_MAX: usize = 256;
+
+multiconst!(u32, [
+ ZX_LOG_FLAG_READABLE = 0x40000000;
+]);
+
include!("definitions.rs");
diff --git a/garnet/public/rust/fuchsia-zircon/src/debuglog.rs b/garnet/public/rust/fuchsia-zircon/src/debuglog.rs
new file mode 100644
index 0000000000000000000000000000000000000000..e0a546e1637ea33cb245972b809d7466dfea92aa
--- /dev/null
+++ b/garnet/public/rust/fuchsia-zircon/src/debuglog.rs
@@ -0,0 +1,152 @@
+// Copyright 2019 The Fuchsia Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+//! Type-safe bindings for Zircon resources.
+
+use crate::{AsHandleRef, HandleBased, HandleRef, Handle, Status};
+use crate::ok;
+use bitflags::bitflags;
+use fuchsia_zircon_sys as sys;
+
+/// An object representing a Zircon 'debuglog' object.
+///
+/// As essentially a subtype of `Handle`, it can be freely interconverted.
+#[derive(Debug, Eq, PartialEq)]
+#[repr(transparent)]
+pub struct DebugLog(Handle);
+impl_handle_based!(DebugLog);
+
+bitflags! {
+ #[repr(transparent)]
+ pub struct DebugLogOpts: u32 {
+ const READABLE = sys::ZX_LOG_FLAG_READABLE;
+ }
+}
+
+impl DebugLog {
+ /// Create a debug log object that allows access to read from and write to the kernel debug
+ /// logging facility.
+ ///
+ /// Wraps the
+ /// [zx_debuglog_create]((https://fuchsia.googlesource.com/fuchsia/+/master/zircon/docs/syscalls/debuglog_create.md)
+ /// syscall.
+ pub fn create(opts: DebugLogOpts) -> Result<DebugLog, Status> {
+ // TODO(ZX-2184): Once the resource required for zx_debuglog_create is defined, add it as a
+ // parameter to this call.
+ let resource = sys::ZX_HANDLE_INVALID;
+ let mut handle = 0;
+ let status = unsafe {
+ sys::zx_debuglog_create(resource, opts.bits(), &mut handle)
+ };
+ ok(status)?;
+ unsafe {
+ Ok(DebugLog::from(Handle::from_raw(handle)))
+ }
+ }
+
+ /// Write a message to the kernel debug log.
+ ///
+ /// Wraps the
+ /// [zx_debuglog_write]((https://fuchsia.googlesource.com/fuchsia/+/master/zircon/docs/syscalls/debuglog_write.md)
+ /// syscall.
+ pub fn write(&self, message: &[u8]) -> Result<(), Status> {
+ // TODO(ZX-3187): Discussion ongoing over whether debuglog levels are supported, so no
+ // options parameter for now.
+ let status = unsafe {
+ sys::zx_debuglog_write(
+ self.raw_handle(),
+ 0,
+ message.as_ptr(),
+ message.len()
+ )
+ };
+ ok(status)
+ }
+
+ /// Read a single log record from the kernel debug log.
+ ///
+ /// The DebugLog object must have been created with DebugLogOpts::READABLE, or this will return
+ /// an error.
+ ///
+ /// Wraps the
+ /// [zx_debuglog_read]((https://fuchsia.googlesource.com/fuchsia/+/master/zircon/docs/syscalls/debuglog_read.md)
+ /// syscall.
+ // TODO(ZX-3187): Return a safe wrapper type for zx_log_record_t rather than raw bytes
+ // depending on resolution.
+ pub fn read(&self, record: &mut Vec<u8>) -> Result<(), Status> {
+ let mut buf = [0; sys::ZX_LOG_RECORD_MAX];
+
+ // zx_debuglog_read options appear to be unused.
+ // zx_debuglog_read returns either an error status or, on success, the actual size of bytes
+ // read into the buffer.
+ let status_or_actual = unsafe {
+ sys::zx_debuglog_read(self.raw_handle(), 0, buf.as_mut_ptr(), buf.len())
+ };
+ let actual = Status::ioctl_ok(status_or_actual)? as usize;
+
+ record.clear();
+ record.extend_from_slice(&buf[0..actual]);
+ Ok(())
+ }
+}
+
+#[cfg(test)]
+mod tests {
+ use super::*;
+ use crate::{cprng_draw, Signals, Time};
+
+ // expect_message_in_debuglog will read the last 10000 messages in zircon's debuglog, looking
+ // for a message that equals `sent_msg`. If found, the function returns. If the first 10,000
+ // messages doesn't contain `sent_msg`, it will panic.
+ fn expect_message_in_debuglog(sent_msg: String) {
+ let debuglog = DebugLog::create(DebugLogOpts::READABLE).unwrap();
+ let mut record = Vec::with_capacity(sys::ZX_LOG_RECORD_MAX);
+ for _ in 0..10000 {
+ match debuglog.read(&mut record) {
+ Ok(()) => {
+ // TODO(ZX-3187): Manually unpack log record until DebugLog::read returns
+ // an wrapper type.
+ let mut len_bytes = [0; 2];
+ len_bytes.copy_from_slice(&record[4..6]);
+ let data_len = u16::from_le_bytes(len_bytes) as usize;
+ let log = &record[32..(32 + data_len)];
+ if log == sent_msg.as_bytes() {
+ // We found our log!
+ return;
+ }
+ }
+ Err(status) if status == Status::SHOULD_WAIT => {
+ debuglog
+ .wait_handle(Signals::LOG_READABLE, Time::INFINITE)
+ .expect("Failed to wait for log readable");
+ continue;
+ }
+ Err(status) => {
+ panic!("Unexpected error from zx_debuglog_read: {}", status);
+ }
+ }
+
+ }
+ panic!("first 10000 log messages didn't include the one we sent!");
+ }
+
+ #[test]
+ fn read_from_nonreadable() {
+ let mut data = vec![];
+ let debuglog = DebugLog::create(DebugLogOpts::empty()).unwrap();
+ assert!(debuglog.read(&mut data).err() == Some(Status::ACCESS_DENIED));
+ }
+
+ #[test]
+ fn write_and_read_back() {
+ let mut bytes = [0; 8];
+ cprng_draw(&mut bytes).unwrap();
+ let rand = u64::from_ne_bytes(bytes);
+ let message = format!("log message {}", rand);
+
+ let debuglog = DebugLog::create(DebugLogOpts::empty()).unwrap();
+ debuglog.write(message.as_bytes()).unwrap();
+ expect_message_in_debuglog(message);
+ }
+}
diff --git a/garnet/public/rust/fuchsia-zircon/src/lib.rs b/garnet/public/rust/fuchsia-zircon/src/lib.rs
index a78af60b1fb14ffe4b98507acd818e3cba79c69e..e888d15fa74039f6400234ba6e91961298c5d45b 100644
--- a/garnet/public/rust/fuchsia-zircon/src/lib.rs
+++ b/garnet/public/rust/fuchsia-zircon/src/lib.rs
@@ -5,8 +5,6 @@
//! Type-safe bindings for Zircon kernel
//! [syscalls](https://fuchsia.googlesource.com/fuchsia/+/master/zircon/docs/syscalls.md).
-#![deny(warnings)]
-
pub mod sys {
pub use fuchsia_zircon_sys::*;
}
@@ -140,6 +138,7 @@ macro_rules! assoc_values {
mod channel;
mod cprng;
+mod debuglog;
mod event;
mod eventpair;
mod fifo;
@@ -164,6 +163,7 @@ mod vmo;
pub use self::channel::*;
pub use self::cprng::*;
+pub use self::debuglog::*;
pub use self::event::*;
pub use self::eventpair::*;
pub use self::fifo::*;
diff --git a/src/sys/component_manager/src/klog.rs b/src/sys/component_manager/src/klog.rs
index cbf431b54c0ab29e701d14093d59345816f05c7c..59a0cb542db5627e635b7892e52a3bac5f92fdfd 100644
--- a/src/sys/component_manager/src/klog.rs
+++ b/src/sys/component_manager/src/klog.rs
@@ -15,7 +15,7 @@ const MAX_LOG_LEVEL: log::Level = log::Level::Info;
/// KernelLogger is a logger implementation for the log crate. It attempts to use the kernel
/// debuglog facility and automatically falls back to stderr if that fails.
pub struct KernelLogger {
- debuglog: zx::sys::zx_handle_t,
+ debuglog: zx::DebugLog,
}
lazy_static! {
@@ -24,18 +24,10 @@ lazy_static! {
impl KernelLogger {
fn new() -> KernelLogger {
- // TODO: Create zx::DebugLog wrappers for zx_debuglog_* syscalls to avoid direct unsafe
- // usage.
- let mut log_handle = zx::sys::ZX_HANDLE_INVALID;
- let status = unsafe {
- zx::sys::zx_debuglog_create(
- zx::sys::ZX_HANDLE_INVALID,
- 0,
- &mut log_handle as *mut zx::sys::zx_handle_t,
- )
- };
- zx::Status::ok(status).context("Failed to create debuglog object").unwrap();
- KernelLogger{debuglog: log_handle}
+ let debuglog = zx::DebugLog::create(zx::DebugLogOpts::empty())
+ .context("Failed to create debuglog object")
+ .unwrap();
+ KernelLogger{debuglog}
}
/// Initialize the global logger to use KernelLogger.
@@ -73,20 +65,10 @@ impl KernelLogger {
fn log_helper(&self, level: &str, args: &fmt::Arguments) {
let msg = format!("[component_manager] {}: {}", level, args);
- // TODO: Create zx::DebugLog wrappers for zx_debuglog_* syscalls to avoid direct unsafe
- // usage.
- // TODO: zx_debuglog_write also accepts options and the possible options include log
- // levels, but they seem to be mostly unused and not displayed today, so we don't pass
+ // TODO(ZX-3187): zx_debuglog_write also accepts options and the possible options include
+ // log levels, but they seem to be mostly unused and not displayed today, so we don't pass
// along log level yet.
- let status = unsafe {
- zx::sys::zx_debuglog_write(
- self.debuglog,
- 0,
- msg.as_ptr(),
- msg.as_bytes().len(),
- )
- };
- if let Err(s) = zx::Status::ok(status) {
+ if let Err(s) = self.debuglog.write(msg.as_bytes()) {
eprintln!("failed to write log ({}): {}", s, msg);
}
}
@@ -110,14 +92,12 @@ impl log::Log for KernelLogger {
mod tests {
use {
super::*,
- byteorder::{ByteOrder, LittleEndian},
+ fuchsia_zircon::AsHandleRef,
log::*,
rand::Rng,
- std::{panic, sync::Once, thread, time},
+ std::{panic, sync::Once},
};
- const ZX_LOG_FLAG_READABLE: u32 = 0x40000000;
-
// KernelLogger::init/log::set_logger will fail if called more than once and there's no way to
// reset.
fn init_logger_once() {
@@ -127,42 +107,37 @@ mod tests {
});
}
- // expect_message_in_debuglog will read the first 10000 messages in zircon's debuglog, looking
+ // expect_message_in_debuglog will read the last 10000 messages in zircon's debuglog, looking
// for a message that equals `sent_msg`. If found, the function returns. If the first 10,000
// messages doesn't contain `sent_msg`, it will panic.
fn expect_message_in_debuglog(sent_msg: String) {
- // TODO: Create zx::DebugLog wrappers for zx_debuglog_* syscalls to avoid direct unsafe
- // usage.
- let mut log_handle_for_reading = zx::sys::ZX_HANDLE_INVALID;
- let status = unsafe {
- zx::sys::zx_debuglog_create(
- zx::sys::ZX_HANDLE_INVALID,
- ZX_LOG_FLAG_READABLE,
- &mut log_handle_for_reading as *mut zx::sys::zx_handle_t,
- )
- };
- assert_eq!(zx::sys::ZX_OK, status);
-
+ let debuglog = zx::DebugLog::create(zx::DebugLogOpts::READABLE).unwrap();
+ let mut record = Vec::with_capacity(zx::sys::ZX_LOG_RECORD_MAX);
for _ in 0..10000 {
- let mut read_buffer = [0; 1024];
- let status = unsafe {
- zx::sys::zx_debuglog_read(log_handle_for_reading, 0, read_buffer.as_mut_ptr(), 1024)
- };
- if status <= 0 {
- if status == zx::sys::ZX_ERR_SHOULD_WAIT {
- thread::sleep(time::Duration::from_millis(100));
+ match debuglog.read(&mut record) {
+ Ok(()) => {
+ // TODO(ZX-3187): Manually unpack log record until zx::DebugLog::read returns
+ // an wrapper type.
+ let mut len_bytes = [0; 2];
+ len_bytes.copy_from_slice(&record[4..6]);
+ let data_len = u16::from_le_bytes(len_bytes) as usize;
+ let log = &record[32..(32 + data_len)];
+ if log == sent_msg.as_bytes() {
+ // We found our log!
+ return;
+ }
+ }
+ Err(status) if status == zx::Status::SHOULD_WAIT => {
+ debuglog
+ .wait_handle(zx::Signals::LOG_READABLE, zx::Time::INFINITE)
+ .expect("Failed to wait for log readable");
continue;
}
- assert_eq!(zx::sys::ZX_OK, status);
+ Err(status) => {
+ panic!("Unexpected error from zx_debuglog_read: {}", status);
+ }
}
- let data_len = LittleEndian::read_u16(&read_buffer[4..8]) as usize;
- let log = String::from_utf8(read_buffer[32..(32 + data_len)].to_vec())
- .expect("failed to read log buffer");
- if log == sent_msg {
- // We found our log!
- return;
- }
}
panic!("first 10000 log messages didn't include the one we sent!");
}