INTERNAL: http2 exception

[shivchelwa]

I am using both automatic and manual instrumentation in my application. When I use Jaeger using otel.exporter=jaeger
and otel.exporter.jaeger.service.name=myapp, I could find the traces in Jaeger.

When I switch to default i.e. otel.exporter=otel. The span exporter is initialized as I see a log as below.
[opentelemetry.auto.trace 2021-01-07 19:50:48:594 -0500] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed span exporter: io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter

But, I get below warning followed by exception when a trace is generated and I think its being exported.

Warning
[opentelemetry.auto.trace 2021-01-07 19:51:08:953 -0500] [grpc-default-executor-1] WARN io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter - Failed to export spans. Error message: INTERNAL: http2 exception

Exception
io.grpc.StatusRuntimeException: INTERNAL: http2 exception at io.grpc.Status.asRuntimeException(Status.java:533) at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533) at io.grpc.internal.DelayedClientCall$DelayedListener$3.run(DelayedClientCall.java:464) at io.grpc.internal.DelayedClientCall$DelayedListener.delayOrExecute(DelayedClientCall.java:428) at io.grpc.internal.DelayedClientCall$DelayedListener.onClose(DelayedClientCall.java:461) at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:617) at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:70) at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:803) at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:782) at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception: First received frame was not SETTINGS. Hex dump for first 5 bytes: 485454502f at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception.connectionError(Http2Exception.java:103) at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.verifyFirstFrameIsSettings(Http2ConnectionHandler.java:338) at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.decode(Http2ConnectionHandler.java:239) at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:438) at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:501) at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:440) at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.grpc.netty.shaded.io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ... 1 more

I am running a otel collector from https://github.com/open-telemetry/opentelemetry-collector/tree/master/examples/demo. Is this not a right setup?

[jkwatson]

If you really did this: otel.exporter=jeager then that is a typo. should be otel.exporter=jaeger

[shivchelwa]

Yes, its just typo. I used correct otel.exporter=jaeger while running my app.

[jkwatson]

I would recommend trying out the example we have set up in this repository and make sure you can get it working with the collector setup that we've provided: https://github.com/open-telemetry/opentelemetry-java/tree/master/examples/otlp

If you suspect the problem is with the agent configuration, please create a discussion about it in the instrumentation repository: https://github.com/open-telemetry/opentelemetry-java-instrumentation/discussions

Thanks!

[shivchelwa]

Hi @jkwatson, everything works fine with example setup in this repository. But, I have to set system property otel.exporter.otlp.endpoint=0.0.0.0:55680. If I don't, I get below warning followed by exception. I guess thats an issue with instrumentation repository, its not using default port 55680 for opentelemetry-collector. I will create an issue in the repository.

[opentelemetry.auto.trace 2021-01-08 09:35:09:671 -0500] [grpc-default-executor-2] WARN io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter - Failed to export spans. Error message: UNAVAILABLE: io exception

Caused by: io.grpc.netty.shaded.io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/0:0:0:0:0:0:0:1:4317
Caused by: java.net.ConnectException: Connection refused
at java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:779)
at io.grpc.netty.shaded.io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:330)
at io.grpc.netty.shaded.io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)
at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:702)
at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at @java.base/java.lang.Thread.run(Thread.java:834)

[jkwatson]

Glad our example works. Yes, getting all the ports to line up is always a fun adventure!