Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
fengli79 opened this issue Jan 27, 2024 · 2 comments
Assignees
Labels
bug Something does not work as expected

Comments

@fengli79
Copy link
Collaborator

fengli79 commented Jan 27, 2024

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?

  • Spring (boot):
  • grpc-java:
  • grpc-spring-boot-starter:
  • java: version + architecture (64bit?)
  • Other relevant libraries...

Additional context

  • Did it ever work before?
  • Do you have a demo?
@fengli79 fengli79 added the bug Something does not work as expected label Jan 27, 2024
@ST-DDT
Copy link
Collaborator

ST-DDT commented Jan 28, 2024

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
Copy link
Collaborator

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something does not work as expected
Projects
None yet
Development

No branches or pull requests

3 participants