yahoo-eng-team team mailing list archive

Thread
Date
[Bug 2066207] [NEW] Polling VM details during VM creation results in the updated_at being later in the previous detail than the later one

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: "lijie.xie" <2066207@xxxxxxxxxxxxxxxxxx>
Date: Tue, 21 May 2024 03:23:03 -0000
Reply-to: Bug 2066207 <2066207@xxxxxxxxxxxxxxxxxx>
Sender: noreply@xxxxxxxxxxxxx
Public bug reported:

Description
===========
To simplify the issue, many details have been omitted here. We're observing the polling process for virtual machine details during their creation. Specifically, two consecutive query requests (request1 and request2) are sent, with corresponding responses being response1 and response2 respectively. In most cases, request1 returns response1 first, followed by request2 returning response2. However, sometimes request2 returns before request1. In such instances, it's possible that the updated_at timestamp in response2 is later than that in response1. This occurs because the show API utilizes timeutils.utcnow() to fill in updated_at when it has not been assigned.


Steps to reproduce
==================
1. Initiate the batch creation of 100 virtual machines by sending 100 POST requests to the create api
2. Continuously poll each VM's details using their unique identifiers, capturing the response data, especially focusing on the updated_at field.
3. Record the sequence of the poll requests and their corresponding response times.
4. Review the updated_at timestamps of each VM's response to identify instances where a later request has an updated_at timestamp that is earlier than an earlier request.
5. Validate these findings across multiple batches to ensure they are not isolated incidents.

Expected result
===============
The expected behavior is that the response for the earlier request should have an updated_at timestamp that precedes the updated_at of a later request's response.

Actual result
=============
 However, the actual observed behavior is that there is a chance that the updated_at timestamp in the response for an earlier request comes after the updated_at of the response for a subsequent request.

Environment
===========
OpenStack version: Wallaby
libvirt version: 6.0.0
QEMU version: 4.2.0

Logs & Configs
==============
request1:
[nova@node-2 /tmp]$ cat nova-api.log |grep req-3a8e3f23-617b-4354-af71-24588713bb47
2023-12-27 10:44:02.446 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
2023-12-27 10:44:02.447 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
2023-12-27 10:44:02.730 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
2023-12-27 10:44:02.731 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_mappings.created_at AS instance_mappings_created_at, instance_mappings.updated_at AS instance_mappings_updated_at, instance_mappings.id AS instance_mappings_id, instance_mappings.instance_uuid AS instance_mappings_instance_uuid, instance_mappings.cell_id AS instance_mappings_cell_id, instance_mappings.project_id AS instance_mappings_project_id, instance_mappings.user_id AS instance_mappings_user_id, instance_mappings.queued_for_delete AS instance_mappings_queued_for_delete, cell_mappings_1.created_at AS cell_mappings_1_created_at, cell_mappings_1.updated_at AS cell_mappings_1_updated_at, cell_mappings_1.id AS cell_mappings_1_id, cell_mappings_1.uuid AS cell_mappings_1_uuid, cell_mappings_1.name AS cell_mappings_1_name, cell_mappings_1.transport_url AS cell_mappings_1_transport_url, cell_mappings_1.database_connection AS cell_mappings_1_database_connection, cell_mappings_1.disabled AS cell_mappings_1_disabled 
2023-12-27 10:44:02.732 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'instance_uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
2023-12-27 10:44:02.809 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] ROLLBACK
2023-12-27 10:44:03.199 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
2023-12-27 10:44:03.201 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
2023-12-27 10:44:03.234 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
2023-12-27 10:44:03.266 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT anon_1.instances_created_at AS anon_1_instances_created_at, anon_1.instances_updated_at AS anon_1_instances_updated_at, anon_1.instances_deleted_at AS anon_1_instances_deleted_at, anon_1.instances_deleted AS anon_1_instances_deleted, anon_1.instances_id AS anon_1_instances_id, anon_1.instances_user_id AS anon_1_instances_user_id, anon_1.instances_project_id AS anon_1_instances_project_id, anon_1.instances_image_ref AS anon_1_instances_image_ref, anon_1.instances_kernel_id AS anon_1_instances_kernel_id, anon_1.instances_ramdisk_id AS anon_1_instances_ramdisk_id, anon_1.instances_hostname AS anon_1_instances_hostname, anon_1.instances_launch_index AS anon_1_instances_launch_index, anon_1.instances_key_name AS anon_1_instances_key_name, anon_1.instances_key_data AS anon_1_instances_key_data, anon_1.instances_power_state AS anon_1_instances_power_state, anon_1.instances_vm_state AS anon_1_instances_vm_state, anon_1.instances_task_state AS anon_1_instances_task_state, anon_1.instances_memory_mb AS anon_1_instances_memory_mb, anon_1.instances_vcpus AS anon_1_instances_vcpus, anon_1.instances_root_gb AS anon_1_instances_root_gb, anon_1.instances_ephemeral_gb AS anon_1_instances_ephemeral_gb, anon_1.instances_ephemeral_key_uuid AS anon_1_instances_ephemeral_key_uuid, anon_1.instances_host AS anon_1_instances_host, anon_1.instances_node AS anon_1_instances_node, anon_1.instances_instance_type_id AS anon_1_instances_instance_type_id, anon_1.instances_user_data AS anon_1_instances_user_data, anon_1.instances_reservation_id AS anon_1_instances_reservation_id, anon_1.instances_launched_at AS anon_1_instances_launched_at, anon_1.instances_terminated_at AS anon_1_instances_terminated_at, anon_1.instances_availability_zone AS anon_1_instances_availability_zone, anon_1.instances_display_name AS anon_1_instances_display_name, anon_1.instances_display_description AS anon_1_instances_display_description, anon_1.instances_launched_on AS anon_1_instances_launched_on, anon_1.instances_locked AS anon_1_instances_locked, anon_1.instances_locked_by AS anon_1_instances_locked_by, anon_1.instances_os_type AS anon_1_instances_os_type, anon_1.instances_architecture AS anon_1_instances_architecture, anon_1.instances_vm_mode AS anon_1_instances_vm_mode, anon_1.instances_uuid AS anon_1_instances_uuid, anon_1.instances_root_device_name AS anon_1_instances_root_device_name, anon_1.instances_default_ephemeral_device AS anon_1_instances_default_ephemeral_device, anon_1.instances_default_swap_device AS anon_1_instances_default_swap_device, anon_1.instances_config_drive AS anon_1_instances_config_drive, anon_1.instances_access_ip_v4 AS anon_1_instances_access_ip_v4, anon_1.instances_access_ip_v6 AS anon_1_instances_access_ip_v6, anon_1.instances_auto_disk_config AS anon_1_instances_auto_disk_config, anon_1.instances_progress AS anon_1_instances_progress, anon_1.instances_shutdown_terminate AS anon_1_instances_shutdown_terminate, anon_1.instances_disable_terminate AS anon_1_instances_disable_terminate, anon_1.instances_cell_name AS anon_1_instances_cell_name, anon_1.instances_cleaned AS anon_1_instances_cleaned, anon_1.instances_hidden AS anon_1_instances_hidden, instance_info_caches_1.created_at AS instance_info_caches_1_created_at, instance_info_caches_1.updated_at AS instance_info_caches_1_updated_at, instance_info_caches_1.deleted_at AS instance_info_caches_1_deleted_at, instance_info_caches_1.deleted AS instance_info_caches_1_deleted, instance_info_caches_1.id AS instance_info_caches_1_id, instance_info_caches_1.network_info AS instance_info_caches_1_network_info, instance_info_caches_1.instance_uuid AS instance_info_caches_1_instance_uuid, instance_extra_1.numa_topology AS instance_extra_1_numa_topology, instance_extra_1.flavor AS instance_extra_1_flavor, instance_extra_1.created_at AS instance_extra_1_created_at, instance_extra_1.updated_at AS instance_extra_1_updated_at, instance_extra_1.deleted_at AS instance_extra_1_deleted_at, instance_extra_1.deleted AS instance_extra_1_deleted, instance_extra_1.id AS instance_extra_1_id, instance_extra_1.instance_uuid AS instance_extra_1_instance_uuid, security_groups_1.created_at AS security_groups_1_created_at, security_groups_1.updated_at AS security_groups_1_updated_at, security_groups_1.deleted_at AS security_groups_1_deleted_at, security_groups_1.deleted AS security_groups_1_deleted, security_groups_1.id AS security_groups_1_id, security_groups_1.name AS security_groups_1_name, security_groups_1.description AS security_groups_1_description, security_groups_1.user_id AS security_groups_1_user_id, security_groups_1.project_id AS security_groups_1_project_id, security_group_rules_1.created_at AS security_group_rules_1_created_at, security_group_rules_1.updated_at AS security_group_rules_1_updated_at, security_group_rules_1.deleted_at AS security_group_rules_1_deleted_at, security_group_rules_1.deleted AS security_group_rules_1_deleted, security_group_rules_1.id AS security_group_rules_1_id, security_group_rules_1.parent_group_id AS security_group_rules_1_parent_group_id, security_group_rules_1.protocol AS security_group_rules_1_protocol, security_group_rules_1.from_port AS security_group_rules_1_from_port, security_group_rules_1.to_port AS security_group_rules_1_to_port, security_group_rules_1.cidr AS security_group_rules_1_cidr, security_group_rules_1.group_id AS security_group_rules_1_group_id, tags_1.resource_id AS tags_1_resource_id, tags_1.tag AS tags_1_tag 
2023-12-27 10:44:03.267 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1, 'deleted_2': 0, 'deleted_3': 0, 'deleted_4': 0, 'deleted_5': 0, 'deleted_6': 0}
2023-12-27 10:44:03.717 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_system_metadata.created_at AS instance_system_metadata_created_at, instance_system_metadata.updated_at AS instance_system_metadata_updated_at, instance_system_metadata.deleted_at AS instance_system_metadata_deleted_at, instance_system_metadata.deleted AS instance_system_metadata_deleted, instance_system_metadata.id AS instance_system_metadata_id, instance_system_metadata.`key` AS instance_system_metadata_key, instance_system_metadata.value AS instance_system_metadata_value, instance_system_metadata.instance_uuid AS instance_system_metadata_instance_uuid, anon_1.instances_uuid AS anon_1_instances_uuid 
2023-12-27 10:44:03.718 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
...
2023-12-27 10:44:04.501 811 INFO nova.osapi_compute.wsgi.server [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] 10.232.2.123 "GET /v2.1/d989deb76b694017ad7d12b165c21418/servers/7777e7c5-199a-4038-820e-2a1b4af73a36 HTTP/1.1" status: 200 len: 2095 time: 3.3989275

request2:
[nova@node-2 /tmp]$ cat nova-api.log |grep req-ce29c984-ba97-451f-b7f9-44b4db25f231
2023-12-27 10:44:03.653 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
2023-12-27 10:44:03.653 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
2023-12-27 10:44:03.669 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
2023-12-27 10:44:03.671 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_mappings.created_at AS instance_mappings_created_at, instance_mappings.updated_at AS instance_mappings_updated_at, instance_mappings.id AS instance_mappings_id, instance_mappings.instance_uuid AS instance_mappings_instance_uuid, instance_mappings.cell_id AS instance_mappings_cell_id, instance_mappings.project_id AS instance_mappings_project_id, instance_mappings.user_id AS instance_mappings_user_id, instance_mappings.queued_for_delete AS instance_mappings_queued_for_delete, cell_mappings_1.created_at AS cell_mappings_1_created_at, cell_mappings_1.updated_at AS cell_mappings_1_updated_at, cell_mappings_1.id AS cell_mappings_1_id, cell_mappings_1.uuid AS cell_mappings_1_uuid, cell_mappings_1.name AS cell_mappings_1_name, cell_mappings_1.transport_url AS cell_mappings_1_transport_url, cell_mappings_1.database_connection AS cell_mappings_1_database_connection, cell_mappings_1.disabled AS cell_mappings_1_disabled 
2023-12-27 10:44:03.671 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'instance_uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
2023-12-27 10:44:03.678 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] ROLLBACK
2023-12-27 10:44:03.699 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
2023-12-27 10:44:03.699 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
2023-12-27 10:44:03.717 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
2023-12-27 10:44:03.723 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT anon_1.instances_created_at AS anon_1_instances_created_at, anon_1.instances_updated_at AS anon_1_instances_updated_at, anon_1.instances_deleted_at AS anon_1_instances_deleted_at, anon_1.instances_deleted AS anon_1_instances_deleted, anon_1.instances_id AS anon_1_instances_id, anon_1.instances_user_id AS anon_1_instances_user_id, anon_1.instances_project_id AS anon_1_instances_project_id, anon_1.instances_image_ref AS anon_1_instances_image_ref, anon_1.instances_kernel_id AS anon_1_instances_kernel_id, anon_1.instances_ramdisk_id AS anon_1_instances_ramdisk_id, anon_1.instances_hostname AS anon_1_instances_hostname, anon_1.instances_launch_index AS anon_1_instances_launch_index, anon_1.instances_key_name AS anon_1_instances_key_name, anon_1.instances_key_data AS anon_1_instances_key_data, anon_1.instances_power_state AS anon_1_instances_power_state, anon_1.instances_vm_state AS anon_1_instances_vm_state, anon_1.instances_task_state AS anon_1_instances_task_state, anon_1.instances_memory_mb AS anon_1_instances_memory_mb, anon_1.instances_vcpus AS anon_1_instances_vcpus, anon_1.instances_root_gb AS anon_1_instances_root_gb, anon_1.instances_ephemeral_gb AS anon_1_instances_ephemeral_gb, anon_1.instances_ephemeral_key_uuid AS anon_1_instances_ephemeral_key_uuid, anon_1.instances_host AS anon_1_instances_host, anon_1.instances_node AS anon_1_instances_node, anon_1.instances_instance_type_id AS anon_1_instances_instance_type_id, anon_1.instances_user_data AS anon_1_instances_user_data, anon_1.instances_reservation_id AS anon_1_instances_reservation_id, anon_1.instances_launched_at AS anon_1_instances_launched_at, anon_1.instances_terminated_at AS anon_1_instances_terminated_at, anon_1.instances_availability_zone AS anon_1_instances_availability_zone, anon_1.instances_display_name AS anon_1_instances_display_name, anon_1.instances_display_description AS anon_1_instances_display_description, anon_1.instances_launched_on AS anon_1_instances_launched_on, anon_1.instances_locked AS anon_1_instances_locked, anon_1.instances_locked_by AS anon_1_instances_locked_by, anon_1.instances_os_type AS anon_1_instances_os_type, anon_1.instances_architecture AS anon_1_instances_architecture, anon_1.instances_vm_mode AS anon_1_instances_vm_mode, anon_1.instances_uuid AS anon_1_instances_uuid, anon_1.instances_root_device_name AS anon_1_instances_root_device_name, anon_1.instances_default_ephemeral_device AS anon_1_instances_default_ephemeral_device, anon_1.instances_default_swap_device AS anon_1_instances_default_swap_device, anon_1.instances_config_drive AS anon_1_instances_config_drive, anon_1.instances_access_ip_v4 AS anon_1_instances_access_ip_v4, anon_1.instances_access_ip_v6 AS anon_1_instances_access_ip_v6, anon_1.instances_auto_disk_config AS anon_1_instances_auto_disk_config, anon_1.instances_progress AS anon_1_instances_progress, anon_1.instances_shutdown_terminate AS anon_1_instances_shutdown_terminate, anon_1.instances_disable_terminate AS anon_1_instances_disable_terminate, anon_1.instances_cell_name AS anon_1_instances_cell_name, anon_1.instances_cleaned AS anon_1_instances_cleaned, anon_1.instances_hidden AS anon_1_instances_hidden, instance_info_caches_1.created_at AS instance_info_caches_1_created_at, instance_info_caches_1.updated_at AS instance_info_caches_1_updated_at, instance_info_caches_1.deleted_at AS instance_info_caches_1_deleted_at, instance_info_caches_1.deleted AS instance_info_caches_1_deleted, instance_info_caches_1.id AS instance_info_caches_1_id, instance_info_caches_1.network_info AS instance_info_caches_1_network_info, instance_info_caches_1.instance_uuid AS instance_info_caches_1_instance_uuid, instance_extra_1.numa_topology AS instance_extra_1_numa_topology, instance_extra_1.flavor AS instance_extra_1_flavor, instance_extra_1.created_at AS instance_extra_1_created_at, instance_extra_1.updated_at AS instance_extra_1_updated_at, instance_extra_1.deleted_at AS instance_extra_1_deleted_at, instance_extra_1.deleted AS instance_extra_1_deleted, instance_extra_1.id AS instance_extra_1_id, instance_extra_1.instance_uuid AS instance_extra_1_instance_uuid, security_groups_1.created_at AS security_groups_1_created_at, security_groups_1.updated_at AS security_groups_1_updated_at, security_groups_1.deleted_at AS security_groups_1_deleted_at, security_groups_1.deleted AS security_groups_1_deleted, security_groups_1.id AS security_groups_1_id, security_groups_1.name AS security_groups_1_name, security_groups_1.description AS security_groups_1_description, security_groups_1.user_id AS security_groups_1_user_id, security_groups_1.project_id AS security_groups_1_project_id, security_group_rules_1.created_at AS security_group_rules_1_created_at, security_group_rules_1.updated_at AS security_group_rules_1_updated_at, security_group_rules_1.deleted_at AS security_group_rules_1_deleted_at, security_group_rules_1.deleted AS security_group_rules_1_deleted, security_group_rules_1.id AS security_group_rules_1_id, security_group_rules_1.parent_group_id AS security_group_rules_1_parent_group_id, security_group_rules_1.protocol AS security_group_rules_1_protocol, security_group_rules_1.from_port AS security_group_rules_1_from_port, security_group_rules_1.to_port AS security_group_rules_1_to_port, security_group_rules_1.cidr AS security_group_rules_1_cidr, security_group_rules_1.group_id AS security_group_rules_1_group_id, tags_1.resource_id AS tags_1_resource_id, tags_1.tag AS tags_1_tag 
2023-12-27 10:44:03.724 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1, 'deleted_2': 0, 'deleted_3': 0, 'deleted_4': 0, 'deleted_5': 0, 'deleted_6': 0}
2023-12-27 10:44:03.785 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_system_metadata.created_at AS instance_system_metadata_created_at, instance_system_metadata.updated_at AS instance_system_metadata_updated_at, instance_system_metadata.deleted_at AS instance_system_metadata_deleted_at, instance_system_metadata.deleted AS instance_system_metadata_deleted, instance_system_metadata.id AS instance_system_metadata_id, instance_system_metadata.`key` AS instance_system_metadata_key, instance_system_metadata.value AS instance_system_metadata_value, instance_system_metadata.instance_uuid AS instance_system_metadata_instance_uuid, anon_1.instances_uuid AS anon_1_instances_uuid 
2023-12-27 10:44:03.786 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
2023-12-27 10:44:03.794 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_metadata.created_at AS instance_metadata_created_at, instance_metadata.updated_at AS instance_metadata_updated_at, instance_metadata.deleted_at AS instance_metadata_deleted_at, instance_metadata.deleted AS instance_metadata_deleted, instance_metadata.id AS instance_metadata_id, instance_metadata.`key` AS instance_metadata_key, instance_metadata.value AS instance_metadata_value, instance_metadata.instance_uuid AS instance_metadata_instance_uuid, anon_1.instances_uuid AS anon_1_instances_uuid 
...
2023-12-27 10:44:03.946 813 INFO nova.osapi_compute.wsgi.server [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] 10.232.2.123 "GET /v2.1/d989deb76b694017ad7d12b165c21418/servers/7777e7c5-199a-4038-820e-2a1b4af73a36 HTTP/1.1" status: 200 len: 4512 time: 0.3163798

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/2066207

Title:
  Polling VM details during VM creation results in the updated_at being
  later in the previous detail than the later one

Status in OpenStack Compute (nova):
  New

Bug description:
  Description
  ===========
  To simplify the issue, many details have been omitted here. We're observing the polling process for virtual machine details during their creation. Specifically, two consecutive query requests (request1 and request2) are sent, with corresponding responses being response1 and response2 respectively. In most cases, request1 returns response1 first, followed by request2 returning response2. However, sometimes request2 returns before request1. In such instances, it's possible that the updated_at timestamp in response2 is later than that in response1. This occurs because the show API utilizes timeutils.utcnow() to fill in updated_at when it has not been assigned.

  
  Steps to reproduce
  ==================
  1. Initiate the batch creation of 100 virtual machines by sending 100 POST requests to the create api
  2. Continuously poll each VM's details using their unique identifiers, capturing the response data, especially focusing on the updated_at field.
  3. Record the sequence of the poll requests and their corresponding response times.
  4. Review the updated_at timestamps of each VM's response to identify instances where a later request has an updated_at timestamp that is earlier than an earlier request.
  5. Validate these findings across multiple batches to ensure they are not isolated incidents.

  Expected result
  ===============
  The expected behavior is that the response for the earlier request should have an updated_at timestamp that precedes the updated_at of a later request's response.

  Actual result
  =============
   However, the actual observed behavior is that there is a chance that the updated_at timestamp in the response for an earlier request comes after the updated_at of the response for a subsequent request.

  Environment
  ===========
  OpenStack version: Wallaby
  libvirt version: 6.0.0
  QEMU version: 4.2.0

  Logs & Configs
  ==============
  request1:
  [nova@node-2 /tmp]$ cat nova-api.log |grep req-3a8e3f23-617b-4354-af71-24588713bb47
  2023-12-27 10:44:02.446 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
  2023-12-27 10:44:02.447 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
  2023-12-27 10:44:02.730 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
  2023-12-27 10:44:02.731 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_mappings.created_at AS instance_mappings_created_at, instance_mappings.updated_at AS instance_mappings_updated_at, instance_mappings.id AS instance_mappings_id, instance_mappings.instance_uuid AS instance_mappings_instance_uuid, instance_mappings.cell_id AS instance_mappings_cell_id, instance_mappings.project_id AS instance_mappings_project_id, instance_mappings.user_id AS instance_mappings_user_id, instance_mappings.queued_for_delete AS instance_mappings_queued_for_delete, cell_mappings_1.created_at AS cell_mappings_1_created_at, cell_mappings_1.updated_at AS cell_mappings_1_updated_at, cell_mappings_1.id AS cell_mappings_1_id, cell_mappings_1.uuid AS cell_mappings_1_uuid, cell_mappings_1.name AS cell_mappings_1_name, cell_mappings_1.transport_url AS cell_mappings_1_transport_url, cell_mappings_1.database_connection AS cell_mappings_1_database_connection, cell_mappings_1.disabled AS cell_mappings_1_disabled 
  2023-12-27 10:44:02.732 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'instance_uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
  2023-12-27 10:44:02.809 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] ROLLBACK
  2023-12-27 10:44:03.199 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
  2023-12-27 10:44:03.201 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
  2023-12-27 10:44:03.234 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
  2023-12-27 10:44:03.266 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT anon_1.instances_created_at AS anon_1_instances_created_at, anon_1.instances_updated_at AS anon_1_instances_updated_at, anon_1.instances_deleted_at AS anon_1_instances_deleted_at, anon_1.instances_deleted AS anon_1_instances_deleted, anon_1.instances_id AS anon_1_instances_id, anon_1.instances_user_id AS anon_1_instances_user_id, anon_1.instances_project_id AS anon_1_instances_project_id, anon_1.instances_image_ref AS anon_1_instances_image_ref, anon_1.instances_kernel_id AS anon_1_instances_kernel_id, anon_1.instances_ramdisk_id AS anon_1_instances_ramdisk_id, anon_1.instances_hostname AS anon_1_instances_hostname, anon_1.instances_launch_index AS anon_1_instances_launch_index, anon_1.instances_key_name AS anon_1_instances_key_name, anon_1.instances_key_data AS anon_1_instances_key_data, anon_1.instances_power_state AS anon_1_instances_power_state, anon_1.instances_vm_state AS anon_1_instances_vm_state, anon_1.instances_task_state AS anon_1_instances_task_state, anon_1.instances_memory_mb AS anon_1_instances_memory_mb, anon_1.instances_vcpus AS anon_1_instances_vcpus, anon_1.instances_root_gb AS anon_1_instances_root_gb, anon_1.instances_ephemeral_gb AS anon_1_instances_ephemeral_gb, anon_1.instances_ephemeral_key_uuid AS anon_1_instances_ephemeral_key_uuid, anon_1.instances_host AS anon_1_instances_host, anon_1.instances_node AS anon_1_instances_node, anon_1.instances_instance_type_id AS anon_1_instances_instance_type_id, anon_1.instances_user_data AS anon_1_instances_user_data, anon_1.instances_reservation_id AS anon_1_instances_reservation_id, anon_1.instances_launched_at AS anon_1_instances_launched_at, anon_1.instances_terminated_at AS anon_1_instances_terminated_at, anon_1.instances_availability_zone AS anon_1_instances_availability_zone, anon_1.instances_display_name AS anon_1_instances_display_name, anon_1.instances_display_description AS anon_1_instances_display_description, anon_1.instances_launched_on AS anon_1_instances_launched_on, anon_1.instances_locked AS anon_1_instances_locked, anon_1.instances_locked_by AS anon_1_instances_locked_by, anon_1.instances_os_type AS anon_1_instances_os_type, anon_1.instances_architecture AS anon_1_instances_architecture, anon_1.instances_vm_mode AS anon_1_instances_vm_mode, anon_1.instances_uuid AS anon_1_instances_uuid, anon_1.instances_root_device_name AS anon_1_instances_root_device_name, anon_1.instances_default_ephemeral_device AS anon_1_instances_default_ephemeral_device, anon_1.instances_default_swap_device AS anon_1_instances_default_swap_device, anon_1.instances_config_drive AS anon_1_instances_config_drive, anon_1.instances_access_ip_v4 AS anon_1_instances_access_ip_v4, anon_1.instances_access_ip_v6 AS anon_1_instances_access_ip_v6, anon_1.instances_auto_disk_config AS anon_1_instances_auto_disk_config, anon_1.instances_progress AS anon_1_instances_progress, anon_1.instances_shutdown_terminate AS anon_1_instances_shutdown_terminate, anon_1.instances_disable_terminate AS anon_1_instances_disable_terminate, anon_1.instances_cell_name AS anon_1_instances_cell_name, anon_1.instances_cleaned AS anon_1_instances_cleaned, anon_1.instances_hidden AS anon_1_instances_hidden, instance_info_caches_1.created_at AS instance_info_caches_1_created_at, instance_info_caches_1.updated_at AS instance_info_caches_1_updated_at, instance_info_caches_1.deleted_at AS instance_info_caches_1_deleted_at, instance_info_caches_1.deleted AS instance_info_caches_1_deleted, instance_info_caches_1.id AS instance_info_caches_1_id, instance_info_caches_1.network_info AS instance_info_caches_1_network_info, instance_info_caches_1.instance_uuid AS instance_info_caches_1_instance_uuid, instance_extra_1.numa_topology AS instance_extra_1_numa_topology, instance_extra_1.flavor AS instance_extra_1_flavor, instance_extra_1.created_at AS instance_extra_1_created_at, instance_extra_1.updated_at AS instance_extra_1_updated_at, instance_extra_1.deleted_at AS instance_extra_1_deleted_at, instance_extra_1.deleted AS instance_extra_1_deleted, instance_extra_1.id AS instance_extra_1_id, instance_extra_1.instance_uuid AS instance_extra_1_instance_uuid, security_groups_1.created_at AS security_groups_1_created_at, security_groups_1.updated_at AS security_groups_1_updated_at, security_groups_1.deleted_at AS security_groups_1_deleted_at, security_groups_1.deleted AS security_groups_1_deleted, security_groups_1.id AS security_groups_1_id, security_groups_1.name AS security_groups_1_name, security_groups_1.description AS security_groups_1_description, security_groups_1.user_id AS security_groups_1_user_id, security_groups_1.project_id AS security_groups_1_project_id, security_group_rules_1.created_at AS security_group_rules_1_created_at, security_group_rules_1.updated_at AS security_group_rules_1_updated_at, security_group_rules_1.deleted_at AS security_group_rules_1_deleted_at, security_group_rules_1.deleted AS security_group_rules_1_deleted, security_group_rules_1.id AS security_group_rules_1_id, security_group_rules_1.parent_group_id AS security_group_rules_1_parent_group_id, security_group_rules_1.protocol AS security_group_rules_1_protocol, security_group_rules_1.from_port AS security_group_rules_1_from_port, security_group_rules_1.to_port AS security_group_rules_1_to_port, security_group_rules_1.cidr AS security_group_rules_1_cidr, security_group_rules_1.group_id AS security_group_rules_1_group_id, tags_1.resource_id AS tags_1_resource_id, tags_1.tag AS tags_1_tag 
  2023-12-27 10:44:03.267 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1, 'deleted_2': 0, 'deleted_3': 0, 'deleted_4': 0, 'deleted_5': 0, 'deleted_6': 0}
  2023-12-27 10:44:03.717 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_system_metadata.created_at AS instance_system_metadata_created_at, instance_system_metadata.updated_at AS instance_system_metadata_updated_at, instance_system_metadata.deleted_at AS instance_system_metadata_deleted_at, instance_system_metadata.deleted AS instance_system_metadata_deleted, instance_system_metadata.id AS instance_system_metadata_id, instance_system_metadata.`key` AS instance_system_metadata_key, instance_system_metadata.value AS instance_system_metadata_value, instance_system_metadata.instance_uuid AS instance_system_metadata_instance_uuid, anon_1.instances_uuid AS anon_1_instances_uuid 
  2023-12-27 10:44:03.718 811 INFO sqlalchemy.engine.base.Engine [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
  ...
  2023-12-27 10:44:04.501 811 INFO nova.osapi_compute.wsgi.server [req-3a8e3f23-617b-4354-af71-24588713bb47 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] 10.232.2.123 "GET /v2.1/d989deb76b694017ad7d12b165c21418/servers/7777e7c5-199a-4038-820e-2a1b4af73a36 HTTP/1.1" status: 200 len: 2095 time: 3.3989275

  request2:
  [nova@node-2 /tmp]$ cat nova-api.log |grep req-ce29c984-ba97-451f-b7f9-44b4db25f231
  2023-12-27 10:44:03.653 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
  2023-12-27 10:44:03.653 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
  2023-12-27 10:44:03.669 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
  2023-12-27 10:44:03.671 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_mappings.created_at AS instance_mappings_created_at, instance_mappings.updated_at AS instance_mappings_updated_at, instance_mappings.id AS instance_mappings_id, instance_mappings.instance_uuid AS instance_mappings_instance_uuid, instance_mappings.cell_id AS instance_mappings_cell_id, instance_mappings.project_id AS instance_mappings_project_id, instance_mappings.user_id AS instance_mappings_user_id, instance_mappings.queued_for_delete AS instance_mappings_queued_for_delete, cell_mappings_1.created_at AS cell_mappings_1_created_at, cell_mappings_1.updated_at AS cell_mappings_1_updated_at, cell_mappings_1.id AS cell_mappings_1_id, cell_mappings_1.uuid AS cell_mappings_1_uuid, cell_mappings_1.name AS cell_mappings_1_name, cell_mappings_1.transport_url AS cell_mappings_1_transport_url, cell_mappings_1.database_connection AS cell_mappings_1_database_connection, cell_mappings_1.disabled AS cell_mappings_1_disabled 
  2023-12-27 10:44:03.671 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'instance_uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
  2023-12-27 10:44:03.678 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] ROLLBACK
  2023-12-27 10:44:03.699 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT 1
  2023-12-27 10:44:03.699 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {}
  2023-12-27 10:44:03.717 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] BEGIN (implicit)
  2023-12-27 10:44:03.723 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT anon_1.instances_created_at AS anon_1_instances_created_at, anon_1.instances_updated_at AS anon_1_instances_updated_at, anon_1.instances_deleted_at AS anon_1_instances_deleted_at, anon_1.instances_deleted AS anon_1_instances_deleted, anon_1.instances_id AS anon_1_instances_id, anon_1.instances_user_id AS anon_1_instances_user_id, anon_1.instances_project_id AS anon_1_instances_project_id, anon_1.instances_image_ref AS anon_1_instances_image_ref, anon_1.instances_kernel_id AS anon_1_instances_kernel_id, anon_1.instances_ramdisk_id AS anon_1_instances_ramdisk_id, anon_1.instances_hostname AS anon_1_instances_hostname, anon_1.instances_launch_index AS anon_1_instances_launch_index, anon_1.instances_key_name AS anon_1_instances_key_name, anon_1.instances_key_data AS anon_1_instances_key_data, anon_1.instances_power_state AS anon_1_instances_power_state, anon_1.instances_vm_state AS anon_1_instances_vm_state, anon_1.instances_task_state AS anon_1_instances_task_state, anon_1.instances_memory_mb AS anon_1_instances_memory_mb, anon_1.instances_vcpus AS anon_1_instances_vcpus, anon_1.instances_root_gb AS anon_1_instances_root_gb, anon_1.instances_ephemeral_gb AS anon_1_instances_ephemeral_gb, anon_1.instances_ephemeral_key_uuid AS anon_1_instances_ephemeral_key_uuid, anon_1.instances_host AS anon_1_instances_host, anon_1.instances_node AS anon_1_instances_node, anon_1.instances_instance_type_id AS anon_1_instances_instance_type_id, anon_1.instances_user_data AS anon_1_instances_user_data, anon_1.instances_reservation_id AS anon_1_instances_reservation_id, anon_1.instances_launched_at AS anon_1_instances_launched_at, anon_1.instances_terminated_at AS anon_1_instances_terminated_at, anon_1.instances_availability_zone AS anon_1_instances_availability_zone, anon_1.instances_display_name AS anon_1_instances_display_name, anon_1.instances_display_description AS anon_1_instances_display_description, anon_1.instances_launched_on AS anon_1_instances_launched_on, anon_1.instances_locked AS anon_1_instances_locked, anon_1.instances_locked_by AS anon_1_instances_locked_by, anon_1.instances_os_type AS anon_1_instances_os_type, anon_1.instances_architecture AS anon_1_instances_architecture, anon_1.instances_vm_mode AS anon_1_instances_vm_mode, anon_1.instances_uuid AS anon_1_instances_uuid, anon_1.instances_root_device_name AS anon_1_instances_root_device_name, anon_1.instances_default_ephemeral_device AS anon_1_instances_default_ephemeral_device, anon_1.instances_default_swap_device AS anon_1_instances_default_swap_device, anon_1.instances_config_drive AS anon_1_instances_config_drive, anon_1.instances_access_ip_v4 AS anon_1_instances_access_ip_v4, anon_1.instances_access_ip_v6 AS anon_1_instances_access_ip_v6, anon_1.instances_auto_disk_config AS anon_1_instances_auto_disk_config, anon_1.instances_progress AS anon_1_instances_progress, anon_1.instances_shutdown_terminate AS anon_1_instances_shutdown_terminate, anon_1.instances_disable_terminate AS anon_1_instances_disable_terminate, anon_1.instances_cell_name AS anon_1_instances_cell_name, anon_1.instances_cleaned AS anon_1_instances_cleaned, anon_1.instances_hidden AS anon_1_instances_hidden, instance_info_caches_1.created_at AS instance_info_caches_1_created_at, instance_info_caches_1.updated_at AS instance_info_caches_1_updated_at, instance_info_caches_1.deleted_at AS instance_info_caches_1_deleted_at, instance_info_caches_1.deleted AS instance_info_caches_1_deleted, instance_info_caches_1.id AS instance_info_caches_1_id, instance_info_caches_1.network_info AS instance_info_caches_1_network_info, instance_info_caches_1.instance_uuid AS instance_info_caches_1_instance_uuid, instance_extra_1.numa_topology AS instance_extra_1_numa_topology, instance_extra_1.flavor AS instance_extra_1_flavor, instance_extra_1.created_at AS instance_extra_1_created_at, instance_extra_1.updated_at AS instance_extra_1_updated_at, instance_extra_1.deleted_at AS instance_extra_1_deleted_at, instance_extra_1.deleted AS instance_extra_1_deleted, instance_extra_1.id AS instance_extra_1_id, instance_extra_1.instance_uuid AS instance_extra_1_instance_uuid, security_groups_1.created_at AS security_groups_1_created_at, security_groups_1.updated_at AS security_groups_1_updated_at, security_groups_1.deleted_at AS security_groups_1_deleted_at, security_groups_1.deleted AS security_groups_1_deleted, security_groups_1.id AS security_groups_1_id, security_groups_1.name AS security_groups_1_name, security_groups_1.description AS security_groups_1_description, security_groups_1.user_id AS security_groups_1_user_id, security_groups_1.project_id AS security_groups_1_project_id, security_group_rules_1.created_at AS security_group_rules_1_created_at, security_group_rules_1.updated_at AS security_group_rules_1_updated_at, security_group_rules_1.deleted_at AS security_group_rules_1_deleted_at, security_group_rules_1.deleted AS security_group_rules_1_deleted, security_group_rules_1.id AS security_group_rules_1_id, security_group_rules_1.parent_group_id AS security_group_rules_1_parent_group_id, security_group_rules_1.protocol AS security_group_rules_1_protocol, security_group_rules_1.from_port AS security_group_rules_1_from_port, security_group_rules_1.to_port AS security_group_rules_1_to_port, security_group_rules_1.cidr AS security_group_rules_1_cidr, security_group_rules_1.group_id AS security_group_rules_1_group_id, tags_1.resource_id AS tags_1_resource_id, tags_1.tag AS tags_1_tag 
  2023-12-27 10:44:03.724 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1, 'deleted_2': 0, 'deleted_3': 0, 'deleted_4': 0, 'deleted_5': 0, 'deleted_6': 0}
  2023-12-27 10:44:03.785 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_system_metadata.created_at AS instance_system_metadata_created_at, instance_system_metadata.updated_at AS instance_system_metadata_updated_at, instance_system_metadata.deleted_at AS instance_system_metadata_deleted_at, instance_system_metadata.deleted AS instance_system_metadata_deleted, instance_system_metadata.id AS instance_system_metadata_id, instance_system_metadata.`key` AS instance_system_metadata_key, instance_system_metadata.value AS instance_system_metadata_value, instance_system_metadata.instance_uuid AS instance_system_metadata_instance_uuid, anon_1.instances_uuid AS anon_1_instances_uuid 
  2023-12-27 10:44:03.786 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] {'deleted_1': 0, 'uuid_1': '7777e7c5-199a-4038-820e-2a1b4af73a36', 'param_1': 1}
  2023-12-27 10:44:03.794 813 INFO sqlalchemy.engine.base.Engine [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] SELECT instance_metadata.created_at AS instance_metadata_created_at, instance_metadata.updated_at AS instance_metadata_updated_at, instance_metadata.deleted_at AS instance_metadata_deleted_at, instance_metadata.deleted AS instance_metadata_deleted, instance_metadata.id AS instance_metadata_id, instance_metadata.`key` AS instance_metadata_key, instance_metadata.value AS instance_metadata_value, instance_metadata.instance_uuid AS instance_metadata_instance_uuid, anon_1.instances_uuid AS anon_1_instances_uuid 
  ...
  2023-12-27 10:44:03.946 813 INFO nova.osapi_compute.wsgi.server [req-ce29c984-ba97-451f-b7f9-44b4db25f231 2d61605b81f6416797107b61eec03765 d989deb76b694017ad7d12b165c21418 - default default] 10.232.2.123 "GET /v2.1/d989deb76b694017ad7d12b165c21418/servers/7777e7c5-199a-4038-820e-2a1b4af73a36 HTTP/1.1" status: 200 len: 4512 time: 0.3163798

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/2066207/+subscriptions
Follow ups

[Bug 2066207] Re: Polling VM details during VM creation results in the updated_at being later in the previous detail than the later one
From: sean mooney, 2024-05-21