[JAVA-1117] 2.12.0-rc0 logs JMX InstanceAlreadyExistsException at WARNING level Created: 19/Feb/14  Updated: 06/Apr/23  Resolved: 26/Feb/14

Status: Closed
Project: Java Driver
Component/s: Monitoring
Affects Version/s: 2.12.0
Fix Version/s: 2.12.0

Type: Bug Priority: Major - P3
Reporter: Alexej Kubarev Assignee: Unassigned
Resolution: Done Votes: 0
Labels: rc
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

JDK 7u51 (Linux and OSX)


Issue Links:
Related
is related to JAVA-1122 Make JMX MBean names unique Closed
Backwards Compatibility: Fully Compatible

 Description   

When running several WAR files under one appserver, and both WAR files create one or several MongoClient instances, with 2.12.0-rc0 we start seeing

WARNING: Unable to register MBean org.mongodb.driver:type=ConnectionPool,clusterId=3,host=localhost,port=27017
javax.management.InstanceAlreadyExistsException: org.mongodb.driver:type=ConnectionPool,clusterId=3,host=localhost,port=27017
	at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
	at com.mongodb.util.management.jmx.JMXMBeanServer.registerMBean(JMXMBeanServer.java:59)
	at com.mongodb.JMXConnectionPoolListener.connectionPoolOpened(JMXConnectionPoolListener.java:52)
	at com.mongodb.PooledConnectionProvider.<init>(PooledConnectionProvider.java:60)
	at com.mongodb.DefaultClusterableServerFactory.create(DefaultClusterableServerFactory.java:50)
	at com.mongodb.BaseCluster.createServer(BaseCluster.java:202)
	at com.mongodb.SingleServerCluster.<init>(SingleServerCluster.java:45)
	at com.mongodb.Clusters.create(Clusters.java:37)
	at com.mongodb.DBTCPConnector.start(DBTCPConnector.java:75)
	at com.mongodb.Mongo.<init>(Mongo.java:346)
	at com.mongodb.Mongo.<init>(Mongo.java:327)
	at com.mongodb.MongoClient.<init>(MongoClient.java:268)
	at com.mongodb.Mongo$Holder.connect(Mongo.java:782)

This happens for the second WAR file starting (first one works fine, even though it started several instances of MongoClient). If we load only one of the WAR files (no matter which) this does not happen.

This is working fine if using 2.11.4 (and a few earlier versions, for sure) of the driver but broke in 2.12.0-rc0



 Comments   
Comment by Jeffrey Yemin [ 27/Feb/14 ]

That's great. Thanks for checking.

Comment by Alexej Kubarev [ 27/Feb/14 ]

Seems to be the same behavior as with 2.11.4.
Had a test run of our project with this drive and things seem to be working as expected

Comment by Jeffrey Yemin [ 27/Feb/14 ]

Hi Alexej,

If possible, can you test with the SNAPSHOT build available at https://oss.sonatype.org/content/repositories/snapshots/org/mongodb/mongo-java-driver/2.12.0-SNAPSHOT/mongo-java-driver-2.12.0-20140227.021034-55.jar.

Thanks,
Jeff

Comment by Githook User [ 26/Feb/14 ]

Author:

{u'username': u'jyemin', u'name': u'Jeff Yemin', u'email': u'jeff.yemin@10gen.com'}

Message: JAVA-1117: Reverting to 2.11.x behavior for registration of JMX MBeans: logging at INFO if a duplicate is found, and adding the MongoClient description to the MBean name to provide a way for the application to remove the duplication.
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/923dfeba5bd17aff4903775f1d554e0a3023827b

Comment by Jeffrey Yemin [ 26/Feb/14 ]

You are right about the external dependencies, though I might consider an optional dependency if we could make that work. That would require a layer of indirection that checked for the existence of SLF4J on the classpath. The driver already does something similar with JMX.

Please open a new JIRA issue for this if you wouldn't mind. It's not going to make 2.12 but we can consider it for 3.0.

Thanks,
Jeff

Comment by Alexej Kubarev [ 26/Feb/14 ]

I see. If this is the only chan ge it does make sense to revert back to original log level.

I know this is a bit off-topic but in the context of searching for the reason for logs not to appear - I've started thinking:
Would it be possible to switch to SLF4J as the logging provider? Given that you only need their API and then users are free to choose which real provider to use (as SLF4J has all of these logging frameworks supported). My guess is that your design philosophy was not to include any external dependencies and thus the reason to use JUL, but it's a pain to use JUL in bigger environments and JUL is the only one that is very hard to override (was reading on SLF4J page about performance problems when trying to bridge from JUL API).

If you believe it's possible I can do a change and submit it as a Pull Request, as this is a very fast and easy change that requires simply changing the imports. Also logger.debug() much more optimised in SLF4J as it allows placeholders and does not evaluate value of placeholders if debug is not enabled - performance gain.

Comment by Jeffrey Yemin [ 26/Feb/14 ]

I changed the title and metadata to reflect the fact that this exception is not actually being thrown, just logged at a different level.

Comment by Jeffrey Yemin [ 25/Feb/14 ]

We've decided to revert to the 2.11.x behavior, which means

  1. log at INFO instead of WARNING if a duplicate is found
  2. add the MongoClient description to the MBean name to provide a way for the application to remove the duplication
Comment by Jeffrey Yemin [ 25/Feb/14 ]

The Java driver is just using java.util.logging (JUL). Since you are getting the WARNING in your logs, it means that JUL calls are being forwarded properly. What doesn't seem to be working is the application of Log4J levels to JUL, and I'm not sure why that is.

Regardless, I'm pretty sure that there is an INFO level message that is being logged in 2.11.x and swallowed by log4j, so the only difference in behavior between 2.11.x and 2.12.x is the log level. Given the severity, I think WARNING is more appropriate than INFO, so I'm not inclined to change that.

What I would consider changing is the clusterId, so that its guaranteed to be unique across class loaders. The only way to do this reliably is to use either GUIDs or ObjectIds as cluster identifiers, instead of integers. I'm going to talk this over with some other driver developers, and I'll get back to you.

Comment by Alexej Kubarev [ 25/Feb/14 ]

Hi Jeff,

This is crazy but for all libraries i have tested so far except mongodb java driver it works fine to enable/disable logging.

log4j.category.com.mongodb=INFO

provides absolutely no effect. Neither does DEBUG...
We have slf4j-api, jcl-over-slf4j and jul-to-slf4j (naturally log4j and slf4j-log4j12 too).
Is mongo driver using something else? Because I can't figure out at this point why there is no driver output. Even if i put rootLogger=INFO and simply disable some of internal classes and springframework - still no luck getting those.

Comment by Jeffrey Yemin [ 25/Feb/14 ]

Hi Alexej,

Are you saying that you aren't getting anything logged at all in "com.mongodb", or just not that line? If so, something is not right, since you should at the very least be getting this one: https://github.com/mongodb/mongo-java-driver/blob/2.11.x/src/main/com/mongodb/Mongo.java#L330.

Comment by Alexej Kubarev [ 25/Feb/14 ]

Hi Jeff, during application startup nothing is happening for both INFO and DEBUG of com.mongodb.
Naturally just double checked that other classes (e.g org.springframework) are spamming as they should during startup.

Comment by Alexej Kubarev [ 25/Feb/14 ]

Hi Jeff, working on getting those logs for you (will take a few minutes). As for the clusterIds - we are getting 3 errors, one for each clusterId. But only after the first web-app deployed, so this is happening during second webapp initialization.
This is because the shared lib creates 3 different connection pools for us. This shared lib is in both WAR files and thus when only 1 WAR is running - we have no problem, but when more than 1 on the same app-server: we get this messages.

And if this would turn out to be the only difference (which is possible), what would your recommendation be on avoiding it?
As it's not uncommon that several web-apps on same appserver will want to connect to the same MongoClientURI (identical settings).

Comment by Jeffrey Yemin [ 25/Feb/14 ]

Can you turn up your logging to INFO on com.mongdb and run again with 2.11.4? I want to see if this is being logged: https://github.com/mongodb/mongo-java-driver/blob/2.11.x/src/main/com/mongodb/DBPortPool.java#L89

If so, then the only real difference here is the level of logging (INFO vs WARNING).

One other thing isn't clear to me. In the description, the log message indicates a clusterId of 3. Is that the only WARNING logged, or are there earlier ones for clusterId 1 and 2 as well?

Thanks,
Jeff

Comment by Alexej Kubarev [ 25/Feb/14 ]

Hi Jeff,

No, we are not providing that property
Even if we provide the property, it will still be same value for both WAR files (as creation of MongoClient is done in a JAR file that is embedded in both WAR files as library). Not sure if it helps, but we are creating MongoClient with help of MongoClientURI.

Comment by Jeffrey Yemin [ 25/Feb/14 ]

Hi Alexej,

After looking at the diffs between 2.11 and 2.12, I have an additional question: are you setting the description property on MongoClientOptions, and if so, are the MongoClient instances each constructed with different values for that property? I ask because of this piece of code that's in 2.11 but not 2.12: https://github.com/mongodb/mongo-java-driver/blob/2.11.x/src/main/com/mongodb/DBPortPool.java#L132-133.

Thanks,
Jeff

Comment by Jeffrey Yemin [ 20/Feb/14 ]

Thank you for testing the RC and for the bug report. We will address this in the final release.

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