[LOG4J2-1042] Socket and Syslog appenders don't take timeout into account at startup

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 2.3
• Fix Version/s: 2.4
• Component/s: Appenders

Environment

Tested on ubuntu 14.04, with java:

java version "1.7.0_79"
OpenJDK Runtime Environment (IcedTea 2.5.5) (7u79-2.5.5-0ubuntu0.14.04.2)
OpenJDK 64-Bit Server VM (build 24.79-b02, mixed mode)

• Assignee: Unassigned
• Reporter: Guillaume Turri
• Created: 05/Jun/15 13:48
• Updated: 10/Jun/15 06:45
• Resolved: 05/Jun/15 18:51

Description

• Steps to reproduce:

run this code

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class App
{
	private static final Logger _logger = LogManager.getLogger("TestLogger");

	public static void main( String[] args )
	{
		_logger.error("some message");
		System.out.println("Done");
	}
}

with this config

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <Syslog name="my-syslog" host="192.168.12.8" port="12201" protocol="TCP" format="RFC5424" mdcId="mdc" includeMDC="true" appName="testGTApp" newLine="true" connectTimeoutMillis="100" immediateFail="true" reconnectionDelayMillis="3000" immediateFlush="true" />
  </Appenders>
  <Loggers>
    <Root level="info">
      <AppenderRef ref="my-syslog"/>
    </Root>
  </Loggers>
</Configuration>

where 192.168.12.8 is a host that actually exist (it can be pinged), but nothing is listening on this port.
(for some reason I don't completely understand, the host must not be localhost; otherwise we correctly get the expected behavior)

• Expected result:
  • log4j2 gives up trying to connect to the server after the specified timeout (here: 100ms)
  • the program prints "Done" on the console, and exits

• Actual result: the program doesn't print anything, and hangs forever.

A thread dump shows

"main" prio=10 tid=0x00007f8eac00a000 nid=0x2ca1 runnable [0x00007f8eb455a000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
	- locked <0x00000007d94f5e38> (a java.net.SocksSocketImpl)
	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
	at java.net.Socket.connect(Socket.java:579)
	at java.net.Socket.connect(Socket.java:528)
	at java.net.Socket.<init>(Socket.java:425)
	at java.net.Socket.<init>(Socket.java:208)
	at org.apache.logging.log4j.core.net.TcpSocketManager$TcpSocketManagerFactory.createManager(TcpSocketManager.java:285)
	at org.apache.logging.log4j.core.net.TcpSocketManager$TcpSocketManagerFactory.createManager(TcpSocketManager.java:272)
	at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:71)
	at org.apache.logging.log4j.core.appender.OutputStreamManager.getManager(OutputStreamManager.java:60)
	at org.apache.logging.log4j.core.net.TcpSocketManager.getSocketManager(TcpSocketManager.java:114)
	at org.apache.logging.log4j.core.appender.SocketAppender.createSocketManager(SocketAppender.java:173)
	at org.apache.logging.log4j.core.appender.SyslogAppender.createAppender(SyslogAppender.java:145)

• potential fix:
  With the following patch, I get the expected result, along with a logged "Error writing to TCP:192.168.12.8:12201 socket not available":

diff --git i/log4j-core/src/main/java/org/apache/logging/log4j/core/net/TcpSocketManager.java w/log4j-core/src/main/java/org/apache/logging/log4j/core/net/TcpSocketManager.java
index 9ab9f5f..0ba8d8a 100644
--- i/log4j-core/src/main/java/org/apache/logging/log4j/core/net/TcpSocketManager.java
+++ w/log4j-core/src/main/java/org/apache/logging/log4j/core/net/TcpSocketManager.java
@@ -282,7 +282,8 @@ public class TcpSocketManager extends AbstractSocketManager {
                 return null;
             }
             try {
-                final Socket socket = new Socket(data.host, data.port);
+               final Socket socket = new Socket();
+               socket.connect(new InetSocketAddress(data.host, data.port), data.connectTimeoutMillis);
                 os = socket.getOutputStream();
                 return new TcpSocketManager(name, os, socket, inetAddress, data.host, data.port,
                         data.connectTimeoutMillis, data.delayMillis, data.immediateFail, data.layout);