long running signaling sessions timeout

[3dstreamingtoolkit]

long running signaling sessions timeout

[bengreenier]

see pending work @ https://github.com/CatalystCode/3dtoolkit/commits/hotfix/issue-45

[bengreenier]

I'm observing this issue even before a video/data connection occurs, (ie just sitting at the client list screen) so i definitely beleive the issue is related to azure timeouts or an issue with our service.

what i see happening at the 2 minute mark is the client getting a 500:

HTTP/1.1 500 Internal Server Error
Content-Length: 0
Server: Microsoft-IIS/8.0
X-Powered-By: ASP.NET
Set-Cookie: ARRAffinity=ae7afc8e63389183359404878a948a7898ad370168172a8c2fe864baa3727afe;Path=/;HttpOnly;Domain=3dtoolkit-signalingserver.azurewebsites.net
Date: Fri, 28 Jul 2017 16:11:03 GMT
Connection: close

Which doesn't feel like something the azure platform would do, but then again i'm not sure. So we need to identify:

• who's sending this 500
• how should we react

[bengreenier]

okay, can confirm the 500 is not from our application. Why azure is terminating a connection with an application level protocol response is beyond me, but it seems to be doing exactly that.

Here's a response from our node app (note the X-Powered-By: Express ):

HTTP/1.1 200 OK
Content-Length: 2
Content-Type: text/plain; charset=utf-8
ETag: W/"2-nOO9QiTIwXgNtWtBJezz8kv3SLc"
Server: Microsoft-IIS/8.0
X-Powered-By: Express
X-Powered-By: ASP.NET
Set-Cookie: ARRAffinity=ae7afc8e63389183359404878a948a7898ad370168172a8c2fe864baa3727afe;Path=/;HttpOnly;Domain=3dtoolkit-signalingserver.azurewebsites.net
Date: Fri, 28 Jul 2017 16:24:12 GMT
Connection: close

OK

this header is only added once the response is handled by our application, so this quickly confirms my suspicion about azure.

[bengreenier]

aha, with logging enabled service side we can see <h3>HTTP Error 500.1013 - Internal Server Error</h3> is occuring - per https://github.com/Azure/iisnode/blob/master/src/iisnode/cnodeconstants.h#L22 it appears this indicates an error to process the http status line, and from this issue it seems possible it's a result of the node app crashing, so i'm going to rule that out first.

[bengreenier]

alright so now i'm completely second guessing myself...i'm writing a small test app to simulate and validate the behavior of timeouts both locally and on azure.

And i'm seeing https://nodejs.org/api/http.html#http_server_timeout is causing 2m timeouts locally. I wonder if this is somehow translated to mean send a 500 status code when running on azure? seems unusual, but i'll continue to pursue my test app and validate our expectations of azure behavior.

[bengreenier]

okay. i understand what this issue is now, i just don't know how to actually "fix" it 😅

explanation

what happens is, our server holds the connection open longer than azure permits. this results in the iis (or maybe some azure specific) timeout being hit. when that occurs, something (seems to be iisnode) tries to read the http level status line, which doesn't exist because we haven't written any data cause we aren't ready to use the channel yet. This results in a 500.1013 since there is no status line. This sends a 500 to our client.

planned "fix"

our client should likely react to 500 status codes with a retry, since this seems like the most reasonable approach. and perhaps after n retries we fallback onto disconnect.

[bengreenier]

discussed with the team, our current approach will be to treat all 500 responses as if they are socket disconnects, and existing retry logic will be leveraged. we'll do this for now as it's the quickest fix, and then circle back and sync with azure folks, as this seems like an...interesting...implementation on their side.

FWIW, this may be an issue with the downlevel opensource package iisnode and not azure - this is likely the code path that's triggering the behavior: https://sourcegraph.com/github.com/tjanczuk/iisnode@master/-/blob/src/iisnode/cprotocolbridge.cpp?q=IISNODE_ERROR_FAILED_PROCESS_HTTP_STATUS_LINE#L1321-1339:2

[bengreenier]

@anastasiia-zolochevska says we are still seeing an issue here - reopening to take a look

[bengreenier]

i've had a connection from native dx client to unity server running for hours, today..no issue

i'm going to reclose this for now as "can't repro"