Crash in HttpManagerThread

PhroZenOne · September 16, 2016, 2:12pm

When upgrading to 4.13 from 4.12.5 we started to see sporadic crashes in the HttpManagerThread.

I havn’t been able to reliably reproduce the crash but it occurs fairly often for us. We do not have any changes to the engine.

We are using FHttpModule::Get() for creating and sending http calls. (btw, the FHttpModule has a comment that says use the FHttpFactory but there is no such thing, I presume it’s a leftover).

Anyone has any ides on what might cause this and how to get around it?

[2016.09.16-13.21.26:420][543]LogWindows:Warning: CreateProc failed (2) ..\..\..\Engine\Binaries/Win64/CrashReportClient.exe  -AppName=UE4-valhalla -CrashGUID=UE4CC-Windows-2C4B05B144897EC941C9D286F85279CC_0000 -DebugSymbols=..\..\..\Engine\Intermediate\Symbols
[2016.09.16-13.21.26:420][543]LogWindows: Could not start CrashReportClient.exe
[2016.09.16-13.21.26:420][543]LogMemory: Platform Memory Stats for WindowsNoEditor
[2016.09.16-13.21.26:420][543]LogMemory: Process Physical Memory: 745.67 MB used, 982.40 MB peak
[2016.09.16-13.21.26:420][543]LogMemory: Process Virtual Memory: 1410.51 MB used, 1747.79 MB peak
[2016.09.16-13.21.26:420][543]LogMemory: Physical Memory: 3942.22 MB used, 8132.55 MB total
[2016.09.16-13.21.26:420][543]LogMemory: Virtual Memory: 2052.29 MB used, 134217728.00 MB total
[2016.09.16-13.21.29:394][709]VHServerCommunicationLog:Display:  is sending to: 127.0.0.1:1234/valhalla/v1/party-service/get, with verb "GET"
[2016.09.16-13.21.30:189][754]LogThreadingWindows:Error: Runnable thread HttpManagerThread crashed.
[2016.09.16-13.21.30:189][754]LogWindows:Error: === Critical error: ===
[2016.09.16-13.21.30:189][754]LogWindows:Error: 
[2016.09.16-13.21.30:189][754]LogWindows:Error: Fatal error!
[2016.09.16-13.21.30:189][754]LogWindows:Error: 
[2016.09.16-13.21.30:189][754]LogWindows:Error: Unhandled Exception: EXCEPTION_ACCESS_VIOLATION reading address 0x25570000
[2016.09.16-13.21.30:189][754]LogWindows:Error: 
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!FCurlHttpRequest::DebugCallback() [c:\valhalla\unrealengine\engine\source\runtime\online\http\private\curl\curlhttp.cpp:420]
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!FCurlHttpRequest::StaticDebugCallback() [c:\valhalla\unrealengine\engine\source\runtime\online\http\private\curl\curlhttp.cpp:262]
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!Curl_write_plain()
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!Curl_debug()
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!Curl_add_buffer_send()
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!Curl_http()
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!Curl_do()
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!curl_multi_wait()
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!curl_multi_perform()
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!FCurlHttpThread::HttpThreadTick() [c:\valhalla\unrealengine\engine\source\runtime\online\http\private\curl\curlhttpthread.cpp:28]
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!FHttpThread::Run() [c:\valhalla\unrealengine\engine\source\runtime\online\http\private\httpthread.cpp:135]
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!FRunnableThreadWin::Run() [c:\valhalla\unrealengine\engine\source\runtime\core\private\windows\windowsrunnablethread.cpp:74]
[2016.09.16-13.21.30:189][754]LogWindows:Error: valhalla.exe!FRunnableThreadWin::GuardedRun() [c:\valhalla\unrealengine\engine\source\runtime\core\private\windows\windowsrunnablethread.cpp:31]
[2016.09.16-13.21.30:189][754]LogWindows:Error: KERNEL32.DLL
[2016.09.16-13.21.30:189][754]LogWindows:Error: ntdll.dll
[2016.09.16-13.21.30:189][754]LogWindows:Error: ntdll.dll
[2016.09.16-13.21.30:189][754]LogWindows:Error: 
[2016.09.16-13.21.30:189][754]LogWindows:Error: Crash in runnable thread HttpManagerThread
[2016.09.16-13.21.30:206][755]LogExit: Executing StaticShutdownAfterError

Sean_L · September 19, 2016, 3:05pm

Hello,

I have a few questions regarding your issue:

Are you getting a crash reporter window? If so, could you please provide your Machine ID and ensure to hit Send & Close on the report?
Is this occurring in a clean project at all?

PhroZenOne · September 20, 2016, 2:18am

No crash reporter window. I guess this is because it is not running in the editor. I have not been able to reproduce this behavior when running in the editor. Nor have I been able to reproduce it on a clean project so I assume it’s some kind of race condition.

The code path that triggers this error is only present on development builds so as of now we have switched to Shipping builds instead, this of course have other side effects so we would like to be able to switch back.

anonymous_user_61b4a355 · September 20, 2016, 1:46pm

Hey PhroZenOne,

Can you let me know if you are running a Blueprint only or C++ project? Also, do you have the engine source or are you using the binary (launcher) version of the engine?

Thanks.

PhroZenOne · September 20, 2016, 4:30pm

Its a C++ project (mainly blueprint but a few c++ sources added to get functionality we cant get from blueprint), In this instance we are using c++ to call a rest api with FHttpModule::Get()

All development is done on the binary (launcher) version of the game. But as we need a linux dedicated server we are building releases from source (with a modified Version.cpp so that it is identical to the launcher version).

We have not been able to make it crash while running in the editor, only the release builds crash (with -clientconfig=Development -serverconfig=Development flags, Shipping works!).

anonymous_user_61b4a355 · September 20, 2016, 5:04pm

The reason I ask about having source is that it is this chunk of code that is causing the crash:

[engine\source\runtime\online\http\private\curl\curlhttp.cpp]

[Lines 418-425]

case CURLINFO_HEADER_OUT:
	{
		FString DebugText(ANSI_TO_TCHAR(DebugInfo));
		DebugText.ReplaceInline(TEXT("\n"), TEXT(""), ESearchCase::CaseSensitive);
		DebugText.ReplaceInline(TEXT("\r"), TEXT(""), ESearchCase::CaseSensitive);
    	UE_LOG(LogHttp, VeryVerbose, TEXT("%p: Sent header (%d bytes) - %s"), this, DebugInfoSize, *DebugText);
    }
    break;

I think it is trying to use “DebugInfo” but it isn’t valid, causing the “EXCEPTION_ACCESS_VIOLATION” crash. If that is not the cause and the exception access violation is being called for another reason, you could also run your server from Visual Studio and see if you could get the crash to happen, and then from the break point you could see the value of DebugInfo and begin to debug from there.

The following is a guess but could potentially fix it by doing:

case CURLINFO_HEADER_OUT:
	{
		if ( DebugInfo )
		{
			FString DebugText(ANSI_TO_TCHAR(DebugInfo));
			DebugText.ReplaceInline(TEXT("\n"), TEXT(""), ESearchCase::CaseSensitive);
			DebugText.ReplaceInline(TEXT("\r"), TEXT(""), ESearchCase::CaseSensitive);
			UE_LOG(LogHttp, VeryVerbose, TEXT("%p: Sent header (%d bytes) - %s"), this, DebugInfoSize, *DebugText);
		}
    }
    break;

This issue in regards to writing up a bug for this is that I need to have either a project or consistent reproduction steps for the issue. As in, If you can replicate this issue on a smaller project or somehow give me steps to reproduce it on my end, I can bug it. Otherwise, there is nothing we can do to move forward.

Please post anymore information in relation to reproducing the issue and I will do my best to get it submitted.

PhroZenOne · September 20, 2016, 8:24pm

While I believe that will fix the issue, I’m a bit curious where DebugInfo comes from and why it would be invalid, I must admit that I weren’t able to trace it as I got lost in the macros.

I will have some time over this weekend so I will try to reproduce it in a more predictable manner.

anonymous_user_61b4a355 · September 20, 2016, 8:38pm

Im not 100% sure what it is for but from looking a bit, it looks like its just a normal C String being used for debugging. I say this cause its getting converted from a char * to FString with ANSI_TO_TCHAR, and then being cast into a FString.

Chances are you are running into a rare instance where the char * being passed in is not valid for some reason ( I tracked the debug function call back to where the curl wrapper is setup to be used in UE4 but have no clue what is being passed in ).

/* This preprocessor magic that replaces a call with the exact same call is
   only done to make sure application authors pass exactly three arguments
   to these functions. */

#define curl_easy_getinfo(handle,info,arg)

That’s the best I can do without debugging, in regards to finding information on it.

PhroZenOne · September 28, 2016, 9:57pm

I have managed to trigger the crash locally by attaching visual studio to the built application and for some reason it says that the variables are optimized away. But if I step up one step the debug info variable is there. Could that be a clue or just an red herring in this case? See screenshot

I dont really know where to go from here as I havn’t managed to reproduce this in a new project. Any tips?

anonymous_user_61b4a355 · September 30, 2016, 3:58pm

Hey PhroZenOne,

The variables being optimized away is normal for when debugging in “Development”. It’s not a part of the issue (or any issue), just how C++ and Visual Studio will compile and debug the code.

As for the actual issue, my original thought doesn’t appear to be correct, as you can see the DebugInfo, and it is valid.

It is tough for me to give you any instruction without being able to reproduce the issue on my end. Is there anything you can do to explain how I could setup an environment / project that would result in the same crash?

PhroZenOne · October 4, 2016, 3:20pm

I’m afraid that I haven’t been able to reliably reproduce it on my end as well. Sometimes it takes more than 2 hours to trigger the error even if I spam with multiple http requests every second.

However, I just realized one thing that seems odd.

The string starts with:

  DebugInfo	0x0000025a8634fdc0 "GET /valhalla/v1/notification-service/get HTTP/1.1\r\nHost: persistent.valhalla-game.com:1234\r\nAccept: */*\r\nUser-Agent: UE4-Custom/1.0\r\nsession: d7d97db7-fab3-4633-8816-fc816cb8dee5\r\nContent-Length: 0\r\n...	char *

The size of the char array is:
DebugInfoSize 220 unsigned __int64

The crash occurs at:
Access violation reading location 0x0000025A86350000.

Thats a difference of 576 bytes (0x240) so it seems to go further than the length of the char array unless I am missing something? Could it be that ansi_to_char assumes null terminated string and for some reason this is not?

Edit: In fact I found that the libcurl library says that: “The data pointed to by the char * passed to this function WILL NOT be zero terminated, but will be exactly of the size as told by the size argument.” See CURLOPT_DEBUGFUNCTION

anonymous_user_61b4a355 · October 4, 2016, 3:39pm

Good catch, but the bad news is I still need steps to reproduce the issue on my end before I am able to report the issue.

If you have any more information on how to do that, please let me know.

Thanks.

WoodsShin · October 5, 2016, 4:28am

Hi, I had the same issue. Our dedicated server updates information to our own web server with IHttpRequest whenever new player connects to it. I assume it crashed when It sent new request before getting previous request’s response. Hopely it will be helpful to you.

anonymous_user_61b4a355 · October 5, 2016, 12:48pm

Hey WoodsShin,

Can you give me reproduction steps on how you are getting this crash? As in, how to setup a project so I can see the crash happen.

WoodsShin · October 5, 2016, 9:33pm

It doesn’t always happen. These are parts of my codes.

 TSharedPtr <IHttpRequest> Request ...
 Request->OnProcessRequestComplete().BindUObject(this, &UAPIServer::OnResponseUpdateInfo);
 Request->ProcessRequest();

I’m calling these codes whenever new player connects to dedicated server. When the map was changed, multiple player connected to it. It means this function was called multi times in a short period.

When I added PhroZenOne’s code which checks null of DebugInfo, no more crash.

PhroZenOne · October 7, 2016, 5:47pm

Added my code? I have not shown any code in this thread.

I did however apply a patch to add null terminator and no crash since so I do think that my hypothesis is correct.

https://github.com/saiaku-gaming/UnrealEngine/commit/06b2dab7e39cfeda6019a98934986f23c17d03c2

edit: maybe you cant see my private repo, so heres the same diff: CurlHttp.diff · GitHub

anonymous_user_61b4a355 · October 7, 2016, 6:01pm

Hey PhroZenOne,

I’m glad you were able to figure something out. If you want, you can also put in a pull request at the UnrealEngine Master Branch for UE4.

PhroZenOne · October 7, 2016, 7:08pm

Sure thing, added a pull request at: https://github.com/EpicGames/UnrealEngine/pull/2845