RavenDb 4: NullReferenceException @ at Raven.Server.Documents.Revisions.RevisionsStorage.Put
210 views
Skip to first unread message
Arno den Uijl
Aug 6, 2018, 3:20:06 PM8/6/18
to RavenDB - 2nd generation document database
Hi,
While abusing a ravendb server I sometimes get the exception below. I think it;s some edge case I hit somewhere in ravendb. I think on the server, but i'm not sure. Maybe it's something to investigate?! If so, i'm happy to help. Some details:
The error
20:25 [Error] () Exception in subscription
Raven.Client.Exceptions.RavenException: System.NullReferenceException: Object reference not set to an instance of an object. at Raven.Server.Documents.Revisions.RevisionsStorage.Put(DocumentsOperationContext context, String id, BlittableJsonReaderObject document, DocumentFlags flags, NonPersistentDocumentFlags nonPersistentFlags, String changeVector, Int64 lastModifiedTicks, RevisionsCollectionConfiguration configuration, CollectionName collectionName) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\Revisions\RevisionsStorage.cs:line 349 at Raven.Server.Documents.DocumentPutAction.PutDocument(DocumentsOperationContext context, String id, String expectedChangeVector, BlittableJsonReaderObject document, Nullable`1 lastModifiedTicks, String changeVector, DocumentFlags flags, NonPersistentDocumentFlags nonPersistentFlags) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\DocumentPutAction.cs:line 153 at Raven.Server.Documents.Handlers.BatchHandler.MergedBatchCommand.Execute(DocumentsOperationContext context) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\Handlers\BatchHandler.cs:line 311 at Raven.Server.Documents.TransactionOperationsMerger.RunEachOperationIndependently(List`1 pendingOps) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\TransactionOperationsMerger.cs:line 787--- End of stack trace from previous location where exception was thrown --- at Raven.Server.Documents.TransactionOperationsMerger.Enqueue(MergedTransactionCommand cmd) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\TransactionOperationsMerger.cs:line 93 at Raven.Server.Documents.Handlers.BatchHandler.BulkDocs() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\Handlers\BatchHandler.cs:line 55 at Raven.Server.Routing.RequestRouter.HandlePath(HttpContext context, String method, String path) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Routing\RequestRouter.cs:line 116 at Raven.Server.RavenServerStartup.RequestHandler(HttpContext context) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\RavenServerStartup.cs:line 161 ---> System.NullReferenceException: System.NullReferenceException: Object reference not set to an instance of an object. at Raven.Server.Documents.Revisions.RevisionsStorage.Put(DocumentsOperationContext context, String id, BlittableJsonReaderObject document, DocumentFlags flags, NonPersistentDocumentFlags nonPersistentFlags, String changeVector, Int64 lastModifiedTicks, RevisionsCollectionConfiguration configuration, CollectionName collectionName) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\Revisions\RevisionsStorage.cs:line 349 at Raven.Server.Documents.DocumentPutAction.PutDocument(DocumentsOperationContext context, String id, String expectedChangeVector, BlittableJsonReaderObject document, Nullable`1 lastModifiedTicks, String changeVector, DocumentFlags flags, NonPersistentDocumentFlags nonPersistentFlags) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\DocumentPutAction.cs:line 153 at Raven.Server.Documents.Handlers.BatchHandler.MergedBatchCommand.Execute(DocumentsOperationContext context) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\Handlers\BatchHandler.cs:line 311 at Raven.Server.Documents.TransactionOperationsMerger.RunEachOperationIndependently(List`1 pendingOps) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\TransactionOperationsMerger.cs:line 787--- End of stack trace from previous location where exception was thrown --- at Raven.Server.Documents.TransactionOperationsMerger.Enqueue(MergedTransactionCommand cmd) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\TransactionOperationsMerger.cs:line 93 at Raven.Server.Documents.Handlers.BatchHandler.BulkDocs() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Documents\Handlers\BatchHandler.cs:line 55 at Raven.Server.Routing.RequestRouter.HandlePath(HttpContext context, String method, String path) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\Routing\RequestRouter.cs:line 116 at Raven.Server.RavenServerStartup.RequestHandler(HttpContext context) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Server\RavenServerStartup.cs:line 161 --- End of inner exception stack trace --- at Raven.Client.Exceptions.ExceptionDispatcher.Throw(JsonOperationContext context, HttpResponseMessage response, Action`1 additionalErrorInfo) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Exceptions\ExceptionDispatcher.cs:line 108 at Raven.Client.Http.RequestExecutor.HandleUnsuccessfulResponse[TResult](ServerNode chosenNode, Nullable`1 nodeIndex, JsonOperationContext context, RavenCommand`1 command, HttpRequestMessage request, HttpResponseMessage response, String url, SessionInfo sessionInfo, Boolean shouldRetry) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Http\RequestExecutor.cs:line 1017 at Raven.Client.Http.RequestExecutor.ExecuteAsync[TResult](ServerNode chosenNode, Nullable`1 nodeIndex, JsonOperationContext context, RavenCommand`1 command, Boolean shouldRetry, SessionInfo sessionInfo, CancellationToken token) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Http\RequestExecutor.cs:line 764 at Raven.Client.Http.RequestExecutor.ExecuteAsync[TResult](ServerNode chosenNode, Nullable`1 nodeIndex, JsonOperationContext context, RavenCommand`1 command, Boolean shouldRetry, SessionInfo sessionInfo, CancellationToken token) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Http\RequestExecutor.cs:line 804 at Raven.Client.Util.AsyncHelpers.RunSync(Func`1 task) in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Util\AsyncHelpers.cs:line 79 at Raven.Client.Documents.Session.DocumentSession.SaveChanges() in C:\Builds\RavenDB-Stable-4.0\src\Raven.Client\Documents\Session\DocumentSession.cs:line 79 at Sogyo.Eventsourcing.RavenDb.GlobalEventNumber.AddGlobalEventNumberSubscription.<>c__DisplayClass2_0.<Start>b__0(SubscriptionBatch`1 batch) in /home/arnodenuijl/projects/Eventsourcing4/Sogyo.Eventsourcing.RavenDb/GlobalEventNumber/AddGlobalEventNumberSubscription.cs:line 96
Versions:
- server: RavenDb 4.0.6 on 64 bit ubuntu. Laptop with 4 core and 32GB Ram
- client: .net core application with RavenDB.Client 4.0.6
What abuse are we doing?
I don't have a short repo and the code is a bit elaborate. But the the gist is:
1. Create a database with revisions
documentStore.Maintenance.Server.Send(new CreateDatabaseOperation(new DatabaseRecord(DatabaseName)
{ Revisions = new RevisionsConfiguration { Default = new RevisionsCollectionConfiguration() } }));2. Create a data subscription on a collection and patch the documents from the batches
This is the code where the exception is caught.
We receive docs from a single collection. And the first time we get a document we add some metadata. If we receive a document andthe metadata is already there we do nothing. So we don't create an infinite loop.
var sub = documentStore.Subscriptions.GetSubscriptionWorker(GlobaleventnumbersubscriptionName);sub.Run(batch =>{ try { using (var session = documentStore.OpenSession()) { foreach (var batchedItem in batch.Items) { if(SomeCondition(batchedItem)) { var globalEventNumber = GetNewGlobalEventNumber(); var command = new PatchCommandData( batchedItem.Id, batchedItem.ChangeVector, new PatchRequest { Script = $"this['@metadata']['GlobalEventNumber']={globalEventNumber};" }, null ); session.Advanced.Defer(command); } } session.SaveChanges(); } } catch (Exception e) { _logger.ErrorException("Exception in subscription", e); throw; }});3. Parallel inserting docs and mutating a single doc with a lot of conflicting edits
Basic setup:
- I have a single document in ravendb
- In 15 seperate concurrent tasks try to insert a new document (in the collection where the data subscription is listening for) and mutate the first document. And in case of a concurrency exception, try again
And I do this for 15 seperate sets of documents
So we try to update the same docs from different concurrent tasks we get a lot concurrency exceptions. After a lot of retries in the end all the edits are processed. We then have 15 new documents and the single document has 16 revisions (the original and 15 updates). And that for 15 sets of documents.
And now?
- Does the exception indicate some edge case in ravendb that we should tackle?
- If so, does this description help?
- If it's not enough, is there some logging in the server I can provide?
- I could give the code, but there is a lot of noise in there. I could also try to replicate the error in a smaller repo
So.......
kind regards,
Arno den Uijl
Oren Eini (Ayende Rahien)
Aug 7, 2018, 2:57:36 AM8/7/18
to ravendb
Hi,
Thanks for the very detailed bug report.
This shouldn't be happening. In general, we consider any NRE, for any reason, to be a bug.
The code in question seems to be here:
And the relevant table is created here:
So I don't see how that can happen, but we'll be trying to reproduce this locally and see what is going on there.
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.
Arno den Uijl
Aug 7, 2018, 4:41:40 AM8/7/18
to RavenDB - 2nd generation document database
Based on some Console.Writeline debugging it appears the null comes from
Oren Eini (Ayende Rahien)
Aug 7, 2018, 4:42:53 AM8/7/18
to ravendb
Yes, there is no table, but there _must_ be a table, because we call ensure
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
On Tue, Aug 7, 2018 at 11:41 AM, Arno den Uijl <arnod...@gmail.com> wrote:
Based on some Console.Writeline debugging it appears the null comes from
Arno den Uijl
Aug 7, 2018, 7:13:45 AM8/7/18
to RavenDB - 2nd generation document database
If I follow the the methods from EnsureRevisionTableCreated it goes through
RevisionsStorage :: EnsureRevisionTableCreated(Transaction tx, CollectionName collection) ->
Transaction :: OpenTable(TableSchema schema, string name) ->
Transaction :: OpenTable(TableSchema schema, Slice name) ->Transaction :: ReadTree(Slice treeName, RootObjectType type = RootObjectType.VariableSizeTree, bool isIndexTree = false, NewPageAllocator newPageAllocator = null)
Here the line
var header = (TreeRootHeader*)_lowLevelTransaction.RootObjects.DirectRead(treeName); is called and that returns null and from that it ends the method with
_trees.Add(treeName, null);
return null;
I see this code mostly being hit from CreateTree after which it checks for null and a new tree is added. But here we come from OpenTable and that doesn't do that.
Also in my case it seems like at some point there was a tree for the key it is looking for. But since header is null it overwrites it in _trees with null
Yes, there is no table, but there _must_ be a table, because we call ensure
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
On Tue, Aug 7, 2018 at 11:41 AM, Arno den Uijl <arnod...@gmail.com> wrote:
Based on some Console.Writeline debugging it appears the null comes from
--
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.
Oren Eini (Ayende Rahien)
Aug 7, 2018, 7:33:50 AM8/7/18
to ravendb
The key here is this call:
If the table does not exists, we are supposed to create it. I'm not seeing how this cannot be.
Given that you can reproduce this on your end, can you say when the
Isn't call?
| RevisionsSchema.Create(tx, tableName, 16); |
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.
Arno den Uijl
Aug 7, 2018, 11:19:33 AM8/7/18
to RavenDB - 2nd generation document database
Hi,
I can see that call being made and it looks like the tableschema is created.
It goes into TableSchema.Create(Transaction tx, Slice name, ushort? sizeInPages) and into TableSchema.Create(Transaction tx, Slice name, ushort? sizeInPages)
I see Transaction.CreateTree being called and in there i see it calls
using (_lowLevelTransaction.RootObjects.DirectAdd(name, len, out byte* ptr))
tree.State.CopyTo((TreeRootHeader*)ptr);
if, after this I call _lowLevelTransaction.RootObjects.DirectRead(name) I get a pointer that is not null
If the same is called later from OpenTable->ReadTree it is null.
One thing i noticed is that it uses TryUseRecentTransactionPage around that point, maybe it's something there?!
I feel it's kind of hard to get good feedback since I'm not that familiar with the ravendb codebase. I'm happy to continue searching, trying things and bouncing suggestions, but maybe thats not the most effective on your end.
I've put the program in a docker container. You can run docker run -it --net host arnodenuijl/testapp and see if you can get it to fail on your side?!
It will connect to http://localhost:8080. You will see a bunch of warning messages running over the screen, that means its busy. It will run for ca. a minute and then just stay quiet. Just CTRL+C and run again. If it runs into the error it will print a stacktrace and stop.
I can also send you the source, but it's a test program with a lot of noise. So making sense of what it does isn't that simple, but it's probably good if you can get the server to fail on your end.
Arno den Uijl
Aug 7, 2018, 5:33:46 PM8/7/18
to RavenDB - 2nd generation document database
In https://github.com/ravendb/ravendb/blob/5e0b86cf42efb736b564ebc4d527a2dff29cca24/src/Raven.Server/Documents/Revisions/RevisionsStorage.cs#L95
The first time if (_tableCreated.Add(collection.Name)) returns true and RevisionsSchema.Create(tx, tableName, 16); is called.
I see I enter EnsureRevisionTableCreated twice.
The first time if (_tableCreated.Add(collection.Name)) returns true and RevisionsSchema.Create(tx, tableName, 16); is called.
The second time if (_tableCreated.Add(collection.Name)) returns false and RevisionsSchema.Create(tx, tableName, 16); is not called.
Can it be that the transaction that creates the revision scheme is rolled back because of an conflict and that that messes things up because _tableCreated is not aware of transactions?
And so the second time, with a new transaction it thinks it already created the revision schema but is unaware it has been rolled back
or something in that nature :-)
Oren Eini (Ayende Rahien)
Aug 8, 2018, 6:54:45 AM8/8/18
to ravendb
Yes, that is _very_ likely what is going on.
Thanks you for the report and the explanation. I'll be sure to fix this shortly.
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
Oren Eini (Ayende Rahien)
Aug 9, 2018, 4:55:52 AM8/9/18
to or...@ravendb.net, ravendb
We have a fix, which will be out soon, in the meantime, a workaround is to explicitly specify revisions support for the collections you have. This will create this in a separate tx and avoid the problem entirely.
Arno den Uijl
Aug 9, 2018, 5:03:02 AM8/9/18
to RavenDB - 2nd generation document database
Thanks. That will work!
Reply all
Reply to author
Forward
0 new messages