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

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

Closed
firebird-automations opened this issue Aug 21, 2018 · 18 comments

Comments

@firebird-automations
Copy link

Submitted by: VENKATESH DODDATHIMMAIAH (venkatesh)

Attachments:
AppDb.java
HelloJaybird.java
pom.xml
Encryption key did not meet algorithm requirements of SymmetricArc4.txt
java.sql.SQLException No suitable driver.txt
java.sql.SQLException No suitable driver.txt

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

Commits: 89b4736 758c0e8

@firebird-automations
Copy link
Author

Commented by: VENKATESH DODDATHIMMAIAH (venkatesh)

Use the above files to create a Maven project to generate "mobileclient.jar" which simulates this issue

@firebird-automations
Copy link
Author

Modified by: VENKATESH DODDATHIMMAIAH (venkatesh)

Attachment: AppDb.java [ 13282 ]

Attachment: HelloJaybird.java [ 13283 ]

Attachment: pom.xml [ 13284 ]

@firebird-automations
Copy link
Author

Commented by: @mrotteveel

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?

@firebird-automations
Copy link
Author

Commented by: VENKATESH DODDATHIMMAIAH (venkatesh)

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.

@firebird-automations
Copy link
Author

Commented by: @mrotteveel

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.

@firebird-automations
Copy link
Author

Modified by: @mrotteveel

Fix Version: Jaybird 3.0.5 [ 10873 ]

Fix Version: Jaybird 4 [ 10441 ]

security: Developers [ 10012 ] =>

@firebird-automations
Copy link
Author

Commented by: @mrotteveel

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.

@firebird-automations
Copy link
Author

Modified by: @mrotteveel

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

@firebird-automations
Copy link
Author

Commented by: VENKATESH DODDATHIMMAIAH (venkatesh)

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.

@firebird-automations
Copy link
Author

Commented by: @mrotteveel

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.

@firebird-automations
Copy link
Author

Commented by: VENKATESH DODDATHIMMAIAH (venkatesh)

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)

@firebird-automations
Copy link
Author

Commented by: @mrotteveel

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.

@firebird-automations
Copy link
Author

Commented by: VENKATESH DODDATHIMMAIAH (venkatesh)

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"

@firebird-automations
Copy link
Author

Modified by: VENKATESH DODDATHIMMAIAH (venkatesh)

Attachment: Encryption key did not meet algorithm requirements of SymmetricArc4.txt [ 13287 ]

Attachment: java.sql.SQLException No suitable driver.txt [ 13288 ]

@firebird-automations
Copy link
Author

Commented by: @mrotteveel

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.

@firebird-automations
Copy link
Author

Commented by: VENKATESH DODDATHIMMAIAH (venkatesh)

I have created a new ticket - JDBC543

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.

@firebird-automations
Copy link
Author

Modified by: VENKATESH DODDATHIMMAIAH (venkatesh)

Attachment: java.sql.SQLException No suitable driver.txt [ 13293 ]

@firebird-automations
Copy link
Author

Modified by: @mrotteveel

status: Resolved [ 5 ] => Closed [ 6 ]

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