David Mabry created CLOUDSTACK-4523:
---------------------------------------
Summary: Secondary Storage was offline, but Cloudstack was still
attempting to use it to create a template
Key: CLOUDSTACK-4523
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4523
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: KVM, Template
Affects Versions: 4.1.1
Environment: CentOS 6.3 KVM Host with NFS Secondary Storage.
Reporter: David Mabry
Priority: Minor
We had an issue with our Secondary Storage that caused it to become
unavailable. The IP wasn't available and NFS was definitely not running. When
looking in the Cloudstack interface the Secondary Storage still showed as
enabled and showed green. During the outage, a user attempted to create a
template from a VM and Cloudstack said that is was created successfully and
sure enough the template showed up to be used in the web interface. Then the
user tried to provision a new VM from the template and Cloudstack returned an
error on the VM creation that is detailed in the logs below.
Once we cleared the issue, the template was still no where to be found and the
user had to recreate the template from the source VM again.
Below are what I think are relevant logs to this issue. Please let me know if
you need more information.
====Template Creation====
2013-08-27 11:06:43,775 DEBUG [agent.transport.Request]
(Job-Executor-148:job-1897) Seq 1-1768326350: Sending { Cmd , MgmtId:
159090354809909, via: 1, Ver: v1, Flags: 100011,
[{"CreatePrivateTemplateFromVolumeCommand":{"_vmName":"i-48-359-VM","_volumePath":"a8ce8492-34d7-4ec2-86c2-fed1d8077557","_userSpecifiedName":"Wk8r2
Gold - IIS &
.net4.5","_uniqueName":"41d2b232-6a60-43b4-b2d7-58e82c095f91","_templateId":317,"_accountId":48,"_primaryPool":{"id":201,"uuid":"d37a92a6-8e01-41d2-ae43-0fad35f092ad","host":"localhost","path":"/store01","port":0,"type":"CLVM"},"_secondaryStorageUrl":"nfs://172.27.15.30/nfs/cssec","primaryStoragePoolNameLabel":"d37a92a6-8e01-41d2-ae43-0fad35f092ad","wait":10800}}]
}
2013-08-27 11:15:46,557 DEBUG [agent.transport.Request]
(AgentManager-Handler-8:null) Seq 1-1768326350: Processing: { Ans: , MgmtId:
159090354809909, via: 1, Ver: v1, Flags: 10,
[{"storage.CreatePrivateTemplateAnswer":{"_path":"/template/tmpl/48/317/41d2b232-6a60-43b4-b2d7-58e82c095f91.qcow2","_virtualSize":21474836480,"_physicalSize":12816744448,"_uniqueName":"41d2b232-6a60-43b4-b2d7-58e82c095f91","_format":"QCOW2","result":true,"wait":0}}]
}
2013-08-27 11:15:46,566 DEBUG [agent.transport.Request]
(Job-Executor-148:job-1897) Seq 28-183400063: Sending { Cmd , MgmtId:
159090354809909, via: 28, Ver: v1, Flags: 100111,
[{"ComputeChecksumCommand":{"templatePath":"/template/tmpl/48/317/41d2b232-6a60-43b4-b2d7-58e82c095f91.qcow2","secUrl":"nfs://192.168.15.30/nfs/cssec","wait":0}}]
}
2013-08-27 11:36:37,287 DEBUG [cloud.user.AccountManagerImpl]
(catalina-exec-5:null) Access to
Tmpl[317-QCOW2-41d2b232-6a60-43b4-b2d7-58e82c095f91 granted to Acct[31-jsmith]
by DomainChecker_EnhancerByCloudStack_6e37dedb
2013-08-27 11:36:37,468 DEBUG [cloud.user.AccountManagerImpl]
(Job-Executor-149:job-1898) Access to
Tmpl[317-QCOW2-41d2b232-6a60-43b4-b2d7-58e82c095f91 granted to Acct[31-jsmith]
by DomainChecker_EnhancerByCloudStack_6e37dedb
2013-08-27 11:36:50,207 DEBUG [agent.transport.Request]
(Job-Executor-149:job-1898) Seq 3-416367865: Sending { Cmd , MgmtId:
159090354809909, via: 3, Ver: v1, Flags: 100111,
[{"storage.CreateCommand":{"volId":416,"pool":{"id":201,"uuid":"d37a92a6-8e01-41d2-ae43-0fad35f092ad","host":"localhost","path":"/NAzone01cluster01store01","port":0,"type":"CLVM"},"diskCharacteristics":{"size":21474836480,"tags":["prod"],"type":"ROOT","name":"ROOT-361","useLocalStorage":false,"recreatable":true,"diskOfferingId":16,"volumeId":416,"hyperType":"KVM"},"templateUrl":"nfs://192.168.15.30/nfs/cssec//template/tmpl/48/317/41d2b232-6a60-43b4-b2d7-58e82c095f91.qcow2","wait":0}}]
}
======Failed VM Deployment======
2013-08-27 11:39:12,475 DEBUG [agent.transport.Request]
(Job-Executor-149:job-1898) Seq 3-416367910: Received: { Ans: , MgmtId:
159090354809909, via: 3, Ver: v1, Flags: 110, { StopAnswer } }
2013-08-27 11:39:12,482 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-149:job-1898) Changing active number of nics for network id=206
on -1
2013-08-27 11:39:12,486 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-149:job-1898) Changing active number of nics for network id=207
on -1
2013-08-27 11:39:12,487 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-149:job-1898) Successfully released network resources for the vm
VM[User|BuildTwo]
2013-08-27 11:39:12,487 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-149:job-1898) Successfully cleanued up resources for the vm
VM[User|BuildTwo] in Starting state
2013-08-27 11:39:12,489 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) DeploymentPlanner allocation algorithm: random
2013-08-27 11:39:12,489 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) Trying to allocate a host and storage pools from
dc:1, pod:1,cluster:1, requested cpu: 4000, requested ram: 2147483648
2013-08-27 11:39:12,489 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) Is ROOT volume READY (pool already allocated)?: No
2013-08-27 11:39:12,489 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) DeploymentPlan has host_id specified, choosing this
host and making no checks on this host: 3
2013-08-27 11:39:12,490 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) Looking for suitable pools for this host under
zone: 1, pod: 1, cluster: 1
2013-08-27 11:39:12,492 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) Checking suitable pools for volume (Id, Type):
(416,ROOT)
2013-08-27 11:39:12,492 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) We need to allocate new storagepool for this volume
2013-08-27 11:39:12,493 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) Calling StoragePoolAllocators to find suitable pools
2013-08-27 11:39:12,493 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-149:job-1898) Looking for pools in dc: 1 pod:1 cluster:1 having
tags:[prod]
2013-08-27 11:39:12,494 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-149:job-1898) FirstFitStoragePoolAllocator has 1 pools to check
for allocation
2013-08-27 11:39:12,495 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-149:job-1898) Checking if storage pool is suitable, name:
NAzone01cluster01store01 ,poolId: 201
2013-08-27 11:39:12,495 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-149:job-1898) StoragePool is in avoid set, skipping this pool
2013-08-27 11:39:12,495 DEBUG [storage.allocator.FirstFitStoragePoolAllocator]
(Job-Executor-149:job-1898) FirstFitStoragePoolAllocator returning 0 suitable
storage pools
2013-08-27 11:39:12,495 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) No suitable pools found for volume:
Vol[416|vm=361|ROOT] under cluster: 1
2013-08-27 11:39:12,495 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) No suitable pools found
2013-08-27 11:39:12,495 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-149:job-1898) Cannnot deploy to specified host, returning.
2013-08-27 11:39:12,498 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-149:job-1898) VM state transitted from :Starting to Stopped with
event: OperationFailedvm's original host id: null new host id: null host id
before state transition: 3
2013-08-27 11:39:12,502 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-149:job-1898) Hosts's actual total CPU: 60000 and CPU after
applying overprovisioning: 90000
2013-08-27 11:39:12,502 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-149:job-1898) release cpu from host: 3, old used: 60596,reserved:
0, actual total: 60000, total with overprovisioning: 90000; new used:
56596,reserved:0; movedfromreserved: false,moveToReserveredfalse
2013-08-27 11:39:12,502 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-149:job-1898) release mem from host: 3, old used:
39132856320,reserved: 0, total: 101395275776; new used: 36985372672,reserved:0;
movedfromreserved: false,moveToReserveredfalse
2013-08-27 11:39:12,505 DEBUG [cloud.vm.UserVmManagerImpl]
(Job-Executor-149:job-1898) Destroying vm VM[User|BuildTwo] as it failed to
create on Host with Id:null
2013-08-27 11:39:12,510 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-149:job-1898) VM state transitted from :Stopped to Error with
event: OperationFailedToErrorvm's original host id: null new host id: null host
id before state transition: null
2013-08-27 11:39:22,592 INFO [user.vm.DeployVMCmd] (Job-Executor-149:job-1898)
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[User|BuildTwo]Scope=interface com.cloud.dc.DataCenter; id=1
2013-08-27 11:39:22,592 INFO [user.vm.DeployVMCmd] (Job-Executor-149:job-1898)
Unable to create a deployment for VM[User|BuildTwo]
2013-08-27 11:39:22,593 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-149:job-1898) Complete async job-1898, jobStatus: 2, resultCode:
530, result: Error Code: 533 Error text: Unable to create a deployment for
VM[User|BuildTwo]
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
