Java APM Agent does not send spans for database queries and error.* document

Victor_C · January 2, 2019, 7:04am

The Java APM Agent does not send spans for database queries and error.* document, but it sends the HTTP request correctly.

I only see one warning in the log but it seems not related to the issue.
[qtp1190035432-17] WARN co.elastic.apm.bci.bytebuddy.ErrorLoggingListener - ERROR on transformation $HttpServletRequest_f5c04b49d0e79
java.lang.IllegalStateException: Cannot resolve type description for $RequestGlobals_f5c04b49d0e41

The dependencies should be up-to-date.
I am using Elastic Java APM 1.1.0, javax.ws.rs 2.0.1, Jetty 9.4.14.v20181114, DBCP 2.5, MySQL connector 8.0.13

I am running with these options:
-javaagent:{workspace}/jars/elastic-apm-agent.jar -Delastic.apm.service_name=my-service -Delastic.apm.server_url=http://{ip}:8200
-Delastic.apm.application_packages=org.example

Thanks!

Eyal_Koren · January 2, 2019, 7:38am

Hi and thanks for using our agent.

You are probably right- this warning doesn't seem to be related and in 1.2.0 we changed it to info level.

Please set -Delastic.apm.log_level=TRACE, maybe we can see something interesting in logs as to why DB queries are not traced.

Some questions for further analysis:
Are you using some asynchronous mechanism so that your DB queries occur on a different thread than the one handling the HTTP request?
Which Java version are you using?
What kind of JDBC APIs are you using that you expect to see (e.g. PreparedStatement, executeBatch etc.)?
What kind of DB error you are expecting to see and don't see

Regardless, note that you better set the elastic.apm.application_packages property to a real list of root packages of your app code, especially since you are using JAX-RS.

Eyal.

Victor_C · January 2, 2019, 9:12am

Hi Eyal, Thanks for replying.

I have added -Delastic.apm.log_level=TRACE, but I don't see any log related to span.

On a side note, I ran the program with the eclipse Jetty plugin (with default config of the plugin) and it successfully send SPAN event like this:
[apm-reporter] DEBUG co.elastic.apm.report.IntakeV2ReportingEventHandler - Receiving SPAN event

Are you using some asynchronous mechanism so that your DB queries occur on a different thread than the one handling the HTTP request?

I don't think so. The Jetty is using QueuedThreadPool.

Which Java version are you using?

java-1.8.0-openjdk-1.8.0.191

What kind of JDBC APIs are you using that you expect to see (e.g. PreparedStatement , executeBatch etc.)?

PreparedStatement.executeQuery() (at org.hibernate.jdbc.AbstractBatcher.getResultSet)

What kind of DB error you are expecting to see and don't see

I actually don't expect to see DB error. By error I meant the all the exceptions thrown in Java.

Victor_C · January 3, 2019, 8:59am

Do you have any idea about where I should look into?

Eyal_Koren · January 3, 2019, 9:25am

Since you seem to be using a supported JDBC implementation, one option is that one of the frameworks you are using is forking from the request handling thread to a different thread, where the DB execution occurs. We currently not support that (we don't correlate such async span to the transaction out of the box), but we have it on our roadmap. If you can check that, e.g. by debugging - this would be very helpful.

I don't think so. The Jetty is using QueuedThreadPool.

I don't know about that, but could be related. For example, if Jetty handles the Servlet Filters in one thread and then executes the actual servlet on a different thread, we may see such behaviour.

Can you elaborate on the eclipse Jetty plugin scenario? What kind of span did you get there? Was it the MySQL/DBCP span you expected?

Victor_C · January 3, 2019, 10:30am

So the eclipse Jetty plugin scenario is that I am running my app in my local machine (Windows) with a different jetty.xml, while other things (like libraries) remains the same.
My production server is in Linux and runs with a different jetty.xml.

I get something like this, which is what I expected:

2019-01-03 14:25:50.292 [qtp206835546-1381] DEBUG co.elastic.apm.impl.ElasticApmTracer - Activating '' 00-ca1b7f160f6765ed7574263f4a38d37e-681d4f87052c7d5f-01 on thread 1381
2019-01-03 14:25:50.299 [qtp206835546-1381] DEBUG co.elastic.apm.impl.ElasticApmTracer - Deactivating 'SELECT' 00-ca1b7f160f6765ed7574263f4a38d37e-681d4f87052c7d5f-01 on thread 1381
2019-01-03 14:25:50.299 [qtp206835546-1381] DEBUG co.elastic.apm.impl.transaction.Span - } endSpan 'SELECT' 00-ca1b7f160f6765ed7574263f4a38d37e-681d4f87052c7d5f-01
2019-01-03 14:25:50.299 [qtp206835546-1381] TRACE co.elastic.apm.impl.transaction.Span - ending span at
java.lang.RuntimeException: this exception is just used to record where the span has been ended from
	at co.elastic.apm.impl.transaction.Span.doEnd(Span.java:97)
	at co.elastic.apm.impl.transaction.AbstractSpan.end(AbstractSpan.java:210)
	at co.elastic.apm.impl.transaction.AbstractSpan.end(AbstractSpan.java:197)
	at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:125)
	at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:186)
	at org.hibernate.loader.Loader.getResultSet(Loader.java:1787)
     ...

Eyal_Koren · January 3, 2019, 12:06pm

So this rules out failure to monitor the DB and increases the suspicion that it has something to do with async execution. Without getting too much into details, can you say what the main differences are between the two jetty.xml versions?

Victor_C · January 4, 2019, 2:36am

There are many differences, I will try to summarize it:

Both using the same ThreadPool setting
Different HTTP serverConnector setting
1 more HTTPS serverConnector with ssl setting etc.
3 handlers (context, default handler and request log handler) is set instead of just WebAppContext
DeploymentManager is added
HashLoginService is added
Also added some logging config

I can provide the details if you wanna see it. Big thanks.

Eyal_Koren · January 6, 2019, 6:51am

Unfortunately, I don't know enough about Jetty...
If possible, just for the analysis, please try to apply the working server connector configurations to the non-working jetty.xml one at a time and see if that makes a difference. I am not suggesting that as a solution, but as a means of isolating the differentiating factor between the working and non-working instances.
If those don't make any difference, maybe the handlers will?
I can't see how the deployment manager can be related, nor the logging config.

system · January 27, 2019, 2:51am

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.