From 722b7f87ffa39a7db2231dff0b51bdedb7520720 Mon Sep 17 00:00:00 2001 From: Sebastian Hedtrich Date: Tue, 18 Aug 2026 21:53:30 +0200 Subject: [PATCH] fix: Sync blockierte dauerhaft und unsichtbar bei fehlerhaftem Ereignis MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit EventApplier.ApplyAsync fing bisher nur LiteException ab - jede andere Ausnahme (z.B. eine fehlerhafte Entschlüsselung/Deserialisierung eines einzelnen Ereignisses) fiel unbehandelt aus der Pull-Schleife in SyncEngine.PullAsync heraus, bevor der Fortschritt (SetLastServerSeq) gespeichert wurde. Der nächste Sync-Versuch lud denselben Batch erneut und scheiterte am selben Ereignis wieder - ein dauerhaft blockierter Sync, bei dem selbst bereits erfolgreich angewendete Ereignisse im selben Batch nie als erledigt markiert wurden. Zusätzlich protokollierte weder SyncEngine noch EventApplier irgendetwas, ein Fehlschlag zeigte sich höchstens als knapper Text in der Sync-Statusleiste. EventApplier fängt jetzt jede Ausnahme pro Ereignis ab (geloggt über AppLogger, übersprungen statt den Batch zu blockieren); SyncEngine loggt jeden Sync-Fehlschlag vollständig. Betrifft nur den Desktop-Client, kein API-Redeploy nötig. Co-Authored-By: Claude Sonnet 5 --- LehrerApp.Desktop/AppBootstrapper.cs | 5 +- LehrerApp.Sync.Tests/SyncEngineTests.cs | 88 +++++++++++++++++++++++++ LehrerApp.Sync/EventApplier.cs | 27 +++++++- LehrerApp.Sync/SyncEngine.cs | 22 ++++++- TODO.md | 30 +++++++++ 5 files changed, 164 insertions(+), 8 deletions(-) create mode 100644 LehrerApp.Sync.Tests/SyncEngineTests.cs diff --git a/LehrerApp.Desktop/AppBootstrapper.cs b/LehrerApp.Desktop/AppBootstrapper.cs index 9ef4713..13aa735 100644 --- a/LehrerApp.Desktop/AppBootstrapper.cs +++ b/LehrerApp.Desktop/AppBootstrapper.cs @@ -200,7 +200,7 @@ public static class AppBootstrapper { services.AddSingleton(sp => new EventApplier( sp.GetRequiredService(), sp.GetRequiredService(), - BuildHttp(serverUrl, syncSettings))); + BuildHttp(serverUrl, syncSettings), sp.GetRequiredService())); services.AddSingleton(sp => new SyncEventPublisher( sp.GetRequiredService(), deviceId, sp.GetRequiredService())); services.AddSingleton(sp => new AttachmentSyncer( @@ -219,7 +219,8 @@ public static class AppBootstrapper DeviceId = deviceId, DeviceType = DeviceType.Desktop, AutoSyncIntervalMinutes = 5, - })); + }, + sp.GetRequiredService())); services.AddSingleton(sp => new SnapshotService( BuildHttp(serverUrl, syncSettings), diff --git a/LehrerApp.Sync.Tests/SyncEngineTests.cs b/LehrerApp.Sync.Tests/SyncEngineTests.cs new file mode 100644 index 0000000..09d6c24 --- /dev/null +++ b/LehrerApp.Sync.Tests/SyncEngineTests.cs @@ -0,0 +1,88 @@ +using System.Net; +using System.Net.Http.Json; +using LehrerApp.Core.Models; +using LehrerApp.Data; +using LehrerApp.Sync.Crypto; +using LehrerApp.Sync.Models; +using Xunit; + +namespace LehrerApp.Sync.Tests; + +public sealed class SyncEngineTests +{ + private static LiteDbContext NewInMemoryContext() => new(new MemoryStream()); + private static readonly byte[] Key = SyncCrypto.GenerateKey(); + + /// Regression: EventApplier.ApplyAsync fing früher nur LiteException ab. Jede andere Ausnahme + /// (z.B. eine ungültige/korrupte Payload eines einzelnen Ereignisses) fiel unbehandelt aus + /// SyncEngine.PullAsync heraus, BEVOR _queue.SetLastServerSeq() erreicht wurde — der nächste + /// Sync-Versuch lud denselben Batch erneut und scheiterte am selben Ereignis erneut: ein + /// dauerhaft blockierter Sync, bei dem selbst bereits im selben Batch erfolgreich angewendete + /// Ereignisse (wie hier "goodStudent") nie durchkamen. + [Fact] + public async Task SyncNowAsync_KorruptesEreignisImPullBatch_BlockiertNachfolgendeEreignisseNicht() + { + using var temp = new TempEventQueue(); + using var db = NewInMemoryContext(); + var applier = new EventApplier(db, Key); + var resolver = new ConflictResolver(temp.Queue); + var attachments = new AttachmentSyncer(db, new HttpClient(), Key); + + var goodStudent = new Student { FirstName = "Anna", LastName = "Beispiel" }; + var badEvent = new SyncEvent + { + DeviceId = "other-device", DeviceType = DeviceType.Desktop, + EntityType = nameof(Student), EntityId = Guid.NewGuid().ToString(), + Operation = "Save", Payload = "offensichtlich-keine-gueltige-verschluesselte-payload", + SequenceNr = 1, + }; + var goodEvent = new SyncEvent + { + DeviceId = "other-device", DeviceType = DeviceType.Desktop, + EntityType = nameof(Student), EntityId = goodStudent.Id.ToString(), + Operation = "Save", Payload = SyncCrypto.EncryptObject(goodStudent, Key), + SequenceNr = 2, + }; + + var handler = new FakeHttpMessageHandler(req => + { + if (req.RequestUri!.AbsolutePath == "/api/sync/pull") + return new HttpResponseMessage(HttpStatusCode.OK) + { + Content = JsonContent.Create(new PullResponse + { Events = [badEvent, goodEvent], ServerSequenceNr = 2 }), + }; + return new HttpResponseMessage(HttpStatusCode.OK); + }); + var http = new HttpClient(handler) { BaseAddress = new Uri("https://example.invalid") }; + var engine = new SyncEngine(temp.Queue, resolver, applier, attachments, http, + new SyncConfig { DeviceId = "this-device" }); + + var result = await engine.SyncNowAsync(); + + Assert.True(result.Success); + Assert.NotNull(db.Students.FindById(goodStudent.Id)); + // Nicht bei 0 stecken geblieben - der Batch gilt als vollständig verarbeitet, auch wenn ein + // einzelnes Ereignis darin übersprungen werden musste. + Assert.Equal(2, temp.Queue.GetLastServerSeq()); + } + + private sealed class TempEventQueue : IDisposable + { + private readonly string _directory = Path.Combine( + Path.GetTempPath(), $"lehrerapp-sync-tests-engine-{Guid.NewGuid():N}"); + public EventQueue Queue { get; } + + public TempEventQueue() + { + Directory.CreateDirectory(_directory); + Queue = new EventQueue(Path.Combine(_directory, "queue.db")); + } + + public void Dispose() + { + Queue.Dispose(); + if (Directory.Exists(_directory)) Directory.Delete(_directory, recursive: true); + } + } +} diff --git a/LehrerApp.Sync/EventApplier.cs b/LehrerApp.Sync/EventApplier.cs index facc140..e0d5585 100644 --- a/LehrerApp.Sync/EventApplier.cs +++ b/LehrerApp.Sync/EventApplier.cs @@ -1,6 +1,7 @@ using System.Text; using JsonSerializer = System.Text.Json.JsonSerializer; using LehrerApp.Core.Models; +using LehrerApp.Core.Services; using LehrerApp.Data; using LehrerApp.Sync.Crypto; using LehrerApp.Sync.Models; @@ -23,13 +24,18 @@ namespace LehrerApp.Sync; /// Pfad bewusst NICHT geprüft (v1-Einschränkung, siehe TODO.md 10.3) — nur harte LiteDB-Unique- /// Constraints greifen noch und führen zum Überspringen des einzelnen Ereignisses. /// -public class EventApplier(LiteDbContext db, byte[] syncKey, HttpClient? http = null) +public class EventApplier(LiteDbContext db, byte[] syncKey, HttpClient? http = null, AppLogger? logger = null) { private static readonly Dictionary Handlers = BuildHandlers(); public async Task ApplyAsync(SyncEvent evt) { - if (!Handlers.TryGetValue(evt.EntityType, out var handler)) return; + if (!Handlers.TryGetValue(evt.EntityType, out var handler)) + { + logger?.Warn($"Sync: kein Handler für Entitätstyp '{evt.EntityType}' (EntityId={evt.EntityId}, " + + $"Operation={evt.Operation}) - Ereignis übersprungen."); + return; + } try { var json = evt.Payload.Length == 0 ? "" : Decrypt(evt.Payload); @@ -37,10 +43,25 @@ public class EventApplier(LiteDbContext db, byte[] syncKey, HttpClient? http = n if (evt.EntityType == nameof(Documentation) && evt.Operation != "Delete" && http is not null) await DownloadMissingAttachmentsAsync(json); } - catch (LiteException) + catch (LiteException ex) { // Harte Constraint-Verletzung (z.B. Unique-Index) - dieses eine Ereignis // überspringen, statt den gesamten Sync-Lauf abzubrechen. + logger?.Error($"Sync: Ereignis übersprungen (LiteDB-Constraint) - {evt.EntityType} " + + $"{evt.Operation} EntityId={evt.EntityId}", ex); + } + catch (Exception ex) + { + // Jede andere Ausnahme (z.B. Entschlüsselung/Deserialisierung fehlgeschlagen) darf + // NICHT aus ApplyAsync herausfallen: SyncEngine.PullAsync ruft dies in einer Schleife + // über einen ganzen Ereignis-Batch auf, ohne eigenes try/catch - eine unbehandelte + // Ausnahme hier würde den kompletten Pull-Lauf abbrechen, BEVOR SetLastServerSeq + // aufgerufen wird. Der Pull würde beim nächsten Versuch denselben Batch erneut laden + // und an genau demselben Ereignis wieder scheitern - ein dauerhaft blockierter Sync, + // bei dem selbst bereits erfolgreich angewendete Ereignisse im selben Batch nie als + // erledigt markiert werden. + logger?.Error($"Sync: Ereignis konnte nicht angewendet werden - {evt.EntityType} " + + $"{evt.Operation} EntityId={evt.EntityId}", ex); } } diff --git a/LehrerApp.Sync/SyncEngine.cs b/LehrerApp.Sync/SyncEngine.cs index 6dc969e..5af3219 100644 --- a/LehrerApp.Sync/SyncEngine.cs +++ b/LehrerApp.Sync/SyncEngine.cs @@ -1,4 +1,5 @@ using System.Net.Http.Json; +using LehrerApp.Core.Services; using LehrerApp.Sync.Models; namespace LehrerApp.Sync; @@ -15,13 +16,14 @@ public class SyncEngine : IDisposable private readonly AttachmentSyncer _attachments; private readonly HttpClient _http; private readonly SyncConfig _config; + private readonly AppLogger? _logger; private readonly Timer _timer; public SyncStatus Status { get; private set; } = new(); public event Action? StatusChanged; public SyncEngine(EventQueue queue, ConflictResolver resolver, EventApplier applier, - AttachmentSyncer attachments, HttpClient http, SyncConfig config) + AttachmentSyncer attachments, HttpClient http, SyncConfig config, AppLogger? logger = null) { _queue = queue; _resolver = resolver; @@ -29,6 +31,7 @@ public class SyncEngine : IDisposable _attachments = attachments; _http = http; _config = config; + _logger = logger; _timer = new Timer( async _ => await SyncNowAsync(true), null, TimeSpan.FromMinutes(config.AutoSyncIntervalMinutes), @@ -50,8 +53,21 @@ public class SyncEngine : IDisposable SetState(SyncState.Idle); return new() { Success = true, EventsPushed = pushed, EventsPulled = pulled, Conflicts = conflicts }; } - catch (HttpRequestException) { SetState(SyncState.Offline); return new() { Reason = "Server nicht erreichbar" }; } - catch (Exception ex) { SetState(SyncState.Error, ex.Message); return new() { Reason = ex.Message }; } + catch (HttpRequestException ex) + { + // Sammelt sowohl echte Netzwerkfehler als auch nicht-erfolgreiche HTTP-Antworten + // (EnsureSuccessStatusCode() in Push/PullAsync) unter demselben "Offline"-Status - + // ohne Log wäre ein z.B. 401/500 vom Server nicht von "kein Internet" unterscheidbar. + _logger?.Error("Sync fehlgeschlagen (HTTP)", ex); + SetState(SyncState.Offline); + return new() { Reason = "Server nicht erreichbar" }; + } + catch (Exception ex) + { + _logger?.Error("Sync fehlgeschlagen", ex); + SetState(SyncState.Error, ex.Message); + return new() { Reason = ex.Message }; + } } private async Task<(int Pushed, int Conflicts)> PushAsync() diff --git a/TODO.md b/TODO.md index 33bda7e..8b6e90e 100644 --- a/TODO.md +++ b/TODO.md @@ -1514,6 +1514,36 @@ die Docker-Verifikation unter 10.2.4 (kein Docker im Entwicklungsstand verfügba Namens-Eindeutigkeit bei Aspekten u.ä.) werden auf diesem Pfad nicht geprüft — nur harte LiteDB-Unique-Constraints greifen noch und führen zum Überspringen des einzelnen Ereignisses. Für Einzel-/Wenig-Geräte-Nutzung akzeptiert, siehe 10.3.4. + + **Nachtrag (Bugfix — blockierter Sync bei jedem Fehler, unsichtbar und ungeloggt):** + Nutzer-Bug-Report — nach erfolgreicher Gerätekopplung kam eine neu angelegte `Lesson` auf dem + zweiten Gerät trotz mehrfacher manueller Synchronisation nicht an. Ursache im Code gefunden + (nicht live reproduziert, da keine zwei physischen Testgeräte zur Verfügung stehen): + `EventApplier.ApplyAsync` fing bisher nur `LiteException` ab — jede andere Ausnahme (z.B. + eine fehlerhafte Entschlüsselung/Deserialisierung eines einzelnen Ereignisses) fiel + unbehandelt aus der `foreach`-Schleife in `SyncEngine.PullAsync` heraus, **bevor** + `_queue.SetLastServerSeq()` erreicht wurde. Der nächste Sync-Versuch lud dadurch denselben + Ereignis-Batch erneut und scheiterte am selben Ereignis erneut — ein dauerhaft blockierter + Pull, bei dem selbst bereits im selben Batch erfolgreich angewendete Ereignisse nie als + erledigt markiert wurden. Verschärft durch fehlende Sichtbarkeit: weder `SyncEngine` noch + `EventApplier` protokollierten Ausnahmen — ein Fehlschlag zeigte sich höchstens als knapper + "Fehler: …"-Text in der kleinen Sync-Statusleiste, ohne Log-Eintrag (derselbe blinde Fleck wie + beim Pairing-Bugfix in 10.3.1). + + **Umsetzung:** `EventApplier.ApplyAsync` fängt jetzt jede Ausnahme pro Ereignis ab (protokolliert + über neu injizierten `AppLogger`, übersprüngen statt den ganzen Batch abzubrechen) — ein + einzelnes fehlerhaftes Ereignis kann den Sync nicht mehr dauerhaft blockieren. `SyncEngine` + loggt seinerseits jeden Sync-Fehlschlag (HTTP wie generisch) vollständig statt nur die + knappe `ex.Message` im Status anzuzeigen. Neuer Regressionstest + (`SyncEngineTests.SyncNowAsync_KorruptesEreignisImPullBatch_BlockiertNachfolgendeEreignisseNicht`) + belegt mit einem absichtlich korrupten Ereignis vor einem gültigen im selben Pull-Batch, dass + Zweiteres trotzdem ankommt und `GetLastServerSeq()` fortschreitet statt stecken zu bleiben. + **Wichtig:** betrifft nur `LehrerApp.Sync`/`LehrerApp.Desktop` — der Server (`LehrerApp.Api`) + ist unverändert, ein Redeploy der API ist für diesen Fix nicht nötig, wohl aber ein + Neu-Build/Neustart der Desktop-Clients. Ob dies tatsächlich die vom Nutzer beobachtete Ursache + war, ist damit noch nicht bestätigt — nach dem Update sollte ein erneuter Testlauf entweder + funktionieren oder jetzt einen konkreten, geloggten Fehler liefern statt eines stillen + Fehlschlags. - [x] **10.1.8** Datei-Anhänge (Dokumentation) über den laufenden Sync mitschicken. **Umsetzung:** Eigener, unverschlüsselt im JSON-Ereigniskanal nicht mitgeführter Binärkanal