Issue got on server

[matcdac]

getting the following exception on server, when using webflux

happened for 7 api calls (request-response)

encountered the issue 14 times within 2 minutes

these were thrown twice for the same api request-response exchange, the turnaround frame of this one was 150ms

> {
  "exceptionTraceHeirarchy": {},
  "exceptionMeta": {
    "className": "reactor.netty.ReactorNetty$InternalNettyException",
    "message": "java.nio.channels.ClosedChannelException",
    "cause": {
      "stackTrace": [
        {
          "methodName": "newClosedChannelException",
          "fileName": "AbstractChannel.java",
          "lineNumber": 955,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannel$AbstractUnsafe"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannel.java",
          "lineNumber": 863,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannel$AbstractUnsafe"
        },
        {
          "methodName": "write",
          "fileName": "DefaultChannelPipeline.java",
          "lineNumber": 1378,
          "nativeMethod": false,
          "className": "io.netty.channel.DefaultChannelPipeline$HeadContext"
        },
        {
          "methodName": "invokeWrite0",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 716,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "invokeWrite",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 708,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 791,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 701,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "LoggingHandler.java",
          "lineNumber": 249,
          "nativeMethod": false,
          "className": "io.netty.handler.logging.LoggingHandler"
        },
        {
          "methodName": "invokeWrite0",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 716,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "invokeWrite",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 708,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 791,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 701,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "CombinedChannelDuplexHandler.java",
          "lineNumber": 528,
          "nativeMethod": false,
          "className": "io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "MessageToMessageEncoder.java",
          "lineNumber": 112,
          "nativeMethod": false,
          "className": "io.netty.handler.codec.MessageToMessageEncoder"
        },
        {
          "methodName": "write",
          "fileName": "CombinedChannelDuplexHandler.java",
          "lineNumber": 348,
          "nativeMethod": false,
          "className": "io.netty.channel.CombinedChannelDuplexHandler"
        },
        {
          "methodName": "invokeWrite0",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 716,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "invokeWrite",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 708,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 791,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 701,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "HttpTrafficHandler.java",
          "lineNumber": 232,
          "nativeMethod": false,
          "className": "reactor.netty.http.server.HttpTrafficHandler"
        },
        {
          "methodName": "invokeWrite0",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 716,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "invokeWrite",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 708,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "access$1700",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 56,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 1102,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask"
        },
        {
          "methodName": "write",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 1149,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask"
        },
        {
          "methodName": "run",
          "fileName": "AbstractChannelHandlerContext.java",
          "lineNumber": 1073,
          "nativeMethod": false,
          "className": "io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask"
        },
        {
          "methodName": "safeExecute",
          "fileName": "AbstractEventExecutor.java",
          "lineNumber": 163,
          "nativeMethod": false,
          "className": "io.netty.util.concurrent.AbstractEventExecutor"
        },
        {
          "methodName": "runAllTasks",
          "fileName": "SingleThreadEventExecutor.java",
          "lineNumber": 416,
          "nativeMethod": false,
          "className": "io.netty.util.concurrent.SingleThreadEventExecutor"
        },
        {
          "methodName": "run",
          "fileName": "EpollEventLoop.java",
          "lineNumber": 331,
          "nativeMethod": false,
          "className": "io.netty.channel.epoll.EpollEventLoop"
        },
        {
          "methodName": "run",
          "fileName": "SingleThreadEventExecutor.java",
          "lineNumber": 918,
          "nativeMethod": false,
          "className": "io.netty.util.concurrent.SingleThreadEventExecutor$5"
        },
        {
          "methodName": "run",
          "fileName": "ThreadExecutorMap.java",
          "lineNumber": 74,
          "nativeMethod": false,
          "className": "io.netty.util.internal.ThreadExecutorMap$2"
        },
        {
          "methodName": "run",
          "fileName": "FastThreadLocalRunnable.java",
          "lineNumber": 30,
          "nativeMethod": false,
          "className": "io.netty.util.concurrent.FastThreadLocalRunnable"
        },
        {
          "moduleName": "java.base",
          "moduleVersion": "15.0.2",
          "methodName": "run",
          "fileName": "Thread.java",
          "lineNumber": 832,
          "nativeMethod": false,
          "className": "java.lang.Thread"
        }
      ],
      "suppressed": []
    }
  }
}

but the request-response transition details were as follows

> {
"signalType": {
    "declaringClass": "reactor.core.publisher.SignalType",
    "name": "ON_COMPLETE",
    "ordinal": 6,
    "clazz": "reactor.core.publisher.SignalType",
    "hashCode": 70220229,
    "toString": "onComplete"
  },
 "events": {
    "Begin": {
      "value": NumberLong(      1614251699546      ),
      "unit": "MilliSecond"
    },
    "End": {
      "value": NumberLong(      1614251699696      ),
      "unit": "MilliSecond"
    },
    "Frame": {
      "value": NumberLong(      150518814      ),
      "unit": "NanoSecond"
    }
  },
"serverHttpRequest": {
"_id": "af109c76",
"method": {
      "declaringClass": "org.springframework.http.HttpMethod",
      "name": "GET",
      "ordinal": 0,
      "clazz": "org.springframework.http.HttpMethod",
      "hashCode": 1493586489,
      "toString": "GET"
    },
    "methodValue": "GET"
},
"path": {
    "contextPath": {
      "elements": [],
      "value": "",
      "clazz": "org.springframework.http.server.DefaultPathContainer",
      "hashCode": 0,
      "toString": ""
    },
    "pathWithinApplication": {
      "elements": [
        {
          "value": "/",
          "clazz": "org.springframework.http.server.DefaultPathContainer$$Lambda$841/0x0000000801358440",
          "hashCode": 1401830440,
          "toString": "org.springframework.http.server.DefaultPathContainer$$Lambda$841/0x0000000801358440@538e3c28"
        },
        {
          "value": "xyz",
          "clazz": "org.springframework.http.server.DefaultPathContainer$DefaultPathSegment",
          "hashCode": -173788331,
          "toString": "[value='xyz']"
        }
      ],
      "value": "/xyz",
      "clazz": "org.springframework.http.server.DefaultPathContainer",
      "hashCode": 775197828,
      "toString": "/xyz"
    },
    "elements": [
      {
        "value": "/",
        "clazz": "org.springframework.http.server.DefaultPathContainer$$Lambda$841/0x0000000801358440",
        "hashCode": 1401830440,
        "toString": "org.springframework.http.server.DefaultPathContainer$$Lambda$841/0x0000000801358440@538e3c28"
      },
      {
        "value": "xyz",
        "clazz": "org.springframework.http.server.DefaultPathContainer$DefaultPathSegment",
        "hashCode": -173788331,
        "toString": "[value='xyz']"
      }
    ],
    "value": "/xyz",
    "clazz": "org.springframework.http.server.DefaultRequestPath",
    "hashCode": -1583998968,
    "toString": "/xyz"
  },
"serverHttpResponse": {
    "cookies": {
      "size": 0,
      "isEmpty": true,
      "clazz": "org.springframework.util.CollectionUtils$MultiValueMapAdapter",
      "hashCode": 0,
      "toString": "{}"
    },
    "headers": {
      "acceptLanguage": [],
      "acceptLanguageAsLocales": [],
      "accessControlAllowCredentials": false,
      "accessControlAllowHeaders": [],
      "accessControlExposeHeaders": [],
      "accessControlMaxAge": NumberLong(      -1      ),
      "accessControlRequestHeaders": [],
      "connection": [],
      "contentDisposition": {
        "type": "",
        "clazz": "org.springframework.http.ContentDisposition",
        "hashCode": 0,
        "toString": ""
      },
      "contentLength": NumberLong(      120515      ),
      "contentType": {
        "charset": {
          "aliases": [
            "unicode-1-1-utf-8",
            "UTF8"
          ],
          "canEncode": true,
          "displayName": "UTF-8",
          "isRegistered": true,
          "name": "UTF-8",
          "clazz": "sun.nio.cs.UTF_8",
          "hashCode": 81070450,
          "toString": "UTF-8"
        },
        "parameters": {
          "charset": "UTF-8"
        },
        "qualityValue": 1.0,
        "type": "application",
        "subtype": "json",
        "isConcrete": true,
        "isWildcardType": false,
        "isWildcardSubtype": false,
        "removeQualityValue": {
          "charset": {
            "aliases": [
              "unicode-1-1-utf-8",
              "UTF8"
            ],
            "canEncode": true,
            "displayName": "UTF-8",
            "isRegistered": true,
            "name": "UTF-8",
            "clazz": "sun.nio.cs.UTF_8",
            "hashCode": 81070450,
            "toString": "UTF-8"
          },
          "parameters": {
            "charset": "UTF-8"
          },
          "qualityValue": 1.0,
          "type": "application",
          "subtype": "json",
          "isConcrete": true,
          "isWildcardType": false,
          "isWildcardSubtype": false,
          "clazz": "org.springframework.http.MediaType",
          "hashCode": -224654938,
          "toString": "application/json;charset=UTF-8"
        },
        "clazz": "org.springframework.http.MediaType",
        "hashCode": -224654938,
        "toString": "application/json;charset=UTF-8"
      },
      "date": NumberLong(      -1      ),
      "expires": NumberLong(      -1      ),
      "ifMatch": [],
      "ifModifiedSince": NumberLong(      -1      ),
      "ifNoneMatch": [],
      "ifUnmodifiedSince": NumberLong(      -1      ),
      "lastModified": NumberLong(      -1      ),
      "vary": [],
      "size": 2,
      "isEmpty": false,
      "mapVsList": {
        "Content-Length": [
          "120515"
        ],
        "Content-Type": [
          "application/json;charset=UTF-8"
        ]
      },
      "clazz": "org.springframework.http.ReadOnlyHttpHeaders",
      "hashCode": 373937919,
      "toString": "[Content-Type:\"application/json;charset=UTF-8\", Content-Length:\"120515\"]"
    },
    "statusCode": {
      "value": 200,
      "reasonPhrase": "OK",
      "is1xxInformational": false,
      "is2xxSuccessful": true,
      "is3xxRedirection": false,
      "is4xxClientError": false,
      "is5xxServerError": false,
      "isError": false,
      "series": {
        "value": 2,
        "declaringClass": "org.springframework.http.HttpStatus$Series",
        "name": "SUCCESSFUL",
        "ordinal": 1,
        "clazz": "org.springframework.http.HttpStatus$Series",
        "hashCode": 2089181889,
        "toString": "SUCCESSFUL"
      },
      "declaringClass": "org.springframework.http.HttpStatus",
      "name": "OK",
      "ordinal": 4,
      "clazz": "org.springframework.http.HttpStatus",
      "hashCode": 2123877965,
      "toString": "200 OK"
    },
    "committedFlag": true,
    "clazz": "org.springframework.http.server.reactive.ReactorServerHttpResponse",
    "hashCode": 2095929933,
    "toString": "org.springframework.http.server.reactive.ReactorServerHttpResponse@7ced5a4d"
  },
}

using the following dependencies to be precise

> `<!-- Spring -->`
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-data-mongodb-reactive</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-data-mongodb</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-data-jpa</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-thymeleaf</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-webflux</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-log4j2</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-mail</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework</groupId>
			<artifactId>spring-context-support</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.data</groupId>
			<artifactId>spring-data-mongodb</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.data</groupId>
			<artifactId>spring-data-redis</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-devtools</artifactId>
			<scope>runtime</scope>
		</dependency>
		`<!-- Test -->`
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-test</artifactId>
			<scope>test</scope>
		</dependency>
		`<!-- Interceptor -->`
		<dependency>
			<groupId>com.github.TurquoiseSpace</groupId>
			<artifactId>spring-webflux-http-interceptor</artifactId>
			<version>${turquoise.space.version}</version>
		</dependency>

[bclozel]

Could you provide us with a repro project for this, without involving the spring-webflux-http-interceptor. Maybe the interceptor is trying to manipulate the exchange after the request/response has been fulfilled?

Thanks!

[matcdac]

Apologies, I cannot provide the repo of the project, since it belongs to the organization

The repository spring-webflux-http-interceptor is parsing and persisting the request and response only, without modifying it
The source code is available at :-
https://github.com/TurquoiseSpace/spring-webflux-http-interceptor
https://github.com/TurquoiseSpace/spring-webflux-http-interceptor/archive/master.zip
git@github.com:TurquoiseSpace/spring-webflux-http-interceptor.git
https://github.com/TurquoiseSpace/spring-webflux-http-interceptor.git
gh repo clone TurquoiseSpace/spring-webflux-http-interceptor

As per the exception log, the issue is not originating at the organization project, but coming from within netty io.netty package and propogated in the same package
The complete exception cause stack trace is attached in the description at the top

[bclozel]

Due to the asynchronous nature of request/response handling, the stacktrace doesn't necessarily means that the issue is in Netty or Spring Framework. A simple repro project is essential here and we can't really help.

There might be an issue with the interceptor implementation, or maybe the HTTP client closed the connection before the server could write the entire response.

Let us know if you manage to get to a sample that we can use. Thanks!

[matcdac]

I am not sure how I can share the whole project with you, since it belongs to the organization I work with

If you can let me know, exactly what you are looking for, code snippet or fragment, perhaps I should be able to help you with it

From the exceptions, it is showing only the cause, and not the exceptionTraceHeirarchy of the actual exception

We have also encountered the following exceptions several time, which neither have the exceptionTraceHeirarchy nor cause :-

{
"requestId" : "4f8dbdea",
"occurenceTimestamp" : NumberLong(1613843901510),
"localizedMessage" : "readAddress(..) failed: Connection reset by peer",
"message" : "readAddress(..) failed: Connection reset by peer",
"clazz" : "io.netty.channel.unix.Errors$NativeIoException",
"hashCode" : 1101967356,
"toString" : "io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection reset by peer"
}

and

{
"requestId" : "a50362e4",
"occurenceTimestamp" : NumberLong(1611243406391),
"localizedMessage" : "Connection prematurely closed BEFORE response",
"message" : "Connection prematurely closed BEFORE response",
"clazz" : "reactor.netty.http.client.PrematureCloseException",
"hashCode" : 374037578,
"toString" : "reactor.netty.http.client.PrematureCloseException: Connection prematurely closed BEFORE response"
}

Also kindly let me know if anything can be done from my end, or it is something which needs to be looked into from Spring side, or if it is expected behaviour which should not be handled

[bclozel]

I'm not asking for a full project - if you believe this is an issue in Spring Framework, trying to narrow down the problem by removing behavior and dependencies from the app (or starting with a new app from start.spring.io and slowly introducing changes until you can reproduce it) is really important.

The exceptions seem to indicate that the client has closed the connection prematurely - there's nothing the server can do here, besides report an exception. Depending on the server, we're trying to catch those exceptions at the handler level and log them in a dedicated group. Since your filter is listening to all signals and gathering information about them (and since the filter is a lower level construct), it might be expected to get those at this level.

Now without knowing what's the behavior of the client, it's hard to figure out if this is the expected behavior because the client is closing the connection prematuerly, or if it's a bug in the filter/interceptor because it might be using resources outside of their expected lifecycle (writing/reading from the exchange after it's done), or an actual bug in Spring Framework or Reactor Netty.

Issues like #26232 or #26181 or even spring-projects/spring-boot#23606 show that it's sometimes hard to come up with proper repro projects for such precise behaviors, but maybe the repros provided there can help.