iOS: Empty HTTP responses

andreasdr · October 7, 2019, 10:57pm

Hi,

I have a issue regarding HTTP requests on iOS.

So I see empty HTTP responses. Then JSON parser crashes then. But in our server access log i see no 0 bytes sized http responses.

Can this be a OpenFL bug on iOS? We do not have issues on HTML or Android like that.

I use a stock openfl installation via HaxeLib and build our game via XCode for iOS.
lime: 5.5.0 5.6.0 5.7.0 5.8.2 6.0.1 6.2.0 6.3.1 6.4.0 7.0.0 7.1.1 7.2.0 7.2.1 7.3.0 7.5.0 7.6.0 [7.6.3]
openfl: 6.1.2 6.2.0 6.2.1 6.5.0 7.0.0 7.1.2 8.0.2 8.2.2 8.4.1 8.5.1 8.6.4 8.7.0 8.8.0 8.9.0 8.9.1 8.9.2 [8.9.5]

Please see attached a screen shot of LLDB being connected to my iPAD.

But access log has no 0 bytes response. And every response had a 200 status code

Any ideas how to debug this issue or find its origin?

Many thanx and

Best regards
Andreeas

singmajesty · October 8, 2019, 8:59pm

Here’s an overview of how the network subsystem should be working:

openfl.net.URLLoader (and similar methods) use Lime internally to make network requests
lime.net.HTTPRequest is the actual place where network requests are made (with separate implementations for native and HTML5 platforms)
lime._backend.native.NativeHTTPRequest is the implementation of HTTPRequest for native targets, using a background thread and a cURL Multi instance internally
lime.net.curl.CURLMulti has a perform() method where network traffic is processed and flushed
“project/src/net/CURLBindings.cpp” is where this is actually implemented in the native C++ code

In order to prevent crashes caused by triggering Haxe garbage collection on the wrong thread we cannot make progress callbacks while we are transferring network data because it is a blocking operation

As a result we use a buffer when downloading then flush the buffer when multi.perform() is called when we can handle the data on the correct thread

Short of a better reproduction case my thoughts do go to the buffer/flush mechanism and wonder if somehow the complete event is triggering without flushing the data or if we somehow are writing the wrong byte length on the callback – regardless there’s a lot of layers here that could be traced to see if the results seem sound

Is there a simple way to reproduce the issue or do you think it would be possible to debug this a bit further to get more information on what is occurring? Thank you!

andreasdr · October 8, 2019, 9:13pm

Hi,

thank you very much. I will tomorrow check in the deepest layer if the data arrives and report here my observations. And then we can see what happens next.

Best regards
Andreas

andreasdr · October 9, 2019, 10:41pm

Hi,

I’ve created a test that can reproduce this issue. Do you want to have it?

This is the output before the app dies:
Main.hx:34: onRequestResponseHandler(): response == ok
Main.hx:39: onRequestResponseHandler(): have a request started
Main.hx:19: doRequest(): response == ok
libc++abi.dylib: terminating with uncaught exception of type Dynamic

thread #1, queue = ‘com.apple.main-thread’, stop reason = signal SIGABRT
- frame #0: 0x00000001c126b104 libsystem_kernel.dylib__pthread_kill + 8 frame #1: 0x00000001c12e7020 libsystem_pthread.dylib + 380
  frame #2: 0x00000001c11c2d78 libsystem_c.dylibabort + 140 frame #3: 0x00000001c088cf78 libc++abi.dylib + 132
  frame #4: 0x00000001c088d120 libc++abi.dylib<redacted> + 304 frame #5: 0x00000001c08a5e68 libobjc.A.dylib + 140
  frame #6: 0x00000001c08990fc libc++abi.dylib<redacted> + 16 frame #7: 0x00000001c0898cec libc++abi.dylib__cxa_rethrow + 144
  frame #8: 0x00000001c08a5c20 libobjc.A.dylibobjc_exception_rethrow + 44 frame #9: 0x00000001c165f25c CoreFoundationCFRunLoopRunSpecific + 544
  frame #10: 0x00000001c38d8584 GraphicsServicesGSEventRunModal + 100 frame #11: 0x00000001ee5b4c00 UIKitCoreUIApplicationMain + 212
  frame #12: 0x0000000101363018 urlloadertestSDL_UIKitRunApp + 208 frame #13: 0x00000001c111ebb4 libdyld.dylib + 4

andreasdr · October 9, 2019, 10:43pm

It seems that the issue does appear If I do a request within a request response handler.

andreasdr · October 9, 2019, 11:32pm

Hmm. I could reproduce the error 2-3 times and now its gone. I will continue to test. Maybe I have a router problem. Idk yet.

andreasdr · October 15, 2019, 11:12pm

Hi,

Ive added some debug output and see the following traces:

URLLoader.hx:420: 14 / 14 (bytesLoaded/bytesTotal)
NativeHTTPRequest.hx:569: http status code: 0
NativeHTTPRequest.hx:349: response string:

This is really strange.

Maybe someone has an idea, I will continue to debug.

andreasdr · October 16, 2019, 1:16am

Hi,

Ive also added a trace to CURL::setOption() in the write function.
It looks like the write function is never called on those broken responses whereas it is called on the normal ones.

Any ideas?

singmajesty · October 16, 2019, 9:15pm

is that the C++ or the Haxe write function?

EDIT: Is it possible that the buffers are being flushed prior to the buffers being written?

andreasdr · October 16, 2019, 11:17pm

Hi,

its the Haxe function in /src/lime/net/curl/CURL.hx at line 170.
If you have something for me to test/change please tell me.

singmajesty · October 16, 2019, 11:20pm

Try adding a print in here:

github.com

openfl/lime/blob/develop/project/src/net/curl/CURLBindings.cpp#L1242


	static size_t write_callback (void *ptr, size_t size, size_t nmemb, void *userp) {


		if (size * nmemb < 1) {


			return 0;


		}


		char* buffer = writeBuffers[userp];
		int writeSize = (size * nmemb);


		if (!buffer) {


			buffer = (char*)malloc (CURL_MAX_WRITE_SIZE);
			memcpy (buffer, ptr, writeSize);
			writeBuffers[userp] = buffer;
			writeBufferPosition[userp] = writeSize;
			writeBufferSize[userp] = CURL_MAX_WRITE_SIZE;


		} else {

Like

printf("WRITE CALLBACK - %d\n", writeSize);

Then lime rebuild and try again

andreasdr · October 18, 2019, 2:45am

Hmm. If I do “lime rebuild macos” I get the following error.

Error: ./src/backend/sdl/SDLWindow.cpp:76:16: error: use of undeclared identifier ‘SDL_HINT_MOUSE_TOUCH_EVENTS’
SDL_SetHint (SDL_HINT_MOUSE_TOUCH_EVENTS, “0”);

andreasdr · October 18, 2019, 2:46am

I was on lime tag 7.6.3.

singmajesty · October 18, 2019, 4:58pm

Sounds like git submodule init && git submodule update might be needed after picking a point in Lime’s history to make sure all the submodules (in this case, SDL) are synced up

andreasdr · October 21, 2019, 10:17pm

Thank you. This worked.

Looks like the C++ write callback is not called regarding the “empty” responses. See attached my log extract:

In short:
Andreass-MBP-2:Downloads andreas$ grep -RIn “WRITE CALLBACK” PR-iOS-Bug.txt | wc -l
24251
Andreass-MBP-2:Downloads andreas$ grep -RIn “Database.hx:128” PR-iOS-Bug.txt | wc -l
24252

Please see attached the log file:

WRITE CALLBACK - 697
URLLoader.hx:420: yyy: 697 / 697

Database.hx:128: com.slipshift.rds90.models.database.Database: -> Getting the following JSON: openfl.events.Event/openfl.net.URLLoader: 0 / 0: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}

WRITE CALLBACK - 697
URLLoader.hx:420: yyy: 697 / 697
URLLoader.hx:315: xxx: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}

Database.hx:128: com.slipshift.rds90.models.database.Database: -> Getting the following JSON: openfl.events.Event/openfl.net.URLLoader: 0 / 0: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}

Main.hx:34: onRequestResponseHandler(): response == ok
Main.hx:19: doRequest(): response == ok
URLLoader.hx:420: yyy: 14 / 14
WRITE CALLBACK - 697
URLLoader.hx:420: yyy: 697 / 697
URLLoader.hx:315: xxx: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}

Database.hx:128: com.slipshift.rds90.models.database.Database: -> Getting the following JSON: openfl.events.Event/openfl.net.URLLoader: 0 / 0: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}

Main.hx:34: onRequestResponseHandler(): response == ok
Main.hx:19: doRequest(): response == ok
WRITE CALLBACK - 697
URLLoader.hx:420: yyy: 697 / 697
URLLoader.hx:315: xxx: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}

Database.hx:128: com.slipshift.rds90.models.database.Database: -> Getting the following JSON: openfl.events.Event/openfl.net.URLLoader: 0 / 0: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}

Main.hx:34: onRequestResponseHandler(): response == ok
Main.hx:19: doRequest(): response == ok
URLLoader.hx:420: yyy: 14 / 14
URLLoader.hx:315: xxx: 
Database.hx:128: com.slipshift.rds90.models.database.Database: -> Getting the following JSON: openfl.events.Event/openfl.net.URLLoader: 0 / 0: 
libc++abi.dylib: terminating with uncaught exception of type Dynamic
(lldb)

Any ideas?

Best regards
Andreas

singmajesty · October 21, 2019, 10:42pm

Okay – one more thing to try

github.com

openfl/lime/blob/develop/src/lime/_internal/backend/native/NativeHTTPRequest.hx#L514


			var code = multi.wait(1000);


			if (code == CURLMultiCode.OK)
			{
				multi.perform();
				var message = multi.infoRead();


				if (message == null && multi.runningHandles == 0)
				{
					multiThreadPool.sendComplete();
					break;
				}


				while (message != null)
				{
					var curl = message.curl;
					var status = curl.getInfo(RESPONSE_CODE);


					multi.removeHandle(curl);
					curl.cleanup();

Remove this break?

We run CURLMulti in a background thread, but exit the background thread when we run out of work, then start again when we have work again

Perhaps there’s something funny that happens when exiting/restarting the background thread quickly?

I’m trying to think of another reason why we could get a COMPLETE before we ever had PROGRESS, it seems like a threading issue

andreasdr · October 21, 2019, 11:22pm

Hi,

now after first COMPLETE event no other COMPLETE events are fired

**Main.hx:19: doRequest(): response == ok**

**2019-10-22 01:17:04.255423+0200 urlloadertest[263:4343] Unbalanced calls to begin/end appearance transitions for <SDL_uikitviewcontroller: 0x104b46b90>.**

**2019-10-22 01:17:04.255601+0200 urlloadertest[263:4343] Unbalanced calls to begin/end appearance transitions for <SDL_uikitviewcontroller: 0x104b46b90>.**

**2019-10-22 01:17:04.255695+0200 urlloadertest[263:4343] Unbalanced calls to begin/end appearance transitions for <SDL_uikitviewcontroller: 0x104b46b90>.**

**2019-10-22 01:17:04.255782+0200 urlloadertest[263:4343] Unbalanced calls to begin/end appearance transitions for <SDL_uikitviewcontroller: 0x104b46b90>.**

**URLLoader.hx:420: yyy: 14 / 14**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**URLLoader.hx:315: xxx: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}**

**Database.hx:128: com.slipshift.rds90.models.database.Database: -> Getting the following JSON: openfl.events.Event/openfl.net.URLLoader: 0 / 0: {"fights":[],"noxAquamarines":[],"response":"ok","resourcesv2":{"lastUpdateAgo":46,"tickDuration":60,"entities":[{"type":"junk","current":34572,"consumption":0},{"type":"stone","current":34556,"consumption":0},{"type":"food","current":34590,"consumption":261},{"type":"energy","current":34508,"consumption":0},{"type":"population","current":750,"consumption":0}]},"units":[{"unitId":1,"amount":45},{"unitId":2,"amount":93},{"unitId":3,"amount":123}],"ships":[{"shipId":5,"amount":5}],"ogFightId":0,"incomingSquads":[],"squads":[],"unreadMessages":4,"finishedQuests":0,"activeQuest":{"activeQuestId":353,"activeQuestState":1,"progress":null},"timePassed":0.078804969787598,"serverUnderPressure":0}**

**Main.hx:34: onRequestResponseHandler(): response == ok**

**Main.hx:39: onRequestResponseHandler(): have a request started**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**Main.hx:19: doRequest(): response == ok**

**URLLoader.hx:420: yyy: 697 / 697**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**URLLoader.hx:420: yyy: 14 / 14**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**URLLoader.hx:420: yyy: 14 / 14**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**WRITE CALLBACK - 697**

**URLLoader.hx:420: yyy: 697 / 697**

**Main.hx:19: doRequest(): response == ok**

**URLLoader.hx:420: yyy: 14 / 14**

I still also see those 14 / 14 responses. But they do not seem to have a obvious effect right now.

singmajesty · October 22, 2019, 3:15am

Oh try commenting out the sendComplete call as well so the multiThreadPool never completes

andreasdr · October 23, 2019, 7:19am

Hmm. This looks much better. Had the test running for 3 hours. No crash or other misbehavior.
I will check the game next.

andreasdr · October 29, 2019, 1:16am

Still seeing the same error when playing the game itself on iOS.