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>
Comment From: 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!
Comment From: 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
Comment From: 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!
Comment From: 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
Comment From: 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.
Comment From: rstoyanchev
From a quick glance, could it be the client closed the connection after the response was committed and writing was in progress but before it was finished?
You have not indicated versions for Reactor Netty and Spring Framework so it's hard to tell much. You might want to look in the Reactor Netty source code and version you have to see in what cases that InternalNettyException is raised. Currently it's only used to wrap OutOfMemoryError but that changed at some point and currently it should be wrapped as AbortedException.
Comment From: matcdac
Spring framework version is 2.1.7.RELEASE io.projectreactor.reactor-core -> 3.2.11.RELEASE io.projectreactor.netty.reactor-netty -> 0.8.10.RELEASE io.projectreactor.addons.* -> 3.2.3.RELEASE
OutOfMemoryError does sound like a logical explanation, has happened in the past, had to optimize the interceptor then