RavenDB 4 - Connection forcibly closed during streaming

[Andrej Krivulčík]

I experience intermittent issues during streaming data.

I'm reading all records from an index and exporting them to a file.

I irregularly encounter the following exception with sync approach [1] and async approach [2]:

System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host.

The occurrences are quite intriguing, sometimes, I can process 500k records without a problem, other times, the processing quite consistently fails after processing 40k-45k records (different records, I always skip the approximate number of records already processed). This 40k-45k "limit" was quite consistent for maybe 10 runs, in other cases, it fails after somewhat random number of records.

The logic is pretty simple:

// I'm using a raw query to work around this issue: https://groups.google.com/forum/#!topic/ravendb/nrUl1CaMCY8

var query = session.Advanced.AsyncRawQuery<MyClass>("from index my_index where string_field != null order by Id select Id, and bunch of other fields")
                    .Skip(skip);

var stream = await session.Advanced.StreamAsync(query);

while (await stream.MoveNextAsync())
{
    var company = stream.Current.Document;
    // export data to file
}

There are 51 fields selected (including Id), two string and 49 double? fields.

There is nothing in server logs, nothing in client logs. How could I go around investigating this issue should it happen again?

[1] Exception when processing synchronously:

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: An existing connection was forcibly closed by the remote host

   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)

   --- End of inner exception stack trace ---

   at System.Net.GZipWrapperStream.Read(Byte[] buffer, Int32 offset, Int32 size)

   at System.Net.Http.HttpClientHandler.WebExceptionWrapperStream.Read(Byte[] buffer, Int32 offset, Int32 count)

   at Sparrow.Json.Parsing.UnmanagedJsonParserHelper.ReadObject(BlittableJsonDocumentBuilder builder, PeepingTomStream peepingTomStream, UnmanagedJsonParser parser, ManagedPinnedBuffer buffer)

   at Sparrow.Json.Parsing.UnmanagedJsonParserHelper.<ReadArrayToMemory>d__10.MoveNext()

   at Raven.Client.Documents.Session.Operations.StreamOperation.<SetResult>d__7.MoveNext()

   at Raven.Client.Documents.Session.DocumentSession.<YieldResults>d__58`1.MoveNext()

   at [my code]

[2] Exception when processing asynchronously:

System.AggregateException: One or more errors occurred. ---> 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: An existing connection was forcibly closed by the remote host

   at System.Net.Sockets.Socket.BeginReceive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)

   at System.Net.Sockets.NetworkStream.BeginRead(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)

   --- End of inner exception stack trace ---

   at System.Net.GZipWrapperStream.EndRead(IAsyncResult asyncResult)

   at System.Threading.Tasks.TaskFactory`1.FromAsyncTrimPromise`1.Complete(TInstance thisRef, Func`3 endMethod, IAsyncResult asyncResult, Boolean requiresSynchronization)

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at System.Net.Http.HttpClientHandler.WebExceptionWrapperStream.<ReadAsync>d__4.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Sparrow.PeepingTomStream.<ReadAsync>d__10.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Sparrow.Json.Parsing.UnmanagedJsonParserHelper.<ReadObjectAsync>d__9.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Documents.Session.Operations.StreamOperation.YieldStreamResults.<MoveNextAsync>d__13.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Documents.Session.AsyncDocumentSession.YieldStream`1.<MoveNextAsync>d__12.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()

   at [my code]

   --- End of inner exception stack trace ---

   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)

   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)

   at System.Threading.Tasks.Task.Wait()

   at [my code]

---> (Inner Exception #0) 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: An existing connection was forcibly closed by the remote host

   at System.Net.Sockets.Socket.BeginReceive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)

   at System.Net.Sockets.NetworkStream.BeginRead(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)

   --- End of inner exception stack trace ---

   at System.Net.GZipWrapperStream.EndRead(IAsyncResult asyncResult)

   at System.Threading.Tasks.TaskFactory`1.FromAsyncTrimPromise`1.Complete(TInstance thisRef, Func`3 endMethod, IAsyncResult asyncResult, Boolean requiresSynchronization)

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at System.Net.Http.HttpClientHandler.WebExceptionWrapperStream.<ReadAsync>d__4.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Sparrow.PeepingTomStream.<ReadAsync>d__10.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Sparrow.Json.Parsing.UnmanagedJsonParserHelper.<ReadObjectAsync>d__9.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Documents.Session.Operations.StreamOperation.YieldStreamResults.<MoveNextAsync>d__13.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at Raven.Client.Documents.Session.AsyncDocumentSession.YieldStream`1.<MoveNextAsync>d__12.MoveNext()

--- End of stack trace from previous location where exception was thrown ---

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()

   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()

   at [my code]

 

[Andrej Krivulčík]

Disregard my previous message, I was looking at something else than I thought.

On Thursday, June 21, 2018 at 1:57:24 PM UTC+2, Andrej Krivulčík wrote:

Nevermind the ...

[Tal Weiss]

Is it possible to messure the time it took to skip all the documents? It sounds like the skip duration is longer than the http timeout, I don't recall the configuration for extending it, can you check it in the documentation (writing from my phone)? 

On Thu, Jun 21, 2018, 14:57 Andrej Krivulčík <kriv...@gmail.com> wrote:

Nevermind the .Skip(skip) on a RawQuery which does nothing, I just did some changes to the code to make it prettier. The problem persisted when really skipping various number of results.

On Thursday, June 21, 2018 at 1:54:33 PM UTC+2, Andrej Krivulčík wrote:

// I'm using a raw query to work around this issue: https://groups.google.com/forum/#!topic/ravendb/nrUl1CaMCY8

var query = session.Advanced.AsyncRawQuery<MyClass>("from index my_index where string_field != null order by Id select Id, and bunch of other fields")
                    .Skip(skip);

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Andrej Krivulčík]

It only takes a while. The processing actually starts, then proceeds for about 10-15 minutes (the 40k records in typical case) and then it is forcibly closed.

[Arkadiusz Palinski]

Is is possible that db gets unloaded because it thinks it's idle? Can you try to increase Databases.MaxIdleTimeInSec (default 900 = 15 minutes) ?

[Andrej Krivulčík]

It might be possible, I'll give it a try. However, I just checked the logs and the processing was stopped after 10-13 minutes so it would need to not take into account anything in the session - connecting, finding out topology and streaming itself.

Is it possible to find out whether the db is unloaded (after failure)?

[Andrej Krivulčík]

Ok, so this is not the cause, it failed for me twice, for Databases.MaxIdleTimeInSec set to 90 and 9000, both times after roughly 12 minutes. The database was freshly restarted in both cases (to apply configuration change).

Any suggestions about how to investigate why the server disconnects the client?

Both server and client run on the same machine.

[Oren Eini (Ayende Rahien)]

Can you try running this through Fiddler?

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Andrej Krivulčík]

No luck replicating with fiddler running.

I run without fiddler - stops after 11 minutes (twice).

Then I run with fiddler - runs ok for more than an hour - I stopped it afterwards.

Immediately after this I run without fiddler - stops after 11 minutes.

Any further ideas?

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

[Arkadiusz Palinski]

Anything in Raven logs? Is the database working correctly after that happens?

[Andrej Krivulčík]

Nothing in logs (Manage Server -> Admin Logs, also replicated to filesystem). Is there a way to have more detailed logging? (https://ravendb.net/docs/article-page/4.0/csharp/server/troubleshooting/logging says that Admin Logs should provide everything there is)

Database works correctly after this, I didn't notice anything unusual, except for these disconnections.

[Arkadiusz Palinski]

Yes, Admin Logs provide everything - you need to have it enabled at the time of performing the streaming operation though 

[Andrej Krivulčík]

Yes, I had it running from before starting the processing until the disconnection. Nothing unusual in the logs though.

[Andrej Krivulčík]

I just double checked again, I'm attaching the exported admin log (query redacted). The processing failed at 12:19:58. No log messages at that time.

There is one interesting log entry:

2018-06-22T12:15:58.1067319Z, 10, Information, Server, Raven.Server.RavenServerStartup, POST /databases/data-prod/streams/queries? - 200 - 1,590,934 ms

This is related to a processing query from a previous run which was started at 11:49:26 and I interrupted it at around 12:09. No idea why it was logged after another 6-7 minutes.

There is no such entry for the failed query until now - around 15 minutes after the disconnection.

[Oren Eini (Ayende Rahien)]

The fact that it works through Fiddler implies that it is something in the network. 

Do you have anything like AV product that might interfer?

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

[Andrej Krivulčík]

No, this runs on a pretty bare Azure VM.

It is probably related to the processing being slow. In Wireshark, I can see TCP Window Full messages (twice), and after the second occurrence, the connection is reset.

I can send the wireshark dump if that would be useful.

This code reproduces the issue pretty well, it disconnects after approximately 10 minutes of processing (running on localhost, 4.1.0-nightly-20180625-0430 both server and client):

using NLog;
using Raven.Client.Documents;
using Raven.Client.Documents.Indexes;
using System;
using System.Collections.Generic;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;

namespace RavenDB4Tests.Tryouts
{
    public static class QueryDisconnect
    {
        private static Logger _logger = LogManager.GetCurrentClassLogger();

        public static async Task QueryDisconnectTest()
        {
            using (var store = new DocumentStore
            {
                Urls = new[] { "http://localhost:8080" },
                Database = "QueryDisconnect"
            }.Initialize())
            {
                await new DocsIndex().ExecuteAsync(store);

                using (var session = store.OpenAsyncSession())
                {
                    if (await ShouldInitData(store))
                    {
                        await InitializeData(store);
                    }

                    // wait for indexing manually
                }
                var docs = await LoadDocs(store);
            }
        }

        private static async Task<Dictionary<string, Doc>> LoadDocs(IDocumentStore store)
        {
            var docs = new Dictionary<string, Doc>();
            using (var session = store.OpenAsyncSession())
            {
                var indexQuery = session.Query<Doc, DocsIndex>();
                _logger.Info("Creating index stream");
                var indexStream = await session.Advanced.StreamAsync(indexQuery);
                _logger.Info("Index stream created");

                while (await indexStream.MoveNextAsync())
                {
                    var doc = indexStream.Current.Document;
                    docs[doc.Id] = doc;
                    if (doc.Id.EndsWith("00"))
                    {
                        _logger.Info($"Processing (index) {doc.Id}");
                    }
                    Thread.Sleep(50);
                }
            }

            return docs;
        }

        private static async Task<bool> ShouldInitData(IDocumentStore documentStore)
        {
            using (var session = documentStore.OpenAsyncSession())
            {
                var doc = await session.LoadAsync<Doc>("doc/1");
                return doc == null;
            }
        }

        private static async Task InitializeData(IDocumentStore documentStore)
        {
            _logger.Info("Generating data.");
            var rng = new Random();
            var batches = 20;
            var perBatch = 1000;
            for (int batchNo = 0; batchNo < batches; batchNo++)
            {
                _logger.Info($"Generating batch {batchNo + 1}/{batches}");
                using (var session = documentStore.OpenAsyncSession())
                {
                    for (int i = 1; i <= perBatch; i++)
                    {
                        await session.StoreAsync(new Doc
                        {
                            Id = "doc/" + (batchNo * perBatch + i),
                            StrVal = new string(Enumerable.Repeat('A', 10000).ToArray()),
                        });
                    }

                    await session.SaveChangesAsync();
                }
            }
            _logger.Info("Data generated.");
        }

        public class Doc
        {
            public string Id { get; set; }
            public string StrVal { get; set; }
        }

        public class DocsIndex : AbstractIndexCreationTask<Doc>
        {
            public DocsIndex()
            {
                Map = docs =>
                    from doc in docs
                    select new
                    {
                        doc.Id,
                        doc.StrVal,
                    };

                StoreAllFields(FieldStorage.Yes);
            }
        }
    }
}

[Oren Eini (Ayende Rahien)]

Yes, that would cause this issue, sure.

See: 

https://ayende.com/blog/170401/timeouts-tcp-and-streaming-operations

You are better off with subscription for such a scenario, they are intended to handle this case.

Hibernating Rhinos Ltd  

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

 

[Andrej Krivulčík]

Thanks for the reminder, that is it. In this case, I could speed it up sufficiently to process it correctly (I had one horrible inefficiency there). Thanks again.