Description

A licensee reported occasionally triggers an ensure during automation testing, potentially when the GameThread flushes Visual Logger via FVisualLogger::Flush() and an animation worker thread executing an FAnimNode_FootPlacement is waiting to acquire a lock.

Ensure condition failed: bIsInitialized && Other.bIsInitialized [File:...\Engine\Private\VisualLogger\VisualLoggerTypes.cpp] [Line: 175] 
Both entries need to be initialized to move to the other 
Steps to Reproduce

Use a gym with some animated character

  1. add some VisualLogger nodes in the Animation graph used by the characters
  2. edit native code in Actor.cpp and add the following call
    void AActor::Tick( float DeltaSeconds )
    {
        FVisualLogger::Get().Flush();
        ...
  1. Open VisualLogger (from the console: vislog or from the )
  2. Start recording in VisualLogger
  3. PIE

You should eventually hit an ensure in the multithread detectors and can access the 2 callstacks involved in the race condition

Callstack

Worker thread:

[Inline Frame] FVisualLogEntry::MoveTo::__l2::<lambda_1>::operator()()
FVisualLogEntry::MoveTo(FVisualLogEntry &)
FVisualLogger::GetEntryToWrite(const UObject *, double, ECreateIfNeeded)
[Inline Frame] FVisualLogger::CheckVisualLogInputInternal(const UObject *, const FName &, ELogVerbosity::Type, UWorld * *, FVisualLogEntry * *)
FVisualLogger::SphereLogfImpl(const UObject *, const FName &, ELogVerbosity::Type, const UE::Math::TVector<double> &, float, const FColor &, bool, const wchar_t *, ...)
[Inline Frame] FVisualLogger::SphereLogf(const UObject *, const FName &, ELogVerbosity::Type, const UE::Math::TVector<double> &, float, const FColor &, bool, const wchar_t[1] &)
FAnimNode_FootPlacement::DrawVLog(const UE::Anim::FootPlacement::FEvaluationContext &, const UE::Anim::FootPlacement::FLegRuntimeData &, const UE::Anim::FootPlacement::FPlantResult &)
FAnimNode_FootPlacement::EvaluateSkeletalControl_AnyThread(FComponentSpacePoseContext &, TArray<FBoneTransform,TSizedDefaultAllocator<32>> &)
FAnimNode_SkeletalControlBase::EvaluateComponentSpace_AnyThread(FComponentSpacePoseContext &)
<callstack trimmed>

Game Thread:

FAutomationTestExecutionInfo::AddEvent(const FAutomationEvent &, int, bool)
FAutomationTestBase::AddInfo(const FString &, int, bool)
FAutomationTestFramework::FAutomationTestOutputDevice::Serialize(const wchar_t *, ELogVerbosity::Type, const FName &)
[Inline Frame] FOutputDeviceRedirector::Serialize::__l2::<lambda>(FOutputDevice * &, const wchar_t * const &, const ELogVerbosity::Type &, const FName &, const double &)
[Inline Frame] Invoke(FOutputDeviceRedirector::Serialize::__l2::void <lambda>(void) &, FOutputDevice * &, const wchar_t * const &, const ELogVerbosity::Type &, const FName &, const double &)
[Inline Frame] UE::Private::FOutputDeviceRedirectorState::BroadcastTo(const unsigned int, const TArray<FOutputDevice *,TSizedDefaultAllocator<32>> &, const TBitArray<TSizedInlineAllocator<1,32,TSizedDefaultAllocator<32>>> &, FOutputDeviceRedirector::Serialize::__l2::void <lambda>(void) &&, const wchar_t * const &, const ELogVerbosity::Type &, const FName &, const double &)
FOutputDeviceRedirector::Serialize(const wchar_t *, ELogVerbosity::Type, const FName &, const double)
FFeedbackContext::Serialize(const wchar_t *, ELogVerbosity::Type, const FName &, double)
FAutomationTestFramework::FAutomationTestMessageFilter::Serialize(const wchar_t *, ELogVerbosity::Type, const FName &, double)
FAutomationTestFramework::FAutomationTestMessageFilter::Serialize(const wchar_t *, ELogVerbosity::Type, const FName &)
[Inline Frame] FMsg::LogV::__l5::<lambda>()
[Inline Frame] AutoRTFM::Open::__l2::<lambda>(void *)
[Inline Frame] AutoRTFM::Open::__l2::void <lambda>(void)::<lambda_invoker_cdecl>(void *)
[Inline Frame] autortfm_open(void(void *), void *)
[Inline Frame] AutoRTFM::Open(const FMsg::LogV::__l5::void <lambda>(void) &)
FMsg::LogV(const char *, int, const FName &, ELogVerbosity::Type, const wchar_t *, char *)
UE::Logging::Private::BasicLog(const FLogCategoryBase &, const UE::Logging::Private::FStaticBasicLogRecord *, ...)
FVisualLoggerBinaryFileDevice::StopRecordingToFile(double)
FVisualLogger::SetIsRecordingToFile(bool)

<callstack trimmed>

AActor::TickActor(float, ELevelTick, FActorTickFunction &)
FActorTickFunction::ExecuteTick(float, ELevelTick, ENamedThreads::Type, const TRefCountPtr<FGraphEvent> &)
FTickFunctionTask::DoTask(ENamedThreads::Type, const TRefCountPtr<FGraphEvent> &)
TGraphTask<FTickFunctionTask>::ExecuteTask(TArray<FBaseGraphTask *,TSizedDefaultAllocator<32>> &, ENamedThreads::Type, bool)
[Inline Frame] FBaseGraphTask::Execute(TArray<FBaseGraphTask *,TSizedDefaultAllocator<32>> &, ENamedThreads::Type, bool)
FNamedTaskThread::ProcessTasksNamedThread(int, bool)
FNamedTaskThread::ProcessTasksUntilQuit(int)
[Inline Frame] FTaskGraphCompatibilityImplementation::ProcessThreadUntilRequestReturn(ENamedThreads::Type)
FTaskGraphCompatibilityImplementation::WaitUntilTasksComplete(const TArray<TRefCountPtr<FGraphEvent>,TSizedInlineAllocator<4,32,TSizedDefaultAllocator<32>>> &, ENamedThreads::Type)
FTickTaskSequencer::ReleaseTickGroup(ETickingGroup, bool)
FTickTaskManager::RunTickGroup(ETickingGroup, bool)
UWorld::RunTickGroup(ETickingGroup, bool)
UWorld::Tick(ELevelTick, float)
UEditorEngine::Tick(float, bool)
UUnrealEdEngine::Tick(float, bool)
FEngineLoop::Tick()
[Inline Frame] EngineTick()
GuardedMain(const wchar_t *)
LaunchWindowsStartup(HINSTANCE__ *, HINSTANCE__ *, char *, int, const wchar_t *)
WinMain(HINSTANCE__ *, HINSTANCE__ *, char *, int) 

Have Comments or More Details?

There's no existing public thread on this issue, so head over to Questions & Answers just mention UE-228253 in the post.

0
Login to Vote

Fixed
ComponentUE - AI - Debugging
Affects Versions5.4
Target Fix5.6
Fix Commit38249940
CreatedOct 18, 2024
ResolvedNov 22, 2024
UpdatedNov 22, 2024
View Jira Issue