[
https://issues.apache.org/jira/browse/HTTPCLIENT-2187?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17446880#comment-17446880
]
Tim te Beek commented on HTTPCLIENT-2187:
-----------------------------------------
So I ran
com.github.tomakehurst.wiremock.JvmProxyConfigAcceptanceTest.configuresHttpsProxyingOnlyFromAWireMockServer()
in this branch: [https://github.com/wiremock/wiremock/pull/1698]
These are the logs:
{code:java}
2021-11-20 22:56:09,340 main ERROR Unable to locate appender "Console" for
logger config "org.apache.hc.client5.http"
2021-11-20 22:56:09,344 main ERROR Unable to locate appender "Console" for
logger config "org.apache.hc.client5.http.wire"
2021-11-20 22:56:09,403 INFO [com.tngtech.archunit.ArchConfiguration] Reading
ArchUnit properties from
file:/home/tim/Documents/workspace/wiremock/bin/test/archunit.properties
2021-11-20 22:56:09,829 INFO [org.eclipse.jetty.util.log] Logging initialized
@1063ms to org.eclipse.jetty.util.log.Slf4jLog
2021-11-20 22:56:10,033 INFO [org.eclipse.jetty.server.Server]
jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git:
8da83308eeca865e495e53ef315a249d63ba9332; jvm 1.8.0_302-b08
2021-11-20 22:56:10,046 INFO [org.eclipse.jetty.server.handler.ContextHandler]
Started o.e.j.s.ServletContextHandler@791cbf87{/__admin,null,AVAILABLE}
2021-11-20 22:56:10,051 INFO
[org.eclipse.jetty.server.handler.ContextHandler.ROOT] RequestHandlerClass from
context returned com.github.tomakehurst.wiremock.http.StubRequestHandler.
Normalized mapped under returned 'null'
2021-11-20 22:56:10,051 INFO [org.eclipse.jetty.server.handler.ContextHandler]
Started o.e.j.s.ServletContextHandler@66971f6b{/,null,AVAILABLE}
2021-11-20 22:56:10,062 INFO [org.eclipse.jetty.server.AbstractConnector]
Started NetworkTrafficServerConnector@1c3b9394{HTTP/1.1, (http/1.1,
h2c)}{0.0.0.0:41447}
2021-11-20 22:56:10,079 INFO [org.eclipse.jetty.server.AbstractConnector]
Started NetworkTrafficServerConnector@54a67a45{SSL, (ssl,
http/1.1)}{0.0.0.0:35709}
2021-11-20 22:56:10,079 INFO [org.eclipse.jetty.server.Server] Started @1314ms
2021-11-20 22:56:10,096 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ex-0000000001
preparing request execution
2021-11-20 22:56:10,100 DEBUG
[org.apache.hc.client5.http.impl.classic.ProtocolExec] ex-0000000001 target
auth state: UNCHALLENGED
2021-11-20 22:56:10,100 DEBUG
[org.apache.hc.client5.http.impl.classic.ConnectExec] ex-0000000001 acquiring
connection with route {tls}->http://localhost:41447->https://example.com:443
2021-11-20 22:56:10,101 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ex-0000000001
acquiring endpoint (3 MINUTES)
2021-11-20 22:56:10,102 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ex-0000000001 endpoint lease request (3 MINUTES) [route:
{tls}->http://localhost:41447->https://example.com:443][total available: 0;
route allocated: 0 of 5; total allocated: 0 of 25]
2021-11-20 22:56:10,104 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ex-0000000001 endpoint leased [route:
{tls}->http://localhost:41447->https://example.com:443][total available: 0;
route allocated: 1 of 5; total allocated: 1 of 25]
2021-11-20 22:56:10,111 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ex-0000000001 acquired ep-0000000000
2021-11-20 22:56:10,112 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ex-0000000001
acquired endpoint ep-0000000000
2021-11-20 22:56:10,112 DEBUG
[org.apache.hc.client5.http.impl.classic.ConnectExec] ex-0000000001 opening
connection {tls}->http://localhost:41447->https://example.com:443
2021-11-20 22:56:10,112 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ep-0000000000
connecting endpoint (3 MINUTES)
2021-11-20 22:56:10,112 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ep-0000000000 connecting endpoint to http://localhost:41447 (3 MINUTES)
2021-11-20 22:56:10,114 DEBUG
[org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator]
http-outgoing-0 connecting to localhost/127.0.0.1:41447
2021-11-20 22:56:10,115 DEBUG
[org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator]
http-outgoing-0 connection established 127.0.0.1:55746<->127.0.0.1:41447
2021-11-20 22:56:10,115 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ep-0000000000 connected http-outgoing-0
2021-11-20 22:56:10,115 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ep-0000000000
endpoint connected
2021-11-20 22:56:10,115 DEBUG
[org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection]
http-outgoing-0 set socket timeout to 30000 MILLISECONDS
2021-11-20 22:56:10,115 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ep-0000000000
start execution ex-0000000001
2021-11-20 22:56:10,115 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ep-0000000000 executing exchange ex-0000000001 over http-outgoing-0
2021-11-20 22:56:10,116 DEBUG [org.apache.hc.client5.http.headers]
http-outgoing-0 >> CONNECT example.com:443 HTTP/1.1
2021-11-20 22:56:10,116 DEBUG [org.apache.hc.client5.http.headers]
http-outgoing-0 >> Host: example.com:443
2021-11-20 22:56:10,116 DEBUG [org.apache.hc.client5.http.headers]
http-outgoing-0 >> User-Agent: Apache-HttpClient/5.1.2 (Java/1.8.0_302)
2021-11-20 22:56:10,116 DEBUG [org.apache.hc.client5.http.wire] http-outgoing-0
>> "CONNECT example.com:443 HTTP/1.1[\r][\n]"
2021-11-20 22:56:10,116 DEBUG [org.apache.hc.client5.http.wire] http-outgoing-0
>> "Host: example.com:443[\r][\n]"
2021-11-20 22:56:10,116 DEBUG [org.apache.hc.client5.http.wire] http-outgoing-0
>> "User-Agent: Apache-HttpClient/5.1.2 (Java/1.8.0_302)[\r][\n]"
2021-11-20 22:56:10,116 DEBUG [org.apache.hc.client5.http.wire] http-outgoing-0
>> "[\r][\n]"
2021-11-20 22:56:10,170 DEBUG [org.apache.hc.client5.http.wire] http-outgoing-0
<< "HTTP/1.1 200 OK[\r][\n]"
2021-11-20 22:56:10,170 DEBUG [org.apache.hc.client5.http.wire] http-outgoing-0
<< "Content-Length: 0[\r][\n]"
2021-11-20 22:56:10,170 DEBUG [org.apache.hc.client5.http.wire] http-outgoing-0
<< "[\r][\n]"
2021-11-20 22:56:10,172 DEBUG [org.apache.hc.client5.http.headers]
http-outgoing-0 << HTTP/1.1 200 OK
2021-11-20 22:56:10,173 DEBUG [org.apache.hc.client5.http.headers]
http-outgoing-0 << Content-Length: 0
2021-11-20 22:56:10,174 DEBUG
[org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection]
http-outgoing-0 close connection GRACEFUL
2021-11-20 22:56:10,175 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ep-0000000000
endpoint closed
2021-11-20 22:56:10,175 DEBUG
[org.apache.hc.client5.http.impl.classic.ConnectExec] ex-0000000001 tunnel to
target created.
2021-11-20 22:56:10,176 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ep-0000000000
upgrading endpoint
2021-11-20 22:56:10,176 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ep-0000000000
endpoint closed
2021-11-20 22:56:10,176 DEBUG
[org.apache.hc.client5.http.impl.classic.InternalHttpClient] ep-0000000000
discarding endpoint
2021-11-20 22:56:10,176 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ep-0000000000 releasing endpoint
2021-11-20 22:56:10,176 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ep-0000000000 connection is not kept alive
2021-11-20 22:56:10,177 DEBUG
[org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager]
ep-0000000000 connection released [route:
{tls}->http://localhost:41447->https://example.com:443][total available: 0;
route allocated: 0 of 5; total allocated: 0 of 25]
2021-11-20 22:56:10,184 INFO [org.eclipse.jetty.server.AbstractConnector]
Stopped NetworkTrafficServerConnector@1c3b9394{HTTP/1.1, (http/1.1,
h2c)}{0.0.0.0:0}
2021-11-20 22:56:10,184 INFO [org.eclipse.jetty.server.AbstractConnector]
Stopped NetworkTrafficServerConnector@54a67a45{SSL, (ssl, http/1.1)}{0.0.0.0:0}
2021-11-20 22:56:10,185 INFO [org.eclipse.jetty.server.handler.ContextHandler]
Stopped o.e.j.s.ServletContextHandler@66971f6b{/,null,STOPPED}
2021-11-20 22:56:10,185 INFO [org.eclipse.jetty.server.handler.ContextHandler]
Stopped o.e.j.s.ServletContextHandler@791cbf87{/__admin,null,STOPPED}{code}
> Classic proxy handling for HTTPS seems broken as of 5.1.1+
> ----------------------------------------------------------
>
> Key: HTTPCLIENT-2187
> URL: https://issues.apache.org/jira/browse/HTTPCLIENT-2187
> Project: HttpComponents HttpClient
> Issue Type: Bug
> Components: HttpClient (classic)
> Affects Versions: 5.1.1, 5.1.2, 5.2-alpha1
> Reporter: Tim te Beek
> Priority: Major
>
> Classic proxy handling for HTTPS seems to have broken as of 5.1.1+, as seen
> here: [https://github.com/wiremock/wiremock/pull/1698]
> To give just one sample, we now see a failure stacktrace such as this:
> {{java.lang.IllegalStateException: Endpoint is not connected}}
> {{ at org.apache.hc.core5.util.Asserts.check(Asserts.java:38)}}
> {{ at
> org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager$InternalConnectionEndpoint.getValidatedPoolEntry(PoolingHttpClientConnectionManager.java:637)}}
> {{ at
> org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.upgrade(PoolingHttpClientConnectionManager.java:454)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.InternalExecRuntime.upgradeTls(InternalExecRuntime.java:190)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.ConnectExec.execute(ConnectExec.java:172)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.ProtocolExec.execute(ProtocolExec.java:197)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.InternalHttpClient.doExecute(InternalHttpClient.java:170)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:75)}}
> {{ at
> org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:89)}}
> {{ at
> com.github.tomakehurst.wiremock.junit5.JUnitJupiterExtensionJvmProxyNonStaticProgrammaticTest.getContent(JUnitJupiterExtensionJvmProxyNonStaticProgrammaticTest.java:67)}}
> {{ at
> com.github.tomakehurst.wiremock.junit5.JUnitJupiterExtensionJvmProxyNonStaticProgrammaticTest.configures_jvm_proxy_and_enables_browser_proxying_https(JUnitJupiterExtensionJvmProxyNonStaticProgrammaticTest.java:63)}}
> That test basically calls this class to set the System proxy properties:
> [https://github.com/wiremock/wiremock/blob/master/src/main/java/com/github/tomakehurst/wiremock/http/JvmProxyConfigurer.java#L48]
> For HTTP that still works fine, for HTTPS it now fails.
>
> There were some recent changes in 5.1.1 related to proxy handling & keep
> alive for async:
> [https://issues.apache.org/jira/projects/HTTPCLIENT/issues/HTTPCLIENT-2177]
> [https://github.com/apache/httpcomponents-client/compare/50f93ec18be8d6f49138825356051c4c0b60dce4...90f69c87b27b721ea8f0e23bdb4baf92bd7cde06]
> However, we're using classic still, and seeing the error above, so not sure
> it's related.
> Could anyone look into why we are now having these issues with only a patch
> version bump?
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@hc.apache.org
For additional commands, e-mail: dev-h...@hc.apache.org
