Pre-created cluster is not found

[theirix]

Description

docker compose up fails with "ClusterNotFoundException: Cluster not found" when an ECS cluster is precreated.

Steps to reproduce the issue:

1. Precreate all needed resources (VPC, ALB, ECS Cluster). Check a simple terraform script.
2. Specify them in x-aws-* variables. Check a simple compose file.
3. Run docker compose --context myecs up -D

Describe the results you received:

Got the 'ClusterNotFoundException: Cluster not found.'

The output of docker compose --context myecs up -D:

DEBU[0000] CheckRequirements if cluster was already created: arn:aws:ecs:eu-west-1:909329722030:cluster/monty-ecs-cluster
DEBU[0000] CheckRequirements on VPC : vpc-025f5d47e9a5b8496
DEBU[0001] Retrieve SubNets
DEBU[0001] Check if LoadBalancer exists: arn:aws:elasticloadbalancing:eu-west-1:909329722030:loadbalancer/app/monty-alb/08b4001ded7d6e37
DEBU[0002] Create CloudFormation stack
DEBU[0002] Stack arn:aws:cloudformation:eu-west-1:909329722030:stack/monty-app/624d08a0-4755-11eb-901d-020629eef10b created
[+] Running 10/12
[+] Running 12/12            CreateInProgress User Initiated                                                                        57.4s
 ⠿ monty-app                 DeleteComplete                                                                                        209.8s
 ⠿ DefaultNetwork            DeleteComplete                                                                                        160.0s
 ⠿ WebTCP80TargetGroup       DeleteComplete                                                                                        161.0s
 ⠿ LogGroup                  DeleteComplete                                                                                         61.0s
 ⠿ WebTaskExecutionRole      DeleteComplete                                                                                        162.0s
 ⠿ CloudMap                  DeleteComplete                                                                                        205.0s
 ⠿ WebTCP80Listener          DeleteComplete                                                                                        157.0s
 ⠿ DefaultNetworkIngress     DeleteComplete                                                                                         53.0s
 ⠿ Default80Ingress          DeleteComplete                                                                                         53.0s
 ⠿ WebTaskDefinition         DeleteComplete                                                                                        142.0s
 ⠿ WebServiceDiscoveryEntry  DeleteComplete                                                                                        111.0s
 ⠿ WebService                DeleteComplete                                                                                        106.0s
ClusterNotFoundException: Cluster not found.

Additional facts:

1. Cluster definitely exists that can be verified by AWS GUI or aws --profile aroot --region eu-west-1 ecs list-clusters

2. If a cluster was not pre-created, compose up succeeds.

3. It does not matter if ECS cluster was created by TerraForm or by GUI

4. Applying CloudFormation script created by convert succeeds, cluster is created:

aws --profile ecsroot cloudformation deploy --template-file converted2.cf --stack-name my-new-stack --capabilities CAPABILITY_IAM

So that means that a failing check was performed in the compose cli. Did not try to launch compose cli after applying CloudFormation though.

Describe the results you expected:

Expected that the app is up.

Additional information you deem important (e.g. issue happens only occasionally):

Output of docker version:

Client: Docker Engine - Community
 Cloud integration: 1.0.4
 Version:           20.10.0
 API version:       1.41
 Go version:        go1.13.15
 Git commit:        7287ab3
 Built:             Tue Dec  8 18:55:43 2020
 OS/Arch:           darwin/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.0
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.13.15
  Git commit:       eeddea2
  Built:            Tue Dec  8 18:58:04 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.4.3
  GitCommit:        269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc:
  Version:          1.0.0-rc92
  GitCommit:        ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Output of docker context show:
You can also run docker context inspect context-name to give us more details but don't forget to remove sensitive content.

[
    {
        "Name": "myecs",
        "Metadata": {
            "Type": "ecs"
        },
        "Endpoints": {
            "docker": {
                "SkipTLSVerify": false
            },
            "ecs": {
                "Profile": "ecsroot",
                "Region": "eu-west-1"
            }
        },
        "TLSMaterial": {},
        "Storage": {
            "MetadataPath": "/Users/irix/.docker/contexts/meta/24835d5af7264331fc20359c2540af7e0f1ba2d94362379f4441258a5e71a631",
            "TLSPath": "/Users/irix/.docker/contexts/tls/24835d5af7264331fc20359c2540af7e0f1ba2d94362379f4441258a5e71a631"
        }
    }
]

Output of docker info:

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.4.2-docker)
  scan: Docker Scan (Docker Inc., v0.5.0)

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 77
 Server Version: 20.10.0
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc version: ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 init version: de40ad0
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 4.19.121-linuxkit
 Operating System: Docker Desktop
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 2.925GiB
 Name: docker-desktop
 ID: <REDACTED>
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 HTTP Proxy: gateway.docker.internal:3128
 HTTPS Proxy: gateway.docker.internal:3129
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false
 Product License: Community Engine

Additional environment details (AWS ECS, Azure ACI, local, etc.):

AWS profile is set up with all IAM permissions.

Resources are in eu-west-1.

AWS CLI version:
aws-cli/2.1.13 Python/3.9.1 Darwin/19.6.0 source/x86_64 prompt/off

[ndeloof]

Can you please check CloudFormation web UI when deploying with compose up to know which resource triggered this "ClusterNotFoundException: Cluster not found" error?
I can't see any reason it fails by compose up but not by applying the same template using aws CLI (we actually just invoke the cloudformation "apply" api)

Makes me wonder if you get the deployment to run in the expected eu-west-1 region by compose up - we should add this to debug logs

[theirix]

According to CF event log, the first error is in WebService resource - "Resource creation cancelled". It fails almost immediately. Again, deploying convert-ed template with the aws cloudformation succeeds in about five minutes (WebService creation is the longest process).

WebService have ARN with a correct region 'arn:aws:ecs:eu-west-1:909329722030:service/monty-ecs-cluster/ecs-bug-1084-WebService-IrVAGUPSOd3X', nothing suspicious.

Full logs:

2021-01-05 13:51:03 UTC+0300	ecs-bug-1084	DELETE_COMPLETE	-
2021-01-05 13:51:02 UTC+0300	CloudMap	DELETE_COMPLETE	-
2021-01-05 13:50:18 UTC+0300	WebTaskExecutionRole	DELETE_COMPLETE	-
2021-01-05 13:50:17 UTC+0300	WebTCP80TargetGroup	DELETE_COMPLETE	-
2021-01-05 13:50:17 UTC+0300	WebTaskExecutionRole	DELETE_IN_PROGRESS	-
2021-01-05 13:50:17 UTC+0300	WebTCP80TargetGroup	DELETE_IN_PROGRESS	-
2021-01-05 13:50:16 UTC+0300	CloudMap	DELETE_IN_PROGRESS	-
2021-01-05 13:50:16 UTC+0300	WebTaskDefinition	DELETE_COMPLETE	-
2021-01-05 13:50:16 UTC+0300	WebTCP80Listener	DELETE_COMPLETE	-
2021-01-05 13:50:15 UTC+0300	WebServiceDiscoveryEntry	DELETE_COMPLETE	-
2021-01-05 13:50:15 UTC+0300	DefaultNetwork	DELETE_COMPLETE	-
2021-01-05 13:50:14 UTC+0300	WebTCP80Listener	DELETE_IN_PROGRESS	-
2021-01-05 13:50:14 UTC+0300	WebTaskDefinition	DELETE_IN_PROGRESS	-
2021-01-05 13:50:14 UTC+0300	WebServiceDiscoveryEntry	DELETE_IN_PROGRESS	-
2021-01-05 13:50:14 UTC+0300	DefaultNetwork	DELETE_IN_PROGRESS	-
2021-01-05 13:50:14 UTC+0300	WebService	DELETE_COMPLETE	-
2021-01-05 13:48:37 UTC+0300	LogGroup	DELETE_COMPLETE	-
2021-01-05 13:48:36 UTC+0300	Default80Ingress	DELETE_COMPLETE	-
2021-01-05 13:48:36 UTC+0300	DefaultNetworkIngress	DELETE_COMPLETE	-
2021-01-05 13:48:36 UTC+0300	Default80Ingress	DELETE_IN_PROGRESS	-
2021-01-05 13:48:35 UTC+0300	WebService	DELETE_IN_PROGRESS	-
2021-01-05 13:48:35 UTC+0300	DefaultNetworkIngress	DELETE_IN_PROGRESS	-
2021-01-05 13:48:35 UTC+0300	LogGroup	DELETE_IN_PROGRESS	-
2021-01-05 13:48:20 UTC+0300	WebService	CREATE_FAILED	Resource creation cancelled
2021-01-05 13:48:19 UTC+0300	ecs-bug-1084	DELETE_IN_PROGRESS	User Initiated
2021-01-05 13:48:19 UTC+0300	WebService	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:48:16 UTC+0300	WebService	CREATE_IN_PROGRESS	-
2021-01-05 13:48:15 UTC+0300	WebServiceDiscoveryEntry	CREATE_COMPLETE	-
2021-01-05 13:48:14 UTC+0300	WebServiceDiscoveryEntry	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:48:12 UTC+0300	WebServiceDiscoveryEntry	CREATE_IN_PROGRESS	-
2021-01-05 13:48:10 UTC+0300	CloudMap	CREATE_COMPLETE	-
2021-01-05 13:47:44 UTC+0300	WebTaskDefinition	CREATE_COMPLETE	-
2021-01-05 13:47:44 UTC+0300	WebTaskDefinition	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:42 UTC+0300	WebTaskDefinition	CREATE_IN_PROGRESS	-
2021-01-05 13:47:40 UTC+0300	WebTaskExecutionRole	CREATE_COMPLETE	-
2021-01-05 13:47:31 UTC+0300	DefaultNetworkIngress	CREATE_COMPLETE	-
2021-01-05 13:47:31 UTC+0300	Default80Ingress	CREATE_COMPLETE	-
2021-01-05 13:47:31 UTC+0300	DefaultNetworkIngress	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:31 UTC+0300	Default80Ingress	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:30 UTC+0300	DefaultNetworkIngress	CREATE_IN_PROGRESS	-
2021-01-05 13:47:30 UTC+0300	Default80Ingress	CREATE_IN_PROGRESS	-
2021-01-05 13:47:29 UTC+0300	DefaultNetwork	CREATE_COMPLETE	-
2021-01-05 13:47:28 UTC+0300	WebTCP80Listener	CREATE_COMPLETE	-
2021-01-05 13:47:28 UTC+0300	DefaultNetwork	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:28 UTC+0300	WebTCP80Listener	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:26 UTC+0300	WebTCP80Listener	CREATE_IN_PROGRESS	-
2021-01-05 13:47:26 UTC+0300	LogGroup	CREATE_COMPLETE	-
2021-01-05 13:47:25 UTC+0300	CloudMap	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:25 UTC+0300	LogGroup	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:24 UTC+0300	WebTaskExecutionRole	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:24 UTC+0300	WebTCP80TargetGroup	CREATE_COMPLETE	-
2021-01-05 13:47:24 UTC+0300	WebTaskExecutionRole	CREATE_IN_PROGRESS	-
2021-01-05 13:47:24 UTC+0300	WebTCP80TargetGroup	CREATE_IN_PROGRESS	Resource creation Initiated
2021-01-05 13:47:23 UTC+0300	DefaultNetwork	CREATE_IN_PROGRESS	-
2021-01-05 13:47:23 UTC+0300	LogGroup	CREATE_IN_PROGRESS	-
2021-01-05 13:47:23 UTC+0300	CloudMap	CREATE_IN_PROGRESS	-
2021-01-05 13:47:23 UTC+0300	WebTCP80TargetGroup	CREATE_IN_PROGRESS	-
2021-01-05 13:47:19 UTC+0300	ecs-bug-1084	CREATE_IN_PROGRESS	User Initiated

[ndeloof]

Thanks for digging into this. Can you please confirm you checked CloudFormation deployment ran by compose up in the expected eu-west-1 region?

I hardly can imagine how aws cloudformation differs from go code invoking the exact same API with the exact same template, anyway devil is in the details ...

[ndeloof]

Please can you also check in the CloudFormation "model" UI that the uploaded template has the expected cluster ARN set for (failing) service?

[theirix]

Checked the UI. Template (Stack -> Template tab) contains the same CloudFormation definition as compose convert provides. When I run compose up, AWS made a call to eu-west-1 endpoints (I see it via Little Snitch), compose output points to it too. Stack -> Resources view shows effective ARNs in the correct region.

Maybe the problem is with setting up docker context. I tried with the following variants:

1. context created from a local AWS profile which has region in ~/.aws/config and ~/.aws/credentials
2. context created from a local AWS profile but manually redacted to add a Endpoints.ecs.Region value
3. context created from AWS key pair and region that was interactively selected
4. Tried exporting AWS_DEFAULT_REGION

All variants do not work. I think this bug can be related with #1056

[JackPriceBurns]

@ndeloof

I've also ran into this issue. I am also experiencing this weird discrepancy between CloudFormation and Docker compose. Taking the output from docker compose convert and running it directly in CloudFormation works fine.

The reason the stack fails to create using docker compose up is listed as "Resource creation cancelled" it looks like docker compose up is cancelling the CloudFormation stack creation before it can finish.

To further this CloudFormation says in the events section DELETE_IN_PROGRESS - User Initiated
Then after it's finished tearing down the CloudFormation docker compose spits out that very unhelpful ClusterNotFoundException: Cluster not found error.

The cluster is definitely there and this is not an issue with the generated CloudFormation template, is docker compose making a background request to check if the cluster exists while the CloudFormation is in the middle of running? (and this request subsequently fails for some reason)

I've tried running this with --debug enabled as well but nothing seems to show up during the stack creation phase.

AND to throw in some even more random stuff, when you run docker compose up -d it runs fine. I have no idea what difference -d is making in this scenario.

Hope this helps.

TL;DR the CloudFormation template is fine, docker compose is manually telling CloudFormation to cancel the stack midway through

[ndeloof]

compose up just invoke the cloudformation API to apply the converted cloudformation template, it does not query AWS API after this step.
I wonder deployment fails due to some timeout (we don't set one)?

Also, "ClusterNotFoundException" is an AWS API error (as demonstrated by the Java-style of this error), so it seems there's a race condition happening on AWS-side applying CloudFormation template, where some resource require the cluster to be up but this one is not yet set.

Can you please check the AWS web console and collect the list of Cloudformation events, so we know the first event to happend that would explain this deployment failure?

[JackPriceBurns]

Here is my output from the AWS cli, this is the most detailed logs that I can get. You can see at 2021-03-01T13:26:13.662000+00:00 there is a User Initiated stack delete and there is nothing else suspicious before then and definitely no mention of this ClusterNotFoundException which makes me think this is coming from a different API call happening somewhere I can't see.

But why does setting this as a deamon work? What difference does -d have in this?

https://pastebin.com/ebnNRHZC

[ndeloof]

running with -d we don't wath CloudFormation events to report deployment progress.
I wonder an error collecting those events will trigger context being canceled, and as a result the initial cloudformation "apply template" API call is also canceled.

[johan123312321]

@ndeloof

I've also ran into this issue.

[+] Running 8/10
[+] Running 10/10 CreateInProgress User Initiated 58.3s
⠿ dev-cluster DeleteComplete 166.0s
⠿ CloudMap DeleteComplete 161.0s
⠿ BackendTCP80TargetGroup DeleteComplete 116.0s
⠿ LogGroup DeleteComplete 117.0s
⠿ Default80Ingress DeleteComplete 59.0s
⠿ BackendTaskExecutionRole DeleteComplete 117.0s
⠿ BackendTCP80Listener DeleteComplete 113.0s
⠿ BackendTaskDefinition DeleteComplete 96.0s
⠿ BackendServiceDiscoveryEntry DeleteComplete 67.0s
⠿ BackendService DeleteComplete 61.0s
ClusterNotFoundException: Cluster not found.

Taking the output from docker compose convert and running it directly in CloudFormation works fine.

[tmeijn]

Also running into this now, would be nice if this could be solved

Running version 1.0.12 of the Compose CLI.

usecase: I want to run the ecs apps on FARGATE_SPOT to save money.