Failing to create template from Volume #11803
Description
To be sure, I reproduced all the steps once more:
- create template from Volume (Windows 11 instance) => succesfull:
mysql> SELECT template_id, id, install_path, local_path, error_str, url FROM template_store_ref WHERE template_id = 263;
+-------------+----+----------------------------------------------------------------+------------+-----------+------+
| template_id | id | install_path | local_path | error_str | url |
+-------------+----+----------------------------------------------------------------+------------+-----------+------+
| 263 | 90 | template/tmpl/2/263/510f8711-4f6e-4c8c-82a7-0d4995cba56d.qcow2 | NULL | NULL | NULL |
+-------------+----+----------------------------------------------------------------+------------+-----------+------+
1 row in set (0.00 sec)
- create instance from template => not succesfull
This is the stack trace (filtered relevant lines):
2025-10-07 08:31:31,466 DEBUG [o.a.c.u.UserDataManagerImpl] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04]) (logid:7bb92677) Null/empty base64 encoded user data set
2025-10-07 08:31:31,467 INFO [c.c.n.NetworkModelImpl] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04]) (logid:7bb92677) Checking permission for account Account [{"accountName":"sysadmin-testing-admin-account","id":5,"uuid":"1a7f3942-ab6d-4c93-91a4-55307885090d"}] on network Network {"id": 294, "name": "Ikdoeict Shared Network 01", "uuid": "dcee468a-13cb-433e-af51-535bd9517080", "networkofferingid": 8}
2025-10-07 08:31:31,574 INFO [c.c.v.ClusteredVirtualMachineManagerImpl] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04]) (logid:7bb92677) allocating virtual machine from template: Template {"format":"QCOW2","id":263,"name":"Win11-test-tpl","uniqueName":"510f8711-4f6e-4c8c-82a7-0d4995cba56d","uuid":"e29df9ab-9f74-45ca-8bf1-153f038badfd"} with hostname: i-5-489-VM and 1 networks
2025-10-07 08:31:31,595 DEBUG [o.a.c.e.o.NetworkOrchestrator] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04]) (logid:7bb92677) Allocating nic for vm VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Stopped","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"} in network Network {"id": 294, "name": "Ikdoeict Shared Network 01", "uuid": "dcee468a-13cb-433e-af51-535bd9517080", "networkofferingid": 8} with requested profile NicProfile {"broadcastUri":null,"deviceId":null,"iPv4Address":null,"id":0,"reservationId":null,"uuid":null,"vmId":0}
2025-10-07 08:31:31,622 INFO [c.c.n.IpAddressManagerImpl] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04]) (logid:7bb92677) successfully allocated ip address 10.129.80.13
2025-10-07 08:31:31,712 INFO [o.a.c.e.o.VolumeOrchestrator] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04, ctx-f25559bc]) (logid:7bb92677) Adding disk object [ROOT-489] to VM [VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Stopped","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}]
2025-10-07 08:31:31,715 DEBUG [o.a.c.e.o.VolumeOrchestrator] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04, ctx-f25559bc]) (logid:7bb92677) Using root disk size of [(100.00 GB) 107374182400] bytes for the volume [ROOT-489].
2025-10-07 08:31:31,806 DEBUG [o.a.c.h.H.HAManagerBgPollTask] (BackgroundTaskPollManager-1:[ctx-5a1bc014]) (logid:17e670d3) HA health check task is running...
2025-10-07 08:31:31,900 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:9924c2ca) Add job-5105 into job monitoring
2025-10-07 08:31:31,906 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (qtp1438988851-9366:[ctx-ff0faeec, ctx-d0fe0d04]) (logid:7bb92677) submit async job-5105, details: AsyncJob {"accountId":2,"cmd":"org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin","cmdInfo":"{\"iptonetworklist[0].networkid\":\"dcee468a-13cb-433e-af51-535bd9517080\",\"sessionkey\":\"bGxxJ4Gan8Atas12n_p822iRv-A\",\"hostid\":\"fb229f10-be5b-4fa8-aceb-c20f10ecac4f\",\"httpmethod\":\"GET\",\"ctxAccountId\":\"2\",\"uuid\":\"c6864f6e-4ac2-4eae-b851-7e89329850f8\",\"domainid\":\"8caad24d-4385-4f3a-9fbd-d483f90f7e1b\",\"cmdEventType\":\"VM.CREATE\",\"bootmode\":\"SECURE\",\"iothreadsenabled\":\"false\",\"rootdisksize\":\"100\",\"ctxStartEventId\":\"40309\",\"id\":\"489\",\"ctxDetails\":\"{\\\"interface com.cloud.host.Host\\\":\\\"fb229f10-be5b-4fa8-aceb-c20f10ecac4f\\\",\\\"interface com.cloud.dc.DataCenter\\\":\\\"52d98511-089b-4911-8e5a-126260da51ff\\\",\\\"interface com.cloud.vm.VirtualMachine\\\":\\\"c6864f6e-4ac2-4eae-b851-7e89329850f8\\\",\\\"interface com.cloud.template.VirtualMachineTemplate\\\":\\\"e29df9ab-9f74-45ca-8bf1-153f038badfd\\\",\\\"interface com.cloud.domain.Domain\\\":\\\"8caad24d-4385-4f3a-9fbd-d483f90f7e1b\\\",\\\"interface com.cloud.offering.ServiceOffering\\\":\\\"39fdf489-e7ad-478b-9440-d5693021ef69\\\"}\",\"dynamicscalingenabled\":\"false\",\"keypairs\":\"\",\"boottype\":\"UEFI\",\"templateid\":\"e29df9ab-9f74-45ca-8bf1-153f038badfd\",\"startvm\":\"true\",\"serviceofferingid\":\"39fdf489-e7ad-478b-9440-d5693021ef69\",\"response\":\"json\",\"ctxUserId\":\"2\",\"displayname\":\"Win11-deploy-test\",\"name\":\"Win11-deploy-test\",\"zoneid\":\"52d98511-089b-4911-8e5a-126260da51ff\",\"account\":\"sysadmin-testing-admin-account\",\"affinitygroupids\":\"\"}","cmdVersion":0,"completeMsid":null,"created":null,"id":5105,"initMsid":206863092750034,"instanceId":489,"instanceType":"VirtualMachine","lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"20a86b86-ec9a-4b6c-b9f9-49497dc0d0f7"}
2025-10-07 08:31:31,907 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Executing AsyncJob {"accountId":2,"cmd":"org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin","cmdInfo":"{\"iptonetworklist[0].networkid\":\"dcee468a-13cb-433e-af51-535bd9517080\",\"sessionkey\":\"bGxxJ4Gan8Atas12n_p822iRv-A\",\"hostid\":\"fb229f10-be5b-4fa8-aceb-c20f10ecac4f\",\"httpmethod\":\"GET\",\"ctxAccountId\":\"2\",\"uuid\":\"c6864f6e-4ac2-4eae-b851-7e89329850f8\",\"domainid\":\"8caad24d-4385-4f3a-9fbd-d483f90f7e1b\",\"cmdEventType\":\"VM.CREATE\",\"bootmode\":\"SECURE\",\"iothreadsenabled\":\"false\",\"rootdisksize\":\"100\",\"ctxStartEventId\":\"40309\",\"id\":\"489\",\"ctxDetails\":\"{\\\"interface com.cloud.host.Host\\\":\\\"fb229f10-be5b-4fa8-aceb-c20f10ecac4f\\\",\\\"interface com.cloud.dc.DataCenter\\\":\\\"52d98511-089b-4911-8e5a-126260da51ff\\\",\\\"interface com.cloud.vm.VirtualMachine\\\":\\\"c6864f6e-4ac2-4eae-b851-7e89329850f8\\\",\\\"interface com.cloud.template.VirtualMachineTemplate\\\":\\\"e29df9ab-9f74-45ca-8bf1-153f038badfd\\\",\\\"interface com.cloud.domain.Domain\\\":\\\"8caad24d-4385-4f3a-9fbd-d483f90f7e1b\\\",\\\"interface com.cloud.offering.ServiceOffering\\\":\\\"39fdf489-e7ad-478b-9440-d5693021ef69\\\"}\",\"dynamicscalingenabled\":\"false\",\"keypairs\":\"\",\"boottype\":\"UEFI\",\"templateid\":\"e29df9ab-9f74-45ca-8bf1-153f038badfd\",\"startvm\":\"true\",\"serviceofferingid\":\"39fdf489-e7ad-478b-9440-d5693021ef69\",\"response\":\"json\",\"ctxUserId\":\"2\",\"displayname\":\"Win11-deploy-test\",\"name\":\"Win11-deploy-test\",\"zoneid\":\"52d98511-089b-4911-8e5a-126260da51ff\",\"account\":\"sysadmin-testing-admin-account\",\"affinitygroupids\":\"\"}","cmdVersion":0,"completeMsid":null,"created":null,"id":5105,"initMsid":206863092750034,"instanceId":489,"instanceType":"VirtualMachine","lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"20a86b86-ec9a-4b6c-b9f9-49497dc0d0f7"}
2025-10-07 08:31:31,928 INFO [o.a.c.a.DynamicRoleBasedAPIAccessChecker] (qtp1438988851-9015:[ctx-bbc7152e, ctx-8ac76e7f]) (logid:fb627921) Account for user id f5dc2a65-88ea-11f0-bda1-bc24112916d2 is Root Admin or Domain Admin, all APIs are allowed.
2025-10-07 08:31:31,928 DEBUG [o.a.c.a.StaticRoleBasedAPIAccessChecker] (qtp1438988851-9015:[ctx-bbc7152e, ctx-8ac76e7f]) (logid:fb627921) RoleService is enabled. We will use it instead of StaticRoleBasedAPIAccessChecker.
2025-10-07 08:31:31,928 DEBUG [o.a.c.r.ApiRateLimitServiceImpl] (qtp1438988851-9015:[ctx-bbc7152e, ctx-8ac76e7f]) (logid:fb627921) API rate limiting is disabled. We will not use ApiRateLimitService.
2025-10-07 08:31:31,969 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) LocalStoragePoolAllocator is returning null since the disk profile does not use local storage and bypassStorageTypeCheck is false.
2025-10-07 08:31:31,969 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Looking for pools in dc [1], pod [1] and cluster [1]. Disabled pools will be ignored.
2025-10-07 08:31:31,973 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Found pools [[StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}]] that match with tags [[]].
2025-10-07 08:31:31,974 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Checking if storage pool [StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}] is suitable to disk [DskChr[ROOT|107374182400|]].
2025-10-07 08:31:31,975 INFO [c.c.s.StorageManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Storage pool StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"} does not supply IOPS capacity, assuming enough capacity
2025-10-07 08:31:31,989 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Found suitable local storage pool [StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}] to allocate disk [DskChr[ROOT|107374182400|]] to it, adding to list.
2025-10-07 08:31:31,989 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) ClusterScopeStoragePoolAllocator is returning [1] suitable storage pools [[StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}]].
2025-10-07 08:31:31,989 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Using allocation algorithm [random] to reorder pools.
2025-10-07 08:31:32,037 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Sync job-5106 execution on object VmWorkJobQueue.489
2025-10-07 08:31:33,728 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:3195dee1) Add job-5106 into job monitoring
2025-10-07 08:31:33,733 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Executing AsyncJob {"accountId":2,"cmd":"com.cloud.vm.VmWorkStart","cmdInfo":"rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAB6XQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFzcQB-AAgAAAAAAAAABnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAAEdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt0AAhCb290TW9kZXQAEnJPMEFCWFFBQmxORlExVlNSUXQACEJvb3RUeXBldAAPck8wQUJYUUFCRlZGUmtrdAAIVWVmaUZsYWd0AA5yTzBBQlhRQUExbGxjd3hw","cmdVersion":0,"completeMsid":null,"created":"Tue Oct 07 08:31:32 UTC 2025","id":5106,"initMsid":206863092750034,"instanceId":null,"instanceType":null,"lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"c47b6d25-9d60-42af-bb32-583e1992364f"}
2025-10-07 08:31:33,760 INFO [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Uefi params UefiFlag: Yes Boot Type: UEFI Boot Mode: SECURE
2025-10-07 08:31:33,773 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) LocalStoragePoolAllocator is returning null since the disk profile does not use local storage and bypassStorageTypeCheck is false.
2025-10-07 08:31:33,773 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Looking for pools in dc [1], pod [1] and cluster [1]. Disabled pools will be ignored.
2025-10-07 08:31:33,776 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Found pools [[StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}]] that match with tags [[]].
2025-10-07 08:31:33,777 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Checking if storage pool [StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}] is suitable to disk [DskChr[ROOT|107374182400|]].
2025-10-07 08:31:33,778 INFO [c.c.s.StorageManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Storage pool StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"} does not supply IOPS capacity, assuming enough capacity
2025-10-07 08:31:33,790 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Found suitable local storage pool [StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}] to allocate disk [DskChr[ROOT|107374182400|]] to it, adding to list.
2025-10-07 08:31:33,790 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) ClusterScopeStoragePoolAllocator is returning [1] suitable storage pools [[StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}]].
2025-10-07 08:31:33,790 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Using allocation algorithm [random] to reorder pools.
2025-10-07 08:31:33,844 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Network Network {"id": 294, "name": "Ikdoeict Shared Network 01", "uuid": "dcee468a-13cb-433e-af51-535bd9517080", "networkofferingid": 8} is already implemented
2025-10-07 08:31:33,851 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Changing active number of nics for network id=Network {"id": 294, "name": "Ikdoeict Shared Network 01", "uuid": "dcee468a-13cb-433e-af51-535bd9517080", "networkofferingid": 8} on 1
2025-10-07 08:31:33,872 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Asking VirtualRouter to prepare for Nic {"broadcastUri":"vxlan:\/\/5000","deviceId":0,"iPv4Address":"10.129.80.13","id":636,"instanceId":489,"reservationId":null,"uuid":"5bfd606f-7003-436f-98bd-b49078aea8ea"}
2025-10-07 08:31:33,881 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) CONFIG DHCP FOR SUBNETS RULES
2025-10-07 08:31:33,886 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) APPLYING VPC DHCP ENTRY RULES
2025-10-07 08:31:33,887 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Applying dhcp entry in network Network {"id": 294, "name": "Ikdoeict Shared Network 01", "uuid": "dcee468a-13cb-433e-af51-535bd9517080", "networkofferingid": 8}
2025-10-07 08:31:35,128 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) APPLYING VPC USERDATA RULES
2025-10-07 08:31:35,129 DEBUG [o.a.c.n.t.BasicNetworkTopology] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Applying userdata and password entry in network Network {"id": 294, "name": "Ikdoeict Shared Network 01", "uuid": "dcee468a-13cb-433e-af51-535bd9517080", "networkofferingid": 8}
2025-10-07 08:31:37,257 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) template Template {"format":"QCOW2","id":263,"name":"Win11-test-tpl","uniqueName":"510f8711-4f6e-4c8c-82a7-0d4995cba56d","uuid":"e29df9ab-9f74-45ca-8bf1-153f038badfd"} with id 263 is already in store:ImageStore {"id":6,"name":"Secondary Storage","uuid":"71ecafa6-791a-45b5-bc0c-21b71754afb2"}, type: Image
2025-10-07 08:31:37,260 DEBUG [o.a.c.s.d.PrimaryDataStoreImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Not found (templateId:263poolId:1conf:null) in template_spool_ref, persisting it
2025-10-07 08:31:37,282 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) template Template {"format":"QCOW2","id":263,"name":"Win11-test-tpl","uniqueName":"510f8711-4f6e-4c8c-82a7-0d4995cba56d","uuid":"e29df9ab-9f74-45ca-8bf1-153f038badfd"} with id 263 is already in store:StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"}, type: Primary
2025-10-07 08:31:37,283 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Found template Template {"format":"QCOW2","id":263,"name":"Win11-test-tpl","uniqueName":"510f8711-4f6e-4c8c-82a7-0d4995cba56d","uuid":"e29df9ab-9f74-45ca-8bf1-153f038badfd"} in storage pool StoragePool {"id":1,"name":"Primary Storage (pool-ikdoeict-01)","poolType":"RBD","uuid":"e57fa515-c914-33e0-affe-0882ba18ec1f"} with VMTemplateStoragePool: TmplPool[72-263-1-null]
2025-10-07 08:31:37,283 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Acquire lock on VMTemplateStoragePool 72 with timeout 3600 seconds
2025-10-07 08:31:37,303 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) lock is acquired for VMTemplateStoragePool 72
2025-10-07 08:31:37,329 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE
2025-10-07 08:31:47,048 WARN [o.a.c.m.w.WebhookServiceImpl] (StatsCollector-4:[ctx-a3574b8a]) (logid:50197e82) Skipping delivering event Event {"description":"{\"event\":\"IMAGE.STORE.ACCESS.UPDATED\",\"status\":\"Completed\"}","eventId":null,"eventType":"IMAGE.STORE.ACCESS.UPDATED","eventUuid":null,"resourceType":"ImageStore","resourceUUID":null} to any webhook as account ID is missing
2025-10-07 08:31:47,049 WARN [o.a.c.f.e.EventDistributorImpl] (StatsCollector-4:[ctx-a3574b8a]) (logid:50197e82) Failed to publish event [category: ActionEvent, type: IMAGE.STORE.ACCESS.UPDATED] on bus webhookEventBus
2025-10-07 08:32:51,998 WARN [o.a.c.m.w.WebhookServiceImpl] (StatsCollector-5:[ctx-7d8efa3b]) (logid:1e2426b4) Skipping delivering event Event {"description":"{\"event\":\"IMAGE.STORE.ACCESS.UPDATED\",\"status\":\"Completed\"}","eventId":null,"eventType":"IMAGE.STORE.ACCESS.UPDATED","eventUuid":null,"resourceType":"ImageStore","resourceUUID":null} to any webhook as account ID is missing
2025-10-07 08:32:51,998 WARN [o.a.c.f.e.EventDistributorImpl] (StatsCollector-5:[ctx-7d8efa3b]) (logid:1e2426b4) Failed to publish event [category: ActionEvent, type: IMAGE.STORE.ACCESS.UPDATED] on bus webhookEventBus
2025-10-07 08:33:57,313 WARN [o.a.c.m.w.WebhookServiceImpl] (StatsCollector-3:[ctx-3ef2fd65]) (logid:2d786396) Skipping delivering event Event {"description":"{\"event\":\"IMAGE.STORE.ACCESS.UPDATED\",\"status\":\"Completed\"}","eventId":null,"eventType":"IMAGE.STORE.ACCESS.UPDATED","eventUuid":null,"resourceType":"ImageStore","resourceUUID":null} to any webhook as account ID is missing
2025-10-07 08:33:57,313 WARN [o.a.c.f.e.EventDistributorImpl] (StatsCollector-3:[ctx-3ef2fd65]) (logid:2d786396) Failed to publish event [category: ActionEvent, type: IMAGE.STORE.ACCESS.UPDATED] on bus webhookEventBus
2025-10-07 08:34:08,857 ERROR [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Unable to create volume [{"name":"ROOT-489","uuid":"c6730494-2799-4b62-bddd-4d4f0935e79e"}] due to [com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt/40ce3983-2f4b-322c-b28d-35c2cf39763f/510f8711-4f6e-4c8c-82a7-0d4995cba56d.qcow2 to e29df9ab-9f74-45ca-8bf1-153f038badfd].
2025-10-07 08:34:08,857 WARN [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Unable to contact resource. com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create volume [{"name":"ROOT-489","uuid":"c6730494-2799-4b62-bddd-4d4f0935e79e"}] due to [com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt/40ce3983-2f4b-322c-b28d-35c2cf39763f/510f8711-4f6e-4c8c-82a7-0d4995cba56d.qcow2 to e29df9ab-9f74-45ca-8bf1-153f038badfd].
at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume(VolumeOrchestrator.java:1797)
at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1944)
at jdk.internal.reflect.GeneratedMethodAccessor976.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at jdk.proxy3/jdk.proxy3.$Proxy268.prepare(Unknown Source)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1289)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5486)
at jdk.internal.reflect.GeneratedMethodAccessor987.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:102)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5610)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:99)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:652)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:600)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)
2025-10-07 08:34:09,163 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Changing active number of nics for network id=Network {"id": 294, "name": "Ikdoeict Shared Network 01", "uuid": "dcee468a-13cb-433e-af51-535bd9517080", "networkofferingid": 8} on -1
2025-10-07 08:34:09,210 INFO [c.c.v.ClusteredVirtualMachineManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Uefi params UefiFlag: Yes Boot Type: UEFI Boot Mode: SECURE
2025-10-07 08:34:09,331 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Starting","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}Scope=interface com.cloud.dc.DataCenter; id=1
2025-10-07 08:34:09,331 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Starting","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}Scope=interface com.cloud.dc.DataCenter; id=1
2025-10-07 08:34:09,331 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Unable to complete AsyncJob {"accountId":2,"cmd":"com.cloud.vm.VmWorkStart","cmdInfo":"rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAB6XQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFzcQB-AAgAAAAAAAAABnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAAEdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt0AAhCb290TW9kZXQAEnJPMEFCWFFBQmxORlExVlNSUXQACEJvb3RUeXBldAAPck8wQUJYUUFCRlZGUmtrdAAIVWVmaUZsYWd0AA5yTzBBQlhRQUExbGxjd3hw","cmdVersion":0,"completeMsid":null,"created":"Tue Oct 07 08:31:32 UTC 2025","id":5106,"initMsid":206863092750034,"instanceId":null,"instanceType":null,"lastPolled":null,"lastUpdated":null,"processStatus":0,"removed":null,"result":null,"resultCode":0,"status":"IN_PROGRESS","userId":2,"uuid":"c47b6d25-9d60-42af-bb32-583e1992364f"}, job origin: 5105 com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Starting","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1261)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5486)
at jdk.internal.reflect.GeneratedMethodAccessor987.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:102)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5610)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:99)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:652)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:600)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)
2025-10-07 08:34:09,335 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Complete async job-5106, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyADdjb20uY2xvdWQuZXhjZXB0aW9uLkluc3VmZmljaWVudFNlcnZlckNhcGFjaXR5RXhjZXB0aW9uVk1PcAAAABACAAFaABVhZmZpbml0eUdyb3Vwc0FwcGxpZWR4cgAxY29tLmNsb3VkLmV4Y2VwdGlvbi5JbnN1ZmZpY2llbnRDYXBhY2l0eUV4Y2VwdGlvblZNT3AAAAAVAgACTAACaWR0ABBMamF2YS9sYW5nL0xvbmc7TAAFc2NvcGV0ABFMamF2YS9sYW5nL0NsYXNzO3hyACJjb20uY2xvdWQuZXhjZXB0aW9uLkNsb3VkRXhjZXB0aW9ueeiOG_HkRMcCAAJMAAtjc0Vycm9yQ29kZXQAE0xqYXZhL2xhbmcvSW50ZWdlcjtMAAZpZExpc3R0ABVMamF2YS91dGlsL0FycmF5TGlzdDt4cgATamF2YS5sYW5nLkV4Y2VwdGlvbtD9Hz4aOxzEAgAAeHIAE2phdmEubGFuZy5UaHJvd2FibGXVxjUnOXe4ywMABEwABWNhdXNldAAVTGphdmEvbGFuZy9UaHJvd2FibGU7TAANZGV0YWlsTWVzc2FnZXQAEkxqYXZhL2xhbmcvU3RyaW5nO1sACnN0YWNrVHJhY2V0AB5bTGphdmEvbGFuZy9TdGFja1RyYWNlRWxlbWVudDtMABRzdXBwcmVzc2VkRXhjZXB0aW9uc3QAEExqYXZhL3V0aWwvTGlzdDt4cHEAfgANdACjVW5hYmxlIHRvIGNyZWF0ZSBhIGRlcGxveW1lbnQgZm9yIFZNIGluc3RhbmNlIHsiaWQiOjQ4OSwiaW5zdGFuY2VOYW1lIjoiaS01LTQ4OS1WTSIsInN0YXRlIjoiU3RhcnRpbmciLCJ0eXBlIjoiVXNlciIsInV1aWQiOiJjNjg2NGY2ZS00YWMyLTRlYWUtYjg1MS03ZTg5MzI5ODUwZjgifXVyAB5bTGphdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudDsCRio8PP0iOQIAAHhwAAAAFHNyABtqYXZhLmxhbmcuU3RhY2tUcmFjZUVsZW1lbnRhCcWaJjbdhQIACEIABmZvcm1hdEkACmxpbmVOdW1iZXJMAA9jbGFzc0xvYWRlck5hbWVxAH4ACkwADmRlY2xhcmluZ0NsYXNzcQB-AApMAAhmaWxlTmFtZXEAfgAKTAAKbWV0aG9kTmFtZXEAfgAKTAAKbW9kdWxlTmFtZXEAfgAKTAANbW9kdWxlVmVyc2lvbnEAfgAKeHABAAAE7XQAA2FwcHQAJmNvbS5jbG91ZC52bS5WaXJ0dWFsTWFjaGluZU1hbmFnZXJJbXBsdAAeVmlydHVhbE1hY2hpbmVNYW5hZ2VySW1wbC5qYXZhdAAQb3JjaGVzdHJhdGVTdGFydHBwc3EAfgARAQAAFW5xAH4AE3EAfgAUcQB-ABVxAH4AFnBwc3EAfgARAP____9wdAAvamRrLmludGVybmFsLnJlZmxlY3QuR2VuZXJhdGVkTWV0aG9kQWNjZXNzb3I5ODdwdAAGaW52b2tlcHBzcQB-ABECAAAAK3B0ADFqZGsuaW50ZXJuYWwucmVmbGVjdC5EZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsdAAhRGVsZWdhdGluZ01ldGhvZEFjY2Vzc29ySW1wbC5qYXZhcQB-ABp0AAlqYXZhLmJhc2V0AAcxNy4wLjE2c3EAfgARAgAAAjlwdAAYamF2YS5sYW5nLnJlZmxlY3QuTWV0aG9kdAALTWV0aG9kLmphdmFxAH4AGnEAfgAecQB-AB9zcQB-ABEBAAAAZnEAfgATdAAiY29tLmNsb3VkLnZtLlZtV29ya0pvYkhhbmRsZXJQcm94eXQAGlZtV29ya0pvYkhhbmRsZXJQcm94eS5qYXZhdAAPaGFuZGxlVm1Xb3JrSm9icHBzcQB-ABEBAAAV6nEAfgATcQB-ABRxAH4AFXEAfgAmcHBzcQB-ABEBAAAAY3EAfgATdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4AEQEAAAKMcQB-ABN0AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4AEQEAAAAxcQB-ABN0AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgARAQAAADhxAH4AE3QAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgARAQAAAGdxAH4AE3QAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4ANnQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgARAQAAADVxAH4AE3EAfgA5cQB-ADZ0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgARAQAAAC5xAH4AE3QAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAycQB-ADNwcHNxAH4AEQEAAAJYcQB-ABNxAH4ALXEAfgAucQB-ADNwcHNxAH4AEQIAAAIbcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgA3cQB-AB5xAH4AH3NxAH4AEQIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AM3EAfgAecQB-AB9zcQB-ABECAAAEcHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAecQB-AB9zcQB-ABECAAACe3B0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AEhxAH4AM3EAfgAecQB-AB9zcQB-ABECAAADSHB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AM3EAfgAecQB-AB9zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4c3IAEWphdmEubGFuZy5JbnRlZ2VyEuKgpPeBhzgCAAFJAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAEO9zcgATamF2YS51dGlsLkFycmF5TGlzdHiB0h2Zx2GdAwABSQAEc2l6ZXhwAAAAAHcEAAAAAHhzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHEAfgBSAAAAAAAAAAF2cgAXY29tLmNsb3VkLmRjLkRhdGFDZW50ZXIQUFRtA0UeAAIAAHhwAA
2025-10-07 08:34:09,335 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Publish async job-5106 complete on message bus
2025-10-07 08:34:09,335 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Wake up jobs related to job-5106
2025-10-07 08:34:09,335 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Update db status for job-5106
2025-10-07 08:34:09,336 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Wake up jobs joined with job-5106 and disjoin all subjobs created from job- 5106
2025-10-07 08:34:09,380 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Done executing com.cloud.vm.VmWorkStart for job-5106
2025-10-07 08:34:09,380 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106]) (logid:20a86b86) Remove job-5106 from job monitoring
2025-10-07 08:34:09,520 WARN [c.c.a.AlertManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) alertType=[8] dataCenterId=[1] podId=[null] clusterId=[null] message=[Failed to deploy Vm VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Error","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}, on Host Host {"id":6,"name":"pbaictkvm10.ikdoeict.be","type":"Routing","uuid":"fb229f10-be5b-4fa8-aceb-c20f10ecac4f"} with Id: 6].
2025-10-07 08:34:09,563 WARN [o.a.c.m.w.WebhookServiceImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Skipping delivering event Event {"description":"{\"details\":\"Vm Id: c6864f6e-4ac2-4eae-b851-7e89329850f8\",\"event\":\"VM.CREATE\",\"status\":\"Completed\"}","eventId":null,"eventType":"VM.CREATE","eventUuid":null,"resourceType":"VirtualMachine","resourceUUID":null} to any webhook as account ID is missing
2025-10-07 08:34:09,563 WARN [o.a.c.f.e.EventDistributorImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105, ctx-655bc14a]) (logid:20a86b86) Failed to publish event [category: ActionEvent, type: VM.CREATE] on bus webhookEventBus
2025-10-07 08:34:09,585 ERROR [c.c.a.ApiAsyncJobDispatcher] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Unexpected exception while executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin com.cloud.utils.exception.CloudRuntimeException: Unable to start a VM [c6864f6e-4ac2-4eae-b851-7e89329850f8] due to [Unable to create a deployment for VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Starting","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}].
at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:879)
at org.apache.cloudstack.engine.cloud.entity.api.VMEntityManagerImpl.deployVirtualMachine(VMEntityManagerImpl.java:245)
at org.apache.cloudstack.engine.cloud.entity.api.VirtualMachineEntityImpl.deploy(VirtualMachineEntityImpl.java:214)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5638)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5490)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5091)
at com.cloud.vm.UserVmManagerImpl.startVirtualMachine(UserVmManagerImpl.java:5080)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.apache.cloudstack.network.contrail.management.EventUtils$EventInterceptor.invoke(EventUtils.java:105)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
at com.cloud.event.ActionEventInterceptor.invoke(ActionEventInterceptor.java:52)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
at jdk.proxy3/jdk.proxy3.$Proxy210.startVirtualMachine(Unknown Source)
at org.apache.cloudstack.api.command.user.vm.DeployVMCmd.execute(DeployVMCmd.java:781)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:173)
at com.cloud.api.ApiAsyncJobDispatcher.runJob(ApiAsyncJobDispatcher.java:110)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:652)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:600)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Starting","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:1261)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5486)
at jdk.internal.reflect.GeneratedMethodAccessor987.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:102)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5610)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:99)
... 12 more
2025-10-07 08:34:09,586 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Complete async job-5105, jobStatus: FAILED, resultCode: 530, result: org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable to start a VM [c6864f6e-4ac2-4eae-b851-7e89329850f8] due to [Unable to create a deployment for VM instance {"id":489,"instanceName":"i-5-489-VM","state":"Starting","type":"User","uuid":"c6864f6e-4ac2-4eae-b851-7e89329850f8"}]."}
2025-10-07 08:34:09,586 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Publish async job-5105 complete on message bus
2025-10-07 08:34:09,586 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Wake up jobs related to job-5105
2025-10-07 08:34:09,586 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Update db status for job-5105
2025-10-07 08:34:09,587 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Wake up jobs joined with job-5105 and disjoin all subjobs created from job- 5105
2025-10-07 08:34:09,614 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl$5] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Done executing org.apache.cloudstack.api.command.admin.vm.DeployVMCmdByAdmin for job-5105
2025-10-07 08:34:09,615 INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-80:[ctx-c48637c3, job-5105]) (logid:20a86b86) Remove job-5105 from job monitoring
What also strikes me in this stack trace (first ERROR line) is that creating a volume fails.
2025-10-07 08:34:08,857 ERROR [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-99:[ctx-6601ae3f, job-5105/job-5106, ctx-69084d16]) (logid:20a86b86) Unable to create volume [{"name":"ROOT-489","uuid":"c6730494-2799-4b62-bddd-4d4f0935e79e"}] due to [com.cloud.utils.exception.CloudRuntimeException: Failed to copy /mnt/40ce3983-2f4b-322c-b28d-35c2cf39763f/510f8711-4f6e-4c8c-82a7-0d4995cba56d.qcow2 to e29df9ab-9f74-45ca-8bf1-153f038badfd].
I find this strange because the host on which I'm trying to start the instance is definitely capable of dynamically creating other NFS mounts.
10.129.97.119:/export/Cloudstack-Secondary-Storage-prod/template/tmpl/2/238 on /mnt/8ce22a03-43ce-3bb9-8491-23b497c1f352 type nfs4 (rw,nosuid,nodev,noexec,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=10.129.96.10,local_lock=none,addr=10.129.97.119)
Originally posted by @svenknockaert in #11791 (reply in thread)