CertPathValidatorException Certificate chaining error using Weblogic 11g and IBM JSSE

This case study describes the complete steps from root cause analysis to resolution of an SSL communication problem between a Weblogic 11g client application and remote Web Service provider that we faced recently when migrating our application from Weblogic 8.1 to Weblogic 11g.

It will also demonstrate the importance for proper understanding of the SSL and Java keystore principles as this is a common problem you may face with a Java EE environment using SSL to communication with your service providers / downstream systems.

Environment specifications

·         Java EE server (client side): Oracle Weblogic 11g

·         OS: AIX 5.3 TL12 64-bit

·         JDK: IBM JRE 1.6 SR9 64-bit

·         RDBMS: Oracle 10gr2

·         HTTP / HTTPS client API: Apache HTTP Client

·         JSSE / SSL provider: IBMJSSEProvider2

·         Platform type: Web Service and middle tier application

Monitoring and troubleshooting tools

·         Java / Javax SSL debug (logging / tracing purpose)

·         Java keytool command (Java keystore inspection)

·         JSP test page (logging / tracing purpose)

Problem overview

Problem type: The java.security.cert.CertPathValidatorException:

The certificate issued by <Root CA issuer> is not trusted; internal cause is: java.security.cert.CertPathValidatorException: Certificate chaining error

Our application backend calls to a remote Web Service provider were unable to complete proper SSL handshake due the above error. The problem was that the certificate of the downstream server was not trusted by the Weblogic 11g / JSSE provider.

Error detail

The error detail below did reveal an IBM JSSE2 component as the source of the SSL handshake failure: com.ibm.security.cert.CertPathUtil.findIssuer(CertPathUtil.java:298) and did reveal the following fact:

·         Fact #1: The failure is triggered during the SSL issuer verification check between the client (Weblogic 11g) list of trust Root CA’s and the remote server SSL certificate issuer found at the root of the certificate path

[[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'] com.ibm.jsse2.util.g: PKIX path building failed: java.security.cert.CertPathBuilderException: PKIXCertPathBuilderImpl could not build a valid CertPath.; internal cause is:

        java.security.cert.CertPathValidatorException: The certificate issued by <Root CA issuer> is not trusted; internal cause is:

        java.security.cert.CertPathValidatorException: Certificate chaining error when connecting to url="https://xyz.xyz.xyz.xyz/WebService"

javax.net.ssl.SSLHandshakeException: com.ibm.jsse2.util.g: PKIX path building failed: java.security.cert.CertPathBuilderException: PKIXCertPathBuilderImpl could not build a valid CertPath.; internal cause is:

        java.security.cert.CertPathValidatorException: The certificate issued by <Root CA issuer> is not trusted; internal cause is:

        java.security.cert.CertPathValidatorException: Certificate chaining error

        at com.ibm.jsse2.n.a(n.java:8)

        at com.ibm.jsse2.tc.a(tc.java:96)

        at com.ibm.jsse2.gb.a(gb.java:241)

        at com.ibm.jsse2.gb.a(gb.java:318)

        at com.ibm.jsse2.hb.a(hb.java:232)

        at com.ibm.jsse2.hb.a(hb.java:23)

        at com.ibm.jsse2.gb.n(gb.java:295)

        at com.ibm.jsse2.gb.a(gb.java:269)

        at com.ibm.jsse2.tc.a(tc.java:347)

        at com.ibm.jsse2.tc.g(tc.java:416)

        at com.ibm.jsse2.tc.a(tc.java:461)

        at com.ibm.jsse2.j.write(j.java:23)

        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:76)

        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:134)

        at org.apache.commons.httpclient.methods.EntityEnclosingMethod.writeRequestBody(EntityEnclosingMethod.java:502)

        at org.apache.commons.httpclient.HttpMethodBase.writeRequest(HttpMethodBase.java:1973)

        at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:993)

        at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:397)

        at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:170)

        at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:396)

        at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:324)

        at com.org.app.HttpConnector.readResponseBody()

              .............................................

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)

        at java.lang.reflect.Method.invoke(Method.java:611)

        at weblogic.wsee.jaxws.WLSInstanceResolver$WLSInvoker.invoke(WLSInstanceResolver.java:92)

        at weblogic.wsee.jaxws.WLSInstanceResolver$WLSInvoker.invoke(WLSInstanceResolver.java:74)

        at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:151)

        at com.sun.xml.ws.server.sei.EndpointMethodHandlerImpl.invoke(EndpointMethodHandlerImpl.java:265)

        at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:100)

        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:604)

        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:563)

        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:548)

        at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:445)

        at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:373)

        at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:524)

        at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:255)

        at com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAdapter.java:140)

        at weblogic.wsee.jaxws.WLSServletAdapter.handle(WLSServletAdapter.java:208)

        at weblogic.wsee.jaxws.HttpServletAdapter$AuthorizedInvoke.run(HttpServletAdapter.java:310)

        at weblogic.wsee.jaxws.HttpServletAdapter.post(HttpServletAdapter.java:223)

        at weblogic.wsee.jaxws.JAXWSServlet.doPost(JAXWSServlet.java:124)

        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)

        at weblogic.wsee.jaxws.JAXWSServlet.service(JAXWSServlet.java:79)

        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)

        at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)

        at weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)

        at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300)

        at weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:183)

        at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.doIt(WebAppServletContext.java:3686)

        at weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3650)

        at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)

        at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121)

        at weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2268)

        at weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2174)

        at weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1446)

        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)

        at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)

Caused by:

com.ibm.jsse2.util.g: PKIX path building failed: java.security.cert.CertPathBuilderException: PKIXCertPathBuilderImpl could not build a valid CertPath.; internal cause is:

        java.security.cert.CertPathValidatorException: The certificate issued by <Root CA issuer> is not trusted; internal cause is:

        java.security.cert.CertPathValidatorException: Certificate chaining error

        at com.ibm.jsse2.util.e.b(e.java:55)

        at com.ibm.jsse2.util.e.b(e.java:77)

        at com.ibm.jsse2.util.d.a(d.java:13)

        at com.ibm.jsse2.hc.a(hc.java:80)

        at com.ibm.jsse2.hc.checkServerTrusted(hc.java:82)

        at com.ibm.jsse2.hc.b(hc.java:24)

        at com.ibm.jsse2.hb.a(hb.java:124)

        ... 66 more

Caused by:

java.security.cert.CertPathBuilderException: PKIXCertPathBuilderImpl could not build a valid CertPath.; internal cause is:

        java.security.cert.CertPathValidatorException: The certificate issued by <Root CA issuer> is not trusted; internal cause is:

        java.security.cert.CertPathValidatorException: Certificate chaining error

        at com.ibm.security.cert.PKIXCertPathBuilderImpl.engineBuild(PKIXCertPathBuilderImpl.java:411)

        at java.security.cert.CertPathBuilder.build(CertPathBuilder.java:258)

        at com.ibm.jsse2.util.e.b(e.java:112)

        ... 72 more

Caused by:

java.security.cert.CertPathValidatorException: The certificate issued by <Root CA issuer> is not trusted; internal cause is:

        java.security.cert.CertPathValidatorException: Certificate chaining error

        at com.ibm.security.cert.BasicChecker.<init>(BasicChecker.java:111)

        at com.ibm.security.cert.PKIXCertPathValidatorImpl.engineValidate(PKIXCertPathValidatorImpl.java:176)

        at com.ibm.security.cert.PKIXCertPathBuilderImpl.myValidator(PKIXCertPathBuilderImpl.java:737)

        at com.ibm.security.cert.PKIXCertPathBuilderImpl.buildCertPath(PKIXCertPathBuilderImpl.java:649)

        at com.ibm.security.cert.PKIXCertPathBuilderImpl.buildCertPath(PKIXCertPathBuilderImpl.java:595)

        at com.ibm.security.cert.PKIXCertPathBuilderImpl.buildCertPath(PKIXCertPathBuilderImpl.java:595)

        at com.ibm.security.cert.PKIXCertPathBuilderImpl.buildCertPath(PKIXCertPathBuilderImpl.java:595)

        at com.ibm.security.cert.PKIXCertPathBuilderImpl.engineBuild(PKIXCertPathBuilderImpl.java:357)

        ... 74 more

Caused by:

java.security.cert.CertPathValidatorException: Certificate chaining error

        at com.ibm.security.cert.CertPathUtil.findIssuer(CertPathUtil.java:298)

        at com.ibm.security.cert.BasicChecker.<init>(BasicChecker.java:108)

        ... 81 more

SSL debug

SSL debug was enabled via the following argument in order to further troubleshoot the problem:

-Djavax.net.debug=ssl:verbose

-Dssl.debug=true

The additional traces below were generated which did confirm problem related to JSSE not trusting the received SSL certificate from the remote service provider.

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', SEND TLSv1 ALERT:  fatal, description = certificate_unknown

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', WRITE: TLSv1 Alert, length = 2

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', called closeSocket()

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', handling exception: javax.net.ssl.SSLHandshakeException: com.ibm.jsse2.util.g: PKIX path building failed: java.security.cert.CertPathBuilderException: PKIXCertPathBuilderImpl could not build a valid CertPath.; internal cause is:

       java.security.cert.CertPathValidatorException: The certificate issued by <Root CA issuer> is not trusted; internal cause is:

       java.security.cert.CertPathValidatorException: Certificate chaining error

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', called close()

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', called closeInternal(true)

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', called close()

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', called closeInternal(true)

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', called close()

[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)', called closeInternal(true)

                    

Java trust keystore configuration verification

The SSL and Java keystore configuration was verified in the Weblogic 11g console which did not reveal any problem. By default, Weblogic is using DemoTrust and JRE trust (cacerts); which contain the ROOT CA signature for most SSL trusted provider such as Entrust which we use in our enterprise.

The remote server issuer was also verified against our Weblogic 11g JRE 1.6 trust keystore (cacerts) which did not reveal any problem and a perfect match.

Java trust keystore runtime verification

Given no clear indication on the root cause at this point, we decided to add additional tracing and verified the location of the trust keystore at runtime. The following code was executed from a test JSP page in order to verify each value at runtime:

//The loaded JSSE trust keystore location

System.getProperty("javax.net.ssl.trustStore"); // mismatch found!

//The Java Home of your Java VM running Weblogic 11g

System.getProperty("java.home");

//The loaded JSSE trust keystore type

System.getProperty("javax.net.ssl.trustStoreType");

//The JSSE trust keystore provider & encrypted password

System.getProperty("javax.net.ssl.trustStoreProvider");

System.getProperty("javax.net.ssl.trustStorePassword");

·         Fact #2: The additional tracing did reveal a mismatch of the location of the trust keystore since it was pointing to an application specific keystore containing only some custom self-signed CA’s and no Entrust ROOT CA

Root cause and resolution

Additional analysis of the application did reveal an override of the trust keystore location (javax.net.ssl.trustStore) which was leading to a SSL communication failure with our remote service provider since all Entrust ROOT CA’s were missing at runtime.

The application was updated and reconfigured in order to use the default JSSE trust keystore and ensure no override of the global Javax JSSE / SSL System properties.

Conclusion and recommendations

·         When facing “CertPathValidatorException: Certificate chaining error” problem with Weblogic and IBM JSSE, first verify your trust keystore configuration and ensure that your keystore does contain proper ROOT CA  entry of your trusted provider and matches your remote service provider SSL certificate issuer and signature

·         Please enable SSL debug in order to analyse the SSL handshake process and understand the source of the failure. These traces are really helpful and will help you pinpoint the root cause

·          Please consider adding code to print the runtime value of the Javax SSL specific System properties. This can really help you pinpoint any wrong SSL configuration or override of your expected SSL / JSSE configuration parameters

Read More

Network Adapter could not establish the connection problem using Weblogic 8.1

This case study describes the complete steps from root cause analysis to resolution of an intermittent Weblogic Connection Pool connectivity problem experienced between an Oracle Weblogic 8.1 application server and an Oracle 10g database.

Related Posts

JDBC Driver - Problem Patterns

It will also demonstrate the importance for an application support person of mastering some basic network troubleshooting skill sets and techniques in order to do proper problem isolation and root cause analysis of such type of problem.

Environment specifications

·         Java EE server: Oracle Weblogic Platform 8.1 SP6

·         OS: AIX 5.3 TL9 64-bit

·          JDK: IBM JRE 1.4.2 SR13 32-bit

·         RDBMS: Oracle 10gr2

·         Platform type: Ordering application

Monitoring and troubleshooting tools

·         AIX 5.3 PING comman

·         AIX 5.3 TRACEROUTE command

·         Weblogic dbping utility

Problem overview

-          Problem type: The DBMS driver exception was: Io exception: The Network Adapter could not establish the connection

An intermittent connectivity problem was observed in our production environment between our application server and database server. Such Weblogic error was spotted in our log during problem reproduction.

Initial problem mitigation did involve restarting the affected Weblogic managed server(s) almost on a daily basis until successful connection established with the remote database server.

Gathering and validation of facts

A Java EE problem investigation requires gathering of technical and non technical facts so we can either derived other facts and/or conclude on the root cause. Before applying a corrective measure, the facts below were verified in order to conclude on the root cause:

·         What is the client impact? Low, problem was intermittent and our platform has proper load balancing and fail-over in place

·         Recent change of the affected platform? No

·         Any recent traffic increase to the affected platform? No

·         Any recent activity or restart of the application server or database server? Yes, the application server is restarted on daily basis. The remote database server was last physically restarted a few weeks ago following a network incident in the server farm

·         Since how long this problem has been observed?  Since a few weeks

·          Is the JDBC Connection Pool connectivity problem is consistent or intermittent? Problem is intermittent

·         Did a restart of the Weblogic server resolve the problem? No, currently only used as a mitigation strategy

·         Did the DBA team found any problem with the Oracle 10g database? No problem found with the database itself

·         Did the support team analysis the Weblogic logs and any error? Yes, Weblogic JDBC error was found and as per Weblogic  / JDBC Driver documentation, this indicates that the JDBC driver is unable to physically connect to the remote Oracle database

·         Conclusion #1: The problem and error type appear to point to a network / connectivity problem between Weblogic application server and remote database server

·         Conclusion #2: The recent network problem and physical restart of the Oracle database server is a potential trigger suspect

Weblogic error log review

The error below was found during problem reproduction. Such error prevented the initialization and deployment of our primary application JDBC Data Source and application.

                    

<Warning> <JDBC> <BEA-001129> <Received exception while creating connection for pool "<App Conn Pool>": Io exception: The Network Adapter could not establish the connection

> 

<Error> <JDBC> <BEA-001150> <Connection Pool "<App Conn Pool>" deployment failed with the following error: 0:Could not create pool connection. The DBMS driver exception was: Io exception: The Network Adapter could not establish the connection.>

<Error> <JDBC> <BEA-001151> <Data Source "<App DS>" deployment failed with the following error: DataSource(App DS) can't be created with non-existent Pool (connection or multi) (App Conn Pool).>

Network health check using PING, TRACEROUTE and other utilities

Given the intermittent behaviour of this problem, the support team decided to perform some additional analysis of the network situation between our application and database server. The AIX PING command was used for that purpose as per below.

# Send 5 packets of 64 bytes to the remote database IP address

ping -c 5 -q -s 64 <IP address>

# Validate the connectivity and route through the different HOP(s)) from the source server (Weblogic application server) to the destination server (Oracle 10g database server)

traceroute <IP address>

As per the above results, ~50% of loss packets were found between our application and database server. The intermittent connectivity problem was also reproduced using the traceroute command.

Please note that Weblogic has also a database "ping" utility that you can use to test your network connectivity and database listener availability from the WebLogic physical server to the remote DB server. This utility basically simulates the creation of a new JDBC Connection via the java.sql.DriverManager.

DB Ping Usage

../<JAVA_HOME>/bin/java -classpath ../<WL_HOME>/<WL_SERVER_HOME>/server/lib/weblogic.jar utils.dbping ORACLE_THIN <dbUserName> <dbPasswoes> <dbURL>

DB Ping - Other RDBMS Provider Usage

java utils.dbping DB2B  [-d dynamicSections] USER PASS HOST:PORT/DBNAME\nor    
java utils.dbping JCONN2       USER PASS HOST:PORT/DBNAME\nor    

java utils.dbping JCONN3       USER PASS HOST:PORT/DBNAME\nor    

java utils.dbping JCONNECT     USER PASS HOST:PORT/DBNAME\nor    

java utils.dbping INFORMIXB    USER PASS HOST:PORT/DBNAME/INFORMIXSERVER\nor    

java utils.dbping MSSQLSERVERB USER PASS HOST:PORT/[DBNAME]\nor    

java utils.dbping MYSQL        USER PASS [HOST][:PORT]/[DBNAME]\nor    

java utils.dbping ORACLEB      USER PASS HOST:PORT/DBNAME\nor    

java utils.dbping ORACLE_THIN  USER PASS HOST:PORT:DBNAME\nor    

java utils.dbping POINTBASE    USER PASS HOST[:PORT]/DBNAME\nor    

java utils.dbping SYBASEB      USER PASS HOST:PORT/DBNAME"); 

Finally, you can also use the TELNET command for that same purpose:

Telnet Usage

telnet <DB hostname> <DB listener port>

Network sniffer analysis

Following the findings, our application support team did engage a network sniffer team to troubleshoot the problem further. Analysis was done by sniffing the inbound and outbound traffic packets generated by the ping and traceroute commands at the network switch level between the source and destination server.

The sniffer team found that the lost packets were actually not coming out of the remote database server; which did isolate the problem further at the remote database server level.

Suspected root cause

The combination of the gathered facts along with application and network support teams did conclude on a routing problem affecting the Oracle 10g database and causing intermittent but consistent packet loss with our application server.

Given the recent network problem in the server farm and physical reboot of the server, it was suspected that the root cause of the problem was related to an invalid ARP table of the network switch and/or our Oracle database server.

ARP stands for address resolution protocol. The delivery an IP packet to the next hop is encapsulated in an Ethernet frame. Such frame must contain a destination address which is determined by inspecting the ARP cache table. If the table does not have an entry the switch will issue an ARP request and wait for a response from the next hop. Any problem with this cached table could lead to routing and connectivity problem; requiring a reset.

Resolution and results

As per the root cause analysis, the physical server support team did proceed with a physical reboot of the affected database server which did reset/clear both ARP tables at the switch and server level.

The results were quite conclusive post restart and the % of packet loss dropped from 50% to 0%. The traceroute command also indicated fast connectivity with no delay.

Conclusion and recommendations

·         When facing “The Network Adapter could not establish the connection” problem with Weblogic, do not assume that the database server is down; gather all the data and facts instead and proceed with simple network problem isolation using ping & traceroute and telnet (port health check

·         Perform your due diligence and problem isolation before engaging a network sniffer team, this will help you speed up the root cause analysis process

·          Please make sure to keep track on key events/deployments inside your environment, including network problem episodes as those type of events are often trigger of Java EE related problems

Read More

Java DNS Cache Reference Guide

Development of complex distributed Java EE systems quite often involves integration with multiple downstream systems. Such system business service(s) can be exposed via HTTP or other protocols, Internet facing or secured within its own private network zone. The most common approach is to centralize the platform access via a front door DNS (Domain Name System) name. When supporting a Java EE production system, it is important to understand the JDK DNS management; especially its default caching policy.

This article will provide you an overview and comparison matrix of the DNS cache policy between JDK 1.4, 1.5 and 1.6 and how you can override the default behaviour when necessary.

Default DNS cache policy and DNS spoofing attack

The default JDK DNS cache policy TTL (time to live) value is -1 (caching forever). You may wonder why as this can cause some problems when network DNS re-pointing changes are required, forcing any Java client to shutdown and restart its JVM / Java EE server.

The main reason for this default behaviour is security. As mentioned in Sun documentation, no DNS caching or any positive value below 30 seconds could expose your environment to DNS spoofing attack; especially for Internet facing Java EE environments vs. applications deployed within a secured and private network zone.

A DNS spoofing attack is an attempt by an attacker to fool a DNS server and re-point a specific DNS entry to a different IP (hacker IP). The DNS server then remains “poisoned” until it refreshes its cache. This means all Java InetSocketAddress DNS lookup requests to the effected DNS Server during that time period will also be “poisoned“ and return an unexpected / hacked IP address.

Now find below the default DNS cache behavior between the different JDK versions and override methods.

DNS cache override and JDK comparison matrix

	JDK 1.4 & 1 .5	JDK 1.6, 1.7 & 1.8
Default value	-1 (caching forever) *JVM restart required to flush the DNS cache	30 secs (When a security manager is not set) -1           (When a security manager is set) * DNS Cache is refreshed every 30 seconds
Editable	yes	yes
Default Value Printing	System.out.println("DEFAULT DNS TTL: "+sun.net.InetAddressCachePolicy.get());	System.out.println("DEFAULT DNS TTL: "+sun.net.InetAddressCachePolicy.get());
Override Option #1	<JDK_HOME>/jre/lib/security/java.security #networkaddress.cache.ttl=-1 * Uncomment the above parameter and change as per your desired positive value in seconds	<JDK_HOME>/jre/lib/security/java.security #networkaddress.cache.ttl=-1 * Uncomment the above parameter and change as per your desired positive value in seconds
Override Option #2	* Execute the code below on JVM start-up java.security.Security.setProperty ("networkaddress.cache.ttl" , TTL_SECS); // TTL_SECS represents your configured TTL value	* Execute the code below on JVM start-up java.security.Security.setProperty ("networkaddress.cache.ttl" , TTL_SECS); // TTL_SECS represents your configured TTL value
Java reference classes	sun.net.InetAddressCachePolicy	sun.net.InetAddressCachePolicy

Read More

Connection pool leak using Hibernate 3.2.3 and Weblogic 10.3

This case study describes the complete steps from root cause analysis to resolution of a JDBC connection pool leak problem experienced with Oracle Weblogic 10.3 and using the open source Java persistence framework Hibernate 3.2.3.

This case study will also demonstrate the importance of best coding practices when using Hibernate and how a simple code problem can have severe consequences on a production environment.

Environment specifications

 

·         Java EE server: Oracle Weblogic Portal 10

·         OS: AIX 5.3 TL9 64-bit

·         JDK: IBM JRE 1.6.0 SR2 64-bit

·         RDBMS: Oracle 11g

·         Persistence API: Hibernate 3.2.3

·         Platform type: Portal application

Monitoring and troubleshooting tools

·         Enterprise internal remote JMX client monitoring tool

Problem overview
 

·         Problem type: JDBC Connection Pool Leak

JDBC Data Source Connection Pool depletion was observed in our production environment following an upgrade from Weblogic Portal 8.1 to Weblogic Portal 10.3.

Initial problem mitigation did involve restarting all the Weblogic managed servers almost every hour until decision was taken to rollback to the previous Weblogic Portal 8.1 environment.

Gathering and validation of facts

As usual, a Java EE problem investigation requires gathering of technical and non technical facts so we can either derived other facts and/or conclude on the root cause. Before applying a corrective measure, the facts below were verified in order to conclude on the root cause:

·         What is the client impact? HIGH

·         Recent change of the affected platform? Yes, the application was migrated recently from Weblogic Portal 8.1 to Weblogic Portal 10.3. Also, the application code was migrated from EJB Entity Beans to Hibernate for the read and write operations to the Oracle database

·         Any recent traffic increase to the affected platform? No

·          Since how long this problem has been observed?  Right after the upgrade project deployment

·          Is the JDBC Connection Pool depletion happening suddenly or over time? It was observed via our internal enterprise JMX client monitoring tool that the connection pool is increasing over time at a fast rate. The current pool capacity is 25

·         Did a restart of the Weblogic server resolve the problem? No, rollback to the previous environment was required

·         Conclusion #1: The problem is related to a JDBC Connection Pool leak of the primary application JDBC data source

·         Conclusion #2: This problems correlates with the Weblogic upgrade and migration of our application code to Hibernate

JDBC Pool utilization

The history of JDBC Pool utilization was captured using our internal enterprise remote JMX monitoring tool. Such monitoring is achieved by connecting remotely to the Weblogic server and pull detail from the runtime Weblogic MBeans:

StringBuffer canonicalObjNameBuffer = new StringBuffer();

// MBean query
canonicalObjNameBuffer.append("com.bea:Name=");
canonicalObjNameBuffer.append(jdbcDSName);
canonicalObjNameBuffer.append(",ServerRuntime=");
canonicalObjNameBuffer.append(instanceName);

canonicalObjName = CanonicalObjectNameObjectCacheFactory.getInstance().getCanonicalObjectName(canonicalObjNameBuffer.toString(), null);

// JDBC data source MBean metrics extraction
int activeConnectionCount = (Integer)adapter.getJMXService().getJMXConnection().getMBeanAttribute(canonicalObjName, "ActiveConnectionsCurrentCount");
int leakedConnectionCount = (Integer)adapter.getJMXService().getJMXConnection().getMBeanAttribute(canonicalObjName, "LeakedConnectionCount");
long reservedRequestCount = (Long)adapter.getJMXService().getJMXConnection().getMBeanAttribute(canonicalObjName, "ReserveRequestCount");
int connectionDelayTime = (Integer)adapter.getJMXService().getJMXConnection().getMBeanAttribute(canonicalObjName, "ConnectionDelayTime");

The graph below represents a history of the ActiveConnectionsCurrentCount MBean metric. This corresponds to your current connection pool utilization.  

The results were quire conclusive as it did reveal such connection pool leak and some sudden surge leading to full depletion.

Error log review

The log review did reveal the following error during these 2 episodes of connection leak surge. There was a very good correlation with # of errors found in these logs and the # of leaked connections increase observed from graph. The error was thrown during execution of the Hibernate Session.flush() method due to null value injection.

Unexpected exception has occured: org.hibernate.PropertyValueException: not-null property references a null or transient value: app.AppComponent.method UnExpected Exception has been occured:

org.hibernate.PropertyValueException: not-null property references a null or transient value: app.AppComponent.method

               at org.hibernate.engine.Nullability.checkNullability(Nullability.java:72)

               at org.hibernate.event.def.DefaultFlushEntityEventListener.scheduleUpdate(DefaultFlushEntityEventListener.java:263)

               at org.hibernate.event.def.DefaultFlushEntityEventListener.onFlushEntity(DefaultFlushEntityEventListener.java:121)

               at org.hibernate.event.def.AbstractFlushingEventListener.flushEntities(AbstractFlushingEventListener.java:196)

               at org.hibernate.event.def.AbstractFlushingEventListener.flushEverythingToExecutions(AbstractFlushingEventListener.java:76)

               at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:26)

               at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)

               at app.DaoComponent.insert

Weblogic Profile Connection Leak

The next step was to enable to Profile Connection Leak; similar to what we did with another JDBC connection pool leak using Weblogic 9.0.

The exercise did reveal the source of the leak from one of our application DAO using Hibernate; same DAO component which was generating errors in our log due to null value injection.

Hibernate best practices and code review

Proper coding best practices are important when using Hibernate to ensure proper Session / Connection resource closure. Any Hibernate Session along with JDBC resource must be closed in a finally{} block to properly handle any failure scenario. Such finally{} block must also be shielded against any failure condition in order to guarantee closure of the Hibernate session by adding proper try{} catch{} block when applicable.

The code analysis did reveal a problem with the Hibernate Session / Connection closure code; bypassing the execution of the Hibernate session.close() in the scenario an Exception is thrown during execution of session.flush().

finally {

       if (session != null) {

       session.flush();  

       session.close();

       }

}

Root cause

The root cause of the connection leak was concluded as a combination code defect within our DAO component. The code portion that is taking care of the Hibernate session flush was not embedded in a try{} catch{} block. Any failure of the Session.flush() was bypassing closure of the Hibernate session; triggering a leak of the associated JDBC connection.

Solution and results

A code fix was applied to the problematic DAO component as per below and deployed to our production environment following proper testing.

BEFORE

AFTER

The results were quite conclusive and did confirm a complete resolution of the JDBC connection pool leak.

Conclusion and recommendations

·         Perform regular code walkthrough of any new code with an increased focus for any new code dealing with JDBC and third party API implementation such as Hibernate. Always ensure that your JDBC and Hibernate related resource closure code is bullet proof against any negative scenario.

·          Perform regular monitoring of your production Weblogic JDBC Pool utilization, ensure no JDBC Pool leak is present (proactive monitoring). Same exercise should be done in your load testing environment before deploying a major release.

Read More