IoT/Greengrass Device Tester Docker Application Manager test always fails - claims cannot find container image

Hi,

I am running the IoT/Greengrass Device Tester (v2) on my device so I can submit to the Device Qualification Program.

I am using the latest device tester version (4.7.0), and Greengrass core 2.11.0 on my DUT (The IDT refuses to run against 2.11.1 or 2.11.2).

When I run the Docker Application Manager test, it always fails claiming the test container image was not downloaded. However, the Docker daemon logs show the container image has definitely been downloaded, and that the tester is failing to check properly.

Strangely, if I pull the container image manually before starting the test, the IDT correctly fails with an error stating the image is already on the device.

My device runs on Arm64 bit (Cortex-A53), but I have reproduced the issue against an x86-64 test system.

I have tried different distributions on the device (Debian, Ubuntu, SuSE) and different docker versions (the "supported" 20.10 and latest 24.0)

When I manually deploy the same DockerApplicationManager component that the device tester uses, the image download succeeds (see below).

All tests fail with the error below:

    dockerapplicationmanager:                   FAILED
----------------------------------
Failed Tests:
    Group Name: dockerapplicationmanager
        Test Name: docker_deploy_image_test
            Reason: Error response from daemon: No such image: public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1

However, the Docker daemon logs clearly show the image was downloaded:

dockerd[2033]: time="2023-08-18T07:05:24.684009212Z" level=debug msg="Calling POST /v1.42/images/create?fromImage=public.ecr.aws%2Faws-ec2%2Famazon-ec2-metadata-mock&tag=v1.10.1"
dockerd[2033]: time="2023-08-18T07:05:24.701911422Z" level=debug msg="hostDir: /etc/docker/certs.d/public.ecr.aws"
dockerd[2033]: time="2023-08-18T07:05:24.702745778Z" level=debug msg="Trying to pull public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock from https://public.ecr.aws"
dockerd[2038]: time="2023-08-18T07:05:26.730940814Z" level=debug msg="(*service).Write started" expected="sha256:477ad0249f5d3bcb0f3c79de3452fb1d5ad8ce48517651fa793b646815b69a2d" ref="index-sha256:477ad0249f5d3bcb0f3c79de3452fb1d5ad8ce48517651fa793b646815b69a2d" total=2021
dockerd[2033]: time="2023-08-18T07:05:26.747390942Z" level=debug msg="Fetching manifest from remote" digest="sha256:477ad0249f5d3bcb0f3c79de3452fb1d5ad8ce48517651fa793b646815b69a2d" error="<nil>" remote="public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1"
dockerd[2033]: time="2023-08-18T07:05:27.494352443Z" level=debug msg="Pulling ref from V2 registry: public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1"
dockerd[2033]: time="2023-08-18T07:05:27.494936364Z" level=debug msg="public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1 resolved to a manifestList object with 6 entries; looking for a unknown/arm64 match"
dockerd[2033]: time="2023-08-18T07:05:27.495245727Z" level=debug msg="found match for linux/arm64 with media type application/vnd.docker.distribution.manifest.v2+json, digest sha256:568fa355afd0e7cc56432ea0290c2ff4bf505ee84d541f9a892dbad6ed32349d"
dockerd[2033]: time="2023-08-18T07:05:27.495525166Z" level=debug msg="found match for linux/arm64 with media type application/vnd.docker.distribution.manifest.v2+json, digest sha256:314a02d937a6b2c0ccf452fb6b1ed6cfdb1907dff0d737b8c0641692946a12e1"
dockerd[2038]: time="2023-08-18T07:05:27.497363861Z" level=debug msg="(*service).Write started" expected="sha256:314a02d937a6b2c0ccf452fb6b1ed6cfdb1907dff0d737b8c0641692946a12e1" ref="manifest-sha256:314a02d937a6b2c0ccf452fb6b1ed6cfdb1907dff0d737b8c0641692946a12e1" total=737
dockerd[2033]: time="2023-08-18T07:05:27.512717557Z" level=debug msg="Fetching manifest from remote" digest="sha256:477ad0249f5d3bcb0f3c79de3452fb1d5ad8ce48517651fa793b646815b69a2d" error="<nil>" remote="public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1"
dockerd[2033]: time="2023-08-18T07:05:28.304134241Z" level=debug msg="pulling blob \"sha256:3400dcdd0866b290597b91935b5438da5ea333f5468fbc658db3f3292189a322\""
dockerd[2033]: time="2023-08-18T07:05:28.306349749Z" level=debug msg="pulling blob \"sha256:0f69e2e81409a5acfe044e012fc82577cd997deba1ff1b956ec7bcc041a423f9\""
dockerd[2033]: time="2023-08-18T07:05:29.178060162Z" level=debug msg="Downloaded 0f69e2e81409 to tempfile /var/lib/docker/tmp/GetImageBlob1602013696"
dockerd[2033]: time="2023-08-18T07:05:29.636499209Z" level=debug msg="Downloaded 3400dcdd0866 to tempfile /var/lib/docker/tmp/GetImageBlob178128522"
dockerd[2033]: time="2023-08-18T07:05:29.639434458Z" level=debug msg="Using /usr/bin/unpigz to decompress"
dockerd[2033]: time="2023-08-18T07:05:29.643245428Z" level=debug msg="Applying tar in /var/lib/docker/overlay2/b46bf4dc1d561531df58bf472ba37671459f9948fec8c6643c5e301f1c16d97a/diff" storage-driver=overlay2
dockerd[2033]: time="2023-08-18T07:05:30.397983890Z" level=debug msg="Applied tar sha256:fca2720b0071a3b2c55b4ca3220c0c0fbbc7c58cb43dfea211a2cc959a02a42d to b46bf4dc1d561531df58bf472ba37671459f9948fec8c6643c5e301f1c16d97a, size: 10975922"
dockerd[2033]: time="2023-08-18T07:05:30.419538368Z" level=debug msg="Using /usr/bin/unpigz to decompress"
dockerd[2033]: time="2023-08-18T07:05:30.423243163Z" level=debug msg="Applying tar in /var/lib/docker/overlay2/da261aab7e35fbdb0d12d5c2ba75b0d7beef824c735fd5cdf560e315dc4e800c/diff" storage-driver=overlay2
dockerd[2033]: time="2023-08-18T07:05:30.836353906Z" level=debug msg="Applied tar sha256:3c3918259274578fe979e10b0c36d05cadc1baeb64e11003d0947c70bfa8cf25 to da261aab7e35fbdb0d12d5c2ba75b0d7beef824c735fd5cdf560e315dc4e800c, size: 74381"
dockerd[2033]: time="2023-08-18T07:05:30.887721931Z" level=debug msg="Adding content digest to lease" digest="sha256:477ad0249f5d3bcb0f3c79de3452fb1d5ad8ce48517651fa793b646815b69a2d" lease="moby-image-sha256:277454ecbd2f1c7d2a4e49a15601254205a51a5616617c99c148f510c1106b2f" remote="public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1"
dockerd[2033]: time="2023-08-18T07:05:30.895655554Z" level=debug msg="Adding content digest to lease" digest="sha256:314a02d937a6b2c0ccf452fb6b1ed6cfdb1907dff0d737b8c0641692946a12e1" lease="moby-image-sha256:277454ecbd2f1c7d2a4e49a15601254205a51a5616617c99c148f510c1106b2f" remote="public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1"
dockerd[2038]: time="2023-08-18T07:05:31.485500520Z" level=debug msg="garbage collected" d=6.61152ms
dockerd[2033]: time="2023-08-18T07:06:14.171467900Z" level=debug msg="Calling HEAD /_ping"

If I register and deploy the very same component IDT is using for test (extracted from the IDT JAR), it works:

$ cat recipes/DockerHubAmazonContainer-1.0.0.yaml
---
RecipeFormatVersion: '2020-01-25'
ComponentName: DockerHubAmazonContainer
ComponentVersion: '1.0.0'
ComponentDependencies:
  aws.greengrass.DockerApplicationManager:
    VersionRequirement: ~2.0.0
Manifests:
  - Platform:
      os: all
    Artifacts:
      - URI: "docker:public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1"
# Check that the image does not already exist

$ docker images
REPOSITORY   TAG       IMAGE ID   CREATED   SIZE

$ localhost:~ # /opt/greengrass/v2/bin/greengrass-cli deployment create --recipeDir /root/testcomponent/recipes/ --artifactDir /root/testcomponent/artifacts/ --merge="DockerHubAmazonContainer=1.0.0"                                                                                                                                                                            [165/1849]
Local deployment submitted! Deployment Id: bdd2bed5-f3f5-44d0-a077-bc52672f2153

# A minute or two later

$ docker images
REPOSITORY                                        TAG       IMAGE ID       CREATED         SIZE
public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock   v1.10.1   277454ecbd2f   18 months ago   11.1MB

# Furthermore, if the DockerHubAmazonContainer component is removed, the container is deleted as part of the removal

$ /opt/greengrass/v2/bin/greengrass-cli deployment create --remove "DockerHubAmazonContainer"
Local deployment submitted! Deployment Id: 636b4a1d-5867-4816-9c4b-38d4bfec7d9c
#
localhost:~ # docker images
REPOSITORY   TAG       IMAGE ID   CREATED   SIZE

The IDT output leading immediately up to the failure is:

02:21:12.455 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] greengrass/features/docker.feature - Finished step: 'my device is registered as a Thing' with status PASSED
02:21:16.287 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] greengrass/features/docker.feature - Finished step: 'my device is running Greengrass' with status PASSED
02:21:16.548 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] greengrass/features/docker.feature - Finished step: 'the docker image public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1 does not exist on the device' with status PASSED
02:21:19.830 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Created S3Bucket in S3Lifecycle
02:21:21.200 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Created GreengrassComponent in GreengrassV2Lifecycle
02:21:21.201 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.component.RecipeComponentPreparationService - Created component DockerHubAmazonContainer:1.0.0-1a64f935eae78f294236 from /greengrass/component/recipes/DockerHubAmazonContainer.yaml
02:21:21.201 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] greengrass/features/docker.feature - Finished step: 'I create a Greengrass deployment with components' with status PASSED
02:21:21.717 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Created GreengrassDeployment in GreengrassV2Lifecycle
02:21:21.717 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.features.DeploymentSteps - Created Greengrass deployment: 7b58c1c0-e621-4e25-bbf6-5457b32089cb
02:21:21.718 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] greengrass/features/docker.feature - Finished step: 'I deploy the Greengrass deployment configuration' with status PASSED
02:21:59.991 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] greengrass/features/docker.feature - Finished step: 'the Greengrass deployment is COMPLETED on the device after 2 minutes' with status PASSED
02:22:00.247 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] greengrass/features/docker.feature - Finished step: 'I can check that the docker image public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1 exists on the device' with status PASSED
02:22:00.507 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.features.DeploymentSteps - Cleaning up component through an empty deployment
02:22:00.987 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Created GreengrassDeployment in GreengrassV2Lifecycle
02:22:30.209 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.features.DeploymentSteps - Cleaning up component through an empty deployment
02:22:30.767 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Created GreengrassDeployment in GreengrassV2Lifecycle
02:23:30.915 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [WARN] com.aws.greengrass.testing.features.DeploymentSteps - Empty deployment did not reach COMPLETED
02:23:30.921 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.DefaultGreengrass - Leaving Greengrass running on pid: 0
02:23:30.924 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.features.FileSteps - Stopping Greengrass service..
02:24:10.169 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.features.FileSteps - Starting Greengrass service..
02:24:10.940 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Removed GreengrassDeployment in GreengrassV2Lifecycle
02:24:11.313 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Removed GreengrassDeployment in GreengrassV2Lifecycle
02:24:11.617 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Removed GreengrassDeployment in GreengrassV2Lifecycle
02:24:11.989 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Removed GreengrassComponent in GreengrassV2Lifecycle
02:24:13.293 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.resources.AbstractAWSResourceLifecycle - Removed S3Bucket in S3Lifecycle
02:24:13.295 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.features.AWSResourcesSteps - Successfully removed externally created resources
02:24:13.781 [otf-1.0.0-SNAPSHOT] [docker] [idt-1a64f935eae78f294236] [INFO] com.aws.greengrass.testing.features.LoggerSteps - Clearing thread context on scenario: 'I can deploy Docker containers as Greengrass Components'
02:24:13.783 [] [docker] [idt-1a64f935eae78f294236] [ERROR] com.aws.greengrass.testing.launcher.reporting.StepTrackingReporting - Failed: 'I can deploy Docker containers as Greengrass Components': Error response from daemon: No such image: public.ecr.aws/aws-ec2/amazon-ec2-metadata-mock:v1.10.1

[ERROR] [2023-08-21 02:24:20]: Test exited unsuccessfully error=exit status 1 executionId=9b9bac3a-3fc5-11ee-9167-00155d50da35 testCaseId=docker_deploy_image_test
[INFO] [2023-08-21 02:24:20]: All tests finished. executionId=9b9bac3a-3fc5-11ee-9167-00155d50da35
[INFO] [2023-08-21 02:24:21]: 

========== Test Summary ==========
Execution Time: 	30m3s
Tests Completed: 	9
Tests Passed: 		8
Tests Failed: 		1
Tests Skipped: 		0
----------------------------------
Test Groups:
    pretestvalidation: 		PASSED
    coredependencies: 		PASSED
    version: 			PASSED
    lambdadeployment: 		PASSED
    component: 			PASSED
    mqtt: 			PASSED
Optional Test Groups:
    dockerapplicationmanagerdependencies: 	PASSED
    dockerapplicationmanager: 			FAILED