[ https://issues.apache.org/jira/browse/CLOUDSTACK-3229?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13727492#comment-13727492 ]
Thomas O'Dowd commented on CLOUDSTACK-3229: ------------------------------------------- Prasanna helped me get instance launching up again on 4.2. Just tried saving a snapshot again. On the UI, I get an ERROR popup: "Failed to create snapshot due to an internal error creating snapshot for volume 6." On the management server I see: WARN [xen.resource.CitrixResourceBase] (DirectAgent-32:) callHostPlugin failed for cmd: deleteSnapshotBackup with args secondaryStorageMountPath: 192.168.56.10:/opt/storage/cache/, localMountPoint: /var/run/cloud_mount/49ab0a32-3113-3ee2-bb24-3e65acb96ce9, path: snapshots/2/6, backupUUID: 5a28d935-47da-4813-a692-db92761ce7de.vhd, due to There was a failure communicating with the plugin. WARN [xen.resource.XenServerStorageProcessor] (DirectAgent-32:) BackupSnapshot Failed due to callHostPlugin failed for cmd: deleteSnapshotBackup with args secondaryStorageMountPath: 192.168.56.10:/opt/storage/cache/, localMountPoint: /var/run/cloud_mount/49ab0a32-3113-3ee2-bb24-3e65acb96ce9, path: snapshots/2/6, backupUUID: 5a28d935-47da-4813-a692-db92761ce7de.vhd, due to There was a failure communicating with the plugin. com.cloud.utils.exception.CloudRuntimeException: callHostPlugin failed for cmd: deleteSnapshotBackup with args secondaryStorageMountPath: 192.168.56.10:/opt/storage/cache/, localMountPoint: /var/run/cloud_mount/49ab0a32-3113-3ee2-bb24-3e65acb96ce9, path: snapshots/2/6, backupUUID: 5a28d935-47da-4813-a692-db92761ce7de.vhd, due to There was a failure communicating with the plugin. at com.cloud.hypervisor.xen.resource.CitrixResourceBase.callHostPlugin(CitrixResourceBase.java:4218) at com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.deleteSnapshotBackup(XenServerStorageProcessor.java:1047) at com.cloud.hypervisor.xen.resource.XenServerStorageProcessor.backupSnapshot(XenServerStorageProcessor.java:1271) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.execute(StorageSubsystemCommandHandlerBase.java:84) at com.cloud.storage.resource.StorageSubsystemCommandHandlerBase.handleStorageCommands(StorageSubsystemCommandHandlerBase.java:49) at com.cloud.hypervisor.xen.resource.CitrixResourceBase.executeRequest(CitrixResourceBase.java:617) at com.cloud.hypervisor.xen.resource.XcpOssResource.executeRequest(XcpOssResource.java:140) at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) at java.util.concurrent.FutureTask.run(FutureTask.java:166) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:724) On devcloud in the SMlog file, I see: [16279] 2013-08-02 08:48:52.174699 #### VMOPS enter s3 #### #### [16279] 2013-08-02 08:48:52.367205 #### VMOPS Attempting execution 1/3 of perform_request #### [16279] 2013-08-02 08:48:54.730958 #### VMOPS Sent PUT request to s3.cloudian.com:18080/images/snapshots/5a28d935-47da-4813-a692-db92761ce7de with headers {'Content-Length': '50430464', 'Content-MD5': 'oafg2xPUPPAnyE1sxmf+qA==', 'Expect': '100-continue', 'Date': 'Fri, 02 Aug 2013 08:48:52 +0000', 'Content-Type': 'application/octet-stream', 'Authorization': 'AWS 00ba9a7f9a8142b070c3:fy03ARq2UQWKW2UndUSYJ/E+QfI='}. Received response status 200: OK #### [16279] 2013-08-02 08:48:54.731880 #### VMOPS exit s3 with result true #### [16282] 2013-08-02 08:48:55.203713 #### VMOPS enter deleteSnapshotBackup #### This shows a successful upload of the snapshot to the S3 server. You can see the plugin received 200 OK response and it exited with result true... Looking at a bucket listing from the S3 server, I can see this snapshot was uploaded successfully also: $ ./list.py -B images KY: snapshots/5a28d935-47da-4813-a692-db92761ce7de 2013-08-02T08:48:53.923Z None 50430464 "a1a7e0db13d43cf027c84d6cc667fea8" KY: template/tmpl/1/1/routing-1/systemvmtemplate-2013-06-12-master-xen.vhd.bz2 2013-08-02T08:05:53.011Z None 221422863 "87c9c5228284c259939acb5d34b0638c-43" KY: template/tmpl/1/5/tiny Linux/ttylinux_pv.vhd 2013-08-02T08:17:16.071Z None 50430464 "4afac316e865adf74ca1a8039fae7399-10" KY: template/tmpl/2/201/201-2-399eae27-c26d-33a3-b2a4-8bb85378d4c7/tinylinux.vhd 2013-08-02T08:14:46.299Z None 50430464 "4afac316e865adf74ca1a8039fae7399-10" So, the S3 part looks good to me. Right after uploading S3, is this next section in SMlog: [16282] 2013-08-02 08:48:55.203713 #### VMOPS enter deleteSnapshotBackup #### [16282] 2013-08-02 08:48:55.204123 Calling deleteSnapshotBackup with {'localMountPoint': '/var/run/cloud_mount/49ab0a32-3113-3ee2-bb24-3e65acb96ce9', 'backupUUID': '5a28d935-47da-4813-a692-db92761ce7de.vhd', 'secondaryStorageMountPath': '192.168.56.10:/opt/storage/cache/', 'path': 'snapshots/2/6'} [16289] 2013-08-02 08:48:55.351722 lock: acquired /var/lock/sm/1d596381-7b74-c877-8f3d-214f9bff47e2/sr [16289] 2013-08-02 08:48:55.351822 sr_detach {'sr_uuid': '1d596381-7b74-c877-8f3d-214f9bff47e2', 'subtask_of': 'DummyRef:|ecf76228-657a-51fd-8966-7aee78dfe51e|SR.detach', 'args': [], 'host_ref': 'OpaqueRef:0d19f3fa-7f04-543a-d906-aaf478fc574c', 'session_ref': 'OpaqueRef:7f10f5c5-8541-92ee-da23-7b7a6ce81d9c', 'device_config': {'SRmaster': 'true', 'serverpath': '/opt/storage/cache/snapshots/2/6', 'server': '192.168.56.10'}, 'command': 'sr_detach', 'sr_ref': 'OpaqueRef:2d53b0ec-1cb3-99c9-ff4a-c39113fc6e72'} [16289] 2013-08-02 08:48:55.352392 Aborting GC/coalesce <16289> 2013-08-02 08:48:55.352659 === SR 1d596381-7b74-c877-8f3d-214f9bff47e2: abort === [16289] 2013-08-02 08:48:55.352942 lock: tried lock /var/lock/sm/1d596381-7b74-c877-8f3d-214f9bff47e2/running, acquired: True (exists: True) <16289> 2013-08-02 08:48:55.353168 abort: releasing the process lock [16289] 2013-08-02 08:48:55.353401 lock: released /var/lock/sm/1d596381-7b74-c877-8f3d-214f9bff47e2/running [16289] 2013-08-02 08:48:55.353635 ['umount', '/var/run/sr-mount/1d596381-7b74-c877-8f3d-214f9bff47e2'] [16289] 2013-08-02 08:48:55.365270 SUCCESS [16289] 2013-08-02 08:48:55.365515 lock: released /var/lock/sm/1d596381-7b74-c877-8f3d-214f9bff47e2/sr [16289] 2013-08-02 08:48:55.365838 lock: closed /var/lock/sm/1d596381-7b74-c877-8f3d-214f9bff47e2/sr [16289] 2013-08-02 08:48:55.369899 lock: closed /var/lock/sm/1d596381-7b74-c877-8f3d-214f9bff47e2/running [16314] 2013-08-02 08:49:30.308524 #### VMOPS enter gethostvmstats #### [16314] 2013-08-02 08:49:30.319569 #### VMOPS exit gethostvmstats #### [16317] 2013-08-02 08:49:30.354644 #### VMOPS enter gethostvmstats #### [16317] 2013-08-02 08:49:30.358999 #### VMOPS exit gethostvmstats #### Still not working but very close perhaps? Tom. > Object_Store_Refactor - Snapshot fails due to an internal error > --------------------------------------------------------------- > > Key: CLOUDSTACK-3229 > URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3229 > Project: CloudStack > Issue Type: Bug > Security Level: Public(Anyone can view this level - this is the > default.) > Affects Versions: 4.2.0 > Environment: chrome on linux > devcloud > Cloudian or Amazon S3 Object store > Reporter: Thomas O'Dowd > Assignee: John Burwell > Priority: Blocker > Fix For: 4.2.0 > > Attachments: SMlog, SMlog.last_5000_lines.txt > > > Assuming initial devcloud state... > I added a cache for the S3 storage like this. > on devcloud machine as root: > # mkdir /opt/storage/cache > # vi /etc/exports (and append this line) > /opt/storage/cache *(rw,no_subtree_check,no_root_squash,fsid=9999) > # exportfs -a > On Mgmt server GUI: > 1. navigate to infrastructure -> secondary storage > 2. delete the NFS SS. > 3. add S3 storage for Cloudian (I used 60000 as the timeouts - assuming > millis). I used the /opt/storage/cache thing as the s3 cache. > 4. nav to templates > 5. register a new template (I uploaded tinyLinux again as "mytiny" (5.3 > 64bit)). > 6. confirm with s3cmd that 2 objects are now on S3. > --------- s3 objects ------- > template/tmpl/1/1/routing-1/acton-systemvm-02062012.vhd.bz2 > 2013-06-27T03:01:46.203Z None 140616708 "b533e7b65219439ee7fca0146ddd7ffa-27" > template/tmpl/2/201/201-2-ae9e9409-4c8e-3ad8-a62f-abec7a35fe26/tinylinux.vhd > 2013-06-27T03:04:06.730Z None 50430464 "4afac316e865adf74ca1a8039fae7399-10" > --------- s3 objects ------- > 7. I restarted the management server at this point which actually resulted in > another object on S3. > --------- the new s3 object ------- > template/tmpl/1/5/tiny Linux/ttylinux_pv.vhd 2013-06-27T03:43:26.494Z None > 50430464 "4afac316e865adf74ca1a8039fae7399-10" > --------- the new s3 object ------- > 8. Go to instance and create a new choosing the "mytiny" template which we > registered. > 9. launch it after selecting all defaults. > 10. wait until it starts. > 11. nav to storage. I see ROOT-8. Click on this to open. > 12. click the camera to take the snapshot. > after a pause I get a popup > "Failed to create snapshot due to an internal error creating snapshot > for volume 8" > Also on the mgmt terminal I get the following log entry (only 1): > INFO [user.snapshot.CreateSnapshotCmd] (Job-Executor-8:job-16) VOLSS: > createSnapshotCmd starts:1372321251009 > If I check the "view snapshots" button under storage, I can however see the > snapshot. It says its on primary. I'm expecting it to go to secondary storage > though. Nothing is in the S3 logs and no snapshots. > If I try to delete that snapshot from here I get this error in the logs: > ERROR [cloud.async.AsyncJobManagerImpl] (Job-Executor-12:job-20) Unexpected > exception while executing > org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd > com.cloud.utils.exception.CloudRuntimeException: Failed to delete > snapshot:com.cloud.exception.InvalidParameterValueException: Can't delete > snapshotshot 4 due to it is not in BackedUp Status > at > com.cloud.storage.snapshot.SnapshotManagerImpl.deleteSnapshot(SnapshotManagerImpl.java:513) > at > com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125) > at > org.apache.cloudstack.api.command.user.snapshot.DeleteSnapshotCmd.execute(DeleteSnapshotCmd.java:96) > at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155) > at > com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437) > at > java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:722) > If I navigate to instance, my instance, and try to take a vm snapshot from > here, I get a different pop-up which says: > "There is other active volume snapshot tasks on the instance to which the > volume is attached, please try again later" > And I get an exception: > ERROR [cloud.api.ApiServer] (352129314@qtp-2110413789-32:) unhandled > exception executing api command: createVMSnapshot > com.cloud.utils.exception.CloudRuntimeException: There is other active volume > snapshot tasks on the instance to which the volume is attached, please try > again later. > at > com.cloud.vm.snapshot.VMSnapshotManagerImpl.allocVMSnapshot(VMSnapshotManagerImpl.java:299) > at > org.apache.cloudstack.api.command.user.vmsnapshot.CreateVMSnapshotCmd.create(CreateVMSnapshotCmd.java:78) > at > com.cloud.api.ApiDispatcher.dispatchCreateCmd(ApiDispatcher.java:101) > at com.cloud.api.ApiServer.queueCommand(ApiServer.java:475) > at com.cloud.api.ApiServer.handleRequest(ApiServer.java:371) > at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:304) > at com.cloud.api.ApiServlet.doGet(ApiServlet.java:66) > at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) > at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) > at > org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511) > at > org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:401) > at > org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) > at > org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182) > at > org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766) > at > org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:450) > at > org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230) > at > org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114) > at > org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) > at org.mortbay.jetty.Server.handle(Server.java:326) > at > org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542) > at > org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:928) > at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:549) > at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212) > at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404) > at > org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410) > at > org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582) > There are no requests going to the S3 storage for the snap-shotting that I > can see and its the only secondary storage that I have setup. -- 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