From 7f7e9c0e390002ff09c7ff64e34a9aae979d7ed9 Mon Sep 17 00:00:00 2001 From: zarzet <42882290+zarzet@users.noreply.github.com> Date: Sun, 4 Oct 2026 01:41:38 +0700 Subject: [PATCH] perf(logging): batch UI updates and gate native log copies --- lib/utils/logger.dart | 21 +++- rust_backend/crates/extensions/src/logging.rs | 107 ++++++++++++++---- test/log_selection_test.dart | 30 +++++ 3 files changed, 133 insertions(+), 25 deletions(-) diff --git a/lib/utils/logger.dart b/lib/utils/logger.dart index 880c6092..58ea3233 100644 --- a/lib/utils/logger.dart +++ b/lib/utils/logger.dart @@ -142,8 +142,21 @@ class LogBuffer extends ChangeNotifier { int get length => _entries.length; void add(LogEntry entry) { + if (_append(entry)) notifyListeners(); + } + + /// A native poll is one UI update, even when it contains hundreds of logs. + void addAll(Iterable entries) { + var changed = false; + for (final entry in entries) { + changed = _append(entry) || changed; + } + if (changed) notifyListeners(); + } + + bool _append(LogEntry entry) { if (!_loggingEnabled && entry.level != 'ERROR' && entry.level != 'FATAL') { - return; + return false; } final sanitizedMessage = _truncateLogText( @@ -172,7 +185,7 @@ class LogBuffer extends ChangeNotifier { _entries.removeFirst(); } _entries.add(sanitizedEntry); - notifyListeners(); + return true; } void startGoLogPolling() { @@ -200,6 +213,7 @@ class LogBuffer extends ChangeNotifier { final logs = result['logs'] as List? ?? []; final nextIndex = result['next_index'] as int? ?? _lastGoLogIndex; final keepNonErrorLogs = _loggingEnabled; + final entries = []; for (final log in logs.whereType>()) { final logMap = Map.from(log); @@ -231,7 +245,7 @@ class LogBuffer extends ChangeNotifier { } catch (_) {} } - add( + entries.add( LogEntry( timestamp: parsedTime, level: level, @@ -242,6 +256,7 @@ class LogBuffer extends ChangeNotifier { ); } + addAll(entries); _lastGoLogIndex = nextIndex; } catch (e) { if (kDebugMode) { diff --git a/rust_backend/crates/extensions/src/logging.rs b/rust_backend/crates/extensions/src/logging.rs index f1f21a9f..29cb6f6f 100644 --- a/rust_backend/crates/extensions/src/logging.rs +++ b/rust_backend/crates/extensions/src/logging.rs @@ -26,7 +26,7 @@ struct State { } #[derive(Default)] -pub struct LogBuffer(Mutex); +pub struct LogBuffer(Mutex, Mutex<()>); #[derive(Clone, Copy, Debug, PartialEq, Eq, thiserror::Error)] #[error("log buffer closed")] @@ -53,16 +53,31 @@ impl LogBuffer { } pub fn add(&self, level: &str, tag: &str, message: &str) -> Result<(), LogClosed> { - self.add_bytes(level, tag, message.as_bytes().to_vec()) + self.add_message(level, tag, || message.as_bytes().to_vec(), false) } - fn add_bytes(&self, level: &str, tag: &str, message: Vec) -> Result<(), LogClosed> { + fn add_message( + &self, + level: &str, + tag: &str, + message: impl FnOnce() -> Vec, + sanitized: bool, + ) -> Result<(), LogClosed> { + // Serialize append/output order without holding the state lock during + // stderr IO. Snapshot readers and shutdown can still access the buffer. + let _output = self.1.lock().expect("log output lock"); let mut state = self.0.lock().expect("log buffer lock"); state.check()?; if !state.enabled && level != "ERROR" && level != "FATAL" { return Ok(()); } - let message = decode_go_utf8(&truncate(sanitize_bytes(message))); + let message = message(); + let message = if sanitized { + message + } else { + sanitize_bytes(message) + }; + let message = decode_go_utf8(&truncate(message)); let entry = LogEntry { timestamp: chrono::Local::now().format("%H:%M:%S%.3f").to_string(), level: level.into(), @@ -72,25 +87,22 @@ impl LogBuffer { if state.entries.len() == CAPACITY { state.entries.pop_front(); } - use std::io::Write; - let _ = writeln!( - std::io::stderr().lock(), - "[{}] {}", - entry.tag, - entry.message - ); + let line = format!("[{}] {}", entry.tag, entry.message); state.entries.push_back(entry); state.next_index = state.next_index.wrapping_add(1); + drop(state); + use std::io::Write; + let _ = writeln!(std::io::stderr().lock(), "{line}"); Ok(()) } pub fn backend(&self, message: &str) -> Result<(), LogClosed> { - self.backend_bytes(message.as_bytes().to_vec()) + self.backend_bytes(message.as_bytes(), false) } - fn backend_bytes(&self, mut message: Vec) -> Result<(), LogClosed> { + fn backend_bytes(&self, mut message: &[u8], sanitized: bool) -> Result<(), LogClosed> { if message.last() == Some(&b'\n') { - message.pop(); + message = &message[..message.len() - 1]; } let mut tag = "Rust".to_owned(); if message.first() == Some(&b'[') @@ -102,7 +114,7 @@ impl LogBuffer { tag = decode_go_utf8(&message[1..end]); message = trim_bytes(&message[end + 1..]); } - let lowercase = spotiflac_core::matching::lowercase(&decode_go_utf8(&message)); + let lowercase = spotiflac_core::matching::lowercase(&decode_go_utf8(message)); let level = if lowercase.contains("error") || lowercase.contains("failed") { "ERROR" } else if lowercase.contains("warning") || lowercase.contains("warn") { @@ -117,7 +129,7 @@ impl LogBuffer { } else { "INFO" }; - self.add_bytes(level, &tag, message) + self.add_message(level, &tag, || message.to_vec(), sanitized) } pub(crate) fn extension(&self, id: &str, level: &str, arguments: Vec, total: usize) { @@ -147,7 +159,7 @@ impl LogBuffer { .into_bytes(); line.extend(formatted); line.push(b'\n'); - let _ = self.backend_bytes(line); + let _ = self.backend_bytes(&line, true); } pub fn all(&self) -> Result { @@ -206,15 +218,66 @@ fn truncate(mut message: Vec) -> Vec { message } -fn trim_bytes(bytes: &[u8]) -> Vec { +fn trim_bytes(bytes: &[u8]) -> &[u8] { // Invalid bytes are non-whitespace in Go and are retained until JSON export. let decoded = decode_go_utf8(bytes); let left = decoded.len() - decoded.trim_start().len(); let right = decoded.len() - decoded.trim_end().len(); let end = bytes.len().saturating_sub(right); - if left >= end { - Vec::new() - } else { - bytes[left..end].to_vec() + if left >= end { &[] } else { &bytes[left..end] } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn disabled_messages_skip_conversion_but_errors_and_closed_state_are_preserved() { + let logs = LogBuffer::default(); + logs.add_message( + "DEBUG", + "Example", + || panic!("disabled message copied"), + false, + ) + .unwrap(); + for level in ["ERROR", "FATAL"] { + logs.add(level, "Example", "password=fixture-secret;") + .unwrap(); + } + let values: serde_json::Value = serde_json::from_str(&logs.all().unwrap()).unwrap(); + assert_eq!(values[0]["message"], "password=[REDACTED];"); + assert_eq!(values[1]["level"], "FATAL"); + logs.shutdown(); + assert_eq!(logs.add("DEBUG", "Example", "ignored"), Err(LogClosed)); + } + + #[test] + fn extension_redaction_precedes_level_inference_and_preserves_raw_byte_truncation() { + let logs = LogBuffer::default(); + logs.set_enabled(true).unwrap(); + logs.extension( + "example", + "WARN", + vec!["password=failed-secret;".into(), "é".repeat(257)], + 2, + ); + let values: serde_json::Value = serde_json::from_str(&logs.all().unwrap()).unwrap(); + assert_eq!(values[0]["level"], "INFO"); + assert_eq!(values[0]["tag"], "Extension:example:WARN"); + assert_eq!( + values[0]["message"], + format!("password=[REDACTED]; {}...[truncated]", "é".repeat(256)) + ); + logs.extension( + "example", + "", + vec!["failure: failed password=fixture-secret;".into()], + 1, + ); + assert_eq!(logs.count().unwrap(), 2); + let values: serde_json::Value = serde_json::from_str(&logs.all().unwrap()).unwrap(); + assert_eq!(values[1]["level"], "ERROR"); + assert!(!logs.all().unwrap().contains("fixture-secret")); } } diff --git a/test/log_selection_test.dart b/test/log_selection_test.dart index ae1de4de..cd928d20 100644 --- a/test/log_selection_test.dart +++ b/test/log_selection_test.dart @@ -6,6 +6,36 @@ import 'package:spotiflac_android/screens/settings/log_screen.dart'; import 'package:spotiflac_android/utils/logger.dart'; void main() { + test( + 'native log batches notify once and preserve redaction and capacity', + () { + final buffer = LogBuffer()..clear(); + var updates = 0; + void listener() => updates++; + buffer.addListener(listener); + addTearDown(() { + buffer.removeListener(listener); + buffer.clear(); + }); + buffer.addAll([ + for (var index = 0; index < 600; index++) + LogEntry( + timestamp: DateTime(2026), + level: 'ERROR', + tag: 'Native', + message: '$index -decryption_key secret-value', + ), + ]); + expect(updates, 1); + expect(buffer.length, LogBuffer.maxEntries); + expect(buffer.entries.first.message, startsWith('100 ')); + expect(buffer.entries.last.message, startsWith('599 ')); + expect(formatLogEntries(buffer.entries), isNot(contains('secret-value'))); + buffer.addAll(const []); + expect(updates, 1); + }, + ); + test('selected log export keeps chronological lines only', () { final entries = [ LogEntry(