search

seqeralabs / wave

On-demand containers provisioning service
https://seqera.io/wave/
GNU Affero General Public License v3.0
33 stars 4 forks source link

IOException "HTTP/1.1 header parser received no bytes" #254

Closed pditommaso closed 1 year ago

pditommaso commented 1 year ago

We are seeing an increasing number of the following exception. This is actually reported by the Wave client in Nextflow, but I was wondering if it could be related by some kind of failure on the backend side. 

Jun-20 15:39:56.768 [Actor Thread 70] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 1
java.io.IOException: HTTP/1.1 header parser received no bytes
    at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
    at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
    at io.seqera.wave.plugin.WaveClient$_httpSend_lambda7.doCall(WaveClient.groovy:611)
    at dev.failsafe.Functions.lambda$toCtxSupplier$11(Functions.java:236)
    at dev.failsafe.Functions.lambda$get$0(Functions.java:46)
    at dev.failsafe.internal.RetryPolicyExecutor.lambda$apply$0(RetryPolicyExecutor.java:75)
    at dev.failsafe.SyncExecutionImpl.executeSync(SyncExecutionImpl.java:176)
    at dev.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:437)
    at dev.failsafe.FailsafeExecutor.get(FailsafeExecutor.java:115)
    at io.seqera.wave.plugin.WaveClient.safeApply(WaveClient.groovy:607)
    at io.seqera.wave.plugin.WaveClient.httpSend(WaveClient.groovy:611)
    at io.seqera.wave.plugin.WaveClient.sendRequest0(WaveClient.groovy:222)
    at io.seqera.wave.plugin.WaveClient.sendRequest(WaveClient.groovy:197)
    at io.seqera.wave.plugin.WaveClient.sendRequest(WaveClient.groovy:181)
    at io.seqera.wave.plugin.WaveClient$_fetchContainerImage_closure5.doCall(WaveClient.groovy:458)
    at io.seqera.wave.plugin.WaveClient$_fetchContainerImage_closure5.call(WaveClient.groovy)
    at com.google.common.cache.LocalCache$LocalManualCache$1.load(LocalCache.java:4868)
    at com.google.common.cache.LocalCache$LoadingValueReference.loadFuture(LocalCache.java:3533)
    at com.google.common.cache.LocalCache$Segment.loadSync(LocalCache.java:2282)
    at com.google.common.cache.LocalCache$Segment.lockedGetOrLoad(LocalCache.java:2159)
    at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2049)
    at com.google.common.cache.LocalCache.get(LocalCache.java:3966)
    at com.google.common.cache.LocalCache$LocalManualCache.get(LocalCache.java:4863)
    at io.seqera.wave.plugin.WaveClient.fetchContainerImage(WaveClient.groovy:458)
    at io.seqera.wave.plugin.resolver.WaveContainerResolver.waveContainer(WaveContainerResolver.groovy:109)
    at io.seqera.wave.plugin.resolver.WaveContainerResolver.resolveImage(WaveContainerResolver.groovy:72)
    at jdk.internal.reflect.GeneratedMethodAccessor351.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.codehaus.groovy.runtime.callsite.PlainObjectMetaMethodSite.doInvoke(PlainObjectMetaMethodSite.java:48)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSite.invoke(PogoMetaMethodSite.java:166)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.call(PogoMetaMethodSite.java:69)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:148)
    at nextflow.processor.TaskRun.containerInfo0(TaskRun.groovy:629)
    at jdk.internal.reflect.GeneratedMethodAccessor350.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:107)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:362)
    at org.codehaus.groovy.runtime.callsite.PogoMetaClassSite.callCurrent(PogoMetaClassSite.java:61)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:176)
    at nextflow.processor.TaskRun$_containerInfo_closure7.doCall(TaskRun.groovy:615)
    at jdk.internal.reflect.GeneratedMethodAccessor349.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:107)
    at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:323)
    at org.codehaus.groovy.runtime.metaclass.ClosureMetaClass.invokeMethod(ClosureMetaClass.java:274)
    at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1035)
    at groovy.lang.Closure.call(Closure.java:412)
    at org.codehaus.groovy.runtime.ConvertedClosure.invokeCustom(ConvertedClosure.java:50)
    at org.codehaus.groovy.runtime.ConversionHandler.invoke(ConversionHandler.java:112)
    at jdk.proxy1/jdk.proxy1.$Proxy63.apply(Unknown Source)
    at java.base/java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1708)
    at java.base/jdk.internal.reflect.GeneratedMethodAccessor252.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.codehaus.groovy.runtime.callsite.PlainObjectMetaMethodSite.doInvoke(PlainObjectMetaMethodSite.java:48)
    at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoCachedMethodSiteNoUnwrap.invoke(PojoMetaMethodSite.java:198)
    at org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite.call(PojoMetaMethodSite.java:51)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:148)
    at nextflow.processor.TaskRun.containerInfo(TaskRun.groovy:615)
    at nextflow.processor.TaskRun.getContainer(TaskRun.groovy:637)
    at nextflow.processor.TaskRun.isContainerEnabled(TaskRun.groovy:682)
    at nextflow.processor.TaskRun$isContainerEnabled$8.call(Unknown Source)
    at nextflow.processor.TaskProcessor.createTaskHashKey(TaskProcessor.groovy:2076)
    at jdk.internal.reflect.GeneratedMethodAccessor348.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.codehaus.groovy.runtime.callsite.PlainObjectMetaMethodSite.doInvoke(PlainObjectMetaMethodSite.java:48)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite$PogoCachedMethodSiteNoUnwrapNoCoerce.invoke(PogoMetaMethodSite.java:189)
    at org.codehaus.groovy.runtime.callsite.PogoMetaMethodSite.callCurrent(PogoMetaMethodSite.java:57)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callCurrent(AbstractCallSite.java:185)
    at nextflow.processor.TaskProcessor.invokeTask(TaskProcessor.groovy:618)
    at nextflow.processor.InvokeTaskAdapter.call(InvokeTaskAdapter.groovy:52)
    at groovyx.gpars.dataflow.operator.DataflowOperatorActor.startTask(DataflowOperatorActor.java:120)
    at groovyx.gpars.dataflow.operator.ForkingDataflowOperatorActor.access$001(ForkingDataflowOperatorActor.java:35)
    at groovyx.gpars.dataflow.operator.ForkingDataflowOperatorActor$1.run(ForkingDataflowOperatorActor.java:58)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
    at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
    at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
    at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
    at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
    ... 3 common frames omitted
Caused by: java.io.IOException: Connection timed out
    at java.base/sun.nio.ch.SocketDispatcher.read0(Native Method)
    at java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:47)
    at java.base/sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:330)
    at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:284)
    at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:259)
    at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:417)
    at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)
pditommaso commented 1 year ago

This is becoming an increasing concern since more customers are reporting it.

Context

pditommaso commented 1 year ago

Tagging @jimmypoms in this issue, please team up with @munishchouhan to try to replicate the problem and identify if it's a problem of the JVM. /cc @swampie

munishchouhan commented 1 year ago

I checked Amazon Corretto repo and the JDK bug fix is present in 17.0.7.7.1 https://github.com/corretto/corretto-17/commit/a800231f17a5081de7f2336742faa97b11f12b3b

pditommaso commented 1 year ago

Is that patch also included in this container image quay.io/seqeralabs/nf-launcher:j17-23.04.1? (this is the one the customers use to run nextflow)

munishchouhan commented 1 year ago

no its using version=17.0.6.10-1

Screenshot 2023-06-22 at 12 19 34

https://quay.io/repository/seqeralabs/nf-launcher/manifest/sha256:6743c57c69cb0caee1c5145c2287699550966f59d88dbc6d5d4a7946920b5b64

munishchouhan commented 1 year ago

quay.io/seqeralabs/nf-launcher:j17-23.04.2 contains Amazon corretto 17.0.7.7.1 we can recommend the latest version https://quay.io/repository/seqeralabs/nf-launcher?tab=tags&tag=j17-23.04.2-up1

pditommaso commented 1 year ago

My fail, customers are using quay.io/seqeralabs/nf-launcher:j17-23.04.2.

How do you know it contains that patch for httpclient issue?

munishchouhan commented 1 year ago

because the Java version mentioned in its manifest is 17.0.7.7-1

jimmypoms commented 1 year ago

Following the referenced issue and looking at the log attached there, the interesting bit is that this seems to happen at the /container-token endpoint which, as far as I know, only interacts with tower.

Looking at the logs of wave for the past week, there's a couple of failures that come up for that endpoint (Request exceeded build rate limit, unauthorized, and some others) but I couldn't find anything really suspicious during the time of the error in this ticket (Jun-20 15:39:56.768). I have a suspicion that there might be some code path that doesn't complete the CF nor error. Could it be that the WS failed silently?

On a slightly related note, @pditommaso given that the logging system is taking shape and we have increasingly complex interactions between services, have we considered introducing a correlation id or similar to requests?

pditommaso commented 1 year ago

because the Java version mentioned in its manifest is 17.0.7.7-1

That's clear, but I'm not sure that patch landed into that distribution, or at least I could not find any evidence

given that the logging system is taking shape and we have increasingly complex interactions between services, have we considered introducing a correlation id or similar to requests?

That makes a lot of sense. What's the best practices? any suggestion?

jimmypoms commented 1 year ago

That makes a lot of sense. What's the best practices? any suggestion?

Back in the day, we added a custom filter to our services that took the value from a header if present or created a new id. It wasn't a particularly hard thing to do but special care needed to be taken to propagate the id across threads and adding it to all client interactions. There might be a case for adapting and extending micronaut-tracing as it solves the same problem with propagating the context. I'm happy to discuss approaches outside of the scope of this issue :)

As for the reported issue, I think we would need more cases of it happening and maybe add some further logs in wave. It would be interesting to know whether the issue is isolated to the /container-token endpoint or affects all endpoints in wave.

pditommaso commented 1 year ago

I had seen micronaut tracing, however, it looks like it requires the use of yet another tool such as Zipkin or Jaeger to the deployed and managed. Is it worth using any of those? do you have any experience with them?

jimmypoms commented 1 year ago

Zipkin or Jaeger is used for distributed tracing, which can be quite useful if the setup is microservice heavy for getting better visibility on which services are involved in a request and how long each part of the code takes (spans and whatnot).

For me personally, I never really had a situation where I saw a lot of benefit from the distributed traces when the logging system was properly setup with correlation ids (or trace ids if you will). The main reason I was mentioning it was because of the context propagation of the trace ids, which in a Netty environment can be a bit tricky. Using the ids from tracing for logs is a natural extension, e.g. OpenTelemetry uses trace ids and span ids for log correlation as well :). The TL;DR is I don't think Zipkin or Jaeger is a hard requirement, but I'm not familiar enough with the implementation to say whether micronaut tracing is required for the log correlation to work.

pditommaso commented 1 year ago

Moving on this thread, I agree Zipkin or Jaeger and overkill at least at this stage.

It makes a lot of sense we just add a unique trace ID in each request. How wonder however if there's a nice to make Grafana aware of it, so that it's rendered in the context of the log

Screenshot 2023-07-03 at 16 20 21

tagging @ashseqera

jimmypoms commented 1 year ago

I'm no expert in Loki, but using structured logging (either json or any other format) we should be able to add filterable information to every log line without the need to add them as labels. Something like {app=~"wave-app|tower|..."} |= "<traceId>". With a small enough time range the performance should be reasonable as well.

In previous setups, we added links to the logging system with reasonable queries and time ranges to the alerts via prometheus's templating. It is not the most intuitive thing to do, but it worked quite nicely.

I hope I understood your wonders correctly :)

pditommaso commented 1 year ago

We have more customers reporting this issue. The weird thing is that it looks like the problem persists even after several retries. Have a look at this log 

Jul-21 16:46:56.648 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave request: https://wave.seqera.io/container-token; attempt=1 - request: SubmitContainerTokenRequest(towerAccessToken:eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiI3MTM0IiwibmJmIjoxNjg5OTU2NjMxLCJyb2xlcyI6WyJ1c2VyIl0sImlzcyI6InRvd2VyLWFwcCIsImV4cCI6MTY4OTk2MDIzMSwiaWF0IjoxNjg5OTU2NjMxfQ.gvGEqrw_UAE5E9kiL_Z3kncfol7XlIApfSpRqWcx2NM, towerRefreshToken:eyJhbGciOiJIUzI1NiJ9.MzIyMmUwMDQtNmI0My00NTYxLThiZTYtMjNkYTJhMzM4OWVh.kbF3kvzyf9U6p1bl6mN9Czf8mrfbiNbgKIB1qbXYu8Q, towerWorkspaceId:152124791902294, towerEndpoint:https://api.tower.nf, workflowId:3lnmizDUUT1IFN, containerImage:quay.io/biocontainers/samtools:1.17--hd87286a_1, containerFile:null, containerConfig:ContainerConfig(entrypoint:[/usr/bin/fusion], cmd:null, env:null, workingDir:null, layers:[ContainerLayer[location=data:H4sIAAAAAAAA/+19/3/a...; tarDigest=sha256:86acae9631a0b7837ff24f5e7788895fefc371b92812e9af517bd16140707dbb; gzipDigest=sha256:84a80a1980647a25501bfb17365ac704e662dab6773c24af84cfb8b5ff50c484; gzipSize=16814], ContainerLayer[location=https://fusionfs.seqera.io/releases/pkg/2/2/5/fusion-amd64.tar.gz; tarDigest=sha256:dd2bdf431d905025443cf89bf7ac15f1d3deb94d0a5333373f23adbc02fe0035; gzipDigest=sha256:d00a4281864b3252d86c6d9edf131dbea6feb4e6e80264dc160aee2745fbe580; gzipSize=15112427]]), condaFile:null, spackFile:null, containerPlatform:linux/amd64, buildRepository:null, cacheRepository:null, timestamp:2023-07-21T16:46:56.648279294Z, fingerprint:d14debb7001bf14e51f6a52aceb2f7c3)
Jul-21 16:46:56.806 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 1
java.io.IOException: HTTP/1.1 header parser received no bytes

Jul-21 16:46:57.112 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 2
java.io.IOException: HTTP/1.1 header parser received no bytes

Jul-21 16:46:57.738 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 3
java.io.IOException: HTTP/1.1 header parser received no bytes

Jul-21 16:46:58.707 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 4
java.io.IOException: HTTP/1.1 header parser received no bytes

Looking more in the cause of the exception it seems that's not always the same tho related 

Jul-21 16:46:56.648 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave request: https://wave.seqera.io/container-token; attempt=1 - request: SubmitContainerTokenRequest(towerAccessToken:eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiI3MTM0IiwibmJmIjoxNjg5OTU2NjMxLCJyb2xlcyI6WyJ1c2VyIl0sImlzcyI6InRvd2VyLWFwcCIsImV4cCI6MTY4OTk2MDIzMSwiaWF0IjoxNjg5OTU2NjMxfQ.gvGEqrw_UAE5E9kiL_Z3kncfol7XlIApfSpRqWcx2NM, towerRefreshToken:eyJhbGciOiJIUzI1NiJ9.MzIyMmUwMDQtNmI0My00NTYxLThiZTYtMjNkYTJhMzM4OWVh.kbF3kvzyf9U6p1bl6mN9Czf8mrfbiNbgKIB1qbXYu8Q, towerWorkspaceId:152124791902294, towerEndpoint:https://api.tower.nf, workflowId:3lnmizDUUT1IFN, containerImage:quay.io/biocontainers/samtools:1.17--hd87286a_1, containerFile:null, containerConfig:ContainerConfig(entrypoint:[/usr/bin/fusion], cmd:null, env:null, workingDir:null, layers:[ContainerLayer[location=data:H4sIAAAAAAAA/+19/3/a...; tarDigest=sha256:86acae9631a0b7837ff24f5e7788895fefc371b92812e9af517bd16140707dbb; gzipDigest=sha256:84a80a1980647a25501bfb17365ac704e662dab6773c24af84cfb8b5ff50c484; gzipSize=16814], ContainerLayer[location=https://fusionfs.seqera.io/releases/pkg/2/2/5/fusion-amd64.tar.gz; tarDigest=sha256:dd2bdf431d905025443cf89bf7ac15f1d3deb94d0a5333373f23adbc02fe0035; gzipDigest=sha256:d00a4281864b3252d86c6d9edf131dbea6feb4e6e80264dc160aee2745fbe580; gzipSize=15112427]]), condaFile:null, spackFile:null, containerPlatform:linux/amd64, buildRepository:null, cacheRepository:null, timestamp:2023-07-21T16:46:56.648279294Z, fingerprint:d14debb7001bf14e51f6a52aceb2f7c3)
Jul-21 16:46:56.806 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 1
java.io.IOException: HTTP/1.1 header parser received no bytes
    at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
    at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
  ...
Caused by: java.io.IOException: Connection reset by peer
    at java.base/sun.nio.ch.FileDispatcherImpl.writev0(Native Method)
    at java.base/sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:66)
    at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:217)
    at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:153)
    at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:563)
    at java.base/java.nio.channels.SocketChannel.write(SocketChannel.java:642)
    at java.net.http/jdk.internal.net.http.SocketTube.writeAvailable(SocketTube.java:1236)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalWriteSubscriber.tryFlushCurrent(SocketTube.java:350)
    ... 154 common frames omitted

Jul-21 16:46:57.112 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 2
java.io.IOException: HTTP/1.1 header parser received no bytes
    at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
    at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
    ...
Caused by: java.net.SocketException: Connection reset
    at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
    at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
    at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)

Jul-21 16:46:57.738 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 3
java.io.IOException: HTTP/1.1 header parser received no bytes
    at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
    at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
    ...
Caused by: java.net.SocketException: Connection reset
    at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
    at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
    at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
    at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)

Jul-21 16:46:58.707 [Actor Thread 93] DEBUG io.seqera.wave.plugin.WaveClient - Wave connection failure - attempt: 4
java.io.IOException: HTTP/1.1 header parser received no bytes
    at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:586)
    at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:123)
    ...
Caused by: java.io.EOFException: EOF reached while reading
    ... 21 common frames omitted

The first time says Connection reset by peer, then twice Connection reset and finally EOF reached while reading

This makes me think there's some instability on the backend side. @munishchouhan @jimmypoms thoughts?

pditommaso commented 1 year ago

I wonder if the lack of @ExecuteOn(TaskExecutors.IO) could be related to this problem.

https://docs.micronaut.io/latest/guide/#atBlocking https://docs.micronaut.io/latest/api/io/micronaut/scheduling/annotation/ExecuteOn.html

munishchouhan commented 1 year ago

We can do load testing to check if it's failing because of the lack of threads using tools like JMeter or Load runner We can target staging, or if there is a dev environment which is connected to tower

pditommaso commented 1 year ago

The stage environment can be used for that wave.stage-tower.net. You may want to coordinate with @jimmypoms

pditommaso commented 1 year ago

Note, I've added @ExecuteOn IO thread pool e0c95a02

pditommaso commented 1 year ago

Another point to clarify is that @Cacheable applied to a CompletableFuture is thread-safe

https://github.com/seqeralabs/wave/blob/1546fe5925ca801d48865a650824e979f353604d/src/main/groovy/io/seqera/wave/tower/client/TowerClient.groovy#L42-L64

munishchouhan commented 1 year ago

To run the load testing, I need the following information:

  1. How can I create a valid request to /container-token',?
  2. Where can I check wave and tower staging logs?
pditommaso commented 1 year ago

How can I create a valid request to /container-token',?

That's the request made by nextflow to get the container, you can see in the nextflow log

Jul-20 15:23:24.594 [Actor Thread 5] DEBUG io.seqera.wave.plugin.WaveClient - Wave request: https://wave.seqera.io/container-token; attempt=1 - request: SubmitContainerTokenRequest(towerAccessToken:eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiI3IiwibmJmIjoxNjg5ODY2NDIzLCJyb2xlcyI6WyJ1c2VyIl0sImlzcyI6InRvd2VyLWFwcCIsImV4cCI6MTY4OTg3MDAyMywiaWF0IjoxNjg5ODY2NDIzfQ.mtw-FjLSI4ReDb_qTwXNwlDl7ikNVym6wSOyebaB5Hs, towerRefreshToken:eyJhbGciOiJIUzI1NiJ9.YjMxOWYzYzktMmNmOS00MjI4LTg3MWItN2JhMmNiNjMwMmRh.dgqigV9KUuDQTojSL7K7I7Lfc7UVXSe9uPeQ-fZLkmc, towerWorkspaceId:263146567680457, towerEndpoint:https://tower.modernatx.net/api, workflowId:26EmPAhz4e97RI, containerImage:quay.io/biocontainers/python:3.8.3, containerFile:null, containerConfig:ContainerConfig(entrypoint:[/usr/bin/fusion], cmd:null, env:null, workingDir:null, layers:[ContainerLayer[location=data:H4sIAAAAAAAA/+1a63Pb...; tarDigest=sha256:8875ce90433dadeea031f06955d2210ad2bc044d002e85f3f193a8f51300eb18; gzipDigest=sha256:8a4b3def6aa92a12a077f085de90dcae7ba9dc971f17c4ce117b2cb029d3249a; gzipSize=3388], ContainerLayer[location=https://fusionfs.seqera.io/releases/pkg/2/1/14/fusion-amd64.tar.gz; tarDigest=sha256:b7f7e82e26b1b49337a5581c186ac327965559dbc668ff61f94abe24b5356c81; gzipDigest=sha256:dc2af1c65a55bbe0870b44ff5e322ca5937ba035232316a430c9e556b84d1f6c; gzipSize=14218941]]), condaFile:null, containerPlatform:null, buildRepository:null, cacheRepository:null, timestamp:2023-07-20T15:23:24.592881144Z, fingerprint:7c5901d337e3229c9e90f94c010b0aae)

You can emulate it also using, the command 

nextflow plugins nf-wave:get-container <container>

or by using the wavelit CLI

jimmypoms commented 1 year ago

Do we have access to the redis cluster that is used as the broker for the WebSocket handling?

I'm wondering whether we could quickly check if we have stale entries there. That would help to clarify whether there's something off in handling the request/response flow.

pditommaso commented 1 year ago

When that happens, this error is reported (and the entries are evicted in any case from redis)

https://github.com/seqeralabs/wave/blob/1546fe5925ca801d48865a650824e979f353604d/src/main/groovy/io/seqera/wave/service/data/future/AbstractFutureStore.groovy#L66-L66

There are a couple of events in the log but they do not seem raised by customer usage

Screenshot 2023-07-24 at 16 55 51
jimmypoms commented 1 year ago

I saw that piece, but as you know, the whole WebSocket session handling is a bit on the complex side :innocent: ... instead of relying on the logs of the behaviour we expect to happen, my suggestion here is to try to find evidence that gives us a better understanding of what might be going wrong, especially if it something as easy as looking at data at rest in tower cloud.

We are currently a little bit in the guessing game with this one after all :/

pditommaso commented 1 year ago

I know, in any case in redis you won't anything because messages are evicted after a while. I think the best thing to do is to try to replicate it as suggest by Munish

jimmypoms commented 1 year ago

Not sure about that. We don't set a TTL on the list used as a queue. Neither do we set one on the mark, nor do we do anything with the heartbeat :shrug:

munishchouhan commented 1 year ago

I have seen the error in Tower. I am unsure if it's relevant because it doesn't happen at the time of the above error.

Screenshot 2023-07-26 at 16 04 03
pditommaso commented 1 year ago

On the client side i.e. nextflow what error are you getting instead?

munishchouhan commented 1 year ago

On the client side i.e. nextflow what error are you getting instead?

I don't see in error again in my local tower, I will post the client once it happens again

But I have something interesting, the same IOException but in Tower this time:

command ran 500 times nextflow plugin nf-wave:get-container biocontainers/samtools

Tower Log

Jul-26 17:39:42.552 [ForkJoinPool.commonPool-worker-1] - ERROR io.seqera.wave.PairingClient - Unexpected error proxing request https://1a583bf0283a.ngrok.app/api/user-info GET -- cause: java.io.IOException: HTTP/1.1 header parser received no bytes
java.util.concurrent.CompletionException: java.io.IOException: HTTP/1.1 header parser received no bytes
        at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368)
        at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:377)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1152)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
        at java.net.http/jdk.internal.net.http.Http1Response.onReadError(Http1Response.java:554)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:676)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
        at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
        ... 8 common frames omitted
Caused by: java.net.SocketException: Connection reset
        at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
        at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
        at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1170)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:833)
        at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:181)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:774)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:957)
        at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:253)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:979)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:934)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:934)

Error in Nextflow:

WARN: Can't update history file: .nextflow/history
ERROR ~ Unexpected error on command: get-container - cause: java.net.http.HttpConnectTimeoutException: HTTP connect timed out

ERROR ~ Unexpected error on command: get-container - cause: Wave invalid response: [408] {"message":"Timeout error connecting to 'https://1a583bf0283a.ngrok.app/api' - HTTP status=408"}

No log in wave

munishchouhan commented 1 year ago

io.seqera.wave.PairingClient is a websocket client

https://github.com/seqeralabs/nf-tower-cloud/blob/master/tower-enterprise/src/main/groovy/io/seqera/wave/PairingClient.groovy

So the the error in question maybe related to Websocket connection

pditommaso commented 1 year ago

This is interesting. Don't think it's related to websocket connection. The websocket connection is used by Wave to execute remotely (ie. in your tower instance) the http requests required by it. Precisely here

https://github.com/seqeralabs/nf-tower-cloud/blob/5e71cf6e5ae738cba9240d720a65ff4c728713c4/tower-enterprise/src/main/groovy/io/seqera/wave/PairingClient.groovy#L91-L110

You are using Java 17, right? it could be interesting to run tower with Corretto 20.0.2, to verify if it's really the issue mentioned here

pditommaso commented 1 year ago

Weird however that the exception in Tower is tracked here and the exception message is java.io.IOException: HTTP/1.1 header parser received no bytes

The same error message is sent back to Wave here, however, looking in the Wave logs there's no mention of that error. weird.

munishchouhan commented 1 year ago

I am using openjdk version "17.0.5" I will try with Corretto 20.0.2

pditommaso commented 1 year ago

I've restarted Wave on stage adding more detailed log level

munishchouhan commented 1 year ago

There are no occurrences IOException in Tower with Corretto 20.0.2. I ran the test twice to confirm the same No Exception in wave only Nextflow is throwing the below error few times ERROR ~ Unexpected error on command: get-container - cause: java.net.http.HttpConnectTimeoutException: HTTP connect timed out

pditommaso commented 1 year ago

Have you use Wave in the stage server? I don't anything in the logs 

e-64d8f75d69-62gst wave-app 18:50:08.677 [default-nioEventLoopGroup-2-5] DEBUG i.s.w.s.p.socket.PairingWebSocket - Opening pairing session - endpoint: https://61030ed345a9.ngrok.app/api [sessionId: hENH4EpvfL7xMPL5tpGg7g==]
wave-64d8f75d69-62gst wave-app 18:50:08.678 [default-nioEventLoopGroup-2-5] DEBUG i.s.w.s.pairing.PairingServiceImpl - Pairing with service 'tower' at address https://61030ed345a9.ngrok.app/api - pairing id: 170885731970145 (key: 4eabad314c8900f5c3f1f649e6d45a63)
wave-64d8f75d69-62gst wave-app 19:05:01.956 [default-nioEventLoopGroup-2-2] DEBUG i.s.w.s.p.socket.PairingWebSocket - Opening pairing session - endpoint: https://api.stage-tower.net [sessionId: QY6rkT36hpMB/SJroxUyew==]
wave-64d8f75d69-62gst wave-app 19:05:04.368 [default-nioEventLoopGroup-2-4] DEBUG i.s.w.s.p.socket.PairingWebSocket - Closing pairing session - endpoint: https://api.stage-tower.net [sessionId: U9U23pxXkv1aud58tQjOGg==]
wave-64d8f75d69-62gst wave-app 19:21:21.271 [default-nioEventLoopGroup-2-5] DEBUG i.s.w.s.p.socket.PairingWebSocket - Closing pairing session - endpoint: https://61030ed345a9.ngrok.app/api [sessionId: hENH4EpvfL7xMPL5tpGg7g==]
wave-64d8f75d69-62gst wave-app 19:27:30.260 [default-nioEventLoopGroup-2-7] DEBUG i.s.w.s.p.socket.PairingWebSocket - Opening pairing session - endpoint: https://61030ed345a9.ngrok.app/api [sessionId: ODky5IUzB5otlTS2+m1qGQ==]
wave-64d8f75d69-62gst wave-app 19:55:58.310 [default-nioEventLoopGroup-2-7] DEBUG i.s.w.s.p.socket.PairingWebSocket - Closing pairing session - endpoint: https://61030ed345a9.ngrok.app/api [sessionId: ODky5IUzB5otlTS2+m1qGQ==]
munishchouhan commented 1 year ago

Yes i am using wave stage server

pditommaso commented 1 year ago

There are no logs 🤔

munishchouhan commented 1 year ago

pairing in tower logs:

Jul-26 21:27:24.957 [default-nioEventLoopGroup-8-2] DEBUG io.seqera.wave.PairingManager - Wave pairing scheduling re-connect
Jul-26 21:27:29.985 [scheduled-executor-thread-17] DEBUG io.seqera.wave.PairingManager - Wave pairing to https://wave.stage-tower.net/pairing/tower/token/bdf66cce1f8a3668289cc351dcf933daac53bf568d3eadfc67f90d7b994cbc4e?endpoint=https%3A%2F%2F61030ed345a9.ngrok.app%2Fapi

and this is my nextflow.config, where i amrunning the tests:

tower {
  endpoint = 'https://61030ed345a9.ngrok.app/api'  
  enabled = true
}

wave {
  endpoint = 'https://wave.stage-tower.net'
  enabled = true
}

docker {
  enabled = true
}
munishchouhan commented 1 year ago

there is no logging in @Get('/container-token/{token}') endpoint https://github.com/seqeralabs/wave/blob/735b765e9841e0c0a06bd5bc9a331a3ebd986875/src/main/groovy/io/seqera/wave/controller/ContainerTokenController.groovy#L121

pditommaso commented 1 year ago

Can you upload the nextflow log file?

munishchouhan commented 1 year ago

Now this is weird, there are no Nextflow log gets generated for nextflow plugin nf-wave:get-container biocontainers/samtools But I have console out: nohup.log

munishchouhan commented 1 year ago

I have seen the error in Tower. I am unsure if it's relevant because it doesn't happen at the time of the above error.

Screenshot 2023-07-26 at 16 04 03

This error is in wave and not in tower.

pditommaso commented 1 year ago 
nextflow -log .nextflow.log plugin nf-wave:get-container biocontainers/samtools
munishchouhan commented 1 year ago
  1. Nextflow log with ERROR ~ Unexpected error on command: get-container - cause: Wave invalid response: [408] {"message":"Timeout error connecting to 'https://a7a83a94a9b8.ngrok.app/api' - HTTP status=408"} 30.log
  2. Nextflow log with ERROR ~ Unexpected error on command: get-container - cause: java.net.http.HttpConnectTimeoutException: HTTP connect timed out 34.log
munishchouhan commented 1 year ago

In this testing attempt, Tower still throws java.util.concurrent.CompletionException: java.io.IOException: HTTP/1.1 header parser received no bytes with Corretto-20.0.2.9.1 attaching part of tower, where error is occuring tower.log

pditommaso commented 1 year ago

Ok, then we can rule out that's a problem with the JVM.

Can try adding the annotation @ExecuteOn(TaskExecutors.IO) to the /user-info endpoint here

https://github.com/seqeralabs/nf-tower-cloud/blob/3ad005e6b6ff36b6399f2518cd7d9f50db654024/tower-services/src/main/groovy/io/seqera/tower/controller/UserController.groovy#L110-L121

munishchouhan commented 1 year ago

Still there is error: Nextflow logs: 4.log 24.log

Tower Error:

Jul-27 17:40:47.637 [ForkJoinPool.commonPool-worker-5] - ERROR io.seqera.wave.PairingClient - Unexpected error proxing request https://46941462849d.ngrok.app/api/user-info GET -- cause: java.io.IOException: HTTP/1.1 header parser received no bytes
java.util.concurrent.CompletionException: java.io.IOException: HTTP/1.1 header parser received no bytes
        at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368)
        at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:377)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1152)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
        at java.net.http/jdk.internal.net.http.Http1Response.onReadError(Http1Response.java:554)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:676)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$DelegatingExecutor.execute(HttpClientImpl.java:157)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:305)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:274)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.onReadError(Http1AsyncReceiver.java:511)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:596)
        at java.net.http/jdk.internal.net.http.common.SSLTube$DelegateWrapper.onComplete(SSLTube.java:276)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.complete(SSLTube.java:440)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onComplete(SSLTube.java:541)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.checkCompletion(SubscriberWrapper.java:472)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:334)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:259)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:232)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:513)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:268)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
        at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
        ... 30 common frames omitted
Caused by: java.io.EOFException: EOF reached while reading
        ... 21 common frames omitted
Jul-27 17:40:47.659 [ForkJoinPool.commonPool-worker-3] - ERROR io.seqera.wave.PairingClient - Unexpected error proxing request https://46941462849d.ngrok.app/api/user-info GET -- cause: java.io.IOException: HTTP/1.1 header parser received no bytes
java.util.concurrent.CompletionException: java.io.IOException: HTTP/1.1 header parser received no bytes
        at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368)
        at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:377)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1152)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
        at java.net.http/jdk.internal.net.http.Http1Response.onReadError(Http1Response.java:554)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:676)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:302)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:268)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$DelegatingExecutor.execute(HttpClientImpl.java:157)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:305)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:274)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.onReadError(Http1AsyncReceiver.java:511)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:596)
        at java.net.http/jdk.internal.net.http.common.SSLTube$DelegateWrapper.onComplete(SSLTube.java:276)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.complete(SSLTube.java:440)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onComplete(SSLTube.java:541)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.checkCompletion(SubscriberWrapper.java:472)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:334)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:259)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:232)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:513)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:268)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.io.IOException: HTTP/1.1 header parser received no bytes
        at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:348)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:675)
        ... 30 common frames omitted
Caused by: java.io.EOFException: EOF reached while reading
        ... 21 common frames omitted
Jul-27 17:41:22.557 [scheduled-executor-thread-7] - TRACE io.seqera.wave.PairingClient - Sending Wave client heartbeat
Jul-27 17:41:23.420 [default-nioEventLoopGroup-8-2] - TRACE io.seqera.wave.PairingClient - Received Heartbeat message=PairingHeartbeat(msgId:ff2300751308)
Jul-27 17:41:23.608 [ForkJoinPool.commonPool-worker-3] - ERROR io.seqera.wave.PairingClient - Unexpected error proxing request https://46941462849d.ngrok.app/api/user-info GET -- cause: javax.net.ssl.SSLHandshakeException: Remote host terminated the handshake
java.util.concurrent.CompletionException: javax.net.ssl.SSLHandshakeException: Remote host terminated the handshake
        at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368)
        at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:377)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1152)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1773)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: javax.net.ssl.SSLHandshakeException: Remote host terminated the handshake
        at java.net.http/jdk.internal.net.http.common.SSLTube.checkForHandshake(SSLTube.java:595)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onComplete(SSLTube.java:536)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.checkCompletion(SubscriberWrapper.java:472)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:334)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:259)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:232)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:513)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:268)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        ... 3 common frames omitted
Jul-27 17:41:23.606 [ForkJoinPool.commonPool-worker-5] - ERROR io.seqera.wave.PairingClient - Unexpected error proxing request https://46941462849d.ngrok.app/api/user-info GET -- cause: javax.net.ssl.SSLHandshakeException: Remote host terminated the handshake
java.util.concurrent.CompletionException: javax.net.ssl.SSLHandshakeException: Remote host terminated the handshake
        at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368)
        at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:377)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1152)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
        at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1773)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: javax.net.ssl.SSLHandshakeException: Remote host terminated the handshake
        at java.net.http/jdk.internal.net.http.common.SSLTube.checkForHandshake(SSLTube.java:595)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onComplete(SSLTube.java:536)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.checkCompletion(SubscriberWrapper.java:472)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:334)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:259)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:303)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:256)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:232)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:513)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:268)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:205)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:230)
        ... 3 common frames omitted