birkeh/o3de
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Changes to desync debug output to make it less stressful on bandwidth and the server, as well as some fixes to corrections on the local client

Browse Source 
Signed-off-by: kberg-amzn <karlberg@amazon.com>
This commit is contained in:
kberg-amzn
2021-08-03 13:12:37 -07:00
parent f0cafd0e9d
commit e0d0bbfdae
15 changed files with 154 additions and 138 deletions
Download Patch File Download Diff File Expand all files Collapse all files
Gems/Multiplayer/Code/Source/AutoGen/LocalPredictionPlayerInputComponent.AutoComponent.xml
-1
View File
@@ -22,7 +22,6 @@
<RemoteProcedure Name="SendClientInput" InvokeFrom="Autonomous" HandleOn="Authority" IsPublic="true" IsReliable="false" GenerateEventBindings="false" Description="Client to server move / input RPC">
<Param Type="Multiplayer::NetworkInputArray" Name="inputArray" />
<Param Type="AZ::HashValue32" Name="stateHash" />
<Param Type="AzNetworking::PacketEncodingBuffer" Name="clientState" Description="This is for debugging desyncs only; release games should not populate this parameter" />
</RemoteProcedure>
<RemoteProcedure Name="SendClientInputCorrection" InvokeFrom="Authority" HandleOn="Autonomous" IsPublic="true" IsReliable="false" GenerateEventBindings="false" Description="Autonomous proxy correction RPC">
Gems/Multiplayer/Code/Source/Components/LocalPredictionPlayerInputComponent.cpp
+74 -102
View File
@@ -21,9 +21,11 @@ namespace Multiplayer
AZ_CVAR(AZ::TimeMs, cl_MaxRewindHistoryMs, AZ::TimeMs{ 2000 }, nullptr, AZ::ConsoleFunctorFlags::Null, "Maximum number of milliseconds to keep for server correction rewind and replay");
#ifndef AZ_RELEASE_BUILD
AZ_CVAR(float, cl_DebugHackTimeMultiplier, 1.0f, nullptr, AZ::ConsoleFunctorFlags::Null, "Scalar value used to simulate clock hacking cheats for validating bank time system and anticheat");
AZ_CVAR(bool, cl_EnableDesyncDebugging, false, nullptr, AZ::ConsoleFunctorFlags::Null, "If enabled, debug logs will contain verbose information on detected state desyncs");
AZ_CVAR(bool, cl_EnableDesyncDebugging, true, nullptr, AZ::ConsoleFunctorFlags::Null, "If enabled, debug logs will contain verbose information on detected state desyncs");
AZ_CVAR(uint32_t, cl_PredictiveStateHistorySize, 120, nullptr, AZ::ConsoleFunctorFlags::Null, "Controls how many inputs of predictive state should be retained for debugging desyncs");
#endif
AZ_CVAR(bool, sv_ForceCorrections, false, nullptr, AZ::ConsoleFunctorFlags::Null, "If enabled, the server will force a correction for every input received for debugging");
AZ_CVAR(bool, sv_EnableCorrections, true, nullptr, AZ::ConsoleFunctorFlags::Null, "Enables server corrections on autonomous proxy desyncs");
AZ_CVAR(double, sv_MaxBankTimeWindowSec, 0.2, nullptr, AZ::ConsoleFunctorFlags::Null, "Maximum bank time we allow before we start rejecting autonomous proxy move inputs due to anticheat kicking in");
AZ_CVAR(double, sv_BankTimeDecay, 0.025, nullptr, AZ::ConsoleFunctorFlags::Null, "Amount to decay bank time by, in case of more permanent shifts in client latency");
@@ -45,6 +47,40 @@ namespace Multiplayer
return serializer.GetString();
}
void PrintCorrectionDifferences(const AzNetworking::StringifySerializer& client, const AzNetworking::StringifySerializer& server)
{
const auto& clientMap = client.GetValueMap();
const auto& serverMap = server.GetValueMap();
AzNetworking::StringifySerializer::ValueMap differences = clientMap;
for (auto iter = server.GetValueMap().begin(); iter != server.GetValueMap().end(); ++iter)
{
auto serverValueIter = clientMap.find(iter->first);
if (iter->second == differences[iter->first])
{
differences.erase(iter->first);
}
}
if (differences.empty())
{
AZLOG_ERROR("The hash mismatched, but no differences were found.")
}
for (auto iter = differences.begin(); iter != differences.end(); ++iter)
{
auto clientValueIter = clientMap.find(iter->first);
auto serverValueIter = serverMap.find(iter->first);
if (clientValueIter == clientMap.end() || serverValueIter == serverMap.end())
{
AZLOG_ERROR(" %s (Not found in server and/or client value map!)", iter->first.c_str());
continue;
}
AZLOG_ERROR(" %s Server=%s Client=%s", iter->first.c_str(), serverValueIter->second.c_str(), clientValueIter->second.c_str());
}
}
void LocalPredictionPlayerInputComponent::LocalPredictionPlayerInputComponent::Reflect(AZ::ReflectContext* context)
{
AZ::SerializeContext* serializeContext = azrtti_cast<AZ::SerializeContext*>(context);
@@ -106,8 +142,7 @@ namespace Multiplayer
(
AzNetworking::IConnection* invokingConnection,
const Multiplayer::NetworkInputArray& inputArray,
const AZ::HashValue32& stateHash,
[[maybe_unused]] const AzNetworking::PacketEncodingBuffer& clientState
const AZ::HashValue32& stateHash
)
{
if (invokingConnection == nullptr)
@@ -176,7 +211,7 @@ namespace Multiplayer
}
}
if (sv_EnableCorrections && (currentTimeMs - m_lastCorrectionSentTimeMs > sv_MinCorrectionTimeMs))
if (sv_ForceCorrections || (sv_EnableCorrections && (currentTimeMs - m_lastCorrectionSentTimeMs > sv_MinCorrectionTimeMs)))
{
m_lastCorrectionSentTimeMs = currentTimeMs;
@@ -210,69 +245,6 @@ namespace Multiplayer
// Send correction
SendClientInputCorrection(GetLastInputId(), correction);
#ifndef AZ_RELEASE_BUILD
AZStd::string clientStateString;
AZStd::string serverStateString;
if (cl_EnableDesyncDebugging)
{
// In debug, show which states caused the correction
// Write in client state
AzNetworking::NetworkOutputSerializer clientStateSerializer(clientState.GetBuffer(), clientState.GetSize());
GetNetBindComponent()->SerializeEntityCorrection(clientStateSerializer);
// Read out state values
AzNetworking::StringifySerializer clientValues;
GetNetBindComponent()->SerializeEntityCorrection(clientValues);
// Restore server state
AzNetworking::NetworkOutputSerializer serverStateSerializer(correction.GetBuffer(), correction.GetSize());
GetNetBindComponent()->SerializeEntityCorrection(serverStateSerializer);
// Read out state values
AzNetworking::StringifySerializer serverValues;
GetNetBindComponent()->SerializeEntityCorrection(serverValues);
AZStd::map<AZStd::string, AZStd::pair<AZStd::string, AZStd::string>> mapComparison;
// put the server value in the first part of the pair
for (const auto& pair : serverValues.GetValueMap())
{
mapComparison[pair.first].first = pair.second;
}
// put the client value in the second part of the pair
for (const auto& pair : clientValues.GetValueMap())
{
mapComparison[pair.first].second = pair.second;
}
bool firstIt = true;
for (const auto& mapPair : mapComparison)
{
if (mapPair.second.first != mapPair.second.second)
{
if (!firstIt)
{
clientStateString += ",";
serverStateString += ",";
}
firstIt = false;
AZStd::string clientValue = mapPair.second.second.empty() ? "<no value>" : mapPair.second.second;
AZStd::string serverValue = mapPair.second.first.empty() ? "<no value>" : mapPair.second.first;
clientStateString += mapPair.first + "=" + clientValue;
serverStateString += mapPair.first + "=" + serverValue;
}
}
}
else
{
clientStateString = "available in debug only";
serverStateString = "available in debug only";
}
AZLOG_ERROR("** Autonomous proxy desync detected! ** clientState=[%s], serverState=[%s]", clientStateString.c_str(), serverStateString.c_str());
#endif
}
}
}
@@ -331,7 +303,7 @@ namespace Multiplayer
void LocalPredictionPlayerInputComponentController::HandleSendClientInputCorrection
(
AzNetworking::IConnection* invokingConnection,
[[maybe_unused]] AzNetworking::IConnection* invokingConnection,
const Multiplayer::ClientInputId& inputId,
const AzNetworking::PacketEncodingBuffer& correction
)
@@ -356,6 +328,25 @@ namespace Multiplayer
GetNetBindComponent()->SerializeEntityCorrection(serializer);
m_correctionEvent.Signal();
#ifndef AZ_RELEASE_BUILD
if (cl_EnableDesyncDebugging)
{
AZLOG_INFO("** Autonomous Desync - Corrected clientInputId=%d ", aznumeric_cast<int32_t>(inputId));
auto iter = m_predictiveStateHistory.find(inputId);
if (iter != m_predictiveStateHistory.end())
{
// Read out state values
AzNetworking::StringifySerializer serverValues;
GetNetBindComponent()->SerializeEntityCorrection(serverValues);
PrintCorrectionDifferences(*iter->second, serverValues);
}
else
{
AZLOG_INFO("Received correction that is too old to diff, increase cl_PredictiveStateHistorySize");
}
}
#endif
AZLOG
(
NET_Prediction,
@@ -370,29 +361,13 @@ namespace Multiplayer
// If this correction is for a move outside our input history window, just start replaying from the oldest move we have available
const uint32_t startReplayIndex = (inputHistorySize > historicalDelta) ? (inputHistorySize - historicalDelta) : 0;
// Flag that we are replaying inputs
struct ScopedReplayingInput
{
ScopedReplayingInput(LocalPredictionPlayerInputComponentController* instance)
: m_instance(instance)
{
m_instance->m_replayingInput = true;
}
~ScopedReplayingInput()
{
m_instance->m_replayingInput = false;
}
LocalPredictionPlayerInputComponentController* m_instance;
};
ScopedReplayingInput markReplayingInput(this);
const float clientInputRateSec = static_cast<float>(static_cast<AZ::TimeMs>(cl_InputRateMs)) / 1000.0;
for (uint32_t replayIndex = startReplayIndex; replayIndex < inputHistorySize; ++replayIndex)
{
// Reprocess the input for this frame
NetworkInput& input = m_inputHistory[replayIndex];
ScopedAlterTime scopedTime(input.GetHostFrameId(), input.GetHostTimeMs(), invokingConnection->GetConnectionId());
GetNetBindComponent()->ProcessInput(input, clientInputRateSec);
GetNetBindComponent()->ReprocessInput(input, clientInputRateSec);
AZLOG
(
@@ -405,11 +380,6 @@ namespace Multiplayer
}
}
bool LocalPredictionPlayerInputComponentController::IsReplayingInput() const
{
return m_replayingInput;
}
bool LocalPredictionPlayerInputComponentController::IsMigrating() const
{
return m_lastMigratedInputId != ClientInputId{ 0 };
@@ -519,17 +489,6 @@ namespace Multiplayer
AzNetworking::HashSerializer hashSerializer;
GetNetBindComponent()->SerializeEntityCorrection(hashSerializer);
// In debug, send the entire client output state to the server to make it easier to debug desync issues
AzNetworking::PacketEncodingBuffer processInputResult;
#ifndef AZ_RELEASE_BUILD
if (cl_EnableDesyncDebugging)
{
AzNetworking::NetworkInputSerializer processInputResultSerializer(processInputResult.GetBuffer(), processInputResult.GetCapacity());
GetNetBindComponent()->SerializeEntityCorrection(processInputResultSerializer);
processInputResult.Resize(processInputResultSerializer.GetSize());
}
#endif
// Save this input and discard move history outside our client rewind window
m_inputHistory.PushBack(input);
while (m_inputHistory.Size() > maxClientInputs)
@@ -548,10 +507,23 @@ namespace Multiplayer
inputArray[i] = m_inputHistory[historyIndex];
}
#ifndef AZ_RELEASE_BUILD
if (cl_EnableDesyncDebugging)
{
StateHistoryItem inputHistory = AZStd::make_unique<AzNetworking::StringifySerializer>();
while (m_predictiveStateHistory.size() > cl_PredictiveStateHistorySize)
{
m_predictiveStateHistory.erase(m_predictiveStateHistory.begin());
}
GetNetBindComponent()->SerializeEntityCorrection(*inputHistory);
m_predictiveStateHistory.emplace(m_clientInputId, AZStd::move(inputHistory));
}
#endif
// Send the input to server (only when we are not migrating)
if (!IsMigrating())
{
SendClientInput(inputArray, hashSerializer.GetHash(), processInputResult);
SendClientInput(inputArray, hashSerializer.GetHash());
}
}
}
Gems/Multiplayer/Code/Source/Components/NetBindComponent.cpp
+15
View File
@@ -267,6 +267,11 @@ namespace Multiplayer
return m_isProcessingInput;
}
bool NetBindComponent::IsReprocessingInput() const
{
return m_isReprocessingInput;
}
void NetBindComponent::CreateInput(NetworkInput& networkInput, float deltaTime)
{
// Only autonomous or authority runs this logic
@@ -279,12 +284,21 @@ namespace Multiplayer
void NetBindComponent::ProcessInput(NetworkInput& networkInput, float deltaTime)
{
m_isProcessingInput = true;
// Only autonomous and authority runs this logic
AZ_Assert((NetworkRoleHasController(m_netEntityRole)), "Incorrect network role for input processing");
for (MultiplayerComponent* multiplayerComponent : m_multiplayerInputComponentVector)
{
multiplayerComponent->GetController()->ProcessInput(networkInput, deltaTime);
}
m_isProcessingInput = false;
}
void NetBindComponent::ReprocessInput(NetworkInput& networkInput, float deltaTime)
{
m_isReprocessingInput = true;
ProcessInput(networkInput, deltaTime);
m_isReprocessingInput = false;
}
bool NetBindComponent::HandleRpcMessage(AzNetworking::IConnection* invokingConnection, NetEntityRole remoteRole, NetworkEntityRpcMessage& message)
@@ -649,6 +663,7 @@ namespace Multiplayer
MultiplayerComponent* multiplayerComponent = azrtti_cast<MultiplayerComponent*>(component);
if (multiplayerComponent != nullptr)
{
multiplayerComponent->SetOwningConnectionId(m_owningConnectionId);
m_multiplayerInputComponentVector.push_back(multiplayerComponent);
}
}
Gems/Multiplayer/Code/Source/MultiplayerSystemComponent.cpp
+2 -2
View File
@@ -554,7 +554,7 @@ namespace Multiplayer
m_tickFactor = 0.0f;
m_lastReplicatedHostTimeMs = packet.GetHostTimeMs();
m_lastReplicatedHostFrameId = packet.GetHostFrameId();
m_networkTime.AlterTime(m_lastReplicatedHostFrameId, m_lastReplicatedHostTimeMs, AzNetworking::InvalidConnectionId);
m_networkTime.ForceSetTime(m_lastReplicatedHostFrameId, m_lastReplicatedHostTimeMs);
}
for (AZStd::size_t i = 0; i < packet.GetEntityMessages().size(); ++i)
@@ -856,7 +856,7 @@ namespace Multiplayer
{
m_tickFactor += deltaTime / serverRateSeconds;
// Linear close to the origin, but asymptote at y = 1
const float renderBlendFactor = AZStd::clamp(1.0f - (std::pow(cl_renderTickBlendBase, m_tickFactor)), 0.0f, 1.0f);
const float renderBlendFactor = AZStd::clamp(1.0f - (std::pow(cl_renderTickBlendBase, m_tickFactor)), 0.0f, m_tickFactor);
AZLOG
(
NET_Blending,
Gems/Multiplayer/Code/Source/NetworkEntity/EntityReplication/EntityReplicationManager.cpp
+11 -3
View File
@@ -524,6 +524,7 @@ namespace Multiplayer
bool EntityReplicationManager::HandlePropertyChangeMessage
(
AzNetworking::IConnection* invokingConnection,
EntityReplicator* entityReplicator,
AzNetworking::PacketId packetId,
NetEntityId netEntityId,
@@ -558,6 +559,12 @@ namespace Multiplayer
NetBindComponent* netBindComponent = replicatorEntity.GetNetBindComponent();
AZ_Assert(netBindComponent != nullptr, "No NetBindComponent");
if (createEntity)
{
// Always set our invoking connectionId for any newly created entities, since this connection now 'owns' them from a rewind perspective
netBindComponent->SetOwningConnectionId(invokingConnection->GetConnectionId());
}
const bool changeNetworkRole = (netBindComponent->GetNetEntityRole() != localNetworkRole);
if (changeNetworkRole)
{
@@ -744,7 +751,7 @@ namespace Multiplayer
bool EntityReplicationManager::HandleEntityUpdateMessage
(
[[maybe_unused]] AzNetworking::IConnection* invokingConnection,
AzNetworking::IConnection* invokingConnection,
const AzNetworking::IPacketHeader& packetHeader,
const NetworkEntityUpdateMessage& updateMessage
)
@@ -794,7 +801,7 @@ namespace Multiplayer
}
// This may implicitly create a replicator for us
bool handled = HandlePropertyChangeMessage(entityReplicator, packetHeader.GetPacketId(), updateMessage.GetEntityId(), updateMessage.GetNetworkRole(), outputSerializer, prefabEntityId);
bool handled = HandlePropertyChangeMessage(invokingConnection, entityReplicator, packetHeader.GetPacketId(), updateMessage.GetEntityId(), updateMessage.GetNetworkRole(), outputSerializer, prefabEntityId);
AZ_Assert(handled, "Failed to handle NetworkEntityUpdateMessage message");
return handled;
@@ -1121,7 +1128,7 @@ namespace Multiplayer
}
}
bool EntityReplicationManager::HandleEntityMigration([[maybe_unused]] AzNetworking::IConnection* invokingConnection, EntityMigrationMessage& message)
bool EntityReplicationManager::HandleEntityMigration(AzNetworking::IConnection* invokingConnection, EntityMigrationMessage& message)
{
EntityReplicator* replicator = GetEntityReplicator(message.m_entityId);
{
@@ -1130,6 +1137,7 @@ namespace Multiplayer
AzNetworking::TrackChangedSerializer<AzNetworking::NetworkOutputSerializer> outputSerializer(message.m_propertyUpdateData.GetBuffer(), message.m_propertyUpdateData.GetSize());
if (!HandlePropertyChangeMessage
(
invokingConnection,
replicator,
AzNetworking::InvalidPacketId,
message.m_entityId,
Gems/Multiplayer/Code/Source/NetworkEntity/EntityReplication/EntityReplicationManager.h
+1
View File
@@ -136,6 +136,7 @@ namespace Multiplayer
bool HandlePropertyChangeMessage
(
AzNetworking::IConnection* invokingConnection,
EntityReplicator* entityReplicator,
AzNetworking::PacketId packetId,
NetEntityId netEntityId,
Gems/Multiplayer/Code/Source/NetworkTime/NetworkTime.cpp
+9
View File
@@ -65,6 +65,15 @@ namespace Multiplayer
return (IsTimeRewound() && (rewindConnectionId == m_rewindingConnectionId)) ? m_unalteredFrameId : m_hostFrameId;
}
void NetworkTime::ForceSetTime(HostFrameId frameId, AZ::TimeMs timeMs)
{
AZ_Assert(!IsTimeRewound(), "Forcibly setting network time is unsupported under a rewound time scope");
m_unalteredFrameId = frameId;
m_hostFrameId = frameId;
m_hostTimeMs = timeMs;
m_rewindingConnectionId = AzNetworking::InvalidConnectionId;
}
void NetworkTime::AlterTime(HostFrameId frameId, AZ::TimeMs timeMs, AzNetworking::ConnectionId rewindConnectionId)
{
m_hostFrameId = frameId;
Gems/Multiplayer/Code/Source/NetworkTime/NetworkTime.h
+1
View File
@@ -32,6 +32,7 @@ namespace Multiplayer
AZ::TimeMs GetHostTimeMs() const override;
AzNetworking::ConnectionId GetRewindingConnectionId() const override;
HostFrameId GetHostFrameIdForRewindingConnection(AzNetworking::ConnectionId rewindConnectionId) const override;
void ForceSetTime(HostFrameId frameId, AZ::TimeMs timeMs) override;
void AlterTime(HostFrameId frameId, AZ::TimeMs timeMs, AzNetworking::ConnectionId rewindConnectionId) override;
void SyncEntitiesToRewindState(const AZ::Aabb& rewindVolume) override;
void ClearRewoundEntities() override;