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) +}