jtriley/StarCluster — Issue #87: SFTPError: Garbage packet received 
Author: ttrifonov
Created: 2012-03-05 08:53:53+00:00
State: open

---------- CRASH DETAILS ----------
COMMAND: starcluster start mycluster
2012-03-05 08:29:27,881 PID: 31369 config.py:551 - DEBUG - Loading config
2012-03-05 08:29:27,883 PID: 31369 config.py:118 - DEBUG - Loading file: /home/ec2-user/.starcluster/config
2012-03-05 08:29:27,885 PID: 31369 awsutils.py:54 - DEBUG - creating self._conn w/ connection_authenticator kwargs = {'proxy_user': None, 'proxy_pass': None, 'proxy_port': None, 'proxy': None, 'is_secure': True, 'path': '/', 'region': None, 'port': None}
2012-03-05 08:29:27,952 PID: 31369 start.py:176 - INFO - Using default cluster template: smallcluster
2012-03-05 08:29:27,952 PID: 31369 cluster.py:1515 - INFO - Validating cluster template settings...
2012-03-05 08:29:28,167 PID: 31369 cluster.py:909 - DEBUG - Launch map: node001 (ami: ami-1b814f72, type: t1.micro)...
2012-03-05 08:29:28,168 PID: 31369 cluster.py:1530 - INFO - Cluster template settings are valid
2012-03-05 08:29:28,168 PID: 31369 cluster.py:1406 - INFO - Starting cluster...
2012-03-05 08:29:28,168 PID: 31369 cluster.py:935 - INFO - Launching a 2-node cluster...
2012-03-05 08:29:28,168 PID: 31369 cluster.py:909 - DEBUG - Launch map: node001 (ami: ami-1b814f72, type: t1.micro)...
2012-03-05 08:29:28,168 PID: 31369 cluster.py:987 - INFO - Launching master node (ami: ami-1b814f72, type: t1.micro)...
2012-03-05 08:29:28,208 PID: 31369 awsutils.py:165 - INFO - Creating security group @sc-mycluster...
2012-03-05 08:29:29,092 PID: 31369 cluster.py:773 - INFO - Reservation:r-71d3e511
2012-03-05 08:29:29,092 PID: 31369 cluster.py:909 - DEBUG - Launch map: node001 (ami: ami-1b814f72, type: t1.micro)...
2012-03-05 08:29:29,092 PID: 31369 cluster.py:1007 - INFO - Launching node001 (ami: ami-1b814f72, type: t1.micro)
2012-03-05 08:29:29,204 PID: 31369 cluster.py:773 - INFO - SpotInstanceRequest:sir-b3a36014
2012-03-05 08:29:29,204 PID: 31369 cluster.py:1218 - INFO - Waiting for cluster to come up... (updating every 30s)
2012-03-05 08:29:29,280 PID: 31369 cluster.py:1148 - INFO - Waiting for open spot requests to become active...
2012-03-05 08:36:30,672 PID: 31369 cluster.py:665 - DEBUG - existing nodes: {}
2012-03-05 08:36:30,672 PID: 31369 cluster.py:673 - DEBUG - adding node i-99a671fd to self._nodes list
2012-03-05 08:36:30,867 PID: 31369 cluster.py:673 - DEBUG - adding node i-63ac7b07 to self._nodes list
2012-03-05 08:36:31,077 PID: 31369 cluster.py:681 - DEBUG - returning self._nodes = [, ]
2012-03-05 08:36:31,078 PID: 31369 cluster.py:1176 - INFO - Waiting for all nodes to be in a 'running' state...
2012-03-05 08:36:31,160 PID: 31369 cluster.py:665 - DEBUG - existing nodes: {u'i-99a671fd': , u'i-63ac7b07': }
2012-03-05 08:36:31,160 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-99a671fd in self._nodes
2012-03-05 08:36:31,160 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-63ac7b07 in self._nodes
2012-03-05 08:36:31,161 PID: 31369 cluster.py:681 - DEBUG - returning self._nodes = [, ]
2012-03-05 08:37:01,278 PID: 31369 cluster.py:665 - DEBUG - existing nodes: {u'i-99a671fd': , u'i-63ac7b07': }
2012-03-05 08:37:01,278 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-99a671fd in self._nodes
2012-03-05 08:37:01,278 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-63ac7b07 in self._nodes
2012-03-05 08:37:01,278 PID: 31369 cluster.py:681 - DEBUG - returning self._nodes = [, ]
2012-03-05 08:37:01,279 PID: 31369 cluster.py:1194 - INFO - Waiting for SSH to come up on all nodes...
2012-03-05 08:37:01,342 PID: 31369 cluster.py:665 - DEBUG - existing nodes: {u'i-99a671fd': , u'i-63ac7b07': }
2012-03-05 08:37:01,342 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-99a671fd in self._nodes
2012-03-05 08:37:01,343 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-63ac7b07 in self._nodes
2012-03-05 08:37:01,343 PID: 31369 cluster.py:681 - DEBUG - returning self._nodes = [, ]
2012-03-05 08:37:01,407 PID: 31369 ssh.py:75 - DEBUG - loading private key /home/ec2-user/.ssh/mykey
2012-03-05 08:37:01,408 PID: 31369 ssh.py:82 - DEBUG - specified key does not end in either rsa or dsa, trying both
2012-03-05 08:37:01,409 PID: 31369 ssh.py:160 - DEBUG - Using private key /home/ec2-user/.ssh/mykey (rsa)
2012-03-05 08:37:01,409 PID: 31369 ssh.py:97 - DEBUG - connecting to host ec2-50-16-7-177.compute-1.amazonaws.com on port 22 as user root
2012-03-05 08:37:07,975 PID: 31369 ssh.py:75 - DEBUG - loading private key /home/ec2-user/.ssh/mykey
2012-03-05 08:37:07,975 PID: 31369 ssh.py:82 - DEBUG - specified key does not end in either rsa or dsa, trying both
2012-03-05 08:37:07,976 PID: 31369 ssh.py:160 - DEBUG - Using private key /home/ec2-user/.ssh/mykey (rsa)
2012-03-05 08:37:07,977 PID: 31369 ssh.py:97 - DEBUG - connecting to host ec2-50-17-43-252.compute-1.amazonaws.com on port 22 as user root
2012-03-05 08:37:38,228 PID: 31369 cluster.py:665 - DEBUG - existing nodes: {u'i-99a671fd': , u'i-63ac7b07': }
2012-03-05 08:37:38,228 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-99a671fd in self._nodes
2012-03-05 08:37:38,228 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-63ac7b07 in self._nodes
2012-03-05 08:37:38,228 PID: 31369 cluster.py:681 - DEBUG - returning self._nodes = [, ]
2012-03-05 08:37:38,350 PID: 31369 ssh.py:97 - DEBUG - connecting to host ec2-50-17-43-252.compute-1.amazonaws.com on port 22 as user root
2012-03-05 08:37:44,247 PID: 31369 utils.py:89 - INFO - Waiting for cluster to come up took 8.251 mins
2012-03-05 08:37:44,248 PID: 31369 cluster.py:1433 - INFO - The master node is ec2-50-16-7-177.compute-1.amazonaws.com
2012-03-05 08:37:44,248 PID: 31369 cluster.py:1434 - INFO - Setting up the cluster...
2012-03-05 08:37:44,304 PID: 31369 cluster.py:665 - DEBUG - existing nodes: {u'i-99a671fd': , u'i-63ac7b07': }
2012-03-05 08:37:44,304 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-99a671fd in self._nodes
2012-03-05 08:37:44,304 PID: 31369 cluster.py:668 - DEBUG - updating existing node i-63ac7b07 in self._nodes
2012-03-05 08:37:44,305 PID: 31369 cluster.py:681 - DEBUG - returning self._nodes = [, ]
2012-03-05 08:37:44,305 PID: 31369 clustersetup.py:94 - INFO - Configuring hostnames...
2012-03-05 08:37:44,309 PID: 31369 threadpool.py:135 - DEBUG - unfinished_tasks = 2
2012-03-05 08:37:44,309 PID: 31369 ssh.py:179 - DEBUG - creating sftp connection
2012-03-05 08:37:44,310 PID: 31369 ssh.py:179 - DEBUG - creating sftp connection
2012-03-05 08:37:45,310 PID: 31369 threadpool.py:123 - INFO - Shutting down threads...
2012-03-05 08:37:45,311 PID: 31369 threadpool.py:135 - DEBUG - unfinished_tasks = 20
2012-03-05 08:37:46,313 PID: 31369 cli.py:266 - DEBUG - error occurred in job (id=master): Garbage packet received
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/threadpool.py", line 31, in run
job.run()
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/threadpool.py", line 58, in run
r = self.method(*self.args, **self.kwargs)
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/node.py", line 678, in set_hostname
hostname_file = self.ssh.remote_file("/etc/hostname", "w")
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/ssh.py", line 290, in remote_file
rfile = self.sftp.open(file, mode)
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/ssh.py", line 180, in sftp
self._sftp = paramiko.SFTPClient.from_transport(self.transport)
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp_client.py", line 106, in from_transport
return cls(chan)
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp_client.py", line 87, in __init__
server_version = self._send_version()
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp.py", line 108, in _send_version
t, data = self._read_packet()
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp.py", line 179, in _read_packet
raise SFTPError('Garbage packet received')
SFTPError: Garbage packet received

error occurred in job (id=node001): Garbage packet received
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/threadpool.py", line 31, in run
job.run()
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/threadpool.py", line 58, in run
r = self.method(*self.args, **self.kwargs)
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/node.py", line 678, in set_hostname
hostname_file = self.ssh.remote_file("/etc/hostname", "w")
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/ssh.py", line 290, in remote_file
rfile = self.sftp.open(file, mode)
File "/usr/lib/python2.6/site-packages/StarCluster-0.93.1-py2.6.egg/starcluster/ssh.py", line 180, in sftp
self._sftp = paramiko.SFTPClient.from_transport(self.transport)
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp_client.py", line 106, in from_transport
return cls(chan)
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp_client.py", line 87, in __init__
server_version = self._send_version()
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp.py", line 108, in _send_version
t, data = self._read_packet()
File "/usr/lib/python2.6/site-packages/paramiko-1.7.7.1-py2.6.egg/paramiko/sftp.py", line 179, in _read_packet
raise SFTPError('Garbage packet received')
SFTPError: Garbage packet received

---------- SYSTEM INFO ----------
StarCluster: 0.93.1
Python: 2.6.7 (r267:88850, Feb 16 2012, 20:52:24) [GCC 4.4.5 20110214 (Red Hat 4.4.5-6)]
Platform: Linux-2.6.35.14-97.44.amzn1.x86_64-x86_64-with-glibc2.2.5
boto: 2.0
paramiko: 1.7.7.1 (George)
Crypto: 2.5
jinja2: 2.5.5
decorator: 3.3.1