"Collection was modified; enumeration operation may not execute." in 2.0

[Vlad Kosarev]

Our setup - 3 web api servers running the same thing, 2 ravendb servers (master-master replication).

We are getting errors below intermittently. Any idea what could be causing this? We got them on writes and I thought that had to do with some etag magic but we are also getting them on reads. The error below came from an index query but that index does depend on a value that gets written.

It seems like on raven side index breaks because one of the values in transform gets changed while it's reindexing?

Here's a part (in bold) of Transform in our index that might be the culprit -

            TransformResults = (database, results) =>

                               from result in results

                               let liveEvent = database.Load<LiveEvent>(result.Id)

                               let sections = database.Load<TicketSection>(liveEvent.TicketSections)

                               select new

                                   {

                                       Etag = MetadataFor(liveEvent)["@etag"],

                                       LiveEvent = liveEvent,

                                       TicketSections = from s in sections

                                                        let inventoryRecord = !string.IsNullOrWhiteSpace(s.InventoryRecordId)

                                                                ? database.Load<InventoryRecord>(s.InventoryRecordId)

                                                                    : (InventoryRecord)null

                                                        where !s.Deleted

                                                        select new

                                                            {

                                                                Etag = MetadataFor(s)["@etag"],

                                                                TicketSection = s,

                                                                InventoryRecord = inventoryRecord,

                                                            }

                                   };

InventoryRecord is the document that changes very rapidly in this case.

We have logging so we know they happen on this url to ravendb - "Url: ""/indexes/ComposedLiveEventsIndex?query=Id%253Aliveevents%252F1&start=0&pageSize=1&aggregation=None""

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.

   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()

   at Raven.Json.Linq.RavenJArray.WriteTo(JsonWriter writer, JsonConverter[] converters) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJArray.cs:line 174

   at Raven.Json.Linq.RavenJObject.WriteTo(JsonWriter writer, JsonConverter[] converters) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJObject.cs:line 275

   at Raven.Json.Linq.RavenJObject.WriteTo(JsonWriter writer, JsonConverter[] converters) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJObject.cs:line 275

   at Raven.Imports.Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeConvertable(JsonWriter writer, JsonConverter converter, Object value, JsonContract contract, JsonContainerContract collectionContract, JsonProperty containerProperty) in c:\Builds\RavenDB-Stable\Imports\Newtonsoft.Json\Src\Newtonsoft.Json\Serialization\JsonSerializerInternalWriter.cs:line 427

   at Raven.Imports.Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeObject(JsonWriter writer, Object value, JsonObjectContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty) in c:\Builds\RavenDB-Stable\Imports\Newtonsoft.Json\Src\Newtonsoft.Json\Serialization\JsonSerializerInternalWriter.cs:line 364

   at Raven.Imports.Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeList(JsonWriter writer, IWrappedCollection values, JsonArrayContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty) in c:\Builds\RavenDB-Stable\Imports\Newtonsoft.Json\Src\Newtonsoft.Json\Serialization\JsonSerializerInternalWriter.cs:line 468

   at Raven.Imports.Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.SerializeObject(JsonWriter writer, Object value, JsonObjectContract contract, JsonProperty member, JsonContainerContract collectionContract, JsonProperty containerProperty) in c:\Builds\RavenDB-Stable\Imports\Newtonsoft.Json\Src\Newtonsoft.Json\Serialization\JsonSerializerInternalWriter.cs:line 364

   at Raven.Imports.Newtonsoft.Json.Serialization.JsonSerializerInternalWriter.Serialize(JsonWriter jsonWriter, Object value) in c:\Builds\RavenDB-Stable\Imports\Newtonsoft.Json\Src\Newtonsoft.Json\Serialization\JsonSerializerInternalWriter.cs:line 61

   at Raven.Imports.Newtonsoft.Json.JsonSerializer.SerializeInternal(JsonWriter jsonWriter, Object value) in c:\Builds\RavenDB-Stable\Imports\Newtonsoft.Json\Src\Newtonsoft.Json\JsonSerializer.cs:line 608

   at Raven.Json.Linq.RavenJToken.FromObjectInternal(Object o, JsonSerializer jsonSerializer) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJToken.cs:line 81

   at Raven.Json.Linq.RavenJObject.FromObject(Object o, JsonSerializer jsonSerializer) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJObject.cs:line 156

   at Raven.Abstractions.Extensions.JsonExtensions.ToJObject(Object result) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Extensions\JsonExtensions.cs:line 30

   at System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()

   at System.Collections.Generic.List`1.InsertRange(Int32 index, IEnumerable`1 collection)

   at Raven.Database.DocumentDatabase.<>c__DisplayClass9a.<Query>b__90(IStorageActionsAccessor actions) in c:\Builds\RavenDB-Stable\Raven.Database\DocumentDatabase.cs:line 1154

   at Raven.Storage.Esent.TransactionalStorage.ExecuteBatch(Action`1 action) in c:\Builds\RavenDB-Stable\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 527

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

   at Raven.Database.DocumentDatabase.Query(String index, IndexQuery query) in c:\Builds\RavenDB-Stable\Raven.Database\DocumentDatabase.cs:line 1159

   at Raven.Database.Server.Responders.Index.PerformQueryAgainstExistingIndex(IHttpContext context, String index, IndexQuery indexQuery, Guid& indexEtag) in c:\Builds\RavenDB-Stable\Raven.Database\Server\Responders\Index.cs:line 481

   at Raven.Database.Server.Responders.Index.ExecuteQuery(IHttpContext context, String index, Guid& indexEtag) in c:\Builds\RavenDB-Stable\Raven.Database\Server\Responders\Index.cs:line 418

   at Raven.Database.Server.Responders.Index.GetIndexQueryResult(IHttpContext context, String index) in c:\Builds\RavenDB-Stable\Raven.Database\Server\Responders\Index.cs:line 357

   at Raven.Database.Server.HttpServer.DispatchRequest(IHttpContext ctx) in c:\Builds\RavenDB-Stable\Raven.Database\Server\HttpServer.cs:line 850

   at Raven.Database.Server.HttpServer.HandleActualRequest(IHttpContext ctx) in c:\Builds\RavenDB-Stable\Raven.Database\Server\HttpServer.cs:line 595

","System.InvalidOperationException: Url: ""/indexes/ComposedLiveEventsIndex?query=Id%253Aliveevents%252F1&start=0&pageSize=1&aggregation=None""

[Vlad Kosarev]

OK I believe replication is the issue here. We recreated DB and ran it on one server. No errors.

We added replication (master-master) and instantly got errors. We took down second master, still errors. I removed replication configuration in primary master (secondary still down), same errors.

Deleted everything and recreated on one server, no issue.

So at least we can run one server for now with no issues but it would be nice to get replication working properly.

[Vlad Kosarev]

Here is another trace (the one from the app itself) -

 ---> System.Net.WebException: The remote server returned an error: (500) Internal Server Error.

   at System.Net.HttpWebRequest.GetResponse()

   at Raven.Client.Connection.HttpJsonRequest.ReadJsonInternal(Func`1 getResponse) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 333

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

   at Raven.Client.Connection.HttpJsonRequest.HandleErrors(WebException e) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 478

   at Raven.Client.Connection.HttpJsonRequest.ReadJsonInternal(Func`1 getResponse) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 339

   at Raven.Client.Connection.HttpJsonRequest.ReadResponseJson() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 226

   at Raven.Client.Connection.ServerClient.DirectQuery(String index, IndexQuery query, String operationUrl, String[] includes, Boolean metadataOnly, Boolean includeEntries) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ServerClient.cs:line 941

   at Raven.Client.Connection.ServerClient.<>c__DisplayClass53.<Query>b__52(String u) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ServerClient.cs:line 917

   at Raven.Client.Connection.ReplicationInformer.TryOperation[T](Func`2 operation, String operationUrl, Boolean avoidThrowing, T& result) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 564

   at Raven.Client.Connection.ReplicationInformer.ExecuteWithReplication[T](String method, String primaryUrl, Int32 currentRequest, Int32 currentReadStripingBase, Func`2 operation) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 523

   at Raven.Client.Connection.ServerClient.ExecuteWithReplication[T](String method, Func`2 operation) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Connection\ServerClient.cs:line 174

   at Raven.Client.Document.AbstractDocumentQuery`2.ExecuteActualQuery() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 496

   at Raven.Client.Document.AbstractDocumentQuery`2.GetEnumerator() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 653

   at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source)

   at Raven.Client.Linq.RavenQueryProviderProcessor`1.GetQueryResult[TProjection](IDocumentQuery`1 finalQuery) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Linq\RavenQueryProviderProcessor.cs:line 1380

   at Raven.Client.Linq.RavenQueryProviderProcessor`1.ExecuteQuery[TProjection]() in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Linq\RavenQueryProviderProcessor.cs:line 1317

   at Raven.Client.Linq.RavenQueryProvider`1.System.Linq.IQueryProvider.Execute[S](Expression expression) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Linq\RavenQueryProvider.cs:line 170

   at System.Linq.Queryable.FirstOrDefault[TSource](IQueryable`1 source)

   at LEAP.WebAPI.Controllers.LiveEventsController.Get(String id, Int32 qualifier) in d:\Projects\Leap\LEAP.WebAPI\Controllers\LiveEventsController.cs:line 73"

[Oren Eini (Ayende Rahien)]

Can you give me the steps that you use to replicate this?

[Vlad Kosarev]

If it was easy to create steps I'd have them ready when I asked the question :) 

It took us a huge amount of time to try and write a repro app for memory/replication issues in December and that really was a waste.

As you can see here, the error is on the raven server. It only happens with replication enabled (we have two raven servers pointing to each other as master-master).

The scenario here is very fast changing property (inventory) and many, many writes to it (depleting inventory). At the same time replication is happening.

There are also indexes that use that fast changing property so they become stale for extended periods of time but we still do queries on them.

By looking at stack trace it seems like between the time raven reads something and serializes it some Collection changes and it bombs.

If you look at the trace more closely maybe it will give you some idea of what could be happening.

If the trace doesn't tell you anything then how about this. Is it possible to create a DB on one server and later on add another server in master-master replication? That way we can run this on just one server until this issue gets resolved and then we bring another server in.

Thanks.

[Oren Eini (Ayende Rahien)]

Yes, you can do start replication after the fact (if you created the db with replication in the first place).

I'll look at the code and try to figure out what may happen here.

[Oren Eini (Ayende Rahien)]

Looking at the code, I just don't see anything were there is any association between the two

You are doing a query, and replication is presumably doing work, but I don't see why they would interact, and not how _could_ they.

[Vlad Kosarev]

Thank you so much for digging into it.

I understand that query shouldn't be a problem. Is it possible that index rebuild is creating an issue? Because the values change very fast index is pretty much permanently stale and it keeps trying to update. In the index we have a  database.Load<InventoryRecord>(s.InventoryRecordId) as I showed in the first post. Is it possible that while index is getting rebuilt, replication has updated/changed the values and for some reason query triggers it? I am pretty sure it has to do with things running at the same time (index rebuild, replication, query) but it's hard for me to pinpoint exactly the moment it breaks. When we do load testing we see a handful of these errors, the more pressure we put on the system the more of that error we see. Grasping at straws here. I'll try and get some time next week to do more load testing and see if newer Raven versions do something else compared to release.

Thanks again, I appreciate you trying to help.

[Oren Eini (Ayende Rahien)]

My major problem is that I am pretty sure that all of those are going to get _ separate _ instances of the same document. So I can't really see how that would happen.

On a hunch, what happen when you disable pre fetching?

--
 
 

[Vlad Kosarev]

I'll try to disable prefetching and let you know. Thanks.

[Vlad Kosarev]

Using 2239 now.

I just needed to add  <add key="Raven/DisableDocumentPreFetchingForIndexing" value="true"/> to config, right?

It didn't help, same error.

By the way, the error happens on one server as long as replication bundle is enabled. Don't even need another server or any replication configuration, just having the bundle triggers this.

I created new DB with replication bundle enabled. Didn't add any configuration to replication bundle. Getting the same error.

Deleted DB, created same DB without replication bundle. Everything is fine.

This is a bigger problem now since I can't add replication bundle later on :(

By the way, also still getting Raven/DocumentsByEntityName index missing. I think it happens if I run our index creation before I access the UI.

[Vlad Kosarev]

Just deleted and recreated DB to test and Raven/DocumentsByEntityName isn't there, so it's not running our index creation first that breaks it. Maybe UI caches db somehow and when you delete/create db it think that index is still there when it tries to create it?

[Vlad Kosarev]

Another thing, maybe I can give an easier fail example - 

Line 178 - inventoryRecord = session.Load<InventoryRecord>(ticketSection.InventoryRecordId);

This line fails with exact same error.

So, as long as replication bundle is enabled (even without having any configuration) even Load fails on data that changes rapidly. We use optimistic concurrency to change that said data. We have Retries in case of exceptions, we reload with new Etag and try to change/save (for like 100 tries if needed).

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.

   at System.Collections.Generic.List`1.Enumerator.MoveNextRare()

   at Raven.Json.Linq.RavenJArray.WriteTo(JsonWriter writer, JsonConverter[] converters) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Abstractions\Json\Linq\RavenJArray.cs:line 174

   at Raven.Json.Linq.RavenJToken.ToString(Formatting formatting, JsonConverter[] converters) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Abstractions\Json\Linq\RavenJToken.cs:line 134

   at Raven.Database.Extensions.HttpExtensions.WriteHeaders(IHttpContext context, RavenJObject headers, Guid etag) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Extensions\HttpExtensions.cs:line 219

   at Raven.Database.Extensions.HttpExtensions.WriteData(IHttpContext context, Byte[] data, RavenJObject headers, Guid etag) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Extensions\HttpExtensions.cs:line 194

   at Raven.Database.Extensions.HttpExtensions.WriteData(IHttpContext context, RavenJObject data, RavenJObject headers, Guid etag) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Extensions\HttpExtensions.cs:line 188

   at Raven.Database.Server.Responders.Document.GetDocumentDirectly(IHttpContext context, String docId) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Server\Responders\Document.cs:line 158

   at Raven.Database.Server.Responders.Document.<>c__DisplayClass1.<Get>b__0(IStorageActionsAccessor _) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Server\Responders\Document.cs:line 112

   at Raven.Storage.Esent.TransactionalStorage.ExecuteBatch(Action`1 action) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 544

   at Raven.Storage.Esent.TransactionalStorage.Batch(Action`1 action) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 502

   at Raven.Database.Server.Responders.Document.Respond(IHttpContext context) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Server\Responders\Document.cs:line 43

   at Raven.Database.Server.HttpServer.DispatchRequest(IHttpContext ctx) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Server\HttpServer.cs:line 850

   at Raven.Database.Server.HttpServer.HandleActualRequest(IHttpContext ctx) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Server\HttpServer.cs:line 595

 ---> System.Net.WebException: The remote server returned an error: (500) Internal Server Error.

   at System.Net.HttpWebRequest.GetResponse()

   at Raven.Client.Connection.HttpJsonRequest.ReadJsonInternal(Func`1 getResponse) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 333

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

   at Raven.Client.Connection.HttpJsonRequest.HandleErrors(WebException e) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 478

   at Raven.Client.Connection.HttpJsonRequest.ReadJsonInternal(Func`1 getResponse) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 339

   at Raven.Client.Connection.HttpJsonRequest.ReadResponseJson() in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\HttpJsonRequest.cs:line 226

   at Raven.Client.Connection.ServerClient.DirectGet(String serverUrl, String key) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\ServerClient.cs:line 203

   at Raven.Client.Connection.ReplicationInformer.TryOperation[T](Func`2 operation, String operationUrl, Boolean avoidThrowing, T& result) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 564

   at Raven.Client.Connection.ReplicationInformer.ExecuteWithReplication[T](String method, String primaryUrl, Int32 currentRequest, Int32 currentReadStripingBase, Func`2 operation) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\ReplicationInformer.cs:line 523

   at Raven.Client.Connection.ServerClient.ExecuteWithReplication[T](String method, Func`2 operation) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Connection\ServerClient.cs:line 174

   at Raven.Client.Document.DocumentSession.Load[T](String id) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Client.Lightweight\Document\DocumentSession.cs:line 223

   at LEAP.WebAPI.Services.InventoryService.TryUpdateReservation(String userName, TicketSection ticketSection, Int32 offset) in d:\Projects\leap\LEAP.WebAPI\Services\InventoryService.cs:line 178

   at LEAP.WebAPI.Services.InventoryService.Retry(String userName, TicketSection ticketSection, Int32 quantity, String attemptName, Func`4 attempt) in d:\Projects\leap\LEAP.WebAPI\Services\InventoryService.cs:line 307"

[Oren Eini (Ayende Rahien)]

Thank you for that, we now have a repro, looking at things now.

--
 
 

[Oren Eini (Ayende Rahien)]

Will be fixed in the next build.

[Vlad Kosarev]

Awesome, thank you! Can't wait to see the code for the fix :)

[Oren Eini (Ayende Rahien)]

It is annoying, we didn't handle nested properties modifications properly, because we shared a mustable instance, and our snapshotting code only went down one level.

On Sun, Jan 27, 2013 at 5:34 PM, Vlad Kosarev <eqpl...@gmail.com> wrote:

Awesome, thank you! Can't wait to see the code for the fix :)

--
 
 

[Vlad Kosarev]

Don't see the commit yet so assuming it's coming in 2243?

So as I understand we've hit that mutable instance in our code but not necessarily the snapshotting issue.

[Oren Eini (Ayende Rahien)]

Yes, it is still pending, we have to make a change very low in the stack, and we are still making sure that there are not bad results for that.

On Mon, Jan 28, 2013 at 3:49 PM, Vlad Kosarev <eqpl...@gmail.com> wrote:

Don't see the commit yet so assuming it's coming in 2243?

So as I understand we've hit that mutable instance in our code but not necessarily the snapshotting issue.

--
You received this message because you are subscribed to the Google Groups "ravendb" group.
To unsubscribe from this group, send email to ravendb+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Vlad Kosarev]

Preliminary test - success!

Tried our test on one server, then did master-master and tried it again, no collection exceptions! Will test a bit more but so far so good.

I looked at the code change and there's no way I would've figured it out so thanks for looking into that and fixing it.

So this makes replication useful again :) Finally at the spot where we know replication works in normal scenario so we can start testing real failure scenarios.

Thanks.