---------- SYSTEM INFO ---------- StarCluster: 0.95.4 Python: 2.7.6 |Anaconda 1.9.2 (x86_64)| (default, Jan 10 2014, 11:23:15) [GCC 4.0.1 (Apple Inc. build 5493)] Platform: Darwin-13.1.0-x86_64-i386-64bit boto: 2.27.0 paramiko: 1.13.0 Crypto: 2.6.1 ---------- CRASH DETAILS ---------- Command: starcluster start -c slow -s 1 TEST 2014-04-23 13:47:38,382 PID: 460 config.py:567 - DEBUG - Loading config 2014-04-23 13:47:38,382 PID: 460 config.py:138 - DEBUG - Loading file: /Users/badr/.starcluster/config 2014-04-23 13:47:38,388 PID: 460 awsutils.py:75 - 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, 'validate_certs': True, 'port': None} 2014-04-23 13:47:38,723 PID: 460 update_pip_pkgs.py:7 - DEBUG - pkg_to_install = tornado 2014-04-23 13:47:38,724 PID: 460 update_pip_pkgs.py:7 - DEBUG - pkg_to_install = ipython 2014-04-23 13:47:38,724 PID: 460 add_pkgs.py:7 - DEBUG - pkg_to_install = python-h5py 2014-04-23 13:47:38,725 PID: 460 cluster.py:1801 - INFO - Validating cluster template settings... 2014-04-23 13:47:39,228 PID: 460 sshutils.py:859 - DEBUG - rsa private key fingerprint (/Users/badr/.ssh/EC2key.rsa): d8:90:aa:a2:11:f8:90:83:98:db:31:8f:68:e5:5e:d9:34:7f:8a:36 2014-04-23 13:47:39,319 PID: 460 cluster.py:759 - DEBUG - existing nodes: {} 2014-04-23 13:47:39,320 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:47:39,619 PID: 460 cluster.py:911 - DEBUG - Userdata size in KB: 0.67 2014-04-23 13:47:39,619 PID: 460 cluster.py:1819 - INFO - Cluster template settings are valid 2014-04-23 13:47:39,619 PID: 460 cluster.py:1639 - INFO - Starting cluster... 2014-04-23 13:47:39,619 PID: 460 cluster.py:1157 - INFO - Launching a 1-node cluster... 2014-04-23 13:47:39,620 PID: 460 cluster.py:1182 - DEBUG - Launching master (ami: ami-765b3e1f, type: t1.micro) 2014-04-23 13:47:39,727 PID: 460 awsutils.py:295 - INFO - Creating security group @sc-TEST... 2014-04-23 13:47:41,644 PID: 460 cluster.py:911 - DEBUG - Userdata size in KB: 0.67 2014-04-23 13:47:41,747 PID: 460 cluster.py:759 - DEBUG - existing nodes: {} 2014-04-23 13:47:41,747 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:47:41,858 PID: 460 awsutils.py:495 - DEBUG - Forcing delete_on_termination for AMI: ami-765b3e1f 2014-04-23 13:47:42,422 PID: 460 cluster.py:968 - INFO - Reservation:r-360ec316 2014-04-23 13:47:42,423 PID: 460 awsutils.py:553 - INFO - Waiting for instances to propagate... 2014-04-23 13:47:42,715 PID: 460 cluster.py:1440 - INFO - Waiting for cluster to come up... (updating every 30s) 2014-04-23 13:47:42,869 PID: 460 cluster.py:1397 - INFO - Waiting for all nodes to be in a 'running' state... 2014-04-23 13:47:42,953 PID: 460 cluster.py:759 - DEBUG - existing nodes: {} 2014-04-23 13:47:42,954 PID: 460 cluster.py:767 - DEBUG - adding node i-bfbfadef to self._nodes list 2014-04-23 13:47:43,473 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:48:13,791 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:48:13,791 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:48:13,791 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:48:13,792 PID: 460 cluster.py:1425 - INFO - Waiting for SSH to come up on all nodes... 2014-04-23 13:48:13,908 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:48:13,908 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:48:13,908 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:48:13,915 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:14,016 PID: 460 sshutils.py:87 - DEBUG - loading private key /Users/badr/.ssh/EC2key.rsa 2014-04-23 13:48:14,017 PID: 460 sshutils.py:185 - DEBUG - Using private key /Users/badr/.ssh/EC2key.rsa (RSA) 2014-04-23 13:48:14,017 PID: 460 sshutils.py:112 - DEBUG - connecting to host ec2-54-198-102-63.compute-1.amazonaws.com on port 22 as user root 2014-04-23 13:48:14,917 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:15,918 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:16,920 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:17,922 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:18,923 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:19,924 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:20,926 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:21,928 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:22,928 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:23,929 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:24,931 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:25,933 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:26,934 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:27,936 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:28,937 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:29,939 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:30,941 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:31,942 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:32,943 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:33,945 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:34,947 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:35,948 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:36,950 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:37,952 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:38,954 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:39,956 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:40,958 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:41,959 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:42,961 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:43,964 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:44,965 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:45,966 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:46,966 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:47,967 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:48,969 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:49,971 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:50,972 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:51,973 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:52,975 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:53,977 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:54,979 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:55,981 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:56,982 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:57,985 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:58,987 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:48:59,989 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:00,990 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:01,992 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:02,993 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:03,994 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:04,546 PID: 460 sshutils.py:112 - DEBUG - connecting to host ec2-54-198-102-63.compute-1.amazonaws.com on port 22 as user root 2014-04-23 13:49:04,996 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:05,110 PID: 460 sshutils.py:204 - DEBUG - creating sftp connection 2014-04-23 13:49:05,998 PID: 460 utils.py:118 - INFO - Waiting for cluster to come up took 1.388 mins 2014-04-23 13:49:05,999 PID: 460 cluster.py:1666 - INFO - The master node is ec2-54-198-102-63.compute-1.amazonaws.com 2014-04-23 13:49:05,999 PID: 460 cluster.py:1667 - INFO - Configuring cluster... 2014-04-23 13:49:06,350 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:49:06,350 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:49:06,350 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:49:06,350 PID: 460 cluster.py:1712 - INFO - Running plugin starcluster.clustersetup.DefaultClusterSetup 2014-04-23 13:49:06,350 PID: 460 clustersetup.py:121 - INFO - Configuring hostnames... 2014-04-23 13:49:06,354 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:06,916 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && hostname -F /etc/hostname 2014-04-23 13:49:07,107 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && hostname -F /etc/hostname': 2014-04-23 13:49:07,574 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && fdisk -l 2>/dev/null 2014-04-23 13:49:07,777 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && fdisk -l 2>/dev/null': Disk /dev/xvda1: 10.7 GB, 10737418240 bytes 255 heads, 63 sectors/track, 1305 cylinders, total 20971520 sectors Units = sectors of 1 * 512 = 512 bytes Sector size (logical/physical): 512 bytes / 512 bytes I/O size (minimum/optimal): 512 bytes / 512 bytes Disk identifier: 0x00000000 2014-04-23 13:49:08,045 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && cat /proc/partitions 2014-04-23 13:49:08,349 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && cat /proc/partitions': major minor #blocks name 202 1 10485760 xvda1 2014-04-23 13:49:08,813 PID: 460 clustersetup.py:192 - INFO - Creating cluster user: sgeadmin (uid: 1001, gid: 1001) 2014-04-23 13:49:08,814 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:08,963 PID: 460 clustersetup.py:209 - DEBUG - user sgeadmin does not exist, creating... 2014-04-23 13:49:08,998 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && groupadd -o -g 1001 sgeadmin 2014-04-23 13:49:09,187 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && groupadd -o -g 1001 sgeadmin': 2014-04-23 13:49:09,288 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && useradd -o -u 1001 -g 1001 -s `which bash` -m sgeadmin 2014-04-23 13:49:09,491 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && useradd -o -u 1001 -g 1001 -s `which bash` -m sgeadmin': 2014-04-23 13:49:09,815 PID: 460 clustersetup.py:238 - INFO - Configuring scratch space for user(s): sgeadmin 2014-04-23 13:49:09,816 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:09,956 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && chown -R sgeadmin:sgeadmin /mnt/sgeadmin 2014-04-23 13:49:10,001 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && chown -R sgeadmin:sgeadmin /mnt/sgeadmin': 2014-04-23 13:49:10,178 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && ln -s /mnt/sgeadmin /scratch 2014-04-23 13:49:10,225 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && ln -s /mnt/sgeadmin /scratch': 2014-04-23 13:49:10,818 PID: 460 clustersetup.py:247 - INFO - Configuring /etc/hosts on each node 2014-04-23 13:49:10,818 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:49:10,987 PID: 460 sshutils.py:307 - DEBUG - new /etc/hosts after removing regex (master) matches: 127.0.0.1 localhost # The following lines are desirable for IPv6 capable hosts ::1 ip6-localhost ip6-loopback fe00::0 ip6-localnet ff00::0 ip6-mcastprefix ff02::1 ip6-allnodes ff02::2 ip6-allrouters ff02::3 ip6-allhosts 2014-04-23 13:49:11,819 PID: 460 node.py:703 - INFO - Starting NFS server on master 2014-04-23 13:49:11,852 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && /etc/init.d/portmap start 2014-04-23 13:49:12,280 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && /etc/init.d/portmap start': Rather than invoking init scripts through /etc/init.d, use the service(8) utility, e.g. service portmap start Since the script you are attempting to invoke has been converted to an Upstart job, you may also use the start(8) utility, e.g. start portmap 2014-04-23 13:49:12,383 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && mount -t rpc_pipefs sunrpc /var/lib/nfs/rpc_pipefs/ 2014-04-23 13:49:12,712 PID: 460 sshutils.py:582 - DEBUG - (ignored) remote command 'source /etc/profile && mount -t rpc_pipefs sunrpc /var/lib/nfs/rpc_pipefs/' failed with status 32: mount: mount point /var/lib/nfs/rpc_pipefs/ does not exist 2014-04-23 13:49:12,815 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && mkdir -p /etc/exports.d 2014-04-23 13:49:12,868 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && mkdir -p /etc/exports.d': 2014-04-23 13:49:12,971 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && mkdir -p /dummy_export_for_broken_init_script 2014-04-23 13:49:13,015 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && mkdir -p /dummy_export_for_broken_init_script': 2014-04-23 13:49:13,207 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && /etc/init.d/nfs start 2014-04-23 13:49:13,340 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && /etc/init.d/nfs start': * Exporting directories for NFS kernel daemon... ...done. * Starting NFS kernel daemon ...done. 2014-04-23 13:49:13,610 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && rm -f /etc/exports.d/dummy.exports 2014-04-23 13:49:13,652 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && rm -f /etc/exports.d/dummy.exports': 2014-04-23 13:49:13,755 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && rm -rf /dummy_export_for_broken_init_script 2014-04-23 13:49:13,802 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && rm -rf /dummy_export_for_broken_init_script': 2014-04-23 13:49:13,939 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && exportfs -fra 2014-04-23 13:49:13,994 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && exportfs -fra': 2014-04-23 13:49:13,994 PID: 460 utils.py:118 - INFO - Setting up NFS took 0.036 mins 2014-04-23 13:49:13,995 PID: 460 clustersetup.py:259 - INFO - Configuring passwordless ssh for root 2014-04-23 13:49:17,859 PID: 460 node.py:538 - DEBUG - adding auth_key_contents 2014-04-23 13:49:19,554 PID: 460 clustersetup.py:267 - INFO - Configuring passwordless ssh for sgeadmin 2014-04-23 13:49:21,752 PID: 460 node.py:538 - DEBUG - adding auth_key_contents 2014-04-23 13:49:21,781 PID: 460 node.py:546 - DEBUG - adding conn_pubkey_contents 2014-04-23 13:49:22,885 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:49:22,886 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:49:22,886 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:49:22,886 PID: 460 cluster.py:1712 - INFO - Running plugin starcluster.plugins.sge.SGEPlugin 2014-04-23 13:49:22,915 PID: 460 sge.py:175 - INFO - Configuring SGE... 2014-04-23 13:49:22,974 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && cp -r /opt/sge6-fresh /opt/sge6 2014-04-23 13:50:03,791 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && cp -r /opt/sge6-fresh /opt/sge6': 2014-04-23 13:50:03,827 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && chown -R sgeadmin:sgeadmin /opt/sge6 2014-04-23 13:50:03,931 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && chown -R sgeadmin:sgeadmin /opt/sge6': 2014-04-23 13:50:04,033 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && cd /opt/sge6 && sed 's/AddQueue/#AddQueue/g' inst_sge > inst_sge_sc 2014-04-23 13:50:04,084 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && cd /opt/sge6 && sed 's/AddQueue/#AddQueue/g' inst_sge > inst_sge_sc': 2014-04-23 13:50:04,218 PID: 460 utils.py:118 - INFO - Setting up NFS took 0.000 mins 2014-04-23 13:50:04,322 PID: 460 sge.py:151 - INFO - Installing Sun Grid Engine... 2014-04-23 13:50:04,385 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && /opt/sge6/util/arch 2014-04-23 13:50:04,444 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && /opt/sge6/util/arch': linux-x64 2014-04-23 13:50:04,634 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && cd /opt/sge6 && TERM=rxvt ./inst_sge_sc -m -x -noremote -auto ./ec2_sge.conf 2014-04-23 13:50:13,531 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && cd /opt/sge6 && TERM=rxvt ./inst_sge_sc -m -x -noremote -auto ./ec2_sge.conf': Reading configuration from file ./ec2_sge.conf [H[2JInstall log can be found in: /opt/sge6/default/common/install_logs/qmaster_install_master_2014-04-23_17:50:05.log Install log can be found in: /opt/sge6/default/common/install_logs/execd_install_master_2014-04-23_17:50:10.log 2014-04-23 13:50:13,566 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && cat /proc/cpuinfo | grep processor | wc -l 2014-04-23 13:50:13,662 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && cat /proc/cpuinfo | grep processor | wc -l': 1 2014-04-23 13:50:13,832 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && qconf -aattr hostgroup hostlist master @allhosts 2014-04-23 13:50:13,889 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && qconf -aattr hostgroup hostlist master @allhosts': root@master modified "@allhosts" in host group list 2014-04-23 13:50:14,127 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && qconf -aattr queue slots "[master=1]" all.q 2014-04-23 13:50:14,261 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && qconf -aattr queue slots "[master=1]" all.q': root@master modified "all.q" in cluster queue list 2014-04-23 13:50:14,297 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && qconf -mattr queue shell "/bin/bash" all.q 2014-04-23 13:50:14,422 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && qconf -mattr queue shell "/bin/bash" all.q': root@master modified "all.q" in cluster queue list 2014-04-23 13:50:14,577 PID: 460 sge.py:70 - INFO - Creating SGE parallel environment 'orte' 2014-04-23 13:50:14,578 PID: 460 threadpool.py:168 - DEBUG - unfinished_tasks = 1 2014-04-23 13:50:16,024 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && qconf -Ap /tmp/pe.txt 2014-04-23 13:50:16,079 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && qconf -Ap /tmp/pe.txt': root@master added "orte" to parallel environment list 2014-04-23 13:50:16,080 PID: 460 sge.py:87 - INFO - Adding parallel environment 'orte' to queue 'all.q' 2014-04-23 13:50:16,182 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && qconf -mattr queue pe_list "orte" all.q 2014-04-23 13:50:16,261 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && qconf -mattr queue pe_list "orte" all.q': Unable to find "orte" in "pe_list" of "all.q" - Adding new element. root@master modified "all.q" in cluster queue list 2014-04-23 13:50:16,363 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:50:16,364 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:50:16,364 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:50:16,364 PID: 460 cluster.py:1712 - INFO - Running plugin update_tornado 2014-04-23 13:50:16,364 PID: 460 update_pip_pkgs.py:10 - INFO - Updating tornado on master 2014-04-23 13:50:16,432 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && pip install --upgrade tornado 2014-04-23 13:50:33,423 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && pip install --upgrade tornado': Downloading/unpacking tornado Running setup.py egg_info for package tornado Downloading/unpacking backports.ssl-match-hostname (from tornado) Downloading backports.ssl_match_hostname-3.4.0.2.tar.gz Running setup.py egg_info for package backports.ssl-match-hostname Installing collected packages: tornado, backports.ssl-match-hostname Found existing installation: tornado 2.4.1 Uninstalling tornado: Successfully uninstalled tornado Running setup.py install for tornado building 'tornado.speedups' extension gcc -pthread -fno-strict-aliasing -DNDEBUG -g -fwrapv -O2 -Wall -Wstrict-prototypes -fPIC -I/usr/include/python2.7 -c tornado/speedups.c -o build/temp.linux-x86_64-2.7/tornado/speedups.o tornado/speedups.c:46:1: warning: function declaration isn’t a prototype [-Wstrict-prototypes] gcc -pthread -shared -Wl,-O1 -Wl,-Bsymbolic-functions -Wl,-Bsymbolic-functions -Wl,-z,relro build/temp.linux-x86_64-2.7/tornado/speedups.o -o build/lib.linux-x86_64-2.7/tornado/speedups.so Running setup.py install for backports.ssl-match-hostname Successfully installed tornado backports.ssl-match-hostname Cleaning up... 2014-04-23 13:50:33,527 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:50:33,527 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:50:33,527 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:50:33,527 PID: 460 cluster.py:1712 - INFO - Running plugin update_ipython 2014-04-23 13:50:33,528 PID: 460 update_pip_pkgs.py:10 - INFO - Updating ipython on master 2014-04-23 13:50:33,562 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && pip install --upgrade ipython 2014-04-23 13:50:51,357 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && pip install --upgrade ipython': Downloading/unpacking ipython Running setup.py egg_info for package ipython Installing collected packages: ipython Found existing installation: ipython 0.13.1 Uninstalling ipython: Successfully uninstalled ipython Running setup.py install for ipython checking package data Installing ipengine2 script to /usr/local/bin Installing iptest script to /usr/local/bin Installing ipython2 script to /usr/local/bin Installing ipcluster2 script to /usr/local/bin Installing ipcluster script to /usr/local/bin Installing ipython script to /usr/local/bin Installing ipcontroller2 script to /usr/local/bin Installing ipcontroller script to /usr/local/bin Installing iptest2 script to /usr/local/bin Installing ipengine script to /usr/local/bin Successfully installed ipython Cleaning up... 2014-04-23 13:50:52,193 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:50:52,193 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:50:52,194 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:50:52,194 PID: 460 cluster.py:1712 - INFO - Running plugin h5py 2014-04-23 13:50:52,194 PID: 460 add_pkgs.py:10 - INFO - Installing python-h5py on master 2014-04-23 13:50:52,227 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && apt-get -y install python-h5py 2014-04-23 13:51:32,369 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && apt-get -y install python-h5py': Reading package lists... Building dependency tree... Reading state information... The following NEW packages will be installed: python-h5py 0 upgraded, 1 newly installed, 0 to remove and 1 not upgraded. Need to get 828 kB of archives. After this operation, 2,615 kB of additional disk space will be used. Get:1 http://archive.ubuntu.com/ubuntu/ precise/universe python-h5py amd64 2.0.1-1build1 [828 kB] Fetched 828 kB in 0s (3,999 kB/s) Selecting previously unselected package python-h5py. (Reading database ... 96393 files and directories currently installed.) Unpacking python-h5py (from .../python-h5py_2.0.1-1build1_amd64.deb) ... Setting up python-h5py (2.0.1-1build1) ... debconf: unable to initialize frontend: Dialog debconf: (TERM is not set, so the dialog frontend is not usable.) debconf: falling back to frontend: Readline debconf: unable to initialize frontend: Readline debconf: (This frontend requires a controlling tty.) debconf: falling back to frontend: Teletype dpkg-preconfigure: unable to re-open stdin: 2014-04-23 13:51:32,484 PID: 460 cluster.py:759 - DEBUG - existing nodes: {u'i-bfbfadef': } 2014-04-23 13:51:32,484 PID: 460 cluster.py:762 - DEBUG - updating existing node i-bfbfadef in self._nodes 2014-04-23 13:51:32,484 PID: 460 cluster.py:775 - DEBUG - returning self._nodes = [] 2014-04-23 13:51:32,484 PID: 460 cluster.py:1712 - INFO - Running plugin ipcluster 2014-04-23 13:51:32,519 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && which ipython 2014-04-23 13:51:32,657 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && which ipython': /usr/local/bin/ipython 2014-04-23 13:51:32,826 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && which ipcluster 2014-04-23 13:51:32,884 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && which ipcluster': /usr/local/bin/ipcluster 2014-04-23 13:51:33,076 PID: 460 sshutils.py:112 - DEBUG - connecting to host ec2-54-198-102-63.compute-1.amazonaws.com on port 22 as user sgeadmin 2014-04-23 13:51:34,084 PID: 460 sshutils.py:204 - DEBUG - creating sftp connection 2014-04-23 13:51:34,776 PID: 460 ipcluster.py:117 - INFO - Writing IPython cluster config files 2014-04-23 13:51:34,811 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && rm -rf '/home/sgeadmin/.ipython/profile_default' 2014-04-23 13:51:34,851 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && rm -rf '/home/sgeadmin/.ipython/profile_default'': 2014-04-23 13:51:34,954 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && ipython profile create 2014-04-23 13:51:40,563 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && ipython profile create': OpenBLAS : Your OS does not support AVX instructions. OpenBLAS is using Nehalem kernels as a fallback, which may give poorer performance. [ProfileCreate] Generating default config file: u'/home/sgeadmin/.ipython/profile_default/ipython_config.py' [ProfileCreate] Generating default config file: u'/home/sgeadmin/.ipython/profile_default/ipython_notebook_config.py' [ProfileCreate] Generating default config file: u'/home/sgeadmin/.ipython/profile_default/ipython_nbconvert_config.py' 2014-04-23 13:51:40,938 PID: 460 ipcluster.py:168 - INFO - Starting the IPython controller and 1 engines on master 2014-04-23 13:51:41,005 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && rm -f /home/sgeadmin/.ipython/profile_default/security/*.json 2014-04-23 13:51:41,065 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && rm -f /home/sgeadmin/.ipython/profile_default/security/*.json': 2014-04-23 13:51:41,101 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && ipcluster start --n=1 --delay=5 --daemonize 2014-04-23 13:51:42,098 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && ipcluster start --n=1 --delay=5 --daemonize': OpenBLAS : Your OS does not support AVX instructions. OpenBLAS is using Nehalem kernels as a fallback, which may give poorer performance. 2014-04-23 17:51:42.031 [IPClusterStart] Using existing profile dir: u'/home/sgeadmin/.ipython/profile_default' 2014-04-23 13:51:42,099 PID: 460 ipcluster.py:176 - INFO - Waiting for JSON connector file... 2014-04-23 13:51:44,504 PID: 460 sshutils.py:212 - DEBUG - creating scp connection 2014-04-23 13:51:44,741 PID: 460 ipcluster.py:274 - INFO - Authorizing tcp ports [40725-40725] on 0.0.0.0/0 for: control 2014-04-23 13:51:46,067 PID: 460 ipcluster.py:274 - INFO - Authorizing tcp ports [51992-51992] on 0.0.0.0/0 for: task 2014-04-23 13:51:46,328 PID: 460 ipcluster.py:274 - INFO - Authorizing tcp ports [50735-50735] on 0.0.0.0/0 for: notification 2014-04-23 13:51:47,034 PID: 460 ipcluster.py:274 - INFO - Authorizing tcp ports [38747-38747] on 0.0.0.0/0 for: mux 2014-04-23 13:51:48,288 PID: 460 ipcluster.py:274 - INFO - Authorizing tcp ports [40507-40507] on 0.0.0.0/0 for: iopub 2014-04-23 13:51:48,503 PID: 460 ipcluster.py:274 - INFO - Authorizing tcp ports [45702-45702] on 0.0.0.0/0 for: registration 2014-04-23 13:51:48,764 PID: 460 ipcluster.py:219 - INFO - Setting up IPython web notebook for user: sgeadmin 2014-04-23 13:51:56,030 PID: 460 ipcluster.py:223 - INFO - Creating SSL certificate for user sgeadmin 2014-04-23 13:51:56,097 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && openssl req -new -newkey rsa:4096 -days 365 -nodes -x509 -subj /C=US/ST=SC/L=STAR/O=Dis/CN=ec2-54-198-102-63.compute-1.amazonaws.com -keyout /home/sgeadmin/.ipython/profile_default/sgeadmin.pem -out /home/sgeadmin/.ipython/profile_default/sgeadmin.pem 2014-04-23 13:51:57,298 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && openssl req -new -newkey rsa:4096 -days 365 -nodes -x509 -subj /C=US/ST=SC/L=STAR/O=Dis/CN=ec2-54-198-102-63.compute-1.amazonaws.com -keyout /home/sgeadmin/.ipython/profile_default/sgeadmin.pem -out /home/sgeadmin/.ipython/profile_default/sgeadmin.pem': Generating a 4096 bit RSA private key ........................++ ..................................................................++ writing new private key to '/home/sgeadmin/.ipython/profile_default/sgeadmin.pem' ----- 2014-04-23 13:51:57,495 PID: 460 sshutils.py:561 - DEBUG - executing remote command: source /etc/profile && python -c 'from IPython.lib import passwd; print passwd("a-secret-password")' 2014-04-23 13:51:57,868 PID: 460 sshutils.py:585 - DEBUG - output of 'source /etc/profile && python -c 'from IPython.lib import passwd; print passwd("a-secret-password")'': sha1:6369bb27f4ad:44ee6aef5d8ebf6b74149e7403e52fb8c69cf920 2014-04-23 13:52:54,634 PID: 460 cluster.py:1722 - ERROR - Error occured while running plugin 'ipcluster': 2014-04-23 13:52:54,635 PID: 460 cli.py:307 - ERROR - Unhandled exception occured Traceback (most recent call last): File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/cli.py", line 274, in main sc.execute(args) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/commands/start.py", line 244, in execute validate_running=validate_running) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/cluster.py", line 1626, in start return self._start(create=create, create_only=create_only) File "", line 2, in _start File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/utils.py", line 112, in wrap_f res = func(*arg, **kargs) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/cluster.py", line 1649, in _start self.setup_cluster() File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/cluster.py", line 1658, in setup_cluster self._setup_cluster() File "", line 2, in _setup_cluster File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/utils.py", line 112, in wrap_f res = func(*arg, **kargs) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/cluster.py", line 1670, in _setup_cluster self.run_plugins() File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/cluster.py", line 1688, in run_plugins self.run_plugin(plug, method_name=method_name, node=node) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/cluster.py", line 1713, in run_plugin func(*args) File "", line 2, in run File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/utils.py", line 112, in wrap_f res = func(*arg, **kargs) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/plugins/ipcluster.py", line 302, in run self._start_notebook(master, user, profile_dir) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/plugins/ipcluster.py", line 249, in _start_notebook master.ssh.makedirs(self.notebook_directory) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/sshutils.py", line 249, in makedirs self.makedirs(head, mode) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/sshutils.py", line 257, in makedirs self.mkdir(path, mode) File "/Users/badr/anaconda/lib/python2.7/site-packages/starcluster/sshutils.py", line 268, in mkdir return self.sftp.mkdir(path, mode) File "/Users/badr/anaconda/lib/python2.7/site-packages/paramiko/sftp_client.py", line 296, in mkdir self._request(CMD_MKDIR, path, attr) File "/Users/badr/anaconda/lib/python2.7/site-packages/paramiko/sftp_client.py", line 647, in _request return self._read_response(num) File "/Users/badr/anaconda/lib/python2.7/site-packages/paramiko/sftp_client.py", line 694, in _read_response self._convert_status(msg) File "/Users/badr/anaconda/lib/python2.7/site-packages/paramiko/sftp_client.py", line 722, in _convert_status raise IOError(errno.EACCES, text) IOError: [Errno 13] Permission denied