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 ***@***.***> 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 <#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?