[lnie@fedora server]$ bash run.sh +++ dirname 0 ++ readlink -f . + '[' /home/lnie/artemis/server '!=' /home/lnie/artemis/server ']' + trap 'kill $(jobs -p)' EXIT ++ pwd + export ARTEMIS_CONFIG_DIR=/home/lnie/artemis/server/configuration + ARTEMIS_CONFIG_DIR=/home/lnie/artemis/server/configuration + '[' -f /home/lnie/artemis/server/configuration/.vault_pass ']' ++ cat /home/lnie/artemis/server/configuration/.vault_pass + export ARTEMIS_VAULT_PASSWORD=checkcheck + ARTEMIS_VAULT_PASSWORD=checkcheck + export 'ARTEMIS_BROKER_URL=amqp://guest:guest@127.0.0.1:5672/?heartbeat=60&blocked_connection_timeout=60' + ARTEMIS_BROKER_URL='amqp://guest:guest@127.0.0.1:5672/?heartbeat=60&blocked_connection_timeout=60' + export ARTEMIS_DB_URL=postgresql://artemis:artemis@127.0.0.1:5432/artemis + ARTEMIS_DB_URL=postgresql://artemis:artemis@127.0.0.1:5432/artemis + export ARTEMIS_CACHE_URL=redis://127.0.0.1:6379 + ARTEMIS_CACHE_URL=redis://127.0.0.1:6379 + export ARTEMIS_LOG_JSON=no + ARTEMIS_LOG_JSON=no + export ARTEMIS_LOG_DB_POOL=no + ARTEMIS_LOG_DB_POOL=no + export ARTEMIS_LOG_DB_QUERIES=no + ARTEMIS_LOG_DB_QUERIES=no + export ARTEMIS_CLOSE_AFTER_DISPATCH=yes + ARTEMIS_CLOSE_AFTER_DISPATCH=yes ++ pwd + export ARTEMIS_HOOK_ROUTE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_ROUTE.py + ARTEMIS_HOOK_ROUTE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_ROUTE.py + export ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE.py + ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE.py + export ARTEMIS_HOOK_OPENSTACK_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_OPENSTACK_ENVIRONMENT_TO_IMAGE.py + ARTEMIS_HOOK_OPENSTACK_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_OPENSTACK_ENVIRONMENT_TO_IMAGE.py + export ARTEMIS_HOOK_AWS_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_AWS_ENVIRONMENT_TO_IMAGE.py + ARTEMIS_HOOK_AWS_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_AWS_ENVIRONMENT_TO_IMAGE.py + export ARTEMIS_HOOK_AZURE_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_AZURE_ENVIRONMENT_TO_IMAGE.py + ARTEMIS_HOOK_AZURE_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_AZURE_ENVIRONMENT_TO_IMAGE.py + export ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE.py + ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE=/home/lnie/artemis/server/configuration/ARTEMIS_HOOK_BEAKER_ENVIRONMENT_TO_IMAGE.py + export ARTEMIS_AWS_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-aws.yaml + ARTEMIS_AWS_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-aws.yaml + export ARTEMIS_AZURE_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-azure.yaml + ARTEMIS_AZURE_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-azure.yaml + export ARTEMIS_BEAKER_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-beaker.yaml + ARTEMIS_BEAKER_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-beaker.yaml + export ARTEMIS_OPENSTACK_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-openstack.yaml + ARTEMIS_OPENSTACK_ENVIRONMENT_TO_IMAGE_MAPPING_FILEPATH=ARTEMIS_CONFIG_DIR/artemis-image-map-openstack.yaml + ARTEMIS_WORKER_OPTIONS= + '[' '' = '' ']' + poetry run alembic upgrade head INFO [alembic.runtime.migration] Context impl PostgresqlImpl. INFO [alembic.runtime.migration] Will assume transactional DDL. + poetry run artemis-db-init-content config-to-db [23:44:49] [+] connecting to db postgresql://artemis:artemis@127.0.0.1:5432/artemis [23:44:49] [+] sqlalchemy create_engine parameters: { "application_name": null, "echo_pool": false, "max_overflow": 10, "pool_size": 20 } [23:44:49] [+] Adding system-level guest tags [23:44:49] [+] Adding ProvisionedBy=Artemis [23:44:50] [+] Adding Owner=lnie [23:44:50] [+] Adding pool-level guest tags for pool beaker [23:44:50] [+] Adding pool-level guest tags for pool openstack [23:44:50] [+] Adding priority groups [23:44:50] [+] Adding priority group "default-priority" [23:44:50] [+] Adding pools [23:44:50] [+] Adding pool "beaker" [23:44:50] [+] Adding pool "openstack" [23:44:50] [+] Adding user "admin" with role "ADMIN" [23:44:50] [+] Adding user "artemis" with role "USER" [23:44:50] [+] Adding user "lnie" with role "USER" [23:44:50] [+] Adding SSH key "fedora-cloud", owner by lnie [23:44:50] [+] Adding SSH key "master-key", owner by artemis + '[' '' '!=' '' ']' + poetry run artemis-api-server + poetry run artemis-dispatcher + sleep 100000 + poetry run artemis-scheduler + poetry run artemis-worker [23:44:54] [+] scheduling all tasks from tft.artemis.tasks package [23:44:54] [+] running all tasks from tft.artemis.tasks package [23:44:54] [+] listening to all queues [23:44:54] [W] spawning *default* number of worker processes [23:44:54] [W] spawning *default* number of worker threads per process [23:44:54] [W] pre-fetching *default* number of messages per worker process [23:44:54] [W] pre-fetching *default* number of delayed messages per worker process [23:44:54] [+] dramatiq command-line: dramatiq tft.artemis.tasks tft.artemis.tasks.guest_request_watchdog tft.artemis.tasks.guest_shelf_lookup tft.artemis.tasks.prepare_verify_ssh tft.artemis.tasks.preprovision tft.artemis.tasks.refresh_pool_avoid_groups_hostnames_dispatcher tft.artemis.tasks.release_guest_request tft.artemis.tasks.remove_shelf tft.artemis.tasks.return_guest_to_shelf tft.artemis.tasks.route_guest_request tft.artemis.tasks.shelved_guest_watchdog tft.artemis.tasks.update_guest_request tft.artemis.tasks.worker_ping [2023-11-16 23:44:54 +0800] [1753528] [INFO] Starting gunicorn 21.2.0 [2023-11-16 23:44:54 +0800] [1753528] [INFO] Listening at: http://0.0.0.0:8001 (1753528) [2023-11-16 23:44:54 +0800] [1753528] [INFO] Using worker: sync [2023-11-16 23:44:54 +0800] [1753541] [INFO] Booting worker with pid: 1753541 [23:44:54] [+] connecting to db postgresql://artemis:artemis@127.0.0.1:5432/artemis [23:44:54] [+] sqlalchemy create_engine parameters: { "application_name": "artemis-dispatcher", "echo_pool": false, "max_overflow": 10, "pool_size": 20 } [23:44:54] [+] tick... [2023-11-16 23:44:54,850] [PID 1753531] [MainThread] [periodiq] [INFO] Starting Periodiq, a simple scheduler for Dramatiq. [23:44:58] [+] connecting to db postgresql://artemis:artemis@127.0.0.1:5432/artemis [23:44:58] [+] sqlalchemy create_engine parameters: { "application_name": "artemis-api-server", "echo_pool": false, "max_overflow": 10, "pool_size": 20 } [23:44:58] [+] API: /v0.0.58 [23:44:58] [+] API: /current => /v0.0.58 [23:44:58] [+] API: / => /v0.0.58 [23:44:58] [+] API: /v0.0.56 [23:44:58] [+] API: /v0.0.55 [23:44:58] [+] API: /v0.0.53 [23:44:58] [+] API: /v0.0.48 [23:44:58] [+] API: /v0.0.47 [23:44:58] [+] API: /v0.0.46 [23:44:58] [+] API: /v0.0.38 [23:44:58] [+] API: /v0.0.37 [23:44:58] [+] API: /v0.0.32 [23:44:58] [+] API: /v0.0.28 [23:44:58] [+] API: /v0.0.27 [23:44:58] [+] API: /v0.0.26 [23:44:58] [+] API: /v0.0.24 [23:44:58] [+] API: /v0.0.21 [23:44:58] [+] API: /v0.0.20 [23:44:58] [+] API: /v0.0.19 [23:44:58] [+] API: /v0.0.18 [23:44:58] [+] API: /v0.0.17 [2023-11-16 23:44:59,041] [PID 1753531] [MainThread] [periodiq] [INFO] Registered periodic actors: [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] m h dom mon dow module:actor@queue [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] ------------------------ ------------------ [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] * * * * * tft.artemis.tasks:refresh_pool_resources_metrics_dispatcher@periodic [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] */5 * * * * tft.artemis.tasks:refresh_pool_image_info_dispatcher@periodic [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] */5 * * * * tft.artemis.tasks:refresh_pool_flavor_info_dispatcher@periodic [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] 15 */4 * * * tft.artemis.tasks:gc_events@periodic [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] */5 * * * * tft.artemis.tasks.refresh_pool_avoid_groups_hostnames_dispatcher:refresh_pool_avoid_groups_hostnames_dispatcher@periodic [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] */5 * * * * tft.artemis.tasks.worker_ping:worker_ping@default [2023-11-16 23:44:59,042] [PID 1753531] [MainThread] [periodiq] [INFO] [2023-11-16 23:44:59,369] [PID 1753530] [MainThread] [dramatiq.MainProcess] [INFO] Dramatiq '1.13.0' is booting up. [23:44:59] [W] metrics refresher started [2023-11-16 23:44:59,368] [PID 1753542] [MainThread] [dramatiq.WorkerProcess(0)] [INFO] Worker process is ready for action. [23:44:58] [W] metrics refresher started [2023-11-16 23:44:58,655] [PID 1753543] [MainThread] [dramatiq.WorkerProcess(1)] [INFO] Worker process is ready for action. [23:44:58] [W] metrics refresher started [2023-11-16 23:44:58,590] [PID 1753544] [MainThread] [dramatiq.WorkerProcess(2)] [INFO] Worker process is ready for action. [23:44:58] [W] metrics refresher started [2023-11-16 23:44:58,798] [PID 1753545] [MainThread] [dramatiq.WorkerProcess(3)] [INFO] Worker process is ready for action. [2023-11-16 23:45:00,044] [PID 1753531] [MainThread] [periodiq] [INFO] Scheduling Actor(refresh_pool_resources_metrics_dispatcher) at 2023-11-16T23:45:00+08:00. [2023-11-16 23:45:00,047] [PID 1753531] [MainThread] [pika.adapters.utils.connection_workflow] [INFO] Pika version 1.3.2 connecting to ('127.0.0.1', 5672) [2023-11-16 23:45:00,048] [PID 1753531] [MainThread] [pika.adapters.utils.io_services_utils] [INFO] Socket connected: [2023-11-16 23:45:00,051] [PID 1753531] [MainThread] [pika.adapters.utils.connection_workflow] [INFO] Streaming transport linked up: (, _StreamingProtocolShim: params=>). [2023-11-16 23:45:00,062] [PID 1753531] [MainThread] [pika.adapters.utils.connection_workflow] [INFO] AMQPConnector - reporting success: params=> [2023-11-16 23:45:00,063] [PID 1753531] [MainThread] [pika.adapters.utils.connection_workflow] [INFO] AMQPConnectionWorkflow - reporting success: params=> [2023-11-16 23:45:00,064] [PID 1753531] [MainThread] [pika.adapters.blocking_connection] [INFO] Connection workflow succeeded: params=> [2023-11-16 23:45:00,065] [PID 1753531] [MainThread] [pika.adapters.blocking_connection] [INFO] Created channel=1 [2023-11-16 23:45:00,082] [PID 1753544] [Thread-15] [periodiq] [INFO] Processing 80ca3e14-912f-4a0c-9aa6-d5460d15ebde:refresh_pool_resources_metrics_dispatcher() scheduled at 2023-11-16T23:45:00+08:00. [23:45:00] [+] [Thread-15] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [refresh_pool_resources_metrics_dispatcher] acquired singleton lock with token 80ca3e14-912f-4a0c-9aa6-d5460d15ebde/599a5080-c41d-4a3e-93e9-2f890782cc24 [23:45:00] [+] [Thread-15] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [refresh-pool-resources-dispatcher] beginning [2023-11-16 23:45:00,093] [PID 1753531] [MainThread] [periodiq] [INFO] Scheduling Actor(refresh_pool_image_info_dispatcher) at 2023-11-16T23:45:00+08:00. [2023-11-16 23:45:00,098] [PID 1753531] [MainThread] [periodiq] [INFO] Scheduling Actor(refresh_pool_flavor_info_dispatcher) at 2023-11-16T23:45:00+08:00. [2023-11-16 23:45:00,100] [PID 1753543] [Thread-16] [periodiq] [INFO] Processing 4dedecce-316b-493c-ba97-21d34ee4070f:refresh_pool_image_info_dispatcher() scheduled at 2023-11-16T23:45:00+08:00. [2023-11-16 23:45:00,102] [PID 1753545] [Thread-17] [periodiq] [INFO] Processing 9cae5875-6b43-4fe6-bda5-73d13a26b6c8:refresh_pool_flavor_info_dispatcher() scheduled at 2023-11-16T23:45:00+08:00. [23:45:00] [+] [Thread-16] [4dedecce-316b-493c-ba97-21d34ee4070f] [refresh_pool_image_info_dispatcher] acquired singleton lock with token 4dedecce-316b-493c-ba97-21d34ee4070f/047cdc74-7253-4df6-a611-e0b5f4e9f97f [23:45:00] [+] [Thread-16] [4dedecce-316b-493c-ba97-21d34ee4070f] [refresh-pool-image-info-dispatcher] beginning [2023-11-16 23:45:00,105] [PID 1753531] [MainThread] [periodiq] [INFO] Scheduling Actor(refresh_pool_avoid_groups_hostnames_dispatcher) at 2023-11-16T23:45:00+08:00. [2023-11-16 23:45:00,110] [PID 1753531] [MainThread] [periodiq] [INFO] Scheduling Actor(worker_ping) at 2023-11-16T23:45:00+08:00. [2023-11-16 23:45:00,114] [PID 1753542] [Thread-10] [periodiq] [INFO] Processing 7721e10f-bb0f-417b-8458-0086a1a981fb:refresh_pool_avoid_groups_hostnames_dispatcher() scheduled at 2023-11-16T23:45:00+08:00. [23:45:00] [+] [Thread-10] [7721e10f-bb0f-417b-8458-0086a1a981fb] [refresh-pool-avoid-groups-hostnames-dispatcher] beginning [23:45:00] [+] [Thread-17] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [refresh_pool_flavor_info_dispatcher] acquired singleton lock with token 9cae5875-6b43-4fe6-bda5-73d13a26b6c8/168837e6-fd1d-4f1b-90db-ff1fb8992cbe [23:45:00] [+] [Thread-17] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [refresh-pool-flavor-info-dispatcher] beginning [2023-11-16 23:45:00,128] [PID 1753544] [Thread-18] [periodiq] [INFO] Processing 514a6e10-713b-4aed-8066-cac94fae7155:worker_ping() scheduled at 2023-11-16T23:45:00+08:00. [23:45:00] [+] [Thread-18] [514a6e10-713b-4aed-8066-cac94fae7155] [worker-ping] beginning [23:45:00] [+] connecting to db postgresql://artemis:artemis@127.0.0.1:5432/artemis [23:45:00] [+] sqlalchemy create_engine parameters: { "application_name": "artemis-worker", "echo_pool": false, "max_overflow": 10, "pool_size": 20 } [23:45:00] [+] [Thread-15_0] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [refresh-pool-resources-dispatcher] scheduling pool metrics refresh [23:45:00] [+] connecting to db postgresql://artemis:artemis@127.0.0.1:5432/artemis [23:45:00] [+] sqlalchemy create_engine parameters: { "application_name": "artemis-worker", "echo_pool": false, "max_overflow": 10, "pool_size": 20 } [23:45:00] [+] connecting to db postgresql://artemis:artemis@127.0.0.1:5432/artemis [23:45:00] [+] connecting to db postgresql://artemis:artemis@127.0.0.1:5432/artemis [23:45:00] [+] sqlalchemy create_engine parameters: { "application_name": "artemis-worker", "echo_pool": false, "max_overflow": 10, "pool_size": 20 } [23:45:00] [+] [Thread-17_0] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [refresh-pool-flavor-info-dispatcher] scheduling pool flavor info refresh [23:45:00] [+] sqlalchemy create_engine parameters: { "application_name": "artemis-worker", "echo_pool": false, "max_overflow": 10, "pool_size": 20 } [23:45:00] [+] [Thread-18] [514a6e10-713b-4aed-8066-cac94fae7155] [worker-ping] RSS: 1753544 worker-ping 98072 100248 2176 [23:45:00] [+] [Thread-18] [514a6e10-713b-4aed-8066-cac94fae7155] [worker-ping] finished [23:45:00] [+] [Thread-16_0] [4dedecce-316b-493c-ba97-21d34ee4070f] [refresh-pool-image-info-dispatcher] scheduling pool image info refresh [23:45:01] [+] [Thread-18] [9a094ef1-c2db-45d8-972e-578d4988f68d] [beaker] [refresh_pool_resources_metrics] acquired singleton lock with token 9a094ef1-c2db-45d8-972e-578d4988f68d/8b7d0ed1-19fa-4e9b-9d50-f9609846f8b7 [23:45:01] [+] [Thread-18] [9a094ef1-c2db-45d8-972e-578d4988f68d] [beaker] [refresh-pool-resources-metrics] beginning [23:45:01] [+] [Thread-15_0] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [beaker] [refresh-pool-resources-metrics-dispatcher] scheduled task: tasks: actor: refresh_pool_resources_metrics args: poolname: beaker delay: message: id: 9a094ef1-c2db-45d8-972e-578d4988f68d age: 0.013 queue: pool-data-refresh options: {} task-request: id: [23:45:01] [+] [Thread-15_0] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [openstack] [refresh-pool-resources-metrics-dispatcher] scheduled task: tasks: actor: refresh_pool_resources_metrics args: poolname: openstack delay: message: id: da2de878-28c6-45c3-8ad5-872cfb3f0bb9 age: 0.022 queue: pool-data-refresh options: {} task-request: id: [23:45:01] [+] [Thread-15] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [refresh-pool-resources-dispatcher] RSS: 1753544 refresh-pool-resources-metrics-dispatcher 97816 105240 7424 [23:45:01] [+] [Thread-15] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [refresh-pool-resources-dispatcher] finished [23:45:01] [+] [Thread-15] [80ca3e14-912f-4a0c-9aa6-d5460d15ebde] [refresh_pool_resources_metrics_dispatcher] released singleton lock [23:45:01] [E] [Thread-19] [da2de878-28c6-45c3-8ad5-872cfb3f0bb9] [openstack] [refresh_pool_resources_metrics] failure poolname: openstack lockname: tasks.singleton.refresh_pool_resources_metrics.openstack lock_deadline: 300 broker_message: queue_name: pool-data-refresh actor_name: refresh_pool_resources_metrics args: - openstack kwargs: {} options: &id001 {} message_id: da2de878-28c6-45c3-8ad5-872cfb3f0bb9 message_timestamp: 1700149501161 locks: tasks.singleton.refresh_pool_resources_metrics.beaker: token: 9a094ef1-c2db-45d8-972e-578d4988f68d/8b7d0ed1-19fa-4e9b-9d50-f9609846f8b7 ttl: 300 tasks.singleton.refresh_pool_resources_metrics.openstack: token: 9ee7d1b1-a918-457b-a9bb-1ca2e6f88f5f/cf8363cb-b870-4cd3-9602-dd0f65352ae5 ttl: 65 tasks.singleton.refresh_pool_flavor_info_dispatcher: token: 9cae5875-6b43-4fe6-bda5-73d13a26b6c8/168837e6-fd1d-4f1b-90db-ff1fb8992cbe ttl: 299 tasks.singleton.refresh_pool_resources_metrics_dispatcher: token: 80ca3e14-912f-4a0c-9aa6-d5460d15ebde/599a5080-c41d-4a3e-93e9-2f890782cc24 ttl: 299 tasks.singleton.refresh_pool_image_info_dispatcher: token: 4dedecce-316b-493c-ba97-21d34ee4070f/047cdc74-7253-4df6-a611-e0b5f4e9f97f ttl: 299 task_call: actor: refresh_pool_resources_metrics args: poolname: openstack delay: message: id: da2de878-28c6-45c3-8ad5-872cfb3f0bb9 age: 0.033 queue: pool-data-refresh options: *id001 task-request: id: message: failed to acquire singleton lock recoverable: true fail_guest_request: true [23:45:01] [+] [Thread-19] [da2de878-28c6-45c3-8ad5-872cfb3f0bb9] [openstack] [refresh_pool_resources_metrics] failed to acquire singleton lock, no retry requested [2023-11-16 23:45:01,209] [PID 1753543] [Thread-19] [dramatiq.worker.WorkerThread] [WARNING] Message refresh_pool_resources_metrics('openstack') was skipped. [23:45:04] [+] tick... [23:45:06] [+] [Thread-20] [85767748-d4c7-4903-9f99-0573f22cd411] [beaker] [refresh_pool_flavor_info] acquired singleton lock with token 85767748-d4c7-4903-9f99-0573f22cd411/9b536406-7040-497d-9e64-8bcd87243266 [23:45:06] [+] [Thread-20] [85767748-d4c7-4903-9f99-0573f22cd411] [beaker] [refresh-pool-flavor-info] beginning [23:45:06] [+] [Thread-16_0] [4dedecce-316b-493c-ba97-21d34ee4070f] [beaker] [refresh-pool-image-info-dispatcher] scheduled task: tasks: actor: refresh_pool_image_info args: poolname: beaker delay: message: id: d718e8c8-81e3-436b-80c9-0ca0491c82bb age: 0.025 queue: pool-data-refresh options: {} task-request: id: [23:45:06] [+] [Thread-11] [d718e8c8-81e3-436b-80c9-0ca0491c82bb] [beaker] [refresh_pool_image_info] acquired singleton lock with token d718e8c8-81e3-436b-80c9-0ca0491c82bb/f6ddbf44-9eec-498e-ba39-1434738bf0fa [23:45:06] [+] [Thread-11] [d718e8c8-81e3-436b-80c9-0ca0491c82bb] [beaker] [refresh-pool-image-info] beginning [23:45:06] [+] [Thread-15] [25329bdb-3120-4b9b-96be-deb0edf557ed] [beaker] [refresh_pool_avoid_groups_hostnames] acquired singleton lock with token 25329bdb-3120-4b9b-96be-deb0edf557ed/add013d1-a6ab-48c8-a146-157fcf5dd2df [23:45:06] [+] [Thread-15] [25329bdb-3120-4b9b-96be-deb0edf557ed] [beaker] [refresh-pool-groups-avoid-hostnames] beginning [23:45:06] [+] [Thread-17_0] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [beaker] [refresh-pool-flavor-info-dispatcher] scheduled task: tasks: actor: refresh_pool_flavor_info args: poolname: beaker delay: message: id: 85767748-d4c7-4903-9f99-0573f22cd411 age: 0.022 queue: pool-data-refresh options: {} task-request: id: [23:45:06] [+] [Thread-10_0] [7721e10f-bb0f-417b-8458-0086a1a981fb] [beaker] [refresh-pool-avoid-groups-hostnames-dispatcher] scheduled task: tasks: actor: refresh_pool_avoid_groups_hostnames args: poolname: beaker delay: message: id: 25329bdb-3120-4b9b-96be-deb0edf557ed age: 0.025 queue: pool-data-refresh options: {} task-request: id: [23:45:06] [+] [Thread-10] [7721e10f-bb0f-417b-8458-0086a1a981fb] [refresh-pool-avoid-groups-hostnames-dispatcher] RSS: 1753542 refresh-pool-avoid-groups-hostnames-dispatcher 97868 105036 7168 [23:45:06] [+] [Thread-10] [7721e10f-bb0f-417b-8458-0086a1a981fb] [refresh-pool-avoid-groups-hostnames-dispatcher] finished [23:45:06] [+] [Thread-19] [98392fd2-eb6b-4088-a296-c6059704adb1] [openstack] [refresh_pool_image_info] acquired singleton lock with token 98392fd2-eb6b-4088-a296-c6059704adb1/6cad5c13-f48b-4efb-abab-3849ccb45018 [23:45:06] [+] [Thread-19] [98392fd2-eb6b-4088-a296-c6059704adb1] [openstack] [refresh-pool-image-info] beginning [23:45:06] [+] [Thread-21] [1990da45-d872-4411-a733-716e954c14c2] [openstack] [refresh_pool_flavor_info] acquired singleton lock with token 1990da45-d872-4411-a733-716e954c14c2/67489e38-2ac2-44b4-82c5-ef8dcdd90113 [23:45:06] [+] [Thread-21] [1990da45-d872-4411-a733-716e954c14c2] [openstack] [refresh-pool-flavor-info] beginning [23:45:06] [+] [Thread-17_0] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [openstack] [refresh-pool-flavor-info-dispatcher] scheduled task: tasks: actor: refresh_pool_flavor_info args: poolname: openstack delay: message: id: 1990da45-d872-4411-a733-716e954c14c2 age: 0.081 queue: pool-data-refresh options: {} task-request: id: [23:45:06] [+] [Thread-16_0] [4dedecce-316b-493c-ba97-21d34ee4070f] [openstack] [refresh-pool-image-info-dispatcher] scheduled task: tasks: actor: refresh_pool_image_info args: poolname: openstack delay: message: id: 98392fd2-eb6b-4088-a296-c6059704adb1 age: 0.065 queue: pool-data-refresh options: {} task-request: id: [23:45:06] [+] [Thread-15] [25329bdb-3120-4b9b-96be-deb0edf557ed] [beaker] [refresh-pool-groups-avoid-hostnames] RSS: 1753544 refresh-pool-avoid-groups-hostnames 105496 105496 0 [23:45:06] [+] [Thread-15] [25329bdb-3120-4b9b-96be-deb0edf557ed] [beaker] [refresh-pool-groups-avoid-hostnames] finished [23:45:06] [+] [Thread-16] [4dedecce-316b-493c-ba97-21d34ee4070f] [refresh-pool-image-info-dispatcher] RSS: 1753543 refresh-pool-image-info-dispatcher 97760 105056 7296 [23:45:06] [+] [Thread-16] [4dedecce-316b-493c-ba97-21d34ee4070f] [refresh-pool-image-info-dispatcher] finished [23:45:06] [+] [Thread-16] [4dedecce-316b-493c-ba97-21d34ee4070f] [refresh_pool_image_info_dispatcher] released singleton lock [23:45:06] [+] [Thread-15] [25329bdb-3120-4b9b-96be-deb0edf557ed] [beaker] [refresh_pool_avoid_groups_hostnames] released singleton lock [23:45:06] [+] [Thread-17] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [refresh-pool-flavor-info-dispatcher] RSS: 1753545 refresh-pool-flavor-info-dispatcher 97904 105200 7296 [23:45:06] [+] [Thread-17] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [refresh-pool-flavor-info-dispatcher] finished [23:45:06] [+] [Thread-17] [9cae5875-6b43-4fe6-bda5-73d13a26b6c8] [refresh_pool_flavor_info_dispatcher] released singleton lock [23:45:07] [+] [Thread-20] [85767748-d4c7-4903-9f99-0573f22cd411] [beaker] [refresh-pool-flavor-info] RSS: 1753545 refresh-pool-flavor-info 104688 105328 640 [23:45:07] [+] [Thread-20] [85767748-d4c7-4903-9f99-0573f22cd411] [beaker] [refresh-pool-flavor-info] finished [23:45:07] [+] [Thread-20] [85767748-d4c7-4903-9f99-0573f22cd411] [beaker] [refresh_pool_flavor_info] released singleton lock [23:45:07] [+] [Thread-11] [d718e8c8-81e3-436b-80c9-0ca0491c82bb] [beaker] [refresh-pool-image-info] RSS: 1753542 refresh-pool-image-info 104780 105164 384 [23:45:07] [+] [Thread-11] [d718e8c8-81e3-436b-80c9-0ca0491c82bb] [beaker] [refresh-pool-image-info] finished [23:45:07] [+] [Thread-11] [d718e8c8-81e3-436b-80c9-0ca0491c82bb] [beaker] [refresh_pool_image_info] released singleton lock iiiiiiiii6666666 artemis master-key iiiiii77777777 Ok(None) [23:45:08] [E] [87e38169-d490-4a89-8bd8-300df80e851c] [create-guest-request] failure api_response_status: 400 Bad Request api_response_payload: message: No such SSH key exists guestname: 87e38169-d490-4a89-8bd8-300df80e851c raw_keyname: master-key raw_environment: hw: arch: aarch64 os: compose: Fedora-38 kickstart: {} raw_shelfname: raw_user_data: {} raw_post_install_script: raw_log_types: message: API error recoverable: true fail_guest_request: true 127.0.0.1 - - [16/Nov/2023:23:45:08 +0800] "POST /v0.0.58/guests/ HTTP/1.1" 400 37 "-" "python-requests/2.28.2" [23:45:12] [+] [Thread-18] [9a094ef1-c2db-45d8-972e-578d4988f68d] [beaker] [refresh-pool-resources-metrics] RSS: 1753544 refresh-pool-resources-metrics 104728 105752 1024 [23:45:12] [+] [Thread-18] [9a094ef1-c2db-45d8-972e-578d4988f68d] [beaker] [refresh-pool-resources-metrics] finished [23:45:12] [+] [Thread-18] [9a094ef1-c2db-45d8-972e-578d4988f68d] [beaker] [refresh_pool_resources_metrics] released singleton lock [23:45:14] [+] [Thread-21] [1990da45-d872-4411-a733-716e954c14c2] [openstack] [refresh-pool-flavor-info] RSS: 1753545 refresh-pool-flavor-info 104944 106224 1280 [23:45:14] [+] [Thread-21] [1990da45-d872-4411-a733-716e954c14c2] [openstack] [refresh-pool-flavor-info] finished [23:45:14] [+] [Thread-21] [1990da45-d872-4411-a733-716e954c14c2] [openstack] [refresh_pool_flavor_info] released singleton lock [23:45:15] [+] tick...