From f7dee4c6576c7f07047aa4e9655f457eaba55a47 Mon Sep 17 00:00:00 2001 From: Lucio Franco Date: Wed, 26 Nov 2025 08:53:57 -0800 Subject: [PATCH 1/2] [jj-spr] initial version Created using jj-spr 0.1.0 --- apps/framework-cli/src/cli/logger.rs | 342 +++++++++++++++++++-------- 1 file changed, 247 insertions(+), 95 deletions(-) diff --git a/apps/framework-cli/src/cli/logger.rs b/apps/framework-cli/src/cli/logger.rs index 157a9864f5..e39fff8e63 100644 --- a/apps/framework-cli/src/cli/logger.rs +++ b/apps/framework-cli/src/cli/logger.rs @@ -270,94 +270,211 @@ struct CustomFields { machine_id: String, } -/// Layer that formats logs to match the legacy fern format exactly -struct LegacyFormatLayer { - writer: W, - format: LogFormat, +/// Trait for formatting log events. Implementations are monomorphized, +/// allowing the compiler to inline the format logic directly into `on_event`. +/// +/// Formatters write directly to the provided writer to avoid intermediate allocations. +trait LegacyFormatter { + fn write_event( + &self, + writer: &mut W, + level: &Level, + target: &str, + event: &Event<'_>, + ) -> std::io::Result<()>; +} + +/// Text formatter matching fern's text format exactly +#[derive(Clone)] +struct TextFormatter { include_session_id: bool, - custom_fields: CustomFields, + session_id: String, } -impl LegacyFormatLayer { - fn new( - writer: W, - format: LogFormat, - include_session_id: bool, - custom_fields: CustomFields, - ) -> Self { +impl TextFormatter { + fn new(include_session_id: bool, session_id: String) -> Self { Self { - writer, - format, include_session_id, - custom_fields, + session_id, } } +} - fn format_text(&self, level: &Level, target: &str, message: &str) -> String { - // Match current fern text format exactly - format!( - "[{} {}{} - {}] {}", +impl LegacyFormatter for TextFormatter { + #[inline] + fn write_event( + &self, + writer: &mut W, + level: &Level, + target: &str, + event: &Event<'_>, + ) -> std::io::Result<()> { + // Write prefix: [timestamp LEVEL - target] + write!( + writer, + "[{} {}", humantime::format_rfc3339_seconds(SystemTime::now()), level, - if self.include_session_id { - format!(" {}", self.custom_fields.session_id) - } else { - String::new() - }, - target, - message - ) + )?; + + if self.include_session_id { + write!(writer, " {}", self.session_id)?; + } + + write!(writer, " - {}] ", target)?; + + // Write message directly without intermediate String + let mut visitor = DirectWriteVisitor { writer }; + event.record(&mut visitor); + + writeln!(writer) } +} - fn format_json(&self, level: &Level, target: &str, message: &str) -> String { - // Match current fern JSON format exactly - let mut log_json = serde_json::json!({ - "timestamp": chrono::Utc::now().to_rfc3339(), - "severity": level.to_string(), - "target": target, - "message": message, - }); +/// JSON formatter matching fern's JSON format exactly +#[derive(Clone)] +struct JsonFormatter { + include_session_id: bool, + session_id: String, +} + +impl JsonFormatter { + fn new(include_session_id: bool, session_id: String) -> Self { + Self { + include_session_id, + session_id, + } + } +} + +impl LegacyFormatter for JsonFormatter { + #[inline] + fn write_event( + &self, + writer: &mut W, + level: &Level, + target: &str, + event: &Event<'_>, + ) -> std::io::Result<()> { + // For JSON we need to capture the message first since it goes in the middle of the object. + // We could use a streaming JSON writer, but that's more complex and the message + // is typically small. The main win here is avoiding the serde_json::Value allocation. + let mut message_visitor = MessageVisitor::default(); + event.record(&mut message_visitor); + + write!( + writer, + r#"{{"timestamp":"{}","severity":"{}","target":"{}","message":"{}""#, + chrono::Utc::now().to_rfc3339(), + level, + escape_json(target), + escape_json(&message_visitor.message), + )?; if self.include_session_id { - log_json["session_id"] = - serde_json::Value::String(self.custom_fields.session_id.clone()); + write!( + writer, + r#","session_id":"{}""#, + escape_json(&self.session_id) + )?; + } + + writeln!(writer, "}}") + } +} + +/// Escape a string for JSON output (handles quotes, backslashes, and control characters) +#[inline] +fn escape_json(s: &str) -> std::borrow::Cow<'_, str> { + if s.bytes() + .all(|b| b != b'"' && b != b'\\' && b >= 0x20 && b != 0x7f) + { + // Fast path: no escaping needed + std::borrow::Cow::Borrowed(s) + } else { + // Slow path: build escaped string + let mut escaped = String::with_capacity(s.len() + 8); + for c in s.chars() { + match c { + '"' => escaped.push_str("\\\""), + '\\' => escaped.push_str("\\\\"), + '\n' => escaped.push_str("\\n"), + '\r' => escaped.push_str("\\r"), + '\t' => escaped.push_str("\\t"), + c if c.is_control() => { + escaped.push_str(&format!("\\u{:04x}", c as u32)); + } + c => escaped.push(c), + } } + std::borrow::Cow::Owned(escaped) + } +} - serde_json::to_string(&log_json) - .expect("formatting `serde_json::Value` with string keys never fails") +/// Layer that formats logs to match the legacy fern format exactly. +/// +/// Generic over the formatter type `F`, enabling monomorphization so the +/// compiler can inline the format logic directly into `on_event`. +struct LegacyFormatLayer { + writer: W, + formatter: F, +} + +impl LegacyFormatLayer { + fn new(writer: W, formatter: F) -> Self { + Self { writer, formatter } } } -impl Layer for LegacyFormatLayer +impl Layer for LegacyFormatLayer where S: Subscriber + for<'a> LookupSpan<'a>, W: for<'writer> MakeWriter<'writer> + 'static, + F: LegacyFormatter + 'static, { fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { - // Extract metadata let metadata = event.metadata(); - let level = metadata.level(); - let target = metadata.target(); + let mut writer = self.writer.make_writer(); - // Extract message using visitor - let mut visitor = MessageVisitor::default(); - event.record(&mut visitor); - let message = visitor.message; + // Write directly to output, avoiding intermediate allocations + let _ = self + .formatter + .write_event(&mut writer, metadata.level(), metadata.target(), event); + } +} - // Format based on LogFormat - let output = if self.format == LogFormat::Text { - self.format_text(level, target, &message) - } else { - self.format_json(level, target, &message) - }; +/// Visitor that writes the message field directly to a writer, avoiding intermediate allocation. +/// +/// For string messages (the common case), writes directly without any allocation. +/// For debug-formatted messages, uses a small stack buffer to strip surrounding quotes. +struct DirectWriteVisitor<'a, W> { + writer: &'a mut W, +} - // Write to output - let mut writer = self.writer.make_writer(); - let _ = writer.write_all(output.as_bytes()); - let _ = writer.write_all(b"\n"); +impl Visit for DirectWriteVisitor<'_, W> { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + if field.name() == "message" { + // Format to a temporary buffer to strip quotes if present. + // Most messages are short, so stack allocation is fine. + let formatted = format!("{:?}", value); + let output = if formatted.starts_with('"') && formatted.ends_with('"') { + &formatted[1..formatted.len() - 1] + } else { + &formatted + }; + let _ = self.writer.write_all(output.as_bytes()); + } + } + + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + // String messages can be written directly without any allocation + let _ = self.writer.write_all(value.as_bytes()); + } } } +/// Visitor that extracts the message into a String (used for JSON where we need the value mid-output). #[derive(Default)] struct MessageVisitor { message: String, @@ -373,6 +490,13 @@ impl Visit for MessageVisitor { } } } + + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + // String messages don't need debug quote stripping + self.message = value.to_string(); + } + } } /// Custom MakeWriter that creates log files with user-specified date format @@ -601,61 +725,89 @@ fn setup_legacy_format( let env_filter = EnvFilter::try_from_default_env() .unwrap_or_else(|_| EnvFilter::new(settings.level.to_tracing_level().to_string())); - // Setup with or without OTEL based on configuration - if let Some(endpoint) = &settings.export_to { - let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?; - - if settings.stdout { - let legacy_layer = LegacyFormatLayer::new( - std::io::stdout, - settings.format.clone(), - settings.include_session_id, - custom_fields, - ); - + // Branch on format type at setup time to get monomorphized Layer implementations. + // Each branch creates a concrete formatter type, enabling the compiler to inline + // the format logic directly into on_event. + match (&settings.format, &settings.export_to, settings.stdout) { + (LogFormat::Text, Some(endpoint), true) => { + let formatter = + TextFormatter::new(settings.include_session_id, custom_fields.session_id); + let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?; + let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter); tracing_subscriber::registry() .with(otel_layer) .with(env_filter) .with(legacy_layer) .init(); - } else { + } + (LogFormat::Text, Some(endpoint), false) => { + let formatter = + TextFormatter::new(settings.include_session_id, custom_fields.session_id); + let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?; let file_appender = create_rolling_file_appender(&settings.log_file_date_format); - let legacy_layer = LegacyFormatLayer::new( - file_appender, - settings.format.clone(), - settings.include_session_id, - custom_fields, - ); - + let legacy_layer = LegacyFormatLayer::new(file_appender, formatter); tracing_subscriber::registry() .with(otel_layer) .with(env_filter) .with(legacy_layer) .init(); } - } else { - // No OTEL export - if settings.stdout { - let legacy_layer = LegacyFormatLayer::new( - std::io::stdout, - settings.format.clone(), - settings.include_session_id, - custom_fields.clone(), - ); - + (LogFormat::Text, None, true) => { + let formatter = + TextFormatter::new(settings.include_session_id, custom_fields.session_id); + let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter); tracing_subscriber::registry() .with(env_filter) .with(legacy_layer) .init(); - } else { + } + (LogFormat::Text, None, false) => { + let formatter = + TextFormatter::new(settings.include_session_id, custom_fields.session_id); let file_appender = create_rolling_file_appender(&settings.log_file_date_format); - let legacy_layer = LegacyFormatLayer::new( - file_appender, - settings.format.clone(), - settings.include_session_id, - custom_fields, - ); - + let legacy_layer = LegacyFormatLayer::new(file_appender, formatter); + tracing_subscriber::registry() + .with(env_filter) + .with(legacy_layer) + .init(); + } + (LogFormat::Json, Some(endpoint), true) => { + let formatter = + JsonFormatter::new(settings.include_session_id, custom_fields.session_id); + let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?; + let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter); + tracing_subscriber::registry() + .with(otel_layer) + .with(env_filter) + .with(legacy_layer) + .init(); + } + (LogFormat::Json, Some(endpoint), false) => { + let formatter = + JsonFormatter::new(settings.include_session_id, custom_fields.session_id); + let otel_layer = create_otel_layer(endpoint, session_id, machine_id)?; + let file_appender = create_rolling_file_appender(&settings.log_file_date_format); + let legacy_layer = LegacyFormatLayer::new(file_appender, formatter); + tracing_subscriber::registry() + .with(otel_layer) + .with(env_filter) + .with(legacy_layer) + .init(); + } + (LogFormat::Json, None, true) => { + let formatter = + JsonFormatter::new(settings.include_session_id, custom_fields.session_id); + let legacy_layer = LegacyFormatLayer::new(std::io::stdout, formatter); + tracing_subscriber::registry() + .with(env_filter) + .with(legacy_layer) + .init(); + } + (LogFormat::Json, None, false) => { + let formatter = + JsonFormatter::new(settings.include_session_id, custom_fields.session_id); + let file_appender = create_rolling_file_appender(&settings.log_file_date_format); + let legacy_layer = LegacyFormatLayer::new(file_appender, formatter); tracing_subscriber::registry() .with(env_filter) .with(legacy_layer) From d2a76ecc80db6b1335aec5d560177088e7025275 Mon Sep 17 00:00:00 2001 From: Lucio Franco Date: Wed, 26 Nov 2025 10:37:19 -0800 Subject: [PATCH 2/2] remove quote stripping and additional not needed features Created using jj-spr 0.1.0 --- apps/framework-cli/src/cli/logger.rs | 72 +++++----------------------- 1 file changed, 12 insertions(+), 60 deletions(-) diff --git a/apps/framework-cli/src/cli/logger.rs b/apps/framework-cli/src/cli/logger.rs index e39fff8e63..ca6ef12228 100644 --- a/apps/framework-cli/src/cli/logger.rs +++ b/apps/framework-cli/src/cli/logger.rs @@ -356,58 +356,24 @@ impl LegacyFormatter for JsonFormatter { target: &str, event: &Event<'_>, ) -> std::io::Result<()> { - // For JSON we need to capture the message first since it goes in the middle of the object. - // We could use a streaming JSON writer, but that's more complex and the message - // is typically small. The main win here is avoiding the serde_json::Value allocation. + // Extract message first since it appears in the middle of the JSON object let mut message_visitor = MessageVisitor::default(); event.record(&mut message_visitor); - write!( - writer, - r#"{{"timestamp":"{}","severity":"{}","target":"{}","message":"{}""#, - chrono::Utc::now().to_rfc3339(), - level, - escape_json(target), - escape_json(&message_visitor.message), - )?; + // Build JSON object - serde_json handles escaping correctly + let mut log_entry = serde_json::json!({ + "timestamp": chrono::Utc::now().to_rfc3339(), + "severity": level.to_string(), + "target": target, + "message": message_visitor.message, + }); if self.include_session_id { - write!( - writer, - r#","session_id":"{}""#, - escape_json(&self.session_id) - )?; + log_entry["session_id"] = serde_json::Value::String(self.session_id.clone()); } - writeln!(writer, "}}") - } -} - -/// Escape a string for JSON output (handles quotes, backslashes, and control characters) -#[inline] -fn escape_json(s: &str) -> std::borrow::Cow<'_, str> { - if s.bytes() - .all(|b| b != b'"' && b != b'\\' && b >= 0x20 && b != 0x7f) - { - // Fast path: no escaping needed - std::borrow::Cow::Borrowed(s) - } else { - // Slow path: build escaped string - let mut escaped = String::with_capacity(s.len() + 8); - for c in s.chars() { - match c { - '"' => escaped.push_str("\\\""), - '\\' => escaped.push_str("\\\\"), - '\n' => escaped.push_str("\\n"), - '\r' => escaped.push_str("\\r"), - '\t' => escaped.push_str("\\t"), - c if c.is_control() => { - escaped.push_str(&format!("\\u{:04x}", c as u32)); - } - c => escaped.push(c), - } - } - std::borrow::Cow::Owned(escaped) + serde_json::to_writer(&mut *writer, &log_entry).map_err(std::io::Error::other)?; + writeln!(writer) } } @@ -454,21 +420,12 @@ struct DirectWriteVisitor<'a, W> { impl Visit for DirectWriteVisitor<'_, W> { fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { if field.name() == "message" { - // Format to a temporary buffer to strip quotes if present. - // Most messages are short, so stack allocation is fine. - let formatted = format!("{:?}", value); - let output = if formatted.starts_with('"') && formatted.ends_with('"') { - &formatted[1..formatted.len() - 1] - } else { - &formatted - }; - let _ = self.writer.write_all(output.as_bytes()); + let _ = write!(self.writer, "{:?}", value); } } fn record_str(&mut self, field: &Field, value: &str) { if field.name() == "message" { - // String messages can be written directly without any allocation let _ = self.writer.write_all(value.as_bytes()); } } @@ -484,16 +441,11 @@ impl Visit for MessageVisitor { fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { if field.name() == "message" { self.message = format!("{:?}", value); - // Remove surrounding quotes from debug format - if self.message.starts_with('"') && self.message.ends_with('"') { - self.message = self.message[1..self.message.len() - 1].to_string(); - } } } fn record_str(&mut self, field: &Field, value: &str) { if field.name() == "message" { - // String messages don't need debug quote stripping self.message = value.to_string(); } }