5-minute delay to seeing Windows instances as 'ready'

[ethanbergstrom]

Brief Description

There is an approximate 5-minute delay to the EC2 driver seeing Windows instances as 'ready'.

Version

kitchen-ec2 3.12.0, but this has been a problem the last couple years I've been using the driver

Environment

Launching Windows Server 2016 spot t3a.medium instances in us-west-2 via Kitchen for integration testing of Chef cookbooks.

Scenario

Rapid automated continuous integration testing of Chef cookbooks for Windows is slowed down significantly by an approximate 5-minute delay between when AWS reports an instance as 'ready' and when the EC2 Kitchen driver sees the instance as 'ready'.

Steps to Reproduce

1. Run 'kitchen test' with the EC2 driver to create pot t3a.medium instances in us-west-2.
2. Note that the EC2 driver always waits in excess of 5 minutes for the instance to become 'ready'
3. Compare the time the EC2 driver saw the instance as 'ready' against the time reported that the instance is 'ready' in the AWS console and note the significant delay.

Example below.

default-windows-2016.log - note the driver sees the instance as ready at 14:34:58 UTC / 8:34:58 CT.

I, [2022-01-29T08:28:14.250148 #85]  INFO -- default-windows-2016: EC2 instance <i-0b86b95f61049d62f> created.
I, [2022-01-29T08:28:14.250959 #85]  INFO -- default-windows-2016: Waited 0/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:28:29.517370 #85]  INFO -- default-windows-2016: Waited 15/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:28:45.150043 #85]  INFO -- default-windows-2016: Waited 30/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:29:01.164095 #85]  INFO -- default-windows-2016: Waited 45/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:29:17.254312 #85]  INFO -- default-windows-2016: Waited 60/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:29:38.204065 #85]  INFO -- default-windows-2016: Waited 75/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:29:54.165964 #85]  INFO -- default-windows-2016: Waited 90/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:30:10.074349 #85]  INFO -- default-windows-2016: Waited 105/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:30:25.983846 #85]  INFO -- default-windows-2016: Waited 120/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:30:42.273861 #85]  INFO -- default-windows-2016: Waited 135/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:30:58.137646 #85]  INFO -- default-windows-2016: Waited 150/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:31:14.050856 #85]  INFO -- default-windows-2016: Waited 165/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:31:29.956542 #85]  INFO -- default-windows-2016: Waited 180/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:31:45.879712 #85]  INFO -- default-windows-2016: Waited 195/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:32:01.858582 #85]  INFO -- default-windows-2016: Waited 210/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:32:17.832743 #85]  INFO -- default-windows-2016: Waited 225/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:32:33.752804 #85]  INFO -- default-windows-2016: Waited 240/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:32:49.644290 #85]  INFO -- default-windows-2016: Waited 255/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:33:05.527292 #85]  INFO -- default-windows-2016: Waited 270/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:33:21.417898 #85]  INFO -- default-windows-2016: Waited 285/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:33:37.274519 #85]  INFO -- default-windows-2016: Waited 300/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:33:53.278242 #85]  INFO -- default-windows-2016: Waited 315/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:34:09.394915 #85]  INFO -- default-windows-2016: Waited 330/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:34:25.431533 #85]  INFO -- default-windows-2016: Waited 345/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:34:41.382463 #85]  INFO -- default-windows-2016: Waited 360/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:34:57.303912 #85]  INFO -- default-windows-2016: Waited 375/600s for instance <i-0b86b95f61049d62f> to become ready.
I, [2022-01-29T08:34:58.058801 #85]  INFO -- default-windows-2016: Waited 0/600s for instance <i-0b86b95f61049d62f> to fetch windows admin password.
I, [2022-01-29T08:34:58.416838 #85]  INFO -- default-windows-2016: Retrieved Windows password for instance <i-0b86b95f61049d62f>.

AWS Console output - note the 'Ready to use' message is logged at 14:29:17 UTC / 8:29:17 CT, about 5 minutes earlier than the EC2 Kitchen driver sees it.

2022/01/29 14:29:01Z: Windows sysprep configuration complete.
2022/01/29 14:29:04Z: Message: Waiting for meta-data accessibility...
2022/01/29 14:29:04Z: Message: Meta-data is now available.
2022/01/29 14:29:05Z: AMI Origin Version: 2022.01.19
2022/01/29 14:29:05Z: AMI Origin Name: Windows_Server-2016-English-Full-Base
2022/01/29 14:29:05Z: OS: Microsoft Windows NT 10.0
2022/01/29 14:29:05Z: OsProductName: Windows Server 2016 Datacenter
2022/01/29 14:29:05Z: OsInstallOption: Full
2022/01/29 14:29:05Z: OsVersion: 10.0
2022/01/29 14:29:05Z: OsBuildLabEx: 14393.4889.amd64fre.rs1_release_inmarket.220114-1730
2022/01/29 14:29:05Z: OsCurrentBuild: 14393
2022/01/29 14:29:05Z: OsReleaseId: 1607
2022/01/29 14:29:05Z: Language: en-US
2022/01/29 14:29:05Z: TimeZone: Coordinated Universal Time
2022/01/29 14:29:05Z: Offset: UTC 00:00:00
2022/01/29 14:29:05Z: AMI-ID: ami-0eed6717967579276
2022/01/29 14:29:05Z: Instance-ID: i-0b86b95f61049d62f
2022/01/29 14:29:05Z: Instance Type: t3a.medium
2022/01/29 14:29:07Z: Driver: AWS NVMe Driver v1.4.0.13 
2022/01/29 14:29:07Z: Driver: AWS PV Driver Package v8.4.1 
2022/01/29 14:29:07Z: Driver: Amazon Elastic Network Adapter v2.2.4.0 
2022/01/29 14:29:07Z: Launch: EC2 Launch v1.3.2003411
2022/01/29 14:29:07Z: SSM: Amazon SSM Agent v3.1.338.0
2022/01/29 14:29:07Z: RDPCERTIFICATE-SUBJECTNAME: EC2AMAZ-SSM801F
2022/01/29 14:29:07Z: RDPCERTIFICATE-THUMBPRINT: 1DEA7AA219A8EDB2ECAD7C667EABF730947509E6
2022/01/29 14:29:14Z: HibernationEnabled: false
2022/01/29 14:29:17Z: Username: Administrator
2022/01/29 14:29:17Z: Password: <Password></Password>
2022/01/29 14:29:17Z: Message: Windows is Ready to use
2022/01/29 14:29:59Z: Amazon SSM Agent v3.1.338.0 is running
2022/01/29 14:29:59Z: OsProductName: Windows Server 2016 Datacenter
2022/01/29 14:29:59Z: OsInstallOption: Full
2022/01/29 14:29:59Z: OsVersion: 10.0
2022/01/29 14:29:59Z: OsBuildLabEx: 14393.4889.amd64fre.rs1_release_inmarket.220114-1730
2022/01/29 14:29:59Z: Driver: AWS PV Driver Package v8.4.1

Expected Result

The EC2 driver should, at most, see the instance as 'ready' a few seconds / within the next polling cycle of when the AWS console reports the instance as 'ready'.

Actual Result

The EC2 driver consistently sees the instance as 'ready' approximately 5 minutes after the AWS console reports the instance as 'ready'.

Additional Content

Example kitchen.yml:

driver:
  name: ec2
  # AWS SDK will try to use AWS_ACCESS_KEY_ID / AWS_SECRET_ACCESS_KEY environment variables first before falling back to config files
  shared_credentials_profile: <%= ENV['AWS_CLI_CREDENTIAL_PROFILE'] || 'personal' %>
  instance_type : <%= ENV['AWS_INSTANCE_TYPE'] || 't3a.medium' %>
  spot_price: <%= ENV['AWS_SPOT_BID'] || '0.04' %>
  # Tenant-specific information
  region: <%= ENV['AWS_REGION'] || 'us-west-2' %>
  subnet_id: <masked>
  # EC2 driver needs at least 360 seconds before it sees the instance is ready
  retryable_tries: 40
  retryable_sleep: 15

provisioner:
  name: chef_zero
  chef_license: accept
  product_name: chef
  product_version: 16.8.14

verifier:
  name: inspec
  reporter:
    - cli
    - junit:%{platform}_%{suite}_inspec.xml

platforms:
  - name: windows-2016

[ethanbergstrom]

I see the issue - EC2 waits about 5 minutes after the instance is up to even create the console.

Note how the console is completely blank at 9:32 CT:

Then at 9:33 CT, suddenly the console is populated, and has data going back from 5 minutes ago:

This seems more like an AWS problem, so I'll open a ticket with them as well.

[ethanbergstrom]

AWS's response:

While I understand the delay in console output can be inconvenient, the AWS documentation on instance console output does not specify any timing details for this process. I've linked the relevant documentation below for your convenience, should you wish to reference it:

https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/instance-console.html#instance-console-console-output

Depending on the instance type and Windows OS version, and whether it is the first launch or subsequent launch of the instance, the instance OS will send the console output to the EC2 console at differing times, and will not immediately populate at instance launch. This is the behavior that you've noticed, as while the console output may appear on the Windows console, the OS may not send it to the EC2 console right away.

You can launch two or three similar instance types with the same configuration if you'd like to figure out the average time it takes for the console output to populate for that instance type.

As an added note, EC2 instances launched from custom AMI's can potentially take an even longer time for the console output to populate.

[jakauppila]

@ethanbergstrom If you have the chance I'd be curious to have you try out the changes in #582