Fetching traces by gRPC causes io.grpc.StatusRuntimeException: INTERNAL: http2 exception

[lennartmohr]

Hi everyone, as already mentioned on the jaeger slack channel on tuesday we have issues fetching traces via gRPC when using the latest version of the docker all-in-one image. When using an older image version, we used 1.18, it works perfectly fine. Here is our code we used to test against the images:

import com.google.protobuf.ByteString import com.google.protobuf.Timestamp import io.grpc.ManagedChannelBuilder import io.jaegertracing.api_v2.Query import io.jaegertracing.api_v2.QueryServiceGrpc import io.vertx.core.json.JsonArray import io.vertx.core.json.JsonObject import io.vertx.core.logging.LoggerFactory import io.vertx.ext.unit.TestContext import io.vertx.ext.unit.junit.VertxUnitRunner import org.apache.commons.codec.binary.Hex import org.junit.BeforeClass import org.junit.Test import org.junit.runner.RunWith import java.time.Instant import java.time.LocalDateTime import java.time.ZoneId import java.time.format.DateTimeFormatter

@RunWith(VertxUnitRunner::class) class JaegerGrpcTest {

companion object {

    lateinit var queryService: QueryServiceGrpc.QueryServiceBlockingStub

    private val jaegerIp = "127.0.0.1"
    private val jaegerPort = "16686"
    private val logger = LoggerFactory.getLogger(JaegerGrpcTest::class.java)

    @BeforeClass
    @JvmStatic
    fun setup(testContext: TestContext) {

        queryService = createJaegerQueryService()
    }

    private fun createJaegerQueryService(): QueryServiceGrpc.QueryServiceBlockingStub {
        logger.info("creating grpc query service with host $jaegerIp")
        val channel = ManagedChannelBuilder.forTarget("$jaegerIp:$jaegerPort").usePlaintext().build()
        return QueryServiceGrpc.newBlockingStub(channel)
    }

}

@Test
fun testFetchTraceStatistics() {
    val startService = "test-service"
    val startTime = 1616667377L 
    val traceQuery = buildTraceQuery(startService, startTime)
    val traceRequest = buildFindTraceRequest(traceQuery)
    val traces = queryService.findTraces(traceRequest)
    if (traces.hasNext()){
        logger.info("found traces for provided service and start time")
    } else {
        logger.info("no traces found for the provided look back time")
    }
}

private fun buildTraceQuery(tracingStartService: String?, startTime: Long): Query.TraceQueryParameters {
    val endTime = System.currentTimeMillis() / 1000
    logger.info("building trace query with start $startTime and end $endTime using service $tracingStartService")
    return Query.TraceQueryParameters.newBuilder()
        .setStartTimeMin(Timestamp.getDefaultInstance().toBuilder().setSeconds(startTime))
        .setStartTimeMax(Timestamp.getDefaultInstance().toBuilder().setSeconds(endTime))
        .setServiceName(tracingStartService)
        .build()
}

private fun buildFindTraceRequest(traceQuery: Query.TraceQueryParameters): Query.FindTracesRequest {
    logger.info("building trace request for fetching traces from jaeger")
    return Query.FindTracesRequest.newBuilder().setQuery(traceQuery).build()
}

}

[joe-elliott]

Can you post the full error and stack trace?

[lennartmohr]

io.grpc.StatusRuntimeException: INTERNAL: http2 exception

at io.grpc.Status.asRuntimeException(Status.java:533)
at io.grpc.stub.ClientCalls$BlockingResponseStream.hasNext(ClientCalls.java:606)
at de.intersales.qbus2.JaegerGrpcTest.testFetchTraceStatistics(JaegerGrpcTest.kt:68)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at io.vertx.ext.unit.junit.VertxUnitRunner.invokeTestMethod(VertxUnitRunner.java:93)
at io.vertx.ext.unit.junit.VertxUnitRunner.lambda$invokeExplosively$0(VertxUnitRunner.java:114)
at io.vertx.ext.unit.impl.TestContextImpl.run(TestContextImpl.java:90)
at io.vertx.ext.unit.junit.VertxUnitRunner.invokeExplosively(VertxUnitRunner.java:130)
at io.vertx.ext.unit.junit.VertxUnitRunner.access$000(VertxUnitRunner.java:39)
at io.vertx.ext.unit.junit.VertxUnitRunner$1.evaluate(VertxUnitRunner.java:84)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at io.vertx.ext.unit.junit.VertxUnitRunner$2.evaluate(VertxUnitRunner.java:196)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:220)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:53)

Caused by: io.netty.handler.codec.http2.Http2Exception: First received frame was not SETTINGS. Hex dump for first 5 bytes: 485454502f at io.netty.handler.codec.http2.Http2Exception.connectionError(Http2Exception.java:103) at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.verifyFirstFrameIsSettings(Http2ConnectionHandler.java:338) at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.decode(Http2ConnectionHandler.java:239) at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:438) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:502) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:441) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:278) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:337) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1408) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:359) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:345) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748)

[joe-elliott]

A quick google search suggests that this error is thrown by the HTTP2 stack when connecting to an HTTP service:

https://github.com/grpc/grpc-java/issues/2905

Caused by: io.netty.handler.codec.http2.Http2Exception: First received frame was not SETTINGS. Hex dump for first 5 bytes: 485454502f

Are you sure you're connecting to the right port?

[lennartmohr]

Inside Kubernetes the service is targeting jaeger-query service on port 80. This still works with the 1.18 image but fails with the latest one.

[yurishkuro]

Find startup logs of query service, the ports are printed.

[lennartmohr]

All right, got it now. Thanks guys! Will close this issue!