spring-cloud-gateway: Cannot route to https URI: unexpected message type

@tony-clarke-amdocs Is your problem solved? I encountered the same problem in stress testing.

The reactor team is looking at things

@spencergibb @violetagg Hi, we are still seeing this problem with Spring Cloud Gateway 2.0.2 which uses reactor-netty 0.7.10.RELEASE. In order to reproduce the problem you need to run for a long time. In an 8 hour run it occurs one time. The latest stack trace looks like:

io.netty.handler.codec.EncoderException: java.lang.IllegalStateException: unexpected message type: DefaultHttpRequest, state: 1
                at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:106) ~[netty-codec-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.CombinedChannelDuplexHandler.write(CombinedChannelDuplexHandler.java:348) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:738) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:730) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:816) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:723) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at reactor.ipc.netty.channel.ChannelOperationsHandler.doWrite(ChannelOperationsHandler.java:293) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at reactor.ipc.netty.channel.ChannelOperationsHandler.drain(ChannelOperationsHandler.java:476) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at reactor.ipc.netty.channel.ChannelOperationsHandler.flush(ChannelOperationsHandler.java:194) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:776) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:802) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:814) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:794) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:831) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1071) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:300) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at reactor.ipc.netty.http.HttpOperations.lambda$then$0(HttpOperations.java:135) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at reactor.ipc.netty.FutureMono$DeferredFutureMono.subscribe(FutureMono.java:200) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at reactor.core.publisher.Mono.subscribe(Mono.java:3088) ~[reactor-core-3.1.10.RELEASE.jar!/:3.1.10.RELEASE]
                at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:172) ~[reactor-core-3.1.10.RELEASE.jar!/:3.1.10.RELEASE]
                at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56) ~[reactor-core-3.1.10.RELEASE.jar!/:3.1.10.RELEASE]
                at reactor.core.publisher.Mono.subscribe(Mono.java:3088) ~[reactor-core-3.1.10.RELEASE.jar!/:3.1.10.RELEASE]
                at reactor.ipc.netty.NettyOutbound.subscribe(NettyOutbound.java:369) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at reactor.core.publisher.MonoSource.subscribe(MonoSource.java:51) ~[reactor-core-3.1.10.RELEASE.jar!/:3.1.10.RELEASE]
                at reactor.ipc.netty.channel.ChannelOperations.applyHandler(ChannelOperations.java:381) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at reactor.ipc.netty.http.client.HttpClientOperations.onHandlerStart(HttpClientOperations.java:505) ~[reactor-netty-0.7.10.RELEASE.jar!/:0.7.10.RELEASE]
                at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) ~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) ~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:446) ~[netty-transport-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) ~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
                at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_181]
Caused by: java.lang.IllegalStateException: unexpected message type: DefaultHttpRequest, state: 1
                at io.netty.handler.codec.http.HttpObjectEncoder.encode(HttpObjectEncoder.java:86) ~[netty-codec-http-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.handler.codec.http.HttpClientCodec$Encoder.encode(HttpClientCodec.java:167) ~[netty-codec-http-4.1.29.Final.jar!/:4.1.29.Final]
                at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:88) ~[netty-codec-4.1.29.Final.jar!/:4.1.29.Final]
                ... 30 common frames omitted

Thank you for the update. I’ve kicked off a test run using reactor-netty-0.7.8.BUILD-20180606.174842-17.jar

I think this one should fix the issue https://github.com/reactor/reactor-netty/pull/371 let us review it a bit and then we will commit it to the 0.7.x snapshot

buildscript {
    ext {
        springBootVersion = '2.0.2.BUILD-SNAPSHOT'
    }
    dependencies {
        classpath("org.springframework.boot:spring-boot-gradle-plugin:${springBootVersion}")
    }
}
dependencyManagement {
    imports {
        mavenBom 'org.springframework.cloud:spring-cloud-gateway:2.0.0.BUILD-SNAPSHOT'
    }
}
dependencies {
    compile('org.springframework.cloud:spring-cloud-starter-gateway')
    compile('org.springframework.cloud:spring-cloud-starter-netflix-hystrix')
    compile('org.springframework.boot:spring-boot-starter-actuator')
}

Not seeing issues so far with this (abbreviated) build.gradle

@bcelenk thanks for the detailed explanation! @spencergibb @tony-clarke-amdocs I’m experiencing this exact problem as well, is there a way to try out 0.8.0.M1 of the reactor-netty with this? When I try to use it with spring-boot-dependencies of version 2.1.0.M1, I can get the reactor-netty on board with version: 0.8.0.M1 but reactor.ipc.netty.http.server.HttpServerOptions class is missing with that so my code doesn’t compile?

Hi,

I’ve come across with the same problem, reproducing is trivial. Below is the stack trace.

java.io.IOException: Connection closed prematurely
	at reactor.ipc.netty.http.client.HttpClientOperations.onInboundClose(HttpClientOperations.java:269) ~[reactor-netty-0.7.8.RELEASE.jar:0.7.8.RELEASE]
	at reactor.ipc.netty.channel.ChannelOperationsHandler.channelInactive(ChannelOperationsHandler.java:113) ~[reactor-netty-0.7.8.RELEASE.jar:0.7.8.RELEASE]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:420) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:377) ~[netty-codec-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:342) ~[netty-codec-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.handler.codec.http.HttpClientCodec$Decoder.channelInactive(HttpClientCodec.java:282) ~[netty-codec-http-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:223) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:224) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1429) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:245) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:231) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:947) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:822) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163) ~[netty-common-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java) ~[netty-common-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404) ~[netty-common-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:464) ~[netty-transport-4.1.27.Final.jar:4.1.27.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884) ~[netty-common-4.1.27.Final.jar:4.1.27.Final]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_171]

I’m using raw cloud-gateway and webflux which are both produced by Spring Initializr/no modifications, just added a uuid to represent each user’s session.

Load is generated using Gatling, 2000rps. Below is the gatling’s scala file.

import io.gatling.core.Predef._
import io.gatling.http.Predef._
import io.gatling.http.request.builder.HttpRequestBuilder.toActionBuilder
import scala.concurrent.duration._
import java.util.UUID

class GatewayLoadTest extends Simulation {
  object UuidFeeder {
    val feeder = Iterator.continually(Map("uuid" -> java.util.UUID.randomUUID.toString()))
  }

  
  val theHttpProtocolBuilder = http
        .baseURL("http://localhost:8080")

  val theScenarioBuilder = scenario("sample")
  .feed(UuidFeeder.feeder)
  .forever(){
  	 exec(http("gateway")
      .get("/premature/${uuid}")
      .header("gatling-user-id", "${uuid}")
  	  .check(
          
                    status.find.in(200)))
  	}
  
    setUp(
        theScenarioBuilder.inject(constantUsersPerSec(100) during (120 seconds))
    )
    .throttle(
  			reachRps(2000) in (1 seconds),
  			holdFor(120 seconds)
		)
      .protocols(theHttpProtocolBuilder)


}

After 11k requests, exception occurred. This number varies between tests.

Gateway/reactor-netty’s context when exception is occurred:

Origin is unaware about exception

Wireshark HTTP packages, user’s first two request were delegated to origin, 3rd one wasn’t forwarded.

Last http package’s details

Frame 275732: 210 bytes on wire (1680 bits), 210 bytes captured (1680 bits) on interface 0
    Interface id: 0 (lo0)
        Interface name: lo0
    Encapsulation type: NULL/Loopback (15)
    Arrival Time: Aug  2, 2018 16:43:41.578082000 +03
    [Time shift for this packet: 0.000000000 seconds]
    Epoch Time: 1533217421.578082000 seconds
    [Time delta from previous captured frame: 0.000009000 seconds]
    [Time delta from previous displayed frame: 0.345598000 seconds]
    [Time since reference or first frame: 233.942944000 seconds]
    Frame Number: 275732
    Frame Length: 210 bytes (1680 bits)
    Capture Length: 210 bytes (1680 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: null:ip:tcp:http]
    [Coloring Rule Name: HTTP]
    [Coloring Rule String: http || tcp.port == 80 || http2]
Null/Loopback
    Family: IP (2)
Internet Protocol Version 4, Src: 127.0.0.1, Dst: 127.0.0.1
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
        0000 00.. = Differentiated Services Codepoint: Default (0)
        .... ..00 = Explicit Congestion Notification: Not ECN-Capable Transport (0)
    Total Length: 206
    Identification: 0x0000 (0)
    Flags: 0x02 (Don't Fragment)
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 64
    Protocol: TCP (6)
    Header checksum: 0x0000 [validation disabled]
    [Header checksum status: Unverified]
    Source: 127.0.0.1
    Destination: 127.0.0.1
    [Source GeoIP: Unknown]
    [Destination GeoIP: Unknown]
Transmission Control Protocol, Src Port: 57374, Dst Port: 8080, Seq: 309, Ack: 299, Len: 154
    Source Port: 57374
    Destination Port: 8080
    [Stream index: 6157]
    [TCP Segment Len: 154]
    Sequence number: 309    (relative sequence number)
    [Next sequence number: 463    (relative sequence number)]
    Acknowledgment number: 299    (relative ack number)
    1000 .... = Header Length: 32 bytes (8)
    Flags: 0x018 (PSH, ACK)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...1 .... = Acknowledgment: Set
        .... .... 1... = Push: Set
        .... .... .0.. = Reset: Not set
        .... .... ..0. = Syn: Not set
        .... .... ...0 = Fin: Not set
        [TCP Flags: ·······AP···]
    Window size value: 12750
    [Calculated window size: 408000]
    [Window size scaling factor: 32]
    Checksum: 0xfec2 [unverified]
    [Checksum Status: Unverified]
    Urgent pointer: 0
    Options: (12 bytes), No-Operation (NOP), No-Operation (NOP), Timestamps
        TCP Option - No-Operation (NOP)
            Kind: No-Operation (1)
        TCP Option - No-Operation (NOP)
            Kind: No-Operation (1)
        TCP Option - Timestamps: TSval 458370685, TSecr 458370364
            Kind: Time Stamp Option (8)
            Length: 10
            Timestamp value: 458370685
            Timestamp echo reply: 458370364
    [SEQ/ACK analysis]
        [iRTT: 0.000137000 seconds]
        [Bytes in flight: 154]
        [Bytes sent since last PSH flag: 154]
    TCP payload (154 bytes)
Hypertext Transfer Protocol
    GET /premature/43d91f31-5fc7-4c65-81eb-84d9865c2ff1 HTTP/1.1\r\n
        [Expert Info (Chat/Sequence): GET /premature/43d91f31-5fc7-4c65-81eb-84d9865c2ff1 HTTP/1.1\r\n]
            [GET /premature/43d91f31-5fc7-4c65-81eb-84d9865c2ff1 HTTP/1.1\r\n]
            [Severity level: Chat]
            [Group: Sequence]
        Request Method: GET
        Request URI: /premature/43d91f31-5fc7-4c65-81eb-84d9865c2ff1
        Request Version: HTTP/1.1
    gatling-user-id: 43d91f31-5fc7-4c65-81eb-84d9865c2ff1\r\n
    Host: localhost:8080\r\n
    Accept: */*\r\n
    \r\n
    [Full request URI: http://localhost:8080/premature/43d91f31-5fc7-4c65-81eb-84d9865c2ff1]
    [HTTP request 3/3]
    [Prev request in frame: 270045]

Tcp stream of the last http package(produces using right-click>follow TCP stream):

All apps are run on my personal macbook, same exception also occurs on EC2/Linux per gateway/origin with genuine clients.

Macbook specs: macOS High Sierra 10.13.6 (17G65) Processor 2.2 GHz Intel Core i7 Memory 16 GB 1600 MHz DDR3 Tried with 3 different jdks: jdk1.8.0_131 jdk1.8.0_171 jdk1.8.0_181

@violetagg @spencergibb Using netty-reactor 0.7.8 is much better, but it is not 100% fixed. Now I see an exception javax.net.ssl.SSLException: SSLEngine closed already at io.netty.handler.ssl.SslHandler.wrap(...)(Unknown Source) ~[netty-handler-4.1.25.Final.jar!/:4.1.25.Final] This exception occurs maybe 10 times in a 5 hour test. You can use this repo to reproduce the problem.

Disabling the netty client pool solves the problems for any recent version of the spring cloud gateway.

I’ve been assuming this problem was originally related to https, but maybe that’s not true anymore. I’ll change my test to use http and see what happens.

@spencergibb is this potentially a release blocker?

@spencergibb any update from the reactor team/issue to track on their end? Running into the same issue intermittently.