My EC2 startup script (supplied in user_data) doesn't seem to be run at startup

Question

I am using boto to launch ec2 instances as part of an autoscale group. I read a simple bash script and pass the base64 encoded string into user_data. I'm using the Ubuntu AMI (ami-a73264ce) but I've also tried another Ubuntu AMI (ami-ad184ac4) and the Amazon Linux AMI (ami-bba18dd2) because one stackoverflow answer suggested that the AMI might be the problem (EC2 instance loads my user-data script but doesn't run it)

Here is my script (startup.sh)

    #!/bin/bash
    mkdir newdir

Here is my boto code:

  conn = AutoScaleConnection(aws_access_key_id=AWS_ACCESS_KEY_ID, aws_secret_access_key=AWS_SECRET_ACCESS_KEY)

  f = open('startup.sh', 'r')
  user_data = f.read()
  lc = LaunchConfiguration(name=launch_config_name, image_id=ami_id,
                           key_name=key_name, security_groups=security_groups,
                           user_data=base64.b64encode(user_data))
  conn.create_launch_configuration(lc)

  ag = AutoScalingGroup(group_name=group_name, load_balancers=load_balancers,
                        availability_zones=availability_zones, launch_config=lc,
                        min_size=min_size, max_size=max_size, connection=conn)

  conn.create_auto_scaling_group(ag)

Here is my /var/log/syslog:

Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] cc_apt_update_upgrade.py[DEBUG]: mirror info: {'security': 'http://security.ubuntu.com/ubuntu', 'primary': 'http://us-east-1.ec2.archive.ubuntu.com/ubuntu/', 'mirror': 'http://us-east-1.ec2.archive.ubuntu.com/ubuntu/'} 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling landscape with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling timezone with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling puppet with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling chef with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling salt-minion with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling mcollective with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling disable-ec2-metadata with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling runcmd with freq=None and args=[] 
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling byobu with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] cloud-init-cfg[INFO]: cloud-init-cfg ['all', 'final'] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling rightscale_userdata with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling scripts-per-once with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling scripts-per-boot with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling scripts-per-instance with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling scripts-user with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling keys-to-console with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling phone-home with freq=None and args=[] 
Jan 27 23:13:17 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling final-message with freq=None and args=[]

Here is my /var/log/cloud-init.log:

2014-01-27 23:12:54,362 - cloud-init[INFO]: cloud-init start-local running: Mon, 27 Jan 2014 23:12:54 +0000. up 14.07 seconds
2014-01-27 23:12:54,659 - __init__.py[DEBUG]: searching for data source in ['DataSourceNoCloud', 'DataSourceConfigDrive', 'DataSourceOVF']
2014-01-27 23:12:55,281 - __init__.py[DEBUG]: Did not find data source. searched classes: ['DataSourceNoCloud', 'DataSourceConfigDrive', 'DataSourceOVF']
2014-01-27 23:12:55,998 - cloud-init[INFO]: cloud-init start running: Mon, 27 Jan 2014 23:12:55 +0000. up 15.43 seconds
2014-01-27 23:12:56,050 - __init__.py[DEBUG]: searching for data source in ['DataSourceNoCloudNet', 'DataSourceConfigDriveNet', 'DataSourceOVFNet', 'DataSourceMAAS', 'DataSourceEc2']
2014-01-27 23:12:56,588 - DataSourceEc2.py[DEBUG]: Using metadata source: 'http://169.254.169.254'
2014-01-27 23:12:56,663 - DataSourceEc2.py[DEBUG]: crawl of metadata service took 0s
2014-01-27 23:12:56,664 - __init__.py[DEBUG]: found data source DataSourceEc2
2014-01-27 23:12:56,670 - cloud-init[DEBUG]: found data source: DataSourceEc2
2014-01-27 23:12:56,675 - __init__.py[WARNING]: Unhandled non-multipart userdata starting 'IyEvYmluL2Jhc2gKbWtkaXIg...'
2014-01-27 23:12:56,684 - __init__.py[DEBUG]: handling bootcmd with freq=None and args=[]
2014-01-27 23:12:56,687 - __init__.py[DEBUG]: handling resizefs with freq=None and args=[]
2014-01-27 23:12:56,712 - cc_resizefs.py[DEBUG]: resize took 0.0159449577332 seconds
2014-01-27 23:12:56,713 - cc_resizefs.py[DEBUG]: resizing root filesystem (type=ext4, maj=202, min=1, val=True)
2014-01-27 23:12:56,713 - __init__.py[DEBUG]: handling set_hostname with freq=None and args=[]
2014-01-27 23:12:56,781 - cc_set_hostname.py[DEBUG]: populated /etc/hostname with ip-10-122-219-105 on first boot
2014-01-27 23:12:56,782 - __init__.py[DEBUG]: handling update_hostname with freq=None and args=[]
2014-01-27 23:12:58,478 - cc_update_hostname.py[DEBUG]: wrote ip-10-122-219-105 to /var/lib/cloud/data/previous-hostname
2014-01-27 23:12:58,478 - __init__.py[DEBUG]: handling update_etc_hosts with freq=None and args=[]
2014-01-27 23:12:58,479 - cc_update_etc_hosts.py[DEBUG]: not managing /etc/hosts
2014-01-27 23:12:58,479 - __init__.py[DEBUG]: handling ca-certs with freq=None and args=[]
2014-01-27 23:12:58,482 - __init__.py[DEBUG]: handling rsyslog with freq=None and args=[]
2014-01-27 23:12:58,620 - __init__.py[DEBUG]: handling ssh with freq=None and args=[]
Jan 27 23:13:02 ip-10-122-219-105 [CLOUDINIT] cloud-init-cfg[INFO]: cloud-init-cfg ['all', 'config']
Jan 27 23:13:02 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling mounts with freq=None and args=[]
Jan 27 23:13:02 ip-10-122-219-105 [CLOUDINIT] DataSourceEc2.py[DEBUG]: remapped device name /dev/sdb => /dev/xvdb
Jan 27 23:13:02 ip-10-122-219-105 [CLOUDINIT] DataSourceEc2.py[DEBUG]: remapped device name /dev/sda3 => /dev/xvda3
Jan 27 23:13:02 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling ssh-import-id with freq=None and args=[]
Jan 27 23:13:02 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling locale with freq=None and args=[]
Jan 27 23:13:02 ip-10-122-219-105 [CLOUDINIT] cc_locale.py[DEBUG]: setting locale to en_US.UTF-8
Jan 27 23:13:13 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling set-passwords with freq=None and args=[]
Jan 27 23:13:13 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling grub-dpkg with freq=None and args=[]
Jan 27 23:13:13 ip-10-122-219-105 [CLOUDINIT] cc_grub_dpkg.py[DEBUG]: setting grub debconf-set-selections with '','true'
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling apt-pipelining with freq=None and args=[]
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] cc_apt_pipelining.py[DEBUG]: Wrote /etc/apt/apt.conf.d/90cloud-init-pipelining with APT pipeline setting
Jan 27 23:13:16 ip-10-122-219-105 [CLOUDINIT] __init__.py[DEBUG]: handling apt-update-upgrade with freq=None and args=[]

EDIT:

It works when I use the command line tool, but I'd still like to know why it doesn't work with boto because it might be more convenient to use boto

Answer 1

Turns out it doesn't have to be base64 in python, this worked for me:

#cat make-a-dir.sh
#!/bin/bash
mkdir newdir

Then my python:

shell_script = 'make-a-dir.sh'
with open (shell_script, "r") as myfile:
  data=myfile.read()

Then I pass that in:

run_instances(ami_id,security_group_ids=["sg-1111111"],key_name="my-key",instance_type=instance_type,placement=az,subnet_id=subnet_id,dry_run=dry_run,user_data=data)

Worked a treat. Good luck!

Answer 2

Check if your user data is getting populated in your instance under:

 /var/lib/cloud/data/scripts

Does it have newlines for every statement ?

How about adding this to your script to check that user data is right ?

f = open('startup.sh', 'r')
user_data = f.read()
print user_data