JVM crash with Java 7 + Agent 1.3.0 #458

Aketzu · 2019-01-29T09:27:36Z

Describe the bug
We updated apm agent to 1.3.0 yesterday and then after about 18 hours two instances got JVM crash which look pretty similar.

# A fatal error has been detected by the Java Runtime Environment:
#  SIGSEGV (0xb) at pc=0x000000008fb018d8, pid=122146, tid=140043922573056

Both are using Java 7 (7.0_75 and 7.0_141). One is running on Glassfish 4.0 and the other Payara 4.1.1.171.1.

Debug logs

Current thread (0x00007f7ee0354800):  JavaThread "apm-reporter" daemon 

Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  0x000000008fb018d8

Also there is co.elastic.apm.agent.report.serialize.DslJsonSerializer::sanitizeTagKey in both compilation events.

Full logs:
hs_err_pid122146.log
hs_err_pid43918.log

This might be related to #444

The text was updated successfully, but these errors were encountered:

felixbarny · 2019-01-29T10:19:09Z

Here is a similar report: https://discuss.elastic.co/t/apm-agent-for-java-is-causing-system-crashes/165211

It also crashes in the apm-reporter thread and has a co.elastic.apm.agent.report.serialize.DslJsonSerializer::sanitizeTagKey compilation event.

Is it possible for you to update to the latest Java 1.7 update release?

felixbarny · 2019-01-29T10:39:18Z

We have a theory what's going on. We have recently found a bug in DslJsonSerializer#replace.

This method is called from sanitizeTagKey. The JIT has probably inlined the replace method intosanitizeTagKey and has compiled the method with an optimization, removing the bounds checks. If accessing an invalid index after the compilation, the OS throws a segfault which crashes the application.

We hope that when merging in the fix, the error goes away. In the meantime, could you check if you are using any of the disallowed characters (., *, \) as part of a tag name in the public API? For example ElasticApm.currentSpan().addTag("foo.bar", "baz"); and replace it with an underscore?

TeroPihlaja · 2019-01-29T11:23:30Z

We don't have any Elastic APM specific code in our application package.

Here's the tail of the Elastic APM agent log from the time of the crash. Notice descending timestamps.

This is from the same service as hs_err_pid43918.log

Crash happened at "Tue Jan 29 01:35:06 2019" according to logs.

2019-01-29 01:35:06.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 77981)
2019-01-29 01:35:01.856 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77980)
2019-01-29 01:35:01.856 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-4f8783aa341168b2c74ffde92525c149-602b037dce03be72-01
2019-01-29 01:35:01.856 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-4f8783aa341168b2c74ffde92525c149-602b037dce03be72-01 on thread 27
2019-01-29 01:35:01.847 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77979)
2019-01-29 01:35:01.846 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:35:01.843 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-4f8783aa341168b2c74ffde92525c149-7461333166643dbc-01
2019-01-29 01:35:01.843 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-4f8783aa341168b2c74ffde92525c149-7461333166643dbc-01 on thread 27
2019-01-29 01:35:01.842 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-4f8783aa341168b2c74ffde92525c149-7461333166643dbc-01 on thread 27
2019-01-29 01:35:01.842 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-4f8783aa341168b2c74ffde92525c149-7461333166643dbc-01 {
2019-01-29 01:35:01.842 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:35:01.842 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77978)
2019-01-29 01:35:01.842 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-4f8783aa341168b2c74ffde92525c149-8395359a7c3875b6-01
2019-01-29 01:35:01.841 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-4f8783aa341168b2c74ffde92525c149-8395359a7c3875b6-01 on thread 27
2019-01-29 01:35:01.841 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-4f8783aa341168b2c74ffde92525c149-8395359a7c3875b6-01 on thread 27
2019-01-29 01:35:01.841 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-4f8783aa341168b2c74ffde92525c149-8395359a7c3875b6-01 {
2019-01-29 01:35:01.839 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-4f8783aa341168b2c74ffde92525c149-602b037dce03be72-01 on thread 27
2019-01-29 01:35:01.838 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-4f8783aa341168b2c74ffde92525c149-602b037dce03be72-01 {
2019-01-29 01:34:37.536 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 5915 uncompressed 1755 compressed bytes
2019-01-29 01:34:37.536 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77977)
2019-01-29 01:34:37.535 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:34:36.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 77976)
2019-01-29 01:34:31.097 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77975)
2019-01-29 01:34:31.097 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-cd8fc47d969b04ac14ec842a888993b7-e83ae055dee4cebc-01
2019-01-29 01:34:31.097 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-cd8fc47d969b04ac14ec842a888993b7-e83ae055dee4cebc-01 on thread 92
2019-01-29 01:34:31.084 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77974)
2019-01-29 01:34:31.080 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-cd8fc47d969b04ac14ec842a888993b7-b7aac2dfb9347855-01
2019-01-29 01:34:31.079 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-cd8fc47d969b04ac14ec842a888993b7-b7aac2dfb9347855-01 on thread 92
2019-01-29 01:34:31.079 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-cd8fc47d969b04ac14ec842a888993b7-b7aac2dfb9347855-01 on thread 92
2019-01-29 01:34:31.079 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-cd8fc47d969b04ac14ec842a888993b7-b7aac2dfb9347855-01 {
2019-01-29 01:34:31.077 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77973)
2019-01-29 01:34:31.076 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-cd8fc47d969b04ac14ec842a888993b7-674e40c8ffe5c661-01
2019-01-29 01:34:31.076 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-cd8fc47d969b04ac14ec842a888993b7-674e40c8ffe5c661-01 on thread 92
2019-01-29 01:34:31.076 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-cd8fc47d969b04ac14ec842a888993b7-674e40c8ffe5c661-01 on thread 92
2019-01-29 01:34:31.076 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-cd8fc47d969b04ac14ec842a888993b7-674e40c8ffe5c661-01 {
2019-01-29 01:34:31.074 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-cd8fc47d969b04ac14ec842a888993b7-e83ae055dee4cebc-01 on thread 92
2019-01-29 01:34:31.074 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-cd8fc47d969b04ac14ec842a888993b7-e83ae055dee4cebc-01 {
2019-01-29 01:34:27.541 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77972)
2019-01-29 01:34:27.541 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-35e0c13588bc31584926a217caa9740b-ef091fb0414afcb1-01
2019-01-29 01:34:27.541 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-35e0c13588bc31584926a217caa9740b-ef091fb0414afcb1-01 on thread 27
2019-01-29 01:34:27.535 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77971)
2019-01-29 01:34:27.535 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77970)
2019-01-29 01:34:27.535 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:34:27.532 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-35e0c13588bc31584926a217caa9740b-4296402f99812412-01
2019-01-29 01:34:27.532 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-35e0c13588bc31584926a217caa9740b-4296402f99812412-01 on thread 27
2019-01-29 01:34:27.531 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-35e0c13588bc31584926a217caa9740b-4296402f99812412-01 on thread 27
2019-01-29 01:34:27.531 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-35e0c13588bc31584926a217caa9740b-4296402f99812412-01 {
2019-01-29 01:34:27.531 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-35e0c13588bc31584926a217caa9740b-b26122d1721941c1-01
2019-01-29 01:34:27.531 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-35e0c13588bc31584926a217caa9740b-b26122d1721941c1-01 on thread 27
2019-01-29 01:34:27.530 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:34:27.530 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77969)
2019-01-29 01:34:27.530 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-35e0c13588bc31584926a217caa9740b-b26122d1721941c1-01 on thread 27
2019-01-29 01:34:27.530 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-35e0c13588bc31584926a217caa9740b-b26122d1721941c1-01 {
2019-01-29 01:34:27.530 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-35e0c13588bc31584926a217caa9740b-7832de6548373798-01
2019-01-29 01:34:27.530 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-35e0c13588bc31584926a217caa9740b-7832de6548373798-01 on thread 27
2019-01-29 01:34:27.529 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-35e0c13588bc31584926a217caa9740b-7832de6548373798-01 on thread 27
2019-01-29 01:34:27.529 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-35e0c13588bc31584926a217caa9740b-7832de6548373798-01 {
2019-01-29 01:34:27.527 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-35e0c13588bc31584926a217caa9740b-ef091fb0414afcb1-01 on thread 27
2019-01-29 01:34:27.527 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-35e0c13588bc31584926a217caa9740b-ef091fb0414afcb1-01 {
2019-01-29 01:34:26.750 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 5756 uncompressed 1641 compressed bytes
2019-01-29 01:34:26.749 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77968)
2019-01-29 01:34:26.749 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:34:18.595 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77967)
2019-01-29 01:34:18.594 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'ExtendedHealthCheckServlet#doGet' 00-6da5790b4c9fca7d71904ce6068d65b4-210325d102ea0793-01
2019-01-29 01:34:18.594 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'ExtendedHealthCheckServlet#doGet' 00-6da5790b4c9fca7d71904ce6068d65b4-210325d102ea0793-01 on thread 92
2019-01-29 01:34:18.592 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77966)
2019-01-29 01:34:18.591 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-6da5790b4c9fca7d71904ce6068d65b4-14fe93140d88cb02-01
2019-01-29 01:34:18.591 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-6da5790b4c9fca7d71904ce6068d65b4-14fe93140d88cb02-01 on thread 92
2019-01-29 01:34:18.591 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-6da5790b4c9fca7d71904ce6068d65b4-14fe93140d88cb02-01 on thread 92
2019-01-29 01:34:18.590 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-6da5790b4c9fca7d71904ce6068d65b4-14fe93140d88cb02-01 {
2019-01-29 01:34:18.585 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-6da5790b4c9fca7d71904ce6068d65b4-210325d102ea0793-01 on thread 92
2019-01-29 01:34:18.585 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-6da5790b4c9fca7d71904ce6068d65b4-210325d102ea0793-01 {
2019-01-29 01:34:17.373 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77965)
2019-01-29 01:34:17.373 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'ExtendedHealthCheckServlet#doGet' 00-d20596a9c7ca602e51a7ee1caa05565c-9826621dcbf1e887-01
2019-01-29 01:34:17.373 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'ExtendedHealthCheckServlet#doGet' 00-d20596a9c7ca602e51a7ee1caa05565c-9826621dcbf1e887-01 on thread 27
2019-01-29 01:34:17.372 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77964)
2019-01-29 01:34:17.371 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-d20596a9c7ca602e51a7ee1caa05565c-b0badc1b7624c382-01
2019-01-29 01:34:17.371 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-d20596a9c7ca602e51a7ee1caa05565c-b0badc1b7624c382-01 on thread 27
2019-01-29 01:34:17.371 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-d20596a9c7ca602e51a7ee1caa05565c-b0badc1b7624c382-01 on thread 27
2019-01-29 01:34:17.370 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-d20596a9c7ca602e51a7ee1caa05565c-b0badc1b7624c382-01 {
2019-01-29 01:34:17.366 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-d20596a9c7ca602e51a7ee1caa05565c-9826621dcbf1e887-01 on thread 27
2019-01-29 01:34:17.366 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-d20596a9c7ca602e51a7ee1caa05565c-9826621dcbf1e887-01 {
2019-01-29 01:34:16.757 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77963)
2019-01-29 01:34:16.757 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-dfbe7959c26a298f6cef00ae5e7a88dc-5e42ceda60479f93-01
2019-01-29 01:34:16.757 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-dfbe7959c26a298f6cef00ae5e7a88dc-5e42ceda60479f93-01 on thread 92
2019-01-29 01:34:16.749 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77962)
2019-01-29 01:34:16.749 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77961)
2019-01-29 01:34:16.749 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:34:16.747 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-dfbe7959c26a298f6cef00ae5e7a88dc-690a8e82901732ce-01
2019-01-29 01:34:16.747 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-dfbe7959c26a298f6cef00ae5e7a88dc-690a8e82901732ce-01 on thread 92
2019-01-29 01:34:16.747 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-690a8e82901732ce-01 on thread 92
2019-01-29 01:34:16.747 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-690a8e82901732ce-01 {
2019-01-29 01:34:16.746 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-dfbe7959c26a298f6cef00ae5e7a88dc-3cb6349764ad34ba-01
2019-01-29 01:34:16.746 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-dfbe7959c26a298f6cef00ae5e7a88dc-3cb6349764ad34ba-01 on thread 92
2019-01-29 01:34:16.746 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-3cb6349764ad34ba-01 on thread 92
2019-01-29 01:34:16.746 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:34:16.746 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-3cb6349764ad34ba-01 {
2019-01-29 01:34:16.746 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77960)
2019-01-29 01:34:16.746 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-dfbe7959c26a298f6cef00ae5e7a88dc-1956772a34d569b4-01
2019-01-29 01:34:16.746 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-dfbe7959c26a298f6cef00ae5e7a88dc-1956772a34d569b4-01 on thread 92
2019-01-29 01:34:16.745 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-1956772a34d569b4-01 on thread 92
2019-01-29 01:34:16.745 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-1956772a34d569b4-01 {
2019-01-29 01:34:16.743 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-5e42ceda60479f93-01 on thread 92
2019-01-29 01:34:16.743 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-dfbe7959c26a298f6cef00ae5e7a88dc-5e42ceda60479f93-01 {
2019-01-29 01:34:07.094 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 6227 uncompressed 1791 compressed bytes
2019-01-29 01:34:07.093 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77959)
2019-01-29 01:34:07.093 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:34:06.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 77958)
2019-01-29 01:34:04.868 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77957)
2019-01-29 01:34:04.867 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-6bd9bb6621a876ada9a979a60e14bc44-d53637401e741145-01
2019-01-29 01:34:04.867 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-6bd9bb6621a876ada9a979a60e14bc44-d53637401e741145-01 on thread 26
2019-01-29 01:34:04.856 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77956)
2019-01-29 01:34:04.855 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-6bd9bb6621a876ada9a979a60e14bc44-2b840e72e079aa04-01
2019-01-29 01:34:04.855 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-6bd9bb6621a876ada9a979a60e14bc44-2b840e72e079aa04-01 on thread 26
2019-01-29 01:34:04.855 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-6bd9bb6621a876ada9a979a60e14bc44-2b840e72e079aa04-01 on thread 26
2019-01-29 01:34:04.855 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-6bd9bb6621a876ada9a979a60e14bc44-2b840e72e079aa04-01 {
2019-01-29 01:34:04.855 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77955)
2019-01-29 01:34:04.855 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-6bd9bb6621a876ada9a979a60e14bc44-0ae4435e7a6aa843-01
2019-01-29 01:34:04.855 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-6bd9bb6621a876ada9a979a60e14bc44-0ae4435e7a6aa843-01 on thread 26
2019-01-29 01:34:04.854 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-6bd9bb6621a876ada9a979a60e14bc44-0ae4435e7a6aa843-01 on thread 26
2019-01-29 01:34:04.854 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77954)
2019-01-29 01:34:04.854 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-6bd9bb6621a876ada9a979a60e14bc44-0ae4435e7a6aa843-01 {
2019-01-29 01:34:04.854 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-6bd9bb6621a876ada9a979a60e14bc44-13c4e66e42ee1e08-01
2019-01-29 01:34:04.854 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-6bd9bb6621a876ada9a979a60e14bc44-13c4e66e42ee1e08-01 on thread 26
2019-01-29 01:34:04.853 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-6bd9bb6621a876ada9a979a60e14bc44-13c4e66e42ee1e08-01 on thread 26
2019-01-29 01:34:04.853 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-6bd9bb6621a876ada9a979a60e14bc44-13c4e66e42ee1e08-01 {
2019-01-29 01:34:04.851 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-6bd9bb6621a876ada9a979a60e14bc44-d53637401e741145-01 on thread 26
2019-01-29 01:34:04.851 [http-listener-1(1)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-6bd9bb6621a876ada9a979a60e14bc44-d53637401e741145-01 {
2019-01-29 01:33:57.112 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77953)
2019-01-29 01:33:57.112 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-1455e192a5a25e08ef4e446bb54d2e66-4b46a9e4ec5e4566-01
2019-01-29 01:33:57.112 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-1455e192a5a25e08ef4e446bb54d2e66-4b46a9e4ec5e4566-01 on thread 92
2019-01-29 01:33:57.100 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77952)
2019-01-29 01:33:57.096 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-1455e192a5a25e08ef4e446bb54d2e66-290eb6b44dabaade-01
2019-01-29 01:33:57.096 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-1455e192a5a25e08ef4e446bb54d2e66-290eb6b44dabaade-01 on thread 92
2019-01-29 01:33:57.094 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77951)
2019-01-29 01:33:57.093 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:33:57.093 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-1455e192a5a25e08ef4e446bb54d2e66-290eb6b44dabaade-01 on thread 92
2019-01-29 01:33:57.093 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-1455e192a5a25e08ef4e446bb54d2e66-290eb6b44dabaade-01 {
2019-01-29 01:33:57.092 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-1455e192a5a25e08ef4e446bb54d2e66-6e350242ba678ee0-01
2019-01-29 01:33:57.092 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-1455e192a5a25e08ef4e446bb54d2e66-6e350242ba678ee0-01 on thread 92
2019-01-29 01:33:57.092 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-1455e192a5a25e08ef4e446bb54d2e66-6e350242ba678ee0-01 on thread 92
2019-01-29 01:33:57.092 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-1455e192a5a25e08ef4e446bb54d2e66-6e350242ba678ee0-01 {
2019-01-29 01:33:57.091 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:33:57.091 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77950)
2019-01-29 01:33:57.091 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-1455e192a5a25e08ef4e446bb54d2e66-f1cf56434eeb8f18-01
2019-01-29 01:33:57.090 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-1455e192a5a25e08ef4e446bb54d2e66-f1cf56434eeb8f18-01 on thread 92
2019-01-29 01:33:57.090 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-1455e192a5a25e08ef4e446bb54d2e66-f1cf56434eeb8f18-01 on thread 92
2019-01-29 01:33:57.090 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-1455e192a5a25e08ef4e446bb54d2e66-f1cf56434eeb8f18-01 {
2019-01-29 01:33:57.088 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-1455e192a5a25e08ef4e446bb54d2e66-4b46a9e4ec5e4566-01 on thread 92
2019-01-29 01:33:57.088 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-1455e192a5a25e08ef4e446bb54d2e66-4b46a9e4ec5e4566-01 {
2019-01-29 01:33:46.844 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1366 uncompressed 573 compressed bytes
2019-01-29 01:33:46.844 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77949)
2019-01-29 01:33:46.843 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:33:36.843 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:33:36.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:33:36.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 77948)
2019-01-29 01:33:33.458 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 4955 uncompressed 1408 compressed bytes
2019-01-29 01:33:33.457 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77947)
2019-01-29 01:33:33.457 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:33:27.034 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77946)
2019-01-29 01:33:27.033 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-262cbc10e7ce6b69a5559f88e4db6db4-879ac0e034a960c4-01
2019-01-29 01:33:27.033 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-262cbc10e7ce6b69a5559f88e4db6db4-879ac0e034a960c4-01 on thread 27
2019-01-29 01:33:27.028 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77945)
2019-01-29 01:33:27.028 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77944)
2019-01-29 01:33:27.021 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-262cbc10e7ce6b69a5559f88e4db6db4-8d45f66ef8bc9d35-01
2019-01-29 01:33:27.021 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-262cbc10e7ce6b69a5559f88e4db6db4-8d45f66ef8bc9d35-01 on thread 27
2019-01-29 01:33:27.021 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-262cbc10e7ce6b69a5559f88e4db6db4-8d45f66ef8bc9d35-01 on thread 27
2019-01-29 01:33:27.021 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-262cbc10e7ce6b69a5559f88e4db6db4-8d45f66ef8bc9d35-01 {
2019-01-29 01:33:27.020 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-262cbc10e7ce6b69a5559f88e4db6db4-cf16862956fe07a1-01
2019-01-29 01:33:27.020 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-262cbc10e7ce6b69a5559f88e4db6db4-cf16862956fe07a1-01 on thread 27
2019-01-29 01:33:27.020 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-262cbc10e7ce6b69a5559f88e4db6db4-cf16862956fe07a1-01 on thread 27
2019-01-29 01:33:27.020 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-262cbc10e7ce6b69a5559f88e4db6db4-cf16862956fe07a1-01 {
2019-01-29 01:33:27.018 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-262cbc10e7ce6b69a5559f88e4db6db4-879ac0e034a960c4-01 on thread 27
2019-01-29 01:33:27.018 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-262cbc10e7ce6b69a5559f88e4db6db4-879ac0e034a960c4-01 {
2019-01-29 01:33:23.474 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77943)
2019-01-29 01:33:23.474 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-dcec3f46fa47302956b2eb8ae8b4eec8-819ca75787aae819-01
2019-01-29 01:33:23.474 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-dcec3f46fa47302956b2eb8ae8b4eec8-819ca75787aae819-01 on thread 92
2019-01-29 01:33:23.460 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77942)
2019-01-29 01:33:23.460 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-dcec3f46fa47302956b2eb8ae8b4eec8-b238c62a6aafc46e-01
2019-01-29 01:33:23.460 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-dcec3f46fa47302956b2eb8ae8b4eec8-b238c62a6aafc46e-01 on thread 92
2019-01-29 01:33:23.458 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77941)
2019-01-29 01:33:23.457 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:33:23.456 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-b238c62a6aafc46e-01 on thread 92
2019-01-29 01:33:23.456 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-b238c62a6aafc46e-01 {
2019-01-29 01:33:23.456 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-dcec3f46fa47302956b2eb8ae8b4eec8-53b17d3127059a2e-01
2019-01-29 01:33:23.456 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-dcec3f46fa47302956b2eb8ae8b4eec8-53b17d3127059a2e-01 on thread 92
2019-01-29 01:33:23.455 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-53b17d3127059a2e-01 on thread 92
2019-01-29 01:33:23.455 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-53b17d3127059a2e-01 {
2019-01-29 01:33:23.454 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:33:23.454 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77940)
2019-01-29 01:33:23.454 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-dcec3f46fa47302956b2eb8ae8b4eec8-29bbece25b08d2bb-01
2019-01-29 01:33:23.454 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-dcec3f46fa47302956b2eb8ae8b4eec8-29bbece25b08d2bb-01 on thread 92
2019-01-29 01:33:23.453 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-29bbece25b08d2bb-01 on thread 92
2019-01-29 01:33:23.453 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-29bbece25b08d2bb-01 {
2019-01-29 01:33:23.451 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-819ca75787aae819-01 on thread 92
2019-01-29 01:33:23.451 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-dcec3f46fa47302956b2eb8ae8b4eec8-819ca75787aae819-01 {
2019-01-29 01:33:16.844 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 3800 uncompressed 1560 compressed bytes
2019-01-29 01:33:16.843 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77939)
2019-01-29 01:33:16.843 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:33:12.592 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77938)
2019-01-29 01:33:12.592 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-3f349f162ffce68b2ab1bfe08cdf957f-699436043a674951-01
2019-01-29 01:33:12.592 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-3f349f162ffce68b2ab1bfe08cdf957f-699436043a674951-01 on thread 92
2019-01-29 01:33:12.577 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77937)
2019-01-29 01:33:12.577 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-3f349f162ffce68b2ab1bfe08cdf957f-64236226e6671f36-01
2019-01-29 01:33:12.577 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-3f349f162ffce68b2ab1bfe08cdf957f-64236226e6671f36-01 on thread 92
2019-01-29 01:33:12.577 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-3f349f162ffce68b2ab1bfe08cdf957f-64236226e6671f36-01 on thread 92
2019-01-29 01:33:12.577 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-3f349f162ffce68b2ab1bfe08cdf957f-64236226e6671f36-01 {
2019-01-29 01:33:12.576 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77936)
2019-01-29 01:33:12.576 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-3f349f162ffce68b2ab1bfe08cdf957f-ed10ca739e928a7c-01
2019-01-29 01:33:12.576 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-3f349f162ffce68b2ab1bfe08cdf957f-ed10ca739e928a7c-01 on thread 92
2019-01-29 01:33:12.575 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-3f349f162ffce68b2ab1bfe08cdf957f-ed10ca739e928a7c-01 on thread 92
2019-01-29 01:33:12.575 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-3f349f162ffce68b2ab1bfe08cdf957f-ed10ca739e928a7c-01 {
2019-01-29 01:33:12.575 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77935)
2019-01-29 01:33:12.575 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-3f349f162ffce68b2ab1bfe08cdf957f-620cb65f511fdd64-01
2019-01-29 01:33:12.575 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-3f349f162ffce68b2ab1bfe08cdf957f-620cb65f511fdd64-01 on thread 92
2019-01-29 01:33:12.574 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-3f349f162ffce68b2ab1bfe08cdf957f-620cb65f511fdd64-01 on thread 92
2019-01-29 01:33:12.574 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-3f349f162ffce68b2ab1bfe08cdf957f-620cb65f511fdd64-01 {
2019-01-29 01:33:12.572 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-3f349f162ffce68b2ab1bfe08cdf957f-699436043a674951-01 on thread 92
2019-01-29 01:33:12.571 [http-listener-1(4)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-3f349f162ffce68b2ab1bfe08cdf957f-699436043a674951-01 {
2019-01-29 01:33:06.843 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:33:06.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:33:06.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 77934)
2019-01-29 01:33:02.113 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 5266 uncompressed 1437 compressed bytes
2019-01-29 01:33:02.113 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77933)
2019-01-29 01:33:02.113 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:32:59.882 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77932)
2019-01-29 01:32:59.881 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-c13a4c990aac4fa9919787c1f73f3543-363f35dce7a99357-01
2019-01-29 01:32:59.881 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-c13a4c990aac4fa9919787c1f73f3543-363f35dce7a99357-01 on thread 46
2019-01-29 01:32:59.872 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77931)
2019-01-29 01:32:59.872 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-c13a4c990aac4fa9919787c1f73f3543-f8298b603ee5a6e8-01
2019-01-29 01:32:59.872 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-c13a4c990aac4fa9919787c1f73f3543-f8298b603ee5a6e8-01 on thread 46
2019-01-29 01:32:59.872 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-c13a4c990aac4fa9919787c1f73f3543-f8298b603ee5a6e8-01 on thread 46
2019-01-29 01:32:59.872 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-c13a4c990aac4fa9919787c1f73f3543-f8298b603ee5a6e8-01 {
2019-01-29 01:32:59.871 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77930)
2019-01-29 01:32:59.871 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-c13a4c990aac4fa9919787c1f73f3543-bd0b0768a4f3fabc-01
2019-01-29 01:32:59.871 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-c13a4c990aac4fa9919787c1f73f3543-bd0b0768a4f3fabc-01 on thread 46
2019-01-29 01:32:59.871 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77929)
2019-01-29 01:32:59.871 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-c13a4c990aac4fa9919787c1f73f3543-bd0b0768a4f3fabc-01 on thread 46
2019-01-29 01:32:59.871 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-c13a4c990aac4fa9919787c1f73f3543-bd0b0768a4f3fabc-01 {
2019-01-29 01:32:59.870 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-c13a4c990aac4fa9919787c1f73f3543-4f15ae5c28233863-01
2019-01-29 01:32:59.870 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-c13a4c990aac4fa9919787c1f73f3543-4f15ae5c28233863-01 on thread 46
2019-01-29 01:32:59.869 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-c13a4c990aac4fa9919787c1f73f3543-4f15ae5c28233863-01 on thread 46
2019-01-29 01:32:59.869 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-c13a4c990aac4fa9919787c1f73f3543-4f15ae5c28233863-01 {
2019-01-29 01:32:59.867 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-c13a4c990aac4fa9919787c1f73f3543-363f35dce7a99357-01 on thread 46
2019-01-29 01:32:59.867 [http-listener-1(3)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-c13a4c990aac4fa9919787c1f73f3543-363f35dce7a99357-01 {
2019-01-29 01:32:52.122 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving TRANSACTION event (sequence 77928)
2019-01-29 01:32:52.122 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - } endTransaction 'LPRestService#heartbeat' 00-8a7cdc84249e2bf062c07b983e782a80-1946ddd1cd6efad6-01
2019-01-29 01:32:52.122 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'LPRestService#heartbeat' 00-8a7cdc84249e2bf062c07b983e782a80-1946ddd1cd6efad6-01 on thread 27
2019-01-29 01:32:52.113 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77927)
2019-01-29 01:32:52.113 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77926)
2019-01-29 01:32:52.112 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:32:52.111 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-8a7cdc84249e2bf062c07b983e782a80-cb3b1019456c3253-01
2019-01-29 01:32:52.111 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-8a7cdc84249e2bf062c07b983e782a80-cb3b1019456c3253-01 on thread 27
2019-01-29 01:32:52.111 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-8a7cdc84249e2bf062c07b983e782a80-cb3b1019456c3253-01 on thread 27
2019-01-29 01:32:52.111 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-8a7cdc84249e2bf062c07b983e782a80-cb3b1019456c3253-01 {
2019-01-29 01:32:52.110 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-8a7cdc84249e2bf062c07b983e782a80-f90af10219cb7e47-01
2019-01-29 01:32:52.110 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-8a7cdc84249e2bf062c07b983e782a80-f90af10219cb7e47-01 on thread 27
2019-01-29 01:32:52.109 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-8a7cdc84249e2bf062c07b983e782a80-f90af10219cb7e47-01 on thread 27
2019-01-29 01:32:52.109 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-8a7cdc84249e2bf062c07b983e782a80-f90af10219cb7e47-01 {
2019-01-29 01:32:52.109 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:32:52.109 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving SPAN event (sequence 77925)
2019-01-29 01:32:52.109 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - } endSpan 'SELECT' 00-8a7cdc84249e2bf062c07b983e782a80-429db3c3d18dd6ce-01
2019-01-29 01:32:52.109 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating 'SELECT' 00-8a7cdc84249e2bf062c07b983e782a80-429db3c3d18dd6ce-01 on thread 27
2019-01-29 01:32:52.108 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-8a7cdc84249e2bf062c07b983e782a80-429db3c3d18dd6ce-01 on thread 27
2019-01-29 01:32:52.108 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.transaction.Span - startSpan '' 00-8a7cdc84249e2bf062c07b983e782a80-429db3c3d18dd6ce-01 {
2019-01-29 01:32:52.106 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - Activating '' 00-8a7cdc84249e2bf062c07b983e782a80-1946ddd1cd6efad6-01 on thread 27
2019-01-29 01:32:52.106 [http-listener-1(2)] DEBUG co.elastic.apm.agent.impl.ElasticApmTracer - startTransaction '' 00-8a7cdc84249e2bf062c07b983e782a80-1946ddd1cd6efad6-01 {
2019-01-29 01:32:46.846 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1366 uncompressed 572 compressed bytes
2019-01-29 01:32:46.845 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77924)
2019-01-29 01:32:46.845 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2019-01-29 01:32:36.845 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2019-01-29 01:32:36.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://dockdock.lan.vilant.com:8200/intake/v2/events
2019-01-29 01:32:36.841 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 77923)
2019-01-29 01:32:27.270 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 8185 uncompressed 1879 compressed bytes
2019-01-29 01:32:27.269 [apm-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 77922)
2019-01-29 01:32:27.269 [apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred

Aketzu · 2019-01-29T12:15:22Z

I updated one host to JDK 7u211. Didn't want to update the other one yet. And also as Tero said, I don't remember us having any APM-specific code in apps.
Is e.g. HTTP request URL included in those sanitized parts?

Aketzu · 2019-01-30T05:15:48Z

And crashed again with 7u211

hs_err_pid71440.log

Works almost like clockwork...

elapsed time: 50011 seconds
elapsed time: 50013 seconds (0d 13h 53m 33s)
elapsed time: 49980 seconds (0d 13h 53m 0s)

Aketzu · 2019-01-30T05:47:39Z

Hmm... There might be a second failure scenario, infinite CPU loop.

Second app (with older JDK) has now hung up twice in a row. Hangs seem to happen after 50000 seconds or so uptime. Both times htop showed 200% CPU usage. There seems to be two threads stuck.

jstack shows lots of BLOCKED threads and a few active (all having same stack trace)

Thread 24784: (state = IN_NATIVE)
 - java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) @bci=0 (Compiled frame; information may be imprecise)
 - java.net.SocketInputStream.read(byte[], int, int, int) @bci=87, line=152 (Compiled frame)
 - java.net.SocketInputStream.read(byte[], int, int) @bci=11, line=122 (Interpreted frame)
 - java.io.BufferedInputStream.fill() @bci=175, line=235 (Compiled frame)
 - java.io.BufferedInputStream.read1(byte[], int, int) @bci=44, line=275 (Compiled frame)
 - java.io.BufferedInputStream.read(byte[], int, int) @bci=49, line=334 (Compiled frame)
 - com.sun.jndi.ldap.Connection.run() @bci=30, line=853 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=745 (Interpreted frame)

Application queries data with LDAP so sounds normal but on both hangs these are the only running threads.

eyalkoren · 2019-02-03T13:26:59Z

@Aketzu I am really sorry to hear about the second scenario. For this one, a full thread dump can be useful. If you have a profiler you can use to get us visibility of where CPU is mostly spent when the app gets to this hang state- it can be super-useful.

For the crash scenario, please try this snapshot and see if the crash is reproduced - elastic-apm-agent-1.3.1-SNAPSHOT.jar.zip

TeroPihlaja · 2019-02-05T08:02:54Z

Looks like the issue still happens with this snapshot:
https://gist.github.com/TeroPihlaja/34567b0f778d0f2c759b2b53a61a5193

felixbarny · 2019-02-05T09:38:31Z

Bummer :(
Are you using the agent with newer Java versions (8+) for other applications? Do you see similar problems there? Or does that seem to be a Java 7 issue only?

eyalkoren · 2019-02-05T09:43:40Z

@TeroPihlaja really sorry to hear that!
I see there are several errors occurring close to the time of the crash related to JNI. Unfortunately, there is not a lot of info to tell me where exactly the problem is. Could you run again with the following cmd-line arguments: -Xcheck:jni, -verbose:jni and if GDB is available, also -XX:OnError="gdb - %p"? Maybe we will have additional information in the applications logs, in addition to the crash log, to direct us to the root cause.

In addition, please add -Delastic.apm.flush_interval=200ms and let's see if it has any effect on the (very consistent) crash time.

Lastly, if you can try running the same on Java 8, that can be very insightful.

Thanks for your invaluable input!

TeroPihlaja · 2019-02-05T09:45:35Z

We are running 1.3.0 with Java 8. This issue seems to only happen on Java 7.

I will try your suggestions and see what happens.

felixbarny · 2019-02-05T09:59:13Z

Another idea would be to disable compilation for the sanitizeTagKey method like this: -XX:CompileCommand=exclude,co.elastic.apm.agent.report.serialize.DslJsonSerializer::sanitizeTagKey

TeroPihlaja · 2019-02-06T13:42:50Z

-Delastic.apm.flush_interval=200msdoes not seem to have any affect on the crash time on 1.3.0 release.

time: Wed Feb  6 15:40:06 2019
elapsed time: 50010 seconds (0d 13h 53m 30s)

eyalkoren · 2019-02-06T15:13:10Z

OK, that was a long shot. But what about additional data in the server logs? Anything new there that can provide additional info about JNI issues? Or any gdb logs?

TeroPihlaja · 2019-02-07T08:18:03Z

Looks like those command line argument changes weren't actually in use yet. I will try again and let you know tomorrow (after it crashes again).

There's no gdb installed on this system and I'm not too familiar with it. If there's something specific you'd like to check from gdb I could probably install it on the server.

eyalkoren · 2019-02-07T09:30:02Z

Nothing specific I know I am looking to get from gdb. I hoped this configuration could provide more info about the time of the crash. Looking forward to hear if there's any additional info in logs after the next crash.
Thanks a lot for your cooperation and input!

felixbarny · 2019-02-07T10:01:12Z

Have you tried out the -XX:CompileCommand option? That could be a workaround for this JVM bug.

TeroPihlaja · 2019-02-07T12:39:07Z

Not yet. I don't want to test many things at the same time.

TeroPihlaja · 2019-02-08T08:10:07Z

test.log
hs_err_pid42129.log

Here's the logs with the -Xcheck:jni -verbose:jni set.

I will try -XX:CompileCommand=exclude,co.elastic.apm.agent.report.serialize.DslJsonSerializer::sanitizeTagKey next.

TeroPihlaja · 2019-02-09T19:06:01Z

Tested with -XX:CompileCommand=exclude,co.elastic.apm.agent.report.serialize.DslJsonSerializer::sanitizeTagKey

Still seems to crash:
hs_err_pid94892.log

eyalkoren · 2019-02-10T09:25:19Z

@TeroPihlaja thanks, that may be very valuable input. It seems that the compilation of java.lang.invoke.LambdaForm$NFI/1305645237::invoke_J_D is the root cause (where 1305645237 in this case is probably a dynamically allocated name). Let's try adding -XX:CompileCommand=exclude,*.invoke_J_D now and see if it resolves the problem.

Assumption: LambdaForms are intermediate Java representation for method handles that were introduced in order to replace the assembly code used previously for method handles implementation. In the JVM, long and double types are represented as J and D respectively (and this convention is used in LambdaForm). Our metrics collection relies on method handles of JMX bean operations and in some cases we use a method handle that returns long and cast it to double, e.g.

apm-agent-java/apm-agent-core/src/main/java/co/elastic/apm/agent/metrics/builtin/SystemMetrics.java

Line 119 in d83d37b

return invoke(freeMemory);

Besides the compiled method name (invoke_J_D), two additional factors make me think this JVM bug was exposed by our metrics mechanism:

the fact that the java.lang.invoke.LambdaForm$NFI/*::invoke_J_D compilation event always happens at 49980 seconds, a round multiple of 30, our default metrics interval time
the fact that these invocations occur on the apm-reporter thread

This assumption may be validated by setting -Delastic.apm.metrics_interval=1s and testing if it affects the crash time. If you could try that out as well it would be really great.

Thanks!

Aketzu · 2019-02-10T10:24:22Z

metrics_interval=1s caused crash in 1668 seconds. Now running with invoke_J_D exclusion.

Aketzu · 2019-02-10T13:54:32Z

Command line is there also in log file. Basically:

pid 16940 exclude invoke_J_D
pid 18872 exclude invoke_J_D, invokeStatic_J_D
pid 20599 exclude invoke_J_D, invokeStatic_J_D, invoke_D_D, invokeStatic_D_D

hs_err_pid20599.log

And it seems to be working. 20599 stdout shows:

Checked JNI functions are being used to validate JNI usage
Checked JNI functions are being used to validate JNI usage
### Excluding compile: static java.lang.invoke.LambdaForm$DMH/1182538353::invokeStatic_J_D
### Excluding compile: static java.lang.invoke.LambdaForm$NFI/1234030171::invoke_D_D
### Excluding compile: static java.lang.invoke.LambdaForm$DMH/20383660::invokeStatic_D_D
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x0000000000000000, pid=20599, tid=0x00007fd01c0be700

Feels like all LambdaForm methods crash...

eyalkoren · 2019-02-10T14:11:10Z

Thanks!!

If you just want to test the agent without metrics, you can disable metrics collection by setting -Delastic.apm.metrics_interval=0s.

However, if you still have the patience to bring this to full resolution, a few more steps will be very helpful:

look for the additional logs (like the test.log attached to JVM crash with Java 7 + Agent 1.3.0 #458 (comment)) from the last crash and attach to the issue (I see that the -Xcheck:jni -verbose:jni -XX:OnError=gdb settings were used)
try it only with -XX:CompileCommand=exclude,*.invoke_J_D -XX:CompileCommand=exclude,*.invoke_L_J and remove the others.
if crashes- look for the additional logs and attach

Again, many thanks!

Aketzu · 2019-02-10T14:24:06Z

Attached pid20599 test.log

It seems strange,

Compiled method (c2) 3334885 3432             java.lang.invoke.LambdaForm$DMH/1207168383::invokeInterface_L_J (14 bytes)
Compiled method (c2) 3334887  470             java.lang.Long::<init> (10 bytes)
Compiled method (c2) 3334888 3431             java.lang.invoke.LambdaForm$NFI/1305645237::invoke_L_J (11 bytes)

eyalkoren · 2019-02-10T14:30:28Z

OK, let's see what happens when only JIT compilation of invoke_L_J and invoke_J_D are disabled as suggested above.

Aketzu · 2019-02-10T15:48:09Z

New crash now with invoke_L_J and invoke_J_D excluded

# Problematic frame:
# J 2783 C2 java.lang.invoke.LambdaForm.basicTypeSignature()Ljava/lang/String; (59 bytes) @ 0x00007f2a910db864 [0x00007f2a910db300+0x564]

Compiled method (c2) 3333944 3370             java.lang.invoke.LambdaForm$NFI/486510138::invoke_L_J (11 bytes)

test-20190210_164814.log
hs_err_pid24029.log

Aketzu · 2019-02-10T16:49:54Z

And I apparently typoed L_J as L_D... Anyhow now with actually L_J it gets invoke_D_D crash.

test-20190210_174606.log
hs_err_pid25670.log

eyalkoren · 2019-02-11T02:41:26Z

Ohh, I am so sorry about that 😫
But we will get there eventually.
Did you try -XX:CompileCommand=exclude,*.invoke_J_D -XX:CompileCommand=exclude,*.invoke_L_J -XX:CompileCommand=exclude,*.invoke_D_D already?

Aketzu · 2019-02-11T06:59:44Z

Now it has been running 14 hours without crashes (with metrics_interval=1s) so looks pretty good.

stdout shows

### Excluding compile: static java.lang.invoke.LambdaForm$NFI/991593213::invoke_J_D
### Excluding compile: static java.lang.invoke.LambdaForm$NFI/1305645237::invoke_L_J
### Excluding compile: static java.lang.invoke.LambdaForm$NFI/1234030171::invoke_D_D
### Excluding compile: static java.lang.invoke.LambdaForm$NFI/2013163400::invoke_L_D

eyalkoren · 2019-02-11T07:14:49Z

Really glad to hear! If it's not a problem, please let it run another day to make sure it is resolved and then you would probably want to restore the metrics collection interval. Looking forward to hear back.

eyalkoren · 2019-02-11T07:19:36Z

Note to self- notify users that reported the same problem at https://discuss.elastic.co/t/apm-agent-for-java-is-causing-system-crashes/165211 once the workaround is verified

felixbarny · 2019-02-11T08:19:39Z

I think we should use reflection instead of method handles if the agent is running on Java 7.

This is a workaround for a bug in the C2 compiler in Java 7 which leads to a segfault closes elastic#458

felixbarny · 2019-02-11T13:07:17Z

I have created a PR which uses reflection as opposed to MethodHanldes to get metrics from the OperatingSystemMXBean. Could you try the attached snapshot and see if it helps? If so, we'll release a fix shortly.

Thanks so much for your help!

Btw: I was unable to reproduce the JVM crash on JDK 1.7.0u80 and Mac OS.

Aketzu · 2019-02-12T08:17:52Z

About 18h uptime now with 1.3.1-SNAPSHOT without any compile exclusions so seems to work.

1.3.0 with exclusions still ended up crashing after 17h uptime.
Last compiled method was java.lang.invoke.BoundMethodHandle$Species_LL::<init> and nothing else obvious to my eye. Really strange how well it breaks JVM :)
hs_err_pid27244.log
test-20190210_184348.log

eyalkoren · 2019-02-12T08:32:56Z

Looks good! Thanks so much for you help!
We will probably make a release soon so you can switch to using that instead.

This is a workaround for a bug in the C2 compiler in Java 7 which leads to a segfault closes #458

eyalkoren · 2019-02-14T11:55:56Z

@Aketzu @TeroPihlaja 1.4.0 is released, feel free to switch to it at your convenience.

jvimal · 2019-07-19T22:29:13Z

Wow, this is a strange issue. Any idea what the root-cause is?

We encountered a similar crash/hung JVM with a custom agent, and it was hard to diagnose (with jdk 8u25). We didn't use MethodHandles anywhere, but they seem to be referenced in the generated bytecode because of lambda functions. Removing all lambda functions from our agent resolved the issue.

lreuven · 2019-07-20T08:04:25Z

@jvimal which agent version are u using?

felixbarny · 2019-07-20T08:29:16Z

The root cause is a JVM bug which gets triggered when the JIT optimizes the MethodHandles. Those are used under the hood for Lambdas.

jvimal · 2019-07-20T13:17:50Z

@lreuven - I am not using elastic agent. I wrote an agent, and encountered the exact same issue mentioned here.

@felixbarny Yeah I figured lambdas were causing the issue. However, I was curious if you had more details (e.g., a link to the JVM bug for more details).

The discussion on this issue thread was super helpful! This was the only detailed thread I could find -- all the other threads I checked just mentioned that upgrading the jvm should resolve such issues.

alvarolobato added [zube]: Inbox and removed [zube]: Inbox labels Jan 30, 2019

felixbarny added type: bug and removed bug labels Jan 31, 2019

eyalkoren added [zube]: In Progress and removed [zube]: Ready labels Feb 3, 2019

felixbarny added a commit to felixbarny/apm-agent-java that referenced this issue Feb 11, 2019

Use reflection rather than MethodHandles

91137e4

This is a workaround for a bug in the C2 compiler in Java 7 which leads to a segfault closes elastic#458

felixbarny mentioned this issue Feb 11, 2019

Use reflection rather than MethodHandles #487

Merged

felixbarny closed this as completed in #487 Feb 12, 2019

felixbarny added a commit that referenced this issue Feb 12, 2019

Use reflection rather than MethodHandles (#487)

90b64b3

This is a workaround for a bug in the C2 compiler in Java 7 which leads to a segfault closes #458

zube bot added [zube]: Done and removed [zube]: In Progress labels Feb 12, 2019

alvarolobato removed the [zube]: Done label Feb 18, 2019

felixbarny mentioned this issue Mar 25, 2020

Customizable advice dispatcher raphw/byte-buddy#830

Closed

duclm2609 mentioned this issue Apr 9, 2020

JVM crash with Java 7 + Agent 1.15.0 #1130

Closed

SylvainJuge added bug Bugs and removed type: bug labels Feb 2, 2021

JVM crash with Java 7 + Agent 1.3.0 #458

JVM crash with Java 7 + Agent 1.3.0 #458

Comments

Aketzu commented Jan 29, 2019 • edited by alvarolobato Loading

felixbarny commented Jan 29, 2019

felixbarny commented Jan 29, 2019

TeroPihlaja commented Jan 29, 2019

Aketzu commented Jan 29, 2019

Aketzu commented Jan 30, 2019

Aketzu commented Jan 30, 2019

eyalkoren commented Feb 3, 2019

TeroPihlaja commented Feb 5, 2019

felixbarny commented Feb 5, 2019

eyalkoren commented Feb 5, 2019

TeroPihlaja commented Feb 5, 2019

felixbarny commented Feb 5, 2019

TeroPihlaja commented Feb 6, 2019 • edited Loading

eyalkoren commented Feb 6, 2019

TeroPihlaja commented Feb 7, 2019

eyalkoren commented Feb 7, 2019

felixbarny commented Feb 7, 2019

TeroPihlaja commented Feb 7, 2019

TeroPihlaja commented Feb 8, 2019

TeroPihlaja commented Feb 9, 2019

eyalkoren commented Feb 10, 2019

Aketzu commented Feb 10, 2019

Aketzu commented Feb 10, 2019

eyalkoren commented Feb 10, 2019

Aketzu commented Feb 10, 2019

eyalkoren commented Feb 10, 2019

Aketzu commented Feb 10, 2019

Aketzu commented Feb 10, 2019

eyalkoren commented Feb 11, 2019

Aketzu commented Feb 11, 2019

eyalkoren commented Feb 11, 2019

eyalkoren commented Feb 11, 2019 • edited Loading

felixbarny commented Feb 11, 2019

felixbarny commented Feb 11, 2019

Aketzu commented Feb 12, 2019

eyalkoren commented Feb 12, 2019

eyalkoren commented Feb 14, 2019

jvimal commented Jul 19, 2019

lreuven commented Jul 20, 2019

felixbarny commented Jul 20, 2019

jvimal commented Jul 20, 2019

Aketzu commented Jan 29, 2019 •

edited by alvarolobato

Loading

TeroPihlaja commented Feb 6, 2019 •

edited

Loading

eyalkoren commented Feb 11, 2019 •

edited

Loading