[
https://issues.apache.org/jira/browse/CLOUDSTACK-4641?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13769377#comment-13769377
]
prashant kumar mishra edited comment on CLOUDSTACK-4641 at 9/17/13 9:58 AM:
----------------------------------------------------------------------------
Tested on top of commit 5e52a86a2ac8783141c99e8ab34a96fb21b8826a ,it took 3
hour to create volume from snapshot ,went successful
Log
------
-->start time 7:28
2013-09-17 07:28:39,087 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
===START=== 10.252.192.86 -- GET
command=createVolume&response=json&sessionkey=fP7mNpuqEmQhAS2IgT8UbBXHOwI%3D&snapshotid=40cf4a09-ff00-4caa-87ab-0df36e2fbea9&name=timeout&_=1379397971935
2013-09-17 07:28:39,473 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-10:null) submit async job-53 = [
620f6a05-14f0-4906-b113-91e881029cdc ], details: AsyncJobVO {id:53, userId: 2,
accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 27, cmd:
org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd, cmdOriginator:
null, cmdInfo:
{"id":"27","response":"json","sessionkey":"fP7mNpuqEmQhAS2IgT8UbBXHOwI\u003d","cmdEventType":"VOLUME.CREATE","ctxUserId":"2","snapshotid":"40cf4a09-ff00-4caa-87ab-0df36e2fbea9","name":"timeout","httpmethod":"GET","_":"1379397971935","ctxAccountId":"2","ctxStartEventId":"221"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 6895939092538,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-09-17 07:28:39,478 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
===END=== 10.252.192.86 -- GET
command=createVolume&response=json&sessionkey=fP7mNpuqEmQhAS2IgT8UbBXHOwI%3D&snapshotid=40cf4a09-ff00-4caa-87ab-0df36e2fbea9&name=timeout&_=1379397971935
2013-09-17 07:28:39,481 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Executing
org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd for job-53 = [
620f6a05-14f0-4906-b113-91e881029cdc ]
2013-09-17 07:28:39,714 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2013-09-17 07:28:39,719 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Checking if
storage pool is suitable, name: null ,poolId: 2
2013-09-17 07:28:39,724 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Checking
pool 2 for storage, totalSize: 52844687360, usedBytes: 8709701632, usedPct:
0.16481697720465047, disable threshold: 1.0
2013-09-17 07:28:39,734 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Checking
pool: 2 for volume allocation [Vol[27|vm=null|DATADISK]], maxSize :
52844687360, totalAllocatedSize : 8589934592, askingSize : 322122547200,
allocated disable threshold: 1.0
2013-09-17 07:28:39,735 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
Insufficient un-allocated capacity on: 2 for volume allocation:
[Vol[27|vm=null|DATADISK]] since its allocated percentage: 6.258197338533748
has crossed the allocated pool.storage.allocated.capacity.disablethreshold:
1.0, skipping this pool
2013-09-17 07:28:39,737 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
LocalStoragePoolAllocator returning 0 suitable storage pools
2013-09-17 07:28:39,737 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-53 =
[ 620f6a05-14f0-4906-b113-91e881029cdc ]) ClusterScopeStoragePoolAllocator
looking for storage pool
2013-09-17 07:28:39,737 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-53 =
[ 620f6a05-14f0-4906-b113-91e881029cdc ]) Looking for pools in dc: 1 pod:1
cluster:null
2013-09-17 07:28:39,741 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-53 =
[ 620f6a05-14f0-4906-b113-91e881029cdc ]) No storage pools available for local
volume allocation, returning
2013-09-17 07:28:39,742 DEBUG [storage.allocator.ZoneWideStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
ZoneWideStoragePoolAllocator to find storage pool
-->completion time 10.28
2013-09-17 10:28:40,842 DEBUG [agent.transport.Request] (Job-Executor-15:job-53
= [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Seq 1-1699480600: Received: { Ans:
, MgmtId: 6895939092538, via: 1, Ver: v1, Flags: 110, { CopyCmdAnswer } }
2013-09-17 10:28:40,847 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-12:null) Seq 1-1699480600: No more commands found
2013-09-17 10:28:40,933 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Complete
async job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ], jobStatus: 1,
resultCode: 0, result:
org.apache.cloudstack.api.response.VolumeResponse@503345a2
2013-09-17 10:28:40,997 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Done
executing org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd for
job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]
2013-09-17 10:28:41,019 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
===START=== 10.252.192.86 -- GET
command=queryAsyncJobResult&jobId=620f6a05-14f0-4906-b113-91e881029cdc&response=json&sessionkey=fP7mNpuqEmQhAS2IgT8UbBXHOwI%3D&_=1379408774322
2013-09-17 10:28:41,037 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-21:null) Async job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]
completed
was (Author: prashantkm):
Tested on top of commit 5e52a86a2ac8783141c99e8ab34a96fb21b8826a
Log
------
2013-09-17 07:28:39,087 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
===START=== 10.252.192.86 -- GET
command=createVolume&response=json&sessionkey=fP7mNpuqEmQhAS2IgT8UbBXHOwI%3D&snapshotid=40cf4a09-ff00-4caa-87ab-0df36e2fbea9&name=timeout&_=1379397971935
2013-09-17 07:28:39,473 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-10:null) submit async job-53 = [
620f6a05-14f0-4906-b113-91e881029cdc ], details: AsyncJobVO {id:53, userId: 2,
accountId: 2, sessionKey: null, instanceType: Volume, instanceId: 27, cmd:
org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd, cmdOriginator:
null, cmdInfo:
{"id":"27","response":"json","sessionkey":"fP7mNpuqEmQhAS2IgT8UbBXHOwI\u003d","cmdEventType":"VOLUME.CREATE","ctxUserId":"2","snapshotid":"40cf4a09-ff00-4caa-87ab-0df36e2fbea9","name":"timeout","httpmethod":"GET","_":"1379397971935","ctxAccountId":"2","ctxStartEventId":"221"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 6895939092538,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-09-17 07:28:39,478 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
===END=== 10.252.192.86 -- GET
command=createVolume&response=json&sessionkey=fP7mNpuqEmQhAS2IgT8UbBXHOwI%3D&snapshotid=40cf4a09-ff00-4caa-87ab-0df36e2fbea9&name=timeout&_=1379397971935
2013-09-17 07:28:39,481 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Executing
org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd for job-53 = [
620f6a05-14f0-4906-b113-91e881029cdc ]
2013-09-17 07:28:39,714 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
LocalStoragePoolAllocator trying to find storage pool to fit the vm
2013-09-17 07:28:39,719 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Checking if
storage pool is suitable, name: null ,poolId: 2
2013-09-17 07:28:39,724 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Checking
pool 2 for storage, totalSize: 52844687360, usedBytes: 8709701632, usedPct:
0.16481697720465047, disable threshold: 1.0
2013-09-17 07:28:39,734 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Checking
pool: 2 for volume allocation [Vol[27|vm=null|DATADISK]], maxSize :
52844687360, totalAllocatedSize : 8589934592, askingSize : 322122547200,
allocated disable threshold: 1.0
2013-09-17 07:28:39,735 DEBUG [cloud.storage.StorageManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
Insufficient un-allocated capacity on: 2 for volume allocation:
[Vol[27|vm=null|DATADISK]] since its allocated percentage: 6.258197338533748
has crossed the allocated pool.storage.allocated.capacity.disablethreshold:
1.0, skipping this pool
2013-09-17 07:28:39,737 DEBUG [storage.allocator.LocalStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
LocalStoragePoolAllocator returning 0 suitable storage pools
2013-09-17 07:28:39,737 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-53 =
[ 620f6a05-14f0-4906-b113-91e881029cdc ]) ClusterScopeStoragePoolAllocator
looking for storage pool
2013-09-17 07:28:39,737 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-53 =
[ 620f6a05-14f0-4906-b113-91e881029cdc ]) Looking for pools in dc: 1 pod:1
cluster:null
2013-09-17 07:28:39,741 DEBUG
[storage.allocator.ClusterScopeStoragePoolAllocator] (Job-Executor-15:job-53 =
[ 620f6a05-14f0-4906-b113-91e881029cdc ]) No storage pools available for local
volume allocation, returning
2013-09-17 07:28:39,742 DEBUG [storage.allocator.ZoneWideStoragePoolAllocator]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ])
ZoneWideStoragePoolAllocator to find storage pool
2013-09-17 10:28:40,842 DEBUG [agent.transport.Request] (Job-Executor-15:job-53
= [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Seq 1-1699480600: Received: { Ans:
, MgmtId: 6895939092538, via: 1, Ver: v1, Flags: 110, { CopyCmdAnswer } }
2013-09-17 10:28:40,847 DEBUG [agent.manager.AgentAttache]
(AgentManager-Handler-12:null) Seq 1-1699480600: No more commands found
2013-09-17 10:28:40,933 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Complete
async job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ], jobStatus: 1,
resultCode: 0, result:
org.apache.cloudstack.api.response.VolumeResponse@503345a2
2013-09-17 10:28:40,997 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-15:job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]) Done
executing org.apache.cloudstack.api.command.user.volume.CreateVolumeCmd for
job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]
2013-09-17 10:28:41,019 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
===START=== 10.252.192.86 -- GET
command=queryAsyncJobResult&jobId=620f6a05-14f0-4906-b113-91e881029cdc&response=json&sessionkey=fP7mNpuqEmQhAS2IgT8UbBXHOwI%3D&_=1379408774322
2013-09-17 10:28:41,037 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-21:null) Async job-53 = [ 620f6a05-14f0-4906-b113-91e881029cdc ]
completed
> Create volume form snapshot command times out exactly after 1 hour in case of
> KVM hosts.
> ----------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-4641
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4641
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Components: KVM
> Affects Versions: 4.2.0
> Reporter: edison su
> Assignee: edison su
> Priority: Critical
>
> KVMStoragePoolManager->copyPhysicalDisk doesn't use timeout parameter passed
> from mgt server during the copy physical disk
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
