search

spring-cloud / spring-cloud-gateway

An API Gateway built on Spring Framework and Spring Boot providing routing and more.
http://cloud.spring.io
Apache License 2.0
4.52k stars 3.32k forks source link

Truncated response in spring-cloud-gateway #1784

Open mxku opened 4 years ago

mxku commented 4 years ago 
Spring Cloud Gateway version: 2.2.2.RELEASE
Spring WebFlux: 5.2.5.RELEASE
reactor-netty: 0.9.6.RELEASE

I am hitting a service through spring-cloud-gateway. Expected response size is 359594. But while hitting it through spring-cloud-gateway, response is marked complete after 262144 bytes.

This works fine with spring-cloud-gateway 2.0.1.RELEASE sprign-webflux: 5.0.6.RELEASE reactor-netty: 0.7.11.RELEASE

AccessLog:

x.x.x.x- - [18/Jun/2020:09:06:24 +1000] "GET /xxxService/pricingPolicies HTTP/1.1" 200 262144 8000 524 ms

Wiretap Below is the full wiretap log for that particular call.

    Line 3315: 2020-06-18 09:06:24.345 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463] Created a new pooled channel, now 1 active connections and 0 inactive connections
    Line 3316: 2020-06-18 09:06:24.346 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.channel.BootstrapHandlers  : [id: 0x5a9f0463] Initialized pipeline DefaultChannelPipeline{(reactor.left.loggingHandler = io.netty.handler.logging.LoggingHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
    Line 3317: 2020-06-18 09:06:24.346 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463] REGISTERED
    Line 3318: 2020-06-18 09:06:24.346 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463] CONNECT: /x.x.x.100:9001
    Line 3319: 2020-06-18 09:06:24.349 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Registering pool release on close event for channel
    Line 3320: 2020-06-18 09:06:24.349 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Channel connected, now 1 active connections and 0 inactive connections
    Line 3321: 2020-06-18 09:06:24.350 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] ACTIVE
    Line 3322: 2020-06-18 09:06:24.350 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}, [connected])
    Line 3322: 2020-06-18 09:06:24.350 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}, [connected])
    Line 3323: 2020-06-18 09:06:24.350 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [configured])
    Line 3323: 2020-06-18 09:06:24.350 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [configured])
    Line 3324: 2020-06-18 09:06:24.350 DEBUG 49772 --- [reactor-http-nio-5] r.netty.http.client.HttpClientConnect    : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Handler is being applied: {uri=http://x.x.x.100:9001/xxxRestService/pricingPolicies, method=GET}
    Line 3325: 2020-06-18 09:06:24.351 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [request_prepared])
    Line 3325: 2020-06-18 09:06:24.351 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [request_prepared])
    Line 3327: 2020-06-18 09:06:24.352 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] WRITE: 6300B
    Line 3726: 2020-06-18 09:06:24.361 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] FLUSH
    Line 3727: 2020-06-18 09:06:24.363 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [request_sent])
    Line 3727: 2020-06-18 09:06:24.363 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [request_sent])
    Line 3728: 2020-06-18 09:06:24.512 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ: 1024B
    Line 3797: 2020-06-18 09:06:24.514 DEBUG 49772 --- [reactor-http-nio-5] r.n.http.client.HttpClientOperations     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Received response (auto-read:false) : [Content-Type=application/json, Accept=application/json, text/plain, */*, Accept-Encoding=gzip, deflate, Access-Control-Allow-Headers=Age,Cache-Control,Expires,Pragma,Origin,Accept,X-Requested-With,Content-Type,Access-Control-Request-Method,Access-Control-Request-Headers, Access-Control-Allow-Methods=GET,POST,PUT,DELETE, Access-Control-Allow-Origin=null, Access-Control-Max-Age=3600, Cache-Control=no-store,no-cache, Host=x.x.x.100:9001, Transfer-Encoding=chunked]
    Line 3798: 2020-06-18 09:06:24.517 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [response_received])
    Line 3798: 2020-06-18 09:06:24.517 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [response_received])
    Line 3799: 2020-06-18 09:06:24.518 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.channel.FluxReceive        : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
    Line 3800: 2020-06-18 09:06:24.519 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ: 16384B
    Line 4829: 2020-06-18 09:06:24.537 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ COMPLETE
    Line 4830: 2020-06-18 09:06:24.541 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ: 65536B
    Line 8931: 2020-06-18 09:06:24.611 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ: 65536B
    Line 13032: 2020-06-18 09:06:24.704 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ: 65536B
    Line 17133: 2020-06-18 09:06:24.788 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ: 48696B
    Line 20182: 2020-06-18 09:06:24.854 DEBUG 49772 --- [reactor-http-nio-5] r.n.http.client.HttpClientOperations     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Received last HTTP packet
    Line 20183: 2020-06-18 09:06:24.854 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [response_completed])
    Line 20183: 2020-06-18 09:06:24.854 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [response_completed])
    Line 20184: 2020-06-18 09:06:24.855 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [disconnecting])
    Line 20184: 2020-06-18 09:06:24.855 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] onStateChange(GET{uri=/xxxRestService/pricingPolicies, connection=PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001]}}, [disconnecting])
    Line 20186: 2020-06-18 09:06:24.855 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Releasing channel
    Line 20189: 2020-06-18 09:06:24.856 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] Channel cleaned, now 0 active connections and 1 inactive connections
    Line 20190: 2020-06-18 09:06:24.857 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ COMPLETE
    Line 20191: 2020-06-18 09:06:24.857 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 - R:/x.x.x.100:9001] READ COMPLETE
    Line 20192: 2020-06-18 09:06:24.857 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 ! R:/x.x.x.100:9001] INACTIVE
    Line 20193: 2020-06-18 09:06:24.858 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 ! R:/x.x.x.100:9001] onStateChange(PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 ! R:/x.x.x.100:9001]}, [disconnecting])
    Line 20193: 2020-06-18 09:06:24.858 DEBUG 49772 --- [reactor-http-nio-5] r.n.resources.PooledConnectionProvider   : [id: 0x5a9f0463, L:/x.x.x.189:50451 ! R:/x.x.x.100:9001] onStateChange(PooledConnection{channel=[id: 0x5a9f0463, L:/x.x.x.189:50451 ! R:/x.x.x.100:9001]}, [disconnecting])
    Line 20194: 2020-06-18 09:06:24.858 DEBUG 49772 --- [reactor-http-nio-5] reactor.netty.http.client.HttpClient     : [id: 0x5a9f0463, L:/x.x.x.189:50451 ! R:/x.x.x.100:9001] UNREGISTERED
mxku commented 4 years ago

Same issue with 2.2.3.RELEASE as well.

spencergibb commented 4 years ago

Can you provide your configuration?

mxku commented 4 years ago 
spring:
  main:
    allow-bean-definition-overriding: true
  aop:
    proxy-target-class: true
  cloud:
    gateway:
      discovery:
        locator:
          enabled: true
          lower-case-service-id: true
      httpclient:
        ssl:
          useInsecureTrustManager: true
        x-forwarded:
          enabled: true
          for-enabled: true
          proto-enabled: true
          host-append: false
          port-append: false
          proto-append: false
    loadbalancer:
      ribbon:
        enabled: false

Route::

     - id: cas
        uri: http://x.x.x.100:9001
        filters:
          - TokenValidation=authObjects,""
        predicates:
          - Path=/xxxRestService/**

TokenValidation is a custom filter which injects a header. This is present in old gateway with version 2.0.1.RELEASE as well. Downstream service instance is also same. Gateway v 2.0.1.RELEASE can get the response successfully while v2.2.2.RELEASE and 2.2.3.RELEASE can't

Further, with TRACE logging enabled, I see couple of these stack traces

mxku commented 4 years ago

Apparently the issue is because of Content-Length : 0 being set for a GET request. When this header is not sent to downstream service, it works fine.

GET /xxxRestService/pricingPolicies HTTP/1.0
Host: xxx
Connection: close
Content-Length: 0
Pragma: no-cache
Accept-Language: en-GB,en-US;q=0.9,en;q=0.8,hi;q=0.7
Authorization: Bearer xxx
Content-Type: application/json;charset=UTF-8
Accept: application/json, text/plain, */*
Cache-Control: no-cache
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.97 Safari/537.36
secTokenId: xxxx
Accept-Encoding: gzip, deflate
x-ov-claims: xxxx
Forwarded: proto=http;host="x.x.x.189:8000";for="x.x.x..189:58877"
X-Forwarded-For: x.x.x..189
X-Forwarded-Proto: http
X-Forwarded-Port: 8000
X-Forwarded-Host: x.x.x..189:8000

There is a related discussion in reactor-netty already. Link

@spencergibb Is there a way to stop setting Content-Length: 0 ?