[CSHARP-1990] ObjectId.GenerateNewId() Generates Invalid Id Randomly Created: 30/May/17  Updated: 14/Jun/17  Resolved: 14/Jun/17

Status: Closed
Project: C# Driver
Component/s: BSON
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Dale Cameron Assignee: Robert Stam
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File screenshot-1.png     PNG File screenshot-2.png    

 Description   

There seems to be a moment in a day or every few days, where the ObjectId.GenerateNewId() generates a 23 length ID, and fails to Parse.
We noticed this error live, and I was able to reproduce this error in leaving a test running all day, where i would call ObjectId.GenerateNewId(), and parse it to an ObjectId. It seems to randomly return a 23 length ID at different times on different days, which of course wont parse.

The error and a sample Invalid id:
System.FormatException: '590262767c771f2b986a59b' is not a valid 24 digit hex string.
at MongoDB.Bson.ObjectId.Parse(String s)



 Comments   
Comment by Robert Stam [ 14/Jun/17 ]

The test program has now been running for almost 12 days without throwing an exception.

2017-06-02T16:35:13 0 iterations
2017-06-02T16:38:56 100000000 iterations
2017-06-02T16:42:40 200000000 iterations
2017-06-02T16:46:23 300000000 iterations
...
2017-06-14T11:35:35 455000000000 iterations
2017-06-14T11:39:23 455100000000 iterations
2017-06-14T11:43:11 455200000000 iterations

That's over 455 billion ObjectIds generated, converted to String and parsed without throwing an exception.

I'm going to stop the test and close this ticket as "Cannot reproduce".

Comment by Robert Stam [ 09/Jun/17 ]

As of Friday afternoon the test program has been running 7 days without throwing an exception. I will let it continue to run for several more days.

So far it has created 269,700,000,000 ObjectIds. That's roughly 300 billion.

Comment by Robert Stam [ 07/Jun/17 ]

So far it has created 194,600,000,000 ObjectIds.

Comment by Robert Stam [ 07/Jun/17 ]

As an update the test program has been running continuously for just over 5 days with no exceptions thrown.

I'll leave it running until next Monday more or less.

Comment by Robert Stam [ 05/Jun/17 ]

I restarted the test program using your exact sample code and it's been running without throwing an exception for 2 days and 18 hours.

I'll leave it running for several more days and see what happens.

Comment by Robert Stam [ 02/Jun/17 ]

OK. So maybe there are two things going on. It is interesting though that the string in the screen shot does have 24 valid digits.

Some additional sample values might help. What I really need are the 24 digits of the ObjectId values that are causing problems, but if you only have 23 digits that's all we have.

I want to clarify a few points:

1. The bug can't be in GenerateNewId (because GenerateNewId doesn't return a string)
2. Either ObjectId.ToString is returning a 23 digit string or the string is being transformed somehow afterwards

I've looked carefully at the implementation of ToString and it doesn't seem possible that it would return a 23 character string, specially in the current version of the driver.

Comment by Dale Cameron [ 02/Jun/17 ]

Hi Robert,
Thanks for your feedback. The Unit test very likely could have been an out of memory exception. Our real code doesnt use a loop, just the part inside the loop. The loop was just to continually generate Ids until we got an invalid one - to be able to see if there was a bug in the GenerateNewId method.
The error with the 23 digit hex string is an exact copy and paste from our error log. There are plenty more I can find in history if you need more sample invalid ids.

Comment by Robert Stam [ 02/Jun/17 ]

One thing I still don't understand is the exception you reported in the description:

System.FormatException: '590262767c771f2b986a59b' is not a valid 24 digit hex string

That string is in fact only 23 digits, not 24, so it really is invalid. Could this just be a copy paste error?

However, the string in the FormatException in your screen shot is in fact a valid 24 digit string.

And I am able to reproduce FormatExceptions for valid 24 digit strings by forcing an OutOfMemoryException.

Comment by Robert Stam [ 02/Jun/17 ]

I can get a FormatException every time by adding this line to ParseHexString in the driver:

var wasted = new byte[1000000];

Wastefully allocating 1MB of memory every time ParseHexString is called increases the chances to near 100% that the OutOfMemoryException will be thrown from this line, which then in turn is swallowed by TryParseHexString and eventually reported as a rogue FormatException instead of an OutOfMemoryException.

Comment by Robert Stam [ 02/Jun/17 ]

I am in fact able to reproduce the FormatException (with a different ObjectId of course) when the test program runs out of memory.

Sometimes I get a real OutOfMemoryException instead of a FormatException, it all depends on where the OutOfMemoryException is thrown, which determines whether it gets swallowed up and turned into a FormatException or not.

I made it fail fast by allocating many 1MB byte arrays to use up about 1.6GB right off the bat.

Comment by Robert Stam [ 02/Jun/17 ]

A few things caught my eye about your test:

1. The string in the FormatException is in fact a valid 24 digit hex string
2. Your results list is going to get very large and you are probably running out of memory

In fact, we may be accidentally hiding the OutOfMemoryException in the TryParseHexString method in the driver:

public static bool TryParseHexString(string s, out byte[] bytes)
{
    try
    {
        bytes = ParseHexString(s);
    }
    catch
    {
        bytes = null;
        return false;
    }
 
    return true;
}

We should only be catching FormatExceptions, not all exceptions. If ParseHexString throws an OutOfMemoryException we're going to swallow it and return false. That's not good.

What do you think? Does that seems like a plausible explanation for your test method failing?

Comment by Robert Stam [ 02/Jun/17 ]

Thanks for the screen shot. Your code is slightly different, so I've stopped my test (it had been running for 24 hours) and altered it to look like yours.

I'm also going to switch to testing against version 2.2.4 of the driver.

Now I'll let it run over the weekend and see what happens.

Comment by Dale Cameron [ 01/Jun/17 ]

Wierd way of testing, I know. I was trying to mimic almost line for line where we had the original exception...

Comment by Dale Cameron [ 01/Jun/17 ]

Hi Robert, I remembered I had sent a screen shot of the Test and the Exception to a colloeage. It is attached:

Comment by Robert Stam [ 01/Jun/17 ]

Do you still have the test program you used to reproduce this?

It would be good for me to use your exact test program if mine doesn't reproduce the issue.

Comment by Robert Stam [ 01/Jun/17 ]

OK. I'll leave my test program running for days and see what happens. So far still no exceptions.

I've added some logging output and restarted the program. I'll leave it running over the weekend.

Comment by Dale Cameron [ 01/Jun/17 ]

Hi Robert,
I can assure you the code was identical to the code i posted above to reproduce the error. Also, I think the reason why its escaped notice is because its so random and intermittent.It doesn't happen every day, it was at various times on various days. The only way we know about it is because we import very large batches of documents into Mongo 24x7 and found this issue randomly occurring, but I would assume you should get it within 3 or 4 days based on our observance. I was able to reproduce the error after about 1hr of running the above code, and then didnt get it again for 24hrs, after which we needed the machine for something else. I hope that helps.
Regards,
Dale

Comment by Robert Stam [ 01/Jun/17 ]

I have been running your sample test code for about 30 hours now and have not had any exceptions thrown.

At this point I think it is more likely that the string got truncated to 23 characters somewhere outside the driver before being passed to ObjectId.Parse.

Let me know if you have any further information that might help reproduce this issue.

Comment by Dale Cameron [ 31/May/17 ]

And sorry - the error I posted was all that we left inside a ticket explaining the issue internally!

Comment by Robert Stam [ 31/May/17 ]

If there is a bug it would be in ObjectId.ToString, not in ObjectId.GenerateNewId.

I have been unable to find any code path that would ever result in ObjectId.ToString returning a string with only 23 hexadecimal characters instead of 24.

I have been running your sample test code for about 6 hours know and no exceptions have been thrown. I'll leave it running at least 24 hours.

Comment by Dale Cameron [ 31/May/17 ]

Hi Robert,
I believe it was version 2.2.4.26 looking at our code history. But could have existed up to 2.4.2.27.
Im not quite sure as we havent had the issue for quite a while since we wrapped the GenerateNewId function into a helper method that checks the output, and if its invalid spits out a new one. So im going off code history for when the error existed..

Comment by Robert Stam [ 31/May/17 ]

It also might be a good idea to look at the full stack trace of the sample error you provided:

System.FormatException: '590262767c771f2b986a59b' is not a valid 24 digit hex string.
   at MongoDB.Bson.ObjectId.Parse(String s)

and determine exactly where that string value came from.

Comment by Robert Stam [ 31/May/17 ]

Thanks for the information. I'll run that code and see if I can reproduce this.

A few additional questions:

1. What version of the driver are you using?
2. How often is this happening to you?

Edit: Sorry, just re-read the description again and realized that you already mentioned that this seems to happen at certain times of day. Do let me know the driver version though.

Comment by Dale Cameron [ 31/May/17 ]

Hi Robert, something like this is how i was trying to catch the error:

                BsonObjectId objId = ObjectId.GenerateNewId();
                ObjectId validId;
                if (ObjectId.TryParse(objId.ToString(), out validId))
                {
                    return validId;
                }
              //else error code here

Comment by Robert Stam [ 31/May/17 ]

Object.GenerateNewId returns an ObjectId, not a string.

How are you converting the ObjectId returned from GenerateNewId to a string?

Generated at Wed Feb 07 21:41:18 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.