From b45b63033faa617145945c66f742ec75f38b7d42 Mon Sep 17 00:00:00 2001 From: Richard Fortier Date: Wed, 4 Feb 2026 20:12:47 -0500 Subject: [PATCH 1/5] Several dialog & subtitle improvements in the way Scenes / Cutscenes work in a party. If the cutscene design is that all party members (or all inrange) play the scene, the Leader's dialog actions would step on and cancel the copies running in the party members. This would mess up the scene phase timing, causing the members to race ahead and abort actions of the Leader, potentially hanging the scene. Found with the Finn/Carbos scene in Enderal. If the cutscene design is only the person(s) who trigger the scene play the scene, and the scene is triggered by a non-Leader, no one except the scene-initiator got any dialog. This is an uncommon case; usually the start of a scene triggers a quest stage change that brings everyone into the scene, or the scene is just random encounter / idle chatter that is just fine to sync to just the triggering player. Because scenes that don't trigger quest stage changes but also would be desirable to sync are rare, and because there is no good way to distinguish them from scenes where syncing the audio will cause dialog cancels and timing problems, this case is left as unsolved, have to live with it. There is some logic to trigger scenes in the rest of the party when one starts the scene. This solves some cases. In others, there are scene start conditions that just stop the scene again. Best known example is the Companions Brotherhood quest stage C02. Unless the entire party stands on the tiny hotspot where the initiator triggers the scene, it just stops again. It's not perfect, but the selected (surviving experiment) solution is: 1) Try to trigger the scene for the entire party, which often works. 2) Each party member plays the scene to themselves, generally with decent audio sync. The party Leader is still controlling the NPCs and motion / animation sync handles most cases. 3) If the scene triggers TaskDialogues (those NPC dialogues where you answer with a menu pick), that dialog is individual to the SceneMaster (they who triggered), so that is synced to party (PlayersInRange). 4) Only flaw known is AI packages. Subtitle sync follows the same rules as Dialogue sync. AI package handling is left for a future iteration, since it also is tricky. Current state: AI packages only run on Leader, so if Member triggers a scene, the AI packages doesn't run. If it is anything of consequence (more than "look at player", say, having to do something and then interact with player), the scene will get stuck and Leader will have to take over. If Leader is close, NPC will just switch to Leader. If farther away or not in scene, Leader will have to get closer, possibly having to unlock the Leader with the EPC (EnablePlayerControls) console command. For the next round, the two big options I see for fixing AI is for 1. SceneMaster to take ownership of NPCs in-scene. They can be released at end of scene, or just wait for a cell change. 2. Find a way to reactivate AI on "remote" NPCs for the duration of the scene, This sounds more fragile. --- Code/client/Games/Misc/SubtitleManager.cpp | 5 +- Code/client/Games/Skyrim/Actor.cpp | 73 ++++++-- Code/client/Games/Skyrim/Actor.h | 14 +- Code/client/Games/Skyrim/Forms/TESQuest.h | 13 ++ Code/client/Games/Skyrim/TESObjectREFR.h | 3 +- .../Services/Generic/CharacterService.cpp | 169 +++++++++++++++--- 6 files changed, 233 insertions(+), 44 deletions(-) diff --git a/Code/client/Games/Misc/SubtitleManager.cpp b/Code/client/Games/Misc/SubtitleManager.cpp index 309152641..ca5cc3a58 100644 --- a/Code/client/Games/Misc/SubtitleManager.cpp +++ b/Code/client/Games/Misc/SubtitleManager.cpp @@ -4,6 +4,7 @@ #include #include +#include #include #include @@ -31,10 +32,8 @@ void* SubtitleManager::HideSubtitle(TESObjectREFR* apSpeaker) noexcept void TP_MAKE_THISCALL(HookShowSubtitle, SubtitleManager, TESObjectREFR* apSpeaker, const char* apSubtitleText, bool aIsInDialogue) { - // spdlog::debug("Subtitle for actor {:X} (bool {}):\n\t{}", apSpeaker ? apSpeaker->formID : 0, aIsInDialogue, apSubtitleText); - Actor* pActor = Cast(apSpeaker); - if (apSubtitleText && pActor && pActor->GetExtension()->IsLocal() && !pActor->GetExtension()->IsPlayer()) + if (apSubtitleText && std::strlen(apSubtitleText) && pActor && !pActor->GetExtension()->IsPlayer()) World::Get().GetRunner().Trigger(SubtitleEvent(apSpeaker->formID, apSubtitleText)); TiltedPhoques::ThisCall(RealShowSubtitle, apThis, apSpeaker, apSubtitleText, aIsInDialogue); diff --git a/Code/client/Games/Skyrim/Actor.cpp b/Code/client/Games/Skyrim/Actor.cpp index 931c2bdf1..453bacd59 100644 --- a/Code/client/Games/Skyrim/Actor.cpp +++ b/Code/client/Games/Skyrim/Actor.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include @@ -55,6 +56,8 @@ #include +#include + #ifdef SAVE_STUFF #include @@ -1189,7 +1192,7 @@ uint64_t TP_MAKE_THISCALL(HookProcessResponse, void, DialogueItem* apVoice, Acto if (apTalkingActor) { if (apTalkingActor->GetExtension()->IsRemotePlayer()) - return 0; + return 0; } return TiltedPhoques::ThisCall(RealProcessResponse, apThis, apVoice, apTalkingActor, apTalkedToActor); } @@ -1210,32 +1213,82 @@ void TP_MAKE_THISCALL(HookUnequipObject, Actor, void* apUnk1, TESBoundObject* ap TiltedPhoques::ThisCall(RealUnequipObject, apThis, apUnk1, apObject, aUnk2, apUnk3); } -TP_THIS_FUNCTION(TSpeakSoundFunction, bool, Actor, const char* apName, uint32_t* a3, uint32_t a4, uint32_t a5, uint32_t a6, uint64_t a7, uint64_t a8, uint64_t a9, bool a10, uint64_t a11, bool a12, bool a13, bool a14); +TP_THIS_FUNCTION(TSpeakSoundFunction, float, Actor, const char* apName, uint32_t* a3, uint32_t a4, uint32_t a5, uint32_t a6, uint64_t a7, uint64_t a8, uint64_t a9, bool a10, uint64_t a11, bool a12, bool a13, bool a14); static TSpeakSoundFunction* RealSpeakSoundFunction = nullptr; -bool TP_MAKE_THISCALL(HookSpeakSoundFunction, Actor, const char* apName, uint32_t* a3, uint32_t a4, uint32_t a5, uint32_t a6, uint64_t a7, uint64_t a8, uint64_t a9, bool a10, uint64_t a11, bool a12, bool a13, bool a14) +float TP_MAKE_THISCALL(HookSpeakSoundFunction, Actor, const char* apName, uint32_t* a3, uint32_t a4, uint32_t a5, uint32_t a6, uint64_t a7, uint64_t a8, uint64_t a9, bool a10, uint64_t a11, bool a12, bool a13, bool a14) { - spdlog::debug("a3: {:X}, a4: {}, a5: {}, a6: {}, a7: {}, a8: {:X}, a9: {:X}, a10: {}, a11: {:X}, a12: {}, a13: {}, a14: {}", (uint64_t)a3, a4, a5, a6, a7, a8, a9, a10, a11, a12, a13, a14); + // Note most dialogues invoke SpeakSoundFunction twice, an initial call that queues it to an update thread, then a reinvocation. - if (apThis->GetExtension()->IsLocal()) - World::Get().GetRunner().Trigger(DialogueEvent(apThis->formID, apName)); + spdlog::debug("a3: {:X}, a4: {}, a5: {}, a6: {}, a7: {}, a8: {:X}, a9: {:X}, a10: {}, a11: {:X}, a12: {}, a13: {}, a14: {}", (uint64_t)a3, a4, a5, a6, a7, a8, a9, a10, a11, a12, a13, a14); + World::Get().GetRunner().Trigger(DialogueEvent(apThis->formID, apName)); + return TiltedPhoques::ThisCall(RealSpeakSoundFunction, apThis, apName, a3, a4, a5, a6, a7, a8, a9, a10, a11, a12, a13, a14); } -void Actor::SpeakSound(const char* pFile) +float Actor::SpeakSound(const char* pFile) { uint32_t handle[3]{}; handle[0] = -1; - TiltedPhoques::ThisCall(RealSpeakSoundFunction, this, pFile, handle, 0, 0x32, 0, 0, 0, 0, 0, 0, 0, 1, 1); + + return TiltedPhoques::ThisCall(RealSpeakSoundFunction, this, pFile, handle, 0, 0x32, 0, 0, 0, 0, 0, 0, 0, 1, 1); +} + +bool Actor::IsTalking() noexcept +{ + TP_THIS_FUNCTION(TIsTalking, bool, Actor); + POINTER_SKYRIMSE(TIsTalking, s_IsTalking, 37266); + return TiltedPhoques::ThisCall(s_IsTalking, this); +} + +bool Actor::IsInScene() noexcept +{ + // We don't have a solution for Condition Functions + //PAPYRUS_FUNCTION(bool, Actor, IsInScene); + //bool papyrusValue = s_pIsInScene(this); + bool flagsValue= (flags1 & ActorBoolBits::kHasSceneExtra) != 0; + + return flagsValue; +} + +bool Actor::IsInDialogueWithPlayer() noexcept +{ + using ObjectReference = TESObjectREFR; + PAPYRUS_FUNCTION(bool, ObjectReference, IsInDialogueWithPlayer); + return s_pIsInDialogueWithPlayer(this); +} + +float Actor::GetVoiceRecoveryTime() noexcept +{ + // Doesn't work. And Wiki only describes w.r.t shouts + // PAPYRUS_FUNCTION(float, Actor, GetVoiceRecoveryTime); + // float fVRT = s_pGetVoiceRecoveryTime(this); + // if (fVRT != fVoiceTimer) + // spdlog::warn(__FUNCTION__ ": fVRT {}, fVoiceTimer {}", fVRT, fVoiceTimer); + + return fVoiceTimer; +} + +bool Actor::IsSpeakingInScene() +{ + auto pScene = GetCurrentScene(); + bool isSpeakingInScene = IsInScene(); + isSpeakingInScene = isSpeakingInScene && GetVoiceRecoveryTime() > 0.0f; + const bool isTalking = IsTalking(); + const bool isLeader = World::Get().GetPartyService().IsLeader(); // Helps distinguish logs in 2-party + + spdlog::debug(__FUNCTION__ ": isSpeakingInScene {}, isTalking {}, voiceRecoveryTime {}, isLeader {}, formId {:X}, name {}", isSpeakingInScene, isTalking, GetVoiceRecoveryTime(), isLeader, formID, baseForm->GetName()); + + return isSpeakingInScene; } char TP_MAKE_THISCALL(HookActorProcess, Actor, float a2) { - // Don't process AI if we own the actor + // Only process AI if we own the actor if (apThis->GetExtension()->IsRemote()) - return 0; + return 0; return TiltedPhoques::ThisCall(RealActorProcess, apThis, a2); } diff --git a/Code/client/Games/Skyrim/Actor.h b/Code/client/Games/Skyrim/Actor.h index 9625c75e1..02039bc98 100644 --- a/Code/client/Games/Skyrim/Actor.h +++ b/Code/client/Games/Skyrim/Actor.h @@ -210,6 +210,12 @@ struct Actor : TESObjectREFR [[nodiscard]] bool IsWearingBodyPiece() const noexcept; [[nodiscard]] bool ShouldWearBodyPiece() const noexcept; [[nodiscard]] bool IsVampireLord() const noexcept; + [[nodiscard]] bool IsTalking() noexcept; + [[nodiscard]] bool IsInScene() noexcept; + [[nodiscard]] bool IsInDialogueWithPlayer() noexcept; + [[nodiscard]] float GetVoiceRecoveryTime() noexcept; + [[nodiscard]] bool IsSpeakingInScene(); + // Setters void SetSpeed(float aSpeed) noexcept; @@ -243,7 +249,7 @@ struct Actor : TESObjectREFR void PickUpObject(TESObjectREFR* apObject, int32_t aCount, bool aUnk1, float aUnk2) noexcept; void DropObject(TESBoundObject* apObject, ExtraDataList* apExtraData, int32_t aCount, NiPoint3* apLocation, NiPoint3* apRotation) noexcept; void DropOrPickUpObject(const Inventory::Entry& arEntry, NiPoint3* apPoint, NiPoint3* apRotate) noexcept; - void SpeakSound(const char* pFile); + float SpeakSound(const char* pFile); void StartCombatEx(Actor* apTarget) noexcept; void SetCombatTargetEx(Actor* apTarget) noexcept; void StartCombat(Actor* apTarget) noexcept; @@ -252,6 +258,12 @@ struct Actor : TESObjectREFR void FixVampireLordModel() noexcept; bool RemoveSpell(MagicItem* apSpell) noexcept; + enum ActorBoolBits + { + kNone = 0, + kHasSceneExtra = 1 << 3, + }; + enum ActorFlags { IS_A_MOUNT = 1 << 1, diff --git a/Code/client/Games/Skyrim/Forms/TESQuest.h b/Code/client/Games/Skyrim/Forms/TESQuest.h index 6c121e202..88e0e841e 100644 --- a/Code/client/Games/Skyrim/Forms/TESQuest.h +++ b/Code/client/Games/Skyrim/Forms/TESQuest.h @@ -9,7 +9,20 @@ struct BGSScene : TESForm { GameArray phases; GameArray actorIds; + GameArray actorFlags; + GameArray actorProgressionFlags; + GameArray actions; + TESQuest* owningQuest; + uint32_t flags; + uint32_t padA4; + TESCondition conditions; + bool isPlaying; + + void ScriptForceStart(); + void ScriptStop(); }; +static_assert(offsetof(BGSScene, owningQuest) == 0x98); +static_assert(offsetof(BGSScene, isPlaying) == 0xB0); struct TESQuest : BGSStoryManagerTreeForm { diff --git a/Code/client/Games/Skyrim/TESObjectREFR.h b/Code/client/Games/Skyrim/TESObjectREFR.h index 504350ae0..99723b90c 100644 --- a/Code/client/Games/Skyrim/TESObjectREFR.h +++ b/Code/client/Games/Skyrim/TESObjectREFR.h @@ -17,6 +17,7 @@ struct AnimationVariables; struct TESWorldSpace; struct TESBoundObject; struct TESContainer; +struct BGSScene; enum class ITEM_REMOVE_REASON { @@ -78,7 +79,7 @@ struct TESObjectREFR : TESForm virtual void sub_47(); virtual void sub_48(); virtual void sub_49(); - virtual void sub_4A(); + virtual BGSScene* GetCurrentScene(); virtual void sub_4B(); virtual void sub_4C(); virtual void sub_4D(); diff --git a/Code/client/Services/Generic/CharacterService.cpp b/Code/client/Services/Generic/CharacterService.cpp index 7a1e83040..6ad234bcc 100644 --- a/Code/client/Services/Generic/CharacterService.cpp +++ b/Code/client/Services/Generic/CharacterService.cpp @@ -515,7 +515,7 @@ void CharacterService::OnRemoteSpawnDataReceived(const NotifySpawnData& acMessag { if (auto serverId = Utils::GetServerId(entity)) { - if (*serverId == id) + if (serverId.has_value() && serverId.value() == id) return true; } return false; @@ -920,44 +920,101 @@ void CharacterService::OnDialogueEvent(const DialogueEvent& acEvent) noexcept if (!m_transport.IsConnected()) return; + const bool isLeader = World::Get().GetPartyService().IsLeader(); // Helps distinguish in 2-party logs auto view = m_world.view(entt::exclude); - auto entityIt = std::find_if(view.begin(), view.end(), [view, formId = acEvent.ActorID](auto entity) { return view.get(entity).Id == formId; }); + auto entityIt = std::find_if(view.begin(), view.end(), [view, formId = acEvent.ActorID](auto entity) { + return view.get(entity).Id == formId; + }); if (entityIt == view.end()) + { + spdlog::debug(__FUNCTION__ ": failed to find speaking Actor's FormIdComponent, formId {:X}, isLeader {}", acEvent.ActorID, isLeader); return; + } auto serverIdRes = Utils::GetServerId(*entityIt); if (!serverIdRes) { - spdlog::error("{}: server id not found for form id {:X}", __FUNCTION__, acEvent.ActorID); + spdlog::debug(__FUNCTION__ ": server id not found for formId {:X}, isLeader {}", acEvent.ActorID, isLeader); return; } + + Actor* pActor = Cast(TESForm::GetById(acEvent.ActorID)); + if (!pActor) + return; - DialogueRequest request{}; - request.ServerId = serverIdRes.value(); - request.SoundFilename = acEvent.VoiceFile; + bool isLocal = pActor->GetExtension()->IsLocal(); + bool isInScene = pActor->IsInScene(); + auto sceneId = isInScene ? pActor->GetCurrentScene()->formID : 0; + bool isTaskDialogue = pActor->IsTalking() && pActor->IsInDialogueWithPlayer(); + bool isSpeakingInScene = pActor->IsSpeakingInScene(); - m_transport.Send(request); + // There's no good way to distinguish the goodbye line + // from the first line of the scene, so disable this. + bool repairEdgeCase = false; +#if 0 + // Fix the edge case, "goodbye line" of TaskDialogue + static Actor* plastDialogueActor = nullptr; + static bool lastIsInDialogueWithPlayer = false; + bool repairEdgeCase = (pActor == plastDialogueActor) && lastIsInDialogueWithPlayer; + + if (repairEdgeCase) + { + plastDialogueActor = nullptr; + lastIsInDialogueWithPlayer = false; + } + + else if (isTaskDialogue) + { + plastDialogueActor = pActor; + lastIsInDialogueWithPlayer = true; + } +#endif + + const bool willSync = isTaskDialogue || repairEdgeCase || isLocal && !isInScene; + + spdlog::debug( + __FUNCTION__ ": isLocal {}, isInScene {}, isSpeakingInScene {}, isTaskDialogue {} repaireEdgeCase {}, willSync {}, scene {:X}, Actor " + "{:X}, serverId {:X}, isLeader {}, name {}, soundFile {}", + isLocal, isInScene, isSpeakingInScene, isTaskDialogue, repairEdgeCase, willSync, sceneId, pActor->formID, serverIdRes.value(), isLeader, pActor->baseForm->GetName(), + acEvent.VoiceFile); + + if (willSync) + { + DialogueRequest request{}; + request.ServerId = serverIdRes.value(); + request.SoundFilename = acEvent.VoiceFile; + + m_transport.Send(request); + } } void CharacterService::OnNotifyDialogue(const NotifyDialogue& acMessage) noexcept { - auto remoteView = m_world.view(); - const auto remoteIt = std::find_if(std::begin(remoteView), std::end(remoteView), [remoteView, Id = acMessage.ServerId](auto entity) { return remoteView.get(entity).Id == Id; }); + const bool isLeader = World::Get().GetPartyService().IsLeader(); // Helps distinguish in 2-party logs + auto view = m_world.view(entt::exclude); + auto viewIt = std::find_if( + view.begin(), view.end(), + [view, id = acMessage.ServerId](auto entity) + { + auto serverId = Utils::GetServerId(entity); + return serverId.has_value() && serverId.value() == id; + }); - if (remoteIt == std::end(remoteView)) + if (viewIt == view.end()) { - spdlog::warn("Actor for dialogue with remote id {:X} not found.", acMessage.ServerId); + spdlog::debug(__FUNCTION__ ": failed to find speaking Actor's FormIdComponent, serverId {:X}, isLeader {}", acMessage.ServerId, isLeader); return; } - auto formIdComponent = remoteView.get(*remoteIt); - const TESForm* pForm = TESForm::GetById(formIdComponent.Id); - Actor* pActor = Cast(pForm); - + Actor* pActor = Cast(TESForm::GetById(view.get(*viewIt).Id)); if (!pActor) return; + spdlog::debug( + __FUNCTION__ ": playing dialogue Actor {:X}, serverId {:X}, isLeader {}, name {}, soundFile {}", pActor->formID, acMessage.ServerId, isLeader, pActor->baseForm->GetName(), + acMessage.SoundFilename); + pActor->StopCurrentDialogue(true); pActor->SpeakSound(acMessage.SoundFilename.c_str()); } @@ -967,42 +1024,92 @@ void CharacterService::OnSubtitleEvent(const SubtitleEvent& acEvent) noexcept if (!m_transport.IsConnected()) return; + const bool isLeader = World::Get().GetPartyService().IsLeader(); // Helps distinguish in 2-party logs auto view = m_world.view(entt::exclude); auto entityIt = std::find_if(view.begin(), view.end(), [view, formId = acEvent.SpeakerID](auto entity) { return view.get(entity).Id == formId; }); if (entityIt == view.end()) + { + spdlog::debug(__FUNCTION__ ": failed to find subtitle Actor's FormIdComponent, formId {:X}, isLeader {}", acEvent.SpeakerID, isLeader); return; + } auto serverIdRes = Utils::GetServerId(*entityIt); if (!serverIdRes) { - spdlog::error("{}: server id not found for form id {:X}", __FUNCTION__, acEvent.SpeakerID); + spdlog::debug(__FUNCTION__ ": server id not found for formId {:X}, isLeader {}", acEvent.SpeakerID, isLeader); return; } - SubtitleRequest request{}; - request.ServerId = serverIdRes.value(); - request.Text = acEvent.Text; - request.TopicFormId = acEvent.TopicFormID; + Actor* pActor = Cast(TESForm::GetById(acEvent.SpeakerID)); + if (!pActor) + return; + + bool isLocal = pActor->GetExtension()->IsLocal(); + bool isInScene = pActor->IsInScene(); + auto isSpeakingInScene = pActor->IsSpeakingInScene(); + auto sceneId = isInScene ? pActor->GetCurrentScene()->formID : 0; + bool isTaskDialogue = pActor->IsTalking() && pActor->IsInDialogueWithPlayer(); - m_transport.Send(request); + // There's no good way to distinguish the goodbye line + // from the first line of the scene, so disable this. + bool repairEdgeCase = false; +#if 0 + // Fix the edge case, "goodbye line" of TaskDialogue + static Actor* plastDialogueActor = nullptr; + static bool lastIsInDialogueWithPlayer = false; + bool repairEdgeCase = (pActor == plastDialogueActor) && lastIsInDialogueWithPlayer; + + if (repairEdgeCase) + { + plastDialogueActor = nullptr; + lastIsInDialogueWithPlayer = false; + } + + else if (isTaskDialogue) + { + plastDialogueActor = pActor; + lastIsInDialogueWithPlayer = true; + } +#endif + + const bool willSync = isTaskDialogue || repairEdgeCase || isLocal && !isInScene; + + spdlog::debug( + __FUNCTION__ ": isLocal {}, isInScene {}, isSpeakingInScene {}, isTaskDialogue {} repaireEdgeCase {}, willSync {}, scene {:X}, Actor " + "{:X}, serverId {:X}, isLeader {}, name {}, subtitle {}", + isLocal, isInScene, isSpeakingInScene, isTaskDialogue, repairEdgeCase, willSync, sceneId, pActor->formID, serverIdRes.value(), isLeader, pActor->baseForm->GetName(), + acEvent.Text); + + if (willSync) + { + SubtitleRequest request{}; + request.ServerId = serverIdRes.value(); + request.Text = acEvent.Text; + request.TopicFormId = acEvent.TopicFormID; + m_transport.Send(request); + } } void CharacterService::OnNotifySubtitle(const NotifySubtitle& acMessage) noexcept { - auto remoteView = m_world.view(); - const auto remoteIt = std::find_if(std::begin(remoteView), std::end(remoteView), [remoteView, Id = acMessage.ServerId](auto entity) { return remoteView.get(entity).Id == Id; }); + const bool isLeader = m_world.Get().GetPartyService().IsLeader(); + auto view = m_world.view(entt::exclude); + auto viewIt = std::find_if( + view.begin(), view.end(), + [view, id = acMessage.ServerId](auto entity) + { + auto serverId = Utils::GetServerId(entity); + return serverId.has_value() && serverId.value() == id; + }); - if (remoteIt == std::end(remoteView)) + if (viewIt == view.end()) { - spdlog::warn("Actor for dialogue with remote id {:X} not found.", acMessage.ServerId); + spdlog::debug(__FUNCTION__ ": failed to find subtitle Actor's FormIdComponent, serverId {:X}, isLeader {}", acMessage.ServerId, isLeader); return; } - auto formIdComponent = remoteView.get(*remoteIt); - const TESForm* pForm = TESForm::GetById(formIdComponent.Id); - Actor* pActor = Cast(pForm); - + Actor* pActor = Cast(TESForm::GetById(view.get(*viewIt).Id)); if (!pActor) return; @@ -1010,6 +1117,10 @@ void CharacterService::OnNotifySubtitle(const NotifySubtitle& acMessage) noexcep TESTopicInfo* pInfo = nullptr; pInfo = Cast(TESForm::GetById(acMessage.TopicFormId)); + spdlog::debug(__FUNCTION__ ": showing subtitle Actor {:X}, serverId {:X}, isLeader {}, name {}, message: {}", + pActor->formID, acMessage.ServerId, isLeader, pActor->baseForm->GetName(), acMessage.Text); + + SubtitleManager::Get()->HideSubtitle(pActor); // Subtitle conflicts can hang, this makes it beter at least. SubtitleManager::Get()->ShowSubtitle(pActor, acMessage.Text.c_str(), pInfo); } From a8c6472982c2f0df21bd8b50c71bae18855ad8ec Mon Sep 17 00:00:00 2001 From: Richard Fortier Date: Sun, 22 Feb 2026 17:26:31 -0500 Subject: [PATCH 2/5] Delete #if 0 code, failed attempt to handle TaskDialogue "goodbye" lines. Getting the failed attempt out of the code, but keeping the commit so you can it was attempted, but there's not enough info. --- .../Services/Generic/CharacterService.cpp | 56 ++----------------- 1 file changed, 6 insertions(+), 50 deletions(-) diff --git a/Code/client/Services/Generic/CharacterService.cpp b/Code/client/Services/Generic/CharacterService.cpp index 6ad234bcc..7f140ca3d 100644 --- a/Code/client/Services/Generic/CharacterService.cpp +++ b/Code/client/Services/Generic/CharacterService.cpp @@ -949,34 +949,12 @@ void CharacterService::OnDialogueEvent(const DialogueEvent& acEvent) noexcept bool isTaskDialogue = pActor->IsTalking() && pActor->IsInDialogueWithPlayer(); bool isSpeakingInScene = pActor->IsSpeakingInScene(); - // There's no good way to distinguish the goodbye line - // from the first line of the scene, so disable this. - bool repairEdgeCase = false; -#if 0 - // Fix the edge case, "goodbye line" of TaskDialogue - static Actor* plastDialogueActor = nullptr; - static bool lastIsInDialogueWithPlayer = false; - bool repairEdgeCase = (pActor == plastDialogueActor) && lastIsInDialogueWithPlayer; - - if (repairEdgeCase) - { - plastDialogueActor = nullptr; - lastIsInDialogueWithPlayer = false; - } - - else if (isTaskDialogue) - { - plastDialogueActor = pActor; - lastIsInDialogueWithPlayer = true; - } -#endif - - const bool willSync = isTaskDialogue || repairEdgeCase || isLocal && !isInScene; + const bool willSync = isTaskDialogue || isLocal && !isInScene; spdlog::debug( - __FUNCTION__ ": isLocal {}, isInScene {}, isSpeakingInScene {}, isTaskDialogue {} repaireEdgeCase {}, willSync {}, scene {:X}, Actor " + __FUNCTION__ ": isLocal {}, isInScene {}, isSpeakingInScene {}, isTaskDialogue {}, willSync {}, scene {:X}, Actor " "{:X}, serverId {:X}, isLeader {}, name {}, soundFile {}", - isLocal, isInScene, isSpeakingInScene, isTaskDialogue, repairEdgeCase, willSync, sceneId, pActor->formID, serverIdRes.value(), isLeader, pActor->baseForm->GetName(), + isLocal, isInScene, isSpeakingInScene, isTaskDialogue, willSync, sceneId, pActor->formID, serverIdRes.value(), isLeader, pActor->baseForm->GetName(), acEvent.VoiceFile); if (willSync) @@ -1051,34 +1029,12 @@ void CharacterService::OnSubtitleEvent(const SubtitleEvent& acEvent) noexcept auto sceneId = isInScene ? pActor->GetCurrentScene()->formID : 0; bool isTaskDialogue = pActor->IsTalking() && pActor->IsInDialogueWithPlayer(); - // There's no good way to distinguish the goodbye line - // from the first line of the scene, so disable this. - bool repairEdgeCase = false; -#if 0 - // Fix the edge case, "goodbye line" of TaskDialogue - static Actor* plastDialogueActor = nullptr; - static bool lastIsInDialogueWithPlayer = false; - bool repairEdgeCase = (pActor == plastDialogueActor) && lastIsInDialogueWithPlayer; - - if (repairEdgeCase) - { - plastDialogueActor = nullptr; - lastIsInDialogueWithPlayer = false; - } - - else if (isTaskDialogue) - { - plastDialogueActor = pActor; - lastIsInDialogueWithPlayer = true; - } -#endif - - const bool willSync = isTaskDialogue || repairEdgeCase || isLocal && !isInScene; + const bool willSync = isTaskDialogue || isLocal && !isInScene; spdlog::debug( - __FUNCTION__ ": isLocal {}, isInScene {}, isSpeakingInScene {}, isTaskDialogue {} repaireEdgeCase {}, willSync {}, scene {:X}, Actor " + __FUNCTION__ ": isLocal {}, isInScene {}, isSpeakingInScene {}, isTaskDialogue {}, willSync {}, scene {:X}, Actor " "{:X}, serverId {:X}, isLeader {}, name {}, subtitle {}", - isLocal, isInScene, isSpeakingInScene, isTaskDialogue, repairEdgeCase, willSync, sceneId, pActor->formID, serverIdRes.value(), isLeader, pActor->baseForm->GetName(), + isLocal, isInScene, isSpeakingInScene, isTaskDialogue, willSync, sceneId, pActor->formID, serverIdRes.value(), isLeader, pActor->baseForm->GetName(), acEvent.Text); if (willSync) From 8bdee420d352d26e9c8c69ab922d593c15c879df Mon Sep 17 00:00:00 2001 From: Richard Fortier Date: Mon, 5 Jan 2026 21:51:05 -0500 Subject: [PATCH 3/5] 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. Partial support for Remote actors to run AI packages when in-Scene --- Code/client/Games/Animation.cpp | 3 + .../Skyrim/AI/Movement/PlayerControls.cpp | 7 + .../Games/Skyrim/AI/Movement/PlayerControls.h | 2 + .../Games/Skyrim/Events/EventDispatcher.h | 15 + Code/client/Games/Skyrim/Forms/TESQuest.cpp | 107 +++- Code/client/Games/Skyrim/Forms/TESQuest.h | 37 +- .../Services/Debug/Views/QuestDebugView.cpp | 38 +- Code/client/Services/Generic/MagicService.cpp | 9 +- Code/client/Services/Generic/QuestService.cpp | 465 ++++++++++++++---- Code/client/Services/QuestService.h | 44 +- Code/client/World.cpp | 3 + Code/encoding/Messages/ClientMessageFactory.h | 3 +- .../Messages/NotifyQuestSceneUpdate.cpp | 21 + .../Messages/NotifyQuestSceneUpdate.h | 23 + Code/encoding/Messages/NotifyQuestUpdate.cpp | 4 + Code/encoding/Messages/NotifyQuestUpdate.h | 6 +- .../Messages/RequestQuestSceneUpdate.cpp | 34 ++ .../Messages/RequestQuestSceneUpdate.h | 29 ++ Code/encoding/Messages/RequestQuestUpdate.h | 5 +- Code/encoding/Messages/ServerMessageFactory.h | 3 +- Code/encoding/Opcodes.h | 2 + Code/server/GameServer.cpp | 19 +- Code/server/GameServer.h | 1 + Code/server/Services/PartyService.h | 69 +++ Code/server/Services/QuestService.cpp | 309 ++++++++++-- Code/server/Services/QuestService.h | 9 +- 26 files changed, 1080 insertions(+), 187 deletions(-) create mode 100644 Code/encoding/Messages/NotifyQuestSceneUpdate.cpp create mode 100644 Code/encoding/Messages/NotifyQuestSceneUpdate.h create mode 100644 Code/encoding/Messages/RequestQuestSceneUpdate.cpp create mode 100644 Code/encoding/Messages/RequestQuestSceneUpdate.h diff --git a/Code/client/Games/Animation.cpp b/Code/client/Games/Animation.cpp index 178caef13..4e54f8f16 100644 --- a/Code/client/Games/Animation.cpp +++ b/Code/client/Games/Animation.cpp @@ -20,6 +20,9 @@ static TPerformAction* RealPerformAction; // TODO: make scoped override thread_local bool g_forceAnimation = false; +// This is where the Actors AI is enabled/disabled: almost all of NPC AI/behavior is +// determined by Actions that are run on them. + uint8_t TP_MAKE_THISCALL(HookPerformAction, ActorMediator, TESActionData* apAction) { auto pActor = apAction->actor; diff --git a/Code/client/Games/Skyrim/AI/Movement/PlayerControls.cpp b/Code/client/Games/Skyrim/AI/Movement/PlayerControls.cpp index 884b859a9..67f5ec195 100644 --- a/Code/client/Games/Skyrim/AI/Movement/PlayerControls.cpp +++ b/Code/client/Games/Skyrim/AI/Movement/PlayerControls.cpp @@ -19,6 +19,13 @@ void PlayerControls::SetCamSwitch(bool aSet) noexcept Data.remapMode = aSet; } +bool PlayerControls::IsMovementControlsEnabled() noexcept +{ + using TIsMovementControlsEnabled = bool(); + POINTER_SKYRIMSE(TIsMovementControlsEnabled, s_isMovementControlsEnabled, 55485); + return s_isMovementControlsEnabled.Get()(); +} + BSInputEnableManager* BSInputEnableManager::Get() { POINTER_SKYRIMSE(BSInputEnableManager*, s_instance, 400863); diff --git a/Code/client/Games/Skyrim/AI/Movement/PlayerControls.h b/Code/client/Games/Skyrim/AI/Movement/PlayerControls.h index 17c1f8101..4ce1c4d04 100644 --- a/Code/client/Games/Skyrim/AI/Movement/PlayerControls.h +++ b/Code/client/Games/Skyrim/AI/Movement/PlayerControls.h @@ -42,6 +42,8 @@ struct PlayerControls void SetCamSwitch(bool aSet) noexcept; + static bool IsMovementControlsEnabled() noexcept; + public: char pad0[0x20]; PlayerControlsData Data; diff --git a/Code/client/Games/Skyrim/Events/EventDispatcher.h b/Code/client/Games/Skyrim/Events/EventDispatcher.h index e7a9a8d96..193f8ed83 100644 --- a/Code/client/Games/Skyrim/Events/EventDispatcher.h +++ b/Code/client/Games/Skyrim/Events/EventDispatcher.h @@ -188,16 +188,31 @@ struct TESResolveNPCTemplatesEvent { }; +// The RE'd fields in TESSceneEvent, TESSceneActionEvent and TESScenePhaseEvent may be incorrect + struct TESSceneEvent { + void* ref; + uint32_t sceneFormId; + uint32_t sceneType; // BEGIN (0) or END (1) }; struct TESSceneActionEvent { + void* ref; + uint32_t sceneFormId; + uint32_t actionIndex; + uint32_t questFormId; + uint32_t actorAliasId; }; struct TESScenePhaseEvent { + void* callback; + uint32_t sceneFormId; + uint16_t phaseIndex; + uint32_t sceneType; // BEGIN (0) or END (1) + uint32_t questStageId; }; struct TESSellEvent diff --git a/Code/client/Games/Skyrim/Forms/TESQuest.cpp b/Code/client/Games/Skyrim/Forms/TESQuest.cpp index 6f4feeb4b..2864eadef 100644 --- a/Code/client/Games/Skyrim/Forms/TESQuest.cpp +++ b/Code/client/Games/Skyrim/Forms/TESQuest.cpp @@ -54,13 +54,9 @@ void TESQuest::SetActive(bool toggle) bool TESQuest::IsStageDone(uint16_t stageIndex) { - for (Stage* it : stages) - { - if (it->stageIndex == stageIndex) - return it->IsDone(); - } - - return false; + TP_THIS_FUNCTION(TIsStageDone, bool, TESQuest, uint16_t); + POINTER_SKYRIMSE(TIsStageDone, IsStageDone, 25011); + return IsStageDone(this, stageIndex); } bool TESQuest::Kill() @@ -88,34 +84,107 @@ bool TESQuest::EnsureQuestStarted(bool& success, bool force) return SetRunning(this, &success, force); } -bool TESQuest::SetStage(uint16_t newStage) +bool TESQuest::SetStage(uint16_t stageIndex) { - ScopedQuestOverride _; - + // According to wiki, calling newStage == currentStage does nothing. + // Calling with newStage < currentStage, will rerun the stage actions + // IFF the target newStage is not marked IsCompleted(). Regardless, + // will not reduce currentStage (it stays the same). + // Actually reducing currentStage requires reset() to be called first. TP_THIS_FUNCTION(TSetStage, bool, TESQuest, uint16_t); POINTER_SKYRIMSE(TSetStage, SetStage, 25004); - return SetStage(this, newStage); + bool bSuccess = SetStage(this, stageIndex); + if (!bSuccess) + { + spdlog::warn(__FUNCTION__ ": returned false quest formId {:X}, currentStage {}, newStage {}, name {}", + formID, currentStage, stageIndex, fullName.value.AsAscii()); + } + return bSuccess; } -void TESQuest::ScriptSetStage(uint16_t stageIndex) +bool TESQuest::ScriptSetStage(uint16_t stageIndex, bool bForce) { - if (currentStage == stageIndex || IsStageDone(stageIndex)) - return; + // Since SetStage() rules are not well-known and hooks may be confused, filter rewind + // according to TESQuest::SetStage rules. + bool bSuccess = stageIndex > currentStage || stageIndex != currentStage && !IsStageDone(stageIndex) || bForce; + + if (bSuccess) + { + using Quest = TESQuest; + PAPYRUS_FUNCTION(bool, Quest, SetCurrentStageID, int); + bSuccess = s_pSetCurrentStageID(this, stageIndex); + } + if (!bSuccess) + { + spdlog::warn(__FUNCTION__ ": returned false quest formId {:X}, currentStage {}, newStage {}, name {}", formID, currentStage, stageIndex, fullName.value.AsAscii()); + } + + return bSuccess; +} + +void TESQuest::ScriptReset() +{ using Quest = TESQuest; - PAPYRUS_FUNCTION(void, Quest, SetCurrentStageID, int); - s_pSetCurrentStageID(this, stageIndex); + PAPYRUS_FUNCTION(void, Quest, Reset); + s_pReset(this); +} + +void TESQuest::ScriptResetAndUpdate() +{ + ScriptReset(); + + if (!IsEnabled()) + { + if (!IsStopped()) + SetStopped(); + } + + else + { + bool isStarted; + if (flags & StartsEnabled && !EnsureQuestStarted(isStarted, false)) + spdlog::warn(__FUNCTION__ ": EnsureQuestStarted failed questId {:X}, is Started {}", formID, isStarted); + } } + void TESQuest::SetStopped() { flags &= 0xFFFE; MarkChanged(2); } +bool TESQuest::IsAnyCutscenePlaying() +{ + for (const auto& scene : scenes) + { + if (scene->isPlaying) + return true; + } + return false; +} + +void BGSScene::ScriptForceStart() +{ + spdlog::info(__FUNCTION__ ": force starting scene questId {:X}, sceneId: {:X}, isPlaying? {}", owningQuest->formID, formID, isPlaying); + using Scene = BGSScene; + PAPYRUS_FUNCTION(void, Scene, ForceStart); + s_pForceStart(this); +} + +void BGSScene::ScriptStop() +{ + spdlog::info(__FUNCTION__ ": stopping scene questId {:X}, sceneId: {:X}, isPlaying? {}", owningQuest->formID, formID, isPlaying); + using Scene = BGSScene; + PAPYRUS_FUNCTION(void, Scene, Stop); + s_pStop(this); +} + static TiltedPhoques::Initializer s_questInitHooks( - []() + []() { - // kill quest init in cold blood - // TiltedPhoques::Write(25003, 0xC3); + // kill quest init in cold blood + // TiltedPhoques::Write(25003, 0xC3); }); + diff --git a/Code/client/Games/Skyrim/Forms/TESQuest.h b/Code/client/Games/Skyrim/Forms/TESQuest.h index 88e0e841e..255ec90b7 100644 --- a/Code/client/Games/Skyrim/Forms/TESQuest.h +++ b/Code/client/Games/Skyrim/Forms/TESQuest.h @@ -5,6 +5,23 @@ #include #include +struct BGSSceneAction +{ + virtual ~BGSSceneAction(); + + uint32_t actorID; + uint16_t startPhase; + uint16_t endPhase; + uint32_t flags; + uint8_t status; + + void Start() + { + this->status |= 1u; + } +}; + +static_assert(offsetof(BGSSceneAction, flags) == 0x10); struct BGSScene : TESForm { GameArray phases; @@ -89,6 +106,10 @@ struct TESQuest : BGSStoryManagerTreeForm uint16_t stageIndex; uint8_t flags; + operator bool() const + { + return *reinterpret_cast(this) != 0; + } inline bool IsDone() { return flags & 1; } }; @@ -103,11 +124,8 @@ struct TESQuest : BGSStoryManagerTreeForm Type type; // 0x00DF int32_t scopedStatus; // 0x00E0 default init: -1, if not -1 outside of story manager scope uint32_t padE4; - GameList stages; - /* - GameList* pExecutedStages; // 0x00E8 - GameList* pWaitingStages; // 0x00F0 - */ + GameValueList* pExecutedStages; // 0x00E8 + GameValueList* pWaitingStages; // 0x00F0 GameList objectives; // 0x00F8 char pad108[0x100]; // 0x0108 GameArray scenes; // 0x0208 @@ -139,15 +157,18 @@ struct TESQuest : BGSStoryManagerTreeForm bool EnsureQuestStarted(bool& succeded, bool force); - bool SetStage(uint16_t stage); - void ScriptSetStage(uint16_t stage); + bool SetStage(uint16_t stageIndex); + bool ScriptSetStage(uint16_t stage, bool bForce = false); + void ScriptReset(); + void ScriptResetAndUpdate(); void SetStopped(); + bool IsAnyCutscenePlaying(); }; static_assert(sizeof(TESQuest) == 0x268); static_assert(offsetof(TESQuest, fullName) == 0x28); static_assert(offsetof(TESQuest, flags) == 0xDC); -static_assert(offsetof(TESQuest, stages) == 0xE8); +static_assert(offsetof(TESQuest, pExecutedStages) == 0xE8); static_assert(offsetof(TESQuest, objectives) == 0xF8); static_assert(offsetof(TESQuest, currentStage) == 0x228); static_assert(offsetof(TESQuest, unkFlags) == 0x248); diff --git a/Code/client/Services/Debug/Views/QuestDebugView.cpp b/Code/client/Services/Debug/Views/QuestDebugView.cpp index 383f6e30a..c2ef21213 100644 --- a/Code/client/Services/Debug/Views/QuestDebugView.cpp +++ b/Code/client/Services/Debug/Views/QuestDebugView.cpp @@ -53,9 +53,11 @@ void DebugService::DrawQuestDebugView() if (ImGui::CollapsingHeader("Stages")) { - for (auto* pStage : pQuest->stages) + for (auto& stage : *pQuest->pExecutedStages) { - ImGui::TextColored({0.f, 255.f, 255.f, 255.f}, "Stage: %d, is done? %s", pStage->stageIndex, pStage->IsDone() ? "true" : "false"); + auto pStage = &stage; + ImGui::TextColored({0.f, 255.f, 255.f, 255.f}, "Stage: %d, is done? %s", pStage->stageIndex, + pStage->IsDone() ? "true" : "false"); char setStage[64]; sprintf_s(setStage, std::size(setStage), "Set stage (%d)", pStage->stageIndex); @@ -64,6 +66,38 @@ void DebugService::DrawQuestDebugView() pQuest->ScriptSetStage(pStage->stageIndex); } } + if (ImGui::CollapsingHeader("Waiting Stages")) + { + for (auto& pStage : *pQuest->pWaitingStages) + { + ImGui::TextColored({0.f, 255.f, 255.f, 255.f}, "Stage: %d, is done? %s", pStage->stageIndex, + pStage->IsDone() ? "true" : "false"); + + char setStage[64]; + sprintf_s(setStage, std::size(setStage), "Set stage (%d)", pStage->stageIndex); + + if (ImGui::Button(setStage)) + pQuest->ScriptSetStage(pStage->stageIndex); + } + } + + if (ImGui::CollapsingHeader("Scenes")) + { + for (auto& pScene : pQuest->scenes) + { + ImGui::TextColored({0.f, 255.f, 255.f, 255.f}, "Scene Form ID: %x, is playing? %s", pScene->formID, + pScene->isPlaying ? "true" : "false"); + + ImGui::Text("Scene actions:"); + for (int i = 0; i < pScene->actions.length; ++i) + { + char startAction[64]; + sprintf_s(startAction, std::size(startAction), "Start action %d", i); + if (ImGui::Button(startAction)) + pScene->actions[i]->Start(); + } + } + } if (ImGui::CollapsingHeader("Actors")) { diff --git a/Code/client/Services/Generic/MagicService.cpp b/Code/client/Services/Generic/MagicService.cpp index d5d5bb45f..978e5570f 100644 --- a/Code/client/Services/Generic/MagicService.cpp +++ b/Code/client/Services/Generic/MagicService.cpp @@ -425,7 +425,14 @@ void MagicService::OnNotifyAddTarget(const NotifyAddTarget& acMessage) noexcept // This hack is here because slow time seems to be twice as slow when cast by an npc if (pEffect->IsSlowEffect()) - pActor = PlayerCharacter::Get(); + { + acMessage.CasterId && (pCaster = PlayerCharacter::Get()); + spdlog::debug( + __FUNCTION__ ": hacking IsSlowEffect() targetId {:X}, casterId {:X}, magnitude {}, IsDualCasting {}", + acMessage.TargetId, acMessage.CasterId, acMessage.Magnitude, acMessage.IsDualCasting); + + } + pActor->magicTarget.AddTarget(data, acMessage.ApplyHealPerkBonus, acMessage.ApplyStaminaPerkBonus); spdlog::debug("Applied remote magic effect"); diff --git a/Code/client/Services/Generic/QuestService.cpp b/Code/client/Services/Generic/QuestService.cpp index b32f501be..09e551d7b 100644 --- a/Code/client/Services/Generic/QuestService.cpp +++ b/Code/client/Services/Generic/QuestService.cpp @@ -9,11 +9,16 @@ #include #include #include +#include #include #include +#include #include +#include + +namespace spdfmt = spdlog::fmt_lib; static TESQuest* FindQuestByNameId(const String& name) { @@ -28,17 +33,23 @@ QuestService::QuestService(World& aWorld, entt::dispatcher& aDispatcher) { m_joinedConnection = aDispatcher.sink().connect<&QuestService::OnConnected>(this); m_questUpdateConnection = aDispatcher.sink().connect<&QuestService::OnQuestUpdate>(this); + m_questSceneUpdateConnection = aDispatcher.sink().connect<&QuestService::OnQuestSceneUpdate>(this); + m_playerId = 0; // A note about the Gameevents: - // TESQuestStageItemDoneEvent gets fired to late, we instead use TESQuestStageEvent, because it responds immediately. + // TESQuestStageItemDoneEvent gets fired too late, we instead use TESQuestStageEvent, because it responds immediately. // TESQuestInitEvent can be instead managed by start stop quest management. // bind game event listeners auto* pEventList = EventDispatcherManager::Get(); pEventList->questStartStopEvent.RegisterSink(this); pEventList->questStageEvent.RegisterSink(this); + + pEventList->scenePhaseEvent.RegisterSink(this); + pEventList->sceneActionEvent.RegisterSink(this); + pEventList->sceneEvent.RegisterSink(this); } -void QuestService::OnConnected(const ConnectedEvent&) noexcept +void QuestService::OnConnected(const ConnectedEvent& apEvent) noexcept { // TODO: this should be followed with whatever the quest leader selected /* @@ -50,149 +61,382 @@ void QuestService::OnConnected(const ConnectedEvent&) noexcept pQuest->SetActive(false); } */ + m_playerId = apEvent.PlayerId; } -BSTEventResult QuestService::OnEvent(const TESQuestStartStopEvent* apEvent, const EventDispatcher*) +BSTEventResult QuestService::OnEvent(const TESQuestStartStopEvent* apEvent, + const EventDispatcher*) { - if (ScopedQuestOverride::IsOverriden() || !m_world.Get().GetPartyService().IsInParty()) - return BSTEventResult::kOk; + GameId Id; + TESQuest* pQuest = Cast(TESForm::GetById(apEvent->formId)); + if (pQuest == nullptr || IsNonSyncableQuest(pQuest) || !m_world.Get().GetPartyService().IsInParty() || !m_world.GetModSystem().GetServerModId(pQuest->formID, Id)) + return BSTEventResult::kOk; // pQuest == nullptr shouldn't happen, nor should getting GameId fail. - spdlog::info("Quest start/stop event: {:X}", apEvent->formId); + const auto startStop = pQuest->IsStopped() ? "stopped" : "started"; + const bool isMiscNone = (pQuest->type == TESQuest::Type::None || pQuest->type == TESQuest::Type::Miscellaneous); + const TiltedPhoques::String miscQuest(isMiscNone ? spdfmt::format("none/misc quest gameId {:X}", Id.LogFormat()) : "quest"); + const bool isLeader = m_world.Get().GetPartyService().IsLeader(); + const auto playerString = isLeader ? "leader" : "player"; - if (TESQuest* pQuest = Cast(TESForm::GetById(apEvent->formId))) - { - if (IsNonSyncableQuest(pQuest)) - return BSTEventResult::kOk; - - if (pQuest->type == TESQuest::Type::None || pQuest->type == TESQuest::Type::Miscellaneous) + spdlog::info( + __FUNCTION__ ": {} {} formId: {:X}, questStage: {}, questType: {}, flags: {:X}, {} {}, name: {}", startStop, miscQuest, apEvent->formId, pQuest->currentStage, + static_cast>(pQuest->type), pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); + + m_world.GetRunner().Queue( + [&, formId = pQuest->formID, stageId = pQuest->currentStage, stopped = pQuest->IsStopped(), type = pQuest->type]() { - // Perhaps redundant, but necessary. We need the logging and - // the lambda coming up is queued and runs later GameId Id; auto& modSys = m_world.GetModSystem(); - if (modSys.GetServerModId(pQuest->formID, Id)) + if (modSys.GetServerModId(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>(pQuest->type), - pQuest->formID, pQuest->fullName.value.AsAscii()); + RequestQuestUpdate update; + update.Id = Id; + update.Stage = stageId; + update.Status = stopped ? RequestQuestUpdate::Stopped : RequestQuestUpdate::Started; + update.ClientQuestType = static_cast>(type); + m_world.GetTransport().Send(update); } - } - - m_world.GetRunner().Queue( - [&, formId = pQuest->formID, stageId = pQuest->currentStage, stopped = pQuest->IsStopped(), type = pQuest->type]() - { - GameId Id; - auto& modSys = m_world.GetModSystem(); - if (modSys.GetServerModId(formId, Id)) - { - RequestQuestUpdate update; - update.Id = Id; - update.Stage = stageId; - update.Status = stopped ? RequestQuestUpdate::Stopped : RequestQuestUpdate::Started; - update.ClientQuestType = static_cast>(type); - - m_world.GetTransport().Send(update); - } - }); - } + }); return BSTEventResult::kOk; } BSTEventResult QuestService::OnEvent(const TESQuestStageEvent* apEvent, const EventDispatcher*) { - if (ScopedQuestOverride::IsOverriden() || !m_world.Get().GetPartyService().IsInParty()) - return BSTEventResult::kOk; + GameId Id; + TESQuest* pQuest = Cast(TESForm::GetById(apEvent->formId)); + if (pQuest == nullptr || IsNonSyncableQuest(pQuest) || !m_world.Get().GetPartyService().IsInParty() || !m_world.GetModSystem().GetServerModId(pQuest->formID, Id)) + return BSTEventResult::kOk; // pQuest == nullptr shouldn't happen, nor should getting GameId fail. - spdlog::info("Quest stage event: {:X}, stage: {}", apEvent->formId, apEvent->stageId); + const auto startStop = pQuest->IsStopped() ? "stopped" : "started"; + const bool isMiscNone = (pQuest->type == TESQuest::Type::None || pQuest->type == TESQuest::Type::Miscellaneous); + const TiltedPhoques::String miscQuest(isMiscNone ? spdfmt::format("none/misc quest gameId {:X}", Id.LogFormat()) : "quest"); + const bool isLeader = m_world.Get().GetPartyService().IsLeader(); + const auto playerString = isLeader ? "leader" : "player"; - // there is no reason to even fetch the quest object, since the event provides everything already.... - if (TESQuest* pQuest = Cast(TESForm::GetById(apEvent->formId))) - { - if (IsNonSyncableQuest(pQuest)) - return BSTEventResult::kOk; + spdlog::info( + __FUNCTION__ ": stage update {} formId: {:X}, questStage: {}, questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", miscQuest, apEvent->formId, apEvent->stageId, + static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); - if (pQuest->type == TESQuest::Type::None || pQuest->type == TESQuest::Type::Miscellaneous) + // We should not see a stage 0 Update to a started quest, unless it started a long time ago in StageWait. + bool isResetUpdate = apEvent->stageId == 0 && + (pQuest->flags & (TESQuest::Flags::Enabled | TESQuest::Flags::StageWait)) != (TESQuest::Flags::Enabled | TESQuest::Flags::StageWait); + if (isResetUpdate) + spdlog::critical( + __FUNCTION__ ": suspected quest reset event NEEDS TEST, quest formId: {:X}, questStage: {}, questType: {}, isStopped: {}, flags {:X}, {} {}, name: {}", + apEvent->formId, apEvent->stageId, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), + pQuest->fullName.value.AsAscii()); + + m_world.GetRunner().Queue( + [&, formId = apEvent->formId, stageId = apEvent->stageId, isReset = isResetUpdate, type = pQuest->type]() { - // Perhaps redundant, but necessary. We need the logging and - // the lambda coming up is queued and runs later GameId Id; auto& modSys = m_world.GetModSystem(); - if (modSys.GetServerModId(pQuest->formID, Id)) + if (modSys.GetServerModId(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>(pQuest->type), - pQuest->formID, pQuest->fullName.value.AsAscii()); + RequestQuestUpdate update; + update.Id = Id; + update.Stage = stageId; + // FIXME EXPERIMENT. If the critical log files, we think it is a reset. If observed in real life + // we can debug it and see if this reset logic actually works + update.Status = isReset ? RequestQuestUpdate::Reset : RequestQuestUpdate::StageUpdate; + update.ClientQuestType = static_cast>(type); + m_world.GetTransport().Send(update); } - } + }); + + return BSTEventResult::kOk; +} + +#if 0 +void SceneService::OnConnected(const ConnectedEvent& apEvent) noexcept +{ + m_playerId = apEvent.PlayerId; + spdlog::info(__FUNCTION__ ": connected, playerId: {:X}", apEvent.PlayerId); +} + +SceneService::SceneService(World& aWorld, entt::dispatcher& aDispatcher) : m_world(aWorld) +{ + m_joinedConnection = aDispatcher.sink().connect<&SceneService::OnConnected>(this); + m_playerId = 0; + + // A note about the Gameevents: + // TESQuestStageItemDoneEvent gets fired to late, we instead use TESQuestStageEvent, because it responds + // immediately. TESQuestInitEvent can be instead managed by start stop quest management. bind game event listeners + auto* pEventList = EventDispatcherManager::Get(); + pEventList->sceneEvent.RegisterSink(this); +} + +BSTEventResult SceneService::OnEvent(const TESSceneEvent* apEvent, const EventDispatcher*) +{ + GameId Id; + auto pScene = Cast(TESForm::GetById(apEvent->sceneFormId)); + auto pQuest = pScene->owningQuest; + if (pQuest == nullptr || QuestService::IsNonSyncableQuest(pQuest) || !m_world.Get().GetPartyService().IsInParty() || + !m_world.GetModSystem().GetServerModId(pQuest->formID, Id)) + return BSTEventResult::kOk; // pQuest == nullptr shouldn't happen, nor should getting GameId fail. - m_world.GetRunner().Queue( - [&, formId = apEvent->formId, stageId = apEvent->stageId, type = pQuest->type]() + const auto beginEnd = apEvent->sceneType ? "End" : "Begin"; + const bool isMiscNone = + (pQuest->type == TESQuest::Type::None || + pQuest->type == TESQuest::Type::Miscellaneous); // If we can't get the GameId we can't sync anyway. + const TiltedPhoques::String miscQuest(isMiscNone ? spdfmt::format("none/misc quest gameId {:X},", Id.LogFormat()) + : "quest"); + const bool isLeader = m_world.Get().GetPartyService().IsLeader(); + const auto playerString = isLeader ? "leader" : "player"; + const auto isPlaying = pScene->isPlaying; + + spdlog::info(__FUNCTION__ ": scene {}, isPlaying {}, formId: {:X}, {} formId: {:X}, questStage: {}, questType: {}, " + "isStopped: {}, flags: {:X}, {} {}, name: {}", + beginEnd, isPlaying, apEvent->sceneFormId, miscQuest, pQuest->formID, pQuest->currentStage, + static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, + playerString, PlayerId(), pQuest->fullName.value.AsAscii()); + + return BSTEventResult::kOk; +} +#endif + +BSTEventResult QuestService::OnEvent(const TESSceneEvent* apEvent, const EventDispatcher*) +{ + GameId Id; + auto pScene = Cast(TESForm::GetById(apEvent->sceneFormId)); + auto pQuest = pScene->owningQuest; + if (pQuest == nullptr || QuestService::IsNonSyncableQuest(pQuest) || !m_world.Get().GetPartyService().IsInParty() || !m_world.GetModSystem().GetServerModId(pQuest->formID, Id)) + return BSTEventResult::kOk; + + const auto beginEnd = apEvent->sceneType ? "End" : "Begin"; + const bool isMiscNone = (pQuest->type == TESQuest::Type::None || pQuest->type == TESQuest::Type::Miscellaneous); + const TiltedPhoques::String miscQuest(isMiscNone ? spdfmt::format("none/misc quest gameId {:X},", Id.LogFormat()) : "quest"); + const bool isLeader = m_world.Get().GetPartyService().IsLeader(); + const auto playerString = isLeader ? "leader" : "player"; + const auto isPlaying = pScene->isPlaying; + + spdlog::info( + __FUNCTION__ "::TESSceneEvent*" + ": sending scene {}, scene {:X}, isPlaying {}, {} formId: {:X}, questStage: {}, " + "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", + beginEnd, apEvent->sceneFormId, isPlaying, miscQuest, pQuest->formID, pQuest->currentStage, static_cast>(pQuest->type), + pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); + + // FIXME EXPERIMENT, seems to work, scene begin/end sent to server so we can choose to send a quest stage poke. + m_world.GetRunner().Queue( + [&, sceneId = apEvent->sceneFormId, questId = pQuest->formID, stageId = pQuest->currentStage, type = pQuest->type, sceneType = apEvent->sceneType]() + { + GameId sceneGameId; + GameId questGameId; + auto& modSys = m_world.GetModSystem(); + if (modSys.GetServerModId(sceneId, sceneGameId) && modSys.GetServerModId(questId, questGameId)) { - GameId Id; - auto& modSys = m_world.GetModSystem(); - if (modSys.GetServerModId(formId, Id)) - { - RequestQuestUpdate update; - update.Id = Id; - update.Stage = stageId; - update.Status = RequestQuestUpdate::StageUpdate; - update.ClientQuestType = static_cast>(type); - - m_world.GetTransport().Send(update); - } - }); - } + RequestQuestSceneUpdate update; + update.SceneId = sceneGameId; + update.QuestId = questGameId; + update.Stage = stageId; + update.Status = stageId == RequestQuestUpdate::StageUpdateForced; + update.ClientQuestType = static_cast>(type); + update.SceneType = sceneType; + + m_world.GetTransport().Send(update); + } + }); + + return BSTEventResult::kOk; +} + +BSTEventResult QuestService::OnEvent(const TESSceneActionEvent* apEvent, const EventDispatcher*) +{ + const bool isLeader = m_world.GetPartyService().IsLeader(); + const auto playerType = isLeader ? "leaderId" : "playerId"; + + spdlog::debug("TESSceneActionEvent: questId {:X}, scene id {:X}, action index {}, {} {}", apEvent->questFormId, + apEvent->sceneFormId, apEvent->actionIndex, playerType, PlayerId()); + return BSTEventResult::kOk; +} + +BSTEventResult QuestService::OnEvent(const TESScenePhaseEvent* apEvent, const EventDispatcher*) +{ + auto pScene = Cast(TESForm::GetById(apEvent->sceneFormId)); + auto pQuest = pScene ? pScene->owningQuest : nullptr; + const String sceneType = apEvent->sceneType == 0 ? "Begin" : "End"; + const bool isLeader = m_world.GetPartyService().IsLeader(); + const auto playerType = isLeader ? "leaderId" : "playerId"; + const auto isAnyScenePlaying = pQuest == nullptr ? false : pQuest->IsAnyCutscenePlaying(); + + spdlog::debug( + "TESScenePhaseEvent event: quest {:X}, stage {}, scene {:X}. phase index {}, type {}, " + "isAnyScenePlaying {},by {} {}", + pQuest ? pQuest->formID : 0, apEvent->questStageId, apEvent->sceneFormId, apEvent->phaseIndex, sceneType, isAnyScenePlaying, playerType, PlayerId()); + + // Failsafe if we did not get a scene Begin event; happens if waiting + // in Phase 0 (Phase 1 in CK), which means the first thing we'll get + // is Phase 0 End. And on very long scenes, refreshes SceneMaster so it doesn't time out. + const TESSceneEvent event = {nullptr, apEvent->sceneFormId, 0}; + if (apEvent->sceneType == 0 || apEvent->phaseIndex == 0) + OnEvent(&event, nullptr); return BSTEventResult::kOk; } void QuestService::OnQuestUpdate(const NotifyQuestUpdate& aUpdate) noexcept { - ModSystem& modSystem = World::Get().GetModSystem(); - uint32_t formId = modSystem.GetGameId(aUpdate.Id); + auto Id = aUpdate.Id; + auto formId = World::Get().GetModSystem().GetGameId(aUpdate.Id); TESQuest* pQuest = Cast(TESForm::GetById(formId)); - if (!pQuest) - { - spdlog::error("Failed to find quest, base id: {:X}, mod id: {:X}", aUpdate.Id.BaseId, aUpdate.Id.ModId); + if (pQuest == nullptr || !m_world.Get().GetPartyService().IsInParty()) return; - } - if (pQuest->type == TESQuest::Type::None || pQuest->type == TESQuest::Type::Miscellaneous) + const auto startStop = pQuest->IsStopped() ? "stopped" : "started"; + const bool isMiscNone = (pQuest->type == TESQuest::Type::None || pQuest->type == TESQuest::Type::Miscellaneous); // If we can't get the GameId we can't sync anyway. + const TiltedPhoques::String miscQuest(isMiscNone ? spdfmt::format("none/misc quest gameId {:X},", Id.LogFormat()) : "quest"); + const bool isLeader = m_world.Get().GetPartyService().IsLeader(); + const auto playerString = isLeader ? "leader" : "player"; + const auto isSceneMaster = aUpdate.SceneMaster == PlayerId(); + + // Quest OnEvent()s send updates to the server where the Leader deduplicates them, + // so most remote updates (QuestService::OnQuestUpdate) are coming from the Leader. + // + // But when Party Members are all playing a scene, the scene itself is advancing + // the quest, so everyone is sending the same quest updates close enough together some + // can sneak through the dedup code. That's solved client-side by not allowing rewind + // when in a scene. + // + // The initiator of the scene is remembered as SceneMaster and sent in NotifyQuestUpdate. + // Currently only used in experiments & logs, we may end up needing it. + // + // FIXME: Experiment: To unstick non-SceneMasters if they get stuck on an interaction, + // the SceneMaster sends a forced quest stage update at the end of the scene. This may + // be unnecessary now that we have fixed scene playing speed sync to be better. + bool updateDisabled = pQuest->IsAnyCutscenePlaying() && (aUpdate.Status == NotifyQuestUpdate::StageUpdate && aUpdate.Stage < pQuest->currentStage); + + if (updateDisabled) { - spdlog::info(__FUNCTION__ ": receiving type none/misc quest update gameId {:X} questStage {} questStatus {} questType {} formId {:X} name {}", - aUpdate.Id.LogFormat(), aUpdate.Stage, aUpdate.Status, - aUpdate.ClientQuestType, formId, pQuest->fullName.value.AsAscii()); + spdlog::info( + __FUNCTION__ ": suppressing quest stage update while playing a scene: gameId: {:X}, formId: {:X}, " + "questStage: {}, questStatus: {}, questType: {}, SceneMaster {}, " + "isAnyCutscenePlaying {}, player {}, formId: {:X}, name: {}", + aUpdate.Id.LogFormat(), formId, aUpdate.Stage, aUpdate.Status, aUpdate.ClientQuestType, PlayerId() == aUpdate.SceneMaster, pQuest->IsAnyCutscenePlaying(), PlayerId(), + formId, pQuest->fullName.value.AsAscii()); + return; } - bool bResult = false; + bool wasUpdated = false; + const bool isRunning = pQuest->getState() == TESQuest::State::Running; switch (aUpdate.Status) { case NotifyQuestUpdate::Started: - { - pQuest->ScriptSetStage(aUpdate.Stage); - pQuest->SetActive(true); - bResult = true; - spdlog::info("Remote quest started: {:X}, stage: {}", formId, aUpdate.Stage); + if (isRunning) + { + spdlog::info( + __FUNCTION__ ": suppressing duplicate start {} formId: {:X}, questStage: {}, " + "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), + pQuest->fullName.value.AsAscii()); + } + else + { + spdlog::info( + __FUNCTION__ ": remotely started {} formId: {:X}, questStage: {}, " + "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), + pQuest->fullName.value.AsAscii()); + + pQuest->ScriptSetStage(aUpdate.Stage); + pQuest->SetActive(true); + } + wasUpdated = true; break; - } - case NotifyQuestUpdate::StageUpdate: - pQuest->ScriptSetStage(aUpdate.Stage); - bResult = true; - spdlog::info("Remote quest updated: {:X}, stage: {}", formId, aUpdate.Stage); + + case NotifyQuestUpdate::Reset: + spdlog::warn( + __FUNCTION__ ": remotely reset {} formId: {:X}, questStage: {}, questType: {}, " + "isStopped: {}, flags: {:X}, {} {}, name: {}", + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), + pQuest->fullName.value.AsAscii()); + + pQuest->ScriptResetAndUpdate(); + wasUpdated = true; + break; + + case NotifyQuestUpdate::StageUpdate: // TODO? Insert START iff needed? + spdlog::info( + __FUNCTION__ ": remotely updated {} formId: {:X}, questStage: {}, questType: {}, " + "isStopped: {}, flags: {:X}, {} {}, name: {}", + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), + pQuest->fullName.value.AsAscii()); + + wasUpdated = pQuest->ScriptSetStage(aUpdate.Stage); break; + case NotifyQuestUpdate::Stopped: - bResult = StopQuest(formId); - spdlog::info("Remote quest stopped: {:X}, stage: {}", formId, aUpdate.Stage); + spdlog::info( + __FUNCTION__ ": remotely stopped {} formId: {:X}, questStage: {}, questType: {}, " + "isStopped: {}, flags: {:X}, {} {}, name: {}", + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), + pQuest->fullName.value.AsAscii()); + wasUpdated = StopQuest(formId); + break; + + default: break; - default: break; + spdlog::error( + __FUNCTION__ ": unknown remote status {} {} formId: {:X}, questStage: {}, " + "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", + aUpdate.Status, miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, + PlayerId(), pQuest->fullName.value.AsAscii()); } - if (!bResult) - spdlog::error("Failed to update the client quest state, quest: {:X}, stage: {}, status: {}", formId, aUpdate.Stage, aUpdate.Status); + if (!wasUpdated) + spdlog::error( + __FUNCTION__ ": failed to remotely update status {} {} formId: {:X}, questStage: " + "{}, questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", + aUpdate.Status, miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, + PlayerId(), pQuest->fullName.value.AsAscii()); +} + +void QuestService::OnQuestSceneUpdate(const NotifyQuestSceneUpdate& aUpdate) noexcept +{ + ModSystem& modSystem = World::Get().GetModSystem(); + auto pQuest = Cast(TESForm::GetById(modSystem.GetGameId(aUpdate.QuestId))); + auto pScene = Cast(TESForm::GetById(modSystem.GetGameId(aUpdate.SceneId))); + const bool bIsLeader = m_world.GetPartyService().IsLeader(); + const auto playerType = bIsLeader ? "leaderId" : "playerId"; + + if (!pQuest) + { + spdlog::error(__FUNCTION__ ": failed to find questId: {:X}, {} {}", aUpdate.QuestId.LogFormat(), playerType, PlayerId()); + return; + } + if (!pScene) + { + spdlog::error(__FUNCTION__ ": failed to find sceneId: {:X}, {} {}", aUpdate.SceneId.LogFormat(), playerType, PlayerId()); + return; + } + + if (aUpdate.SceneType == 0) // Scene Begin + { + if (pScene->isPlaying) + spdlog::info( + __FUNCTION__ ": skip starting scene already playing, questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, + PlayerId()); + else + { + spdlog::error( + __FUNCTION__ ": FIXME DISABLED starting scene questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); + // pScene->ScriptForceStart(); + } + } + + else // Scene End + { + if (!pScene->isPlaying) + spdlog::info( + __FUNCTION__ ": skip stopping scene not playing, questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, + PlayerId()); + else + { + spdlog::error(__FUNCTION__ ": stopping scene questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); + pScene->ScriptStop(); + } + } } bool QuestService::StopQuest(uint32_t aformId) @@ -200,8 +444,18 @@ bool QuestService::StopQuest(uint32_t aformId) TESQuest* pQuest = Cast(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(pQuest->flags), static_cast(pQuest->type), aformId, pQuest->fullName.value.AsAscii()); + } + else + { + pQuest->SetActive(false); + pQuest->SetStopped(); + } + return true; } @@ -218,11 +472,12 @@ static constexpr std::array kNonSyncableQuestIds = std::to_array({ bool QuestService::IsNonSyncableQuest(TESQuest* apQuest) { - // Quests with no quest stages are never synced. Most TESQues::Type:: quests should - // be synced, including Type::None and Type::Miscellaneous, but there are a few - // known exceptions that should be excluded that are in the table. - return apQuest->stages.Empty() - || std::find(kNonSyncableQuestIds.begin(), kNonSyncableQuestIds.end(), apQuest->formID) != kNonSyncableQuestIds.end(); + // Quests with no quest stages are never synced (check both lists). + // Most TESQues::Type:: quests should be synced, including Type::None + // and Type::Miscellaneous, but there are a few // known exceptions to exclude. + bool noStages = !apQuest->pExecutedStages || apQuest->pExecutedStages->Empty(); + noStages = noStages || !apQuest->pWaitingStages || apQuest->pWaitingStages->Empty(); + return noStages || std::find(kNonSyncableQuestIds.begin(), kNonSyncableQuestIds.end(), apQuest->formID) != kNonSyncableQuestIds.end(); } void QuestService::DebugDumpQuests() diff --git a/Code/client/Services/QuestService.h b/Code/client/Services/QuestService.h index b4f1b58fc..ada56bdc4 100644 --- a/Code/client/Services/QuestService.h +++ b/Code/client/Services/QuestService.h @@ -5,15 +5,14 @@ #include struct NotifyQuestUpdate; +struct NotifyQuestSceneUpdate; struct TESQuest; /** * @brief Handles quest sync - * - * This service is currently not in use. */ -class QuestService final : public BSTEventSink, BSTEventSink +class QuestService final : public BSTEventSink, BSTEventSink, BSTEventSink, BSTEventSink, BSTEventSink { public: QuestService(World&, entt::dispatcher&); @@ -22,20 +21,57 @@ class QuestService final : public BSTEventSink, BSTEvent static bool IsNonSyncableQuest(TESQuest* apQuest); static void DebugDumpQuests(); static bool StopQuest(uint32_t aformId); + const uint32_t PlayerId() const noexcept { return m_playerId; } private: friend struct QuestEventHandler; void OnConnected(const ConnectedEvent&) noexcept; + void Disconnected(const DisconnectedEvent&) noexcept { m_playerId = 0; } + BSTEventResult OnEvent(const TESQuestStartStopEvent*, const EventDispatcher*) override; BSTEventResult OnEvent(const TESQuestStageEvent*, const EventDispatcher*) override; - + BSTEventResult OnEvent(const TESSceneEvent*, const EventDispatcher*) override; +#if 1 + BSTEventResult OnEvent(const TESSceneActionEvent*, const EventDispatcher*) override; + BSTEventResult OnEvent(const TESScenePhaseEvent*, const EventDispatcher*) override; +#endif void OnQuestUpdate(const NotifyQuestUpdate&) noexcept; + void OnQuestSceneUpdate(const NotifyQuestSceneUpdate&) noexcept; + + bool CanAdvanceQuestForParty() const noexcept; World& m_world; + uint32_t m_playerId; entt::scoped_connection m_joinedConnection; entt::scoped_connection m_leftConnection; entt::scoped_connection m_questUpdateConnection; + entt::scoped_connection m_questSceneUpdateConnection; +}; + +#if 0 +class SceneService final : public BSTEventSink +{ + public: + SceneService(World&, entt::dispatcher&); + ~SceneService() = default; + + const uint32_t PlayerId() const noexcept { return m_playerId; } + + private: + friend struct SceneEventHandler; + + void OnConnected(const ConnectedEvent&) noexcept; + void Disconnected(const DisconnectedEvent&) noexcept { m_playerId = 0; } + + BSTEventResult OnEvent(const TESSceneEvent*, const EventDispatcher*) override; + + World& m_world; + uint32_t m_playerId; + + entt::scoped_connection m_joinedConnection; + entt::scoped_connection m_leftConnection; }; +#endif diff --git a/Code/client/World.cpp b/Code/client/World.cpp index b0596604b..94c7eb7f9 100644 --- a/Code/client/World.cpp +++ b/Code/client/World.cpp @@ -44,6 +44,9 @@ World::World() ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher); +#if 0 + ctx().emplace(*this, m_dispatcher); +#endif ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher, m_transport); diff --git a/Code/encoding/Messages/ClientMessageFactory.h b/Code/encoding/Messages/ClientMessageFactory.h index 30e7984cd..d90eb0d22 100644 --- a/Code/encoding/Messages/ClientMessageFactory.h +++ b/Code/encoding/Messages/ClientMessageFactory.h @@ -11,6 +11,7 @@ #include #include #include +#include #include #include #include @@ -66,7 +67,7 @@ struct ClientMessageFactory template static auto Visit(T&& func) { auto s_visitor = CreateMessageVisitor< - AuthenticationRequest, AssignCharacterRequest, CancelAssignmentRequest, ClientReferencesMoveRequest, EnterInteriorCellRequest, RequestInventoryChanges, RequestFactionsChanges, RequestQuestUpdate, PartyInviteRequest, PartyAcceptInviteRequest, PartyLeaveRequest, PartyCreateRequest, + AuthenticationRequest, AssignCharacterRequest, CancelAssignmentRequest, ClientReferencesMoveRequest, EnterInteriorCellRequest, RequestInventoryChanges, RequestFactionsChanges, RequestQuestUpdate, RequestQuestSceneUpdate, PartyInviteRequest, PartyAcceptInviteRequest, PartyLeaveRequest, PartyCreateRequest, PartyChangeLeaderRequest, PartyKickRequest, RequestActorValueChanges, RequestActorMaxValueChanges, EnterExteriorCellRequest, RequestHealthChangeBroadcast, ActivateRequest, LockChangeRequest, AssignObjectsRequest, RequestDeathStateChange, ShiftGridCellRequest, RequestOwnershipTransfer, RequestOwnershipClaim, RequestObjectInventoryChanges, SpellCastRequest, ProjectileLaunchRequest, InterruptCastRequest, AddTargetRequest, ScriptAnimationRequest, DrawWeaponRequest, MountRequest, NewPackageRequest, RequestRespawn, SyncExperienceRequest, RequestEquipmentChanges, SendChatMessageRequest, TeleportCommandRequest, PlayerRespawnRequest, DialogueRequest, SubtitleRequest, PlayerDialogueRequest, PlayerLevelRequest, TeleportRequest, RequestPlayerHealthUpdate, RequestWeatherChange, RequestCurrentWeather, RequestSetWaypoint, diff --git a/Code/encoding/Messages/NotifyQuestSceneUpdate.cpp b/Code/encoding/Messages/NotifyQuestSceneUpdate.cpp new file mode 100644 index 000000000..878528117 --- /dev/null +++ b/Code/encoding/Messages/NotifyQuestSceneUpdate.cpp @@ -0,0 +1,21 @@ + +#include +#include + +void NotifyQuestSceneUpdate::SerializeRaw(TiltedPhoques::Buffer::Writer& aWriter) const noexcept +{ + SceneId.Serialize(aWriter); + QuestId.Serialize(aWriter); + aWriter.WriteBits(SceneType, 8); +} + +void NotifyQuestSceneUpdate::DeserializeRaw(TiltedPhoques::Buffer::Reader& aReader) noexcept +{ + ServerMessage::DeserializeRaw(aReader); + SceneId.Deserialize(aReader); + QuestId.Deserialize(aReader); + + uint64_t tmp; + aReader.ReadBits(tmp, 8); + SceneType = tmp & 0xFF; +} diff --git a/Code/encoding/Messages/NotifyQuestSceneUpdate.h b/Code/encoding/Messages/NotifyQuestSceneUpdate.h new file mode 100644 index 000000000..a4e68bd51 --- /dev/null +++ b/Code/encoding/Messages/NotifyQuestSceneUpdate.h @@ -0,0 +1,23 @@ +#pragma once + +#include "Message.h" +#include + +struct NotifyQuestSceneUpdate final : ServerMessage +{ + static constexpr ServerOpcode Opcode = kNotifyQuestSceneUpdate; + + NotifyQuestSceneUpdate() + : ServerMessage(Opcode) + { + } + + void SerializeRaw(TiltedPhoques::Buffer::Writer& aWriter) const noexcept override; + void DeserializeRaw(TiltedPhoques::Buffer::Reader& aReader) noexcept override; + + bool operator==(const NotifyQuestSceneUpdate& acRhs) const noexcept { return GetOpcode() == acRhs.GetOpcode() && SceneId == acRhs.SceneId && QuestId == acRhs.QuestId && SceneType == acRhs.SceneType; } + + GameId SceneId; + GameId QuestId; + uint8_t SceneType; // BEGIN (0) or END (1) +}; diff --git a/Code/encoding/Messages/NotifyQuestUpdate.cpp b/Code/encoding/Messages/NotifyQuestUpdate.cpp index f4ec157de..8fab019b5 100644 --- a/Code/encoding/Messages/NotifyQuestUpdate.cpp +++ b/Code/encoding/Messages/NotifyQuestUpdate.cpp @@ -5,6 +5,7 @@ void NotifyQuestUpdate::SerializeRaw(TiltedPhoques::Buffer::Writer& aWriter) const noexcept { Id.Serialize(aWriter); + aWriter.WriteBits(SceneMaster, 32); aWriter.WriteBits(Stage, 16); aWriter.WriteBits(Status, 8); aWriter.WriteBits(ClientQuestType, 8); @@ -16,6 +17,9 @@ void NotifyQuestUpdate::DeserializeRaw(TiltedPhoques::Buffer::Reader& aReader) n Id.Deserialize(aReader); uint64_t tmp; + aReader.ReadBits(tmp, 32); + SceneMaster = tmp & 0xFFFFFFFF; + aReader.ReadBits(tmp, 16); Stage = tmp & 0xFFFF; diff --git a/Code/encoding/Messages/NotifyQuestUpdate.h b/Code/encoding/Messages/NotifyQuestUpdate.h index ab2a88d94..983da950b 100644 --- a/Code/encoding/Messages/NotifyQuestUpdate.h +++ b/Code/encoding/Messages/NotifyQuestUpdate.h @@ -15,16 +15,18 @@ struct NotifyQuestUpdate final : ServerMessage void SerializeRaw(TiltedPhoques::Buffer::Writer& aWriter) const noexcept override; void DeserializeRaw(TiltedPhoques::Buffer::Reader& aReader) noexcept override; - bool operator==(const NotifyQuestUpdate& acRhs) const noexcept { return GetOpcode() == acRhs.GetOpcode() && Id == acRhs.Id && Stage == acRhs.Stage && Status == acRhs.Status && ClientQuestType == acRhs.ClientQuestType; } + bool operator==(const NotifyQuestUpdate& acRhs) const noexcept { return GetOpcode() == acRhs.GetOpcode() && Id == acRhs.Id && Stage == acRhs.Stage && Status == acRhs.Status && SceneMaster == acRhs.SceneMaster && ClientQuestType == acRhs.ClientQuestType; } enum StatusCode : uint8_t { StageUpdate, Started, - Stopped + Stopped, + Reset }; GameId Id; + uint32_t SceneMaster{0}; uint16_t Stage; uint8_t Status; uint8_t ClientQuestType; diff --git a/Code/encoding/Messages/RequestQuestSceneUpdate.cpp b/Code/encoding/Messages/RequestQuestSceneUpdate.cpp new file mode 100644 index 000000000..f7d803cec --- /dev/null +++ b/Code/encoding/Messages/RequestQuestSceneUpdate.cpp @@ -0,0 +1,34 @@ + +#include +#include + +void RequestQuestSceneUpdate::SerializeRaw(TiltedPhoques::Buffer::Writer& aWriter) const noexcept +{ + SceneId.Serialize(aWriter); + QuestId.Serialize(aWriter); + aWriter.WriteBits(Stage, 16); + aWriter.WriteBits(Status, 8); + aWriter.WriteBits(ClientQuestType, 8); + aWriter.WriteBits(SceneType, 8); +} + +void RequestQuestSceneUpdate::DeserializeRaw(TiltedPhoques::Buffer::Reader& aReader) noexcept +{ + ClientMessage::DeserializeRaw(aReader); + SceneId.Deserialize(aReader); + QuestId.Deserialize(aReader); + + uint64_t tmp; + aReader.ReadBits(tmp, 16); + Stage = tmp & 0xFFFF; + + aReader.ReadBits(tmp, 8); + Status = tmp & 0xFF; + + aReader.ReadBits(tmp, 8); + ClientQuestType = tmp & 0xFF; + + aReader.ReadBits(tmp, 8); + SceneType = tmp & 0xFF; +} + diff --git a/Code/encoding/Messages/RequestQuestSceneUpdate.h b/Code/encoding/Messages/RequestQuestSceneUpdate.h new file mode 100644 index 000000000..a3fd78b6c --- /dev/null +++ b/Code/encoding/Messages/RequestQuestSceneUpdate.h @@ -0,0 +1,29 @@ +#pragma once + +#include "Message.h" +#include + +struct RequestQuestSceneUpdate final : ClientMessage +{ + static constexpr ClientOpcode Opcode = kRequestQuestSceneUpdate; + + RequestQuestSceneUpdate() + : ClientMessage(Opcode) + { + } + + void SerializeRaw(TiltedPhoques::Buffer::Writer& aWriter) const noexcept override; + void DeserializeRaw(TiltedPhoques::Buffer::Reader& aReader) noexcept override; + + bool operator==(const RequestQuestSceneUpdate& acRhs) const noexcept + { + return GetOpcode() == acRhs.GetOpcode() && SceneId == acRhs.SceneId && QuestId == acRhs.QuestId && Stage == acRhs.Stage && Status == acRhs.Status && ClientQuestType == acRhs.ClientQuestType && SceneType == acRhs.SceneType; + } + + GameId SceneId; + GameId QuestId; + uint16_t Stage; + uint8_t Status; + uint8_t ClientQuestType; + uint8_t SceneType; // BEGIN (0) or END (1) +}; diff --git a/Code/encoding/Messages/RequestQuestUpdate.h b/Code/encoding/Messages/RequestQuestUpdate.h index 5ebe83584..4fa846415 100644 --- a/Code/encoding/Messages/RequestQuestUpdate.h +++ b/Code/encoding/Messages/RequestQuestUpdate.h @@ -21,7 +21,10 @@ struct RequestQuestUpdate final : ClientMessage { StageUpdate, Started, - Stopped + Stopped, + Reset, + SceneUpdate, + StageUpdateForced }; GameId Id; diff --git a/Code/encoding/Messages/ServerMessageFactory.h b/Code/encoding/Messages/ServerMessageFactory.h index 942c30fec..d0ed6437b 100644 --- a/Code/encoding/Messages/ServerMessageFactory.h +++ b/Code/encoding/Messages/ServerMessageFactory.h @@ -13,6 +13,7 @@ #include #include #include +#include #include #include #include @@ -70,7 +71,7 @@ struct ServerMessageFactory template static auto Visit(T&& func) { auto s_visitor = CreateMessageVisitor< - AuthenticationResponse, AssignCharacterResponse, ServerReferencesMoveRequest, ServerTimeSettings, CharacterSpawnRequest, NotifyInventoryChanges, StringCacheUpdate, NotifyFactionsChanges, NotifyRemoveCharacter, NotifyQuestUpdate, NotifyPlayerList, NotifyPartyInfo, NotifyPartyInvite, + AuthenticationResponse, AssignCharacterResponse, ServerReferencesMoveRequest, ServerTimeSettings, CharacterSpawnRequest, NotifyInventoryChanges, StringCacheUpdate, NotifyFactionsChanges, NotifyRemoveCharacter, NotifyQuestUpdate, NotifyQuestSceneUpdate, NotifyPlayerList, NotifyPartyInfo, NotifyPartyInvite, NotifyActorValueChanges, NotifyPartyJoined, NotifyPartyLeft, NotifyActorMaxValueChanges, NotifyHealthChangeBroadcast, NotifySpawnData, NotifyActivate, NotifyLockChange, AssignObjectsResponse, NotifyDeathStateChange, NotifyOwnershipTransfer, NotifyObjectInventoryChanges, NotifySpellCast, NotifyProjectileLaunch, NotifyInterruptCast, NotifyAddTarget, NotifyScriptAnimation, NotifyDrawWeapon, NotifyMount, NotifyNewPackage, NotifyRespawn, NotifySyncExperience, NotifyEquipmentChanges, NotifyChatMessageBroadcast, TeleportCommandResponse, NotifyPlayerRespawn, NotifyDialogue, NotifySubtitle, NotifyPlayerDialogue, NotifyActorTeleport, NotifyRelinquishControl, NotifyPlayerLeft, NotifyPlayerJoined, NotifyDialogue, NotifySubtitle, NotifyPlayerDialogue, NotifyPlayerLevel, NotifyPlayerCellChanged, NotifyTeleport, NotifyPlayerHealthUpdate, NotifySettingsChange, diff --git a/Code/encoding/Opcodes.h b/Code/encoding/Opcodes.h index 8f0b10592..c6b0b97fd 100644 --- a/Code/encoding/Opcodes.h +++ b/Code/encoding/Opcodes.h @@ -10,6 +10,7 @@ enum ClientOpcode : unsigned char kEnterInteriorCellRequest, kRequestFactionsChanges, kRequestQuestUpdate, + kRequestQuestSceneUpdate, kPartyInviteRequest, kPartyAcceptInviteRequest, kPartyLeaveRequest, @@ -67,6 +68,7 @@ enum ServerOpcode : unsigned char kNotifyFactionsChanges, kNotifyRemoveCharacter, kNotifyQuestUpdate, + kNotifyQuestSceneUpdate, kNotifyPlayerList, kNotifyPartyInfo, kNotifyPartyInvite, diff --git a/Code/server/GameServer.cpp b/Code/server/GameServer.cpp index ba4176b83..39a3be79e 100644 --- a/Code/server/GameServer.cpp +++ b/Code/server/GameServer.cpp @@ -1,4 +1,4 @@ -#include +#include #include #include @@ -732,6 +732,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(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()) diff --git a/Code/server/GameServer.h b/Code/server/GameServer.h index f7256d7a8..00fefbb18 100644 --- a/Code/server/GameServer.h +++ b/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; diff --git a/Code/server/Services/PartyService.h b/Code/server/Services/PartyService.h index fbb0f7f7d..ba4307c62 100644 --- a/Code/server/Services/PartyService.h +++ b/Code/server/Services/PartyService.h @@ -14,6 +14,73 @@ struct PartyCreateRequest; struct PartyChangeLeaderRequest; struct PartyKickRequest; +/* 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 QuestService::OnEvent calls + sometimes 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 +{ + using QuestOrSceneId = GameId; + using QuestStage = uint16_t; + using QuestStatus = uint8_t; + using PlayerId = uint32_t; + using TimeStamp = std::chrono::time_point; + + struct Entry + { + QuestOrSceneId questOrSceneId{}; + QuestStage questStage{}; + QuestStatus questStatus{}; + PlayerId playerId{}; + TimeStamp timestamp{}; + }; + + using Container = std::deque; + using iterator = Container::iterator; + using const_iterator = Container::const_iterator; + + void Add(const QuestOrSceneId& acQuestOrSceneId, const QuestStage acQuestStage, const QuestStatus acQuestStatus, + const PlayerId& acPlayerId, const TimeStamp acTimeStamp = std::chrono::steady_clock::now()); + + const_iterator Find(const QuestOrSceneId& acQuestOrSceneId, const QuestStage acQuestStage, + const QuestStatus acQuestStatus) noexcept; + const_iterator FindWPlayerId(const QuestOrSceneId& acQuestOrSceneId, const QuestStage acQuestStage, + const QuestStatus acQuestStatus, const PlayerId& acPlayerId) noexcept; + + void Reset() noexcept { m_cache.clear(); } + bool Found(const QuestOrSceneId& acQuestOrSceneId, const QuestStage acQuestStage, + const QuestStatus acQuestStatus) noexcept + { + return Find(acQuestOrSceneId, acQuestStage, acQuestStatus) != m_cache.end(); + } + bool FoundWPlayerId(const QuestOrSceneId& acQuestOrSceneId, const QuestStage acQuestStage, + const QuestStatus acQuestStatus, const PlayerId& acPlayerId) noexcept + { + return FindWPlayerId(acQuestOrSceneId, acQuestStage, acQuestStatus, acPlayerId) != m_cache.end(); + } + + uint32_t GetSceneMaster() const noexcept { return m_sceneMaster; } + void SetSceneMaster(const uint32_t acSceneMaster) noexcept { m_sceneMaster = acSceneMaster; } + void ResetSceneMaster() noexcept { m_sceneMaster = 0; } + const bool NeedSceneMaster() const noexcept { return !m_sceneMaster; } + + private: + void inline Expire() noexcept; + Container m_cache{}; // Short, time-ordered, duplicates valid (do they ever happen?) + uint32_t m_sceneMaster{0}; // PlayerIDs start at 1, so zero is "not set." +}; + /** * @brief Manages every party in the server. */ @@ -24,6 +91,8 @@ struct PartyService uint32_t LeaderPlayerId; Vector Members; GameId CachedWeather{}; + QuestStageDedupHistory m_questStageDedupHistory; + QuestStageDedupHistory& GetQuestStageDedupHistory() { return m_questStageDedupHistory; } }; PartyService(World& aWorld, entt::dispatcher& aDispatcher) noexcept; diff --git a/Code/server/Services/QuestService.cpp b/Code/server/Services/QuestService.cpp index 52133e74c..9f4d4dca5 100644 --- a/Code/server/Services/QuestService.cpp +++ b/Code/server/Services/QuestService.cpp @@ -3,96 +3,329 @@ #include #include +#include #include +#include #include +#include #include namespace { Console::Setting bEnableMiscQuestSync{"Gameplay:bEnableMiscQuestSync", "(Experimental) Syncs miscellaneous quests when possible", false}; - +Console::Setting uQuestHistoryExpiration("GameServer:uQuestHistoryExpiration", "Time in milliseconds to retain quest progression changes for deduplication", 30000U); } QuestService::QuestService(World& aWorld, entt::dispatcher& aDispatcher) : m_world(aWorld) { m_questUpdateConnection = aDispatcher.sink>().connect<&QuestService::OnQuestChanges>(this); + m_questSceneUpdateConnection = aDispatcher.sink>().connect<&QuestService::OnQuestSceneChanges>(this); } void QuestService::OnQuestChanges(const PacketEvent& acMessage) noexcept { const auto& message = acMessage.Packet; - auto* pPlayer = acMessage.pPlayer; + // We'll want to know the player party status for messaging & decisions + // We want the leader to change things whenever possible, if a Member + // advances a quest we can't undo it and need to remember. + auto& partyService = m_world.GetPartyService(); + bool inParty = partyService.IsPlayerInParty(pPlayer); + bool isLeader = partyService.IsPlayerLeader(pPlayer); + auto playerTypeString = isLeader ? "leader" : "player"; + auto partyId = pPlayer->GetParty().JoinedPartyId; + PartyService::Party* pParty = partyService.GetPlayerParty(pPlayer); + Player* pLeader = isLeader ? pPlayer : m_world.GetPlayerManager().GetById(pParty->LeaderPlayerId); + auto& dedupHistory = pParty->GetQuestStageDedupHistory(); + + // Find the corresponding quest log entry auto& questComponent = pPlayer->GetQuestLogComponent(); auto& entries = questComponent.QuestContent.Entries; - auto questIt = std::find_if(entries.begin(), entries.end(), [&message](const auto& e) { return e.Id == message.Id; }); NotifyQuestUpdate notify{}; notify.Id = message.Id; notify.Stage = message.Stage; - notify.Status = message.Status; + // notify.Status = message.Status; // Now set correctly in switch + notify.SceneMaster = dedupHistory.GetSceneMaster(); notify.ClientQuestType = message.ClientQuestType; - if (notify.ClientQuestType == 0 || notify.ClientQuestType == 6) // Types None or Miscellaneous. Hard-coded to avoid client header file. + // Update QuestComponent. In order to prevent bugs when + // we "discover" a quest in-progress (first seen with something + // Other than RequestQuestUpdate::Start), we add it as a new + // quest record if not found + if (questIt != entries.end()) + { + questIt->Id = message.Id; + questIt->Stage = message.Stage; + } + + else { - if (!bEnableMiscQuestSync) - return; - spdlog::info("{}: syncing type none/misc quest to party, gameId {:X} questStage {} questStatus {} questType {}", - __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, notify.ClientQuestType); + entries.emplace_back(message.Id, message.Stage); + questIt = std::prev(entries.end()); + spdlog::info("{}: started/discovered quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); } - if (message.Status == RequestQuestUpdate::Started || message.Status == RequestQuestUpdate::StageUpdate) + bool useAggressiveSend = false; + switch (message.Status) { - // in order to prevent bugs when a quest is in progress - // and being updated we add it as a new quest record to - // maintain a proper remote questlog state. - if (questIt == entries.end()) + case RequestQuestUpdate::Started: notify.Status = NotifyQuestUpdate::Started; break; + + case RequestQuestUpdate::StageUpdateForced: useAggressiveSend = true; [[fallthrough]]; + case RequestQuestUpdate::StageUpdate: + notify.Status = NotifyQuestUpdate::StageUpdate; + spdlog::info( + "{}: updated quest: {:X}, stage: {}, SceneMaster {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, notify.SceneMaster, playerTypeString, + pPlayer->GetId()); + break; + + case RequestQuestUpdate::Stopped: + notify.Status = NotifyQuestUpdate::Stopped; + spdlog::info("{}: stopped quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); + + if (questIt != entries.end()) + entries.erase(questIt); + else { - auto& newQuest = entries.emplace_back(); - newQuest.Id = message.Id; - newQuest.Stage = message.Stage; + spdlog::warn("{}: unable to delete quest object {:X} (already stopped or first update is stopped)", __FUNCTION__, notify.Id.LogFormat()); + } + break; - if (message.Status == RequestQuestUpdate::Started) - { - spdlog::debug("Started quest: {:X} stage: {}", message.Id.LogFormat(), message.Stage); + case RequestQuestUpdate::Reset: + useAggressiveSend = true; + notify.Status = NotifyQuestUpdate::Reset; + spdlog::warn("{}: reset quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); + break; - notify.Status = NotifyQuestUpdate::Started; - } + default: + spdlog::error( + "{}: unknown quest status {} quest: {:X}, stage: {}, status {}, by {} {:X}", __FUNCTION__, notify.Status, message.Id.LogFormat(), notify.Stage, notify.Status, + playerTypeString, pPlayer->GetId()); + break; + } + + // All side effects have been generated. Now just logging and a forwarding decision left. + if (inParty) + { + if (notify.ClientQuestType == 0 || notify.ClientQuestType == 6) // Types None or Miscellaneous. Hard-coded to avoid including client header file. + { + if (!bEnableMiscQuestSync) + return; + + spdlog::info( + "{}: syncing type none/misc quest to party, quest: {:X}, questStage: {}, questStatus: {}, " + "questType: {}", + __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, notify.ClientQuestType); + } + + // Now that party MEMBERS can advance quests in addition to the party leader, must prevent loops/reflections. + // If the sender of the request is a party Member, SendToLeader() if noone is in the QuestStageDedpHistory for + // this quest+stage, then add self to the dedup history. + // + // If the requesting player is the party Leader, add self to the quest deduping history and SendToParty(). If + // the originator was a party member, they are already in the dedup history. SendToParty() skips sending to any + // party member who already has this quest+stage change. + // + // If the SceneEndFlag is set and is not a duplicate, we want to kick the entire party so don't loop around through Leader, + // pretend to be leader if the request came from a party Member. + // + + if (isLeader) + { + // Leader originated or party member sent to leader. + // SendToParty unless Leader has already done it. + if (!useAggressiveSend && dedupHistory.FoundWPlayerId(notify.Id, notify.Stage, notify.Status, pPlayer->GetId())) + spdlog::info( + "{}: SendToParty dropping duplicate: quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, + playerTypeString, pPlayer->GetId()); else { - notify.Status = NotifyQuestUpdate::StageUpdate; + spdlog::info( + "{}: SendToParty: quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, playerTypeString, + pPlayer->GetId()); + + dedupHistory.Add(notify.Id, notify.Stage, notify.Status, pPlayer->GetId()); + + // We need our own loop since SendToParty can't decide which members already have updates + for (Player* pPlayer : m_world.GetPlayerManager()) + { + const auto& partyComponent = pPlayer->GetParty(); + if (partyComponent.JoinedPartyId == partyId) + { + if (!useAggressiveSend && dedupHistory.FoundWPlayerId(notify.Id, notify.Stage, notify.Status, pPlayer->GetId())) + { + spdlog::info( + "{}: SendToParty skipping duplicate send quest: {:X}, stage: {}, status: {}, " + "SceneMaster {}, to player {:X}", + __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, notify.SceneMaster, pPlayer->GetId()); + } + else + { + spdlog::info( + "{}: SendToParty sending quest: {:X}, stage: {}, status: {}, SceneMaster {}, " + "to player {:X}", + __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, notify.SceneMaster, pPlayer->GetId()); + pPlayer->Send(notify); + } + } + } } } + else { - spdlog::debug("Updated quest: {:X}, stage: {}", message.Id.LogFormat(), message.Id.BaseId, message.Stage); + // Party member advanced quest; forward just to party leader + // But don't if someone already has! + bool bFound = !useAggressiveSend && dedupHistory.Found(notify.Id, notify.Stage, notify.Status); + dedupHistory.Add(notify.Id, notify.Stage, notify.Status, pPlayer->GetId()); - auto& record = *questIt; - record.Id = message.Id; - record.Stage = message.Stage; + if (bFound) + spdlog::info( + "{}: SendToLeader dropping duplicate quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, + playerTypeString, pPlayer->GetId()); + else + { + spdlog::info( + "{}: SendToLeader quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, playerTypeString, + pPlayer->GetId()); - notify.Status = NotifyQuestUpdate::StageUpdate; + GameServer::Get()->SendToLeader(notify, pPlayer->GetParty(), pLeader); + } } } - else if (message.Status == RequestQuestUpdate::Stopped) +} + +void QuestService::OnQuestSceneChanges(const PacketEvent& acMessage) noexcept +{ + const auto& message = acMessage.Packet; + + auto* pPlayer = acMessage.pPlayer; + auto& partyService = m_world.GetPartyService(); + bool isLeader = partyService.IsPlayerLeader(pPlayer); + auto playerTypeString = isLeader ? "leader" : "player"; + auto sceneTypeString = message.SceneType ? "End" : "Begin"; + + const auto& partyComponent = pPlayer->GetParty(); + if (!partyComponent.JoinedPartyId.has_value()) + return; + + PartyService::Party* pParty = partyService.GetPlayerParty(pPlayer); + Player* pLeader = isLeader ? pPlayer : m_world.GetPlayerManager().GetById(pParty->LeaderPlayerId); + auto& dedupHistory = pParty->GetQuestStageDedupHistory(); + + // Make sure party knows scene state. + NotifyQuestSceneUpdate notify{}; + notify.SceneId = message.SceneId; + notify.QuestId = message.QuestId; + notify.SceneType = message.SceneType; + + // Scene Begin + // Set as SceneMaster if there isn't one for this scene. + // Checking for a recent scene change in history keeps us unstuck in case scene end event is missed + // Or in the case where the scene changes without a scene end, we should get a new scenemaster. + // Neither of those should happen, but, Bethesda + STR == flakes + if (message.SceneType == 0) // BEGIN { - spdlog::debug("Stopped quest: {:X}, stage: {}", message.Id.LogFormat(), message.Id.BaseId, message.Stage); + bool needSceneMaster = dedupHistory.NeedSceneMaster() || !dedupHistory.Found(message.SceneId, 0, RequestQuestUpdate::StatusCode::SceneUpdate); + // if (needSceneMaster || pPlayer->GetId() == dedupHistory.GetSceneMaster()) + dedupHistory.Add(message.SceneId, 0, RequestQuestUpdate::StatusCode::SceneUpdate, pPlayer->GetId()); - if (questIt != entries.end()) - entries.erase(questIt); + if (!needSceneMaster) + spdlog::info( + "{}: quest {:X}, scene {:X}, sceneType {}, {} {} already have SceneMaster player {}", __FUNCTION__, message.QuestId.LogFormat(), message.SceneId.LogFormat(), + sceneTypeString, playerTypeString, pPlayer->GetId(), dedupHistory.GetSceneMaster()); else - spdlog::warn("Unable to delete quest object {:X}", message.Id.LogFormat(), message.Id.BaseId); + { + dedupHistory.SetSceneMaster(pPlayer->GetId()); + spdlog::info( + "{}: quest {:X}, scene {:X}, sceneType {}, {} {} is now SceneMaster", __FUNCTION__, message.QuestId.LogFormat(), message.SceneId.LogFormat(), sceneTypeString, + playerTypeString, pPlayer->GetId()); - notify.Status = NotifyQuestUpdate::Stopped; + spdlog::info( + "{}: sending scene {} update quest {:X}, scene {:X}, by {} {}", __FUNCTION__, sceneTypeString, notify.QuestId.LogFormat(), notify.SceneId.LogFormat(), + playerTypeString, pPlayer->GetId()); + GameServer::Get()->SendToParty(notify, partyComponent, acMessage.GetSender()); + } } - const auto& partyComponent = acMessage.pPlayer->GetParty(); - if (!partyComponent.JoinedPartyId.has_value()) - return; + else // END scene + { + if (dedupHistory.GetSceneMaster() == pPlayer->GetId()) + { + spdlog::info( + "{}: sending scene {} update quest {:X}, scene {:X}, by {} {}", __FUNCTION__, sceneTypeString, notify.QuestId.LogFormat(), notify.SceneId.LogFormat(), + playerTypeString, pPlayer->GetId()); + GameServer::Get()->SendToParty(notify, partyComponent, acMessage.GetSender()); + + spdlog::info( + "{}: quest {:X}, scene {:X}, scenetype {}, {} {} removing SceneMaster player {}", __FUNCTION__, message.QuestId.LogFormat(), message.SceneId.LogFormat(), + sceneTypeString, playerTypeString, pPlayer->GetId(), dedupHistory.GetSceneMaster()); + // dedupHistory.ResetSceneMaster(); + + // Force an update out to bring anyone behind to current quest stage. + spdlog::info( + "{}: SceneMaster {} {} sending force current quest stage {} to party quest {:X}, scene {:X}, scenetype {}", __FUNCTION__, playerTypeString, pPlayer->GetId(), + message.Stage, message.QuestId.LogFormat(), message.SceneId.LogFormat(), sceneTypeString); + + RequestQuestUpdate newUpdate; + newUpdate.Id = message.QuestId; + newUpdate.Stage = message.Stage; + newUpdate.Status = RequestQuestUpdate::StageUpdateForced; + newUpdate.ClientQuestType = message.ClientQuestType; + const PacketEvent newMessage(&newUpdate, pPlayer); + QuestService::OnQuestChanges(newMessage); + } + } +} + + +void inline QuestStageDedupHistory::Expire() noexcept +{ + const auto expiration = + std::chrono::steady_clock::now() - uQuestHistoryExpiration.value_as(); + + while (!m_cache.empty() && m_cache.front().timestamp < expiration) + { + auto& it = m_cache.front(); + spdlog::info("{}: expiring dedup history entry quest/scene: {:X}, stage: {}, status: {}, by player {:X}", __FUNCTION__, + it.questOrSceneId.LogFormat(), it.questStage, it.questStatus, it.playerId); + m_cache.pop_front(); + } +} + - GameServer::Get()->SendToParty(notify, partyComponent, acMessage.GetSender()); +QuestStageDedupHistory::const_iterator QuestStageDedupHistory::Find(const QuestOrSceneId& acQuestOrSceneId, + const QuestStage acQuestStage, + const QuestStatus acQuestStatus) noexcept +{ + Expire(); + + return std::find_if(m_cache.begin(), m_cache.end(), [&](const QuestStageDedupHistory::Entry& e) { + return e.questOrSceneId == acQuestOrSceneId && e.questStage == acQuestStage && e.questStatus == acQuestStatus; + }); +} + +QuestStageDedupHistory::const_iterator QuestStageDedupHistory::FindWPlayerId(const QuestOrSceneId& acQuestOrSceneId, + const QuestStage acQuestStage, + const QuestStatus acQuestStatus, + const PlayerId& acPlayerId) noexcept +{ + Expire(); + + return std::find_if(m_cache.begin(), m_cache.end(), [&](const QuestStageDedupHistory::Entry& e) { + return e.questOrSceneId == acQuestOrSceneId && e.questStage == acQuestStage && e.questStatus == acQuestStatus && + acPlayerId == e.playerId; + }); +} + +void QuestStageDedupHistory::Add(const QuestOrSceneId& acQuestOrSceneId, const QuestStage acQuestStage, + const QuestStatus acQuestStatus, const PlayerId& acPlayerId, + const TimeStamp acTimeStamp) +{ + Expire(); + m_cache.emplace_back(acQuestOrSceneId, acQuestStage, acQuestStatus, acPlayerId, acTimeStamp); } diff --git a/Code/server/Services/QuestService.h b/Code/server/Services/QuestService.h index 1e6a90539..2bd30e9ac 100644 --- a/Code/server/Services/QuestService.h +++ b/Code/server/Services/QuestService.h @@ -6,23 +6,24 @@ struct World; struct UpdateEvent; struct RequestQuestUpdate; +struct RequestQuestSceneUpdate; /** * @brief Dispatch quest sync messages. - * - * This service is currently not in use. */ class QuestService { -public: + public: QuestService(World& aWorld, entt::dispatcher& aDispatcher); -private: + private: void OnQuestChanges(const PacketEvent& aChanges) noexcept; + void OnQuestSceneChanges(const PacketEvent& aChanges) noexcept; World& m_world; entt::scoped_connection m_questUpdateConnection; + entt::scoped_connection m_questSceneUpdateConnection; entt::scoped_connection m_updateConnection; entt::scoped_connection m_joinConnection; }; From 3d2eb3c57deb22160fabc611a9c93d371d962612 Mon Sep 17 00:00:00 2001 From: Richard Fortier Date: Sun, 22 Feb 2026 17:02:51 -0500 Subject: [PATCH 4/5] Delete #if 0 failed attempts code. Has some value in a commit to say "already tried that." --- Code/client/Services/Generic/QuestService.cpp | 48 ------------------- Code/client/Services/QuestService.h | 25 ---------- Code/client/World.cpp | 3 -- 3 files changed, 76 deletions(-) diff --git a/Code/client/Services/Generic/QuestService.cpp b/Code/client/Services/Generic/QuestService.cpp index 09e551d7b..d9502693b 100644 --- a/Code/client/Services/Generic/QuestService.cpp +++ b/Code/client/Services/Generic/QuestService.cpp @@ -148,54 +148,6 @@ BSTEventResult QuestService::OnEvent(const TESQuestStageEvent* apEvent, const Ev return BSTEventResult::kOk; } -#if 0 -void SceneService::OnConnected(const ConnectedEvent& apEvent) noexcept -{ - m_playerId = apEvent.PlayerId; - spdlog::info(__FUNCTION__ ": connected, playerId: {:X}", apEvent.PlayerId); -} - -SceneService::SceneService(World& aWorld, entt::dispatcher& aDispatcher) : m_world(aWorld) -{ - m_joinedConnection = aDispatcher.sink().connect<&SceneService::OnConnected>(this); - m_playerId = 0; - - // A note about the Gameevents: - // TESQuestStageItemDoneEvent gets fired to late, we instead use TESQuestStageEvent, because it responds - // immediately. TESQuestInitEvent can be instead managed by start stop quest management. bind game event listeners - auto* pEventList = EventDispatcherManager::Get(); - pEventList->sceneEvent.RegisterSink(this); -} - -BSTEventResult SceneService::OnEvent(const TESSceneEvent* apEvent, const EventDispatcher*) -{ - GameId Id; - auto pScene = Cast(TESForm::GetById(apEvent->sceneFormId)); - auto pQuest = pScene->owningQuest; - if (pQuest == nullptr || QuestService::IsNonSyncableQuest(pQuest) || !m_world.Get().GetPartyService().IsInParty() || - !m_world.GetModSystem().GetServerModId(pQuest->formID, Id)) - return BSTEventResult::kOk; // pQuest == nullptr shouldn't happen, nor should getting GameId fail. - - const auto beginEnd = apEvent->sceneType ? "End" : "Begin"; - const bool isMiscNone = - (pQuest->type == TESQuest::Type::None || - pQuest->type == TESQuest::Type::Miscellaneous); // If we can't get the GameId we can't sync anyway. - const TiltedPhoques::String miscQuest(isMiscNone ? spdfmt::format("none/misc quest gameId {:X},", Id.LogFormat()) - : "quest"); - const bool isLeader = m_world.Get().GetPartyService().IsLeader(); - const auto playerString = isLeader ? "leader" : "player"; - const auto isPlaying = pScene->isPlaying; - - spdlog::info(__FUNCTION__ ": scene {}, isPlaying {}, formId: {:X}, {} formId: {:X}, questStage: {}, questType: {}, " - "isStopped: {}, flags: {:X}, {} {}, name: {}", - beginEnd, isPlaying, apEvent->sceneFormId, miscQuest, pQuest->formID, pQuest->currentStage, - static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, - playerString, PlayerId(), pQuest->fullName.value.AsAscii()); - - return BSTEventResult::kOk; -} -#endif - BSTEventResult QuestService::OnEvent(const TESSceneEvent* apEvent, const EventDispatcher*) { GameId Id; diff --git a/Code/client/Services/QuestService.h b/Code/client/Services/QuestService.h index ada56bdc4..76dbd2c20 100644 --- a/Code/client/Services/QuestService.h +++ b/Code/client/Services/QuestService.h @@ -50,28 +50,3 @@ class QuestService final : public BSTEventSink, BSTEvent entt::scoped_connection m_questUpdateConnection; entt::scoped_connection m_questSceneUpdateConnection; }; - -#if 0 -class SceneService final : public BSTEventSink -{ - public: - SceneService(World&, entt::dispatcher&); - ~SceneService() = default; - - const uint32_t PlayerId() const noexcept { return m_playerId; } - - private: - friend struct SceneEventHandler; - - void OnConnected(const ConnectedEvent&) noexcept; - void Disconnected(const DisconnectedEvent&) noexcept { m_playerId = 0; } - - BSTEventResult OnEvent(const TESSceneEvent*, const EventDispatcher*) override; - - World& m_world; - uint32_t m_playerId; - - entt::scoped_connection m_joinedConnection; - entt::scoped_connection m_leftConnection; -}; -#endif diff --git a/Code/client/World.cpp b/Code/client/World.cpp index 94c7eb7f9..b0596604b 100644 --- a/Code/client/World.cpp +++ b/Code/client/World.cpp @@ -44,9 +44,6 @@ World::World() ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher); -#if 0 - ctx().emplace(*this, m_dispatcher); -#endif ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher, m_transport); ctx().emplace(*this, m_dispatcher, m_transport); From 112493d63e5de34f1ada64eae5544ed6dcf4aabc Mon Sep 17 00:00:00 2001 From: Richard Fortier Date: Mon, 23 Feb 2026 10:06:50 -0500 Subject: [PATCH 5/5] Turn logs down to debug, cleanup some messages. --- Code/client/Services/Generic/QuestService.cpp | 58 +++++++++---------- Code/server/Services/QuestService.cpp | 50 ++++++++-------- 2 files changed, 53 insertions(+), 55 deletions(-) diff --git a/Code/client/Services/Generic/QuestService.cpp b/Code/client/Services/Generic/QuestService.cpp index d9502693b..47f4d1a2c 100644 --- a/Code/client/Services/Generic/QuestService.cpp +++ b/Code/client/Services/Generic/QuestService.cpp @@ -137,7 +137,7 @@ BSTEventResult QuestService::OnEvent(const TESQuestStageEvent* apEvent, const Ev RequestQuestUpdate update; update.Id = Id; update.Stage = stageId; - // FIXME EXPERIMENT. If the critical log files, we think it is a reset. If observed in real life + // FIXME EXPERIMENT. If the critical log fires, we think it is a reset. If observed in real life // we can debug it and see if this reset logic actually works update.Status = isReset ? RequestQuestUpdate::Reset : RequestQuestUpdate::StageUpdate; update.ClientQuestType = static_cast>(type); @@ -163,7 +163,7 @@ BSTEventResult QuestService::OnEvent(const TESSceneEvent* apEvent, const EventDi const auto playerString = isLeader ? "leader" : "player"; const auto isPlaying = pScene->isPlaying; - spdlog::info( + spdlog::debug( __FUNCTION__ "::TESSceneEvent*" ": sending scene {}, scene {:X}, isPlaying {}, {} formId: {:X}, questStage: {}, " "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", @@ -261,7 +261,7 @@ void QuestService::OnQuestUpdate(const NotifyQuestUpdate& aUpdate) noexcept if (updateDisabled) { - spdlog::info( + spdlog::debug( __FUNCTION__ ": suppressing quest stage update while playing a scene: gameId: {:X}, formId: {:X}, " "questStage: {}, questStatus: {}, questType: {}, SceneMaster {}, " "isAnyCutscenePlaying {}, player {}, formId: {:X}, name: {}", @@ -277,19 +277,19 @@ void QuestService::OnQuestUpdate(const NotifyQuestUpdate& aUpdate) noexcept case NotifyQuestUpdate::Started: if (isRunning) { - spdlog::info( + spdlog::debug( __FUNCTION__ ": suppressing duplicate start {} formId: {:X}, questStage: {}, " "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", - miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), - pQuest->fullName.value.AsAscii()); + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), + pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); } else { - spdlog::info( + spdlog::debug( __FUNCTION__ ": remotely started {} formId: {:X}, questStage: {}, " "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", - miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), - pQuest->fullName.value.AsAscii()); + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), + pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); pQuest->ScriptSetStage(aUpdate.Stage); pQuest->SetActive(true); @@ -298,32 +298,32 @@ void QuestService::OnQuestUpdate(const NotifyQuestUpdate& aUpdate) noexcept break; case NotifyQuestUpdate::Reset: - spdlog::warn( - __FUNCTION__ ": remotely reset {} formId: {:X}, questStage: {}, questType: {}, " + spdlog::critical( + __FUNCTION__ ": REPORT THIS LOG, experimental remote reset {} formId: {:X}, questStage: {}, questType: {}, " "isStopped: {}, flags: {:X}, {} {}, name: {}", - miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), - pQuest->fullName.value.AsAscii()); + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), + pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); pQuest->ScriptResetAndUpdate(); wasUpdated = true; break; case NotifyQuestUpdate::StageUpdate: // TODO? Insert START iff needed? - spdlog::info( + spdlog::debug( __FUNCTION__ ": remotely updated {} formId: {:X}, questStage: {}, questType: {}, " "isStopped: {}, flags: {:X}, {} {}, name: {}", - miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), - pQuest->fullName.value.AsAscii()); + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), + pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); wasUpdated = pQuest->ScriptSetStage(aUpdate.Stage); break; case NotifyQuestUpdate::Stopped: - spdlog::info( + spdlog::debug( __FUNCTION__ ": remotely stopped {} formId: {:X}, questStage: {}, questType: {}, " "isStopped: {}, flags: {:X}, {} {}, name: {}", - miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), - pQuest->fullName.value.AsAscii()); + miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), + pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); wasUpdated = StopQuest(formId); break; @@ -332,16 +332,16 @@ void QuestService::OnQuestUpdate(const NotifyQuestUpdate& aUpdate) noexcept spdlog::error( __FUNCTION__ ": unknown remote status {} {} formId: {:X}, questStage: {}, " "questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", - aUpdate.Status, miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, - PlayerId(), pQuest->fullName.value.AsAscii()); + aUpdate.Status, miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), + pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); } if (!wasUpdated) spdlog::error( __FUNCTION__ ": failed to remotely update status {} {} formId: {:X}, questStage: " "{}, questType: {}, isStopped: {}, flags: {:X}, {} {}, name: {}", - aUpdate.Status, miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), pQuest->IsStopped(), pQuest->flags, playerString, - PlayerId(), pQuest->fullName.value.AsAscii()); + aUpdate.Status, miscQuest, formId, aUpdate.Stage, static_cast>(pQuest->type), + pQuest->IsStopped(), pQuest->flags, playerString, PlayerId(), pQuest->fullName.value.AsAscii()); } void QuestService::OnQuestSceneUpdate(const NotifyQuestSceneUpdate& aUpdate) noexcept @@ -366,13 +366,13 @@ void QuestService::OnQuestSceneUpdate(const NotifyQuestSceneUpdate& aUpdate) noe if (aUpdate.SceneType == 0) // Scene Begin { if (pScene->isPlaying) - spdlog::info( + spdlog::debug( __FUNCTION__ ": skip starting scene already playing, questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); else { - spdlog::error( - __FUNCTION__ ": FIXME DISABLED starting scene questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); + spdlog::debug( + __FUNCTION__ ": BLOCKED starting scene, causes more bugs than fixed, questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); // pScene->ScriptForceStart(); } } @@ -380,12 +380,12 @@ void QuestService::OnQuestSceneUpdate(const NotifyQuestSceneUpdate& aUpdate) noe else // Scene End { if (!pScene->isPlaying) - spdlog::info( + spdlog::debug( __FUNCTION__ ": skip stopping scene not playing, questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); else { - spdlog::error(__FUNCTION__ ": stopping scene questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); + spdlog::warn(__FUNCTION__ ": FIXME/REVIEW stopping scene questId {:X}, sceneId {:X}, {} {}", aUpdate.QuestId.LogFormat(), aUpdate.SceneId.LogFormat(), playerType, PlayerId()); pScene->ScriptStop(); } } @@ -398,7 +398,7 @@ bool QuestService::StopQuest(uint32_t aformId) { if (pQuest->getState() == TESQuest::State::Stopped) // Supress duplicate or loopback quest stop { - spdlog::info( + spdlog::debug( __FUNCTION__ ": suppressing duplicate quest stop formId: {:X}, questStage: {}, questFlags: {:X}, questType: {}, formId: {:X}, name: {}", aformId, pQuest->currentStage, static_cast(pQuest->flags), static_cast(pQuest->type), aformId, pQuest->fullName.value.AsAscii()); } diff --git a/Code/server/Services/QuestService.cpp b/Code/server/Services/QuestService.cpp index 9f4d4dca5..8fac6c20f 100644 --- a/Code/server/Services/QuestService.cpp +++ b/Code/server/Services/QuestService.cpp @@ -67,7 +67,7 @@ void QuestService::OnQuestChanges(const PacketEvent& acMessa { entries.emplace_back(message.Id, message.Stage); questIt = std::prev(entries.end()); - spdlog::info("{}: started/discovered quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); + spdlog::debug("{}: started/discovered quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); } bool useAggressiveSend = false; @@ -78,14 +78,14 @@ void QuestService::OnQuestChanges(const PacketEvent& acMessa case RequestQuestUpdate::StageUpdateForced: useAggressiveSend = true; [[fallthrough]]; case RequestQuestUpdate::StageUpdate: notify.Status = NotifyQuestUpdate::StageUpdate; - spdlog::info( + spdlog::debug( "{}: updated quest: {:X}, stage: {}, SceneMaster {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, notify.SceneMaster, playerTypeString, pPlayer->GetId()); break; case RequestQuestUpdate::Stopped: notify.Status = NotifyQuestUpdate::Stopped; - spdlog::info("{}: stopped quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); + spdlog::debug("{}: stopped quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); if (questIt != entries.end()) entries.erase(questIt); @@ -98,7 +98,7 @@ void QuestService::OnQuestChanges(const PacketEvent& acMessa case RequestQuestUpdate::Reset: useAggressiveSend = true; notify.Status = NotifyQuestUpdate::Reset; - spdlog::warn("{}: reset quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); + spdlog::warn("{}: FIXME/REVIEW reset quest: {:X}, stage: {}, by {} {:X}", __FUNCTION__, message.Id.LogFormat(), notify.Stage, playerTypeString, pPlayer->GetId()); break; default: @@ -111,12 +111,13 @@ void QuestService::OnQuestChanges(const PacketEvent& acMessa // All side effects have been generated. Now just logging and a forwarding decision left. if (inParty) { - if (notify.ClientQuestType == 0 || notify.ClientQuestType == 6) // Types None or Miscellaneous. Hard-coded to avoid including client header file. + if (notify.ClientQuestType == 0 || + notify.ClientQuestType == 6) // Types None or Miscellaneous. Hard-coded to avoid including client header file. { if (!bEnableMiscQuestSync) return; - spdlog::info( + spdlog::debug( "{}: syncing type none/misc quest to party, quest: {:X}, questStage: {}, questStatus: {}, " "questType: {}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, notify.ClientQuestType); @@ -130,21 +131,18 @@ void QuestService::OnQuestChanges(const PacketEvent& acMessa // the originator was a party member, they are already in the dedup history. SendToParty() skips sending to any // party member who already has this quest+stage change. // - // If the SceneEndFlag is set and is not a duplicate, we want to kick the entire party so don't loop around through Leader, - // pretend to be leader if the request came from a party Member. - // - + // Scene End sends ::StageUpdateForced, setting useAggressiveSend, to kick any players that got stuck in a scene dialog. if (isLeader) { // Leader originated or party member sent to leader. // SendToParty unless Leader has already done it. if (!useAggressiveSend && dedupHistory.FoundWPlayerId(notify.Id, notify.Stage, notify.Status, pPlayer->GetId())) - spdlog::info( + spdlog::debug( "{}: SendToParty dropping duplicate: quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, playerTypeString, pPlayer->GetId()); else { - spdlog::info( + spdlog::debug( "{}: SendToParty: quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, playerTypeString, pPlayer->GetId()); @@ -158,14 +156,14 @@ void QuestService::OnQuestChanges(const PacketEvent& acMessa { if (!useAggressiveSend && dedupHistory.FoundWPlayerId(notify.Id, notify.Stage, notify.Status, pPlayer->GetId())) { - spdlog::info( + spdlog::debug( "{}: SendToParty skipping duplicate send quest: {:X}, stage: {}, status: {}, " "SceneMaster {}, to player {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, notify.SceneMaster, pPlayer->GetId()); } else { - spdlog::info( + spdlog::debug( "{}: SendToParty sending quest: {:X}, stage: {}, status: {}, SceneMaster {}, " "to player {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, notify.SceneMaster, pPlayer->GetId()); @@ -184,12 +182,12 @@ void QuestService::OnQuestChanges(const PacketEvent& acMessa dedupHistory.Add(notify.Id, notify.Stage, notify.Status, pPlayer->GetId()); if (bFound) - spdlog::info( + spdlog::debug( "{}: SendToLeader dropping duplicate quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, playerTypeString, pPlayer->GetId()); else { - spdlog::info( + spdlog::debug( "{}: SendToLeader quest: {:X}, stage: {}, status: {}, by {} {:X}", __FUNCTION__, notify.Id.LogFormat(), notify.Stage, notify.Status, playerTypeString, pPlayer->GetId()); @@ -235,17 +233,17 @@ void QuestService::OnQuestSceneChanges(const PacketEventGetId()); if (!needSceneMaster) - spdlog::info( + spdlog::debug( "{}: quest {:X}, scene {:X}, sceneType {}, {} {} already have SceneMaster player {}", __FUNCTION__, message.QuestId.LogFormat(), message.SceneId.LogFormat(), sceneTypeString, playerTypeString, pPlayer->GetId(), dedupHistory.GetSceneMaster()); else { dedupHistory.SetSceneMaster(pPlayer->GetId()); - spdlog::info( + spdlog::debug( "{}: quest {:X}, scene {:X}, sceneType {}, {} {} is now SceneMaster", __FUNCTION__, message.QuestId.LogFormat(), message.SceneId.LogFormat(), sceneTypeString, playerTypeString, pPlayer->GetId()); - spdlog::info( + spdlog::debug( "{}: sending scene {} update quest {:X}, scene {:X}, by {} {}", __FUNCTION__, sceneTypeString, notify.QuestId.LogFormat(), notify.SceneId.LogFormat(), playerTypeString, pPlayer->GetId()); GameServer::Get()->SendToParty(notify, partyComponent, acMessage.GetSender()); @@ -256,18 +254,18 @@ void QuestService::OnQuestSceneChanges(const PacketEventGetId()) { - spdlog::info( + spdlog::debug( "{}: sending scene {} update quest {:X}, scene {:X}, by {} {}", __FUNCTION__, sceneTypeString, notify.QuestId.LogFormat(), notify.SceneId.LogFormat(), playerTypeString, pPlayer->GetId()); GameServer::Get()->SendToParty(notify, partyComponent, acMessage.GetSender()); - spdlog::info( + spdlog::debug( "{}: quest {:X}, scene {:X}, scenetype {}, {} {} removing SceneMaster player {}", __FUNCTION__, message.QuestId.LogFormat(), message.SceneId.LogFormat(), sceneTypeString, playerTypeString, pPlayer->GetId(), dedupHistory.GetSceneMaster()); // dedupHistory.ResetSceneMaster(); // Force an update out to bring anyone behind to current quest stage. - spdlog::info( + spdlog::debug( "{}: SceneMaster {} {} sending force current quest stage {} to party quest {:X}, scene {:X}, scenetype {}", __FUNCTION__, playerTypeString, pPlayer->GetId(), message.Stage, message.QuestId.LogFormat(), message.SceneId.LogFormat(), sceneTypeString); @@ -285,14 +283,14 @@ void QuestService::OnQuestSceneChanges(const PacketEvent(); + const auto expiration = std::chrono::steady_clock::now() - uQuestHistoryExpiration.value_as(); while (!m_cache.empty() && m_cache.front().timestamp < expiration) { auto& it = m_cache.front(); - spdlog::info("{}: expiring dedup history entry quest/scene: {:X}, stage: {}, status: {}, by player {:X}", __FUNCTION__, - it.questOrSceneId.LogFormat(), it.questStage, it.questStatus, it.playerId); + spdlog::debug( + "{}: expiring dedup history entry quest/scene: {:X}, stage: {}, status: {}, by player {:X}", __FUNCTION__, + it.questOrSceneId.LogFormat(), it.questStage, it.questStatus, it.playerId); m_cache.pop_front(); } }