Hi All,
I'm new to cloudstack and our production environment is having cloudstack as an
in-house cloud. The first task was given to me to update expiring console SSL
certificate.
I went through all the wiki pages on how to upload cert, private key, root CA &
intermediate CA. (Note: before uploading the same I had taken old keystore
table backup.)
Restarted cloud management service.
But now console system VM is in the stopped state and when I try to start then
it goes to running state and then back to the stopped state.
I had done grep on log file for this VM and same is attached to the email.
I know this might be an old query, but it will be helpful if someone guide me
further or point me to old archive.
Thanks & Regards,
Amit Dalia
2018-02-07 05:13:18,726 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Successfully transitioned to start state for
VM[ConsoleProxy|v-39029-VM] reservation id =
dfc49231-cc16-4dd1-a886-84ffacdbb846
2018-02-07 05:13:18,732 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-2:null) Ping from 45
2018-02-07 05:13:18,736 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Trying to deploy VM, vm has dcId: 2 and podId: 3
2018-02-07 05:13:18,736 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Deploy avoids pods: null, clusters: null, hosts:
null
2018-02-07 05:13:18,738 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Root volume is ready, need to place VM in volume's
cluster
2018-02-07 05:13:18,738 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Vol[38516|vm=39029|ROOT] is READY, changing
deployment plan to use this pool's dcId: 2 , podId: 3 , and clusterId: 25
2018-02-07 05:13:18,738 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Vol[38516|vm=39029|ROOT] is READY, changing
deployment plan to use this pool's dcId: 2 , podId: 3 , and clusterId: 25
2018-02-07 05:13:18,740 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-106325) DeploymentPlanner allocation algorithm:
userdispersing
2018-02-07 05:13:18,740 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-106325) Trying to allocate a host and storage pools from
dc:2, pod:3,cluster:25, requested cpu: 500, requested ram: 1073741824
2018-02-07 05:13:18,740 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-106325) Trying to allocate a host and storage pools from
dc:2, pod:3,cluster:25, requested cpu: 500, requested ram: 1073741824
2018-02-07 05:13:18,740 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-106325) Is ROOT volume READY (pool already allocated)?: Yes
2018-02-07 05:13:18,740 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-106325) This VM has last host_id specified, trying to
choose the same host: 158
018-02-07 05:13:18,740 DEBUG [cloud.deploy.FirstFitPlanner]
(Job-Executor-3:job-106325) This VM has last host_id specified, trying to
choose the same host: 158
2018-02-07 05:13:18,741 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) Checking if host: 158 has enough capacity for
requested CPU: 500 and requested RAM: 1073741824 , cpuOverprovisioningFactor:
1.5
2018-02-07 05:13:18,744 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) Hosts's actual total CPU: 59976 and CPU after
applying overprovisioning: 89964
2018-02-07 05:13:18,744 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) We need to allocate to the last host again, so
checking if there is enough reserved capacity
--
2018-02-07 05:13:18,751 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Deployment found - P0=VM[ConsoleProxy|v-39029-VM],
P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))]
: Dest[Zone(2)-Pod(3)-Cluster(25)-Host(158)-Storage()]
2018-02-07 05:13:18,755 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) VM state transitted from :Starting to Starting with
event: OperationRetryvm's original host id: 158 new host id: 158 host id before
state transition: null
2018-02-07 05:13:18,757 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-43:null) Ping from 294
2018-02-07 05:13:18,765 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) Hosts's actual total CPU: 59976 and CPU after
applying overprovisioning: 89964
2018-02-07 05:13:18,765 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) We are allocating VM, increasing the used capacity
of this host:158
2018-02-07 05:13:18,765 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) Current Used CPU: 49652 , Free CPU:39812 ,Requested
CPU: 500
2018-02-07 05:13:18,765 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) Current Used RAM: 51808043008 , Free
RAM:150177312768 ,Requested RAM: 1073741824
2018-02-07 05:13:18,765 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) CPU STATS after allocation: for host: 158, old
used: 49652, old reserved: 500, actual total: 59976, total with
overprovisioning: 89964; new used:50152, reserved:500; requested
cpu:500,alloc_from_last:false
2018-02-07 05:13:18,765 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) RAM STATS after allocation: for host: 158, old
used: 51808043008, old reserved: 1073741824, total: 203059097600; new used:
52881784832, reserved: 1073741824; requested mem:
1073741824,alloc_from_last:false
2018-02-07 05:13:18,772 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) VM is being started in podId: 3
2018-02-07 05:13:18,776 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Network id=204 is already implemented
2018-02-07 05:13:18,803 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking JuniperSRX to prepare for
Nic[102480-39029-null-172.21.65.11]
2018-02-07 05:13:18,803 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking Netscaler to prepare for
Nic[102480-39029-null-172.21.65.11]
2018-02-07 05:13:18,803 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking Netscaler to prepare for
Nic[102480-39029-null-172.21.65.11]
2018-02-07 05:13:18,803 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking F5BigIp to prepare for
Nic[102480-39029-null-172.21.65.11]
2018-02-07 05:13:18,803 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking VirtualRouter to prepare for
Nic[102480-39029-null-172.21.65.11]
--
2018-02-07 05:13:18,847 DEBUG [network.guru.PodBasedNetworkGuru]
(Job-Executor-3:job-106325) Allocated a nic
NicProfile[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846 for
VM[ConsoleProxy|v-39029-VM]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking JuniperSRX to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking Netscaler to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking F5BigIp to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking VirtualRouter to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking VirtualRouter to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking Ovs to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking Ovs to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking ExternalDhcpServer to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking BareMetal to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,850 DEBUG [cloud.network.NetworkManagerImpl]
(Job-Executor-3:job-106325) Asking SecurityGroupProvider to prepare for
Nic[102482-39029-dfc49231-cc16-4dd1-a886-84ffacdbb846-172.21.64.55]
2018-02-07 05:13:18,852 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-3:job-106325) Checking if we need to prepare 1 volumes for
VM[ConsoleProxy|v-39029-VM]
2018-02-07 05:13:18,852 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-3:job-106325) No need to recreate the volume:
Vol[38516|vm=39029|ROOT], since it already has a pool assigned: 363, adding
disk to VM
2018-02-07 05:13:18,852 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-3:job-106325) No need to recreate the volume:
Vol[38516|vm=39029|ROOT], since it already has a pool assigned: 363, adding
disk to VM
2018-02-07 05:13:18,857 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(Job-Executor-3:job-106325) Boot Args for VM[ConsoleProxy|v-39029-VM]:
template=domP type=consoleproxy host=172.21.129.129 port=8250 name=v-39029-VM
premium=true zone=2 pod=3 guid=Proxy.39029 proxy_vm=39029
disable_rp_filter=true eth2ip=172.21.65.11 eth2mask=255.255.255.192
gateway=172.21.65.1 eth0ip=169.254.2.152 eth0mask=255.255.0.0
eth1ip=172.21.64.55 eth1mask=255.255.255.192 mgmtcidr=172.21.129.0/25
localgw=172.21.64.1 internaldns1=172.21.65.72 dns1=172.21.65.72
dns2=172.21.65.74
2018-02-07 05:13:18,866 DEBUG [agent.transport.Request]
(Job-Executor-3:job-106325) Seq 158-2083192843: Sending { Cmd , MgmtId:
233845173793706, via: 158, Ver: v1, Flags: 100111,
[{"StartCommand":{"vm":{"id":39029,"name":"v-39029-VM","type":"ConsoleProxy","cpus":1,"speed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Debian
GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy
host=172.21.129.129 port=8250 name=v-39029-VM premium=true zone=2 pod=3
guid=Proxy.39029 proxy_vm=39029 disable_rp_filter=true eth2ip=172.21.65.11
eth2mask=255.255.255.192 gateway=172.21.65.1 eth0ip=169.254.2.152
eth0mask=255.255.0.0 eth1ip=172.21.64.55 eth1mask=255.255.255.192
mgmtcidr=172.21.129.0/25 localgw=172.21.64.1 internaldns1=172.21.65.72
dns1=172.21.65.72
dns2=172.21.65.74","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"f24b341f5c40dbd1","params":{},"disks":[{"id":38516,"name":"ROOT-39029","mountPoint":"/primary/ams2z2p1c4","path":"cf268831-19f1-4883-9693-3fe074e969ed","size":139264,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"e9bee434-caaa-375d-b443-b31509e0ade3","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"ip":"172.21.65.11","netmask":"255.255.255.192","gateway":"172.21.65.1","mac":"06:c3:dc:00:00:0a","dns1":"172.21.65.72","dns2":"172.21.65.74","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://2502","isolationUri":"vlan://2502","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"ip":"169.254.2.152","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:98","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"ip":"172.21.64.55","netmask":"255.255.255.192","gateway":"172.21.64.1","mac":"06:c7:00:00:00:05","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"wait":0}},{"check.CheckSshCommand":{"ip":"169.254.2.152","port":3922,"interval":6,"retries":100,"name":"v-39029-VM","wait":0}}]
}
2018-02-07 05:13:18,869 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) Ping from 371
2018-02-07 05:13:19,038 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-36:null) Ping from 358
2018-02-07 05:13:19,074 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-29:null) Ping from 442
2018-02-07 05:13:19,097 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-135:null) Ping from 332
2018-02-07 05:13:19,116 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-95:null) Ping from 269
2018-02-07 05:13:19,130 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-68:null) Ping from 389
2018-02-07 05:13:19,156 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-64:null) Ping from 21
2018-02-07 05:13:19,213 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-25:null) Ping from 192
2018-02-07 05:13:19,235 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-80:null) Cleanup succeeded. Details null
2018-02-07 05:13:19,235 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 253-859242510: Received: { Ans: , MgmtId: 233845173793706, via: 253, Ver:
v1, Flags: 10, { GetVmStatsAnswer } }
2018-02-07 05:13:19,235 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-3:null) Cleanup succeeded. Details null
2018-02-07 05:13:19,242 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-42:null) Ping from 130
2018-02-07 05:13:19,252 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-31:null) Ping from 16
2018-02-07 05:13:19,263 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-53:null) Ping from 365
2018-02-07 05:13:19,265 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-124:null) Ping from 198
--
2018-02-07 05:14:06,977 DEBUG [agent.transport.Request]
(AgentManager-Handler-108:null) Seq -1-0: Processing the first command { Cmd ,
MgmtId: -1, via: -1, Ver: v1, Flags: 101,
[{"StartupProxyCommand":{"proxyPort":80,"proxyVmId":39029,"type":"ConsoleProxy","dataCenter":"2","pod":"3","guid":"Proxy.39029-ConsoleProxyResource","name":"v-39029-VM","version":"3.0.2.20120506223416","iqn":"NoIqn","publicIpAddress":"172.21.65.11","publicNetmask":"255.255.255.192","publicMacAddress":"06:c3:dc:00:00:0a","privateIpAddress":"172.21.64.55","privateMacAddress":"06:c7:00:00:00:05","privateNetmask":"255.255.255.192","storageIpAddress":"172.21.64.55","storageNetmask":"255.255.255.192","storageMacAddress":"06:c7:00:00:00:05","resourceName":"ConsoleProxyResource","wait":0}}]
}
2018-02-07 05:14:06,983 DEBUG [cloud.resource.ResourceManagerImpl]
(AgentManager-Handler-108:null) Dispatching resource state event
CREATE_HOST_VO_FOR_CONNECTED to
ConsoleProxyManagerImpl$$EnhancerByCGLIB$$a1ad7652
2018-02-07 05:14:07,012 DEBUG [cloud.resource.ResourceState]
(AgentManager-Handler-108:null) Resource state update: [id = 16155; name =
v-39029-VM; old state = Enabled; event = InternalCreated; new state = Enabled]
2018-02-07 05:14:07,012 DEBUG [cloud.host.Status]
(AgentManager-Handler-108:null) Transition:[Resource state = Enabled, Agent
event = AgentConnected, Host id = 16155, name = v-39029-VM]
2018-02-07 05:14:07,016 DEBUG [cloud.host.Status]
(AgentManager-Handler-108:null) Agent status update: [id = 16155; name =
v-39029-VM; old status = Disconnected; event = AgentConnected; new status =
Connecting; old update count = 4157; new update count = 4158]
2018-02-07 05:14:07,016 DEBUG [agent.manager.ClusteredAgentManagerImpl]
(AgentManager-Handler-108:null) create ClusteredAgentAttache for 16155
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
XcpServerDiscoverer$$EnhancerByCGLIB$$fca62e51
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
VmwareManagerImpl$$EnhancerByCGLIB$$3af8539d
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
ClusteredVirtualMachineManagerImpl$$EnhancerByCGLIB$$f96eb8f6
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
SecurityGroupListener
2018-02-07 05:14:07,018 INFO [network.security.SecurityGroupListener]
(AgentManager-Handler-108:null) Received a host startup notification
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener: StoragePoolMonitor
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
SecondaryStorageListener
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
NetworkManagerImpl$$EnhancerByCGLIB$$a32e9812
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
AgentMonitor$$EnhancerByCGLIB$$13cf1a72
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener: DownloadListener
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener: UploadListener
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener: UploadListener
2018-02-07 05:14:07,018 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
LocalStoragePoolListener$$EnhancerByCGLIB$$a3bd40a6
2018-02-07 05:14:07,019 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-108:null) Sending Connect to listener:
SshKeysDistriMonitor
--
2018-02-07 05:14:07,352 DEBUG [cloud.host.Status]
(AgentManager-Handler-108:null) Transition:[Resource state = Enabled, Agent
event = Ready, Host id = 16155, name = v-39029-VM]
2018-02-07 05:14:07,356 DEBUG [cloud.host.Status]
(AgentManager-Handler-108:null) Agent status update: [id = 16155; name =
v-39029-VM; old status = Connecting; event = Ready; new status = Up; old update
count = 4158; new update count = 4159]
2018-02-07 05:14:07,727 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-91:null) Ping from 468
2018-02-07 05:14:07,824 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-128:null) Ping from 241
2018-02-07 05:14:07,884 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-44:null) Ping from 244
2018-02-07 05:14:08,030 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-71:null) Ping from 158
2018-02-07 05:14:08,339 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-130:null) Ping from 255
2018-02-07 05:14:08,363 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-109:null) Ping from 430
2018-02-07 05:14:08,447 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-6:null) Ping from 243
2018-02-07 05:14:08,563 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-20:null) Cleanup succeeded. Details null
2018-02-07 05:14:08,563 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 16-630259727: Received: { Ans: , MgmtId: 233845173793706, via: 16, Ver:
v1, Flags: 10, { GetHostStatsAnswer } }
2018-02-07 05:14:08,563 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-3:null) Cleanup succeeded. Details null
2018-02-07 05:14:08,683 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-41:null) Ping from 71
2018-02-07 05:14:08,728 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-105:null) Ping from 61
2018-02-07 05:14:08,924 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-22:null) Ping from 89
2018-02-07 05:14:08,996 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-134:null) Ping from 394
2018-02-07 05:14:09,226 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-113:null) Ping from 460
--
2018-02-07 05:14:12,602 DEBUG [agent.transport.Request]
(AgentManager-Handler-106:null) Seq 158-2083192843: Processing: { Ans: ,
MgmtId: 233845173793706, via: 158, Ver: v1, Flags: 110,
[{"StartAnswer":{"vm":{"id":39029,"name":"v-39029-VM","type":"ConsoleProxy","cpus":1,"speed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"x86_64","os":"Debian
GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy
host=172.21.129.129 port=8250 name=v-39029-VM premium=true zone=2 pod=3
guid=Proxy.39029 proxy_vm=39029 disable_rp_filter=true eth2ip=172.21.65.11
eth2mask=255.255.255.192 gateway=172.21.65.1 eth0ip=169.254.2.152
eth0mask=255.255.0.0 eth1ip=172.21.64.55 eth1mask=255.255.255.192
mgmtcidr=172.21.129.0/25 localgw=172.21.64.1 internaldns1=172.21.65.72
dns1=172.21.65.72
dns2=172.21.65.74","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"vncPassword":"f24b341f5c40dbd1","params":{},"disks":[{"id":38516,"name":"ROOT-39029","mountPoint":"/primary/ams2z2p1c4","path":"cf268831-19f1-4883-9693-3fe074e969ed","size":139264,"type":"ROOT","storagePoolType":"NetworkFilesystem","storagePoolUuid":"e9bee434-caaa-375d-b443-b31509e0ade3","deviceId":0}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"ip":"172.21.65.11","netmask":"255.255.255.192","gateway":"172.21.65.1","mac":"06:c3:dc:00:00:0a","dns1":"172.21.65.72","dns2":"172.21.65.74","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://2502","isolationUri":"vlan://2502","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"ip":"169.254.2.152","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:02:98","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"ip":"172.21.64.55","netmask":"255.255.255.192","gateway":"172.21.64.1","mac":"06:c7:00:00:00:05","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"result":true,"wait":0}},{"check.CheckSshAnswer":{"result":true,"wait":0}}]
}
2018-02-07 05:14:12,602 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-106:null) Cleanup succeeded. Details null
2018-02-07 05:14:12,602 DEBUG [agent.transport.Request]
(Job-Executor-3:job-106325) Seq 158-2083192843: Received: { Ans: , MgmtId:
233845173793706, via: 158, Ver: v1, Flags: 110, { StartAnswer, CheckSshAnswer }
}
2018-02-07 05:14:12,602 DEBUG [agent.transport.Request]
(Job-Executor-3:job-106325) Seq 158-2083192843: Received: { Ans: , MgmtId:
233845173793706, via: 158, Ver: v1, Flags: 110, { StartAnswer, CheckSshAnswer }
}
2018-02-07 05:14:12,602 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-106:null) Cleanup succeeded. Details null
2018-02-07 05:14:12,602 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Cleanup succeeded. Details null
2018-02-07 05:14:12,602 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Cleanup succeeded. Details null
2018-02-07 05:14:12,602 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-106:null) Seq 158-2083192843: No more commands found
2018-02-07 05:14:12,612 DEBUG [cloud.capacity.CapacityManagerImpl]
(Job-Executor-3:job-106325) VM state transitted from :Starting to Running with
event: OperationSucceededvm's original host id: 158 new host id: 158 host id
before state transition: 158
2018-02-07 05:14:12,612 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(Job-Executor-3:job-106325) Start completed for VM VM[ConsoleProxy|v-39029-VM]
2018-02-07 05:14:12,652 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-3:job-106325) Complete async job-106325, jobStatus: 1,
resultCode: 0, result: com.cloud.api.response.SystemVmResponse@9fdecf7
2018-02-07 05:14:12,656 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-3:job-106325) Done executing
com.cloud.api.commands.StartSystemVMCmd for job-106325
2018-02-07 05:14:12,911 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-82:null) Cleanup succeeded. Details null
2018-02-07 05:14:12,911 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 24-268566540: Received: { Ans: , MgmtId: 233845173793706, via: 24, Ver:
v1, Flags: 10, { GetHostStatsAnswer } }
2018-02-07 05:14:12,911 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-3:null) Cleanup succeeded. Details null
2018-02-07 05:14:13,875 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-45:null) Cleanup succeeded. Details null
2018-02-07 05:14:13,875 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 27-1574567951: Received: { Ans: , MgmtId: 233845173793706, via: 27, Ver:
v1, Flags: 10, { GetHostStatsAnswer } }
2018-02-07 05:14:13,875 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-3:null) Cleanup succeeded. Details null
2018-02-07 05:14:13,937 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-23:null) Async job-106325 completed
2018-02-07 05:14:14,705 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-72:null) Cleanup succeeded. Details null
2018-02-07 05:14:14,705 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 28-1016266767: Received: { Ans: , MgmtId: 233845173793706, via: 28, Ver:
v1, Flags: 10, { GetHostStatsAnswer } }
2018-02-07 05:14:14,705 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-3:null) Cleanup succeeded. Details null
2018-02-07 05:14:15,008 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-93:null) Ping from 16223
2018-02-07 05:14:15,463 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-74:null) Cleanup succeeded. Details null
2018-02-07 05:14:15,463 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 29-1367605263: Received: { Ans: , MgmtId: 233845173793706, via: 29, Ver:
v1, Flags: 10, { GetHostStatsAnswer } }
--
2018-02-07 05:14:41,624 DEBUG [agent.transport.Request] (consoleproxy-1:null)
Seq 158-2083192844: Sending { Cmd , MgmtId: 233845173793706, via: 158, Ver:
v1, Flags: 100111,
[{"StopCommand":{"isProxy":false,"vmName":"v-39029-VM","wait":0}}] }
2018-02-07 05:14:41,636 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Zone 2 is ready to launch secondary storage VM
2018-02-07 05:14:41,688 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Zone 4 is ready to launch secondary storage VM
2018-02-07 05:14:41,709 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Zone 5 is ready to launch secondary storage VM
2018-02-07 05:14:41,722 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Zone 6 is not ready to launch secondary storage VM yet
2018-02-07 05:14:41,827 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-19:null) Cleanup succeeded. Details null
2018-02-07 05:14:41,827 DEBUG [agent.transport.Request] (StatsCollector-2:null)
Seq 96-1688928273: Received: { Ans: , MgmtId: 233845173793706, via: 96, Ver:
v1, Flags: 10, { GetStorageStatsAnswer } }
2018-02-07 05:14:41,827 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-2:null) Cleanup succeeded. Details null
2018-02-07 05:14:41,905 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-108:null) Cleanup succeeded. Details null
2018-02-07 05:14:41,905 DEBUG [agent.transport.Request] (StatsCollector-1:null)
Seq 81-890634259: Received: { Ans: , MgmtId: 233845173793706, via: 81, Ver:
v1, Flags: 10, { GetVmStatsAnswer } }
2018-02-07 05:14:41,905 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-1:null) Cleanup succeeded. Details null
2018-02-07 05:14:41,935 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 routers.
2018-02-07 05:14:42,179 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-91:null) SeqA 16155--1: Processing Seq 16155--1: { Cmd ,
MgmtId: -1, via: 16155, Ver: v1, Flags: 111,
[{"ShutdownCommand":{"reason":"sig.kill","wait":0}}] }
2018-02-07 05:14:42,179 INFO [agent.manager.AgentManagerImpl]
(AgentManager-Handler-91:null) Host 16155 has informed us that it is shutting
down with reason sig.kill and detail null
2018-02-07 05:14:42,181 INFO [agent.manager.AgentManagerImpl]
(AgentTaskPool-2:null) Host 16155 is disconnecting with event ShutdownRequested
2018-02-07 05:14:42,184 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-2:null) The next status of agent 16155is Disconnected, current
status is Up
--
2018-02-07 05:14:42,198 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl]
(AgentTaskPool-2:null) Console proxy agent disconnected, proxy: v-39029-VM
2018-02-07 05:14:42,201 DEBUG [agent.manager.AgentManagerImpl]
(AgentTaskPool-2:null) Sending Disconnect to listener:
com.cloud.network.NetworkUsageManagerImpl$DirectNetworkStatsListener
2018-02-07 05:14:42,201 DEBUG [cloud.network.NetworkUsageManagerImpl]
(AgentTaskPool-2:null) Disconnected called on 16155 with status Disconnected
2018-02-07 05:14:42,201 DEBUG [cloud.host.Status] (AgentTaskPool-2:null)
Transition:[Resource state = Enabled, Agent event = ShutdownRequested, Host id
= 16155, name = v-39029-VM]
2018-02-07 05:14:42,214 DEBUG [cloud.host.Status] (AgentTaskPool-2:null) Agent
status update: [id = 16155; name = v-39029-VM; old status = Up; event =
ShutdownRequested; new status = Disconnected; old update count = 4159; new
update count = 4160]
2018-02-07 05:14:42,215 DEBUG [agent.manager.ClusteredAgentManagerImpl]
(AgentTaskPool-2:null) Notifying other nodes of to disconnect
2018-02-07 05:14:42,475 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-128:null) Cleanup succeeded. Details null
2018-02-07 05:14:42,475 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 81-890634258: Received: { Ans: , MgmtId: 233845173793706, via: 81, Ver:
v1, Flags: 10, { GetHostStatsAnswer } }
2018-02-07 05:14:42,475 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-3:null) Cleanup succeeded. Details null
2018-02-07 05:14:42,606 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-44:null) Cleanup succeeded. Details null
2018-02-07 05:14:42,606 DEBUG [agent.transport.Request] (StatsCollector-1:null)
Seq 82-1223557137: Received: { Ans: , MgmtId: 233845173793706, via: 82, Ver:
v1, Flags: 10, { GetVmStatsAnswer } }
2018-02-07 05:14:42,606 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-1:null) Cleanup succeeded. Details null
2018-02-07 05:14:42,636 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-71:null) Cleanup succeeded. Details null
2018-02-07 05:14:42,636 DEBUG [agent.transport.Request] (StatsCollector-2:null)
Seq 97-1884291087: Received: { Ans: , MgmtId: 233845173793706, via: 97, Ver:
v1, Flags: 10, { GetStorageStatsAnswer } }
2018-02-07 05:14:42,637 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-2:null) Cleanup succeeded. Details null
2018-02-07 05:14:43,299 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-130:null) Cleanup succeeded. Details null
2018-02-07 05:14:43,299 DEBUG [agent.transport.Request] (StatsCollector-1:null)
Seq 83-1901658128: Received: { Ans: , MgmtId: 233845173793706, via: 83, Ver:
v1, Flags: 10, { GetVmStatsAnswer } }
2018-02-07 05:14:43,299 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-1:null) Cleanup succeeded. Details null
2018-02-07 05:14:43,299 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(StatsCollector-1:null) Cleanup succeeded. Details null
2018-02-07 05:14:43,475 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(AgentManager-Handler-109:null) Cleanup succeeded. Details null
--
2018-02-07 05:14:48,130 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) VM[ConsoleProxy|v-39029-VM] is stopped on the host.
Proceeding to release resource held.
2018-02-07 05:14:48,145 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-89:null) Ping from 8350
2018-02-07 05:14:48,152 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-76:null) Ping from 67
2018-02-07 05:14:48,154 DEBUG [dc.dao.DataCenterIpAddressDaoImpl]
(consoleproxy-1:null) Releasing ip address for
reservationId=dfc49231-cc16-4dd1-a886-84ffacdbb846, instance=102482
2018-02-07 05:14:48,159 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Successfully released network resources for the vm
VM[ConsoleProxy|v-39029-VM]
2018-02-07 05:14:48,159 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Successfully released storage resources for the vm
VM[ConsoleProxy|v-39029-VM]
2018-02-07 05:14:48,163 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) VM state transitted from :Stopping to Stopped with event:
OperationSucceededvm's original host id: 158 new host id: null host id before
state transition: 158
2018-02-07 05:14:48,168 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) Hosts's actual total CPU: 59976 and CPU after applying
overprovisioning: 89964
2018-02-07 05:14:48,168 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) release cpu from host: 158, old used: 50152,reserved:
500, actual total: 59976, total with overprovisioning: 89964; new used:
49652,reserved:1000; movedfromreserved: false,moveToReserveredtrue
gerImpl] (consoleproxy-1:null) release cpu from host: 158, old used:
50152,reserved: 500, actual total: 59976, total with overprovisioning: 89964;
new used: 49652,reserved:1000; movedfromreserved: false,moveToReserveredtrue
2018-02-07 05:14:48,168 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) release mem from host: 158, old used:
52881784832,reserved: 1073741824, total: 203059097600; new used:
51808043008,reserved:2147483648; movedfromreserved: false,moveToReserveredtrue
2018-02-07 05:14:48,168 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) release mem from host: 158, old used:
52881784832,reserved: 1073741824, total: 203059097600; new used:
51808043008,reserved:2147483648; movedfromreserved: false,moveToReserveredtrue
2018-02-07 05:14:48,171 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Stop console proxy 91993 because of we are currently in
ResetSuspending management mode
2018-02-07 05:14:48,177 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-2:null) Ping from 279
2018-02-07 05:14:48,179 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) VM state transitted from :Running to Stopping with event:
StopRequestedvm's original host id: 16208 new host id: 16208 host id before
state transition: 16208
2018-02-07 05:14:48,182 WARN [cloud.vm.VirtualMachineManagerImpl]
(consoleproxy-1:null) Unable to stop vm VM[ConsoleProxy|v-91993-VM]
2018-02-07 05:14:48,183 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-43:null) Ping from 15221
2018-02-07 05:14:48,186 DEBUG [cloud.capacity.CapacityManagerImpl]
(consoleproxy-1:null) VM state transitted from :Stopping to Running with event:
OperationFailedvm's original host id: 16208 new host id: 16208 host id before
state transition: 16208
2018-02-07 05:14:48,188 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-107:null) Ping from 318
2018-02-07 05:14:48,192 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Reserving standby capacity is disable, skip capacity scan
2018-02-07 05:14:48,193 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-13:null) Ping from 152
