Debugging Example
As we work to streamline and refine the debugging process, we wanted to share an example of the steps we took to troubleshoot a real issue we were having. The actual problem will likely differ from what you're trying to debug, but the steps taken below should offer a good template to follow.
The Issue
NPCs were browsing props that were not set-up to be browsed. E.g. The forge does not have a slot on it's Smart Object definition that would allow someone to come up and browse.
The Troubleshooting Process
Before starting PIE, go into the Output log and clear all the messages. This will remove anything stale from a previous session.
In the editor fly to the location the bug will happen, in this case in front of the blacksmith table.
Make sure you’re spawn using the current camera position.
Dock the Visual Logger to your screen. The Visual Logger is in Tools → Debug → Visual Logger.
Clear any previous captures from the Visual Logger
Start the Visual Logger
Hit PIE
Wait for an NPC to come by and do a browse at the sword table or the forge
As soon as you realize the NPC is browsing, hit pause. Also pause the Visual Logger. Background processes can keep feeding events.
You need to figure out the identity of the NCP. A convenient way is to hit F8, which disconnects from your pawn. You can now fly around to inspect the paused world.
Click the NPC to select it
In the Outliner, you’ll see the NPCs name. We encode the entity id into the name. In my case, its' BP_Villager_04[VILLAGER_villager_716]. The entity id is the number at the end, 716
In the Visual Logger, the left side shows the names of the actors that have recorded Visual Logger events. There are a lot of them. The names here don’t have the entityid, unfortunately. To help find which one you care about, type the entityid we are looking for in the “Log Data Search” filter. This will reduce the number of rows to just ones that mention 716 in their logs. One of them is going to be the NPC.
Click on an BP_NPCController_XXX row and then click on an event in that row.
By clicking the event, you can see the data snapshot in the bottom left and any logs targeting that actor in the bottom right. But we still need to find the right NPC.
In the data snapshot, expand the WorldStateFacts. The entityid for the selected actor will be shown. If it’s not the one you’re looking for, click on a different NPC row until you find it. I’m looking for EntityId: 716
Once you've found it, type the name of the row in the search bar above it so you just see that one row. Clear the entityid you typed into the “Log Data Search” bar.
All the vertical bars to the right are events that happened in different frames. Got the very last frame and click it. This is what the NPC is doing right before you paused the game.
Expand the BehaviorTree items on the bottom left to see more info about the actions.
Since the NPC is already browsing, we need to go back in time to when the npc was told to browse, so we can find out why it was told to browse the sword.
Hold CTRL down and scroll up on the scroll wheel to zoom in to the events at the end. They will start to separate. Stop zooming once you have maybe 20 seconds in view.
You should currently see the npc in a behaviortree doing a BT_Bitpart_Main->BT_Bitpart_UseOnSurface->BT_Bitpart_MoveAndUseSmartObject.
As you go back in time, you’ll see that chain of BehaviorTrees reduce until it’s just BT_BitpartMain. That would be right before the NPC was told to browse. Find that event. It should have logs that say something like “LogBitpartAIGameplay (Verbose) FBehaviorTreeAction::OnBegin - Beginning Action. Agent[VILLAGER, villager, 716] Verb[browse idle]”
Unfortunately, this log doesn’t mention the actor the NPC should browse.
Go forward in time until you see BT_Bitpart_UseOnSurface is showing a ResolveActionSpec. This is where it translates the data from the director to store it into the blackboard for the ai to use during its actions.
Open the Blackboard in the snapshot data. Should be right above BehaviorTree entry
A use on surface activity is intended to use an optional prop being held on a surface prop. Something like using the rag on counter would mean the rag would be in the hand, and the counter would be the surface. For browsing, there’s no requirement for the held prop, just the surface. Look for what the SurfaceActor is set to.
The SurfaceActor is set to None. And strangely, the ObjectActor is set to BP_Townsperson_Market_Stand_C_xxxxx
So the marketstand was being specified, but it’s in the wrong blackboard variable.
If we look at the domain content in Coppola, we can go to our project, Selkie. Then it’s the Townsperson doing the Browse Shelf.
There’s just 1 method that tells the villager to “browse idle” object: market_shelf.
This should be villager “browse idle” surface: market_shelf.
That’s the bug. Fixing it is just changing to use the “surface” parameter instead of “object”.
But why was it browsing the sword? We should follow the trail from the command “browse idle”
Open the BAM_Townsperson and find “browse idle”. This tells you what BehaviorTree it will use and what AnimTag it will feed the smartobject to help identify what prop to consider. “browse idle” uses BT_Bitpart_UseOnSurface, as we saw before. And the AnimTag is “BitpartAnim.Browse”.
Go back to the VisualLogger and go forward in time until you get to BT_Bitpart_UseOnSurface doing step “Find And Use Smart Object”. This is the thing that will take the object the director told it to use and find it in the world. It also could rebind to use a similar object if it wanted.
Find the log that says “UBTTask_BitpartFindSmartObject::ExecuteTask - Making request to find smartobjects”. This is going to show the search criteria it used to find the surface actor. Ours is “LogSmartObject (Verbose) UBTTask_BitpartFindSmartObject::ExecuteTask - Making request to find smartobjects | Avatar[BP_Villager_04_C_1] AvatarLocation[X=-1120.000 Y=1330.000 Z=194.757] Radius[2500.0] Filter.ActivityRequirements[ALL(BitpartAnim.Browse)] Filter.UserTags[Empty] StrictMatch[0] StrictTarget[None]”
You can see that it specified Filter.ActivityRequirements of ALL(BitpartAnim.Browse). That’s the correct AnimTag. The result is on the next line: “UBTTask_BitpartFindSmartObject::ExecuteTask - Found smart object | Avatar[BP_Villager_04_C_1] SmartObject[BP_Blacksmith_Sword_C_UAID_BCC746F46F11CAD102_1496881983] SlotHandle[{0318E45E-4127-924E-1EEE-6991BD043578}:1]”
It found the sword “BP_Blacksmith_Sword_C_xxxx”! Why? It should have only swapped to a different prop of the same type. The Market_Shelf and the sword are not the same prop type.
Ah, but the SurfaceActor was empty, so it didn’t know what PropType to look for. But why the Sword?
Open the BP_Blacksmith_Sword asset. Select its SmartObject in the components, and open the SmartObjectDefinition it references in the details: SO_Blacksmith_Sword
The sword has a Browse slot. Open that slot up. The ActivityTags show Bitpart.Prop.Sword and BitpartAnim.Browse.
Open the smartobject for the market_stand: SO_Market_Stand
It has an Idle slot, which is used for browse. It has ActivityTags of Bitpart.Prop.MarketStand and BitpartAnim.Browse.
The ActivityTags filter out to just specific PropTypes and AnimTags. So we should have only found other Bitpart.Prop.MarketStand. But because we didn’t have a SurfaceActor, we didn’t have anything feeding the ActivityTags with a PropType. Recall on step 39, the ActivityTags were only set to “ALL(BitpartAnim.Browse)”. No PropType. So any prop that had a BitpartAnim.Browse would do.
Now we know why it chose the sword.
We can help get to the solution faster if we detect no surface when we’re doing a UseOnSurface action.
Last updated