search

grpc-ecosystem / grpc-spring

Spring Boot starter module for gRPC framework.
https://grpc-ecosystem.github.io/grpc-spring/
Apache License 2.0
3.43k stars 809 forks source link

Micrometer throws ArrayIndexOutOfBoundsException exception when the grpc client cannot access a backend with metrics enabled. #1040

Open fengli79 opened 5 months ago

fengli79 commented 5 months ago

The context

Makes gRPC client call with metrics

The bug

When the backend is unavailable the client crash in micrometer

Stacktrace and logs

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.2.0)

2024-01-27T06:45:28.916Z  INFO 1 --- [           main] c.g.c.m.g.s.o.e.f.FrontendApplication    : Starting FrontendApplication v0.0.1-SNAPSHOT using Java 17.0.10 with PID 1 (/frontend.jar started by root in /)
2024-01-27T06:45:28.923Z  INFO 1 --- [           main] c.g.c.m.g.s.o.e.f.FrontendApplication    : No active profile set, falling back to 1 default profile: "default"
2024-01-27T06:45:40.230Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port 8080 (http)
2024-01-27T06:45:40.412Z  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2024-01-27T06:45:40.413Z  INFO 1 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.16]
2024-01-27T06:45:41.633Z  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2024-01-27T06:45:41.636Z  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 12320 ms
2024-01-27T06:45:45.019Z  INFO 1 --- [           main] n.d.b.g.c.a.GrpcClientAutoConfiguration  : Detected grpc-netty-shaded: Creating ShadedNettyChannelFactory + InProcessChannelFactory
2024-01-27T06:45:50.512Z  INFO 1 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 4 endpoint(s) beneath base path '/actuator'
2024-01-27T06:45:51.016Z  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port 8080 (http) with context path ''
2024-01-27T06:45:51.120Z  INFO 1 --- [           main] c.g.c.m.g.s.o.e.f.FrontendApplication    : Started FrontendApplication in 25.804 seconds (process running for 30.554)
2024-01-27T06:45:52.328Z  INFO 1 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-01-27T06:45:52.330Z  INFO 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2024-01-27T06:45:52.410Z  INFO 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 6 ms
2024-01-27T06:48:24.017Z ERROR 1 --- [ault-executor-7] io.grpc.internal.SerializingExecutor     : Exception while executing runnable io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed@3aa9f71d

java.lang.ArrayIndexOutOfBoundsException: Index 3 out of bounds for length 3
    at java.base/java.util.LinkedHashMap.valuesToArray(LinkedHashMap.java:555) ~[na:na]
    at java.base/java.util.LinkedHashMap$LinkedValues.toArray(LinkedHashMap.java:639) ~[na:na]
    at io.micrometer.common.KeyValues.of(KeyValues.java:268) ~[micrometer-commons-1.12.0.jar!/:1.12.0]
    at io.micrometer.observation.Observation$Context.getLowCardinalityKeyValues(Observation.java:1210) ~[micrometer-observation-1.12.0.jar!/:1.12.0]
    at io.micrometer.core.instrument.observation.DefaultMeterObservationHandler.createTags(DefaultMeterObservationHandler.java:87) ~[micrometer-core-1.12.0.jar!/:1.12.0]
    at io.micrometer.core.instrument.observation.DefaultMeterObservationHandler.onEvent(DefaultMeterObservationHandler.java:75) ~[micrometer-core-1.12.0.jar!/:1.12.0]
    at io.micrometer.observation.ObservationHandler$FirstMatchingCompositeObservationHandler.onEvent(ObservationHandler.java:165) ~[micrometer-observation-1.12.0.jar!/:1.12.0]
    at io.micrometer.observation.SimpleObservation.notifyOnEvent(SimpleObservation.java:228) ~[micrometer-observation-1.12.0.jar!/:1.12.0]
    at io.micrometer.observation.SimpleObservation.event(SimpleObservation.java:145) ~[micrometer-observation-1.12.0.jar!/:1.12.0]
    at io.micrometer.core.instrument.binder.grpc.ObservationGrpcClientCall.sendMessage(ObservationGrpcClientCall.java:65) ~[micrometer-core-1.12.0.jar!/:1.12.0]
    at io.grpc.ForwardingClientCall.sendMessage(ForwardingClientCall.java:37) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.grpc.ForwardingClientCall.sendMessage(ForwardingClientCall.java:37) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.micrometer.core.instrument.binder.grpc.MetricCollectingClientCall.sendMessage(MetricCollectingClientCall.java:68) ~[micrometer-core-1.12.0.jar!/:1.12.0]
    at io.grpc.stub.ClientCalls$CallToStreamObserverAdapter.onNext(ClientCalls.java:368) ~[grpc-stub-1.60.1.jar!/:1.60.1]
    at com.google.cloud.microservices.grpc.spring.observability.examples.frontend.FrontendApplication.CallBidStreamingRpc(FrontendApplication.java:133) ~[!/:0.0.1-SNAPSHOT]
    at com.google.cloud.microservices.grpc.spring.observability.examples.frontend.FrontendApplication$4.onError(FrontendApplication.java:125) ~[!/:0.0.1-SNAPSHOT]
    at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:481) ~[grpc-stub-1.60.1.jar!/:1.60.1]
    at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.micrometer.core.instrument.binder.grpc.MetricCollectingClientCallListener.onClose(MetricCollectingClientCallListener.java:57) ~[micrometer-core-1.12.0.jar!/:1.12.0]
    at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at net.devh.boot.grpc.client.metrics.MetricsClientInterceptor$1$1.onClose(MetricsClientInterceptor.java:72) ~[grpc-client-spring-boot-autoconfigure-3.0.0-SNAPSHOT.jar!/:3.0.0-SNAPSHOT]
    at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-api-1.60.1.jar!/:1.60.1]
    at io.micrometer.core.instrument.binder.grpc.ObservationGrpcClientCallListener.onClose(ObservationGrpcClientCallListener.java:48) ~[micrometer-core-1.12.0.jar!/:1.12.0]
    at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:574) ~[grpc-core-1.60.1.jar!/:1.60.1]
    at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:72) ~[grpc-core-1.60.1.jar!/:1.60.1]
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:742) ~[grpc-core-1.60.1.jar!/:1.60.1]
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:723) ~[grpc-core-1.60.1.jar!/:1.60.1]
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.60.1.jar!/:1.60.1]
    at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133) ~[grpc-core-1.60.1.jar!/:1.60.1]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
    at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na]

Steps to Reproduce

Steps to reproduce the behavior:

  1. Go to '...'
  2. Click on '....'
  3. Scroll down to '....'
  4. See error

The application's environment

Which versions do you use?

Additional context

ST-DDT commented 5 months ago

I try to have a look at this soon, but my todo-stack is currently overflowing.

I have to reschedule a few things to find some time to do some major tasks I would like to do before the major release. FFR: Currently only yidongnan has the release instructions/access.

DNVindhya commented 5 months ago

Seems to be related to an open micrometer issue #4356.