New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Postgresql shared timer thread being stopped #60

Closed
hdeadman opened this Issue Oct 6, 2016 · 15 comments

Comments

Projects
None yet
2 participants
@hdeadman

hdeadman commented Oct 6, 2016

I am using classloader-leak-prevention-1.15.4.jar with Postgresql JDBC (postgresql-9.4-1201-jdbc41.jar) in the tomcat ${catalilna.base}/lib folder (and not in the webapp) but the listener is stopping a thread that probably shouldn't be tied to the webapp classloader (but apparently it is).

Stopping Timer thread 'PostgreSQL-JDBC-SharedTimer-1' running in classloader.

When the new version of the app tries to deploy and use Postgresql jdbc driver it gets an error like this:

java.lang.IllegalStateException: Timer already cancelled.
        at java.util.Timer.sched(Timer.java:397) ~[na:1.8.0_102]
        at java.util.Timer.schedule(Timer.java:193) ~[na:1.8.0_102]
        at org.postgresql.jdbc2.AbstractJdbc2Connection.addTimerTask(AbstractJdbc2Connection.java:1319) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.startTimer(AbstractJdbc2Statement.java:3494) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:569) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:420) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:305) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:688) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:629) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:680) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:712) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:722) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:777) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]

I haven't looked into this but I guessing that whichever app uses Postgresql first will get that thread tied to its webapp classloader and postgresql will stop working if that app is ever undeployed.

@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 6, 2016

They said they fixed a classloader memory leak in 9.4.1200 but I am still seeing it in 1201.
Fix Timer thread classloader leak - 197

I tried using the latest jdbc driver a couple weeks ago and ran into an issue so I backed off, not sure why I ended up on 1201.

This is really a driver bug but its a case where leaving the leak in place is probably better since it kills the driver.

hdeadman commented Oct 6, 2016

They said they fixed a classloader memory leak in 9.4.1200 but I am still seeing it in 1201.
Fix Timer thread classloader leak - 197

I tried using the latest jdbc driver a couple weeks ago and ran into an issue so I backed off, not sure why I ended up on 1201.

This is really a driver bug but its a case where leaving the leak in place is probably better since it kills the driver.

@mjiderhamn mjiderhamn closed this in fd02f84 Oct 9, 2016

@mjiderhamn

This comment has been minimized.

Show comment
Hide comment
@mjiderhamn

mjiderhamn Oct 9, 2016

Owner

Thanks for another report @hdeadman. I belive I have created a workaround for this. Would you mind giving it a try before I release a new version? I have no intent of backporting this to 1.x however, so this assumes you'd either upgrade to 2.0 or backport my solution yourself.

Owner

mjiderhamn commented Oct 9, 2016

Thanks for another report @hdeadman. I belive I have created a workaround for this. Would you mind giving it a try before I release a new version? I have no intent of backporting this to 1.x however, so this assumes you'd either upgrade to 2.0 or backport my solution yourself.

@mjiderhamn

This comment has been minimized.

Show comment
Hide comment
@mjiderhamn

mjiderhamn Oct 10, 2016

Owner

Trying to make sense of the change they made in the Postegresql driver and why it's still a problem. @hdeadman , are you reusing the same connection pool between redeploys, or in multiple applications within the server?

Owner

mjiderhamn commented Oct 10, 2016

Trying to make sense of the change they made in the Postegresql driver and why it's still a problem. @hdeadman , are you reusing the same connection pool between redeploys, or in multiple applications within the server?

mjiderhamn pushed a commit that referenced this issue Oct 10, 2016

Mattias Jiderhamn
Make Postgresql JDBC timer threads start in leak safe (system) ClassL…
…oader rather than protected ClassLoader. Fixes #60. Avoid Postgresql driver interfering with DriverManagerCleanUpTest.
@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 10, 2016

I will look into upgrading to 2.0 tomorrow to try it out. There are some apps that run in same Tomcat that are sharing data sources defined in Tomcat. I do have some apps that don't share connection pools across applications but I can't recall which servers I have seen this problem on, I will have to check when I am in the office tomorrow. I assume the connection pool would be re-used across re-deploys of the same application because it is looked up via JNDI, not defined within the application.

I will look into upgrading to 2.0 tomorrow to try it out. There are some apps that run in same Tomcat that are sharing data sources defined in Tomcat. I do have some apps that don't share connection pools across applications but I can't recall which servers I have seen this problem on, I will have to check when I am in the office tomorrow. I assume the connection pool would be re-used across re-deploys of the same application because it is looked up via JNDI, not defined within the application.

@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 11, 2016

I have confirmed that it can happen when re-deploying an application that is deployed by itself on a tomcat cluster/server. Sharing a connection pool across applications is not necessary to recreate. I am deploying using parallel versioned deployments but in this case I am just re-deploying the same version over top of the old version (copying appname##2.0.0.war into farm deploy folder and letting tomcat farm deployer deploy the app (which first results in undeploy of the app).

Now I will try 2.0.

I have confirmed that it can happen when re-deploying an application that is deployed by itself on a tomcat cluster/server. Sharing a connection pool across applications is not necessary to recreate. I am deploying using parallel versioned deployments but in this case I am just re-deploying the same version over top of the old version (copying appname##2.0.0.war into farm deploy folder and letting tomcat farm deployer deploy the app (which first results in undeploy of the app).

Now I will try 2.0.

@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 11, 2016

I saw this error on undeploy with the latest 2.0 snapshot but it looks like I can redeploy multiple times without the postgresql timer being shut down.

java.lang.NullPointerException: null
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_102]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_102]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_102]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_102]
        at se.jiderhamn.classloader.leak.prevention.cleanup.X509TrustManagerImplUnparseableExtensionCleanUp.cleanUp(X509TrustManagerImplUnparseableExtensionCleanUp.java:38) ~[classloader-leak-prevention-core-2.0.3-20161011.213922-1.jar:na]
        at se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor.runCleanUps(ClassLoaderLeakPreventor.java:226) [classloader-leak-prevention-core-2.0.3-20161011.213922-1.jar:na]
        at se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventorListener.contextDestroyed(ClassLoaderLeakPreventorListener.java:242) [classloader-leak-prevention-servlet-2.0.3-20161011.213923-1.jar:na]

I saw this error on undeploy with the latest 2.0 snapshot but it looks like I can redeploy multiple times without the postgresql timer being shut down.

java.lang.NullPointerException: null
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_102]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_102]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_102]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_102]
        at se.jiderhamn.classloader.leak.prevention.cleanup.X509TrustManagerImplUnparseableExtensionCleanUp.cleanUp(X509TrustManagerImplUnparseableExtensionCleanUp.java:38) ~[classloader-leak-prevention-core-2.0.3-20161011.213922-1.jar:na]
        at se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor.runCleanUps(ClassLoaderLeakPreventor.java:226) [classloader-leak-prevention-core-2.0.3-20161011.213922-1.jar:na]
        at se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventorListener.contextDestroyed(ClassLoaderLeakPreventorListener.java:242) [classloader-leak-prevention-servlet-2.0.3-20161011.213923-1.jar:na]
@mjiderhamn

This comment has been minimized.

Show comment
Hide comment
@mjiderhamn

mjiderhamn Oct 12, 2016

Owner

Thanks. The NPE was related to #58, and should be fixed now also on master.

Owner

mjiderhamn commented Oct 12, 2016

Thanks. The NPE was related to #58, and should be fixed now also on master.

@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 12, 2016

In the 1.x version of this listener I could extend the listener and override the logging methods. I am currently using SLF4J/Logback and I was going to provide an implementation of Logger that used that but I didn't see an easy way to extend the listener and pass in my instance of the Logger so it could be set on ClassLoaderLeakPreventorFactory. Should "void contextInitialized(final ServletContext servletContext)" be overloaded with a version that takes a Logger?

It's not a big deal for me because I am using the org.slf4/jul-to-slf4j bridge so the default JULLogger happens to work for me but it isn't clear to me how one is supposed to specify their own logger (or use StdLogger).

Another option would be to have more implementations of Logger and have a context parameter for choosing between them. If the context parameter specified the Logger impl class name then you wouldn't have to bundle all the impl classes.

In the 1.x version of this listener I could extend the listener and override the logging methods. I am currently using SLF4J/Logback and I was going to provide an implementation of Logger that used that but I didn't see an easy way to extend the listener and pass in my instance of the Logger so it could be set on ClassLoaderLeakPreventorFactory. Should "void contextInitialized(final ServletContext servletContext)" be overloaded with a version that takes a Logger?

It's not a big deal for me because I am using the org.slf4/jul-to-slf4j bridge so the default JULLogger happens to work for me but it isn't clear to me how one is supposed to specify their own logger (or use StdLogger).

Another option would be to have more implementations of Logger and have a context parameter for choosing between them. If the context parameter specified the Logger impl class name then you wouldn't have to bundle all the impl classes.

@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 12, 2016

I might have spoke too soon regarding the postgresql issue being resolved. I am still seeing the timer get cancelled. I will add some debug to make sure the PostgresqlJdbcThreadInitiator is running.

I might have spoke too soon regarding the postgresql issue being resolved. I am still seeing the timer get cancelled. I will add some debug to make sure the PostgresqlJdbcThreadInitiator is running.

@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 12, 2016

Initial Deploy on startup (with some debug added):

2016-10-12 14:34:52 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Initializing by loading some known offenders with leak safe classloader
2016-10-12 14:34:52 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] About to look for postgresql shared timer
2016-10-12 14:34:52 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] About invoke postgresql getSharedTimer()

Undeploy as part of re-deploy, still stopping Timer thread.

2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] private java.util.Map javax.faces.component.UIComponentBase.descriptors is not static
2016-10-12 14:39:04 ERROR [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Internal registry of java.beans.PropertyEditorManager not found
2016-10-12 14:39:04 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 14:39:04 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-0' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-1' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-2' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-3' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'PostgreSQL-JDBC-SharedTimer-1' running in classloader.
2016-10-12 14:39:04 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Custom ThreadLocal of type javax.faces.context.FacesContext$1: javax.faces.context.FacesContext$1@44eae0f with value null will be remove()d from Thread[ContainerBackgroundProcessor[StandardEngine[Catalina]],5,main]
2016-10-12 14:39:05 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Since Java 1.6+ is used, we can call public static final void java.util.ResourceBundle.clearCache(java.lang.ClassLoader)
2016-10-12 14:39:05 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Releasing web app classloader from Apache Commons Logging

Still getting Timer cancelled error.

java.lang.IllegalStateException: Timer already cancelled.
        at java.util.Timer.sched(Timer.java:397) ~[na:1.8.0_102]
        at java.util.Timer.schedule(Timer.java:193) ~[na:1.8.0_102]
        at org.postgresql.jdbc2.AbstractJdbc2Connection.addTimerTask(AbstractJdbc2Connection.java:1319) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.startTimer(AbstractJdbc2Statement.java:3494) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:569) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:420) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:305) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:688) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:629) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:680) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:712) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:722) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:777) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]

Initial Deploy on startup (with some debug added):

2016-10-12 14:34:52 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Initializing by loading some known offenders with leak safe classloader
2016-10-12 14:34:52 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] About to look for postgresql shared timer
2016-10-12 14:34:52 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] About invoke postgresql getSharedTimer()

Undeploy as part of re-deploy, still stopping Timer thread.

2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] private java.util.Map javax.faces.component.UIComponentBase.descriptors is not static
2016-10-12 14:39:04 ERROR [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Internal registry of java.beans.PropertyEditorManager not found
2016-10-12 14:39:04 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 14:39:04 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-0' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-1' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-2' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-3' running in classloader.
2016-10-12 14:39:04 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'PostgreSQL-JDBC-SharedTimer-1' running in classloader.
2016-10-12 14:39:04 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Custom ThreadLocal of type javax.faces.context.FacesContext$1: javax.faces.context.FacesContext$1@44eae0f with value null will be remove()d from Thread[ContainerBackgroundProcessor[StandardEngine[Catalina]],5,main]
2016-10-12 14:39:05 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Since Java 1.6+ is used, we can call public static final void java.util.ResourceBundle.clearCache(java.lang.ClassLoader)
2016-10-12 14:39:05 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Releasing web app classloader from Apache Commons Logging

Still getting Timer cancelled error.

java.lang.IllegalStateException: Timer already cancelled.
        at java.util.Timer.sched(Timer.java:397) ~[na:1.8.0_102]
        at java.util.Timer.schedule(Timer.java:193) ~[na:1.8.0_102]
        at org.postgresql.jdbc2.AbstractJdbc2Connection.addTimerTask(AbstractJdbc2Connection.java:1319) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.startTimer(AbstractJdbc2Statement.java:3494) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:569) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:420) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:305) ~[postgresql-9.4-1201-jdbc41.jar:9.4]
        at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:688) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:629) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:680) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:712) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:722) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]
        at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:777) ~[spring-jdbc-4.2.4.RELEASE.jar:4.2.4.RELEASE]

@mjiderhamn

This comment has been minimized.

Show comment
Hide comment
@mjiderhamn

mjiderhamn Oct 12, 2016

Owner

Turned out the JUnit tests passed due to interference from the MySQL JDBC driver used in other tests...

Thinking about this some more I have decided to switch approach. Even if the timer thread is force started in the correct ClassLoader, it may be stopped and restarted during the lifespan of the application. To avoid that we'd need to circumvent the mechanisms created by the driver authors, and I don't dare do that without understanding their motives.

I have some ideas how to fix the driver itself too, so hopefully that will result in a pull request.

Owner

mjiderhamn commented Oct 12, 2016

Turned out the JUnit tests passed due to interference from the MySQL JDBC driver used in other tests...

Thinking about this some more I have decided to switch approach. Even if the timer thread is force started in the correct ClassLoader, it may be stopped and restarted during the lifespan of the application. To avoid that we'd need to circumvent the mechanisms created by the driver authors, and I don't dare do that without understanding their motives.

I have some ideas how to fix the driver itself too, so hopefully that will result in a pull request.

@mjiderhamn

This comment has been minimized.

Show comment
Hide comment
@mjiderhamn

mjiderhamn Oct 12, 2016

Owner

@hdeadman , would you mind trying out the new approach?

Owner

mjiderhamn commented Oct 12, 2016

@hdeadman , would you mind trying out the new approach?

@hdeadman

This comment has been minimized.

Show comment
Hide comment
@hdeadman

hdeadman Oct 12, 2016

That seems to work better. I can't say there are no leaks but at least the driver still works after a re-deploy. If your pull request to the postgresql driver people makes it into a release I will try it out, but last time I tried the latest driver it was blowing up when Spring would start a transaction and it would try to process a result set from the "set transaction isolation ... ". I captured some debug from a working driver and was going to compare to debug from the latest driver but the debug jdbc parameter was not working in the new driver.

Here is debug from test with latest jar:

2016-10-12 22:00:32 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 22:00:32 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-0' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-1' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-2' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-3' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Thread 'Thread[Quartz Scheduler [quartzScheduler],5,main]' of type org.springframework.scheduling.quartz.SchedulerFactoryBean$1 running in web app after 5000 ms
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Changing contextClassLoader of Thread[PostgreSQL-JDBC-SharedTimer-1,5,main] to java.net.URLClassLoader@736e9adb
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] AccessControlContext of thread Thread[PostgreSQL-JDBC-SharedTimer-1,5,main] used custom combiner - unsetting

That seems to work better. I can't say there are no leaks but at least the driver still works after a re-deploy. If your pull request to the postgresql driver people makes it into a release I will try it out, but last time I tried the latest driver it was blowing up when Spring would start a transaction and it would try to process a result set from the "set transaction isolation ... ". I captured some debug from a working driver and was going to compare to debug from the latest driver but the debug jdbc parameter was not working in the new driver.

Here is debug from test with latest jar:

2016-10-12 22:00:32 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 22:00:32 INFO  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Looping 4 RMI Targets to find leaks
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-0' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-1' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-2' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Timer thread 'Timer-3' running in classloader.
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Stopping Thread 'Thread[Quartz Scheduler [quartzScheduler],5,main]' of type org.springframework.scheduling.quartz.SchedulerFactoryBean$1 running in web app after 5000 ms
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] Changing contextClassLoader of Thread[PostgreSQL-JDBC-SharedTimer-1,5,main] to java.net.URLClassLoader@736e9adb
2016-10-12 22:00:32 WARN  [] [] [] [] [se.jiderhamn.classloader.leak.prevention.ClassLoaderLeakPreventor] AccessControlContext of thread Thread[PostgreSQL-JDBC-SharedTimer-1,5,main] used custom combiner - unsetting
@mjiderhamn

This comment has been minimized.

Show comment
Hide comment
@mjiderhamn

mjiderhamn Oct 13, 2016

Owner

Here is my Pull Request on the Postgresql JDBC driver.

Owner

mjiderhamn commented Oct 13, 2016

Here is my Pull Request on the Postgresql JDBC driver.

@mjiderhamn

This comment has been minimized.

Show comment
Hide comment
@mjiderhamn

mjiderhamn Oct 23, 2016

Owner

Just released version 2.1.0 which includes the changes made to resolve this.

Owner

mjiderhamn commented Oct 23, 2016

Just released version 2.1.0 which includes the changes made to resolve this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment