better logging

trace log the low level details on recovery

bin/plugin

@@ -28,7 +28,6 @@ else
     JAVA=`which java`
 fi
 
-# this is a poor mans getopt replacement
 # real getopt cannot be used because we need to hand options over to the PluginManager
 while [ $# -gt 0 ]; do
   case $1 in

src/main/java/org/elasticsearch/index/gateway/IndexShardGatewayService.java

@@ -189,6 +189,8 @@ public class IndexShardGatewayService extends AbstractIndexShardComponent implem
                     recoveryStatus.updateStage(RecoveryStatus.Stage.DONE);
 
                     if (logger.isDebugEnabled()) {
+                        logger.debug("recovery completed from [{}], took [{}]", shardGateway, timeValueMillis(recoveryStatus.time()));
+                    } else if (logger.isTraceEnabled()) {
                         StringBuilder sb = new StringBuilder();
                         sb.append("recovery completed from ").append(shardGateway).append(", took [").append(timeValueMillis(recoveryStatus.time())).append("]\n");
                         sb.append("    index    : files           [").append(recoveryStatus.index().numberOfFiles()).append("] with total_size [").append(new ByteSizeValue(recoveryStatus.index().totalSize())).append("], took[").append(TimeValue.timeValueMillis(recoveryStatus.index().time())).append("]\n");
@@ -196,7 +198,7 @@ public class IndexShardGatewayService extends AbstractIndexShardComponent implem
                         sb.append("             : reusing_files   [").append(recoveryStatus.index().numberOfReusedFiles()).append("] with total_size [").append(new ByteSizeValue(recoveryStatus.index().reusedTotalSize())).append("]\n");
                         sb.append("    start    : took [").append(TimeValue.timeValueMillis(recoveryStatus.start().time())).append("], check_index [").append(timeValueMillis(recoveryStatus.start().checkIndexTime())).append("]\n");
                         sb.append("    translog : number_of_operations [").append(recoveryStatus.translog().currentTranslogOperations()).append("], took [").append(TimeValue.timeValueMillis(recoveryStatus.translog().time())).append("]");
-                        logger.debug(sb.toString());
+                        logger.trace(sb.toString());
                     }
                     listener.onRecoveryDone();
                     scheduleSnapshotIfNeeded();

src/main/java/org/elasticsearch/index/gateway/none/NoneIndexShardGateway.java

@@ -61,7 +61,7 @@ public class NoneIndexShardGateway extends AbstractIndexShardComponent implement
 
     @Override
     public void recover(boolean indexShouldExists, RecoveryStatus recoveryStatus) throws IndexShardGatewayRecoveryException {
-        recoveryStatus().index().startTime(System.currentTimeMillis());
+        recoveryStatus.index().startTime(System.currentTimeMillis());
         // in the none case, we simply start the shard
         // clean the store, there should be nothing there...
         try {

src/main/java/org/elasticsearch/indices/recovery/RecoveryTarget.java

@@ -47,8 +47,11 @@ import org.elasticsearch.indices.IndicesService;
 import org.elasticsearch.threadpool.ThreadPool;
 import org.elasticsearch.transport.*;
 
-import java.util.*;
+import java.util.Collections;
+import java.util.Iterator;
+import java.util.Map;
 import java.util.Map.Entry;
+import java.util.Set;
 
 import static org.elasticsearch.common.unit.TimeValue.timeValueMillis;
 
@@ -217,6 +220,8 @@ public class RecoveryTarget extends AbstractComponent {
             }
             stopWatch.stop();
             if (logger.isDebugEnabled()) {
+                logger.debug("recovery completed from [{}], took [{}]", request.shardId(), request.sourceNode(), stopWatch.totalTime());
+            } else if (logger.isTraceEnabled()) {
                 StringBuilder sb = new StringBuilder();
                 sb.append('[').append(request.shardId().index().name()).append(']').append('[').append(request.shardId().id()).append("] ");
                 sb.append("recovery completed from ").append(request.sourceNode()).append(", took[").append(stopWatch.totalTime()).append("]\n");
@@ -230,7 +235,7 @@ public class RecoveryTarget extends AbstractComponent {
                         .append("\n");
                 sb.append("   phase3: recovered [").append(recoveryResponse.phase3Operations).append("]").append(" transaction log operations")
                         .append(", took [").append(timeValueMillis(recoveryResponse.phase3Time)).append("]");
-                logger.debug(sb.toString());
+                logger.trace(sb.toString());
             }
             removeAndCleanOnGoingRecovery(recoveryStatus);
             listener.onRecoveryDone();