From 3da54fade814d9e5fe715ef4e25f481ac81caa8d Mon Sep 17 00:00:00 2001 From: Houmgaor Date: Sat, 1 Nov 2025 17:14:05 +0100 Subject: [PATCH] chore: adds remaining logging for Hunter Navi and Plate data. --- CHANGELOG.md | 3 +- server/channelserver/handlers_mercenary.go | 50 ++++++++++++++++++-- server/channelserver/handlers_plate.go | 53 ++++++++++++++++++---- 3 files changed, 91 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index ee90fb760..d3408a543 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,9 +11,10 @@ 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) +- Comprehensive production logging for save operations (warehouse, Koryo points, savedata, Hunter Navi, plate equipment) - Disconnect type tracking (graceful, connection_lost, error) with detailed logging - Session lifecycle logging with duration and metrics tracking +- Structured logging with timing metrics for all database save operations ### Changed diff --git a/server/channelserver/handlers_mercenary.go b/server/channelserver/handlers_mercenary.go index 7d92a7d86..d0312f464 100644 --- a/server/channelserver/handlers_mercenary.go +++ b/server/channelserver/handlers_mercenary.go @@ -69,6 +69,15 @@ func handleMsgMhfLoadHunterNavi(s *Session, p mhfpacket.MHFPacket) { func handleMsgMhfSaveHunterNavi(s *Session, p mhfpacket.MHFPacket) { pkt := p.(*mhfpacket.MsgMhfSaveHunterNavi) + saveStart := time.Now() + + s.logger.Debug("Hunter Navi save request", + zap.Uint32("charID", s.charID), + zap.Bool("is_diff", pkt.IsDataDiff), + zap.Int("data_size", len(pkt.RawDataPayload)), + ) + + var dataSize int if pkt.IsDataDiff { naviLength := 552 if s.server.erupeConfig.RealClientMode <= _config.G7 { @@ -78,7 +87,10 @@ func handleMsgMhfSaveHunterNavi(s *Session, p mhfpacket.MHFPacket) { // Load existing save err := s.server.db.QueryRow("SELECT hunternavi FROM characters WHERE id = $1", s.charID).Scan(&data) if err != nil { - s.logger.Error("Failed to load hunternavi", zap.Error(err)) + s.logger.Error("Failed to load hunternavi", + zap.Error(err), + zap.Uint32("charID", s.charID), + ) } // Check if we actually had any hunternavi data, using a blank buffer if not. @@ -88,21 +100,49 @@ func handleMsgMhfSaveHunterNavi(s *Session, p mhfpacket.MHFPacket) { } // Perform diff and compress it to write back to db - s.logger.Info("Diffing...") + s.logger.Debug("Applying Hunter Navi diff", + zap.Uint32("charID", s.charID), + zap.Int("base_size", len(data)), + zap.Int("diff_size", len(pkt.RawDataPayload)), + ) saveOutput := deltacomp.ApplyDataDiff(pkt.RawDataPayload, data) + dataSize = len(saveOutput) + _, err = s.server.db.Exec("UPDATE characters SET hunternavi=$1 WHERE id=$2", saveOutput, s.charID) if err != nil { - s.logger.Error("Failed to save hunternavi", zap.Error(err)) + s.logger.Error("Failed to save hunternavi", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.Int("data_size", dataSize), + ) + doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) + return } - s.logger.Info("Wrote recompressed hunternavi back to DB") } else { dumpSaveData(s, pkt.RawDataPayload, "hunternavi") + dataSize = len(pkt.RawDataPayload) + // simply update database, no extra processing _, err := s.server.db.Exec("UPDATE characters SET hunternavi=$1 WHERE id=$2", pkt.RawDataPayload, s.charID) if err != nil { - s.logger.Error("Failed to save hunternavi", zap.Error(err)) + s.logger.Error("Failed to save hunternavi", + zap.Error(err), + zap.Uint32("charID", s.charID), + zap.Int("data_size", dataSize), + ) + doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) + return } } + + saveDuration := time.Since(saveStart) + s.logger.Info("Hunter Navi saved successfully", + zap.Uint32("charID", s.charID), + zap.Bool("was_diff", pkt.IsDataDiff), + zap.Int("data_size", dataSize), + zap.Duration("duration", saveDuration), + ) + doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) } diff --git a/server/channelserver/handlers_plate.go b/server/channelserver/handlers_plate.go index 19fdd84a2..f44e78164 100644 --- a/server/channelserver/handlers_plate.go +++ b/server/channelserver/handlers_plate.go @@ -5,6 +5,7 @@ import ( "erupe-ce/server/channelserver/compression/deltacomp" "erupe-ce/server/channelserver/compression/nullcomp" "go.uber.org/zap" + "time" ) func handleMsgMhfLoadPlateData(s *Session, p mhfpacket.MHFPacket) { @@ -19,24 +20,38 @@ func handleMsgMhfLoadPlateData(s *Session, p mhfpacket.MHFPacket) { func handleMsgMhfSavePlateData(s *Session, p mhfpacket.MHFPacket) { pkt := p.(*mhfpacket.MsgMhfSavePlateData) + saveStart := time.Now() + s.logger.Debug("PlateData save request", + zap.Uint32("charID", s.charID), + zap.Bool("is_diff", pkt.IsDataDiff), + zap.Int("data_size", len(pkt.RawDataPayload)), + ) + + var dataSize int if pkt.IsDataDiff { var data []byte // Load existing save err := s.server.db.QueryRow("SELECT platedata FROM characters WHERE id = $1", s.charID).Scan(&data) if err != nil { - s.logger.Error("Failed to load platedata", zap.Error(err)) + s.logger.Error("Failed to load platedata", + zap.Error(err), + zap.Uint32("charID", s.charID), + ) doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) return } if len(data) > 0 { // Decompress - s.logger.Info("Decompressing...") + s.logger.Debug("Decompressing PlateData", zap.Int("compressed_size", len(data))) data, err = nullcomp.Decompress(data) if err != nil { - s.logger.Error("Failed to decompress platedata", zap.Error(err)) + s.logger.Error("Failed to decompress platedata", + zap.Error(err), + zap.Uint32("charID", s.charID), + ) doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) return } @@ -46,31 +61,51 @@ func handleMsgMhfSavePlateData(s *Session, p mhfpacket.MHFPacket) { } // Perform diff and compress it to write back to db - s.logger.Info("Diffing...") + s.logger.Debug("Applying PlateData diff", zap.Int("base_size", len(data))) saveOutput, err := nullcomp.Compress(deltacomp.ApplyDataDiff(pkt.RawDataPayload, data)) if err != nil { - s.logger.Error("Failed to diff and compress platedata", zap.Error(err)) + s.logger.Error("Failed to diff and compress platedata", + zap.Error(err), + zap.Uint32("charID", s.charID), + ) doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) return } + dataSize = len(saveOutput) _, err = s.server.db.Exec("UPDATE characters SET platedata=$1 WHERE id=$2", saveOutput, s.charID) if err != nil { - s.logger.Error("Failed to save platedata", zap.Error(err)) + s.logger.Error("Failed to save platedata", + zap.Error(err), + zap.Uint32("charID", s.charID), + ) doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) return } - - s.logger.Info("Wrote recompressed platedata back to DB") } else { dumpSaveData(s, pkt.RawDataPayload, "platedata") + dataSize = len(pkt.RawDataPayload) + // simply update database, no extra processing _, err := s.server.db.Exec("UPDATE characters SET platedata=$1 WHERE id=$2", pkt.RawDataPayload, s.charID) if err != nil { - s.logger.Error("Failed to save platedata", zap.Error(err)) + s.logger.Error("Failed to save platedata", + zap.Error(err), + zap.Uint32("charID", s.charID), + ) + doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) + return } } + saveDuration := time.Since(saveStart) + s.logger.Info("PlateData saved successfully", + zap.Uint32("charID", s.charID), + zap.Bool("was_diff", pkt.IsDataDiff), + zap.Int("data_size", dataSize), + zap.Duration("duration", saveDuration), + ) + doAckSimpleSucceed(s, pkt.AckHandle, []byte{0x00, 0x00, 0x00, 0x00}) }