jclouds hang bug

java test

    @Test
    public void createVm() {
        String groupId = "mygroup-"+System.getProperty("user.name")+"-"+UUID.randomUUID().toString();
 
        Properties properties = new Properties();
        properties.setProperty(Constants.PROPERTY_PROVIDER, "aws-ec2");
        properties.setProperty(Constants.PROPERTY_IDENTITY, identity);
        properties.setProperty(Constants.PROPERTY_CREDENTIAL, credential);
        properties.setProperty(Constants.PROPERTY_TRUST_ALL_CERTS, Boolean.toString(true));
        properties.setProperty(Constants.PROPERTY_RELAX_HOSTNAME, Boolean.toString(true));
        
        properties.setProperty(AWSEC2Constants.PROPERTY_EC2_AMI_QUERY, "state=available;image-type=machine");

        Iterable<Module> modules = ImmutableSet.<Module> of(new SshjSshClientModule(), new SLF4JLoggingModule());
        
        ComputeServiceContextFactory computeServiceFactory = new ComputeServiceContextFactory();
        
        final ComputeService computeService = computeServiceFactory
                .createContext("aws-ec2", modules, properties)
                .getComputeService();
        
        NodeMetadata node = null;
        try {
            LOG.info("Creating VM");

            TemplateBuilder templateBuilder = computeService.templateBuilder();
            templateBuilder.locationId("eu-west-1");
            
            Template template = templateBuilder.build();
            Set<? extends NodeMetadata> nodes = computeService.createNodesInGroup(groupId, 1, template);
            node = Iterables.getOnlyElement(nodes, null);
            if (node == null) throw new IllegalStateException("No nodes returned");

            Credentials nodeCredentials = node.getCredentials();
            final LoginCredentials expectedCredentials = LoginCredentials.fromCredentials(nodeCredentials);
            
            LOG.info("Started VM, waiting for it to be sshable");
            boolean reachable = false;
            for (int i=0; i<120; i++) {
                try {
                    Statement statement = Statements.newStatementList(Statements.exec("date"));
                    ExecResponse response = computeService.runScriptOnNode(node.getId(), statement,
                            RunScriptOptions.Builder.overrideLoginCredentials(expectedCredentials));
                    if (response.getExitStatus() == 0) {
                        LOG.info("ssh 'date' succeeded");
                        reachable = true;
                        break;
                    }
                    LOG.info("ssh 'date' failed, exit "+response.getExitStatus()+", but still in retry loop");
                } catch (Exception e) {
                    if (i<120)
                        LOG.info("ssh 'date' failed, but still in retry loop: "+e);
                    else {
                        LOG.error("ssh 'date' failed after timeout: "+e, e);
                        Throwables.propagate(e);
                    }
                }
                Thread.sleep(1000);
            }
        
            if (!reachable) {
                throw new IllegalStateException("SSH failed, never reachable");
            }

        } catch (RunNodesException e) {
            if (e.getNodeErrors().size() > 0) {
                node = Iterables.get(e.getNodeErrors().keySet(), 0);
            }
            LOG.error("Failed to start VM: "+e, e);
            throw Throwables.propagate(e);
        } catch (Exception e) {
            LOG.error("Failed to start VM: "+e, e);
            throw Throwables.propagate(e);
        } finally {
            LOG.info("Now destroying VM: "+node);
            computeService.destroyNode( node.getId() );

            computeService.getContext().close();
        }
        
    }

jstack

"main" prio=5 tid=101803000 nid=0x100401000 runnable [1003fe000]
   java.lang.Thread.State: RUNNABLE
	at net.schmizz.sshj.common.Buffer.getNextPowerOf2(Buffer.java:80)
	at net.schmizz.sshj.common.Buffer.ensureCapacity(Buffer.java:152)
	at net.schmizz.sshj.sftp.PacketReader.readPacket(PacketReader.java:72)
	at net.schmizz.sshj.sftp.SFTPEngine.init(SFTPEngine.java:71)
	at net.schmizz.sshj.SSHClient.newSFTPClient(SSHClient.java:623)
	at org.jclouds.sshj.SshjSshClient$2.create(SshjSshClient.java:280)
	at org.jclouds.sshj.SshjSshClient$2.create(SshjSshClient.java:263)
	at org.jclouds.sshj.SshjSshClient.acquire(SshjSshClient.java:228)
	at org.jclouds.sshj.SshjSshClient$PutConnection.create(SshjSshClient.java:343)
	at org.jclouds.sshj.SshjSshClient$PutConnection.create(SshjSshClient.java:321)
	at org.jclouds.sshj.SshjSshClient.acquire(SshjSshClient.java:228)
	at org.jclouds.sshj.SshjSshClient.put(SshjSshClient.java:377)
	at org.jclouds.sshj.SshjSshClient.put(SshjSshClient.java:166)
	at org.jclouds.compute.callables.RunScriptOnNodeAsInitScriptUsingSsh.doCall(RunScriptOnNodeAsInitScriptUsingSsh.java:110)
	at org.jclouds.compute.callables.RunScriptOnNodeAsInitScriptUsingSshAndBlockUntilComplete.future(RunScriptOnNodeAsInitScriptUsingSshAndBlockUntilComplete.java:70)
	at org.jclouds.compute.callables.RunScriptOnNodeAsInitScriptUsingSshAndBlockUntilComplete.doCall(RunScriptOnNodeAsInitScriptUsingSshAndBlockUntilComplete.java:62)
	at org.jclouds.compute.callables.RunScriptOnNodeAsInitScriptUsingSsh.call(RunScriptOnNodeAsInitScriptUsingSsh.java:79)
	at org.jclouds.compute.internal.BaseComputeService.runScriptOnNode(BaseComputeService.java:571)
	at brooklyn.location.basic.jclouds.StandaloneJcloudsTest.createVm(StandaloneJcloudsTest.java:147)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
	at org.testng.internal.Invoker.invokeMethod(Invoker.java:691)
	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:883)
	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1208)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
	at org.testng.TestRunner.privateRun(TestRunner.java:753)
	at org.testng.TestRunner.run(TestRunner.java:613)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:335)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:330)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:292)
	at org.testng.SuiteRunner.run(SuiteRunner.java:241)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1169)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1094)
	at org.testng.TestNG.run(TestNG.java:1006)
	at org.testng.remote.RemoteTestNG.run(RemoteTestNG.java:107)
	at org.testng.remote.RemoteTestNG.initAndRun(RemoteTestNG.java:199)
	at org.testng.remote.RemoteTestNG.main(RemoteTestNG.java:170)

log

2012-04-25 12:49:32,489 INFO  Creating VM
2012-04-25 12:52:21,952 INFO  Started VM in ${allconf.providerLocationId ?: allconf.provider}; waiting for it to be sshable by ${allconf.userName}@${vmIp}
2012-04-25 12:52:23,402 INFO  Trying to register BouncyCastle as a JCE provider
2012-04-25 12:52:24,204 INFO  Registration succeeded
2012-04-25 12:52:24,455 INFO  Client identity string: SSH-2.0-SSHJ_0_7
2012-04-25 12:52:24,650 INFO  Server identity string: SSH-2.0-OpenSSH_5.5p1 Debian-4ubuntu5
2012-04-25 12:52:24,653 INFO  Sending SSH_MSG_KEXINIT
2012-04-25 12:52:24,766 INFO  Received SSH_MSG_KEXINIT
2012-04-25 12:52:24,868 INFO  Sending SSH_MSG_KEXDH_INIT
2012-04-25 12:52:24,942 INFO  Received kex followup data
2012-04-25 12:52:24,942 INFO  Received SSH_MSG_KEXDH_REPLY
2012-04-25 12:52:25,025 INFO  Sending SSH_MSG_NEWKEYS
2012-04-25 12:52:25,026 INFO  Received SSH_MSG_NEWKEYS
2012-04-25 12:52:25,031 INFO  Key exchange took 0.378 seconds
2012-04-25 12:52:25,192 INFO  Setting active service to ssh-userauth
2012-04-25 12:52:25,193 INFO  Trying `publickey` auth...
2012-04-25 12:52:25,661 INFO  `publickey` auth successful
2012-04-25 12:52:25,661 INFO  Setting active service to ssh-connection
2012-04-25 12:52:25,690 INFO  Attaching `session` channel (#0)
2012-04-25 12:52:26,637 INFO  Received SSH_MSG_DEBUG (display=false) 'Forced command: echo 'Please login as the ubuntu user rather than root user.';echo;sleep 10'
2012-04-25 12:52:26,705 INFO  Received SSH_MSG_DEBUG (display=false) 'Forced command: echo 'Please login as the ubuntu user rather than root user.';echo;sleep 10'
2012-04-25 12:52:26,711 INFO  Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=0] >
2012-04-25 12:52:26,711 INFO  Will request `sftp` subsystem
2012-04-25 12:52:26,712 INFO  Sending channel request for `subsystem`
2012-04-25 12:52:26,773 INFO  Received window adjustment for 2097152 bytes
2012-04-25 12:52:36,869 INFO  Got chan request for `exit-status`
2012-04-25 12:52:36,880 INFO  Got EOF
2012-04-25 12:52:36,880 INFO  Got close
2012-04-25 12:52:36,883 INFO  Sending EOF
2012-04-25 12:52:36,883 INFO  Sending close
2012-04-25 12:52:36,883 INFO  Forgetting `session` channel (#0)
2012-04-25 12:53:36,882 ERROR Dying because - java.net.SocketTimeoutException: Read timed out
2012-04-25 12:53:36,885 INFO  Setting active service to null-service