[JAVA-3606] NullPointerException: DecoderContext.decodeWithChildContext Created: 24/Jan/20  Updated: 09/Oct/20  Resolved: 09/Oct/20

Status: Closed
Project: Java Driver
Component/s: POJO
Affects Version/s: 3.12.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Carlos S Assignee: Brian DeLeonardis (Inactive)
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

java 8, documentdb(aws)


Attachments: Text File 3.12.2-stack.txt     Zip Archive Reproducer.zip     Java Source File pojos.java    
Issue Links:
Duplicate
is duplicated by JAVA-3605 NullPointerException: DecoderContext.... Closed
is duplicated by JAVA-3775 Concurrency issue causing PropertyMod... Closed
Related
is related to JAVA-3775 Concurrency issue causing PropertyMod... Closed

 Description   

I am getting NPE at DecoderContext.  The issue presents rarely, about 5% of the time, but when it does is at server start. Once it happens, all other calls to the same find method decoder fail with the same error.

There are other tickets JAVA-3376 and JAVA-3456 that describe the same problem but has not been addressed, and the tickets are now closed.

If possible, please provide an intermediate improvement to improve the error response (NPE does not include any context information). Maybe providing the context of the call in the exception would help to find the issue:

PojoCodecImpl#decodePropertyModel(){ 
   ...
 
 if (propertyModel.getCachedCodec()==null)
 throw new CodecConfigurationException("no cached codec reading x in codec y")
          

 

Notes

  • codecs are loaded using the default automatic codec builder on the main registry: PojoCodecProvider.builder().automatic(true).build(); 
  • The POJO structure is relatively large (9 classes) but does not have cycles.
  • The system runs many parallel threads, the main codec registry seems to create multiple (equivalent?) codec instances when first invoked, but the last codec built seems to be cached and returned afterwards.

 

 

 

java.lang.NullPointerException
        at org.bson.codecs.DecoderContext.decodeWithChildContext(DecoderContext.java:93)
        at org.bson.codecs.pojo.PojoCodecImpl.decodePropertyModel(PojoCodecImpl.java:213)
        at org.bson.codecs.pojo.PojoCodecImpl.decodeProperties(PojoCodecImpl.java:197)
        at org.bson.codecs.pojo.PojoCodecImpl.decode(PojoCodecImpl.java:121)
        at org.bson.codecs.pojo.PojoCodecImpl.decode(PojoCodecImpl.java:125)
        at org.bson.codecs.pojo.LazyPojoCodec.decode(LazyPojoCodec.java:57)
        at org.bson.codecs.DecoderContext.decodeWithChildContext(DecoderContext.java:93)
        at org.bson.codecs.pojo.PojoCodecImpl.decodePropertyModel(PojoCodecImpl.java:213)
        at org.bson.codecs.pojo.PojoCodecImpl.decodeProperties(PojoCodecImpl.java:197)
        at org.bson.codecs.pojo.PojoCodecImpl.decode(PojoCodecImpl.java:121)
        at org.bson.codecs.pojo.PojoCodecImpl.decode(PojoCodecImpl.java:125)
        at org.bson.codecs.pojo.AutomaticPojoCodec.decode(AutomaticPojoCodec.java:37)
        at com.mongodb.operation.CommandResultArrayCodec.decode(CommandResultArrayCodec.java:52)
        at com.mongodb.operation.CommandResultDocumentCodec.readValue(CommandResultDocumentCodec.java:60)
        at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:84)
        at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:41)
        at org.bson.internal.LazyCodec.decode(LazyCodec.java:48)
        at org.bson.codecs.BsonDocumentCodec.readValue(BsonDocumentCodec.java:101)
        at com.mongodb.operation.CommandResultDocumentCodec.readValue(CommandResultDocumentCodec.java:63)
        at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:84)
        at org.bson.codecs.BsonDocumentCodec.decode(BsonDocumentCodec.java:41)
        at com.mongodb.internal.connection.ReplyMessage.<init>(ReplyMessage.java:51)
        at com.mongodb.internal.connection.InternalStreamConnection.getCommandResult(InternalStreamConnection.java:413)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:309)
        at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:259)
        at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
        at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:450)
        at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
        at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:226)
        at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
        at com.mongodb.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:343)
        at com.mongodb.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:334)
        at com.mongodb.operation.CommandOperationHelper.executeCommandWithConnection(CommandOperationHelper.java:220)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:731)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:725)
        at com.mongodb.operation.OperationHelper.withReadConnectionSource(OperationHelper.java:463)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:725)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:89)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:196)
        at com.mongodb.client.internal.MongoIterableImpl.execute(MongoIterableImpl.java:143)
        at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:92)
        at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:39)
        at java.lang.Iterable.spliterator(Iterable.java:101)
        at Dao.findAll(Dao.java:123)
        ... 

 



 Comments   
Comment by Brian DeLeonardis (Inactive) [ 09/Oct/20 ]

I was able to reproduce this bug with the following code (PojoQuickTour has the main method): Reproducer.zip. It does not fail every time and sometimes it hangs without producing an error message, but if you restart it a couple of times you should get an error that looks like this:

Failed to decode 'Container'. Decoding 'one' errored with: Failed to decode 'One'. Decoding 'two' errored with: Failed to decode 'Two'. Decoding 'three' errored with: Failed to decode 'Three'. Decoding 'four' errored with: Failed to decode 'Four'. Decoding 'five' errored with: Missing codec in 'Four' for 'five'

 

A custom Codec or PojoCodec may need to be explicitly configured and registered to handle this type.
 We caught an exception:
 org.bson.codecs.configuration.CodecConfigurationException: An exception occurred when decoding using the AutomaticPojoCodec.
 Decoding into a 'Container' failed with the following exception:
Failed to decode 'Container'. Decoding 'one' errored with: Failed to decode 'One'. Decoding 'two' errored with: Failed to decode 'Two'. Decoding 'three' errored with: Failed to decode 'Three'. Decoding 'four' errored with: Failed to decode 'Four'. Decoding 'five' errored with: Missing codec in 'Four' for 'five'
A custom Codec or PojoCodec may need to be explicitly configured and registered to handle this type.

 

After this commit I can no longer reproduce the error and the program runs to completion each time. I believe the same bug that was causing JAVA-3775 was causing this bug. For this reason I am closing this ticket as a duplicate of JAVA-3775. Thanks everyone for reporting this and helping us debug it.

Best,
Brian

Comment by Ross Lawley [ 30/Apr/20 ]

HI daniel.desprez@zerpsed.com,

Could you open a new ticket and add as much information as possible.

If you can create a reproduction case that would be super helpful.

Ross

Comment by Daniel Desprez [ 29/Apr/20 ]

@Ross Lawley thanks for the reply. Perhaps it looks that way, but I disagree for these reasons:

1. I'm not using @BsonDiscriminator or derived classes in my POJOs, which JAVA-3665 deals with.

2. This is rare. I can bounce my application and reads of the same data into POJO's are decoded with no problem. 95% of the time, there is not problem.

3. If I downgrade to 3.11.1 I get the occasional NPE at app startup, which continues for subsequent reads of the same data. If I upgrade to 3.12.2 I no longer the the NPE and instead handle the CodecConfigurationException at the same read locations. Still, only occasional on app startup and resolvable by restarting the app.

I'm trying to give you more visibility now that a null check is in place. Please let me know if I can provide anything else that would assist you and I'll be happy to do so.

Comment by Ross Lawley [ 29/Apr/20 ]

daniel.desprez@zerpsed.com that is another issue as per the exception error message you may have to explicitly declare the class in the PojoCodec.

JAVA-3665 looks at fixing this issue.

Comment by Daniel Desprez [ 28/Apr/20 ]

Hi @Ross Lawley . I started monitoring this bug after encountering it around 3/20/2020. I updated our clients to use 3.12.2 and we have recently begun catching the wrapped exception. Thought I would share the new stack trace with you (attached). All behavior is the same between our app handling the NPE from 3.11.1 and the stack below using 3.12.2. Only on app startup, occurrence is rare, the calling code using the mongo client is similar as well. One commonality I see is this behavior is only occurring in environments where the client connects to a single mongo process. In my production and test env's with clustered mongos this behavior has not occurred; this could be purely coincidental.

 

Thanks,

Daniel

 

3.12.2-stack.txt

 

 

Comment by Ross Lawley [ 30/Mar/20 ]

csamail@gmail.com just to let you know 3.12.2 has been released.

Ross

Comment by Carlos S [ 20/Feb/20 ]

Thank you Ross, I am looking forward for the release

Comment by Ross Lawley [ 03/Feb/20 ]

Hi csamail@gmail.com,

I've added a null check so hopefully some more context will be provided and that will help identify the cause of this bug. Also I made a change to how the ProvidersRegistry handles caching , which should stop a race creating multiple instances of the PojoCodecImpl.

These fixes will be released in 3.12.2

I'll refrain from closing this ticket until we learn if the changes have made a difference. So for now I'm changing the status back to Scheduled and once 3.12.2 is released we'll follow up.

Ross

Comment by Githook User [ 03/Feb/20 ]

Author:

{'username': 'rozza', 'name': 'Ross Lawley', 'email': 'ross.lawley@gmail.com'}

Message: Codec improvements

Ensure DecoderContext null checks the decoder
PojoCodec improve error message if the cached codec is null
Remove creation race condition when creating automatic PojoCodecs

JAVA-3606
Branch: 3.12.x
https://github.com/mongodb/mongo-java-driver/commit/4c5fc2e59ef9c1df3e849fb0976d3398d570a7fa

Comment by Githook User [ 03/Feb/20 ]

Author:

{'username': 'rozza', 'name': 'Ross Lawley', 'email': 'ross.lawley@gmail.com'}

Message: Codec improvements

Ensure DecoderContext null checks the decoder
PojoCodec improve error message if the cached codec is null
Remove creation race condition when creating automatic PojoCodecs

JAVA-3606
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/716da74c5085ddac8c054652dcf60f3dea41fbc6

Comment by Ross Lawley [ 30/Jan/20 ]

PR: https://github.com/rozza/mongo-java-driver/pull/359

Comment by Carlos S [ 29/Jan/20 ]

Again, I have only been able to reproduce in production, with higher and more random loads than I know how to produce in development environment. At this moment, what would really help a null pointer check (with context).

Comment by Carlos S [ 29/Jan/20 ]

Yes, the error has happened in both 3.10.2 and 3.12.0 drivers.

Attached is the skeleton of all the pojos used (no getters or setters). The main  Pojo in my case is named PG   and the collection has about 40 entries of that type, each entry is about 20kb when formatted as json text.

pojos.java

Comment by Ross Lawley [ 29/Jan/20 ]

Hi csamail@gmail.com,

I've closed JAVA-3605 as asked and will focus our efforts on this ticket.

Unfortunately, in JAVA-3376 we were unable to reproduce the error. Could you provide an example of the POJO(s) you are using and the operations within the multi threaded environment? Hopefully, that will shed some light on the issue and we'll be able to make progress.

Also just to clarify you are seeing this issue with the 3.12 driver?

Many thanks,
Ross

Comment by Carlos S [ 24/Jan/20 ]

In answer to questions in other tickets, the query does not use projections:

  return StreamSupport
          .stream(collection.find(gte("version", intValue)).spliterator(), false)
          .collect(Collectors.toList());  

     

Generated at Thu Feb 08 09:00:00 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.