PrintStreamMessageLogger: thread name and unique message IDs

TODO.txt

@@ -99,12 +99,13 @@ TODO NEXT:
 	!! - pluggable logger
 		OK - create interface MessageLogger, class NullMessageLogger
 		OK - replace logging in MessageQueue with it
-		- create class SimpleMessageLogger to core tests, use in SuiteRunnerIntegrationHelper
+		!! - create class SimpleMessageLogger to core tests, use in SuiteRunnerIntegrationHelper
 		- write a test for the information shown in Actors.MessageToActor.toString()
 		- make sure that toString of reflective and generated messages are the same
+		- add logging to Executors, to see which actor started which worker thread?
 	- support for stopping actors?
 		- create ActorThread.stop()
-		- create ActorThread.isAlive()
+		- create ActorThread.isAlive(), or is it unnecessary? or useful for testing?
 		- SingleThreadedActors: unifying actors and the Executor
 			- implement commands as actors which are stopped immediately after executing them?
 			- have only one actor thread? might not be possible when supporting stopping?

jumi-actors/src/main/java/fi/jumi/actors/logging/PrintStreamMessageLogger.java

@@ -10,6 +10,9 @@
 @ThreadSafe
 public class PrintStreamMessageLogger implements MessageLogger {
 
+    private static final String OUTGOING_MESSAGE = "->";
+    private static final String INCOMING_MESSAGE = "<-";
+
     private final PrintStream out;
     private final ThreadLocal<Object> currentActor = new ThreadLocal<Object>();
 
@@ -19,7 +22,20 @@ public PrintStreamMessageLogger(PrintStream out) {
 
     @Override
     public void onMessageSent(Object message) {
-        out.println(currentActorFormatted() + " -> " + message);
+        logMessage(OUTGOING_MESSAGE, message);
+    }
+
+    @Override
+    public void onProcessingStarted(Object actor, Object message) {
+        currentActor.set(actor);
+        logMessage(INCOMING_MESSAGE, message);
+    }
+
+    private void logMessage(String messageDirection, Object message) {
+        String threadName = Thread.currentThread().getName();
+        int messageId = System.identityHashCode(message);
+        out.println(String.format("[%s] %s %s 0x%08x %s",
+                threadName, currentActorFormatted(), messageDirection, messageId, message));
     }
 
     private String currentActorFormatted() {
@@ -30,12 +46,6 @@ private String currentActorFormatted() {
         return currentActor.toString();
     }
 
-    @Override
-    public void onProcessingStarted(Object actor, Object message) {
-        currentActor.set(actor);
-        out.println(currentActorFormatted() + " <- " + message);
-    }
-
     @Override
     public void onProcessingFinished() {
         currentActor.remove();

jumi-actors/src/test/java/fi/jumi/actors/logging/PrintStreamMessageLoggerTest.java

@@ -9,6 +9,8 @@
 import java.io.*;
 import java.util.concurrent.*;
 
+import static fi.jumi.actors.logging.Matchers.containsLineWithWords;
+import static org.fest.assertions.Assertions.assertThat;
 import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.Matchers.containsString;
 
@@ -23,14 +25,14 @@ public class PrintStreamMessageLoggerTest {
     public void processing_messages_logs_both_the_actor_and_the_message() {
         logger.onProcessingStarted("actor1", "message1");
 
-        assertThat(output.toString(), containsString("actor1 <- message1"));
+        assertThat(output.toString(), containsLineWithWords("actor1 <-", "message1"));
     }
 
     @Test
     public void sending_messages_outside_an_actor_logs_only_the_message() {
         logger.onMessageSent("message1");
 
-        assertThat(output.toString(), containsString("<external> -> message1"));
+        assertThat(output.toString(), containsLineWithWords("<external> ->", "message1"));
     }
 
     @Test
@@ -39,7 +41,7 @@ public void sending_messages_from_an_actor_logs_both_the_actor_and_the_message()
 
         logger.onMessageSent("message1");
 
-        assertThat(output.toString(), containsString("actor1 -> message1"));
+        assertThat(output.toString(), containsLineWithWords("actor1 ->", "message1"));
     }
 
     @Test
@@ -67,8 +69,8 @@ public void run() {
                 }
         );
 
-        assertThat(output.toString(), containsString("actor1 -> message1"));
-        assertThat(output.toString(), containsString("actor2 -> message2"));
+        assertThat(output.toString(), containsLineWithWords("actor1 ->", "message1"));
+        assertThat(output.toString(), containsLineWithWords("actor2 ->", "message2"));
     }
 
     private static void executeConcurrently(Runnable... tasks) throws InterruptedException {
@@ -98,11 +100,29 @@ public void the_actor_of_the_current_thread_is_cleared_after_processing_the_mess
 
         logger.onMessageSent("message2");
 
-        assertThat(output.toString(), containsString("<external> -> message2"));
+        assertThat(output.toString(), containsLineWithWords("<external> ->", "message2"));
     }
 
-    // TODO: unique id for messages
-    // TODO: current thread
+    @Test
+    public void the_current_thread_is_logged() {
+        logger.onMessageSent("message1");
+
+        assertThat(output.toString(), containsString(Thread.currentThread().getName()));
+    }
+
+    @Test
+    public void unique_id_for_each_message_is_logged() {
+        String message = "message1";
+        int messageId = System.identityHashCode(message);
+
+        logger.onMessageSent(message);
+
+        String output = this.output.toString();
+        assertThat(output, containsString(Integer.toHexString(messageId)));
+        assertThat(output).matches("(?s).* 0x[0-9a-f]{8} .*");
+    }
+
+
     // TODO: timestamps
     // TODO: by default use System.out
 }