I am getting java.sql.SQLFeatureNotSupportedException and I can not see the query transaction.

[stLalo]

Describe the bug

I am running APM-agent-java as an agent to my jar file. I am using the JDBC Clickhouse driver to reach my Clickhouse Database. I work with Clojure to do SQL queries into my Database. To create a connection pool to my database I use Hikari CP. My service works perfectly and it reaches the database with no problem, however, the logs of my services are getting out of hand and creating noise in my Filebeat logs.

Steps to reproduce

Steps to reproduce the behavior:

1. Use this config jdbc:clickhouse//localhost:9999
2. Then call 'SELECT first_name, last_name, email FROM customer WHERE _id='1234ABC''
3. Then do return the data to the UI
4. See error

Expected behavior

I am expecting to see the SQL query in the APM transaction and not seeing the logs about the SQL feature not supported

Debug logs

2020-02-07 17:59:07.919 [XNIO-2 task-7] WARN co.elastic.apm.agent.jdbc.helper.JdbcHelperImpl - Ignored exception
java.sql.SQLFeatureNotSupportedException
	at com.github.housepower.jdbc.wrapper.SQLConnection.getMetaData(SQLConnection.java:69)
	at co.elastic.apm.agent.jdbc.helper.JdbcHelperImpl.getConnectionMetaData(JdbcHelperImpl.java:124)
	at co.elastic.apm.agent.jdbc.helper.JdbcHelperImpl.createJdbcSpan(JdbcHelperImpl.java:74)
	at com.github.housepower.jdbc.statement.ClickHouseStatement.execute(ClickHouseStatement.java:29)
	at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:164)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:185)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
	at sun.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at clojure.lang.Reflector.invokeMatchingMethod(Reflector.java:167)
	at clojure.lang.Reflector.invokeNoArgInstanceMember(Reflector.java:438)

I know that using Clickhouse and an open-source adapter that could potentially cause this issue. However, is there a way to turn this off at least in the logs or fix it?

[SylvainJuge]

Hi @stLalo , thanks a lot for reporting this.

In this case, apart from the verbose error logging, you should not have have any other side-effects on the application itself, it only affects what the agent is able to monitor at JDBC level. Can you please confirm that ?

We recently had a very similar error with a JDBC driver that does not implement Statement.getUpdateCount() and it has been fixed with #1008 (not yet released, but likely in a few days), thus I feel that fixing this in a very similar way would be a good option to prevent having those recurring error messages every time the agent tries to get connection metadata.

[stLalo]

@SylvainJuge Indeed, there are no side-effects in the actual application, per se. It works fine and there are still some APM metrics sent to Elasticsearch.

[stLalo]

I found this on my logs today

2020-02-12 03:05:49.525 [qtp1322237527-140] WARN co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating a span ('GET /pipelines' 00-acc575d90f13aa29d543c4841f33d33e-c442e13a300d5018-01 (3f38fc47)) which is not the currently active span ('SELECT FROM user' 00-acc575d90f13aa29d543c4841f33d33e-b70397ae207824b4-01 (1257dcd9)). This can happen when not properly deactivating a previous span. 2020-02-12 03:05:49.534 [qtp1322237527-78] WARN co.elastic.apm.agent.jdbc.helper.JdbcHelperImpl - Ignored exception java.sql.SQLFeatureNotSupportedException

[SylvainJuge]

Thanks for this update.

Agent keeps track of which span is currently active on current thread, most of the time a span is kept active for it's whole duration (while SQL query is executing for example), and thus activated when starting span, and deactivated when ending span.

However, if there is any bug in the agent plugins, like in your case an unexpected exception has been thrown while using JDBC instrumentation, this state is not consistent. In other words, it's very likely a side effect of the issue you've already reported.

[felixbarny]

let's make sure we deactivate and end the span in a finally block