Span isn't closed if JDBC implementation errors on the getUpdateCount method

[HoveringHalibut]

Describe the bug

The JDBC plugin throws an error and doesn't deactivate and end the span if the JDBC implementation errors on the getUpdateCount method.

                span.getContext()
                    .getDb()
                    // getUpdateCount javadoc indicates that this method should be called only once
                    // however in practice adding this extra call seem to not have noticeable side effects
                    .withAffectedRowsCount(statement.getUpdateCount());

                span.captureException(t)
                    .deactivate()
                    .end();

This admittedly is an edge case where my company's application uses a partial implementation of the JDBC API in RMI connections between services. It doesn't include the getUpdateCount method currently.

Steps to reproduce

1. Find a JDBC driver that doesn't implement getUpdateCount
2. Then call any method that queries the driver
3. See WARN error in logs: 2020-01-23 19:52:36.660 [thread] WARN co.elastic.apm.agent.jdbc.helper.JdbcHelperImpl - Ignored exception
4. All further spans will then fall under the JDBC span that doesn't get closed, causing the transaction to hit the max spans limit

Expected behavior

An error should be logged and the span should be closed.

Debug logs

Click to expand

``` Time | Class | Log Jan 23, 2020 @ 13:52:36.660 | co.elastic.apm.agent.jdbc.helper.JdbcHelperImpl | 2020-01-23 19:52:36.660 [http-apr-8080-exec-9] WARN co.elastic.apm.agent.jdbc.helper.JdbcHelperImpl - Ignored exception Jan 23, 2020 @ 13:52:36.660 | co.elastic.apm.agent.impl.transaction.AbstractSpan | 2020-01-23 19:52:36.660 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - decrement references to 'Cpaas#query' 00-e111478a4e929d0ab905aca8d4e812ba-b38e98da3afb26b9-01 (618fb395) (4) Jan 23, 2020 @ 13:52:36.660 | co.elastic.apm.agent.impl.ElasticApmTracer | 2020-01-23 19:52:36.660 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'Cpaas#query' 00-e111478a4e929d0ab905aca8d4e812ba-b38e98da3afb26b9-01 (618fb395) Jan 23, 2020 @ 13:52:36.660 | co.elastic.apm.agent.impl.ElasticApmTracer | 2020-01-23 19:52:36.660 [http-apr-8080-exec-9] WARN co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating a span ('Cpaas#query' 00-e111478a4e929d0ab905aca8d4e812ba-b38e98da3afb26b9-01 (618fb395)) which is not the currently active span ('/*messages_withstyle*/ Jan 23, 2020 @ 13:52:36.660 | co.elastic.apm.agent.impl.ElasticApmTracer | 2020-01-23 19:52:36.660 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'Cpaas#query' 00-e111478a4e929d0ab905aca8d4e812ba-b38e98da3afb26b9-01 (618fb395) on thread 728 Jan 23, 2020 @ 13:52:36.644 | co.elastic.apm.agent.impl.ElasticApmTracer | 2020-01-23 19:52:36.644 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-e111478a4e929d0ab905aca8d4e812ba-f333510d189a9399-01 (1d4a9d76) on thread 728 Jan 23, 2020 @ 13:52:36.644 | co.elastic.apm.agent.impl.transaction.AbstractSpan | 2020-01-23 19:52:36.644 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to '' 00-e111478a4e929d0ab905aca8d4e812ba-f333510d189a9399-01 (1d4a9d76) (2) Jan 23, 2020 @ 13:52:36.644 | co.elastic.apm.agent.impl.transaction.AbstractSpan | 2020-01-23 19:52:36.644 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.impl.transaction.AbstractSpan - increment references to 'Cpaas#query' 00-e111478a4e929d0ab905aca8d4e812ba-b38e98da3afb26b9-01 (618fb395) (4) Jan 23, 2020 @ 13:52:36.644 | co.elastic.apm.agent.impl.transaction.Span | 2020-01-23 19:52:36.644 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-e111478a4e929d0ab905aca8d4e812ba-f333510d189a9399-01 (1d4a9d76) { Jan 23, 2020 @ 13:52:36.644 | co.elastic.apm.agent.bci.ElasticApmAgent | 2020-01-23 19:52:36.644 [http-apr-8080-exec-9] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation ExecuteUpdateWithQueryInstrumentation: (((name(equals(executeUpdate)) or name(equals(executeLargeUpdate))) and hasParameter(hasTypes(with(0 matches erasure(is(class java.lang.String)))))) and isPublic()) matches public int com.corp.app.AppStatement.executeUpdate(java.lang.String,java.lang.String[]) throws java.sql.SQLException ```

[SylvainJuge]

Thanks a lot for this nice bug report @HoveringHalibut !

I agree it's an edge case, but any faulty implementation would produce a span that is not closed. Actually having JDBC over RMI is quite common on some application servers like Weblogic that use it to expose JDBC connection pools to deployed web applications.

Regarding logging of this error though, given it's likely at every statement execution I'd rather keep it silent (end-user can't really do anything about it anyway), or log it at debug level.

Also, technically this kind of error can happen when calling any part of the JDBC driver, not just this method.

[felixbarny]

Might make sense to not call this method again after it threw an exception.

On Fri 24. Jan 2020 at 09:39 SylvainJuge notifications@github.com wrote:

Thanks a lot for this nice bug report @HoveringHalibut https://github.com/HoveringHalibut !

I agree it's an edge case, but any faulty implementation would produce a span that is not closed. Actually having JDBC over RMI is quite common on some application servers like Weblogic that use it to expose JDBC connection pools to deployed web applications.

Regarding logging of this error though, given it's likely at every statement execution I'd rather keep it silent (end-user can't really do anything about it anyway), or log it at debug level.

Also, technically this kind of error can happen when calling any part of the JDBC driver, not just this method.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/elastic/apm-agent-java/issues/1006?email_source=notifications&email_token=AAQQGCCAPT6GWYTHINSJPPDQ7KSK3A5CNFSM4KLAXOSKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ2DEYI#issuecomment-578040417, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAQQGCHHEDOFL2C2NNVBFBDQ7KSK3ANCNFSM4KLAXOSA .

[eyalkoren]

@HoveringHalibut please download and test the relevant snapshot build artefact of the proposed fix and verify that if fixes the problem.

[HoveringHalibut]

@eyalkoren Thanks for the quick turnaround on this.

I'll run it through our test environment tomorrow.

[eyalkoren]

@HoveringHalibut Did you get the chance to verify the fix?