QueryAsync HttpRequestExceptions - Response ended prematurely

ticontask · November 8, 2021, 5:12pm

Running a DotNet Core 3.1 app with the Couchbase .NET client 2.7.26.

I recently updated a test server from Couchbase Enterprise Edition 6.0.3 build 2895 to Enterprise Edition 6.6.3 build 9808 in preparation for an update of production servers. After the update, I started seeing QueryClient Errors similar to the following:

2021/11/05 16:01:47.075|ERR|006|Couchbase.N1QL.QueryClient||
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 Couchbase.N1QL.QueryClient.ExecuteQueryAsync[T](IQueryRequest queryRequest, CancellationToken cancellationToken)

Is there a configuration option that needs to be set?

Thanks,
T

ticontask · November 23, 2021, 5:34pm

I have done some addition investigation in the the HttpRequestException caught when executing a query. It appears the Couchbase server is disconnecting from the client, captured a TCP RST command from the Couchbase Server just prior to the HttpRequestException.

My question; is there a way to disable this behavior in the Couchbase Server, and if not, is there a change I can make to the application to prevent this from happening?

The application uses Dependency Injection to establish the client connection to the Couchbase server, and holds on to the bucket retrieved from a NamedBucketProvider. This bucket object is repeatedly used to run queries.

Any help would be appreciated

Thanks,
T

btburnett3 · November 23, 2021, 6:12pm

@ticontask

Are these long-running queries? There is a query timeout which is enforced on the server, I’m wondering if that could be a factor. Also, are you using SSL/TLS?

ticontask · November 23, 2021, 6:21pm

These are not long-running queries, simple selects which most of the time return nothing. Not using SSL

Thanks,
T

jmorris · November 23, 2021, 6:25pm

@ticontask -

I don’t have a resolution, but this was reported elsewhere. It can be triggered by “select 1”.

Jeff

ticontask · November 23, 2021, 6:35pm

@jmorris

Is there any additional logging on the server or client that would help me identify the issue?

Thanks,
T

jmorris · November 23, 2021, 8:29pm

There are server logs to correlate, but I am not 100% sure which ones to TBH.

vsr1 · November 23, 2021, 8:34pm

Try run the same query via Query Workbench and see if that works to eliminate server issues.

jmorris · November 23, 2021, 8:51pm

@ticontask -

Is it intermittent or every query?

jmorris · November 24, 2021, 7:56pm

@ticontask -

We think we have identified the issue and its related to a server change involving idle timeouts. There is a ticket and were working on a fix.

Jeff

ticontask · November 29, 2021, 11:50am

@jmorris

Intermittent - Here are the query errors logged during an hour run against the same bucket object. This query is triggered every second:

2021/11/29 10:02:59.779|WRN|0ae|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:04:51.776|WRN|077|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:05:05.780|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:09:04.821|WRN|07e|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:09:23.789|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:09:52.781|WRN|03f|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:12:01.780|WRN|054|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:12:10.786|WRN|06d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:15:11.775|WRN|0ae|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:15:39.780|WRN|08e|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:18:03.778|WRN|077|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:20:03.803|WRN|03f|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:21:33.817|WRN|054|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:23:02.791|WRN|0ae|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:24:11.781|WRN|077|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:26:12.790|WRN|0a3|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:26:50.782|WRN|053|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:29:16.776|WRN|06d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:29:40.775|WRN|077|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:30:12.779|WRN|0ae|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:30:33.775|WRN|062|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:31:22.803|WRN|053|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:31:29.778|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:31:49.781|WRN|053|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:32:00.774|WRN|06d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:32:12.785|WRN|0ae|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:33:09.787|WRN|06d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:33:14.784|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70749','70750','70751','70752','70753','70754'] - retrying; An error occurred while sending the request.
2021/11/29 10:36:21.781|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:37:31.793|WRN|0a3|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:37:37.781|WRN|092|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:38:17.787|WRN|092|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:39:09.795|WRN|092|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:39:31.795|WRN|06d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:39:51.779|WRN|054|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:41:13.808|WRN|053|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:43:46.779|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:44:14.792|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:44:51.785|WRN|0a3|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:47:17.790|WRN|092|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:49:08.801|WRN|06d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:49:23.789|WRN|092|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:49:50.810|WRN|08e|SmsDataRepo||HttpRequest Error(1) counting pending work for ['39460','51070'] - retrying; An error occurred while sending the request.
2021/11/29 10:51:04.785|WRN|092|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:51:24.792|WRN|054|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:56:08.786|WRN|062|SmsDataRepo||HttpRequest Error(1) counting pending work for ['18444634066','18444634067','18444634068'] - retrying; An error occurred while sending the request.
2021/11/29 10:58:07.779|WRN|07d|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.
2021/11/29 10:58:48.782|WRN|0a3|SmsDataRepo||HttpRequest Error(1) counting pending work for ['70755','70756','70757','70758','70759'] - retrying; An error occurred while sending the request.

ticontask · November 30, 2021, 2:43pm

@jmorris

Are there instructions somewhere to build the dotnet sdk so I can test the fix?

Thanks,
T

ticontask · December 8, 2021, 8:53pm

I downloaded the couchbase-net-client sdk from github this morning and built it to test the fix.
Build command: dotnet build -c Release -o bin Src/Couchbase/Couchbase.csproj

I ran the app for about 10 minutes and am still seeing the client being disconnected from the host.

2021/12/08 15:08:25.687|DBG|005|Couchbase.Query.QueryClient||Request canceled
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.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Couchbase.Query.QueryClient.ExecuteQuery[T](QueryOptions options, ITypeSerializer serializer, IRequestSpan span)

Is my build command correct?
Are there any new configuration properties that I need to set on the client?

Thanks

jmorris · December 8, 2021, 9:21pm

ticontask:

---> 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 ---

That is actually a slightly different error (and a different SDK version 2.7.x vs 3.x) than previously reported:

This could be caused by a different issue, we would have to figure out why the socket is being closed by the remote host.

What version of .NET are you using? The original post was CB SDK 2.7.2 and .NET Core App 3.1 (note that we haven’t yet patched 2.7.x).

There are a couple of different settings which you can adjust in ClusterOptions:

IdleHttpConnectionTimeout
EnableTcpKeepAlives with TcpKeepAliveTime.TotalMilliseconds and TcpKeepAliveInterval
HttpConnectionLifetime
PooledConnectionIdleTimeout

Which ones the SDK actually uses is determined by the .NET version you are using…internally we use HttpClientHandler or SocketsHttpHandler and/or the ServicePointManager to set these values.

Jeff

ticontask · December 8, 2021, 9:40pm

@jmorris

Sorry, for leaving out that information, I upgrade the to the Couchbase .NET 3.2.4 client, so that output is from the 3.2.4.
Yesterday, I built Couchbase.NetClient.dll from the Github source code and did not see any difference.

.NET Core 3.1
Couchbase .NET client 3.2.4+

Thanks,
T

ticontask · December 9, 2021, 7:07pm

@jmorris
I mispoke in my last communication, I have not been testing with a locally built version of the SDK. Can’t seem to get the app lo load and run with the locally built package.

I am a novice when it comes to NuGet packages. I tried replacing the package DLL with one built locally with no success.
Created a local package and added that to the project and Just replacing the DLL gives manifest errors. Creating a local package and adding to the project results in build errors “The type ‘IBucket’ is defined in an assembly that is not referenced”. Still trying to work my way through this. Any help would be appreciated.

Thanks for all the help,
T

ticontask · December 13, 2021, 9:46pm

@jmorris
Jeff,

I updated the .NET SDK to version 3.2.5 and tried the test again. I am still seeing RequestCancelledExceptions with a HTTP reset being sent by the server.
.NET Core 3.1 app
Couchbase .NET SDK version 3.2.5
Server Enterprise Edition 6.6.3 build 9808 - IPv4

Sample Exception trace:

Couchbase.Core.Exceptions.RequestCanceledException: The query was canceled.
 ---> 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 Couchbase.Query.QueryClient.ExecuteQuery[T](QueryOptions options, ITypeSerializer serializer, IRequestSpan span)
   --- End of inner exception stack trace ---
   at Couchbase.Query.QueryClient.ExecuteQuery[T](QueryOptions options, ITypeSerializer serializer, IRequestSpan span)
   at Couchbase.Query.QueryClient.QueryAsync[T](String statement, QueryOptions options)
   at Couchbase.Cluster.<>c__DisplayClass33_0`1.<<QueryAsync>g__Func|0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Couchbase.Core.Retry.RetryOrchestrator.RetryAsync[T](Func`1 send, IRequest request)
   at Couchbase.Cluster.QueryAsync[T](String statement, QueryOptions options)
   at SmsDataRepo.NotificationsGet(BlockingCollection`1 workQueue, Int32 maxItems) in SmsDataRepo-Notification.cs:line 318
-----------------------Context Info---------------------------
{"Statement":"[{\"prepared\":\"[127.0.0.1:8091]bdb5801a-61ca-5e04-9b5b-9fe9a6b67bd7\",\"timeout\":\"75000ms\",\"readonly\":true,\"metrics\":false,\"$hostname\":\"vm03\",\"scan_consistency\":\"request_plus\",\"client_context_id\":\"0c21eb0d-8a5b-4f4c-be7d-e15764a93917\"}]","ClientContextId":"0c21eb0d-8a5b-4f4c-be7d-e15764a93917","Parameters":"{\"Named\":{\"$hostname\":\"vm03\"},\"Raw\":{},\"Positional\":[]}","HttpStatus":408,"QueryStatus":6,"Errors":null,"Message":null}

This query runs every 5 seconds. I tried setting “IdleHttpConnectionTimeout” to 6000 in my ClusterOptions, but it made no difference.

Not sure what else to try. Any assistance appreciated.

Thanks,
T

jmorris · December 15, 2021, 6:25pm

@ticontask

Have you tried using .NET 5.0 or greater?

ticontask · December 15, 2021, 7:33pm

@jmorris
Jeff,

I have, no change that I could see in the log. Still seeing query failures with Couchbase.Core.Exceptions.RwquestCanceledException and HttpStatus of 408 in the context.

Thanks,
T

jmorris · December 15, 2021, 7:37pm

@ticontask -

Can you post your client configuration (ClusterOptions)? I’ll see if I can reproduce again.