Assertion Failed: Index >= 0 in AsyncLoading::PostLoadDeferredObjects()

FacePalm.exe · May 6, 2016, 1:55am

So we have a large level which contains about 34 streaming levels, each with a reasonable number of objects within them, with a streaming distance of ~34000.

Randomly moving the character throughout this level causes the following assert to happen randomly:

[2016.05.06-01.28.31:141][909]LogWindows:Error: === Critical error: ===

Assertion failed: Index >= 0 [File:d:\perforce\submerged_mobile\engine\source\runtime\coreuobject\public\uobject\UObjectArray.h] [Line: 401] 

KERNELBASE.dll

UE4Editor-Core.dll!FOutputDeviceWindowsError::Serialize() [d:\perforce\submerged_mobile\engine\source\runtime\core\private\windows\windowsplatformoutputdevices.cpp:95]

UE4Editor-Core.dll!FOutputDevice::Logf__VA() [d:\perforce\submerged_mobile\engine\source\runtime\core\private\misc\outputdevice.cpp:149]

UE4Editor-Core.dll!FDebug::AssertFailed() [d:\perforce\submerged_mobile\engine\source\runtime\core\private\misc\outputdevice.cpp:430]

UE4Editor-CoreUObject.dll!FAsyncPackage::PostLoadDeferredObjects() [d:\perforce\submerged_mobile\engine\source\runtime\coreuobject\private\serialization\asyncloading.cpp:1941]

UE4Editor-CoreUObject.dll!FAsyncLoadingThread::ProcessLoadedPackages() [d:\perforce\submerged_mobile\engine\source\runtime\coreuobject\private\serialization\asyncloading.cpp:716]

UE4Editor-CoreUObject.dll!FAsyncLoadingThread::TickAsyncLoading() [d:\perforce\submerged_mobile\engine\source\runtime\coreuobject\private\serialization\asyncloading.cpp:788]

UE4Editor-CoreUObject.dll!ProcessAsyncLoading() [d:\perforce\submerged_mobile\engine\source\runtime\coreuobject\private\serialization\asyncloading.cpp:2233]

UE4Editor-CoreUObject.dll!StaticTick() [d:\perforce\submerged_mobile\engine\source\runtime\coreuobject\private\uobject\uobjectglobals.cpp:409]

UE4Editor-UnrealEd.dll!UEditorEngine::Tick() [d:\perforce\submerged_mobile\engine\source\editor\unrealed\private\editorengine.cpp:997]

UE4Editor-UnrealEd.dll!UUnrealEdEngine::Tick() [d:\perforce\submerged_mobile\engine\source\editor\unrealed\private\unrealedengine.cpp:370]

UE4Editor.exe!FEngineLoop::Tick() [d:\perforce\submerged_mobile\engine\source\runtime\launch\private\launchengineloop.cpp:2644]

UE4Editor.exe!GuardedMain() [d:\perforce\submerged_mobile\engine\source\runtime\launch\private\launch.cpp:142]

UE4Editor.exe!GuardedMainWrapper() [d:\perforce\submerged_mobile\engine\source\runtime\launch\private\windows\launchwindows.cpp:126]

UE4Editor.exe!WinMain() [d:\perforce\submerged_mobile\engine\source\runtime\launch\private\windows\launchwindows.cpp:200]

UE4Editor.exe!__scrt_common_main_seh() [f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl:264]

kernel32.dll

ntdll.dll

ntdll.dll

This is also not limited to the Editor/PC, as I am also seeing the same crash on our iOS build:

May  6 11:14:35 iPad-Pro-1 Submerged[789] <Warning>: [2016.05.06-01.14.35:551][811]LogStreaming:Display: UWorld::AddToWorld: routing Initialize on actors for /Game/Maps/Streaming/d24 took (less than) 24.92 ms
May  6 11:14:35 iPad-Pro-1 Submerged[789] <Warning>: [2016.05.06-01.14.35:741][814]LogEngine:Error: FGenericPlatformStackWalk::StackWalkAndDump(char*, unsigned long, int, void*) Address = 0x9c8c38   (filename not found) [in Submerged]
	
	SignalHandler(int, __siginfo*, void*) Address = 0xacfbdc   (filename not found) [in Submerged]
	
	_sigtramp() Address = 0x830e194c (filename not found) [in libsystem_platform.dylib]
	
	FAsyncPackage::PostLoadDeferredObjects(double, bool, float&) Address = 0xdb1030   (filename not found) [in Submerged]
	
	FAsyncLoadingThread::ProcessLoadedPackages(bool, bool, float, int) Address = 0xdafb6c   (filename not found) [in Submerged]
	
	FAsyncLoadingThread::TickAsyncLoading(bool, bool, float, int) Address = 0xdb2278   (filename not found) [in Submerged]
	
	ProcessAsyncLoading(bool, bool, float) Address = 0xdc01cc   (filename not found) [in Submerged]
	
	StaticTick(float, bool, float) Address = 0xf33de0   (filename not found) [in Submerged]
	
	UGameEngine::Tick(float, bool) Address = 0x2c1f5d4  (filename not found) [in Submerged]
	
	FEngineLoop::Tick() Address = 0x5efbd8   (filename not found) [in Submerged]
	
	-[IOSAppDelegate MainAppThread:] Address = 0xacfea4   (filename not found) [in Submerged]
	
	<redacted>() Address = 0x83e57e1c (filename not found) [in Foundation]
	
	<redacted>() Address = 0x830e7b28 (filename not found) [in libsystem_pthread.dylib]
	
	<redacted>() Address = 0x830e7a8c (filename not found) [in libsystem_pthread.dylib]
	
	thread_start() Address = 0x830e5028 (filename not found) [in libsystem_pthread.dylib]

To be honest I have no idea where to begin debugging this, as it seems to be breaking on the following line:

		for (UObject* Object : DeferredFinalizeObjects)
		{
			// This line is the culprit
			Object->AtomicallyClearInternalFlags(EInternalObjectFlags::AsyncLoading); // <---
		}

This seems like quite the nasty assert, possibly a race condition of some sort.

I’ve attached the full editor log here and the iOS log here.

Let me know if you need any more info.

Cheers.

anonymous_user_41845f4a · May 6, 2016, 3:36pm

Hello FacePalm.exe,

As this is a randomly occurring issue as you mentioned and the logs don’t really say much as to what caused the assert, would you be willing to do some tests to attempt to narrow down the problem?

It would be helpful if you could migrating the level that you’re asserting on to a new project to see if it happens there as well.

Also, did this work previously as in a previous version of some sort?

FacePalm.exe · May 6, 2016, 10:33pm

I’ll try to migrate the levels on Monday, (currently Saturday here)

And yes, it does work fine in previous versions, as I’m working on the mobile version of our currently shipped UE4 title, which is running 4.7.

This crash became prevalent after the upgrade to 4.11.

I vaguely remember seeing this issue back then, however it was incredibly rare.

FacePalm.exe · May 10, 2016, 6:58am

So spent today and yesterday migrating our content across to a new blank project, and it does indeed assert still.

I was actually able to catch it in the debugger and looking at the DeferredFinalizedObjects array it seems that the objects contained within it are being garbage collected midway through initialization.

Find a quick shot of the array here:

Our current theory is the level is being streamed out and garbage collected before it has a chance to fully initialize.

Note that this is happening to a LOD level, so we are not 100% certain whether it uses the TilesStreamingTimeThreshold variable correctly or not.

anonymous_user_41845f4a · May 10, 2016, 2:07pm

Thank you for the information. It seems like you’re on the right track as I was able to find a similar report in our system already. For tracking reasons, the report’s number is UE-30285. The bug report refers to a particular problem happening in KiteDemo with objects being used for Async loading being released before it finishes loading all of the packages. A fix has gone into one of our internal branches and is being verified at the moment, so we should be able to see an integration into main / push to Github soon.

I’ll let you know about the details as they develop.

Have a nice day!

LuaChunk · May 10, 2016, 11:49pm

Thanks Matt,
This is currently holding us up quite a bit so a link to the github commit once it’s in would be awesome!

anonymous_user_41845f4a · May 11, 2016, 1:31pm

Looks like this change went straight into Release instead of Master so here it is:

.com/EpicGames/UnrealEngine/commit/2fb69465