Diagnose JDBC proxy connection

Oracle REST Data Services connects to your database through JDBC. When a request is initially received by ORDS, it will use the database credentials in the pool configuration file ( e.g. apex_pu.xml ) to determine which REST enabled schema should be used to execute the corresponding SQL. The database connection for that REST enabled schema is achieved through a Oracle JDBC proxy connection. This uses the connect through concept in Oracle database. When a schema is REST enabled, GRANT CONNECT THROUGH to that schema is given to the ORDS_PUBLIC_USER role.

All good so far. This works across different versions of Oracle database and different deployment topologies. However, in some cases the database configuration can cause this proxy connection feature to fail.

For ORDS, this manifests as a TargetNotAvailableException. The error message looks like this:

The database user for the connection pool named |apex|pu|, is not able to proxy to the schema named HR. This could be a configured restriction on the maximum number of database sessions or an authorization failure.

The cause could be a login trigger, resource constraints on sessions per schema, or something else configured on the database. Trying to diagnose this issue can be problematic because ORDS can only report on the exception it’s getting from JDBC. That exception can be found in the stacktrace:

Caused by: java.sql.SQLException: ORA-01017: invalid username/password; logon denied

To reiterate, this is not an ORDS configuration problem. It is some database configuration causing a problem for Oracle JDBC. In an article earlier this year, Kris Rice covers the same JDBC openProxySession logic and provides steps to use SQLcl to confirm the JDBC behaviour: Debugging ORDS Proxy Connection Issues.

To help diagnose this problem and move closer to determine the root cause on the database side, a reproducible test case without ORDS, using JDBC logging is an essential step. Here’s how to do it…

JDBC Jars

The first step is to get the publicly available JDBC jars for logging. ORDS currently ships with the 19.3 JDBC drivers for Java 1.8. Also known as OJDBC8. Get the ojdbc8 diagnostic jars from https://www.oracle.com/database/technologies/appdev/jdbc-ucp-19c-downloads.html. All you need is ojdbc8_g.jar.

ProxyTest class

The next step is to write a class to use JDBC. This java class makes a JDBC connection to the database using one set of credentials and then attempts to proxy to the specified schema. The credentials and schema don’t have to be ORDS specific but if you have found this article, you’ve probably encountered this problem after installing ORDS and testing with your first REST Enabled schema. The credentials and schema could just as easily be any database account that has CONNECT THROUGH privilege to another schema.

import java.sql.Connection;
import java.sql.DatabaseMetaData;
import java.sql.DriverManager;
import java.sql.SQLException;
import java.util.Properties;

import oracle.jdbc.OracleConnection;

public class ProxyTest {
  public static void main(final String args[]) throws SQLException {
    if (args.length < 4) {
      System.out.println("Tests that a user can proxy to another schema. Parameters by position ...");
      System.out.println("\turl      JDBC url to for the database. For example jdbc:oracle:thin:@localhost:1521/orclpdb1");
      System.out.println("\tusername Username for a DB account with connect through privilege");
      System.out.println("\tpassword Password for that DB account");
      System.out.println("\tschema   Name of the schema that the DB account has permission to proxy as");
      System.out.println("");
      System.out.println("Example");
      System.out.println("\tProxyText jdbc:oracle:thin:@localhost:1521/orclpdb1 ORDS_PUBLIC_USER oracle HR");

      return;
    }
    final String url = args[0];
    final String username = args[1];
    final String password = args[2];
    final String schema = args[3];

    try {

      final Connection conn = DriverManager.getConnection(
          url, username, password);

      final Properties prop = new Properties();

      System.out.println("Trying to open proxy connection ...");

      prop.put(OracleConnection.PROXY_USER_NAME, schema);

      ((OracleConnection) conn).openProxySession(OracleConnection.PROXYTYPE_USER_NAME, prop);
      final DatabaseMetaData meta = conn.getMetaData();

      System.out.println("Connection user: " + meta.getUserName());
      System.out.println("Product Version: " + meta.getDatabaseProductVersion());

      ((OracleConnection) conn).close(OracleConnection.PROXY_SESSION);
      System.out.println("Succeeded. Proxy connection closed");

    } catch (final SQLException e) {
      e.printStackTrace();
    }
  }
}

The above class uses the Oracle JDBC openProxySession in the same way that ORDS does. It should reproduce the issue and show the same SQLException. Save the above text in a file called ProxyTest.java in the same directory you have the ojdbc8_g.jar.

Compile

Using JDK 1.8, compile ProxyTest.java to produce ProxyTest.class in the same directory:

javac -classpath ojdbc8_g.jar ProxyTest.java

Why JDK 1.8? It’s the Oracle Java for JDBC that corresponds to the OJDBC8. If using a more recent Oracle Java in production you could use that version but in this example, I’m using JDK 1.8.

Logging configuration

The purpose of this exercise is to get a detailed log of what JDBC is doing, as well as what it is receiving from the database, to get closer to diagnosing the root cause of the proxy connection failure. Let’s create a logging configuration to get all that diagnostic data. We’ll call the file oracledebug.properties and give it the following content:

.level=SEVERE
oracle.jdbc.level=FINEST
oracle.ucp.level=FINEST
jdbcbug.level=FINEST
.handlers=java.util.logging.FileHandler
java.util.logging.FileHandler.level=ALL
java.util.logging.FileHandler.pattern=jdbc.log
java.util.logging.FileHandler.count=1
java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

In summary, this configuration will result in JDBC logging entries at the FINEST level showing up in a file called jdbc.log

Run it

Run the ProxyTest class with parameters to connect to the database, attempt the openProxySession call and log everything to jdbc.log

java -classpath ojdbc8_g.jar:. \
     -Doracle.jdbc.Trace=true \
     -Djava.util.logging.config.file=oracledebug.properties \
     ProxyTest \
     jdbc:oracle:thin:@localhost:1521/orclpdb1 \
     ORDS_PUBLIC_USER \
     MySecretPassword \
     HR

Note the classpath includes ojdbc8.jar and the current working directory. The latter is essential to find ProxyTest.class. The other parameters are:

• -Doracle.jdbc.Trace=true – this enables the logging
• -Djava.util.logging.config.file=oracledebug.properties – this says how and what to log
• ProxyTest – the name of the class to run
• jdbc:oracle:thin:@localhost:1521/orclpdb1 – the JDBC connection string for the database
• ORDS_PUBLIC_USER – the database account used for the initial connection.
• MySecretPassword – the password for the above database account
• HR – the schema to open a proxy session for

As you would expect, for your environment, some of these parameters will be different. The output should look something like this if there are no issues:

Trying to open proxy connection ...
Connection user: HR
Product Version: Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
Succeeded. Proxy connection closed

Of course, the only reason you are running this is because the environment has issues and you will see a SQLException stack trace instead. Moreover, you’ll have jdbc.log detailing everything that JDBC did. It will include entries that may get you closer to the root cause of the JDBC openProxySession connection problem:

Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.T4CConnection doProxySession
 FINEST: 6EA12C19 Enter: 1, {PROXY_USER_NAME=HR}
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.T4CTTIoauthenticate doOAUTH
 FINEST: 65D6B83B Enter: 1, {PROXY_USER_NAME=HR}, 702, 43458
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.DBConversion StringToCharBytes
 FINEST: 4E7DC304 Enter: "HR"
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.DBConversion stringToDriverCharBytes
 FINEST:          Enter: "HR", 873
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.DBConversion stringToDriverCharBytes
 FINEST:          Return: [B@21b2e768
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.DBConversion stringToDriverCharBytes
 FINEST:          Exit: [0.018982 ms]
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.DBConversion StringToCharBytes
 FINEST: 4E7DC304 Return: [B@21b2e768
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.DBConversion StringToCharBytes
 FINEST: 4E7DC304 Exit: [0.042244 ms]
 Dec 09, 2020 12:20:57 PM oracle.jdbc.driver.T4CTTIoauthenticate doOAUTH
 FINEST: 65D6B83B Enter: [B@21b2e768, "", "", 0, null, true, null, null, null, 702, 43458, null

At the very least, you have a log file to begin a meaningful conversation in the JDBC developer community. In fact, some of these steps and java code are based on forum entries, blog posts from Oracle employees and Oracle Support documents. I’m grateful that such a body of knowledge is easily accessible.