"A task was canceled" exception on first session.Load after programmatic upgrade

[Kyle Levien]

We have upgrade code built into a wix msi that upgrades our raven databases and client sites from ravenDB 2.5 to 3.5.1 and are encountering a task canceled exception on first document load (in the msi, after binary replacement and server startup) for large content stores. We are wondering if this is an artifact from the data file format conversion taking too long and trying to read data before it's done? Is there a way to detect whether the upgrade process is complete?

We also see this error occurring when performing a Session.Load<>() as well as DatabaseCommands.Get() with the following stack trace (using dbcommands.get example):

Server stack trace: at Raven.Client.Connection.Implementation.HttpJsonRequest.<>c__DisplayClass36_0.<<SendRequestInternal>b0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Raven.Client.Connection.Implementation.HttpJsonRequest.<RunWithAuthRetry>d38`1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Raven.Client.Connection.Implementation.HttpJsonRequest.<ReadResponseJsonAsync>d35.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task) at Raven.Client.Connection.Async.AsyncServerClient.<DirectGetAsync>d71.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Raven.Client.Connection.ReplicationInformerBase`1.<TryOperationAsync>d34`1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task) at Raven.Client.Connection.ReplicationInformerBase`1.<ExecuteWithReplicationAsync>d33`1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Raven.Client.Connection.Async.AsyncServerClient.<ExecuteWithReplication>d163`1.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Raven.Abstractions.Util.AsyncHelpers.<>cDisplayClass1_1`1.<<RunSync>b__0>d.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at Raven.Abstractions.Util.AsyncHelpers.RunSync(Func`1 task) at Raven.Client.Connection.ServerClient.Get(String key)

[Oren Eini (Ayende Rahien)]

Yes, this is a timeout from the server.

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.
For more options, visit https://groups.google.com/d/optout.

[Kyle Levien]

Is this an expected timeout when upgrading a large site? Is there a way to detect if/when the upgrade is complete?

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

[Oren Eini (Ayende Rahien)]

Access the /stats endpoint, it will either throw on timeout, or give you a valid response, in which case it is done.

And yes, for large datasets, this can take a bit

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

[Kyle Levien]

Would polling DatabaseCommands.GetStatistics() until it succeeds be sufficient?

[Oren Eini (Ayende Rahien)]

Yes

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

[Kyle Levien]

Thanks

[Kyle Levien]

The polling for GetStatistics() on start up appears to work and handles the timeouts on large dataset upgrades, but we are now getting an odd task canceled error during normal operation. During a series of reads with a handful of writes we get the following exception during a document load:

A task was canceled.

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<>c__DisplayClass36_0.<<SendRequestInternal>b__0>d.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Connection\Implementation\HttpJsonRequest.cs:line 258

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

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

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

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<RunWithAuthRetry>d__38`1.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Connection\Implementation\HttpJsonRequest.cs:line 314

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

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

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

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<ReadResponseJsonAsync>d__35.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Connection\Implementation\HttpJsonRequest.cs:line 221

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

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

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

   at Raven.Client.Connection.Async.AsyncServerClient.<DirectGetAsync>d__71.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Connection\Async\AsyncServerClient.cs:line 798

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

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

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

   at Raven.Client.Connection.ReplicationInformerBase`1.<TryOperationAsync>d__34`1.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Connection\ReplicationInformerBase.cs:line 419

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

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

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

   at Raven.Client.Connection.ReplicationInformerBase`1.<ExecuteWithReplicationAsync>d__33`1.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Connection\ReplicationInformerBase.cs:line 314

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

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

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

   at Raven.Client.Connection.Async.AsyncServerClient.<ExecuteWithReplication>d__163`1.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Connection\Async\AsyncServerClient.cs:line 0

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

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

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

   at Raven.Abstractions.Util.AsyncHelpers.<>c__DisplayClass1_1`1.<<RunSync>b__0>d.MoveNext() in C:\Builds\RavenDB-Stable-3.5\Raven.Abstractions\Util\AsyncHelpers.cs:line 75

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

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

   at Raven.Abstractions.Util.AsyncHelpers.RunSync[T](Func`1 task) in C:\Builds\RavenDB-Stable-3.5\Raven.Abstractions\Util\AsyncHelpers.cs:line 89

   at Raven.Client.Document.DocumentSession.Load[T](String id) in C:\Builds\RavenDB-Stable-3.5\Raven.Client.Lightweight\Document\DocumentSession.cs:line 277

I've had a look in the raven nlog file which is on Info level with no messages.

In the event viewer the only thing from that time is the following error 2 minutes after the exception:

Raven (207328) 6-64PSKsoqa4a/--B:\sites\cms-v9-506\site\RavenWeb\..\..\DB\IGXContentStore\Data: The database engine stopped the instance (1). 

 

Dirty Shutdown: 0 

 

Internal Timing Sequence: [1] 0.000, [2] 0.000, [3] 0.000, [4] 0.000, [5] 0.016, [6] 0.000, [7] 0.000, [8] 0.000, [9] 0.000, [10] 0.000, [11] 0.000, [12] 0.000, [13] 0.000, [14] 0.000, [15] 0.000.

When I debug into the repro I see a series of socket timeout exceptions with the message "A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond" before the task is canceled and everything rolls back.

We have the following set in our DocumentStore constructor to handle the socket overrun issue:

HttpMessageHandlerFactory = () => new WebRequestHandler()

{

UnsafeAuthenticatedConnectionSharing = true,

PreAuthenticate = true,

Credentials = CredentialCache.DefaultNetworkCredentials

}

Any help would be appreciated. I can also file this as a new thread if that's better.

Thanks,

Kyle.

[Oren Eini (Ayende Rahien)]

Can you show the fiddler output?

What exact build are you using on both client & server?

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

[Kyle Levien]

We were using the 3.5.1 release and just upgraded to 3.5.2 today and still see the error.

The google drive link to the fiddler dump is here:

https://drive.google.com/file/d/0B5N8gyqsPHlrSzg0ejFVXzk3UDA/view?usp=sharing

Though there didn't seem to be much out of the ordinary. It cruises along until around request #7776 when the client then hangs for a number of minutes, throws a 'task canceled' exception which bails out of the main session, but continues with some background operations.

When debugging the server there is no exception of note and no errors in the log. When debugging the raven client there will be a series of socket exceptions immediately followed by the task canceled exception.

I hope something in there helps, this is currently a blocking issue in our 2.5-3.5 upgrade.

Thanks,

Kyle

[Kyle Levien]

Double post.

I created a fairly simple failing unit test that I'll post here.

After more investigation it appears the culprit might be the deferred delete action when used to remove a large number of objects.

Here is our test:

using System;

using Microsoft.VisualStudio.TestTools.UnitTesting;

using Raven.Tests.Helpers;

using Raven.Client.Embedded;

using System.Linq;

using Raven.Client.Document;

namespace RavenDeferDeleteTest

{

public class Item

{

public string Id { get; set; }

}

[TestClass]

public class UnitTest1 : RavenTestBase

{

[TestMethod]

public void TestMethod1()

{

using (EmbeddableDocumentStore store = NewDocumentStore(requestedStorage: "esent"))

{

string[] itemIds = Enumerable.Range(0, 100000).Select(i => $"item/{i}").ToArray();

using (var session = store.OpenSession())

{

foreach (string itemId in itemIds)

session.Store(new Item() { Id = itemId });

session.SaveChanges();

}

using (var session = store.OpenSession())

{

Item item = session.Load<Item>("item/55");

Assert.IsNotNull(item);

}

using (var session = store.OpenSession())

{

foreach (string itemId in itemIds)

session.Delete(itemId);

session.SaveChanges();

}

using (var session = store.OpenSession())

{

Item item = session.Load<Item>("item/55");

Assert.IsNull(item);

}

}

}

}

}

It is failing in the delete session with the same "A task was canceled" exception and ...MoveNext() stack trace as above.

Kyle

[Oren Eini (Ayende Rahien)]

This actually repro the issue?!

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

[Kyle Levien]

Yep. In fact, if we change the session.Delete(itemId) to the older api: session.Advanced.Defer(new DeleteCommandData { Key = itemId });

we see it work just fine with the RavenDB 2.5 test helper package, but fail with the 3.5 package.

[Oren Eini (Ayende Rahien)]

Okay, I had a chance to look at this, and it make sense.

You are violating a lot of assumptions here.

Saving 100,000 documents in a single transaction, that requires us to do a LOT of work.

That is done a in a single transaction,and means that the HTTP request is waiting for it to happen. It is quite likely that the request will time out in this case.

Note that deletes are expensive, so you are more likely to see it there, but the general scenario is the same.

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

[Kyle Levien]

Did a timeout change between 2.5 and 3.5? Or something change in the Advanced.Defer code? Did it used to be async maybe? The exact same test case passes in 2.5.2956 in ~18seconds but with 3.5.2 it fails after 3 minutes.

If this is now no longer viable, does that mean it is impossible to do ACID deletions of many documents in RavenDB?

[Kyle Levien]

I see the following high level change --

Raven 2.5:

public BatchResult[] Batch(IEnumerable<ICommandData> commandDatas)

{

return ExecuteWithReplication("POST", u => DirectBatch(commandDatas, u));

}

Raven 3.5:

public BatchResult[] Batch(IEnumerable<ICommandData> commandDatas, BatchOptions options = null)

{

return AsyncHelpers.RunSync(() => asyncServerClient.BatchAsync(commandDatas, options));

[Jahmai Lay]

Async socket methods (and therefore HTTP methods) don't respect the Timeout values on reads and writes, so this would do it.

[Kyle Levien]

Should there maybe be another setting on the DocumentSession similar to the MaxNumberOfRequestsPerSession setting that can be counted and compared to help in automatically paginating large saves or deletes? We currently have a UserSession wrapper that opens new raven sessions on demand when it exhausts its number of requests, but there's not an immediately helpful way to split up loaded entities into separate sessions to alleviate this socket cancellation issue.

Our data structure allows large batch operations that have to be ACID so manually splitting up the update requests into separate sessions is not ideal.

[Kyle Levien]

For completeness here is the full unit test output for the failing test:

Test Name: TestMethod1

Test Outcome: Failed

Result Message:

Test method RavenDeferDeleteTest.UnitTest1.TestMethod1 threw exception: 

Raven.Abstractions.Connection.ErrorResponseException: A task was canceled.

Error calling Test Cleanup method for test class RavenDeferDeleteTest.UnitTest1: System.IO.IOException: The following processes are locking C:\Users\klevien\Documents\Visual Studio 2015\Projects\RavenDeferDeleteTest\RavenDeferDeleteTest\bin\Debug\TestMethod1-2017-01-05,17-19-02-1\System\Data

 vstest.executionengine.x86 111340

Result StandardOutput:

Debug Trace:

1/5/2017 5:19:04 PM Starting Mass Store...

TransactionalStorage.Batch was called after it was disposed, call was ignored.

System.AggregateException: DocumentStorageActions disposal error. ---> Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetCloseDatabase(JET_SESID sesid, JET_DBID dbid, CloseDatabaseGrbit grbit) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 366

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<Dispose>b__69_1() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 160

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31

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

   at Raven.Database.Impl.ExceptionAggregator.ThrowIfNeeded() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 49

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.Dispose() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 169

   at Raven.Storage.Esent.TransactionalStorage.ExecuteBatch(Action`1 action, EsentTransactionContext transactionContext) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 913

   at Raven.Storage.Esent.TransactionalStorage.Batch(Action`1 action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 819

---> (Inner Exception #0) Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetCloseDatabase(JET_SESID sesid, JET_DBID dbid, CloseDatabaseGrbit grbit) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 366

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<Dispose>b__69_1() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 160

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31<---

---> (Inner Exception #1) Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetRollback(JET_SESID sesid, RollbackTransactionGrbit grbit) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 1030

   at Microsoft.Isam.Esent.Interop.Transaction.Rollback() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Transaction.cs:line 104

   at Microsoft.Isam.Esent.Interop.Transaction.ReleaseResource() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Transaction.cs:line 115

   at Microsoft.Isam.Esent.Interop.EsentResource.Dispose(Boolean isDisposing) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\EsentResource.cs:line 71

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<.ctor>b__68_0() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 84

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<Dispose>b__69_2() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 166

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31<---

---> (Inner Exception #2) Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetCloseTable(JET_SESID sesid, JET_TABLEID tableid) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 895

   at Microsoft.Isam.Esent.Interop.Table.ReleaseResource() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Table.cs:line 107

   at Microsoft.Isam.Esent.Interop.EsentResource.Dispose(Boolean isDisposing) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\EsentResource.cs:line 71

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<>c__DisplayClass69_0.<Dispose>b__0() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 154

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31<---

TransactionalStorage.Batch was called after it was disposed, call was ignored.

System.AggregateException: DocumentStorageActions disposal error. ---> Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetRollback(JET_SESID sesid, RollbackTransactionGrbit grbit) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 1030

   at Microsoft.Isam.Esent.Interop.Transaction.Rollback() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Transaction.cs:line 104

   at Microsoft.Isam.Esent.Interop.Transaction.ReleaseResource() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Transaction.cs:line 115

   at Microsoft.Isam.Esent.Interop.EsentResource.Dispose(Boolean isDisposing) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\EsentResource.cs:line 71

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<.ctor>b__68_0() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 84

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<Dispose>b__69_2() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 166

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31

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

   at Raven.Database.Impl.ExceptionAggregator.ThrowIfNeeded() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 49

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.Dispose() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 169

   at Raven.Storage.Esent.TransactionalStorage.ExecuteBatch(Action`1 action, EsentTransactionContext transactionContext) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 913

   at Raven.Storage.Esent.TransactionalStorage.Batch(Action`1 action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 819

---> (Inner Exception #0) Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetRollback(JET_SESID sesid, RollbackTransactionGrbit grbit) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 1030

   at Microsoft.Isam.Esent.Interop.Transaction.Rollback() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Transaction.cs:line 104

   at Microsoft.Isam.Esent.Interop.Transaction.ReleaseResource() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Transaction.cs:line 115

   at Microsoft.Isam.Esent.Interop.EsentResource.Dispose(Boolean isDisposing) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\EsentResource.cs:line 71

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<.ctor>b__68_0() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 84

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<Dispose>b__69_2() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 166

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31<---

---> (Inner Exception #1) Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetCloseTable(JET_SESID sesid, JET_TABLEID tableid) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 895

   at Microsoft.Isam.Esent.Interop.Table.ReleaseResource() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Table.cs:line 107

   at Microsoft.Isam.Esent.Interop.EsentResource.Dispose(Boolean isDisposing) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\EsentResource.cs:line 71

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<>c__DisplayClass69_0.<Dispose>b__0() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 154

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31<---

---> (Inner Exception #2) Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetCloseDatabase(JET_SESID sesid, JET_DBID dbid, CloseDatabaseGrbit grbit) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 366

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<Dispose>b__69_1() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 160

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31<---

---> (Inner Exception #3) Microsoft.Isam.Esent.Interop.EsentTermInProgressException: Termination in progress

   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739

   at Microsoft.Isam.Esent.Interop.Api.JetCloseTable(JET_SESID sesid, JET_TABLEID tableid) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 895

   at Microsoft.Isam.Esent.Interop.Table.ReleaseResource() in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Table.cs:line 107

   at Microsoft.Isam.Esent.Interop.EsentResource.Dispose(Boolean isDisposing) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\EsentResource.cs:line 71

   at Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions.<>c__DisplayClass69_0.<Dispose>b__0() in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Storage\Esent\StorageActions\General.cs:line 154

   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in C:\Builds\RavenDB-Stable-3.5\Raven.Database\Impl\ExceptionAggregator.cs:line 31<---

[Oren Eini (Ayende Rahien)]

Are you runnging this embedded in 2.5?

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

[Oren Eini (Ayende Rahien)]

That is a really bad idea. There max number is there for a reason ( and it is settable so you can override that logic ).

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

[Kyle Levien]

For the above test I am using the NewDocumentStore(requestedStorage: "esent") command from the Raven.Tests.Helpers nuget package from both 2.5 and 3.5. The test fails in 3.5 but passes in 2.5 (and runs much quicker).

For our product itself we do not use embedded raven, instead we run raven through IIS. Our builds with raven 2.5 do not exhibit the task canceled behavior on large operations but the builds with raven 3.5.1 and 3.5.2 do.

I can provide the test solution itself if needed, but it's nothing more than what I pasted above.

I agree having a max stores or max deletes per session setting would be bad because if it is due to an async http call timeout there's no hard number that could guarantee acceptance. Larger documents or slower infrastructure could affect it.

Here's an example where we need a large store operation to be ACID. We have a site tree of pages that use a version of materialized paths to create hierarchy IDs and store their structure for indexing. If we copy a portion of this tree to another location we need the entire set of pages and associated content to be created or none of it and return an error. Any kind of partial store would create an incomplete tree and be difficult to resolve.

[Kyle Levien]

As an aside, I updated the test case to batch sessions by 1024 documents and while it passes in both versions, the 2.5 test takes only 15 seconds while 3.5 is a whopping 50s.

[Kyle Levien]

Attached are the fiddler captures of the failing (3.5) and succeeding (2.5) tests. Request packet size looks the same between the two, the 2.5 test has a server think time of 12s and returns 200 while the 3.5 test has a server think time of 300s and returns 408 timout.

[Oren Eini (Ayende Rahien)]

In 2.5, that is using embedded instance to directly talk to the database, there can't be a timeout, since this is a direct method call.

In 3.5, this is going over the local network, and is subject to timeout.

It is also much more expensive for large data loads like this.

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

[Kyle Levien]

Sorry I should have added that the two tests I did that have a fiddler capture (same behavior as base unit test) were initialized with document stores connecting to actual databases running behind IIS, neither of which are embedded.

[Oren Eini (Ayende Rahien)]

Okay, thanks for this, we are going to look at this next week

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

[Oren Eini (Ayende Rahien)]

http://issues.hibernatingrhinos.com/issue/RavenDB-6061

[Kyle Levien]

Thanks!

[Michael Yarichuk]

Hi,

This issue is fixed and soon we will issue a build with the fix.

On Fri, Jan 6, 2017 at 9:48 PM, Kyle Levien <teh...@gmail.com> wrote:

Thanks!

--
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.
For more options, visit https://groups.google.com/d/optout.

--

Best regards,

 

Hibernating Rhinos Ltd  

Michael Yarichuk l RavenDB Core Team 

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

 

RavenDB paving the way to "Data Made Simple"   http://ravendb.net/  

[Kyle Levien]

Looking forward to it, thanks!

On Sunday, January 8, 2017 at 5:41:30 AM UTC-8, Michael Yarichuk wrote:

Hi,

This issue is fixed and soon we will issue a build with the fix.

On Fri, Jan 6, 2017 at 9:48 PM, Kyle Levien <teh...@gmail.com> wrote:

Thanks!

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

[Kyle Levien]

As an update from our tests while the above is being worked on. Is there a limit to the number of documents that can be returned through the Advanced.Stream() enumerator?

We're seeing similar timeouts when trying to start a stream that would cover a large number of documents.

I've made a raven test case to illustrate the issue:

1) The database is populated with 2,000,000 documents of 'Item' type, defined above.

2) the following code is run in a unit test using Raven.Test.Helpers nuget package and pointing at the pre-populated db:

DateTime start = DateTime.Now;

using (var session = store.OpenSession())

{

Item item;

int i = 0;

var query = session.Query<Item>("Raven/DocumentsByEntityName");

try

{

using (var enumerator = session.Advanced.Stream(query))

while (enumerator.MoveNext())

{

Debug.WriteLine(i++);

item = enumerator.Current.Document;

}

}

catch (Exception e)

{

Debug.WriteLine((DateTime.Now - start).ToString() + " -- " + i);

throw e;

}

Debug.WriteLine(i + " -- " + docCount);

Debug.WriteLine((DateTime.Now - start).ToString());

Assert.IsTrue(i == docCount);

}

3) The test fails with a task canceled/operation timed out exception after: 00:01:40.0272885 with the following output:

Test Name: TestMethod1

Test Outcome: Failed

Result Message:

Test method RavenDeferDeleteTest.UnitTest1.TestMethod1 threw exception: 

System.TimeoutException: Operation timed out after: 00:01:40.0272885 ---> System.AggregateException: AsyncHelpers.Run method threw an exception. ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.

Result StandardOutput:

Debug Trace:

1/12/2017 2:14:05 PM - Test Read...

128

00:01:40.0341017 -- 0

From this it looks like the client is timing out and/or the server is trying to produce the entire result before anything is sent over the stream.

I am inspecting in fiddler and can see the stream request still running after the client has timed out:

I'm able to reproduce it against the same db on a remote machine as well as locally. I've attached the fiddler traffic for the local test.

Do you think that the work being done on the filed bug would apply to this issue as well or is there something else at play on the 3.0+ server?

Thanks,

Kyle

[Oren Eini (Ayende Rahien)]

Are you running this on IIS? Did the server time out the request?

There isn't a limit to the size that you can send on a stream.

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.

[Kyle Levien]

Our product runs through IIS, but my tests are through visual studio.

What's strange to me is that when using raven 2.5 (client and server) for our product I can see the data streaming in piecemeal. There is no delay in receiving the first packet and I can report to the log consistently through the stream. When we use the 3.5.2 raven dlls (client and server) it never seems to get into the while (enumerator.MoveNext()) {} loop to begin with. In fiddler I can see the stream request sent and it continues sending data long after the client code throws an exception with "Operation timed out after: 00:01:40" (always 100 seconds). There are two inner exceptions as well:

Exception: Operation timed out after: 00:01:40.0271048

Inner:                  AsyncHelpers.Run method threw an exception.

Inner:                             A task was canceled.

This behavior is consistent with what we see in the unit tests running long streams as well.

[Kyle Levien]

After some further tests it appears that fiddler is getting in the way of the stream api. If I disable the fiddler capture I see the documents streaming in incrementally. Is there a fidder configuration that I might be missing that allows the stream to pass through?

[Oren Eini (Ayende Rahien)]

Yes,

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

[Kyle Levien]

Perfect, did the trick!

Thanks!