AWS: Simple cfn-init fails on Amazon Linux 2 for no apparent reason

Question

I am provisioning a cloudformation stack. I am just trying to run the simplest possible cfn-initever on an instance started using a custom ami that was based on Amazon Linux 2:

 EC2ESMasterNode1:
    Type: AWS::EC2::Instance
    Metadata:
      Comment: ES Cluster Master 1 instance
      AWS::CloudFormation::Init:
        config:
          commands:
            01_template_elastic:
              command:
                !Sub |
                  echo "'Hello World'"
    Properties:
      ImageId: ami-09693313102a30b2c
      InstanceType: !Ref MasterInstanceType
      SubnetId: !Ref Subn1ID
      SecurityGroupIds: [!Ref SGES]
      KeyName: mykey
      UserData:
        "Fn::Base64":
          !Sub |
            #!/bin/bash -xe
            # Start cfn-init
            /opt/aws/bin/cfn-init -s ${AWS::StackName} --resource EC2ESMasterNode1 --region ${AWS::Region}
            # Send the respective signal to Cloudformation
            /opt/aws/bin/cfn-signal -e 0 --stack ${AWS::StackName} --resource EC2ESMasterNode1 --region ${AWS::Region}
      Tags:
        - Key: "Name"
          Value: !Ref Master1NodeName

The /var/log/cloud-init-output.log has the following print

No packages needed for security; 15 packages available
Resolving Dependencies
Cloud-init v. 18.2-72.amzn2.0.6 running 'modules:final' at Wed, 02 Jan 2019 12:41:26 +0000. Up 14.42 seconds.
+ /opt/aws/bin/cfn-init -s test-elastic --resource EC2ESMasterNode1 --region eu-west-1
+ /opt/aws/bin/cfn-signal -e 0 --stack test-elastic --resource EC2ESMasterNode1 --region eu-west-1
ValidationError: Stack arn:aws:cloudformation:eu-west-1:248059334340:stack/test-elastic/9fc79150-0e8b-11e9-b135-503ac9e74cfd is in CREATE_COMPLETE state and cannot be signaled
Jan 02 12:41:27 cloud-init[2575]: util.py[WARNING]: Failed running /var/lib/cloud/instance/scripts/part-001 [1]
Jan 02 12:41:27 cloud-init[2575]: cc_scripts_user.py[WARNING]: Failed to run module scripts-user (scripts in /var/lib/cloud/instance/scripts)
Jan 02 12:41:27 cloud-init[2575]: util.py[WARNING]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.pyc'>) failed
Cloud-init v. 18.2-72.amzn2.0.6 finished at Wed, 02 Jan 2019 12:41:27 +0000. Datasource DataSourceEc2.  Up 15.30 seconds

The /var/log/cloud-init.log has the following errors:

    Jan 02 12:41:26 cloud-init[2575]: handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance
Jan 02 12:41:26 cloud-init[2575]: util.py[DEBUG]: Writing to /var/lib/cloud/instances/i-0c10a5ff1be475b99/sem/config_scripts_user - wb: [644] 20 bytes
Jan 02 12:41:26 cloud-init[2575]: helpers.py[DEBUG]: Running config-scripts-user using lock (<FileLock using file '/var/lib/cloud/instances/i-0c10a5ff1be475b99/sem/config_scripts_user'>)
Jan 02 12:41:26 cloud-init[2575]: util.py[DEBUG]: Running command ['/var/lib/cloud/instance/scripts/part-001'] with allowed return codes [0] (shell=True, capture=False)
Jan 02 12:41:27 cloud-init[2575]: util.py[WARNING]: Failed running /var/lib/cloud/instance/scripts/part-001 [1]
Jan 02 12:41:27 cloud-init[2575]: util.py[DEBUG]: Failed running /var/lib/cloud/instance/scripts/part-001 [1]
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cloudinit/util.py", line 860, in runparts
    subp(prefix + [exe_path], capture=False, shell=True)
  File "/usr/lib/python2.7/site-packages/cloudinit/util.py", line 2053, in subp
    cmd=args)
ProcessExecutionError: Unexpected error while running command.
Command: ['/var/lib/cloud/instance/scripts/part-001']
Exit code: 1
Reason: -
Stdout: -
Stderr: -
Jan 02 12:41:27 cloud-init[2575]: cc_scripts_user.py[WARNING]: Failed to run module scripts-user (scripts in /var/lib/cloud/instance/scripts)
Jan 02 12:41:27 cloud-init[2575]: handlers.py[DEBUG]: finish: modules-final/config-scripts-user: FAIL: running config-scripts-user with frequency once-per-instance
Jan 02 12:41:27 cloud-init[2575]: util.py[WARNING]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.pyc'>) failed
Jan 02 12:41:27 cloud-init[2575]: util.py[DEBUG]: Running module scripts-user (<module 'cloudinit.config.cc_scripts_user' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.pyc'>) failed
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/cloudinit/stages.py", line 798, in _run_modules
    freq=freq)
  File "/usr/lib/python2.7/site-packages/cloudinit/cloud.py", line 54, in run
    return self._runners.run(name, functor, args, freq, clear_on_fail)
  File "/usr/lib/python2.7/site-packages/cloudinit/helpers.py", line 187, in run
    results = functor(*args)
  File "/usr/lib/python2.7/site-packages/cloudinit/config/cc_scripts_user.py", line 45, in handle
    util.runparts(runparts_path)
  File "/usr/lib/python2.7/site-packages/cloudinit/util.py", line 867, in runparts
    % (len(failed), len(attempted)))
RuntimeError: Runparts: 1 failures in 1 attempted commands
Jan 02 12:41:27 cloud-init[2575]: stages.py[DEBUG]: Running module ssh-authkey-fingerprints (<module 'cloudinit.config.cc_ssh_authkey_fingerprints' from '/usr/lib/python2.7/site-packages/cloudinit/config/cc_ssh_authkey_fingerprints.pyc'>) with frequency once-per-instance

_

cat /var/log/cfn-init-cmd.log
2019-01-02 12:50:54,777 P2582 [INFO] ************************************************************
2019-01-02 12:50:54,777 P2582 [INFO] ConfigSet default
2019-01-02 12:50:54,778 P2582 [INFO] ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
2019-01-02 12:50:54,778 P2582 [INFO] Config config
2019-01-02 12:50:54,778 P2582 [INFO] ============================================================
2019-01-02 12:50:54,778 P2582 [INFO] Command 01_template_elastic
2019-01-02 12:50:54,782 P2582 [INFO] -----------------------Command Output-----------------------
2019-01-02 12:50:54,782 P2582 [INFO]     'Hello World'
2019-01-02 12:50:54,783 P2582 [INFO] ------------------------------------------------------------
2019-01-02 12:50:54,783 P2582 [INFO] Completed successfully.

Does anyone have a clue what the error is about?

Furthermore, why the stack is created with success? (as also the specific resource?)

Nolannolana

Answer 1

The error message in /var/log/cloud-init.log means that your UserData script exited with error status 1 rather than the expected 0.

Meanwhile, your /var/log/cloud-init-output.log contains this line:

ValidationError: Stack arn:aws:cloudformation:eu-west-1:248059334340:stack/test-elastic/9fc79150-0e8b-11e9-b135-503ac9e74cfd
  is in CREATE_COMPLETE state and cannot be signaled

To your other question:

Furthermore, why the stack is created with success? (as also the specific resource?)

It is the normal behaviour of the stack to go into CREATE_COMPLETE state once the resources are created. The running of the UserData script doesn't by default delay this state.

Because you are using the cfn-signal, I assume that you have a requirement for the CREATE_COMPLETE state to be deferred until such time as you send the signal in UserData.

There is a good blog post on how to set this all up here.

But tl;dr -

You probably just need to add a CreationPolicy to your EC2 instance resource like this:

Resources:
  EC2ESMasterNode1:
    ...
    CreationPolicy:
      ResourceSignal:
        Count: 1
        Timeout: PT10M

That says wait for 1 signal and time out after 10 minutes. Set those according to your requirements obviously.

Agnomen

I have updated my question; I now use the plain vanilla Amazon Linux 2 ami; I am also attaching cloud-init-output.log output. Ignore any identation errors they are copy-paste related; this is the exact code run on my cf template; – Nolannolana

also adding /var/log/cfn-init-cmd.log – Nolannolana

Yes, thanks. I updated the answer in light the additional information. – Agnomen