TcpNetConnection: Read exception - Socket is closed

[membersound]

I'm creating a spring-integration client that connects to a server socket. The socket is a singleUse connection.

Problem: the server that I connect to forcibly closes the connection after my client received the server response. Therefore I'm getting lots of errors as follows.
I have to add that those errors do not occur all the time, only occasionally. But still often enough.

2019-06-24 12:15:25,106 ERROR o.s.i.i.t.c.TcpNetConnection: Read exception my.socket.host:10136:42132:e89e5c73-4987-428e-834d-61a85a739036 SocketException:Socket is closed
2019-06-24 12:16:14,026 ERROR o.s.i.i.t.c.TcpNetConnection: Read exception my.socket.host:10136:42148:07957d9e-9191-49d1-b8ad-96acf85ed6ef SocketException:Socket is closed
2019-06-24 12:16:24,736 ERROR o.s.i.i.t.c.TcpNetConnection: Read exception my.socket.host:10136:42158:53b879c5-289c-478e-b1b5-97a9cbc956fa SocketException:Socket is closed
2019-06-24 12:17:17,207 ERROR o.s.i.i.t.c.TcpNetConnection: Read exception my.socket.host:10136:42202:864c413e-7cac-4fc4-9c0e-79cbc98e8645 SocketException:Socket is closed

This is my simple socket config:

    @Bean
    public AbstractClientConnectionFactory clientFactory() throws Exception {
        TcpConnectionFactoryFactoryBean fact = new TcpConnectionFactoryFactoryBean();
        fact.setType("client");
        fact.setHost(host);
        fact.setPort(port);
        fact.setUsingNio(false);
	fact.setSingleUse(true);
        fact.setDeserializer(new MyDeserializer());
        fact.afterPropertiesSet();
        return (AbstractClientConnectionFactory) fact.getObject();
    }

      static class MyDeserializer implements Deserializer<String> {
		@Override
		public String deserialize(InputStream inputStream) throws IOException {
			try (BufferedReader br = new BufferedReader(new InputStreamReader(inputStream))) {
				return br.lines().collect(Collectors.joining("\n"));
			}
		}
	}

Suggestion: could you add a feature that should NOT log any error if socket is forcibly closed by the remote server? Or could there be a workaround?

    @Bean
    @ServiceActivator(inputChannel = "clientChannel")
    public TcpOutboundGateway outboundGateway(AbstractClientConnectionFactory factory) throws Exception {
        TcpOutboundGateway gateway = new TcpOutboundGateway();
        gateway.setConnectionFactory(factory);
        gateway.setRequiresReply(true);
        return gateway;
    }

[garyrussell]

Getting an error log there implies that you have an incomplete reply packet.

What is the context in which you are using that factory? I assume an outbound gateway?

The default deserializer expects \r\n at the end of the packet.

When the socket is closed between messages, the deserializer throws a SoftEndOfStreamException, which is a signal to the connection that this is a "normal" close, and nothing is logged.

Getting an ERROR log there means that there is some undecoded data that has been received, hence it's an ERROR condition.

I suggest you look at the reply packet(s) in WireShark (or similar) to see exactly what the server is replying with.

[membersound]

Yes, I'm using a TcpOutboundGateway together with a DirectChannel.
I'm also using a custom serializer. Added the code above.

Regardless of what whireshark would show, how could I prevent the error logging? Because all of my communication is working correctly. I always receive the full server response. And as I'm not in control of the socket server, there's not much I could do about the way it responds or terminates the socket. I just need a way to ignore those exceptions (as in my case they are false negative).

I mean: my serializer simply reads until -1 is received as char, which ends the serializer. Anything happening thereafter should not log any errors.

[garyrussell]

In future, please don't supply misleading configuration; I can't "guess" you are using a custom deserializer when your configuration showed no deserializer provisioned.

As I said, for a normal close, the deserializer should throw a SoftEndOfStreamException.

You can add a catch clause to your try block and rethrow the IOException as a SoftEndOfStreamException. However, with your implementation, it will be difficult to determine a "normal" close Vs. a real IOException.

With the standard deserializers, we can tell if we have actually read any incomplete data when we detect the end of stream.

One solution for your implementation would be to enable push back on the input stream.

DefaultTcpNetConnectionSupport connectionSupport = new DefaultTcpNetConnectionSupport();
connectionSupport.setPushbackCapable(true); // default push back buffer size is 1
fact.setTcpNetConnectionSupport(connectionSupport);

Then

      static class MyDeserializer implements Deserializer<String> {
		@Override
		public String deserialize(InputStream inputStream) throws IOException {
			try (BufferedReader br = new BufferedReader(new InputStreamReader(inputStream))) {
				PushbackInputStream pbis = (PushbackInputStream) inputStream;
				int first = pbis.read();
				if (first < 0) {
					throw new SoftEndOfStreamException();
				}
				pbis.unread(first);
				return br.lines().collect(Collectors.joining("\n"));
			}
		}
	}

See The TcpNetConnectionSupport Strategy Interface.

This interface is invoked to create objects of type TcpNetConnection (or its subclasses). The framework provides a single implementation (DefatulTcpNetConnectionSupport), which, by default, creates simple TcpNetConnection objects. It has two properties: pushbackCapable and pushbackBufferSize. When push back is enabled, the implementation returns a subclass that wraps the connection’s InputStream in a PushbackInputStream. Aligned with the PushbackInputStream default, the buffer size defaults to 1. This lets deserializers “unread” (push back) bytes into the stream. The following trivial example ...

[membersound]

I will investigate into this. But the root cause is not that the Deserializer throws an exception. Because I always get my payload correctly; an exception would prevent the payload being returned fromtry-catch block.
Thus nonetheless, the raised exception and logging is coming from inside the spring-integration framework.

[membersound]

Maybe this proofs that the exception is coming from the framework?

2019-06-25 15:34:21,278 DEBUG o.s.i.i.t.c.TcpNetClientConnectionFactory: Opening new socket connection to 123.456.789.123:1234
2019-06-25 15:34:21,282 DEBUG o.s.i.i.t.c.TcpNetConnection: New connection my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32
2019-06-25 15:34:21,282 DEBUG o.s.i.i.t.c.TcpNetClientConnectionFactory: clientFactory: Added new connection: my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32
2019-06-25 15:34:21,283 TRACE o.s.i.i.t.c.TcpNetClientConnectionFactory: clientFactory: Connection is open: my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32
DEBUG o.s.i.i.t.c.TcpNetConnection: my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32 Reading...
2019-06-25 15:34:21,286 TRACE o.s.i.i.t.c.TcpNetConnection: Published: TcpConnectionOpenEvent [source=TcpNetConnection:my.doamin:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32], [factory=clientFactory, connectionId=my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32] **OPENED**
2019-06-25 15:34:21,287 DEBUG o.s.i.i.t.c.TcpNetConnection: my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32 Message sent GenericMessage [payload=<mycontent>, headers={replyChannel=GenericMessagingTemplate$TemporaryReplyChannel@79c29215, errorChannel=GenericMessagingTemplate$TemporaryReplyChannel@79c29215, id=1af9d2bb-8527-d009-6cbd-7c37cdc2ce24, timestamp=1561469661277}]
2019-06-25 15:34:21,357 DEBUG o.s.i.i.t.c.TcpNetConnection: Message received GenericMessage [payload=<mypayload>, headers={ip_tcp_remotePort=1234, ip_connectionId=my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32, ip_localInetAddress=0.0.0.0/0.0.0.0, ip_address=123.456.789.123, id=98080e61-9ead-24e3-cfdb-3381a5aba9ef, ip_hostname=my.domain, timestamp=1561469661357}]
2019-06-25 15:34:21,358 TRACE o.s.i.i.t.c.TcpNetConnection: Published: TcpConnectionExceptionEvent [source=TcpNetConnection:my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32, cause=java.net.SocketException: Socket is closed], [factory=clientFactory, connectionId=my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32]
2019-06-25 15:34:21,359 TRACE o.s.i.i.t.c.TcpNetConnection: Published: TcpConnectionCloseEvent [source=TcpNetConnection:my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32], [factory=clientFactory, connectionId=my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32] **CLOSED**
2019-06-25 15:34:21,360 ERROR o.s.i.i.t.c.TcpNetConnection: Read exception my.domain:1234:35512:d43477b4-ebed-4922-a9e7-053f193aac32
java.net.SocketException: Socket is closed
	at java.net.Socket.getInputStream(Socket.java:905) ~[?:?]
	at org.springframework.integration.ip.tcp.connection.TcpNetConnection.inputStream(TcpNetConnection.java:163) ~[spring-integration-ip-5.1.5.RELEASE.jar:5.1.5.RELEASE]
	at org.springframework.integration.ip.tcp.connection.TcpNetConnection.getPayload(TcpNetConnection.java:126) ~[spring-integration-ip-5.1.5.RELEASE.jar:5.1.5.RELEASE]
	at org.springframework.integration.ip.tcp.connection.TcpMessageMapper.toMessage(TcpMessageMapper.java:176) ~[spring-integration-ip-5.1.5.RELEASE.jar:5.1.5.RELEASE]
	at org.springframework.integration.ip.tcp.connection.TcpMessageMapper.toMessage(TcpMessageMapper.java:63) ~[spring-integration-ip-5.1.5.RELEASE.jar:5.1.5.RELEASE]
	at org.springframework.integration.mapping.InboundMessageMapper.toMessage(InboundMessageMapper.java:42) ~[spring-integration-core-5.1.5.RELEASE.jar:5.1.5.RELEASE]
	at org.springframework.integration.ip.tcp.connection.TcpNetConnection.run(TcpNetConnection.java:181) ~[spring-integration-ip-5.1.5.RELEASE.jar:5.1.5.RELEASE]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

[garyrussell]

Interesting - which JVM are you using? I've never seen an exception on getInputStream(), we generally get EOF on the next read.

But, clearly you're getting an exception there.

Update: I just reproduced it in the debugger so there is a race condition that we don't deal with.

Will fix.

[membersound]

OpenJDK Runtime Environment (build 11.0.3+7-Ubuntu-1ubuntu218.04.1)

Race condition seems to fit my observation that this issue occurs only occasionally. Thank you so far!

[garyrussell]

Thanks for your patience. I still think you'll need the pushback trick in your deserializer, even with the fix, because there will still be a (smal) race between the framework getting the inputStream successfully and your BufferedReader.lines() call. It may be small enough, however, that you won't encounter it.