Search code examples
javamultithreadingloggingprintstream

Java PrintStream redirection behaving unexpectedly


I was writing a basic server program when I used System.out.println to print out my log messages. I wrote a basic class file that uses that to write out to log. If I were to write the following:

System.out.println("Hello, world!");
System.out.println("Goodbye, world");

The desired output would be:

Log message - Hello, world!
Log message - Goodbye, world!

What ends up happening doesn't match the desired output. Instead, it outputs to the following.

Log message - Hello, world!
Goodbye, world!

The code for the main method:

public static void main(String[] args){
    LogManager.start();
    System.out.println("Hello, world!");
    System.out.println("Goodbye, world!");
    LogManager.stop();
}

The class LogManager switches the default PrintStream that is printed out to, and keeps a copy of the old one to print out log messages. However, "Log message - " isn't always being prefixed. Although, when sleeping for 2000ms between each println call, the output looks like the following.

Log message - Hello, world!
Log message - Goodbye, world!Log message - 

The code for LogManager is as follows.

import java.io.ByteArrayOutputStream;
import java.io.OutputStream;
import java.io.PrintStream;

public class LogManager implements Runnable{

    private final PrintStream ps;
    private final OutputStream out;
    private static boolean cont = true;

    public static void start(){
        OutputStream stdout = new ByteArrayOutputStream();
        PrintStream ps = new PrintStream(stdout);
        Thread th = new Thread(new LogManager(System.out, stdout));
        System.setOut(ps);
        th.start();
    }

    public static void stop(){
        cont = false;
    }

    public LogManager(PrintStream std, OutputStream out){
        this.ps = std;
        this.out = out;
    }

    @Override
    public void run() {
        ByteArrayOutputStream baos = (ByteArrayOutputStream) out;
        while(true){
            if(!cont) return;
            byte[] bytes = baos.toByteArray();
            if(bytes.length > 0){
                baos.reset();
                ps.print("Log message - " + new String(bytes));
            }
        }
    }
}

Could someone please point me to what I'm doing wrong, help would greatly be appreciated. I would like to stay away from libraries, as I would like to keep my JAR size to a minimum, with no additional packages having to be included, although mostly for knowing I didn't use anyone else's library to achieve what I am doing.


Solution

  • You have a few race conditions.

    Firstly, your program ends as soon as stop() finishes. When that happens, it could be before the LogManager thread has a chance to see the new bytes that have been written:

    1. main thread writes "Goodbye, world\n"
    2. main thread sets cont = false
    3. LogManager thread sees cont == false and halts, before having a chance to write its bytes.

    Additionally, you use baos.toByteArray(), and then as a separate action do baos.reset(). What happens if someone writes something between the two actions? They wouldn't be reflected in the bytes variable, but the reset() would erase them.

    To solve the first problem, you could do one last check before you return. In other words, if you imaging refactoring that whole toByteArray()/reset()/println bit to a method readAndPrint(), the return statement becomes:

    if (!cont) {
        readAndPrint(); // one last read to empty the buffer
        return;
    } 
    

    To solve the second problem, you should do the toByteArray() and reset() while holding a lock on boas (which will also lock against writes to that stream, since all reads and writes in ByteArrayOutputStream are synchronized). That will ensure that nobody else can get in a write while you're performing those two actions.

    byte[] bytes;
    synchronized (baos) {
        bytes = baos.toByteArray();
        baos.reset();
    }
    if (bytes.length > ) { ...
    

    Additionally, you should make the cont field volatile, so that a write in one thread is always seen in another.

    Note that the above will still leave you open to some races. For instance, if you had two "main" threads, you could imagine a scenario in which one of them calls stop() while the other is still trying to print messages out. The solution there is to somehow coordinate it such that by the time you call stop(), all threads have finished their logging.

    Multithreading is a very complicated and subtle topic, and hard to learn by experimentation. If you haven't yet, I would strongly suggest reading a book or in-depth tutorial to get a strong grasp of the problems and approaches to solving them.

    Lastly, you didn't ask about the odd newlines in your output, but they're likely due to the fact that you're using the PrintStream being flushed (and thus writing their contents out to the BAOS) as the signal for printing the prefix, as opposed to something like seeing a newline in the bytes buffer. If that flush happens before the newline gets written, you'll see the behavior you're seeing.