FAIL - DataSource instrumentation on Tomcat using org.apache.tomcat.jdbc.pool.DataSource

[pb00068]

We are trying stagemonitor 0.84 for monitoring tomcat version 8 using org.apache.tomcat.jdbc.pool.DataSource but in debug logging, it says that it fails to instrument the datasource:

2017-10-13 14:48:51,403 | DEBUG | main       | agemonitorByteBuddyTransformer |  |  | Error while creating advice. This usually means that a optional type is not present so this is nothing wo worry about. Error message: org/springframework/http/client/support/InterceptingHttpAccessor
2017-10-13 14:48:51,492 | WARN  | main       | t.StagemonitorClassNameMatcher |  |  | No includes for instrumentation configured. Please set the stagemonitor.instrument.include property.
2017-10-13 14:48:51,698 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | Measurement Session is initialized: [application=Cis] [instance=TestInstance] [host=pbzcislx002.wp.lan]
2017-10-13 14:48:51,740 | INFO  | main       | g.stagemonitor.core.CorePlugin |  |  | Not sending metrics to InfluxDB (url=null, interval=60s)
2017-10-13 14:48:51,741 | INFO  | main       | g.stagemonitor.core.CorePlugin |  |  | Not sending metrics to Elasticsearch (url=[], interval=60s)
2017-10-13 14:48:51,825 | INFO  | main       | emonitor.tracing.TracingPlugin |  |  | No OpenTracing implementation found. Falling back to NoopTracer. This is fine if you just want to use stagemonitor for development, for example with the in-browser-widget. If you want to report your traces to Elasticsearch, add a dependency to stagemonitor-tracing-elasticsearch. If you want to report to Zipkin, add stagemonitor-tracing-zipkin.
2017-10-13 14:48:51,881 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | # stagemonitor status
2017-10-13 14:48:51,882 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | System information: Java 1.8.0_131 (Oracle Corporation) Linux 2.6.18-128.el5
2017-10-13 14:48:51,894 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - Agent attachment
2017-10-13 14:48:51,895 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - CorePlugin (version 0.82.0)
2017-10-13 14:48:51,895 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | FAIL - DataSource instrumentation (No DataSource instrumented)
2017-10-13 14:48:51,895 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | FAIL - Elasticsearch (Elasticsearch is not available)
2017-10-13 14:48:51,895 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - JdbcPlugin (version 0.82.0)
2017-10-13 14:48:51,895 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - JvmPlugin (version 0.82.0)
2017-10-13 14:48:51,896 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - ServletPlugin (version 0.82.0)
2017-10-13 14:48:51,896 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - SoapTracingPlugin (version 0.82.0)
2017-10-13 14:48:51,896 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - TracingPlugin (version 0.82.0)
2017-10-13 14:48:51,897 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | # stagemonitor configuration, listing non-default values:
2017-10-13 14:48:51,898 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | stagemonitor.instrument.jdbc.dataSource.implementations: org.apache.tomcat.jdbc.pool.DataSource, org.apache.t... (source: stagemonitor.properties)
2017-10-13 14:48:51,899 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | stagemonitor.applicationName: Cis (source: stagemonitor.properties)
2017-10-13 14:48:51,899 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | stagemonitor.instanceName: TestInstance (source: stagemonitor.properties)
2017-10-13 14:49:00,853 | INFO  | tartStop-1 | iguration.ConfigurationServlet |  |  | Registering configuration Endpoint /stagemonitor/configuration. You can dynamically change the configuration by issuing a POST request to /stagemonitor/configuration?key=stagemonitor.config.key&value=configValue&stagemonitor.password=password. If the password is not set, dynamically changing the configuration is not available. The password can be omitted if set to an empty string.
2017-10-13 14:49:01,113 | INFO  | tartStop-1 | um.ClientSpanJavaScriptServlet |  |  | built new end user monitoring JavaScript, size=6394 bytes, etag="113823574"
2017-10-13 14:49:01,128 | DEBUG | tartStop-1 | ilter.HttpRequestMonitorFilter |  |  | Instantiating HttpRequestMonitorFilter

The Datasource is defined as following in our conf/server.xml:

 <Resource name="jdbc/TestServer2" auth="Container"
          type="javax.sql.DataSource"
          username="foo" password="secret"   
          driverClassName="com.microsoft.sqlserver.jdbc.SQLServerDriver"
          url="jdbc:sqlserver://ourmachine2:1433;databasename=TestServer2"
          factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
          initialSize="34"/>

It is visible under MBeans -> Catalina -> DataSource and working with our application which uses hibernate to access the persistence. In the stagemonitor we can see the HTTP- and JVM-metrics but not the ones belonging to JDBC.

Here is how we defined stagemonitor.properties:

stagemonitor.instanceName=TestInstance
stagemonitor.applicationName=Cis
stagemonitor.instrument.jdbc.dataSource.implementations=org.apache.tomcat.jdbc.pool.DataSource, org.apache.tomcat.dbcp.dbcp.PoolingDataSource, org.apache.tomcat.jdbc.pool.DataSourceProxy, org.apache.commons.dbcp2.PoolingDataSource, org.apache.commons.dbcp.PoolingDataSource, com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource, com.mchange.v2.c3p0.PoolBackedDataSource, com.mchange.v2.c3p0.ComboPooledDataSource, com.jolbox.bonecp.BoneCPDataSource, snaq.db.DBPoolDataSource, com.zaxxer.hikari.HikariDataSource, org.jboss.jca.adapters.jdbc.WrapperDataSource, org.springframework.jdbc.datasource.AbstractDriverBasedDataSource, org.apache.tomcat.dbcp.dbcp2.BasicDataSource

Any help is welcome, thanks

[felixbarny]

Seems like you are using stagemonitor 0.82.0. This is likely a false positive. Please try 0.84.0 and watch out for logs like:

INFO org.stagemonitor.jdbc.ConnectionMonitoringTransformer - TRANSFORM DataSource org.apache.tomcat.jdbc.pool.DataSource (DefaultConnectionMonitoringTransformer)

[pb00068]

Apologies, our deployer said he installed the latest version. Indeed it was 0.82.0, should have double check this before opening..

[pb00068]

@felixbarny Unfortunately we have the same problem with 0.84.0 too: no JDBC activity is getting monitored.

This is the output:

2017-10-16 09:29:28,814 | DEBUG | main       | agemonitorByteBuddyTransformer |  |  | Error while creating advice. This usually means that an optional type is not present so this is nothing wo worry about. Error message: org/springframework/http/client/support/InterceptingHttpAccessor
2017-10-16 09:29:28,908 | WARN  | main       | t.StagemonitorClassNameMatcher |  |  | No includes for instrumentation configured. Please set the stagemonitor.instrument.include property.
2017-10-16 09:29:29,157 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | Measurement Session is initialized: [application=Cis] [instance=TestInstance] [host=pbzcislx002.wp.lan]
2017-10-16 09:29:29,229 | INFO  | main       | g.stagemonitor.core.CorePlugin |  |  | Not sending metrics to InfluxDB (url=null, interval=60s)
2017-10-16 09:29:29,230 | INFO  | main       | g.stagemonitor.core.CorePlugin |  |  | Not sending metrics to Elasticsearch (url=[], interval=60s)
2017-10-16 09:29:29,314 | INFO  | main       | emonitor.tracing.TracingPlugin |  |  | No OpenTracing implementation found. Falling back to NoopTracer. This is fine if you just want to use stagemonitor for development, for example with the in-browser-widget. If you want to report your traces to Elasticsearch, add a dependency to stagemonitor-tracing-elasticsearch. If you want to report to Zipkin, add stagemonitor-tracing-zipkin.
2017-10-16 09:29:29,363 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | # stagemonitor status
2017-10-16 09:29:29,364 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | System information: Java 1.8.0_131 (Oracle Corporation) Linux 2.6.18-128.el5
2017-10-16 09:29:29,365 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - Agent attachment
2017-10-16 09:29:29,365 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - CorePlugin (version 0.84.0)
2017-10-16 09:29:29,365 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | FAIL - Elasticsearch (Elasticsearch is not available)
2017-10-16 09:29:29,365 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - JdbcPlugin (version 0.84.0)
2017-10-16 09:29:29,366 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - JvmPlugin (version 0.84.0)
2017-10-16 09:29:29,366 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - ServletPlugin (version 0.84.0)
2017-10-16 09:29:29,366 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - SoapTracingPlugin (version 0.84.0)
2017-10-16 09:29:29,366 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - Startup
2017-10-16 09:29:29,366 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | OK   - TracingPlugin (version 0.84.0)
2017-10-16 09:29:29,366 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | # stagemonitor configuration, listing non-default values:
2017-10-16 09:29:29,367 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | stagemonitor.instrument.jdbc.dataSource.implementations: org.apache.tomcat.jdbc.pool.DataSource, org.apache.t... (source: stagemonitor.properties)
2017-10-16 09:29:29,367 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | stagemonitor.applicationName: Cis (source: stagemonitor.properties)
2017-10-16 09:29:29,368 | INFO  | main       | stagemonitor.core.Stagemonitor |  |  | stagemonitor.instanceName: TestInstance (source: stagemonitor.properties)
2017-10-16 09:29:29,832 | INFO  | main       | onnectionMonitoringTransformer |  |  | TRANSFORM DataSource org.apache.tomcat.jdbc.pool.DataSource (DefaultConnectionMonitoringTransformer)
2017-10-16 09:29:29,956 | INFO  | main       | onnectionMonitoringTransformer |  |  | TRANSFORM DataSource org.apache.tomcat.jdbc.pool.DataSourceProxy (DefaultConnectionMonitoringTransformer)
2017-10-16 09:29:38,378 | INFO  | tartStop-1 | iguration.ConfigurationServlet |  |  | Registering configuration Endpoint /stagemonitor/configuration. You can dynamically change the configuration by issuing a POST request to /stagemonitor/configuration?key=stagemonitor.config.key&value=configValue&stagemonitor.password=password. If the password is not set, dynamically changing the configuration is not available. The password can be omitted if set to an empty string.
2017-10-16 09:29:38,686 | INFO  | tartStop-1 | um.ClientSpanJavaScriptServlet |  |  | built new end user monitoring JavaScript, size=6394 bytes, etag="113823574"
2017-10-16 09:29:38,701 | DEBUG | tartStop-1 | ilter.HttpRequestMonitorFilter |  |  | Instantiating HttpRequestMonitorFilter
2017-10-16 09:29:48,175 | INFO  | tartStop-1 | onnectionMonitoringTransformer |  |  | TRANSFORM DataSource org.apache.tomcat.dbcp.dbcp2.BasicDataSource (DefaultConnectionMonitoringTransformer)
2017-10-16 09:29:48,966 | DEBUG | tartStop-1 | agemonitorByteBuddyTransformer |  |  | Error while creating advice. This usually means that an optional type is not present so this is nothing wo worry about. Error message: org/springframework/http/client/support/InterceptingHttpAccessor
2017-10-16 09:29:49,061 | WARN  | tartStop-1 | t.StagemonitorClassNameMatcher |  |  | No includes for instrumentation configured. Please set the stagemonitor.instrument.include property.
2017-10-16 09:29:49,515 | INFO  | tartStop-1 | stagemonitor.core.Stagemonitor |  |  | Measurement Session is initialized: [application=Cis] [instance=TestInstance] [host=pbzcislx002.wp.lan]

N.B.: There are multiple TRANSFORM entries because we have the Datasource mapped twice: https://imgur.com/a/kdhIM

[felixbarny]

Could you debug to see if org.stagemonitor.jdbc.ConnectionMonitor#monitorGetConnection gets invoked?

[pb00068]

Yes, Of course. Will do it when I return from Vacation next week...