NPE using java driver 2.6.3

[Jon Ivmark]

When trying out mongodb in production for the first time I
unfortunately ran into some unexpected problems, see stack trace:

java.lang.NullPointerException
at
com.mongodb.ReplicaSetStatus.ensureMaster(ReplicaSetStatus.java:301)
at com.mongodb.DBTCPConnector.checkMaster(DBTCPConnector.java:
383)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:192)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:
295)
at com.mongodb.DB.getCollectionNames(DB.java:259)
at com.mongodb.DB.collectionExists(DB.java:300)
at
net.avail.db.mongodb.MongoHourlyMetricsAggregator.ensureCollectionsExists(MongoHourlyMetricsAggregator.java:
43)

I'm guessing this is a bug that causes an NPE when the master changes?

Any workaround?

Thanks

Jon

[Nat]

Your exception doesn't match the code. Are you sure that you use 2.6.3 version? Do you have other version in classpath?

[Jon Ivmark]

Sorry about that, the 2.6 driver never reached our production
environment and we were using 2.5.3. Is the issue fixed in 2.6?

[Nat]

That makes more sense. Can you do db.printReplicationInfo() from each box? It could be that your resolved DNS name is not consistent.

[Antoine Girbal]

Is that exception happening consistently?
Or did it just happen once (i.e. race condition)?
We did fix some NPE and race conditions in newer versions like 2.6.3

[Jon Ivmark]

It seems to happen rather rarely. We ran around 80 clients and the
problem occurred on two of them, both times just after initiating the
Mongo instance.

[Jon Ivmark]

From looking att the code a null check seems to be missing in
ReplicaSetStatus.ensureMaster (also in 2.6.3)? If getMasterNode()
returns null or a non master node, and findNode(_lastPrimarySignal)
returns null a NPE will occur. Hard to tell why findNode would return
null, but a more descriptive exception than a NPE would help with
troubleshooting.

[Jon Ivmark]

Nat, I don't have access to the servers from where I'm at but I'll get
back to you with the info tomorrow (if that helps). We are using
Amazon instances with elastic IPs and most clients have had no
problems.

[Jon Ivmark]

mainSet:PRIMARY> db.printReplicationInfo()
configured oplog size: 4763.455859375MB
log length start to end: 587150secs (163.1hrs)
oplog first event time: Thu Jun 09 2011 11:10:56 GMT+0000 (UTC)
oplog last event time: Thu Jun 16 2011 06:16:46 GMT+0000 (UTC)
now: Thu Jun 16 2011 06:16:47 GMT+0000 (UTC)

mainSet:SECONDARY> db.printReplicationInfo()
configured oplog size: 4763.455859375MB
log length start to end: 587113secs (163.09hrs)
oplog first event time: Thu Jun 09 2011 11:11:33 GMT+0000 (UTC)
oplog last event time: Thu Jun 16 2011 06:16:46 GMT+0000 (UTC)
now: Thu Jun 16 2011 06:17:03 GMT+0000 (UTC)

mainSet:SECONDARY> db.printReplicationInfo()
configured oplog size: 4773.855859375MB
log length start to end: 587238secs (163.12hrs)
oplog first event time: Thu Jun 09 2011 11:09:27 GMT+0000 (UTC)
oplog last event time: Thu Jun 16 2011 06:16:45 GMT+0000 (UTC)
now: Thu Jun 16 2011 06:16:49 GMT+0000 (UTC)

[Nat]

oops.. I forgot rs.conf() and db.isMaster()

[Jon Ivmark]

********************************************************

mainSet:SECONDARY> rs.conf()
{
"_id" : "mainSet",
"version" : 3,
"members" : [
{
"_id" : 0,
"host" : "ip-10-56-55-252:27017"
},
{
"_id" : 1,
"host" : "10.58.254.148"
},
{
"_id" : 2,
"host" : "10.58.83.23"
}
]
}
mainSet:SECONDARY> db.isMaster()
{
"setName" : "mainSet",
"ismaster" : false,
"secondary" : true,
"hosts" : [
"ip-10-56-55-252:27017",
"10.58.83.23",
"10.58.254.148"
],
"primary" : "10.58.254.148",
"maxBsonObjectSize" : 16777216,
"ok" : 1
}

********************************************************

mainSet:SECONDARY> rs.conf()
{
"_id" : "mainSet",
"version" : 3,
"members" : [
{
"_id" : 0,
"host" : "ip-10-56-55-252:27017"
},
{
"_id" : 1,
"host" : "10.58.254.148"
},
{
"_id" : 2,
"host" : "10.58.83.23"
}
]
}
mainSet:SECONDARY> db.isMaster()
{
"setName" : "mainSet",
"ismaster" : false,
"secondary" : true,
"hosts" : [
"10.58.83.23",
"10.58.254.148",
"ip-10-56-55-252:27017"
],
"primary" : "10.58.254.148",
"maxBsonObjectSize" : 16777216,
"ok" : 1
}


********************************************************

mainSet:PRIMARY> rs.conf()
{
"_id" : "mainSet",
"version" : 3,
"members" : [
{
"_id" : 0,
"host" : "ip-10-56-55-252:27017"
},
{
"_id" : 1,
"host" : "10.58.254.148"
},
{
"_id" : 2,
"host" : "10.58.83.23"
}
]
}
mainSet:PRIMARY> db.isMaster()
{
"setName" : "mainSet",
"ismaster" : true,
"secondary" : false,
"hosts" : [
"10.58.254.148",
"10.58.83.23",
"ip-10-56-55-252:27017"
],
"maxBsonObjectSize" : 16777216,
"ok" : 1
}

********************************************************

[Nat]

Your data looks right. I looked at the code and there seems to be a race condition where _lastPrimarySignal can be set before the node is added to _all causing the problem you saw. 2.6.3 should reduce the chance that it will occur but it still can happen during the initialization.

[Jon Ivmark]

Ok, thanks for that. Two questions:

1) Will there be some synchronization added in 2.6.4?
2) In the meantime, which workaround would you suggest? Making a few
bogus calls to the db after initializing the Mongo instance?

[Nat]

File a JIRA issue. I will submit a patch.

-----Original Message-----
From: Jon Ivmark <jon.i...@gmail.com>
Sender: mongod...@googlegroups.com
Date: Thu, 16 Jun 2011 00:00:33
To: mongodb-user<mongod...@googlegroups.com>
Reply-To: mongod...@googlegroups.com
Subject: [mongodb-user] Re: NPE using java driver 2.6.3

Ok, thanks for that. Two questions:

1) Will there be some synchronization added in 2.6.4?
2) In the meantime, which workaround would you suggest? Making a few
bogus calls to the db after initializing the Mongo instance?

On Jun 16, 8:53 am, Nat <nat.lu...@gmail.com> wrote:
> Your data looks right. I looked at the code and there seems to be a race

> condition where_lastPrimarySignal can be set before the node is added to

>_all causing the problem you saw. 2.6.3 should reduce the chance that it
> will occur but it still can happen during the initialization.

--
You received this message because you are subscribed to the Google Groups "mongodb-user" group.
To post to this group, send email to mongod...@googlegroups.com.
To unsubscribe from this group, send email to mongodb-user...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

[Jon Ivmark]

https://jira.mongodb.org/browse/JAVA-382

[Antoine Girbal]

thanks for report & fix

[Jon Ivmark]

I just got the exception with 2.6.3 as well.

java.lang.NullPointerException
at com.mongodb.ReplicaSetStatus.ensureMaster(ReplicaSetStatus.java:
318)
at com.mongodb.DBTCPConnector.checkMaster(DBTCPConnector.java:393)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:198)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:296)

at com.mongodb.DB.getCollectionNames(DB.java:259)
at com.mongodb.DB.collectionExists(DB.java:300)
at
net.avail.db.mongodb.MongoHourlyMetricsAggregator.ensureCollectionsExists(MongoHourlyMetricsAggregator.java:
43)

The suggested patch in the JIRA doesn't really solve the problem of
not finding a master either, does it?

Any suggestion on how to handle this?

On Jun 16, 8:43 pm, Antoine Girbal <anto...@10gen.com> wrote:
> thanks for report & fix
>

[Nat]

It should fix NPE. Did you have a problem with not finding master?

[Jon Ivmark]

Oh sorry, I might have misunderstood. Since null has to be returned by
getMasterNode in ensureMaster for the NPE ever to occurr, I assumed
there was a problem there. But I guess updateAll should fix that so
the the next call to getMasterNode will actually return the master?

How are patches handled by the way, am I supposed to apply them myself
and build the jar from source or will there be a jar with the patch
made available?

Thanks

Jon

[Nat]

Usually, it will come out with later release but you should have no problem building it yourself using maven.

[Antoine Girbal]

integrated patch, will be released with 2.6.4