OverflowException

[Jonas Cannehag]

Hi, we just deployed our ravendb log feature in a test environment and suddenly getting these OverflowExceptions. Looking at the latest id generated it is 900880.

We are using one DocumentStore per application pool.

What gets me thinking that this is related to the Id is mostly since GenerateEntityIdOnTheClient is mentioned in the stacktrace.

Any help on this ?

System.OverflowException: Value was either too large or too small for an Int32. 

at System.Number.ParseInt32(String s, NumberStyles style, NumberFormatInfo info) 

at Raven.Client.Converters.Int32Converter.ConvertTo(String value) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Converters\Int32Converter.cs:line 53 

at Raven.Client.Document.GenerateEntityIdOnTheClient.SetPropertyOrField(Type propertyOrFieldType, Object entity, Action`1 setIdentifier, String id) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\GenerateEntityIdOnTheClient.cs:line 164 

at Raven.Client.Document.GenerateEntityIdOnTheClient.TrySetIdentity(Object entity, String id) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\GenerateEntityIdOnTheClient.cs:line 122 

at Raven.Client.Document.GenerateEntityIdOnTheClient.GenerateDocumentKeyForStorage(Object entity) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\GenerateEntityIdOnTheClient.cs:line 85 

at Raven.Client.Document.InMemoryDocumentSessionOperations.StoreInternal(Object entity, Etag etag, String id, Boolean forceConcurrencyCheck) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\InMemoryDocumentSessionOperations.cs:line 675 

at Raven.Client.Document.InMemoryDocumentSessionOperations.Store(Object entity) in c:\Builds\RavenDB-Stable\Raven.Client.Lightweight\Document\InMemoryDocumentSessionOperations.cs:line 631 at Netaxept.Core.Repositories.NoSqlRepository.Store(Entity entity, TimeSpan expiry)

Regards

Jonas

[Oren Eini (Ayende Rahien)]

Please check to see if your Raven/Hilo/collection-name document has a very high value.

Oren Eini

CEO

Mobile: + 972-52-548-6969

Office:  + 972-4-622-7811

Fax:      + 972-153-4622-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+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Jonas Cannehag]

Looks like so yes:

{

  "Max": 1125902056402944

[Oren Eini (Ayende Rahien)]

Changed that to a more reasonable value.

[Jonas Cannehag]

So should i just set it to int.MaxValue (2147483647) ? Or do you have any better suggestion?

[Derek den Haas]

900880 + 1

Op donderdag 4 september 2014 11:55:10 UTC+2 schreef Jonas Cannehag:

[Oren Eini (Ayende Rahien)]

If you put it at max value, it would overflow that very quickly.

Find the highest document id, then set it to 1 above that

[Jonas Cannehag]

Alright, I changed it accordingly. But, any idea WHY this value went all the way up to 1125902056402944?

[Oren Eini (Ayende Rahien)]

I'm not sure, did you do something strange recently?

[Jonas Cannehag]

No, and it's a quite new environment. Installed the 25:th of august and been running fine since. But the suddenly this happened.

[Jonas Cannehag]

We need to investigate why this happen, how can we feel confident about releasing this in our production environment ?

[Oren Eini (Ayende Rahien)]

Do you have any logs that can help?

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

 

[Jonas Cannehag]

The only logs I have is the exception that's included in the first post. It just suddenly had that value

[Oren Eini (Ayende Rahien)]

It is nearly impossible to help if we don't have the debug logs, because we don't know who might have changed this value.

This is just a document, it can be changed by anything that would update a document.

[Jonas Cannehag]

Hi, now the exact thing happended again and we need to figure this out. I can assure that we have NOT manually edited this document. There is something in our implementation OR RavenDB's code that is causing this value to suddenly increase this much.

Please assist in how to enable whatever logs you need to figure out this behavior, this is blocking our plans on going live with RavenDB.

Regards

Jonas

[Oren Eini (Ayende Rahien)]

Those are the logs we need:

http://ravendb.net/docs/2.5/server/deployment/docs-debug-logging

Also, see if you have anything that generate a LOT of documents and not saving them, or uses hilo or HiLoKeyGenerator class, or something like that.

[Jonas Cannehag]

Hi, we don't explicitly use hilo or hilokeygenerator, and we save all documents we create since we are currently only using RavenDB for logging purposes (mostly to evalutate the product for further use).

I have enabled logging accordingly and will update whenever it occurs again

Thanks!

Regards

Jonas 

[Jonas Cannehag]

Now I have a log file for a whole day where the problem occured. The problem is that i cannot upload the file. Getting an error message that the upload failed. The file is 25Mb

[Oren Eini (Ayende Rahien)]

Throw that on Google Drive and send the link

--

[Jonas Cannehag]

https://drive.google.com/file/d/0B8QT8iXLK-fCNEkzZzdFLWNnaUU/view?usp=sharing

[Oren Eini (Ayende Rahien)]

And the doc name?

[Jonas Cannehag]

RavenDB-2014-10-25.zip

Or what do you mean?

[Oren Eini (Ayende Rahien)]

The doc with the overflow

[Jonas Cannehag]

Raven/Hilo/SystemLogs

[Oren Eini (Ayende Rahien)]

Okay, look here ( I snipped the log for the relevant parts).

2014-10-25 19:17:11.2589;Raven.Database.Server.HttpServer;Debug;Request #636,000

A few requests after that, we have the set on the SystemLogs:

2014-10-25 19:19:36.6671;Raven.Database.Server.HttpServer;Debug;Request #636,079: PUT     -     4 ms - Netaxept   - 201 - /docs/Raven/Hilo/SystemLogs;

2014-10-25 19:19:36.6788;Raven.Database.Server.HttpServer;Debug;Request #636,080: POST    -     6 ms - Netaxept   - 200 - /bulk_docs;

     PUT SystemLogs/6067719

So that works, and we can assume that the value is proper.

Then we have:

2014-10-25 23:54:23.7555;Raven.Database.Server.HttpServer;Debug;Request #639,117: POST    -     6 ms - Netaxept   - 200 - /bulk_docs;

2014-10-25 23:54:23.7555;Raven.Database.Server.HttpServer;Debug;" PUT SystemLogs/6068290

So it is okay at this point, and then we have:

2014-10-25 23:57:24.1560;Raven.Database.Server.HttpServer;Debug;Request #639,144: PUT     -     6 ms - Netaxept   - 201 - /docs/Raven/Hilo/SystemLogs;

And we don't see any further put on system log.

What happened at that point?

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

 

[Jonas Cannehag]

That is what we are needing your help for. Suddenly the /Raven/Hilo/SystemLogs value are to high for a int value, and all put's (using the C# library) are failing. We are NOT updating this value ourselves so what is actually doing that and how can it increase that much ?!

[Oren Eini (Ayende Rahien)]

We need to see the behavior from the client side.

I just went over the code, and I don't see any way that this can happen.

The relevant parts are here: 

https://github.com/ravendb/ravendb/blob/master/Raven.Client.Lightweight/Document/HiLoKeyGenerator.cs#L71

[Jonas Cannehag]

The client code is dead simple, it aquires a session and puts an entity in there.

What does Range.Max do ?

[Oren Eini (Ayende Rahien)]

Range.Max is a long property

[Jonas Cannehag]

And that seems to me to maybe have some kind of relation to the problem we get, or you don't ?

[Oren Eini (Ayende Rahien)]

Jonas,

Can you post the code that you are using?

It looks like something is causing this to generate a LOT of ids, since except for writing directly to this document, that is about the only thing that can cause this.

I don't know what the cause is.

Can you reproduce this in some way? Preferably with Fiddler enabled and tracking?

[Jonas Cannehag]

We are unable to reproduce since it just happens from time to time.

This is the DocumentStoreFactory that we use

public static class DocumentStoreFactory

{

   private static readonly ConnectionStringSettings RavenDbConnectionString = ConfigurationManager.ConnectionStrings["ravenDb"];

   private static readonly Lazy<IDocumentStore> DocStore = new Lazy<IDocumentStore>(CreateDocumentStore);

   internal static IDocumentStore CreateDocumentStore()

   {

      var docStore = new DocumentStore

         {

            ConnectionStringName = "ravenDb"

         };

         docStore.Initialize();

         try

         {

            IndexCreation.CreateIndexes(typeof (DocumentStoreFactory).Assembly, docStore);

         }

         catch (Exception exception)

         {

            var message = exception.ToString();

            Helper.LogToEventView(EventLogEntryType.Error, message);

         }

      return docStore;

   }

}

When then use Ninject to register this in the container:

Kernel.Bind<IDocumentStore>()

   .ToMethod(ctx => DocumentStoreFactory.DocumentStore);

And at last we use this code to store entitys

using (var session = DocumentStore.OpenSession())

{

   session.Store(entity);

   session.SaveChanges();

   session.Advanced.GetMetadataFor(entity).SetExpiration(expiry);

   session.SaveChanges();

[Oren Eini (Ayende Rahien)]

a) Why are you calling save changes twice here?

[Jonas Cannehag]

We save the entity first and then get the metadata to store the expiration and then save again. Thought that was needed...?

[Oren Eini (Ayende Rahien)]

No, you don't need to.

You can just call store, then immediately get the metadata and store the expiration there, then save _once_.

[Jonas Cannehag]

Understood, but hardly the cause of this exception ?

[Oren Eini (Ayende Rahien)]

No, that isn't the cause.

Something is changing this, and I'll need to see more of your code to understand what is going on.

[Jonas Cannehag]

What more code do you need to see? This is basically what we have... The "read" parts of the code will most probably not affecting this so that is out of the scope. The store parts are those you see in my earlier answer. Looking through our code, the base class used for our entities that we store in Raven, this is the definition:

public abstract class Entity

    {

        /// <summary>

        /// Numeric ID used by RavenDB

        /// </summary>

        public int Id { get; set; }

        /// <summary>

        /// Full ID of entities in RavenDB, ex: SystemLogs/123456

        /// </summary>

        public string FullId { get; set; }

    }

So, the FullId property is NEVER used in our project, and the Id is an int which will make it impossible for us to manually set this value to something as big as in the exception.

I don't know what else to share about this, we are NOT the cause of this high value. Are you totally sure that you are not either ?

//Jonas

[Oren Eini (Ayende Rahien)]

Who sets the FullId?

And by seeing all the code, I mean, everything that related to setting up the document store, for example, how your code is using it, etc.

Just from the code above, I can assume that you are customizing things, and I need to see what and how.

[Jonas Cannehag]

Our code is not setting the FullId, it was actually a plan to get the Id (including document name), but now it is always null and never used.

Setting up the document store is done according to your blog post: http://ayende.com/blog/160161/managing-ravendb-document-store-startup

We are not customizing more than that, except for running the Indexes according to my earlier code that I posted.

As I explained we are registering the IDocumentStore interface in our IoC container (Ninject) as a method to use the DocumentStoreFactory.DocumentStore property. That is really our customization...

I would so love to send you more code, if we had any. This is the implementation we have and the code related to RavenDB is the one I have posted here!

[Oren Eini (Ayende Rahien)]

Then I have no idea what is going on. 

Something is going on there, but I don't think that this is in our code. This particular code path hasn't changed in a long time, and it is in very high use.

[Jonas Cannehag]

This DocumentStoreFactory of ours. It is uses in different applications within our website, eg. we have different application pools for all of them, so there will be instances for each of them. Could that have some effect? The wierdest part is that it does work fine for a long time and then suddenly it happens, with us having no clue why. Could the application pool recycling be involved?

The thing is that our code prevents us from setting such a value because it's an int. So will all due respect, I do think that this is something in our code, but most probably happens because of something in our implementation.

...

[Oren Eini (Ayende Rahien)]

No, hilo is designed to be used concurrently, that isn't an issue.

[Jonas Cannehag]

So, what do you suggest we should do? We can never go into production with this so if we can't get any help from you, we need to look for another vendor

...

[Oren Eini (Ayende Rahien)]

You can write a trigger to check for the hilo updates, to see when it jumps, at which point you can tell why that happens.

[Kijana Woodard]

Fwiw, having an int Id was a modeling mistake. If you need something like that, it would have been better to have 

string Id

int ParsedId [or whatever]

Note that this should rarely be needed.

When integrating with another db that has int keys, use a static Format function to determine the string id.

For something like MVC binding, use attribute routing and capture the entire string id.