PlayerSync/ERROR_LOG.md
laforetbrut a83543853c Phase 6: docs (CHANGELOG, ERROR_LOG, TEST_PROCEDURE)
Adds three documentation files covering the Phase 0-5 hardening work:

CHANGELOG.md
  - Bilingual EN/FR, strict template (English first, then ---, then French).
  - Version section 2.1.5 dated 2026-04-22 (NO version bump per
    CLAUDE.md version-lock rule).
  - Sections: Fixed / Added / Changed / Correctifs / Ajouts / Modifications.

ERROR_LOG.md
  - Journal of 8 bugs discovered and fixed during the hardening sweep.
  - Each entry: Context / Error / Root cause / Fix / Prevention rule.
  - Cross-references commits bea5f80 / c84f920 / 746cb56 / c70ca9f / bd0482c.

TEST_PROCEDURE_v2.1.5.html
  - Self-contained HTML (no external deps), bilingual EN/FR.
  - 10 test scenarios tagged CRITICAL / HIGH / MEDIUM with Setup, Steps,
    Expected Results, and a regression-check block.
  - Covers: drop+deco+reco, backpack dup, SS shulker dup, kill -9 recovery,
    zombie-peer short-circuit, periodic save, pool stats, heartbeat,
    curios cap unavailable, cross-server claim.
2026-04-22 06:09:08 +02:00

10 KiB

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.