diff --git a/core/src/test/java/org/jclouds/logging/BufferLogger.java b/core/src/test/java/org/jclouds/logging/BufferLogger.java new file mode 100644 index 0000000000..9618c01353 --- /dev/null +++ b/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 messages = Collections.synchronizedList(new ArrayList()); + + 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 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 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)); + } + +} diff --git a/core/src/test/java/org/jclouds/logging/BufferLoggerTest.java b/core/src/test/java/org/jclouds/logging/BufferLoggerTest.java new file mode 100644 index 0000000000..b054c8d07d --- /dev/null +++ b/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"); + } + +} diff --git a/drivers/sshj/src/main/java/org/jclouds/sshj/SshjSshClient.java b/drivers/sshj/src/main/java/org/jclouds/sshj/SshjSshClient.java index c8d642f6ef..97ded631c0 100644 --- a/drivers/sshj/src/main/java/org/jclouds/sshj/SshjSshClient.java +++ b/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)"); } } } diff --git a/drivers/sshj/src/test/java/org/jclouds/sshj/SshjSshClientTest.java b/drivers/sshj/src/test/java/org/jclouds/sshj/SshjSshClientTest.java index e94f0dd201..9b5a130b46 100644 --- a/drivers/sshj/src/test/java/org/jclouds/sshj/SshjSshClientTest.java +++ b/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 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()); + } + }