[
https://issues.apache.org/jira/browse/CLOUDSTACK-4523?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Rafael Weingärtner closed CLOUDSTACK-4523.
------------------------------------------
Resolution: Invalid
> 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 was sent by Atlassian JIRA
(v6.3.15#6346)
