[jira] [Resolved] (DBCP-599) destroyObject method behaves incorrectly on ABANDONED connection, issue with unhandled AbstractMethodError

["Gary D. Gregory (Jira)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/DBCP-599?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Gary D. Gregory resolved DBCP-599.
----------------------------------
    Fix Version/s: 2.12.1
       Resolution: Fixed

> destroyObject method behaves incorrectly on ABANDONED connection, issue with unhandled AbstractMethodError
> ----------------------------------------------------------------------------------------------------------
>
>                 Key: DBCP-599
>                 URL: https://issues.apache.org/jira/browse/DBCP-599
>             Project: Commons DBCP
>          Issue Type: Bug
>    Affects Versions: 2.12.0
>         Environment: Linux, Tomcat 9.0.82, openjdk 17, jconn4.jar (Sybase JDBC 4.0 spec DB driver) in tomcat's lib dir
>            Reporter: denixx baykin
>            Priority: Major
>             Fix For: 2.12.1
>
>         Attachments: TestPoolableConnectionFactory.java, abandoned_objects_1.txt, abandoned_objects_other_1.txt, abandoned_objects_query_1.txt, abandoned_traces_1.txt, errors_getting_connection_traces_1_filtered_1.txt, errors_getting_connection_traces_2_filtered_1.txt, part_of_server_xml.txt, part_of_stacktrace_1.txt, successfully_killed_1_filtered_1.txt, testcase_PoolableConnectionFactory_1.patch
>
>
> Short description of the problem:
> The PoolableConnectionFactory.destroyObject method is called for a connection in ABANDONED status, which results in an AbstractMethodError on a real connection due to not calling DelegatingConnection#abort, which takes into account throwing such an error due to Jdbc41Bridge#abort.
> Details:
> It all started when we determined from the application logs in tomcat 9.0.82 that stacktraces were being dumped for allegedly not being able to get a new connection from the connect pool.
> At the same time, I know and I am sure that we are configured to handle Abandoned connections and remove them from the pool.
> However, on that day we received an application that after some time started to “complain” that it can't give new connections and that the pool doesn't give these new connections for 20 seconds.
> Stacktrace-dump and heapdump were obtained, and after restarting the application “everything was normalized”.
> After parsing the contents of the heapdump I found out that with maxTotal equal to 20 connections we had 18 connections in ABANDONED state, and only 2 in IDLE state, which on that day continued to hold all the load that fell only on them, and, apparently, “when the application needed 3 connections at once in a row” - we had problems with getting them from the pool, why we saw a lot of stacktraces about the impossibility to get these connections from the pool.
> On that day, apparently, a stored procedure was changed, the call of which under certain conditions caused the connection to “freeze”, waiting for a response from the database, and of course it was killed by the pool and transferred to the ABANDONED status.
> We counted 18 such connections in the heapdump, but the most interesting thing is that the configuration for the Abandoned mechanism is set up in such a way that we assumed that such connections would be thrown out of the connection pool and their place would be taken by “fresh” ones, but it was obviously not so.
> As a result, what was the situation: when calling BasicDataSource.getConnection on stacktrace, our application reached the method PoolableConnectionFactory.destroyObject, which resulted in AbstractMethodError, which, due to the fact that it is Error, was not captured by catch-blocks, and knocked out the connection obtaining from the pool, because of which we had a few 500 errors at times when more than 2 connections were required at the same time (this is my assumption at the moment).
> I “looked through” the sources of Tomcat 9.0.82 in terms of working with dbcp2, stacktrace frames, and in many of the errors we received at that time, associated with getting a connection from the pool involved method org.apache.commons.dbcp2.PoolableConnectionFactory#destroyObject(org.apache.commons.pool2.PooledObject<org.apache.commons.dbcp2.PoolableConnection>, org.apache.commons.pool2.DestroyMode), designated by Gary Gregory as '@since 2.9.0'.
> This method itself is recorded in the history of git as having appeared in such a commit:
> cbf77a08b7c64c1df3e2b2d2ee5e1415c9a885a1    Mon Dec 28 18:17:43 CET 2020    Phil Steitz*    Use abort rather than close to destroy abandoned connections. Fixes DBCP-567. (#68)
> [https://issues.apache.org/jira/projects/DBCP/issues/DBCP-567]
> Its current implementation results in the line org/apache/commons/dbcp2/PoolableConnectionFactory.java:152 where we have p.getObject().getInnermostDelegate().abort(Runnable::run), but getInnermostDelegate does retrieve the “last” connection, which is at the end of the nesting chain, rather than PoolableConnection, which inherits from the DelegatingConnection class and implements the method org.apache.commons.dbcp2.DelegatingConnection#abort , which takes into account that a database driver may be used that supports the JDBC 4.0 specification, and there is no abort method implementation there. The org.apache.commons.dbcp2.Jdbc41Bridge#abort method provides "workaround" in this case, ensuring that close is called instead of abort when the JVM throws an AbstractMethodError.
> In fact, we have in our application with a tomcat that supports the JDBC 4.2 specification, a driver that is implemented according to the JDBC 4.0 specification, and it is this nuance that made DBCP2 unable to cope with pool cleanup when the removeAbandonedOnBorrow="true" parameter is specified in the pool settings. The only thing I don't understand yet is why the pool didn't perform OnMaintenance cleanup with the specified parameters removeAbandonedTimeout="600" removeAbandonedOnMaintenance="true" logAbandoned="true" minEvictableIdleTimeMillis="30000". Is this a settings for some internal sheduler?
> To reinforce all of the above, I attach the files:
> testcase_PoolableConnectionFactory_1.patch - a testcase for PoolableConnectionFactory.destroyObject, which enlightens the problem.
> TestPoolableConnectionFactory.java - the same file, but in form of the java source file.
> part_of_stacktrace_1.txt - the most important file of all, it contains the part of the stacktrace that is repeated in all connection acquisition errors.
> abandoned_traces_1.txt - all (anonymized) stacktraces from catalina.out, which are related to connection rejection in the database when the response time is exceeded, and transfer to ABANDONED status.
> errors_getting_connection_traces_2_filtered_1.txt - All (anonymized) errors that include Caused by: java.lang.AbstractMethodError: Method com/sybase/jdbc4/jdbc/SybConnection.abort(Ljava/util/concurrent/Executor;)V is abstract.
> errors_getting_connection_traces_1_filtered_1.txt - All (anonymized) errors where we tried to get a new connection from the pool and didn't wait the item.
> part_of_server_xml.txt - (Anonymized) Resources from the conf/server.xml file.
> abandoned_objects_1.txt - List of 18 DefaultPooledObject that appeared in the pool in ABANDONED status in heapdump, and “did not want to be destroyed”.
> abandoned_objects_other_1.txt - Several other connections, from other pools, and 2 connections from the same pool that were involved in the “problem”, in IDLE status, which seem to be holding the load.
> abandoned_objects_query_1.txt - queries for VisualVM , OQL Console tab, which retrieved the previous 2 files.



--
This message was sent by Atlassian Jira
(v8.20.10#820010)