From 4616d1a4b21a471a7b02058872268f9309f287d0 Mon Sep 17 00:00:00 2001 From: Thorsten Sommer Date: Sat, 10 Oct 2026 19:05:41 +0200 Subject: [PATCH] Logged .NET events with the time they happened (#1042) --- .../Assistants/I18N/allTexts.lua | 3 + .../Pages/Information.razor | 1 + .../plugin.lua | 3 + .../plugin.lua | 3 + .../Tools/Rust/LogEventRequest.cs | 9 + .../Tools/Services/RustService.Log.cs | 2 +- .../Tools/TerminalLogger.cs | 22 +- .../wwwroot/changelog/v26.10.1.md | 1 + app/Tests/Tools/TerminalLoggerTests.cs | 48 +++ runtime/Cargo.lock | 1 + runtime/Cargo.toml | 1 + runtime/src/log.rs | 277 +++++++++++++++++- 12 files changed, 354 insertions(+), 17 deletions(-) create mode 100644 app/Tests/Tools/TerminalLoggerTests.cs diff --git a/app/MindWork AI Studio/Assistants/I18N/allTexts.lua b/app/MindWork AI Studio/Assistants/I18N/allTexts.lua index faf03898..0a2c9c5e 100644 --- a/app/MindWork AI Studio/Assistants/I18N/allTexts.lua +++ b/app/MindWork AI Studio/Assistants/I18N/allTexts.lua @@ -10129,6 +10129,9 @@ UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3454691558"] = "You are running -- Unknown error UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3461425987"] = "Unknown error" +-- chrono handles dates and times in the Rust runtime. We use it to record in the log when each event actually happened, even when the message about it arrives a moment later. +UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3489383665"] = "chrono handles dates and times in the Rust runtime. We use it to record in the log when each event actually happened, even when the message about it arrives a moment later." + -- Tauri is used to host the Blazor user interface. It is a great project that allows the creation of desktop applications using web technologies. I love Tauri! UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3494984593"] = "Tauri is used to host the Blazor user interface. It is a great project that allows the creation of desktop applications using web technologies. I love Tauri!" diff --git a/app/MindWork AI Studio/Pages/Information.razor b/app/MindWork AI Studio/Pages/Information.razor index d60bee75..446bedfe 100644 --- a/app/MindWork AI Studio/Pages/Information.razor +++ b/app/MindWork AI Studio/Pages/Information.razor @@ -382,6 +382,7 @@ + diff --git a/app/MindWork AI Studio/Plugins/languages/de-de-43065dbc-78d0-45b7-92be-f14c2926e2dc/plugin.lua b/app/MindWork AI Studio/Plugins/languages/de-de-43065dbc-78d0-45b7-92be-f14c2926e2dc/plugin.lua index d07b9109..89cf2374 100644 --- a/app/MindWork AI Studio/Plugins/languages/de-de-43065dbc-78d0-45b7-92be-f14c2926e2dc/plugin.lua +++ b/app/MindWork AI Studio/Plugins/languages/de-de-43065dbc-78d0-45b7-92be-f14c2926e2dc/plugin.lua @@ -10131,6 +10131,9 @@ UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3454691558"] = "Sie verwenden ei -- Unknown error UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3461425987"] = "Unbekannter Fehler" +-- chrono handles dates and times in the Rust runtime. We use it to record in the log when each event actually happened, even when the message about it arrives a moment later. +UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3489383665"] = "chrono verarbeitet Datums- und Zeitangaben in der Rust-Laufzeitumgebung. Damit halten wir im Protokoll fest, wann jedes Ereignis tatsächlich stattgefunden hat – auch wenn die entsprechende Nachricht erst einen Moment später eintrifft." + -- Tauri is used to host the Blazor user interface. It is a great project that allows the creation of desktop applications using web technologies. I love Tauri! UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3494984593"] = "Tauri wird verwendet, um die Blazor-Benutzeroberfläche bereitzustellen. Es ist ein großartiges Projekt, das die Erstellung von Desktop-Anwendungen mit Webtechnologien ermöglicht. Ich liebe Tauri!" diff --git a/app/MindWork AI Studio/Plugins/languages/en-us-97dfb1ba-50c4-4440-8dfa-6575daf543c8/plugin.lua b/app/MindWork AI Studio/Plugins/languages/en-us-97dfb1ba-50c4-4440-8dfa-6575daf543c8/plugin.lua index bfe38724..74375902 100644 --- a/app/MindWork AI Studio/Plugins/languages/en-us-97dfb1ba-50c4-4440-8dfa-6575daf543c8/plugin.lua +++ b/app/MindWork AI Studio/Plugins/languages/en-us-97dfb1ba-50c4-4440-8dfa-6575daf543c8/plugin.lua @@ -10131,6 +10131,9 @@ UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3454691558"] = "You are running -- Unknown error UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3461425987"] = "Unknown error" +-- chrono handles dates and times in the Rust runtime. We use it to record in the log when each event actually happened, even when the message about it arrives a moment later. +UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3489383665"] = "chrono handles dates and times in the Rust runtime. We use it to record in the log when each event actually happened, even when the message about it arrives a moment later." + -- Tauri is used to host the Blazor user interface. It is a great project that allows the creation of desktop applications using web technologies. I love Tauri! UI_TEXT_CONTENT["AISTUDIO::PAGES::INFORMATION::T3494984593"] = "Tauri is used to host the Blazor user interface. It is a great project that allows the creation of desktop applications using web technologies. I love Tauri!" diff --git a/app/MindWork AI Studio/Tools/Rust/LogEventRequest.cs b/app/MindWork AI Studio/Tools/Rust/LogEventRequest.cs index c3f8fe89..71437314 100644 --- a/app/MindWork AI Studio/Tools/Rust/LogEventRequest.cs +++ b/app/MindWork AI Studio/Tools/Rust/LogEventRequest.cs @@ -1,5 +1,14 @@ namespace AIStudio.Tools.Rust; +/// +/// A log event the Rust runtime writes to the log file. +/// +/// When the event happened, in the round-trip format of TerminalLogger.FormatTransportTimestamp, e.g., 2026-10-09T17:53:54.5629130+00:00. The Rust runtime logs the event with this time; when it cannot read it, the event shows the time it arrived instead. +/// The log level. +/// The category of the log event. +/// The log message. +/// Optional exception message. +/// Optional exception stack trace. public readonly record struct LogEventRequest( string Timestamp, string Level, diff --git a/app/MindWork AI Studio/Tools/Services/RustService.Log.cs b/app/MindWork AI Studio/Tools/Services/RustService.Log.cs index 4898e3b1..5268310e 100644 --- a/app/MindWork AI Studio/Tools/Services/RustService.Log.cs +++ b/app/MindWork AI Studio/Tools/Services/RustService.Log.cs @@ -16,7 +16,7 @@ public sealed partial class RustService /// /// Sends a log event to the Rust runtime. /// - /// The timestamp of the log event. + /// When the log event happened, formatted by TerminalLogger.FormatTransportTimestamp. /// The log level. /// The category of the log event. /// The log message. diff --git a/app/MindWork AI Studio/Tools/TerminalLogger.cs b/app/MindWork AI Studio/Tools/TerminalLogger.cs index 2c20d510..2eb8c84c 100644 --- a/app/MindWork AI Studio/Tools/TerminalLogger.cs +++ b/app/MindWork AI Studio/Tools/TerminalLogger.cs @@ -1,4 +1,5 @@ using System.Collections.Concurrent; +using System.Globalization; using AIStudio.Tools.Rust; using AIStudio.Tools.Services; @@ -59,7 +60,9 @@ public sealed class TerminalLogger() : ConsoleFormatter(FORMATTER_NAME) public override void Write(in LogEntry logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter) { var message = logEntry.Formatter(logEntry.State, logEntry.Exception); - var timestamp = DateTimeOffset.UtcNow.ToString("yyyy-MM-dd HH:mm:ss.fff"); + var now = DateTimeOffset.UtcNow; + var timestamp = now.ToString("yyyy-MM-dd HH:mm:ss.fff", CultureInfo.InvariantCulture); + var transportTimestamp = FormatTransportTimestamp(now); var logLevel = logEntry.LogLevel.ToString(); var category = logEntry.Category; var exceptionMessage = logEntry.Exception?.Message; @@ -85,13 +88,26 @@ public sealed class TerminalLogger() : ConsoleFormatter(FORMATTER_NAME) // Send log event to Rust via API (fire-and-forget): if (RUST_SERVICE is not null) - RUST_SERVICE.LogEvent(timestamp, logLevel, category, message, exceptionMessage, stackTrace); + RUST_SERVICE.LogEvent(transportTimestamp, logLevel, category, message, exceptionMessage, stackTrace); // Buffer early log events until the RustService is available: else - EARLY_LOG_BUFFER.Enqueue(new LogEventRequest(timestamp, logLevel, category, message, exceptionMessage, stackTrace)); + EARLY_LOG_BUFFER.Enqueue(new LogEventRequest(transportTimestamp, logLevel, category, message, exceptionMessage, stackTrace)); } + /// + /// Formats the time of a log event for the Rust runtime. + /// + /// + /// The round-trip format is ISO 8601 with seven fractional digits and the offset, e.g., + /// 2026-10-09T17:53:54.5629130+00:00, and it is the same in every culture. The Rust runtime + /// reads it as RFC 3339, so it can log the event with the time it happened instead of the + /// time it arrived. + /// + /// The time of the log event. + /// The time in the round-trip format. + public static string FormatTransportTimestamp(DateTimeOffset timestamp) => timestamp.ToString("O", CultureInfo.InvariantCulture); + private static string GetColorForLogLevel(LogLevel logLevel) => logLevel switch { LogLevel.Trace => ANSI_GRAY, diff --git a/app/MindWork AI Studio/wwwroot/changelog/v26.10.1.md b/app/MindWork AI Studio/wwwroot/changelog/v26.10.1.md index eb806441..a0752685 100644 --- a/app/MindWork AI Studio/wwwroot/changelog/v26.10.1.md +++ b/app/MindWork AI Studio/wwwroot/changelog/v26.10.1.md @@ -25,6 +25,7 @@ - Fixed OpenAI models using about 4,300 more tokens than necessary with every request. AI Studio offered them OpenAI's own web search in the background, even when you had not selected a web search. To let a model search the web, select the Web Search tool below the message field. - Fixed AI Studio sometimes rebuilding the index of a data source from scratch when the configuration of your organization was applied while the data source was being updated. - Fixed justified texts being hyphenated by the rules of English even when AI Studio shows another language, such as German. Screen readers now also know which language AI Studio uses. +- Fixed the log file of AI Studio showing the wrong time for some entries when AI Studio was busy. Each entry now shows when it actually happened. - Updated the code contributions on the supporters page, which now thank everyone who has contributed code to AI Studio so far. - Upgraded several libraries to improve security. - Upgraded to Rust v1.99.0 \ No newline at end of file diff --git a/app/Tests/Tools/TerminalLoggerTests.cs b/app/Tests/Tools/TerminalLoggerTests.cs new file mode 100644 index 00000000..4882252f --- /dev/null +++ b/app/Tests/Tools/TerminalLoggerTests.cs @@ -0,0 +1,48 @@ +using System.Globalization; + +using AIStudio.Tools; + +namespace AIStudio.Tests.Tools; + +/// +/// Pins the format in which log events travel to the Rust runtime. +/// +/// +/// The Rust runtime reads this format to log each event with the time it happened. Its tests in +/// runtime/src/log.rs parse the same text, so both sides have to change together. +/// +[TestFixture] +public sealed class TerminalLoggerTests +{ + private const string TRANSPORT_TIMESTAMP = "2026-10-09T17:53:54.5629130+00:00"; + + private static readonly DateTimeOffset EVENT_TIME = new DateTimeOffset(2026, 10, 9, 17, 53, 54, TimeSpan.Zero).AddTicks(5_629_130); + + [Test] + public void TheTransportTimestampIsPinned() + { + Assert.That(TerminalLogger.FormatTransportTimestamp(EVENT_TIME), Is.EqualTo(TRANSPORT_TIMESTAMP)); + } + + [Test] + public void TheTransportTimestampIgnoresTheCurrentCulture() + { + var culture = (CultureInfo)CultureInfo.InvariantCulture.Clone(); + culture.DateTimeFormat.TimeSeparator = "."; + + var previousCulture = CultureInfo.CurrentCulture; + try + { + CultureInfo.CurrentCulture = culture; + Assert.Multiple(() => + { + Assert.That(EVENT_TIME.ToString("yyyy-MM-dd HH:mm:ss.fff"), Is.EqualTo("2026-10-09 17.53.54.562"), "The format sent before followed the time separator of the current culture."); + Assert.That(TerminalLogger.FormatTransportTimestamp(EVENT_TIME), Is.EqualTo(TRANSPORT_TIMESTAMP)); + }); + } + finally + { + CultureInfo.CurrentCulture = previousCulture; + } + } +} \ No newline at end of file diff --git a/runtime/Cargo.lock b/runtime/Cargo.lock index 543a2a97..e391e027 100644 --- a/runtime/Cargo.lock +++ b/runtime/Cargo.lock @@ -4267,6 +4267,7 @@ dependencies = [ "cbc 0.2.1", "cfg-if", "chardetng", + "chrono", "dbus-secret-service", "dbus-secret-service-keyring-store", "dirs", diff --git a/runtime/Cargo.toml b/runtime/Cargo.toml index 1d042f80..b9f2785e 100644 --- a/runtime/Cargo.toml +++ b/runtime/Cargo.toml @@ -24,6 +24,7 @@ tokio-stream = { version = "0.1.18", features = ["sync"] } futures = "0.3.32" async-stream = "0.3.6" flexi_logger = "0.31.9" +chrono = "0.4.44" dirs = "6.0.0" log = { version = "0.4.33", features = ["kv"] } once_cell = "1.21.4" diff --git a/runtime/src/log.rs b/runtime/src/log.rs index 4bda2ed7..b460cbf2 100644 --- a/runtime/src/log.rs +++ b/runtime/src/log.rs @@ -4,7 +4,9 @@ use std::error::Error; use std::fmt::Debug; use std::fs::{create_dir_all, OpenOptions}; use std::path::{absolute, Path, PathBuf}; +use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::OnceLock; +use chrono::{DateTime, Utc}; use flexi_logger::{DeferredNow, Duplicate, FileSpec, Logger, LoggerHandle}; use flexi_logger::writers::FileLogWriter; use log::{kv, Level}; @@ -16,12 +18,28 @@ use crate::environment::{is_dev, is_flatpak}; const FLATPAK_PERSISTENT_DATA_DIRECTORY: &str = "/var/data"; +/// The key under which a log record carries the time its event happened, in microseconds +/// since the Unix epoch. A record without it happened when it reached the logger. The +/// formatters start the line with this time and never write the key itself. +const CREATED_AT_KEY: &str = "created_at_micros"; + +/// The key under which a line shows how late its record reached the logger. +const DELAY_KEY: &str = "Delay"; + +/// From this many milliseconds on, a line shows how late its record reached the logger. +/// Below it lies the usual transport time, which would only be noise. +const DELAY_THRESHOLD_MS: i64 = 100; + static LOGGER: OnceLock = OnceLock::new(); static LOG_STARTUP_PATH: OnceLock = OnceLock::new(); static LOG_APP_PATH: OnceLock = OnceLock::new(); +/// Whether we already warned that the .NET server sent a timestamp we cannot read. +/// Once is enough: when one is unreadable, all of them are. +static WARNED_ABOUT_UNREADABLE_DOTNET_TIMESTAMP: AtomicBool = AtomicBool::new(false); + /// Initialize the logging system. pub fn init_logging(bundle_identifier: &str) { @@ -270,15 +288,24 @@ struct LogKVCollect<'kvs>(BTreeMap, Value<'kvs>>); impl<'kvs> VisitSource<'kvs> for LogKVCollect<'kvs> { fn visit_pair(&mut self, key: Key<'kvs>, value: Value<'kvs>) -> Result<(), kv::Error> { - self.0.insert(key, value); + // The creation time is the timestamp of the line, not one of its pairs: + if key.as_str() != CREATED_AT_KEY { + self.0.insert(key, value); + } + Ok(()) } } -fn write_kv_pairs(w: &mut dyn std::io::Write, record: &log::Record) -> Result<(), std::io::Error> { - if record.key_values().count() > 0 { - let mut visitor = LogKVCollect(BTreeMap::new()); - record.key_values().visit(&mut visitor).unwrap(); +fn write_kv_pairs(w: &mut dyn std::io::Write, record: &log::Record, delay_ms: Option) -> Result<(), std::io::Error> { + let delay = delay_ms.map(|delay_ms| format!("{delay_ms} ms")); + let mut visitor = LogKVCollect(BTreeMap::new()); + record.key_values().visit(&mut visitor).unwrap(); + if let Some(delay) = &delay { + visitor.0.insert(Key::from_str(DELAY_KEY), Value::from_display(delay)); + } + + if !visitor.0.is_empty() { write!(w, "[")?; let mut index = 0; for (key, value) in visitor.0 { @@ -295,6 +322,41 @@ fn write_kv_pairs(w: &mut dyn std::io::Write, record: &log::Record) -> Result<() Ok(()) } +/// When the event of a log record happened, and how late the record reached the logger. +struct LogTime { + timestamp: String, + delay_ms: Option, +} + +fn get_log_time(now: &mut DeferredNow, record: &log::Record) -> LogTime { + let created_at = record + .key_values() + .get(Key::from_str(CREATED_AT_KEY)) + .and_then(|value| value.to_i64()) + .and_then(DateTime::::from_timestamp_micros); + + match created_at { + // Case: The event happened when its record reached the logger: + None => LogTime { + timestamp: now.format(flexi_logger::TS_DASHES_BLANK_COLONS_DOT_BLANK).to_string(), + delay_ms: None, + }, + + // Case: The event happened earlier, e.g., in the .NET server. The logger + // runs in UTC (see init_logging), so this time is written in UTC as well: + Some(created_at) => LogTime { + timestamp: created_at.format(flexi_logger::TS_DASHES_BLANK_COLONS_DOT_BLANK).to_string(), + delay_ms: get_notable_delay_ms(created_at, now.now_utc_owned()), + }, + } +} + +/// Returns how late a record reached the logger, but only when the delay is notable. +fn get_notable_delay_ms(created_at: DateTime, arrived_at: DateTime) -> Option { + let delay_ms = (arrived_at - created_at).num_milliseconds(); + (delay_ms >= DELAY_THRESHOLD_MS).then_some(delay_ms) +} + // Custom LOGGER format for the terminal: fn terminal_colored_logger_format( w: &mut dyn std::io::Write, @@ -302,18 +364,19 @@ fn terminal_colored_logger_format( record: &log::Record, ) -> Result<(), std::io::Error> { let level = record.level(); + let log_time = get_log_time(now, record); // Write the timestamp, log level, and module path: write!( w, "[{}] {} [{}] ", - flexi_logger::style(level).paint(now.format(flexi_logger::TS_DASHES_BLANK_COLONS_DOT_BLANK).to_string()), + flexi_logger::style(level).paint(log_time.timestamp), flexi_logger::style(level).paint(record.level().to_string()), record.module_path().unwrap_or(""), )?; // Write all key-value pairs: - write_kv_pairs(w, record)?; + write_kv_pairs(w, record, log_time.delay_ms)?; // Write the log message: write!(w, "{}", flexi_logger::style(level).paint(record.args().to_string())) @@ -325,18 +388,19 @@ fn file_logger_format( now: &mut DeferredNow, record: &log::Record, ) -> Result<(), std::io::Error> { + let log_time = get_log_time(now, record); // Write the timestamp, log level, and module path: write!( w, "[{}] {} [{}] ", - now.format(flexi_logger::TS_DASHES_BLANK_COLONS_DOT_BLANK), + log_time.timestamp, record.level(), record.module_path().unwrap_or(""), )?; // Write all key-value pairs: - write_kv_pairs(w, record)?; + write_kv_pairs(w, record, log_time.delay_ms)?; // Write the log message: write!(w, "{}", record.args()) @@ -361,26 +425,37 @@ fn parse_dotnet_log_level(level: &str) -> Level { } } +/// Reads the timestamp of a .NET log event, e.g., `2026-10-09T17:53:54.5629130+00:00`, +/// and returns it in microseconds since the Unix epoch. +fn parse_dotnet_timestamp(timestamp: &str) -> Option { + DateTime::parse_from_rfc3339(timestamp) + .ok() + .map(|timestamp| timestamp.timestamp_micros()) +} + /// Logs a message with the specified level, including optional exception and stack trace. +/// When the time the event happened is known, every line carries it. fn log_with_level( + logger: &dyn log::Log, level: Level, category: &str, + created_at: Option, message: &str, exception: Option<&String>, stack_trace: Option<&String> ) { // Log the main message: - log::log!(level, Source = ".NET Server", Comp = category; "{message}"); + log::log!(logger: logger, level, Source = ".NET Server", Comp = category, (CREATED_AT_KEY) = created_at; "{message}"); // Log exception if present: if let Some(ex) = exception { - log::log!(level, Source = ".NET Server", Comp = category; " Exception: {ex}"); + log::log!(logger: logger, level, Source = ".NET Server", Comp = category, (CREATED_AT_KEY) = created_at; " Exception: {ex}"); } // Log stack trace if present: if let Some(stack_trace) = stack_trace { for line in stack_trace.lines() { - log::log!(level, Source = ".NET Server", Comp = category; " {line}"); + log::log!(logger: logger, level, Source = ".NET Server", Comp = category, (CREATED_AT_KEY) = created_at; " {line}"); } } } @@ -390,10 +465,13 @@ pub async fn log_event(_token: APIToken, Json(event): Json) -> Json) -> Json String { + let mut line = Vec::new(); + format( + &mut line, + &mut DeferredNow::new(), + &log::Record::builder() + .args(format_args!("Hello")) + .level(Level::Info) + .module_path(Some(MODULE_PATH)) + .key_values(key_values) + .build(), + ).unwrap(); + + String::from_utf8(line).unwrap() + } + + fn micros_ago(milliseconds: i64) -> i64 { + (Utc::now() - TimeDelta::milliseconds(milliseconds)).timestamp_micros() + } + + fn format_micros(micros: i64) -> String { + DateTime::::from_timestamp_micros(micros) + .unwrap() + .format(flexi_logger::TS_DASHES_BLANK_COLONS_DOT_BLANK) + .to_string() + } + + #[test] + fn late_line_starts_with_the_time_its_event_happened() { + let created_at = micros_ago(2_000); + let line = write_line(file_logger_format, &[ + ("Source", ".NET Server".to_value()), + (CREATED_AT_KEY, Some(created_at).to_value()), + ]); + + let prefix = format!("[{}] INFO [{MODULE_PATH}] [Delay = ", format_micros(created_at)); + assert!(line.starts_with(&prefix), "{line}"); + assert!(line.ends_with(" ms, Source = .NET Server] Hello"), "{line}"); + + let delay_ms: i64 = line[prefix.len()..].split(" ms").next().unwrap().parse().unwrap(); + assert!((2_000..60_000).contains(&delay_ms), "{line}"); + } + + #[test] + fn usual_transport_time_shows_no_delay() { + let created_at = micros_ago(0); + let line = write_line(file_logger_format, &[ + ("Source", ".NET Server".to_value()), + (CREATED_AT_KEY, Some(created_at).to_value()), + ]); + + assert_eq!(line, format!("[{}] INFO [{MODULE_PATH}] [Source = .NET Server] Hello", format_micros(created_at))); + } + + #[test] + fn line_without_creation_time_shows_its_arrival_time() { + let missing_created_at: Option = None; + let without_key: [(&str, Value); 1] = [("Source", ".NET Server".to_value())]; + let without_value: [(&str, Value); 2] = [ + ("Source", ".NET Server".to_value()), + (CREATED_AT_KEY, missing_created_at.to_value()), + ]; + + for key_values in [&without_key as &dyn Source, &without_value] { + let before = Utc::now().timestamp_micros(); + let line = write_line(file_logger_format, key_values); + let after = Utc::now().timestamp_micros(); + + let timestamp = &line[1..line.find(']').unwrap()]; + let arrived_at = DateTime::parse_from_str(timestamp, flexi_logger::TS_DASHES_BLANK_COLONS_DOT_BLANK).unwrap().timestamp_micros(); + assert!((before..=after).contains(&arrived_at), "{line}"); + assert!(line.ends_with(&format!("INFO [{MODULE_PATH}] [Source = .NET Server] Hello")), "{line}"); + } + } + + #[test] + fn creation_time_is_never_written_as_a_pair() { + let formats: [FormatFunction; 2] = [file_logger_format, terminal_colored_logger_format]; + for format in formats { + let late_line = write_line(format, &[(CREATED_AT_KEY, micros_ago(2_000))]); + assert!(late_line.contains("[Delay = "), "{late_line}"); + assert!(!late_line.contains(CREATED_AT_KEY), "{late_line}"); + + let line = write_line(format, &[(CREATED_AT_KEY, micros_ago(0))]); + assert!(!line.contains(CREATED_AT_KEY), "{line}"); + assert!(!line.contains("[] "), "{line}"); + } + } + + #[test] + fn delay_counts_only_from_the_threshold_on() { + let created_at = Utc::now(); + let arrived_after = |milliseconds| created_at + TimeDelta::milliseconds(milliseconds); + + assert_eq!(get_notable_delay_ms(created_at, arrived_after(DELAY_THRESHOLD_MS - 1)), None); + assert_eq!(get_notable_delay_ms(created_at, arrived_after(DELAY_THRESHOLD_MS)), Some(DELAY_THRESHOLD_MS)); + assert_eq!(get_notable_delay_ms(created_at, arrived_after(1_583)), Some(1_583)); + + // A record that seems to arrive before its event happened shows no delay: + assert_eq!(get_notable_delay_ms(created_at, arrived_after(-5)), None); + } + + #[test] + fn dotnet_timestamps_are_read_in_microseconds() { + let expected = (Utc.with_ymd_and_hms(2026, 10, 9, 17, 53, 54).unwrap() + TimeDelta::microseconds(562_913)).timestamp_micros(); + + assert_eq!(parse_dotnet_timestamp("2026-10-09T17:53:54.5629130+00:00"), Some(expected)); + assert_eq!(parse_dotnet_timestamp("2026-10-09T19:53:54.5629130+02:00"), Some(expected)); + } + + #[test] + fn unreadable_dotnet_timestamps_are_rejected() { + // The format .NET sent before, with the time separator of the current culture: + assert_eq!(parse_dotnet_timestamp("2026-10-09 17:53:54.562"), None); + assert_eq!(parse_dotnet_timestamp("2026-10-09 17.53.54.562"), None); + assert_eq!(parse_dotnet_timestamp(""), None); + } + + /// Remembers the message and the creation time of every record it receives. + #[derive(Default)] + struct CapturingLogger(Mutex)>>); + + impl log::Log for CapturingLogger { + fn enabled(&self, _: &log::Metadata) -> bool { + true + } + + fn log(&self, record: &log::Record) { + let created_at = record + .key_values() + .get(Key::from_str(CREATED_AT_KEY)) + .and_then(|value| value.to_i64()); + + self.0.lock().unwrap().push((record.args().to_string(), created_at)); + } + + fn flush(&self) {} + } + + #[test] + fn every_line_of_a_dotnet_event_carries_its_time() { + // Without a global logger, the log macros would drop every record before it reaches ours: + log::set_max_level(LevelFilter::Info); + + let logger = CapturingLogger::default(); + let created_at = parse_dotnet_timestamp("2026-10-09T17:53:54.5629130+00:00"); + let exception = String::from("Boom"); + let stack_trace = String::from("at First()\nat Second()"); + assert!(created_at.is_some()); + + log_with_level(&logger, Level::Info, "Tests", created_at, "Hello", Some(&exception), Some(&stack_trace)); + + assert_eq!(logger.0.into_inner().unwrap(), vec![ + (String::from("Hello"), created_at), + (String::from(" Exception: Boom"), created_at), + (String::from(" at First()"), created_at), + (String::from(" at Second()"), created_at), + ]); + } + #[test] fn flatpak_standard_path_matches_tauri_local_data_path() { let base_directory = PathBuf::from("/var/data");