feat(codegen): restore default log level, improve error messages (#1211)

* feat(codegen): restore default log level, improve error messages

* feedback

Cargo.toml

@@ -98,7 +98,6 @@ tracing = { version = "0.1.37", default-features = false }
 tracing-opentelemetry = "0.19.0"
 tracing-subscriber = { version = "0.3.16", default-features = false, features = [
   "registry",
-  "std",
 ] }
 ttl_cache = "0.5.1"
 utoipa = { version = "3.2.1", features = [ "uuid", "chrono" ] }

cargo-shuttle/src/lib.rs

@@ -1461,7 +1461,7 @@ impl Shuttle {
 
 fn check_version(runtime_path: &Path) -> Result<()> {
     let valid_version = semver::Version::from_str(VERSION)
-        .context("failed to convert runtime version to semver")?;
+        .context("failed to convert cargo-shuttle version to semver")?;
 
     if !runtime_path.try_exists()? {
         bail!("shuttle-runtime is not installed");
@@ -1484,7 +1484,7 @@ fn check_version(runtime_path: &Path) -> Result<()> {
             .1
             .trim(),
     )
-    .context("failed to convert runtime version to semver")?;
+    .context("failed to convert user's runtime version to semver")?;
 
     if semvers_are_compatible(&valid_version, &runtime_version) {
         Ok(())

codegen/src/shuttle_main/mod.rs

@@ -15,21 +15,41 @@ pub(crate) fn r#impl(_attr: TokenStream, item: TokenStream) -> TokenStream {
 
     let tracing_setup = if cfg!(feature = "setup-tracing") {
         Some(quote! {
-                use shuttle_runtime::colored::*;
-                use shuttle_runtime::tracing_subscriber::{registry, fmt, prelude::*};
-                shuttle_runtime::colored::control::set_override(true);
-                registry().with(fmt::layer().without_time()).init();
-
-                println!(
-                    "{}\n{}\nTo disable tracing, remove the default features from {}:\n{}\n{}",
-                    "Shuttle's default tracing subscriber is initialized!".yellow().bold(),
-                    "=".repeat(52).yellow(),
-                    "shuttle-runtime".italic(),
-                    "shuttle-runtime = { version = \"*\", default-features = false }"
-                        .white()
-                        .italic(),
-                    "=".repeat(52).yellow()
-                );
+            use shuttle_runtime::colored::{control, Colorize};
+            control::set_override(true); // always apply color
+
+            use shuttle_runtime::tracing_subscriber::prelude::*;
+            let level = if cfg!(debug_assertions) {
+                "debug,shuttle=trace,h2=info,tower=info,hyper=info"
+            } else {
+                "info,shuttle=trace"
+            };
+            shuttle_runtime::tracing_subscriber::registry()
+                .with(shuttle_runtime::tracing_subscriber::fmt::layer().without_time())
+                .with(
+                    // let user override RUST_LOG in local run if they want to
+                    shuttle_runtime::tracing_subscriber::EnvFilter::try_from_default_env()
+                        // otherwise use our default
+                        .or_else(|_| shuttle_runtime::tracing_subscriber::EnvFilter::try_new(level))
+                        .unwrap()
+                )
+                .init();
+            eprintln!( // stderr to not interfere with runtime's --version output on stdout
+                "{}\n\
+                {}\n\
+                To disable the subscriber and use your own,\n\
+                remove the default features for {}:\n\
+                \n\
+                {}\n\
+                {}",
+                "=".repeat(63).yellow(),
+                "Shuttle's default tracing subscriber is initialized!".yellow().bold(),
+                "shuttle-runtime".italic(),
+                r#"shuttle-runtime = { version = "...", default-features = false }"#
+                    .white()
+                    .italic(),
+                "=".repeat(63).yellow()
+            );
         })
     } else {
         None

common/src/deployment.rs

@@ -29,14 +29,22 @@ pub enum Environment {
 }
 
 pub const DEPLOYER_END_MSG_STARTUP_ERR: &str = "Service startup encountered an error";
+pub const DEPLOYER_END_MSG_BUILD_ERR: &str = "Service build encountered an error";
 pub const DEPLOYER_END_MSG_CRASHED: &str = "Service encountered an error and crashed";
 pub const DEPLOYER_END_MSG_STOPPED: &str = "Service was stopped by the user";
 pub const DEPLOYER_END_MSG_COMPLETED: &str = "Service finished running all on its own";
+pub const DEPLOYER_RUNTIME_START_RESPONSE: &str = "Runtime started successully";
 
-pub const DEPLOYER_END_MESSAGES_BAD: &[&str] =
-    &[DEPLOYER_END_MSG_STARTUP_ERR, DEPLOYER_END_MSG_CRASHED];
-pub const DEPLOYER_END_MESSAGES_GOOD: &[&str] =
-    &[DEPLOYER_END_MSG_STOPPED, DEPLOYER_END_MSG_COMPLETED];
+pub const DEPLOYER_END_MESSAGES_BAD: &[&str] = &[
+    DEPLOYER_END_MSG_STARTUP_ERR,
+    DEPLOYER_END_MSG_BUILD_ERR,
+    DEPLOYER_END_MSG_CRASHED,
+];
+pub const DEPLOYER_END_MESSAGES_GOOD: &[&str] = &[
+    DEPLOYER_END_MSG_STOPPED,
+    DEPLOYER_END_MSG_COMPLETED,
+    DEPLOYER_RUNTIME_START_RESPONSE,
+];
 
 #[cfg(test)]
 mod tests {

deployer/src/deployment/queue.rs

@@ -10,6 +10,7 @@ use cargo_metadata::Message;
 use crossbeam_channel::Sender;
 use flate2::read::GzDecoder;
 use opentelemetry::global;
+use shuttle_common::deployment::DEPLOYER_END_MSG_BUILD_ERR;
 use shuttle_common::log::LogRecorder;
 use tar::Archive;
 use tokio::fs;
@@ -115,7 +116,7 @@ pub async fn task(
 fn build_failed(_id: &Uuid, error: impl std::error::Error + 'static) {
     error!(
         error = &error as &dyn std::error::Error,
-        "service build encountered an error"
+        DEPLOYER_END_MSG_BUILD_ERR,
     );
 }
 

deployer/src/deployment/run.rs

@@ -12,7 +12,7 @@ use shuttle_common::{
     claims::{Claim, ClaimService, InjectPropagation},
     deployment::{
         DEPLOYER_END_MSG_COMPLETED, DEPLOYER_END_MSG_CRASHED, DEPLOYER_END_MSG_STARTUP_ERR,
-        DEPLOYER_END_MSG_STOPPED,
+        DEPLOYER_END_MSG_STOPPED, DEPLOYER_RUNTIME_START_RESPONSE,
     },
     resource,
     storage_manager::ArtifactsStorageManager,
@@ -351,10 +351,11 @@ async fn load(
     match response {
         Ok(response) => {
             let response = response.into_inner();
+            // Make sure to not log the entire response, the resources field is likely to contain secrets.
+            if response.success {
+                info!("successfully loaded service");
+            }
 
-            // Make sure to not log the entire response, the resources field is likely to contain
-            // secrets.
-            info!(success = %response.success, "loading response");
             let resources = response
                 .resources
                 .into_iter()
@@ -417,7 +418,9 @@ async fn run(
 
     match response {
         Ok(response) => {
-            info!(response = ?response.into_inner(),  "start client response: ");
+            if response.into_inner().success {
+                info!(DEPLOYER_RUNTIME_START_RESPONSE);
+            }
 
             // Wait for stop reason
             let reason = stream.message().await.expect("message from tonic stream");
@@ -431,12 +434,11 @@ async fn run(
             }));
         }
         Err(ref status) => {
+            error!(%status, "failed to start service");
             start_crashed_cleanup(
                 &id,
                 Error::Start("runtime failed to start deployment".to_string()),
             );
-
-            error!(%status, "failed to start service");
         }
     }
 }

runtime/Cargo.toml

@@ -70,7 +70,8 @@ next = [
     "shuttle-common/wasm",
 ]
 setup-tracing = [
-    "tracing-subscriber",
+    "tracing-subscriber/default",
+    "tracing-subscriber/env-filter",
     "colored",
     "shuttle-codegen/setup-tracing",
 ]

runtime/src/alpha/mod.rs

@@ -56,10 +56,10 @@ pub async fn start(loader: impl Loader<ProvisionerFactory> + Send + 'static) {
     let args = match Args::parse() {
         Ok(args) => args,
         Err(e) => {
-            println!("runtime received malformed or incorrect args, {e}");
+            eprintln!("Runtime received malformed or incorrect args, {e}");
             let help_str = "[HINT]: Run shuttle with `cargo shuttle run`";
             let wrapper_str = "-".repeat(help_str.len());
-            println!("{wrapper_str}\n{help_str}\n{wrapper_str}");
+            eprintln!("{wrapper_str}\n{help_str}\n{wrapper_str}");
             return;
         }
     };
@@ -186,7 +186,7 @@ where
             service_name,
             deployment_id,
         } = request.into_inner();
-        println!("loading alpha project at {path}");
+        println!("loading alpha service at {path}");
 
         let secrets = BTreeMap::from_iter(secrets.into_iter());
 
@@ -225,6 +225,7 @@ where
 
         let loader = self.loader.lock().unwrap().deref_mut().take().unwrap();
 
+        // send to new thread to catch panics
         let service =
             match tokio::spawn(loader.load(factory, resource_tracker, deployment_id)).await {
                 Ok(res) => match res {
@@ -302,7 +303,7 @@ where
         &self,
         request: Request<StartRequest>,
     ) -> Result<Response<StartResponse>, Status> {
-        println!("alpha starting");
+        println!("alpha runtime starting");
         let service = self.service.lock().unwrap().deref_mut().take();
         let service = service.unwrap();
 
@@ -344,13 +345,13 @@ where
                                     },
                                 };
 
-                                println!( "service panicked: {msg}");
+                                println!("service panicked: {msg}");
 
                                 let _ = stopped_tx
                                     .send((StopReason::Crash, msg))
                                     .map_err(|e| println!("{e}"));
                             } else {
-                                println!( "service crashed: {error}");
+                                println!("service crashed: {error}");
                                 let _ = stopped_tx
                                     .send((StopReason::Crash, error.to_string()))
                                     .map_err(|e| println!("{e}"));

service/src/builder.rs

@@ -56,7 +56,8 @@ impl BuiltService {
 }
 
 fn extract_shuttle_toml_name(path: PathBuf) -> anyhow::Result<String> {
-    let shuttle_toml = read_to_string(path).context("Shuttle.toml not found")?;
+    let shuttle_toml =
+        read_to_string(path.as_path()).map_err(|_| anyhow!("{} not found", path.display()))?;
 
     let toml: toml::Value =
         toml::from_str(&shuttle_toml).context("failed to parse Shuttle.toml")?;