feat(runtime): improve beta tracing (#1879)

* feat(runtime): improve beta tracing * feat: capture stderr on local run * refa: simplify tracing sub callout
shuttle-hq · Sep 17, 2024 · 89b995f · 89b995f
1 parent 00fa268
commit 89b995f
Show file tree

Hide file tree

Showing 6 changed files with 87 additions and 65 deletions.
diff --git a/Cargo.lock b/Cargo.lock
diff --git a/cargo-shuttle/src/lib.rs b/cargo-shuttle/src/lib.rs
@@ -1960,18 +1960,38 @@ impl Shuttle {
             ),
         ])
         .stdout(std::process::Stdio::piped())
+        .stderr(std::process::Stdio::piped())
         .kill_on_drop(true)
         .spawn()
         .context("spawning runtime process")?;
 
-        let child_stdout = runtime
-            .stdout
-            .take()
-            .context("child process did not have a handle to stdout")?;
-        let mut reader = BufReader::new(child_stdout).lines();
         let raw = run_args.raw;
+        let mut stdout_reader = BufReader::new(
+            runtime
+                .stdout
+                .take()
+                .context("child process did not have a handle to stdout")?,
+        )
+        .lines();
         tokio::spawn(async move {
-            while let Some(line) = reader.next_line().await.unwrap() {
+            while let Some(line) = stdout_reader.next_line().await.unwrap() {
+                if raw {
+                    println!("{}", line);
+                } else {
+                    let log_item = LogItemBeta::new(Utc::now(), "app".to_owned(), line);
+                    println!("{log_item}");
+                }
+            }
+        });
+        let mut stderr_reader = BufReader::new(
+            runtime
+                .stderr
+                .take()
+                .context("child process did not have a handle to stderr")?,
+        )
+        .lines();
+        tokio::spawn(async move {
+            while let Some(line) = stderr_reader.next_line().await.unwrap() {
                 if raw {
                     println!("{}", line);
                 } else {

diff --git a/runtime/Cargo.toml b/runtime/Cargo.toml
@@ -4,7 +4,7 @@ version = "0.47.0"
 edition.workspace = true
 license.workspace = true
 repository.workspace = true
-description = "Runtime to start and manage any service that runs on shuttle"
+description = "Runtime to run a service on the Shuttle platform"
 
 [lib]
 doctest = false
@@ -18,7 +18,6 @@ shuttle-service = { workspace = true }
 
 anyhow = { workspace = true }
 async-trait = { workspace = true }
-colored = { workspace = true, optional = true }
 hyper = { workspace = true, features = ["http1", "server", "tcp"] }
 serde = { workspace = true }
 serde_json = { workspace = true }
@@ -27,6 +26,7 @@ tokio = { workspace = true, features = ["full"] }
 tokio-util = { workspace = true }
 tokio-stream = { workspace = true }
 tonic = { workspace = true }
+tracing = { workspace = true }
 tracing-subscriber = { workspace = true, optional = true }
 
 [dev-dependencies]
@@ -42,5 +42,4 @@ api-client-tracing = ["shuttle-api-client/tracing"]
 setup-tracing = [
     "tracing-subscriber/default",
     "tracing-subscriber/env-filter",
-    "dep:colored",
 ]
diff --git a/runtime/src/beta.rs b/runtime/src/beta.rs
@@ -17,6 +17,7 @@ use shuttle_common::{
     secrets::Secret,
 };
 use shuttle_service::{Environment, ResourceFactory, Service};
+use tracing::{debug, info, trace};
 
 use crate::__internals::{Loader, Runner};
 
@@ -69,6 +70,7 @@ impl BetaEnvArgs {
 }
 
 pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + Send + 'static) {
+    debug!("Parsing environment variables");
     let BetaEnvArgs {
         shuttle,
         project_id,
@@ -86,17 +88,21 @@ pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + S
 
     // start a health check server if requested
     if let Some(healthz_port) = healthz_port {
+        trace!("Starting health check server on port {healthz_port}");
         tokio::task::spawn(async move {
             let make_service = make_service_fn(|_conn| async {
                 Ok::<_, Infallible>(service_fn(|_req| async move {
+                    trace!("Receivied health check");
+                    // TODO: A hook into the `Service` trait can be added here
+                    trace!("Responding to health check");
                     Result::<Response<Body>, hyper::Error>::Ok(Response::new(Body::empty()))
                 }))
             });
             let server = Server::bind(&SocketAddr::new(Ipv4Addr::LOCALHOST.into(), healthz_port))
                 .serve(make_service);
 
             if let Err(e) = server.await {
-                eprintln!("Health check error: {}", e);
+                eprintln!("ERROR: Health check error: {e}");
                 exit(200);
             }
         });
@@ -105,28 +111,30 @@ pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + S
     //
     // LOADING / PROVISIONING PHASE
     //
-    println!("Loading resources...");
+    info!("Loading resources");
 
+    trace!("Getting secrets");
     let secrets: BTreeMap<String, String> = match client
         .get_secrets_beta(&project_id)
         .await
         .and_then(|r| serde_json::from_value(r.output).context("failed to deserialize secrets"))
     {
         Ok(s) => s,
         Err(e) => {
-            eprintln!("Runtime Secret Loading phase failed: {e}");
+            eprintln!("ERROR: Runtime Secret Loading phase failed: {e}");
             exit(101);
         }
     };
 
     // Sort secrets by key
     let secrets = BTreeMap::from_iter(secrets.into_iter().map(|(k, v)| (k, Secret::new(v))));
 
+    // TODO: rework resourcefactory
     let factory = ResourceFactory::new(project_name, secrets.clone(), env);
     let mut resources = match loader.load(factory).await {
         Ok(r) => r,
         Err(e) => {
-            eprintln!("Runtime Loader phase failed: {e}");
+            eprintln!("ERROR: Runtime Loader phase failed: {e}");
             exit(111);
         }
     };
@@ -141,7 +149,7 @@ pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + S
     {
         Ok(v) => v,
         Err(e) => {
-            eprintln!("Runtime Provisioning phase failed: {e}");
+            eprintln!("ERROR: Runtime Provisioning phase failed: {e}");
             exit(121);
         }
     };
@@ -162,31 +170,36 @@ pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + S
             *bytes = serde_json::to_vec(&secrets).expect("to serialize struct");
             continue;
         }
-        println!("Provisioning {:?}", shuttle_resource.r#type);
+
+        info!("Provisioning {:?}", shuttle_resource.r#type);
         loop {
+            trace!("Checking state of {:?}", shuttle_resource.r#type);
             match client
                 .provision_resource_beta(&project_id, shuttle_resource.clone())
                 .await
             {
-                Ok(res) => match res.state.clone() {
-                    ResourceState::Provisioning | ResourceState::Authorizing => {
-                        tokio::time::sleep(tokio::time::Duration::from_millis(2000)).await;
-                    }
-                    ResourceState::Ready => {
-                        *bytes = serde_json::to_vec(&res.output).expect("to serialize struct");
-                        break;
+                Ok(res) => {
+                    trace!("Got response {:?}", res);
+                    match res.state {
+                        ResourceState::Provisioning | ResourceState::Authorizing => {
+                            tokio::time::sleep(tokio::time::Duration::from_millis(2000)).await;
+                        }
+                        ResourceState::Ready => {
+                            *bytes = serde_json::to_vec(&res.output).expect("to serialize struct");
+                            break;
+                        }
+                        bad_state => {
+                            eprintln!(
+                                "ERROR: Runtime Provisioning phase failed: Received {:?} resource with state '{}'.",
+                                shuttle_resource.r#type,
+                                bad_state
+                            );
+                            exit(132);
+                        }
                     }
-                    bad_state => {
-                        eprintln!(
-                            "Runtime Provisioning phase failed: Received '{:?}' resource with state '{}'.",
-                            shuttle_resource.r#type,
-                            bad_state
-                        );
-                        exit(132);
-                    }
-                },
+                }
                 Err(e) => {
-                    eprintln!("Runtime Provisioning phase failed: {e}");
+                    eprintln!("ERROR: Runtime Provisioning phase failed: {e}");
                     exit(131);
                 }
             };
@@ -196,6 +209,7 @@ pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + S
     // TODO?: call API to say running state is being entered
 
     if shuttle {
+        trace!("Sending sidecar shutdown request");
         // Tell sidecar to shut down.
         // Ignore error, since the endpoint does not send a response.
         let _ = client.client.get("/__shuttle/shutdown").send().await;
@@ -208,18 +222,18 @@ pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + S
     let service = match runner.run(resources).await {
         Ok(s) => s,
         Err(e) => {
-            eprintln!("Runtime Resource Initialization phase failed: {e}");
+            eprintln!("ERROR: Runtime Resource Initialization phase failed: {e}");
             exit(151);
         }
     };
 
     //
     // RUNNING PHASE
     //
-    println!("Starting service!");
+    info!("Starting service");
 
     if let Err(e) = service.bind(service_addr).await {
-        eprintln!("Service encountered an error in `bind`: {e}");
+        eprintln!("ERROR: Service encountered an error in `bind`: {e}");
         exit(1);
     }
 }
diff --git a/runtime/src/lib.rs b/runtime/src/lib.rs
@@ -4,7 +4,14 @@
     html_favicon_url = "https://raw.githubusercontent.com/shuttle-hq/shuttle/main/assets/favicon.ico"
 )]
 
+mod alpha;
+mod beta;
+/// Built-in plugins
+mod plugins;
+mod start;
+
 // Public API
+pub use plugins::{Metadata, Secrets};
 pub use shuttle_codegen::main;
 pub use shuttle_service::{
     CustomError, DbInput, DeploymentMetadata, Environment, Error, IntoResource, ResourceFactory,
@@ -15,35 +22,22 @@ pub use shuttle_service::{
 pub use async_trait::async_trait;
 pub use tokio;
 
-mod alpha;
-mod beta;
-mod start;
-
 const NAME: &str = env!("CARGO_PKG_NAME");
 const VERSION: &str = env!("CARGO_PKG_VERSION");
 fn version() -> String {
     format!("{} {}", crate::NAME, crate::VERSION)
 }
 
-pub use plugins::{Metadata, Secrets};
-/// Built-in plugins
-mod plugins;
-
 // Not part of public API
 #[doc(hidden)]
 pub mod __internals {
     // Internals used by the codegen
-    pub use crate::alpha::Alpha;
     pub use crate::start::start;
 
     // Dependencies required by the codegen
     pub use anyhow::Context;
-    #[cfg(feature = "setup-tracing")]
-    pub use colored;
     pub use serde_json;
     pub use strfmt::strfmt;
-    #[cfg(feature = "setup-tracing")]
-    pub use tracing_subscriber;
 
     use super::*;
     use std::future::Future;

diff --git a/runtime/src/start.rs b/runtime/src/start.rs
@@ -1,4 +1,5 @@
 use anyhow::Context;
+use tracing::warn;
 
 use crate::{
     __internals::{Loader, Runner},
@@ -53,43 +54,37 @@ pub async fn start(loader: impl Loader + Send + 'static, runner: impl Runner + S
         return;
     }
 
+    println!("{} {} starting", crate::NAME, crate::VERSION);
+
     let args = match Args::parse() {
         Ok(args) => args,
         Err(e) => {
-            eprintln!("Runtime failed to parse args: {e}");
+            eprintln!("ERROR: Runtime failed to parse args: {e}");
             let help_str = "[HINT]: Run your Shuttle app with `cargo shuttle run`";
             let wrapper_str = "-".repeat(help_str.len());
             eprintln!("{wrapper_str}\n{help_str}\n{wrapper_str}");
             return;
         }
     };
 
-    println!("{} {} executable started", crate::NAME, crate::VERSION);
-
     // this is handled after arg parsing to not interfere with --version above
     #[cfg(feature = "setup-tracing")]
     {
-        use colored::Colorize;
-        use tracing_subscriber::prelude::*;
-
-        colored::control::set_override(true); // always apply color
-
-        tracing_subscriber::registry()
-            .with(tracing_subscriber::fmt::layer().without_time())
+        use tracing_subscriber::{fmt, prelude::*, registry, EnvFilter};
+        registry()
+            .with(fmt::layer().without_time())
             .with(
                 // let user override RUST_LOG in local run if they want to
-                tracing_subscriber::EnvFilter::try_from_default_env()
+                EnvFilter::try_from_default_env()
                     // otherwise use our default
-                    .or_else(|_| tracing_subscriber::EnvFilter::try_new("info,shuttle=trace"))
+                    .or_else(|_| EnvFilter::try_new("info,shuttle=trace"))
                     .unwrap(),
             )
             .init();
 
-        println!(
-            "{}",
-            "Shuttle's default tracing subscriber is initialized!".yellow(),
+        warn!(
+            "Default tracing subscriber initialized (https://docs.shuttle.rs/configuration/logs)"
         );
-        println!("To disable it and use your own, check the docs: https://docs.shuttle.rs/configuration/logs");
     }
 
     if args.beta {