HttpClient: proxy host and path become the request destination

[ttiurani]

Expected behavior

Using a TCP proxy doesn't change the destination of the request itself, but only proxies the request.

Actual behavior

With 0.7.9. this worked with the hoverfly proxy:

WebClient.builder().clientConnector(
    new ReactorClientHttpConnector(
        options -> { options.proxy(proxyOptions->
             proxyOptions.type(ClientProxyOptions.Proxy.HTTP).host("localhost").port(1234)
       }))
.build()
.post()
.uri("http://www.example.org");

and the Destination was "http://www.example.org" but with 0.8.2 and this kind of refactoring:

HttpClient httpClient =
      HttpClient.create()
        .tcpConfiguration(
          tcpClient ->
            tcpClient.proxy(
              ops ->
                ops.type(ProxyProvider.Proxy.HTTP).host("localhost").port(1234)
           )
        )
WebClient.builder()
          .clientConnector(new ReactorClientHttpConnector(httpClient))
         .build()
         .post()
         .uri("http://www.example.org");

The Destination becomes hoverfly itself, i.e. "localhost:1234". So setting the tcpClient.proxy overrides whatever I put into the uri of the call itself.

Steps to reproduce

Unfortunately didn't have time to create a short test case for this.

Reactor Netty version

0.8.2

JVM version (e.g. java -version)

openjdk version "11" 2018-09-25
OpenJDK Runtime Environment AdoptOpenJDK (build 11+28)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11+28, mixed mode)

OS version (e.g. uname -a)

OSX 10.13.6

[ttiurani]

Unfortunately this didn't fix it for me, with the latest 0.8.3.BUILD-20181101.191149-7 snapshot build the bug is still present @violetagg

[violetagg]

@ttiurani Can you post here your logs? Also can you execute it with Hoverfly and with some other proxy server? Please enable the wire logging and logging.level.reactor.netty=debug in the application.properties

HttpClient httpClient =
      HttpClient.create()
        .wiretap(true)
        .tcpConfiguration(
          tcpClient ->
            tcpClient.proxy(
              ops ->
                ops.type(ProxyProvider.Proxy.HTTP).host("localhost").port(1234)
           )
        )

[ttiurani]

@violetagg here are two logs, that should show how things go wrong, the code is from a real example, so I masked the values a bit. Note the host: line there.

0.7.9.RELEASE:

2018-11-02 16:35:57.388 DEBUG 12885 --- [           main] r.i.n.resources.DefaultPoolResources     : New http client pool for www.example.org:9999
2018-11-02 16:35:57.429 DEBUG 12885 --- [           main] r.i.n.c.PooledClientContextHandler       : Acquiring existing channel from pool: DefaultPromise@5d5574c7(incomplete) SimpleChannelPool{activeConnections=0, inactiveConnections=0}
2018-11-02 16:35:57.430 DEBUG 12885 --- [ctor-http-nio-4] r.i.n.resources.DefaultPoolResources     : [id: 0x40f32f85] Created new pooled channel, now 0 active connections and 1 inactive connections
2018-11-02 16:35:57.475 DEBUG 12885 --- [ctor-http-nio-4] r.ipc.netty.channel.ContextHandler       : [id: 0x40f32f85] After pipeline DefaultChannelPipeline{(LoggingHandler#0 = io.netty.handler.logging.LoggingHandler), (HttpClientCodec#0 = io.netty.handler.codec.http.HttpClientCodec), (reactor.left.proxyHandler = io.netty.handler.proxy.HttpProxyHandler), (reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.ipc.netty.channel.ChannelOperationsHandler)}
2018-11-02 16:35:57.477 DEBUG 12885 --- [ctor-http-nio-4] reactor.ipc.netty.proxy                  : [id: 0x40f32f85] REGISTERED
2018-11-02 16:35:57.478 DEBUG 12885 --- [ctor-http-nio-4] r.ipc.netty.http.client.HttpClient       : [id: 0x40f32f85] REGISTERED
2018-11-02 16:35:57.478 DEBUG 12885 --- [ctor-http-nio-4] r.ipc.netty.http.client.HttpClient       : [id: 0x40f32f85] CONNECT: www.example.org:9999
2018-11-02 16:35:57.478 DEBUG 12885 --- [ctor-http-nio-4] reactor.ipc.netty.proxy                  : [id: 0x40f32f85] CONNECT: localhost/127.0.0.1:62201
2018-11-02 16:35:57.483 DEBUG 12885 --- [ctor-http-nio-4] reactor.ipc.netty.proxy                  : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] ACTIVE
2018-11-02 16:35:57.483 DEBUG 12885 --- [ctor-http-nio-3] r.i.n.resources.DefaultPoolResources     : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] Channel acquired, now 1 active connections and 0 inactive connections
2018-11-02 16:35:57.483 DEBUG 12885 --- [ctor-http-nio-3] r.i.n.resources.DefaultPoolResources     : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] Registering close event to pool release
2018-11-02 16:35:57.538 DEBUG 12885 --- [ctor-http-nio-4] reactor.ipc.netty.proxy                  : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] WRITE: 69B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 43 4f 4e 4e 45 43 54 20 72 65 6e 2e 63 63 2e 65 |CONNECT www.exam|
|00000010| 6c 69 73 61 2e 66 69 3a 38 31 36 34 20 48 54 54 |ple.org:9999 HTT|
|00000020| 50 2f 31 2e 31 0d 0a 68 6f 73 74 3a 20 72 65 6e |P/1.1..host: www|
|00000030| 2e 63 63 2e 65 6c 69 73 61 2e 66 69 3a 38 31 36 |.example.org:999|
|00000040| 34 0d 0a 0d 0a                                  |9....           |
+--------+-------------------------------------------------+----------------+
2018-11-02 16:35:57.539 DEBUG 12885 --- [ctor-http-nio-4] reactor.ipc.netty.proxy                  : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] FLUSH
2018-11-02 16:35:57.543 DEBUG 12885 --- [ctor-http-nio-4] r.ipc.netty.http.client.HttpClient       : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] ACTIVE
2018-11-02 16:35:57.544 DEBUG 12885 --- [ctor-http-nio-4] r.i.n.c.PooledClientContextHandler       : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] Acquired active channel
2018-11-02 16:35:57.568 DEBUG 12885 --- [ctor-http-nio-4] r.ipc.netty.channel.ChannelOperations    : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] [HttpClient] Handler is being applied: HttpClientHandler{startURI=http://www.example.org:9999/my-path, method=POST, handler=org.springframework.http.client.reactive.ReactorClientHttpConnector$$Lambda$597/0x00000008006cdc40@172bf47f}
2018-11-02 16:35:57.589 DEBUG 12885 --- [ctor-http-nio-4] r.i.n.channel.ChannelOperationsHandler   : [id: 0x40f32f85, L:/127.0.0.1:62213 - R:localhost/127.0.0.1:62201] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /my-path HTTP/1.1
user-agent: ReactorNetty/0.7.9.RELEASE
host: www.example.org:9999
Content-Type: application/x-www-form-urlencoded;charset=UTF-8
Accept: application/json
Accept-Charset: UTF-8
Content-Length: 118

and 0.8.3.BUILD-20181101.191149-7:

2018-11-02 16:28:19.689 DEBUG 6526 --- [           main] r.n.resources.PooledConnectionProvider   : Creating new client pool [http] for www.example.org:9999
2018-11-02 16:28:19.696 DEBUG 6526 --- [lient-kqueue-13] r.n.resources.PooledConnectionProvider   : [id: 0xbc8b07a9] Created new pooled channel, now 0 active connections and 1 inactive connections
2018-11-02 16:28:19.739 DEBUG 6526 --- [lient-kqueue-13] reactor.netty.channel.BootstrapHandlers  : [id: 0xbc8b07a9] Initialized pipeline DefaultChannelPipeline{(LoggingHandler#0 = io.netty.handler.logging.LoggingHandler), (HttpClientCodec#0 = io.netty.handler.codec.http.HttpClientCodec), (reactor.left.proxyHandler = io.netty.handler.proxy.HttpProxyHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2018-11-02 16:28:19.742 DEBUG 6526 --- [lient-kqueue-13] reactor.netty.proxy                      : [id: 0xbc8b07a9] REGISTERED
2018-11-02 16:28:19.743 DEBUG 6526 --- [lient-kqueue-13] reactor.netty.proxy                      : [id: 0xbc8b07a9] CONNECT: localhost/127.0.0.1:62012
2018-11-02 16:28:19.746 DEBUG 6526 --- [lient-kqueue-13] reactor.netty.proxy                      : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] ACTIVE
2018-11-02 16:28:19.783 DEBUG 6526 --- [lient-kqueue-13] reactor.netty.proxy                      : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] WRITE: 69B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 43 4f 4e 4e 45 43 54 20 72 65 6e 2e 63 63 2e 65 |CONNECT www.exam|
|00000010| 6c 69 73 61 2e 66 69 3a 38 31 36 34 20 48 54 54 |ple.org:9999 HTT|
|00000020| 50 2f 31 2e 31 0d 0a 68 6f 73 74 3a 20 72 65 6e |P/1.1..host: www|
|00000030| 2e 63 63 2e 65 6c 69 73 61 2e 66 69 3a 38 31 36 |.example.org:999|
|00000040| 34 0d 0a 0d 0a                                  |9....           |
+--------+-------------------------------------------------+----------------+
2018-11-02 16:28:19.784 DEBUG 6526 --- [lient-kqueue-13] reactor.netty.proxy                      : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] FLUSH
2018-11-02 16:28:19.786 DEBUG 6526 --- [lient-kqueue-13] r.n.resources.PooledConnectionProvider   : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] onStateChange(PooledConnection{channel=[id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012]}, [connected])
2018-11-02 16:28:19.792 DEBUG 6526 --- [lient-kqueue-13] r.n.resources.PooledConnectionProvider   : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012]}}, [configured])
2018-11-02 16:28:19.793 DEBUG 6526 --- [lient-kqueue-13] r.n.resources.PooledConnectionProvider   : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] Registering pool release on close event for channel
2018-11-02 16:28:19.795 DEBUG 6526 --- [lient-kqueue-13] r.netty.http.client.HttpClientConnect    : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] Handler is being applied: {uri=http://www.example.org:9999/my-path, method=POST}
2018-11-02 16:28:19.813 DEBUG 6526 --- [lient-kqueue-13] r.n.channel.ChannelOperationsHandler     : [id: 0xbc8b07a9, L:/127.0.0.1:62025 - R:localhost/127.0.0.1:62012] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
POST /my-path HTTP/1.1
user-agent: ReactorNetty/0.8.3.BUILD-SNAPSHOT
host: localhost:62012
Accept: application/json
Accept-Charset: UTF-8
Content-Type: application/x-www-form-urlencoded;charset=UTF-8
Content-Length: 118

[violetagg]

@ttiurani Try with the latest snapshot, it should be OK.

[ttiurani]

@violetagg nice, I confirmed that the fix works, thanks a lot! Are you planning a 0.8.3 release soon? Would be great if this fix would end up in the Spring releases sooner than later.