Elastic apm cannot collect GRPC requests

Elastic Observability APM
1

Kibana version: v7.6.1

Elasticsearch version: v7.6.1

APM Server version:v7.6.1

APM Agent language and version: Java version 1.15

Browser version:chrome

Original install method (e.g. download page, yum, deb, from source, etc.) and version:download page

Fresh install or upgraded from other version? Fresh. Just started making sense of things.

Is there anything special in your setup? For example, are you using the Logstash or Kafka outputs? Are you using a load balancer in front of the APM Servers? Have you changed index pattern, generated custom templates, changed agent configuration etc.
NO, all default

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant):
GRPC version 1.14. The javaagent has been deployed. HTTP requests can be collected. But GRPC can't collect it. this is the log

微信图片_20200428144009
微信图片_202004281440092535×1270 252 KB

2

Hi and welcome to the forum!

Could you please attach your full debug agent logs as described here? https://www.elastic.co/guide/en/apm/agent/java/current/trouble-shooting.html

3

When the agent starts up, you should see logs similar to these:

2020-04-28 02:55:43.487 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - environment: 'spot-trading' (source: Java System Properties)
2020-04-28 02:55:43.487 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - secret_token: 'XXXX' (source: Java System Properties)
2020-04-28 02:55:43.487 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - server_urls: 'http://log.bitmartlocal.com:8200' (source: Java System Properties)
2020-04-28 02:55:43.487 [main] WARN co.elastic.apm.agent.configuration.StartupInfo - Detected usage of an old configuration key: 'server_url'. Please use 'server_urls' instead.
2020-04-28 02:55:43.487 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - application_packages: 'org.example' (source: Java System Properties)
2020-04-28 02:55:43.487 [main] DEBUG co.elastic.apm.agent.configuration.StartupInfo - log_level: 'TRACE' (source: Java System Properties)
2020-04-28 02:55:43.488 [elastic-apm-remote-config-poller] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {"service":{"name":"quotation-query-v1-dev","environment":"spot-trading","agent":{"name":"java","ephemeral_id":"1dcec204-faca-46a8-943c-00d4d69c309e","version":"1.15.0"},"language":{"name":"Java","version":"1.8.0_212"},"runtime":{"name":"Java","version":"1.8.0_212"},"version":null},"process":{"pid":1,"title":"/usr/local/openjdk-8/jre/bin/java"},"system":{"container":{"id":"04c57d3f57c544bc1eef305b05bf6e9c296abe30dcea95b08d8c55d81a6c8b02"},"kubernetes":{"pod":{"name":"quotation-query-v1-dev-57cbdf78b6-5rcgd","uid":"b3414db2-88fb-11ea-a248-005056a62017"},"namespace":null},"architecture":"amd64","hostname":"quotation-query-v1-dev-57cbdf78b6-5rcgd","platform":"Linux"}}

Make sure to execute some requests to your application before posting your log files. Each request should at least add some lines similar to these in the logs:

2020-04-28 03:05:14.076 INFO 1 --- [ault-executor-2] c.b.q.a.g.i.QuotationQueryApiGrpcImpl : uuid=[ec979836-5f4d-408b-8048-bfadd5c0b0be]-接收到queryDepth grpc查询请求：[uuid: "ec979836-5f4d-408b-8048-bfadd5c0b0be"
trade_mapping_id: 154
precision: 6
],89ms
2020-04-28 03:05:16.498 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:05:20.496 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-04-28 03:05:20.499 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 37)
2020-04-28 03:05:20.500 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {"metadata":{"service":{"name":"quotation-query-v1-dev","environment":"spot-trading","agent":{"name":"java","ephemeral_id":"1dcec204-faca-46a8-943c-00d4d69c309e","version":"1.15.0"},"language":{"name":"Java","version":"1.8.0_212"},"runtime":{"name":"Java","version":"1.8.0_212"},"version":null},"process":{"pid":1,"title":"/usr/local/openjdk-8/jre/bin/java"},"system":{"container":{"id":"04c57d3f57c544bc1eef305b05bf6e9c296abe30dcea95b08d8c55d81a6c8b02"},"kubernetes":{"pod":{"name":"quotation-query-v1-dev-57cbdf78b6-5rcgd","uid":"b3414db2-88fb-11ea-a248-005056a62017"},"namespace":null},"architecture":"amd64","hostname":"quotation-query-v1-dev-57cbdf78b6-5rcgd","platform":"Linux"}}}
{"metricset":{"timestamp":1588043110495000,"samples":{"system.process.cpu.total.norm.pct":{"value":0.002536517099623896},"jvm.memory.heap.used":{"value":127095792.0},"jvm.memory.non_heap.used":{"value":96837840.0},"jvm.memory.heap.max":{"value":518979584.0},"jvm.gc.alloc":{"value":151658936.0},"jvm.memory.non_heap.committed":{"value":100474880.0},"system.cpu.total.norm.pct":{"value":0.3741800052479664},"system.process.memory.size":{"value":4744876032.0},"jvm.memory.heap.committed":{"value":518979584.0},"jvm.memory.non_heap.max":{"value":-1.0},"system.memory.actual.free":{"value":10640715776.0},"system.memory.total":{"value":33566777344.0},"jvm.thread.count":{"value":29.0}}}}
{"metricset":{"timestamp":1588043110495000,"tags":{"name":"MarkSweepCompact"},"samples":{"jvm.gc.time":{"value":5324.0},"jvm.gc.count":{"value":3.0}}}}
{"metricset":{"timestamp":1588043110495000,"tags":{"name":"Copy"},"samples":{"jvm.gc.time":{"value":6835.0},"jvm.gc.count":{"value":13.0}}}}

2020-04-28 03:05:20.500 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1664 uncompressed 731 compressed bytes
2020-04-28 03:05:21.499 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:05:26.499 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:05:31.500 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:05:33.288 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2020-04-28 03:05:33.289 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2020-04-28 03:05:36.500 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:05:40.478 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 38)
2020-04-28 03:05:40.479 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to http://log.bitmartlocal.com:8200/intake/v2/events
2020-04-28 03:05:40.481 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Scheduling request timeout in 10s
2020-04-28 03:05:41.500 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:05:43.781 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server http://log.bitmartlocal.com:8200/config/v1/agents
2020-04-28 03:05:43.785 [elastic-apm-remote-config-poller] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {"service":{"name":"quotation-query-v1-dev","environment":"spot-trading","agent":{"name":"java","ephemeral_id":"1dcec204-faca-46a8-943c-00d4d69c309e","version":"1.15.0"},"language":{"name":"Java","version":"1.8.0_212"},"runtime":{"name":"Java","version":"1.8.0_212"},"version":null},"process":{"pid":1,"title":"/usr/local/openjdk-8/jre/bin/java"},"system":{"container":{"id":"04c57d3f57c544bc1eef305b05bf6e9c296abe30dcea95b08d8c55d81a6c8b02"},"kubernetes":{"pod":{"name":"quotation-query-v1-dev-57cbdf78b6-5rcgd","uid":"b3414db2-88fb-11ea-a248-005056a62017"},"namespace":null},"architecture":"amd64","hostname":"quotation-query-v1-dev-57cbdf78b6-5rcgd","platform":"Linux"}}
2020-04-28 03:05:43.786 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Central configuration is disabled. Set kibana.enabled: true in your APM Server configuration.
2020-04-28 03:05:43.786 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 300s

After that, you should see logs indicating that the agent has successfully sent data to the APM server:

2020-04-28 03:06:16.505 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:06:20.486 [elastic-apm-request-timeout-timer] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Request flush because the request timeout occurred
2020-04-28 03:06:20.492 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving FLUSH event (sequence 41)
2020-04-28 03:06:20.492 [elastic-apm-server-reporter] TRACE co.elastic.apm.agent.report.serialize.DslJsonSerializer - {"metadata":{"service":{"name":"quotation-query-v1-dev","environment":"spot-trading","agent":{"name":"java","ephemeral_id":"1dcec204-faca-46a8-943c-00d4d69c309e","version":"1.15.0"},"language":{"name":"Java","version":"1.8.0_212"},"runtime":{"name":"Java","version":"1.8.0_212"},"version":null},"process":{"pid":1,"title":"/usr/local/openjdk-8/jre/bin/java"},"system":{"container":{"id":"04c57d3f57c544bc1eef305b05bf6e9c296abe30dcea95b08d8c55d81a6c8b02"},"kubernetes":{"pod":{"name":"quotation-query-v1-dev-57cbdf78b6-5rcgd","uid":"b3414db2-88fb-11ea-a248-005056a62017"},"namespace":null},"architecture":"amd64","hostname":"quotation-query-v1-dev-57cbdf78b6-5rcgd","platform":"Linux"}}}
{"metricset":{"timestamp":1588043170486000,"samples":{"system.process.cpu.total.norm.pct":{"value":0.002314410480349345},"jvm.memory.heap.used":{"value":130012928.0},"jvm.memory.non_heap.used":{"value":97333504.0},"jvm.memory.heap.max":{"value":518979584.0},"jvm.gc.alloc":{"value":144801400.0},"jvm.memory.non_heap.committed":{"value":101064704.0},"system.cpu.total.norm.pct":{"value":0.36908296943231444},"system.process.memory.size":{"value":4744876032.0},"jvm.memory.heap.committed":{"value":518979584.0},"jvm.memory.non_heap.max":{"value":-1.0},"system.memory.actual.free":{"value":11031728128.0},"system.memory.total":{"value":33566777344.0},"jvm.thread.count":{"value":28.0}}}}
{"metricset":{"timestamp":1588043170486000,"tags":{"name":"MarkSweepCompact"},"samples":{"jvm.gc.time":{"value":5324.0},"jvm.gc.count":{"value":3.0}}}}
{"metricset":{"timestamp":1588043170486000,"tags":{"name":"Copy"},"samples":{"jvm.gc.time":{"value":6835.0},"jvm.gc.count":{"value":13.0}}}}

2020-04-28 03:06:20.493 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Flushing 1665 uncompressed 727 compressed bytes
2020-04-28 03:06:21.506 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:06:26.507 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:06:31.507 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:06:33.288 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2020-04-28 03:06:33.289 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2020-04-28 03:06:36.508 [elastic-apm-circuit-breaker] TRACE co.elastic.apm.agent.impl.circuitbreaker.CircuitBreaker - Scheduling next stress monitor polling in 5000s
2020-04-28 03:06:40.484 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 42)

4

What I meant was to do this:

IMPORTANT: If you do so, please attach your debug logs so that we can analyze the problem. Upload the complete logs to a service like https://gist.github.com. The logs should include everything from the application startup up until the first request has been executed.

With just a snippet of the logs it's not possible to debug the issue.

Thanks :slightly_smiling_face:

5
6

Is this okay?

7

Thanks for providing the logs!
It helped me to find out that there's currently a bug in the build which prevents the gRPC plugin to be included in the agent.

I've created a PR to fix this. As soon as the build has executed the CI will add a link to the artifacts, containing a new agent snapshot. Could you try if it fixes the problem for you?

Note that we currently don't support streaming calls with gRPC.

8

I try the new SNAPSHOT. Here is the issue

2020-04-29T03:30:58.901970508Z java.lang.NoClassDefFoundError: io/grpc/Metadata

2020-04-29T03:30:58.902067306Z at co.elastic.apm.agent.grpc.helper.GrpcHelperImpl$GrpcHeaderGetter.getFirstHeader(GrpcHelperImpl.java:307)

2020-04-29T03:30:58.902085661Z at co.elastic.apm.agent.impl.transaction.TraceContext$3.asChildOf(TraceContext.java:131)

2020-04-29T03:30:58.902098372Z at co.elastic.apm.agent.impl.transaction.TraceContext$3.asChildOf(TraceContext.java:123)

2020-04-29T03:30:58.902557798Z at co.elastic.apm.agent.impl.transaction.Transaction.start(Transaction.java:109)

2020-04-29T03:30:58.902578106Z at co.elastic.apm.agent.impl.ElasticApmTracer.startChildTransaction(ElasticApmTracer.java:249)

2020-04-29T03:30:58.902603261Z at co.elastic.apm.agent.impl.ElasticApmTracer.startChildTransaction(ElasticApmTracer.java:227)

2020-04-29T03:30:58.902614705Z at co.elastic.apm.agent.grpc.helper.GrpcHelperImpl.startTransaction(GrpcHelperImpl.java:106)

2020-04-29T03:30:58.902624486Z at io.grpc.stub.ServerCalls$UnaryServerCallHandler.startCall(ServerCalls.java:116)

2020-04-29T03:30:58.902646062Z at io.grpc.internal.ServerImpl$ServerTransportListenerImpl.startWrappedCall(ServerImpl.java:560)

2020-04-29T03:30:58.902660515Z at io.grpc.internal.ServerImpl$ServerTransportListenerImpl.startCall(ServerImpl.java:541)

2020-04-29T03:30:58.902672347Z at io.grpc.internal.ServerImpl$ServerTransportListenerImpl.access$1800(ServerImpl.java:361)

2020-04-29T03:30:58.90268329Z at io.grpc.internal.ServerImpl$ServerTransportListenerImpl$1StreamCreated.runInContext(ServerImpl.java:477)

2020-04-29T03:30:58.902695193Z at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)

2020-04-29T03:30:58.90278821Z at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)

2020-04-29T03:30:58.902808115Z at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

2020-04-29T03:30:58.902821037Z at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

2020-04-29T03:30:58.902846355Z at java.lang.Thread.run(Thread.java:748)

I noticed that you have discovered this problem. Is there a way to solve it？

9

new log

10

Does the error still occur when using a snapshot from here? https://github.com/elastic/apm-agent-java#snapshots

Which gRPC and Spring Boot version are you using?

11

I found another issue. Please try the snapshot from this PR once available: Elastic apm cannot collect GRPC requests

Thanks a lot for your feedback :heart:

12

Yes .I tried the latest version. Here is the URL https://oss.sonatype.org/service/local/repositories/snapshots/content/co/elastic/apm/elastic-apm-agent/1.15.1-SNAPSHOT/elastic-apm-agent-1.15.1-20200428.153435-35.jar
and I cloned the master branch. Execute ./mvn clean install -DskipTests=true -Dmaven.javadoc.skip=true to build the artifacts.
You can see the log .

Picked up _JAVA_OPTIONS: -Xms512m -Xmx512m
2020-04-29 06:41:50.454 [elastic-apm-server-healthcheck] INFO co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: {  "build_date": "2020-02-28T22:18:38Z",  "build_sha": "3b7823bb329e0e5bfe25e106a3b93e8f61d0451f",  "version": "7.6.1"}
2020-04-29 06:41:50.567 [main] INFO co.elastic.apm.agent.util.JmxUtils - Found JVM-specific OperatingSystemMXBean interface: com.sun.management.OperatingSystemMXBean
2020-04-29 06:41:51.570 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.15.1-SNAPSHOT as quotation-query-v1-dev on Java 1.8.0_212 (Oracle Corporation) Linux 3.10.0-957.el7.x86_64
2020-04-29 06:41:51.570 [main] WARN co.elastic.apm.agent.configuration.StartupInfo - Detected usage of an old configuration key: 'server_url'. Please use 'server_urls' instead.
2020-04-29 06:41:51.662 [main] INFO co.elastic.apm.agent.impl.ElasticApmTracer - Tracer switched to RUNNING state
13

Did it work now?

14

Did you try the version from this PR? https://github.com/elastic/apm-agent-java/pull/1163#issuecomment-621058121

15

Wait

16

Oh my god . It worked . Thank you very much. I will test for a while if there are problems I will continue to feedback

2 Likes
17

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