Improve logging experience

docs/docs/get-started/debugging/enable-logging.mdx

@@ -5,10 +5,32 @@ slug: docs/get-started/debugging/enable-logging
 You can add logging to determine what the BAML runtime is doing.
 
 To enable logging, set the `BAML_LOG` environment variable:
-```
+```sh
+# default is warn
 BAML_LOG=info
 ```
 
-BAML uses the rust `log` crate for logging. You can see more information on how to better configure the `log` crate [here](https://rust-lang-nursery.github.io/rust-cookbook/development_tools/debugging/config_log.html).
+| Level | Description |
+|-------|-------------|
+| `error` | Fatal errors by BAML |
+| `warn` | Logs any time a function fails (includes LLM calling failures, parsing failures) |
+| `info` | Logs every call to a function (including prompt, raw response, and parsed response) |
+| `debug` | Way more than you think you need |
+| `trace` | Everything and more |
+| `off` | No logging |
+
+
+Example log:
+<img src="../../../assets/log_message.png" />
+
+---
+
+Since `>0.54.0`:
+
+To truncate each log entry to a certain length, set the `BOUNDARY_MAX_LOG_CHUNK_CHARS` environment variable:
+
+```sh
+BOUNDARY_MAX_LOG_CHUNK_CHARS=3000
+```
 
-Just instead of using the `RUST_LOG` environment variable, use the `BAML_LOG` environment variable.
+This will truncate each part in a log entry to 3000 characters.

engine/baml-runtime/src/internal/llm_client/mod.rs

@@ -93,6 +93,18 @@ pub enum LLMResponse {
 
 impl Error for LLMResponse {}
 
+impl crate::tracing::Visualize for LLMResponse {
+    fn visualize(&self, max_chunk_size: usize) -> String {
+        match self {
+            Self::Success(response) => response.visualize(max_chunk_size),
+            Self::LLMFailure(failure) => failure.visualize(max_chunk_size),
+            Self::OtherFailure(message) => {
+                format!("{}", format!("LLM call failed: {message}").red())
+            }
+        }
+    }
+}
+
 impl std::fmt::Display for LLMResponse {
     fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
         match self {
@@ -232,6 +244,74 @@ impl std::fmt::Display for LLMCompleteResponse {
     }
 }
 
+impl crate::tracing::Visualize for LLMCompleteResponse {
+    fn visualize(&self, max_chunk_size: usize) -> String {
+        let s = vec![
+            format!(
+                "{}",
+                format!(
+                    "Client: {} ({}) - {}ms. StopReason: {}",
+                    self.client,
+                    self.model,
+                    self.latency.as_millis(),
+                    self.metadata.finish_reason.as_deref().unwrap_or("unknown")
+                )
+                .yellow()
+            ),
+            format!("{}", "---PROMPT---".blue()),
+            format!(
+                "{}",
+                crate::tracing::truncate_string(&self.prompt.to_string(), max_chunk_size).dimmed()
+            ),
+            format!("{}", "---LLM REPLY---".blue()),
+            format!(
+                "{}",
+                crate::tracing::truncate_string(&self.content, max_chunk_size).dimmed()
+            ),
+        ];
+        s.join("\n")
+    }
+}
+
+impl crate::tracing::Visualize for LLMErrorResponse {
+    fn visualize(&self, max_chunk_size: usize) -> String {
+        let mut s = vec![
+            format!(
+                "{}",
+                format!(
+                    "Client: {} ({}) - {}ms",
+                    self.client,
+                    self.model.as_deref().unwrap_or("<unknown>"),
+                    self.latency.as_millis(),
+                )
+                .yellow(),
+            ),
+            format!("{}", "---PROMPT---".blue()),
+            format!(
+                "{}",
+                crate::tracing::truncate_string(&self.prompt.to_string(), max_chunk_size).dimmed()
+            ),
+            format!("{}", "---REQUEST OPTIONS---".blue()),
+        ];
+        for (k, v) in &self.request_options {
+            s.push(format!(
+                "{}: {}",
+                k,
+                crate::tracing::truncate_string(&v.to_string(), max_chunk_size)
+            ));
+        }
+        s.push(format!(
+            "{}",
+            format!("---ERROR ({})---", self.code.to_string()).red()
+        ));
+        s.push(format!(
+            "{}",
+            crate::tracing::truncate_string(&self.message, max_chunk_size).red()
+        ));
+        s.join("\n")
+    }
+}
+
 // For parsing args
 fn resolve_properties_walker(
     client: &ClientWalker,

engine/baml-runtime/src/tracing/api_wrapper/env_setup.rs

@@ -17,6 +17,8 @@ pub struct Config {
     pub log_redaction_enabled: bool,
     #[serde(default = "default_redaction_placeholder")]
     pub log_redaction_placeholder: String,
+    #[serde(default = "default_max_log_chunk_chars")]
+    pub max_log_chunk_chars: usize,
 }
 
 fn default_base_url() -> String {
@@ -45,6 +47,10 @@ fn default_host_name() -> String {
         .unwrap_or("unknown".to_string())
 }
 
+fn default_max_log_chunk_chars() -> usize {
+    64_000
+}
+
 impl Config {
     pub fn from_env_vars<T: AsRef<str>>(env_vars: impl Iterator<Item = (T, T)>) -> Result<Self> {
         let config: Result<Config, envy::Error> = envy::prefixed("BOUNDARY_")

engine/baml-runtime/src/tracing/api_wrapper/mod.rs

@@ -71,6 +71,13 @@ impl APIConfig {
             Self::Web(config) => &config.log_redaction_placeholder,
         }
     }
+
+    pub fn max_log_chunk_chars(&self) -> usize {
+        match self {
+            Self::LocalOnly(config) => config.max_log_chunk_chars,
+            Self::Web(config) => config.max_log_chunk_chars,
+        }
+    }
 }
 
 #[derive(Debug, Clone)]
@@ -83,6 +90,7 @@ pub(super) struct CompleteAPIConfig {
     pub host_name: String,
     pub log_redaction_enabled: bool,
     pub log_redaction_placeholder: String,
+    pub max_log_chunk_chars: usize,
 
     client: reqwest::Client,
 }
@@ -99,6 +107,7 @@ pub(super) struct PartialAPIConfig {
     host_name: String,
     log_redaction_enabled: bool,
     log_redaction_placeholder: String,
+    pub max_log_chunk_chars: usize,
 }
 
 impl CompleteAPIConfig {
@@ -303,6 +312,7 @@ impl APIWrapper {
                     client: create_tracing_client()?,
                     log_redaction_enabled: config.log_redaction_enabled,
                     log_redaction_placeholder: config.log_redaction_placeholder,
+                    max_log_chunk_chars: config.max_log_chunk_chars,
                 }),
             },
             _ => Self {
@@ -315,6 +325,7 @@ impl APIWrapper {
                     host_name: config.host_name,
                     log_redaction_enabled: config.log_redaction_enabled,
                     log_redaction_placeholder: config.log_redaction_placeholder,
+                    max_log_chunk_chars: config.max_log_chunk_chars,
                 }),
             },
         })

engine/baml-runtime/src/tracing/mod.rs

@@ -54,6 +54,61 @@ pub struct BamlTracer {
 #[cfg(not(target_arch = "wasm32"))]
 static_assertions::assert_impl_all!(BamlTracer: Send, Sync);
 
+/// Trait for types that can be visualized in terminal logs
+pub trait Visualize {
+    fn visualize(&self, max_chunk_size: usize) -> String;
+}
+
+pub fn truncate_string(s: &str, max_size: usize) -> String {
+    if max_size > 0 && s.len() > max_size {
+        let half_size = max_size / 2;
+        format!(
+            "{}{}{}",
+            &s[..half_size],
+            "...[log trimmed]...".yellow().dimmed(),
+            &s[s.len() - half_size..]
+        )
+    } else {
+        s.to_string()
+    }
+}
+
+impl<'a> Visualize for FunctionResult {
+    fn visualize(&self, max_chunk_size: usize) -> String {
+        let mut s = vec![];
+        if self.event_chain().len() > 1 {
+            s.push(format!(
+                "{}",
+                format!("({} other previous tries)", self.event_chain().len() - 1).yellow()
+            ));
+        }
+        s.push(self.llm_response().visualize(max_chunk_size));
+        match self.parsed() {
+            Some(Ok(val)) => {
+                let val: BamlValue = val.into();
+                s.push(format!(
+                    "{}",
+                    format!("---Parsed Response ({})---", val.r#type()).blue()
+                ));
+                let json_str = serde_json::to_string_pretty(&val).unwrap();
+                s.push(format!("{}", truncate_string(&json_str, max_chunk_size)));
+            }
+            Some(Err(e)) => {
+                s.push(format!(
+                    "{}",
+                    format!("---Parsed Response ({})---", "Error".red()).blue()
+                ));
+                s.push(format!(
+                    "{}",
+                    truncate_string(&e.to_string(), max_chunk_size).red()
+                ));
+            }
+            None => {}
+        };
+        s.join("\n")
+    }
+}
+
 impl BamlTracer {
     pub fn new<T: AsRef<str>>(
         options: Option<APIWrapper>,
@@ -212,7 +267,7 @@ impl BamlTracer {
                 if is_ok { log::Level::Info } else { log::Level::Warn },
                 "{}{}",
                 name.map(|s| format!("Function {}:\n", s)).unwrap_or_default().purple(),
-                response
+                VisualFunctionResult(response)
             );
         }
 
@@ -259,7 +314,7 @@ impl BamlTracer {
                 if is_ok { log::Level::Info } else { log::Level::Warn },
                 "{}{}",
                 name.map(|s| format!("Function {}:\n", s)).unwrap_or_default().purple(),
-                response
+                response.visualize(self.options.config.max_log_chunk_chars())
             );
         }