[
https://issues.apache.org/jira/browse/CLOUDSTACK-2653?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13665751#comment-13665751
]
Wido den Hollander commented on CLOUDSTACK-2653:
------------------------------------------------
I didn't post the right piece of logs I think, so here is some more:
2013-05-24 00:09:12,069 INFO
[cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) No
running secondary storage vms found in datacenter id=1, starting one
2013-05-24 00:09:12,072 TRACE [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Allocate secondary storage vm standby capacity for data
center : 1
2013-05-24 00:09:12,074 INFO [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) No stopped secondary storage vm is available, need to
allocate a new secondary storage vm
2013-05-24 00:09:12,076 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Assign secondary storage vm from a newly started instance
for request from data center : 1
2013-05-24 00:09:12,099 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Found existing network configuration for offering [Network
Offering [6-Guest-DefaultSharedNetworkOfferingWithSGService]: Ntwk[204|Guest|6]
2013-05-24 00:09:12,099 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Releasing lock for Acct[1-system]
2013-05-24 00:09:12,103 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Found existing network configuration for offering [Network
Offering [3-Control-System-Control-Network]: Ntwk[202|Control|3]
2013-05-24 00:09:12,103 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Releasing lock for Acct[1-system]
2013-05-24 00:09:12,106 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Found existing network configuration for offering [Network
Offering [2-Management-System-Management-Network]: Ntwk[201|Management|2]
2013-05-24 00:09:12,107 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Releasing lock for Acct[1-system]
2013-05-24 00:09:12,110 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Found existing network configuration for offering [Network
Offering [4-Storage-System-Storage-Network]: Ntwk[203|Storage|4]
2013-05-24 00:09:12,110 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Releasing lock for Acct[1-system]
2013-05-24 00:09:12,118 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Allocating entries for VM: VM[SecondaryStorageVm|s-4070-VM]
2013-05-24 00:09:12,121 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Allocating nics for VM[SecondaryStorageVm|s-4070-VM]
2013-05-24 00:09:12,122 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-4070-VM] in
network Ntwk[204|Guest|6] with requested profile NicProfile[0-0-null-null-null
2013-05-24 00:09:12,136 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-4070-VM] in
network Ntwk[202|Control|3] with requested profile null
2013-05-24 00:09:12,145 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-4070-VM] in
network Ntwk[201|Management|2] with requested profile null
2013-05-24 00:09:12,154 DEBUG [cloud.network.NetworkManagerImpl]
(secstorage-1:null) Allocating nic for vm VM[SecondaryStorageVm|s-4070-VM] in
network Ntwk[203|Storage|4] with requested profile null
2013-05-24 00:09:12,165 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Allocaing disks for VM[SecondaryStorageVm|s-4070-VM]
2013-05-24 00:09:12,193 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Allocation completed for VM:
VM[SecondaryStorageVm|s-4070-VM]
2013-05-24 00:09:12,196 DEBUG [cloud.alert.SecondaryStorageVmAlertAdapter]
(secstorage-1:null) received secondary storage vm alert
2013-05-24 00:09:12,196 DEBUG [cloud.alert.SecondaryStorageVmAlertAdapter]
(secstorage-1:null) New secondary storage vm created, zone: Amsterdam Zone 1,
secStorageVm: s-4070-VM, public IP: null, private IP: null
2013-05-24 00:09:12,302 DEBUG [cloud.capacity.CapacityManagerImpl]
(secstorage-1:null) VM state transitted from :Stopped to Starting with event:
StartRequestedvm's original host id: null new host id: null host id before
state transition: null
2013-05-24 00:09:12,302 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Successfully transitioned to start state for
VM[SecondaryStorageVm|s-4070-VM] reservation id =
83c82265-c0df-4d43-83a9-b59b4ea7152a
2013-05-24 00:09:12,302 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-05-24 00:09:12,576 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Trying to deploy VM, vm has dcId: 1 and podId: null
2013-05-24 00:09:12,576 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2013-05-24 00:09:12,579 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
2013-05-24 00:09:12,580 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(secstorage-1:null) DeploymentPlanner allocation algorithm:
com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_acb25894@26b53114
2013-05-24 00:09:12,580 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(secstorage-1:null) Trying to allocate a host and storage pools from dc:1,
pod:null,cluster:null, requested cpu: 500, requested ram: 268435456
2013-05-24 00:09:12,580 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
(secstorage-1:null) Is ROOT volume READY (pool already allocated)?: No
2013-05-24 00:09:12,580 DEBUG [cloud.deploy.FirstFitPlanner]
(secstorage-1:null) Searching all possible resources under this Zone: 1
2013-05-24 00:09:12,581 DEBUG [cloud.deploy.FirstFitPlanner]
(secstorage-1:null) Listing clusters in order of aggregate capacity, that have
(atleast one host with) enough CPU and RAM capacity under this Zone: 1
2013-05-24 00:09:12,584 DEBUG [cloud.deploy.FirstFitPlanner]
(secstorage-1:null) No clusters found having a host with enough capacity,
returning.
2013-05-24 00:09:12,884 DEBUG [cloud.capacity.CapacityManagerImpl]
(secstorage-1:null) VM state transitted from :Starting to Stopped with event:
OperationFailedvm's original host id: null new host id: null host id before
state transition: null
2013-05-24 00:09:12,887 WARN [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.InsufficientServerCapacityException: Unable to create a
deployment for VM[SecondaryStorageVm|s-4070-VM]Scope=interface
com.cloud.dc.DataCenter; id=1
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:813)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:543)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:262)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:687)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1303)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
at
com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
at
com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at
com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
2013-05-24 00:09:12,888 INFO [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Unable to start secondary storage vm for standby capacity,
secStorageVm vm Id : 4070, will recycle it and start a new one
Watch this:
New secondary storage vm created, zone: Amsterdam Zone 1, secStorageVm:
s-4070-VM, public IP: null, private IP: null
And
Allocating nic for vm VM[SecondaryStorageVm|s-4070-VM] in network
Ntwk[204|Guest|6] with requested profile NicProfile[0-0-null-null-null
During the allocation the IP addresses and offerings don't seem to be fetched
from the database correctly and resulting in null everywhere.
I assigned it to Mural since I think this is due to the merge of the elastic
IPs.
Could you shed some light on this?
> Resources aren't allocated for SystemVMs correctly
> --------------------------------------------------
>
> Key: CLOUDSTACK-2653
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2653
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: Management Server
> Affects Versions: Future
> Environment: Ubuntu 12.04 running master branch
> Reporter: Wido den Hollander
> Assignee: Murali Reddy
> Fix For: 4.2.0
>
>
> I just upgraded my 4.1 management server to the master branch and after a
> painful database upgrade it is running.
> I don't have a SSVM, so it's trying to start it, but that fails.
> The logs show:
> 2013-05-23 17:50:13,199 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
> (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
> 2013-05-23 17:50:13,203 INFO
> [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) No
> running secondary storage vms found in datacenter id=1, starting one
> 2013-05-23 17:50:13,207 INFO [storage.secondary.SecondaryStorageManagerImpl]
> (secstorage-1:null) Found a stopped secondary storage vm, bring it up to
> running pool. secStorageVm vm id : 3864
> 2013-05-23 17:50:13,212 DEBUG [cloud.capacity.CapacityManagerImpl]
> (secstorage-1:null) VM state transitted from :Stopped to Starting with event:
> StartRequestedvm's original host id: null new host id: null host id before
> state transition: null
> 2013-05-23 17:50:13,212 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (secstorage-1:null) Successfully transitioned to start state for
> VM[SecondaryStorageVm|s-3864-VM] reservation id =
> 6a001536-691b-406d-b7fe-9d8236cefc17
> 2013-05-23 17:50:13,246 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (secstorage-1:null) Trying to deploy VM, vm has dcId: 1 and podId: null
> 2013-05-23 17:50:13,246 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
> 2013-05-23 17:50:13,247 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (secstorage-1:null) Deploy avoids pods: null, clusters: null, hosts: null
> 2013-05-23 17:50:13,248 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (secstorage-1:null) DeploymentPlanner allocation algorithm:
> com.cloud.deploy.FirstFitPlanner_EnhancerByCloudStack_eb858ef2@67cb9b56
> 2013-05-23 17:50:13,248 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (secstorage-1:null) Trying to allocate a host and storage pools from dc:1,
> pod:null,cluster:null, requested cpu: 500, requested ram: 268435456
> 2013-05-23 17:50:13,248 DEBUG [cloud.deploy.DeploymentPlanningManagerImpl]
> (secstorage-1:null) Is ROOT volume READY (pool already allocated)?: No
> 2013-05-23 17:50:13,248 DEBUG [cloud.deploy.FirstFitPlanner]
> (secstorage-1:null) Searching all possible resources under this Zone: 1
> 2013-05-23 17:50:13,248 DEBUG [cloud.deploy.FirstFitPlanner]
> (secstorage-1:null) Listing clusters in order of aggregate capacity, that
> have (atleast one host with) enough CPU and RAM capacity under this Zone: 1
> 2013-05-23 17:50:13,250 DEBUG [cloud.deploy.FirstFitPlanner]
> (secstorage-1:null) No clusters found having a host with enough capacity,
> returning.
> 2013-05-23 17:50:13,313 DEBUG [cloud.capacity.CapacityManagerImpl]
> (secstorage-1:null) VM state transitted from :Starting to Stopped with event:
> OperationFailedvm's original host id: null new host id: null host id before
> state transition: null
> 2013-05-23 17:50:13,314 WARN [storage.secondary.SecondaryStorageManagerImpl]
> (secstorage-1:null) Exception while trying to start secondary storage vm
> com.cloud.exception.InsufficientServerCapacityException: Unable to create a
> deployment for VM[SecondaryStorageVm|s-3864-VM]Scope=interface
> com.cloud.dc.DataCenter; id=1
> at
> com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:813)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550)
> at
> com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:543)
> at
> com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:262)
> at
> com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:687)
> at
> com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1303)
> at
> com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
> at
> com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
> at
> com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
> at
> com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at
> com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at
> java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:679)
> 2013-05-23 17:50:13,315 INFO [storage.secondary.SecondaryStorageManagerImpl]
> (secstorage-1:null) Unable to start secondary storage vm for standby
> capacity, secStorageVm vm Id : 3864, will recycle it and start a new one
> 2013-05-23 17:50:13,317 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (secstorage-1:null) VM is already stopped: VM[SecondaryStorageVm|s-3864-VM]
> 2013-05-23 17:50:13,329 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
> (consoleproxy-1:null) Zone 1 is ready to launch console proxy
> 2013-05-23 17:50:13,364 DEBUG [cloud.capacity.CapacityManagerImpl]
> (secstorage-1:null) VM state transitted from :Stopped to Expunging with
> event: ExpungeOperationvm's original host id: null new host id: null host id
> before state transition: null
> 2013-05-23 17:50:13,365 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (secstorage-1:null) Destroying vm VM[SecondaryStorageVm|s-3864-VM]
> 2013-05-23 17:50:13,365 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (secstorage-1:null) Cleaning up NICS
> 2013-05-23 17:50:13,365 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Cleaning network for vm: 3864
> 2013-05-23 17:50:13,419 DEBUG [network.guru.DirectNetworkGuru]
> (secstorage-1:null) Deallocate network: networkId: 204, ip: null
> 2013-05-23 17:50:13,464 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Removed nic id=15280
> 2013-05-23 17:50:13,465 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Revoving nic secondary ip entry ...
> 2013-05-23 17:50:13,515 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Removed nic id=15281
> 2013-05-23 17:50:13,516 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Revoving nic secondary ip entry ...
> 2013-05-23 17:50:13,590 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Removed nic id=15282
> 2013-05-23 17:50:13,591 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Revoving nic secondary ip entry ...
> 2013-05-23 17:50:13,683 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Removed nic id=15283
> 2013-05-23 17:50:13,683 DEBUG [cloud.network.NetworkManagerImpl]
> (secstorage-1:null) Revoving nic secondary ip entry ...
> 2013-05-23 17:50:13,685 DEBUG [cloud.storage.VolumeManagerImpl]
> (secstorage-1:null) Cleaning storage for vm: 3864
> 2013-05-23 17:50:13,712 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) HostStatsCollector is running...
> 2013-05-23 17:50:13,827 DEBUG [cloud.vm.VirtualMachineManagerImpl]
> (secstorage-1:null) Expunged VM[SecondaryStorageVm|s-3864-VM]
> 2013-05-23 17:50:13,844 INFO
> [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null)
> Primary secondary storage is not even started, wait until next turn
> Watch all the nulls everywhere.
> I checked the database, but the table "vm_instance" has a lot of NULL values.
> For example private_macaddress, private_ip_address, disk_offering_id, etc.
> The resource allocation for this SystemVM seems to fail which prevents it
> from being deployed.
> Any ideas?
--
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
