Add more detail to log messages (elastic#47)

Add details of the publication that is timing out, and more timings to the
start/end of stabilisation. Also the logging of the start of the stabilisation
phase wasn't actually at the start.

Author: DaveCTurner

server/src/main/java/org/elasticsearch/discovery/zen2/Legislator.java

@@ -457,6 +457,8 @@ public void onTimeout() {
             failActiveTargets();
 
             if (mode == Mode.LEADER && applyCommitReference.get() == null) {
+                logger.debug("Publication.onTimeout(): failed to commit version [{}] in term [{}]",
+                    publishRequest.getAcceptedState().version(), publishRequest.getAcceptedState().term());
                 becomeCandidate("Publication.onTimeout()");
             }
         }

server/src/test/java/org/elasticsearch/discovery/zen2/LegislatorTests.java

@@ -448,20 +448,21 @@ public void stabilise() {
 
         public void stabilise(long stabilisationTimeMillis, long delayVariability) {
             // Stabilisation phase: just wake up nodes in order for long enough to allow a leader to be elected
+
+            final long stabilisationPhaseEndMillis = currentTimeMillis + stabilisationTimeMillis;
+            logger.info("--> starting stabilisation phase at [{}ms]: run for [{}ms] until [{}ms] with delayVariability [{}ms]",
+                currentTimeMillis, stabilisationTimeMillis, stabilisationPhaseEndMillis, delayVariability);
+
             setDelayVariability(delayVariability);
 
             deliverNextMessageUntilQuiescent();
 
-            final long stabilisationPhaseEndMillis = currentTimeMillis + stabilisationTimeMillis;
-            logger.info("--> start of stabilisation phase ({}ms): run until time {}ms", stabilisationTimeMillis,
-                stabilisationPhaseEndMillis);
-
             while (tasks.isEmpty() == false && getNextTaskExecutionTime() <= stabilisationPhaseEndMillis) {
                 doNextWakeUp();
                 deliverNextMessageUntilQuiescent();
             }
 
-            logger.info("--> end of stabilisation phase");
+            logger.info("--> end of stabilisation phase at [{}ms]", currentTimeMillis);
 
             assertUniqueLeaderAndExpectedModes();
         }