diff --git a/LehrerApp.Desktop/AppBootstrapper.cs b/LehrerApp.Desktop/AppBootstrapper.cs index 13aa735..d775704 100644 --- a/LehrerApp.Desktop/AppBootstrapper.cs +++ b/LehrerApp.Desktop/AppBootstrapper.cs @@ -202,7 +202,8 @@ public static class AppBootstrapper sp.GetRequiredService(), sp.GetRequiredService(), BuildHttp(serverUrl, syncSettings), sp.GetRequiredService())); services.AddSingleton(sp => new SyncEventPublisher( - sp.GetRequiredService(), deviceId, sp.GetRequiredService())); + sp.GetRequiredService(), deviceId, sp.GetRequiredService(), + sp.GetRequiredService())); services.AddSingleton(sp => new AttachmentSyncer( sp.GetRequiredService(), BuildHttp(serverUrl, syncSettings), sp.GetRequiredService())); diff --git a/LehrerApp.Sync/EventApplier.cs b/LehrerApp.Sync/EventApplier.cs index e0d5585..7083e7d 100644 --- a/LehrerApp.Sync/EventApplier.cs +++ b/LehrerApp.Sync/EventApplier.cs @@ -42,6 +42,7 @@ public class EventApplier(LiteDbContext db, byte[] syncKey, HttpClient? http = n handler(db, evt.Operation, evt.EntityId, json); if (evt.EntityType == nameof(Documentation) && evt.Operation != "Delete" && http is not null) await DownloadMissingAttachmentsAsync(json); + logger?.Info($"Sync: Ereignis angewendet - {evt.EntityType} {evt.Operation} EntityId={evt.EntityId}"); } catch (LiteException ex) { diff --git a/LehrerApp.Sync/SyncEngine.cs b/LehrerApp.Sync/SyncEngine.cs index 5af3219..ad20d41 100644 --- a/LehrerApp.Sync/SyncEngine.cs +++ b/LehrerApp.Sync/SyncEngine.cs @@ -44,13 +44,17 @@ public class SyncEngine : IDisposable if (Status.State == SyncState.Syncing) return new() { Skipped = true, Reason = "Sync bereits aktiv" }; SetState(SyncState.Syncing); + _logger?.Info($"Sync: Start ({(isAutomatic ? "automatisch" : "manuell")}), Gerät={_config.DeviceId}, " + + $"{_queue.PendingCount()} lokal ausstehend"); try { - var (pushed, _) = await PushAsync(); + var (pushed, pushConflicts) = await PushAsync(); await _attachments.UploadPendingAsync(_queue); var (pulled, conflicts) = await PullAsync(); _queue.SetLastSyncAt(DateTime.UtcNow); SetState(SyncState.Idle); + _logger?.Info($"Sync: Fertig - {pushed} gepusht ({pushConflicts} Push-Konflikte), " + + $"{pulled} gepullt ({conflicts} Pull-Konflikte)"); return new() { Success = true, EventsPushed = pushed, EventsPulled = pulled, Conflicts = conflicts }; } catch (HttpRequestException ex) @@ -74,14 +78,18 @@ public class SyncEngine : IDisposable { var pending = _queue.GetPending(); if (pending.Count == 0) return (0, 0); + _logger?.Info($"Sync: Push - {pending.Count} Ereignis(se) ausstehend: " + + string.Join(", ", pending.Select(e => $"{e.EntityType}/{e.Operation}"))); var resp = await _http.PostAsJsonAsync("/api/sync/push", pending); resp.EnsureSuccessStatusCode(); var result = await resp.Content.ReadFromJsonAsync(); - if (result is null) return (0, 0); + if (result is null) { _logger?.Warn("Sync: Push - leere Server-Antwort."); return (0, 0); } _queue.Acknowledge(pending .Where(e => !result.ConflictingEventIds.Contains(e.EventId)) .Select(e => e.EventId)); _queue.SetLastServerSeq(result.ServerSequenceNr); + _logger?.Info($"Sync: Push - vom Server bestätigt bis ServerSequenceNr={result.ServerSequenceNr}, " + + $"{result.ConflictingEventIds.Count} vom Server abgelehnt (Konflikt)."); return (pending.Count - result.ConflictingEventIds.Count, result.ConflictingEventIds.Count); } @@ -89,9 +97,16 @@ public class SyncEngine : IDisposable private async Task<(int Pulled, int Conflicts)> PullAsync() { var since = _queue.GetLastServerSeq(); + _logger?.Info($"Sync: Pull - frage Server nach Ereignissen seit ServerSequenceNr={since}."); var resp = await _http.GetFromJsonAsync( $"/api/sync/pull?since={since}&deviceId={_config.DeviceId}"); - if (resp is null || resp.Events.Count == 0) return (0, 0); + if (resp is null || resp.Events.Count == 0) + { + _logger?.Info("Sync: Pull - keine neuen Ereignisse vom Server."); + return (0, 0); + } + _logger?.Info($"Sync: Pull - {resp.Events.Count} Ereignis(se) vom Server erhalten: " + + string.Join(", ", resp.Events.Select(e => $"{e.EntityType}/{e.Operation}"))); var conflicts = 0; foreach (var evt in resp.Events) { @@ -99,6 +114,8 @@ public class SyncEngine : IDisposable if (c is null) { await _applier.ApplyAsync(evt); continue; } _queue.AddConflict(c); conflicts++; + _logger?.Info($"Sync: Pull - Konflikt bei {evt.EntityType}/{evt.EntityId}, " + + $"Auflösung={c.Resolution}"); if (c.Resolution == "RemoteWon") await _applier.ApplyAsync(evt); } _queue.SetLastServerSeq(resp.ServerSequenceNr); diff --git a/LehrerApp.Sync/SyncEventPublisher.cs b/LehrerApp.Sync/SyncEventPublisher.cs index 01e38e9..298ce1c 100644 --- a/LehrerApp.Sync/SyncEventPublisher.cs +++ b/LehrerApp.Sync/SyncEventPublisher.cs @@ -1,4 +1,5 @@ using LehrerApp.Core.Models; +using LehrerApp.Core.Services; using LehrerApp.Data; using LehrerApp.Sync.Crypto; using LehrerApp.Sync.Models; @@ -10,12 +11,17 @@ namespace LehrerApp.Sync; /// AppBootstrapper an gehängt, wenn Sync konfiguriert ist — /// dort entsteht aus den ~27 Repository-Aufrufen genau ein verschlüsseltes Ereignis pro Aufruf. /// -public class SyncEventPublisher(EventQueue queue, string deviceId, byte[] syncKey) +public class SyncEventPublisher(EventQueue queue, string deviceId, byte[] syncKey, AppLogger? logger = null) { public void Publish(string entityType, string entityId, string operation, object? payload) { var encrypted = payload is null ? "" : SyncCrypto.EncryptObject(payload, syncKey); - queue.Enqueue(deviceId, DeviceType.Desktop, entityType, entityId, operation, encrypted); + var evt = queue.Enqueue(deviceId, DeviceType.Desktop, entityType, entityId, operation, encrypted); + // Erfolgs-Protokollierung (nicht nur Fehler, siehe SyncEngine/EventApplier) — sonst lässt + // sich ohne zwei parallele Testgeräte nie nachvollziehen, ob eine lokale Änderung + // überhaupt in die Outbox gelangt ist, bevor Push/Pull überhaupt ins Spiel kommen. + logger?.Info($"Sync: Ereignis eingereiht (SequenceNr={evt.SequenceNr}) - {entityType} {operation} " + + $"EntityId={entityId}"); // Anhänge reisen nicht im JSON-Ereignis mit (würde den Kanal für Fotos/Scans aufblähen), // sondern als eigener Binärtransfer über AttachmentSyncer — hier nur zur Warteliste hinzufügen. diff --git a/TODO.md b/TODO.md index 52fba76..954fa87 100644 --- a/TODO.md +++ b/TODO.md @@ -1544,6 +1544,19 @@ die Docker-Verifikation unter 10.2.4 (kein Docker im Entwicklungsstand verfügba 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. + + **Nachtrag (Erfolgs-Protokollierung nachgerüstet):** Der Fix oben half nicht — beide Geräte + meldeten einen sauberen Sync ohne Fehler, die neu angelegte Lesson kam trotzdem nicht an. + Grund: bis dahin protokollierten `SyncEventPublisher`/`SyncEngine`/`EventApplier` + ausschließlich Fehlschläge — ein sauberes Log bewies also nur "nichts ist abgestürzt", nicht + "die Änderung wurde tatsächlich hoch-/heruntergeladen". Jetzt protokollieren alle drei auch + den Erfolgspfad: `SyncEventPublisher.Publish` beim Einreihen in die Outbox (mit + `SequenceNr`), `SyncEngine.PushAsync`/`PullAsync` mit Anzahl und Entitätstypen der + gesendeten/empfangenen Ereignisse sowie der vom Server bestätigten `ServerSequenceNr`, und + `EventApplier.ApplyAsync` bei jedem tatsächlich angewendeten Ereignis. Damit lässt sich beim + nächsten Testlauf anhand der Log-Dateien beider Geräte lückenlos nachvollziehen, an welcher + Stelle der Kette (Einreihen → Push → Server → Pull → Anwenden) eine Änderung tatsächlich + verloren geht — bisher war das reine Spekulation ohne Live-Testgeräte. - [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