tsinik-dw commented on issue #5916:
URL: https://github.com/apache/cloudstack/issues/5916#issuecomment-1034673218
Hi @slavkap, I had to reproduce the error. So, I am trying to attach the
volume named _DATA-on-NFS-for-VM-B1_ on the VM named _VM-B1_. The _VM-B1_ has
already a ROOT volume on solidfire.
Following is the management log output:
~~~
tail -f /var/log/cloudstack/management/management-server.log
2022-02-10 11:02:43,282 DEBUG [c.c.a.ApiServer]
(qtp1603198149-16:ctx-a905112a ctx-94fcf9b2) (logid:e2809762) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:02:43,361 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-16:ctx-a905112a ctx-94fcf9b2) (logid:e2809762) ===END===
213.140.132.130 -- GET
jobId=778d0ee6-79cc-4ef3-a48e-ebf39c367fe3&command=queryAsyncJobResult&response=json
2022-02-10 11:02:43,404 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-19:ctx-144b9da0) (logid:cac4a4f2) ===START=== 213.140.132.130
-- GET listall=true&page=1&pagesize=20&command=listVolumesMetrics&response=json
2022-02-10 11:02:43,415 DEBUG [c.c.a.ApiServer]
(qtp1603198149-19:ctx-144b9da0 ctx-c347609e) (logid:cac4a4f2) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:02:43,468 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-19:ctx-144b9da0 ctx-c347609e) (logid:cac4a4f2) ===END===
213.140.132.130 -- GET
listall=true&page=1&pagesize=20&command=listVolumesMetrics&response=json
2022-02-10 11:02:45,164 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-11:null) (logid:) SeqA 2-36239: Processing Seq 2-36239:
{ Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:02:45,172 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-11:null) (logid:) SeqA 2-36239: Sending Seq 2-36239: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:02:46,875 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-3:ctx-e44acec5) (logid:efc3517a) HA health check
task is running...
2022-02-10 11:02:50,166 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-15:null) (logid:) SeqA 2-36240: Processing Seq 2-36240:
{ Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:02:50,273 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-15:null) (logid:) SeqA 2-36240: Sending Seq 2-36240: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:02:50,877 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-3:ctx-8dafd8bd) (logid:01972d94) HA health check
task is running...
2022-02-10 11:02:52,993 DEBUG [c.c.s.StatsCollector]
(secstorage-1:ctx-d2b730cf) (logid:73b83e3b) Verifying image storage [1].
Capacity: total=[446 GB], used=[30 GB], threshold=[89.99999761581421%].
2022-02-10 11:02:53,000 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-d2b730cf) (logid:73b83e3b) Zone [1] is ready to launch
secondary storage VM.
2022-02-10 11:02:53,491 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-17fda104) (logid:3f2706c5) Zone 1 is ready to launch
console proxy
2022-02-10 11:02:53,905 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterMonitor-1:ctx-5bf19c7f) (logid:a8791374) Found 2 running routers.
2022-02-10 11:02:53,917 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-231:ctx-a8679f3b) (logid:6b7b071f) Seq 1-4395794711290366163:
Executing request
2022-02-10 11:02:53,923 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-b28657b9) (logid:049df982) Found 2 routers to update
status.
2022-02-10 11:02:53,926 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-b28657b9) (logid:049df982) Found 0 VPC's to update
Redundant State.
2022-02-10 11:02:53,929 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-b28657b9) (logid:049df982) Found 0 networks to
update RvR status.
2022-02-10 11:02:53,934 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-231:ctx-a8679f3b) (logid:a8791374) Executing command in VR:
/opt/cloud/bin/router_proxy.sh netusage.sh 169.254.106.30 -g
2022-02-10 11:02:54,219 INFO [c.c.r.ResourceLimitManagerImpl]
(ResourceCountChecker-1:ctx-88301ce6) (logid:01a2b55c) Started resource
counters recalculation periodic task.
2022-02-10 11:02:54,320 DEBUG [c.c.n.ExternalDeviceUsageManagerImpl]
(ExternalNetworkMonitor-1:ctx-83247c5d) (logid:1af2467b) External devices are
not used. Skipping external device usage collection
2022-02-10 11:02:54,806 DEBUG [o.a.c.b.BackupManagerImpl]
(BackupPollTask:ctx-1322f7db) (logid:88ac6fcc) Backup backup.poll is being
called at 2022-02-10 09:02:54 GMT
2022-02-10 11:02:54,879 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-aea72511) (logid:5b2e3e60) HA health check
task is running...
2022-02-10 11:02:55,129 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) (logid:) SeqA 2-36241: Processing Seq 2-36241: {
Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:02:55,180 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-8:null) (logid:) SeqA 2-36241: Sending Seq 2-36241: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:02:55,362 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-6c976a69) (logid:105c6d41) Snapshot scheduler.poll is
being called at 2022-02-10 09:02:55 GMT
2022-02-10 11:02:55,363 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-6c976a69) (logid:105c6d41) Got 0 snapshots to be executed
at 2022-02-10 09:02:55 GMT
2022-02-10 11:02:55,802 DEBUG [c.c.s.StatsCollector]
(StatsCollector-6:ctx-07ae3b52) (logid:32dddba7) HostStatsCollector is
running...
2022-02-10 11:02:55,813 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-226:ctx-f8433e45) (logid:71936e8b) Seq 1-4395794711290366164:
Executing request
2022-02-10 11:02:55,859 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-226:ctx-f8433e45) (logid:32dddba7) Seq 1-4395794711290366164:
Response Received:
2022-02-10 11:02:55,860 DEBUG [c.c.a.t.Request]
(StatsCollector-6:ctx-07ae3b52) (logid:32dddba7) Seq 1-4395794711290366164:
Received: { Ans: , MgmtId: 77131838024934, via: 1(xcp1.noc-dev.localdomain),
Ver: v1, Flags: 10, { GetHostStatsAnswer } }
2022-02-10 11:02:55,871 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-232:ctx-c14dd484) (logid:2ccb7456) Seq 4-3925450025206868591:
Executing request
2022-02-10 11:02:55,909 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-232:ctx-c14dd484) (logid:32dddba7) Seq 4-3925450025206868591:
Response Received:
2022-02-10 11:02:55,909 DEBUG [c.c.a.t.Request]
(StatsCollector-6:ctx-07ae3b52) (logid:32dddba7) Seq 4-3925450025206868591:
Received: { Ans: , MgmtId: 77131838024934, via: 4(xen1), Ver: v1, Flags: 10, {
GetHostStatsAnswer } }
2022-02-10 11:02:55,917 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-230:ctx-3ee30a61) (logid:58810ba1) Seq 1-4395794711290366165:
Executing request
2022-02-10 11:02:55,938 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-230:ctx-3ee30a61) (logid:32dddba7) Seq 1-4395794711290366165:
Response Received:
2022-02-10 11:02:55,939 DEBUG [c.c.a.t.Request]
(StatsCollector-6:ctx-07ae3b52) (logid:32dddba7) Seq 1-4395794711290366165:
Received: { Ans: , MgmtId: 77131838024934, via: 1(xcp1.noc-dev.localdomain),
Ver: v1, Flags: 10, { GetGPUStatsAnswer } }
2022-02-10 11:02:55,944 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-453:ctx-9cd99514) (logid:ce8d9bcf) Seq 4-3925450025206868592:
Executing request
2022-02-10 11:02:55,981 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-453:ctx-9cd99514) (logid:32dddba7) Seq 4-3925450025206868592:
Response Received:
2022-02-10 11:02:55,982 DEBUG [c.c.a.t.Request]
(StatsCollector-6:ctx-07ae3b52) (logid:32dddba7) Seq 4-3925450025206868592:
Received: { Ans: , MgmtId: 77131838024934, via: 4(xen1), Ver: v1, Flags: 10, {
GetGPUStatsAnswer } }
2022-02-10 11:02:56,137 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-18:ctx-2780129c) (logid:ca84683b) ===START=== 213.140.132.130
-- GET
zoneid=7980e0b4-ebbd-425a-97d3-c09af5890cee&account=admin&domainid=ce4fbcaf-8031-11ec-8660-4626a7ce6ce6&state=Running&command=listVirtualMachines&response=json
2022-02-10 11:02:56,137 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-16:ctx-39f22c2a) (logid:b1eb1a29) ===START=== 213.140.132.130
-- GET
zoneid=7980e0b4-ebbd-425a-97d3-c09af5890cee&account=admin&domainid=ce4fbcaf-8031-11ec-8660-4626a7ce6ce6&state=Stopped&command=listVirtualMachines&response=json
2022-02-10 11:02:56,148 DEBUG [c.c.a.ApiServer]
(qtp1603198149-16:ctx-39f22c2a ctx-b75bfe64) (logid:b1eb1a29) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:02:56,148 DEBUG [c.c.a.ApiServer]
(qtp1603198149-18:ctx-2780129c ctx-d7453677) (logid:ca84683b) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:02:56,184 DEBUG [c.c.u.AccountManagerImpl]
(qtp1603198149-16:ctx-39f22c2a ctx-b75bfe64) (logid:b1eb1a29) Access granted to
Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2, "name":
"admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"} to Domain:1/ by
AffinityGroupAccessChecker
2022-02-10 11:02:56,186 DEBUG [c.c.u.AccountManagerImpl]
(qtp1603198149-18:ctx-2780129c ctx-d7453677) (logid:ca84683b) Access granted to
Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2, "name":
"admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"} to Domain:1/ by
AffinityGroupAccessChecker
2022-02-10 11:02:56,203 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-16:ctx-39f22c2a ctx-b75bfe64) (logid:b1eb1a29) ===END===
213.140.132.130 -- GET
zoneid=7980e0b4-ebbd-425a-97d3-c09af5890cee&account=admin&domainid=ce4fbcaf-8031-11ec-8660-4626a7ce6ce6&state=Stopped&command=listVirtualMachines&response=json
2022-02-10 11:02:56,236 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-18:ctx-2780129c ctx-d7453677) (logid:ca84683b) ===END===
213.140.132.130 -- GET
zoneid=7980e0b4-ebbd-425a-97d3-c09af5890cee&account=admin&domainid=ce4fbcaf-8031-11ec-8660-4626a7ce6ce6&state=Running&command=listVirtualMachines&response=json
2022-02-10 11:02:58,881 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-56063b75) (logid:204dcda0) HA health check
task is running...
2022-02-10 11:03:00,131 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-1:null) (logid:) SeqA 2-36242: Processing Seq 2-36242: {
Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:00,139 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-1:null) (logid:) SeqA 2-36242: Sending Seq 2-36242: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:03:00,748 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-14:ctx-6302685e) (logid:67f0b782) ===START=== 213.140.132.130
-- GET
id=3e77eb93-2ece-4675-9d7b-e14d7f38ee95&virtualmachineid=504e9a30-cec4-4c5b-8cf6-2b36af18fc9b&command=attachVolume&response=json
2022-02-10 11:03:00,761 DEBUG [c.c.a.ApiServer]
(qtp1603198149-14:ctx-6302685e ctx-aad18dda) (logid:67f0b782) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:03:00,848 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:7bf06dcd) Add job-134 into
job monitoring
2022-02-10 11:03:00,852 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(qtp1603198149-14:ctx-6302685e ctx-aad18dda) (logid:67f0b782) submit async
job-134, details: AsyncJobVO {id:134, userId: 2, accountId: 2, instanceType:
Volume, instanceId: 22, cmd:
org.apache.cloudstack.api.command.admin.volume.AttachVolumeCmdByAdmin, cmdInfo:
{"virtualmachineid":"504e9a30-cec4-4c5b-8cf6-2b36af18fc9b","response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"250","id":"3e77eb93-2ece-4675-9d7b-e14d7f38ee95","ctxDetails":"{\"interface
com.cloud.vm.VirtualMachine\":\"504e9a30-cec4-4c5b-8cf6-2b36af18fc9b\",\"interface
com.cloud.storage.Volume\":\"3e77eb93-2ece-4675-9d7b-e14d7f38ee95\"}","ctxAccountId":"2","uuid":"3e77eb93-2ece-4675-9d7b-e14d7f38ee95","cmdEventType":"VOLUME.ATTACH"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 77131838024934, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2022-02-10 11:03:00,853 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Executing
AsyncJobVO {id:134, userId: 2, accountId: 2, instanceType: Volume, instanceId:
22, cmd: org.apache.cloudstack.api.command.admin.volume.AttachVolumeCmdByAdmin,
cmdInfo:
{"virtualmachineid":"504e9a30-cec4-4c5b-8cf6-2b36af18fc9b","response":"json","ctxUserId":"2","httpmethod":"GET","ctxStartEventId":"250","id":"3e77eb93-2ece-4675-9d7b-e14d7f38ee95","ctxDetails":"{\"interface
com.cloud.vm.VirtualMachine\":\"504e9a30-cec4-4c5b-8cf6-2b36af18fc9b\",\"interface
com.cloud.storage.Volume\":\"3e77eb93-2ece-4675-9d7b-e14d7f38ee95\"}","ctxAccountId":"2","uuid":"3e77eb93-2ece-4675-9d7b-e14d7f38ee95","cmdEventType":"VOLUME.ATTACH"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 77131838024934, completeMsid: null, lastUpdated: null,
lastPolled: null, created: null, removed: null}
2022-02-10 11:03:00,862 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-14:ctx-6302685e ctx-aad18dda) (logid:67f0b782) ===END===
213.140.132.130 -- GET
id=3e77eb93-2ece-4675-9d7b-e14d7f38ee95&virtualmachineid=504e9a30-cec4-4c5b-8cf6-2b36af18fc9b&command=attachVolume&response=json
2022-02-10 11:03:00,894 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-16:ctx-dad763c7) (logid:4621c93f) ===START=== 213.140.132.130
-- GET
jobId=28b53b49-aeb6-492e-9a33-cee17ff3a69b&command=queryAsyncJobResult&response=json
2022-02-10 11:03:00,905 DEBUG [c.c.a.ApiServer]
(qtp1603198149-16:ctx-dad763c7 ctx-24d27883) (logid:4621c93f) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:03:00,938 INFO [c.c.s.VolumeApiServiceImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134 ctx-70e1c1c9) (logid:28b53b49) Trying
to attaching volume 22 to vm instance:16, update async job-134 progress status
2022-02-10 11:03:00,951 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-16:ctx-dad763c7 ctx-24d27883) (logid:4621c93f) ===END===
213.140.132.130 -- GET
jobId=28b53b49-aeb6-492e-9a33-cee17ff3a69b&command=queryAsyncJobResult&response=json
2022-02-10 11:03:00,952 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134 ctx-70e1c1c9) (logid:28b53b49) Update
async-job attachment, job-134, instanceType: Volume, instanceId: 22
2022-02-10 11:03:01,028 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134 ctx-70e1c1c9) (logid:28b53b49) Sync
job-135 execution on object VmWorkJobQueue.16
2022-02-10 11:03:01,071 DEBUG [c.c.s.VolumeApiServiceImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134 ctx-70e1c1c9) (logid:28b53b49) New
job 135, result field: null
2022-02-10 11:03:01,834 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-c9bf540d) (logid:cec320bf) Execute sync-queue
item: SyncQueueItemVO {id:60, queueId: 59, contentType: AsyncJob, contentId:
135, lastProcessMsid: 77131838024934, lastprocessNumber: 2, lastProcessTime:
Thu Feb 10 11:03:01 EET 2022, created: Thu Feb 10 11:03:01 EET 2022}
2022-02-10 11:03:01,835 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(AsyncJobMgr-Heartbeat-1:ctx-c9bf540d) (logid:cec320bf) Schedule queued job-135
2022-02-10 11:03:01,871 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:a1097037) Add
job-135 into job monitoring
2022-02-10 11:03:01,878 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Executing
AsyncJobVO {id:135, userId: 2, accountId: 2, instanceType: null, instanceId:
null, cmd: com.cloud.vm.VmWorkAttachVolume, cmdInfo:
rO0ABXNyAB9jb20uY2xvdWQudm0uVm1Xb3JrQXR0YWNoVm9sdW1lB62v-WGH4hwCAAJMAAhkZXZpY2VJZHQAEExqYXZhL2xhbmcvTG9uZztMAAh2b2x1bWVJZHEAfgABeHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAAIAAAAAAAAAAgAAAAAAAAAQdAAUVm9sdW1lQXBpU2VydmljZUltcGxwc3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAAAAAAAAW,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 77131838024934, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Thu Feb 10 11:03:01 EET 2022, removed: null}
2022-02-10 11:03:01,880 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Run VM
work job: com.cloud.vm.VmWorkAttachVolume for VM 16, job origin: 134
2022-02-10 11:03:01,885 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135 ctx-16708bf6)
(logid:28b53b49) Execute VM work job:
com.cloud.vm.VmWorkAttachVolume{"volumeId":22,"userId":2,"accountId":2,"vmId":16,"handlerName":"VolumeApiServiceImpl"}
2022-02-10 11:03:01,922 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135 ctx-16708bf6)
(logid:28b53b49) LocalStoragePoolAllocator trying to find storage pool to fit
the vm
2022-02-10 11:03:01,922 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135 ctx-16708bf6)
(logid:28b53b49) ClusterScopeStoragePoolAllocator looking for storage pool
2022-02-10 11:03:01,923 DEBUG [o.a.c.s.a.ZoneWideStoragePoolAllocator]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135 ctx-16708bf6)
(logid:28b53b49) ZoneWideStoragePoolAllocator to find storage pool
2022-02-10 11:03:01,929 WARN [o.a.c.e.o.VolumeOrchestrator]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135 ctx-16708bf6)
(logid:28b53b49) Unable to find suitable primary storage when creating volume
DATA-on-NFS-for-VM-B1
2022-02-10 11:03:01,930 ERROR [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135 ctx-16708bf6)
(logid:28b53b49) Invocation exception, caused by:
com.cloud.utils.exception.CloudRuntimeException: Unable to find suitable
primary storage when creating volume DATA-on-NFS-for-VM-B1
2022-02-10 11:03:01,930 INFO [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135 ctx-16708bf6)
(logid:28b53b49) Rethrow exception
com.cloud.utils.exception.CloudRuntimeException: Unable to find suitable
primary storage when creating volume DATA-on-NFS-for-VM-B1
2022-02-10 11:03:01,931 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Done with
run of VM work job: com.cloud.vm.VmWorkAttachVolume for VM 16, job origin: 134
2022-02-10 11:03:01,931 ERROR [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Unable to
complete AsyncJobVO {id:135, userId: 2, accountId: 2, instanceType: null,
instanceId: null, cmd: com.cloud.vm.VmWorkAttachVolume, cmdInfo:
rO0ABXNyAB9jb20uY2xvdWQudm0uVm1Xb3JrQXR0YWNoVm9sdW1lB62v-WGH4hwCAAJMAAhkZXZpY2VJZHQAEExqYXZhL2xhbmcvTG9uZztMAAh2b2x1bWVJZHEAfgABeHIAE2NvbS5jbG91ZC52bS5WbVdvcmufmbZW8CVnawIABEoACWFjY291bnRJZEoABnVzZXJJZEoABHZtSWRMAAtoYW5kbGVyTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO3hwAAAAAAAAAAIAAAAAAAAAAgAAAAAAAAAQdAAUVm9sdW1lQXBpU2VydmljZUltcGxwc3IADmphdmEubGFuZy5Mb25nO4vkkMyPI98CAAFKAAV2YWx1ZXhyABBqYXZhLmxhbmcuTnVtYmVyhqyVHQuU4IsCAAB4cAAAAAAAAAAW,
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result:
null, initMsid: 77131838024934, completeMsid: null, lastUpdated: null,
lastPolled: null, created: Thu Feb 10 11:03:01 EET 2022, removed: null}, job
origin:134
com.cloud.utils.exception.CloudRuntimeException: Unable to find suitable
primary storage when creating volume DATA-on-NFS-for-VM-B1
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolume(VolumeOrchestrator.java:654)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolumeOnPrimaryStorage(VolumeOrchestrator.java:1034)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:1658)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:3789)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3827)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
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 com.sun.proxy.$Proxy224.handleVmWorkJob(Unknown Source)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2022-02-10 11:03:01,974 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Complete
async job-135, jobStatus: FAILED, resultCode: 0, result:
rO0ABXNyAC9jb20uY2xvdWQudXRpbHMuZXhjZXB0aW9uLkNsb3VkUnVudGltZUV4Y2VwdGlvbgAAAABWTU9yAwABSQALY3NFcnJvckNvZGV4cgAaamF2YS5sYW5nLlJ1bnRpbWVFeGNlcHRpb26eXwZHCjSD5QIAAHhyABNqYXZhLmxhbmcuRXhjZXB0aW9u0P0fPho7HMQCAAB4cgATamF2YS5sYW5nLlRocm93YWJsZdXGNSc5d7jLAwAETAAFY2F1c2V0ABVMamF2YS9sYW5nL1Rocm93YWJsZTtMAA1kZXRhaWxNZXNzYWdldAASTGphdmEvbGFuZy9TdHJpbmc7WwAKc3RhY2tUcmFjZXQAHltMamF2YS9sYW5nL1N0YWNrVHJhY2VFbGVtZW50O0wAFHN1cHByZXNzZWRFeGNlcHRpb25zdAAQTGphdmEvdXRpbC9MaXN0O3hwcQB-AAh0AFJVbmFibGUgdG8gZmluZCBzdWl0YWJsZSBwcmltYXJ5IHN0b3JhZ2Ugd2hlbiBjcmVhdGluZyB2b2x1bWUgREFUQS1vbi1ORlMtZm9yLVZNLUIxdXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAAic3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAIQgAGZm9ybWF0SQAKbGluZU51bWJlckwAD2NsYXNzTG9hZGVyTmFtZXEAfgAFTAAOZGVjbGFyaW5nQ2xhc3NxAH4A
BUwACGZpbGVOYW1lcQB-AAVMAAptZXRob2ROYW1lcQB-AAVMAAptb2R1bGVOYW1lcQB-AAVMAA1tb2R1bGVWZXJzaW9ucQB-AAV4cAEAAAKOdAADYXBwdAA9b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmVuZ2luZS5vcmNoZXN0cmF0aW9uLlZvbHVtZU9yY2hlc3RyYXRvcnQAF1ZvbHVtZU9yY2hlc3RyYXRvci5qYXZhdAAMY3JlYXRlVm9sdW1lcHBzcQB-AAwBAAAECnEAfgAOcQB-AA9xAH4AEHQAHGNyZWF0ZVZvbHVtZU9uUHJpbWFyeVN0b3JhZ2VwcHNxAH4ADAEAAAZ6cQB-AA50ACZjb20uY2xvdWQuc3RvcmFnZS5Wb2x1bWVBcGlTZXJ2aWNlSW1wbHQAGVZvbHVtZUFwaVNlcnZpY2VJbXBsLmphdmF0ABtvcmNoZXN0cmF0ZUF0dGFjaFZvbHVtZVRvVk1wcHNxAH4ADAEAAA7NcQB-AA5xAH4AFXEAfgAWcQB-ABdwcHNxAH4ADAL____-cHQALWpkay5pbnRlcm5hbC5yZWZsZWN0Lk5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbHQAHU5hdGl2ZU1ldGhvZEFjY2Vzc29ySW1wbC5qYXZhdAAHaW52b2tlMHQACWphdmEuYmFzZXQABzExLjAuMTRzcQB-AAwCAAAAPnBxAH4AGnEAfgAbdAAGaW52b2tlcQB-AB1xAH4AHnNxAH4ADAIAAAArcHQAMWpkay5pbnRlcm5hbC5yZWZsZWN0LkRlbGVnYXRpbmdNZXRob2RBY2Nlc3NvckltcGx0ACFEZWxlZ2F0aW5nTWV0aG9kQWNjZXNzb3JJbXBsLmphdmFxAH4AIHEAfgAdcQB-AB5zcQB-AAwCAAACNnB0ABhqYXZhLmxhbmcucmVmbGVjdC5NZXRob2R0AAtNZXRob2QuamF2YXEAfgAgcQB-AB1xA
H4AHnNxAH4ADAEAAABrcQB-AA50ACJjb20uY2xvdWQudm0uVm1Xb3JrSm9iSGFuZGxlclByb3h5dAAaVm1Xb3JrSm9iSGFuZGxlclByb3h5LmphdmF0AA9oYW5kbGVWbVdvcmtKb2JwcHNxAH4ADAEAAA7zcQB-AA5xAH4AFXEAfgAWcQB-ACpwcHNxAH4ADAL____-cHEAfgAacQB-ABtxAH4AHHEAfgAdcQB-AB5zcQB-AAwCAAAAPnBxAH4AGnEAfgAbcQB-ACBxAH4AHXEAfgAec3EAfgAMAgAAACtwcQB-ACJxAH4AI3EAfgAgcQB-AB1xAH4AHnNxAH4ADAIAAAI2cHEAfgAlcQB-ACZxAH4AIHEAfgAdcQB-AB5zcQB-AAwBAAABWHEAfgAOdAAob3JnLnNwcmluZ2ZyYW1ld29yay5hb3Auc3VwcG9ydC5Bb3BVdGlsc3QADUFvcFV0aWxzLmphdmF0AB5pbnZva2VKb2lucG9pbnRVc2luZ1JlZmxlY3Rpb25wcHNxAH4ADAEAAADGcQB-AA50ADxvcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5mcmFtZXdvcmsuUmVmbGVjdGl2ZU1ldGhvZEludm9jYXRpb250AB9SZWZsZWN0aXZlTWV0aG9kSW52b2NhdGlvbi5qYXZhdAAPaW52b2tlSm9pbnBvaW50cHBzcQB-AAwBAAAAo3EAfgAOcQB-ADVxAH4ANnQAB3Byb2NlZWRwcHNxAH4ADAEAAABhcQB-AA50AD9vcmcuc3ByaW5nZnJhbWV3b3JrLmFvcC5pbnRlcmNlcHRvci5FeHBvc2VJbnZvY2F0aW9uSW50ZXJjZXB0b3J0ACBFeHBvc2VJbnZvY2F0aW9uSW50ZXJjZXB0b3IuamF2YXEAfgAgcHBzcQB-AAwBAAAAunEAfgAOcQB-ADVxAH4ANnEAfgA5cHBzcQB-AAwBAAAA13EAfgAOdAA0b3JnLn
NwcmluZ2ZyYW1ld29yay5hb3AuZnJhbWV3b3JrLkpka0R5bmFtaWNBb3BQcm94eXQAF0pka0R5bmFtaWNBb3BQcm94eS5qYXZhcQB-ACBwcHNxAH4ADAD_____cHQAF2NvbS5zdW4ucHJveHkuJFByb3h5MjI0cHEAfgAqcHBzcQB-AAwBAAAAZnEAfgAOdAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JwcHNxAH4ADAEAAAJscQB-AA50AD9vcmcuYXBhY2hlLmNsb3Vkc3RhY2suZnJhbWV3b3JrLmpvYnMuaW1wbC5Bc3luY0pvYk1hbmFnZXJJbXBsJDV0ABhBc3luY0pvYk1hbmFnZXJJbXBsLmphdmF0AAxydW5JbkNvbnRleHRwcHNxAH4ADAEAAAAwcQB-AA50AD5vcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lk1hbmFnZWRDb250ZXh0UnVubmFibGUkMXQAG01hbmFnZWRDb250ZXh0UnVubmFibGUuamF2YXQAA3J1bnBwc3EAfgAMAQAAADdxAH4ADnQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHBwc3EAfgAMAQAAAGZxAH4ADnQAQG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHRxAH4AUXQAD2NhbGxXaXRoQ29udGV4dHBwc3EAfgAMAQAAADRxAH4ADnEAfgBUcQB-AFF0AA5ydW5XaXRoQ29udGV4dHBwc3EAfgAMAQAAAC1
xAH4ADnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgBNcQB-AE5wcHNxAH4ADAEAAAI4cQB-AA5xAH4ASHEAfgBJcQB-AE5wcHNxAH4ADAIAAAIDcHQALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgBScQB-AB1xAH4AHnNxAH4ADAIAAAEIcHQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4ATnEAfgAdcQB-AB5zcQB-AAwCAAAEaHB0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnEAfgAdcQB-AB5zcQB-AAwCAAACdHB0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-AGNxAH4ATnEAfgAdcQB-AB5zcQB-AAwCAAADPXB0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4ATnEAfgAdcQB-AB5zcgAfamF2YS51dGlsLkNvbGxlY3Rpb25zJEVtcHR5TGlzdHq4F7Q8p57eAgAAeHB4AAAQmncIAAAAAAAAAAB4
2022-02-10 11:03:01,976 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Publish
async job-135 complete on message bus
2022-02-10 11:03:01,976 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Wake up
jobs related to job-135
2022-02-10 11:03:01,976 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Update db
status for job-135
2022-02-10 11:03:01,980 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Wake up
jobs joined with job-135 and disjoin all subjobs created from job- 135
2022-02-10 11:03:02,003 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Done
executing com.cloud.vm.VmWorkAttachVolume for job-135
2022-02-10 11:03:02,006 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(Work-Job-Executor-58:ctx-ec339d41 job-134/job-135) (logid:28b53b49) Remove
job-135 from job monitoring
2022-02-10 11:03:02,032 ERROR [c.c.a.ApiAsyncJobDispatcher]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Unexpected
exception while executing
org.apache.cloudstack.api.command.admin.volume.AttachVolumeCmdByAdmin
com.cloud.utils.exception.CloudRuntimeException: Unable to find suitable
primary storage when creating volume DATA-on-NFS-for-VM-B1
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolume(VolumeOrchestrator.java:654)
at
org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.createVolumeOnPrimaryStorage(VolumeOrchestrator.java:1034)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:1658)
at
com.cloud.storage.VolumeApiServiceImpl.orchestrateAttachVolumeToVM(VolumeApiServiceImpl.java:3789)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at
com.cloud.storage.VolumeApiServiceImpl.handleVmWorkJob(VolumeApiServiceImpl.java:3827)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
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 com.sun.proxy.$Proxy224.handleVmWorkJob(Unknown Source)
at
com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:620)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:48)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at
org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:45)
at
org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:568)
at
java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
2022-02-10 11:03:02,039 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Complete async
job-134, jobStatus: FAILED, resultCode: 530, result:
org.apache.cloudstack.api.response.ExceptionResponse/null/{"uuidList":[],"errorcode":"530","errortext":"Unable
to find suitable primary storage when creating volume DATA-on-NFS-for-VM-B1"}
2022-02-10 11:03:02,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Publish async
job-134 complete on message bus
2022-02-10 11:03:02,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Wake up jobs
related to job-134
2022-02-10 11:03:02,043 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Update db status
for job-134
2022-02-10 11:03:02,046 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Wake up jobs joined
with job-134 and disjoin all subjobs created from job- 134
2022-02-10 11:03:02,060 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Done executing
org.apache.cloudstack.api.command.admin.volume.AttachVolumeCmdByAdmin for
job-134
2022-02-10 11:03:02,061 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-38:ctx-10cfcb4f job-134) (logid:28b53b49) Remove job-134 from
job monitoring
2022-02-10 11:03:02,883 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-80836090) (logid:6137b786) HA health check
task is running...
2022-02-10 11:03:03,972 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-14:ctx-89174f60) (logid:47d1be64) ===START=== 213.140.132.130
-- GET
jobId=28b53b49-aeb6-492e-9a33-cee17ff3a69b&command=queryAsyncJobResult&response=json
2022-02-10 11:03:03,983 DEBUG [c.c.a.ApiServer]
(qtp1603198149-14:ctx-89174f60 ctx-2d6d9404) (logid:47d1be64) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:03:04,133 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-14:ctx-89174f60 ctx-2d6d9404) (logid:47d1be64) ===END===
213.140.132.130 -- GET
jobId=28b53b49-aeb6-492e-9a33-cee17ff3a69b&command=queryAsyncJobResult&response=json
2022-02-10 11:03:04,187 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-16:ctx-3662f09f) (logid:5ba9d6a9) ===START=== 213.140.132.130
-- GET listall=true&page=1&pagesize=20&command=listVolumesMetrics&response=json
2022-02-10 11:03:04,198 DEBUG [c.c.a.ApiServer]
(qtp1603198149-16:ctx-3662f09f ctx-9e232454) (logid:5ba9d6a9) CIDRs from which
account 'Acct[48ae3b86-8032-11ec-8660-4626a7ce6ce6-admin] -- Account {"id": 2,
"name": "admin", "uuid": "48ae3b86-8032-11ec-8660-4626a7ce6ce6"}' is allowed to
perform API calls: 0.0.0.0/0,::/0
2022-02-10 11:03:04,294 DEBUG [c.c.a.ApiServlet]
(qtp1603198149-16:ctx-3662f09f ctx-9e232454) (logid:5ba9d6a9) ===END===
213.140.132.130 -- GET
listall=true&page=1&pagesize=20&command=listVolumesMetrics&response=json
2022-02-10 11:03:04,294 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) Ping from 4(xen1)
2022-02-10 11:03:04,294 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) Process host VM state
report from ping process. host: 4
2022-02-10 11:03:04,308 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) Process VM state report.
host: 4, number of records in report: 4
2022-02-10 11:03:04,308 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) VM state report. host: 4,
vm id: 1, power state: PowerOn
2022-02-10 11:03:04,311 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) VM state report. host: 4,
vm id: 2, power state: PowerOn
2022-02-10 11:03:04,314 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) VM state report. host: 4,
vm id: 11, power state: PowerOn
2022-02-10 11:03:04,317 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) VM state report. host: 4,
vm id: 12, power state: PowerOn
2022-02-10 11:03:04,326 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-64:ctx-03c676f1) (logid:4f68c2d0) Done with process of VM
state report. host: 4
2022-02-10 11:03:05,172 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-10:null) (logid:) SeqA 2-36243: Processing Seq 2-36243:
{ Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:05,187 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-10:null) (logid:) SeqA 2-36243: Sending Seq 2-36243: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:03:06,267 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgentCronJob-195:ctx-4d1a5c61) (logid:286e47fa) Ping from
1(xcp1.noc-dev.localdomain)
2022-02-10 11:03:06,268 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-195:ctx-4d1a5c61) (logid:286e47fa) Process host VM state
report from ping process. host: 1
2022-02-10 11:03:06,275 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-195:ctx-4d1a5c61) (logid:286e47fa) Process VM state report.
host: 1, number of records in report: 2
2022-02-10 11:03:06,275 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-195:ctx-4d1a5c61) (logid:286e47fa) VM state report. host:
1, vm id: 16, power state: PowerOn
2022-02-10 11:03:06,278 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-195:ctx-4d1a5c61) (logid:286e47fa) VM state report. host:
1, vm id: 4, power state: PowerOn
2022-02-10 11:03:06,285 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
(DirectAgentCronJob-195:ctx-4d1a5c61) (logid:286e47fa) Done with process of VM
state report. host: 1
2022-02-10 11:03:06,885 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-5:ctx-9cac4812) (logid:bf54d9cb) HA health check
task is running...
2022-02-10 11:03:06,950 DEBUG [o.a.c.b.BackupManagerImpl]
(BackgroundTaskPollManager-1:ctx-1a6017d9) (logid:d4b6e977) Backup Sync Task is
not enabled in zone [1]. Skipping this zone!
2022-02-10 11:03:10,174 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) (logid:) SeqA 2-36244: Processing Seq 2-36244: {
Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:10,191 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-9:null) (logid:) SeqA 2-36244: Sending Seq 2-36244: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:03:10,888 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-5ad92276) (logid:f49298dd) HA health check
task is running...
2022-02-10 11:03:14,890 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-5f76d180) (logid:4deb7b3e) HA health check
task is running...
2022-02-10 11:03:15,176 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-13:null) (logid:) SeqA 2-36245: Processing Seq 2-36245:
{ Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:15,211 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-13:null) (logid:) SeqA 2-36245: Sending Seq 2-36245: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:03:15,537 ERROR [c.c.u.s.SshHelper]
(DirectAgent-231:ctx-a8679f3b) (logid:a8791374) SSH execution of command
/opt/cloud/bin/router_proxy.sh netusage.sh 169.254.106.30 -g has an error
status code in return. Result output:
2022-02-10 11:03:15,542 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-231:ctx-a8679f3b) (logid:a8791374) Seq 1-4395794711290366163:
Response Received:
2022-02-10 11:03:15,543 DEBUG [c.c.a.t.Request]
(DirectAgent-231:ctx-a8679f3b) (logid:a8791374) Seq 1-4395794711290366163:
Processing: { Ans: , MgmtId: 77131838024934, via: 1(xcp1.noc-dev.localdomain),
Ver: v1, Flags: 10,
[{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-4-VM","bytesSent":"(0
bytes) 0","bytesReceived":"(0 bytes)
0","result":"true","details":"","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:15,543 DEBUG [c.c.a.t.Request]
(RouterMonitor-1:ctx-5bf19c7f) (logid:a8791374) Seq 1-4395794711290366163:
Received: { Ans: , MgmtId: 77131838024934, via: 1(xcp1.noc-dev.localdomain),
Ver: v1, Flags: 10, { NetworkUsageAnswer } }
2022-02-10 11:03:15,543 DEBUG [c.c.a.m.AgentManagerImpl]
(RouterMonitor-1:ctx-5bf19c7f) (logid:a8791374) Details from executing class
com.cloud.agent.api.NetworkUsageCommand:
2022-02-10 11:03:15,543 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterMonitor-1:ctx-5bf19c7f) (logid:a8791374) Recieved and Sent bytes are
both 0. Not updating user_statistics
2022-02-10 11:03:15,560 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-58:ctx-8ea198cb) (logid:097bf28a) Seq 4-3925450025206868593:
Executing request
2022-02-10 11:03:15,574 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-58:ctx-8ea198cb) (logid:a8791374) Executing command in VR:
/opt/cloud/bin/router_proxy.sh netusage.sh 169.254.38.132 -g
2022-02-10 11:03:16,573 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-58:ctx-8ea198cb) (logid:a8791374) Seq 4-3925450025206868593:
Response Received:
2022-02-10 11:03:16,581 DEBUG [c.c.a.t.Request]
(DirectAgent-58:ctx-8ea198cb) (logid:a8791374) Seq 4-3925450025206868593:
Processing: { Ans: , MgmtId: 77131838024934, via: 4(xen1), Ver: v1, Flags: 10,
[{"com.cloud.agent.api.NetworkUsageAnswer":{"routerName":"r-12-VM","bytesSent":"(2.38
KB) 2432","bytesReceived":"(0 bytes)
0","result":"true","details":"","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:16,581 DEBUG [c.c.a.t.Request]
(RouterMonitor-1:ctx-5bf19c7f) (logid:a8791374) Seq 4-3925450025206868593:
Received: { Ans: , MgmtId: 77131838024934, via: 4(xen1), Ver: v1, Flags: 10, {
NetworkUsageAnswer } }
2022-02-10 11:03:16,582 DEBUG [c.c.a.m.AgentManagerImpl]
(RouterMonitor-1:ctx-5bf19c7f) (logid:a8791374) Details from executing class
com.cloud.agent.api.NetworkUsageCommand:
2022-02-10 11:03:17,113 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-458:ctx-7f1fb4a3) (logid:ca721edf) Seq 1-4395794711290366166:
Executing request
2022-02-10 11:03:17,144 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-458:ctx-7f1fb4a3) (logid:121b4976) Vm cpu utilization
8.471944444444446
2022-02-10 11:03:17,144 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-458:ctx-7f1fb4a3) (logid:121b4976) Seq 1-4395794711290366166:
Response Received:
2022-02-10 11:03:17,145 DEBUG [c.c.a.t.Request]
(StatsCollector-1:ctx-d0e71602) (logid:121b4976) Seq 1-4395794711290366166:
Received: { Ans: , MgmtId: 77131838024934, via: 1(xcp1.noc-dev.localdomain),
Ver: v1, Flags: 10, { GetVmStatsAnswer } }
2022-02-10 11:03:17,149 DEBUG [c.c.s.StatsCollector]
(StatsCollector-1:ctx-d0e71602) (logid:121b4976) Increment saved values of
NetworkReadKBs, NetworkWriteKBs, DiskWriteKBs, DiskReadKBs, DiskReadIOs,
DiskWriteIOs, with current metrics for VM with ID [16]. To change this process,
check value of 'vm.stats.increment.metrics.in.memory' configuration.
2022-02-10 11:03:17,162 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-461:ctx-3dc41513) (logid:707e5208) Seq 4-3925450025206868594:
Executing request
2022-02-10 11:03:17,202 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-461:ctx-3dc41513) (logid:121b4976) Vm cpu utilization
3.9311111111111114
2022-02-10 11:03:17,202 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-461:ctx-3dc41513) (logid:121b4976) Seq 4-3925450025206868594:
Response Received:
2022-02-10 11:03:17,202 DEBUG [c.c.a.t.Request]
(StatsCollector-1:ctx-d0e71602) (logid:121b4976) Seq 4-3925450025206868594:
Received: { Ans: , MgmtId: 77131838024934, via: 4(xen1), Ver: v1, Flags: 10, {
GetVmStatsAnswer } }
2022-02-10 11:03:17,206 DEBUG [c.c.s.StatsCollector]
(StatsCollector-1:ctx-d0e71602) (logid:121b4976) Increment saved values of
NetworkReadKBs, NetworkWriteKBs, DiskWriteKBs, DiskReadKBs, DiskReadIOs,
DiskWriteIOs, with current metrics for VM with ID [11]. To change this process,
check value of 'vm.stats.increment.metrics.in.memory' configuration.
2022-02-10 11:03:17,664 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-2:null) (logid:) Ping from 3(s-2-VM)
2022-02-10 11:03:18,892 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-8d2da898) (logid:8e10936b) HA health check
task is running...
2022-02-10 11:03:20,178 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 2-36246: Processing Seq 2-36246:
{ Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:20,199 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) (logid:) SeqA 2-36246: Sending Seq 2-36246: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:03:22,894 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-d650f7da) (logid:c247687d) HA health check
task is running...
2022-02-10 11:03:22,993 DEBUG [c.c.s.StatsCollector]
(secstorage-1:ctx-ac78d8ba) (logid:410376f2) Verifying image storage [1].
Capacity: total=[446 GB], used=[30 GB], threshold=[89.99999761581421%].
2022-02-10 11:03:23,001 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
(secstorage-1:ctx-ac78d8ba) (logid:410376f2) Zone [1] is ready to launch
secondary storage VM.
2022-02-10 11:03:23,487 DEBUG [c.c.c.ConsoleProxyManagerImpl]
(consoleproxy-1:ctx-2006d3a3) (logid:91ad0fba) Zone 1 is ready to launch
console proxy
2022-02-10 11:03:23,924 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-44205128) (logid:db154647) Found 2 routers to update
status.
2022-02-10 11:03:23,925 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-44205128) (logid:db154647) Found 0 VPC's to update
Redundant State.
2022-02-10 11:03:23,927 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-44205128) (logid:db154647) Found 0 networks to
update RvR status.
2022-02-10 11:03:24,681 DEBUG [c.c.s.StatsCollector]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) StorageCollector is running...
2022-02-10 11:03:24,693 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2022-02-10 11:03:24,693 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) We are returning the default
host to execute commands because the command is not of Copy type.
2022-02-10 11:03:24,788 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) Seq 3-6020749751840934603:
Received: { Ans: , MgmtId: 77131838024934, via: 3(s-2-VM), Ver: v1, Flags: 10,
{ GetStorageStatsAnswer } }
2022-02-10 11:03:24,792 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2022-02-10 11:03:24,792 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) We are returning the default
host to execute commands because the command is not of Copy type.
2022-02-10 11:03:24,795 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-234:ctx-3b94181b) (logid:933c0a87) Seq 1-4395794711290366167:
Executing request
2022-02-10 11:03:24,959 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Running Capacity Checker ...
2022-02-10 11:03:24,960 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) recalculating system capacity
2022-02-10 11:03:24,960 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Executing cpu/ram capacity
update
2022-02-10 11:03:24,969 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found 2 VMs on host 1
2022-02-10 11:03:24,970 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found 0 VMs are Migrating from
host 1
2022-02-10 11:03:24,975 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found 0 VM, not running on host
1
2022-02-10 11:03:24,979 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) No need to calibrate cpu
capacity, host:1 usedCpuCore: 3 reservedCpuCore: 0
2022-02-10 11:03:24,980 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) No need to calibrate cpu
capacity, host:1 usedCpu: 2500 reservedCpu: 0
2022-02-10 11:03:24,980 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) No need to calibrate memory
capacity, host:1 usedMem: (2.25 GB) 2415919104 reservedMem: (0 bytes) 0
2022-02-10 11:03:25,083 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found 4 VMs on host 4
2022-02-10 11:03:25,085 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found 0 VMs are Migrating from
host 4
2022-02-10 11:03:25,095 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found 0 VM, not running on host
4
2022-02-10 11:03:25,099 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) No need to calibrate cpu
capacity, host:4 usedCpuCore: 5 reservedCpuCore: 0
2022-02-10 11:03:25,099 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) No need to calibrate cpu
capacity, host:4 usedCpu: 3500 reservedCpu: 0
2022-02-10 11:03:25,099 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) No need to calibrate memory
capacity, host:4 usedMem: (3.75 GB) 4026531840 reservedMem: (0 bytes) 0
2022-02-10 11:03:25,106 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Done executing cpu/ram capacity
update
2022-02-10 11:03:25,106 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Executing storage capacity
update
2022-02-10 11:03:25,117 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found storage pool XCP-Primary
of type NetworkFilesystem with overprovisioning factor 2
2022-02-10 11:03:25,117 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Total over provisioned capacity
calculated is 2 * (446.77 GB) 479720112128
2022-02-10 11:03:25,117 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Total over provisioned capacity
of the pool XCP-Primary id: 1 is (893.55 GB) 959440224256
2022-02-10 11:03:25,120 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Successfully set Capacity -
(893.55 GB) 959440224256 for capacity type - 3 , DataCenterId - 1, HostOrPoolId
- 1, PodId 1
2022-02-10 11:03:25,124 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found storage pool SOLIDFIRE of
type Iscsi
2022-02-10 11:03:25,124 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Total over provisioned capacity
of the pool SOLIDFIRE id: 2 is (60.00 GB) 64424476455
2022-02-10 11:03:25,125 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Successfully set Capacity -
(60.00 GB) 64424476455 for capacity type - 3 , DataCenterId - 1, HostOrPoolId -
2, PodId null
2022-02-10 11:03:25,130 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Found storage pool
XENSERVER-Primary of type NetworkFilesystem with overprovisioning factor 2
2022-02-10 11:03:25,130 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Total over provisioned capacity
calculated is 2 * (446.77 GB) 479720112128
2022-02-10 11:03:25,130 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Total over provisioned capacity
of the pool XENSERVER-Primary id: 4 is (893.55 GB) 959440224256
2022-02-10 11:03:25,133 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Successfully set Capacity -
(893.55 GB) 959440224256 for capacity type - 3 , DataCenterId - 1, HostOrPoolId
- 4, PodId 1
2022-02-10 11:03:25,133 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Done executing storage capacity
update
2022-02-10 11:03:25,133 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Executing capacity updates for
public ip and Vlans
2022-02-10 11:03:25,157 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Done capacity updates for
public ip and Vlans
2022-02-10 11:03:25,157 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Executing capacity updates for
private ip
2022-02-10 11:03:25,165 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Done executing capacity updates
for private ip
2022-02-10 11:03:25,165 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Done recalculating system
capacity
2022-02-10 11:03:25,181 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-5:null) (logid:) SeqA 2-36247: Processing Seq 2-36247: {
Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:25,207 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-1be13c29) (logid:10d16f10) Done running Capacity Checker
...
2022-02-10 11:03:25,215 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-5:null) (logid:) SeqA 2-36247: Sending Seq 2-36247: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:03:25,268 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(HostReservationReleaseChecker:ctx-8526c946) (logid:9d1c2e01) Checking if any
host reservation can be released ...
2022-02-10 11:03:25,277 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(HostReservationReleaseChecker:ctx-8526c946) (logid:9d1c2e01) Cannot release
reservation, Found 2 VMs Running on host 1
2022-02-10 11:03:25,285 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(HostReservationReleaseChecker:ctx-8526c946) (logid:9d1c2e01) Cannot release
reservation, Found 4 VMs Running on host 4
2022-02-10 11:03:25,285 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(HostReservationReleaseChecker:ctx-8526c946) (logid:9d1c2e01) Done running
HostReservationReleaseChecker ...
2022-02-10 11:03:26,215 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-234:ctx-3b94181b) (logid:076a9bc8) Seq 1-4395794711290366167:
Response Received:
2022-02-10 11:03:26,215 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) Seq 1-4395794711290366167:
Received: { Ans: , MgmtId: 77131838024934, via: 1(xcp1.noc-dev.localdomain),
Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2022-02-10 11:03:26,218 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2022-02-10 11:03:26,218 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) We are returning the default
host to execute commands because the command is not of Copy type.
2022-02-10 11:03:26,221 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-466:ctx-164629c7) (logid:1fb19d1b) Seq 1-4395794711290366168:
Executing request
2022-02-10 11:03:26,286 WARN
[c.c.h.x.r.w.x.CitrixGetStorageStatsCommandWrapper]
(DirectAgent-466:ctx-164629c7) (logid:076a9bc8) There are 0 storageid:
2a30020a-76f9-4f47-89f1-a447739b934d
2022-02-10 11:03:26,286 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-466:ctx-164629c7) (logid:076a9bc8) Seq 1-4395794711290366168:
Response Received:
2022-02-10 11:03:26,287 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) Seq 1-4395794711290366168:
Received: { Ans: , MgmtId: 77131838024934, via: 1(xcp1.noc-dev.localdomain),
Ver: v1, Flags: 10, { GetStorageStatsAnswer } }
2022-02-10 11:03:26,289 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) getCommandHostDelegation:
class com.cloud.agent.api.GetStorageStatsCommand
2022-02-10 11:03:26,289 DEBUG [c.c.h.XenServerGuru]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) We are returning the default
host to execute commands because the command is not of Copy type.
2022-02-10 11:03:26,293 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-463:ctx-f968d00f) (logid:572b4e9c) Seq 4-3925450025206868595:
Executing request
2022-02-10 11:03:26,852 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-463:ctx-f968d00f) (logid:076a9bc8) Seq 4-3925450025206868595:
Response Received:
2022-02-10 11:03:26,853 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-7e35f862) (logid:076a9bc8) Seq 4-3925450025206868595:
Received: { Ans: , MgmtId: 77131838024934, via: 4(xen1), Ver: v1, Flags: 10, {
GetStorageStatsAnswer } }
2022-02-10 11:03:26,896 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-6:ctx-9fdeb804) (logid:42aeef01) HA health check
task is running...
2022-02-10 11:03:30,182 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-6:null) (logid:) SeqA 2-36248: Processing Seq 2-36248: {
Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":"1","_loadInfo":"{
"connections": []
}","wait":"0","bypassHostMaintenance":"false"}}] }
2022-02-10 11:03:30,405 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-6:null) (logid:) SeqA 2-36248: Sending Seq 2-36248: {
Ans: , MgmtId: 77131838024934, via: 2, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":"true","wait":"0","bypassHostMaintenance":"false"}}]
}
2022-02-10 11:03:30,899 DEBUG [o.a.c.h.HAManagerImpl]
(BackgroundTaskPollManager-3:ctx-59791c1d) (logid:f8e312c6) HA health check
task is running...
~~~
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
