Reading past the end of the stream

[Andrej Krivulčík]

I'm still working on the processing of documents (https://groups.google.com/forum/#!topic/ravendb/rx4v9te-Kzc and https://groups.google.com/forum/#!topic/ravendb/Iu6mkfF1CaQ).

Today, the processing was stuck mid-batch. I can't determine where exactly (removed some of the logging to speed up the processing) but in there are no RavenDB calls in the part where it got stuck.

When I restarted the processing, the subscription with the used ID was not available. I confirmed this through the studio - no subscriptions were available. although I have had several from prior testing.

When trying to create a new subscription (no big deal), I received the following error:

Unhandled Exception: Raven.Abstractions.Connection.ErrorResponseException: Url: "/databases/[my-database]/subscriptions/create"

System.AggregateException: Error when executing write ---> System.IO.EndOfStreamException: Attempted to read past the end of the stream.

   at Voron.Impl.FreeSpace.StreamBitArray..ctor(ValueReader reader)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryFindSmallValue(Transaction tx, TreeIterator it, Int32 num)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryAllocateFromFreeSpace(Transaction tx, Int32 num)

   at Voron.Impl.Transaction.AllocatePage(Int32 numberOfPages, PageFlags flags, Nullable`1 pageNumber)

   at Voron.Trees.Tree.NewPage(PageFlags flags, Int32 num)

   at Voron.Trees.PageSplitter.Execute()

   at Voron.Trees.Tree.DirectAdd(MemorySlice key, Int32 len, NodeFlags nodeType, Nullable`1 version)

   at Voron.Trees.Tree.Add(Slice key, Stream value, Nullable`1 version)

   at Voron.Impl.TransactionMergingWriter.HandleOperations(Transaction tx, List`1 writes, CancellationToken token)

   at Voron.Impl.TransactionMergingWriter.HandleActualWrites(OutstandingWrite mine, CancellationToken token)

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

   at Voron.Impl.TransactionMergingWriter.Write(WriteBatch batch)

   at Raven.Database.Storage.Voron.Impl.TableStorage.Write(WriteBatch writeBatch) in C:\Builds\RavenDB-3.5-RC\Raven.Database\Storage\Voron\Impl\TableStorage.cs:line 135

   at Raven.Storage.Voron.TransactionalStorage.ExecuteBatch(Action`1 action) in C:\Builds\RavenDB-3.5-RC\Raven.Database\Storage\Voron\TransactionalStorage.cs:line 402

   at Raven.Storage.Voron.TransactionalStorage.Batch(Action`1 action) in C:\Builds\RavenDB-3.5-RC\Raven.Database\Storage\Voron\TransactionalStorage.cs:line 338

   at Raven.Database.Actions.SubscriptionActions.CreateSubscription(SubscriptionCriteria criteria) in C:\Builds\RavenDB-3.5-RC\Raven.Database\Actions\SubscriptionActions.cs:line 47

   at Raven.Database.Server.Controllers.SubscriptionsController.<Create>d__1.MoveNext() in C:\Builds\RavenDB-3.5-RC\Raven.Database\Server\Controllers\SubscriptionsController.cs:line 46

--- 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.Threading.Tasks.TaskHelpersExtensions.<CastToObject>d__3`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`1.GetResult()

   at System.Web.Http.Controllers.ApiControllerActionInvoker.<InvokeActionAsyncCore>d__0.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`1.GetResult()

   at System.Web.Http.Controllers.ActionFilterResult.<ExecuteAsync>d__2.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`1.GetResult()

   at System.Web.Http.Controllers.ExceptionFilterResult.<ExecuteAsync>d__0.MoveNext()

---> (Inner Exception #0) System.IO.EndOfStreamException: Attempted to read past the end of the stream.

   at Voron.Impl.FreeSpace.StreamBitArray..ctor(ValueReader reader)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryFindSmallValue(Transaction tx, TreeIterator it, Int32 num)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryAllocateFromFreeSpace(Transaction tx, Int32 num)

   at Voron.Impl.Transaction.AllocatePage(Int32 numberOfPages, PageFlags flags, Nullable`1 pageNumber)

   at Voron.Trees.Tree.NewPage(PageFlags flags, Int32 num)

   at Voron.Trees.PageSplitter.Execute()

   at Voron.Trees.Tree.DirectAdd(MemorySlice key, Int32 len, NodeFlags nodeType, Nullable`1 version)

   at Voron.Trees.Tree.Add(Slice key, Stream value, Nullable`1 version)

   at Voron.Impl.TransactionMergingWriter.HandleOperations(Transaction tx, List`1 writes, CancellationToken token)

   at Voron.Impl.TransactionMergingWriter.HandleActualWrites(OutstandingWrite mine, CancellationToken token)<---

   at Raven.Client.Connection.Implementation.HttpJsonRequest.<CheckForErrorsAndReturnCachedResultIfAnyAsync>d__41.MoveNext() in C:\Builds\RavenDB-3.5-RC\Raven.Client.Lightweight\Connection\Implementation\HttpJsonRequest.cs:line 488

--- 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.<>c__DisplayClass36_0.<<SendRequestInternal>b__0>d.MoveNext() in C:\Builds\RavenDB-3.5-RC\Raven.Client.Lightweight\Connection\Implementation\HttpJsonRequest.cs:line 268

--- 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-3.5-RC\Raven.Client.Lightweight\Connection\Implementation\HttpJsonRequest.cs:line 312

--- 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.Document.AsyncDocumentSubscriptions.<CreateAsync>d__4.MoveNext() in C:\Builds\RavenDB-3.5-RC\Raven.Client.Lightweight\Document\AsyncDocumentSubscriptions.cs:line 61

--- 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-3.5-RC\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-3.5-RC\Raven.Abstractions\Util\AsyncHelpers.cs:line 89

   at Raven.Client.Document.DocumentSubscriptions.Create(SubscriptionCriteria criteria, String database) in C:\Builds\RavenDB-3.5-RC\Raven.Client.Lightweight\Document\DocumentSubscriptions.cs:line 25

   at [my code]

I didn't notice the RAM or storage usage at that point of time.

After restarting the database, some HTTP calls from studio fail with the following error:

{

  "Url": "/databases/[my-database]/reduced-database-stats",

  "Error": "System.IO.InvalidDataException: Failed to de-serialize a document: raven/alerts ---> Raven.Imports.Newtonsoft.Json.JsonReaderException: Unexpected character encountered while parsing value: ?. Path '', line 0, position 0.

   at Raven.Imports.Newtonsoft.Json.JsonTextReader.ParseValue() in C:\\Builds\\RavenDB-3.5-RC\\Imports\\Newtonsoft.Json\\Src\\Newtonsoft.Json\\JsonTextReader.cs:line 935

   at Raven.Imports.Newtonsoft.Json.JsonTextReader.ReadInternal() in C:\\Builds\\RavenDB-3.5-RC\\Imports\\Newtonsoft.Json\\Src\\Newtonsoft.Json\\JsonTextReader.cs:line 393

   at Raven.Imports.Newtonsoft.Json.JsonTextReader.Read() in C:\\Builds\\RavenDB-3.5-RC\\Imports\\Newtonsoft.Json\\Src\\Newtonsoft.Json\\JsonTextReader.cs:line 314

   at Raven.Json.Linq.RavenJObject.Load(JsonReader reader) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Abstractions\\Json\\Linq\\RavenJObject.cs:line 191

   at Raven.Abstractions.Extensions.JsonExtensions.ToJObject(Stream self) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Abstractions\\Extensions\\JsonExtensions.cs:line 83

   at Raven.Database.Storage.Voron.StorageActions.DocumentsStorageActions.ReadDocumentData(String normalizedKey, Slice sliceKey, Etag existingEtag, RavenJObject metadata, Int32& size) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\StorageActions\\DocumentsStorageActions.cs:line 838

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

   at Raven.Database.Storage.Voron.StorageActions.DocumentsStorageActions.ReadDocumentData(String normalizedKey, Slice sliceKey, Etag existingEtag, RavenJObject metadata, Int32& size) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\StorageActions\\DocumentsStorageActions.cs:line 880

   at Raven.Database.Storage.Voron.StorageActions.DocumentsStorageActions.DocumentByKey(String key) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\StorageActions\\DocumentsStorageActions.cs:line 460

   at Raven.Database.Actions.DocumentActions.<>c__DisplayClass16_0.<Get>b__0(IStorageActionsAccessor actions) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Actions\\DocumentActions.cs:line 592

   at Raven.Storage.Voron.TransactionalStorage.ExecuteBatch(Action`1 action) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\TransactionalStorage.cs:line 402

   at Raven.Storage.Voron.TransactionalStorage.Batch(Action`1 action) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\TransactionalStorage.cs:line 338

   at Raven.Database.Actions.DocumentActions.Get(String key, TransactionInformation transactionInformation) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Actions\\DocumentActions.cs:line 616

   at Raven.Database.DocumentDatabase.GetNumberOfAlerts() in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\DocumentDatabase.cs:line 716

   at Raven.Database.DocumentDatabase.get_ReducedStatistics() in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\DocumentDatabase.cs:line 617

   at Raven.Database.Server.Controllers.StatisticsController.ReducedDatabaseStats() in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Server\\Controllers\\StatisticsController.cs:line 23

   at lambda_method(Closure , Object , Object[] )

   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass10.<GetExecutor>b__9(Object instance, Object[] methodParameters)

   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)

--- 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`1.GetResult()

   at System.Web.Http.Controllers.ApiControllerActionInvoker.<InvokeActionAsyncCore>d__0.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`1.GetResult()

   at System.Web.Http.Controllers.ActionFilterResult.<ExecuteAsync>d__2.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`1.GetResult()

   at System.Web.Http.Controllers.ExceptionFilterResult.<ExecuteAsync>d__0.MoveNext()"

}

(The question mark is actually the unicode unknown symbol. I replaced \r\n with newlines manually.)

When trying to delete the "raven/alerts" document (store.DatabaseCommands.Delete("raven/alerts", null);), I get the following error:

{

  "Url":"/databases/[my-database]/docs/raven/alerts",

  "Error":"System.AggregateException: Error when executing write ---> System.IO.EndOfStreamException: Attempted to read past the end of the stream.

   at Voron.Impl.FreeSpace.StreamBitArray..ctor(ValueReader reader)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryFindSmallValue(Transaction tx, TreeIterator it, Int32 num)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryAllocateFromFreeSpace(Transaction tx, Int32 num)

   at Voron.Impl.Transaction.AllocatePage(Int32 numberOfPages, PageFlags flags, Nullable`1 pageNumber)

   at Voron.Trees.Tree.NewPage(PageFlags flags, Int32 num)

   at Voron.Trees.PageSplitter.Execute()

   at Voron.Trees.Tree.DirectAdd(MemorySlice key, Int32 len, NodeFlags nodeType, Nullable`1 version)

   at Voron.Trees.Tree.Add(Slice key, Stream value, Nullable`1 version)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.FreePage(Transaction tx, Int64 pageNumber)

   at Voron.Impl.Transaction.FreePage(Int64 pageNumber)

   at Voron.Trees.Tree.FreePage(Page p)

   at Voron.Trees.TreeRebalancer.Execute(Page page)

   at Voron.Trees.Tree.Delete(Slice key, Nullable`1 version)

   at Voron.Impl.TransactionMergingWriter.HandleOperations(Transaction tx, List`1 writes, CancellationToken token)

   at Voron.Impl.TransactionMergingWriter.HandleActualWrites(OutstandingWrite mine, CancellationToken token)

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

   at Voron.Impl.TransactionMergingWriter.Write(WriteBatch batch)

   at Raven.Database.Storage.Voron.Impl.TableStorage.Write(WriteBatch writeBatch) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\Impl\\TableStorage.cs:line 135

   at Raven.Storage.Voron.TransactionalStorage.ExecuteBatch(Action`1 action) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\TransactionalStorage.cs:line 402

   at Raven.Storage.Voron.TransactionalStorage.Batch(Action`1 action) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Storage\\Voron\\TransactionalStorage.cs:line 338

   at Raven.Database.Actions.DocumentActions.Delete(String key, Etag etag, TransactionInformation transactionInformation, RavenJObject& metadata, String[] participatingIds) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Actions\\DocumentActions.cs:line 873

   at Raven.Database.Server.Controllers.DocumentsController.DocDelete(String docId) in C:\\Builds\\RavenDB-3.5-RC\\Raven.Database\\Server\\Controllers\\DocumentsController.cs:line 195

   at lambda_method(Closure , Object , Object[] )

   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass10.<GetExecutor>b__9(Object instance, Object[] methodParameters)

   at System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)

--- 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`1.GetResult()

   at System.Web.Http.Controllers.ApiControllerActionInvoker.<InvokeActionAsyncCore>d__0.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`1.GetResult()

   at System.Web.Http.Controllers.ActionFilterResult.<ExecuteAsync>d__2.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`1.GetResult()

   at System.Web.Http.Controllers.ExceptionFilterResult.<ExecuteAsync>d__0.MoveNext()

---> (Inner Exception #0) System.IO.EndOfStreamException: Attempted to read past the end of the stream.

   at Voron.Impl.FreeSpace.StreamBitArray..ctor(ValueReader reader)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryFindSmallValue(Transaction tx, TreeIterator it, Int32 num)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.TryAllocateFromFreeSpace(Transaction tx, Int32 num)

   at Voron.Impl.Transaction.AllocatePage(Int32 numberOfPages, PageFlags flags, Nullable`1 pageNumber)

   at Voron.Trees.Tree.NewPage(PageFlags flags, Int32 num)

   at Voron.Trees.PageSplitter.Execute()

   at Voron.Trees.Tree.DirectAdd(MemorySlice key, Int32 len, NodeFlags nodeType, Nullable`1 version)

   at Voron.Trees.Tree.Add(Slice key, Stream value, Nullable`1 version)

   at Voron.Impl.FreeSpace.FreeSpaceHandling.FreePage(Transaction tx, Int64 pageNumber)

   at Voron.Impl.Transaction.FreePage(Int64 pageNumber)

   at Voron.Trees.Tree.FreePage(Page p)

   at Voron.Trees.TreeRebalancer.Execute(Page page)

   at Voron.Trees.Tree.Delete(Slice key, Nullable`1 version)

   at Voron.Impl.TransactionMergingWriter.HandleOperations(Transaction tx, List`1 writes, CancellationToken token)

   at Voron.Impl.TransactionMergingWriter.HandleActualWrites(OutstandingWrite mine, CancellationToken token)<---

"

}

(Replaced \r\n with newlines manually.)

There is plenty of free storage on the server. System disk where RavenDB and system database are located has 107 GB out of 126 GB free. Data disk where the database is located has 200 GB out of 511 GB free. There is around 5 GB of RAM available (standby + free) on the server. There is one map/reduce index being side-by-side-recomputed. Server/client build #35169.

How can I recover from this situation?

[Oren Eini (Ayende Rahien)]

How did you restart things? 

This kind of error usually indicate a disk corruption

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.

[Andrej Krivulčík]

Services -> RavenDB -> right click -> Restart. It restarted quite fast (before the progressbar got to half and slowed down) which was surprising for me. It started immediately quite fast. There are no errors in the log, logs "Service stopped successfully." and "Service started successfully." are 11 seconds apart. I didn't notice anything unusual during this restart.

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

[Andrej Krivulčík]

Hi everyone, I ended up recovering the database from export, RavenDB team will examine the corrupted database more closely to determine if there is anything that could be done to prevent this kind of issues.