Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

An established connection was aborted by the software in your host machine #60

Closed
DaniilSokolyuk opened this issue Dec 5, 2019 · 12 comments · Fixed by #61
Closed

An established connection was aborted by the software in your host machine #60

DaniilSokolyuk opened this issue Dec 5, 2019 · 12 comments · Fixed by #61
Labels
bug Something isn't working

Comments

@DaniilSokolyuk
Copy link
Contributor

DaniilSokolyuk commented Dec 5, 2019

Sometime we got that error


An invocation attempt failed. Retries remaining: 1. Exception: System.Net.Http.HttpRequestException: Error while copying content to a stream. ---> System.IO.IOException: Unable to read data from the transport connection: An established connection was aborted by the software in your host machine.. ---> System.Net.Sockets.SocketException (10053): An established connection was aborted by the software in your host machine. 
--- End of inner exception stack trace --- at System.Net.Http.HttpConnection.WriteAsync(ReadOnlyMemory`1 source) 
at System.Net.Http.HttpConnection.ChunkedEncodingWriteStream.<WriteAsync>g__WriteChunkAsync\|2_0(HttpConnection connection, ReadOnlyMemory`1 buffer) 
at System.Text.Json.JsonSerializer.WriteAsyncCore(Stream utf8Json, Object value, Type inputType, JsonSerializerOptions options, CancellationToken cancellationToken) 
at Jering.Javascript.NodeJS.InvocationContent.SerializeToStreamAsync(Stream stream, TransportContext context) at System.Net.Http.HttpContent.CopyToAsyncCore(ValueTask copyTask) --- End of inner exception stack trace --- at System.Net.Http.HttpContent.CopyToAsyncCore(ValueTask copyTask) at System.Net.Http.HttpConnection.SendRequestContentAsync(HttpRequestMessage request, HttpContentWriteStream stream, CancellationToken cancellationToken) 
at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken) 
at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken) at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken) 
at System.Net.Http.RedirectHandler.SendAsyn…

I suppose that happen because Content-Length is not setted here and HttpClient and node-js works in chunked mode
https://github.com/dotnet/corefx/blob/master/src/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs
and
https://github.com/dotnet/corefx/blob/master/src/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs

by documentation here

Sending a 'Content-Length' header will disable the default chunked encoding.

For set
res.setHeader('Content-Length', Buffer.byteLength(responseJson));
and for string case too

Also thats can be increase performance for nodejs and HttpClient, need benchmarks :)

@DaniilSokolyuk
Copy link
Contributor Author

Problem not in Content-Length, node.js always return Content-Length, when response.end used (idk why)

@JeremyTCD JeremyTCD added the bug Something isn't working label Dec 6, 2019
@JeremyTCD
Copy link
Member

JeremyTCD commented Dec 6, 2019

Note: I deleted a couple of comments because my points weren't concise.

Clarification and Dirty Fix

Your trace is from a log message. It is logged before retrying an invocation request:

Logger.LogWarning(string.Format(Strings.LogWarning_InvocationAttemptFailed, numRetries < 0 ? "infinity" : numRetries.ToString(), exception.ToString()));

From the log message, we're retrying because a connection was aborted by NodeJS while the .Net process was sending data to it:

System.Net.Sockets.SocketException (10053): An established connection was aborted by the software in your host machine.

Does the retry succeed? If it fails, an InvocationException is thrown by Jering.Javascript.NodeJS.

Dirty fix: I'd suggest increasing the number of retries for now (OutOfProcessNodeJSServiceOptions.NumRetries) to be safe.

Possible Causes

  1. By default (pre-v13), NodeJS connections time out after 120 seconds (Default http[2s] server timeout is problematic nodejs/node#27556). What is your workload like? Is it possible a request has to wait that long?
  2. A malformed request can cause a connection to drop (Malformed HTTP request causes connection drop nodejs/node#4543). This is not the issue if the request works on retry.
  3. You're hitting some concurrent connection limit - Node.js maxing out at 1000 concurrent connections. Please provide more information about your environment - OS, Node.js version and .Net target framework.

Possible Fix (#61)

  1. Manually remove connection timeout.
  2. Add client error listener so if the issue persists, we might get more information about why the connection is dropping.

@DaniilSokolyuk
Copy link
Contributor Author

DaniilSokolyuk commented Dec 6, 2019

  1. Average request time is about ~10-30ms
  2. Hosted on windows, node.js process have 2-3 opened connections
  3. Retry count is 1. Thats works perfect

Error occurs 1-2 times per hour.

@JeremyTCD JeremyTCD changed the title Set Content-Length on node.js An established connection was aborted by the software in your host machine Dec 6, 2019
@JeremyTCD
Copy link
Member

Thanks for the extra info. My "possible causes" seem unlikely. Anyway I've released 5.2.1 with 2 changes:

  • Removed NodeJS connection timeout. No harm doing this since NodeJS is removing it anyway. Might solve the issue if it is caused by requests somehow taking longer than usual.

  • Added a listener in NodeJS for client errors. The listener should tell us why NodeJS is dropping connections - look out for the exception printed in log messages:

    An invocation attempt failed. Retries remaining: 1. <exception>
    

Incidentally, while running benchmarks for Microsoft.AspNetCore.NodeServices, NodeJS dropped a connection and the same exception, System.Net.Http.HttpRequestException, was thrown:

System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
 ---> System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.IO.IOException: The response ended prematurely.
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.AspNetCore.NodeServices.HostingModels.HttpNodeInstance.InvokeExportAsync[T](NodeInvocationInfo invocationInfo, CancellationToken cancellationToken)
   at Microsoft.AspNetCore.NodeServices.HostingModels.OutOfProcessNodeInstance.InvokeExportAsync[T](CancellationToken cancellationToken, String moduleName, String exportNameOrNull, Object[] args)
   at Microsoft.AspNetCore.NodeServices.NodeServicesImpl.InvokeExportWithPossibleRetryAsync[T](String moduleName, String exportedFunctionName, Object[] args, Boolean allowRetry, CancellationToken cancellationToken)
   at Jering.Javascript.NodeJS.Performance.RealWorkloadBenchmarks.INodeServices_RealWorkload() in C:\Projects\Jering.Javascript.NodeJS\perf\NodeJS\RealWorkloadBenchmarks.cs:line 102
   at BenchmarkDotNet.Autogenerated.Runnable_1.<.ctor>b__3_2() in C:\Projects\Jering.Javascript.NodeJS\perf\NodeJS\bin\Release\netcoreapp3\e831b542-5daa-4111-833a-3c6d7fdeb24b\e831b542-5daa-4111-833a-3c6d7fdeb24b.notcs:line 829
   at BenchmarkDotNet.Autogenerated.Runnable_1.WorkloadActionUnroll(Int64 invokeCount) in C:\Projects\Jering.Javascript.NodeJS\perf\NodeJS\bin\Release\netcoreapp3\e831b542-5daa-4111-833a-3c6d7fdeb24b\e831b542-5daa-4111-833a-3c6d7fdeb24b.notcs:line 1122
   at BenchmarkDotNet.Engines.Engine.RunIteration(IterationData data)
   at BenchmarkDotNet.Engines.EngineStage.RunIteration(IterationMode mode, IterationStage stage, Int32 index, Int64 invokeCount, Int32 unrollFactor)
   at BenchmarkDotNet.Engines.EngineStage.Run(IStoppingCriteria criteria, Int64 invokeCount, IterationMode mode, IterationStage stage, Int32 unrollFactor)
   at BenchmarkDotNet.Engines.EngineWarmupStage.Run(Int64 invokeCount, IterationMode iterationMode, Int32 unrollFactor, RunStrategy runStrategy)
   at BenchmarkDotNet.Engines.EngineWarmupStage.RunWorkload(Int64 invokeCount, Int32 unrollFactor, RunStrategy runStrategy)
   at BenchmarkDotNet.Engines.Engine.Run()
   at BenchmarkDotNet.Autogenerated.Runnable_1.Run(IHost host, String benchmarkName) in C:\Projects\Jering.Javascript.NodeJS\perf\NodeJS\bin\Release\netcoreapp3\e831b542-5daa-4111-833a-3c6d7fdeb24b\e831b542-5daa-4111-833a-3c6d7fdeb24b.notcs:line 812
   --- End of inner exception stack trace ---
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters)
   at BenchmarkDotNet.Autogenerated.UniqueProgramName.AfterAssemblyLoadingAttached(String[] args) in C:\Projects\Jering.Javascript.NodeJS\perf\NodeJS\bin\Release\netcoreapp3\e831b542-5daa-4111-833a-3c6d7fdeb24b\e831b542-5daa-4111-833a-3c6d7fdeb24b.notcs:line 49

Heads up for the guys cloning INodeServices @johnnyoshika.

@JeremyTCD JeremyTCD linked a pull request Apr 2, 2020 that will close this issue
@aKzenT
Copy link
Collaborator

aKzenT commented May 5, 2020

I'm also getting the "The response ended prematurely." error frequently. Since the errors are also triggered from a web test that always sends the same data to node, I know that it cannot be from a malformed request. Any ideas?

@JeremyTCD
Copy link
Member

Hey @aKzenT, could you could provide the full stack trace? Let me know if you have any problems capturing it.

@aKzenT
Copy link
Collaborator

aKzenT commented May 6, 2020

System.Net.Http.HttpRequestException:An error occurred while sending the request. The response ended prematurely.

   at System.Net.Http.HttpConnection+<SendAsyncCore>d__53.MoveNext (System.Net.Http, Version=4.2.2.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a)

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Net.Http.HttpConnectionPool+<SendWithNtConnectionAuthAsync>d__48.MoveNext (System.Net.Http, Version=4.2.2.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a)

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Net.Http.HttpConnectionPool+<SendWithRetryAsync>d__47.MoveNext (System.Net.Http, Version=4.2.2.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a)

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Net.Http.RedirectHandler+<SendAsync>d__4.MoveNext (System.Net.Http, Version=4.2.2.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a)

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e)

   at System.Net.Http.DiagnosticsHandler+<SendAsync>d__2.MoveNext (System.Net.Http, Version=4.2.2.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a)

Inner exception System.IO.IOException handled at System.Net.Http.HttpConnection+<SendAsyncCore>d__53.MoveNext:

   at System.Net.Http.HttpConnection+<SendAsyncCore>d__53.MoveNext (System.Net.Http, Version=4.2.2.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a)

@JeremyTCD
Copy link
Member

Thanks for the extra details. We'll need a bit more information, System.Net.Http.HttpRequestException is quite a high level exception. The following inner exception's message would help:

Inner exception System.IO.IOException handled at System.Net.Http.HttpConnection+d__53.MoveNext:

Are you able to add logging to your project? Check out the first comment, it includes this library's log output, which lists retry count and the hierarchy of inner exceptions and their log messages.

Also is it possible for you to reproduce the issue in a public repository?

@aKzenT
Copy link
Collaborator

aKzenT commented May 8, 2020

This is the log output from the library:

An invocation attempt failed. Retries remaining: 1.
Exception:
  System.Net.Http.HttpRequestException: An error occurred while sending the request.
---> System.IO.IOException: The response ended prematurely.
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.DiagnosticsHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Jering.Javascript.NodeJS.HttpNodeJSService.TryInvokeAsync[T](InvocationRequest invocationRequest, CancellationToken cancellationToken)
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.TryInvokeCoreAsync[T](InvocationRequest invocationRequest, CancellationToken cancellationToken)

I don't think I can reproduce this in a pulic repository. It is worth noticing that this affects about on in a thousand calls.

@JeremyTCD
Copy link
Member

Did some reading up on the .Net side. Found an identical issue: dotnet/runtime#31528. Also took a look at the code throwing the IOException:
https://github.com/dotnet/runtime/blob/c06810bf654e09f016fe34dd2b4ac31fb73370a1/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs#L477-L490.

Noticed that HttpConnection uses NetEventSource to log, e.g. https://github.com/dotnet/runtime/blob/c06810bf654e09f016fe34dd2b4ac31fb73370a1/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs#L160. If you could enable event source tracing, it might give us a clue. I haven't tried tracing HttpConnection, but from this article it seems straightforward: https://developers.redhat.com/blog/2019/12/23/tracing-net-core-applications/.

Short-term, I suggest increasing retries to 3: OutOfProcessNodeJSServiceOptions.NumRetries.

@blushingpenguin
Copy link
Contributor

This call stack seems to be very similar to what you get if the node process dies for some reason, e.g.

System.Net.Http.HttpRequestException: An error occurred while sending the request.
 ---> System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..
 ---> System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.
   --- End of inner exception stack trace ---
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Jering.Javascript.NodeJS.HttpNodeJSService.TryInvokeAsync[T](InvocationRequest invocationRequest, CancellationToken cancellationToken)
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.TryInvokeCoreAsync[T](InvocationRequest invocationRequest, CancellationToken cancellationToken)
   at Jering.Javascript.NodeJS.OutOfProcessNodeJSService.InvokeFromStringAsync[T](String moduleString, String newCacheIdentifier, String exportName, Object[] args, CancellationToken cancellationToken)

which can be easily reproduced by running the node process out of ram using a combination of:

        let bigThing = {}
        for (let i = 0; i < 1024000; ++i) {
            bigThing[`prop${i}1`] = "a".repeat(1024 * 1024);
        }

and

            services.Configure<NodeJSProcessOptions>(
                options => options.NodeAndV8Options = "--max-old-space-size=512"); // 512Mb

When this happens node produces detailed diagnostic messages, but these are lost making it difficult to know what actually went wrong. I think collating the messages from node's stderr/stdout would likely help diagnose the issues above.

@JeremyTCD
Copy link
Member

JeremyTCD commented Mar 5, 2021

6.0.0-beta.2 now uses HTTP/2 which should mitigate connection issues.

It also exposes a new option, OutOfProcessNodeJSServiceOptions.NumProcessRetries that retries in a new process if retries in the original process fail:

/// <summary>
/// <para>The number of times we create a new NodeJS process to retry an invocation.</para>
/// <para>Invocations are retried <see cref="NumRetries"/> times in the existing NodeJS process. Once <b>existing process retries</b> are exhausted,
/// if any <b>process retries</b> remain, a new NodeJS process is created and invocations are tried <see cref="NumRetries"/> times in the new process.</para>
/// <para>For example, consider the situation where <see cref="NumRetries"/> and this value are both 1. An invocation is first tried in the existing process.
/// If it fails it is retried in the same process. If it fails again, a new process is created and the invocation is retried there once. In total, the
/// invocation is attempted 3 times.</para>
/// <para>If set to a negative value, new NodeJS processes are recreated for retries indefinitely.</para>
/// <para>If the module source of an invocation is an unseekable stream, the invocation is not retried.
/// If you require retries for such streams, copy their contents to a <see cref="MemoryStream"/>.</para>
/// <para>Defaults to 1.</para>
/// </summary>
public int NumProcessRetries { get; set; } = 1;

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants