Robust logging solution to file on disk from multiple threads on serverside code

Question

I have implemented a socket listener that runs on my Linux Ubuntu server accepting connections and then starting up a new thread to listen on those connections (classic socket listener approach). The socket listener is persistant and the way it is restarted is by restarting the server.

I have implemented a logging feature in the code so that information such as the data received, any events that have occurred etc are logged to a file. All threads log to this same file and the file is named by the day it's on. So I end up with log files such as 2012-May-01.txt, 2012-May-02.txt etc etc.

In order to provide this logging, I implemented a couple of classes to handle the logging.

• EventLog - Just a wrapper to hide away my actual logger and what is used by the various threads etc for logging
• Logstream - The class that does the logging to file

I'm a bit concerned about this class and ensuring I capture all log events. As it can be called by multiple threads I do not want to lose any information.

I'm pretty sure logging is such a common issue so I'm hoping someone can point out the issues in this code and provide a much more robust solution. I am potentially going to look into other existing logging solutions as suggested by sudmong, but for now this is the easiest for me to get my head around (assuming it's a valid solution).

Important: I want to keep the facility to log items in a file naming convention that fits the day the item was logged. I don't want one log file that spans multiple days etc

EDIT: Following from X-Zero's comments I've changed my logging mechanism to use a BlockingQueue approach. Does this seem like a scalable solution if I was to look at logging perhaps up to 100 lines per second? The main issue I can see is perhaps the opening and closing of my log file for every log write and whether I should catch the FileWriter handle and only re-create on each new day?

// Class interface through which all logging occurs
public class EventLog {

    private static Logstream _eventLog;

    public static Logstream create(BlockingQueue<StringBuilder> queue, String rootPath, int port)
    {
        _eventLog = new Logstream(queue, rootPath, port);
        return _eventLog;
    }

    public static Logstream create(String rootPath, int port)
    {
        return create(new LinkedBlockingQueue<StringBuilder>(), rootPath, port);
    }

    public static void write(Exception ex, String cls, String func)
    {
        write("Exception: " + ex.toString(), cls, func);
    }

    public static void write(String msg, String cls, String func)
    {
        _eventLog.write(msg, cls, func);
    }
}

And the actual logging class:

import java.io.BufferedWriter;
import java.io.FileWriter;
import java.io.IOException;
import java.util.Calendar;
import java.util.Date;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
import java.text.SimpleDateFormat;

public class Logstream implements Runnable {

    private final String _path;         // The root path we will use for logging
    private final int _port;            // the port of the application using this logger
    private final BlockingQueue<StringBuilder> _queue; // Used to queue up messages for logging
    private final Thread _writeThread;  // Thread to run this logstream on

    private int _dayOfMonth = -1;       // The current day of the month
    private String _cachedPath = "";    // Our log path.  Changes for each day of the month

   protected Logstream(BlockingQueue<StringBuilder> queue, String rootPath, int port) {
            _port = port;
        _path  = rootPath;

        _queue = queue;  // LinkedBlockingQueue<StringBuilder>();

        _writeThread = new Thread(this);
        _writeThread.start();
   }

    public void write(String msg, String cls, String func)
    {
        queue(msg, cls, func);      
    }

    public void run()
    {
        // logging never stops unless we restart the entire server so just loop forever
        while(true) {
            try {
                StringBuilder builder = _queue.take();  
                flush(builder);
            } catch(InterruptedException ex) {
                flush(ex.toString());
                System.out.println("Exception: LogStream.run: " + ex.getMessage());
            }    
        }
    }

    private void flush(StringBuilder builder) { 
        flush(builder.toString());
    }

    private void flush(String data) {

        BufferedWriter writer = null;

        try {

            System.out.println(data);

            writer = getOutputStream();

            writer.write(data);
            writer.newLine();
            writer.flush();             
        }
        catch(IOException ex) {
            // what to do if we can't even log to our log file????
            System.out.println("IOException: EventLog.flush: " + ex.getMessage());
        }
        finally {
            closeOutputStream(writer);
        }
    }

    private boolean dayOfMonthHasChanged(Calendar calendar) {
        return calendar.get(Calendar.DAY_OF_MONTH) != _dayOfMonth;
    }

    private String getPath() {

        Calendar calendar = Calendar.getInstance();

        if(dayOfMonthHasChanged(calendar)) {

            StringBuilder pathBuilder = new StringBuilder();
            SimpleDateFormat df = new SimpleDateFormat("dd-MMM-yy");
            Date date = new Date(System.currentTimeMillis());

            _dayOfMonth = calendar.get(Calendar.DAY_OF_MONTH);

            pathBuilder.append(_path);
            pathBuilder.append(df.format(date)).append("_");
            pathBuilder.append(_port);
            pathBuilder.append(".txt");

            _cachedPath = pathBuilder.toString();       
        }

        return _cachedPath;
    }

    private BufferedWriter getOutputStream() throws IOException {
        return new BufferedWriter(new FileWriter(getPath(), true));         
    }

    private void closeOutputStream(BufferedWriter writer) {
        try {
            if(writer != null) {
                writer.close();
            }
        }
        catch(Exception ex) {
            System.out.println("Exception: LogStream.closeOutputStream: " + ex.getMessage());
        }   
    }

    private StringBuilder queue(String msg, String cls, String func) {
        Date date = new Date(System.currentTimeMillis());

        // $time  . ": " . $func . ": " . $msg ."\n"
        StringBuilder msgBuilder = new StringBuilder();
        msgBuilder.append(new SimpleDateFormat("H:mm:ss").format(date));
        msgBuilder.append(": ");
        msgBuilder.append(cls);
        msgBuilder.append("->");
        msgBuilder.append(func);
        msgBuilder.append("()");
        msgBuilder.append(" :: ");
        msgBuilder.append(msg);

        try {
            _queue.put(msgBuilder);
        }
        catch (InterruptedException e) {
            flush(new StringBuilder(e.toString()));
            flush(msgBuilder);
        }

        return msgBuilder;
    }
}

So I created a unit test to check if overloading the log writing with multiple writes at once will ensure all events get written. I toggled between using two blockingqueue approaches.

• ArrayBlockingQueue, with capacity set to 1
• LinkedBlockingQueue

When using these I noticed that LinkedBlockingQueue could not keep up, where as ArrayBlockingQueue seemed to work 100% of the time. The LinkedBlockingQueue would often get to about 100 and stop outputing lines to the console where as the ArrayQueue would go through the full 1000.

My unit test code was:

    @Test
public void testLogStreamArrayBlockingQueue() {

    EventLog.create(new ArrayBlockingQueue<StringBuilder>(1), "", 1);

    for(int i = 0; i < 1000; i++) {
        EventLog.write("ArrayBlockingQueue: " + i, "EventLogUnitTest", "testLogStreamArrayBlockingQueue");
    }

    Assert.assertTrue(true);
}

@Test
public void testLogStreamLinkedBlockingQueue() {

    EventLog.create(new LinkedBlockingQueue<StringBuilder>(), "", 1);

    for(int i = 0; i < 1000; i++) {
        EventLog.write("LinkedBlockingQueue: " + i, "EventLogUnitTest", "testLogStreamLinkedBlockingQueue");
    }

    Assert.assertTrue(true);
}

Answer 1

Just some random notes about the code and the comments:

1. The cause of missing log messages in the testLogStreamLinkedBlockingQueue is that that JUnit (or JUnit in Eclipse, I haven't tested from command line) stops the threads of the tests when the test method ends. Because writing is done by another thread it may need some time to write out every message from the queue. If you put a Thread.sleep(5000) at the end of the test method both version writes out all the 1000 messages.

2. It's good to know that logging system sometimes are best-effort fail-stop logging systems which means that you could loose messages without any exception if there is an IO error. (Logback reliability)

3. Field names should not start with underscore. Logstream should be LogStream. See Effective Java, 2nd edition, Item 56: Adhere to generally accepted naming conventions and The Java Language Specification, Java SE 7 Edition, 6.1 Declarations:

   Class and Interface Type Names

   Names of class types should be descriptive nouns or noun phrases, not overly long, in mixed case with the first letter of each word capitalized.

   [...]

   Names of fields that are not final should be in mixed case with a lowercase first letter and the first letters of subsequent words capitalized.

4. What is cls? A longer name would be easier to understand.

5. Starting a thread from a constructor does not smell well. It's rather error-prone. Java theory and practice: Safe construction techniques

6. new Date(System.currentTimeMillis()); is the same as new Date().

7. I'd store String objects in the queue. Strings are immutable which is more concurrency-friendly (there is no risk that another thread modifies the object without synchronization). Furthermore, usage of Strings would move the cost of StringBuilder.toString() to other threads. The writer thread could be a bottleneck, so it's better if it has to do as less work as possible.

8. flush(new StringBuilder(e.toString())) could be simply flush(e.toString()).

9. I'd check nulls in the constructors. checkNotNull from Guava is a great choice for that. (Also see: Effective Java, 2nd edition, Item 38: Check parameters for validity)

Answer 2

Here are some ideas:

• For better granularity of logs, if you're looking at high performance, write on a minutely, or hourly basis. Use the idea of writing to logs as jobs, each dispatched to a thread. This makes searchability of log files inherently parallelizable.
• Use a shutdown hook to flush on shutdown.
• Keep an option to convert your log class into out-of-proc - like a TCP Daemon or web server + client library.... That will definitely help all the applications you write, including those which crash sporadically.