Bug 44108

Summary: Telnet Appender misses messages
Product: Log4j - Now in Jira Reporter: Dan Armbrust <daniel.armbrust.list>
Component: AppenderAssignee: log4j-dev <log4j-dev>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 1.2   
Target Milestone: ---   
Hardware: Other   
OS: other   

Description Dan Armbrust 2007-12-19 14:13:31 UTC
Using the newest 1.2 log4j, the TelnetAppender has an implementation mis-design
which causes it to not write messages to telnet sessions to random telnet
sessions after another telnet session has disconnected.

Here is the offending code:

    /** sends a message to each of the clients in telnet-friendly output. */
    public void send(String message) {
      Enumeration ce = connections.elements();
      for(Enumeration e = writers.elements();e.hasMoreElements();) {
        Socket sock = (Socket)ce.nextElement();
        PrintWriter writer = (PrintWriter)e.nextElement();
        writer.print(message);
        if(writer.checkError()) {
          // The client has closed the connection, remove it from our list:
          connections.remove(sock);
          writers.remove(writer);
        }
      }
    }

It is not safe to do a remove from a vector while you have an enumeration open
on it!  It results in the enumeration missing a valid element for each time you
call remove on the vector.

For example:

public static void main(String[] args) throws SocketException,
InterruptedException, URISyntaxException
{
        Vector temp = new Vector();
        temp.add("1");
	temp.add("2");
	temp.add("3");
	temp.add("4");
	Enumeration e = temp.elements();
	System.out.println(e.nextElement());
	Object o = e.nextElement();
	System.out.println(o);
	temp.remove(o);
	System.out.println(e.nextElement());
	System.out.println(e.nextElement());
}

The TelnetAppender code makes the assumption that this would print 1, 2, 3, and
4 to the console.  In fact, it prints 1, 2, 4 (and then takes and out of bounds
exception)
Comment 1 Dan Armbrust 2007-12-19 15:33:44 UTC
Here is a refactored and bug fixed version of the 2nd half of this class - the
SocketHandler part.

This corrects the bug that causes it to miss messages, cleans up some areas of
the code where the print writers were not closed properly, and makes the code
safe for multi-threaded operation - the previous code was not safe, because it
was using two vectors that were assumed to be the same size - but in reality,
they could be different sizes depending on how the threads stop and start.

You may need to remove the generics, if you still need to support 1.4.



// ---------------------------------------------------------- SocketHandler:

	/**
	 * The SocketHandler class is used to accept connections from clients. It is
	 * threaded so that clients can connect/disconnect asynchronously.
	 */
	protected class SocketHandler extends Thread
	{
		private Vector<TelnetClient> connections = new Vector<TelnetClient>();
		private ServerSocket serverSocket;
		private int MAX_CONNECTIONS = 20;

		public void finalize()
		{
			close();
		}

		/**
		 * make sure we close all network connections when this handler is
		 * destroyed.
		 * 
		 * @since 1.2.15
		 */
		public void close()
		{
			for (Enumeration<TelnetClient> e = connections.elements(); e.hasMoreElements();)
			{
				try
				{
					e.nextElement().close();
				}
				catch (Exception ex)
				{
				}
			}

			try
			{
				serverSocket.close();
			}
			catch (Exception ex)
			{
			}
		}

		/** sends a message to each of the clients in telnet-friendly output. */
		public void send(String message)
		{
			Vector<TelnetClient> lostClients = new Vector<TelnetClient>();
			for (Enumeration<TelnetClient> e = connections.elements(); e.hasMoreElements();)
			{
				TelnetClient tc = e.nextElement();
				tc.writer.print(message);
				if (tc.writer.checkError())
				{
					// The client has closed the connection, remove it from our list:
					lostClients.add(tc);
				}
			}
			
			for (Enumeration<TelnetClient> e = lostClients.elements(); e.hasMoreElements();)
			{
				TelnetClient tc = e.nextElement();
				tc.close();
				connections.remove(tc);
			}
			
		}

		/**
		 * Continually accepts client connections. Client connections are
		 * refused when MAX_CONNECTIONS is reached.
		 */
		public void run()
		{
			while (!serverSocket.isClosed())
			{
				try
				{
					Socket newClient = serverSocket.accept();
					TelnetClient tc = new TelnetClient(newClient);
					if (connections.size() < MAX_CONNECTIONS)
					{
						connections.addElement(tc);
						tc.writer.println("TelnetAppender v1.0 (" + connections.size() + " active
connections)");
						tc.writer.println();
						tc.writer.flush();
					}
					else
					{
						tc.writer.println("Too many connections.");
						tc.writer.flush();
						tc.close();
					}
				}
				catch (Exception e)
				{
					if (!serverSocket.isClosed())
					{
						LogLog.error("Encountered error while in SocketHandler loop.", e);
					}
					break;
				}
			}

			try
			{
				serverSocket.close();
			}
			catch (IOException ex)
			{
			}
		}

		public SocketHandler(int port) throws IOException
		{
			serverSocket = new ServerSocket(port);
			setName("TelnetAppender-" + getName() + "-" + port);
		}

	}

	protected class TelnetClient
	{
		private PrintWriter writer;
		private Socket connection;

		protected TelnetClient(Socket socket) throws IOException
		{
			connection = socket;
			writer = new PrintWriter(connection.getOutputStream());
		}

		protected void close()
		{
			if (writer != null)
			{
				try
				{
					writer.flush();
					writer.close();
				}
				catch (Exception e)
				{
					// noop
				}
			}

			if (connection != null)
			{
				try
				{
					connection.close();
				}
				catch (Exception e)
				{
					// noop
				}
			}
		}
	}
Comment 2 Dan Armbrust 2007-12-19 15:56:16 UTC
1 more issue regarding line feeds - one in my new code, one in the other
existing code.

My code posted above needs this replacement (I was using system line feeds, and
not the line feeds called out in the telnet RFC):

if (connections.size() < MAX_CONNECTIONS)
					{
						connections.addElement(tc);
						tc.writer.print("TelnetAppender v1.0 (" + connections.size() + " active
connections)\r\n\r\n");
						tc.writer.flush();
					}
					else
					{
						tc.writer.print("Too many connections.\r\n");
						tc.writer.flush();
						tc.close();
					}



Finally, the append method should have this in it:

for (int i = 0; i < len; i++)
{
	sh.send(s[i] + "\r\n");
}

The existing code uses the system line feed character instead of the correct
telnet line feed.
Comment 3 Curt Arnold 2007-12-19 17:12:56 UTC
Thanks for the bug report and patches.  log4j 1.2.x targets JDK 1.2 and later, so can't use generics in its 
code.  Will likely not get attention until after Christmas, sorry.
Comment 4 Curt Arnold 2008-01-17 12:27:32 UTC
Committed a change in rev 612959 that should address the same issues with less code changes.

 JDK 1.2 added Iterator as a replacement for Enumerator and Iterator.remove() can safely remove an 
element while iterating.  So SocketHandler.send was rewritten using Iterator. 

The occasions that writers and connections could get out of sync would be when a connection is being 
accepted while a message is being sent.  I've added sync blocks so that any access to connections or 
writers must have a lock of SocketHandler.  You could rewrite everything so that you could safely 
accept a connection while messages were being sent, but that seems to be overkill.

The Telnet RFC does require CRLF's.  The main message requires that you specify the layout including 
the line feed, so you should not use %n in a layout with TelnetAppender.  It would be possible to fix 
this after the fact, but I haven't attempted that.  I did change the EOL's used in the exception messages.
Comment 5 Dan Armbrust 2008-01-18 07:17:33 UTC
Changes look good to me.