NPE in MongoMetricsConnectionPoolListener on shutdown

[jshields-squarespace]

With Micrometer 1.3.14, during application shutdown we get NPEs from MongoMetricsConnectionPoolListener.

This looks related to #2117. However that was supposedly fixed in 1.3.10, and we're experiencing this issue with 1.3.14.

It seems like checkedOutCount no longer has an entry for the server ID, presumably because connectionPoolClosed was already called during the application shutdown.

Stack trace:

java.lang.NullPointerException: null
	at io.micrometer.core.instrument.binder.mongodb.MongoMetricsConnectionPoolListener.connectionCheckedIn(MongoMetricsConnectionPoolListener.java:91) ~[micrometer-core-1.3.14.jar:1.3.14]
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.close(DefaultConnectionPool.java:411) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.internal.connection.DefaultServerConnection.release(DefaultServerConnection.java:69) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.operation.CommandOperationHelper$13.call(CommandOperationHelper.java:721) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.operation.OperationHelper.withReleasableConnection(OperationHelper.java:501) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.operation.CommandOperationHelper.executeRetryableCommand(CommandOperationHelper.java:703) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.operation.CommandOperationHelper.executeRetryableCommand(CommandOperationHelper.java:695) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.operation.BaseFindAndModifyOperation.execute(BaseFindAndModifyOperation.java:70) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:206) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.client.internal.MongoCollectionImpl.executeFindOneAndUpdate(MongoCollectionImpl.java:792) ~[mongo-java-driver-3.11.2.jar:?]
	at com.mongodb.client.internal.MongoCollectionImpl.findOneAndUpdate(MongoCollectionImpl.java:772) ~[mongo-java-driver-3.11.2.jar:?]
	at org.springframework.data.mongodb.core.MongoTemplate$FindAndModifyCallback.doInCollection(MongoTemplate.java:3073) ~[spring-data-mongodb-2.2.10.RELEASE.jar:2.2.10.RELEASE]
	at org.springframework.data.mongodb.core.MongoTemplate$FindAndModifyCallback.doInCollection(MongoTemplate.java:3036) ~[spring-data-mongodb-2.2.10.RELEASE.jar:2.2.10.RELEASE]
	at org.springframework.data.mongodb.core.MongoTemplate.executeFindOneInternal(MongoTemplate.java:2757) ~[spring-data-mongodb-2.2.10.RELEASE.jar:2.2.10.RELEASE]
	at org.springframework.data.mongodb.core.MongoTemplate.doFindAndModify(MongoTemplate.java:2676) ~[spring-data-mongodb-2.2.10.RELEASE.jar:2.2.10.RELEASE]
	at org.springframework.data.mongodb.core.MongoTemplate.findAndModify(MongoTemplate.java:1086) ~[spring-data-mongodb-2.2.10.RELEASE.jar:2.2.10.RELEASE]
	at org.springframework.data.mongodb.core.MongoTemplate.findAndModify(MongoTemplate.java:1061) ~[spring-data-mongodb-2.2.10.RELEASE.jar:2.2.10.RELEASE]
	...
	at io.opentracing.contrib.concurrent.TracedRunnable.run(TracedRunnable.java:30) ~[opentracing-concurrent-0.4.0.jar:?]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.2.9.RELEASE.jar:5.2.9.RELEASE]
	at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:93) ~[spring-context-5.2.9.RELEASE.jar:5.2.9.RELEASE]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

I'm not sure if it's useful information, but it seems like in our case these NPEs are exclusively being thrown in threads that are created via a ScheduledTaskRegistrar or AsyncListenableTaskExecutor—the latter from Spring Kafka.

[jshields-squarespace]

@Stephan202 Can you confirm if the fix for #2117 resolved the issue in your case?

[shakuzen]

Your analysis makes sense given the stacktrace, but it does seem odd that a ConnectionCheckedInEvent would happen after the ConnectionPoolClosedEvent. I guess the order isn't guaranteed.

[Stephan202]

@jshields-squarespace @shakuzen thanks for pinging me. I just checked our company logs over the past month, and indeed, while the issue no longer happens in apps against which it was first reported, one of our applications in particular does log these NPEs. (~All our applications, including this particular one, are on Micrometer 1.6.0.) I've asked the associated team whether maybe they're aware of a slightly different usage of either MongoDB or Micrometer, compared to other applications.

[Stephan202]

Heard back. The team doesn't use MongoDB differently from our other applications, but what does set it apart is its use of GraalVM rather than OpenJDK. I suppose that might make certain race conditions more apparent.

[Stephan202]

Update: this morning I missed part of our logs due to a misapplied filter (yeah... ☕). Now did a more thorough seach and unfortunately we also still see the NPEs on other applications, so indeed the issue is not fixed. (The aforementioned GraalVM application ran in a crash loop on the previously selected environment, which merely made the problem more pronounced there.)

[jshields-squarespace]

@Stephan202 Thanks for the confirmation.

@shakuzen Yes, my suspicion is that these threads in our application continue to run during application shutdown, rather than stopping and cleaning up nicely before shutdown proceeds. And so the connection pool is closed out from underneath them. While that might be an unideal app behavior, I wonder if Micrometer should be resilient to it all the same.