From ac2a24ecc9df66279a7b6df478593b34e1d2449f Mon Sep 17 00:00:00 2001 From: Alex Crichton Date: Mon, 6 Jan 2014 10:26:11 -0800 Subject: [PATCH] Support arbitrary stdout/stderr/logger handles This will allow capturing of common things like logging messages, stdout prints (using stdio println), and failure messages (printed to stderr). Any new prints added to libstd should be funneled through these task handles to allow capture as well. Additionally, this commit redirects logging back through a `Logger` trait so the log level can be usefully consumed by an arbitrary logger. This commit also introduces methods to set the task-local stdout handles: * std::io::stdio::set_stdout * std::io::stdio::set_stderr * std::io::logging::set_logger These methods all return the previous logger just in case it needs to be used for inspection. I plan on using this infrastructure for extra::test soon, but we don't quite have the primitives that I'd like to use for it, so it doesn't migrate extra::test at this time. Closes #6369 --- src/libgreen/task.rs | 6 +- src/libnative/lib.rs | 2 +- src/libnative/task.rs | 6 +- src/libstd/io/stdio.rs | 134 +++++++++++++++++++------ src/libstd/logging.rs | 58 +++++++++-- src/libstd/rt/logging.rs | 26 ----- src/libstd/rt/task.rs | 44 ++++---- src/libstd/rt/unwind.rs | 120 ++++++++++++++-------- src/libstd/task.rs | 48 +++------ src/test/run-pass/capturing-logging.rs | 46 +++++++++ 10 files changed, 330 insertions(+), 160 deletions(-) create mode 100644 src/test/run-pass/capturing-logging.rs diff --git a/src/libgreen/task.rs b/src/libgreen/task.rs index 183fe8d0555..62c9ad12535 100644 --- a/src/libgreen/task.rs +++ b/src/libgreen/task.rs @@ -118,13 +118,17 @@ impl GreenTask { f: proc()) -> ~GreenTask { let TaskOpts { watched: _watched, - notify_chan, name, stack_size + notify_chan, name, stack_size, + stderr, stdout, logger, } = opts; let mut green = GreenTask::new(pool, stack_size, f); { let task = green.task.get_mut_ref(); task.name = name; + task.logger = logger; + task.stderr = stderr; + task.stdout = stdout; match notify_chan { Some(chan) => { let on_exit = proc(task_result) { chan.send(task_result) }; diff --git a/src/libnative/lib.rs b/src/libnative/lib.rs index 9c30e94194d..31395216f2b 100644 --- a/src/libnative/lib.rs +++ b/src/libnative/lib.rs @@ -34,7 +34,7 @@ pub mod io; pub mod task; // XXX: this should not exist here -#[cfg(stage0)] +#[cfg(stage0, nativestart)] #[lang = "start"] pub fn lang_start(main: *u8, argc: int, argv: **u8) -> int { use std::cast; diff --git a/src/libnative/task.rs b/src/libnative/task.rs index 661358a64e9..ad3cbc7db92 100644 --- a/src/libnative/task.rs +++ b/src/libnative/task.rs @@ -55,11 +55,15 @@ pub fn spawn(f: proc()) { pub fn spawn_opts(opts: TaskOpts, f: proc()) { let TaskOpts { watched: _watched, - notify_chan, name, stack_size + notify_chan, name, stack_size, + logger, stderr, stdout, } = opts; let mut task = ~Task::new(); task.name = name; + task.logger = logger; + task.stderr = stderr; + task.stdout = stdout; match notify_chan { Some(chan) => { let on_exit = proc(task_result) { chan.send(task_result) }; diff --git a/src/libstd/io/stdio.rs b/src/libstd/io/stdio.rs index 1e4fa7968dc..7d930894049 100644 --- a/src/libstd/io/stdio.rs +++ b/src/libstd/io/stdio.rs @@ -32,8 +32,12 @@ use io::{Reader, Writer, io_error, IoError, OtherIoError, standard_error, EndOfFile}; use libc; use option::{Option, Some, None}; +use prelude::drop; use result::{Ok, Err}; +use rt::local::Local; use rt::rtio::{DontClose, IoFactory, LocalIo, RtioFileStream, RtioTTY}; +use rt::task::Task; +use util; // And so begins the tale of acquiring a uv handle to a stdio stream on all // platforms in all situations. Our story begins by splitting the world into two @@ -101,6 +105,44 @@ pub fn stderr() -> StdWriter { src(libc::STDERR_FILENO, false, |src| StdWriter { inner: src }) } +fn reset_helper(w: ~Writer, + f: |&mut Task, ~Writer| -> Option<~Writer>) -> Option<~Writer> { + let mut t = Local::borrow(None::); + // Be sure to flush any pending output from the writer + match f(t.get(), w) { + Some(mut w) => { + drop(t); + w.flush(); + Some(w) + } + None => None + } +} + +/// Resets the task-local stdout handle to the specified writer +/// +/// This will replace the current task's stdout handle, returning the old +/// handle. All future calls to `print` and friends will emit their output to +/// this specified handle. +/// +/// Note that this does not need to be called for all new tasks; the default +/// output handle is to the process's stdout stream. +pub fn set_stdout(stdout: ~Writer) -> Option<~Writer> { + reset_helper(stdout, |t, w| util::replace(&mut t.stdout, Some(w))) +} + +/// Resets the task-local stderr handle to the specified writer +/// +/// This will replace the current task's stderr handle, returning the old +/// handle. Currently, the stderr handle is used for printing failure messages +/// during task failure. +/// +/// Note that this does not need to be called for all new tasks; the default +/// output handle is to the process's stderr stream. +pub fn set_stderr(stderr: ~Writer) -> Option<~Writer> { + reset_helper(stderr, |t, w| util::replace(&mut t.stderr, Some(w))) +} + // Helper to access the local task's stdout handle // // Note that this is not a safe function to expose because you can create an @@ -112,38 +154,49 @@ pub fn stderr() -> StdWriter { // }) // }) fn with_task_stdout(f: |&mut Writer|) { - use rt::local::Local; - use rt::task::Task; + let task: Option<~Task> = Local::try_take(); + match task { + Some(mut task) => { + // Printing may run arbitrary code, so ensure that the task is in + // TLS to allow all std services. Note that this means a print while + // printing won't use the task's normal stdout handle, but this is + // necessary to ensure safety (no aliasing). + let mut my_stdout = task.stdout.take(); + Local::put(task); - unsafe { - let task: Option<*mut Task> = Local::try_unsafe_borrow(); - match task { - Some(task) => { - match (*task).stdout_handle { - Some(ref mut handle) => f(*handle), - None => { - let handle = ~LineBufferedWriter::new(stdout()); - let mut handle = handle as ~Writer; - f(handle); - (*task).stdout_handle = Some(handle); + if my_stdout.is_none() { + my_stdout = Some(~LineBufferedWriter::new(stdout()) as ~Writer); + } + f(*my_stdout.get_mut_ref()); + + // Note that we need to be careful when putting the stdout handle + // back into the task. If the handle was set to `Some` while + // printing, then we can run aribitrary code when destroying the + // previous handle. This means that the local task needs to be in + // TLS while we do this. + // + // To protect against this, we do a little dance in which we + // temporarily take the task, swap the handles, put the task in TLS, + // and only then drop the previous handle. + let mut t = Local::borrow(None::); + let prev = util::replace(&mut t.get().stdout, my_stdout); + drop(t); + drop(prev); + } + + None => { + struct Stdout; + impl Writer for Stdout { + fn write(&mut self, data: &[u8]) { + unsafe { + libc::write(libc::STDOUT_FILENO, + data.as_ptr() as *libc::c_void, + data.len() as libc::size_t); } } } - - None => { - struct Stdout; - impl Writer for Stdout { - fn write(&mut self, data: &[u8]) { - unsafe { - libc::write(libc::STDOUT_FILENO, - data.as_ptr() as *libc::c_void, - data.len() as libc::size_t); - } - } - } - let mut io = Stdout; - f(&mut io as &mut Writer); - } + let mut io = Stdout; + f(&mut io as &mut Writer); } } } @@ -313,4 +366,29 @@ mod tests { stdout(); stderr(); }) + + iotest!(fn capture_stdout() { + use io::comm_adapters::{PortReader, ChanWriter}; + + let (p, c) = Chan::new(); + let (mut r, w) = (PortReader::new(p), ChanWriter::new(c)); + do spawn { + set_stdout(~w as ~Writer); + println!("hello!"); + } + assert_eq!(r.read_to_str(), ~"hello!\n"); + }) + + iotest!(fn capture_stderr() { + use io::comm_adapters::{PortReader, ChanWriter}; + + let (p, c) = Chan::new(); + let (mut r, w) = (PortReader::new(p), ChanWriter::new(c)); + do spawn { + set_stderr(~w as ~Writer); + fail!("my special message"); + } + let s = r.read_to_str(); + assert!(s.contains("my special message")); + }) } diff --git a/src/libstd/logging.rs b/src/libstd/logging.rs index d1b812ae365..d10b873c5b5 100644 --- a/src/libstd/logging.rs +++ b/src/libstd/logging.rs @@ -96,10 +96,15 @@ start, print out all modules registered for logging, and then exit. */ use fmt; -use option::*; +use io::buffered::LineBufferedWriter; +use io; +use io::Writer; +use ops::Drop; +use option::{Some, None, Option}; +use prelude::drop; use rt::local::Local; -use rt::logging::{Logger, StdErrLogger}; use rt::task::Task; +use util; /// Debug log level pub static DEBUG: u32 = 4; @@ -110,6 +115,32 @@ pub static WARN: u32 = 2; /// Error log level pub static ERROR: u32 = 1; +/// A trait used to represent an interface to a task-local logger. Each task +/// can have its own custom logger which can respond to logging messages +/// however it likes. +pub trait Logger { + /// Logs a single message described by the `args` structure. The level is + /// provided in case you want to do things like color the message, etc. + fn log(&mut self, level: u32, args: &fmt::Arguments); +} + +struct DefaultLogger { + handle: LineBufferedWriter, +} + +impl Logger for DefaultLogger { + // by default, just ignore the level + fn log(&mut self, _level: u32, args: &fmt::Arguments) { + fmt::writeln(&mut self.handle, args); + } +} + +impl Drop for DefaultLogger { + fn drop(&mut self) { + self.handle.flush(); + } +} + /// This function is called directly by the compiler when using the logging /// macros. This function does not take into account whether the log level /// specified is active or not, it will always log something if this method is @@ -117,17 +148,32 @@ pub static ERROR: u32 = 1; /// /// It is not recommended to call this function directly, rather it should be /// invoked through the logging family of macros. -pub fn log(_level: u32, args: &fmt::Arguments) { +pub fn log(level: u32, args: &fmt::Arguments) { + // See io::stdio::with_task_stdout for why there's a few dances here. The + // gist of it is that arbitrary code can run during logging (and set an + // arbitrary logging handle into the task) so we need to be careful that the + // local task is in TLS while we're running arbitrary code. let mut logger = { let mut task = Local::borrow(None::); task.get().logger.take() }; if logger.is_none() { - logger = Some(StdErrLogger::new()); + logger = Some(~DefaultLogger { + handle: LineBufferedWriter::new(io::stderr()), + } as ~Logger); } - logger.get_mut_ref().log(args); + logger.get_mut_ref().log(level, args); let mut task = Local::borrow(None::); - task.get().logger = logger; + let prev = util::replace(&mut task.get().logger, logger); + drop(task); + drop(prev); +} + +/// Replaces the task-local logger with the specified logger, returning the old +/// logger. +pub fn set_logger(logger: ~Logger) -> Option<~Logger> { + let mut task = Local::borrow(None::); + util::replace(&mut task.get().logger, Some(logger)) } diff --git a/src/libstd/rt/logging.rs b/src/libstd/rt/logging.rs index dfcf49734df..586d26a24e3 100644 --- a/src/libstd/rt/logging.rs +++ b/src/libstd/rt/logging.rs @@ -8,13 +8,9 @@ // option. This file may not be copied, modified, or distributed // except according to those terms. -use fmt; use from_str::from_str; use libc::exit; use option::{Some, None, Option}; -use io; -use io::stdio::StdWriter; -use io::buffered::LineBufferedWriter; use rt::crate_map::{ModEntry, CrateMap, iter_crate_map, get_crate_map}; use str::StrSlice; use vec::{ImmutableVector, MutableTotalOrdVector}; @@ -168,28 +164,6 @@ fn update_log_settings(crate_map: &CrateMap, settings: ~str) { } } -pub trait Logger { - fn log(&mut self, args: &fmt::Arguments); -} - -/// This logger emits output to the stderr of the process, and contains a lazily -/// initialized event-loop driven handle to the stream. -pub struct StdErrLogger { - priv handle: LineBufferedWriter, -} - -impl StdErrLogger { - pub fn new() -> StdErrLogger { - StdErrLogger { handle: LineBufferedWriter::new(io::stderr()) } - } -} - -impl Logger for StdErrLogger { - fn log(&mut self, args: &fmt::Arguments) { - fmt::writeln(&mut self.handle as &mut io::Writer, args); - } -} - /// Configure logging by traversing the crate map and setting the /// per-module global logging flags based on the logging spec pub fn init() { diff --git a/src/libstd/rt/task.rs b/src/libstd/rt/task.rs index 3efa979e515..56fab6fe499 100644 --- a/src/libstd/rt/task.rs +++ b/src/libstd/rt/task.rs @@ -20,6 +20,7 @@ use cleanup; use io::Writer; use iter::{Iterator, Take}; use local_data; +use logging::Logger; use ops::Drop; use option::{Option, Some, None}; use prelude::drop; @@ -29,7 +30,6 @@ use rt::borrowck::BorrowRecord; use rt::borrowck; use rt::local::Local; use rt::local_heap::LocalHeap; -use rt::logging::StdErrLogger; use rt::rtio::LocalIo; use rt::unwind::Unwinder; use send_str::SendStr; @@ -58,8 +58,9 @@ pub struct Task { // Dynamic borrowck debugging info borrow_list: Option<~[BorrowRecord]>, - logger: Option, - stdout_handle: Option<~Writer>, + logger: Option<~Logger>, + stdout: Option<~Writer>, + stderr: Option<~Writer>, priv imp: Option<~Runtime>, } @@ -97,7 +98,8 @@ impl Task { name: None, borrow_list: None, logger: None, - stdout_handle: None, + stdout: None, + stderr: None, imp: None, } } @@ -126,13 +128,21 @@ impl Task { // Run the task main function, then do some cleanup. f.finally(|| { - fn flush(w: Option<~Writer>) { - match w { - Some(mut w) => { w.flush(); } - None => {} - } + fn close_outputs() { + let mut task = Local::borrow(None::); + let logger = task.get().logger.take(); + let stderr = task.get().stderr.take(); + let stdout = task.get().stdout.take(); + drop(task); + drop(logger); // loggers are responsible for flushing + match stdout { Some(mut w) => w.flush(), None => {} } + match stderr { Some(mut w) => w.flush(), None => {} } } + // First, flush/destroy the user stdout/logger because these + // destructors can run arbitrary code. + close_outputs(); + // First, destroy task-local storage. This may run user dtors. // // FIXME #8302: Dear diary. I'm so tired and confused. @@ -164,16 +174,12 @@ impl Task { // Destroy remaining boxes. Also may run user dtors. unsafe { cleanup::annihilate(); } - // Finally flush and destroy any output handles which the task - // owns. There are no boxes here, and no user destructors should - // run after this any more. - let mut task = Local::borrow(None::); - let stdout = task.get().stdout_handle.take(); - let logger = task.get().logger.take(); - drop(task); - - flush(stdout); - drop(logger); + // Finally, just in case user dtors printed/logged during TLS + // cleanup and annihilation, re-destroy stdout and the logger. + // Note that these will have been initialized with a + // runtime-provided type which we have control over what the + // destructor does. + close_outputs(); }) }; diff --git a/src/libstd/rt/unwind.rs b/src/libstd/rt/unwind.rs index 217782195e6..cb5360200d5 100644 --- a/src/libstd/rt/unwind.rs +++ b/src/libstd/rt/unwind.rs @@ -61,12 +61,14 @@ use cast; use kinds::Send; use libc::{c_void, c_char, size_t}; use option::{Some, None, Option}; +use prelude::drop; use result::{Err, Ok}; use rt::local::Local; use rt::task::Task; use str::Str; use task::TaskResult; use unstable::intrinsics; +use util; use uw = self::libunwind; @@ -385,58 +387,90 @@ pub fn begin_unwind_raw(msg: *c_char, file: *c_char, line: size_t) -> ! { /// This is the entry point of unwinding for fail!() and assert!(). pub fn begin_unwind(msg: M, file: &'static str, line: uint) -> ! { - unsafe { - let task: *mut Task; - // Note that this should be the only allocation performed in this block. - // Currently this means that fail!() on OOM will invoke this code path, - // but then again we're not really ready for failing on OOM anyway. If - // we do start doing this, then we should propagate this allocation to - // be performed in the parent of this task instead of the task that's - // failing. - let msg = ~msg as ~Any; + // Note that this should be the only allocation performed in this block. + // Currently this means that fail!() on OOM will invoke this code path, + // but then again we're not really ready for failing on OOM anyway. If + // we do start doing this, then we should propagate this allocation to + // be performed in the parent of this task instead of the task that's + // failing. + let msg = ~msg as ~Any; + let mut task; + { + let msg_s = match msg.as_ref::<&'static str>() { + Some(s) => *s, + None => match msg.as_ref::<~str>() { + Some(s) => s.as_slice(), + None => "~Any", + } + }; + + // It is assumed that all reasonable rust code will have a local task at + // all times. This means that this `try_take` will succeed almost all of + // the time. There are border cases, however, when the runtime has + // *almost* set up the local task, but hasn't quite gotten there yet. In + // order to get some better diagnostics, we print on failure and + // immediately abort the whole process if there is no local task + // available. + let opt_task: Option<~Task> = Local::try_take(); + task = match opt_task { + Some(t) => t, + None => { + rterrln!("failed at '{}', {}:{}", msg_s, file, line); + unsafe { intrinsics::abort() } + } + }; + + // See comments in io::stdio::with_task_stdout as to why we have to be + // careful when using an arbitrary I/O handle from the task. We + // essentially need to dance to make sure when a task is in TLS when + // running user code. + let name = task.name.take(); { - let msg_s = match msg.as_ref::<&'static str>() { - Some(s) => *s, - None => match msg.as_ref::<~str>() { - Some(s) => s.as_slice(), - None => "~Any", + let n = name.as_ref().map(|n| n.as_slice()).unwrap_or(""); + + match task.stderr.take() { + Some(mut stderr) => { + Local::put(task); + format_args!(|args| ::fmt::writeln(stderr, args), + "task '{}' failed at '{}', {}:{}", + n, msg_s, file, line); + task = Local::take(); + + match util::replace(&mut task.stderr, Some(stderr)) { + Some(prev) => { + Local::put(task); + drop(prev); + task = Local::take(); + } + None => {} + } } - }; - - // It is assumed that all reasonable rust code will have a local - // task at all times. This means that this `try_unsafe_borrow` will - // succeed almost all of the time. There are border cases, however, - // when the runtime has *almost* set up the local task, but hasn't - // quite gotten there yet. In order to get some better diagnostics, - // we print on failure and immediately abort the whole process if - // there is no local task available. - match Local::try_unsafe_borrow() { - Some(t) => { - task = t; - let n = (*task).name.as_ref() - .map(|n| n.as_slice()).unwrap_or(""); - + None => { rterrln!("task '{}' failed at '{}', {}:{}", n, msg_s, file, line); } - None => { - rterrln!("failed at '{}', {}:{}", msg_s, file, line); - intrinsics::abort(); - } - } - - if (*task).unwinder.unwinding { - // If a task fails while it's already unwinding then we - // have limited options. Currently our preference is to - // just abort. In the future we may consider resuming - // unwinding or otherwise exiting the task cleanly. - rterrln!("task failed during unwinding (double-failure - total drag!)") - rterrln!("rust must abort now. so sorry."); - intrinsics::abort(); } } + task.name = name; + if task.unwinder.unwinding { + // If a task fails while it's already unwinding then we + // have limited options. Currently our preference is to + // just abort. In the future we may consider resuming + // unwinding or otherwise exiting the task cleanly. + rterrln!("task failed during unwinding (double-failure - total drag!)") + rterrln!("rust must abort now. so sorry."); + unsafe { intrinsics::abort() } + } + } + + // The unwinder won't actually use the task at all, so we put the task back + // into TLS right before we invoke the unwinder, but this means we need an + // unsafe reference back to the unwinder once it's in TLS. + Local::put(task); + unsafe { + let task: *mut Task = Local::unsafe_borrow(); (*task).unwinder.begin_unwind(msg); } } diff --git a/src/libstd/task.rs b/src/libstd/task.rs index bc45b9e3c4a..900b6d49cc6 100644 --- a/src/libstd/task.rs +++ b/src/libstd/task.rs @@ -55,7 +55,9 @@ use any::Any; use comm::{Chan, Port}; +use io::Writer; use kinds::Send; +use logging::Logger; use option::{None, Some, Option}; use result::{Result, Ok, Err}; use rt::local::Local; @@ -103,7 +105,10 @@ pub struct TaskOpts { watched: bool, notify_chan: Option>, name: Option, - stack_size: Option + stack_size: Option, + logger: Option<~Logger>, + stdout: Option<~Writer>, + stderr: Option<~Writer>, } /** @@ -138,22 +143,6 @@ pub fn task() -> TaskBuilder { } impl TaskBuilder { - fn consume(mut self) -> TaskBuilder { - let gen_body = self.gen_body.take(); - let notify_chan = self.opts.notify_chan.take(); - let name = self.opts.name.take(); - TaskBuilder { - opts: TaskOpts { - watched: self.opts.watched, - notify_chan: notify_chan, - name: name, - stack_size: self.opts.stack_size - }, - gen_body: gen_body, - can_not_copy: None, - } - } - /// Cause the parent task to collect the child's exit status (and that of /// all transitively-watched grandchildren) before reporting its own. pub fn watched(&mut self) { @@ -250,26 +239,12 @@ impl TaskBuilder { */ pub fn spawn(mut self, f: proc()) { let gen_body = self.gen_body.take(); - let notify_chan = self.opts.notify_chan.take(); - let name = self.opts.name.take(); - let x = self.consume(); - let opts = TaskOpts { - watched: x.opts.watched, - notify_chan: notify_chan, - name: name, - stack_size: x.opts.stack_size - }; let f = match gen_body { - Some(gen) => { - gen(f) - } - None => { - f - } + Some(gen) => gen(f), + None => f }; - let t: ~Task = Local::take(); - t.spawn_sibling(opts, f); + t.spawn_sibling(self.opts, f); } /** @@ -316,7 +291,10 @@ impl TaskOpts { watched: true, notify_chan: None, name: None, - stack_size: None + stack_size: None, + logger: None, + stdout: None, + stderr: None, } } } diff --git a/src/test/run-pass/capturing-logging.rs b/src/test/run-pass/capturing-logging.rs new file mode 100644 index 00000000000..f5230416041 --- /dev/null +++ b/src/test/run-pass/capturing-logging.rs @@ -0,0 +1,46 @@ +// Copyright 2014 The Rust Project Developers. See the COPYRIGHT +// file at the top-level directory of this distribution and at +// http://rust-lang.org/COPYRIGHT. +// +// Licensed under the Apache License, Version 2.0 or the MIT license +// , at your +// option. This file may not be copied, modified, or distributed +// except according to those terms. + +// xfail-fast +// exec-env:RUST_LOG=info + +#[no_uv]; +extern mod native; + +use std::fmt; +use std::io::comm_adapters::{PortReader, ChanWriter}; +use std::logging::{set_logger, Logger}; + +struct MyWriter(ChanWriter); + +impl Logger for MyWriter { + fn log(&mut self, _level: u32, args: &fmt::Arguments) { + let MyWriter(ref mut inner) = *self; + fmt::writeln(inner as &mut Writer, args); + } +} + +#[start] +fn start(argc: int, argv: **u8) -> int { + do native::start(argc, argv) { + main(); + } +} + +fn main() { + let (p, c) = Chan::new(); + let (mut r, w) = (PortReader::new(p), ChanWriter::new(c)); + do spawn { + set_logger(~MyWriter(w) as ~Logger); + debug!("debug"); + info!("info"); + } + assert_eq!(r.read_to_str(), ~"info\n"); +}