Why am I seeing this weird output in Java threads in Socket connections?

Question

So I have this little code:

public class MyCounterClass {
    private static int counter = 0;
    synchronized public static int getCounter(){
        return counter++;
    }
}

This is the server:

public class MyServer implements Runnable{

    public static void go() throws IOException {

        System.out.println("MyServer: Go called...");
        ServerSocket serverSocket = new ServerSocket(5000);
        while(true){
            Socket socket = serverSocket.accept();
            System.out.println(time() + "MyServer: Connection accepted!");
            OutputStream outputStream = socket.getOutputStream();
            System.out.println(time() + "MyServer: socket.getOutputStream");
            PrintWriter printWriter = new PrintWriter(outputStream);
            System.out.println(time() + "MyServer: New PrintWriter object created!");
            printWriter.write(time() + "Hello from my socket!");
            System.out.println(time() + "MyServer: printwriter.write method called..");
            printWriter.flush();
            System.out.println(time() + "MyServer: Flushed!");
            printWriter.close();
            System.out.println(time() + "MyServer: printWriter closed...");
        }
    }

    public static String time(){
        return String.valueOf(MyCounterClass.getCounter()) + " ";
    }

    @Override
    public void run() {
        try {
            go();
        } catch (IOException e) {
            e.printStackTrace();
        }
    }
}

This is the Client:

public class MyClient implements Runnable {

    public static void go() throws IOException {
        Socket socket = new Socket("localhost",5000);
        System.out.println(time() + "My Client: Connection established...");
        InputStream inputStream = socket.getInputStream();
        System.out.println(time() + "MyClient: socket.getInputStream...");
        BufferedReader bufferedReader = new BufferedReader(new InputStreamReader(inputStream));
        System.out.println(time() + "MyClient: BufferedReader object created...");
        System.out.println(time() + bufferedReader.readLine());
    }

    public static String time(){
        return String.valueOf(MyCounterClass.getCounter()) + " ";
    }

    @Override
    public void run() {
        try {
            go();
        } catch (IOException e) {
            e.printStackTrace();
        }
    }
}

And how I run the program:

public class TestClass {
    public static void main(String[] args) throws IOException, InterruptedException {
        Thread server = new Thread(new MyServer());
        server.start();
        Thread.sleep(750);
        Thread client = new Thread(new MyClient());
        client.start();
    }
}

And the output:

MyServer: Go called...
0 My Client: Connection established...
1 MyServer: Connection accepted!
2 MyClient: socket.getInputStream...
3 MyServer: socket.getOutputStream
4 MyClient: BufferedReader object created...
6 MyServer: New PrintWriter object created!
8 MyServer: printwriter.write method called..
9 MyServer: Flushed!
10 MyServer: printWriter closed...
5 7 Hello from my socket!

My question is, how can the last line get "5 and 7"?

jtahlborn · Answer 1 · 2014-06-28T16:38:52.220

5 -> the "time" the client receives the message
7 -> the "time" the server sent the message

since the client and server are independent threads, they will not output times in order.

the primary confusion comes because of this line:

System.out.println(time() + bufferedReader.readLine());

It seems like the println is going "back in time". what is happening, however, is that the time() method is called way back at time "5". but, since normal java sockets are blocking, the bufferedReader.readLine() call hangs until the data is actually available from the server, which doesn't happen until after it is sent by the server (of course). then, once the readLine method returns, the println call actually completes.

if you want to see a more "logical" progression, change the last client line to:

String result = bufferedReader.readLine();
System.out.println(time() + result);

that will delay the client's last time() call until after the response is actually received.

The responsible line is: System.out.println(time() + bufferedReader.readLine()); How can 2 time values be printed anyway? — Koray Tugay, Jun 28 '14 at 15:49
`5` is time when client **requested** the message, not the acctual message receive. — kajacx, Jun 28 '14 at 15:50

score 2 · Answer 2 · edited May 23 '17 at 12:05

Because you prepend (prepend = oposite of append) time both at your server and at your client, at server:

printWriter.write(time() + "Hello from my socket!");

'7' gets prepended to your message, then '7 Hello from my socket!' is sent and then 5 is prepended at your client:

System.out.println(time() + bufferedReader.readLine());

Resulting in 5 7 Hello from my socket!.

So how comes that time() returns 7 first and then 5?

Well, not because counter isn't volatile, see the reason here.

Now consider following scenario: At your client, time() is called and the result is stored, then the thread waits untul it recieves data, then server creates the data and sends them. It would explaint why client is printing lower values then server on the message sent.

You can also try to write:

System.out.println(time() + bufferedReader.readLine() + time());

To see if the second call of time will give greater value that first call + 1, due to the fact that readLine() freezes current thread until some data to read is avaliable.

Ah yes... that crazy printWriter.. Thanks for catching that. — Koray Tugay, Jun 28 '14 at 15:52
acces to counter is synchronized, no need to make it volatile. — jtahlborn, Jun 28 '14 at 16:33

Why am I seeing this weird output in Java threads in Socket connections?

2 Answers2

Linked