Hi Unreal,
We have been working extensively with behavior trees in our project and have run into a problem which we have been unable to solve. We will try to give as much detail as possible for you to reproduce the problem, but we will simplify the details of the implementation a bit.
We have implemented a decorator that functions as a ‘scope’ object, overriding OnNodeActivation and OnNodeDeactivation. OnNodeActivation sets a boolean in the actor controlled by the AI controller to true, and OnNodeDeactivation sets that boolean to false. We were operating under the assumption that an activation will always be followed by a deactivation and that deactivation will only be called once. As such deactivation verifies (asserts) that the boolean was not already set to false. This assert however was triggered, but with a very low reproduction rate making it hard to track the underlying issue.
To further look into the issue we added a memory struct to the decorator as is done in the engine also and added extra logging to trace the activation / deactivation pattern. We found that when the assert is triggered, OnNodeDeactivation is called twice in a row (but with some time in between). We added state to the memory struct to try to detect this double activation setting a bool (Activated) when OnNodeActivation is called and setting a different bool (Deactivated) when OnNodeDeactivation is called. Both are set to false in CalculateRawConditionValue and InitializeMemory. We expected that on the second OnNodeDeactivation call Deactivated would already be set to true, but this happened not to be the case. In the end we logged the memory address of the used memory struct as well and found that upon the 2nd entry of OnNodeDeactivation a different address was used.
An example of the log:
[2016.03.14-14.16.22:502][355]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::InitializeMemory | 0xea54e98
[2016.03.14-14.16.23:270][378]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::CleanupMemory | 0xda87898
[2016.03.14-14.16.23:437][383]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::InitializeMemory | 0x10294518
[2016.03.14-14.16.24:171][405]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::CleanupMemory | 0xc74fa18
[2016.03.14-14.16.24:340][410]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::InitializeMemory | 0x10294998
[2016.03.14-14.16.24:873][426]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::CleanupMemory | 0xb1c0f18
[2016.03.14-14.16.25:039][431]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::InitializeMemory | 0xe2bf618
[2016.03.14-14.16.25:876][456]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::CleanupMemory | 0xda85d98
[2016.03.14-14.16.26:042][461]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::InitializeMemory | 0xe1c3918
[2016.03.14-14.16.26:444][473]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::CalculateRawConditionValue | 0xe1bdf18
[2016.03.14-14.16.26:444][473]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::OnNodeActivation | 0xe1bdf18
[2016.03.14-14.16.27:079][492]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::OnNodeDeactivation | 0xe1bdf18
[2016.03.14-14.16.27:711][511]LogMyBehaviorTree:VeryVerbose: BP_AICharacter_C_1: UMyScopeDecorator::OnNodeDeactivation | 0xb1bf598
Assert triggered here.
The last hexadecimal number on each log line here is the address of the node memory (Obtained through GetNodeMemory(SearchData))
As you can see the memory address it the same for the CalculateRawConditionValue, OnNodeActivation and OnNodeDeactivation. But then the last OnNodeDeactivation has different adress. The state of that memory is not the initial state of the memory (both booleans set to false) nor the state after the first OnNodeDeactivation (both booleans set to true). The state is what the memory would be after OnNodeActivation but before OnNodeDeactivation. To us it seems that the underlying system might have made a copy of the memory after OnNodeActivation and used that for the second OnNodeDeactivation.
The callstack for the 2nd deactivation is:
FDebug::AssertFailed()
UMyScopeDecorator::OnNodeDeactivation()
UBTCompositeNode::NotifyDecoratorsOnDeactivation()
UBTCompositeNode::OnChildDeactivation()
OnChildDeactivation()
UBehaviorTreeComponent::DeactivateUpTo()
UBehaviorTreeComponent::ProcessExecutionRequest()
UBehaviorTreeComponent::TickComponent()
ConditionalTickComponent()
FActorComponentTickFunction::ExecuteTick()
FTickFunctionTask::DoTask()
TGraphTask<FTickFunctionTask>::ExecuteTask()
Execute()
FTaskThread::ProcessTasks()
FTaskThread::ProcessTasksUntilQuit()
FTickTaskSequencer::ReleaseTickGroup()
FTickTaskManager::RunTickGroup()
UWorld::RunTickGroup()
UWorld::Tick()
UGameEngine::Tick()
FEngineLoop::Tick()
EngineTick()
GuardedMain()
main()
Some extra information that might be helpful:
- We have seen this issue on a linux server, windows client and windows UE4 editor.
- The decorator is not instanced (bCreateNodeInstance = false)
- The decorator is only used once within the tree and is placed on a Wait task.
- The decorator is placed in a behavior tree which is run from another behavior tree using the RunBehavior task.
- The NodeResult of the 2nd OnNodeDeactivation is Succeeded.
What we would expect:
- OnNodeDeactivation NOT to be called twice in a row.
- Otherwise that this event would at least be detectable by tracking additional memory.
We hope you can provide some insight into what is going wrong, or if we are doing something wrong. Thanks in advance.