Issue Details (XML | Word | Printable)

Key: JDBC-542
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Blocker Blocker
Assignee: Mark Rotteveel
Reporter: VENKATESH DODDATHIMMAIAH
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Jaybird JCA/JDBC Driver

FBEventManager triggering "org/firebirdsql/gds/ng/wire/AsynchronousProcessor" thread spikes CPU and goes in to infinite IOException loop when FB is shut down

Created: 21/Aug/18 09:32 AM   Updated: 07/Sep/18 03:41 PM
Component/s: Events
Affects Version/s: Jaybird 3.0.3
Fix Version/s: Jaybird 3.0.5, Jaybird 4

File Attachments: 1. Java Source File AppDb.java (3 kB)
2. Text File Encryption key did not meet algorithm requirements of SymmetricArc4.txt (18 kB)
3. Java Source File HelloJaybird.java (0.3 kB)
4. Text File java.sql.SQLException No suitable driver.txt (12 kB)
5. Text File java.sql.SQLException No suitable driver.txt (4 kB)
6. XML File pom.xml (3 kB)

Environment: jaybird-jdk17 (3.0.3), Firebird 3.0, c3p0 (0.9.5.1), Java (1.8.0_161), Windows 10 & 2012 R2


 Description  « Hide
Application
-------------------------------------------------------------------
A Java application using FBEventManager to register for Firebird events via Jaybird.

Behavior
-------------------------------------------------------------------
Application launch connects to Firebird database successfully, followed by successful activation of FBEventManager channel.

State & Issue
-------------------------------------------------------------------
In this connected state when the Firebird is killed/shutdown, "org/firebirdsql/gds/ng/wire/AsynchronousProcessor", throws an IOException infinitely making the occupied thread peg CPU. If logging is enabled, the log file shoots to multiple GBs in size within minutes with these exception logs. This would lead to production server crashes or unable to serve any client requests because of high CPU utilization and disk usage/fullness.

Source of exception
-------------------------------------------------------------------
Exception thrown at line "#170 int count = socketChannel.read(eventBuffer);" from master version of "org/firebirdsql/gds/ng/wire/AsynchronousProcessor.java". Exception caught and logged at line "#187". Not sure if we are missing to do "selectionKey.cancel();" as Firebird is crashed/shutdown/killed - just my two cents. Exception handling is still open with "// TODO handle?".

Current impact
-------------------------------------------------------------------
All the customer sites deployed with our application servers gets in to frozen state, whenever there is a Firebird crash/restart. The server becomes unresponsive because of excessive CPU usage and mandates to restart our application server losing all the session states.

Simulation
-------------------------------------------------------------------
Attached is a sample application (with two Java files and associated pom) which can be used to directly simulate the issue.

Prerequisites
-------------------------------------------------------------------
1. Sample & valid FDB database file in a specific file system location
2. Firebird database server

Steps
-------------------------------------------------------------------
1. Change the source file "AppDb.java" to reflect above database file path & associated credentials
2. Build the application from the source as a maven project to get "mobileclient.jar"
3. Ensure Firebird server is up and running
4. Run the jar from a command prompt using "java -jar mobileclient.jar" and watch for the informational logs
5. Kill/shutdown Firebird service

Observation
-------------------------------------------------------------------
1. Watch for the infinite IOException logs impacting CPU performance

Expected behavior
-------------------------------------------------------------------
1. The IOException log should have appeared once and should have been handled properly clearing the stale socket channels with Firebird
2. The associated thread should not get into infinite IOException loop and utilize CPU only when needed on valid socket channels

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
VENKATESH DODDATHIMMAIAH added a comment - 21/Aug/18 09:35 AM
Use the above files to create a Maven project to generate "mobileclient.jar" which simulates this issue

Mark Rotteveel added a comment - 21/Aug/18 10:30 AM
Thanks. Did you have a specific reason to mark this as security level "Developers (Visible only to project developers (and administrators))", or is it OK if I make this publicly visible?

VENKATESH DODDATHIMMAIAH added a comment - 21/Aug/18 10:37 AM
Hi Mark,

There was no specific reason but intent was to reach out to the original authors of the component, so marked it as "Developers". Please make it public, not an issue.

Thanks for the quick response.

-- Venkatesh D.

Mark Rotteveel added a comment - 21/Aug/18 11:11 AM
I managed to reproduce this. When implementing I thought this would fall under the AsynchronousCloseException case, but apparently I have never verified that. I have a fix that will explicitly close for these exceptions.

Mark Rotteveel added a comment - 21/Aug/18 12:12 PM
Fix committed. Let me know if you want a snapshot version of Jaybird 3.0.5 for testing. I expect to release Jaybird 3.0.5 before the end of August.

VENKATESH DODDATHIMMAIAH added a comment - 21/Aug/18 01:10 PM
Please share the snapshot. Would greatly help us in verifying the fix and roll out the new version of our stable app server. Awaiting for the snapshot.

Thank you very much & we appreciate the timely fix/support.


Mark Rotteveel added a comment - 21/Aug/18 05:24 PM
Links for the snapshot

Jaybird 3.0.5-SNAPSHOT for Java 8 (and higher): https://www.dropbox.com/s/0cb6zo0j6soctgx/Jaybird-3.0.5-SNAPSHOT-JDK_1.8.zip?dl=0
Jaybird 3.0.5-SNAPSHOT for Java 7: https://www.dropbox.com/s/zcrxcqudxkicvbp/Jaybird-3.0.5-SNAPSHOT-JDK_1.7.zip?dl=0

I recommend you check the change log in the release notes so you are aware of the changes in 3.0.4 and 3.0.5-SNAPSHOT.

VENKATESH DODDATHIMMAIAH added a comment - 22/Aug/18 05:43 AM
Thanks for the snapshots.

I was able to add the Jaybird 3.0.5 JDK 1.7 library in my local maven repository, deployed and added its updated snapshot version in to my pom. All well till here, no errors in pom in resolving the artifact from local maven repository. Have few issues as below, any further help in resolving these is much appreciated.

When I try to build the application, I get the below console errors.

==================================================================================================================================
Aug 22, 2018 11:01:54 AM org.firebirdsql.logging.JulLogger warn
WARNING: Wire encryption established, but some plugins failed; see other loglines for details
Aug 22, 2018 11:01:54 AM org.firebirdsql.logging.JulLogger warn
WARNING: Encryption plugin failed
org.firebirdsql.gds.ng.wire.crypt.FBSQLEncryptException: Encryption key did not meet algorithm requirements of Symmetric/Arc4 [SQLState:28000, ISC error code:337248282]
               at org.firebirdsql.gds.ng.FbExceptionBuilder$Type$4.createSQLException(FbExceptionBuilder.java:570)
               at org.firebirdsql.gds.ng.FbExceptionBuilder.toFlatSQLException(FbExceptionBuilder.java:302)
               at org.firebirdsql.gds.ng.wire.crypt.arc4.Arc4EncryptionPlugin.createCipher(Arc4EncryptionPlugin.java:118)
               at org.firebirdsql.gds.ng.wire.crypt.arc4.Arc4EncryptionPlugin.createCipher(Arc4EncryptionPlugin.java:100)
               at org.firebirdsql.gds.ng.wire.crypt.arc4.Arc4EncryptionPlugin.createEncryptionCipher(Arc4EncryptionPlugin.java:82)
               at org.firebirdsql.gds.ng.wire.crypt.arc4.Arc4EncryptionPlugin.initializeEncryption(Arc4EncryptionPlugin.java:62)
               at org.firebirdsql.gds.ng.wire.version13.V13WireOperations.tryKnownServerKeys(V13WireOperations.java:194)
               at org.firebirdsql.gds.ng.wire.version13.V13WireOperations.authReceiveResponse(V13WireOperations.java:131)
               at org.firebirdsql.gds.ng.wire.version10.V10Database.authReceiveResponse(V10Database.java:569)
               at org.firebirdsql.gds.ng.wire.WireConnection.identify(WireConnection.java:309)
               at org.firebirdsql.gds.ng.wire.FbWireDatabaseFactory.performConnect(FbWireDatabaseFactory.java:51)
               at org.firebirdsql.gds.ng.wire.FbWireDatabaseFactory.connect(FbWireDatabaseFactory.java:39)
               at org.firebirdsql.gds.ng.wire.FbWireDatabaseFactory.connect(FbWireDatabaseFactory.java:32)
               at org.firebirdsql.event.FBEventManager.connect(FBEventManager.java:94)
=============================================================================================================================

It also seems that the driver is not able to establish itself and when I run the application, I see console logs as
=============================================================================================================================
32753 [C3P0PooledConnectionPoolManager[identityToken->2sb6uc9xqo7hli19z0aid|783859]-HelperThread-#0] WARN com.mchange.v2.resourcepool.BasicResourcePool - com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@8138a6 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception:
32753 [C3P0PooledConnectionPoolManager[identityToken->2sb6uc9xqo7hli19z0aid|783859]-HelperThread-#2] WARN com.mchange.v2.resourcepool.BasicResourcePool - com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@486392 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception:
32753 [C3P0PooledConnectionPoolManager[identityToken->2sb6uc9xqo7hli19z0aid|783859]-HelperThread-#1] WARN com.mchange.v2.resourcepool.BasicResourcePool - com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@1ddac04 -- Acquisition Attempt Failed!!! Clearing pending acquires. While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception:
java.sql.SQLException: No suitable driver
               at java.sql.DriverManager.getDriver(Unknown Source)
               at com.mchange.v2.c3p0.DriverManagerDataSource.driver(DriverManagerDataSource.java:285)
               at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:175)
               at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:220)
               at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206)
               at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203)
               at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1138)
               at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1125)
               at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44)
               at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1870)
               at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
java.sql.SQLException: No suitable driver
               at java.sql.DriverManager.getDriver(Unknown Source)
               at com.mchange.v2.c3p0.DriverManagerDataSource.driver(DriverManagerDataSource.java:285)
               at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:175)
               at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:220)
               at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:206)
               at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:203)
               at com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1138)
               at com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1125)
               at com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:44)
               at com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1870)
               at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
java.sql.SQLException: No suitable driver
               at java.sql.DriverManager.getDriver(Unknown Source)
=============================================================================================================================



Mark Rotteveel added a comment - 22/Aug/18 07:35 AM
This seems to be an unrelated problem, but can you try the following:

- Try with the Java 8 version instead of the Java 7 version; Jaybird 3.0.4 introduced a dependency on JAXB for the Java 7 version only, and depending on your deployment, you may need to explicitly depend on JAXB (for example, in Wildfly/JBoss, but likely also in other environments) when deploying the Java 7 version
- Try with version 3.0.4 to see if this is related to changes introduced in Jaybird 3.0.4 or in this snapshot.

If you can reproduce this, could you please create a separate ticket? It would also be helpful to have more logging. The first exception with message " Encryption key did not meet algorithm requirements of Symmetric/Arc4" should have an exception cause with a java.security.InvalidKeyException describing the underlying problem.

The second exception suggests that the driver has not been loaded for some reason, and I would expect a ClassNotFoundException or maybe a NoClassDefFoundError (and maybe other exceptions) earlier in your logs.


VENKATESH DODDATHIMMAIAH added a comment - 22/Aug/18 08:53 AM
Yes, seems unrelated.

I already have Java 8. As there were errors with "3.0.5-SNAPSHOT", I had tried with 3.0.4 as well and errors seems to exist from 3.0.4 itself.

So the migration path from 3.0.3 to 3.0.4 or 3.0.5 is simply broken.

I will create a separate ticket for this, would help if you have any hint on which component/module it falls in to.

I have attached both the exception logs as below files for your analysis
1. "Encryption key did not meet algorithm requirements of SymmetricArc4.txt" and
2. "java.sql.SQLException No suitable driver.txt"


Mark Rotteveel added a comment - 22/Aug/18 09:05 AM
According to you earlier comment, you use the Jaybird JDK 1.7 library (which is for Java 7), did you also try with Jaybird JDK 1.8 (which is for Java 8 and higher)?

When creating a new ticket, could you provide a reproducible test case, because the full Jaybird test suite works fine. The only thing I can think of is that the first problem might be an issue with the specific Firebird version used. Your environment states you're using Firebird 3.0, does this mean literally Firebird 3.0.0? If not, exactly which version are you using?

I'm not sure what could be causing the second issue though, I would expect a class loading error earlier in your logs. It would also be helpful to know the specifics of your environment.

VENKATESH DODDATHIMMAIAH added a comment - 22/Aug/18 09:45 AM
I have created a new ticket - http://tracker.firebirdsql.org/browse/JDBC-543

Unfortunately exceptions are thrown even with Jaybird JDK 1.8.

Your assumption could be right. It could be with Firebird version or its configuration which have to be changed while upgrading Jaybird from 3.0.3 to higher. I have explored the release notes of 3.0.4 and above for any modifications required, but found none.

Firebird is actually at version 3.0.3.

I received the second set of logs while trying to verify the simulation. i.e. to shutdown Firebird and watch for the exception logs from the SNAPSHOT version. When Firebird is killed, after few seconds the logs get generated. I have attached an updated log file with full logs that were received.