Probe route observer callbacks

docs/red4ext-logging-shim.md

@@ -29,9 +29,15 @@ Current behavior:
 - Hooks the route handoff found from the journal listener bridge:
   `0x598250`, `0x13763d8`, `0xaa62d0`, `0xaa6330`, `0x27abd7c`, and
   `0x5625a4`.
-- Logs mappin route-event fields, active/deactive route refs, the mappin
+- Logs mappin route-event fields, active/deactive route keys, the mappin
   active-route map at `system + 0x1a0`, and the route observer list at
   `system + 0x280`.
+- Hooks the route observer callbacks reached by route activation/deactivation:
+  `0xaa6610`, `0xaa6628`, `0xaa63e0`, `0x27b10c0`, `0x295d4a0`, and
+  `0x286a85c`.
+- Logs the route entry pointer and route object pointer passed to those
+  observers, including route object vtable slots and common fields such as the
+  active byte at offset `0x84`.
 - Resolves the native mappin system when one of those paths fires, logs relevant
   vtable slot addresses, and temporarily hooks the route-adjacent slots.
 
@@ -48,6 +54,8 @@ Current route-probe focus:
 - mappin route-event enqueue: `0x13763d8`
 - mappin route-event handler: `0xaa62d0`
 - mappin route activate/deactivate: `0xaa6330`, `0x27abd7c`
+- mappin route observer callbacks: `0xaa6610`, `0xaa6628`, `0xaa63e0`,
+  `0x27b10c0`, `0x295d4a0`, `0x286a85c`
 - route-build candidate called by the bridge: `0x5625a4`
 
 Quest/objective pins did not fire the mappin tracking hooks in live tests. The
@@ -66,6 +74,22 @@ Most recent controlled test:
   dispatch to no-op `0x14a700`; the non-default callbacks above are the current
   drill-down targets.
 
+Newest controlled test:
+
+- User clock `01:05`: Continue on the main menu. The log saw
+  `GPSSystem/Tick`.
+- User clock `01:27`: Space to continue. The log saw automatic
+  `JournalManager.TrackEntry`, a dense `JournalRouteBridge` burst, and thirty
+  `RouteBuildCandidate 0x5625a4` calls. About 5.5 seconds later the mappin route
+  activation/deactivation functions fired.
+- User clock `01:52`: map open. Hovering icons produced the expected
+  `SetSelectedMappin` bursts.
+- Deliberate quest route clicks produced `JournalManager.TrackEntry`, route
+  event enqueue calls for old-route-off/new-route-on, and route event handler
+  calls roughly 11-18 ms later.
+- Custom pin routing used the separate custom-position mappin path, then the
+  shared route activate/deactivate helper.
+
 Build and install from the Fedora toolbox:
 
 ```bash

docs/traffic-system-debrief.md

@@ -302,13 +302,49 @@ deactivates an old route ref and activates a new route ref. That is likely the
 common mappin state transition path for both journal/objective routes and
 custom/player pins.
 
+The newest controlled run confirms the queued route event timing:
+
+```text
+quest route click
+  -> JournalManager.TrackEntry from wrapper return RVA 0x26ac34e
+    -> MappinSystem route-event enqueue old route active=0
+    -> MappinSystem route-event enqueue new route active=1
+      -> 11-18 ms later: MappinRouteEvent::Handle
+        -> MappinSystem::RouteDeactivate(old route key)
+        -> MappinSystem::RouteActivate(new route key)
+          -> route observers at system + 0x280
+```
+
+The click-to-event delay matched the in-game behavior: the old GPS path
+disappears for a few frames, then the new path appears. That makes the route
+observer fanout the next most useful runtime layer to inspect.
+
+The activation/deactivation argument is not an object pointer. It is a 64-bit
+route key. Static disassembly of `0xaa6330` and `0x27abd7c` shows that key being
+looked up in the active-route map at `mappinSystem + 0x1a0`; the resulting map
+entry's `+0x08` field points at the actual route object/smart pointer passed to
+route observers.
+
+The first observer callback set seen at runtime is:
+
+```text
+observer vtable 0x14310e760: slot 0x48 -> 0xaa6610,  slot 0x50 -> 0x27b10c0
+observer vtable 0x143136050: slot 0x48 -> 0xaa6628,  slot 0x50 -> 0x295d4a0
+observer vtable 0x143121458: slot 0x48 -> 0xaa63e0,  slot 0x50 -> 0x286a85c
+```
+
+The installed probe now hooks those callbacks directly and logs the route entry,
+route object, route object vtable slots, and the route object's active byte at
+offset `0x84`.
+
 The most route-building-looking static candidate currently in this chain is
 `0x5625a4`, called once from the bridge at `0x5984ec`. The bridge resolves
 journal route ids through virtual journal-manager calls, collects several route
-descriptor/data pointers, and passes them to `0x5625a4`. The current RED4ext
+descriptor/data pointers, and passes them to `0x5625a4`. Runtime evidence now
-probe hooks this function with a 12-argument inferred signature to determine
+shows this function firing in a dense load-time/minimap setup burst, not during
-whether it builds GPS/path display data or merely updates UI-facing route
+later deliberate map-click route plotting. It may build cached route descriptors
-metadata.
+or GPS display metadata, but it is probably not the direct click-time solver
+entry point.
 
 ## Native False Positives
 

red4ext/EdgeWeightGPS/src/Main.cpp

@@ -131,6 +131,12 @@ constexpr uintptr_t kMappinRouteEventHandlerRva = 0x0AA62D0;
 constexpr uintptr_t kMappinRouteActivateRva = 0x0AA6330;
 constexpr uintptr_t kMappinRouteDeactivateRva = 0x27ABD7C;
 constexpr uintptr_t kRouteBuildCandidateRva = 0x05625A4;
+constexpr uintptr_t kRouteObserver0ActivateRva = 0x0AA6610;
+constexpr uintptr_t kRouteObserver1ActivateRva = 0x0AA6628;
+constexpr uintptr_t kRouteObserver23ActivateRva = 0x0AA63E0;
+constexpr uintptr_t kRouteObserver0DeactivateRva = 0x27B10C0;
+constexpr uintptr_t kRouteObserver1DeactivateRva = 0x295D4A0;
+constexpr uintptr_t kRouteObserver23DeactivateRva = 0x286A85C;
 
 HMODULE gModule = nullptr;
 std::mutex gLogMutex;
@@ -177,6 +183,12 @@ uint32_t gMappinRouteEventHandlerLogCount = 0;
 uint32_t gMappinRouteActivateLogCount = 0;
 uint32_t gMappinRouteDeactivateLogCount = 0;
 uint32_t gRouteBuildCandidateLogCount = 0;
+uint32_t gRouteObserver0ActivateLogCount = 0;
+uint32_t gRouteObserver1ActivateLogCount = 0;
+uint32_t gRouteObserver23ActivateLogCount = 0;
+uint32_t gRouteObserver0DeactivateLogCount = 0;
+uint32_t gRouteObserver1DeactivateLogCount = 0;
+uint32_t gRouteObserver23DeactivateLogCount = 0;
 uint64_t gLogStartTick = 0;
 uint64_t gLogFrequency = 0;
 void* gMappinSetTrackedTarget = nullptr;
@@ -209,12 +221,13 @@ using JournalListenerCallbackFunc = void (*)(void* aListener, void* aEvent);
 using JournalRouteBridgeFunc = bool (*)(void* aThis, void* aEntryHandle);
 using MappinRouteEventEnqueueFunc = void (*)(void* aSystem, uint32_t aRouteId, uint8_t aActive);
 using MappinRouteEventHandlerFunc = void (*)(void* aEvent, void* aRouteHandle);
-using MappinRouteToggleFunc = void (*)(void* aSystem, void* aRouteRef);
+using MappinRouteToggleFunc = void (*)(void* aSystem, uint64_t aRouteKey);
 using RouteBuildCandidateFunc = void (*)(void* aThis, uint32_t aRouteId, uint32_t aAltRouteId,
                                          uint32_t aPreviousRouteId, void* aRoutePositionData,
                                          void* aPrimaryDescriptor, void* aSecondaryDescriptor, void* aRouteData88,
                                          void* aRouteData108, void* aRouteData114, uint8_t aFlag,
                                          uint32_t aMode);
+using RouteObserverCallbackFunc = void (*)(void* aObserver, void* aRouteEntry);
 ProbeFunc gOriginalGpsSystemTick = nullptr;
 JournalTrackEntryFunc gOriginalJournalTrackEntry = nullptr;
 ScriptNativeVoidFunc gOriginalFrameMappinPathWrapper = nullptr;
@@ -252,6 +265,12 @@ MappinRouteEventHandlerFunc gOriginalMappinRouteEventHandler = nullptr;
 MappinRouteToggleFunc gOriginalMappinRouteActivate = nullptr;
 MappinRouteToggleFunc gOriginalMappinRouteDeactivate = nullptr;
 RouteBuildCandidateFunc gOriginalRouteBuildCandidate = nullptr;
+RouteObserverCallbackFunc gOriginalRouteObserver0Activate = nullptr;
+RouteObserverCallbackFunc gOriginalRouteObserver1Activate = nullptr;
+RouteObserverCallbackFunc gOriginalRouteObserver23Activate = nullptr;
+RouteObserverCallbackFunc gOriginalRouteObserver0Deactivate = nullptr;
+RouteObserverCallbackFunc gOriginalRouteObserver1Deactivate = nullptr;
+RouteObserverCallbackFunc gOriginalRouteObserver23Deactivate = nullptr;
 
 std::filesystem::path GetLogPath()
 {
@@ -361,6 +380,11 @@ void AppendReturnRva(std::ostringstream& aLine, const void* aReturnAddress)
     }
 }
 
+void AppendHexValue(std::ostringstream& aLine, const char* aLabel, uint64_t aValue)
+{
+    aLine << " " << aLabel << "=0x" << std::hex << aValue << std::dec;
+}
+
 void LogHookCall(const char* aName, uint32_t aCount, void* aThis, void* a2, void* a3, void* a4)
 {
     std::ostringstream line;
@@ -645,11 +669,53 @@ void LogMappinRouteCollections(const char* aName, uint32_t aCount, void* aSystem
         std::ostringstream observerLine;
         observerLine << "mappin-route-observer " << aName << " call=" << aCount << " index=" << index;
         AppendPointerWithRva(observerLine, "observer", observer);
-        AppendObjectVtableSlots(observerLine, observer, {0x48, 0x50, 0x210, 0x260});
+        AppendObjectVtableSlots(observerLine, observer, {0x48, 0x50});
         LogRed4ext(observerLine.str());
     }
 }
 
+void LogRouteObserverContext(const char* aName, uint32_t aCount, void* aObserver, void* aRouteEntry)
+{
+    auto* observerInner = ReadPointerField(aObserver, 0x08);
+    auto* routeObject = ReadPointerField(aRouteEntry, 0x00);
+
+    std::ostringstream line;
+    line << "hook " << aName << " call=" << aCount;
+    AppendPointerWithRva(line, "observer", aObserver);
+    AppendPointerWithRva(line, "observerInner", observerInner);
+    AppendPointerWithRva(line, "routeEntry", aRouteEntry);
+    AppendPointerWithRva(line, "routeObject", routeObject);
+    AppendPointerField(line, "routeEntry_f08", aRouteEntry, 0x08);
+    AppendPointerField(line, "routeEntry_f10", aRouteEntry, 0x10);
+    AppendReturnRva(line, __builtin_return_address(0));
+    LogRed4ext(line.str());
+
+    std::ostringstream observerLine;
+    observerLine << "route-observer-object " << aName << " call=" << aCount;
+    AppendPointerWithRva(observerLine, "observer", aObserver);
+    AppendObjectVtableSlots(observerLine, aObserver, {0x48, 0x50});
+    LogRed4ext(observerLine.str());
+
+    if (!routeObject)
+    {
+        return;
+    }
+
+    std::ostringstream routeLine;
+    routeLine << "route-observer-route-object " << aName << " call=" << aCount;
+    AppendPointerWithRva(routeLine, "routeObject", routeObject);
+    AppendObjectVtableSlots(routeLine, routeObject, {0x140, 0x188, 0x198, 0x1A8});
+    AppendPointerField(routeLine, "field40", routeObject, 0x40);
+    AppendPointerField(routeLine, "field48", routeObject, 0x48);
+    AppendPointerField(routeLine, "field78", routeObject, 0x78);
+    AppendUint32Field(routeLine, "field80", routeObject, 0x80);
+    AppendByteField(routeLine, "active84", routeObject, 0x84);
+    AppendPointerField(routeLine, "field88", routeObject, 0x88);
+    AppendPointerField(routeLine, "fieldF8", routeObject, 0xF8);
+    AppendPointerField(routeLine, "field120", routeObject, 0x120);
+    LogRed4ext(routeLine.str());
+}
+
 void LogRouteEventFields(const char* aName, uint32_t aCount, void* aEvent)
 {
     uint32_t routeId = 0;
@@ -1087,14 +1153,14 @@ void DetourMappinRouteEventHandler(void* aEvent, void* aRouteHandle)
     {
         const auto callCount = gMappinRouteEventHandlerLogCount;
         void* routeOwner = ReadPointerField(aRouteHandle, 0);
-        void* routeRef = ReadPointerField(routeOwner, 0x40);
+        const auto routeKey = reinterpret_cast<uint64_t>(ReadPointerField(routeOwner, 0x40));
 
         std::ostringstream line;
         line << "hook MappinRouteEvent::Handle call=" << callCount;
         AppendPointerWithRva(line, "event", aEvent);
         AppendPointerWithRva(line, "routeHandle", aRouteHandle);
         AppendPointerWithRva(line, "routeOwner", routeOwner);
-        AppendRouteRefFields(line, "routeRef", routeRef);
+        AppendHexValue(line, "routeKey", routeKey);
         AppendReturnRva(line, __builtin_return_address(0));
         LogRed4ext(line.str());
         LogRouteEventFields("handler-before", callCount, aEvent);
@@ -1107,7 +1173,7 @@ void DetourMappinRouteEventHandler(void* aEvent, void* aRouteHandle)
     }
 }
 
-void DetourMappinRouteActivate(void* aSystem, void* aRouteRef)
+void DetourMappinRouteActivate(void* aSystem, uint64_t aRouteKey)
 {
     constexpr uint32_t kMaxCalls = 64;
 
@@ -1117,7 +1183,7 @@ void DetourMappinRouteActivate(void* aSystem, void* aRouteRef)
         std::ostringstream line;
         line << "hook MappinSystem::RouteActivate call=" << callCount;
         AppendPointerWithRva(line, "system", aSystem);
-        AppendRouteRefFields(line, "routeRef", aRouteRef);
+        AppendHexValue(line, "routeKey", aRouteKey);
         AppendReturnRva(line, __builtin_return_address(0));
         LogRed4ext(line.str());
         LogMappinRouteCollections("activate-before", callCount, aSystem);
@@ -1126,11 +1192,11 @@ void DetourMappinRouteActivate(void* aSystem, void* aRouteRef)
 
     if (gOriginalMappinRouteActivate)
     {
-        gOriginalMappinRouteActivate(aSystem, aRouteRef);
+        gOriginalMappinRouteActivate(aSystem, aRouteKey);
     }
 }
 
-void DetourMappinRouteDeactivate(void* aSystem, void* aRouteRef)
+void DetourMappinRouteDeactivate(void* aSystem, uint64_t aRouteKey)
 {
     constexpr uint32_t kMaxCalls = 64;
 
@@ -1140,7 +1206,7 @@ void DetourMappinRouteDeactivate(void* aSystem, void* aRouteRef)
         std::ostringstream line;
         line << "hook MappinSystem::RouteDeactivate call=" << callCount;
         AppendPointerWithRva(line, "system", aSystem);
-        AppendRouteRefFields(line, "routeRef", aRouteRef);
+        AppendHexValue(line, "routeKey", aRouteKey);
         AppendReturnRva(line, __builtin_return_address(0));
         LogRed4ext(line.str());
         LogMappinRouteCollections("deactivate-before", callCount, aSystem);
@@ -1149,7 +1215,7 @@ void DetourMappinRouteDeactivate(void* aSystem, void* aRouteRef)
 
     if (gOriginalMappinRouteDeactivate)
     {
-        gOriginalMappinRouteDeactivate(aSystem, aRouteRef);
+        gOriginalMappinRouteDeactivate(aSystem, aRouteKey);
     }
 }
 
@@ -1187,6 +1253,59 @@ void DetourRouteBuildCandidate(void* aThis, uint32_t aRouteId, uint32_t aAltRout
     }
 }
 
+void DispatchRouteObserverCallback(const char* aName, uint32_t& aCounter, RouteObserverCallbackFunc aOriginal,
+                                   void* aObserver, void* aRouteEntry)
+{
+    constexpr uint32_t kMaxCalls = 96;
+
+    if (aCounter < kMaxCalls)
+    {
+        LogRouteObserverContext(aName, aCounter, aObserver, aRouteEntry);
+        ++aCounter;
+    }
+
+    if (aOriginal)
+    {
+        aOriginal(aObserver, aRouteEntry);
+    }
+}
+
+void DetourRouteObserver0Activate(void* aObserver, void* aRouteEntry)
+{
+    DispatchRouteObserverCallback("RouteObserver0::Activate slot48", gRouteObserver0ActivateLogCount,
+                                  gOriginalRouteObserver0Activate, aObserver, aRouteEntry);
+}
+
+void DetourRouteObserver1Activate(void* aObserver, void* aRouteEntry)
+{
+    DispatchRouteObserverCallback("RouteObserver1::Activate slot48", gRouteObserver1ActivateLogCount,
+                                  gOriginalRouteObserver1Activate, aObserver, aRouteEntry);
+}
+
+void DetourRouteObserver23Activate(void* aObserver, void* aRouteEntry)
+{
+    DispatchRouteObserverCallback("RouteObserver23::Activate slot48", gRouteObserver23ActivateLogCount,
+                                  gOriginalRouteObserver23Activate, aObserver, aRouteEntry);
+}
+
+void DetourRouteObserver0Deactivate(void* aObserver, void* aRouteEntry)
+{
+    DispatchRouteObserverCallback("RouteObserver0::Deactivate slot50", gRouteObserver0DeactivateLogCount,
+                                  gOriginalRouteObserver0Deactivate, aObserver, aRouteEntry);
+}
+
+void DetourRouteObserver1Deactivate(void* aObserver, void* aRouteEntry)
+{
+    DispatchRouteObserverCallback("RouteObserver1::Deactivate slot50", gRouteObserver1DeactivateLogCount,
+                                  gOriginalRouteObserver1Deactivate, aObserver, aRouteEntry);
+}
+
+void DetourRouteObserver23Deactivate(void* aObserver, void* aRouteEntry)
+{
+    DispatchRouteObserverCallback("RouteObserver23::Deactivate slot50", gRouteObserver23DeactivateLogCount,
+                                  gOriginalRouteObserver23Deactivate, aObserver, aRouteEntry);
+}
+
 void DetourFrameMappinPathWrapper(void* aThis, void* aStack, void* aResult)
 {
     if (gFrameMappinPathWrapperLogCount < 64)
@@ -1829,6 +1948,24 @@ RED4EXT_C_EXPORT bool RED4EXT_CALL Main(RED4ext::v1::PluginHandle aHandle, RED4e
         AttachProbeHook("RouteBuildCandidate 0x5625a4", kRouteBuildCandidateRva,
                         reinterpret_cast<void*>(&DetourRouteBuildCandidate),
                         reinterpret_cast<void**>(&gOriginalRouteBuildCandidate));
+        AttachProbeHook("RouteObserver0::Activate slot48", kRouteObserver0ActivateRva,
+                        reinterpret_cast<void*>(&DetourRouteObserver0Activate),
+                        reinterpret_cast<void**>(&gOriginalRouteObserver0Activate));
+        AttachProbeHook("RouteObserver1::Activate slot48", kRouteObserver1ActivateRva,
+                        reinterpret_cast<void*>(&DetourRouteObserver1Activate),
+                        reinterpret_cast<void**>(&gOriginalRouteObserver1Activate));
+        AttachProbeHook("RouteObserver23::Activate slot48", kRouteObserver23ActivateRva,
+                        reinterpret_cast<void*>(&DetourRouteObserver23Activate),
+                        reinterpret_cast<void**>(&gOriginalRouteObserver23Activate));
+        AttachProbeHook("RouteObserver0::Deactivate slot50", kRouteObserver0DeactivateRva,
+                        reinterpret_cast<void*>(&DetourRouteObserver0Deactivate),
+                        reinterpret_cast<void**>(&gOriginalRouteObserver0Deactivate));
+        AttachProbeHook("RouteObserver1::Deactivate slot50", kRouteObserver1DeactivateRva,
+                        reinterpret_cast<void*>(&DetourRouteObserver1Deactivate),
+                        reinterpret_cast<void**>(&gOriginalRouteObserver1Deactivate));
+        AttachProbeHook("RouteObserver23::Deactivate slot50", kRouteObserver23DeactivateRva,
+                        reinterpret_cast<void*>(&DetourRouteObserver23Deactivate),
+                        reinterpret_cast<void**>(&gOriginalRouteObserver23Deactivate));
         AttachProbeHook("FrameMappinPathWrapper", kFrameMappinPathWrapperRva,
                         reinterpret_cast<void*>(&DetourFrameMappinPathWrapper),
                         reinterpret_cast<void**>(&gOriginalFrameMappinPathWrapper));
@@ -1885,6 +2022,12 @@ RED4EXT_C_EXPORT bool RED4EXT_CALL Main(RED4ext::v1::PluginHandle aHandle, RED4e
         DetachProbeHook("MappinSystem::RouteActivate", kMappinRouteActivateRva);
         DetachProbeHook("MappinSystem::RouteDeactivate", kMappinRouteDeactivateRva);
         DetachProbeHook("RouteBuildCandidate 0x5625a4", kRouteBuildCandidateRva);
+        DetachProbeHook("RouteObserver0::Activate slot48", kRouteObserver0ActivateRva);
+        DetachProbeHook("RouteObserver1::Activate slot48", kRouteObserver1ActivateRva);
+        DetachProbeHook("RouteObserver23::Activate slot48", kRouteObserver23ActivateRva);
+        DetachProbeHook("RouteObserver0::Deactivate slot50", kRouteObserver0DeactivateRva);
+        DetachProbeHook("RouteObserver1::Deactivate slot50", kRouteObserver1DeactivateRva);
+        DetachProbeHook("RouteObserver23::Deactivate slot50", kRouteObserver23DeactivateRva);
         DetachProbeHook("FrameMappinPathWrapper", kFrameMappinPathWrapperRva);
         DetachProbeHook("FrameMappinPathCore", kFrameMappinPathCoreRva);
         DetachProbeHook("SetSelectedMappinWrapper", kSetSelectedMappinWrapperRva);