fix: span names, log levels and messages (#1213)

* fix: span names, log levels and messages

* fix: codegen feature

* improve log output

* Update common/src/claims.rs

Co-authored-by: Oddbjørn Grødem <29732646+oddgrd@users.noreply.github.com>

---------

Co-authored-by: Oddbjørn Grødem <29732646+oddgrd@users.noreply.github.com>

Makefile

@@ -28,7 +28,6 @@ GATEWAY_TAG?=$(TAG)
 LOGGER_TAG?=$(TAG)
 PROVISIONER_TAG?=$(TAG)
 RESOURCE_RECORDER_TAG?=$(TAG)
-RESOURCE_RECORDER_TAG?=$(TAG)
 
 DOCKER_BUILD?=docker buildx build
 ifeq ($(CI),true)

cargo-shuttle/src/lib.rs

@@ -843,12 +843,9 @@ impl Shuttle {
             while let Ok(message) = rx.recv() {
                 match message {
                     Message::TextLine(line) => println!("{line}"),
-                    Message::CompilerMessage(message) => {
-                        if let Some(rendered) = message.message.rendered {
-                            println!("{rendered}");
-                        }
+                    message => {
+                        trace!("skipping cargo line: {message:?}")
                     }
-                    _ => {}
                 }
             }
         });

codegen/Cargo.toml

@@ -28,4 +28,3 @@ tokio = { version = "1", features = ["full"] }
 default = []
 frameworks = []
 next = []
-setup-tracing = []

codegen/src/shuttle_main/mod.rs

@@ -13,52 +13,9 @@ pub(crate) fn r#impl(_attr: TokenStream, item: TokenStream) -> TokenStream {
 
     let loader = Loader::from_item_fn(&mut fn_decl);
 
-    let tracing_setup = if cfg!(feature = "setup-tracing") {
-        Some(quote! {
-            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
-    };
-
     quote! {
         #[tokio::main]
         async fn main() {
-            #tracing_setup
             shuttle_runtime::start(loader).await;
         }
 

common/src/claims.rs

@@ -219,7 +219,7 @@ impl Claim {
         let mut validation = Validation::new(jsonwebtoken::Algorithm::EdDSA);
         validation.set_issuer(&[ISS]);
 
-        trace!(token, "converting token to claim");
+        trace!("converting token to claim");
         let mut claim: Self = decode(token, &decoding_key, &validation)
             .map_err(|err| {
                 error!(

common/src/deployment.rs

@@ -31,7 +31,7 @@ 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_STOPPED: &str = "Service was stopped by the user"; // don't include this in end messages so that logs are not stopped too early
 pub const DEPLOYER_END_MSG_COMPLETED: &str = "Service finished running all on its own";
 pub const DEPLOYER_RUNTIME_START_RESPONSE: &str = "Runtime started successully";
 
@@ -40,11 +40,8 @@ pub const DEPLOYER_END_MESSAGES_BAD: &[&str] = &[
     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,
-];
+pub const DEPLOYER_END_MESSAGES_GOOD: &[&str] =
+    &[DEPLOYER_END_MSG_COMPLETED, DEPLOYER_RUNTIME_START_RESPONSE];
 
 #[cfg(test)]
 mod tests {

common/src/log.rs

@@ -202,11 +202,7 @@ where
 
         let metadata = attrs.metadata();
 
-        let message = format!(
-            "{} Entering span {}",
-            metadata.level().colored(),
-            metadata.name().blue(),
-        );
+        let message = format!("{} {}", metadata.level().colored(), metadata.name().blue());
 
         self.log_recorder.record(LogItem::new(
             details.deployment_id,

deployer/src/deployment/mod.rs

@@ -244,7 +244,7 @@ impl DeploymentManager {
         self.queue_send.send(queued).await.unwrap();
     }
 
-    #[instrument(skip(self), fields(deployment_id = %built.id, state = %State::Built))]
+    #[instrument(name = "Starting deployment", skip(self), fields(deployment_id = %built.id, state = %State::Built))]
     pub async fn run_push(&self, built: Built) {
         self.run_send.send(built).await.unwrap();
     }

deployer/src/deployment/queue.rs

@@ -112,17 +112,16 @@ pub async fn task(
     }
 }
 
-#[instrument(skip(_id), fields(deployment_id = %_id, state = %State::Crashed))]
+#[instrument(name = "Build failed", skip(_id), fields(deployment_id = %_id, state = %State::Crashed))]
 fn build_failed(_id: &Uuid, error: impl std::error::Error + 'static) {
     error!(
         error = &error as &dyn std::error::Error,
         DEPLOYER_END_MSG_BUILD_ERR,
     );
 }
 
-#[instrument(skip(queue_client), fields(state = %State::Queued))]
+#[instrument(name = "Waiting for queue slot", skip(queue_client), fields(deployment_id = %id, state = %State::Queued))]
 async fn wait_for_queue(queue_client: impl BuildQueueClient, id: Uuid) -> Result<()> {
-    trace!("getting a build slot");
     loop {
         let got_slot = queue_client.get_slot(id).await?;
 
@@ -138,6 +137,7 @@ async fn wait_for_queue(queue_client: impl BuildQueueClient, id: Uuid) -> Result
     Ok(())
 }
 
+#[instrument(name = "Releasing queue slot", skip(queue_client), fields(deployment_id = %id))]
 async fn remove_from_queue(queue_client: impl BuildQueueClient, id: Uuid) {
     match queue_client.release_slot(id).await {
         Ok(_) => {}
@@ -148,7 +148,7 @@ async fn remove_from_queue(queue_client: impl BuildQueueClient, id: Uuid) {
     }
 }
 
-#[instrument(skip(run_send), fields(deployment_id = %built.id, state = %State::Built))]
+#[instrument(name = "Starting deployment", skip(run_send), fields(deployment_id = %built.id, state = %State::Built))]
 async fn promote_to_run(mut built: Built, run_send: RunSender) {
     let cx = Span::current().context();
 
@@ -173,22 +173,19 @@ pub struct Queued {
 }
 
 impl Queued {
-    #[instrument(skip(self, storage_manager, deployment_updater, log_recorder, secret_recorder), fields(deployment_id = %self.id, state = %State::Building))]
+    #[instrument(name = "Building project", skip(self, storage_manager, deployment_updater, log_recorder, secret_recorder), fields(deployment_id = %self.id, state = %State::Building))]
     async fn handle(
         self,
         storage_manager: ArtifactsStorageManager,
         deployment_updater: impl DeploymentUpdater,
         log_recorder: impl LogRecorder,
         secret_recorder: impl SecretRecorder,
     ) -> Result<Built> {
-        info!("Extracting received data");
-
         let project_path = storage_manager.service_build_path(&self.service_name)?;
 
+        info!("Extracting files");
         extract_tar_gz_data(self.data.as_slice(), &project_path).await?;
 
-        info!("Building deployment");
-
         let (tx, rx): (crossbeam_channel::Sender<Message>, _) = crossbeam_channel::bounded(0);
 
         tokio::task::spawn_blocking(move || {
@@ -208,6 +205,7 @@ impl Queued {
 
         let project_path = project_path.canonicalize()?;
 
+        info!("Building deployment");
         // Currently returns the first found shuttle service in a given workspace.
         let built_service = build_deployment(&project_path, tx.clone()).await?;
 
@@ -220,11 +218,7 @@ impl Queued {
         set_secrets(secrets, &self.service_id, secret_recorder).await?;
 
         if self.will_run_tests {
-            info!(
-                build_line = "Running tests before starting up",
-                "Running deployment's unit tests"
-            );
-
+            info!("Running tests before starting up");
             run_pre_deploy_tests(&project_path, tx).await?;
         }
 
@@ -359,27 +353,29 @@ async fn run_pre_deploy_tests(
     let (read, write) = pipe::pipe();
     let project_path = project_path.to_owned();
 
-    // This needs to be on a separate thread, else deployer will block (reason currently unknown :D)
     tokio::task::spawn_blocking(move || {
-        for message in Message::parse_stream(read) {
-            match message {
-                Ok(message) => {
-                    if let Err(error) = tx.send(message) {
+        for line in read.lines() {
+            match line {
+                Ok(line) => {
+                    if let Err(error) = tx.send(Message::TextLine(line)) {
                         error!("failed to send cargo message on channel: {error}");
                     }
                 }
                 Err(error) => {
-                    error!("failed to parse cargo message: {error}");
+                    error!("failed to read cargo output line: {error}");
                 }
             }
         }
     });
 
     let mut cmd = Command::new("cargo")
         .arg("test")
+        // We set the tests to build with the release profile since deployments compile
+        // with the release profile by default. This means crates don't need to be
+        // recompiled in debug mode for the tests, reducing memory usage during deployment.
         .arg("--release")
         .arg("--jobs=4")
-        .arg("--message-format=json")
+        .arg("--color=always")
         .current_dir(project_path)
         .stdout(Stdio::piped())
         .spawn()

deployer/src/deployment/run.rs

@@ -30,7 +30,7 @@ use tokio::{
     task::{JoinHandle, JoinSet},
 };
 use tonic::{transport::Channel, Code};
-use tracing::{debug, debug_span, error, info, instrument, trace, warn, Instrument};
+use tracing::{debug, debug_span, error, info, instrument, warn, Instrument};
 use tracing_opentelemetry::OpenTelemetrySpanExt;
 use ulid::Ulid;
 use uuid::Uuid;
@@ -147,7 +147,7 @@ pub async fn task(
 #[instrument(skip(active_deployment_getter, runtime_manager))]
 async fn kill_old_deployments(
     service_id: Ulid,
-    deployment_id: Uuid,
+    __deployment_id: Uuid, // prefixed to not catch this span in DeploymentLogLayer
     active_deployment_getter: impl ActiveDeploymentsGetter,
     runtime_manager: Arc<Mutex<RuntimeManager>>,
 ) -> Result<()> {
@@ -159,37 +159,37 @@ async fn kill_old_deployments(
         .await
         .map_err(|e| Error::OldCleanup(Box::new(e)))?
         .into_iter()
-        .filter(|old_id| old_id != &deployment_id)
+        .filter(|old_id| old_id != &__deployment_id)
     {
-        trace!(%old_id, "stopping old deployment");
+        info!("stopping old deployment (id {old_id})");
 
         if !guard.kill(&old_id).await {
-            warn!(id = %old_id, "failed to kill old deployment");
+            warn!("failed to kill old deployment (id {old_id})");
         }
     }
 
     Ok(())
 }
 
-#[instrument(skip(_id), fields(deployment_id = %_id, state = %State::Completed))]
+#[instrument(name = "Cleaning up completed deployment", skip(_id), fields(deployment_id = %_id, state = %State::Completed))]
 fn completed_cleanup(_id: &Uuid) {
     info!("{}", DEPLOYER_END_MSG_COMPLETED);
 }
 
-#[instrument(skip(_id), fields(deployment_id = %_id, state = %State::Stopped))]
+#[instrument(name = "Cleaning up stopped deployment", skip(_id), fields(deployment_id = %_id, state = %State::Stopped))]
 fn stopped_cleanup(_id: &Uuid) {
     info!("{}", DEPLOYER_END_MSG_STOPPED);
 }
 
-#[instrument(skip(_id), fields(deployment_id = %_id, state = %State::Crashed))]
+#[instrument(name = "Cleaning up crashed deployment", skip(_id), fields(deployment_id = %_id, state = %State::Crashed))]
 fn crashed_cleanup(_id: &Uuid, error: impl std::error::Error + 'static) {
     error!(
         error = &error as &dyn std::error::Error,
         "{}", DEPLOYER_END_MSG_CRASHED
     );
 }
 
-#[instrument(skip(_id), fields(deployment_id = %_id, state = %State::Crashed))]
+#[instrument(name = "Cleaning up startup crashed deployment", skip(_id), fields(deployment_id = %_id, state = %State::Crashed))]
 fn start_crashed_cleanup(_id: &Uuid, error: impl std::error::Error + 'static) {
     error!(
         error = &error as &dyn std::error::Error,
@@ -219,7 +219,7 @@ pub struct Built {
 }
 
 impl Built {
-    #[instrument(skip(self, storage_manager, secret_getter, resource_manager, runtime_manager, deployment_updater, kill_old_deployments, cleanup), fields(deployment_id = %self.id, state = %State::Loading))]
+    #[instrument(name = "Loading resources", skip(self, storage_manager, secret_getter, resource_manager, runtime_manager, deployment_updater, kill_old_deployments, cleanup), fields(deployment_id = %self.id, state = %State::Loading))]
     #[allow(clippy::too_many_arguments)]
     async fn handle(
         self,
@@ -304,14 +304,7 @@ async fn load(
     mut runtime_client: RuntimeClient<ClaimService<InjectPropagation<Channel>>>,
     claim: Claim,
 ) -> Result<()> {
-    info!(
-        "loading project from: {}",
-        executable_path
-            .clone()
-            .into_os_string()
-            .into_string()
-            .unwrap_or_default()
-    );
+    info!("Loading resources");
 
     let resources = resource_manager
         .get_resources(&service_id, claim.clone())
@@ -398,7 +391,7 @@ async fn load(
 }
 
 // TODO: add ticket to add deployment_id to more functions that need to be instrumented in deployer.
-#[instrument(skip(runtime_client, deployment_updater, cleanup), fields(deployment_id = %id, state = %State::Running))]
+#[instrument(name = "Starting service", skip(runtime_client, deployment_updater, cleanup), fields(deployment_id = %id, state = %State::Running))]
 async fn run(
     id: Uuid,
     service_name: String,
@@ -423,13 +416,12 @@ async fn run(
         .unwrap()
         .into_inner();
 
-    info!("starting service");
     let response = runtime_client.start(start_request).await;
 
     match response {
         Ok(response) => {
             if response.into_inner().success {
-                info!(DEPLOYER_RUNTIME_START_RESPONSE);
+                info!("{}", DEPLOYER_RUNTIME_START_RESPONSE);
             }
 
             // Wait for stop reason