Http requests not working in plugin

edcolmar · April 6, 2019, 10:04pm

I updated to 4.22, and my plugin’s http requests are no longer working. The requests are never made, and never complete, with the thread stuck. It fails silently, until trying to close the client, the following error is logged repeatedly:

LogHttp: Display: Sleeping for 0.5s to wait for 1 outstanding Http requests.

This is using the FHttpModule inside of a plugin.

Any hints on what changed, or how I might fix this in 4.22?

TSharedRef<IHttpRequest> HttpRequest = FHttpModule::Get().CreateRequest();
				LoginUserRequests.Add(&HttpRequest.Get(), FPendingLoginUser(LocalUserNum, AccessToken));

				FString FinalURL = MeURL.Replace(TEXT("`token"), *AccessToken, ESearchCase::IgnoreCase);
				if (InProfileFields.Num() > 0)
				{
					FinalURL += FString::Printf(TEXT("&fields=%s"), *FString::Join(InProfileFields, TEXT(",")));
				}

				HttpRequest->OnProcessRequestComplete().BindRaw(this, &FOnlineIdentityUEtopia::MeUser_HttpRequestComplete, InCompletionDelegate);
				HttpRequest->SetURL(FinalURL);
				HttpRequest->SetHeader(TEXT("Content-Type"), TEXT("application/"));
				HttpRequest->SetVerb(TEXT("GET"));

				HttpRequest->ProcessRequest();

VeryVerbose Logs:

    [2019.04.08-20.51.44:089][361]LogHttp: VeryVerbose: FHttpRequestImpl::OnProcessRequestComplete()
    [2019.04.08-20.52.07:643][361]LogHttp: Verbose: 000001C1258654C0: URL='https://ue4topia.appspot.com/me?access_token=XXXTRIMMEDXXX'
    [2019.04.08-20.52.07:644][361]LogHttp: Verbose: 000001C1258654C0: Verb='GET'
    [2019.04.08-20.52.07:644][361]LogHttp: Verbose: 000001C1258654C0: Custom headers are present
    [2019.04.08-20.52.07:644][361]LogHttp: Verbose: 000001C1258654C0: Payload size=0
    [2019.04.08-20.52.07:644][361]LogHttp: Verbose: 000001C1258654C0: Adding header 'Content-Type: application/'
    [2019.04.08-20.52.07:644][361]LogHttp: Verbose: 000001C1258654C0: Adding header 'User-Agent: ProMMO/++UE4+Release-4.22-CL-0 Windows/10.0.17134.1.256.64bit'
    [2019.04.08-20.52.07:645][361]LogHttp: Verbose: 000001C1258654C0: Adding header 'Content-Length: 0'
    [2019.04.08-20.52.07:645][361]LogHttp: Verbose: 000001C1258654C0: Adding header 'Expect: '
    [2019.04.08-20.52.07:645][361]LogHttp: 000001C1258654C0: Starting GET request to URL='https://ue4topia.appspot.com/me?access_token=XXXTRIMMEDXXX'
    [2019.04.08-20.52.17:171][361]LogHttp: Verbose: 000001C1258654C0: request (easy handle:000001C131215560) has been added to threaded queue for processing
    [2019.04.08-20.52.17:172][361]LogTemp: [UETOPIA] [UMyUserWidget] OnDismissLoginWidget
    [2019.04.08-20.52.17:188][362]LogHttp: Verbose: 000001C1258654C0: request (easy handle:000001C131215560) has started threaded processing
    The thread 0x55a0 has exited with code 0 (0x0).
    [2019.04.08-20.52.17:200][362]LogHttp: VeryVerbose: 000001C1258654C0: '  Trying 172.217.11.244...'
    [2019.04.08-20.52.17:200][362]LogHttp: VeryVerbose: 000001C1258654C0: 'TCP_NODELAY set'
    [2019.04.08-20.52.17:234][362]LogHttp: VeryVerbose: 000001C1258654C0: 'Connected to ue4topia.appspot.com (172.217.11.244) port 443 (#0)'
    [2019.04.08-20.52.17:241][363]LogHttp: VeryVerbose: 000001C1258654C0: 'ALPN, offering http/1.1'
    [2019.04.08-20.52.17:241][363]LogHttp: VeryVerbose: 000001C1258654C0: 'Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH'
    [2019.04.08-20.52.17:243][363]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (5 bytes)
    [2019.04.08-20.52.17:245][363]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.3 (OUT), TLS handshake, Client hello (1):'
    [2019.04.08-20.52.17:245][363]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (512 bytes)
    [2019.04.08-20.52.17:301][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (5 bytes)
    [2019.04.08-20.52.17:301][364]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.3 (IN), TLS handshake, Server hello (2):'
    [2019.04.08-20.52.17:301][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (106 bytes)
    [2019.04.08-20.52.17:301][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (5 bytes)
    [2019.04.08-20.52.17:301][364]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.2 (IN), TLS handshake, Certificate (11):'
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (2449 bytes)
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (5 bytes)
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.2 (IN), TLS handshake, Server key exchange (12):'
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (300 bytes)
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (5 bytes)
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.2 (IN), TLS handshake, Server finished (14):'
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: Received SSL data (4 bytes)
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (5 bytes)
    [2019.04.08-20.52.17:302][364]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.2 (OUT), TLS handshake, Client key exchange (16):'
    [2019.04.08-20.52.17:303][364]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (37 bytes)
    [2019.04.08-20.52.17:305][364]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (5 bytes)
    [2019.04.08-20.52.17:305][364]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.2 (OUT), TLS change cipher, Client hello (1):'
    [2019.04.08-20.52.17:305][364]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (1 bytes)
    [2019.04.08-20.52.17:305][364]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (5 bytes)
    [2019.04.08-20.52.17:305][364]LogHttp: VeryVerbose: 000001C1258654C0: 'TLSv1.2 (OUT), TLS handshake, Finished (20):'
    [2019.04.08-20.52.17:305][364]LogHttp: VeryVerbose: 000001C1258654C0: Sent SSL data (16 bytes)

FreezerNick · April 7, 2019, 3:29pm

My plugins works fine in 4.22.
Did you make the plugin yourself? Any messages in Visual Studio?

edcolmar · April 7, 2019, 4:02pm

I made the plugin, yes. It is based on the other online subsystem plugins, like OnlineSubsystemFacebook. This code is identical to the code in OnlineSubsystemFacebook plugin in 4.22 There are no errors or warnings in VS.

Shadowriver · April 7, 2019, 7:01pm

Can you provide logs from Saved/Logs when you try to run this code(trying HTTP conneciton)?

edcolmar · April 7, 2019, 11:01pm

There aren’t any lines logged that are related to this. It just silently fails. The only log that appears is after closing the client: LogHttp: Display: Sleeping for 0.5s to wait for 1 outstanding Http requests. I placed breakpoints in this code and it is getting executed, but nothing is happening.

edcolmar · April 8, 2019, 9:17pm

I changed the LogHttp to VeryVerbose, and added the lines to the original question.

RobCannaday · May 15, 2019, 6:57pm

Hi, we had found that on some systems, the HTTP thread had a seemingly infinite sleep. We think it was related to the version of Visual Studio 2017 that was installed, but we have not figured out the exact cause yet. I was never able to reproduce it and I was on Visual Studio 2017 15.9.8, and a coworker that was able to reproduce it was on Visual Studio 2017 15.9.1. Another coworker that reproduced it was on Visual Studio 2015.
We found that inside of FHttpThread::Run, InnerLoopEnd seemed to be some bogus number sometimes.
Our workaround is to wrap FHttpThread::Run with PRAGMA_DISABLE_OPTIMIZATION / PRAGMA_ENABLE_OPTIMIZATION.

DanielGomez420 · May 15, 2019, 9:48pm

I suspect that Rob was just seeing garbage values due to compiler optimizations.

We had this same issue. Turned out to be an issue with Go’s 1.1.1 TLS libraries. After putting a TLS terminating load balancer up the issue went away.

edcolmar · May 16, 2019, 4:07pm

Thanks for the response Rob. Will an upgrade to VS 2019 solve this issue?

anonymous_user_f1a2a30c · June 6, 2019, 6:37pm

I found similar behaviour on VS 15.9.3 and this workaround also solved it for me. Occasionally on certain HTTP requests the thread would sleep indefinitely and stop sending requests.

edcolmar · June 13, 2019, 2:10pm

I upgraded to VS 2019 and it is working again. Thank you.

anonymous_user_bfbd1c20 · November 8, 2019, 11:16pm

We are seeing the same thing on Unreal version 4.22.3 and Visual Studio 15.9.16. It also occurs when using Visual Studio 15.9.17, but it doesn’t occur with Visual Studio 15.9.15.

I tracked down the issue to how the optimized code handles the constant offset that FWindowsPlatformTime::Seconds() uses. In the unoptimized code, it adds the value from static memory, but in the optimized code, it saves off that static value into an xmm register at the start of the outer while loop and adds the register value each time later. (Eg. addsd xmm8,mmword ptr [__real@4170000000000000 (07FFEE0D792B0h)] vs addsd xmm8,xmm9)

Depending on which xmm register the compiler decides to use to store the constant, at a certain point during execution, that xmm register gets set to 0. If that point in time happens to be between when InnerLoopBegin and InnerLoopEnd are calculated, InnerLoopEnd will be 16777216 too small (because the offset being used is now 0 instead) and cause the thread to sleep for practically forever.

I can get it to work or not work by adding checkf calls which cause the xmm register being used to change. My guess is that the VS version changes or TLS library changes are just enough to cause the compiler to change the register being used to something that isn’t going to get reset and so are just masking the underlying issue.

My best guesses are that this is a compiler bug and it’s not realizing that some nested function call is going to modify that register, or that somehow during a context switch, the saved off values of the registers of this thread get stomped on.

anonymous_user_a0a2453b · May 18, 2022, 4:23pm

I am as well finding this bug however its only appearing on my companies ASUS laptops and not on my companies MSI laptops

Ben_Cykyria · December 30, 2022, 8:36pm

Hurray, I found another bug with only one hit on Google!

Thanks RobCannaday for the solution!

Custom Engine 4.26, moved project to a new developer machine. All works fine, except very strange behaviors regarding anything HTTP - but ONLY in the editor. Builds from that machine work flawlessly, too.

After a bit - ok I admit it - lot’s of back and forth eventually I see the hanging UE4 editor processes in the task manager and the bloated logsfiles in Saved directory: “LogHttp: Display: Sleeping for 0.5s to wait for 1 outstanding Http requests.” and so on…

Pretty nasty, because the lines only show up after I closed the editor.

For the poor souls who will hit this bug in a few months or years, welcome to the club!

The solution is simple, just edit \Engine\Source\Runtime\Online\HTTP\Private\HttpThread.cpp:

PRAGMA_DISABLE_OPTIMIZATION
uint32 FHttpThread::Run()
{
…
}
PRAGMA_ENABLE_OPTIMIZATION

Then rebuild & enjoy.

For the record:
Windows 11 Home, Version 22H2, Build 22621.963
Microsoft Visual Studio Community 2019, Version 16.11.20

S_Q_R · July 4, 2023, 2:20pm

This fix worked great for a long time for me but at one point some of the multithreaded part of my project started to crash the game.It tried to read incomplete http request. It did not happened on the binary version of the engine so I guess it was because of this PRAGMA_DISABLE_OPTIMALIZATION fix.

And as mentioned before in this thread I can also confim that this happens on ASUS hardware. It occured on my PC with ASUS Prime B650 Plus motherboard. On my friend’s Asus laptop and on one of the office PC also with asus motherboard.

At first I fixed it with putting volatile qualifiers inside FHttpThread::Run()

uint32 FHttpThread::Run()
{
	// Arrays declared outside of loop to re-use memory
	TArray<IHttpThreadedRequest*> RequestsToCancel;
	TArray<IHttpThreadedRequest*> RequestsToComplete;
	while (!ExitRequest.GetValue())
	{
		if (ensureMsgf(!bIsSingleThread, TEXT("HTTP Thread was set to singlethread mode while it was running autonomously!")))
		{
			const /*volatile*/ double OuterLoopBegin = FPlatformTime::Seconds();
			/*volatile*/ double OuterLoopEnd = 0.0;
			bool bKeepProcessing = true;
			while (bKeepProcessing)
			{
				const /*volatile*/ double InnerLoopBegin = FPlatformTime::Seconds();
			
				Process(RequestsToCancel, RequestsToComplete);
			
				if (RunningThreadedRequests.Num() == 0)
				{
					bKeepProcessing = false;
				}

				const /*volatile*/ double InnerLoopEnd = FPlatformTime::Seconds();
				if (bKeepProcessing)
				{
					SCOPE_CYCLE_COUNTER(STAT_HTTPThread_ActiveSleep);
					double InnerLoopTime = InnerLoopEnd - InnerLoopBegin;
					double InnerSleep = FMath::Max(HttpThreadActiveFrameTimeInSeconds - InnerLoopTime, HttpThreadActiveMinimumSleepTimeInSeconds);
					FPlatformProcess::SleepNoStats(InnerSleep);
				}
				else
				{
					OuterLoopEnd = InnerLoopEnd;
				}
			}
			SCOPE_CYCLE_COUNTER(STAT_HTTPThread_IdleSleep)
			double OuterLoopTime = OuterLoopEnd - OuterLoopBegin;
			double OuterSleep = FMath::Max(HttpThreadIdleFrameTimeInSeconds - OuterLoopTime, HttpThreadIdleMinimumSleepTimeInSeconds);
			FPlatformProcess::SleepNoStats(OuterSleep);
		}
		else
		{
			break;
		}
	}
	return 0;
}

That fixed the issue but I’ve read that volatile qualifier is not really safe for multithreaded applications.

So my second fix was to change FWindowsPlatformTime::Seconds(), ::Cycles() and ::Cycles64 to regular functions (removed FORCEINLINE).
Both fixes worked on their own. I think second one is more elegant. Feel free to use them as you want. You can combine them just to be extra safe

The_Regurgitator · September 7, 2023, 6:05am

Seems like I reproduced this issue. My team is strictly on pure Epic Games engine versions, so looks like I won’t be able to fix this for myself; I might need to replace the HTTP library in full.

Windows 11 Pro, 22H2, Build 22621.2134
Visual Studio Community 2019, Version 16.11.28
Unreal Engine 4.27.2

The_Regurgitator · September 7, 2023, 6:35am

One quirk of my situation is this issue seems entirely localized to one domain: our website / database. Doing the same request at https://www.google.com/ or a number of other random websites would result in a response (instead of an infinite-wait). My guess for the reason for this is some quirk in the code that only triggers this issue under certain timing conditions, or something to do with TLS configuration, or something even weirder.

S_Q_R · September 8, 2023, 7:37am

When I was digging for solution with this one I also found this forum thread
If thats only one domain it might be that UE don’t trust that connection. Not sure if solution with certificate will help but you can give it a go. Hope it helps

YeHaike · September 10, 2023, 2:58am

About HTTP requests in plugin, maybe get some inspiration from this plugin: