ACS4.4.0 and Xenserver 6.2 all patched.
Here is the error message for a failing snapshot
2014-11-18 10:41:53,705 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-1:ctx-2149b75d job-1186) Add job-1186 into job monitoring
2014-11-18 10:41:53,707 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-2149b75d job-1186) Executing AsyncJobVO {id:1186,
userId: 3, accountId: 2, instanceType: Snapshot, instanceId: 1, cmd:
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
{"id":"1","response":"json","sessionkey":"piP4PlGoqRRvl5qkhOrYaxtMPGI\u003d"
,"ctxDetails":"{\"com.cloud.storage.Snapshot\":\"b44be7af-bc61-4753-9ea9-90c
b262876e7\",\"com.cloud.storage.Volume\":\"13b90ebc-f408-4298-b4b7-7d2f5fb8a
19f\"}","cmdEventType":"SNAPSHOT.CREATE","ctxUserId":"3","httpmethod":"GET",
"quiescevm":"false","_":"1416325309501","volumeid":"13b90ebc-f408-4298-b4b7-
7d2f5fb8a19f","uuid":"b44be7af-bc61-4753-9ea9-90cb262876e7","ctxAccountId":"
2","ctxStartEventId":"1882"}, cmdVersion: 0, status: IN_PROGRESS,
processStatus: 0, resultCode: 0, result: null, initMsid: 34031122767759,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2014-11-18 10:41:53,708 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(catalina-exec-9:ctx-5810441b ctx-d27aafa9) submit async job-1186, details:
AsyncJobVO {id:1186, userId: 3, accountId: 2, instanceType: Snapshot,
instanceId: 1, cmd:
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
{"id":"1","response":"json","sessionkey":"piP4PlGoqRRvl5qkhOrYaxtMPGI\u003d"
,"ctxDetails":"{\"com.cloud.storage.Snapshot\":\"b44be7af-bc61-4753-9ea9-90c
b262876e7\",\"com.cloud.storage.Volume\":\"13b90ebc-f408-4298-b4b7-7d2f5fb8a
19f\"}","cmdEventType":"SNAPSHOT.CREATE","ctxUserId":"3","httpmethod":"GET",
"quiescevm":"false","_":"1416325309501","volumeid":"13b90ebc-f408-4298-b4b7-
7d2f5fb8a19f","uuid":"b44be7af-bc61-4753-9ea9-90cb262876e7","ctxAccountId":"
2","ctxStartEventId":"1882"}, cmdVersion: 0, status: IN_PROGRESS,
processStatus: 0, resultCode: 0, result: null, initMsid: 34031122767759,
completeMsid: null, lastUpdated: null, lastPolled:
null, created: null}
2014-11-18 10:41:53,718 DEBUG [c.c.a.ApiServlet]
(catalina-exec-9:ctx-5810441b ctx-d27aafa9) ===END=== 172.16.0.67 --
GET
command=createSnapshot&volumeid=13b90ebc-f408-4298-b4b7-7d2f5fb8a19f&quiesce
vm=false&response=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=141632530
9501
2014-11-18 10:41:53,825 INFO [o.a.c.a.c.u.s.CreateSnapshotCmd]
(API-Job-Executor-1:ctx-2149b75d job-1186 ctx-e45c0ae3) VOLSS:
createSnapshotCmd starts:1416325313825
2014-11-18 10:41:53,869 DEBUG [o.a.c.f.j.i.JobSerializerHelper]
(API-Job-Executor-1:ctx-2149b75d job-1186 ctx-e45c0ae3) Job GSON Builder
initialized.
2014-11-18 10:41:53,884 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-2149b75d job-1186 ctx-e45c0ae3) Sync job-1188
execution on object VmWorkJobQueue.21
2014-11-18 10:41:53,901 WARN [c.c.u.d.Merovingian2]
(API-Job-Executor-1:ctx-2149b75d job-1186 ctx-e45c0ae3) Was unable to find
lock for the key vm_instance21 and thread id 1028777108
2014-11-18 10:41:56,337 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 17-8920: Processing Seq 17-8920: { Cmd
, MgmtId: -1, via: 17, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":12,"_loa
dInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-18 10:41:56,348 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-12:null) SeqA 17-8920: Sending Seq 17-8920: { Ans: ,
MgmtId: 34031122767759, via: 17, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-18 10:41:56,962 DEBUG [c.c.a.ApiServlet]
(catalina-exec-10:ctx-bab8a7c7) ===START=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325313043
2014-11-18 10:41:57,048 DEBUG [c.c.a.ApiServlet]
(catalina-exec-10:ctx-bab8a7c7 ctx-bfc78b1f) ===END=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325313043
2014-11-18 10:41:57,205 DEBUG [c.c.s.StatsCollector]
(StatsCollector-4:ctx-7ae0471e) AutoScaling Monitor is running...
2014-11-18 10:41:59,980 DEBUG [c.c.a.ApiServlet]
(catalina-exec-13:ctx-42c503da) ===START=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325316042
2014-11-18 10:42:00,048 DEBUG [c.c.a.ApiServlet]
(catalina-exec-13:ctx-42c503da ctx-3f73ec88) ===END=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325316042
2014-11-18 10:42:02,965 DEBUG [c.c.a.ApiServlet]
(catalina-exec-3:ctx-50d2cd68) ===START=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325319041
2014-11-18 10:42:03,035 DEBUG [c.c.a.ApiServlet]
(catalina-exec-3:ctx-50d2cd68 ctx-da977302) ===END=== 172.16.0.67 --
GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325319041
2014-11-18 10:42:05,963 DEBUG [c.c.a.ApiServlet]
(catalina-exec-14:ctx-5c860177) ===START=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325322041
2014-11-18 10:42:06,034 DEBUG [c.c.a.ApiServlet]
(catalina-exec-14:ctx-5c860177 ctx-5db1d308) ===END=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325322041
2014-11-18 10:42:06,072 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-4b419eda) Found 0 routers to update status.
2014-11-18 10:42:06,076 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:ctx-4b419eda) Found 0 networks to update RvR status.
2014-11-18 10:42:06,229 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(HostReservationReleaseChecker:ctx-74937272) Checking if any host
reservation can be released ...
2014-11-18 10:42:06,242 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
(HostReservationReleaseChecker:ctx-74937272) Done running
HostReservationReleaseChecker ...
2014-11-18 10:42:06,330 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Running Capacity Checker ...
2014-11-18 10:42:06,330 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) recalculating system capacity
2014-11-18 10:42:06,330 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Executing cpu/ram capacity update
2014-11-18 10:42:06,340 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 17-8921: Processing Seq 17-8921: { Cmd
, MgmtId: -1, via: 17, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":12,"_loa
dInfo":"{\n \"connections\": []\n}","wait":0}}] }
2014-11-18 10:42:06,343 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) Found 3 VMs on host 1
2014-11-18 10:42:06,352 DEBUG [c.c.a.m.AgentManagerImpl]
(AgentManager-Handler-14:null) SeqA 17-8921: Sending Seq 17-8921: { Ans: ,
MgmtId: 34031122767759, via: 17, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2014-11-18 10:42:06,355 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) Found 0 VM, not running on host 1
2014-11-18 10:42:06,357 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) No need to calibrate cpu capacity, host:1
usedCpu: 2000 reservedCpu: 0
2014-11-18 10:42:06,357 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) No need to calibrate memory capacity, host:1
usedMem: 1744830464 reservedMem: 0
2014-11-18 10:42:06,382 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) Found 2 VMs on host 4
2014-11-18 10:42:06,403 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) Found 0 VM, not running on host 4
2014-11-18 10:42:06,411 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) No need to calibrate cpu capacity, host:4
usedCpu: 1500 reservedCpu: 0
2014-11-18 10:42:06,412 DEBUG [c.c.c.CapacityManagerImpl]
(CapacityChecker:ctx-112e4df3) No need to calibrate memory capacity, host:4
usedMem: 2147483648 reservedMem: 0
2014-11-18 10:42:06,420 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Done executing cpu/ram capacity update
2014-11-18 10:42:06,420 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Executing storage capacity update
2014-11-18 10:42:06,438 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-112e4df3) Found storage pool HP-MSA1000-1 of type
PreSetup
2014-11-18 10:42:06,438 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-112e4df3) Total over provisioned capacity of the pool
HP-MSA1000-1 id: 1 is 1825348517888
2014-11-18 10:42:06,452 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-112e4df3) Successfully set Capacity - 1825348517888 for
capacity type - 3 , DataCenterId - 1, HostOrPoolId - 1, PodId 1
2014-11-18 10:42:06,467 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-112e4df3) Found storage pool HP-MSA1000-2 of type
PreSetup
2014-11-18 10:42:06,467 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-112e4df3) Total over provisioned capacity of the pool
HP-MSA1000-2 id: 3 is 1698189803520
2014-11-18 10:42:06,467 DEBUG [c.c.s.StorageManagerImpl]
(CapacityChecker:ctx-112e4df3) Successfully set Capacity - 1698189803520 for
capacity type - 3 , DataCenterId - 1, HostOrPoolId - 3, PodId 1
2014-11-18 10:42:06,467 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Done executing storage capacity update
2014-11-18 10:42:06,467 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Executing capacity updates for public ip and
Vlans
2014-11-18 10:42:06,519 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Done capacity updates for public
ip and Vlans
2014-11-18 10:42:06,519 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Executing capacity updates for private ip
2014-11-18 10:42:06,542 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Done executing capacity updates for private
ip
2014-11-18 10:42:06,542 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Done recalculating system capacity
2014-11-18 10:42:06,606 DEBUG [c.c.a.AlertManagerImpl]
(CapacityChecker:ctx-112e4df3) Done running Capacity Checker ...2014-11-18
10:42:07,036 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-17b26d8a)
StorageCollector is running...
2014-11-18 10:42:07,114 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-17b26d8a) Seq 23-9145121993329214568: Received:
{ Ans: , MgmtId: 34031122767759, via: 23, Ver: v1, Flags: 10, {
GetStorageStatsAnswer } }
2014-11-18 10:42:07,123 DEBUG [c.c.a.m.ClusteredAgentAttache]
(StatsCollector-3:ctx-17b26d8a) Seq 4-8070169057271221486: Forwarding null
to 78036335168611
2014-11-18 10:42:08,492 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-17b26d8a) Seq 4-8070169057271221486: Received: { Ans:
, MgmtId: 34031122767759, via: 4, Ver: v1, Flags: 10, {
GetStorageStatsAnswer } }
2014-11-18 10:42:08,501 DEBUG [c.c.a.m.ClusteredAgentAttache]
(StatsCollector-3:ctx-17b26d8a) Seq 1-6979172047540718937: Forwarding null
to 78036335168611
2014-11-18 10:42:08,899 DEBUG [c.c.a.t.Request]
(StatsCollector-3:ctx-17b26d8a) Seq 1-6979172047540718937: Received: { Ans:
, MgmtId: 34031122767759, via: 1, Ver: v1, Flags: 10, {
GetStorageStatsAnswer } }
2014-11-18 10:42:09,036 DEBUG [c.c.a.ApiResponseHelper]
(API-Job-Executor-1:ctx-2149b75d job-1186 ctx-e45c0ae3) Unable
to find info for image store snapshot with uuid
b44be7af-bc61-4753-9ea9-90cb262876e7
2014-11-18 10:42:09,042 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-2149b75d job-1186 ctx-e45c0ae3) Complete async
job-1186, jobStatus: SUCCEEDED, resultCode: 0, result:
org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"b44be7af
-bc61-4753-9ea9-90cb262876e7","account":"dasia","domainid":"ab8d2a81-e86d-44
b6-ba90-97a87cbd58ee","domain":"Dasia.Net","snapshottype":"MANUAL","volumeid
":"13b90ebc-f408-4298-b4b7-7d2f5fb8a19f","volumename":"ROOT-21","volumetype"
:"ROOT","created":"2014-11-18T10:41:53-0500","name":"dzabmon_ROOT-21_2014111
8154153","intervaltype":"MANUAL","state":"Error","tags":[],"revertable":fals
e}
2014-11-18 10:42:09,046 DEBUG [c.c.a.ApiServlet]
(catalina-exec-11:ctx-5d57011e) ===START=== 172.16.0.67 -- GET
command=queryAsyncJobResult&jobId=8189879c-21d0-4905-a795-d88f41aae501&respo
nse=json&sessionkey=piP4PlGoqRRvl5qkhOrYaxtMPGI%3D&_=1416325325041
2014-11-18 10:42:09,072 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-1:ctx-2149b75d job-1186) Done executing
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
job-1186
2014-11-18 10:42:09,090 INFO [o.a.c.f.j.i.AsyncJobMonitor]
(API-Job-Executor-1:ctx-2149b75d job-1186) Remove job-1186
from job monitoring
Catalina.out
Add job-1186 into job monitoring
INFO [o.a.c.a.c.u.s.CreateSnapshotCmd] (API-Job-Executor-1:ctx-2149b75d
job-1186 ctx-e45c0ae3) VOLSS: createSnapshotCmd starts:1416325313825
WARN [c.c.u.d.Merovingian2] (API-Job-Executor-1:ctx-2149b75d job-1186
ctx-e45c0ae3) Was unable to find lock for the key vm_instance21 and thread
id 1028777108
INFO [o.a.c.f.j.i.AsyncJobMonitor] (API-Job-Executor-1:ctx-2149b75d
job-1186) Remove job-1186 from job monitoring
CONFIDENTIAL: This electronic mail, including any attachment(s) may contain
information that is privileged, confidential, and/or otherwise protected
from disclosure to anyone other than its intended recipient(s). Any
dissemination or use of this electronic email or its contents (including any
attachments) by persons other than the intended recipient(s) is strictly
prohibited. If you have received this message in error, please notify me
immediately by reply email so that I may correct my internal records.
Please then delete the original message (including any attachments) in its
entirety. Thank you.
