[JAVA-2155] Mongo Async JDBC driver 3.0.4 and leak Created: 18/Mar/16  Updated: 11/Sep/19  Resolved: 21/Mar/16

Status: Closed
Project: Java Driver
Component/s: Async
Affects Version/s: 3.0.4
Fix Version/s: None

Type: Task Priority: Blocker - P1
Reporter: pradeep Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

mongo db 2.6


Attachments: Text File jira.log    

 Description   

Mongo Async JDBC driver 3.0.4 and leak, When I am using the code in a stand alone java program I am getting result back and no issue. same code if i apply in a spring app , I am seeing that I never got result back and tomcat gave me below warning. On SinleResultCallbak apply method never get the result and I keep getting below error.

Thu Mar 17 11:08:15 MDT 2016 WARN [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.apache.catalina.loader.WebappClassLoaderBase - The web application [ROOT] appears to have started a thread named [expiringMap-0] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
java.lang.Thread.run(Thread.java:745)



 Comments   
Comment by pradeep [ 24/Mar/16 ]

This is coming only if I am using asynch driver, if I removed it then I
don't see any isuse.

Thanks,
Pradeep Singh
Please excuse typos.

On Thu, Mar 24, 2016 at 11:06 AM, Ross Lawley (JIRA) <jira@mongodb.org>

Comment by Ross Lawley [ 24/Mar/16 ]

Hi pradeepkusingh@gmail.com,

Looking at the error message its caused by:

The web application [ROOT] appears to have started a thread named [expiringMap-0] but has failed to stop it

You need to find the creator of the expiringMap-0 thread and ensure its stopped. I don't think its related to the Java Driver, perhaps asking on stackoverflow will yield an answer.

Ross

Comment by pradeep [ 24/Mar/16 ]

I have created a predestry spring bean method and tried to close mongoClient still I don't see that threads are cleaning up.

 
@PreDestroy
    public void cleanupMongoClient() {
        System.out.println("Shutting down and closing mongoClient connections!");
        client.close();
        client = null;
    }
 
 

Thu Mar 24 09:36:07 MDT 2016 ERROR [APP:null TRACKING_ID:null ACCOUNT_NUM:null] com.netflix.discovery.DiscoveryClient - DiscoveryClient_SPARROW-API-GATEWAY/:sparrow-api-gateway:8080 - de-registration failedBad status: 404
 
 
Shutting down and closing mongoClient connections!
 
 
 
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:1, serverValue:883103}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:5, serverValue:883104}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:11, serverValue:883105}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:14, serverValue:883106}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:19, serverValue:883107}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:23, serverValue:883108}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:25, serverValue:883109}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:28, serverValue:883110}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:31, serverValue:883111}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:33, serverValue:883112}] to sprwdb-dt-a1q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:7, serverValue:866724}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:9, serverValue:866726}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:12, serverValue:866727}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:13, serverValue:866728}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:16, serverValue:866729}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:17, serverValue:866730}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:20, serverValue:866731}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:22, serverValue:866732}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:24, serverValue:866733}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:27, serverValue:866734}] to sprwdb-dt-a3q.ula.comcast.net:30000 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:3, serverValue:863051}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:6, serverValue:863052}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:10, serverValue:863053}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:15, serverValue:863054}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:18, serverValue:863055}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:21, serverValue:863056}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:26, serverValue:863057}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:29, serverValue:863058}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:30, serverValue:863059}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.mongodb.driver.connection - Closed connection [connectionId{localValue:32, serverValue:863060}] to sprwdb-dt-a2q.ula.comcast.net:27017 because the pool has been closed.
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.apache.coyote.http11.Http11NioProtocol - Pausing ProtocolHandler ["http-nio-8080"]
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.apache.catalina.core.StandardService - Stopping service Tomcat
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/] - Destroying Spring FrameworkServlet 'dispatcherServlet'
Thu Mar 24 09:36:07 MDT 2016 INFO [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.springframework.cloud.netflix.zuul.ZuulFilterInitializer - Stopping filter initializer context listener
Thu Mar 24 09:36:07 MDT 2016 WARN [APP:null TRACKING_ID:null ACCOUNT_NUM:null] org.apache.catalina.loader.WebappClassLoaderBase - The web application [ROOT] appears to have started a thread named [expiringMap-0] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
 java.lang.Thread.run(Thread.java:745)

Comment by Ross Lawley [ 21/Mar/16 ]

Hi pradeepkusingh@gmail.com,

No problems - could you provide insight into the cause of the issue and the solution you used? So to help any future users that have this issue.

For future reference, the best place for questions regarding MongoDB usage or the Java driver specifics is the mongodb-user mailinglist or stackoverflow as you will reach a boarder audience there.

All the best,

Ross

Comment by pradeep [ 19/Mar/16 ]

Thanks for help, please close the ticket.

Comment by pradeep [ 18/Mar/16 ]

Thanks Ross for help , it helped , ,after 5 calls I got one operation finished with this message : - Can't find a codec for class java.util.GregorianCalendar.org.bson.codecs.configuration.CodecConfigurationException:

strange. I may be missing something here. why this error in spring app not in Stand alone program. Another question is what is the sla for call backs ?

Comment by Ross Lawley [ 18/Mar/16 ]

Thanks for the logs, that clarifies the issue. Firstly the reported possible connection leak is because the MongoClient is not closed correctly. In the background the MongoClient has a thread that monitors the state of MongoDB. When you shutdown Tomcat you also need to call MongoClient#close(), so that it can shutdown the client correctly.

Secondly, I can see it is calling the callback on the iterable as there is *Operation Finished* in the logs. You should always check the Throwable t value to see if there was an error when running the operation. If there is no error and the forEach block isn't called it means that the iterable was empty (eg. No matching Documents).

I hope that helps clarify what is happening in the code.

Ross

Comment by pradeep [ 18/Mar/16 ]

Another concern is why this program is not returning result. if I put same in a standalone program it return result within milliseconds. same db and from same machine , same editor. which indicates that thread are not getting back to pool. If needed we can do some screen sharing session.

Comment by pradeep [ 18/Mar/16 ]

Attaching logs to review.

Comment by pradeep [ 18/Mar/16 ]

In logs if you notice this line , I waited more than 5 minutesto get response back yesterday and I never got response back from DB.

The web application [ROOT] appears to have started a thread named [cluster-ClusterId

{value='56ec3adea8a983067b788576', description='null'}

-hostt:27017] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:

Comment by pradeep [ 18/Mar/16 ]

Once I send a request and then I am shutting down the tomcat and seeing these error messages. Attaching log where I don't see any callback error. This is spring boot app so tomcat container is embedded one.

Comment by Ross Lawley [ 18/Mar/16 ]

In the Spring app are you seeing any logs? If there was an error in a callback I would expect a "Callback onResult call produced an error" message. Having looked at the callback in the code above I can't see anything obvious regarding the reported leak.

Regarding the leak itself, is that reported during normal running or when tomcat is stopped or restarted?

Comment by pradeep [ 18/Mar/16 ]

Code to get data from DB :

public void getBlockedCpeIp() {
		MongoDatabase dataBase =null;
		
		final CountDownLatch latch = new CountDownLatch(1);
		try {
			System.out.println("start getBlockedCpeIp");
			  
		 dataBase = mongoDBUtil.getDatabase();
		
		blockedCpeIp = new ArrayList<String>();
		DateFormat dateFormat = new SimpleDateFormat("MMdd-yyyy hh:mm:ss");
		Calendar cal = Calendar.getInstance();
		cal.add(Calendar.MONTH, -10);
 
		System.out.println("start getBlockedCpeIp 2");
 
		/*AggregateIterable<Document> iterable = dataBase.getCollection("uiActivityLog").aggregate(Arrays.asList(new Document("$match", new Document("taskCode", "58020").append("lastModifiedDate", new Document("$gte", cal.getTime()))), new Document("$group", new Document("_id", "$cpeIpAddress").append("count", new Document("$sum", 1))), new Document("$sort", new Document("count", -1)),
				new Document("$sort", new Document("count", -1)), new Document("$project", new Document("_id", 0).append("ipAddress", "$_id").append("count", "$count"))));*/
		
		 AggregateIterable<Document> iterable = dataBase.getCollection("uiActivityLog")
                 .aggregate(Arrays.asList(
                               new Document("$match",
                                             new Document("taskCode", "58020").append("lastModifiedDate", new Document("$gte",
                                                          cal))),
                 new Document("$group", new Document("_id", "$accountNumber").append("count", new Document("$sum", 1))),
                 new Document("$match", new Document("count", new Document ("$gte",1))),
                 new Document("$sort", new Document("count", -1)),
                 new Document("$project", new Document("_id", 0).append("account", "$_id").append("count", "$count"))
                               ));
		// @code: end
		System.out.println("start getBlockedCpeIp 2==="+iterable);
		// @pre: Iterate the results and apply a block to each resulting
		// document
		// @code: start
		
		
		
		iterable.forEach(new Block<Document>() {
 
			public void apply(final Document document) {
				System.out.println("got row ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^   **********************: " + document.toJson());
 
				if (null != document.get("count")) {
 
					if (StringUtils.isNumeric(document.get("count").toString())) {
 
						int count = Integer.parseInt(document.get("count").toString());
 
						if (count >= limit) {
 
							blockedCpeIp.add(document.get("ipAddress").toString());
 
						}
 
					}
 
				}
			}
		}, new SingleResultCallback<Void>() {
 
			public void onResult(final Void result, final Throwable t) {
				System.out.println("***********************************Operation Finished***************************");
				latch.countDown();
 
			}
		});
 
		System.out.println("%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%end%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%");
		try {
			latch.await();
			
			System.out.println("111111111111111111111111111111111%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%end%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%");
		} catch (InterruptedException e) {
			// TODO Auto-generated catch block
			System.out.println("%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%end%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%_-------"+e);
		}
		} catch (Exception e) {
			
			System.out.println("Error while calling MongoDB=**************************="+e);
		} finally {
			
			System.out.println(" while calling MongoDB=**************************=((((((((((");
			if(null != dataBase) {
				
				//dataBase.
			}
			
		}
		
	}

Comment by pradeep [ 18/Mar/16 ]

DB connectivity : -

public MongoDatabase getDatabase() {
 
		MongoDatabase database = null;
		try {
		String[] hosts = { "host:27017", "host:27017" };
		List<ServerAddress> list = new ArrayList<ServerAddress>();
		for (String host : hosts) {
 
			list.add(new ServerAddress(host));
 
		}
 
		// username , source , password
		MongoCredential journaldevAuth = MongoCredential.createPlainCredential("db", "db", "db".toCharArray());
		MongoCredential credential = MongoCredential.createScramSha1Credential("sparrow", "db", "db".toCharArray());
		List<MongoCredential> auths = new ArrayList<MongoCredential>();
		auths.add(journaldevAuth);
		auths.add(credential);
 
	/*	MongoClient client = MongoClients.create(MongoClientSettings.builder()
				.clusterSettings(ClusterSettings.builder()
						// .hosts(singletonList(new ServerAddress()))
						.hosts(list).build())
				.connectionPoolSettings(ConnectionPoolSettings.builder().minSize(10).maxSize(25).maxConnectionIdleTime(maxWaitTime, TimeUnit.SECONDS).maxWaitTime(maxWaitTime, TimeUnit.SECONDS) // set
						.build())
				.credentialList(auths).build());
*/
		
		MongoClient  mongo = MongoClients.create(new ConnectionString(
                   "mongodb://host:27017,host:27017/?authSource="));
		 database = mongo.getDatabase("db");
		} catch (Exception e) {
			
			System.out.println("Error while connecting to MongoDB---"+e);
		}
 
		return database;
 
	}

Comment by pradeep [ 18/Mar/16 ]

Thanks , Sure, I will put code in the couple of hours. As I said same code works fine in a stand alone java program I get the result from DB , but in spring app no result and apply method never called and if call my code multiple times I can see that it hit the onResult method. and threads name are keep changing. In app logs I don't see any error. if you want me to enable any debugging I can try that also.

Comment by Ross Lawley [ 18/Mar/16 ]

Hi pradeepkusingh@gmail.com,

Thanks for the ticket, can you provide some code? It could be a runtime error in the callback, the driver logs might provide some insight if that is the case.

Ross

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