Sanjeev N created CLOUDSTACK-3359:
-------------------------------------
Summary: [Object_Store_Refactor] Failed to bring up System VMs
with s3 as the storage provider
Key: CLOUDSTACK-3359
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3359
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Install and Setup
Affects Versions: 4.2.0
Environment: Latest build from master branch
CloudStack-non-OSS-MASTER-506-rhel6.3.tar.gz
Reporter: Sanjeev N
Priority: Blocker
Fix For: 4.2.0
Attachments: management-server.rar
Failed to bring up System VMs with s3 as the storage provider
Steps to Reproduce:
==================
1.Bring up CS in advanced zone with S3 as the storage provider with xen cluster
After adding s3 provider , system template was successfully downloaded to S3
image store. However bringing up system vms failed with following exceptions:
2013-07-04 12:12:07,762 INFO [storage.template.S3TemplateDownloader]
(pool-15-thread-1:null) Starting download from
http://10.147.28.7/templates/newsysvmtemp/systemvmtemplate-2013-06-23-master-xen.vhd.bz2
to s3 bucket imagestore remoteSize=222905783 , max size=53687091200
2013-07-04 12:12:07,764 DEBUG [cloud.utils.S3Utils] (pool-15-thread-1:null)
Creating S3 client with configuration: [protocol: http, connectionTimeOut:
50000, maxErrorRetry: 3, socketTimeout: 50000]
2013-07-04 12:12:07,790 DEBUG [cloud.utils.S3Utils] (pool-15-thread-1:null)
Setting the end point for S3 client
com.amazonaws.services.s3.AmazonS3Client@33cc26b8 to 10.147.29.57:8080.
2013-07-04 12:12:19,921 DEBUG [cloud.server.StatsCollector]
(StatsCollector-2:null) VmStatsCollector is running...
2013-07-04 12:12:23,760 INFO [storage.template.S3TemplateDownloader]
(s3-transfer-manager-worker-1:null) download completed
2013-07-04 12:12:23,767 INFO [storage.template.S3TemplateDownloader]
(s3-transfer-manager-worker-1:null) download completed
2013-07-04 12:12:23,767 INFO [storage.template.DownloadManagerImpl]
(pool-15-thread-1:null) Download Completion for jobId:
873e9285-5ec4-48eb-a8c6-597d63ee5cbe, status=DOWNLOAD_FINISHED
2013-07-04 12:12:23,767 INFO [storage.template.DownloadManagerImpl]
(pool-15-thread-1:null) local:
template/tmpl/1/1/routing-1/systemvmtemplate-2013-06-23-master-xen.vhd.bz2,
bytes=222905783, error= , pct=100
2013-07-04 12:13:30,844 DEBUG [storage.motion.AncientDataMotionStrategy]
(secstorage-1:null) copy object failed:
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@11aa9e9f: SELECT template_store_ref.id,
template_store_ref.store_id, template_store_ref.template_id,
template_store_ref.store_role, template_store_ref.created,
template_store_ref.last_updated, template_store_ref.download_pct,
template_store_ref.size, template_store_ref.physical_size,
template_store_ref.download_state, template_store_ref.local_path,
template_store_ref.error_str, template_store_ref.job_id,
template_store_ref.install_path, template_store_ref.url,
template_store_ref.is_copy, template_store_ref.destroyed,
template_store_ref.update_count, template_store_ref.updated,
template_store_ref.state, template_store_ref.ref_cnt FROM template_store_ref
WHERE template_store_ref.store_id = 1 AND template_store_ref.template_id = 1
AND template_store_ref.destroyed = 0 ORDER BY RAND() LIMIT 1
2013-07-04 12:13:30,846 DEBUG [storage.motion.AncientDataMotionStrategy]
(secstorage-1:null) copy failed
com.cloud.utils.exception.CloudRuntimeException:
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@11aa9e9f: SELECT template_store_ref.id,
template_store_ref.store_id, template_store_ref.template_id,
template_store_ref.store_role, template_store_ref.created,
template_store_ref.last_updated, template_store_ref.download_pct,
template_store_ref.size, template_store_ref.physical_size,
template_store_ref.download_state, template_store_ref.local_path,
template_store_ref.error_str, template_store_ref.job_id,
template_store_ref.install_path, template_store_ref.url,
template_store_ref.is_copy, template_store_ref.destroyed,
template_store_ref.update_count, template_store_ref.updated,
template_store_ref.state, template_store_ref.ref_cnt FROM template_store_ref
WHERE template_store_ref.store_id = 1 AND template_store_ref.template_id = 1
AND template_store_ref.destroyed = 0 ORDER BY RAND() LIMIT 1
at
org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyObject(AncientDataMotionStrategy.java:204)
at
org.apache.cloudstack.storage.motion.AncientDataMotionStrategy.copyAsync(AncientDataMotionStrategy.java:351)
at
org.apache.cloudstack.storage.motion.DataMotionServiceImpl.copyAsync(DataMotionServiceImpl.java:55)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createBaseImageAsync(VolumeServiceImpl.java:390)
at
org.apache.cloudstack.storage.volume.VolumeServiceImpl.createVolumeFromTemplateAsync(VolumeServiceImpl.java:490)
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2485)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2542)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:852)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:557)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:260)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:683)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1290)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
at
com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
at
com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at
com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-07-04 12:13:30,850 DEBUG [storage.allocator.AbstractStoragePoolAllocator]
(consoleproxy-1:null) Checking if storage pool is suitable, name: null ,poolId:
1
2013-07-04 12:13:30,863 DEBUG [cloud.storage.VolumeManagerImpl]
(secstorage-1:null) Unable to create
Vol[51|vm=51|ROOT]:com.cloud.utils.exception.CloudRuntimeException:
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@11aa9e9f: SELECT template_store_ref.id,
template_store_ref.store_id, template_store_ref.template_id,
template_store_ref.store_role, template_store_ref.created,
template_store_ref.last_updated, template_store_ref.download_pct,
template_store_ref.size, template_store_ref.physical_size,
template_store_ref.download_state, template_store_ref.local_path,
template_store_ref.error_str, template_store_ref.job_id,
template_store_ref.install_path, template_store_ref.url,
template_store_ref.is_copy, template_store_ref.destroyed,
template_store_ref.update_count, template_store_ref.updated,
template_store_ref.state, template_store_ref.ref_cnt FROM template_store_ref
WHERE template_store_ref.store_id = 1 AND template_store_ref.template_id = 1
AND template_store_ref.destroyed = 0 ORDER BY RAND() LIMIT 1
2013-07-04 12:13:30,864 INFO [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is
unreachable: Unable to create
Vol[51|vm=51|ROOT]:com.cloud.utils.exception.CloudRuntimeException:
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@11aa9e9f: SELECT template_store_ref.id,
template_store_ref.store_id, template_store_ref.template_id,
template_store_ref.store_role, template_store_ref.created,
template_store_ref.last_updated, template_store_ref.download_pct,
template_store_ref.size, template_store_ref.physical_size,
template_store_ref.download_state, template_store_ref.local_path,
template_store_ref.error_str, template_store_ref.job_id,
template_store_ref.install_path, template_store_ref.url,
template_store_ref.is_copy, template_store_ref.destroyed,
template_store_ref.update_count, template_store_ref.updated,
template_store_ref.state, template_store_ref.ref_cnt FROM template_store_ref
WHERE template_store_ref.store_id = 1 AND template_store_ref.template_id = 1
AND template_store_ref.destroyed = 0 ORDER BY RAND() LIMIT 1
at
com.cloud.storage.VolumeManagerImpl.recreateVolume(VolumeManagerImpl.java:2493)
at
com.cloud.storage.VolumeManagerImpl.prepare(VolumeManagerImpl.java:2542)
at
com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:852)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:557)
at
com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:550)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:260)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:683)
at
com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1290)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
at
com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
at
com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
at
com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
at
com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at
java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
2013-07-04 12:13:30,862 DEBUG [cloud.storage.StorageManagerImpl]
(consoleproxy-1:null) Checking pool 1 for storage, totalSize: 5902284816384,
usedBytes: 3571783729152, usedPct: 0.6051527231009215, disable threshold: 0.85
2013-07-04 12:13:30,870 DEBUG [cloud.vm.VirtualMachineManagerImpl]
(secstorage-1:null) Cleaning up resources for the vm
VM[SecondaryStorageVm|s-51-VM] in Starting state
2013-07-04 12:13:30,873 DEBUG [agent.transport.Request] (secstorage-1:null) Seq
1-1357447677: Sending { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags:
100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"s-51-VM","wait":0}}]
}
2013-07-04 12:13:30,874 DEBUG [agent.transport.Request] (secstorage-1:null) Seq
1-1357447677: Executing: { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1,
Flags: 100011,
[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"s-51-VM","wait":0}}]
}
Image store details:
================
mysql> select * from image_store where removed is null;
+----+--------------------------------------------------+---------------------+----------+--------------------------------------------------+----------------+--------+------------+--------------------------------------+--------+---------------------+---------+------------+------------+
| id | name | image_provider_name |
protocol | url | data_center_id |
scope | role | uuid | parent | created
| removed | total_size | used_bytes |
+----+--------------------------------------------------+---------------------+----------+--------------------------------------------------+----------------+--------+------------+--------------------------------------+--------+---------------------+---------+------------+------------+
| 1 | nfs://10.147.28.7/export/home/sanjeev/sec_xen_os | NFS |
nfs | nfs://10.147.28.7/export/home/sanjeev/sec_xen_os | 1 |
ZONE | ImageCache | ac765666-9d65-4342-a60f-fa57c8c4ef3a | NULL |
2013-07-04 13:21:56 | NULL | NULL | NULL |
| 3 | obj_store | S3 |
http | NULL | NULL |
REGION | Image | 61b196ef-e946-4a41-bc86-77b499f398e9 | NULL |
2013-07-04 16:11:57 | NULL | NULL | NULL |
+----+--------------------------------------------------+---------------------+----------+--------------------------------------------------+----------------+--------+------------+--------------------------------------+--------+---------------------+---------+------------+------------+
2 rows in set (0.00 sec)
--
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
