"An Item With the Same Key . . ." Error in ProfilingContext Constructor

[Phil Sandler]

Raven Client Lightweight v3.0.30152

We are getting the following sporadically on one of our servers.  Sometimes it recovers and operates correctly, sometimes it continues to fail until we restart the service.

An item with the same key has already been added. 

 System.ArgumentException: An item with the same key has already been added.

   at Raven.Client.Connection.Profiling.ProfilingContext..ctor()

   at Raven.Client.DocumentStoreBase..ctor() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\DocumentStoreBase.cs:line 371

   at Raven.Client.Document.DocumentStore..ctor() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\DocumentStore.cs:line 127

We will update the client to the latest stable version; however, I'd like to know if this is a known issue with our current version so I can feel confident that we have it resolved.

Let me know if there are other details I can provide.

Thanks,

Phil

[Phil Sandler]

I should have also noted the server version:  Server Build #30156.

[Oren Eini (Ayende Rahien)]

I'm not seeing any way such an error can be thrown here.

It is called here:

https://github.com/ravendb/ravendb/blob/v3.0/Raven.Client.Lightweight/DocumentStoreBase.cs#L365

And then we have this:

https://github.com/ravendb/ravendb/blob/v3.0/Raven.Client.Lightweight/Connection/Profiling/ProfilingContext.cs

And the dictionary is here:

https://github.com/ravendb/ravendb/blob/v3.0/Raven.Sparrow/Sparrow/Collections/ConcurrentLruSet.cs

This is basically a noop all the way, pretty much.

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.

[Phil Sandler]

We actually poked around in the source code before posting and came to the same conclusion: it seems impossible.

That said, the source you linked looks slightly different than what we see when view the source via Visual Studio (right-click | go to implementation or CTRL-B in R#).  Out version has compiler directives in it, e.g. (from DocumentStoreBase):

#if !DNXCORE50

        public ITransactionRecoveryStorage TransactionRecoveryStorage { get; set; }

#endif

We can't navigate to the ConcurrentLruSet from ProfilingContext, so can't check that, but everything up to that point makes the error seem impossible.

I tried to get the source for the exact versions of both the client and ConcurrentLruSet, but was unable to find the exact commit.  I can't completely follow the revision history, but it does look like at one point, the locking mechanism in ConcurrentLruSet was changed from a ReaderWriterLockSlim to an object().  It's not clear (to me at least) how that could cause this issue.  That said, I can't think of any other explanation for why this is happening.

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

[Oren Eini (Ayende Rahien)]

This is roughly the relevant time:

https://github.com/ravendb/ravendb/tree/fdca7f19bd4b9d6d9e186b187a6d0a40a3a1e4cd

But those things changed last time in 2015, so this doesn't seem related.

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

[Phil Sandler]

I tried to put together a reproduction case, but was unable to get it to happen anywhere but the one server.

The version in question was only downloaded via nuget 176 times, and there was another release the next day which was downloaded ~10K times.  No idea what this would indicate.  The whole thing is pretty perplexing based on the source code.

In any case, we've pushed the updated version into production, so hopefully if there was an issue it has since been addressed.

Thanks,

Phil

[Oren Eini (Ayende Rahien)]

Okay, we'll wait to see if this repros

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

[Phil Sandler]

We had this happen again this morning with the updated client DLLs (3.0.30171).  It's only happening on one production server, but I've since learned that we've seen this in development from time to time.

I downloaded the source code again--I'm completely perplexed as to how this could be happening.  I don't even have a theory.  The updated stack trace is:

System.ArgumentException: An item with the same key has already been added.

   at Raven.Client.Connection.Profiling.ProfilingContext..ctor()

   at Raven.Client.DocumentStoreBase..ctor() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\DocumentStoreBase.cs:line 365

   at Raven.Client.Document.DocumentStore..ctor() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\DocumentStore.cs:line 124

The ProfilingContext has only a default constructor (not explicit). The only thing that could make sense is that static initialization is throwing the exception.  That would lead me to this line in ProfilingContext:

        private readonly ConcurrentLruSet<ProfilingInformation> leastRecentlyUsedCache = new ConcurrentLruSet<ProfilingInformation>(NumberOfSessionsToTrack);

But the ConcurrentLruSet constructor is just:

        public ConcurrentLruSet(int maxCapacity, Action<T> onDrop = null)

        {

            this.maxCapacity = maxCapacity;

            this.onDrop = onDrop;

        }

The only static initializer in this class is:

private Dictionary<T, LinkedListNode<T>> itemsLookupTable = new Dictionary<T, LinkedListNode<T>>();

I don't see how that could throw the above exception.

We initialize the document store loosely based on this blog post:  https://ayende.com/blog/160161/managing-ravendb-document-store-startup

No one else has reported this problem?  Any thoughts on how to proceed in tracking down the problem?

[Oren Eini (Ayende Rahien)]

Never seen this before, no. And as you noted, there is nothing that we can think that could cause this

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

[Phil Sandler]

I'm going to remove the lazy initialization and just initialize at startup.  I don't see how that could cause the problem, but it HAS to be some sort of race condition.

Also, in looking more closely at the log history, this problem never happened before we added startup code to clear a specific database at startup that we use as a cache:

        public void ClearCache()

        {

            try

            {

                var documentStore = DocumentStore.Value;

                documentStore.DatabaseCommands.ForDatabase(ConfigurationManager.AppSettings["Raven/CacheDatabaseName"]);

                var indexDefinitions = documentStore.DatabaseCommands.GetIndexes(0, 100);

                foreach (var indexDefinition in indexDefinitions)

                {

                    documentStore.DatabaseCommands.DeleteByIndex(indexDefinition.Name, new IndexQuery());

                }

            }

            catch (Exception ex)

            {

                Logger.Log("(non-critical) Error deleting cache.", ex);

            }

        }

I will remove this code as well.  Again, I can't draw a line between cause and effect, but it seems unlikely to be a coincidence.