Elastic apm cannot collect GRPC requests

topstargogo · April 28, 2020, 6:43am

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

felixbarny · April 28, 2020, 6:58am

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

topstargogo · April 28, 2020, 8:11am

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)

felixbarny · April 28, 2020, 8:34am

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

topstargogo · April 28, 2020, 9:46am

gist.github.com

https://gist.github.com/tosptargogo/a2ec2bc27ca273e64a3a01119b7d69dc

gistfile1.txt

--2020-04-28 02:55:29--  http://log.bitmartlocal.com/files/elastic-apm-agent-1.15.0.jar
Resolving log.bitmartlocal.com (log.bitmartlocal.com)... 192.168.2.60
Connecting to log.bitmartlocal.com (log.bitmartlocal.com)|192.168.2.60|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 5786844 (5.5M) [application/java-archive]
Saving to: ‘elastic-apm-agent-1.15.0.jar’

     0K .......... .......... .......... .......... ..........  0%  166M 0s
    50K .......... .......... .......... .......... ..........  1% 28.9M 0s
   100K .......... .......... .......... .......... ..........  2% 34.5M 0s

This file has been truncated. show original

topstargogo · April 28, 2020, 10:18am

Is this okay?

felixbarny · April 28, 2020, 11:22am

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.

topstargogo · April 29, 2020, 3:38am

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？

topstargogo · April 29, 2020, 6:48am

gist.github.com

https://gist.github.com/tosptargogo/1b010b0bcd0a8addabbb7857daf50032

new issue

--2020-04-29 06:41:47--  http://log.bitmartlocal.com/files/elastic-apm-agent-1.15.0.jar
Resolving log.bitmartlocal.com (log.bitmartlocal.com)... 192.168.2.60
Connecting to log.bitmartlocal.com (log.bitmartlocal.com)|192.168.2.60|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 5824754 (5.6M) [application/java-archive]
Saving to: ‘elastic-apm-agent-1.15.0.jar’

     0K .......... .......... .......... .......... ..........  0%  215M 0s
    50K .......... .......... .......... .......... ..........  1% 99.7M 0s
   100K .......... .......... .......... .......... ..........  2% 54.3M 0s

This file has been truncated. show original

new log

felixbarny · April 29, 2020, 7:38am

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?

felixbarny · April 29, 2020, 7:44am

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

topstargogo · April 29, 2020, 9:40am

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

felixbarny · April 29, 2020, 9:53am

Did it work now?

felixbarny · April 29, 2020, 9:56am

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

topstargogo · April 29, 2020, 9:57am

Wait

topstargogo · April 29, 2020, 10:31am

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

system · May 20, 2020, 6:33am

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

Topic		Replies	Views
Java Agent grpc not working APM java	3	755	May 20, 2020
Java apm agent not collecting all the transactions APM java	1	223	June 30, 2023
Java Automatic Agent Configuration Options are not working APM java	5	789	May 16, 2021
Elastic APM (Java Agent) getting 400 error APM java , server	8	2497	June 14, 2021
Agent logs, how can I make it in debug mode APM java	2	325	October 7, 2019

Elastic apm cannot collect GRPC requests

Related topics