From 98daeff408f0eeb191169884442e8341b687ac2c Mon Sep 17 00:00:00 2001 From: genxium Date: Fri, 11 Nov 2022 23:43:51 +0800 Subject: [PATCH] Updated frontend logging. --- battle_srv/models/room.go | 21 +++++++++++---------- frontend/assets/scenes/login.fire | 2 +- frontend/assets/scripts/Map.js | 16 ++++++++-------- frontend/assets/scripts/WsSessionMgr.js | 18 ++++++------------ 4 files changed, 26 insertions(+), 31 deletions(-) diff --git a/battle_srv/models/room.go b/battle_srv/models/room.go index 6ed12ab..9dc1b36 100644 --- a/battle_srv/models/room.go +++ b/battle_srv/models/room.go @@ -532,11 +532,14 @@ func (pR *Room) StartBattle() { continue } - indiceInJoinIndexBooleanArr := uint32(player.JoinIndex - 1) - var joinMask uint64 = (1 << indiceInJoinIndexBooleanArr) - shouldResyncForSlowerClocker := (0 < (unconfirmedMask & joinMask)) // This condition is critical, if we don't send resync upon this condition, the player with a slower frontend clock might never get its input synced - if pR.BackendDynamicsEnabled && (MAGIC_LAST_SENT_INPUT_FRAME_ID_READDED == player.LastSentInputFrameId || shouldResyncForSlowerClocker) { - // [WARNING] Even upon "MAGIC_LAST_SENT_INPUT_FRAME_ID_READDED", it could be true that "0 == ()"! + /* + Resync helps + 1. when player with a slower frontend clock lags significantly behind and thus wouldn't get its inputUpsync recognized due to faster "forceConfirmation" + 2. reconnection + */ + shouldResync1 := (MAGIC_LAST_SENT_INPUT_FRAME_ID_READDED == player.LastSentInputFrameId) + shouldResync2 := (0 < unconfirmedMask) // This condition is critical, if we don't send resync upon this condition, the might never get its input synced + if pR.BackendDynamicsEnabled && (shouldResync1 || shouldResync2) { tmp := pR.RenderFrameBuffer.GetByFrameId(refRenderFrameId) if nil == tmp { panic(fmt.Sprintf("Required refRenderFrameId=%v for roomId=%v, playerId=%v, candidateToSendInputFrameId=%v doesn't exist! InputsBuffer=%v, RenderFrameBuffer=%v", refRenderFrameId, pR.Id, playerId, candidateToSendInputFrameId, pR.InputsBufferString(false), pR.RenderFrameBufferString())) @@ -560,9 +563,7 @@ func (pR *Room) StartBattle() { toApplyInputFrameId := pR.ConvertToInputFrameId(refRenderFrameId, pR.InputDelayFrames) /* [WARNING] - The following updates to "toApplyInputFrameId" is necessary because - 1. When "false == pR.BackendDynamicsEnabled", the variable "refRenderFrameId" is not well defined; - 2. When "true == pR.BackendDynamicsEnabled", the initial value of "toApplyInputFrameId" might be too big and thus making frontends unable to receive consecutive all-confirmed inputFrameDownsync sequence - which is what we want during a battle if no one disconnects. + The following updates to "toApplyInputFrameId" is necessary because when "false == pR.BackendDynamicsEnabled", the variable "refRenderFrameId" is not well defined. */ minLastSentInputFrameId := int32(math.MaxInt32) for _, player := range pR.Players { @@ -578,7 +579,7 @@ func (pR *Room) StartBattle() { f := pR.InputsBuffer.Pop().(*InputFrameDownsync) if pR.inputFrameIdDebuggable(f.InputFrameId) { // Popping of an "inputFrame" would be AFTER its being all being confirmed, because it requires the "inputFrame" to be all acked - Logger.Debug("inputFrame lifecycle#4[popped]:", zap.Any("roomId", pR.Id), zap.Any("inputFrameId", f.InputFrameId), zap.Any("minLastSentInputFrameId", minLastSentInputFrameId), zap.Any("toApplyInputFrameId", toApplyInputFrameId), zap.Any("InputsBuffer", pR.InputsBufferString(false))) + Logger.Debug("inputFrame lifecycle#4[popped]:", zap.Any("roomId", pR.Id), zap.Any("inputFrameId", f.InputFrameId), zap.Any("toApplyInputFrameId", toApplyInputFrameId), zap.Any("InputsBuffer", pR.InputsBufferString(false))) } } @@ -818,7 +819,7 @@ func (pR *Room) OnDismissed() { pR.BattleDurationFrames = 30 * pR.ServerFps pR.BattleDurationNanos = int64(pR.BattleDurationFrames) * (pR.RollbackEstimatedDtNanos + 1) pR.InputFrameUpsyncDelayTolerance = 2 - pR.MaxChasingRenderFramesPerUpdate = 10 + pR.MaxChasingRenderFramesPerUpdate = 5 pR.BackendDynamicsEnabled = true // [WARNING] When "false", recovery upon reconnection wouldn't work! diff --git a/frontend/assets/scenes/login.fire b/frontend/assets/scenes/login.fire index a527072..63dcfdb 100644 --- a/frontend/assets/scenes/login.fire +++ b/frontend/assets/scenes/login.fire @@ -440,7 +440,7 @@ "array": [ 0, 0, - 377.5870760500153, + 237.35666382819272, 0, 0, 0, diff --git a/frontend/assets/scripts/Map.js b/frontend/assets/scripts/Map.js index 9b00b67..65e15de 100644 --- a/frontend/assets/scripts/Map.js +++ b/frontend/assets/scripts/Map.js @@ -595,7 +595,7 @@ cc.Class({ // The logic below applies to ( || window.RING_BUFF_NON_CONSECUTIVE_SET == dumpRenderCacheRet) if (window.MAGIC_ROOM_DOWNSYNC_FRAME_ID.BATTLE_START == rdf.id) { - console.log('On battle resynced! renderFrameId=', rdf.id); + console.log('On battle started! renderFrameId=', rdf.id); } else { console.log('On battle resynced! renderFrameId=', rdf.id); } @@ -696,7 +696,7 @@ cc.Class({ -------------------------------------------------------- */ // The actual rollback-and-chase would later be executed in update(dt). - console.warn("Mismatched input detected, resetting chaserRenderFrameId: inputFrameId1:", inputFrameId1, ", renderFrameId1:", renderFrameId1, ", chaserRenderFrameId before reset: ", self.chaserRenderFrameId); + console.warn(`Mismatched input detected, resetting chaserRenderFrameId: ${self.chaserRenderFrameId}->${renderFrameId1} by firstPredictedYetIncorrectInputFrameId: ${inputFrameId1}`); self.chaserRenderFrameId = renderFrameId1; }, @@ -713,7 +713,7 @@ cc.Class({ logBattleStats() { const self = this; let s = []; - s.push("Battle stats: renderFrameId=" + self.renderFrameId + ", lastAllConfirmedRenderFrameId=" + self.lastAllConfirmedRenderFrameId + ", lastUpsyncInputFrameId=" + self.lastUpsyncInputFrameId + ", lastAllConfirmedInputFrameId=" + self.lastAllConfirmedInputFrameId); + s.push(`Battle stats: renderFrameId=${self.renderFrameId}, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastUpsyncInputFrameId=${self.lastUpsyncInputFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}, chaserRenderFrameId=${self.chaserRenderFrameId}`); for (let i = self.recentInputCache.stFrameId; i < self.recentInputCache.edFrameId; ++i) { const inputFrameDownsync = self.recentInputCache.getByFrameId(i); @@ -1073,7 +1073,7 @@ cc.Class({ const self = this; let latestRdf = self.recentRenderCache.getByFrameId(renderFrameIdSt); // typed "RoomDownsyncFrame" if (null == latestRdf) { - console.error("Couldn't find renderFrameId=", renderFrameIdSt, " to rollback, lastAllConfirmedRenderFrameId=", self.lastAllConfirmedRenderFrameId, ", lastAllConfirmedInputFrameId=", self.lastAllConfirmedInputFrameId, ", recentRenderCache=", self._stringifyRecentRenderCache(false), ", recentInputCache=", self._stringifyRecentInputCache(false)); + console.error(`Couldn't find renderFrameId=${renderFrameIdSt}, to rollback, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}, recentRenderCache=${self._stringifyRecentRenderCache(false)}, recentInputCache=${self._stringifyRecentInputCache(false)}`); return latestRdf; } @@ -1084,13 +1084,13 @@ cc.Class({ for (let i = renderFrameIdSt; i < renderFrameIdEd; ++i) { const currRenderFrame = self.recentRenderCache.getByFrameId(i); // typed "RoomDownsyncFrame"; [WARNING] When "true == isChasing", this function can be interruptted by "onRoomDownsyncFrame(rdf)" asynchronously anytime, making this line return "null"! if (null == currRenderFrame) { - console.warn("Couldn't find renderFrame for i=", i, " to rollback, self.renderFrameId=", self.renderFrameId, ", lastAllConfirmedRenderFrameId=", self.lastAllConfirmedRenderFrameId, ", lastAllConfirmedInputFrameId=", self.lastAllConfirmedInputFrameId, ", might've been interruptted by `onRoomDownsyncFrame`"); + console.warn(`Couldn't find renderFrame for i=${i} to rollback, self.renderFrameId=${self.renderFrameId}, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}, might've been interruptted by onRoomDownsyncFrame`); return latestRdf; } const j = self._convertToInputFrameId(i, self.inputDelayFrames); const delayedInputFrame = self.getCachedInputFrameDownsyncWithPrediction(j); if (null == delayedInputFrame) { - console.warn("Failed to get cached delayedInputFrame for i=", i, ", j=", j, ", self.renderFrameId=", self.renderFrameId, ", lastAllConfirmedRenderFrameId=", self.lastAllConfirmedRenderFrameId, ", lastAllConfirmedInputFrameId=", self.lastAllConfirmedInputFrameId); + console.warn(`Failed to get cached delayedInputFrame for i=${i}, j=${j}, self.renderFrameId=${self.renderFrameId}, lastAllConfirmedRenderFrameId=${self.lastAllConfirmedRenderFrameId}, lastAllConfirmedInputFrameId=${self.lastAllConfirmedInputFrameId}`); return latestRdf; } @@ -1156,7 +1156,7 @@ cc.Class({ return s.join('\n'); } - return "[stInputFrameId=" + self.recentInputCache.stFrameId + ", edInputFrameId=" + self.recentInputCache.edFrameId + ")"; + return `[stInputFrameId=${self.recentInputCache.stFrameId}, edInputFrameId=${self.recentInputCache.edFrameId})`; }, _stringifyRecentRenderCache(usefullOutput) { @@ -1169,7 +1169,7 @@ cc.Class({ return s.join('\n'); } - return "[stRenderFrameId=" + self.recentRenderCache.stFrameId + ", edRenderFrameId=" + self.recentRenderCache.edFrameId + ")"; + return `[stRenderFrameId=${self.recentRenderCache.stFrameId}, edRenderFrameId=${self.recentRenderCache.edFrameId})`; }, worldToVirtualGridPos(x, y) { diff --git a/frontend/assets/scripts/WsSessionMgr.js b/frontend/assets/scripts/WsSessionMgr.js index 1204219..42ec8fe 100644 --- a/frontend/assets/scripts/WsSessionMgr.js +++ b/frontend/assets/scripts/WsSessionMgr.js @@ -172,22 +172,16 @@ window.initPersistentSessionClient = function(onopenCb, expectedRoomId) { break; case window.DOWNSYNC_MSG_ACT_FORCED_RESYNC: if (null == resp.inputFrameDownsyncBatch || 0 >= resp.inputFrameDownsyncBatch.length) { - console.error("Got empty inputFrameDownsyncBatch upon resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", the incoming resp=\n", JSON.stringify(resp, null, 2)); + console.error(`Got empty inputFrameDownsyncBatch upon resync@localRenderFrameId=${mapIns.renderFrameId}, @lastAllConfirmedRenderFrameId=${mapIns.lastAllConfirmedRenderFrameId}, @lastAllConfirmedInputFrameId=${mapIns.lastAllConfirmedInputFrameId}, @chaserRenderFrameId=${mapIns.chaserRenderFrameId}, @localRecentInputCache=${mapIns._stringifyRecentInputCache(false)}, the incoming resp= +${JSON.stringify(resp, null, 2)}`); return; } - // Unless upon ws session lost and reconnected, it's maintained true that "inputFrameDownsyncBatch[0].inputFrameId == frontend.lastAllConfirmedInputFrameId+1", and in this case we should try to keep frontend moving only by "frontend.recentInputCache" to avoid jiggling of synced positions const inputFrameIdConsecutive = (resp.inputFrameDownsyncBatch[0].inputFrameId == mapIns.lastAllConfirmedInputFrameId + 1); const renderFrameIdConsecutive = (resp.rdf.id <= mapIns.renderFrameId + mapIns.renderFrameIdLagTolerance); - if (inputFrameIdConsecutive && renderFrameIdConsecutive) { - // console.log("Got consecutive resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", the incoming resp=\n", JSON.stringify(resp)); - mapIns.onInputFrameDownsyncBatch(resp.inputFrameDownsyncBatch); - } else { - // console.warn("Got forced resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", the incoming resp=\n", JSON.stringify(resp, null, 2)); - console.warn("Got forced resync@localRenderFrameId=", mapIns.renderFrameId, ", @lastAllConfirmedRenderFrameId=", mapIns.lastAllConfirmedRenderFrameId, "@lastAllConfirmedInputFrameId=", mapIns.lastAllConfirmedInputFrameId, ", @localRecentInputCache=", mapIns._stringifyRecentInputCache(false), ", inputFrameIdConsecutive=", inputFrameIdConsecutive, ", renderFrameIdConsecutive=", renderFrameIdConsecutive); - // The following order of execution is important - mapIns.onRoomDownsyncFrame(resp.rdf); - mapIns.onInputFrameDownsyncBatch(resp.inputFrameDownsyncBatch); - } + console.warn(`Got resync@localRenderFrameId=${mapIns.renderFrameId}, @lastAllConfirmedRenderFrameId=${mapIns.lastAllConfirmedRenderFrameId}, @lastAllConfirmedInputFrameId=${mapIns.lastAllConfirmedInputFrameId}, @chaserRenderFrameId=${mapIns.chaserRenderFrameId}, @localRecentInputCache=${mapIns._stringifyRecentInputCache(false)}, inputFrameIdConsecutive=${inputFrameIdConsecutive}, renderFrameIdConsecutive=${renderFrameIdConsecutive}`); + // The following order of execution is important + mapIns.onRoomDownsyncFrame(resp.rdf); + mapIns.onInputFrameDownsyncBatch(resp.inputFrameDownsyncBatch); break; default: break;