[
https://issues.apache.org/jira/browse/CLOUDSTACK-3229?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13741926#comment-13741926
]
Thomas O'Dowd commented on CLOUDSTACK-3229:
-------------------------------------------
Min - sorry for the long wait. I went to lunch.
Following the other lines quoted above, I can see the following...
[13872] 2013-08-16 03:29:34.137590 lock: acquired
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
[13872] 2013-08-16 03:29:34.138373 sr_scan {'sr_uuid':
'9f3f9262-3f77-09cc-2df7-0d8475676260', 'subtask_of':
'DummyRef:|61e45046-c481-6607-89d4-d08e7134a759|SR.scan', 'args': [],
'host_ref': 'OpaqueRef:0d19f3fa-7f04-543a-d906-aaf478fc574c', 'session_ref':
'OpaqueRef:17f831b6-9115-37a2-8b81-e9a496c1a1f9', 'device_config': {'SRmaster':
'true', 'location': '/opt/storage/primary'}, 'command': 'sr_scan', 'sr_ref':
'OpaqueRef:75f9feeb-8309-b7b7-8455-9a1021a3baa4'}
[13872] 2013-08-16 03:29:34.138570 ['/usr/bin/vhd-util', 'scan', '-f',
'-c', '-m', '/opt/storage/primary/*.vhd']
[13872] 2013-08-16 03:29:34.151355 SUCCESS
[13872] 2013-08-16 03:29:34.153339 ['ls', '/opt/storage/primary', '-1',
'--color=never']
[13872] 2013-08-16 03:29:34.160103 SUCCESS
[13872] 2013-08-16 03:29:34.160386 Scan found hidden leaf
(ab85c9d3-56a1-45fa-b698-3410b77e83be), ignoring
[13872] 2013-08-16 03:29:34.160454 Scan found hidden leaf
(9fd77231-04a9-4b24-94b8-d61cee1ef9e0), ignoring
[13872] 2013-08-16 03:29:34.160775 lock: tried lock
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running, acquired: True
(exists: True)
[13872] 2013-08-16 03:29:34.160851 lock: released
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running
[13872] 2013-08-16 03:29:34.160892 Kicking GC
<13872> 2013-08-16 03:29:34.160955 === SR
9f3f9262-3f77-09cc-2df7-0d8475676260: gc ===
<13876> 2013-08-16 03:29:34.164529 Will finish as PID [13877]
<13872> 2013-08-16 03:29:34.165298 New PID [13876]
[13872] 2013-08-16 03:29:34.165699 lock: closed
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running
[13872] 2013-08-16 03:29:34.230920 lock: released
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
<13877> 2013-08-16 03:29:34.236035
*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*
<13877> 2013-08-16 03:29:34.236143 ***********************
<13877> 2013-08-16 03:29:34.236191 * E X C E P T I O N *
<13877> 2013-08-16 03:29:34.236235 ***********************
<13877> 2013-08-16 03:29:34.236319 gc: EXCEPTION <type
'exceptions.OSError'>, [Errno 2] No such file or directory:
'/var/run/sr-mount/9f3f9262-3f77-09cc-2df7-0d8475676260'
<13877> 2013-08-16 03:29:34.236367 File "/usr/lib/xcp/sm/cleanup.py",
line 2515, in gc
_gc(None, srUuid, dryRun)
File "/usr/lib/xcp/sm/cleanup.py", line 2415, in _gc
sr.cleanupCache()
File "/usr/lib/xcp/sm/cleanup.py", line 1867, in cleanupCache
cacheFiles = filter(self._isCacheFileName, os.listdir(self.path))
<13877> 2013-08-16 03:29:34.236413
*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*
<13877> 2013-08-16 03:29:34.236459 * * * * * SR
9f3f9262-3f77-09cc-2df7-0d8475676260: ERROR
[13872] 2013-08-16 03:29:34.238564 lock: closed
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
[13910] 2013-08-16 03:30:15.889586 #### VMOPS enter gethostvmstats ####
[13910] 2013-08-16 03:30:15.893586 #### VMOPS exit gethostvmstats ####
[13917] 2013-08-16 03:30:18.591527 #### VMOPS enter gethostvmstats ####
[13917] 2013-08-16 03:30:18.595713 #### VMOPS exit gethostvmstats ####
[13927] 2013-08-16 03:30:34.465665 lock: acquired
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
[13927] 2013-08-16 03:30:34.465770 sr_scan {'sr_uuid':
'9f3f9262-3f77-09cc-2df7-0d8475676260', 'subtask_of':
'DummyRef:|34268ce3-fc3a-ceb8-9821-9eafc05a6277|SR.scan', 'args': [],
'host_ref': 'OpaqueRef:0d19f3fa-7f04-543a-d906-aaf478fc574c', 'session_ref':
'OpaqueRef:0b1853b4-58c4-45de-c159-0482bccf6bab', 'device_config': {'SRmaster':
'true', 'location': '/opt/storage/primary'}, 'command': 'sr_scan', 'sr_ref':
'OpaqueRef:75f9feeb-8309-b7b7-8455-9a1021a3baa4'}
[13927] 2013-08-16 03:30:34.465931 ['/usr/bin/vhd-util', 'scan', '-f',
'-c', '-m', '/opt/storage/primary/*.vhd']
[13927] 2013-08-16 03:30:34.474920 SUCCESS
[13927] 2013-08-16 03:30:34.478510 ['ls', '/opt/storage/primary', '-1',
'--color=never']
[13927] 2013-08-16 03:30:34.483966 SUCCESS
[13927] 2013-08-16 03:30:34.484193 Scan found hidden leaf
(ab85c9d3-56a1-45fa-b698-3410b77e83be), ignoring
[13927] 2013-08-16 03:30:34.484271 Scan found hidden leaf
(9fd77231-04a9-4b24-94b8-d61cee1ef9e0), ignoring
[13927] 2013-08-16 03:30:34.484581 lock: tried lock
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running, acquired: True
(exists: True)
[13927] 2013-08-16 03:30:34.484662 lock: released
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running
[13927] 2013-08-16 03:30:34.484707 Kicking GC
<13927> 2013-08-16 03:30:34.484772 === SR
9f3f9262-3f77-09cc-2df7-0d8475676260: gc ===
<13931> 2013-08-16 03:30:34.487964 Will finish as PID [13932]
<13927> 2013-08-16 03:30:34.488619 New PID [13931]
[13927] 2013-08-16 03:30:34.488937 lock: closed
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running
[13927] 2013-08-16 03:30:34.536340 lock: released
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
[13927] 2013-08-16 03:30:34.540301 lock: closed
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
<13932> 2013-08-16 03:30:34.561067
*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*
<13932> 2013-08-16 03:30:34.561168 ***********************
<13932> 2013-08-16 03:30:34.561212 * E X C E P T I O N *
<13932> 2013-08-16 03:30:34.561255 ***********************
<13932> 2013-08-16 03:30:34.561326 gc: EXCEPTION <type
'exceptions.OSError'>, [Errno 2] No such file or directory:
'/var/run/sr-mount/9f3f9262-3f77-09cc-2df7-0d8475676260'
<13932> 2013-08-16 03:30:34.561370 File "/usr/lib/xcp/sm/cleanup.py",
line 2515, in gc
_gc(None, srUuid, dryRun)
File "/usr/lib/xcp/sm/cleanup.py", line 2415, in _gc
sr.cleanupCache()
File "/usr/lib/xcp/sm/cleanup.py", line 1867, in cleanupCache
cacheFiles = filter(self._isCacheFileName, os.listdir(self.path))
<13932> 2013-08-16 03:30:34.561413
*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*
<13932> 2013-08-16 03:30:34.561456 * * * * * SR
9f3f9262-3f77-09cc-2df7-0d8475676260: ERROR
[13965] 2013-08-16 03:31:16.167244 #### VMOPS enter gethostvmstats ####
[13965] 2013-08-16 03:31:16.171111 #### VMOPS exit gethostvmstats ####
[13972] 2013-08-16 03:31:18.806609 #### VMOPS enter gethostvmstats ####
[13972] 2013-08-16 03:31:18.810897 #### VMOPS exit gethostvmstats ####
[13982] 2013-08-16 03:31:34.776573 lock: acquired
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
[13982] 2013-08-16 03:31:34.776677 sr_scan {'sr_uuid':
'9f3f9262-3f77-09cc-2df7-0d8475676260', 'subtask_of':
'DummyRef:|7cfbd3bc-5082-6a5b-6c38-63456ef108b1|SR.scan', 'args': [],
'host_ref': 'OpaqueRef:0d19f3fa-7f04-543a-d906-aaf478fc574c', 'session_ref':
'OpaqueRef:1b3d55b9-a110-3c47-c890-147f475de984', 'device_config': {'SRmaster':
'true', 'location': '/opt/storage/primary'}, 'command': 'sr_scan', 'sr_ref':
'OpaqueRef:75f9feeb-8309-b7b7-8455-9a1021a3baa4'}
[13982] 2013-08-16 03:31:34.776807 ['/usr/bin/vhd-util', 'scan', '-f',
'-c', '-m', '/opt/storage/primary/*.vhd']
[13982] 2013-08-16 03:31:34.784780 SUCCESS
[13982] 2013-08-16 03:31:34.788399 ['ls', '/opt/storage/primary', '-1',
'--color=never']
[13982] 2013-08-16 03:31:34.793583 SUCCESS
[13982] 2013-08-16 03:31:34.793794 Scan found hidden leaf
(ab85c9d3-56a1-45fa-b698-3410b77e83be), ignoring
[13982] 2013-08-16 03:31:34.793887 Scan found hidden leaf
(9fd77231-04a9-4b24-94b8-d61cee1ef9e0), ignoring
[13982] 2013-08-16 03:31:34.794182 lock: tried lock
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running, acquired: True
(exists: True)
[13982] 2013-08-16 03:31:34.794262 lock: released
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running
[13982] 2013-08-16 03:31:34.794305 Kicking GC
<13982> 2013-08-16 03:31:34.794366 === SR
9f3f9262-3f77-09cc-2df7-0d8475676260: gc ===
<13986> 2013-08-16 03:31:34.797329 Will finish as PID [13987]
<13982> 2013-08-16 03:31:34.797952 New PID [13986]
[13982] 2013-08-16 03:31:34.798274 lock: closed
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/running
[13982] 2013-08-16 03:31:34.850358 lock: released
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
<13987> 2013-08-16 03:31:34.858440
*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*
<13987> 2013-08-16 03:31:34.858535 ***********************
<13987> 2013-08-16 03:31:34.858576 * E X C E P T I O N *
<13987> 2013-08-16 03:31:34.858615 ***********************
<13987> 2013-08-16 03:31:34.858680 gc: EXCEPTION <type
'exceptions.OSError'>, [Errno 2] No such file or directory:
'/var/run/sr-mount/9f3f9262-3f77-09cc-2df7-0d8475676260'
<13987> 2013-08-16 03:31:34.858721 File "/usr/lib/xcp/sm/cleanup.py",
line 2515, in gc
_gc(None, srUuid, dryRun)
File "/usr/lib/xcp/sm/cleanup.py", line 2415, in _gc
sr.cleanupCache()
File "/usr/lib/xcp/sm/cleanup.py", line 1867, in cleanupCache
cacheFiles = filter(self._isCacheFileName, os.listdir(self.path))
<13987> 2013-08-16 03:31:34.858761
*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*~*
<13987> 2013-08-16 03:31:34.858801 * * * * * SR
9f3f9262-3f77-09cc-2df7-0d8475676260: ERROR
[13982] 2013-08-16 03:31:34.859919 lock: closed
/var/lock/sm/9f3f9262-3f77-09cc-2df7-0d8475676260/sr
[14020] 2013-08-16 03:32:16.440440 #### VMOPS enter gethostvmstats ####
[14020] 2013-08-16 03:32:16.444436 #### VMOPS exit gethostvmstats ####
[14027] 2013-08-16 03:32:19.016155 #### VMOPS enter gethostvmstats ####
[14027] 2013-08-16 03:32:19.020161 #### VMOPS exit gethostvmstats ####
.... etc .... (seems to be repeating).
If it helps I can attach the SMlog file. Let me know.
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: Min Chen
> 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
