Skip to content

[Test] Fix race condition in test_build_image caused by export-image-logs and facilitate troubleshooting #7487

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
gmarciani merged 1 commit into from
Jul 15, 2026
+64 −27
Merged

[Test] Fix race condition in test_build_image caused by export-image-logs and facilitate troubleshooting #7487

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 6 additions & 2 deletions tests/integration-tests/tests/common/assertions.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -291,7 +291,9 @@ def assert_instance_has_desired_imds_v2_setting(instance, status):

logging.info(f"Instance {instance_id}{instance_name_part} has IMDSv2 {imds_v2_status}")

assert_that(imds_v2_status).is_equal_to(status)
assert_that(imds_v2_status).described_as(
f"IMDSv2 HttpTokens setting of instance {instance_id}{instance_name_part}"
).is_equal_to(status)


def assert_instance_has_desired_tags(instance, tags: List[dict]):
Expand All @@ -303,7 +305,9 @@ def assert_instance_has_desired_tags(instance, tags: List[dict]):
logging.info(f"Instance {instance_id}{instance_name_part} has tags {instance_tags}")

for tag in tags:
assert_that(instance_tags).contains(tag)
assert_that(instance_tags).described_as(
f"tags of instance {instance_id}{instance_name_part} should contain {tag}"
).contains(tag)


def assert_aws_identity_access_is_correct(cluster, users_allow_list, remote_command_executor=None):
Expand Down
83 changes: 58 additions & 25 deletions tests/integration-tests/tests/createami/test_createami.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -192,17 +192,19 @@ def test_build_image(
)

with soft_assertions():
# Validate export-image-logs as early as possible: as soon as the build log stream is
# available the image is still BUILD_IN_PROGRESS, so the build-image stack (which
# self-deletes only at BUILD_COMPLETE) is guaranteed to still exist.
_wait_for_image_log_stream(image)
_test_export_logs(s3_bucket_factory, image, region)
_test_export_logs(s3_bucket_factory, image, region, True)

_wait_for_build_instance(image, region)
_test_build_instances_tags(image, image.config["Build"]["Tags"], region)
_test_build_imds_settings(image, "required", region)

# Export logs during BUILD_IN_PROGRESS: on a successful build the stack self-deletes at
# BUILD_COMPLETE and that teardown removes the CloudWatch log group (ImageBuilder.delete calls
# delete_log_group), so the log can be exported reliably only while the stack still exists.
# Wait for a non-empty build log stream first, since the export produces the cloudwatch-logs
# entry only once the stream has ingested events.
_wait_for_image_log_stream(image)
_test_export_logs(s3_bucket_factory, image, region)
_test_export_logs(s3_bucket_factory, image, region, True)

_test_build_image_success(image, request.config.getoption("output_dir"))
_test_image_tag_and_volume(image)
_test_list_image_log_streams(image)
Expand All @@ -212,6 +214,8 @@ def test_build_image(
_test_cluster_creation(
image.ec2_image_id, pcluster_config_reader, region, clusters_factory, scheduler_commands_factory
)

# On a successful build the stack self-deletes; assert that the deletion completed.
_assert_build_image_stack_deleted(image.image_id, region, 900, 30)


Expand Down Expand Up @@ -293,13 +297,19 @@ def test_kernel4_build_image_run_cluster(
def _test_list_images(image):
images = image.list_images(region=image.region, image_status="AVAILABLE")["images"]
matches = [img for img in images if img["imageId"] == image.image_id]
assert_that(matches).is_length(1)
assert_that(matches[0]["imageId"]).is_equal_to(image.image_id)
assert_that(matches[0]["region"]).is_equal_to(image.region)
assert_that(matches).described_as(
f"list-images (status=AVAILABLE) should return exactly one image with id {image.image_id}"
).is_length(1)
assert_that(matches[0]["imageId"]).described_as("list-images returned image id").is_equal_to(image.image_id)
assert_that(matches[0]["region"]).described_as("list-images returned image region").is_equal_to(image.region)
image.describe()
assert_that(matches[0]["ec2AmiInfo"]["amiId"]).is_equal_to(image.ec2_image_id)
assert_that(matches[0]["imageBuildStatus"]).is_equal_to("BUILD_COMPLETE")
assert_that(matches[0]).contains("version")
assert_that(matches[0]["ec2AmiInfo"]["amiId"]).described_as("list-images returned EC2 AMI id").is_equal_to(
image.ec2_image_id
)
assert_that(matches[0]["imageBuildStatus"]).described_as("list-images returned image build status").is_equal_to(
"BUILD_COMPLETE"
)
assert_that(matches[0]).described_as("list-images entry should contain a 'version' field").contains("version")


def _test_image_stack_events(image):
Expand All @@ -323,7 +333,9 @@ def _test_list_image_log_streams(image):

stream_names = {stream["logStreamName"] for stream in streams}
expected_log_stream = f"{get_installed_parallelcluster_base_version()}/1"
assert_that(stream_names).contains(expected_log_stream)
assert_that(stream_names).described_as(
f"list-image-log-streams should contain the build log stream {expected_log_stream}"
).contains(expected_log_stream)


def _test_get_image_log_events(image):
Expand Down Expand Up @@ -355,13 +367,19 @@ def _test_get_image_log_events(image):
events = image.get_log_events(log_stream_name, **args)["events"]

if expect_count is not None:
assert_that(events).is_length(expect_count)
assert_that(events).described_as(
f"get-image-log-events with args {args} should return {expect_count} event(s)"
).is_length(expect_count)

if expect_first is True:
assert_that(events[0]["message"]).contains(first_event["message"])
assert_that(events[0]["message"]).described_as(
f"get-image-log-events with args {args} should return the first log event"
).contains(first_event["message"])

if expect_first is False:
assert_that(events[0]["message"]).does_not_contain(first_event["message"])
assert_that(events[0]["message"]).described_as(
f"get-image-log-events with args {args} should not return the first log event"
).does_not_contain(first_event["message"])


def _set_s3_bucket_policy(bucket_name, partition, region):
Expand Down Expand Up @@ -438,13 +456,17 @@ def _test_image_tag_and_volume(image):
logging.info(f"Image List: {image_list}, length {len(image_list)}")
if not image_list:
raise ImageNotFound()
assert_that(len(image_list)).is_equal_to(1)
assert_that(len(image_list)).described_as(
f"exactly one EC2 image should be tagged with parallelcluster:image_id={image.image_id}"
).is_equal_to(1)

if len(image_list) > 0:
created_image = image_list[0]
volume_size = created_image.get("BlockDeviceMappings")[0].get("Ebs").get("VolumeSize")
assert_that(volume_size).is_equal_to(200)
assert_that(created_image["Tags"]).contains({"Key": "dummyImageTag", "Value": "dummyImageTag"})
assert_that(volume_size).described_as("root volume size of the built image").is_equal_to(200)
assert_that(created_image["Tags"]).described_as(
"built image tags should contain the configured dummyImageTag"
).contains({"Key": "dummyImageTag", "Value": "dummyImageTag"})


@pytest.fixture()
Expand Down Expand Up @@ -581,19 +603,28 @@ def _wait_for_build_instance(image, region):


@retry(
retry_on_result=lambda log_stream_available: not log_stream_available,
retry_on_result=lambda log_stream_ready: not log_stream_ready,
wait_fixed=seconds(20),
stop_max_delay=minutes(10),
)
def _wait_for_image_log_stream(image):
"""Wait until the image build log stream is available in CloudWatch."""
"""Wait until the image build log stream exists in CloudWatch and contains at least one event.

export-image-logs produces the cloudwatch-logs entry only if the build log stream both exists and
has ingested events: create-export-task writes objects only for streams that have data in the
window. Waiting for a non-empty stream (rather than mere existence) is what removes the export
race caused by CloudWatch eventual consistency.
"""
expected_log_stream = f"{get_installed_parallelcluster_base_version()}/1"
try:
stream_names = {stream["logStreamName"] for stream in image.list_log_streams()["logStreams"]}
if expected_log_stream not in stream_names:
return False
events = image.get_log_events(expected_log_stream, limit=1)["events"]
except Exception as e: # noqa: BLE001 # log group/stream not created yet
logging.info("Image %s log streams not available yet: %s", image.image_id, e)
logging.info("Image %s build log stream not ready yet: %s", image.image_id, e)
return False
return expected_log_stream in stream_names
return len(events) > 0


def _test_build_imds_settings(image, status, region):
Expand Down Expand Up @@ -645,7 +676,9 @@ def _test_build_image_success(image, output_dir):
if image.image_status != "BUILD_COMPLETE":
_export_image_logs(image, output_dir)
_keep_recent_logs(image)
assert_that(image.image_status).is_equal_to("BUILD_COMPLETE")
assert_that(image.image_status).described_as(f"final build status of image {image.image_id}").is_equal_to(
"BUILD_COMPLETE"
)


@pytest.mark.usefixtures("os")
Expand Down
Loading