diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..45abc4e --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,61 @@ +# Changelog + +All notable changes to **PlayerSync** are documented here. + +--- + +## [2.1.5] - 2026-04-22 + +### Fixed (English first) + +- **Critical item duplication on drop + quick disconnect + reconnect** — Race condition between the auto-save background task and the logout background task could commit a stale snapshot AFTER the logout save, resurrecting dropped items. Triple guard now applied: `pendingLogoutSaves` check (early + under lock) and `SELECT online FROM player_data` skip if logout already committed. Logout BG now acquires `bgLock` with blocking `.lock()` for proper serialization. +- **Backpack / Sophisticated Storage merge-on-restore duplication** — `setBackpackContents` / `setStorageContents` upstream are shallow merges, not replaces. Restore now calls `removeBackpackContents` / `removeStorageContents` (with reflection fallback if absent) AND passes a defensive NBT copy. Fixes mass-duplication of items in backpacks/shulkers on every cross-server transfer. +- **Cross-server save overwrite** — When `writeSnapshotToDB`'s `last_server` guard blocked the core player_data UPDATE, the downstream backpack/SS/RS2 saves still executed and overwrote the claiming server's data. The function now returns a boolean; all 5 callers short-circuit downstream writes on guard block. +- **30-second join delay on zombie peer servers** — `doPlayerJoin` poll waited the full 60 attempts (30s) for server_ids that no longer existed (legacy `server_id=0` rows, or peers that crashed without clearing `online=0`). New `isPeerServerStale` check (peer_id=0 OR heartbeat >60s) takes over immediately and force-clears the orphaned flag. Poll max raised from 60 to 120 attempts (60s) for legitimate slow shutdowns. +- **Curios wipe on dead player** — Legacy `StoreCurios` wrote an empty flatMap when the Curios capability was unavailable, wiping DB data. Now early-returns with a WARN log. + +### Added + +- **JVM shutdown hook (kill -9 / OOM / SIGTERM recovery)** — New `CrashRecovery.installShutdownHook` registers a non-daemon hook that calls `VanillaSync.emergencyFlushAll` synchronously to snapshot and write every online player before process exit. Marks `server_info.enable=0` so peers detect the shutdown. +- **Startup orphan-flag recovery** — `CrashRecovery.clearOrphanedOnlineFlags` runs at `onServerStarting` to clear any `player_data.online=1` rows left by a previous ungraceful exit. Logs the count via `SyncLogger`. +- **Zombie-peer reporter** — `CrashRecovery.reportZombiePeers` logs peer `server_id`s whose heartbeat is stale or missing at boot time. +- **Server heartbeat service** — `HeartbeatService` pings `server_info.last_update` every 10 seconds so peer servers can distinguish live from dead via the new `isPeerServerStale` check. +- **Periodic full-save scheduler** — `PeriodicSaveService` triggers a complete save (player data + backpacks + SS + RS2) for every online synced player every `auto_save_interval_minutes` (new config, default 10, range 0-1440). Independent of NeoForge's vanilla `PlayerEvent.SaveToFile` cadence. +- **Dimension-change save trigger** — New `onPlayerChangeDimension` handler, gated by `save_on_dimension_change` config (default false). Protects against mid-teleport crashes. +- **Executor + HikariCP pool stats reporter** — `PoolStatsReporter` logs `[POOL] executor active/queue/idle, hikari active/idle` every 5 minutes. WARN thresholds trigger when queue >400/512 or Hikari active >=14/15. +- **Structured logging events** — `SyncLogger` gained `containerForceClosed`, `modCompatSkip`, `modCompatSaved`, `modCompatRestored`, `storageSave`, `poolStats`, `warnPlayer`, `nbtAnomaly` for finer-grained diagnostics. + +### Changed + +- **`writeSnapshotToDB` signature** — Now returns `boolean` instead of `void`. `true` means the core UPDATE persisted, `false` means the `last_server` guard blocked. All callers MUST check the return before firing downstream backpack/SS/RS2 writes. +- **Default `auto_save_interval_minutes`** — 10 min (new config key). Trades data-loss window on crash for DB load. Set to 0 to disable. +- **Backpack / SS restore** — Now uses two-step clear (public API + reflection fallback) and defensive NBT copy before upstream setter. Full log line per restore with `cleared_via=api|reflection` and `nbt_keys=N`. + +--- + +### Correctifs (French mirror) + +- **Duplication d'items critique lors d'un drop + déconnexion rapide + reconnexion** — Race condition entre la task auto-save background et la task logout background pouvait commiter un snapshot périmé APRÈS le save logout, ressuscitant les items drop. Triple garde maintenant appliquée : check `pendingLogoutSaves` (early + sous lock) et skip via `SELECT online FROM player_data` si le logout a déjà commité. La task logout BG acquiert maintenant `bgLock` en blocking `.lock()` pour sérialiser proprement. +- **Duplication Backpack / Sophisticated Storage par merge au restore** — `setBackpackContents` / `setStorageContents` en amont sont des merges shallow, pas des replaces. Le restore appelle maintenant `removeBackpackContents` / `removeStorageContents` (avec fallback reflection si absent) ET passe une copie défensive du NBT. Corrige la duplication massive d'items dans les backpacks/shulkers à chaque transfert cross-server. +- **Écrasement cross-server des saves** — Quand le guard `last_server` de `writeSnapshotToDB` bloquait l'UPDATE core player_data, les saves downstream backpack/SS/RS2 s'exécutaient quand même et écrasaient les données du serveur ayant claim. La fonction retourne maintenant un boolean ; les 5 callers court-circuitent les writes downstream en cas de guard block. +- **Délai de 30 secondes à la connexion sur serveurs zombies** — Le poll `doPlayerJoin` attendait les 60 tentatives (30s) pour des `server_id` n'existant plus (lignes legacy `server_id=0`, ou peers ayant crashé sans clear `online=0`). Nouveau check `isPeerServerStale` (peer_id=0 OU heartbeat >60s) prend la main immédiatement et force-clear le flag orphelin. Poll max passé de 60 à 120 tentatives (60s) pour couvrir les shutdowns lents légitimes. +- **Wipe Curios sur joueur mort** — La méthode legacy `StoreCurios` écrivait un flatMap vide quand la capability Curios était absente, wipant les données DB. Elle early-return maintenant avec un log WARN. + +### Ajouts (French mirror) + +- **Hook JVM shutdown (kill -9 / OOM / SIGTERM recovery)** — Nouveau `CrashRecovery.installShutdownHook` enregistre un hook non-daemon qui appelle `VanillaSync.emergencyFlushAll` synchronement pour snapshot et écrire chaque joueur online avant la fin du process. Marque `server_info.enable=0` pour que les peers détectent le shutdown. +- **Recovery des flags orphelins au boot** — `CrashRecovery.clearOrphanedOnlineFlags` tourne au `onServerStarting` pour clear les rows `player_data.online=1` laissées par une sortie ungracieuse précédente. Log le compte via `SyncLogger`. +- **Reporter de peers zombies** — `CrashRecovery.reportZombiePeers` log les `server_id` peers dont le heartbeat est stale ou absent au boot. +- **Service heartbeat** — `HeartbeatService` ping `server_info.last_update` toutes les 10 secondes pour que les peers distinguent live vs dead via le nouveau check `isPeerServerStale`. +- **Scheduler de sauvegarde périodique** — `PeriodicSaveService` déclenche une save complète (player data + backpacks + SS + RS2) pour chaque joueur online synced toutes les `auto_save_interval_minutes` (nouvelle config, défaut 10, plage 0-1440). Indépendant de la cadence vanilla `PlayerEvent.SaveToFile` de NeoForge. +- **Trigger save sur changement de dimension** — Nouveau handler `onPlayerChangeDimension`, gated par la config `save_on_dimension_change` (défaut false). Protège contre les crashes en plein téléport. +- **Reporter stats executor + HikariCP** — `PoolStatsReporter` log `[POOL] executor active/queue/idle, hikari active/idle` toutes les 5 min. Seuils WARN quand queue >400/512 ou Hikari active >=14/15. +- **Événements structurés** — `SyncLogger` a gagné `containerForceClosed`, `modCompatSkip`, `modCompatSaved`, `modCompatRestored`, `storageSave`, `poolStats`, `warnPlayer`, `nbtAnomaly` pour un diagnostic plus fin. + +### Modifications + +- **Signature `writeSnapshotToDB`** — Retourne maintenant `boolean` au lieu de `void`. `true` = l'UPDATE core a persisté, `false` = le guard `last_server` a bloqué. Tous les callers DOIVENT vérifier le retour avant de déclencher les writes downstream backpack/SS/RS2. +- **Défaut `auto_save_interval_minutes`** — 10 min (nouvelle clé config). Trade-off entre fenêtre de perte de données sur crash et charge DB. 0 pour désactiver. +- **Restore Backpack / SS** — Utilise maintenant un clear en deux étapes (API publique + fallback reflection) et une copie défensive NBT avant le setter upstream. Log complet par restore avec `cleared_via=api|reflection` et `nbt_keys=N`. + +--- diff --git a/ERROR_LOG.md b/ERROR_LOG.md new file mode 100644 index 0000000..275710a --- /dev/null +++ b/ERROR_LOG.md @@ -0,0 +1,141 @@ +# PlayerSync — Error Log + +Journal des erreurs rencontrées et corrigées. Chaque entrée documente un bug, sa cause racine, son correctif et la règle de prévention à appliquer systématiquement. + +--- + +## [2026-04-22 02:54] — Item duplication on drop + quick disconnect + reconnect + +**Context** : Un joueur drop un item au sol, se déconnecte très rapidement, puis se reconnecte → l'item est présent deux fois (en inventory restauré + encore au sol). + +**Error** : Duplication systématique reproductible en production. + +**Root cause** : Race condition entre `onPlayerSaveToFile` background task (auto-save périodique) et `onPlayerLogout` background task. +1. `SaveToFile` capture un snapshot sur main thread AVANT le drop (item encore en inventory) → task async soumise. +2. Le joueur drop l'item → inventory vide, ItemEntity dans le monde. +3. Le joueur disconnect → logout capture un snapshot FRESH (sans item), soumet le write. +4. Les deux BG tasks s'exécutent en parallèle. Si la task auto-save (qui portait une snapshot STALE avec l'item) commit APRÈS la task logout (qui portait FRESH sans l'item), la DB finit en STALE. +5. Reconnexion → inventory restauré avec l'item + ItemEntity toujours au sol → 2 copies. + +**Fix** (commit `bea5f80`) : Triple guard dans l'auto-save BG task : +- Early skip si `pendingLogoutSaves.containsKey(uuid)` avant tryLock. +- Re-check sous lock après tryLock (race window fermée). +- `SELECT online FROM player_data WHERE uuid=?` — skip si online=0 (logout a committé). + +Logout BG task acquiert maintenant `bgLock.lock()` (blocking) pour sérialiser proprement avec les auto-save BG qui utilisent `tryLock`. `removePlayerLock` réordonné avant `bgLock.unlock()` pour que les auto-save BG qui wake après unlock voient `containsKey=false` et skip. + +**Prevention** : **JAMAIS de BG task qui modifie la DB sans un guard `online=0` + `pendingLogoutSaves` check**. Si deux paths peuvent écrire le même row, ils DOIVENT partager un lock blocking OU le path "fresh" doit être détectable via DB state (online flag, version column). + +--- + +## [2026-04-22 03:15] — Backpack duplication on cross-server transfer + +**Context** : Un joueur utilise un backpack Sophisticated Backpacks sur Server A, change de serveur, et constate que le contenu du backpack est dupliqué. + +**Error** : Duplication systématique d'items dans les backpacks et shulkers Sophisticated Storage lors de transferts cross-server ou reconnexions. + +**Root cause** : `BackpackStorage.setBackpackContents()` et `ItemContentsStorage.setStorageContents()` en amont sont des **merges shallow**, pas des replaces. Quand le restore applique le snapshot sauvegardé, il MERGE avec les contents existants en mémoire (SavedData persistée sur disk localement ou vue ouverte par un autre joueur). Les sous-tags "items" survivent → duplication. + +**Fix** (commit `c84f920`) : +- Backpack : appel `store.removeBackpackContents(uuid)` EXPLICITE avant `setBackpackContents`. Si l'API throw (absent dans certaines versions), fallback reflection qui parcourt les champs `Map` de `BackpackStorage` et remove l'entrée directement. +- SS : nouveau helper `clearSSStorageContents` qui tente `removeStorageContents(UUID)` via reflection, puis fallback reflection sur champs Map. `setDirty()` appelé pour forcer le flush. +- Les deux paths passent maintenant une **copie défensive** (`nbt.copy()`) à l'upstream setter, jamais la référence partagée. + +**Prevention** : +- **Toujours clear avant restore pour toute structure qui merge au lieu de replace** (backpack, SS, RS2 disks). +- **Toujours passer une copie défensive** d'un CompoundTag à un setter qui peut la stocker en interne. +- **Logger `clear_via=api/reflection`** pour diagnostiquer les régressions upstream. + +--- + +## [2026-04-22 03:20] — Cross-server saves can overwrite claimed data + +**Context** : Deux serveurs sauvent un même joueur simultanément (edge case lors de changements de serveurs rapides). + +**Error** : Les données de l'un écrasent silencieusement les données de l'autre. Backpack/SS/RS2 perdus. + +**Root cause** : `writeSnapshotToDB` retournait `void`. Même si son guard `last_server=?` bloquait le write du core player_data (rows affected = 0), les appels downstream `saveBackpackSnapshots` / `saveSSSnapshots` / `saveRS2DisksByLevel` s'exécutaient INCONDITIONNELLEMENT et écrasaient `backpack_data` (qui n'a pas de guard propre — keyé par storage UUID, pas player UUID). + +**Fix** (commit `c84f920`) : `writeSnapshotToDB` retourne maintenant `boolean`. Les 5 callers (logout, shutdown, auto-save SaveToFile, staggered auto-save, death-save) vérifient le retour et **short-circuitent** les writes downstream si le core a été blocké. + +**Prevention** : **Une fonction qui a un guard silencieux DOIT signaler son résultat au caller**. Ne jamais supposer que les writes downstream sont implicitement protégés par un guard en amont — vérifier explicitement. + +--- + +## [2026-04-22 03:25] — 30s delay on player join (RACE timeout 60/60) + +**Context** : À chaque connexion, log flood `Waiting for server X to finish saving (attempt 60/60)` et le joueur attend 30s avant de récupérer ses données. + +**Error** : Poll timeout systématique sur des server_ids qui n'existent plus ou sur un server_id=0. + +**Root cause** : +- Le poll `doPlayerJoin` attend que l'autre serveur clear `online=0`. Si l'autre serveur a crashé sans le faire (pas de shutdown hook), le poll attend jusqu'à épuisement des 60 tentatives. +- `server_id=0` est une ligne orpheline héritée d'une écriture legacy (avant que le default `Random().nextInt(1, MAX-1)` soit appliqué). + +**Fix** (commit `c84f920`) : +- Nouvelle méthode `isPeerServerStale(peerId, staleMs)` qui check `server_info.last_update`. Si l'heartbeat est vieux de >60s OU si `peerId == 0`, le poll considère le serveur comme zombie et force-clear `online=0`. +- Poll max passé de 60 à 120 tentatives (60s total) pour couvrir les shutdowns lents. +- Phase 3 : `HeartbeatService` tick toutes les 10s → permet aux peers de détecter les zombies. +- Phase 3 : `CrashRecovery.clearOrphanedOnlineFlags()` au boot → nettoie les rows stuck à online=1 après un crash ungracieux. + +**Prevention** : **Tout état "en cours" en DB doit avoir un heartbeat OU un timeout**. Un flag `online=1` sans heartbeat est un bug en attendant de se produire (le process qui l'a set peut crasher). + +--- + +## [2026-04-22 03:30] — StoreCurios NPE / data wipe on dead player + +**Context** : Un joueur meurt puis se déconnecte rapidement. Son curios sont vidés de la DB. + +**Error** : Méthode legacy `StoreCurios` écrivait un flatMap vide quand `CuriosApi.getCuriosInventory(player)` retournait un `Optional.empty()` (capability détachée après death). + +**Root cause** : La méthode utilisait `handlerOpt.ifPresent(...)` mais fallait au `REPLACE INTO` même si le flatMap était vide → wipe DB data pour un joueur mort. + +**Fix** (commit `c84f920`) : Early return avec log `WARN [store-curios] handler unavailable for UUID — skipping write to avoid wiping DB data` si `handlerOpt.isEmpty()`. + +**Prevention** : **Ne JAMAIS écrire un état "vide" dans la DB si la source est incertaine**. Une capability absente ≠ joueur sans curios — c'est un état indéterminé. Skip write + log. + +--- + +## [2026-04-22 03:40] — Player data loss on kill -9 / OOM + +**Context** : Process serveur tué via `kill -9` ou OOM — au redémarrage, les joueurs qui étaient online ne récupèrent pas leurs données des dernières minutes. + +**Error** : `ServerStoppingEvent` n'est pas déclenché lors d'un kill ungracieux, donc aucune save n'est exécutée. Les rows `player_data` restent aussi à `online=1` → le poll de doPlayerJoin sur un autre serveur attend 30s pour rien. + +**Fix** (commit `746cb56`, Phase 3) : +- `CrashRecovery.installShutdownHook(() -> emergencyFlushAll())` — JVM hook non-daemon enregistré au boot. Appelle une méthode synchrone qui snapshot et write tous les joueurs online sans passer par l'executor (qui peut être déjà mort). +- Marque `server_info.enable=0` à la sortie pour notifier les peers. +- `CrashRecovery.clearOrphanedOnlineFlags()` au boot suivant — clear les rows stuck et log le nombre via SyncLogger. +- `HeartbeatService` tick toutes les 10s pendant le run — permet aux peers de détecter la mort. + +**Prevention** : +- **Tout process long-running doit avoir un JVM shutdown hook** pour couvrir SIGTERM / kill doux / OOM soft. +- **Tout flag "en cours" persistant doit avoir un recovery path au boot suivant**. +- **Un heartbeat périodique est obligatoire** si d'autres processus dépendent de savoir si on est alive. + +--- + +## [2026-04-22 03:50] — Inventory loss window of 30 min between auto-saves + +**Context** : Les auto-saves ne se déclenchaient que lors des PlayerEvent.SaveToFile natifs (cadence vanilla = autosave world, typiquement 6000 ticks). Si un crash survenait entre deux saves, jusqu'à 15+ minutes de jeu étaient perdus. + +**Fix** (commit `c70ca9f`, Phase 4) : +- `PeriodicSaveService` — scheduler indépendant qui déclenche un full-flush toutes les `auto_save_interval_minutes` (défaut 10). Hops au main thread pour snapshotter, puis soumet les writes async via `snapshotAndQueueSave`. +- `onPlayerChangeDimension` — trigger additionnel gated par `save_on_dimension_change` (défaut false). Sauve avant teleport cross-dimension. + +**Prevention** : **Ne jamais dépendre uniquement des events du framework** pour déclencher une sauvegarde critique. Doubler avec un scheduler indépendant et rendre l'intervalle configurable. + +--- + +## [2026-04-22 04:00] — Executor queue saturation invisible + +**Context** : Sous charge (35+ joueurs), l'executor `PlayerSync` peut saturer (queue >400) et déclencher `CallerRunsPolicy` qui bloque le main thread. Aucune alerte dans les logs. + +**Fix** (commit `bd0482c`, Phase 5) : +- `PoolStatsReporter` — scheduler dédié 5-min qui log `[POOL] executor active/queue/idle, hikari active/idle`. +- WARN log si queue > 400/512 ou hikari active >= 14/15. +- Accesseur `JDBCsetUp.getPoolMXBean()` pour exposer Hikari en read-only. + +**Prevention** : **Tout pool/queue critique doit être monitoré périodiquement** avec des seuils d'alerte sous la capacité max. Invisible ≠ sain. + +--- diff --git a/TEST_PROCEDURE_v2.1.5.html b/TEST_PROCEDURE_v2.1.5.html new file mode 100644 index 0000000..21b26a8 --- /dev/null +++ b/TEST_PROCEDURE_v2.1.5.html @@ -0,0 +1,523 @@ + + +
+ +docker compose up -d./gradlew build — le JAR apparaît dans build/libs/playersync-1.21.1-2.1.5.jar./gradlew runServer (Server A) + copie avec Server_id différent dans run-2/config/playersync-common.toml (Server B)http://localhost:8080 (login playersync/playersync)tail -f run/logs/playersync/sync.log[SAVE] LOGOUT completed then either no SaveToFile BG write or a [GUARD] SaveToFile BG skipped — player already offline in DB[restore-backpack] uuid=... nbt_keys=... cleared_via=api (or reflection as fallback)[CONTAINER_CLOSE] for Player B (viewer forced closed)[restore-ss] uuid=... nbt_keys=...jps | grep Forgekill -9 <pid> (or Task Manager → End Task on Windows)[crash-recovery] cleared N orphan online=1 rows[crash-recovery] JVM shutdown hook installed AND ideally (if hook ran): [emergency-flush] flushed N playersplayer_data.last_server=99999 and online=1 for a test UUID[RACE] Peer server 99999 is dead/zombie — taking overlast_server=<thisServer>, online=1auto_save_interval_minutes=1 in config for quick test[periodic-save] queued snapshots for N player(s) after 1 min[POOL][POOL] executor active=0 queue=0 pool_idle=4 | hikari active=0 idle=4server_info.last_update for this server's idlast_update advances by ~10000 ms at every refresh[heartbeat] started on boot[store-curios] handler unavailable for ... skipping write[GUARD] (last_server guard blocked) if B claimed during A's save[SAVE_SKIP] LOGOUT skipped: core guard blockedleakDetectionThreshold=25000, warnings mean a connection held >25s[pool-stats] executor queue high[SAVE] LOGOUT completed within ~500msdocker compose up -d./gradlew build — le JAR sort dans build/libs/playersync-1.21.1-2.1.5.jar./gradlew runServer (Serveur A) + copie avec Server_id différent dans run-2/config/playersync-common.toml (Serveur B)http://localhost:8080 (login playersync/playersync)tail -f run/logs/playersync/sync.log[SAVE] LOGOUT completed puis soit aucun write SaveToFile BG, soit [GUARD] SaveToFile BG skipped — player already offline in DB[restore-backpack] uuid=... nbt_keys=... cleared_via=api (ou reflection en fallback)[CONTAINER_CLOSE] pour le Joueur B (viewer force-fermé)[restore-ss] uuid=... nbt_keys=...jps | grep Forgekill -9 <pid> (ou Task Manager → End Task sur Windows)[crash-recovery] cleared N orphan online=1 rows[crash-recovery] JVM shutdown hook installed ET idéalement (si le hook a tourné) : [emergency-flush] flushed N playersplayer_data.last_server=99999 et online=1 pour un UUID test[RACE] Peer server 99999 is dead/zombie — taking overlast_server=<thisServer>, online=1auto_save_interval_minutes=1 en config pour un test rapide[periodic-save] queued snapshots for N player(s) après 1 min[POOL][POOL] executor active=0 queue=0 pool_idle=4 | hikari active=0 idle=4server_info.last_update pour l'id de ce serveurlast_update avance de ~10000 ms à chaque refresh[heartbeat] started au boot[store-curios] handler unavailable for ... skipping write[GUARD] (last_server guard a bloqué) si B a claim pendant la save de A[SAVE_SKIP] LOGOUT skipped: core guard blockedleakDetectionThreshold=25000, warnings = connexion tenue >25s[pool-stats] executor queue high[SAVE] LOGOUT completed en ~500ms+Author: vyrriox | PlayerSync v2.1.5 | 2026-04-22 +
+ + +