Rework of party member quest progresion PR #769

Definitely is not compatible with 1.8.0 servers.

The community loves Members being able to advance quests (instead of only Party Leader), but it introduced a bunch of problems with duplicate quest triggers. This rework deals with it (hopefully).

The most fundamental problem is that ScopedQuestOverride() doesn't work, because quest progress is executed on a different thread; the ScopedQuestOverride() is destructed before the quest OnEvent...() routines are invoked. So all the Members send their updates to the server even when told not to. The server just ignored them all before, but now with Member quest progression enabled, it ends up causing replicated quest updates. Some quests ignore it, many break.

The engine is in control of the content of events passed to the OnEvent routines. I could not find a reliable way to pass any context to the OnEvent routines through that barrier (it runs async, so matching up was nigh-on impossible). So ended up implementing a dedup history server-side, where there is enough context to figure this out.

The worst-case flow (when a Member triggers progress), is:
1) Member sends update.
2) Update is forwarded to Leader, only.
3) Leader OnEvent hooks send the Leader update to the server.
4) Leader SendsToParty
5) Party members reflect the updates to the Server, but are dropped by the dedup history because the Leader has already sent it.
6) Entries in the dedup history time out in seconds (needs some tuning), so quests can rewind and stages can be triggered multiple times to evaluate.

Merged with old duplicate quest stage "fix"

Author: rfortier

Code/client/Games/Skyrim/Forms/TESQuest.cpp

@@ -90,16 +90,14 @@ bool TESQuest::EnsureQuestStarted(bool& success, bool force)
 
 bool TESQuest::SetStage(uint16_t newStage)
 {
-    ScopedQuestOverride _;
-
     TP_THIS_FUNCTION(TSetStage, bool, TESQuest, uint16_t);
     POINTER_SKYRIMSE(TSetStage, SetStage, 25004);
     return SetStage(this, newStage);
 }
 
-void TESQuest::ScriptSetStage(uint16_t stageIndex)
+void TESQuest::ScriptSetStage(uint16_t stageIndex, bool bForce)
 {
-    if (currentStage == stageIndex || IsStageDone(stageIndex))
+    if ((currentStage == stageIndex || IsStageDone(stageIndex)) && !bForce) // Not clear this should be suppressed now that server dedups
         return;
 
     using Quest = TESQuest;

Code/client/Games/Skyrim/Forms/TESQuest.h

@@ -127,7 +127,7 @@ struct TESQuest : BGSStoryManagerTreeForm
     bool EnsureQuestStarted(bool& succeded, bool force);
 
     bool SetStage(uint16_t stage);
-    void ScriptSetStage(uint16_t stage);
+    void ScriptSetStage(uint16_t stage, bool bForce = false);
     void SetStopped();
 };
 

Code/client/Services/Debug/Views/QuestDebugView.cpp

@@ -61,7 +61,7 @@ void DebugService::DrawQuestDebugView()
                     sprintf_s(setStage, std::size(setStage), "Set stage (%d)", pStage->stageIndex);
 
                     if (ImGui::Button(setStage))
-                        pQuest->ScriptSetStage(pStage->stageIndex);
+                        pQuest->ScriptSetStage(pStage->stageIndex, true);
                 }
             }
 

Code/client/Services/Generic/QuestService.cpp

@@ -57,8 +57,6 @@ BSTEventResult QuestService::OnEvent(const TESQuestStartStopEvent* apEvent, cons
     if (ScopedQuestOverride::IsOverriden() || !m_world.Get().GetPartyService().IsInParty())
         return BSTEventResult::kOk;
 
-    spdlog::info("Quest start/stop event: {:X}", apEvent->formId);
-
     if (TESQuest* pQuest = Cast<TESQuest>(TESForm::GetById(apEvent->formId)))
     {
         if (IsNonSyncableQuest(pQuest))
@@ -72,15 +70,21 @@ BSTEventResult QuestService::OnEvent(const TESQuestStartStopEvent* apEvent, cons
             auto& modSys = m_world.GetModSystem();
             if (modSys.GetServerModId(pQuest->formID, Id))
             {
-                spdlog::info(__FUNCTION__ ": queuing type none/misc quest gameId {:X} questStage {} questStatus {} questType {} formId {:X} name {}",
-                             Id.LogFormat(),  pQuest->currentStage, pQuest->IsStopped() ? RequestQuestUpdate::Stopped : RequestQuestUpdate::Started,
-                             static_cast<std::underlying_type_t<TESQuest::Type>>(pQuest->type), 
-                             pQuest->formID, pQuest->fullName.value.AsAscii());
+                spdlog::info(__FUNCTION__ ": queuing type none/misc quest {} gameId {:X} questStage {} questType {} formId {:X} name {}",
+                             pQuest->IsStopped() ? "stop" : "start", Id.LogFormat(), pQuest->currentStage,  
+                             static_cast<std::underlying_type_t<TESQuest::Type>>(pQuest->type), pQuest->formID, pQuest->fullName.value.AsAscii());
             }
         }
-        
-        m_world.GetRunner().Queue(
-            [&, formId = pQuest->formID, stageId = pQuest->currentStage, stopped = pQuest->IsStopped(), type = pQuest->type]()
+
+        spdlog::info(__FUNCTION__ ":  quest {} formId: {:X}, questStage: {}, questType: {}, name: {}",
+                     pQuest->IsStopped() ? "stopped" : "started", 
+                     pQuest->formID,
+                     pQuest->currentStage, 
+                     static_cast<std::underlying_type_t<TESQuest::Type>>(pQuest->type),
+                     pQuest->fullName.value.AsAscii());
+
+        m_world.GetRunner().Queue([&, formId = pQuest->formID, stageId = pQuest->currentStage,
+                                   stopped = pQuest->IsStopped(), type = pQuest->type]()
             {
                 GameId Id;
                 auto& modSys = m_world.GetModSystem();
@@ -91,7 +95,6 @@ BSTEventResult QuestService::OnEvent(const TESQuestStartStopEvent* apEvent, cons
                     update.Stage = stageId;
                     update.Status = stopped ? RequestQuestUpdate::Stopped : RequestQuestUpdate::Started;
                     update.ClientQuestType = static_cast<std::underlying_type_t<TESQuest::Type>>(type); 
-
                     m_world.GetTransport().Send(update);
                 }
             });
@@ -105,9 +108,6 @@ BSTEventResult QuestService::OnEvent(const TESQuestStageEvent* apEvent, const Ev
     if (ScopedQuestOverride::IsOverriden() || !m_world.Get().GetPartyService().IsInParty())
         return BSTEventResult::kOk;
 
-    spdlog::info("Quest stage event: {:X}, stage: {}", apEvent->formId, apEvent->stageId);
-
-    // there is no reason to even fetch the quest object, since the event provides everything already....
     if (TESQuest* pQuest = Cast<TESQuest>(TESForm::GetById(apEvent->formId)))
     {
         if (IsNonSyncableQuest(pQuest))
@@ -121,14 +121,15 @@ BSTEventResult QuestService::OnEvent(const TESQuestStageEvent* apEvent, const Ev
             auto& modSys = m_world.GetModSystem();
             if (modSys.GetServerModId(pQuest->formID, Id))
             {
-                spdlog::info(__FUNCTION__ ": queuing type none/misc quest gameId {:X} questStage {} questStatus {} questType {} formId {:X} name {}",
-                             Id.LogFormat(), pQuest->currentStage,
-                             RequestQuestUpdate::StageUpdate,
-                             static_cast<std::underlying_type_t<TESQuest::Type>>(pQuest->type),
+                spdlog::info(__FUNCTION__ ": queuing type none/misc quest update gameId {:X} questStage {} questType {} formId {:X} name {}",
+                             Id.LogFormat(), pQuest->currentStage, static_cast<std::underlying_type_t<TESQuest::Type>>(pQuest->type),
                              pQuest->formID, pQuest->fullName.value.AsAscii());
             }
         }
 
+        spdlog::info(__FUNCTION__ ":  quest updated formId: {:X}, questStage: {}, questType: {}, name: {}",
+                     pQuest->formID, pQuest->currentStage, static_cast<std::underlying_type_t<TESQuest::Type>>(pQuest->type), pQuest->fullName.value.AsAscii());
+
         m_world.GetRunner().Queue(
             [&, formId = apEvent->formId, stageId = apEvent->stageId, type = pQuest->type]()
             {
@@ -141,7 +142,6 @@ BSTEventResult QuestService::OnEvent(const TESQuestStageEvent* apEvent, const Ev
                     update.Stage = stageId;
                     update.Status = RequestQuestUpdate::StageUpdate;
                     update.ClientQuestType = static_cast<std::underlying_type_t<TESQuest::Type>>(type);
-
                     m_world.GetTransport().Send(update);
                 }
             });
@@ -157,7 +157,7 @@ void QuestService::OnQuestUpdate(const NotifyQuestUpdate& aUpdate) noexcept
     TESQuest* pQuest = Cast<TESQuest>(TESForm::GetById(formId));
     if (!pQuest)
     {
-        spdlog::error("Failed to find quest, base id: {:X}, mod id: {:X}", aUpdate.Id.BaseId, aUpdate.Id.ModId);
+        spdlog::error(__FUNCTION__ ": failed to find quest, gameId: {:X}, stage: {}", aUpdate.Id.LogFormat(), aUpdate.Stage);
         return;
     }
 
@@ -169,39 +169,64 @@ void QuestService::OnQuestUpdate(const NotifyQuestUpdate& aUpdate) noexcept
     }
 
     bool bResult = false;
+    bool bRunning = pQuest->getState() == TESQuest::State::Running;
     switch (aUpdate.Status)
     {
     case NotifyQuestUpdate::Started:
-    {
-        pQuest->ScriptSetStage(aUpdate.Stage);
-        pQuest->SetActive(true);
+        if (bRunning)
+        {
+            spdlog::info(__FUNCTION__ ": suppressing duplicate quest start gameId: {:X}, questStage: {}, questStatus: {}, questType: {}, formId: {:X}, name: {}",
+                         aUpdate.Id.LogFormat(), aUpdate.Stage, aUpdate.Status, aUpdate.ClientQuestType, formId, pQuest->fullName.value.AsAscii());
+        }
+        else
+        {
+            spdlog::info(__FUNCTION__ ":  quest started remotely gameId: {:X}, questStage: {}, questStatus: {}, questType: {}, formId: {:X}, name: {}",
+                         aUpdate.Id.LogFormat(), aUpdate.Stage, aUpdate.Status, aUpdate.ClientQuestType, formId, pQuest->fullName.value.AsAscii());
+            pQuest->ScriptSetStage(aUpdate.Stage);
+            pQuest->SetActive(true);
+        }
         bResult = true;
         spdlog::info("Remote quest started: {:X}, stage: {}", formId, aUpdate.Stage);
         break;
-    }
+
     case NotifyQuestUpdate::StageUpdate:
+        spdlog::info(__FUNCTION__ ":  quest updated remotely gameId: {:X}, questStage: {}, questStatus: {}, questType: {}, formId: {:X}, name: {}",
+                     aUpdate.Id.LogFormat(), aUpdate.Stage, aUpdate.Status, aUpdate.ClientQuestType, formId, pQuest->fullName.value.AsAscii());
+
         pQuest->ScriptSetStage(aUpdate.Stage);
         bResult = true;
-        spdlog::info("Remote quest updated: {:X}, stage: {}", formId, aUpdate.Stage);
         break;
+
     case NotifyQuestUpdate::Stopped:
+        spdlog::info(__FUNCTION__ ":  quest stopped remotely gameId: {:X}, questStage: {}, questStatus: {}, questType: {}, formId: {:X}, name: {}",
+                     aUpdate.Id.LogFormat(), aUpdate.Stage, aUpdate.Status, aUpdate.ClientQuestType, formId, pQuest->fullName.value.AsAscii());
         bResult = StopQuest(formId);
-        spdlog::info("Remote quest stopped: {:X}, stage: {}", formId, aUpdate.Stage);
         break;
+ 
     default: break;
     }
 
     if (!bResult)
-        spdlog::error("Failed to update the client quest state, quest: {:X}, stage: {}, status: {}", formId, aUpdate.Stage, aUpdate.Status);
+        spdlog::error(__FUNCTION__ ": failed to update the client quest state gameId: {:X}, questStage: {}, questStatus: {}, questType: {}, formId: {:X}, name: {}",
+                      aUpdate.Id.LogFormat(), aUpdate.Stage, aUpdate.Status, aUpdate.ClientQuestType, formId, pQuest->fullName.value.AsAscii());
 }
 
 bool QuestService::StopQuest(uint32_t aformId)
 {
     TESQuest* pQuest = Cast<TESQuest>(TESForm::GetById(aformId));
     if (pQuest)
     {
-        pQuest->SetActive(false);
-        pQuest->SetStopped();
+        if (pQuest->getState() == TESQuest::State::Stopped) // Supress duplicate or loopback quest stop
+        {
+            spdlog::info(__FUNCTION__ ": suppressing duplicate quest stop formId: {:X}, questStage: {}, questFlags: {:X}, questType: {}, formId: {:X}, name: {}",
+                         aformId, pQuest->currentStage, static_cast<uint8_t>(pQuest->flags), static_cast<uint16_t>(pQuest->type), aformId, pQuest->fullName.value.AsAscii());
+        }
+        else
+        {
+            pQuest->SetActive(false);
+            pQuest->SetStopped();
+        }
+
         return true;
     }
 

Code/server/Game/Player.h

@@ -1,5 +1,64 @@
 #pragma once
 
+/*  With the introduction of party member (not just leader) quest progression, there are a few challenges:
+    SendToParty() will cause reflections of the same quest updates from all party members.
+    This is because ScopedQuestOverride() doesn't work as intended because QuestServic::OnEvent calls
+    happen later on a different thread. We need to prevent these reflections from sending out dups.
+
+    We want the quest progress to be sent out by the Leader. It has already happened for one Member when
+    members advance the quest and it is theoretically possible more than one sends progress, so SendToParty
+    needs to not send to those who already have it.
+
+    Since we have to track this anyway, if a Member advances quest, we forward it to the Leader for broadcast.
+    This means Leader gets the update in QuestService::OnUpdate(), and when the Leader update reflects back, the
+    Leader does SendToParty() (with the original Member and the Leadre in the cache, so SendToParty doesn't send
+    to them). This enables the Leader to make a centralized decision; it can reject sending out a member update
+    that shouldn't be forwarded; it looks like there are a couple of exceptions like that.
+*/
+struct QuestStageDedupHistory
+{
+    static constexpr std::chrono::seconds timeout{30s};
+
+    using QuestId = GameId;
+    using QuestStage = uint16_t;
+    using PlayerId = uint32_t;
+    using TimeStamp = std::chrono::time_point<std::chrono::steady_clock>;
+
+    struct Entry
+    {
+        QuestId questId{};
+        QuestStage questStage{};
+        PlayerId playerId{};
+        TimeStamp timestamp{};
+    };
+
+    using Container = std::deque<Entry>;
+    using iterator = Container::iterator;
+    using const_iterator = Container::const_iterator;
+
+    void Add(QuestId aQuestId, QuestStage aQuestStage, PlayerId aPlayerId,
+             TimeStamp aTimeStamp = std::chrono::steady_clock::now());
+
+    const_iterator FindStage(const QuestId& aQuestId, const QuestStage& aQuestStage);
+    const_iterator FindStageWPlayerId(const QuestId& aQuestId, const QuestStage& aQuestStage, const PlayerId& aPlayerId);
+
+    void Reset() noexcept { m_Cache.clear(); }
+    bool FoundStage(const QuestId& aQuestId, const QuestStage& aQuestStage)
+    {
+        return FindStage(aQuestId, aQuestStage) != m_Cache.end();
+    }
+    bool FoundStageWPlayerId(const QuestId& aQuestId, const QuestStage& aQuestStage, const PlayerId& aPlayerId)
+    {
+        return FindStageWPlayerId(aQuestId, aQuestStage, aPlayerId) != m_Cache.end();
+    }
+
+  private:
+    void inline Expire();
+    Container m_Cache; // Short, time-ordered, duplicates valid (do they ever happen?)
+};
+
+
+
 struct ServerMessage;
 struct Player
 {
@@ -40,6 +99,9 @@ struct Player
     void SetCellComponent(const CellIdComponent& aCellComponent) noexcept;
 
     void Send(const ServerMessage& acServerMessage) const;
+    QuestStageDedupHistory m_questStageDedupHistory;
+    QuestStageDedupHistory& GetQuestStageDedupHistory() { return m_questStageDedupHistory; }
+
 
 private:
     uint32_t m_id{0};

Code/server/GameServer.cpp

@@ -1,4 +1,4 @@
-#include <Components.h>
+#include <Components.h>
 #include <GameServer.h>
 #include <Packet.hpp>
 
@@ -601,6 +601,7 @@ void GameServer::OnDisconnection(const ConnectionId_t aConnectionId, EDisconnect
     m_adminSessions.erase(aConnectionId);
 
     auto* pPlayer = m_pWorld->GetPlayerManager().GetByConnectionId(aConnectionId);
+    pPlayer->GetQuestStageDedupHistory().Reset();
 
     spdlog::info("Connection ended {:x} - '{}' disconnected", aConnectionId, (pPlayer != NULL ? pPlayer->GetUsername().c_str() : "NULL"));
 
@@ -732,6 +733,23 @@ bool GameServer::SendToPlayersInRange(const ServerMessage& acServerMessage, cons
     return true;
 }
 
+void GameServer::SendToLeader(const ServerMessage& acServerMessage, const PartyComponent& acPartyComponent, const Player* apLeader) const
+{
+    if (!acPartyComponent.JoinedPartyId.has_value())
+    {
+        spdlog::warn("Party does not exist, canceling broadcast.");
+        return;
+    }
+
+    if (const_cast<Player*>(apLeader)->GetParty().JoinedPartyId != acPartyComponent.JoinedPartyId)
+    {
+        spdlog::warn("Specified party leader belongs to different party? Canceling send");
+        return;
+    }
+
+    apLeader->Send(acServerMessage);
+}
+
 void GameServer::SendToParty(const ServerMessage& acServerMessage, const PartyComponent& acPartyComponent, const Player* apExcludeSender) const
 {
     if (!acPartyComponent.JoinedPartyId.has_value())

Code/server/GameServer.h

@@ -59,6 +59,7 @@ struct GameServer final : Server
     void SendToLoaded(const ServerMessage& acServerMessage) const;
     void SendToPlayers(const ServerMessage& acServerMessage, const Player* apExcludeSender = nullptr) const;
     bool SendToPlayersInRange(const ServerMessage& acServerMessage, const entt::entity acOrigin, const Player* apExcludeSender = nullptr) const;
+    void SendToLeader(const ServerMessage& acServerMessage, const PartyComponent& acPartyComponent, const Player* apLeader) const;
     void SendToParty(const ServerMessage& acServerMessage, const PartyComponent& acPartyComponent, const Player* apExcludeSender = nullptr) const;
     void SendToPartyInRange(const ServerMessage& acServerMessage, const PartyComponent& acPartyComponent, const entt::entity acOrigin, const Player* apExcludeSender = nullptr) const;
 

Code/server/Services/PartyService.cpp

@@ -130,6 +130,7 @@ void PartyService::OnPartyCreate(const PacketEvent<PartyCreateRequest>& acPacket
                 {
                     party.Members.push_back(otherPlayer);
                     otherPlayer->GetParty().JoinedPartyId = partyId;
+                    otherPlayer->GetQuestStageDedupHistory().Reset();
 
                     SendPartyJoinedEvent(party, otherPlayer);
                 }