From d728938b59b5dbd97fe2b671c58ceb7531a6d965 Mon Sep 17 00:00:00 2001 From: Blazico Date: Sun, 12 Oct 2025 18:24:33 +0200 Subject: [PATCH 01/11] Update .gitignore --- .gitignore | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.gitignore b/.gitignore index f733bca..091ad0b 100644 --- a/.gitignore +++ b/.gitignore @@ -20,6 +20,8 @@ state # Executables *.exe *.exe~ +wwfc # Editor files .vscode +.github From b9594ee603133e4f12962663bf07c50b261dcddb Mon Sep 17 00:00:00 2001 From: Blazico Date: Sun, 12 Oct 2025 18:40:58 +0200 Subject: [PATCH 02/11] Add handling for 'wl:mkw_race_result' in WWFC report processing --- gpcm/report.go | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/gpcm/report.go b/gpcm/report.go index 97dfb38..f353341 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -63,6 +63,15 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { } qr2.ProcessMKWSelectRecord(g.User.ProfileId, key, value) + + case "wl:mkw_race_result": + if g.GameName != "mariokartwii" { + logging.Warn(g.ModuleName, "Ignoring", keyColored, "from wrong game") + continue + } + + logging.Info(g.ModuleName, "Received race result from profile", aurora.BrightCyan(strconv.FormatUint(uint64(g.User.ProfileId), 10))) + logging.Info(g.ModuleName, "Race result payload:", aurora.BrightMagenta(value)) } } } From c597f75a8aad322e88250b520e677877699982f4 Mon Sep 17 00:00:00 2001 From: Blazico Date: Sat, 18 Oct 2025 23:45:03 +0200 Subject: [PATCH 03/11] Enhance WWFC report handling to parse and log race results with player details --- gpcm/report.go | 38 ++++++++++++++++++++++++++++++++++++-- 1 file changed, 36 insertions(+), 2 deletions(-) diff --git a/gpcm/report.go b/gpcm/report.go index f353341..7449372 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -1,14 +1,29 @@ package gpcm import ( + "encoding/json" "strconv" "wwfc/common" "wwfc/logging" "wwfc/qr2" - "github.com/logrusorgru/aurora/v3" ) +type RaceResultPlayer struct { + Pid *int `json:"pid"` + FinishPosition *int `json:"finish_position"` + FinishTimeMs *int `json:"finish_time_ms"` + CharacterId *int `json:"character_id"` + KartId *int `json:"kart_id"` + ClientRttMs *float64 `json:"client_rtt_ms"` +} + +type RaceResult struct { + ClientReportVersion string `json:"client_report_version"` + TimestampClient string `json:"timestamp_client"` + Players []RaceResultPlayer `json:"players"` +} + func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { for key, value := range command.OtherValues { logging.Info(g.ModuleName, "WiiLink Report:", aurora.Yellow(key)) @@ -71,7 +86,26 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { } logging.Info(g.ModuleName, "Received race result from profile", aurora.BrightCyan(strconv.FormatUint(uint64(g.User.ProfileId), 10))) - logging.Info(g.ModuleName, "Race result payload:", aurora.BrightMagenta(value)) + + var raceResult RaceResult + err := json.Unmarshal([]byte(value), &raceResult) + if err != nil { + logging.Error(g.ModuleName, "Error parsing race result JSON:", err.Error()) + logging.Info(g.ModuleName, "Raw payload:", aurora.BrightMagenta(value)) + continue + } + + logging.Info(g.ModuleName, "Race result version:", aurora.Yellow(raceResult.ClientReportVersion)) + logging.Info(g.ModuleName, "Timestamp:", aurora.Yellow(raceResult.TimestampClient)) + logging.Info(g.ModuleName, "Player count:", aurora.Yellow(len(raceResult.Players))) + + for i, player := range raceResult.Players { + logging.Info(g.ModuleName, "Player", aurora.Cyan(i), "- PID:", aurora.Cyan(player.Pid), + "Pos:", aurora.Cyan(player.FinishPosition), + "Time:", aurora.Cyan(player.FinishTimeMs), "ms", + "Char:", aurora.Cyan(player.CharacterId), + "Kart:", aurora.Cyan(player.KartId)) + } } } } From a9a6ce22df2fb82022e7c30014ac5e6ef1d300c6 Mon Sep 17 00:00:00 2001 From: Blazico Date: Sun, 19 Oct 2025 16:27:53 +0200 Subject: [PATCH 04/11] Removed unnecessary rtt field --- gpcm/report.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/gpcm/report.go b/gpcm/report.go index 7449372..2443546 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -6,6 +6,7 @@ import ( "wwfc/common" "wwfc/logging" "wwfc/qr2" + "github.com/logrusorgru/aurora/v3" ) @@ -15,7 +16,6 @@ type RaceResultPlayer struct { FinishTimeMs *int `json:"finish_time_ms"` CharacterId *int `json:"character_id"` KartId *int `json:"kart_id"` - ClientRttMs *float64 `json:"client_rtt_ms"` } type RaceResult struct { From 44076fab7a14f3ccf820a3805ca0505bf1521b5a Mon Sep 17 00:00:00 2001 From: Blazico Date: Sun, 19 Oct 2025 16:44:43 +0200 Subject: [PATCH 05/11] Dereferenced pointers --- gpcm/report.go | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/gpcm/report.go b/gpcm/report.go index 2443546..bbb5142 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -100,12 +100,16 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { logging.Info(g.ModuleName, "Player count:", aurora.Yellow(len(raceResult.Players))) for i, player := range raceResult.Players { - logging.Info(g.ModuleName, "Player", aurora.Cyan(i), "- PID:", aurora.Cyan(player.Pid), - "Pos:", aurora.Cyan(player.FinishPosition), - "Time:", aurora.Cyan(player.FinishTimeMs), "ms", - "Char:", aurora.Cyan(player.CharacterId), - "Kart:", aurora.Cyan(player.KartId)) + // Force dereference as requested; assume fields are always present + logging.Info(g.ModuleName, + "Player", aurora.Cyan(i), + "- PID:", aurora.Cyan(strconv.Itoa(*player.Pid)), + "Pos:", aurora.Cyan(strconv.Itoa(*player.FinishPosition)), + "Time:", aurora.Cyan(strconv.Itoa(*player.FinishTimeMs)), "ms", + "Char:", aurora.Cyan(strconv.Itoa(*player.CharacterId)), + "Kart:", aurora.Cyan(strconv.Itoa(*player.KartId))) } + //TODO : Hand off to qr2 for processing instead of logging each field here } } } From 3ec7f68a6d84eb71f80a6218015588555db46962 Mon Sep 17 00:00:00 2001 From: Blazico Date: Sun, 19 Oct 2025 20:28:11 +0200 Subject: [PATCH 06/11] Updated race report structure --- gpcm/report.go | 25 ++++++++++--------------- 1 file changed, 10 insertions(+), 15 deletions(-) diff --git a/gpcm/report.go b/gpcm/report.go index bbb5142..4447790 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -19,9 +19,8 @@ type RaceResultPlayer struct { } type RaceResult struct { - ClientReportVersion string `json:"client_report_version"` - TimestampClient string `json:"timestamp_client"` - Players []RaceResultPlayer `json:"players"` + ClientReportVersion string `json:"client_report_version"` + Player RaceResultPlayer `json:"player"` } func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { @@ -96,19 +95,15 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { } logging.Info(g.ModuleName, "Race result version:", aurora.Yellow(raceResult.ClientReportVersion)) - logging.Info(g.ModuleName, "Timestamp:", aurora.Yellow(raceResult.TimestampClient)) - logging.Info(g.ModuleName, "Player count:", aurora.Yellow(len(raceResult.Players))) - for i, player := range raceResult.Players { - // Force dereference as requested; assume fields are always present - logging.Info(g.ModuleName, - "Player", aurora.Cyan(i), - "- PID:", aurora.Cyan(strconv.Itoa(*player.Pid)), - "Pos:", aurora.Cyan(strconv.Itoa(*player.FinishPosition)), - "Time:", aurora.Cyan(strconv.Itoa(*player.FinishTimeMs)), "ms", - "Char:", aurora.Cyan(strconv.Itoa(*player.CharacterId)), - "Kart:", aurora.Cyan(strconv.Itoa(*player.KartId))) - } + player := raceResult.Player + logging.Info(g.ModuleName, + "Player", + "- PID:", aurora.Cyan(strconv.Itoa(*player.Pid)), + "Pos:", aurora.Cyan(strconv.Itoa(*player.FinishPosition)), + "Time:", aurora.Cyan(strconv.Itoa(*player.FinishTimeMs)), "ms", + "Char:", aurora.Cyan(strconv.Itoa(*player.CharacterId)), + "Kart:", aurora.Cyan(strconv.Itoa(*player.KartId))) //TODO : Hand off to qr2 for processing instead of logging each field here } } From 5cb0b8f2dafea47351de1a07f4e1264373133d72 Mon Sep 17 00:00:00 2001 From: Blazico Date: Sun, 19 Oct 2025 20:47:21 +0200 Subject: [PATCH 07/11] Removed faulty finishposition field --- gpcm/report.go | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/gpcm/report.go b/gpcm/report.go index 4447790..5f18e8a 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -11,11 +11,10 @@ import ( ) type RaceResultPlayer struct { - Pid *int `json:"pid"` - FinishPosition *int `json:"finish_position"` - FinishTimeMs *int `json:"finish_time_ms"` - CharacterId *int `json:"character_id"` - KartId *int `json:"kart_id"` + Pid *int `json:"pid"` + FinishTimeMs *int `json:"finish_time_ms"` + CharacterId *int `json:"character_id"` + KartId *int `json:"kart_id"` } type RaceResult struct { @@ -100,7 +99,6 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { logging.Info(g.ModuleName, "Player", "- PID:", aurora.Cyan(strconv.Itoa(*player.Pid)), - "Pos:", aurora.Cyan(strconv.Itoa(*player.FinishPosition)), "Time:", aurora.Cyan(strconv.Itoa(*player.FinishTimeMs)), "ms", "Char:", aurora.Cyan(strconv.Itoa(*player.CharacterId)), "Kart:", aurora.Cyan(strconv.Itoa(*player.KartId))) From 24f9838eee18db186912bc771316ac0e0ee159f4 Mon Sep 17 00:00:00 2001 From: Blazico Date: Mon, 20 Oct 2025 00:07:41 +0200 Subject: [PATCH 08/11] Remove reserved profile ID checks to allow all profile IDs during user creation and profile ID updates --- database/user.go | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/database/user.go b/database/user.go index 0e79d89..3757c27 100644 --- a/database/user.go +++ b/database/user.go @@ -56,9 +56,7 @@ func (user *User) CreateUser(pool *pgxpool.Pool, ctx context.Context) error { return pool.QueryRow(ctx, InsertUser, user.UserId, user.GsbrCode, "", user.NgDeviceId, user.Email, user.UniqueNick).Scan(&user.ProfileId) } - if user.ProfileId >= 1000000000 { - return ErrReservedProfileIDRange - } + // Reserved profile ID check removed; all profile IDs allowed var exists bool err := pool.QueryRow(ctx, IsProfileIDInUse, user.ProfileId).Scan(&exists) @@ -75,9 +73,7 @@ func (user *User) CreateUser(pool *pgxpool.Pool, ctx context.Context) error { } func (user *User) UpdateProfileID(pool *pgxpool.Pool, ctx context.Context, newProfileId uint32) error { - if newProfileId >= 1000000000 { - return ErrReservedProfileIDRange - } + // Reserved profile ID check removed; all profile IDs allowed var exists bool err := pool.QueryRow(ctx, IsProfileIDInUse, newProfileId).Scan(&exists) From 000aac92ec1d1ec69c06a55c684cac8ec53f3cbf Mon Sep 17 00:00:00 2001 From: nwoik Date: Fri, 24 Oct 2025 19:09:51 +0100 Subject: [PATCH 09/11] fixed pointers --- gpcm/report.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/gpcm/report.go b/gpcm/report.go index 5f18e8a..95a2274 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -11,15 +11,15 @@ import ( ) type RaceResultPlayer struct { - Pid *int `json:"pid"` - FinishTimeMs *int `json:"finish_time_ms"` - CharacterId *int `json:"character_id"` - KartId *int `json:"kart_id"` + Pid int `json:"pid"` + FinishTimeMs int `json:"finish_time_ms"` + CharacterId int `json:"character_id"` + KartId int `json:"kart_id"` } type RaceResult struct { - ClientReportVersion string `json:"client_report_version"` - Player RaceResultPlayer `json:"player"` + ClientReportVersion string `json:"client_report_version"` + Player *RaceResultPlayer `json:"player"` } func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { @@ -98,10 +98,10 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { player := raceResult.Player logging.Info(g.ModuleName, "Player", - "- PID:", aurora.Cyan(strconv.Itoa(*player.Pid)), - "Time:", aurora.Cyan(strconv.Itoa(*player.FinishTimeMs)), "ms", - "Char:", aurora.Cyan(strconv.Itoa(*player.CharacterId)), - "Kart:", aurora.Cyan(strconv.Itoa(*player.KartId))) + "- PID:", aurora.Cyan(strconv.Itoa(player.Pid)), + "Time:", aurora.Cyan(strconv.Itoa(player.FinishTimeMs)), "ms", + "Char:", aurora.Cyan(strconv.Itoa(player.CharacterId)), + "Kart:", aurora.Cyan(strconv.Itoa(player.KartId))) //TODO : Hand off to qr2 for processing instead of logging each field here } } From 997f2fb6cd2aec0fc8da3ec8591a74170a6706af Mon Sep 17 00:00:00 2001 From: Blazico Date: Sun, 1 Mar 2026 16:58:51 +0100 Subject: [PATCH 10/11] Race results API integration --- api/mkw_rr.go | 58 ++++++++++++ gpcm/report.go | 46 +++++++++- nas/main.go | 6 ++ qr2/group.go | 109 +++++++++++++++++++++++ race/race_progress.go | 199 ++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 417 insertions(+), 1 deletion(-) create mode 100644 api/mkw_rr.go create mode 100644 race/race_progress.go diff --git a/api/mkw_rr.go b/api/mkw_rr.go new file mode 100644 index 0000000..6bea79b --- /dev/null +++ b/api/mkw_rr.go @@ -0,0 +1,58 @@ +package api + +import ( + "encoding/json" + "net/http" + "net/url" + "strconv" + "wwfc/qr2" +) + +type RaceResultInfo struct { + Results map[int][]qr2.RaceResult `json:"results"` +} + +func HandleMKWRR(w http.ResponseWriter, r *http.Request) { + u, err := url.Parse(r.URL.String()) + if err != nil { + w.WriteHeader(http.StatusBadRequest) + return + } + + query, err := url.ParseQuery(u.RawQuery) + if err != nil { + w.WriteHeader(http.StatusBadRequest) + return + } + + groupNames := query["id"] + if len(groupNames) != 1 { + w.WriteHeader(http.StatusBadRequest) + return + } + + results := qr2.GetRaceResultsForGroup(query["id"][0]) + if results == nil { + w.WriteHeader(http.StatusNotFound) + return + } + + var jsonData []byte + if len(results) == 0 { + w.WriteHeader(http.StatusNotFound) + return + } else { + jsonData, err = json.Marshal(RaceResultInfo{ + Results: results, + }) + if err != nil { + w.WriteHeader(http.StatusInternalServerError) + return + } + } + + w.Header().Set("Content-Type", "application/json") + w.Header().Set("Access-Control-Allow-Origin", "*") + w.Header().Set("Content-Length", strconv.Itoa(len(jsonData))) + w.Write(jsonData) +} diff --git a/gpcm/report.go b/gpcm/report.go index 95a2274..0844fb7 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -3,9 +3,11 @@ package gpcm import ( "encoding/json" "strconv" + "time" "wwfc/common" "wwfc/logging" "wwfc/qr2" + "wwfc/race" "github.com/logrusorgru/aurora/v3" ) @@ -96,13 +98,55 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { logging.Info(g.ModuleName, "Race result version:", aurora.Yellow(raceResult.ClientReportVersion)) player := raceResult.Player + logging.Info(g.ModuleName, "Player", "- PID:", aurora.Cyan(strconv.Itoa(player.Pid)), "Time:", aurora.Cyan(strconv.Itoa(player.FinishTimeMs)), "ms", "Char:", aurora.Cyan(strconv.Itoa(player.CharacterId)), "Kart:", aurora.Cyan(strconv.Itoa(player.KartId))) - //TODO : Hand off to qr2 for processing instead of logging each field here + + // Hand off to qr2 for processing + qr2.ProcessMKWRaceResult(g.User.ProfileId, player.Pid, player.FinishTimeMs, player.CharacterId, player.KartId) + case "wl:mkw_race_start_time": + serverTime := time.Now().UnixMilli() + logging.Info(g.ModuleName, + "Race start time:", aurora.Yellow(value), + "Server time:", aurora.Yellow(strconv.FormatInt(serverTime, 10))) + + // Parse client timestamp + clientTime, err := strconv.ParseInt(value, 10, 64) + if err != nil { + logging.Error(g.ModuleName, "Failed to parse client timestamp:", err.Error()) + return + } + + // Initialize progress timing data for this race + race.RaceProgressTimings[g.User.ProfileId] = &race.RaceProgressTiming{ + ClientStartTime: clientTime, + ServerStartTime: serverTime, + RecentDelays: make([]float64, 0, race.MaxDelays), + } + + case "wl:mkw_race_progress_time": + race.HandleRaceProgressTime(g.User.ProfileId, value) + + case "wl:mkw_race_finish_time": + serverTime := time.Now().UnixMilli() + logging.Info(g.ModuleName, + "Race finish time:", aurora.Yellow(value), + "Server time:", aurora.Yellow(strconv.FormatInt(serverTime, 10))) + + // Parse client timestamp + clientTime, err := strconv.ParseInt(value, 10, 64) + if err != nil { + logging.Error(g.ModuleName, "Failed to parse client finish timestamp:", err.Error()) + return + } + + // Calculate and log final race delays + race.LogRaceProgressDelay(g.User.ProfileId, clientTime, serverTime) } + } } diff --git a/nas/main.go b/nas/main.go index 22630d2..722675d 100644 --- a/nas/main.go +++ b/nas/main.go @@ -177,6 +177,12 @@ func handleRequest(w http.ResponseWriter, r *http.Request) { return } + // Check for /api/mkw_rr + if r.URL.Path == "/api/mkw_rr" { + api.HandleMKWRR(w, r) + return + } + logging.Info("NAS", aurora.Yellow(r.Method), aurora.Cyan(r.URL), "via", aurora.Cyan(r.Host), "from", aurora.BrightCyan(r.RemoteAddr)) replyHTTPError(w, 404, "404 Not Found") } diff --git a/qr2/group.go b/qr2/group.go index 6fb901a..f24086e 100644 --- a/qr2/group.go +++ b/qr2/group.go @@ -5,12 +5,14 @@ import ( "encoding/binary" "encoding/gob" "fmt" + "math" "os" "strconv" "strings" "time" "wwfc/common" "wwfc/logging" + "wwfc/race" "github.com/logrusorgru/aurora/v3" ) @@ -31,6 +33,28 @@ type Group struct { MKWEngineClassID int } +type RaceResultPlayer struct { + Pid int `json:"pid"` + FinishTimeMs int `json:"finish_time_ms"` + CharacterId int `json:"character_id"` + KartId int `json:"kart_id"` +} + +type RaceResult struct { + ProfileID uint32 + PlayerID int + FinishTime uint32 + CharacterID uint32 + VehicleID uint32 + PlayerCount uint32 + FinishPos int + CourseID int + EngineClassID int + Delta int +} + +var raceResults = map[string]map[int][]RaceResult{} // GroupName -> RaceNumber -> []RaceResult + var groups = map[string]*Group{} func processResvOK(moduleName string, matchVersion int, reservation common.MatchCommandDataReservation, resvOK common.MatchCommandDataResvOK, sender, destination *Session) bool { @@ -525,6 +549,91 @@ func ProcessMKWSelectRecord(profileId uint32, key string, value string) { } +func ProcessMKWRaceResult(profileId uint32, playerPid int, finishTimeMs int, characterId int, kartId int) { + moduleName := "QR2:MKWRaceResult:" + strconv.FormatUint(uint64(profileId), 10) + + mutex.Lock() + login := logins[profileId] + if login == nil { + mutex.Unlock() + logging.Warn(moduleName, "Received race result from non-existent profile ID", aurora.Cyan(profileId)) + return + } + + session := login.session + if session == nil { + mutex.Unlock() + logging.Warn(moduleName, "Received race result from profile ID", aurora.Cyan(profileId), "but no session exists") + return + } + mutex.Unlock() + + group := session.groupPointer + if group == nil { + return + } + + if group.MKWRaceNumber == 0 { + logging.Error(moduleName, "Received race result but no races have been started") + return + } + + // Get the accumulated lag from race progress timing + var delta int + if timing, exists := race.RaceProgressTimings[profileId]; exists && len(timing.RecentDelays) > 0 { + // Get the final smoothed delay and convert to int + finalDelay := timing.RecentDelays[len(timing.RecentDelays)-1] + delta = int(math.Round(finalDelay)) + } + + // Convert race result data to internal format + raceResultData := RaceResult{ + ProfileID: profileId, + PlayerID: playerPid, + FinishTime: uint32(finishTimeMs), + CharacterID: uint32(characterId), + VehicleID: uint32(kartId), + PlayerCount: 12, // Default value, could be extracted from race data if available + FinishPos: 0, // Default value, could be calculated from finish times + CourseID: group.MKWCourseID, + EngineClassID: group.MKWEngineClassID, + Delta: delta, + } + + mutex.Lock() + defer mutex.Unlock() + + if raceResults[group.GroupName] == nil { + raceResults[group.GroupName] = map[int][]RaceResult{} + } + + raceResults[group.GroupName][group.MKWRaceNumber] = append(raceResults[group.GroupName][group.MKWRaceNumber], raceResultData) + + logging.Info(moduleName, "Stored race result for profile", aurora.BrightCyan(strconv.FormatUint(uint64(profileId), 10)), + "Race #:", aurora.Cyan(strconv.Itoa(group.MKWRaceNumber)), + "Course:", aurora.Cyan(strconv.Itoa(group.MKWCourseID)), + "Delta:", aurora.Cyan(strconv.Itoa(delta))) +} + +func GetRaceResultsForGroup(groupName string) map[int][]RaceResult { + mutex.Lock() + defer mutex.Unlock() + + groupResults, ok := raceResults[groupName] + if !ok { + return nil + } + + // Return a copy to prevent external modification + copiedRaceResults := make(map[int][]RaceResult) + for raceNumber, results := range groupResults { + copiedRaceResults[raceNumber] = make([]RaceResult, len(results)) + copy(copiedRaceResults[raceNumber], results) + } + + return copiedRaceResults +} + // saveGroups saves the current groups state to disk. // Expects the mutex to be locked. func saveGroups() error { diff --git a/race/race_progress.go b/race/race_progress.go new file mode 100644 index 0000000..80d615c --- /dev/null +++ b/race/race_progress.go @@ -0,0 +1,199 @@ +package race + +import ( + "fmt" + "os" + "strconv" + "time" + "wwfc/logging" + + "github.com/logrusorgru/aurora/v3" +) + +const ( + MaxDelays = 20 // Maximum delays to track in rolling window + SmoothingFactor = 0.3 // For exponential smoothing algorithm +) + +type DelayMeasurement struct { + Timestamp int64 // Server timestamp when delay was measured + RawDelay float64 // Raw delay measurement + SmoothedDelay float64 // Smoothed delay using exponential smoothing +} + +type RaceProgressTiming struct { + ClientStartTime int64 // Client's race start time (absolute timestamp) + ServerStartTime int64 // Server's race start time (absolute timestamp) + RecentDelays []float64 // Rolling window of recent delays + DelayData []DelayMeasurement // All delay measurements for this race +} + +// Global map to track race progress timing data by profile ID +var RaceProgressTimings = make(map[uint32]*RaceProgressTiming) + +// logFinalRaceDelay logs the final smoothed and unsmoothed delays for a race to a separate file +func logFinalRaceDelay(pid uint32, finalSmoothedDelay float64, finalUnsmoothedDelay float64) { + file, err := os.OpenFile("delay_logs/race_progress_delays.txt", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644) + if err != nil { + logging.Error("race", "Failed to open race progress delays log file:", err.Error()) + return + } + defer file.Close() + + // Write to file: PID,Final_Smoothed_Delay,Final_Unsmoothed_Delay + logEntry := fmt.Sprintf("%d,%.2f,%.2f\n", pid, finalSmoothedDelay, finalUnsmoothedDelay) + _, err = file.WriteString(logEntry) + if err != nil { + logging.Error("race", "Failed to write to race progress delays log file:", err.Error()) + } +} + +// logRaceProgressDelay stores delay measurements in memory for later batch writing +func logRaceProgressDelay(pid uint32, timestamp int64, rawDelay float64, smoothedDelay float64) { + // Get the race start time to use as the race identifier + if timing, exists := RaceProgressTimings[pid]; exists { + // Store delay data in memory for batch writing at race end + // We'll add a field to RaceProgressTiming to store the delay data + if timing.DelayData == nil { + timing.DelayData = make([]DelayMeasurement, 0) + } + + measurement := DelayMeasurement{ + Timestamp: timestamp, + RawDelay: rawDelay, + SmoothedDelay: smoothedDelay, + } + timing.DelayData = append(timing.DelayData, measurement) + } +} + +// addDelayToWindow adds a new delay to the rolling window and returns the smoothed delay +func addDelayToWindow(timing *RaceProgressTiming, newDelay float64) float64 { + // Add new delay to the window + timing.RecentDelays = append(timing.RecentDelays, newDelay) + + // Maintain rolling window size + if len(timing.RecentDelays) > MaxDelays { + timing.RecentDelays = timing.RecentDelays[1:] + } + + // Calculate smoothed delay using exponential smoothing + var smoothedDelay float64 + if len(timing.RecentDelays) == 1 { + // First delay, no smoothing needed + smoothedDelay = newDelay + } else { + // Apply exponential smoothing + previousSmoothed := timing.RecentDelays[len(timing.RecentDelays)-2] + smoothedDelay = SmoothingFactor*newDelay + (1-SmoothingFactor)*previousSmoothed + } + + return smoothedDelay +} + +// HandleRaceProgressTime handles the wl:mkw_race_progress_time report case +func HandleRaceProgressTime(pid uint32, value string) { + // Parse client absolute timestamp (this is the client's current time) + clientTimestamp, err := strconv.ParseInt(value, 10, 64) + if err != nil { + logging.Error("race", "Failed to parse client progress timestamp:", err.Error()) + return + } + + serverTime := time.Now().UnixMilli() + + // logging.Info("race", "Race progress time:", aurora.Yellow(value), "Server time:", aurora.Yellow(strconv.FormatInt(serverTime, 10))) + + // Get or create progress timing for this player + timing, exists := RaceProgressTimings[pid] + if !exists { + logging.Warn("race", "No race start timing found for progress report from profile", aurora.BrightCyan(strconv.FormatUint(uint64(pid), 10))) + return + } + + // Calculate client elapsed time: current client timestamp - client start timestamp + clientElapsedTime := clientTimestamp - timing.ClientStartTime + + // Calculate server elapsed time: current server time - server start time + serverElapsedTime := serverTime - timing.ServerStartTime + + // Calculate delay: client elapsed time - server elapsed time + // This gives us the time difference between what the client thinks has passed vs what the server thinks has passed + delay := float64(clientElapsedTime - serverElapsedTime) + + // Add to rolling window and get smoothed delay + smoothedDelay := addDelayToWindow(timing, delay) + + // Log this delay measurement to per-race CSV file + logRaceProgressDelay(pid, serverTime, delay, smoothedDelay) + + // logging.Info("race", + // "Progress delay:", aurora.Cyan(fmt.Sprintf("%.2f", delay)), + // "Smoothed delay:", aurora.Cyan(fmt.Sprintf("%.2f", smoothedDelay)), + // "Delays tracked:", aurora.Cyan(strconv.Itoa(len(timing.RecentDelays)))) + + // Progress delays are tracked in memory for smoothing calculation + // Final delays are logged when race finishes +} + +// LogRaceProgressDelay logs final race delays and cleans up timing data +func LogRaceProgressDelay(pid uint32, clientFinishTime int64, serverFinishTime int64) { + if timing, exists := RaceProgressTimings[pid]; exists { + // Calculate final unsmoothed delay using start and finish timestamps + finalUnsmoothedDelay := float64((clientFinishTime - timing.ClientStartTime) - (serverFinishTime - timing.ServerStartTime)) + + // Get final smoothed delay from the rolling window + var finalSmoothedDelay float64 + if len(timing.RecentDelays) > 0 { + finalSmoothedDelay = timing.RecentDelays[len(timing.RecentDelays)-1] + } + + // Log both delays + logFinalRaceDelay(pid, finalSmoothedDelay, finalUnsmoothedDelay) + + // Write all delay measurements to CSV file in batch + writeRaceProgressDelaysToFile(pid, timing) + + // Clean up timing data for this player + delete(RaceProgressTimings, pid) + } +} + +// writeRaceProgressDelaysToFile writes all stored delay measurements to a CSV file +func writeRaceProgressDelaysToFile(pid uint32, timing *RaceProgressTiming) { + // Create filename with PID and race start time for uniqueness (one file per race per player) + filename := fmt.Sprintf("delay_logs/race_delays_%d_%d.csv", pid, timing.ClientStartTime) + + file, err := os.OpenFile(filename, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644) + if err != nil { + logging.Error("race", "Failed to open race delay CSV file:", err.Error()) + return + } + defer file.Close() + + // Write header if file is empty + fileInfo, _ := file.Stat() + if fileInfo.Size() == 0 { + header := "timestamp,raw_delay,smoothed_delay\n" + _, err = file.WriteString(header) + if err != nil { + logging.Error("race", "Failed to write CSV header:", err.Error()) + return + } + } + + // Write all delay measurements in batch + for _, measurement := range timing.DelayData { + logEntry := fmt.Sprintf("%d,%.2f,%.2f\n", measurement.Timestamp, measurement.RawDelay, measurement.SmoothedDelay) + _, err = file.WriteString(logEntry) + if err != nil { + logging.Error("race", "Failed to write to race delay CSV file:", err.Error()) + return + } + } +} + +// CleanupRaceProgressTiming cleans up race progress timing data for a player +func CleanupRaceProgressTiming(pid uint32) { + delete(RaceProgressTimings, pid) +} From 81c6045f02d078ae1bfb4656ca2482f2660a68c3 Mon Sep 17 00:00:00 2001 From: Blazico Date: Mon, 2 Mar 2026 14:15:34 +0100 Subject: [PATCH 11/11] Simplified race result handling --- gpcm/report.go | 24 ++--- qr2/group.go | 61 ++++++++++--- race/race_progress.go | 199 ------------------------------------------ 3 files changed, 60 insertions(+), 224 deletions(-) delete mode 100644 race/race_progress.go diff --git a/gpcm/report.go b/gpcm/report.go index 0844fb7..80c83bf 100644 --- a/gpcm/report.go +++ b/gpcm/report.go @@ -7,7 +7,6 @@ import ( "wwfc/common" "wwfc/logging" "wwfc/qr2" - "wwfc/race" "github.com/logrusorgru/aurora/v3" ) @@ -17,6 +16,7 @@ type RaceResultPlayer struct { FinishTimeMs int `json:"finish_time_ms"` CharacterId int `json:"character_id"` KartId int `json:"kart_id"` + PlayerCount int `json:"player_count"` } type RaceResult struct { @@ -104,10 +104,12 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { "- PID:", aurora.Cyan(strconv.Itoa(player.Pid)), "Time:", aurora.Cyan(strconv.Itoa(player.FinishTimeMs)), "ms", "Char:", aurora.Cyan(strconv.Itoa(player.CharacterId)), - "Kart:", aurora.Cyan(strconv.Itoa(player.KartId))) + "Kart:", aurora.Cyan(strconv.Itoa(player.KartId)), + "Count:", aurora.Cyan(strconv.Itoa(player.PlayerCount))) // Hand off to qr2 for processing - qr2.ProcessMKWRaceResult(g.User.ProfileId, player.Pid, player.FinishTimeMs, player.CharacterId, player.KartId) + qr2.ProcessMKWRaceResult(g.User.ProfileId, player.Pid, player.FinishTimeMs, player.CharacterId, player.KartId, player.PlayerCount) + case "wl:mkw_race_start_time": serverTime := time.Now().UnixMilli() logging.Info(g.ModuleName, @@ -121,15 +123,8 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { return } - // Initialize progress timing data for this race - race.RaceProgressTimings[g.User.ProfileId] = &race.RaceProgressTiming{ - ClientStartTime: clientTime, - ServerStartTime: serverTime, - RecentDelays: make([]float64, 0, race.MaxDelays), - } - - case "wl:mkw_race_progress_time": - race.HandleRaceProgressTime(g.User.ProfileId, value) + // Store timing data in qr2 module + qr2.StoreRaceStartTime(g.User.ProfileId, clientTime, serverTime) case "wl:mkw_race_finish_time": serverTime := time.Now().UnixMilli() @@ -144,9 +139,8 @@ func (g *GameSpySession) handleWWFCReport(command common.GameSpyCommand) { return } - // Calculate and log final race delays - race.LogRaceProgressDelay(g.User.ProfileId, clientTime, serverTime) + // Store timing data in qr2 module + qr2.StoreRaceFinishTime(g.User.ProfileId, clientTime, serverTime) } - } } diff --git a/qr2/group.go b/qr2/group.go index f24086e..bf6a6b1 100644 --- a/qr2/group.go +++ b/qr2/group.go @@ -5,14 +5,12 @@ import ( "encoding/binary" "encoding/gob" "fmt" - "math" "os" "strconv" "strings" "time" "wwfc/common" "wwfc/logging" - "wwfc/race" "github.com/logrusorgru/aurora/v3" ) @@ -55,6 +53,17 @@ type RaceResult struct { var raceResults = map[string]map[int][]RaceResult{} // GroupName -> RaceNumber -> []RaceResult +// Timing storage for delta calculation using start/finish times +var raceStartTimings = map[uint32]struct { + ClientTime int64 + ServerTime int64 +}{} + +var raceFinishTimings = map[uint32]struct { + ClientTime int64 + ServerTime int64 +}{} + var groups = map[string]*Group{} func processResvOK(moduleName string, matchVersion int, reservation common.MatchCommandDataReservation, resvOK common.MatchCommandDataResvOK, sender, destination *Session) bool { @@ -334,6 +343,22 @@ func CheckGPReservationAllowed(senderIP uint64, senderPid uint32, destPid uint32 return checkReservationAllowed(moduleName, from, to, joinType) } +// StoreRaceStartTime stores the start timing data for delta calculation +func StoreRaceStartTime(profileId uint32, clientTime, serverTime int64) { + raceStartTimings[profileId] = struct { + ClientTime int64 + ServerTime int64 + }{ClientTime: clientTime, ServerTime: serverTime} +} + +// StoreRaceFinishTime stores the finish timing data for delta calculation +func StoreRaceFinishTime(profileId uint32, clientTime, serverTime int64) { + raceFinishTimings[profileId] = struct { + ClientTime int64 + ServerTime int64 + }{ClientTime: clientTime, ServerTime: serverTime} +} + func ProcessNATNEGReport(result byte, ip1 string, ip2 string) { moduleName := "QR2:NATNEGReport" @@ -549,7 +574,7 @@ func ProcessMKWSelectRecord(profileId uint32, key string, value string) { } -func ProcessMKWRaceResult(profileId uint32, playerPid int, finishTimeMs int, characterId int, kartId int) { +func ProcessMKWRaceResult(profileId uint32, playerPid int, finishTimeMs int, characterId int, kartId int, playerCount int) { moduleName := "QR2:MKWRaceResult:" + strconv.FormatUint(uint64(profileId), 10) mutex.Lock() @@ -578,12 +603,28 @@ func ProcessMKWRaceResult(profileId uint32, playerPid int, finishTimeMs int, cha return } - // Get the accumulated lag from race progress timing + // Calculate delta using start/finish times var delta int - if timing, exists := race.RaceProgressTimings[profileId]; exists && len(timing.RecentDelays) > 0 { - // Get the final smoothed delay and convert to int - finalDelay := timing.RecentDelays[len(timing.RecentDelays)-1] - delta = int(math.Round(finalDelay)) + if startTiming, exists := raceStartTimings[profileId]; exists { + if finishTiming, exists := raceFinishTimings[profileId]; exists { + clientElapsedTime := finishTiming.ClientTime - startTiming.ClientTime + serverElapsedTime := finishTiming.ServerTime - startTiming.ServerTime + delta = int(serverElapsedTime - clientElapsedTime) + } + } + + // Calculate finish position based on current race results + finishPos := 1 + if raceResults[group.GroupName] != nil && len(raceResults[group.GroupName][group.MKWRaceNumber]) > 0 { + // Get current race results for this race number + currentResults := raceResults[group.GroupName][group.MKWRaceNumber] + + // Count how many players have finished with better times + for _, existingResult := range currentResults { + if existingResult.FinishTime < uint32(finishTimeMs) { + finishPos++ + } + } } // Convert race result data to internal format @@ -593,8 +634,8 @@ func ProcessMKWRaceResult(profileId uint32, playerPid int, finishTimeMs int, cha FinishTime: uint32(finishTimeMs), CharacterID: uint32(characterId), VehicleID: uint32(kartId), - PlayerCount: 12, // Default value, could be extracted from race data if available - FinishPos: 0, // Default value, could be calculated from finish times + PlayerCount: uint32(playerCount), + FinishPos: finishPos, CourseID: group.MKWCourseID, EngineClassID: group.MKWEngineClassID, Delta: delta, diff --git a/race/race_progress.go b/race/race_progress.go deleted file mode 100644 index 80d615c..0000000 --- a/race/race_progress.go +++ /dev/null @@ -1,199 +0,0 @@ -package race - -import ( - "fmt" - "os" - "strconv" - "time" - "wwfc/logging" - - "github.com/logrusorgru/aurora/v3" -) - -const ( - MaxDelays = 20 // Maximum delays to track in rolling window - SmoothingFactor = 0.3 // For exponential smoothing algorithm -) - -type DelayMeasurement struct { - Timestamp int64 // Server timestamp when delay was measured - RawDelay float64 // Raw delay measurement - SmoothedDelay float64 // Smoothed delay using exponential smoothing -} - -type RaceProgressTiming struct { - ClientStartTime int64 // Client's race start time (absolute timestamp) - ServerStartTime int64 // Server's race start time (absolute timestamp) - RecentDelays []float64 // Rolling window of recent delays - DelayData []DelayMeasurement // All delay measurements for this race -} - -// Global map to track race progress timing data by profile ID -var RaceProgressTimings = make(map[uint32]*RaceProgressTiming) - -// logFinalRaceDelay logs the final smoothed and unsmoothed delays for a race to a separate file -func logFinalRaceDelay(pid uint32, finalSmoothedDelay float64, finalUnsmoothedDelay float64) { - file, err := os.OpenFile("delay_logs/race_progress_delays.txt", os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644) - if err != nil { - logging.Error("race", "Failed to open race progress delays log file:", err.Error()) - return - } - defer file.Close() - - // Write to file: PID,Final_Smoothed_Delay,Final_Unsmoothed_Delay - logEntry := fmt.Sprintf("%d,%.2f,%.2f\n", pid, finalSmoothedDelay, finalUnsmoothedDelay) - _, err = file.WriteString(logEntry) - if err != nil { - logging.Error("race", "Failed to write to race progress delays log file:", err.Error()) - } -} - -// logRaceProgressDelay stores delay measurements in memory for later batch writing -func logRaceProgressDelay(pid uint32, timestamp int64, rawDelay float64, smoothedDelay float64) { - // Get the race start time to use as the race identifier - if timing, exists := RaceProgressTimings[pid]; exists { - // Store delay data in memory for batch writing at race end - // We'll add a field to RaceProgressTiming to store the delay data - if timing.DelayData == nil { - timing.DelayData = make([]DelayMeasurement, 0) - } - - measurement := DelayMeasurement{ - Timestamp: timestamp, - RawDelay: rawDelay, - SmoothedDelay: smoothedDelay, - } - timing.DelayData = append(timing.DelayData, measurement) - } -} - -// addDelayToWindow adds a new delay to the rolling window and returns the smoothed delay -func addDelayToWindow(timing *RaceProgressTiming, newDelay float64) float64 { - // Add new delay to the window - timing.RecentDelays = append(timing.RecentDelays, newDelay) - - // Maintain rolling window size - if len(timing.RecentDelays) > MaxDelays { - timing.RecentDelays = timing.RecentDelays[1:] - } - - // Calculate smoothed delay using exponential smoothing - var smoothedDelay float64 - if len(timing.RecentDelays) == 1 { - // First delay, no smoothing needed - smoothedDelay = newDelay - } else { - // Apply exponential smoothing - previousSmoothed := timing.RecentDelays[len(timing.RecentDelays)-2] - smoothedDelay = SmoothingFactor*newDelay + (1-SmoothingFactor)*previousSmoothed - } - - return smoothedDelay -} - -// HandleRaceProgressTime handles the wl:mkw_race_progress_time report case -func HandleRaceProgressTime(pid uint32, value string) { - // Parse client absolute timestamp (this is the client's current time) - clientTimestamp, err := strconv.ParseInt(value, 10, 64) - if err != nil { - logging.Error("race", "Failed to parse client progress timestamp:", err.Error()) - return - } - - serverTime := time.Now().UnixMilli() - - // logging.Info("race", "Race progress time:", aurora.Yellow(value), "Server time:", aurora.Yellow(strconv.FormatInt(serverTime, 10))) - - // Get or create progress timing for this player - timing, exists := RaceProgressTimings[pid] - if !exists { - logging.Warn("race", "No race start timing found for progress report from profile", aurora.BrightCyan(strconv.FormatUint(uint64(pid), 10))) - return - } - - // Calculate client elapsed time: current client timestamp - client start timestamp - clientElapsedTime := clientTimestamp - timing.ClientStartTime - - // Calculate server elapsed time: current server time - server start time - serverElapsedTime := serverTime - timing.ServerStartTime - - // Calculate delay: client elapsed time - server elapsed time - // This gives us the time difference between what the client thinks has passed vs what the server thinks has passed - delay := float64(clientElapsedTime - serverElapsedTime) - - // Add to rolling window and get smoothed delay - smoothedDelay := addDelayToWindow(timing, delay) - - // Log this delay measurement to per-race CSV file - logRaceProgressDelay(pid, serverTime, delay, smoothedDelay) - - // logging.Info("race", - // "Progress delay:", aurora.Cyan(fmt.Sprintf("%.2f", delay)), - // "Smoothed delay:", aurora.Cyan(fmt.Sprintf("%.2f", smoothedDelay)), - // "Delays tracked:", aurora.Cyan(strconv.Itoa(len(timing.RecentDelays)))) - - // Progress delays are tracked in memory for smoothing calculation - // Final delays are logged when race finishes -} - -// LogRaceProgressDelay logs final race delays and cleans up timing data -func LogRaceProgressDelay(pid uint32, clientFinishTime int64, serverFinishTime int64) { - if timing, exists := RaceProgressTimings[pid]; exists { - // Calculate final unsmoothed delay using start and finish timestamps - finalUnsmoothedDelay := float64((clientFinishTime - timing.ClientStartTime) - (serverFinishTime - timing.ServerStartTime)) - - // Get final smoothed delay from the rolling window - var finalSmoothedDelay float64 - if len(timing.RecentDelays) > 0 { - finalSmoothedDelay = timing.RecentDelays[len(timing.RecentDelays)-1] - } - - // Log both delays - logFinalRaceDelay(pid, finalSmoothedDelay, finalUnsmoothedDelay) - - // Write all delay measurements to CSV file in batch - writeRaceProgressDelaysToFile(pid, timing) - - // Clean up timing data for this player - delete(RaceProgressTimings, pid) - } -} - -// writeRaceProgressDelaysToFile writes all stored delay measurements to a CSV file -func writeRaceProgressDelaysToFile(pid uint32, timing *RaceProgressTiming) { - // Create filename with PID and race start time for uniqueness (one file per race per player) - filename := fmt.Sprintf("delay_logs/race_delays_%d_%d.csv", pid, timing.ClientStartTime) - - file, err := os.OpenFile(filename, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644) - if err != nil { - logging.Error("race", "Failed to open race delay CSV file:", err.Error()) - return - } - defer file.Close() - - // Write header if file is empty - fileInfo, _ := file.Stat() - if fileInfo.Size() == 0 { - header := "timestamp,raw_delay,smoothed_delay\n" - _, err = file.WriteString(header) - if err != nil { - logging.Error("race", "Failed to write CSV header:", err.Error()) - return - } - } - - // Write all delay measurements in batch - for _, measurement := range timing.DelayData { - logEntry := fmt.Sprintf("%d,%.2f,%.2f\n", measurement.Timestamp, measurement.RawDelay, measurement.SmoothedDelay) - _, err = file.WriteString(logEntry) - if err != nil { - logging.Error("race", "Failed to write to race delay CSV file:", err.Error()) - return - } - } -} - -// CleanupRaceProgressTiming cleans up race progress timing data for a player -func CleanupRaceProgressTiming(pid uint32) { - delete(RaceProgressTimings, pid) -}