diff --git a/ExtLibs/Utilities/DFLogBuffer.cs b/ExtLibs/Utilities/DFLogBuffer.cs index b001bb24b1..530ebc2a3c 100644 --- a/ExtLibs/Utilities/DFLogBuffer.cs +++ b/ExtLibs/Utilities/DFLogBuffer.cs @@ -6,7 +6,6 @@ using System.IO; using System.IO.Compression; using System.Linq; -using System.Runtime.Serialization.Formatters.Binary; using System.Text; using System.Text.RegularExpressions; using System.Threading.Tasks; @@ -95,7 +94,8 @@ public DFLogBuffer(Stream instream) void setlinecount() { - if (string.IsNullOrEmpty(_filename) || !LoadCache()) + LastLoadFromCache = !string.IsNullOrEmpty(_filename) && LoadCache(); + if (!LastLoadFromCache) { byte[] buffer = new byte[1024 * 1024]; @@ -331,14 +331,21 @@ void setlinecount() indexcachelineno = -1; } - [Serializable] - struct cache - { - public List[] messageindex; - public List[] messageindexline; - public List linestartoffset; - public long lineCount; - } + // index cache file format: gzip over a small header (magic, version, + // source length and last-write ticks) followed by the raw index longs. + // Upstream serialized this with BinaryFormatter, which throws + // unconditionally on modern .NET - saving a large log crashed the open + // and loading silently never worked. + const uint CacheMagic = 0x4C444D31; // "1MDL" + const int CacheVersion = 1; + + /// Logs at or above this many bytes get an index cache + /// (test seam; the product default matches upstream's 300 MB). + internal static long CacheThresholdBytes = 1024L * 1024 * 300; + + /// Whether the last setlinecount loaded the index cache + /// instead of scanning (test observability). + internal static bool LastLoadFromCache; private string CachePath { @@ -359,59 +366,134 @@ private void SaveCache() { if (string.IsNullOrEmpty(_filename)) return; - // save cache if file is over 300mb - if (basestream.Length < 1024 * 1024 * 300) + // save cache if file is over the threshold (upstream: 300mb) + if (basestream.Length < CacheThresholdBytes) return; - //save cache - cache cache = new cache(); - cache.messageindex = messageindex; - cache.messageindexline = messageindexline; - cache.linestartoffset = linestartoffset; - cache.lineCount = _count; - - using (var file = File.OpenWrite(CachePath)) + + try { - using (GZipStream gs = new GZipStream(file, CompressionMode.Compress)) + var source = new FileInfo(_filename); + // computed once: the property re-derives the path (and, in its + // degraded catch branch, a different name) on every access + var cachePath = CachePath; + var temp = cachePath + ".tmp"; + using (var file = File.Create(temp)) + using (var gs = new GZipStream(file, CompressionMode.Compress)) + using (var writer = new BinaryWriter(gs)) { - BinaryFormatter serializer = new BinaryFormatter(); - serializer.Serialize(gs, cache); + writer.Write(CacheMagic); + writer.Write(CacheVersion); + writer.Write(source.Length); + writer.Write(source.LastWriteTimeUtc.Ticks); + + writer.Write(_count); + WriteLongList(writer, linestartoffset); + for (int a = 0; a < messageindex.Length; a++) + { + WriteLongList(writer, messageindex[a]); + WriteLongList(writer, messageindexline[a]); + } } + + // replace through a temp file so a torn write never lands at the + // cache path; the delete+move pair leaves at worst a moment with + // no cache, which just means a rescan + File.Delete(cachePath); + File.Move(temp, cachePath); + } + catch + { + // the cache is an optimization - never fail an open over it } } private bool LoadCache() { - if (File.Exists(CachePath)) + try { - //load cache - cache cache = new cache(); - BinaryFormatter deserializer = new BinaryFormatter(); - using (var file = File.OpenRead(CachePath)) + // computed once: the property re-derives the path (and, in its + // degraded catch branch, a different name) on every access + var cachePath = CachePath; + if (!File.Exists(cachePath)) + return false; + + var source = new FileInfo(_filename); + using (var file = File.OpenRead(cachePath)) + using (var gs = new GZipStream(file, CompressionMode.Decompress)) + using (var reader = new BinaryReader(gs)) { - using (GZipStream gs = new GZipStream(file, CompressionMode.Decompress)) + if (reader.ReadUInt32() != CacheMagic || reader.ReadInt32() != CacheVersion) + return false; + + // a cache for an older copy of the log must not survive an + // in-place change; the path only encodes the file length, + // so a same-length edit is caught by the write time here + if (reader.ReadInt64() != source.Length || + reader.ReadInt64() != source.LastWriteTimeUtc.Ticks) + return false; + + // the cache lives in the shared temp directory, so its + // contents are untrusted: no index list can have more + // entries than the log has records (every record is at + // least 3 bytes), and a corrupt count must be rejected + // before it becomes a pre-allocation + var maxEntries = source.Length / 3 + 1; + var lineCount = reader.ReadInt64(); + var offsets = ReadLongList(reader, maxEntries); + var index = new List[messageindex.Length]; + var indexline = new List[messageindex.Length]; + for (int a = 0; a < index.Length; a++) { - try - { - cache = (cache)deserializer.Deserialize(gs); - } - catch - { - return false; - } + index[a] = ReadLongList(reader, maxEntries); + indexline[a] = ReadLongList(reader, maxEntries); } - } - messageindex = cache.messageindex; - messageindexline = cache.messageindexline; - linestartoffset = cache.linestartoffset; - _count = cache.lineCount; + // commit only after the whole cache read back cleanly + messageindex = index; + messageindexline = indexline; + linestartoffset = offsets; + _count = lineCount; + } // build fmt line database to pre seed the FMT message messageindexline[128].ForEach(a => dflog.FMTLine(this[(int)a])); return true; } + catch + { + // a torn or foreign cache must not leave a half-loaded index + // behind - the caller's rescan appends into these collections. + // (dflog.logformat entries FMTLine seeded before the throw are + // deliberately left alone: nothing enumerates a type whose + // messageindex is empty, and the rescan re-seeds every real FMT + // line by key) + linestartoffset = new List(); + for (int a = 0; a < messageindex.Length; a++) + { + messageindex[a] = new List(0); + messageindexline[a] = new List(0); + } + _count = 0; + return false; + } + } + + static void WriteLongList(BinaryWriter writer, List values) + { + writer.Write(values.Count); + foreach (var value in values) + writer.Write(value); + } - return false; + static List ReadLongList(BinaryReader reader, long maxEntries) + { + var count = reader.ReadInt32(); + if (count < 0 || count > maxEntries) + throw new InvalidDataException("implausible index list length " + count); + var values = new List(count); + for (int i = 0; i < count; i++) + values.Add(reader.ReadInt64()); + return values; } public void SplitLog(int pieces = 0) diff --git a/MissionPlannerTests/Avalonia/MissionPlanner.Tests/DflogBufferCacheTests.cs b/MissionPlannerTests/Avalonia/MissionPlanner.Tests/DflogBufferCacheTests.cs new file mode 100644 index 0000000000..74842a5016 --- /dev/null +++ b/MissionPlannerTests/Avalonia/MissionPlanner.Tests/DflogBufferCacheTests.cs @@ -0,0 +1,186 @@ +using MissionPlanner.Utilities; + +namespace MissionPlanner.Tests; + +/// +/// The DFLogBuffer index cache for large logs. Upstream serialized it with +/// BinaryFormatter, which throws unconditionally on modern .NET - saving +/// crashed the open of any path-backed log over the threshold, and loading +/// silently never worked. These tests pin the replacement format: round-trip +/// fidelity, stale- and corrupt-cache rejection, and that an over-threshold +/// open never throws (the first open here fails outright on the old code). +/// +public class DflogBufferCacheTests { + private static byte[] BuildLog(int rows, byte flip = 0) { + // FMT: type 0xA0 "TST", format "Hf", labels "N,V", len 3+2+4 + var data = new List { 0xA3, 0x95, 0x80 }; + var fmt = new byte[86]; + fmt[0] = 0xA0; + fmt[1] = 3 + 2 + 4; + System.Text.Encoding.ASCII.GetBytes("TST").CopyTo(fmt, 2); + System.Text.Encoding.ASCII.GetBytes("Hf").CopyTo(fmt, 6); + System.Text.Encoding.ASCII.GetBytes("N,V").CopyTo(fmt, 22); + data.AddRange(fmt); + for (int i = 0; i < rows; i++) { + data.AddRange(new byte[] { 0xA3, 0x95, 0xA0 }); + data.AddRange(BitConverter.GetBytes((ushort)(i ^ flip))); + data.AddRange(BitConverter.GetBytes(1.5f * i)); + } + return data.ToArray(); + } + + private static List Lines(DFLogBuffer buffer) { + var lines = new List(); + for (int i = 0; i < buffer.Count; i++) { + lines.Add(buffer[i]); + } + return lines; + } + + /// + /// Lowers the cache threshold so kilobyte fixtures exercise the cache, and + /// sweeps the cache files (which live in the system temp directory, keyed + /// by the log's mangled path) on the way out. + /// + private sealed class CacheScope : IDisposable { + private readonly long _oldThreshold; + + public DirectoryInfo Dir { get; } + public string LogPath { get; } + + public CacheScope() { + _oldThreshold = DFLogBuffer.CacheThresholdBytes; + DFLogBuffer.CacheThresholdBytes = 1; + Dir = Directory.CreateTempSubdirectory("DflogBufferCacheTests"); + LogPath = Path.Combine(Dir.FullName, "test.bin"); + } + + public string[] CacheFiles() { + return Directory.GetFiles(Path.GetTempPath(), "*" + Dir.Name + "*"); + } + + public void Dispose() { + DFLogBuffer.CacheThresholdBytes = _oldThreshold; + try { + Dir.Delete(true); + } catch (IOException) { + } + foreach (string stale in CacheFiles()) { + try { + File.Delete(stale); + } catch (IOException) { + } + } + } + } + + [Fact] + public void Cache_round_trip_restores_the_identical_index() { + using var scope = new CacheScope(); + File.WriteAllBytes(scope.LogPath, BuildLog(50)); + + List scanned; + long count; + // the first open scans and saves the cache; on the BinaryFormatter code + // this line throws for any over-threshold log + using (var buffer = new DFLogBuffer(scope.LogPath)) { + Assert.False(DFLogBuffer.LastLoadFromCache); + scanned = Lines(buffer); + count = buffer.Count; + Assert.Equal(51, count); + } + + Assert.NotEmpty(scope.CacheFiles()); + + using (var buffer = new DFLogBuffer(scope.LogPath)) { + Assert.True(DFLogBuffer.LastLoadFromCache, + "second open scanned instead of loading the cache"); + Assert.Equal(count, buffer.Count); + Assert.Equal(scanned, Lines(buffer)); + Assert.Equal(50, buffer.GetEnumeratorType("TST").Count()); + } + } + + [Fact] + public void Same_length_edit_rejects_the_stale_cache() { + using var scope = new CacheScope(); + File.WriteAllBytes(scope.LogPath, BuildLog(50)); + using (new DFLogBuffer(scope.LogPath)) { + } + Assert.NotEmpty(scope.CacheFiles()); + + // same byte count, different content - the cache path encodes only the + // length, so this must be caught by the recorded write time + File.WriteAllBytes(scope.LogPath, BuildLog(50, flip: 1)); + File.SetLastWriteTimeUtc(scope.LogPath, DateTime.UtcNow.AddSeconds(3)); + + using var buffer = new DFLogBuffer(scope.LogPath); + Assert.False(DFLogBuffer.LastLoadFromCache, + "a cache for an older copy of the log was loaded"); + Assert.Equal(51, buffer.Count); + } + + /// + /// The cache lives in the shared temp directory, so a crafted file with a + /// valid header but an absurd list length must be rejected by the + /// plausibility bound instead of turning into a giant pre-allocation. + /// + [Fact] + public void Implausible_list_length_in_the_cache_is_rejected() { + using var scope = new CacheScope(); + File.WriteAllBytes(scope.LogPath, BuildLog(50)); + + List scanned; + using (var buffer = new DFLogBuffer(scope.LogPath)) { + scanned = Lines(buffer); + } + + string cache = Assert.Single(scope.CacheFiles()); + var source = new FileInfo(scope.LogPath); + using (var file = File.Create(cache)) + using (var gzip = new System.IO.Compression.GZipStream( + file, System.IO.Compression.CompressionMode.Compress)) + using (var writer = new BinaryWriter(gzip)) { + writer.Write(0x4C444D31u); // valid magic + writer.Write(1); // valid version + writer.Write(source.Length); // matching identity + writer.Write(source.LastWriteTimeUtc.Ticks); + writer.Write(51L); // line count + writer.Write(int.MaxValue); // absurd list length + } + + using (var buffer = new DFLogBuffer(scope.LogPath)) { + Assert.False(DFLogBuffer.LastLoadFromCache); + Assert.Equal(scanned, Lines(buffer)); + } + } + + [Theory] + [InlineData("garbage")] + [InlineData("truncated")] + public void Corrupt_cache_falls_back_to_a_clean_rescan(string mode) { + using var scope = new CacheScope(); + File.WriteAllBytes(scope.LogPath, BuildLog(50)); + + List scanned; + using (var buffer = new DFLogBuffer(scope.LogPath)) { + scanned = Lines(buffer); + } + + string cache = Assert.Single(scope.CacheFiles()); + if (mode == "garbage") { + File.WriteAllBytes(cache, new byte[] { 1, 2, 3, 4, 5, 6, 7, 8 }); + } else { + // a torn write: valid prefix, missing tail - the loader must reject it + // without leaving a half-committed index behind for the rescan + byte[] full = File.ReadAllBytes(cache); + File.WriteAllBytes(cache, full.Take(full.Length / 2).ToArray()); + } + + using (var buffer = new DFLogBuffer(scope.LogPath)) { + Assert.False(DFLogBuffer.LastLoadFromCache); + Assert.Equal(scanned, Lines(buffer)); + Assert.Equal(50, buffer.GetEnumeratorType("TST").Count()); + } + } +} diff --git a/Porting/STATUS.md b/Porting/STATUS.md index 437fe000e4..6c622c1b3f 100644 --- a/Porting/STATUS.md +++ b/Porting/STATUS.md @@ -2,6 +2,41 @@ Updated: **2026-08-31**. +## DFLogBuffer index cache rebuilt without BinaryFormatter (branch fix/dflogbuffer-savecache-net10) + +- `BinaryFormatter` throws unconditionally on modern .NET, which made `DFLogBuffer`'s large-log + index cache doubly broken: `SaveCache` crashed the open of any path-backed log at or over + 300 MB (`LoadCache` only survived because its `Deserialize` sat in a try/catch, so loading + silently never worked either). Stream-wrapping callers (`LogIndexService`, + `OfflineMagFitService`) dodge it by hiding the filename; every path-based consumer - LogBrowse + curves/rows, expressions, FFT, GeoRef - was exposed. +- The cache is reimplemented with `BinaryWriter`/`BinaryReader` over the existing GZip stream: + magic + version header, then the source file's length and last-write ticks (the cache path only + encodes the length, so a same-length in-place edit is now caught too - an upstream gap), then + the raw index longs. Writes go through a temp file and replace, so a torn write never lands at + the cache path (also fixing upstream's non-truncating `File.OpenWrite`; the delete+move pair + leaves at worst a moment with no cache). List lengths read from the cache - which lives in the + shared temp directory and is untrusted - are bounded by the source log's possible record count + before any pre-allocation. The load commits only after the whole cache reads back cleanly and resets + the collections on any failure so a torn cache cannot leave a half-loaded index for the rescan + to append onto, and both directions degrade to a fresh scan instead of throwing. The + `System.Runtime.Serialization.Formatters.Binary` using and the `[Serializable]` struct are gone. +- Threshold promoted to an internal test seam (`CacheThresholdBytes`, default unchanged) plus a + `LastLoadFromCache` observability flag. `DflogBufferCacheTests` (4 cases over a synthesized + binary log): round-trip index identity, same-length-edit stale-cache rejection, and + garbage/truncated cache fallback - all four fail against the old code (verified by reverting + the implementation under the new tests; the round-trip test's first open throws exactly like + production). +- Real-log proof (433.6 MiB / 10.55M-record log from uav.tridgell.net/tmp, which crashes the + open on master): first open 5.66 s scan + cache save, second open 1.78 s from the cache with + an identical index. Full suite 1536/1548; the failures are the known environment-dependent + set, unchanged from master. +- Interaction note: the dflog phase-2 branch (`feature/dflog-native-bindings`) edits the same + `setlinecount` region; whichever lands second takes a small rebase, and the semantics compose + (the native scanner skips this cache in both directions, the managed fallback now has a + working cache again). +- Remaining blocker: none. Follow-up candidates recorded previously: un-wrapping the + `CancellationReadStream` callers so they can share the cache and native paths. ## Flight Data bearing-overlay zoom stability - Dedicated branch `fix/flight-data-bearing-overlay-zoom` starts from merged `master`