fix: truncate log item strings (#1227)

* feat: limit log line length to 2048 chars

* log line touchups

* feedback: reduce iterations and allocations when truncating

* print at better time

* cleanup

common/src/log.rs

@@ -54,15 +54,42 @@ pub struct LogItem {
     pub line: String,
 }
 
+const LOGLINE_MAX_CHARS: usize = 2048;
+const TRUNC_MSG: &str = "... (truncated)";
+
 impl LogItem {
-    pub fn new(id: Uuid, internal_origin: Backend, line: String) -> Self {
+    pub fn new(id: Uuid, internal_origin: Backend, line: impl Into<String>) -> Self {
+        let mut line: String = line.into();
+
+        Self::truncate_line(&mut line);
+
         Self {
             id,
             internal_origin,
             timestamp: Utc::now(),
             line,
         }
     }
+
+    fn truncate_line(line: &mut String) {
+        // Check if it can be over the limit (assuming ascii only), no iteration
+        if line.len() > LOGLINE_MAX_CHARS {
+            // Then, check if it actually is over the limit.
+            // Find the char boundrary of the last char, but iterate no more than
+            // the max number of chars allowed.
+            let x = line
+                .char_indices()
+                .enumerate()
+                .find(|(i, _)| *i == LOGLINE_MAX_CHARS);
+            // If char iterator reached max iteration count
+            if let Some((_, (ci, _))) = x {
+                // Truncate to the char boundrary found
+                line.truncate(ci);
+                // New allocation unlikely since it keeps its capacity
+                write!(line, "{}", TRUNC_MSG).expect("write to string");
+            }
+        }
+    }
 }
 
 #[cfg(feature = "display")]
@@ -282,4 +309,30 @@ mod tests {
             assert!(log_line.contains(&utc_dt));
         });
     }
+
+    #[test]
+    fn log_item_truncate() {
+        let mut l = "öl".repeat(100);
+        LogItem::truncate_line(&mut l);
+        assert_eq!(l.len(), 300);
+        assert_eq!(l.chars().count(), 200);
+
+        let mut l = "🍪".repeat(LOGLINE_MAX_CHARS);
+        LogItem::truncate_line(&mut l);
+        assert_eq!(l.len(), 4 * (LOGLINE_MAX_CHARS));
+        assert_eq!(l.chars().count(), LOGLINE_MAX_CHARS);
+
+        // one cookie should be truncated, and the suffix message should be appended
+        // ✨ = 3b, 🍪 = 4b
+
+        let mut l = format!("A{}", "🍪".repeat(LOGLINE_MAX_CHARS));
+        LogItem::truncate_line(&mut l);
+        assert_eq!(l.len(), 1 + 4 * (LOGLINE_MAX_CHARS - 1) + TRUNC_MSG.len());
+        assert_eq!(l.chars().count(), LOGLINE_MAX_CHARS + TRUNC_MSG.len());
+
+        let mut l = format!("✨{}", "🍪".repeat(LOGLINE_MAX_CHARS));
+        LogItem::truncate_line(&mut l);
+        assert_eq!(l.len(), 3 + 4 * (LOGLINE_MAX_CHARS - 1) + TRUNC_MSG.len());
+        assert_eq!(l.chars().count(), LOGLINE_MAX_CHARS + TRUNC_MSG.len());
+    }
 }

deployer/src/handlers/mod.rs

@@ -354,6 +354,7 @@ pub async fn create_service(
     let pid = persistence.project_id();
 
     span.in_scope(|| {
+        info!("Deployer version: {}", crate::VERSION);
         info!("Deployment ID: {}", id);
         info!("Service ID: {}", service.id);
         info!("Service name: {}", service.name);

deployer/src/lib.rs

@@ -26,6 +26,8 @@ pub use crate::persistence::Persistence;
 use crate::proxy::AddressGetter;
 pub use crate::runtime_manager::RuntimeManager;
 
+const VERSION: &str = env!("CARGO_PKG_VERSION");
+
 pub async fn start(
     persistence: Persistence,
     runtime_manager: Arc<Mutex<RuntimeManager>>,

runtime/src/alpha/mod.rs

@@ -64,6 +64,11 @@ pub async fn start(loader: impl Loader<ProvisionerFactory> + Send + 'static) {
         }
     };
 
+    println!(
+        "shuttle-runtime executable started (version {})",
+        crate::VERSION
+    );
+
     // this is handled after arg parsing to not interfere with --version above
     #[cfg(feature = "setup-tracing")]
     {
@@ -336,7 +341,6 @@ where
         &self,
         request: Request<StartRequest>,
     ) -> Result<Response<StartResponse>, Status> {
-        println!("alpha runtime starting");
         let service = self.service.lock().unwrap().deref_mut().take();
         let service = service.unwrap();
 
@@ -345,7 +349,7 @@ where
             .context("invalid socket address")
             .map_err(|err| Status::invalid_argument(err.to_string()))?;
 
-        println!("starting on {service_address}");
+        println!("Starting on {service_address}");
 
         let (kill_tx, kill_rx) = tokio::sync::oneshot::channel();
         *self.kill_tx.lock().unwrap() = Some(kill_tx);

runtime/src/lib.rs

@@ -241,10 +241,10 @@ pub use strfmt::strfmt;
 #[cfg(feature = "setup-tracing")]
 pub use {colored, tracing_subscriber};
 
+const NAME: &str = env!("CARGO_PKG_NAME");
+const VERSION: &str = env!("CARGO_PKG_VERSION");
+
 // Print the version of the runtime.
 pub fn print_version() {
-    let name = env!("CARGO_PKG_NAME");
-    let version = env!("CARGO_PKG_VERSION");
-
-    println!("{name} {version}");
+    println!("{NAME} {VERSION}");
 }