Merge pull request #208 from ahgittin/738-zealous-logging

issue 738 - improved logging for errors on retries

core/src/test/java/org/jclouds/logging/BufferLogger.java

@@ -0,0 +1,154 @@
+package org.jclouds.logging;
+
+import java.util.ArrayList;
+import java.util.Collections;
+import java.util.List;
+import java.util.logging.Level;
+
+import junit.framework.AssertionFailedError;
+
+import org.jclouds.logging.BaseLogger;
+
+import com.google.common.base.Predicate;
+
+/** A logger implementation for use in testing; all log messages are remembered, \
+ * but not written anywhere. The messages can then be inspected {@link #getMessages()}
+ * or certain assertions applied (see assertXxx methods on these instances) */
+public class BufferLogger extends BaseLogger {
+
+   final String category;
+   Level level = Level.INFO;
+   List<Record> messages = Collections.synchronizedList(new ArrayList<Record>());
+
+   public static class Record {
+      Level level;
+      String message;
+      Throwable trace;
+      public Record(Level level, String message, Throwable trace) {
+         this.level = level;
+         this.message = message;
+         this.trace = trace;
+      }
+      public Level getLevel() {
+         return level;
+      }
+      public String getMessage() {
+         return message;
+      }
+      public Throwable getTrace() {
+         return trace;
+      }
+   }
+
+   
+   public BufferLogger(String category) {
+      this.category = category;
+   }
+   
+   public List<Record> getMessages() {
+      return messages;
+   }
+   
+   /** throws AssertionFailedError if the log does not contain the indicated fragment;
+    * otherwise returns a record which does satisfy the constraint 
+    */
+   public Record assertLogContains(String fragment) {
+      for (Record r: messages) {
+         if (r.getMessage()!=null && r.getMessage().contains(fragment)) return r;
+      }
+      throw new AssertionFailedError("log did not contain expected '"+fragment+"'");
+   }
+   /** fails if log _does_ contain the indicated fragment */
+   public void assertLogDoesntContain(String fragment) {
+      for (Record r: messages) {
+         if (r.getMessage()!=null && r.getMessage().contains(fragment)) 
+            throw new AssertionFailedError("log contained unexpected '"+fragment+"'");
+      }
+   }
+
+   /** throws AssertionFailedError if the log does not contain the indicated fragment;
+    * otherwise returns a record which does satisfy the constraint 
+    */
+   public Record assertLogContains(Predicate<Record> test) {
+      for (Record r: messages) {
+         if (r.getMessage()!=null && test.apply(r)) return r;
+      }
+      throw new AssertionFailedError("log did not contain any records satisfying expected predicate");      
+   }
+   
+   @Override
+   public String getCategory() {
+      return category;
+   }
+
+   public void setLevel(Level level) {
+      this.level = level;
+   }
+   public void setAllLevelsEnabled() {
+      level = Level.ALL;
+   }
+   public void setAllLevelsDisabled() {
+      level = Level.OFF;
+   }
+   
+   @Override
+   public boolean isTraceEnabled() {
+      return level.intValue() <= Level.FINER.intValue();
+   }
+   @Override
+   public boolean isDebugEnabled() {
+      return level.intValue() <= Level.FINE.intValue();
+   }
+
+   @Override
+   public boolean isInfoEnabled() {
+      return level.intValue() <= Level.INFO.intValue();
+   }
+
+   @Override
+   public boolean isWarnEnabled() {
+      return level.intValue() <= Level.WARNING.intValue();
+   }
+
+   @Override
+   public boolean isErrorEnabled() {
+      return level.intValue() <= Level.SEVERE.intValue();
+   }
+   
+   
+   @Override
+   protected void logError(String message, Throwable e) {
+      getMessages().add(new Record(Level.SEVERE, message, e));
+   }
+
+   @Override
+   protected void logError(String message) {
+      getMessages().add(new Record(Level.SEVERE, message, null));
+   }
+
+   @Override
+   protected void logWarn(String message, Throwable e) {
+      getMessages().add(new Record(Level.WARNING, message, e));   
+   }
+
+   @Override
+   protected void logWarn(String message) {
+      getMessages().add(new Record(Level.WARNING, message, null));   
+   }
+
+   @Override
+   protected void logInfo(String message) {
+      getMessages().add(new Record(Level.INFO, message, null));   
+   }
+
+   @Override
+   protected void logDebug(String message) {
+      getMessages().add(new Record(Level.FINE, message, null));   
+   }
+
+   @Override
+   protected void logTrace(String message) {
+      getMessages().add(new Record(Level.FINER, message, null));   
+   }
+
+}

core/src/test/java/org/jclouds/logging/BufferLoggerTest.java

@@ -0,0 +1,31 @@
+package org.jclouds.logging;
+
+import java.util.logging.Level;
+
+import org.jclouds.logging.BufferLogger.Record;
+import org.testng.Assert;
+import org.testng.annotations.Test;
+
+@Test
+public class BufferLoggerTest {
+
+   public void testLogCapturesRightMessages() {
+      BufferLogger b = new BufferLogger("foo");
+      b.setLevel(Level.INFO);
+      b.info("hi 1");
+      b.error(new Throwable("check"), "hi 2");
+      b.debug("hi 3 nope");
+      
+      Record r;
+      r = b.assertLogContains("hi 1");
+      Assert.assertEquals(Level.INFO, r.getLevel());
+      Assert.assertNull(r.getTrace());
+      
+      r = b.assertLogContains("hi 2");
+      Assert.assertEquals(Level.SEVERE, r.getLevel());
+      Assert.assertEquals(r.getTrace().getMessage(), "check");
+      
+      b.assertLogDoesntContain("hi 3");
+   }
+   
+}

drivers/sshj/src/main/java/org/jclouds/sshj/SshjSshClient.java

@@ -229,23 +229,16 @@ public class SshjSshClient implements SshClient {
                logger.warn(from, "<< (%s) error closing connection", toString());
             }
             if (i + 1 == sshRetries) {
-               logger.error(from, "<< " + errorMessage + ": out of retries %d", sshRetries);
-               throw propagate(from, errorMessage);
-            } else if (Throwables2.getFirstThrowableOfType(from, IllegalStateException.class) != null) {
-               logger.warn(from, "<< " + errorMessage + ": " + from.getMessage());
-               backoffForAttempt(i + 1, errorMessage + ": " + from.getMessage());
-               if (connection != sshConnection)
-                  connect();
-               continue;
-            } else if (shouldRetry(from)) {
-               logger.warn(from, "<< " + errorMessage + ": " + from.getMessage());
+               throw propagate(from, errorMessage+" (out of retries - max "+sshRetries+")");
+            } else if (shouldRetry(from) ||
+                  (Throwables2.getFirstThrowableOfType(from, IllegalStateException.class) != null)) {
+               logger.info("<< " + errorMessage + " (attempt " + (i + 1) + " of " + sshRetries + "): " + from.getMessage());
                backoffForAttempt(i + 1, errorMessage + ": " + from.getMessage());
                if (connection != sshConnection)
                   connect();
                continue;
             } else {
-               logger.error(from, "<< " + errorMessage + ": exception not retryable");
-               throw propagate(from, errorMessage);
+               throw propagate(from, errorMessage+" (not retryable)");
             }
          }
       }

drivers/sshj/src/test/java/org/jclouds/sshj/SshjSshClientTest.java

@@ -29,6 +29,7 @@ import java.io.IOException;
 import java.net.ConnectException;
 import java.net.SocketTimeoutException;
 import java.util.Properties;
+import java.util.logging.Level;
 
 import net.schmizz.sshj.SSHClient;
 import net.schmizz.sshj.common.SSHException;
@@ -37,11 +38,14 @@ import net.schmizz.sshj.transport.TransportException;
 import net.schmizz.sshj.userauth.UserAuthException;
 
 import org.jclouds.domain.Credentials;
+import org.jclouds.logging.BufferLogger;
+import org.jclouds.logging.BufferLogger.Record;
 import org.jclouds.logging.slf4j.config.SLF4JLoggingModule;
 import org.jclouds.net.IPSocket;
 import org.jclouds.rest.AuthorizationException;
 import org.jclouds.ssh.SshClient;
 import org.jclouds.sshj.config.SshjSshClientModule;
+import org.testng.Assert;
 import org.testng.annotations.BeforeTest;
 import org.testng.annotations.Test;
 
@@ -179,4 +183,33 @@ public class SshjSshClientTest {
       assert !ssh1.shouldRetry(new RuntimeException(nex));
    }
 
+   public void testRetriesLoggedAtInfoWithCount() throws Exception {
+      @SuppressWarnings("unchecked")
+      SshjSshClient.Connection<net.schmizz.sshj.SSHClient> mockConnection = createMock(SshjSshClient.Connection.class);
+      net.schmizz.sshj.SSHClient mockClient = createMock(net.schmizz.sshj.SSHClient.class);
+      
+      mockConnection.clear(); expectLastCall();
+      mockConnection.create(); expectLastCall().andThrow(new ConnectionException("test1"));
+      mockConnection.clear(); expectLastCall();
+      //currently does two clears, one on failure (above) and one on next iteration (below)
+      mockConnection.clear(); expectLastCall();
+      mockConnection.create(); expectLastCall().andReturn(mockClient);
+      replay(mockConnection);
+      replay(mockClient);
+      
+      ssh.sshConnection = mockConnection;
+      BufferLogger logcheck = new BufferLogger(ssh.getClass().getCanonicalName()); 
+      ssh.logger = logcheck;
+      logcheck.setLevel(Level.INFO);
+      
+      ssh.connect();
+      
+      Assert.assertEquals(ssh.ssh, mockClient);
+      verify(mockConnection);
+      verify(mockClient);
+      Record r = logcheck.assertLogContains("attempt 1 of 5");
+      logcheck.assertLogDoesntContain("attempt 2 of 5");
+      Assert.assertEquals(Level.INFO, r.getLevel());
+   }
+
 }