ECS Execの有効化が原因でECSタスクがPROVISIONING状態から遷移しなくなった話
よくあるPENDING状態で固まるやつかと思ったらどハマリしてしまいました
CX事業本部@大阪の岩田です。
先日ある環境でECSのタスクがPROVISIONING状態のまま固まって(PENDINGではないのがポイントです！)起動できなくなるという問題が発生しました。※正確にいうとPROVISIONING状態で30分程度固まる→STOPPEDに遷移→新しいタスクがPROVISIONINGされ再度30分程度固まり...という状況です。
最初はNATゲートウェイ周りの設定漏れやECRのVPCエンドポイント設定漏れに起因したよくある問題かと思っていたのですが、色々調査しても一向に原因が分かりませんでした。最終的にECS Execの有効化が原因だったことが分かったので、同じ事象でハマる人が出ないように改めてブログにまとめてみました。
結論
先に結論ですがECS Execを有効化したECSサービスでAuto Scaling グループキャパシティープロバイダーを利用するとタスクが起動できなくなるようです。ドキュメントに記載されている以下の制限事項に抵触するためと思われます。
ECS Exec は現在、Auto Scaling グループのキャパシティープロバイダーを使用して起動されたタスクに対応していません。
環境など
問題が発生していた環境はざっくり以下のような環境でした
- ECS on EC2を利用
- ネットワークモードはdefault(bridge)
- 特にタスク配置戦略やタスク配置の制限は設定されていない
- ASG配下のEC2インスタンスが5台起動していて、クラスタ全体で見るとCPUやメモリは余裕がある状態
- 3つのECSサービスが存在する ※ECSサービスA~Cとします。
- これらのECSサービスは全て同一のコンテナイメージを利用する
事象
この環境下で、ある時点からECSサービスAのタスクが起動できなくなりました。ただし、この状態でもECSサービスB,Cに関してはタスク数を増やすと普通にタスクが起動できる状態です。状況を詳しく確認するとECSタスクがPROVISIONINGのまま一向に進まない状態です。
Stopped状態のタスクのログを確認しても何もログが出力されていません。
ECSサービスのイベントを見てもservice <サービス名> has started 1 tasks: task <タスクID>.というログが続くだけで、特にエラーログのようなものは出力されていませんでした。
AWSのナレッジセンターの記述を参考に1つ1つ原因候補を潰していきましたが、特に原因らしきものは見つかりませんでした。
Amazon ECS タスクが保留状態のまま止まっているのはなぜですか?
その後色々あってサービスAにECS Execを有効化する更新が入っていたことが判明したため、改めてECS Execの無効化を試行すると無事にタスクが起動できるようになりました。その後ECS Execに関するドキュメントを確認すると結論のセクションで記載した通りAuto Scaling グループキャパシティープロバイダーはECS Execに非対応という記述が見つかりました。
検証してみる
ECS Execの有効化が原因のようだと切り分けられたので、改めて検証してみます。
まず以下のCFnテンプレートを使ってECS関連のリソースをまとめてデプロイします。これはCloudFormationのドキュメント記載のAmazon Elastic Container Service テンプレートスニペット ほぼそのままです。ECS Execに対応した環境を利用したいので、AMI IDの部分だけ本日時点での最新版ami-0ed1560bb509908b1に変更しています。
AWSTemplateFormatVersion: 2010-09-09
Parameters:
KeyName:
Type: 'AWS::EC2::KeyPair::KeyName'
Description: Name of an existing EC2 KeyPair to enable SSH access to the ECS instances.
VpcId:
Type: 'AWS::EC2::VPC::Id'
Description: Select a VPC that allows instances to access the Internet.
SubnetId:
Type: 'List<AWS::EC2::Subnet::Id>'
Description: Select at least two subnets in your selected VPC.
DesiredCapacity:
Type: Number
Default: '1'
Description: Number of instances to launch in your ECS cluster.
MaxSize:
Type: Number
Default: '1'
Description: Maximum number of instances that can be launched in your ECS cluster.
InstanceType:
Description: EC2 instance type
Type: String
Default: t2.micro
AllowedValues:
- t2.micro
- t2.small
- t2.medium
- t2.large
- m3.medium
- m3.large
- m3.xlarge
- m3.2xlarge
- m4.large
- m4.xlarge
- m4.2xlarge
- m4.4xlarge
- m4.10xlarge
- c4.large
- c4.xlarge
- c4.2xlarge
- c4.4xlarge
- c4.8xlarge
- c3.large
- c3.xlarge
- c3.2xlarge
- c3.4xlarge
- c3.8xlarge
- r3.large
- r3.xlarge
- r3.2xlarge
- r3.4xlarge
- r3.8xlarge
- i2.xlarge
- i2.2xlarge
- i2.4xlarge
- i2.8xlarge
ConstraintDescription: Please choose a valid instance type.
Mappings:
AWSRegionToAMI:
us-east-1:
AMIID: ami-09bee01cc997a78a6
us-east-2:
AMIID: ami-0a9e12068cb98a01d
us-west-1:
AMIID: ami-0fa6c8d131a220017
us-west-2:
AMIID: ami-078c97cf1cefd1b38
eu-west-1:
AMIID: ami-0c9ef930279337028
eu-central-1:
AMIID: ami-065c1e34da68f2b02
ap-northeast-1:
AMIID: ami-0ed1560bb509908b1
#AMIID: ami-02265963d1614d04d
ap-southeast-1:
AMIID: ami-0b68661b29b9e058c
ap-southeast-2:
AMIID: ami-00e4b147599c13588
Resources:
ECSCluster:
Type: 'AWS::ECS::Cluster'
EcsSecurityGroup:
Type: 'AWS::EC2::SecurityGroup'
Properties:
GroupDescription: ECS Security Group
VpcId: !Ref VpcId
EcsSecurityGroupHTTPinbound:
Type: 'AWS::EC2::SecurityGroupIngress'
Properties:
GroupId: !Ref EcsSecurityGroup
IpProtocol: tcp
FromPort: 80
ToPort: 80
CidrIp: 0.0.0.0/0
EcsSecurityGroupSSHinbound:
Type: 'AWS::EC2::SecurityGroupIngress'
Properties:
GroupId: !Ref EcsSecurityGroup
IpProtocol: tcp
FromPort: 22
ToPort: 22
CidrIp: 0.0.0.0/0
EcsSecurityGroupALBports:
Type: 'AWS::EC2::SecurityGroupIngress'
Properties:
GroupId: !Ref EcsSecurityGroup
IpProtocol: tcp
FromPort: 31000
ToPort: 61000
SourceSecurityGroupId: !Ref EcsSecurityGroup
CloudwatchLogsGroup:
Type: 'AWS::Logs::LogGroup'
Properties:
LogGroupName: !Join
- '-'
- - ECSLogGroup
- !Ref 'AWS::StackName'
RetentionInDays: 14
taskdefinition:
Type: 'AWS::ECS::TaskDefinition'
Properties:
Family: !Join
- ''
- - !Ref 'AWS::StackName'
- '-ecs-demo-app'
ContainerDefinitions:
- Name: simple-app
Cpu: '10'
Essential: 'true'
Image: 'httpd:2.4'
Memory: '300'
LogConfiguration:
LogDriver: awslogs
Options:
awslogs-group: !Ref CloudwatchLogsGroup
awslogs-region: !Ref 'AWS::Region'
awslogs-stream-prefix: ecs-demo-app
MountPoints:
- ContainerPath: /usr/local/apache2/htdocs
SourceVolume: my-vol
PortMappings:
- ContainerPort: 80
- Name: busybox
Cpu: 10
Command:
- >-
/bin/sh -c "while true; do echo '>html< >head< >title<Amazon ECS
Sample App>/title< >style<body {margin-top: 40px;
background-color: #333;} >/style< >/head<>body< >div
style=color:white;text-align:center< >h1<Amazon ECS Sample
App>/h1< >h2<Congratulations!>/h2< >p<Your application is now
running on a container in Amazon ECS.>/p<' < top; /bin/date < date
; echo '>/div<>/body<>/html<' < bottom; cat top date bottom <
/usr/local/apache2/htdocs/index.html ; sleep 1; done"
EntryPoint:
- sh
- '-c'
Essential: false
Image: busybox
Memory: 200
LogConfiguration:
LogDriver: awslogs
Options:
awslogs-group: !Ref CloudwatchLogsGroup
awslogs-region: !Ref 'AWS::Region'
awslogs-stream-prefix: ecs-demo-app
VolumesFrom:
- SourceContainer: simple-app
Volumes:
- Name: my-vol
ECSALB:
Type: 'AWS::ElasticLoadBalancingV2::LoadBalancer'
Properties:
Name: ECSALB
Scheme: internet-facing
LoadBalancerAttributes:
- Key: idle_timeout.timeout_seconds
Value: '30'
Subnets: !Ref SubnetId
SecurityGroups:
- !Ref EcsSecurityGroup
ALBListener:
Type: 'AWS::ElasticLoadBalancingV2::Listener'
DependsOn: ECSServiceRole
Properties:
DefaultActions:
- Type: forward
TargetGroupArn: !Ref ECSTG
LoadBalancerArn: !Ref ECSALB
Port: '80'
Protocol: HTTP
ECSALBListenerRule:
Type: 'AWS::ElasticLoadBalancingV2::ListenerRule'
DependsOn: ALBListener
Properties:
Actions:
- Type: forward
TargetGroupArn: !Ref ECSTG
Conditions:
- Field: path-pattern
Values:
- /
ListenerArn: !Ref ALBListener
Priority: 1
ECSTG:
Type: 'AWS::ElasticLoadBalancingV2::TargetGroup'
DependsOn: ECSALB
Properties:
HealthCheckIntervalSeconds: 10
HealthCheckPath: /
HealthCheckProtocol: HTTP
HealthCheckTimeoutSeconds: 5
HealthyThresholdCount: 2
Name: ECSTG
Port: 80
Protocol: HTTP
UnhealthyThresholdCount: 2
VpcId: !Ref VpcId
ECSAutoScalingGroup:
Type: 'AWS::AutoScaling::AutoScalingGroup'
Properties:
VPCZoneIdentifier: !Ref SubnetId
LaunchConfigurationName: !Ref ContainerInstances
MinSize: '1'
MaxSize: !Ref MaxSize
DesiredCapacity: !Ref DesiredCapacity
CreationPolicy:
ResourceSignal:
Timeout: PT15M
UpdatePolicy:
AutoScalingReplacingUpdate:
WillReplace: 'true'
ContainerInstances:
Type: 'AWS::AutoScaling::LaunchConfiguration'
Properties:
ImageId: !FindInMap
- AWSRegionToAMI
- !Ref 'AWS::Region'
- AMIID
SecurityGroups:
- !Ref EcsSecurityGroup
InstanceType: !Ref InstanceType
IamInstanceProfile: !Ref EC2InstanceProfile
KeyName: !Ref KeyName
UserData: !Base64
'Fn::Join':
- ''
- - |
#!/bin/bash -xe
- echo ECS_CLUSTER=
- !Ref ECSCluster
- |2
>> /etc/ecs/ecs.config
- |
yum install -y aws-cfn-bootstrap
- '/opt/aws/bin/cfn-signal -e $? '
- ' --stack '
- !Ref 'AWS::StackName'
- ' --resource ECSAutoScalingGroup '
- ' --region '
- !Ref 'AWS::Region'
- |+
service:
Type: 'AWS::ECS::Service'
DependsOn: ALBListener
Properties:
Cluster: !Ref ECSCluster
DesiredCount: '1'
LoadBalancers:
- ContainerName: simple-app
ContainerPort: '80'
TargetGroupArn: !Ref ECSTG
Role: !Ref ECSServiceRole
TaskDefinition: !Ref taskdefinition
ECSServiceRole:
Type: 'AWS::IAM::Role'
Properties:
AssumeRolePolicyDocument:
Statement:
- Effect: Allow
Principal:
Service:
- ecs.amazonaws.com
Action:
- 'sts:AssumeRole'
Path: /
Policies:
- PolicyName: ecs-service
PolicyDocument:
Statement:
- Effect: Allow
Action:
- 'elasticloadbalancing:DeregisterInstancesFromLoadBalancer'
- 'elasticloadbalancing:DeregisterTargets'
- 'elasticloadbalancing:Describe*'
- 'elasticloadbalancing:RegisterInstancesWithLoadBalancer'
- 'elasticloadbalancing:RegisterTargets'
- 'ec2:Describe*'
- 'ec2:AuthorizeSecurityGroupIngress'
Resource: '*'
ServiceScalingTarget:
Type: 'AWS::ApplicationAutoScaling::ScalableTarget'
DependsOn: service
Properties:
MaxCapacity: 2
MinCapacity: 1
ResourceId: !Join
- ''
- - service/
- !Ref ECSCluster
- /
- !GetAtt
- service
- Name
RoleARN: !GetAtt
- AutoscalingRole
- Arn
ScalableDimension: 'ecs:service:DesiredCount'
ServiceNamespace: ecs
ServiceScalingPolicy:
Type: 'AWS::ApplicationAutoScaling::ScalingPolicy'
Properties:
PolicyName: AStepPolicy
PolicyType: StepScaling
ScalingTargetId: !Ref ServiceScalingTarget
StepScalingPolicyConfiguration:
AdjustmentType: PercentChangeInCapacity
Cooldown: 60
MetricAggregationType: Average
StepAdjustments:
- MetricIntervalLowerBound: 0
ScalingAdjustment: 200
ALB500sAlarmScaleUp:
Type: 'AWS::CloudWatch::Alarm'
Properties:
EvaluationPeriods: '1'
Statistic: Average
Threshold: '10'
AlarmDescription: Alarm if our ALB generates too many HTTP 500s.
Period: '60'
AlarmActions:
- !Ref ServiceScalingPolicy
Namespace: AWS/ApplicationELB
Dimensions:
- Name: LoadBalancer
Value: !GetAtt
- ECSALB
- LoadBalancerFullName
ComparisonOperator: GreaterThanThreshold
MetricName: HTTPCode_ELB_5XX_Count
EC2Role:
Type: 'AWS::IAM::Role'
Properties:
AssumeRolePolicyDocument:
Statement:
- Effect: Allow
Principal:
Service:
- ec2.amazonaws.com
Action:
- 'sts:AssumeRole'
Path: /
Policies:
- PolicyName: ecs-service
PolicyDocument:
Statement:
- Effect: Allow
Action:
- 'ecs:CreateCluster'
- 'ecs:DeregisterContainerInstance'
- 'ecs:DiscoverPollEndpoint'
- 'ecs:Poll'
- 'ecs:RegisterContainerInstance'
- 'ecs:StartTelemetrySession'
- 'ecs:Submit*'
- 'logs:CreateLogStream'
- 'logs:PutLogEvents'
Resource: '*'
AutoscalingRole:
Type: 'AWS::IAM::Role'
Properties:
AssumeRolePolicyDocument:
Statement:
- Effect: Allow
Principal:
Service:
- application-autoscaling.amazonaws.com
Action:
- 'sts:AssumeRole'
Path: /
Policies:
- PolicyName: service-autoscaling
PolicyDocument:
Statement:
- Effect: Allow
Action:
- 'application-autoscaling:*'
- 'cloudwatch:DescribeAlarms'
- 'cloudwatch:PutMetricAlarm'
- 'ecs:DescribeServices'
- 'ecs:UpdateService'
Resource: '*'
EC2InstanceProfile:
Type: 'AWS::IAM::InstanceProfile'
Properties:
Path: /
Roles:
- !Ref EC2Role
Outputs:
ecsservice:
Value: !Ref service
ecscluster:
Value: !Ref ECSCluster
ECSALB:
Description: Your ALB DNS URL
Value: !Join
- ''
- - !GetAtt
- ECSALB
- DNSName
taskdef:
Value: !Ref taskdefinition
このテンプレートでデプロイしたECSサービスはECS Execが有効化されていないため、AWS CLIからECS Execを有効化しておきます。
aws ecs update-service --cluster クラスタ名 --service サービス名 --enable-execute-command
この時点ではECSサービスの起動タイプはEC2に設定されています。
このままタスクの数を1にしてみましょう。
無事に起動できました。起動タイプ:EC2の状態であればECS Execが有効でもタスクが起動できることが確認できました。一旦タスクの数を0に戻しておきます。
今度は起動タイプ:EC2となっていたところをキャパシティープロバイダー戦略に切り替えてみましょう。キャパシィプロバイダーの定義を作成した後、サービスの設定を更新します。
設定が更新できたら再度タスクの数を1に更新します。すると...タスクがPROVISIONING状態の進まない事象が再現できました
各種ログを確認してみる
無事に？タスクが起動しない状態が再現できましたが、意図せずこの状況を引き起こした場合に気づく術はないのでしょうか？諸々のログを見ていきたいと思います。まずECSタスクとECSサービスのイベントからは前述の通り有用な情報が得られませんでした。
ECSエージェントのログはどうでしょうか？ログレベルをdebugに上げた状態でEC2インスタンスの/var/log/ecs/ecs-agent.logを確認してみます。
level=debug time=2022-10-19T11:43:39Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:43:39Z msg="Received message of type: AckPublishInstanceStatus" module=client.go level=debug time=2022-10-19T11:43:39Z msg="Received AckPublishInstanceStatus from tcs" module=handler.go level=debug time=2022-10-19T11:43:56Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:43:56Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:43:56Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:43:59Z msg="Skipping publishing container instance status message that was already sent" module=client.go level=debug time=2022-10-19T11:43:59Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:01Z msg="Received message of type: HeartbeatMessage" module=client.go level=debug time=2022-10-19T11:44:01Z msg="ACS activity occurred" module=acs_handler.go level=debug time=2022-10-19T11:44:01Z msg="instance healthcheck result: OK" module=doctor.go level=debug time=2022-10-19T11:44:02Z msg="Handling http requestmethodHEADfrom127.0.0.1:45496" module=logging_handler.go level=debug time=2022-10-19T11:44:16Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:44:16Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:44:16Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:44:19Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:19Z msg="Received message of type: AckPublishInstanceStatus" module=client.go level=debug time=2022-10-19T11:44:19Z msg="Received AckPublishInstanceStatus from tcs" module=handler.go level=debug time=2022-10-19T11:44:26Z msg="Received message of type: HeartbeatMessage" module=client.go level=debug time=2022-10-19T11:44:26Z msg="ACS activity occurred" module=acs_handler.go level=debug time=2022-10-19T11:44:26Z msg="instance healthcheck result: OK" module=doctor.go level=debug time=2022-10-19T11:44:32Z msg="Handling http requestmethodHEADfrom127.0.0.1:53362" module=logging_handler.go level=debug time=2022-10-19T11:44:36Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:44:36Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:44:36Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:44:39Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:39Z msg="Received message of type: AckPublishInstanceStatus" module=client.go level=debug time=2022-10-19T11:44:39Z msg="Received AckPublishInstanceStatus from tcs" module=handler.go level=debug time=2022-10-19T11:44:51Z msg="Received message of type: HeartbeatMessage" module=client.go level=debug time=2022-10-19T11:44:51Z msg="ACS activity occurred" module=acs_handler.go level=debug time=2022-10-19T11:44:51Z msg="instance healthcheck result: OK" module=doctor.go level=debug time=2022-10-19T11:44:56Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:44:56Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:44:56Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:44:59Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:59Z msg="Received message of type: AckPublishInstanceStatus" module=client.go ...略
特にエラーらしくログは出力されていません。
Event Bridgeに送信されるECSイベントから何か分かったりしないでしょうか？こちらのブログで紹介しているようなやり方でECSイベントをEvent Bridge経由でCW Logsに保管し、ログを確認してみました。
ECS タスクの停止理由を CloudWatch Logs に保管する方法を教えてください
以下のようなログが出力されていました。
{
"version": "0",
"id": "ac39557e-a880-4a00-cd3d-a6694581132b",
"detail-type": "ECS Task State Change",
"source": "aws.ecs",
"account": "<AWSアカウントID>",
"time": "2022-10-19T02:27:38Z",
"region": "ap-northeast-1",
"resources": [
"arn:aws:ecs:ap-northeast-1:<AWSアカウントID>:task/<クラスタ名>/428df540a5e2420a9c5b207ba465e1c9"
],
"detail": {
"attachments": [],
"capacityProviderName": "<キャパシティプロバイダー名>",
"clusterArn": "<ECSクラスタのARN>",
"containers": [],
"cpu": "20",
"createdAt": "2022-10-19T01:57:36.165Z",
"desiredStatus": "STOPPED",
"enableExecuteCommand": false,
"group": "service:<ECSサービス名>",
"launchType": "EC2",
"lastStatus": "STOPPED",
"memory": "500",
"overrides": {
"containerOverrides": []
},
"startedBy": "ecs-svc/7648301721650541975",
"stoppingAt": "2022-10-19T02:27:38.829Z",
"stoppedAt": "2022-10-19T02:27:38.829Z",
"stoppedReason": "Task failed to start",
"stopCode": "TaskFailedToStart",
"taskArn": "<ECSタスクのARN>",
"taskDefinitionArn": "<ECSタスク定義のARN>",
"updatedAt": "2022-10-19T02:27:38.829Z",
"version": 2
}
}
stoppedReasonに"Task failed to start"と出力されていますが、これ以上詳細な情報は分からなそうです。残念。
まとめ
ECSタスクがPENDING状態で固まるという状況は何度か経験しており、どうせ類似の事象だろうと高をくくっていたのですが、今回経験した事象はPROVISIONING状態で固まってしまうという事象でした。各種ログを見ても有用な情報は見当たりませんし、ECS Execの有効/無効はマネコンからは判断できないことから、トラブルシューティングとしてはなかなか難易度の高い事象だったのではないでしょうか。同様の事象でハマった方の参考になれば幸いです。
![[レポート] Optimize data processing with built-in AWS Step Functions featuresに参加しました #AWSreInvent #API207](https://images.ctfassets.net/ct0aopd36mqt/3IQLlbdUkRvu7Q2LupRW2o/edff8982184ea7cc2d5efa2ddd2915f5/reinvent-2024-sessionreport-jp.jpg)
