Tracing endpoint (#3)

* Add a TracingConfig and some components

Co-authored-by: Deirdre Connolly <deirdre@zfnd.org>

* Restructure, use dependency injection, initialize tracing

* Start a placeholder loop in start command

* Add hyper alpha.1, bump tokio to alpha.4

* Hello world endpoint using async/await from hyper 0.13 alpha

Also cleaned up some linter messages.

Co-authored-by: Henry de Valence <hdevalence@hdevalence.ca>

* Update to tracing_subscriber 0.1

* fmt

* add rust-toolchain

* Remove hyper::Version import

* wip: start filter_handler impl

* Add .rustfmt.toml

* rustfmt

* Tidy up .rustfmt.toml

* Add filter reloading handling.

* bump toolchain

* Remove generated hello world acceptance tests.

These test the behaviour of the autogenerated binary and work as examples of
how to test the behaviour of abscissa binaries.  Since we don't print "Hello
World" any more, they fail, but we don't yet have replacement behaviour to add
tests for, so they're removed for now.

* Clean up config file handling with Option::and_then.

.rustfmt.toml

@@ -0,0 +1,66 @@
+max_width = 100
+hard_tabs = false
+tab_spaces = 4
+newline_style = "Auto"
+use_small_heuristics = "Default"
+indent_style = "Block"
+wrap_comments = false
+format_code_in_doc_comments = false
+comment_width = 80
+normalize_comments = false
+normalize_doc_attributes = false
+#license_template_path = ""
+format_strings = false
+format_macro_matchers = false
+format_macro_bodies = true
+empty_item_single_line = true
+struct_lit_single_line = true
+fn_single_line = false
+where_single_line = false
+imports_indent = "Block"
+imports_layout = "Mixed"
+merge_imports = false
+reorder_imports = true
+reorder_modules = true
+reorder_impl_items = false
+type_punctuation_density = "Wide"
+space_before_colon = false
+space_after_colon = true
+spaces_around_ranges = false
+binop_separator = "Front"
+remove_nested_parens = true
+combine_control_expr = true
+overflow_delimited_expr = false
+struct_field_align_threshold = 0
+enum_discrim_align_threshold = 0
+match_arm_blocks = true
+force_multiline_blocks = false
+fn_args_layout = "Tall"
+brace_style = "SameLineWhere"
+control_brace_style = "AlwaysSameLine"
+trailing_semicolon = true
+trailing_comma = "Vertical"
+match_block_trailing_comma = false
+blank_lines_upper_bound = 1
+blank_lines_lower_bound = 0
+edition = "2018"
+version = "One"
+inline_attribute_width = 0
+merge_derives = true
+use_try_shorthand = false
+use_field_init_shorthand = false
+force_explicit_abi = true
+condense_wildcard_suffixes = false
+color = "Auto"
+#required_version = "1.3.0"
+unstable_features = false
+disable_all_formatting = false
+skip_children = false
+hide_parse_errors = false
+error_on_line_overflow = false
+error_on_unformatted = false
+report_todo = "Never"
+report_fixme = "Never"
+ignore = []
+emit_mode = "Files"
+make_backup = false

rust-toolchain

@@ -0,0 +1 @@
+nightly-2019-09-05

zebrad/Cargo.toml

@@ -10,6 +10,14 @@ failure = "0.1"
 gumdrop = "0.6"
 lazy_static = "1"
 serde = { version = "1", features = ["serde_derive"] }
+toml = "0.5"
+tokio = "=0.2.0-alpha.4"
+tracing = "0.1"
+tracing-subscriber = "0.1"
+tracing-log = "=0.0.1-alpha.2"
+hyper = "=0.13.0-alpha.1"
+futures-core-preview = { version = "=0.3.0-alpha.18" }
+futures-util-preview = { version = "=0.3.0-alpha.18" }
 
 [dev-dependencies.abscissa_core]
 version = "0.3.0"

zebrad/src/application.rs

@@ -2,7 +2,7 @@
 
 use crate::{commands::ZebradCmd, config::ZebradConfig};
 use abscissa_core::{
-    application, config, logging, Application, EntryPoint, FrameworkError, StandardPaths,
+    application, config, logging, Application, Component, EntryPoint, FrameworkError, StandardPaths,
 };
 use lazy_static::lazy_static;
 
@@ -78,13 +78,32 @@ impl Application for ZebradApp {
         &mut self.state
     }
 
+    /// Override the provided impl to skip the default logging component.
+    ///
+    /// We want to use tracing as the log subscriber in our tracing component,
+    /// so only initialize the abscissa Terminal component.
+    fn framework_components(
+        &mut self,
+        _command: &Self::Cmd,
+    ) -> Result<Vec<Box<dyn Component<Self>>>, FrameworkError> {
+        use abscissa_core::terminal::{component::Terminal, ColorChoice};
+        // XXX abscissa uses self.term_colors(command), check if we should match
+        let terminal = Terminal::new(ColorChoice::Auto);
+        Ok(vec![Box::new(terminal)])
+    }
+
     /// Register all components used by this application.
     ///
     /// If you would like to add additional components to your application
     /// beyond the default ones provided by the framework, this is the place
     /// to do so.
     fn register_components(&mut self, command: &Self::Cmd) -> Result<(), FrameworkError> {
-        let components = self.framework_components(command)?;
+        use crate::components::{tokio::TokioComponent, tracing::TracingEndpoint};
+
+        let mut components = self.framework_components(command)?;
+        components.push(Box::new(TokioComponent::new()?));
+        components.push(Box::new(TracingEndpoint::new()?));
+
         self.state.components.register(components)
     }
 

zebrad/src/commands.rs

@@ -43,16 +43,14 @@ pub enum ZebradCmd {
 impl Configurable<ZebradConfig> for ZebradCmd {
     /// Location of the configuration file
     fn config_path(&self) -> Option<PathBuf> {
-        // Check if the config file exists, and if it does not, ignore it.
-        // If you'd like for a missing configuration file to be a hard error
-        // instead, always return `Some(CONFIG_FILE)` here.
-        let filename = PathBuf::from(CONFIG_FILE);
+        let filename = std::env::current_dir().ok().map(|mut dir_path| {
+            dir_path.push(CONFIG_FILE);
+            dir_path
+        });
 
-        if filename.exists() {
-            Some(filename)
-        } else {
-            None
-        }
+        let if_exists = |f: PathBuf| if f.exists() { Some(f) } else { None };
+
+        filename.and_then(|f| if_exists(f))
     }
 
     /// Apply changes to the config after it's been loaded, e.g. overriding
@@ -60,10 +58,7 @@ impl Configurable<ZebradConfig> for ZebradCmd {
     ///
     /// This can be safely deleted if you don't want to override config
     /// settings from command-line options.
-    fn process_config(
-        &self,
-        config: ZebradConfig,
-    ) -> Result<ZebradConfig, FrameworkError> {
+    fn process_config(&self, config: ZebradConfig) -> Result<ZebradConfig, FrameworkError> {
         match self {
             ZebradCmd::Start(cmd) => cmd.override_config(config),
             _ => Ok(config),

zebrad/src/commands/start.rs

@@ -16,16 +16,34 @@ use abscissa_core::{config, Command, FrameworkError, Options, Runnable};
 /// <https://docs.rs/gumdrop/>
 #[derive(Command, Debug, Options)]
 pub struct StartCmd {
-    /// To whom are we saying hello?
+    /// Filter strings
     #[options(free)]
-    recipient: Vec<String>,
+    filters: Vec<String>,
 }
 
 impl Runnable for StartCmd {
     /// Start the application.
     fn run(&self) {
+        warn!("starting application");
         let config = app_config();
-        println!("Hello, {}!", &config.hello.recipient);
+        println!("filter: {}!", &config.tracing.filter);
+
+        let default_config = ZebradConfig::default();
+        println!("Default config: {:?}", default_config);
+
+        println!("Toml:\n{}", toml::to_string(&default_config).unwrap());
+
+        info!("Starting placeholder loop");
+
+        use crate::components::tokio::TokioComponent;
+
+        app_reader()
+            .state()
+            .components
+            .get_downcast_ref::<TokioComponent>()
+            .expect("TokioComponent should be available")
+            .rt
+            .block_on(tokio::future::pending::<()>());
     }
 }
 
@@ -33,12 +51,9 @@ impl config::Override<ZebradConfig> for StartCmd {
     // Process the given command line options, overriding settings from
     // a configuration file using explicit flags taken from command-line
     // arguments.
-    fn override_config(
-        &self,
-        mut config: ZebradConfig,
-    ) -> Result<ZebradConfig, FrameworkError> {
-        if !self.recipient.is_empty() {
-            config.hello.recipient = self.recipient.join(" ");
+    fn override_config(&self, mut config: ZebradConfig) -> Result<ZebradConfig, FrameworkError> {
+        if !self.filters.is_empty() {
+            config.tracing.filter = self.filters.join(",");
         }
 
         Ok(config)

zebrad/src/commands/version.rs

@@ -12,10 +12,6 @@ pub struct VersionCmd {}
 impl Runnable for VersionCmd {
     /// Print version message
     fn run(&self) {
-        println!(
-            "{} {}",
-            ZebradCmd::name(),
-            ZebradCmd::version()
-        );
+        println!("{} {}", ZebradCmd::name(), ZebradCmd::version());
     }
 }

zebrad/src/components.rs

@@ -0,0 +1,2 @@
+pub mod tokio;
+pub mod tracing;

zebrad/src/components/tokio.rs

@@ -0,0 +1,19 @@
+//! A component owning the Tokio runtime.
+
+use abscissa_core::{Component, FrameworkError};
+
+use tokio::runtime::Runtime;
+
+/// An Abscissa component which owns a Tokio runtime.
+#[derive(Component, Debug)]
+pub struct TokioComponent {
+    pub rt: Runtime,
+}
+
+impl TokioComponent {
+    pub fn new() -> Result<Self, FrameworkError> {
+        Ok(Self {
+            rt: Runtime::new().unwrap(),
+        })
+    }
+}

zebrad/src/components/tracing.rs

@@ -0,0 +1,144 @@
+//! An HTTP endpoint for dynamically setting tracing filters.
+
+use crate::components::tokio::TokioComponent;
+
+use abscissa_core::{err, Component, FrameworkError, FrameworkErrorKind};
+
+use hyper::service::{make_service_fn, service_fn};
+use hyper::{Body, Request, Response, Server};
+
+use tracing::Subscriber;
+use tracing_log::LogTracer;
+use tracing_subscriber::{filter::Filter, reload::Handle, FmtSubscriber};
+
+/// Abscissa component which runs a tracing filter endpoint.
+#[derive(Component)]
+#[component(inject = "init_tokio(zebrad::components::tokio::TokioComponent)")]
+// XXX ideally this would be TracingEndpoint<S: Subscriber>
+// but this doesn't seem to play well with derive(Component)
+pub struct TracingEndpoint {
+    filter_handle: Handle<Filter, FmtSubscriber>,
+}
+
+impl ::std::fmt::Debug for TracingEndpoint {
+    fn fmt(&self, f: &mut ::std::fmt::Formatter) -> Result<(), ::std::fmt::Error> {
+        // Debug is required by Component, can't be derived as a Handle is not Debug
+        write!(f, "TracingEndpoint")
+    }
+}
+
+impl TracingEndpoint {
+    /// Create the component.
+    pub fn new() -> Result<Self, FrameworkError> {
+        // Set the global logger for the log crate to emit tracing events.
+        // XXX this is only required if we have a dependency that uses log;
+        // currently this is maybe only abscissa itself?
+        LogTracer::init().map_err(|e| {
+            err!(
+                FrameworkErrorKind::ComponentError,
+                "could not set log subscriber: {}",
+                e
+            )
+        })?;
+
+        let builder = FmtSubscriber::builder()
+            .with_ansi(true)
+            // Set the initial filter from the RUST_LOG env variable
+            // XXX pull from config file?
+            .with_filter(Filter::from_default_env())
+            .with_filter_reloading();
+        let filter_handle = builder.reload_handle();
+        let subscriber = builder.finish();
+
+        // Set that subscriber to be the global tracing subscriber
+        tracing::subscriber::set_global_default(subscriber).map_err(|e| {
+            err!(
+                FrameworkErrorKind::ComponentError,
+                "could not set tracing subscriber: {}",
+                e
+            )
+        })?;
+
+        Ok(Self { filter_handle })
+    }
+
+    /// Do setup after receiving a tokio runtime.
+    pub fn init_tokio(&mut self, tokio_component: &TokioComponent) -> Result<(), FrameworkError> {
+        info!("Initializing tracing endpoint");
+
+        // Clone the filter handle so it can be moved into make_service_fn closure
+        let handle = self.filter_handle.clone();
+        let service = make_service_fn(move |_| {
+            // Clone again to move into the service_fn closure
+            let handle = handle.clone();
+            async move {
+                Ok::<_, hyper::Error>(service_fn(move |req| filter_handler(handle.clone(), req)))
+            }
+        });
+
+        // XXX load tracing addr from config
+        let addr = "127.0.0.1:3000".parse().unwrap();
+
+        let server = Server::bind(&addr).serve(service);
+
+        tokio_component.rt.spawn(async {
+            if let Err(e) = server.await {
+                error!("Server error: {}", e);
+            }
+        });
+
+        Ok(())
+    }
+}
+
+fn reload_filter_from_chunk<S: Subscriber>(
+    handle: Handle<Filter, S>,
+    chunk: hyper::Chunk,
+) -> Result<(), String> {
+    let bytes = chunk.into_bytes();
+    let body = std::str::from_utf8(bytes.as_ref()).map_err(|e| format!("{}", e))?;
+    trace!(request.body = ?body);
+    let filter = body.parse::<Filter>().map_err(|e| format!("{}", e))?;
+    handle.reload(filter).map_err(|e| format!("{}", e))
+}
+
+async fn filter_handler<S: Subscriber>(
+    handle: Handle<Filter, S>,
+    req: Request<Body>,
+) -> Result<Response<Body>, hyper::Error> {
+    use futures_util::TryStreamExt;
+    use hyper::{Method, StatusCode};
+
+    // We can't use #[instrument] because Handle<_,_> is not Debug,
+    // so we create a span manually.
+    let handler_span =
+        info_span!("filter_handler", method = ?req.method(), path = ?req.uri().path());
+    let _enter = handler_span.enter(); // dropping _enter closes the span
+
+    let rsp = match (req.method(), req.uri().path()) {
+        (&Method::GET, "/") => Response::new(Body::from(
+            r#"
+This HTTP endpoint allows dynamic control of the filter applied to
+tracing events.  To set the filter, POST it to /filter:
+
+curl -X POST localhost:3000/filter -d "zebrad=trace"
+"#,
+        )),
+        (&Method::POST, "/filter") => {
+            // Combine all HTTP request chunks into one
+            let whole_chunk = req.into_body().try_concat().await?;
+            match reload_filter_from_chunk(handle, whole_chunk) {
+                Err(e) => Response::builder()
+                    .status(StatusCode::BAD_REQUEST)
+                    .body(Body::from(e))
+                    .expect("response with known status code cannot fail"),
+                Ok(()) => Response::new(Body::from("")),
+            }
+        }
+        _ => Response::builder()
+            .status(StatusCode::NOT_FOUND)
+            .body(Body::from(""))
+            .expect("response with known status cannot fail"),
+    };
+    Ok(rsp)
+}

zebrad/src/config.rs

@@ -11,8 +11,8 @@ use serde::{Deserialize, Serialize};
 #[derive(Clone, Config, Debug, Deserialize, Serialize)]
 #[serde(deny_unknown_fields)]
 pub struct ZebradConfig {
-    /// An example configuration section
-    pub hello: ExampleSection,
+    /// Tracing configuration
+    pub tracing: TracingSection,
 }
 
 /// Default configuration settings.
@@ -22,25 +22,23 @@ pub struct ZebradConfig {
 impl Default for ZebradConfig {
     fn default() -> Self {
         Self {
-            hello: ExampleSection::default(),
+            tracing: TracingSection::default(),
         }
     }
 }
 
-/// Example configuration section.
-///
-/// Delete this and replace it with your actual configuration structs.
+/// Tracing configuration section.
 #[derive(Clone, Debug, Deserialize, Serialize)]
 #[serde(deny_unknown_fields)]
-pub struct ExampleSection {
-    /// Example configuration value
-    pub recipient: String,
+pub struct TracingSection {
+    /// The filter used for tracing events.
+    pub filter: String,
 }
 
-impl Default for ExampleSection {
+impl Default for TracingSection {
     fn default() -> Self {
         Self {
-            recipient: "world".to_owned(),
+            filter: "info".to_owned(),
         }
     }
 }

zebrad/src/lib.rs

@@ -4,8 +4,14 @@
 //!
 //! [Abscissa]: https://github.com/iqlusioninc/abscissa
 
-#![deny(warnings, missing_docs, trivial_casts, unused_qualifications)]
+//#![deny(warnings, missing_docs, trivial_casts, unused_qualifications)]
 #![forbid(unsafe_code)]
+#![feature(async_await)]
+
+#[macro_use]
+extern crate tracing;
+
+mod components;
 
 pub mod application;
 pub mod commands;

zebrad/src/prelude.rs

@@ -7,5 +7,6 @@ pub use crate::application::{app_config, app_reader, app_writer};
 /// Commonly used Abscissa traits
 pub use abscissa_core::{Application, Command, Runnable};
 
-/// Logging macros
-pub use abscissa_core::log::{debug, error, info, log, log_enabled, trace, warn};
+// These are disabled because we use tracing.
+// Logging macros
+//pub use abscissa_core::log::{debug, error, info, log, log_enabled, trace, warn};

zebrad/tests/acceptance.rs

@@ -11,7 +11,6 @@
 #![forbid(unsafe_code)]
 
 use abscissa_core::testing::prelude::*;
-use zebrad::config::ZebradConfig;
 use lazy_static::lazy_static;
 
 lazy_static! {
@@ -24,58 +23,6 @@ lazy_static! {
     pub static ref RUNNER: CmdRunner = CmdRunner::default();
 }
 
-/// Use `ZebradConfig::default()` value if no config or args
-#[test]
-fn start_no_args() {
-    let mut runner = RUNNER.clone();
-    let mut cmd = runner.arg("start").capture_stdout().run();
-    cmd.stdout().expect_line("Hello, world!");
-    cmd.wait().unwrap().expect_success();
-}
-
-/// Use command-line argument value
-#[test]
-fn start_with_args() {
-    let mut runner = RUNNER.clone();
-    let mut cmd = runner
-        .args(&["start", "acceptance", "test"])
-        .capture_stdout()
-        .run();
-
-    cmd.stdout().expect_line("Hello, acceptance test!");
-    cmd.wait().unwrap().expect_success();
-}
-
-/// Use configured value
-#[test]
-fn start_with_config_no_args() {
-    let mut config = ZebradConfig::default();
-    config.hello.recipient = "configured recipient".to_owned();
-    let expected_line = format!("Hello, {}!", &config.hello.recipient);
-
-    let mut runner = RUNNER.clone();
-    let mut cmd = runner.config(&config).arg("start").capture_stdout().run();
-    cmd.stdout().expect_line(&expected_line);
-    cmd.wait().unwrap().expect_success();
-}
-
-/// Override configured value with command-line argument
-#[test]
-fn start_with_config_and_args() {
-    let mut config = ZebradConfig::default();
-    config.hello.recipient = "configured recipient".to_owned();
-
-    let mut runner = RUNNER.clone();
-    let mut cmd = runner
-        .config(&config)
-        .args(&["start", "acceptance", "test"])
-        .capture_stdout()
-        .run();
-
-    cmd.stdout().expect_line("Hello, acceptance test!");
-    cmd.wait().unwrap().expect_success();
-}
-
 /// Example of a test which matches a regular expression
 #[test]
 fn version_no_args() {