From afc554f1ec290b14f5b4dc469df15e7dcc45fcfb Mon Sep 17 00:00:00 2001 From: Houmgaor Date: Sat, 1 Nov 2025 00:37:59 +0100 Subject: [PATCH] fix(save): avoid double-save. feat(logging): more complete logging data. --- CHANGELOG.md | 8 + server/channelserver/handlers.go | 212 +++++++++++++++++------ server/channelserver/handlers_house.go | 56 +++++- server/channelserver/handlers_kouryou.go | 57 +++++- server/channelserver/sys_session.go | 26 ++- 5 files changed, 297 insertions(+), 62 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 16b3930c1..ee90fb760 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,10 +11,16 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Alpelo object system backport functionality - Better config file handling and structure +- Comprehensive production logging for save operations (warehouse, Koryo points, savedata) +- Disconnect type tracking (graceful, connection_lost, error) with detailed logging +- Session lifecycle logging with duration and metrics tracking ### Changed - Improved config handling +- Refactored logout flow to save all data before cleanup (prevents data loss race conditions) +- Unified save operation into single `saveAllCharacterData()` function with proper error handling +- Removed duplicate save calls in `logoutPlayer()` function ### Fixed @@ -26,6 +32,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Fixed missing stage transfer packet for empty zones - Fixed save data corruption check rejecting valid saves due to name encoding mismatches (SJIS/UTF-8) - Fixed incomplete saves during logout - character savedata now persisted even during ungraceful disconnects +- Fixed double-save bug in logout flow that caused unnecessary database operations +- Fixed save operation ordering - now saves data before session cleanup instead of after ### Security diff --git a/server/channelserver/handlers.go b/server/channelserver/handlers.go index a0e2c1850..97b0ff531 100644 --- a/server/channelserver/handlers.go +++ b/server/channelserver/handlers.go @@ -177,35 +177,158 @@ func handleMsgSysLogout(s *Session, p mhfpacket.MHFPacket) { logoutPlayer(s) } +// saveAllCharacterData saves all character data to the database with proper error handling. +// This function ensures data persistence even if the client disconnects unexpectedly. +// It handles: +// - Main savedata blob (compressed) +// - User binary data (house, gallery, etc.) +// - Playtime updates +// - RP updates +// - Name corruption prevention +func saveAllCharacterData(s *Session, rpToAdd int) error { + saveStart := time.Now() + + // Get current savedata from database + characterSaveData, err := GetCharacterSaveData(s, s.charID) + if err != nil { + s.logger.Error("Failed to retrieve character save data", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + ) + return err + } + + if characterSaveData == nil { + s.logger.Warn("Character save data is nil, skipping save", + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + ) + return nil + } + + // Force name to match to prevent corruption detection issues + // This handles SJIS/UTF-8 encoding differences across game versions + if characterSaveData.Name != s.Name { + s.logger.Debug("Correcting name mismatch before save", + zap.String("savedata_name", characterSaveData.Name), + zap.String("session_name", s.Name), + zap.Uint32("charID", s.charID), + ) + characterSaveData.Name = s.Name + characterSaveData.updateSaveDataWithStruct() + } + + // Update playtime from session + if !s.playtimeTime.IsZero() { + sessionPlaytime := uint32(time.Since(s.playtimeTime).Seconds()) + s.playtime += sessionPlaytime + s.logger.Debug("Updated playtime", + zap.Uint32("session_playtime_seconds", sessionPlaytime), + zap.Uint32("total_playtime", s.playtime), + zap.Uint32("charID", s.charID), + ) + } + characterSaveData.Playtime = s.playtime + + // Update RP if any gained during session + if rpToAdd > 0 { + characterSaveData.RP += uint16(rpToAdd) + if characterSaveData.RP >= s.server.erupeConfig.GameplayOptions.MaximumRP { + characterSaveData.RP = s.server.erupeConfig.GameplayOptions.MaximumRP + s.logger.Debug("RP capped at maximum", + zap.Uint16("max_rp", s.server.erupeConfig.GameplayOptions.MaximumRP), + zap.Uint32("charID", s.charID), + ) + } + s.logger.Debug("Added RP", + zap.Int("rp_gained", rpToAdd), + zap.Uint16("new_rp", characterSaveData.RP), + zap.Uint32("charID", s.charID), + ) + } + + // Save to database (main savedata + user_binary) + characterSaveData.Save(s) + + saveDuration := time.Since(saveStart) + s.logger.Info("Saved character data successfully", + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + zap.Duration("duration", saveDuration), + zap.Int("rp_added", rpToAdd), + zap.Uint32("playtime", s.playtime), + ) + + return nil +} + func logoutPlayer(s *Session) { + logoutStart := time.Now() + + // Log logout initiation with session details + sessionDuration := time.Duration(0) + if s.sessionStart > 0 { + sessionDuration = time.Since(time.Unix(s.sessionStart, 0)) + } + + s.logger.Info("Player logout initiated", + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + zap.Duration("session_duration", sessionDuration), + ) + + // Calculate session metrics FIRST (before cleanup) + var timePlayed int + var sessionTime int + var rpGained int + + if s.charID != 0 { + _ = s.server.db.QueryRow("SELECT time_played FROM characters WHERE id = $1", s.charID).Scan(&timePlayed) + sessionTime = int(TimeAdjusted().Unix()) - int(s.sessionStart) + timePlayed += sessionTime + + if mhfcourse.CourseExists(30, s.courses) { + rpGained = timePlayed / 900 + timePlayed = timePlayed % 900 + s.server.db.Exec("UPDATE characters SET cafe_time=cafe_time+$1 WHERE id=$2", sessionTime, s.charID) + } else { + rpGained = timePlayed / 1800 + timePlayed = timePlayed % 1800 + } + + s.logger.Debug("Session metrics calculated", + zap.Uint32("charID", s.charID), + zap.Int("session_time_seconds", sessionTime), + zap.Int("rp_gained", rpGained), + zap.Int("time_played_remainder", timePlayed), + ) + + // Save all character data ONCE with all updates + // This is the safety net that ensures data persistence even if client + // didn't send save packets before disconnecting + if err := saveAllCharacterData(s, rpGained); err != nil { + s.logger.Error("Failed to save character data during logout", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + ) + // Continue with logout even if save fails + } + + // Update time_played and guild treasure hunt + s.server.db.Exec("UPDATE characters SET time_played = $1 WHERE id = $2", timePlayed, s.charID) + s.server.db.Exec(`UPDATE guild_characters SET treasure_hunt=NULL WHERE character_id=$1`, s.charID) + } + + // NOW do cleanup (after save is complete) s.server.Lock() delete(s.server.sessions, s.rawConn) s.rawConn.Close() delete(s.server.objectIDs, s) s.server.Unlock() - // Save all character data before logout to prevent data loss - // This ensures data is persisted even if client disconnects unexpectedly - if s.charID != 0 { - characterSaveData, err := GetCharacterSaveData(s, s.charID) - if err == nil && characterSaveData != nil { - // Force name to match to prevent corruption detection issues - characterSaveData.Name = s.Name - characterSaveData.updateSaveDataWithStruct() - - // Update playtime in savedata before saving - if !s.playtimeTime.IsZero() { - s.playtime += uint32(time.Since(s.playtimeTime).Seconds()) - } - characterSaveData.Playtime = s.playtime - - characterSaveData.Save(s) - s.logger.Info("Saved character data during logout", zap.Uint32("charID", s.charID)) - } else if err != nil { - s.logger.Warn("Failed to retrieve character save data during logout", zap.Error(err), zap.Uint32("charID", s.charID)) - } - } - + // Stage cleanup for _, stage := range s.server.stages { // Tell sessions registered to disconnecting players quest to unregister if stage.host != nil && stage.host.charID == s.charID { @@ -224,6 +347,7 @@ func logoutPlayer(s *Session) { } } + // Update sign sessions and server player count _, err := s.server.db.Exec("UPDATE sign_sessions SET server_id=NULL, char_id=NULL WHERE token=$1", s.token) if err != nil { panic(err) @@ -234,30 +358,17 @@ func logoutPlayer(s *Session) { panic(err) } - var timePlayed int - var sessionTime int - _ = s.server.db.QueryRow("SELECT time_played FROM characters WHERE id = $1", s.charID).Scan(&timePlayed) - sessionTime = int(TimeAdjusted().Unix()) - int(s.sessionStart) - timePlayed += sessionTime - - var rpGained int - if mhfcourse.CourseExists(30, s.courses) { - rpGained = timePlayed / 900 - timePlayed = timePlayed % 900 - s.server.db.Exec("UPDATE characters SET cafe_time=cafe_time+$1 WHERE id=$2", sessionTime, s.charID) - } else { - rpGained = timePlayed / 1800 - timePlayed = timePlayed % 1800 - } - - s.server.db.Exec("UPDATE characters SET time_played = $1 WHERE id = $2", timePlayed, s.charID) - - s.server.db.Exec(`UPDATE guild_characters SET treasure_hunt=NULL WHERE character_id=$1`, s.charID) - if s.stage == nil { + logoutDuration := time.Since(logoutStart) + s.logger.Info("Player logout completed", + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + zap.Duration("logout_duration", logoutDuration), + ) return } + // Broadcast user deletion and final cleanup s.server.BroadcastMHF(&mhfpacket.MsgSysDeleteUser{ CharID: s.charID, }, s) @@ -271,16 +382,13 @@ func logoutPlayer(s *Session) { removeSessionFromSemaphore(s) removeSessionFromStage(s) - saveData, err := GetCharacterSaveData(s, s.charID) - if err != nil || saveData == nil { - s.logger.Error("Failed to get savedata") - return - } - saveData.RP += uint16(rpGained) - if saveData.RP >= s.server.erupeConfig.GameplayOptions.MaximumRP { - saveData.RP = s.server.erupeConfig.GameplayOptions.MaximumRP - } - saveData.Save(s) + logoutDuration := time.Since(logoutStart) + s.logger.Info("Player logout completed", + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + zap.Duration("logout_duration", logoutDuration), + zap.Int("rp_gained", rpGained), + ) } func handleMsgSysSetStatus(s *Session, p mhfpacket.MHFPacket) {} diff --git a/server/channelserver/handlers_house.go b/server/channelserver/handlers_house.go index d1e9660ba..7261194e0 100644 --- a/server/channelserver/handlers_house.go +++ b/server/channelserver/handlers_house.go @@ -493,17 +493,39 @@ func handleMsgMhfEnumerateWarehouse(s *Session, p mhfpacket.MHFPacket) { func handleMsgMhfUpdateWarehouse(s *Session, p mhfpacket.MHFPacket) { pkt := p.(*mhfpacket.MsgMhfUpdateWarehouse) + saveStart := time.Now() + var err error + var boxTypeName string + var dataSize int + switch pkt.BoxType { case 0: + boxTypeName = "items" newStacks := mhfitem.DiffItemStacks(warehouseGetItems(s, pkt.BoxIndex), pkt.UpdatedItems) - _, err = s.server.db.Exec(fmt.Sprintf(`UPDATE warehouse SET item%d=$1 WHERE character_id=$2`, pkt.BoxIndex), mhfitem.SerializeWarehouseItems(newStacks), s.charID) + serialized := mhfitem.SerializeWarehouseItems(newStacks) + dataSize = len(serialized) + + s.logger.Debug("Warehouse save request", + zap.Uint32("charID", s.charID), + zap.String("box_type", boxTypeName), + zap.Uint8("box_index", pkt.BoxIndex), + zap.Int("item_count", len(pkt.UpdatedItems)), + zap.Int("data_size", dataSize), + ) + + _, err = s.server.db.Exec(fmt.Sprintf(`UPDATE warehouse SET item%d=$1 WHERE character_id=$2`, pkt.BoxIndex), serialized, s.charID) if err != nil { - s.logger.Error("Failed to update warehouse items", zap.Error(err)) + s.logger.Error("Failed to update warehouse items", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.Uint8("box_index", pkt.BoxIndex), + ) doAckSimpleFail(s, pkt.AckHandle, make([]byte, 4)) return } case 1: + boxTypeName = "equipment" var fEquip []mhfitem.MHFEquipment oEquips := warehouseGetEquipment(s, pkt.BoxIndex) for _, uEquip := range pkt.UpdatedEquipment { @@ -526,12 +548,38 @@ func handleMsgMhfUpdateWarehouse(s *Session, p mhfpacket.MHFPacket) { fEquip = append(fEquip, oEquip) } } - _, err = s.server.db.Exec(fmt.Sprintf(`UPDATE warehouse SET equip%d=$1 WHERE character_id=$2`, pkt.BoxIndex), mhfitem.SerializeWarehouseEquipment(fEquip), s.charID) + + serialized := mhfitem.SerializeWarehouseEquipment(fEquip) + dataSize = len(serialized) + + s.logger.Debug("Warehouse save request", + zap.Uint32("charID", s.charID), + zap.String("box_type", boxTypeName), + zap.Uint8("box_index", pkt.BoxIndex), + zap.Int("equip_count", len(pkt.UpdatedEquipment)), + zap.Int("data_size", dataSize), + ) + + _, err = s.server.db.Exec(fmt.Sprintf(`UPDATE warehouse SET equip%d=$1 WHERE character_id=$2`, pkt.BoxIndex), serialized, s.charID) if err != nil { - s.logger.Error("Failed to update warehouse equipment", zap.Error(err)) + s.logger.Error("Failed to update warehouse equipment", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.Uint8("box_index", pkt.BoxIndex), + ) doAckSimpleFail(s, pkt.AckHandle, make([]byte, 4)) return } } + + saveDuration := time.Since(saveStart) + s.logger.Info("Warehouse saved successfully", + zap.Uint32("charID", s.charID), + zap.String("box_type", boxTypeName), + zap.Uint8("box_index", pkt.BoxIndex), + zap.Int("data_size", dataSize), + zap.Duration("duration", saveDuration), + ) + doAckSimpleSucceed(s, pkt.AckHandle, make([]byte, 4)) } diff --git a/server/channelserver/handlers_kouryou.go b/server/channelserver/handlers_kouryou.go index bff9292a6..9bde1fe0f 100644 --- a/server/channelserver/handlers_kouryou.go +++ b/server/channelserver/handlers_kouryou.go @@ -4,16 +4,37 @@ import ( "erupe-ce/common/byteframe" "erupe-ce/network/mhfpacket" "go.uber.org/zap" + "time" ) func handleMsgMhfAddKouryouPoint(s *Session, p mhfpacket.MHFPacket) { // hunting with both ranks maxed gets you these pkt := p.(*mhfpacket.MsgMhfAddKouryouPoint) + saveStart := time.Now() + + s.logger.Debug("Adding Koryo points", + zap.Uint32("charID", s.charID), + zap.Uint32("points_to_add", pkt.KouryouPoints), + ) + var points int err := s.server.db.QueryRow("UPDATE characters SET kouryou_point=COALESCE(kouryou_point + $1, $1) WHERE id=$2 RETURNING kouryou_point", pkt.KouryouPoints, s.charID).Scan(&points) if err != nil { - s.logger.Error("Failed to update KouryouPoint in db", zap.Error(err)) + s.logger.Error("Failed to update KouryouPoint in db", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.Uint32("points_to_add", pkt.KouryouPoints), + ) + } else { + saveDuration := time.Since(saveStart) + s.logger.Info("Koryo points added successfully", + zap.Uint32("charID", s.charID), + zap.Uint32("points_added", pkt.KouryouPoints), + zap.Int("new_total", points), + zap.Duration("duration", saveDuration), + ) } + resp := byteframe.NewByteFrame() resp.WriteUint32(uint32(points)) doAckBufSucceed(s, pkt.AckHandle, resp.Data()) @@ -24,7 +45,15 @@ func handleMsgMhfGetKouryouPoint(s *Session, p mhfpacket.MHFPacket) { var points int err := s.server.db.QueryRow("SELECT COALESCE(kouryou_point, 0) FROM characters WHERE id = $1", s.charID).Scan(&points) if err != nil { - s.logger.Error("Failed to get kouryou_point savedata from db", zap.Error(err)) + s.logger.Error("Failed to get kouryou_point from db", + zap.Error(err), + zap.Uint32("charID", s.charID), + ) + } else { + s.logger.Debug("Retrieved Koryo points", + zap.Uint32("charID", s.charID), + zap.Int("points", points), + ) } resp := byteframe.NewByteFrame() resp.WriteUint32(uint32(points)) @@ -33,12 +62,32 @@ func handleMsgMhfGetKouryouPoint(s *Session, p mhfpacket.MHFPacket) { func handleMsgMhfExchangeKouryouPoint(s *Session, p mhfpacket.MHFPacket) { // spent at the guildmaster, 10000 a roll - var points int pkt := p.(*mhfpacket.MsgMhfExchangeKouryouPoint) + saveStart := time.Now() + + s.logger.Debug("Exchanging Koryo points", + zap.Uint32("charID", s.charID), + zap.Uint32("points_to_spend", pkt.KouryouPoints), + ) + + var points int err := s.server.db.QueryRow("UPDATE characters SET kouryou_point=kouryou_point - $1 WHERE id=$2 RETURNING kouryou_point", pkt.KouryouPoints, s.charID).Scan(&points) if err != nil { - s.logger.Error("Failed to update platemyset savedata in db", zap.Error(err)) + s.logger.Error("Failed to exchange Koryo points", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.Uint32("points_to_spend", pkt.KouryouPoints), + ) + } else { + saveDuration := time.Since(saveStart) + s.logger.Info("Koryo points exchanged successfully", + zap.Uint32("charID", s.charID), + zap.Uint32("points_spent", pkt.KouryouPoints), + zap.Int("remaining_points", points), + zap.Duration("duration", saveDuration), + ) } + resp := byteframe.NewByteFrame() resp.WriteUint32(uint32(points)) doAckBufSucceed(s, pkt.AckHandle, resp.Data()) diff --git a/server/channelserver/sys_session.go b/server/channelserver/sys_session.go index fc1f5e05b..747f94674 100644 --- a/server/channelserver/sys_session.go +++ b/server/channelserver/sys_session.go @@ -177,16 +177,38 @@ func (s *Session) sendLoop() { func (s *Session) recvLoop() { for { if s.closed.Load() { + // Graceful disconnect - client sent logout packet + s.logger.Info("Session closed gracefully", + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + zap.String("disconnect_type", "graceful"), + ) logoutPlayer(s) return } pkt, err := s.cryptConn.ReadPacket() if err == io.EOF { - s.logger.Info(fmt.Sprintf("[%s] Disconnected", s.Name)) + // Connection lost - client disconnected without logout packet + sessionDuration := time.Duration(0) + if s.sessionStart > 0 { + sessionDuration = time.Since(time.Unix(s.sessionStart, 0)) + } + s.logger.Info("Connection lost (EOF)", + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + zap.String("disconnect_type", "connection_lost"), + zap.Duration("session_duration", sessionDuration), + ) logoutPlayer(s) return } else if err != nil { - s.logger.Warn("Error on ReadPacket, exiting recv loop", zap.Error(err)) + // Connection error - network issue or malformed packet + s.logger.Warn("Connection error, exiting recv loop", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.String("name", s.Name), + zap.String("disconnect_type", "error"), + ) logoutPlayer(s) return }