search

loki4j / loki-logback-appender

Fast and lightweight implementation of Logback appender for Grafana Loki
https://loki4j.github.io/loki-logback-appender/
BSD 2-Clause "Simplified" License
300 stars 26 forks source link

Sending logs to Grafana Cloud via JavaHttpClient fails with "Received RST_STREAM: Protocol error" on JDK 11.0.14 #132

Closed nehaev closed 2 years ago

nehaev commented 2 years ago

On JDK 11.0.13 everything worked fine, but after switching to JDK 11.0.14, the CI started to fail on Grafana Cloud integration test:

22:39:09,475 |-ERROR in com.github.loki4j.client.pipeline.DefaultPipeline@502efa63 - Error while sending Batch #32fa6944ba (60,813 bytes) to Loki (https://logs-prod-us-central1.grafana.net/loki/api/v1/push) java.io.IOException: Received RST_STREAM: Protocol error
        at java.io.IOException: Received RST_STREAM: Protocol error
        at  at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:565)
        at  at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:119)
        at  at com.github.loki4j.client.http.JavaHttpClient.send(JavaHttpClient.java:66)
        at  at com.github.loki4j.client.pipeline.DefaultPipeline.sendBatch(DefaultPipeline.java:263)
        at  at com.github.loki4j.client.pipeline.DefaultPipeline.sendStep(DefaultPipeline.java:249)
        at  at com.github.loki4j.client.pipeline.DefaultPipeline.runSendLoop(DefaultPipeline.java:183)
        at  at com.github.loki4j.client.pipeline.DefaultPipeline.lambda$start$2(DefaultPipeline.java:108)
        at  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at  at java.base/java.lang.Thread.run(Thread.java:829)
    Caused by: java.io.IOException: Received RST_STREAM: Protocol error
        at  at java.net.http/jdk.internal.net.http.Stream.handleReset(Stream.java:504)
        at  at java.net.http/jdk.internal.net.http.Stream.schedule(Stream.java:178)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
        at  at java.net.http/jdk.internal.net.http.Stream.receiveResetFrame(Stream.java:336)
        at  at java.net.http/jdk.internal.net.http.Stream.incoming_reset(Stream.java:482)
        at  at java.net.http/jdk.internal.net.http.Stream.otherFrame(Stream.java:418)
        at  at java.net.http/jdk.internal.net.http.Stream.incoming(Stream.java:408)
        at  at java.net.http/jdk.internal.net.http.Http2Connection.processFrame(Http2Connection.java:801)
        at  at java.net.http/jdk.internal.net.http.frame.FramesDecoder.decode(FramesDecoder.java:155)
        at  at java.net.http/jdk.internal.net.http.Http2Connection$FramesController.processReceivedData(Http2Connection.java:232)
        at  at java.net.http/jdk.internal.net.http.Http2Connection.asyncReceive(Http2Connection.java:663)
        at  at java.net.http/jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.processQueue(Http2Connection.java:1292)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
        at  at java.net.http/jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.runOrSchedule(Http2Connection.java:1310)
        at  at java.net.http/jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.onNext(Http2Connection.java:1336)
        at  at java.net.http/jdk.internal.net.http.Http2Connection$Http2TubeSubscriber.onNext(Http2Connection.java:1270)
        at  at java.net.http/jdk.internal.net.http.common.SSLTube$DelegateWrapper.onNext(SSLTube.java:202)
        at  at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onNext(SSLTube.java:484)
        at  at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onNext(SSLTube.java:287)
        at  at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:318)
        at  at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:261)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
        at  at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:234)
        at  at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:200)
        at  at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:403)
        at  at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:264)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
        at  at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
        at  ... 3 common frames omitted

I guess the same behavior is likely to reproduce on JDK 17.0.2 (not available on CI yet).

Apart from that, log query code that is used for tests only started to fail with timeouts.

nehaev commented 2 years ago

Hotfix applied in #131 was to explicitly configure JavaHttpClient to run HTTP/1.1 queries instead of HTTP/2.0 by default.

var client = HttpClient
                .newBuilder()
                .version(Version.HTTP_1_1)
                .build();
abouquet commented 2 years ago

I encounter this issue beeing also on 11.0.14 with the following jdk

openjdk version "11.0.14" 2022-01-18
OpenJDK Runtime Environment Temurin-11.0.14+9 (build 11.0.14+9)
OpenJDK 64-Bit Server VM Temurin-11.0.14+9 (build 11.0.14+9, mixed mode)

After upgrading to 1.3.1, still have the issue. Do you mean you have only corrected the IT and not the lib ?

nehaev commented 2 years ago

Hi @abouquet! I've published the fix in v1.3.2. Please upgrade.

nehaev commented 2 years ago

Though it still seems to me as JDK bug, I'll stick with a fix on loki4j side for now. Closing the issue.

abouquet commented 2 years ago

Hi @abouquet! I've published the fix in v1.3.2. Please upgrade.

Thanks ! Will try it asap :)