Elastic Beanstalk, EB, is a bit of a magic box. I’d thought it would be good to poke around a little bit under the hood, see how things actually work and learn from it. Understanding just enough of how EB works is extremely helpful for debugging. For this example I’m using a “64bit Amazon Linux 2017.03 v2.7.0 running Docker 17.03.1-ce” EB solution stack.

What Happens When We Deploy Code

So what happens when we deploy code to a EB environment? Let’s deploy a simple little rails app and trace the environment to find out. The source code the simple rails app is on GitHub at tongueroo/hi though for the sake of this post it really doesn’t matter which app you used to deploy

$ eb deploy
WARNING: Deploying a previously deployed commit
INFO: Environment update is starting.
INFO: Deploying new version to instance(s).
INFO: Successfully pulled tongueroo/hi:base
INFO: Successfully built aws_beanstalk/staging-app
INFO: Successfully built aws_beanstalk/staging-app
INFO: Docker container 3691fd5e5d46 is running aws_beanstalk/current-app.
INFO: Command execution completed on 1 of 2 instances in environment.
INFO: Docker container 14638e61c6ee is running aws_beanstalk/current-app.
INFO: Command execution completed on 2 of 2 instances in environment.
INFO: New application version was deployed to running EC2 instances.
INFO: Environment update completed successfully.
$

That’s great, but what actually happened when we ran eb deploy?

EB Host Manager

EB talks about a host manager process in the documentation architecture section. This is a daemon process that sits there and manages the server. It listens for events like code deployment or environmental variable updates and process those events when they are triggered. The host manager actually leverages the /opt/aws/bin/cfn-hup command.

/opt/aws/bin/cfn-hup
root      1276  0.0  0.2 110456  2196 pts/0    S+   22:48   0:00 grep --color=auto cfn-hup
root      2796  0.2  2.5 530956 26060 ?        Ssl  Jul15   3:46 /usr/bin/python2.7 /opt/aws/bin/cfn-hup

The cfn-hup process is started by upstart. If you tail the /var/log/cfn-hup.log , you can see the cfn-hup process is listening to events from an sqs queue.

2017-07-16 23:09:15,432 [DEBUG] Receiving messages for queue
2017-07-16 23:09:33,602 [DEBUG] Processing message: {'EventHandle': 'blah', 'DispatcherId': 'blah', 'CommandName': 'blah', 'ResultQueue': 'blah', 'Data': 'blah', 'InvocationId': 'blah'}
2017-07-16 23:09:33,602 [DEBUG] Command message: {'EventHandle': 'blah', 'DispatcherId': 'blah', 'CommandName': 'blah', 'Expiration': 1500246693428, 'ResultQueue': 'blah', 'Data': 'blah', 'InvocationId': 'blah'}
2017-07-16 23:09:33,602 [INFO] Received command ElasticBeanstalkCommand-AWSEBAutoScalingGroup (invocation id: blah)
2017-07-16 23:09:33,602 [INFO] Running action for aws-eb-command-handler
2017-07-16 23:09:33,602 [DEBUG] Action environment: {'LANG': 'en_US.UTF-8', 'TERM': 'linux', 'LISTENER_ID': u'blah', 'RESULT_SECRET_KEY': u'blah', 'SHLVL': '1', 'RESULT_ACCESS_KEY': u'blah', 'STACK_NAME': 'blah', 'RESULT_SESSION_TOKEN': u'blah', 'UPSTART_JOB': 'cfn-hup', 'CMD_DATA': 'blah', 'UPSTART_INSTANCE': '', 'PWD': '/', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/bin:/usr/sbin:/sbin:/bin', 'CMD_NAME': 'ElasticBeanstalkCommand-AWSEBAutoScalingGroup', 'RESULT_QUEUE': 'blah', 'DISPATCHER_ID': 'blah', 'EVENT_HANDLE': 'blah', '_': '/opt/aws/bin/cfn-hup', 'INVOCATION_ID': 'blah'}
2017-07-16 23:09:47,841 [DEBUG] Action for aws-eb-command-handler output: {"status":"SUCCESS","api_version":"1.0","results":[{"status":"SUCCESS","msg":"","returncode":0,"events":[{"msg":"Successfully pulled ruby:2.3.3","severity":"TRACE","timestamp":1500246578},{"msg":"Successfully built aws_beanstalk/staging-app","severity":"TRACE","timestamp":1500246578},{"msg":"Docker container 1c4d4630b9e6 is running aws_beanstalk/current-app.","severity":"TRACE","timestamp":1500246587}]}]}
2017-07-16 23:09:47,842 [INFO] Action for aws-eb-command-handler succeeded, returning SUCCESS
2017-07-16 23:09:47,842 [DEBUG] Sending {"Status": "SUCCESS", "DispatcherId": "blah", "ListenerId": "blah", "CommandName": "ElasticBeanstalkCommand-AWSEBAutoScalingGroup", "InvocationId": "blah", "Data": "{\"status\":\"SUCCESS\",\"api_version\":\"1.0\",\"results\":[{\"status\":\"SUCCESS\",\"msg\":\"\",\"returncode\":0,\"events\":[{\"msg\":\"Successfully pulled ruby:2.3.3\",\"severity\":\"TRACE\",\"timestamp\":1500246578},{\"msg\":\"Successfully built aws_beanstalk/staging-app\",\"severity\":\"TRACE\",\"timestamp\":1500246578},{\"msg\":\"blah.\",\"severity\":\"TRACE\",\"timestamp\":1500246587}]}]}"} to queue
 from queue
2017-07-16 23:09:47,971 [DEBUG] Receiving messages for queue

So when we run the eb deploy command or deploy via the EB api, what eventually happens is that the AWS EB service writes to an sqs queue under our AWS account. The host manager daemon process, in turn, listens to this queue and does its bidding. Note: I have redacted all sensitive information.

What does cfn-hup do?

If you trace through the files and the libraries, you will find AWS EB service goes through the following steps:

* /usr/bin/python2.7 /opt/aws/bin/cfn-hup
* /bin/bash -e /opt/elasticbeanstalk/bin/command-processor
* /opt/elasticbeanstalk/lib/ruby/bin/ruby /opt/elasticbeanstalk/lib/ruby/bin/command-processor

The trace jumps from Python, Bash and Ruby scripts. It is easier and quicker to actually see what is going on with the ps command. Run this watch command watch ‘ps auxwwf | grep -A 5 "python /opt/aws/bin/cfn-hup"' during a deploy.

The important thing is that eventually a ruby /opt/elasticbeanstalk/lib/ruby/bin/command-processor script is called. Tracing that code you’ll see that it loads a beanstalk-core gem. Finally, the /opt/elasticbeanstalk/lib/ruby/lib/ruby/gems/2.2.0/gems/beanstalk-core-2.3/lib/elasticbeanstalk/command-processor.rb file contains the heart of the logic for how ElasticBeanstalk handles deployment. You can also see in here that the command-processor command logs what it does to /var/log/eb-commandprocessor.log. Here’s an example of some of it’s output:

$ tail -f /var/log/eb-commandprocessor.log
...
[2017-07-19T06:24:05.584Z] DEBUG [4510]  : Loaded 6 actions for stage 0.
[2017-07-19T06:24:05.584Z] INFO  [4510]  : Running 1 of 6 actions: InfraWriteConfig...
[2017-07-19T06:24:05.587Z] INFO  [4510]  : Running 2 of 6 actions: DownloadSourceBundle...
[2017-07-19T06:24:05.895Z] INFO  [4510]  : Running 3 of 6 actions: EbExtensionPreBuild...
[2017-07-19T06:24:06.177Z] INFO  [4510]  : Running 4 of 6 actions: AppDeployPreHook...
[2017-07-19T06:24:09.086Z] INFO  [4510]  : Running 5 of 6 actions: EbExtensionPostBuild...
[2017-07-19T06:24:09.368Z] INFO  [4510]  : Running 6 of 6 actions: InfraCleanEbextension...
[2017-07-19T06:24:09.370Z] INFO  [4510]  : Running stage 1 of command CMD-AppDeploy...
[2017-07-19T06:24:09.370Z] DEBUG [4510]  : Loaded 2 actions for stage 1.
[2017-07-19T06:24:09.370Z] INFO  [4510]  : Running 1 of 2 actions: AppDeployEnactHook...
[2017-07-19T06:24:17.592Z] INFO  [4510]  : Running 2 of 2 actions: AppDeployPostHook...
[2017-07-19T06:24:18.186Z] INFO  [4510]  : Running AddonsAfter for command CMD-AppDeploy...
[2017-07-19T06:24:18.305Z] INFO  [4510]  : Command CMD-AppDeploy succeeded!
[2017-07-19T06:24:18.306Z] INFO  [4510]  : Command processor returning results:
{"status":"SUCCESS","api_version":"1.0","results":[{"status":"SUCCESS","msg":"","returncode":0,"events":[{"msg":"Successfully pulled ruby:2.3.3","severity":"TRACE","timestamp":1500445448},{"msg":"Successfully built aws_beanstalk/staging-app","severity":"TRACE","timestamp":1500445449},{"msg":"Docker container d8cdffc1b069 is running aws_beanstalk/current-app.","severity":"TRACE","timestamp":1500445457}]}]}

$

You can see that it goes through a set of actions and it downloads the code, runs some hooks, does some building and cleans up. It reports success at the end.

There are a few interesting files in the gem to look at to get a better understanding of how it works:

  • lib/elasticbeanstalk/command.rb
  • lib/elasticbeanstalk/hook-directory-executor.rb
  • lib/elasticbeanstalk/executable.rb

Looking at command.rb we can see that the hooks scripts are in the /opt/elasticbeanstalk/hooks/ directory. Looking at executable.rb, ElasticBeanstalk’s command processor interestingly instance_eval’s the scripts if it is a ruby script and shells out and executes it as a subprocess it is not.

Ultimately, the trace of the code leads to the /opt/elasticbeanstalk/hooks/appdeploy/folder:

00run.sh  01flip.sh
00clean_dir.sh  01unzip.sh  02loopback-check.sh  03build.sh
00run.sh  01flip.sh
00_clean_imgs.sh  01_monitor_pids.sh

This scripts are basically run in order and calls 03build.sh to build the docker image and 00run.sh to run the docker container.

Most Useful Thing To Know When Docker Container Won’t Start

The biggest takeaway from this blog post is knowing where to focus your debugging efforts when AWS EB Service does not behave in a way you expect it to. If you cannot figure out why the environment is not working. It is very likely that the docker container did not start up properly. Run this command as root:

$ sudo su

From there you’ll see a docker run command. Copy and paste that command and change the docker image from aws_beanstalk/staging-app to aws_beanstalk/current-app. For example:

docker run -d --env PARAM3= XXXXX --env PARAM4= XXXXX --env PARAM1= XXXXX --env PARAM2= XXXXX --env PARAM5= XXXXX --env AWS_SECRET_KEY=XXXXX --env AWS_ACCESS_KEY_ID= XXXXX --env RDS_PORT=3306 --env RDS_PASSWORD= XXXXX --env RDS_USERNAME= XXXXX --env RDS_HOSTNAME= XXXXX --env RDS_DB_NAME= XXXXX -v /var/log/eb-docker/containers/eb-current-app:/var/log/nginx aws_beanstalk/staging-app

to:

docker run -d --env PARAM3= --env PARAM4= --env PARAM1= --env PARAM2= --env PARAM5= --env AWS_SECRET_KEY= --env AWS_ACCESS_KEY_ID= --env RDS_PORT=3306 --env RDS_PASSWORD=blah --env RDS_USERNAME=blah --env RDS_HOSTNAME=blah --env RDS_DB_NAME=blah -v /var/log/eb-docker/containers/eb-current-app:/var/log/nginx aws_beanstalk/current-app

Here’s a debugging session:

# docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
163ebbeedede aws_beanstalk/current-app:latest "/bin/sh -c docker/b About an hour ago Up About an
hour 3000/tcp hopeful_brattain
# docker images
REPOSITORY TAG IMAGE ID CREATED VIRTUAL SIZE
aws_beanstalk/current-app latest 14f8d8a3276b About an hour ago 959.4 MB
tongueroo/hi base 1f2b3ca72e39 2 weeks ago 959.4 MB
# docker run -d --env PARAM3= --env PARAM4= --env PARAM1= --env PARAM2= --env PARAM5= --env
AWS_SECRET_KEY= --env AWS_ACCESS_KEY_ID= --env RDS_PORT=3306 --env RDS_PASSWORD=blah --env
RDS_USERNAME=blah --env RDS_HOSTNAME=blah --env RDS_DB_NAME=blah -v /var/log/eb-docker/containers
eb-current-app:/var/log/nginx aws_beanstalk/current-app
b7ce5a7e4d90f1f34d77545c9005b33bc414171e58685c34f2d7b988e8a00c15
# docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
b7ce5a7e4d90 aws_beanstalk/current-app:latest "/bin/sh -c docker/b 4 seconds ago Up 3 seconds 3000
tcp insane_pasteur
163ebbeedede aws_beanstalk/current-app:latest "/bin/sh -c docker/b About an hour ago Up About an
hour 3000/tcp hopeful_brattain
# docker stop b7ce5a7e4d90
b7ce5a7e4d90

In this debugging session, there are eventually 2 docker containers running because the first container started up just fine. If there are no containers running, the debugging technique demonstrated above should be very useful. Most of the time, the app is misconfigured with an invalid or missing environmental variable. If you can get the docker container to run locally just fine and are sure you are using the same docker image, the issue is most likely with your environmental variables.