INT-2911 IO Exceptions Not Logged as ERROR

TcpNetConnection IO errors were only logged under DEBUG.

* Code was added to suppress the error log when the exception was due to a normal close. This inadvertently suppressed all ERROR logs.
* Capture a local copy of this.noReadErrorOnClose before closing the socket after an exception.
* Add test case to ensure ERROR log is emitted.

spring-integration-ip/src/main/java/org/springframework/integration/ip/tcp/connection/TcpNetConnection.java

@@ -110,7 +110,8 @@ public class TcpNetConnection extends TcpConnectionSupport {
 			try {
 				message = this.getMapper().toMessage(this);
 				this.lastRead = System.currentTimeMillis();
-			} catch (Exception e) {
+			}
+			catch (Exception e) {
 				if (handleReadException(e)) {
 					okToRun = false;
 				}
@@ -175,12 +176,16 @@ public class TcpNetConnection extends TcpConnectionSupport {
 			}
 		}
 		if (doClose) {
+			boolean noReadErrorOnClose = this.noReadErrorOnClose;
 			this.closeConnection();
 			if (!(e instanceof SoftEndOfStreamException)) {
 				if (e instanceof SocketTimeoutException && this.isSingleUse()) {
-					logger.debug("Closing single use socket after timeout");
-				} else {
-					if (this.noReadErrorOnClose) {
+					if (logger.isDebugEnabled()) {
+						logger.debug("Closed single use socket after timeout:" + this.getConnectionId());
+					}
+				}
+				else {
+					if (noReadErrorOnClose) {
 						if (logger.isTraceEnabled()) {
 							logger.trace("Read exception " +
 									 this.getConnectionId(), e);
@@ -189,16 +194,18 @@ public class TcpNetConnection extends TcpConnectionSupport {
 							logger.debug("Read exception " +
 									 this.getConnectionId() + " " +
 									 e.getClass().getSimpleName() +
-								     ":" + e.getCause() + ":" + e.getMessage());
+								     ":" + (e.getCause() != null ? e.getCause() + ":" : "") + e.getMessage());
 						}
-					} else if (logger.isTraceEnabled()) {
+					}
+					else if (logger.isTraceEnabled()) {
 						logger.error("Read exception " +
 								 this.getConnectionId(), e);
-					} else {
+					}
+					else {
 						logger.error("Read exception " +
 									 this.getConnectionId() + " " +
 									 e.getClass().getSimpleName() +
-								     ":" + e.getCause() + ":" + e.getMessage());
+								     ":" + (e.getCause() != null ? e.getCause() + ":" : "") + e.getMessage());
 					}
 				}
 			}

spring-integration-ip/src/test/java/org/springframework/integration/ip/tcp/connection/TcpNetConnectionTests.java

@@ -0,0 +1,71 @@
+/*
+ * Copyright 2002-2013 the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.springframework.integration.ip.tcp.connection;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNotNull;
+import static org.mockito.Mockito.doAnswer;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+
+import java.io.InputStream;
+import java.net.Socket;
+import java.util.concurrent.atomic.AtomicReference;
+
+import org.apache.commons.logging.Log;
+import org.junit.Test;
+import org.mockito.Mockito;
+import org.mockito.invocation.InvocationOnMock;
+import org.mockito.stubbing.Answer;
+import org.springframework.beans.DirectFieldAccessor;
+import org.springframework.integration.ip.tcp.serializer.ByteArrayStxEtxSerializer;
+
+/**
+ * @author Gary Russell
+ * @since 2.2.2
+ *
+ */
+public class TcpNetConnectionTests {
+
+	@Test
+	public void testErrorLog() throws Exception {
+		Socket socket = mock(Socket.class);
+		InputStream stream = mock(InputStream.class);
+		when(socket.getInputStream()).thenReturn(stream);
+		when(stream.read()).thenReturn((int) 'x');
+		TcpNetConnection connection = new TcpNetConnection(socket, true, false);
+		connection.setDeserializer(new ByteArrayStxEtxSerializer());
+		final AtomicReference<Object> log = new AtomicReference<Object>();
+		Log logger = mock(Log.class);
+		doAnswer(new Answer<Object>() {
+			public Object answer(InvocationOnMock invocation) throws Throwable {
+				log.set(invocation.getArguments()[0]);
+				return null;
+			}
+		}).when(logger).error(Mockito.anyString());
+		DirectFieldAccessor accessor = new DirectFieldAccessor(connection);
+		accessor.setPropertyValue("logger", logger);
+		connection.registerListener(mock(TcpListener.class));
+		connection.setMapper(new TcpMessageMapper());
+		connection.run();
+		assertNotNull(log.get());
+		assertEquals("Read exception " +
+				connection.getConnectionId() +
+				" MessageMappingException:Expected STX to begin message",
+				log.get());
+	}
+
+}