Skip to content
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

pgjdbc JDBC driver goes missing after OSGi bundle restart #1476

Closed
1 task
steinarb opened this issue Apr 28, 2019 · 10 comments
Closed
1 task

pgjdbc JDBC driver goes missing after OSGi bundle restart #1476

steinarb opened this issue Apr 28, 2019 · 10 comments

Comments

@steinarb
Copy link
Contributor

@steinarb steinarb commented Apr 28, 2019

I'm submitting a ...

  • [X ] bug report
  • feature request

Describe the issue
On initial startup of the pgjdbc OSGi bundle datasources created by the DataSourceFactory works fine. After a pgjdbc bundle stop and start, datasources startet by the DataSourceFactory gets this stack trace:

java.sql.SQLException: No suitable driver found for jdbc:postgresql://:5432/authservice?prepareThreshold=5&preparedStatementCacheQueries=256&preparedStatementCacheSizeMiB=5&databaseMetadataCacheFields=65536&databaseMetadataCacheFieldsMiB=5&defaultRowFetchSize=0&binaryTransfer=true&readOnly=false&binaryTransferEnable=&binaryTransferDisable=&unknownLength=2147483647&logUnclosedConnections=false&disableColumnSanitiser=false&tcpKeepAlive=false&loginTimeout=0&connectTimeout=10&socketTimeout=0&cancelSignalTimeout=10&receiveBufferSize=-1&sendBufferSize=-1&ApplicationName=PostgreSQL+JDBC+Driver&jaasLogin=true&useSpnego=false&gsslib=auto&sspiServiceClass=POSTGRES&allowEncodingChanges=false&targetServerType=any&loadBalanceHosts=false&hostRecheckSeconds=10&preferQueryMode=extended&autosave=never&reWriteBatchedInserts=false
	at java.sql.DriverManager.getConnection(DriverManager.java:689)
	at java.sql.DriverManager.getConnection(DriverManager.java:247)
	at org.postgresql.ds.common.BaseDataSource.getConnection(BaseDataSource.java:94)
	at org.postgresql.ds.common.BaseDataSource.getConnection(BaseDataSource.java:79)
	... 

Driver Version?
42.2.5

Java Version?
openjdk 8u212-b01-1~deb9u1

OS Version?
Debian 9.9 "stretch", on amd64

PostgreSQL Version?
9.6.12-0+deb9u1

To Reproduce
Steps to reproduce the behaviour:

  1. Clone and build the two applications used to reproduce the issue
git clone https://github.com/steinarb/authservice.git
cd authservice
git checkout bug/pgjdbc-1476
mvn clean install -DskipTests=true
cd ..
https://github.com/steinarb/ukelonn.git
cd ukelonn
git checkout bug/pgjdbc-1476
mvn clean install -DskipTests=true
  1. Create a PostgreSQL user "karaf" with password "karaf" to match the connection settings below
  2. Create a blank database "authservice" and a blank database "ukelonn", both owned by user karaf
  3. Install "apache karaf" using the karaf quick start guide (basically just download the tarball/zip, unpack it somewhere, and start it using the instructions in the quick start guide)
  4. From the karaf console command line, add connection info for the two databases that will be used in the test:
config:edit no.priv.bang.authservice.db.postgresql.PostgresqlDatabase
config:property-set authservice.db.jdbc.url "jdbc:postgresql:///authservice"
config:property-set authservice.db.jdbc.user "karaf"
config:property-set authservice.db.jdbc.password "karaf"
config:update
config:edit no.priv.bang.ukelonn.db.postgresql.PGUkelonnDatabaseProvider
config:property-set ukelonn.db.jdbc.url "jdbc:postgresql:///ukelonn"
config:property-set ukelonn.db.jdbc.user "karaf"
config:property-set ukelonn.db.jdbc.password "karaf"
config:update
  1. From the karaf console install the first application
feature:repo-add mvn:no.priv.bang.authservice/authservice/LATEST/xml/features
feature:install authservice-db-postgresql
  1. Open the URL http://localhost:8181/authservice in a browser (replace localhost with the hostname of the machine karaf is run on if necessary), log in with username admin and password admin
  2. Click on the link "User administration UI" and the URL http://localhost:28181/authservice/useradmin/ opens
  3. From the karaf console command line, install the second application
feature:repo-add mvn:no.priv.bang.ukelonn/karaf/LATEST/xml/features
feature:install ukelonn-with-postgresql-and-provided-authservice
  1. Reloading the URL http://localhost:28181/authservice/useradmin/ will now result in a 500 internal server error, caused by the pgjdbc JDBC driver not being found

Expected behaviour
I expected the pgjdbc driver to continue afer the reload

Logs
pgjdbc-trace.log: https://gist.github.com/steinarb/19bc1420544ddc60860498f65fae25f0
(the file was to big to inline here)

@steinarb
Copy link
Contributor Author

@steinarb steinarb commented Apr 28, 2019

I'm guessing the culprit is this bit of code in the PGBundleActivator.stop() method:

    if (Driver.isRegistered()) {
      Driver.deregister();
    }

@bokken
Copy link
Member

@bokken bokken commented Apr 28, 2019

@steinarb
Copy link
Contributor Author

@steinarb steinarb commented Apr 28, 2019

I've debugged the issue using karaf remote debugging and the PGBundleActivator does the right thing: call Driver.register() on startup (actually called from a static initializer) and Driver.deregister() on stop.

The Driver.register() is called correctly on the reload startup as well, and all variables and calls are correct as seen from the PostgreSQL driver.

The problem is in the DriverManager class in rt.jar:

  1. The problem is the method DriverManager.isDriverAllowed()
  2. Before the reload isDriverAllowed returns true
  3. After the reload isDriverAllowed returns false
  4. isDriverAllowed returning false causes the single driver in DriverManager.registeredDrivers not to be used in DriverManager.getConnection()
  5. the reason isDriverAllowed returns false is that the result of Class.forName() of the driver class is not identical to the single class in DriverManager.registeredDrivers

Code from rt.jar:

    private static boolean isDriverAllowed(Driver driver, ClassLoader classLoader) {
        boolean result = false;
        if(driver != null) {
            Class<?> aClass = null;
            try {
                aClass =  Class.forName(driver.getClass().getName(), true, classLoader);
            } catch (Exception ex) {
                result = false;
            }

             result = ( aClass == driver.getClass() ) ? true : false;
        }

        return result;
    }

So it looks like this is a weird OSGi classloader issue (classes are identical but still not identical).

@bokken
Copy link
Member

@bokken bokken commented Apr 29, 2019

@bokken
Copy link
Member

@bokken bokken commented Apr 29, 2019

@steinarb, what specific path through isDriverAllowed is resulting in unexpected behavior? It looks like that should be called during deregister and getDriver.
Do you see deregister process correctly/successfully?

@steinarb
Copy link
Contributor Author

@steinarb steinarb commented Apr 29, 2019

In the code below:

  1. line 553
  2. line 553
  3. line 554
  4. line 556
  5. linr 562
  6. line 564
551    private static boolean isDriverAllowed(Driver driver, ClassLoader classLoader) {
552        boolean result = false;
553        if(driver != null) {
554            Class<?> aClass = null;
555            try {
556                aClass =  Class.forName(driver.getClass().getName(), true, classLoader);
557            } catch (Exception ex) {
558                result = false;
559            }
560
561             result = ( aClass == driver.getClass() ) ? true : false;
562        }
563
564        return result;

aClass, which is the result of Class.forName(driver.getClass().getName()) is not identical to driver.getClass(). Before the bundle reload, ie. after the first start(), the class comparison in line 561 doesn't fail.

@steinarb
Copy link
Contributor Author

@steinarb steinarb commented Apr 30, 2019

@bokken Note on debugging inside rt.jar: I don't see the value of local variables (ie. I don't see the values of result and aClass or driver above), I can examine the value of static fields (and maybe non-static fields...?), so I'm not sure how much can trust what I see.

However, the lines in the code seems to match the flow (I enter the correct method and hit the expected lines, such as the assignment in 556 and comparison in 561), and I see the true/false returned by this method as an effect in DriverManager.getConnection() (ie. a false causes it to skip out of using the JDBC driver to get a connection).

Anyway, if I can trust what I'm seeing then either Class.forName() returns the old driver class, or aClass and driver.getClass() are actually the same new JDBC driver class, but class comparison fails because of OSGi classloader issues.

@steinarb
Copy link
Contributor Author

@steinarb steinarb commented May 1, 2019

I asked on the OPS4J mailing list how the pax-jdbc DataSourceFactory implementations do it, and got the following answer:

DriverManger.register/unregister can't work reliable in OSGi (especially with static insitilizer), thus always the DataSourceFactory should be used instead!

Maybe the PGDataSourceFactory should create and own a Driver class directly, instead of registering one with DriverManager?

@grgrzybek
Copy link

@grgrzybek grgrzybek commented May 31, 2019

I worked on pax-jdbc and ensured that it works well with PostgreSQL. I did many tests with pooling/non-pooling, XA/non-XA and similar tests, but never tried the most trivial test - restart of postgresql driver bundle...

@steinarb you said:

I've debugged the issue using karaf remote debugging and the PGBundleActivator does the right thing: call Driver.register() on startup (actually called from a static initializer) and Driver.deregister() on stop.

it's actually not the right thing. static block is invoked only once - consecutive stop()/start() calls on the bundle won't call the block again, because the classloader doesn't change.
So in fact, postgresql driver has unmatched register/unregister calls - after you stop() the bundle, start() won't register the driver again.

To call the static block again, you have to refresh the bundle and in fact that does the trick - if you stop + start + refresh (Karaf commands), everything's working again.

@bokken you said:

The deregister on stopping bundle is important. Otherwise a reference will remain to the old bundle/class loader.

Indeed - but only if you end up with new classloader. Doing only stop + start won't give you new classloader, so here, unregistration is not needed.

BUT if for some reason (there are plenty of them in OSGi runtime), you had new classloader (after refreshing the bundle), what you added in org.postgresql.osgi.PGBundleActivator#stop() is ok, because there's no place to add code to run when bundle's classloader changes - stop() is the right method.

Actually simple:

diff --git a/pgjdbc/src/main/java/org/postgresql/osgi/PGBundleActivator.java b/pgjdbc/src/main/java/org/postgresql/osgi/PGBundleActivator.java
index 28fb2f03..cbe811cb 100644
--- a/pgjdbc/src/main/java/org/postgresql/osgi/PGBundleActivator.java
+++ b/pgjdbc/src/main/java/org/postgresql/osgi/PGBundleActivator.java
@@ -22,6 +22,9 @@ public class PGBundleActivator implements BundleActivator {
   private ServiceRegistration<?> _registration;
 
   public void start(BundleContext context) throws Exception {
+    if (!Driver.isRegistered()) {
+      Driver.register();
+    }
     Dictionary<String, Object> properties = new Hashtable<String, Object>();
     properties.put(DataSourceFactory.OSGI_JDBC_DRIVER_CLASS, Driver.class.getName());
     properties.put(DataSourceFactory.OSGI_JDBC_DRIVER_NAME, org.postgresql.util.DriverInfo.DRIVER_NAME);

fixes the problem - both restart and refresh of the bundle work (just checked).

Summarizing - you have to ensure in org.postgresql.osgi.PGBundleActivator#start() that the driver is registered - both in java.sql.DriverManager and in org.postgresql.Driver#registeredDriver field.

@steinarb
Copy link
Contributor Author

@steinarb steinarb commented Aug 29, 2019

Since this fix is in 42.2.6 which was released in june, shouldn't this issue be closed?

@davecramer davecramer closed this Aug 29, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants