search

http4s / blaze

Blazing fast NIO microframework and Http Parser
Apache License 2.0
350 stars 63 forks source link

"Bad HTTP version" in blaze-client #645

Open rintcius opened 4 years ago

rintcius commented 4 years ago

We are getting exceptions like below after trying to upgrade to v0.20.10. 

Bad HTTP version: DSLU":
org.http4s.blaze.http.parser.BaseExceptions$BadMessage: Bad HTTP version: DSLU":
        at org.http4s.blaze.http.parser.Http1ClientParser.parseResponseLine(Http1ClientParser.java:122) ~[blaze-http_2.12-0.14.8.jar:0.14.8]
        at org.http4s.client.blaze.BlazeHttp1ClientParser.finishedResponseLine(BlazeHttp1ClientParser.scala:49) ~[http4s-blaze-client_2.12-0.20.10.jar:0.20.10]
        at org.http4s.client.blaze.Http1Connection.parsePrelude(Http1Connection.scala:208) ~[http4s-blaze-client_2.12-0.20.10.jar:0.20.10]
        at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1(Http1Connection.scala:189) ~[http4s-blaze-client_2.12-0.20.10.jar:0.20.10]
        at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1$adapted(Http1Connection.scala:188) ~[http4s-blaze-client_2.12-0.20.10.jar:0.20.10]
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60) [scala-library-2.12.1.jar:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_131]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]

After investigation it turns out to be caused by http4s/http4s#2458: In my reproduction, curling a particular request on v0.20.10 results in the above exception every other request, the other half goes ok. See https://gist.github.com/rintcius/f01dfe9e113458dbd0df530783cbddc2 for the error.log and ok.log. Using v0.20.10 with http4s/http4s#2458 reverted these requests return ok.

rintcius commented 4 years ago

FYI just tried: with AsyncHttpClient on v0.20.10 it's running ok.

daddykotex commented 3 years ago

I'm writing a small app to extract something from a web page. I have failures on occasion and it looks like this one but it may not be exactly the same:

org.http4s.blaze.http.parser.BaseExceptions$BadMessage: Bad HTTP version:
0

HTTP/1.1
    at org.http4s.blaze.http.parser.Http1ClientParser.parseResponseLine(Http1ClientParser.java:135)
    at org.http4s.client.blaze.BlazeHttp1ClientParser.finishedResponseLine(BlazeHttp1ClientParser.scala:56)
    at org.http4s.client.blaze.Http1Connection.parsePrelude(Http1Connection.scala:214)
    at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1(Http1Connection.scala:196)
    at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1$adapted(Http1Connection.scala:195)
    at async @ org.http4s.client.blaze.Http1Connection.receiveResponse(Http1Connection.scala:185)

I believe it may be related to HTTPS. The website I'm trying to scrape serves content over HTTPS. In an attempt to debug this failure (that I could not reproduce in a test) I lauched a proxy in between me and the service. The goal was to sniff the exchange between my app and the proxy (raw http) to see if there was an obvious problem.

After starting the proxy and sending my request through it, I could never reproduce the issue. I never had a problem in a browser either so I suppose something wrong happen when parsing the encrypted messages.

daddykotex commented 3 years ago

Using AsyncHttpClient.resource[IO]() also works.

rossabaker commented 3 years ago

Which JVM? We've seen some quirks with SSL and Blaze on Java 11, starting around Java 11.0.3.

daddykotex commented 3 years ago

If I run the main via sbt, can I assume what sbt tells me is true? If yes: 1.8:

sbt
[info] welcome to sbt 1.4.2 (AdoptOpenJDK Java 1.8.0_265)

I'm on a Mac, 10.15.7

rossabaker commented 3 years ago

That should be correct, yes.

Reverting http4s/http4s#2458 would have a terrible effect on performance: we need it for connection reuse. But there appears to be some sort of a race condition on recycling that connection. A reliable, public reproduction would help a lot here.

daddykotex commented 3 years ago

Ok, I'll work a bit on trying to reproduce, I do only a few simple queries, one after the others, but the service require a login so I'll try to do it on another website.

daddykotex commented 3 years ago

I wrote a reproduction program. It's a part of the other ebox-cli module, but it can be run independently.

https://github.com/daddykotex/ebox/tree/4bcf44065b891023c89324eae5677c077dc73058/blaze-repro/src/main/scala/blaze

Here's the result:

➜  ebox git:(main) ✗ sbt "blazeRepro/run"
[info] welcome to sbt 1.4.2 (AdoptOpenJDK Java 1.8.0_265)
[info] loading settings for project global-plugins from sbt-updates.sbt ...
[info] loading global plugins from /Users/david/.sbt/1.0/plugins
[info] loading settings for project ebox-build-build-build from metals.sbt ...
[info] loading project definition from /Users/david/workspace/ebox/project/project/project
[info] loading settings for project ebox-build-build from metals.sbt ...
[info] loading project definition from /Users/david/workspace/ebox/project/project
[success] Generated .bloop/ebox-build-build.json
[success] Total time: 0 s, completed 24-Nov-2020 11:08:15 PM
[info] loading settings for project ebox-build from metals.sbt,plugins.sbt ...
[info] loading project definition from /Users/david/workspace/ebox/project
[success] Generated .bloop/ebox-build.json
[success] Total time: 0 s, completed 24-Nov-2020 11:08:16 PM
[info] loading settings for project root from build.sbt ...
[info] set current project to ebox (in build file:/Users/david/workspace/ebox/)
[warn] There may be incompatibilities among your library dependencies; run 'evicted' to see detailed eviction warnings.
[info] running (fork) blaze.Main
[error] SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
[error] SLF4J: Defaulting to no-operation (NOP) logger implementation
[error] SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
[info] Error occurred on 1 attempt.
[error] org.http4s.blaze.http.parser.BaseExceptions$BadMessage: Bad HTTP version:
[error] 0
[error] HTTP/1.1
[error]     at org.http4s.blaze.http.parser.Http1ClientParser.parseResponseLine(Http1ClientParser.java:135)
[error]     at org.http4s.client.blaze.BlazeHttp1ClientParser.finishedResponseLine(BlazeHttp1ClientParser.scala:56)
[error]     at org.http4s.client.blaze.Http1Connection.parsePrelude(Http1Connection.scala:214)
[error]     at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1(Http1Connection.scala:196
[error]     at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1$adapted(Http1Connection.scala:195)
[error]     at async @ org.http4s.client.blaze.Http1Connection.receiveResponse(Http1Connection.scala:185)
[error]     at $greater$greater$extension @ org.http4s.client.blaze.Http1Connection.$anonfun$executeRequest$2(Http1Connection.scala:168)
[error]     at main$ @ blaze.Main$.main(main.scala:11)
[error] Nonzero exit code returned from runner: 1
[error] (blazeRepro / Compile / run) Nonzero exit code returned from runner: 1
[error] Total time: 14 s, completed 24-Nov-2020 11:08:31 PM

In short my program attempt a login, and it seems to fail on the 302 redirect received:

I could not reproduce with just GET requests to some random https websites.

rossabaker commented 3 years ago

Excellent, thank you! I'll see what I can do with this over the US holiday break.

daddykotex commented 3 years ago

If you have a high level plan for debugging, I would be happy to help. I'm just very unfamiliar with the SSL shenanigans on the JVM.

If you tell me, for example,:

  1. active X flag to enable tracing (or whatever debugging config)
  2. build a new (local) version of the client with extra debugging flags

I can probably help and you'd know more before starting the investigation.

rossabaker commented 3 years ago

If you have a logback.xml, you can get more info without building:

  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>

To try new client code locally, from the http4s repo, publishLocal, and depend on the ensuing snapshot. Or git dependencies. Or pull the failing example into the http4s tree.

daddykotex commented 3 years ago

Sorry, I forgot a bit about this. With the right loggers, it prints the following: 

[info] welcome to sbt 1.4.2 (AdoptOpenJDK Java 1.8.0_265)
[info] loading settings for project global-plugins from sbt-updates.sbt ...
[info] loading global plugins from /Users/david/.sbt/1.0/plugins
[info] loading settings for project ebox-build-build-build from metals.sbt ...
[info] loading project definition from /Users/david/workspace/ebox/project/project/project
[info] loading settings for project ebox-build-build from metals.sbt ...
[info] loading project definition from /Users/david/workspace/ebox/project/project
[success] Generated .bloop/ebox-build-build.json
[success] Total time: 0 s, completed 30-Nov-2020 11:27:37 PM
[info] loading settings for project ebox-build from metals.sbt,plugins.sbt ...
[info] loading project definition from /Users/david/workspace/ebox/project
[success] Generated .bloop/ebox-build.json
[success] Total time: 0 s, completed 30-Nov-2020 11:27:38 PM
[info] loading settings for project root from build.sbt ...
[info] set current project to ebox (in build file:/Users/david/workspace/ebox/)
[warn] There may be incompatibilities among your library dependencies; run 'evicted' to see detailed eviction warnings.
[info] running (fork) blaze.Main 
[info] 23:27:42,770 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
[info] 23:27:42,770 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
[info] 23:27:42,770 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/Users/david/workspace/ebox/target/bg-jobs/sbt_1440c1b5/job-1/target/61a601ca/61e69e51/blaze-repro_2.13-0.0.0+12-4bcf4406+20201130-2327.jar!/logback.xml]
[info] 23:27:42,777 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@fc93f1 - URL [jar:file:/Users/david/workspace/ebox/target/bg-jobs/sbt_1440c1b5/job-1/target/61a601ca/61e69e51/blaze-repro_2.13-0.0.0+12-4bcf4406+20201130-2327.jar!/logback.xml] is not of type file
[info] 23:27:42,812 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
[info] 23:27:42,812 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
[info] 23:27:42,817 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
[info] 23:27:42,847 |-WARN in ch.qos.logback.core.ConsoleAppender[CONSOLE] - This appender no longer admits a layout as a sub-component, set an encoder instead.
[info] 23:27:42,847 |-WARN in ch.qos.logback.core.ConsoleAppender[CONSOLE] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
[info] 23:27:42,847 |-WARN in ch.qos.logback.core.ConsoleAppender[CONSOLE] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
[info] 23:27:42,848 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [blaze] to DEBUG
[info] 23:27:42,848 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [blaze] to false
[info] 23:27:42,848 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[blaze]
[info] 23:27:42,848 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
[info] 23:27:42,848 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
[info] 23:27:42,848 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
[info] 23:27:42,849 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@413151e5 - Registering current configuration as safe fallback point
[info] 23:27:48.159 [ioapp-compute-2] DEBUG org.http4s.client.PoolManager - Requesting connection for https://client.ebox.ca: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:48.166 [ioapp-compute-2] DEBUG org.http4s.client.PoolManager - Active connection not found for https://client.ebox.ca. Creating new one. curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:48.246 [cats-effect-blocker-0] DEBUG o.h.b.channel.nio2.ByteBufferHead - Starting up.
[info] 23:27:48.246 [cats-effect-blocker-0] DEBUG o.h.b.channel.nio2.ByteBufferHead - Stage ByteBufferHead sending inbound command: Connected
[info] 23:27:48.246 [cats-effect-blocker-0] DEBUG o.h.blaze.pipeline.stages.SSLStage - Starting up.
[info] 23:27:48.246 [cats-effect-blocker-0] DEBUG o.h.blaze.pipeline.stages.SSLStage - Stage SSLStage sending inbound command: Connected
[info] 23:27:48.246 [cats-effect-blocker-0] DEBUG o.h.client.blaze.ReadBufferStage - Stage started up. Beginning read buffering
[info] 23:27:48.256 [cats-effect-blocker-0] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NEED_WRAP
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:48.261 [cats-effect-blocker-0] DEBUG o.h.client.blaze.ReadBufferStage - Stage ReadBufferStage sending inbound command: Connected
[info] 23:27:48.262 [cats-effect-blocker-0] DEBUG o.h.client.blaze.Http1Connection - Starting up.
[info] 23:27:48.267 [cats-effect-blocker-0] DEBUG o.h.client.blaze.Http1Connection - Connection was idle. Running.
[info] 23:27:48.267 [cats-effect-blocker-0] DEBUG o.h.client.blaze.Http1Connection - Beginning request: GET https://client.ebox.ca
[info] 23:27:48.281 [ioapp-compute-5] DEBUG o.http4s.blazecore.IdleTimeoutStage - Starting idle timeout stage with timeout of 60000 ms
[info] 23:27:48.422 [Thread-4] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:48.542 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 437 bytesProduced = 357, java.nio.HeapByteBuffer[pos=357 lim=16921 cap=16921]
[info] 23:27:48.543 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 85 bytesProduced = 6, java.nio.HeapByteBuffer[pos=6 lim=16921 cap=16921]
[info] 23:27:48.543 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:48.545 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:48.549 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 8581 bytesProduced = 8500, java.nio.HeapByteBuffer[pos=8500 lim=16921 cap=16921]
[info] 23:27:48.550 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 85 bytesProduced = 2, java.nio.HeapByteBuffer[pos=2 lim=16921 cap=16921]
[info] 23:27:48.550 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 85 bytesProduced = 5, java.nio.HeapByteBuffer[pos=5 lim=16921 cap=16921]
[info] 23:27:48.550 [Thread-5] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:48.839 [ioapp-compute-1] DEBUG o.h.client.blaze.Http1Connection - Parse result: None, content complete: false
[info] 23:27:48.839 [ioapp-compute-1] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:48.842 [cats-effect-blocker-0] DEBUG o.h.client.blaze.Http1Connection - Parse result: Some(java.nio.HeapByteBufferR[pos=0 lim=8500 cap=8500]), content complete: false
[info] 23:27:48.861 [cats-effect-blocker-1] DEBUG o.h.client.blaze.Http1Connection - Resetting org.http4s.client.blaze.Http1Connection after completing request.
[info] 23:27:48.863 [cats-effect-blocker-1] DEBUG org.http4s.client.PoolManager - Recycling connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:48.865 [cats-effect-blocker-1] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
[info] 23:27:48.865 [cats-effect-blocker-1] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down.
[info] 23:27:48.865 [cats-effect-blocker-1] DEBUG o.http4s.blazecore.IdleTimeoutStage - Removed mid-stage: IdleTimeoutStage
[info] 23:27:48.867 [cats-effect-blocker-1] DEBUG org.http4s.client.PoolManager - Returning idle connection to pool for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:48.894 [ioapp-compute-7] DEBUG org.http4s.client.PoolManager - Requesting connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=1 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:48.895 [ioapp-compute-7] DEBUG org.http4s.client.PoolManager - Recycling connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:48.895 [ioapp-compute-7] DEBUG o.h.client.blaze.Http1Connection - Connection was idle. Running.
[info] 23:27:48.895 [ioapp-compute-7] DEBUG o.h.client.blaze.Http1Connection - Beginning request: POST https://client.ebox.ca/login
[info] 23:27:48.899 [ioapp-compute-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Starting idle timeout stage with timeout of 60000 ms
[info] 23:27:49.014 [Thread-6] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 309 bytesProduced = 235, java.nio.HeapByteBuffer[pos=235 lim=16921 cap=16921]
[info] 23:27:49.014 [Thread-6] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 437 bytesProduced = 352, java.nio.HeapByteBuffer[pos=352 lim=16921 cap=16921]
[info] 23:27:49.014 [Thread-6] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:49.015 [Thread-6] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:49.016 [cats-effect-blocker-1] DEBUG o.h.client.blaze.Http1Connection - Resetting org.http4s.client.blaze.Http1Connection after completing request.
[info] 23:27:49.017 [cats-effect-blocker-1] DEBUG org.http4s.client.PoolManager - Recycling connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:49.017 [cats-effect-blocker-1] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
[info] 23:27:49.017 [cats-effect-blocker-1] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down.
[info] 23:27:49.017 [cats-effect-blocker-1] DEBUG o.http4s.blazecore.IdleTimeoutStage - Removed mid-stage: IdleTimeoutStage
[info] 23:27:49.018 [cats-effect-blocker-1] DEBUG org.http4s.client.PoolManager - Returning idle connection to pool for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:53.133 [ioapp-compute-1] DEBUG org.http4s.client.PoolManager - Requesting connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=1 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:53.133 [ioapp-compute-1] DEBUG org.http4s.client.PoolManager - Recycling connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:53.134 [ioapp-compute-1] DEBUG o.h.client.blaze.Http1Connection - Connection was idle. Running.
[info] 23:27:53.134 [ioapp-compute-1] DEBUG o.h.client.blaze.Http1Connection - Beginning request: GET https://client.ebox.ca
[info] 23:27:53.134 [ioapp-compute-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Starting idle timeout stage with timeout of 60000 ms
[info] 23:27:53.256 [Thread-7] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 437 bytesProduced = 357, java.nio.HeapByteBuffer[pos=357 lim=16921 cap=16921]
[info] 23:27:53.257 [Thread-7] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 85 bytesProduced = 6, java.nio.HeapByteBuffer[pos=6 lim=16921 cap=16921]
[info] 23:27:53.257 [Thread-7] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.257 [Thread-7] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.260 [Thread-7] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 8581 bytesProduced = 8500, java.nio.HeapByteBuffer[pos=8500 lim=16921 cap=16921]
[info] 23:27:53.260 [Thread-7] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.262 [ioapp-compute-0] DEBUG o.h.client.blaze.Http1Connection - Parse result: None, content complete: false
[info] 23:27:53.262 [ioapp-compute-0] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.262 [cats-effect-blocker-1] DEBUG o.h.client.blaze.Http1Connection - Parse result: Some(java.nio.HeapByteBufferR[pos=0 lim=8500 cap=8500]), content complete: false
[info] 23:27:53.262 [Thread-10] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 85 bytesProduced = 2, java.nio.HeapByteBuffer[pos=2 lim=16921 cap=16921]
[info] 23:27:53.263 [Thread-10] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 85 bytesProduced = 5, java.nio.HeapByteBuffer[pos=5 lim=16921 cap=16921]
[info] 23:27:53.263 [Thread-10] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.264 [cats-effect-blocker-0] DEBUG o.h.client.blaze.Http1Connection - Resetting org.http4s.client.blaze.Http1Connection after completing request.
[info] 23:27:53.265 [cats-effect-blocker-0] DEBUG org.http4s.client.PoolManager - Recycling connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:53.265 [cats-effect-blocker-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
[info] 23:27:53.265 [cats-effect-blocker-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down.
[info] 23:27:53.265 [cats-effect-blocker-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Removed mid-stage: IdleTimeoutStage
[info] 23:27:53.266 [cats-effect-blocker-0] DEBUG org.http4s.client.PoolManager - Returning idle connection to pool for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:53.267 [ioapp-compute-7] DEBUG org.http4s.client.PoolManager - Requesting connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=1 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:53.267 [ioapp-compute-7] DEBUG org.http4s.client.PoolManager - Recycling connection for https://client.ebox.ca: curAllocated=1 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] 23:27:53.268 [ioapp-compute-7] DEBUG o.h.client.blaze.Http1Connection - Connection was idle. Running.
[info] 23:27:53.268 [ioapp-compute-7] DEBUG o.h.client.blaze.Http1Connection - Beginning request: POST https://client.ebox.ca/login
[info] 23:27:53.268 [ioapp-compute-1] DEBUG o.http4s.blazecore.IdleTimeoutStage - Starting idle timeout stage with timeout of 60000 ms
[info] 23:27:53.269 [ioapp-compute-6] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.338 [Thread-8] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 309 bytesProduced = 235, java.nio.HeapByteBuffer[pos=235 lim=16921 cap=16921]
[info] 23:27:53.339 [Thread-8] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = OK HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 437 bytesProduced = 352, java.nio.HeapByteBuffer[pos=352 lim=16921 cap=16921]
[info] 23:27:53.339 [Thread-8] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.340 [Thread-8] DEBUG o.h.blaze.pipeline.stages.SSLStage - SSL Read Request Status: Status = BUFFER_UNDERFLOW HandshakeStatus = NOT_HANDSHAKING
[info] bytesConsumed = 0 bytesProduced = 0, java.nio.HeapByteBuffer[pos=0 lim=16921 cap=16921]
[info] 23:27:53.343 [cats-effect-blocker-0] ERROR o.h.client.blaze.Http1Connection - Error during client request decode loop
[info] org.http4s.blaze.http.parser.BaseExceptions$BadMessage: Bad HTTP version: 
[info] 0
[info] HTTP/1.1
[info]  at org.http4s.blaze.http.parser.Http1ClientParser.parseResponseLine(Http1ClientParser.java:135)
[info]  at org.http4s.client.blaze.BlazeHttp1ClientParser.finishedResponseLine(BlazeHttp1ClientParser.scala:56)
[info]  at org.http4s.client.blaze.Http1Connection.parsePrelude(Http1Connection.scala:214)
[info]  at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1(Http1Connection.scala:196)
[info]  at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1$adapted(Http1Connection.scala:195)
[info]  at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:447)
[info]  at cats.effect.internals.PoolUtils$$anon$2$$anon$3.run(PoolUtils.scala:52)
[info]  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[info]  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[info]  at java.lang.Thread.run(Thread.java:748)
[info] 23:27:53.359 [cats-effect-blocker-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down idle timeout stage
[info] 23:27:53.359 [cats-effect-blocker-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Shutting down.
[info] 23:27:53.359 [cats-effect-blocker-0] DEBUG o.http4s.blazecore.IdleTimeoutStage - Removed mid-stage: IdleTimeoutStage
[info] 23:27:53.361 [cats-effect-blocker-0] DEBUG o.h.client.blaze.ReadBufferStage - Shutting down.
[info] 23:27:53.362 [cats-effect-blocker-0] DEBUG o.h.blaze.pipeline.stages.SSLStage - Error while closing SSL Engine
[info] javax.net.ssl.SSLException: Inbound closed before receiving peer's close_notify: possible truncation attack?
[info]  at sun.security.ssl.Alerts.getSSLException(Alerts.java:214)
[info]  at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1667)
[info]  at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1635)
[info]  at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:1562)
[info]  at org.http4s.blaze.pipeline.stages.SSLStage.stageShutdown(SSLStage.scala:66)
[info]  at org.http4s.blaze.pipeline.Tail.closePipeline(Stages.scala:85)
[info]  at org.http4s.blaze.pipeline.Tail.closePipeline$(Stages.scala:84)
[info]  at org.http4s.blaze.pipeline.stages.SSLStage.closePipeline(SSLStage.scala:47)
[info]  at org.http4s.blaze.pipeline.Tail.closePipeline(Stages.scala:88)
[info]  at org.http4s.blaze.pipeline.Tail.closePipeline$(Stages.scala:84)
[info]  at org.http4s.client.blaze.ReadBufferStage.closePipeline(ReadBufferStage.scala:20)
[info]  at org.http4s.blaze.pipeline.Tail.closePipeline(Stages.scala:88)
[info]  at org.http4s.blaze.pipeline.Tail.closePipeline$(Stages.scala:84)
[info]  at org.http4s.client.blaze.Http1Connection.closePipeline(Http1Connection.scala:31)
[info]  at org.http4s.client.blaze.Http1Connection.shutdownWithError(Http1Connection.scala:91)
[info]  at org.http4s.client.blaze.Http1Connection.stageShutdown(Http1Connection.scala:61)
[info]  at org.http4s.client.blaze.Http1Connection.shutdown(Http1Connection.scala:59)
[info]  at org.http4s.client.PoolManager.$anonfun$invalidate$1(PoolManager.scala:319)
[info]  at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
[info]  at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:103)
[info]  at cats.effect.internals.IORunLoop$.restartCancelable(IORunLoop.scala:50)
[info]  at cats.effect.internals.IOBracket$BracketStart.run(IOBracket.scala:100)
[info]  at cats.effect.internals.Trampoline.cats$effect$internals$Trampoline$$immediateLoop(Trampoline.scala:67)
[info]  at cats.effect.internals.Trampoline.startLoop(Trampoline.scala:35)
[info]  at cats.effect.internals.TrampolineEC$JVMTrampoline.super$startLoop(TrampolineEC.scala:90)
[info]  at cats.effect.internals.TrampolineEC$JVMTrampoline.$anonfun$startLoop$1(TrampolineEC.scala:90)
[info]  at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
[info]  at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:94)
[info]  at cats.effect.internals.TrampolineEC$JVMTrampoline.startLoop(TrampolineEC.scala:90)
[info]  at cats.effect.internals.Trampoline.execute(Trampoline.scala:43)
[info]  at cats.effect.internals.TrampolineEC.execute(TrampolineEC.scala:42)
[info]  at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:137)
[info]  at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:126)
[info]  at org.http4s.client.blaze.Http1Connection.parsePrelude(Http1Connection.scala:303)
[info]  at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1(Http1Connection.scala:196)
[info]  at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1$adapted(Http1Connection.scala:195)
[info]  at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:447)
[info]  at cats.effect.internals.PoolUtils$$anon$2$$anon$3.run(PoolUtils.scala:52)
[info]  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[info]  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[info]  at java.lang.Thread.run(Thread.java:748)
[info] 23:27:53.362 [cats-effect-blocker-0] DEBUG o.h.b.channel.nio2.ByteBufferHead - Shutting down.
[info] 23:27:53.363 [cats-effect-blocker-0] DEBUG o.h.b.channel.nio2.ByteBufferHead - doClosePipeline(None)
[info] 23:27:53.363 [cats-effect-blocker-0] DEBUG o.h.client.blaze.Http1Connection - Shutting down.
[info] 23:27:53.365 [cats-effect-blocker-0] DEBUG org.http4s.client.PoolManager - Invalidated connection for https://client.ebox.ca, no pending requests. Shrinking pool: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[info] Error occurred on 1 attempt.
[info] 23:27:53.368 [cats-effect-blocker-0] INFO  org.http4s.client.PoolManager - Shutting down connection pool: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false
[error] org.http4s.blaze.http.parser.BaseExceptions$BadMessage: Bad HTTP version: 
[error] 0
[error] HTTP/1.1
[error]     at org.http4s.blaze.http.parser.Http1ClientParser.parseResponseLine(Http1ClientParser.java:135)
[error]     at org.http4s.client.blaze.BlazeHttp1ClientParser.finishedResponseLine(BlazeHttp1ClientParser.scala:56)
[error]     at org.http4s.client.blaze.Http1Connection.parsePrelude(Http1Connection.scala:214)
[error]     at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1(Http1Connection.scala:196)
[error]     at org.http4s.client.blaze.Http1Connection.$anonfun$readAndParsePrelude$1$adapted(Http1Connection.scala:195)
[error]     at async @ org.http4s.client.blaze.Http1Connection.receiveResponse(Http1Connection.scala:185)
[error]     at $greater$greater$extension @ org.http4s.client.blaze.Http1Connection.$anonfun$executeRequest$2(Http1Connection.scala:168)
[error]     at main$ @ blaze.Main$.main(main.scala:11)
[error] Nonzero exit code returned from runner: 1
[error] (blazeRepro / Compile / run) Nonzero exit code returned from runner: 1
[error] Total time: 14 s, completed 30-Nov-2020 11:27:53 PM