Amazon-ecs-agent: ECS Agent Mark Knowstatus as Stopped but container runs in the background

Created on 16 Apr 2019 · 8Comments · Source: aws/amazon-ecs-agent
Summary

ECS Agent mark known status as stopped but contaoner does not get terminated.
It runs the job in the background.
Observed Behavior

I run the ECS task and after running that ECS agent mark known status from PENDING to RUNNING and after immidiately It mark RUNNING to STOPPED but docker container does not get terminated.
Expected Behavior

If there is no error then it should not mark known status as STOPPED. If it mark as STOPPED then docker container should get terminate or stop.
Notes

Re-opening from #1702 as that one was closed and no one is replying to my re-open request.
kinquestion
Source
pecigonzalo
Most helpful comment

@pecigonzalo Sorry I need to correct my last statement. There are two different status for task: desired status and last status. So when user initiates a stop action(in your case, service did this on behalf of you), the desired status is set as stoppped, however, the last status will not be changed until agent detects the task is fully stopped on the instance and communicates back the status change. That's why @cyastella wants to get more information about when you talk about "task shown as stopped", which status you are referring to.
Can you double check the value of env ECS_CONTAINER_STOP_TIMEOUT that you set? Docker will send SIGTERM to stop container first and after timeout, SIGKILL will be sent to container to forcefully kill the container.
If ECS_CONTAINER_STOP_TIMEOUT is not the root cause, in order to figure it out, we do need to the debug level agent log as @cyastella mentioned, which should tell the information of the whole life cycle of the task. Besides, if you use the log collector, it will also collect docker logs and agent data file, which may also help.
yumex93 on 15 Oct 2019
👍2
All 8 comments

@pecigonzalo
I'm still facing the same issue and I'm using ecs-agent version 1.24.0 and docker 18.06 CE
jaykam on 23 Apr 2019
Could you please provide the debug level Agent log as previously asked on https://github.com/aws/amazon-ecs-agent/issues/1702? you can send it to yhlee at amazon.com.
yhlee-aws on 13 May 2019
@yunhee-l
Task: 556380e3574c423eaf6b46161175d2ca
Image: alpine:latest
Command: sleep 240
Logs:
-- Logs begin at Mon 2019-05-13 15:56:09 UTC, end at Tue 2019-05-14 11:34:22 UTC. --
May 14 11:29:25 ip-10-10-1-180 systemd[1]: Started AWS ECS Agent.
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Loading configuration
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty: ECS_TASK_METADATA_RPS_LIMIT
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty: ECS_ENGINE_TASK_CLEANUP_WAIT_DURATION
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty: ECS_CONTAINER_START_TIMEOUT
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty: ECS_IMAGE_PULL_INACTIVITY_TIMEOUT
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty: ECS_IMAGE_MINIMUM_CLEANUP_AGE
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty: ECS_IMAGE_CLEANUP_INTERVAL
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty:
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Image excluded from cleanup: amazon/amazon-ecs-agent:latest
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Image excluded from cleanup: amazon/amazon-ecs-pause:0.1.0
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Environment variable empty: ECS_POLLING_METRICS_WAIT_DURATION
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Non-json user data, skip merging into agent config: invalid character '\x1f' looking for beginning of value
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Amazon ECS agent Version: 1.24.0, Commit: 8b5e1863
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Loaded config: Cluster: default-tf-dev-cluster,  Region: eu-central-1,  DataDir: /data, Checkpoint: true, AuthType: , UpdatesEnabled: false, DisableMetrics: false, PollMetrics: false, PollingMetricsWaitDuration: 15s, ReservedMem: 256, TaskCleanupWaitDuration: 3h0m0s, DockerStopTimeout: 15m0s, ContainerStartTimeout: 3m0s, TaskCPUMemLimit: 3, , PauseContainerImageName: amazon/amazon-ecs-pause, PauseContainerTag: 0.1.0
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Creating root ecs cgroup: /ecs
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Creating cgroup /ecs
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [WARN] Disabling TaskCPUMemLimit because agent is unabled to setup '/ecs' cgroup: cgroup create: unable to create controller: mkdir /sys/fs/cgroup/systemd/ecs: read-only file system
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Loading state! module="statemanager"
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Event stream ContainerChange start listening...
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [DEBUG] Loaded state! module="statemanager" state="&{Data:map[TaskEngine:0xc4203e9050 ContainerInstanceArn:0xc4203e9060 Cluster:0xc4203e9070 EC2InstanceID:0xc4203e9080 availabilityZone:0xc4203e9090] Version:18}"
May 14 11:29:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:25Z [INFO] Restored cluster 'default-tf-dev-cluster'
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Retrieved Tags from EC2 DescribeTags API:
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: [{
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Key: "Cluster",
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Value: "default-tf-dev-cluster"
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: } {
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Key: "Environment",
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Value: "dev"
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: } {
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Key: "Name",
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Value: "dev-default-ecs"
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: } {
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Key: "Namespace",
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Value: ""
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: } {
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Key: "Terraform",
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Value: "true"
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: }]
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Restored from checkpoint file. I am running as 'arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41' in cluster 'default-tf-dev-cluster'
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Remaining mem: 7730
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Registered container instance with cluster!
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [ERROR] Unable to retrieve Host Instance PublicIPv4 Address: EC2MetadataError: failed to make EC2Metadata request
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: caused by: <?xml version="1.0" encoding="iso-8859-1"?>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:          "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: <html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:  <head>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   <title>404 - Not Found</title>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:  </head>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:  <body>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   <h1>404 - Not Found</h1>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:  </body>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: </html>
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Updating container reference prometheus in Image State - sha256:72f49afe1ed28fde061e1c62735b2be7a328af2ffa82cca1b1dfea7b81c98707
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Saving state! module="statemanager"
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Beginning Polling for updates
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Received connect to ACS message
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Invoking DiscoverPollEndpoint for 'arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41'
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Updating task's known status, task: prometheus:45 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96, TaskStatus: (RUNNING->RUNNING) Containers: [prometheus (RUNNING->RUNNING),]
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Container with earliest known container is [prometheus(856621972995.dkr.ecr.eu-central-1.amazonaws.com/prometheus:v1.1.1) (RUNNING->RUNNING)] for task: prometheus:45 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96, TaskStatus: (RUNNING->RUNNING) Containers: [prometheus (RUNNING->RUNNING),]
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Updating task: [prometheus:45 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96, TaskStatus: (RUNNING->RUNNING) Containers: [prometheus (RUNNING->RUNNING),]]
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: unable to create state change event for container [prometheus]: create container state change event api: status [RUNNING] already sent for container prometheus, task arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: unable to create task state change event []: create task state change event api: status [RUNNING] already sent
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: waiting for any previous stops to complete. Sequence number: 636
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: waiting for event for task
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: no longer waiting
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: wait over; ready to move towards status: RUNNING
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: task at steady state: RUNNING
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96]: waiting for event for task
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Initializing stats engine
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Event stream DeregisterContainerInstance start listening...
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Establishing a Websocket connection to https://ecs-a-1.eu-central-1.amazonaws.com/ws?agentHash=8b5e1863&agentVersion=1.24.0&clusterArn=default-tf-dev-cluster&containerInstanceArn=arn%3Aaws%3Aecs%3Aeu-central-1%3A155161382138%3Acontainer-instance%2Fdefault-tf-dev-cluster%2F3254d068e3a54de6ab8777e6d2fd9b41&dockerVersion=DockerVersion%3A+18.03.1-ce&sendCredentials=true&seqNum=1
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] NO_PROXY set:169.254.169.254,169.254.170.2,/var/run/weave/weave.sock
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list failed, container: 3bad4c66b5f1692765492a288460c49c8c6a54cd4189723c4102e587d00b8361, err: could not map container to task, ignoring container: 3bad4c66b5f1692765492a288460c49c8c6a54cd4189723c4102e587d00b8361: Could not map docker id to task: 3bad4c66b5f1692765492a288460c49c8c6a54cd4189723c4102e587d00b8361
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list, id: 3e360a3f4a222ef256c688ac8907209e0c63999e4ac0695eae2e724c1fb38ad5, task: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list failed, container: f4d83ff2fd7c289fc25ba96723dfc7d8afa8b72006855328b8296d844753fee2, err: could not map container to task, ignoring container: f4d83ff2fd7c289fc25ba96723dfc7d8afa8b72006855328b8296d844753fee2: Could not map docker id to task: f4d83ff2fd7c289fc25ba96723dfc7d8afa8b72006855328b8296d844753fee2
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list failed, container: da1d92c3fd075cb1c2cb226f24f3dc96c16a953f26f7dcefae4f50b5c8907d80, err: could not map container to task, ignoring container: da1d92c3fd075cb1c2cb226f24f3dc96c16a953f26f7dcefae4f50b5c8907d80: Could not map docker id to task: da1d92c3fd075cb1c2cb226f24f3dc96c16a953f26f7dcefae4f50b5c8907d80
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list failed, container: 1bb3022121e37babf5423613ea75197df32412eed810db751b769bd03bca39cb, err: could not map container to task, ignoring container: 1bb3022121e37babf5423613ea75197df32412eed810db751b769bd03bca39cb: Could not map docker id to task: 1bb3022121e37babf5423613ea75197df32412eed810db751b769bd03bca39cb
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list failed, container: 3090f0ee00653bb5b095794f4382d5cdb6d6cc065614f047abfcabd3f95fcaeb, err: could not map container to task, ignoring container: 3090f0ee00653bb5b095794f4382d5cdb6d6cc065614f047abfcabd3f95fcaeb: Could not map docker id to task: 3090f0ee00653bb5b095794f4382d5cdb6d6cc065614f047abfcabd3f95fcaeb
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list failed, container: 99d7f04745da48a63865e0d9e7467f5befe2dc9e44572d623506f9f7e60a16f7, err: could not map container to task, ignoring container: 99d7f04745da48a63865e0d9e7467f5befe2dc9e44572d623506f9f7e60a16f7: Could not map docker id to task: 99d7f04745da48a63865e0d9e7467f5befe2dc9e44572d623506f9f7e60a16f7
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Adding container to stats watch list failed, container: dedd7eb898fa317fe73cab3600d210fa7fa76d750d429eaafa7adceb247bbe3f, err: could not map container to task, ignoring container: dedd7eb898fa317fe73cab3600d210fa7fa76d750d429eaafa7adceb247bbe3f: Could not map docker id to task: dedd7eb898fa317fe73cab3600d210fa7fa76d750d429eaafa7adceb247bbe3f
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Establishing a Websocket connection to https://ecs-t-1.eu-central-1.amazonaws.com/ws?cluster=default-tf-dev-cluster&containerInstance=arn%3Aaws%3Aecs%3Aeu-central-1%3A155161382138%3Acontainer-instance%2Fdefault-tf-dev-cluster%2F3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Collecting stats for container 3e360a3f4a222ef256c688ac8907209e0c63999e4ac0695eae2e724c1fb38ad5
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Established a Websocket connection to https://ecs-a-1.eu-central-1.amazonaws.com/ws?agentHash=8b5e1863&agentVersion=1.24.0&clusterArn=default-tf-dev-cluster&containerInstanceArn=arn%3Aaws%3Aecs%3Aeu-central-1%3A155161382138%3Acontainer-instance%2Fdefault-tf-dev-cluster%2F3254d068e3a54de6ab8777e6d2fd9b41&dockerVersion=DockerVersion%3A+18.03.1-ce&sendCredentials=true&seqNum=1
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Connected to ACS endpoint
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] ACS client starting websocket poll loop
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Received message of type: IAMRoleCredentialsMessage
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] ACS activity occurred
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Acking credentials message: {
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   CredentialsId: "52f98cdf-4800-4ddb-98fb-3fcec86f6232",
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   Expiration: "2019-05-14T17:29:26Z",
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]:   MessageId: "82b9dbd9-58a2-49f9-8989-9a4aa6261922"
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: }
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Established a Websocket connection to https://ecs-t-1.eu-central-1.amazonaws.com/ws?cluster=default-tf-dev-cluster&containerInstance=arn%3Aaws%3Aecs%3Aeu-central-1%3A155161382138%3Acontainer-instance%2Fdefault-tf-dev-cluster%2F3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [INFO] Connected to TCS endpoint
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] TCS client starting websocket poll loop
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Stats not ready for container 3e360a3f4a222ef256c688ac8907209e0c63999e4ac0695eae2e724c1fb38ad5
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] Empty containerMetrics for task, ignoring, task: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96
May 14 11:29:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:26Z [DEBUG] No container health metrics to report
May 14 11:29:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:40Z 200 172.17.0.4:36478 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:29:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36478
May 14 11:29:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:40Z 200 172.17.0.4:36478 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:29:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:40Z 200 172.17.0.4:36478 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:29:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36478
May 14 11:29:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:46Z [DEBUG] No container health metrics to report
May 14 11:29:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:46Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:29:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:29:46Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:30:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:06Z [DEBUG] No container health metrics to report
May 14 11:30:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:06Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:30:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:06Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:30:21 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:21Z [DEBUG] Received message of type: HeartbeatMessage
May 14 11:30:21 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:21Z [DEBUG] ACS activity occurred
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Received message of type: PayloadMessage
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] ACS activity occurred
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Received payload message, message id: b2daa6c4-e174-47b9-88ca-bb5c6441bbaf
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (NONE->NONE),]]
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [INFO] Saving state! module="statemanager"
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Updating task's known status, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (NONE->RUNNING),]
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Container with earliest known container is [sleeper(alpine:latest) (NONE->RUNNING)] for task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (NONE->RUNNING),]
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (NONE->RUNNING),]]
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: unable to create state change event for container [sleeper]: create container state change event api: status not recognized by ECS: NONE
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: unable to create task state change event []: create task state change event api: status not recognized by ECS: NONE
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for any previous stops to complete. Sequence number: 637
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for event for task
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: no longer waiting
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: wait over; ready to move towards status: RUNNING
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: task not steady state or terminal; progressing it
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: progressing containers and resources in task
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for event for task
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: pulling container sleeper concurrently
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: attempting to obtain ImagePullDeleteLock to pull image - alpine:latest
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: Acquired ImagePullDeleteLock, start pulling image - alpine:latest
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: Recording timestamp for starting image pulltime: 2019-05-14 11:30:24.489235764 +0000 UTC m=+58.729692494
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] DockerGoClient: pulling image: alpine:latest
May 14 11:30:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:24Z [DEBUG] Acking payload message id: b2daa6c4-e174-47b9-88ca-bb5c6441bbaf
May 14 11:30:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:25Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Pulling from library/alpine
May 14 11:30:25 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:25Z [DEBUG] DockerGoClient: pull began for image: alpine:latest
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Pulling fs layer
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] No container health metrics to report
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Downloading
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Verifying Checksum
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Download complete
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Extracting
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Pull complete
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Digest: sha256:769fddc7cc2f0a1c35abb2f91432e8beecf83916c421420e6a6da9f8975464b6
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image alpine:latest, status Status: Downloaded newer image for alpine:latest
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: pulling image complete: alpine:latest
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Adding image name- alpine:latest to Image state- sha256:055936d3920576da37aa9bc460d70c5f212028bda1c08c0879aedf03d7a66ea1
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Updating container reference sleeper in Image State - sha256:055936d3920576da37aa9bc460d70c5f212028bda1c08c0879aedf03d7a66ea1
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Saving state! module="statemanager"
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: Finished pulling container alpine:latest in 2.311955263s
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: Released ImagePullDeleteLock after pulling image - alpine:latest
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: transitioned container [sleeper] to [PULLED]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: got container [sleeper] event: [PULLED]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: handling container change [{PULLED { <nil> [] <nil> [] map[] 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC {UNKNOWN <nil> 0 }} ContainerStatusChangeEvent}] for container [sleeper]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: sending container change event to tcs, container: [sleeper()], status: PULLED
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: unable to create state change event for container [sleeper]: create container state change event api: status not recognized by ECS: PULLED
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task's known status, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (PULLED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Container with earliest known container is [sleeper(alpine:latest) (PULLED->RUNNING)] for task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (PULLED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (PULLED->RUNNING),]]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: container change also resulted in task change [sleeper]: [RUNNING]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: received non-transition events
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task's known status, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (PULLED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Container with earliest known container is [sleeper(alpine:latest) (PULLED->RUNNING)] for task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (PULLED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (PULLED->RUNNING),]]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: task not steady state or terminal; progressing it
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: progressing containers and resources in task
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for event for task
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: creating container: sleeper
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Converting CPU shares to allowed minimum of 2 for task arn: [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca] and cpu shares: 0
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: created container name mapping for task:  sleeper -> ecs-Sleeper-1-sleeper-d0f5b796a593a1965000
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Saving state! module="statemanager"
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Event stream ContainerChange received events, broadcasting to listeners...
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Ignoring event for container, id: , status: 1
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] DockerGoClient: got event from docker daemon: &{create 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1 alpine:latest container create {9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1 map[com.amazonaws.ecs.task-definition-version:1 image:alpine:latest name:ecs-Sleeper-1-sleeper-d0f5b796a593a1965000 com.amazonaws.ecs.cluster:default-tf-dev-cluster com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca com.amazonaws.ecs.task-definition-family:Sleeper]} local 1557833426 1557833426862073754}
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Task engine: handling a docker event: Status: CREATED, DockerID: 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, health: UNKNOWN
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Task engine: event for container [9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1] not managed, unable to map container id to task
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: created docker container for task: sleeper -> 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: created docker container for task: sleeper -> 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, took 62.399003ms
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: transitioned container [sleeper] to [CREATED]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: got container [sleeper] event: [CREATED]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: handling container change [{CREATED {9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1 <nil> [] <nil> [] map[com.amazonaws.ecs.task-definition-family:Sleeper com.amazonaws.ecs.task-definition-version:1 com.amazonaws.ecs.cluster:default-tf-dev-cluster com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca] 2019-05-14 11:30:26.809965357 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC {UNKNOWN <nil> 0 }} ContainerStatusChangeEvent}] for container [sleeper]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: sending container change event to tcs, container: [sleeper(9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1)], status: CREATED
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: unable to create state change event for container [sleeper]: create container state change event api: status not recognized by ECS: CREATED
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task's known status, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (CREATED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Container with earliest known container is [sleeper(alpine:latest) (CREATED->RUNNING)] for task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (CREATED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task's known status to: CREATED, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (NONE->RUNNING) Containers: [sleeper (CREATED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (CREATED->RUNNING) Containers: [sleeper (CREATED->RUNNING),]]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: container change also resulted in task change [sleeper]: [RUNNING]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: unable to create task state change event []: create task state change event api: status not recognized by ECS: CREATED
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: container change also resulted in task change [sleeper]: [RUNNING]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: received non-transition events
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task's known status, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (CREATED->RUNNING) Containers: [sleeper (CREATED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Container with earliest known container is [sleeper(alpine:latest) (CREATED->RUNNING)] for task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (CREATED->RUNNING) Containers: [sleeper (CREATED->RUNNING),]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (CREATED->RUNNING) Containers: [sleeper (CREATED->RUNNING),]]
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: task not steady state or terminal; progressing it
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: progressing containers and resources in task
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for event for task
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: starting container: sleeper
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Event stream ContainerChange received events, broadcasting to listeners...
May 14 11:30:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:26Z [DEBUG] Ignoring event for container, id: 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, status: 2
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] DockerGoClient: got event from docker daemon: &{start 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1 alpine:latest container start {9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1 map[com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca com.amazonaws.ecs.task-definition-family:Sleeper com.amazonaws.ecs.task-definition-version:1 image:alpine:latest name:ecs-Sleeper-1-sleeper-d0f5b796a593a1965000 com.amazonaws.ecs.cluster:default-tf-dev-cluster]} local 1557833427 1557833427155486063}
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Task engine: handling a docker event: Status: RUNNING, DockerID: 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, health: UNKNOWN, Volumes: [{bind  /var/lib/ecs/data/metadata/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca/sleeper /opt/ecs/metadata/669aa757-63f5-4da3-86de-8205fa73333f   true rprivate} {bind  /var/lib/docker/volumes/b2268e52bd693d39f2f55ce676a145f201beb460526ef7297691f0fa8beaf5b8/_data /w  ro false rslave}], Labels: map[com.amazonaws.ecs.cluster:default-tf-dev-cluster com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca com.amazonaws.ecs.task-definition-family:Sleeper com.amazonaws.ecs.task-definition-version:1], CreatedAt: 2019-05-14 11:30:26.809965357 +0000 UTC, StartedAt: 2019-05-14 11:30:27.150290285 +0000 UTC
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: writing docker event to the task: Status: RUNNING, DockerID: 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, health: UNKNOWN, Volumes: [{bind  /var/lib/ecs/data/metadata/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca/sleeper /opt/ecs/metadata/669aa757-63f5-4da3-86de-8205fa73333f   true rprivate} {bind  /var/lib/docker/volumes/b2268e52bd693d39f2f55ce676a145f201beb460526ef7297691f0fa8beaf5b8/_data /w  ro false rslave}], Labels: map[com.amazonaws.ecs.task-definition-family:Sleeper com.amazonaws.ecs.task-definition-version:1 com.amazonaws.ecs.cluster:default-tf-dev-cluster com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca], CreatedAt: 2019-05-14 11:30:26.809965357 +0000 UTC, StartedAt: 2019-05-14 11:30:27.150290285 +0000 UTC
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: wrote docker event to the task: Status: RUNNING, DockerID: 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, health: UNKNOWN, Volumes: [{bind  /var/lib/ecs/data/metadata/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca/sleeper /opt/ecs/metadata/669aa757-63f5-4da3-86de-8205fa73333f   true rprivate} {bind  /var/lib/docker/volumes/b2268e52bd693d39f2f55ce676a145f201beb460526ef7297691f0fa8beaf5b8/_data /w  ro false rslave}], Labels: map[com.amazonaws.ecs.cluster:default-tf-dev-cluster com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca com.amazonaws.ecs.task-definition-family:Sleeper com.amazonaws.ecs.task-definition-version:1], CreatedAt: 2019-05-14 11:30:26.809965357 +0000 UTC, StartedAt: 2019-05-14 11:30:27.150290285 +0000 UTC
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: got container [sleeper] event: [RUNNING]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: handling container change [{RUNNING {9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1 <nil> [] <nil> [{bind  /var/lib/ecs/data/metadata/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca/sleeper /opt/ecs/metadata/669aa757-63f5-4da3-86de-8205fa73333f   true rprivate} {bind  /var/lib/docker/volumes/b2268e52bd693d39f2f55ce676a145f201beb460526ef7297691f0fa8beaf5b8/_data /w  ro false rslave}] map[com.amazonaws.ecs.cluster:default-tf-dev-cluster com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca com.amazonaws.ecs.task-definition-family:Sleeper com.amazonaws.ecs.task-definition-version:1] 2019-05-14 11:30:26.809965357 +0000 UTC 2019-05-14 11:30:27.150290285 +0000 UTC 0001-01-01 00:00:00 +0000 UTC {UNKNOWN <nil> 0 }} ContainerStatusChangeEvent}] for container [sleeper]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: sending container change event to tcs, container: [sleeper(9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1)], status: RUNNING
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: sending container change event [sleeper]: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca sleeper -> RUNNING, Known Sent: NONE
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: sent container change event [sleeper]: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca sleeper -> RUNNING, Known Sent: NONE
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Updating task's known status, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (CREATED->RUNNING) Containers: [sleeper (RUNNING->RUNNING),]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Container with earliest known container is [sleeper(alpine:latest) (RUNNING->RUNNING)] for task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (CREATED->RUNNING) Containers: [sleeper (RUNNING->RUNNING),]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Updating task's known status to: RUNNING, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (CREATED->RUNNING) Containers: [sleeper (RUNNING->RUNNING),]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (RUNNING->RUNNING) Containers: [sleeper (RUNNING->RUNNING),]]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: container change also resulted in task change [sleeper]: [RUNNING]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: sending task change event [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca -> RUNNING, Known Sent: NONE, PullStartedAt: 2019-05-14 11:30:24.489235764 +0000 UTC m=+58.729692494, PullStoppedAt: 2019-05-14 11:30:26.80122764 +0000 UTC m=+61.041684284, ExecutionStoppedAt: 0001-01-01 00:00:00 +0000 UTC]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] TaskHandler: batching container event: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca sleeper -> RUNNING, Known Sent: NONE
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] TaskHandler: collecting events for new task; event: TaskChange: [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca -> RUNNING, Known Sent: NONE, PullStartedAt: 2019-05-14 11:30:24.489235764 +0000 UTC m=+58.729692494, PullStoppedAt: 2019-05-14 11:30:26.80122764 +0000 UTC m=+61.041684284, ExecutionStoppedAt: 0001-01-01 00:00:00 +0000 UTC, arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca sleeper -> RUNNING, Known Sent: NONE] sent: false; events: Task event list [taskARN: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, sending: false, createdAt: 2019-05-14 11:30:27.168144415 +0000 UTC m=+61.408601208]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] TaskHandler: Adding event: TaskChange: [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca -> RUNNING, Known Sent: NONE, PullStartedAt: 2019-05-14 11:30:24.489235764 +0000 UTC m=+58.729692494, PullStoppedAt: 2019-05-14 11:30:26.80122764 +0000 UTC m=+61.041684284, ExecutionStoppedAt: 0001-01-01 00:00:00 +0000 UTC, arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca sleeper -> RUNNING, Known Sent: NONE] sent: false
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] TaskHandler: Waiting on semaphore to send events...
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] TaskHandler: Acquiring lock for sending event...
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] TaskHandler: Acquired lock, processing event list: : Task event list [taskARN: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, sending: true, createdAt: 2019-05-14 11:30:27.168144415 +0000 UTC m=+61.408601208]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] TaskHandler: Sending task change: TaskChange: [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca -> RUNNING, Known Sent: NONE, PullStartedAt: 2019-05-14 11:30:24.489235764 +0000 UTC m=+58.729692494, PullStoppedAt: 2019-05-14 11:30:26.80122764 +0000 UTC m=+61.041684284, ExecutionStoppedAt: 0001-01-01 00:00:00 +0000 UTC, arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca sleeper -> RUNNING, Known Sent: NONE] sent: false
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Event stream ContainerChange received events, broadcasting to listeners...
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Adding container to stats watch list, id: 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, task: arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Collecting stats for container 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: sent task change event [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca -> RUNNING, Known Sent: NONE, PullStartedAt: 2019-05-14 11:30:24.489235764 +0000 UTC m=+58.729692494, PullStoppedAt: 2019-05-14 11:30:26.80122764 +0000 UTC m=+61.041684284, ExecutionStoppedAt: 0001-01-01 00:00:00 +0000 UTC]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: container change also resulted in task change [sleeper]: [RUNNING]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: received non-transition events
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Updating task's known status, task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (RUNNING->RUNNING) Containers: [sleeper (RUNNING->RUNNING),]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Container with earliest known container is [sleeper(alpine:latest) (RUNNING->RUNNING)] for task: Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (RUNNING->RUNNING) Containers: [sleeper (RUNNING->RUNNING),]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (RUNNING->RUNNING) Containers: [sleeper (RUNNING->RUNNING),]]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: task at steady state: RUNNING
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for event for task
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] TaskHandler: Submitted task state change: TaskChange: [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca -> RUNNING, Known Sent: RUNNING, PullStartedAt: 2019-05-14 11:30:24.489235764 +0000 UTC m=+58.729692494, PullStoppedAt: 2019-05-14 11:30:26.80122764 +0000 UTC m=+61.041684284, ExecutionStoppedAt: 0001-01-01 00:00:00 +0000 UTC, arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca sleeper -> RUNNING, Known Sent: RUNNING] sent: true
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] TaskHandler: Removed the last element, no longer sending
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: started docker container for task: sleeper -> 9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1, took 439.530854ms
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: transitioned container [sleeper] to [RUNNING]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: got container [sleeper] event: [RUNNING]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: handling container change [{RUNNING {9a29c91210abc7bc806c5d5b4dde4304feeb11f59fbcc4cb9810b57a4e8b28a1 <nil> [] <nil> [] map[com.amazonaws.ecs.cluster:default-tf-dev-cluster com.amazonaws.ecs.container-name:sleeper com.amazonaws.ecs.task-arn:arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca com.amazonaws.ecs.task-definition-family:Sleeper com.amazonaws.ecs.task-definition-version:1] 2019-05-14 11:30:26.809965357 +0000 UTC 2019-05-14 11:30:27.150290285 +0000 UTC 0001-01-01 00:00:00 +0000 UTC {UNKNOWN <nil> 0 }} ContainerStatusChangeEvent}] for container [sleeper]
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: redundant container state change. sleeper to RUNNING, but already RUNNING
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [INFO] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: task at steady state: RUNNING
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for event for task
May 14 11:30:27 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:27Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: updated metadata file for container sleeper
May 14 11:30:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:34Z [INFO] Saving state! module="statemanager"
May 14 11:30:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36626
May 14 11:30:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:40Z 200 172.17.0.4:36626 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:30:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36626
May 14 11:30:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:40Z 200 172.17.0.4:36626 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:30:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:40Z 200 172.17.0.4:36626 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:30:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36626
May 14 11:30:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:46Z [DEBUG] No container health metrics to report
May 14 11:30:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:46Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:30:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:30:46Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:31:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:06Z [DEBUG] No container health metrics to report
May 14 11:31:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:06Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:31:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:06Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:31:19 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:19Z [DEBUG] Received message of type: HeartbeatMessage
May 14 11:31:19 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:19Z [DEBUG] ACS activity occurred
May 14 11:31:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:26Z [DEBUG] No container health metrics to report
May 14 11:31:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:26Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:31:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:26Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Received message of type: PayloadMessage
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] ACS activity occurred
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Received payload message, message id: 2cf4064a-b251-4a06-9309-a3f3e9b88fa7
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: putting update on the acs channel: [STOPPED] with seqnum [638]
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: update taken off the acs channel: [STOPPED] with seqnum [638]
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [INFO] Saving state! module="statemanager"
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: got acs event
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: new acs transition to: STOPPED; sequence number: 638; task stop sequence number: 0
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: task moving to stopped, adding to stopgroup with sequence number: 638
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Updating task: [Sleeper:1 arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca, TaskStatus: (RUNNING->STOPPED) Containers: [sleeper (RUNNING->RUNNING),]]
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: task not steady state or terminal; progressing it
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: progressing containers and resources in task
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Managed task [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: waiting for event for task
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [INFO] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: stopping container [sleeper]
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Acking payload message id: 2cf4064a-b251-4a06-9309-a3f3e9b88fa7
May 14 11:31:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36796
May 14 11:31:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:40Z 200 172.17.0.4:36796 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:31:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36796
May 14 11:31:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:40Z 200 172.17.0.4:36796 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:31:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:40Z 200 172.17.0.4:36796 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:31:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36796
May 14 11:31:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:46Z [DEBUG] No container health metrics to report
May 14 11:31:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:46Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:31:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:46Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:32:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:06Z [DEBUG] No container health metrics to report
May 14 11:32:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:06Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:32:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:06Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:32:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:26Z [DEBUG] No container health metrics to report
May 14 11:32:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:26Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:32:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:26Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:32:29 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:29Z [DEBUG] Received message of type: HeartbeatMessage
May 14 11:32:29 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:29Z [DEBUG] ACS activity occurred
May 14 11:32:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36920
May 14 11:32:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:40Z 200 172.17.0.4:36920 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:32:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36920
May 14 11:32:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:40Z 200 172.17.0.4:36920 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:32:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:36920
May 14 11:32:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:40Z 200 172.17.0.4:36920 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:32:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:46Z [DEBUG] No container health metrics to report
May 14 11:32:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:46Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:32:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:32:46Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:33:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:06Z [DEBUG] No container health metrics to report
May 14 11:33:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:06Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:33:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:06Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:33:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:24Z [DEBUG] Received message of type: HeartbeatMessage
May 14 11:33:24 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:24Z [DEBUG] ACS activity occurred
May 14 11:33:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:26Z [DEBUG] No container health metrics to report
May 14 11:33:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:26Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:33:26 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:26Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:33:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:37048
May 14 11:33:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:40Z 200 172.17.0.4:37048 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:33:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:37048
May 14 11:33:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:40Z 200 172.17.0.4:37048 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:33:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:40Z 200 172.17.0.4:37050 "/v2/credentials" "aws-sdk-go/1.5.1 (go1.10; linux; amd64)" arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/55b2d99162c54cfaa84e419a94121f96 GetCredentials 2 default-tf-dev-cluster arn:aws:ecs:eu-central-1:155161382138:container-instance/default-tf-dev-cluster/3254d068e3a54de6ab8777e6d2fd9b41
May 14 11:33:40 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:40Z [INFO] Handling http requestmethodGETfrom172.17.0.4:37050
May 14 11:33:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:46Z [DEBUG] No container health metrics to report
May 14 11:33:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:46Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:33:46 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:33:46Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:34:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:34:06Z [DEBUG] No container health metrics to report
May 14 11:34:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:34:06Z [DEBUG] Received message of type: AckPublishMetric
May 14 11:34:06 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:34:06Z [DEBUG] Received AckPublishMetric from tcs
May 14 11:34:19 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:34:19Z [DEBUG] Received message of type: HeartbeatMessage
May 14 11:34:19 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:34:19Z [DEBUG] ACS activity occurred
The task showed as stopped in ECS console, but I could see it still running on the ECS Instance.
pecigonzalo on 14 May 2019
Hi! Sorry for the late response. I did not see anything in the log you sent shown the agent update known status to stopped. From the current log, looks like the stop action is initiated by ECS backend side.
May 14 11:31:34 ip-10-10-1-180 ecs-agent[649]: 2019-05-14T11:31:34Z [DEBUG] Task engine [arn:aws:ecs:eu-central-1:155161382138:task/default-tf-dev-cluster/556380e3574c423eaf6b46161175d2ca]: putting update on the acs channel: [STOPPED] with seqnum [638]
For such cases, the task status on the backend side will be directly set to STOPPED without waiting for agent really stopping the container. That's our current design.
yumex93 on 16 Aug 2019
Hi! @pecigonzalo,
Sorry for the late response. Want to confirm when the task showed as stopped in ECS console, do you mean the stopped status is the last status or the desired status?
The logs provided above doesn’t give enough information for us to debug in a meaningful manner. When you can reproduce this error, could you please provide the debug level Agent log or (use https://docs.aws.amazon.com/AmazonECS/latest/developerguide/ecs-logs-collector.html) to cya AT amazon dot com to further assist you.
Thanks
cyastella on 8 Oct 2019
@cyastella You can test it youself, create a container that does not stop, stop a task on ECS while you also check docker ps in your instance, you will find that ECS shows the task as stopped, while the task is not truly stopped.
Probably this is the key:
For such cases, the task status on the backend side will be directly set to STOPPED without waiting for agent really stopping the container. That's our current design.
That design IMO is really bad, because it means I cant rely on ECS task status to know the state of a container/task.
We had the case where more containers than desired were running on our cluster, most likely because ECS believes the containers are already stopped.
pecigonzalo on 15 Oct 2019
yumex93 on 15 Oct 2019
👍2
Closing this issue since we haven't heard back, please feel free to reopen when you get the logs ready.
Thanks
cyastella on 21 Oct 2019
Was this page helpful?
0 / 5 - 0 ratings
Related issues

Logentries docker driver
AbelGuti · 5Comments
container stopped immediately when run with ECS Task but stays run with 'docker run'
YurgenUA · 3Comments
Service:AmazonECS, Code:ClientException, Message:Actual length: '34432'. Max allowed length is '32768' bytes., Class:com.amazonaws.services.ecs.model.ClientException
devotox · 3Comments
Refactor Agent logging
sparrc · 4Comments
ECS Agent 1.36.0 becomes unhealthy, resulting in tasks stuck in pending state
truppert-mdsol · 5Comments