added additional logging; minor change in test store classes

src/java/voldemort/routing/ConsistentRoutingStrategy.java

@@ -113,12 +113,12 @@ public List<Node> routeRequest(byte[] key) {
             preferenceList.add(partitionToNode[partition]);
         }
         if(logger.isDebugEnabled()) {
-            StringBuilder nodeList = new StringBuilder();
+            List<Integer> nodeIdList = new ArrayList<Integer>();
             for(int partition: partitionList) {
-                nodeList.append(partitionToNode[partition].getId() + ",");
+                nodeIdList.add(partitionToNode[partition].getId());
             }
-            logger.debug("Key " + ByteUtils.toHexString(key) + " mapped to Nodes [" + nodeList
-                         + "] Partitions [" + partitionList + "]");
+            logger.debug("Key " + ByteUtils.toHexString(key) + " mapped to Nodes " + nodeIdList
+                         + " Partitions " + partitionList);
         }
         return preferenceList;
     }

src/java/voldemort/store/routed/action/AbstractAction.java

@@ -74,6 +74,9 @@ protected boolean handleResponseError(Exception e,
         }
 
         if(e instanceof UnreachableStoreException) {
+            if(logger.isTraceEnabled()) {
+                logger.trace("Adding node [" + node + "] to failed nodes list");
+            }
             pipelineData.addFailedNode(node);
             pipelineData.recordFailure(e);
             failureDetector.recordException(node, requestTime, (UnreachableStoreException) e);

src/java/voldemort/store/routed/action/PerformParallelRequests.java

@@ -90,7 +90,7 @@ public void execute(final Pipeline pipeline) {
 
         if(logger.isTraceEnabled())
             logger.trace("Attempting " + attempts + " " + pipeline.getOperation().getSimpleName()
-                         + " operations in parallel");
+                         + " operations in parallel for key " + key);
 
         for(int i = 0; i < attempts; i++) {
             final Node node = nodes.get(i);
@@ -104,7 +104,7 @@ public void requestComplete(Object result, long requestTime) {
                     if(logger.isTraceEnabled())
                         logger.trace(pipeline.getOperation().getSimpleName()
                                      + " response received (" + requestTime + " ms.) from node "
-                                     + node.getId());
+                                     + node.getId() + "for key " + key);
 
                     Response<ByteArray, Object> response = new Response<ByteArray, Object>(node,
                                                                                            key,
@@ -129,7 +129,7 @@ public void requestComplete(Object result, long requestTime) {
                             logger.warn("Received invalid metadata problem after a successful "
                                         + pipeline.getOperation().getSimpleName()
                                         + " call on node " + node.getId() + ", store '"
-                                        + pipelineData.getStoreName() + "'");
+                                        + pipelineData.getStoreName() + "' for key " + key);
                         } else {
                             handleResponseError(response, pipeline, failureDetector);
                         }
@@ -140,7 +140,7 @@ public void requestComplete(Object result, long requestTime) {
 
             if(logger.isTraceEnabled())
                 logger.trace("Submitting " + pipeline.getOperation().getSimpleName()
-                             + " request on node " + node.getId());
+                             + " request on node " + node.getId() + " for key " + key);
 
             NonblockingStore store = nonblockingStores.get(node.getId());
 
@@ -212,7 +212,8 @@ else if(pipeline.getOperation() == Operation.GET_VERSIONS)
                         logger.debug("Operation " + pipeline.getOperation().getSimpleName()
                                      + "failed due to insufficent zone responses, required "
                                      + pipelineData.getZonesRequired() + " obtained "
-                                     + zonesSatisfied + " " + pipelineData.getZoneResponses());
+                                     + zonesSatisfied + " " + pipelineData.getZoneResponses()
+                                     + " for key " + key);
                     }
                     if(this.insufficientZonesEvent != null) {
                         pipeline.addEvent(this.insufficientZonesEvent);

src/java/voldemort/store/routed/action/PerformSerialPutRequests.java

@@ -114,6 +114,7 @@ public void execute(Pipeline pipeline) {
                 pipelineData.setMaster(node);
                 pipelineData.setVersionedCopy(versionedCopy);
                 pipelineData.getZoneResponses().add(node.getZoneId());
+                currentNode++;
                 break;
             } catch(Exception e) {
                 long requestTime = (System.nanoTime() - start) / Time.NS_PER_MS;
@@ -129,6 +130,11 @@ public void execute(Pipeline pipeline) {
             }
         }
 
+        if(logger.isTraceEnabled()) {
+            logger.trace("PUT {key:" + key + "} currentNode=" + currentNode + " nodes.size()="
+                         + nodes.size());
+        }
+
         if(pipelineData.getSuccesses() < 1) {
             List<Exception> failures = pipelineData.getFailures();
             pipelineData.setFatalError(new InsufficientOperationalNodesException("No master node succeeded!",
@@ -138,8 +144,6 @@ public void execute(Pipeline pipeline) {
             return;
         }
 
-        currentNode++;
-
         // There aren't any more requests to make...
         if(currentNode == nodes.size()) {
             if(pipelineData.getSuccesses() < required) {

src/java/voldemort/store/slop/HintedHandoff.java

@@ -121,6 +121,7 @@ public void sendHintParallel(final Node failedNode, final Version version, final
                 NonblockingStoreCallback callback = new NonblockingStoreCallback() {
 
                     public void requestComplete(Object result, long requestTime) {
+                        logger.debug("Got response for async hint request");
                         Response<ByteArray, Object> response = new Response<ByteArray, Object>(node,
                                                                                                slopKey,
                                                                                                result,
@@ -189,7 +190,7 @@ public boolean sendHintSerial(Node failedNode, Version version, Slop slop) {
         for(Node node: handoffStrategy.routeHint(failedNode)) {
             int nodeId = node.getId();
             if(logger.isDebugEnabled())
-                logger.debug("Trying to send hint to " + nodeId);
+                logger.debug("Trying to send hint to " + nodeId + " for key " + slop.getKey());
 
             if(!failedNodes.contains(node) && failureDetector.isAvailable(node)) {
                 Store<ByteArray, Slop, byte[]> slopStore = slopStores.get(nodeId);
@@ -223,8 +224,8 @@ public boolean sendHintSerial(Node failedNode, Version version, Slop slop) {
                 if(logger.isDebugEnabled())
                     logger.debug("Slop write of key " + slop.getKey() + " (keyRef: "
                                  + System.identityHashCode(slop.getKey()) + ") for " + failedNode
-                                 + " to node " + node + " succeeded in "
-                                 + (System.nanoTime() - startNs) + " ns");
+                                 + " to node " + node + (persisted ? " succeeded" : " failed")
+                                 + " in " + (System.nanoTime() - startNs) + " ns");
             }
         }
 

src/java/voldemort/store/slop/Slop.java

@@ -148,7 +148,8 @@ public int hashCode() {
     @Override
     public String toString() {
         return "Slop(storeName = " + storeName + ", operation = " + operation + ", key = " + key
-               + ", value = " + Arrays.toString(value) + ", nodeId = " + nodeId + ", arrived = " + arrived + ")";
+               + ", value = " + ByteUtils.toHexString(value) + ", nodeId = " + nodeId
+               + ", arrived = " + arrived + ")";
     }
 
 }

test/common/voldemort/store/ForceFailStore.java

@@ -19,12 +19,15 @@
 import java.util.List;
 import java.util.Map;
 
+import org.apache.log4j.Logger;
+
 import voldemort.VoldemortException;
 import voldemort.versioning.Version;
 import voldemort.versioning.Versioned;
 
 public class ForceFailStore<K, V, T> extends DelegatingStore<K, V, T> {
 
+    private final static Logger logger = Logger.getLogger(ForceFailStore.class);
     private final VoldemortException e;
 
     private volatile boolean fail = false;
@@ -40,33 +43,49 @@ public void setFail(boolean fail) {
 
     @Override
     public void put(K key, Versioned<V> value, T transform) throws VoldemortException {
-        if(fail)
+        if(fail) {
+            if(logger.isDebugEnabled()) {
+                logger.debug("PUT key " + key + " was forced to fail");
+            }
             throw e;
+        }
 
         getInnerStore().put(key, value, transform);
     }
 
     @Override
     public boolean delete(K key, Version version) throws VoldemortException {
-        if(fail)
+        if(fail) {
+            if(logger.isDebugEnabled()) {
+                logger.debug("DELETE key " + key + " was forced to fail");
+            }
             throw e;
+        }
 
         return getInnerStore().delete(key, version);
     }
 
     @Override
     public Map<K, List<Versioned<V>>> getAll(Iterable<K> keys, Map<K, T> transforms)
             throws VoldemortException {
-        if(fail)
+        if(fail) {
+            if(logger.isDebugEnabled()) {
+                logger.debug("GETALL was forced to fail");
+            }
             throw e;
+        }
 
         return getInnerStore().getAll(keys, transforms);
     }
 
     @Override
     public List<Versioned<V>> get(K key, T transform) throws VoldemortException {
-        if(fail)
+        if(fail) {
+            if(logger.isDebugEnabled()) {
+                logger.debug("GET key " + key + " was forced to fail");
+            }
             throw e;
+        }
 
         return getInnerStore().get(key, transform);
     }

test/common/voldemort/store/SleepyStore.java

@@ -25,13 +25,17 @@
 
 public class SleepyStore<K, V, T> extends DelegatingStore<K, V, T> {
 
-    private final long sleepTimeMs;
+    private long sleepTimeMs;
 
     public SleepyStore(long sleepTimeMs, Store<K, V, T> innerStore) {
         super(innerStore);
         this.sleepTimeMs = sleepTimeMs;
     }
 
+    public void setSleepTimeMs(long sleepTimeMs) {
+        this.sleepTimeMs = sleepTimeMs;
+    }
+
     @Override
     public boolean delete(K key, Version version) throws VoldemortException {
         try {