You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Edward St Pierre <ed...@gmail.com> on 2021/03/02 16:15:51 UTC
Issue with Snapshots
Hi All,
I Wonder if someone could help me.
Currently using ceph for primary storage and have
'snapshot.backup.to.secondary' enabled.
Since upgrading to 4.15 the volume snapshots do not seem to be getting
deleted from the secondary storage. Could this be a bug?
Also when logged in as the main admin account when navigating to 'Storage /
Snapshots' an Error 500 is returned with the following error in the logs:
2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
(qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb) unhandled
exception executing api command: [Ljava.lang.String;@7ac2d249
java.lang.NullPointerException
at
org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
at
org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
at
org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
at
org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
at
org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
at
org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
at
com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
at
org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
at com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
at
com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
at
org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
at
org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
at
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at
org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
at
org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
at org.eclipse.jetty.server.Server.handle(Server.java:500)
at
org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
at
org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
at
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at
org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
at
org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
at
org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
at
org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
at
org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
at
org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
at java.base/java.lang.Thread.run(Thread.java:834)
Re: Issue with Snapshots
Posted by Edward St Pierre <ed...@gmail.com>.
Hi,
Yes it was working on the previous version which 4.13
Regards
On Mon, 8 Mar 2021 at 13:02, Gabriel Bräscher <ga...@gmail.com> wrote:
> Hi,
>
> I think that we might have a bug on snapshot backed up on secondary. I have
> checked my tests and the image on secondary storage is not deleted as well;
> it has been passed more than enough time for CloudStack cleanup sec storage
> garbage.
> One question. Was it working before upgrading to 4.15? Which was the
> version that you were using before the upgrade?
>
> Maybe this issue is a good one to be reported via GitHub so we can have
> more developers looking at and keeping track of it.
> To open an issue you can go to https://github.com/apache/cloudstack/issues
> .
>
> Regards,
> Gabriel.
>
> Em sex., 5 de mar. de 2021 às 13:00, Edward St Pierre <
> edward.stpierre@gmail.com> escreveu:
>
> > Hi,
> >
> > Thanks for that information and pointers on where to look, I have checked
> > it out and the data was also on the secondary storage and the storage VM
> is
> > mounting the NFS servers etc. (I have redeployed it just incase)
> >
> > I have gone through some of the older snapshots that are not getting
> > removed, and they do have that reference in the Ready Status:
> >
> > MariaDB [cloud]> select
> > id,store_id,snapshot_id,state,store_role,install_path from
> > snapshot_store_ref where install_path like
> > '%8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07';
> >
> >
> +------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
> > | id | store_id | snapshot_id | state | store_role | install_path
> > |
> >
> >
> +------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
> > | 1554 | 7 | 852 | Destroyed | Primary |
> >
> >
> cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
> > |
> > | 1555 | 1 | 852 | Ready | Image |
> > snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
> > |
> >
> >
> +------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
> > 2 rows in set (0.00 sec)
> >
> > MariaDB [cloud]> select * from snapshots where id=852;
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
> >
> >
> >
> -+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
> > -----+
> > | id | data_center_id | account_id | domain_id | volume_id |
> > disk_offering_id | status | path | name
> > | uuid | snapshot_type
> |
> > type_description | size | created | removed |
> > backup_snap_id | swift_id | sechost_id | prev_snap_id | hypervisor_type |
> > version | s3_id | min_iops | max_iops | location_ type |
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
> >
> >
> >
> -+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
> > -----+
> > | 852 | 1 | 2 | 1 | 146 |
> > 6 | Destroyed | NULL | vxtr-ln1-box01_DATA-86_20210226010342 |
> > 10ece2f5-39cf-4afe-9894-48c7c47e1463 | 4 |
> > DAILY | 214748364800 | 2021-02-26 01:03:42 | NULL | NULL
> > | NULL | NULL | NULL | KVM | 2.2
> |
> > NULL | NULL | NULL | NULL |
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
> >
> >
> >
> -+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
> > -----+
> >
> > I also cannot see any errors when it is created:
> >
> > 2021-02-26 01:03:42,019 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Got 1 snapshots to be
> > executed at 2021-02-26 01:03:42 GMT
> > 2021-02-26 01:03:42,023 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Scheduling 1 snapshot
> for
> > volume id 146 (volume name:DATA-86) for schedule id: 7 at 2021-02-26
> > 01:00:00 GMT
> > 2021-02-26 01:03:42,064 DEBUG [c.c.r.ResourceLimitManagerImpl]
> > (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Updating resource Type =
> > snapshot count for Account = 2 Operation = increasing Amount = 1
> > 2021-02-26 01:03:42,083 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) submit async job-6123,
> > details: AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType:
> > Snapshot, instanceId: 852, cmd:
> > org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd,
> cmdInfo:
> >
> >
> {"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
> > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
> > result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
> > null, lastPolled: null, created: null, removed: null}
> > 2021-02-26 01:03:42,088 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Executing
> > AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType: Snapshot,
> > instanceId: 852, cmd:
> > org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd,
> cmdInfo:
> >
> >
> {"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
> > cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
> > result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
> > null, lastPolled: null, created: null, removed: null}
> > 2021-02-26 01:03:43,284 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> > (logid:7c83430b) Execute VM work job:
> >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
> > 2021-02-26 01:03:45,111 DEBUG [c.c.a.t.Request]
> > (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> > (logid:7c83430b) Seq 10-5259641414815547085: Sending { Cmd , MgmtId:
> > 345050527765, via: 10(chst01.vxtream.com), Ver: v1, Flags: 100011,
> >
> >
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.
> > apache.cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
> > GB)
> >
> >
> 214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/146","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
> > GB)
> >
> >
> 214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
> > 10.100.7.51/export/secondary
> >
> ","_role":"Image"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
> > }
> > 2021-02-26 01:22:17,334 DEBUG [c.c.a.t.Request]
> > (AgentManager-Handler-7:null) (logid:) Seq 10-5259641414815547085:
> > Processing: { Ans: , MgmtId: 345050527765, via: 10, Ver: v1, Flags: 10,
> >
> >
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","id":"0","quiescevm":"false","physicalSize":"112297967616"}},"result":"true","wait":"0"}}]
> > }
> > 2021-02-26 01:22:17,355 DEBUG [c.c.s.s.SnapshotManagerImpl]
> > (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> > (logid:7c83430b) Max snaps: 3 exceeded for snapshot policy with Id: 7.
> > Deleting oldest snapshot: 849
> > 2021-02-26 01:22:18,473 DEBUG [c.c.r.ResourceLimitManagerImpl]
> > (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> > (logid:7c83430b) Updating resource Type = snapshot count for Account = 2
> > Operation = decreasing Amount = 1
> > 2021-02-26 01:22:18,499 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> > (logid:7c83430b) Done executing VM work job:
> >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
> > 2021-02-26 01:22:18,565 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (API-Job-Executor-10:ctx-c366f638 job-6123 ctx-1be547c7) (logid:7c83430b)
> > Complete async job-6123, jobStatus: SUCCEEDED, resultCode: 0, result:
> >
> >
> org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"10ece2f5-39cf-4afe-9894-48c7c47e1463","account":"admin","domainid":"1e48287f-ee6a-11e9-8f54-0050569d3815","domain":"ROOT","snapshottype":"DAILY","volumeid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumename":"DATA-86","volumetype":"DATADISK","created":"2021-02-26T01:03:42+0000","name":"vxtr-ln1-box01_DATA-86_20210226010342","intervaltype":"DAILY","state":"BackedUp","physicalsize":"112297967616","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","virtualsize":"214748364800","tags":[]}
> > 2021-02-26 01:22:18,592 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Done
> executing
> > org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
> > job-6123
> >
> > This log indicates when it is set to be removed:
> > 2021-03-01 01:22:13,750 DEBUG [c.c.s.s.SnapshotManagerImpl]
> > (Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
> > (logid:503cabb8) Max snaps: 3 exceeded for snapshot policy with Id: 7.
> > Deleting olest snapshot: 852
> > 2021-03-01 01:22:13,797 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
> > (Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
> > (logid:503cabb8) getCommandHostDelegation: class
> > org.apache.cloudstack.storage.comand.DeleteCommand
> >
> > Any indication on what I should look for in the logs for regarding the
> > 'secondary storage "garbage" should be cleaned up'?
> >
> > Many thanks for your help.
> >
> > Ed
> >
> > On Fri, 5 Mar 2021 at 15:12, Gabriel Bräscher <ga...@gmail.com>
> > wrote:
> >
> > > Before seeing the last reply I had just tested on CloudStack 4.15 +
> Ceph
> > +
> > > KVM, and it worked fine; however, I did the test with one snapshot of
> the
> > > volume.
> > > Maybe the scheduled/incremental snapshotting adds a different variable
> to
> > > the equation.
> > >
> > > From my tests, the DB holds one reference as Ready on the secondary
> > > storage, and one as Destroyed (on primary storage). I think that it is
> > the
> > > expected behavior and the secondary storage "garbage" should be cleaned
> > up
> > > on a window of 24-48 hours (by default, as the cleanup thread runs each
> > 24
> > > hours and it checks for a timestamp of 24 hours as well, on the worst
> > case
> > > it can take up to 48 hours, on the best 24 hours).
> > >
> > > I find it quite weird the fact that it has been thrown a null pointer
> > > before; as if the volume has been deleted and the Snapshot already
> > exists.
> > >
> > > Your log presents the following ERROR:
> > > 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> > > inspecting dest type SNAPSHOT
> > > 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary
> 861
> > > dest=861
> > >
> > > It indicates an issue when copying the snapshot from primary to
> secondary
> > > storage; I would look closely at the secondary storage pool and check
> the
> > > SSVM (secondary storage system VM).
> > >
> > > For reference,here follows an example from the deleted backed-up
> snapshot
> > > from my test:
> > >
> > > > select id,store_id,snapshot_id,state,store_role,install_path from
> > > snapshot_store_ref where snapshot_id=759;
> > >
> > >
> >
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
> > >
> > > | id | store_id | snapshot_id | state | store_role | install_path
> > > |
> > >
> > >
> >
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
> > >
> > > | 838 | 21 | 759 | Destroyed | Primary |
> > >
> > >
> >
> rbd/8e918c48-f32a-4c4e-81b2-0ba374d705dc/b41ba753-afad-42b5-849f-839736cb3a77
> > > |
> > > | 839 | 1 | 759 | Ready | Image |
> > > snapshots/6/12872/b41ba753-afad-42b5-849f-839736cb3a77
> > > |
> > >
> > >
> >
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
> > >
> > >
> > >
> > >
> > >
> > > Em sex., 5 de mar. de 2021 às 07:59, Edward St Pierre <
> > > edward.stpierre@gmail.com> escreveu:
> > >
> > > > Hi
> > > >
> > > > The issue happens multiple snapshots, I have run a test with
> > > > scheduled hourly volume snapshots for a test, here are the logs:
> > > >
> > > > 2021-03-05 10:03:43,277 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Execute VM work job:
> > > >
> > > >
> > >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > > > 2021-03-05 10:03:43,342 DEBUG [c.c.a.t.Request]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Seq 6-5629781009189976396: Sending { Cmd , MgmtId:
> > > > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> > > 100011,
> > > >
> > > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > > GB)
> > > >
> > > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > > > cloudstack.storage.to
> > > >
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > > > }
> > > > 2021-03-05 10:03:44,670 DEBUG [c.c.a.t.Request]
> > > > (AgentManager-Handler-9:null) (logid:) Seq 6-5629781009189976396:
> > > > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags:
> 10,
> > > >
> > > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0"}}]
> > > > }
> > > > 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> > > > inspecting dest type SNAPSHOT
> > > > 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary
> > 861
> > > > dest=861
> > > > 2021-03-05 10:03:44,898 DEBUG [c.c.a.t.Request]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Seq 6-5629781009189976397: Sending { Cmd , MgmtId:
> > > > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> > > 100011,
> > > >
> > > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
> > > > cloudstack.storage.to
> > > >
> > >
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > > > apache.cloudstack.storage.to
> > > >
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > > GB)
> > > >
> > > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > > > cloudstack.storage.to
> > > >
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/9/225","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > > GB)
> > > >
> > > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
> > > > 10.100.7.51/export/secondary
> > > >
> > >
> >
> ","_role":"Image"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
> > > > }
> > > > 2021-03-05 10:08:42,314 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > > > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Snapshot
> > scheduler.poll
> > > is
> > > > being called at 2021-03-05 10:08:42 GMT
> > > > 2021-03-05 10:08:42,315 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > > > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Got 0 snapshots to
> be
> > > > executed at 2021-03-05 10:08:42 GMT
> > > > 2021-03-05 10:09:24,952 DEBUG [c.c.a.t.Request]
> > > > (AgentManager-Handler-2:null) (logid:) Seq 6-5629781009189976397:
> > > > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags:
> 10,
> > > >
> > > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.
> > > > cloudstack.storage.to
> > > >
> > >
> >
> .SnapshotObjectTO":{"path":"snapshots/9/225/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"16888233984"}},"result":"true","wait":"0"}}]
> > > > }
> > > > 2021-03-05 10:09:24,976 DEBUG [c.c.s.s.SnapshotManagerImpl]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Max snaps: 1 exceeded for snapshot policy with Id:
> 8.
> > > > Deleting oldest snapshot: 860
> > > > 2021-03-05 10:09:24,978 DEBUG [c.c.u.AccountManagerImpl]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Access to
> > > > com.cloud.storage.SnapshotVO$$EnhancerByCGLIB$$43460565@642f5e4f
> > granted
> > > > to
> > > > Acct[2ad78538-d6d9-4f24-967a-90701ff3a35f-edward] by DomainChecker
> > > > 2021-03-05 10:09:25,037 DEBUG [c.c.a.t.Request]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Seq 16-5311714285507142014: Sending { Cmd , MgmtId:
> > > > 345050527765, via: 16(vxtr-ln1-chst03.vxtream.com), Ver: v1, Flags:
> > > > 100011,
> > > >
> > > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.
> > > > cloudstack.storage.to
> > > >
> > >
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/b8e3403e-7b6c-4bee-8b27-5ad9843353cd","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > > > apache.cloudstack.storage.to
> > > >
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > > GB)
> > > >
> > > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > > > cloudstack.storage.to
> > > >
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305090342","hypervisorType":"KVM","id":"860","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > > > }
> > > > 2021-03-05 10:09:25,574 DEBUG [c.c.a.t.Request]
> > > > (AgentManager-Handler-9:null) (logid:) Seq 16-5311714285507142014:
> > > > Processing: { Ans: , MgmtId: 345050527765, via: 16, Ver: v1, Flags:
> > 10,
> > > > [{"com.cloud.agent.api.Answer":{"result":"true","details":"Snapshot
> > > >
> > 3c6bbe64-e924-4c94-a0eb-4b18e5786d58@b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> > > > removed successfully.","wait":"0"}}] }
> > > > 2021-03-05 10:09:25,588 DEBUG [c.c.r.ResourceLimitManagerImpl]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Updating resource Type = snapshot count for Account
> =
> > 9
> > > > Operation = decreasing Amount = 1
> > > > 2021-03-05 10:09:25,620 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > > (logid:fc7d7320) Done executing VM work job:
> > > >
> > > >
> > >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > > > 2021-03-05 10:09:25,628 DEBUG [c.c.v.VmWorkJobDispatcher]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142)
> (logid:fc7d7320)
> > > Done
> > > > with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM
> > > 156,
> > > > job origin: 6141
> > > > 2021-03-05 10:09:25,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142)
> (logid:fc7d7320)
> > > Done
> > > > executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-6142
> > > > 2021-03-05 10:09:25,666 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > > > (API-Job-Executor-19:ctx-3956f4cc job-6141 ctx-d69f2a1d)
> > (logid:fc7d7320)
> > > > Complete async job-6141, jobStatus: SUCCEEDED, resultCode: 0, result:
> > > >
> > > >
> > >
> >
> org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"076c3f3e-4875-419d-beed-398e6d938f41","account":"edward","domainid":"76fcd53c-c1bc-47cf-946c-336c30a53ca1","domain":"ESP","snapshottype":"HOURLY","volumeid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumename":"ROOT-156","volumetype":"ROOT","created":"2021-03-05T10:03:42+0000","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","intervaltype":"HOURLY","state":"BackedUp","physicalsize":"16888233984","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","ostypeid":"2cd2aa56-ee6a-11e9-8f54-0050569d3815","osdisplayname":"CentOS
> > > > 7","virtualsize":"107374182400","tags":[]}
> > > > 2021-03-05 10:09:25,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > > > (API-Job-Executor-19:ctx-3956f4cc job-6141) (logid:fc7d7320) Done
> > > executing
> > > > org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
> > > > job-6141
> > > >
> > > > Here are the actual snapshots on secondary storage:
> > > >
> > > > -rw-r--r--. 1 root root 16888233984 Mar 5 10:09
> > > > a00ba130-19f0-454c-9b74-55f95a64bfb5
> > > > -rw-r--r--. 1 root root 16888233984 Mar 5 09:09
> > > > b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> > > >
> > > > Here are the entries in the DB relating to the snapshots:
> > > >
> > > > select * from snapshots order by created desc limit 2;
> > > >
> > > >
> > >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > > > | id | data_center_id | account_id | domain_id | volume_id |
> > > > disk_offering_id | status | path | name
> > > > | uuid | snapshot_type |
> > > type_description
> > > > | size | created | removed | backup_snap_id |
> > > swift_id
> > > > | sechost_id | prev_snap_id | hypervisor_type | version | s3_id |
> > > min_iops
> > > > | max_iops | location_type |
> > > >
> > > >
> > >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > > > | 861 | 1 | 9 | 6 | 225 |
> > > > 5 | BackedUp | NULL | ESP-LN1-VOIP01_ROOT-156_20210305100342 |
> > > > 076c3f3e-4875-419d-beed-398e6d938f41 | 3 | HOURLY
> > |
> > > > 107374182400 | 2021-03-05 10:03:42 | NULL | NULL |
> > NULL
> > > |
> > > > NULL | NULL | KVM | 2.2 | NULL |
> > NULL
> > > |
> > > > NULL | NULL |
> > > > | 860 | 1 | 9 | 6 | 225 |
> > > > 5 | Destroyed | NULL | ESP-LN1-VOIP01_ROOT-156_20210305090342 |
> > > > 2998a50e-7282-45c5-bab6-8231e6343783 | 3 | HOURLY
> > |
> > > > 107374182400 | 2021-03-05 09:03:42 | NULL | NULL |
> > NULL
> > > |
> > > > NULL | NULL | KVM | 2.2 | NULL |
> > NULL
> > > |
> > > > NULL | NULL |
> > > >
> > > >
> > >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > > >
> > > >
> > > >
> > > > Regards
> > > >
> > > > Ed
> > > >
> > > > On Fri, 5 Mar 2021 at 02:20, Gabriel Bräscher <ga...@gmail.com>
> > > > wrote:
> > > >
> > > > > There was an open issue indeed but a PR solved it for 4.15. The
> issue
> > > > > reported on this email looks a bit different than the ones I have
> > seen.
> > > > >
> > > > > Background on a recent issue:
> > > > > - Issue #4498 "RBD Snapshot fails when
> snapshot.backup.to.secondary:
> > > > true"
> > > > > has been fixed by PR #4568 "kvm: Fix double-escape issue while
> > creating
> > > > rbd
> > > > > disk options"
> > > > >
> > > > > Reading the log:
> > > > > - In order for such a null pointer to happen the volume from the
> > > snapshot
> > > > > has been deleted on DB. Thus, it is either a bug or an
> inconsistency
> > on
> > > > the
> > > > > DB; e.g.: deleting the volume prior to its Snapshots.
> > > > >
> > > > > Is this occurrence an isolated one or does it happen with multiple
> > > > > snapshots that have been deleted?
> > > > >
> > > > > #4498: https://github.com/apache/cloudstack/issues/4498
> > > > > #4568: https://github.com/apache/cloudstack/pull/4568
> > > > >
> > > > > Em qui., 4 de mar. de 2021 às 18:55, Rakesh v <
> > > www.rakeshv.com@gmail.com
> > > > >
> > > > > escreveu:
> > > > >
> > > > > > If I remember properly there is already an issue raised for it in
> > > > github
> > > > > >
> > > > > > Sent from my iPhone
> > > > > >
> > > > > > > On Mar 4, 2021, at 9:48 PM, Andrija Panic <
> > andrija.panic@gmail.com
> > > >
> > > > > > wrote:
> > > > > > >
> > > > > > > @Gabriel Beims Bräscher <ga...@gmail.com> does this
> rings
> > > any
> > > > > > bells
> > > > > > > for you? I haven't played with Ceph / snap clean-up issue on
> 4.15
> > > > > myself.
> > > > > > >
> > > > > > > Best,
> > > > > > >
> > > > > > >> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <
> > > > > > edward.stpierre@gmail.com>
> > > > > > >> wrote:
> > > > > > >>
> > > > > > >> Hi All,
> > > > > > >>
> > > > > > >> I Wonder if someone could help me.
> > > > > > >>
> > > > > > >> Currently using ceph for primary storage and have
> > > > > > >> 'snapshot.backup.to.secondary' enabled.
> > > > > > >>
> > > > > > >> Since upgrading to 4.15 the volume snapshots do not seem to be
> > > > getting
> > > > > > >> deleted from the secondary storage. Could this be a bug?
> > > > > > >>
> > > > > > >> Also when logged in as the main admin account when navigating
> to
> > > > > > 'Storage /
> > > > > > >> Snapshots' an Error 500 is returned with the following error
> in
> > > the
> > > > > > logs:
> > > > > > >>
> > > > > > >> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> > > > > > >> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb)
> > > > > unhandled
> > > > > > >> exception executing api command: [Ljava.lang.String;@7ac2d249
> > > > > > >> java.lang.NullPointerException
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> > > > > > >> at
> > > > com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> > > > > > >> at
> > com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> > > > > > >> at
> > > com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> > > > > > >> at
> > > > > > >>
> > > > com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> > > > > > >> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> > > > > > >> at
> > > > com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> > > > > > >> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> > > > > > >> at
> > > > javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> > > > > > >> at
> > > > javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> > > > > > >> at
> > > > > > >>
> > > >
> org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> > > > > > >> at
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> > > > > > >> at
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> > > > > > >> at
> > > > > > >>
> > > > > >
> > > >
> > org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > > > >> at
> > org.eclipse.jetty.server.Server.handle(Server.java:500)
> > > > > > >> at
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> > > > > > >> at
> > > > > > >>
> > > org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> > > > > > >> at
> > > > > > >>
> > org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> > > > > > >> at
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> > > > > > >> at
> > > > > > >> org.eclipse.jetty.io
> > > > > > >>
> > > > >
> > .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> > > > > > >> at org.eclipse.jetty.io
> > > > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> > > > > > >> at
> > > > > > >>
> > > > > >
> > > >
> > org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> > > > > > >> at
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> > > > > > >> at org.eclipse.jetty.io
> > > > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > > > >> at
> > > > > > >> org.eclipse.jetty.io
> > > > .ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> > > > > > >> at
> > > > > > >>
> > > > > > >>
> > > > > >
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> > > > > > >> at java.base/java.lang.Thread.run(Thread.java:834)
> > > > > > >>
> > > > > > >
> > > > > > >
> > > > > > > --
> > > > > > >
> > > > > > > Andrija Panić
> > > > > >
> > > > >
> > > >
> > >
> >
>
Re: Issue with Snapshots
Posted by Gabriel Bräscher <ga...@gmail.com>.
Hi,
I think that we might have a bug on snapshot backed up on secondary. I have
checked my tests and the image on secondary storage is not deleted as well;
it has been passed more than enough time for CloudStack cleanup sec storage
garbage.
One question. Was it working before upgrading to 4.15? Which was the
version that you were using before the upgrade?
Maybe this issue is a good one to be reported via GitHub so we can have
more developers looking at and keeping track of it.
To open an issue you can go to https://github.com/apache/cloudstack/issues.
Regards,
Gabriel.
Em sex., 5 de mar. de 2021 às 13:00, Edward St Pierre <
edward.stpierre@gmail.com> escreveu:
> Hi,
>
> Thanks for that information and pointers on where to look, I have checked
> it out and the data was also on the secondary storage and the storage VM is
> mounting the NFS servers etc. (I have redeployed it just incase)
>
> I have gone through some of the older snapshots that are not getting
> removed, and they do have that reference in the Ready Status:
>
> MariaDB [cloud]> select
> id,store_id,snapshot_id,state,store_role,install_path from
> snapshot_store_ref where install_path like
> '%8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07';
>
> +------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
> | id | store_id | snapshot_id | state | store_role | install_path
> |
>
> +------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
> | 1554 | 7 | 852 | Destroyed | Primary |
>
> cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
> |
> | 1555 | 1 | 852 | Ready | Image |
> snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
> |
>
> +------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
> 2 rows in set (0.00 sec)
>
> MariaDB [cloud]> select * from snapshots where id=852;
>
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
>
>
> -+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
> -----+
> | id | data_center_id | account_id | domain_id | volume_id |
> disk_offering_id | status | path | name
> | uuid | snapshot_type |
> type_description | size | created | removed |
> backup_snap_id | swift_id | sechost_id | prev_snap_id | hypervisor_type |
> version | s3_id | min_iops | max_iops | location_ type |
>
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
>
>
> -+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
> -----+
> | 852 | 1 | 2 | 1 | 146 |
> 6 | Destroyed | NULL | vxtr-ln1-box01_DATA-86_20210226010342 |
> 10ece2f5-39cf-4afe-9894-48c7c47e1463 | 4 |
> DAILY | 214748364800 | 2021-02-26 01:03:42 | NULL | NULL
> | NULL | NULL | NULL | KVM | 2.2 |
> NULL | NULL | NULL | NULL |
>
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
>
>
> -+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
> -----+
>
> I also cannot see any errors when it is created:
>
> 2021-02-26 01:03:42,019 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Got 1 snapshots to be
> executed at 2021-02-26 01:03:42 GMT
> 2021-02-26 01:03:42,023 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Scheduling 1 snapshot for
> volume id 146 (volume name:DATA-86) for schedule id: 7 at 2021-02-26
> 01:00:00 GMT
> 2021-02-26 01:03:42,064 DEBUG [c.c.r.ResourceLimitManagerImpl]
> (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Updating resource Type =
> snapshot count for Account = 2 Operation = increasing Amount = 1
> 2021-02-26 01:03:42,083 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (SnapshotPollTask:ctx-69729307) (logid:3b2789b3) submit async job-6123,
> details: AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType:
> Snapshot, instanceId: 852, cmd:
> org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
>
> {"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
> result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
> null, lastPolled: null, created: null, removed: null}
> 2021-02-26 01:03:42,088 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Executing
> AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType: Snapshot,
> instanceId: 852, cmd:
> org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
>
> {"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
> cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
> result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
> null, lastPolled: null, created: null, removed: null}
> 2021-02-26 01:03:43,284 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> (logid:7c83430b) Execute VM work job:
>
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
> 2021-02-26 01:03:45,111 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> (logid:7c83430b) Seq 10-5259641414815547085: Sending { Cmd , MgmtId:
> 345050527765, via: 10(chst01.vxtream.com), Ver: v1, Flags: 100011,
>
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
> cloudstack.storage.to
> .SnapshotObjectTO":{"path":"cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.
> apache.cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
> GB)
>
> 214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/146","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.apache.
> cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
> GB)
>
> 214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
> 10.100.7.51/export/secondary
> ","_role":"Image"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
> }
> 2021-02-26 01:22:17,334 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-7:null) (logid:) Seq 10-5259641414815547085:
> Processing: { Ans: , MgmtId: 345050527765, via: 10, Ver: v1, Flags: 10,
>
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.
> cloudstack.storage.to
> .SnapshotObjectTO":{"path":"snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","id":"0","quiescevm":"false","physicalSize":"112297967616"}},"result":"true","wait":"0"}}]
> }
> 2021-02-26 01:22:17,355 DEBUG [c.c.s.s.SnapshotManagerImpl]
> (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> (logid:7c83430b) Max snaps: 3 exceeded for snapshot policy with Id: 7.
> Deleting oldest snapshot: 849
> 2021-02-26 01:22:18,473 DEBUG [c.c.r.ResourceLimitManagerImpl]
> (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> (logid:7c83430b) Updating resource Type = snapshot count for Account = 2
> Operation = decreasing Amount = 1
> 2021-02-26 01:22:18,499 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
> (logid:7c83430b) Done executing VM work job:
>
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
> 2021-02-26 01:22:18,565 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-10:ctx-c366f638 job-6123 ctx-1be547c7) (logid:7c83430b)
> Complete async job-6123, jobStatus: SUCCEEDED, resultCode: 0, result:
>
> org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"10ece2f5-39cf-4afe-9894-48c7c47e1463","account":"admin","domainid":"1e48287f-ee6a-11e9-8f54-0050569d3815","domain":"ROOT","snapshottype":"DAILY","volumeid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumename":"DATA-86","volumetype":"DATADISK","created":"2021-02-26T01:03:42+0000","name":"vxtr-ln1-box01_DATA-86_20210226010342","intervaltype":"DAILY","state":"BackedUp","physicalsize":"112297967616","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","virtualsize":"214748364800","tags":[]}
> 2021-02-26 01:22:18,592 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Done executing
> org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
> job-6123
>
> This log indicates when it is set to be removed:
> 2021-03-01 01:22:13,750 DEBUG [c.c.s.s.SnapshotManagerImpl]
> (Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
> (logid:503cabb8) Max snaps: 3 exceeded for snapshot policy with Id: 7.
> Deleting olest snapshot: 852
> 2021-03-01 01:22:13,797 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
> (Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
> (logid:503cabb8) getCommandHostDelegation: class
> org.apache.cloudstack.storage.comand.DeleteCommand
>
> Any indication on what I should look for in the logs for regarding the
> 'secondary storage "garbage" should be cleaned up'?
>
> Many thanks for your help.
>
> Ed
>
> On Fri, 5 Mar 2021 at 15:12, Gabriel Bräscher <ga...@gmail.com>
> wrote:
>
> > Before seeing the last reply I had just tested on CloudStack 4.15 + Ceph
> +
> > KVM, and it worked fine; however, I did the test with one snapshot of the
> > volume.
> > Maybe the scheduled/incremental snapshotting adds a different variable to
> > the equation.
> >
> > From my tests, the DB holds one reference as Ready on the secondary
> > storage, and one as Destroyed (on primary storage). I think that it is
> the
> > expected behavior and the secondary storage "garbage" should be cleaned
> up
> > on a window of 24-48 hours (by default, as the cleanup thread runs each
> 24
> > hours and it checks for a timestamp of 24 hours as well, on the worst
> case
> > it can take up to 48 hours, on the best 24 hours).
> >
> > I find it quite weird the fact that it has been thrown a null pointer
> > before; as if the volume has been deleted and the Snapshot already
> exists.
> >
> > Your log presents the following ERROR:
> > 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> > inspecting dest type SNAPSHOT
> > 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
> > dest=861
> >
> > It indicates an issue when copying the snapshot from primary to secondary
> > storage; I would look closely at the secondary storage pool and check the
> > SSVM (secondary storage system VM).
> >
> > For reference,here follows an example from the deleted backed-up snapshot
> > from my test:
> >
> > > select id,store_id,snapshot_id,state,store_role,install_path from
> > snapshot_store_ref where snapshot_id=759;
> >
> >
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
> >
> > | id | store_id | snapshot_id | state | store_role | install_path
> > |
> >
> >
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
> >
> > | 838 | 21 | 759 | Destroyed | Primary |
> >
> >
> rbd/8e918c48-f32a-4c4e-81b2-0ba374d705dc/b41ba753-afad-42b5-849f-839736cb3a77
> > |
> > | 839 | 1 | 759 | Ready | Image |
> > snapshots/6/12872/b41ba753-afad-42b5-849f-839736cb3a77
> > |
> >
> >
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
> >
> >
> >
> >
> >
> > Em sex., 5 de mar. de 2021 às 07:59, Edward St Pierre <
> > edward.stpierre@gmail.com> escreveu:
> >
> > > Hi
> > >
> > > The issue happens multiple snapshots, I have run a test with
> > > scheduled hourly volume snapshots for a test, here are the logs:
> > >
> > > 2021-03-05 10:03:43,277 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Execute VM work job:
> > >
> > >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > > 2021-03-05 10:03:43,342 DEBUG [c.c.a.t.Request]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Seq 6-5629781009189976396: Sending { Cmd , MgmtId:
> > > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> > 100011,
> > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > GB)
> > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > > cloudstack.storage.to
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > > }
> > > 2021-03-05 10:03:44,670 DEBUG [c.c.a.t.Request]
> > > (AgentManager-Handler-9:null) (logid:) Seq 6-5629781009189976396:
> > > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
> > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0"}}]
> > > }
> > > 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> > > inspecting dest type SNAPSHOT
> > > 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary
> 861
> > > dest=861
> > > 2021-03-05 10:03:44,898 DEBUG [c.c.a.t.Request]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Seq 6-5629781009189976397: Sending { Cmd , MgmtId:
> > > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> > 100011,
> > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
> > > cloudstack.storage.to
> > >
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > > apache.cloudstack.storage.to
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > GB)
> > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > > cloudstack.storage.to
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/9/225","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > GB)
> > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
> > > 10.100.7.51/export/secondary
> > >
> >
> ","_role":"Image"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
> > > }
> > > 2021-03-05 10:08:42,314 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Snapshot
> scheduler.poll
> > is
> > > being called at 2021-03-05 10:08:42 GMT
> > > 2021-03-05 10:08:42,315 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Got 0 snapshots to be
> > > executed at 2021-03-05 10:08:42 GMT
> > > 2021-03-05 10:09:24,952 DEBUG [c.c.a.t.Request]
> > > (AgentManager-Handler-2:null) (logid:) Seq 6-5629781009189976397:
> > > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
> > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.
> > > cloudstack.storage.to
> > >
> >
> .SnapshotObjectTO":{"path":"snapshots/9/225/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"16888233984"}},"result":"true","wait":"0"}}]
> > > }
> > > 2021-03-05 10:09:24,976 DEBUG [c.c.s.s.SnapshotManagerImpl]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Max snaps: 1 exceeded for snapshot policy with Id: 8.
> > > Deleting oldest snapshot: 860
> > > 2021-03-05 10:09:24,978 DEBUG [c.c.u.AccountManagerImpl]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Access to
> > > com.cloud.storage.SnapshotVO$$EnhancerByCGLIB$$43460565@642f5e4f
> granted
> > > to
> > > Acct[2ad78538-d6d9-4f24-967a-90701ff3a35f-edward] by DomainChecker
> > > 2021-03-05 10:09:25,037 DEBUG [c.c.a.t.Request]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Seq 16-5311714285507142014: Sending { Cmd , MgmtId:
> > > 345050527765, via: 16(vxtr-ln1-chst03.vxtream.com), Ver: v1, Flags:
> > > 100011,
> > >
> > >
> >
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.
> > > cloudstack.storage.to
> > >
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/b8e3403e-7b6c-4bee-8b27-5ad9843353cd","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > > apache.cloudstack.storage.to
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > > GB)
> > >
> > >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > > cloudstack.storage.to
> > >
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305090342","hypervisorType":"KVM","id":"860","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > > }
> > > 2021-03-05 10:09:25,574 DEBUG [c.c.a.t.Request]
> > > (AgentManager-Handler-9:null) (logid:) Seq 16-5311714285507142014:
> > > Processing: { Ans: , MgmtId: 345050527765, via: 16, Ver: v1, Flags:
> 10,
> > > [{"com.cloud.agent.api.Answer":{"result":"true","details":"Snapshot
> > >
> 3c6bbe64-e924-4c94-a0eb-4b18e5786d58@b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> > > removed successfully.","wait":"0"}}] }
> > > 2021-03-05 10:09:25,588 DEBUG [c.c.r.ResourceLimitManagerImpl]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Updating resource Type = snapshot count for Account =
> 9
> > > Operation = decreasing Amount = 1
> > > 2021-03-05 10:09:25,620 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > > (logid:fc7d7320) Done executing VM work job:
> > >
> > >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > > 2021-03-05 10:09:25,628 DEBUG [c.c.v.VmWorkJobDispatcher]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320)
> > Done
> > > with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM
> > 156,
> > > job origin: 6141
> > > 2021-03-05 10:09:25,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320)
> > Done
> > > executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-6142
> > > 2021-03-05 10:09:25,666 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > > (API-Job-Executor-19:ctx-3956f4cc job-6141 ctx-d69f2a1d)
> (logid:fc7d7320)
> > > Complete async job-6141, jobStatus: SUCCEEDED, resultCode: 0, result:
> > >
> > >
> >
> org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"076c3f3e-4875-419d-beed-398e6d938f41","account":"edward","domainid":"76fcd53c-c1bc-47cf-946c-336c30a53ca1","domain":"ESP","snapshottype":"HOURLY","volumeid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumename":"ROOT-156","volumetype":"ROOT","created":"2021-03-05T10:03:42+0000","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","intervaltype":"HOURLY","state":"BackedUp","physicalsize":"16888233984","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","ostypeid":"2cd2aa56-ee6a-11e9-8f54-0050569d3815","osdisplayname":"CentOS
> > > 7","virtualsize":"107374182400","tags":[]}
> > > 2021-03-05 10:09:25,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > > (API-Job-Executor-19:ctx-3956f4cc job-6141) (logid:fc7d7320) Done
> > executing
> > > org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
> > > job-6141
> > >
> > > Here are the actual snapshots on secondary storage:
> > >
> > > -rw-r--r--. 1 root root 16888233984 Mar 5 10:09
> > > a00ba130-19f0-454c-9b74-55f95a64bfb5
> > > -rw-r--r--. 1 root root 16888233984 Mar 5 09:09
> > > b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> > >
> > > Here are the entries in the DB relating to the snapshots:
> > >
> > > select * from snapshots order by created desc limit 2;
> > >
> > >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > > | id | data_center_id | account_id | domain_id | volume_id |
> > > disk_offering_id | status | path | name
> > > | uuid | snapshot_type |
> > type_description
> > > | size | created | removed | backup_snap_id |
> > swift_id
> > > | sechost_id | prev_snap_id | hypervisor_type | version | s3_id |
> > min_iops
> > > | max_iops | location_type |
> > >
> > >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > > | 861 | 1 | 9 | 6 | 225 |
> > > 5 | BackedUp | NULL | ESP-LN1-VOIP01_ROOT-156_20210305100342 |
> > > 076c3f3e-4875-419d-beed-398e6d938f41 | 3 | HOURLY
> |
> > > 107374182400 | 2021-03-05 10:03:42 | NULL | NULL |
> NULL
> > |
> > > NULL | NULL | KVM | 2.2 | NULL |
> NULL
> > |
> > > NULL | NULL |
> > > | 860 | 1 | 9 | 6 | 225 |
> > > 5 | Destroyed | NULL | ESP-LN1-VOIP01_ROOT-156_20210305090342 |
> > > 2998a50e-7282-45c5-bab6-8231e6343783 | 3 | HOURLY
> |
> > > 107374182400 | 2021-03-05 09:03:42 | NULL | NULL |
> NULL
> > |
> > > NULL | NULL | KVM | 2.2 | NULL |
> NULL
> > |
> > > NULL | NULL |
> > >
> > >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > >
> > >
> > >
> > > Regards
> > >
> > > Ed
> > >
> > > On Fri, 5 Mar 2021 at 02:20, Gabriel Bräscher <ga...@gmail.com>
> > > wrote:
> > >
> > > > There was an open issue indeed but a PR solved it for 4.15. The issue
> > > > reported on this email looks a bit different than the ones I have
> seen.
> > > >
> > > > Background on a recent issue:
> > > > - Issue #4498 "RBD Snapshot fails when snapshot.backup.to.secondary:
> > > true"
> > > > has been fixed by PR #4568 "kvm: Fix double-escape issue while
> creating
> > > rbd
> > > > disk options"
> > > >
> > > > Reading the log:
> > > > - In order for such a null pointer to happen the volume from the
> > snapshot
> > > > has been deleted on DB. Thus, it is either a bug or an inconsistency
> on
> > > the
> > > > DB; e.g.: deleting the volume prior to its Snapshots.
> > > >
> > > > Is this occurrence an isolated one or does it happen with multiple
> > > > snapshots that have been deleted?
> > > >
> > > > #4498: https://github.com/apache/cloudstack/issues/4498
> > > > #4568: https://github.com/apache/cloudstack/pull/4568
> > > >
> > > > Em qui., 4 de mar. de 2021 às 18:55, Rakesh v <
> > www.rakeshv.com@gmail.com
> > > >
> > > > escreveu:
> > > >
> > > > > If I remember properly there is already an issue raised for it in
> > > github
> > > > >
> > > > > Sent from my iPhone
> > > > >
> > > > > > On Mar 4, 2021, at 9:48 PM, Andrija Panic <
> andrija.panic@gmail.com
> > >
> > > > > wrote:
> > > > > >
> > > > > > @Gabriel Beims Bräscher <ga...@gmail.com> does this rings
> > any
> > > > > bells
> > > > > > for you? I haven't played with Ceph / snap clean-up issue on 4.15
> > > > myself.
> > > > > >
> > > > > > Best,
> > > > > >
> > > > > >> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <
> > > > > edward.stpierre@gmail.com>
> > > > > >> wrote:
> > > > > >>
> > > > > >> Hi All,
> > > > > >>
> > > > > >> I Wonder if someone could help me.
> > > > > >>
> > > > > >> Currently using ceph for primary storage and have
> > > > > >> 'snapshot.backup.to.secondary' enabled.
> > > > > >>
> > > > > >> Since upgrading to 4.15 the volume snapshots do not seem to be
> > > getting
> > > > > >> deleted from the secondary storage. Could this be a bug?
> > > > > >>
> > > > > >> Also when logged in as the main admin account when navigating to
> > > > > 'Storage /
> > > > > >> Snapshots' an Error 500 is returned with the following error in
> > the
> > > > > logs:
> > > > > >>
> > > > > >> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> > > > > >> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb)
> > > > unhandled
> > > > > >> exception executing api command: [Ljava.lang.String;@7ac2d249
> > > > > >> java.lang.NullPointerException
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> > > > > >> at
> > > com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> > > > > >> at
> com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> > > > > >> at
> > com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> > > > > >> at
> > > > > >>
> > > com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> > > > > >> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> > > > > >> at
> > > com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> > > > > >> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> > > > > >> at
> > > javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> > > > > >> at
> > > javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> > > > > >> at
> > > > > >>
> > > org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> > > > > >> at
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> > > > > >> at
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> > > > > >> at
> > > > > >>
> > > > >
> > >
> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > > >> at
> org.eclipse.jetty.server.Server.handle(Server.java:500)
> > > > > >> at
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> > > > > >> at
> > > > > >>
> > org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> > > > > >> at
> > > > > >>
> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> > > > > >> at
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> > > > > >> at
> > > > > >> org.eclipse.jetty.io
> > > > > >>
> > > >
> .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> > > > > >> at org.eclipse.jetty.io
> > > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> > > > > >> at
> > > > > >>
> > > > >
> > >
> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> > > > > >> at
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> > > > > >> at org.eclipse.jetty.io
> > > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > > >> at
> > > > > >> org.eclipse.jetty.io
> > > .ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> > > > > >> at
> > > > > >>
> > > > > >>
> > > > >
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> > > > > >> at java.base/java.lang.Thread.run(Thread.java:834)
> > > > > >>
> > > > > >
> > > > > >
> > > > > > --
> > > > > >
> > > > > > Andrija Panić
> > > > >
> > > >
> > >
> >
>
Re: Issue with Snapshots
Posted by Edward St Pierre <ed...@gmail.com>.
Hi,
Thanks for that information and pointers on where to look, I have checked
it out and the data was also on the secondary storage and the storage VM is
mounting the NFS servers etc. (I have redeployed it just incase)
I have gone through some of the older snapshots that are not getting
removed, and they do have that reference in the Ready Status:
MariaDB [cloud]> select
id,store_id,snapshot_id,state,store_role,install_path from
snapshot_store_ref where install_path like
'%8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07';
+------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
| id | store_id | snapshot_id | state | store_role | install_path
|
+------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
| 1554 | 7 | 852 | Destroyed | Primary |
cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
|
| 1555 | 1 | 852 | Ready | Image |
snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07
|
+------+----------+-------------+-----------+------------+------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)
MariaDB [cloud]> select * from snapshots where id=852;
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
-+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
-----+
| id | data_center_id | account_id | domain_id | volume_id |
disk_offering_id | status | path | name
| uuid | snapshot_type |
type_description | size | created | removed |
backup_snap_id | swift_id | sechost_id | prev_snap_id | hypervisor_type |
version | s3_id | min_iops | max_iops | location_ type |
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
-+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
-----+
| 852 | 1 | 2 | 1 | 146 |
6 | Destroyed | NULL | vxtr-ln1-box01_DATA-86_20210226010342 |
10ece2f5-39cf-4afe-9894-48c7c47e1463 | 4 |
DAILY | 214748364800 | 2021-02-26 01:03:42 | NULL | NULL
| NULL | NULL | NULL | KVM | 2.2 |
NULL | NULL | NULL | NULL |
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+---------------------------------------+--------------------------------------+--------------
-+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+----------
-----+
I also cannot see any errors when it is created:
2021-02-26 01:03:42,019 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Got 1 snapshots to be
executed at 2021-02-26 01:03:42 GMT
2021-02-26 01:03:42,023 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Scheduling 1 snapshot for
volume id 146 (volume name:DATA-86) for schedule id: 7 at 2021-02-26
01:00:00 GMT
2021-02-26 01:03:42,064 DEBUG [c.c.r.ResourceLimitManagerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) Updating resource Type =
snapshot count for Account = 2 Operation = increasing Amount = 1
2021-02-26 01:03:42,083 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(SnapshotPollTask:ctx-69729307) (logid:3b2789b3) submit async job-6123,
details: AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType:
Snapshot, instanceId: 852, cmd:
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
{"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2021-02-26 01:03:42,088 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Executing
AsyncJobVO {id:6123, userId: 1, accountId: 2, instanceType: Snapshot,
instanceId: 852, cmd:
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd, cmdInfo:
{"policyid":"7","ctxUserId":"1","volumeid":"146","ctxStartEventId":"1","id":"852","ctxAccountId":"2"},
cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
result: null, initMsid: 345050527765, completeMsid: null, lastUpdated:
null, lastPolled: null, created: null, removed: null}
2021-02-26 01:03:43,284 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Execute VM work job:
com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
2021-02-26 01:03:45,111 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Seq 10-5259641414815547085: Sending { Cmd , MgmtId:
345050527765, via: 10(chst01.vxtream.com), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/79625868-979a-4ed5-9f8d-2af6f612824c/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
GB)
214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/146","volume":{"uuid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeType":"DATADISK","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"DATA-86","size":"(200.00
GB)
214748364800","path":"79625868-979a-4ed5-9f8d-2af6f612824c","volumeId":"146","vmName":"i-2-86-VM","accountId":"2","format":"QCOW2","provisioningType":"THIN","id":"146","deviceId":"1","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
10.100.7.51/export/secondary","_role":"Image"}},"vmName":"i-2-86-VM","name":"vxtr-ln1-box01_DATA-86_20210226010342","hypervisorType":"KVM","id":"852","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
}
2021-02-26 01:22:17,334 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-7:null) (logid:) Seq 10-5259641414815547085:
Processing: { Ans: , MgmtId: 345050527765, via: 10, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/146/8c8fbbde-7d5b-4d25-a6ac-dd5ddedf7e07","id":"0","quiescevm":"false","physicalSize":"112297967616"}},"result":"true","wait":"0"}}]
}
2021-02-26 01:22:17,355 DEBUG [c.c.s.s.SnapshotManagerImpl]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Max snaps: 3 exceeded for snapshot policy with Id: 7.
Deleting oldest snapshot: 849
2021-02-26 01:22:18,473 DEBUG [c.c.r.ResourceLimitManagerImpl]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Updating resource Type = snapshot count for Account = 2
Operation = decreasing Amount = 1
2021-02-26 01:22:18,499 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-17:ctx-efb43f2f job-6123/job-6124 ctx-bd5f01a2)
(logid:7c83430b) Done executing VM work job:
com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":146,"policyId":7,"snapshotId":852,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":2,"vmId":86,"handlerName":"VolumeApiServiceImpl"}
2021-02-26 01:22:18,565 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-10:ctx-c366f638 job-6123 ctx-1be547c7) (logid:7c83430b)
Complete async job-6123, jobStatus: SUCCEEDED, resultCode: 0, result:
org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"10ece2f5-39cf-4afe-9894-48c7c47e1463","account":"admin","domainid":"1e48287f-ee6a-11e9-8f54-0050569d3815","domain":"ROOT","snapshottype":"DAILY","volumeid":"79625868-979a-4ed5-9f8d-2af6f612824c","volumename":"DATA-86","volumetype":"DATADISK","created":"2021-02-26T01:03:42+0000","name":"vxtr-ln1-box01_DATA-86_20210226010342","intervaltype":"DAILY","state":"BackedUp","physicalsize":"112297967616","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","virtualsize":"214748364800","tags":[]}
2021-02-26 01:22:18,592 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-10:ctx-c366f638 job-6123) (logid:7c83430b) Done executing
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
job-6123
This log indicates when it is set to be removed:
2021-03-01 01:22:13,750 DEBUG [c.c.s.s.SnapshotManagerImpl]
(Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
(logid:503cabb8) Max snaps: 3 exceeded for snapshot policy with Id: 7.
Deleting olest snapshot: 852
2021-03-01 01:22:13,797 DEBUG [c.c.h.o.r.Ovm3HypervisorGuru]
(Work-Job-Executor-20:ctx-df45986f job-6129/job-6130 ctx-a889fd20)
(logid:503cabb8) getCommandHostDelegation: class
org.apache.cloudstack.storage.comand.DeleteCommand
Any indication on what I should look for in the logs for regarding the
'secondary storage "garbage" should be cleaned up'?
Many thanks for your help.
Ed
On Fri, 5 Mar 2021 at 15:12, Gabriel Bräscher <ga...@gmail.com> wrote:
> Before seeing the last reply I had just tested on CloudStack 4.15 + Ceph +
> KVM, and it worked fine; however, I did the test with one snapshot of the
> volume.
> Maybe the scheduled/incremental snapshotting adds a different variable to
> the equation.
>
> From my tests, the DB holds one reference as Ready on the secondary
> storage, and one as Destroyed (on primary storage). I think that it is the
> expected behavior and the secondary storage "garbage" should be cleaned up
> on a window of 24-48 hours (by default, as the cleanup thread runs each 24
> hours and it checks for a timestamp of 24 hours as well, on the worst case
> it can take up to 48 hours, on the best 24 hours).
>
> I find it quite weird the fact that it has been thrown a null pointer
> before; as if the volume has been deleted and the Snapshot already exists.
>
> Your log presents the following ERROR:
> 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> inspecting dest type SNAPSHOT
> 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
> dest=861
>
> It indicates an issue when copying the snapshot from primary to secondary
> storage; I would look closely at the secondary storage pool and check the
> SSVM (secondary storage system VM).
>
> For reference,here follows an example from the deleted backed-up snapshot
> from my test:
>
> > select id,store_id,snapshot_id,state,store_role,install_path from
> snapshot_store_ref where snapshot_id=759;
>
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
>
> | id | store_id | snapshot_id | state | store_role | install_path
> |
>
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
>
> | 838 | 21 | 759 | Destroyed | Primary |
>
> rbd/8e918c48-f32a-4c4e-81b2-0ba374d705dc/b41ba753-afad-42b5-849f-839736cb3a77
> |
> | 839 | 1 | 759 | Ready | Image |
> snapshots/6/12872/b41ba753-afad-42b5-849f-839736cb3a77
> |
>
> +-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
>
>
>
>
>
> Em sex., 5 de mar. de 2021 às 07:59, Edward St Pierre <
> edward.stpierre@gmail.com> escreveu:
>
> > Hi
> >
> > The issue happens multiple snapshots, I have run a test with
> > scheduled hourly volume snapshots for a test, here are the logs:
> >
> > 2021-03-05 10:03:43,277 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Execute VM work job:
> >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > 2021-03-05 10:03:43,342 DEBUG [c.c.a.t.Request]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Seq 6-5629781009189976396: Sending { Cmd , MgmtId:
> > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> 100011,
> >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > }
> > 2021-03-05 10:03:44,670 DEBUG [c.c.a.t.Request]
> > (AgentManager-Handler-9:null) (logid:) Seq 6-5629781009189976396:
> > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
> >
> >
> [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0"}}]
> > }
> > 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> > inspecting dest type SNAPSHOT
> > 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
> > dest=861
> > 2021-03-05 10:03:44,898 DEBUG [c.c.a.t.Request]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Seq 6-5629781009189976397: Sending { Cmd , MgmtId:
> > 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags:
> 100011,
> >
> >
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > apache.cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/9/225","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
> > 10.100.7.51/export/secondary
> >
> ","_role":"Image"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
> > }
> > 2021-03-05 10:08:42,314 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Snapshot scheduler.poll
> is
> > being called at 2021-03-05 10:08:42 GMT
> > 2021-03-05 10:08:42,315 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> > (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Got 0 snapshots to be
> > executed at 2021-03-05 10:08:42 GMT
> > 2021-03-05 10:09:24,952 DEBUG [c.c.a.t.Request]
> > (AgentManager-Handler-2:null) (logid:) Seq 6-5629781009189976397:
> > Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
> >
> >
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"snapshots/9/225/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"16888233984"}},"result":"true","wait":"0"}}]
> > }
> > 2021-03-05 10:09:24,976 DEBUG [c.c.s.s.SnapshotManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Max snaps: 1 exceeded for snapshot policy with Id: 8.
> > Deleting oldest snapshot: 860
> > 2021-03-05 10:09:24,978 DEBUG [c.c.u.AccountManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Access to
> > com.cloud.storage.SnapshotVO$$EnhancerByCGLIB$$43460565@642f5e4f granted
> > to
> > Acct[2ad78538-d6d9-4f24-967a-90701ff3a35f-edward] by DomainChecker
> > 2021-03-05 10:09:25,037 DEBUG [c.c.a.t.Request]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Seq 16-5311714285507142014: Sending { Cmd , MgmtId:
> > 345050527765, via: 16(vxtr-ln1-chst03.vxtream.com), Ver: v1, Flags:
> > 100011,
> >
> >
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.
> > cloudstack.storage.to
> >
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/b8e3403e-7b6c-4bee-8b27-5ad9843353cd","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> > apache.cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> > GB)
> >
> >
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> > cloudstack.storage.to
> >
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305090342","hypervisorType":"KVM","id":"860","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> > }
> > 2021-03-05 10:09:25,574 DEBUG [c.c.a.t.Request]
> > (AgentManager-Handler-9:null) (logid:) Seq 16-5311714285507142014:
> > Processing: { Ans: , MgmtId: 345050527765, via: 16, Ver: v1, Flags: 10,
> > [{"com.cloud.agent.api.Answer":{"result":"true","details":"Snapshot
> > 3c6bbe64-e924-4c94-a0eb-4b18e5786d58@b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> > removed successfully.","wait":"0"}}] }
> > 2021-03-05 10:09:25,588 DEBUG [c.c.r.ResourceLimitManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Updating resource Type = snapshot count for Account = 9
> > Operation = decreasing Amount = 1
> > 2021-03-05 10:09:25,620 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> > (logid:fc7d7320) Done executing VM work job:
> >
> >
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> > 2021-03-05 10:09:25,628 DEBUG [c.c.v.VmWorkJobDispatcher]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320)
> Done
> > with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM
> 156,
> > job origin: 6141
> > 2021-03-05 10:09:25,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320)
> Done
> > executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-6142
> > 2021-03-05 10:09:25,666 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (API-Job-Executor-19:ctx-3956f4cc job-6141 ctx-d69f2a1d) (logid:fc7d7320)
> > Complete async job-6141, jobStatus: SUCCEEDED, resultCode: 0, result:
> >
> >
> org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"076c3f3e-4875-419d-beed-398e6d938f41","account":"edward","domainid":"76fcd53c-c1bc-47cf-946c-336c30a53ca1","domain":"ESP","snapshottype":"HOURLY","volumeid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumename":"ROOT-156","volumetype":"ROOT","created":"2021-03-05T10:03:42+0000","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","intervaltype":"HOURLY","state":"BackedUp","physicalsize":"16888233984","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","ostypeid":"2cd2aa56-ee6a-11e9-8f54-0050569d3815","osdisplayname":"CentOS
> > 7","virtualsize":"107374182400","tags":[]}
> > 2021-03-05 10:09:25,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> > (API-Job-Executor-19:ctx-3956f4cc job-6141) (logid:fc7d7320) Done
> executing
> > org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
> > job-6141
> >
> > Here are the actual snapshots on secondary storage:
> >
> > -rw-r--r--. 1 root root 16888233984 Mar 5 10:09
> > a00ba130-19f0-454c-9b74-55f95a64bfb5
> > -rw-r--r--. 1 root root 16888233984 Mar 5 09:09
> > b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> >
> > Here are the entries in the DB relating to the snapshots:
> >
> > select * from snapshots order by created desc limit 2;
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > | id | data_center_id | account_id | domain_id | volume_id |
> > disk_offering_id | status | path | name
> > | uuid | snapshot_type |
> type_description
> > | size | created | removed | backup_snap_id |
> swift_id
> > | sechost_id | prev_snap_id | hypervisor_type | version | s3_id |
> min_iops
> > | max_iops | location_type |
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> > | 861 | 1 | 9 | 6 | 225 |
> > 5 | BackedUp | NULL | ESP-LN1-VOIP01_ROOT-156_20210305100342 |
> > 076c3f3e-4875-419d-beed-398e6d938f41 | 3 | HOURLY |
> > 107374182400 | 2021-03-05 10:03:42 | NULL | NULL | NULL
> |
> > NULL | NULL | KVM | 2.2 | NULL | NULL
> |
> > NULL | NULL |
> > | 860 | 1 | 9 | 6 | 225 |
> > 5 | Destroyed | NULL | ESP-LN1-VOIP01_ROOT-156_20210305090342 |
> > 2998a50e-7282-45c5-bab6-8231e6343783 | 3 | HOURLY |
> > 107374182400 | 2021-03-05 09:03:42 | NULL | NULL | NULL
> |
> > NULL | NULL | KVM | 2.2 | NULL | NULL
> |
> > NULL | NULL |
> >
> >
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> >
> >
> >
> > Regards
> >
> > Ed
> >
> > On Fri, 5 Mar 2021 at 02:20, Gabriel Bräscher <ga...@gmail.com>
> > wrote:
> >
> > > There was an open issue indeed but a PR solved it for 4.15. The issue
> > > reported on this email looks a bit different than the ones I have seen.
> > >
> > > Background on a recent issue:
> > > - Issue #4498 "RBD Snapshot fails when snapshot.backup.to.secondary:
> > true"
> > > has been fixed by PR #4568 "kvm: Fix double-escape issue while creating
> > rbd
> > > disk options"
> > >
> > > Reading the log:
> > > - In order for such a null pointer to happen the volume from the
> snapshot
> > > has been deleted on DB. Thus, it is either a bug or an inconsistency on
> > the
> > > DB; e.g.: deleting the volume prior to its Snapshots.
> > >
> > > Is this occurrence an isolated one or does it happen with multiple
> > > snapshots that have been deleted?
> > >
> > > #4498: https://github.com/apache/cloudstack/issues/4498
> > > #4568: https://github.com/apache/cloudstack/pull/4568
> > >
> > > Em qui., 4 de mar. de 2021 às 18:55, Rakesh v <
> www.rakeshv.com@gmail.com
> > >
> > > escreveu:
> > >
> > > > If I remember properly there is already an issue raised for it in
> > github
> > > >
> > > > Sent from my iPhone
> > > >
> > > > > On Mar 4, 2021, at 9:48 PM, Andrija Panic <andrija.panic@gmail.com
> >
> > > > wrote:
> > > > >
> > > > > @Gabriel Beims Bräscher <ga...@gmail.com> does this rings
> any
> > > > bells
> > > > > for you? I haven't played with Ceph / snap clean-up issue on 4.15
> > > myself.
> > > > >
> > > > > Best,
> > > > >
> > > > >> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <
> > > > edward.stpierre@gmail.com>
> > > > >> wrote:
> > > > >>
> > > > >> Hi All,
> > > > >>
> > > > >> I Wonder if someone could help me.
> > > > >>
> > > > >> Currently using ceph for primary storage and have
> > > > >> 'snapshot.backup.to.secondary' enabled.
> > > > >>
> > > > >> Since upgrading to 4.15 the volume snapshots do not seem to be
> > getting
> > > > >> deleted from the secondary storage. Could this be a bug?
> > > > >>
> > > > >> Also when logged in as the main admin account when navigating to
> > > > 'Storage /
> > > > >> Snapshots' an Error 500 is returned with the following error in
> the
> > > > logs:
> > > > >>
> > > > >> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> > > > >> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb)
> > > unhandled
> > > > >> exception executing api command: [Ljava.lang.String;@7ac2d249
> > > > >> java.lang.NullPointerException
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> > > > >> at
> > com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> > > > >> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> > > > >> at
> com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> > > > >> at
> > > > >>
> > com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> > > > >> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> > > > >> at
> > com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> > > > >> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> > > > >> at
> > javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> > > > >> at
> > javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> > > > >> at
> > > > >>
> > org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> > > > >> at
> > > > >>
> > > >
> > org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > > >> at org.eclipse.jetty.server.Server.handle(Server.java:500)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> > > > >> at
> > > > >>
> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> > > > >> at
> > > > >> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> > > > >> at
> > > > >> org.eclipse.jetty.io
> > > > >>
> > > .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> > > > >> at org.eclipse.jetty.io
> > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> > > > >> at
> > > > >>
> > > >
> > org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> > > > >> at
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> > > > >> at org.eclipse.jetty.io
> > > > >> .FillInterest.fillable(FillInterest.java:103)
> > > > >> at
> > > > >> org.eclipse.jetty.io
> > .ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> > > > >> at
> > > > >>
> > > > >>
> > > >
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> > > > >> at java.base/java.lang.Thread.run(Thread.java:834)
> > > > >>
> > > > >
> > > > >
> > > > > --
> > > > >
> > > > > Andrija Panić
> > > >
> > >
> >
>
Re: Issue with Snapshots
Posted by Gabriel Bräscher <ga...@gmail.com>.
Before seeing the last reply I had just tested on CloudStack 4.15 + Ceph +
KVM, and it worked fine; however, I did the test with one snapshot of the
volume.
Maybe the scheduled/incremental snapshotting adds a different variable to
the equation.
From my tests, the DB holds one reference as Ready on the secondary
storage, and one as Destroyed (on primary storage). I think that it is the
expected behavior and the secondary storage "garbage" should be cleaned up
on a window of 24-48 hours (by default, as the cleanup thread runs each 24
hours and it checks for a timestamp of 24 hours as well, on the worst case
it can take up to 48 hours, on the best 24 hours).
I find it quite weird the fact that it has been thrown a null pointer
before; as if the volume has been deleted and the Snapshot already exists.
Your log presents the following ERROR:
2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
inspecting dest type SNAPSHOT
2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
dest=861
It indicates an issue when copying the snapshot from primary to secondary
storage; I would look closely at the secondary storage pool and check the
SSVM (secondary storage system VM).
For reference,here follows an example from the deleted backed-up snapshot
from my test:
> select id,store_id,snapshot_id,state,store_role,install_path from
snapshot_store_ref where snapshot_id=759;
+-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
| id | store_id | snapshot_id | state | store_role | install_path
|
+-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
| 838 | 21 | 759 | Destroyed | Primary |
rbd/8e918c48-f32a-4c4e-81b2-0ba374d705dc/b41ba753-afad-42b5-849f-839736cb3a77
|
| 839 | 1 | 759 | Ready | Image |
snapshots/6/12872/b41ba753-afad-42b5-849f-839736cb3a77
|
+-----+----------+-------------+-----------+------------+-------------------------------------------------------------------------------+
Em sex., 5 de mar. de 2021 às 07:59, Edward St Pierre <
edward.stpierre@gmail.com> escreveu:
> Hi
>
> The issue happens multiple snapshots, I have run a test with
> scheduled hourly volume snapshots for a test, here are the logs:
>
> 2021-03-05 10:03:43,277 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Execute VM work job:
>
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> 2021-03-05 10:03:43,342 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Seq 6-5629781009189976396: Sending { Cmd , MgmtId:
> 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags: 100011,
>
> [{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> GB)
>
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> }
> 2021-03-05 10:03:44,670 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-9:null) (logid:) Seq 6-5629781009189976396:
> Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
>
> [{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0"}}]
> }
> 2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
> inspecting dest type SNAPSHOT
> 2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
> dest=861
> 2021-03-05 10:03:44,898 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Seq 6-5629781009189976397: Sending { Cmd , MgmtId:
> 345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags: 100011,
>
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.
> cloudstack.storage.to
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> apache.cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> GB)
>
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/9/225","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> GB)
>
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
> 10.100.7.51/export/secondary
> ","_role":"Image"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
> }
> 2021-03-05 10:08:42,314 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Snapshot scheduler.poll is
> being called at 2021-03-05 10:08:42 GMT
> 2021-03-05 10:08:42,315 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
> (SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Got 0 snapshots to be
> executed at 2021-03-05 10:08:42 GMT
> 2021-03-05 10:09:24,952 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-2:null) (logid:) Seq 6-5629781009189976397:
> Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
>
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.
> cloudstack.storage.to
> .SnapshotObjectTO":{"path":"snapshots/9/225/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"16888233984"}},"result":"true","wait":"0"}}]
> }
> 2021-03-05 10:09:24,976 DEBUG [c.c.s.s.SnapshotManagerImpl]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Max snaps: 1 exceeded for snapshot policy with Id: 8.
> Deleting oldest snapshot: 860
> 2021-03-05 10:09:24,978 DEBUG [c.c.u.AccountManagerImpl]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Access to
> com.cloud.storage.SnapshotVO$$EnhancerByCGLIB$$43460565@642f5e4f granted
> to
> Acct[2ad78538-d6d9-4f24-967a-90701ff3a35f-edward] by DomainChecker
> 2021-03-05 10:09:25,037 DEBUG [c.c.a.t.Request]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Seq 16-5311714285507142014: Sending { Cmd , MgmtId:
> 345050527765, via: 16(vxtr-ln1-chst03.vxtream.com), Ver: v1, Flags:
> 100011,
>
> [{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.
> cloudstack.storage.to
> .SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/b8e3403e-7b6c-4bee-8b27-5ad9843353cd","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.
> apache.cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
> GB)
>
> 107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.
> cloudstack.storage.to
> .PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305090342","hypervisorType":"KVM","id":"860","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
> }
> 2021-03-05 10:09:25,574 DEBUG [c.c.a.t.Request]
> (AgentManager-Handler-9:null) (logid:) Seq 16-5311714285507142014:
> Processing: { Ans: , MgmtId: 345050527765, via: 16, Ver: v1, Flags: 10,
> [{"com.cloud.agent.api.Answer":{"result":"true","details":"Snapshot
> 3c6bbe64-e924-4c94-a0eb-4b18e5786d58@b8e3403e-7b6c-4bee-8b27-5ad9843353cd
> removed successfully.","wait":"0"}}] }
> 2021-03-05 10:09:25,588 DEBUG [c.c.r.ResourceLimitManagerImpl]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Updating resource Type = snapshot count for Account = 9
> Operation = decreasing Amount = 1
> 2021-03-05 10:09:25,620 DEBUG [c.c.v.VmWorkJobHandlerProxy]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
> (logid:fc7d7320) Done executing VM work job:
>
> com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
> 2021-03-05 10:09:25,628 DEBUG [c.c.v.VmWorkJobDispatcher]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320) Done
> with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 156,
> job origin: 6141
> 2021-03-05 10:09:25,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320) Done
> executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-6142
> 2021-03-05 10:09:25,666 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-19:ctx-3956f4cc job-6141 ctx-d69f2a1d) (logid:fc7d7320)
> Complete async job-6141, jobStatus: SUCCEEDED, resultCode: 0, result:
>
> org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"076c3f3e-4875-419d-beed-398e6d938f41","account":"edward","domainid":"76fcd53c-c1bc-47cf-946c-336c30a53ca1","domain":"ESP","snapshottype":"HOURLY","volumeid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumename":"ROOT-156","volumetype":"ROOT","created":"2021-03-05T10:03:42+0000","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","intervaltype":"HOURLY","state":"BackedUp","physicalsize":"16888233984","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","ostypeid":"2cd2aa56-ee6a-11e9-8f54-0050569d3815","osdisplayname":"CentOS
> 7","virtualsize":"107374182400","tags":[]}
> 2021-03-05 10:09:25,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
> (API-Job-Executor-19:ctx-3956f4cc job-6141) (logid:fc7d7320) Done executing
> org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
> job-6141
>
> Here are the actual snapshots on secondary storage:
>
> -rw-r--r--. 1 root root 16888233984 Mar 5 10:09
> a00ba130-19f0-454c-9b74-55f95a64bfb5
> -rw-r--r--. 1 root root 16888233984 Mar 5 09:09
> b8e3403e-7b6c-4bee-8b27-5ad9843353cd
>
> Here are the entries in the DB relating to the snapshots:
>
> select * from snapshots order by created desc limit 2;
>
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> | id | data_center_id | account_id | domain_id | volume_id |
> disk_offering_id | status | path | name
> | uuid | snapshot_type | type_description
> | size | created | removed | backup_snap_id | swift_id
> | sechost_id | prev_snap_id | hypervisor_type | version | s3_id | min_iops
> | max_iops | location_type |
>
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
> | 861 | 1 | 9 | 6 | 225 |
> 5 | BackedUp | NULL | ESP-LN1-VOIP01_ROOT-156_20210305100342 |
> 076c3f3e-4875-419d-beed-398e6d938f41 | 3 | HOURLY |
> 107374182400 | 2021-03-05 10:03:42 | NULL | NULL | NULL |
> NULL | NULL | KVM | 2.2 | NULL | NULL |
> NULL | NULL |
> | 860 | 1 | 9 | 6 | 225 |
> 5 | Destroyed | NULL | ESP-LN1-VOIP01_ROOT-156_20210305090342 |
> 2998a50e-7282-45c5-bab6-8231e6343783 | 3 | HOURLY |
> 107374182400 | 2021-03-05 09:03:42 | NULL | NULL | NULL |
> NULL | NULL | KVM | 2.2 | NULL | NULL |
> NULL | NULL |
>
> +-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
>
>
>
> Regards
>
> Ed
>
> On Fri, 5 Mar 2021 at 02:20, Gabriel Bräscher <ga...@gmail.com>
> wrote:
>
> > There was an open issue indeed but a PR solved it for 4.15. The issue
> > reported on this email looks a bit different than the ones I have seen.
> >
> > Background on a recent issue:
> > - Issue #4498 "RBD Snapshot fails when snapshot.backup.to.secondary:
> true"
> > has been fixed by PR #4568 "kvm: Fix double-escape issue while creating
> rbd
> > disk options"
> >
> > Reading the log:
> > - In order for such a null pointer to happen the volume from the snapshot
> > has been deleted on DB. Thus, it is either a bug or an inconsistency on
> the
> > DB; e.g.: deleting the volume prior to its Snapshots.
> >
> > Is this occurrence an isolated one or does it happen with multiple
> > snapshots that have been deleted?
> >
> > #4498: https://github.com/apache/cloudstack/issues/4498
> > #4568: https://github.com/apache/cloudstack/pull/4568
> >
> > Em qui., 4 de mar. de 2021 às 18:55, Rakesh v <www.rakeshv.com@gmail.com
> >
> > escreveu:
> >
> > > If I remember properly there is already an issue raised for it in
> github
> > >
> > > Sent from my iPhone
> > >
> > > > On Mar 4, 2021, at 9:48 PM, Andrija Panic <an...@gmail.com>
> > > wrote:
> > > >
> > > > @Gabriel Beims Bräscher <ga...@gmail.com> does this rings any
> > > bells
> > > > for you? I haven't played with Ceph / snap clean-up issue on 4.15
> > myself.
> > > >
> > > > Best,
> > > >
> > > >> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <
> > > edward.stpierre@gmail.com>
> > > >> wrote:
> > > >>
> > > >> Hi All,
> > > >>
> > > >> I Wonder if someone could help me.
> > > >>
> > > >> Currently using ceph for primary storage and have
> > > >> 'snapshot.backup.to.secondary' enabled.
> > > >>
> > > >> Since upgrading to 4.15 the volume snapshots do not seem to be
> getting
> > > >> deleted from the secondary storage. Could this be a bug?
> > > >>
> > > >> Also when logged in as the main admin account when navigating to
> > > 'Storage /
> > > >> Snapshots' an Error 500 is returned with the following error in the
> > > logs:
> > > >>
> > > >> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> > > >> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb)
> > unhandled
> > > >> exception executing api command: [Ljava.lang.String;@7ac2d249
> > > >> java.lang.NullPointerException
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> > > >> at
> > > >>
> > > >>
> > >
> >
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> > > >> at
> com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> > > >> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> > > >> at com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> > > >> at
> > > >>
> com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> > > >> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> > > >> at
> com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> > > >> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> > > >> at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> > > >> at
> javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> > > >> at
> > > >>
> org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> > > >> at
> > > >>
> > >
> >
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> > > >> at
> > > >>
> > >
> >
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> > > >> at
> > > >>
> > >
> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > > >> at org.eclipse.jetty.server.Server.handle(Server.java:500)
> > > >> at
> > > >>
> > >
> >
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> > > >> at
> > > >> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> > > >> at
> > > >> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> > > >> at
> > > >>
> > >
> >
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> > > >> at
> > > >> org.eclipse.jetty.io
> > > >>
> > .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> > > >> at org.eclipse.jetty.io
> > > >> .FillInterest.fillable(FillInterest.java:103)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> > > >> at
> > > >>
> > >
> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> > > >> at
> > > >>
> > >
> >
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> > > >> at org.eclipse.jetty.io
> > > >> .FillInterest.fillable(FillInterest.java:103)
> > > >> at
> > > >> org.eclipse.jetty.io
> .ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> > > >> at
> > > >>
> > > >>
> > >
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> > > >> at java.base/java.lang.Thread.run(Thread.java:834)
> > > >>
> > > >
> > > >
> > > > --
> > > >
> > > > Andrija Panić
> > >
> >
>
Re: Issue with Snapshots
Posted by Edward St Pierre <ed...@gmail.com>.
Hi
The issue happens multiple snapshots, I have run a test with
scheduled hourly volume snapshots for a test, here are the logs:
2021-03-05 10:03:43,277 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Execute VM work job:
com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
2021-03-05 10:03:43,342 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Seq 6-5629781009189976396: Sending { Cmd , MgmtId:
345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CreateObjectCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
GB)
107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
}
2021-03-05 10:03:44,670 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-9:null) (logid:) Seq 6-5629781009189976396:
Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CreateObjectAnswer":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"0"}},"result":"true","wait":"0"}}]
}
2021-03-05 10:03:44,757 DEBUG [o.a.c.s.m.AncientDataMotionStrategy]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) copyAsync inspecting src type SNAPSHOT copyAsync
inspecting dest type SNAPSHOT
2021-03-05 10:03:44,888 ERROR [o.a.c.s.e.DefaultEndPointSelector]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) IR24 select BACKUPSNAPSHOT from primary to secondary 861
dest=861
2021-03-05 10:03:44,898 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Seq 6-5629781009189976397: Sending { Cmd , MgmtId:
345050527765, via: 6(vxtr-ln1-chst02.vxtream.com), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/a00ba130-19f0-454c-9b74-55f95a64bfb5","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
GB)
107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"destTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/9/225","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
GB)
107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://
10.100.7.51/export/secondary","_role":"Image"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","hypervisorType":"KVM","id":"861","quiescevm":"false","physicalSize":"0"}},"executeInSequence":"false","options":{"fullSnapshot":"true"},"options2":{},"wait":"21600"}}]
}
2021-03-05 10:08:42,314 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Snapshot scheduler.poll is
being called at 2021-03-05 10:08:42 GMT
2021-03-05 10:08:42,315 DEBUG [c.c.s.s.SnapshotSchedulerImpl]
(SnapshotPollTask:ctx-357a9dcc) (logid:7175331e) Got 0 snapshots to be
executed at 2021-03-05 10:08:42 GMT
2021-03-05 10:09:24,952 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-2:null) (logid:) Seq 6-5629781009189976397:
Processing: { Ans: , MgmtId: 345050527765, via: 6, Ver: v1, Flags: 10,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/9/225/a00ba130-19f0-454c-9b74-55f95a64bfb5","id":"0","quiescevm":"false","physicalSize":"16888233984"}},"result":"true","wait":"0"}}]
}
2021-03-05 10:09:24,976 DEBUG [c.c.s.s.SnapshotManagerImpl]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Max snaps: 1 exceeded for snapshot policy with Id: 8.
Deleting oldest snapshot: 860
2021-03-05 10:09:24,978 DEBUG [c.c.u.AccountManagerImpl]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Access to
com.cloud.storage.SnapshotVO$$EnhancerByCGLIB$$43460565@642f5e4f granted to
Acct[2ad78538-d6d9-4f24-967a-90701ff3a35f-edward] by DomainChecker
2021-03-05 10:09:25,037 DEBUG [c.c.a.t.Request]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Seq 16-5311714285507142014: Sending { Cmd , MgmtId:
345050527765, via: 16(vxtr-ln1-chst03.vxtream.com), Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.DeleteCommand":{"data":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"cloudstack2019/3c6bbe64-e924-4c94-a0eb-4b18e5786d58/b8e3403e-7b6c-4bee-8b27-5ad9843353cd","volume":{"uuid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"name":"ROOT-156","size":"(100.00
GB)
107374182400","path":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumeId":"225","vmName":"i-9-156-VM","accountId":"9","format":"QCOW2","provisioningType":"THIN","id":"225","deviceId":"0","hypervisorType":"KVM","directDownload":"false","deployAsIs":"false"},"dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"658c4937-b7bc-3aa7-a0d3-aa144224dd52","id":"7","poolType":"RBD","host":"ceph-mon.cloudstack","path":"cloudstack2019","port":"6789","url":"RBD://ceph-mon.cloudstack/cloudstack2019/?ROLE=Primary&STOREUUID=658c4937-b7bc-3aa7-a0d3-aa144224dd52","isManaged":"false"}},"vmName":"i-9-156-VM","name":"ESP-LN1-VOIP01_ROOT-156_20210305090342","hypervisorType":"KVM","id":"860","quiescevm":"false","physicalSize":"0"}},"wait":"0"}}]
}
2021-03-05 10:09:25,574 DEBUG [c.c.a.t.Request]
(AgentManager-Handler-9:null) (logid:) Seq 16-5311714285507142014:
Processing: { Ans: , MgmtId: 345050527765, via: 16, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.Answer":{"result":"true","details":"Snapshot
3c6bbe64-e924-4c94-a0eb-4b18e5786d58@b8e3403e-7b6c-4bee-8b27-5ad9843353cd
removed successfully.","wait":"0"}}] }
2021-03-05 10:09:25,588 DEBUG [c.c.r.ResourceLimitManagerImpl]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Updating resource Type = snapshot count for Account = 9
Operation = decreasing Amount = 1
2021-03-05 10:09:25,620 DEBUG [c.c.v.VmWorkJobHandlerProxy]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142 ctx-43a8373c)
(logid:fc7d7320) Done executing VM work job:
com.cloud.vm.VmWorkTakeVolumeSnapshot{"volumeId":225,"policyId":8,"snapshotId":861,"quiesceVm":false,"asyncBackup":false,"userId":1,"accountId":9,"vmId":156,"handlerName":"VolumeApiServiceImpl"}
2021-03-05 10:09:25,628 DEBUG [c.c.v.VmWorkJobDispatcher]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320) Done
with run of VM work job: com.cloud.vm.VmWorkTakeVolumeSnapshot for VM 156,
job origin: 6141
2021-03-05 10:09:25,628 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(Work-Job-Executor-26:ctx-65993d1d job-6141/job-6142) (logid:fc7d7320) Done
executing com.cloud.vm.VmWorkTakeVolumeSnapshot for job-6142
2021-03-05 10:09:25,666 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-19:ctx-3956f4cc job-6141 ctx-d69f2a1d) (logid:fc7d7320)
Complete async job-6141, jobStatus: SUCCEEDED, resultCode: 0, result:
org.apache.cloudstack.api.response.SnapshotResponse/snapshot/{"id":"076c3f3e-4875-419d-beed-398e6d938f41","account":"edward","domainid":"76fcd53c-c1bc-47cf-946c-336c30a53ca1","domain":"ESP","snapshottype":"HOURLY","volumeid":"3c6bbe64-e924-4c94-a0eb-4b18e5786d58","volumename":"ROOT-156","volumetype":"ROOT","created":"2021-03-05T10:03:42+0000","name":"ESP-LN1-VOIP01_ROOT-156_20210305100342","intervaltype":"HOURLY","state":"BackedUp","physicalsize":"16888233984","zoneid":"9000b853-f5e0-4451-ad49-64dfae95db84","revertable":"true","ostypeid":"2cd2aa56-ee6a-11e9-8f54-0050569d3815","osdisplayname":"CentOS
7","virtualsize":"107374182400","tags":[]}
2021-03-05 10:09:25,670 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
(API-Job-Executor-19:ctx-3956f4cc job-6141) (logid:fc7d7320) Done executing
org.apache.cloudstack.api.command.user.snapshot.CreateSnapshotCmd for
job-6141
Here are the actual snapshots on secondary storage:
-rw-r--r--. 1 root root 16888233984 Mar 5 10:09
a00ba130-19f0-454c-9b74-55f95a64bfb5
-rw-r--r--. 1 root root 16888233984 Mar 5 09:09
b8e3403e-7b6c-4bee-8b27-5ad9843353cd
Here are the entries in the DB relating to the snapshots:
select * from snapshots order by created desc limit 2;
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
| id | data_center_id | account_id | domain_id | volume_id |
disk_offering_id | status | path | name
| uuid | snapshot_type | type_description
| size | created | removed | backup_snap_id | swift_id
| sechost_id | prev_snap_id | hypervisor_type | version | s3_id | min_iops
| max_iops | location_type |
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
| 861 | 1 | 9 | 6 | 225 |
5 | BackedUp | NULL | ESP-LN1-VOIP01_ROOT-156_20210305100342 |
076c3f3e-4875-419d-beed-398e6d938f41 | 3 | HOURLY |
107374182400 | 2021-03-05 10:03:42 | NULL | NULL | NULL |
NULL | NULL | KVM | 2.2 | NULL | NULL |
NULL | NULL |
| 860 | 1 | 9 | 6 | 225 |
5 | Destroyed | NULL | ESP-LN1-VOIP01_ROOT-156_20210305090342 |
2998a50e-7282-45c5-bab6-8231e6343783 | 3 | HOURLY |
107374182400 | 2021-03-05 09:03:42 | NULL | NULL | NULL |
NULL | NULL | KVM | 2.2 | NULL | NULL |
NULL | NULL |
+-----+----------------+------------+-----------+-----------+------------------+-----------+------+----------------------------------------+--------------------------------------+---------------+------------------+--------------+---------------------+---------+----------------+----------+------------+--------------+-----------------+---------+-------+----------+----------+---------------+
Regards
Ed
On Fri, 5 Mar 2021 at 02:20, Gabriel Bräscher <ga...@gmail.com> wrote:
> There was an open issue indeed but a PR solved it for 4.15. The issue
> reported on this email looks a bit different than the ones I have seen.
>
> Background on a recent issue:
> - Issue #4498 "RBD Snapshot fails when snapshot.backup.to.secondary: true"
> has been fixed by PR #4568 "kvm: Fix double-escape issue while creating rbd
> disk options"
>
> Reading the log:
> - In order for such a null pointer to happen the volume from the snapshot
> has been deleted on DB. Thus, it is either a bug or an inconsistency on the
> DB; e.g.: deleting the volume prior to its Snapshots.
>
> Is this occurrence an isolated one or does it happen with multiple
> snapshots that have been deleted?
>
> #4498: https://github.com/apache/cloudstack/issues/4498
> #4568: https://github.com/apache/cloudstack/pull/4568
>
> Em qui., 4 de mar. de 2021 às 18:55, Rakesh v <ww...@gmail.com>
> escreveu:
>
> > If I remember properly there is already an issue raised for it in github
> >
> > Sent from my iPhone
> >
> > > On Mar 4, 2021, at 9:48 PM, Andrija Panic <an...@gmail.com>
> > wrote:
> > >
> > > @Gabriel Beims Bräscher <ga...@gmail.com> does this rings any
> > bells
> > > for you? I haven't played with Ceph / snap clean-up issue on 4.15
> myself.
> > >
> > > Best,
> > >
> > >> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <
> > edward.stpierre@gmail.com>
> > >> wrote:
> > >>
> > >> Hi All,
> > >>
> > >> I Wonder if someone could help me.
> > >>
> > >> Currently using ceph for primary storage and have
> > >> 'snapshot.backup.to.secondary' enabled.
> > >>
> > >> Since upgrading to 4.15 the volume snapshots do not seem to be getting
> > >> deleted from the secondary storage. Could this be a bug?
> > >>
> > >> Also when logged in as the main admin account when navigating to
> > 'Storage /
> > >> Snapshots' an Error 500 is returned with the following error in the
> > logs:
> > >>
> > >> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> > >> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb)
> unhandled
> > >> exception executing api command: [Ljava.lang.String;@7ac2d249
> > >> java.lang.NullPointerException
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> > >> at
> > >>
> > >>
> >
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> > >> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> > >> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> > >> at com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> > >> at
> > >> com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> > >> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> > >> at
> > >>
> > >>
> >
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> > >> at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> > >> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> > >> at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> > >> at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> > >> at
> > >> org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> > >> at
> > >>
> >
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> > >> at
> > >>
> >
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> > >> at
> > >>
> > org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> > >> at org.eclipse.jetty.server.Server.handle(Server.java:500)
> > >> at
> > >>
> >
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> > >> at
> > >> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> > >> at
> > >> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> > >> at
> > >>
> >
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> > >> at
> > >> org.eclipse.jetty.io
> > >>
> .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> > >> at org.eclipse.jetty.io
> > >> .FillInterest.fillable(FillInterest.java:103)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> > >> at
> > >>
> > org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> > >> at
> > >>
> >
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> > >> at org.eclipse.jetty.io
> > >> .FillInterest.fillable(FillInterest.java:103)
> > >> at
> > >> org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> > >> at
> > >>
> > >>
> >
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> > >> at java.base/java.lang.Thread.run(Thread.java:834)
> > >>
> > >
> > >
> > > --
> > >
> > > Andrija Panić
> >
>
Re: Issue with Snapshots
Posted by Gabriel Bräscher <ga...@gmail.com>.
There was an open issue indeed but a PR solved it for 4.15. The issue
reported on this email looks a bit different than the ones I have seen.
Background on a recent issue:
- Issue #4498 "RBD Snapshot fails when snapshot.backup.to.secondary: true"
has been fixed by PR #4568 "kvm: Fix double-escape issue while creating rbd
disk options"
Reading the log:
- In order for such a null pointer to happen the volume from the snapshot
has been deleted on DB. Thus, it is either a bug or an inconsistency on the
DB; e.g.: deleting the volume prior to its Snapshots.
Is this occurrence an isolated one or does it happen with multiple
snapshots that have been deleted?
#4498: https://github.com/apache/cloudstack/issues/4498
#4568: https://github.com/apache/cloudstack/pull/4568
Em qui., 4 de mar. de 2021 às 18:55, Rakesh v <ww...@gmail.com>
escreveu:
> If I remember properly there is already an issue raised for it in github
>
> Sent from my iPhone
>
> > On Mar 4, 2021, at 9:48 PM, Andrija Panic <an...@gmail.com>
> wrote:
> >
> > @Gabriel Beims Bräscher <ga...@gmail.com> does this rings any
> bells
> > for you? I haven't played with Ceph / snap clean-up issue on 4.15 myself.
> >
> > Best,
> >
> >> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <
> edward.stpierre@gmail.com>
> >> wrote:
> >>
> >> Hi All,
> >>
> >> I Wonder if someone could help me.
> >>
> >> Currently using ceph for primary storage and have
> >> 'snapshot.backup.to.secondary' enabled.
> >>
> >> Since upgrading to 4.15 the volume snapshots do not seem to be getting
> >> deleted from the secondary storage. Could this be a bug?
> >>
> >> Also when logged in as the main admin account when navigating to
> 'Storage /
> >> Snapshots' an Error 500 is returned with the following error in the
> logs:
> >>
> >> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> >> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb) unhandled
> >> exception executing api command: [Ljava.lang.String;@7ac2d249
> >> java.lang.NullPointerException
> >> at
> >>
> >>
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> >> at
> >>
> >>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> >> at
> >>
> >>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> >> at
> >>
> >>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> >> at
> >>
> >>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> >> at
> >>
> >>
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> >> at
> >>
> >>
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> >> at
> >>
> >>
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> >> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> >> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> >> at com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> >> at
> >> com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> >> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> >> at
> >>
> >>
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> >> at
> >>
> >>
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> >> at
> >>
> >>
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> >> at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> >> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> >> at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> >> at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> >> at
> >>
> >>
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> >> at
> >> org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> >> at
> >>
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> >> at
> >>
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> >> at
> >>
> >>
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> >> at
> >>
> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> >> at
> >>
> >>
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> >> at
> >>
> >>
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> >> at org.eclipse.jetty.server.Server.handle(Server.java:500)
> >> at
> >>
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> >> at
> >> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> >> at
> >> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> >> at
> >>
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> >> at
> >> org.eclipse.jetty.io
> >> .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> >> at org.eclipse.jetty.io
> >> .FillInterest.fillable(FillInterest.java:103)
> >> at
> >>
> >>
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> >> at
> >>
> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> >> at
> >>
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> >> at org.eclipse.jetty.io
> >> .FillInterest.fillable(FillInterest.java:103)
> >> at
> >> org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> >> at
> >>
> >>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> >> at
> >>
> >>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> >> at
> >>
> >>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> >> at
> >>
> >>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> >> at
> >>
> >>
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> >> at
> >>
> >>
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> >> at
> >>
> >>
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> >> at java.base/java.lang.Thread.run(Thread.java:834)
> >>
> >
> >
> > --
> >
> > Andrija Panić
>
Re: Issue with Snapshots
Posted by Rakesh v <ww...@gmail.com>.
If I remember properly there is already an issue raised for it in github
Sent from my iPhone
> On Mar 4, 2021, at 9:48 PM, Andrija Panic <an...@gmail.com> wrote:
>
> @Gabriel Beims Bräscher <ga...@gmail.com> does this rings any bells
> for you? I haven't played with Ceph / snap clean-up issue on 4.15 myself.
>
> Best,
>
>> On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <ed...@gmail.com>
>> wrote:
>>
>> Hi All,
>>
>> I Wonder if someone could help me.
>>
>> Currently using ceph for primary storage and have
>> 'snapshot.backup.to.secondary' enabled.
>>
>> Since upgrading to 4.15 the volume snapshots do not seem to be getting
>> deleted from the secondary storage. Could this be a bug?
>>
>> Also when logged in as the main admin account when navigating to 'Storage /
>> Snapshots' an Error 500 is returned with the following error in the logs:
>>
>> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
>> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb) unhandled
>> exception executing api command: [Ljava.lang.String;@7ac2d249
>> java.lang.NullPointerException
>> at
>>
>> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
>> at
>>
>> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
>> at
>>
>> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
>> at
>>
>> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
>> at
>>
>> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
>> at
>>
>> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
>> at
>>
>> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
>> at
>>
>> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
>> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
>> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
>> at com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
>> at
>> com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
>> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
>> at
>>
>> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
>> at
>>
>> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
>> at
>>
>> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
>> at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
>> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
>> at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
>> at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
>> at
>>
>> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
>> at
>> org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
>> at
>> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
>> at
>>
>> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
>> at
>> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
>> at
>>
>> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
>> at
>>
>> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
>> at
>>
>> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
>> at
>>
>> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
>> at
>>
>> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
>> at
>>
>> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
>> at
>> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
>> at
>>
>> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
>> at
>>
>> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
>> at
>>
>> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
>> at
>>
>> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
>> at
>>
>> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
>> at
>>
>> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
>> at
>>
>> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
>> at org.eclipse.jetty.server.Server.handle(Server.java:500)
>> at
>> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
>> at
>> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
>> at
>> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
>> at
>> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
>> at
>> org.eclipse.jetty.io
>> .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
>> at org.eclipse.jetty.io
>> .FillInterest.fillable(FillInterest.java:103)
>> at
>>
>> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
>> at
>> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
>> at
>> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
>> at org.eclipse.jetty.io
>> .FillInterest.fillable(FillInterest.java:103)
>> at
>> org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
>> at
>>
>> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
>> at
>>
>> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
>> at
>>
>> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
>> at
>>
>> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
>> at
>>
>> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
>> at
>>
>> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
>> at
>>
>> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
>> at java.base/java.lang.Thread.run(Thread.java:834)
>>
>
>
> --
>
> Andrija Panić
Re: Issue with Snapshots
Posted by Andrija Panic <an...@gmail.com>.
@Gabriel Beims Bräscher <ga...@gmail.com> does this rings any bells
for you? I haven't played with Ceph / snap clean-up issue on 4.15 myself.
Best,
On Tue, 2 Mar 2021 at 17:16, Edward St Pierre <ed...@gmail.com>
wrote:
> Hi All,
>
> I Wonder if someone could help me.
>
> Currently using ceph for primary storage and have
> 'snapshot.backup.to.secondary' enabled.
>
> Since upgrading to 4.15 the volume snapshots do not seem to be getting
> deleted from the secondary storage. Could this be a bug?
>
> Also when logged in as the main admin account when navigating to 'Storage /
> Snapshots' an Error 500 is returned with the following error in the logs:
>
> 2021-03-02 16:11:01,018 ERROR [c.c.a.ApiServer]
> (qtp1762902523-19:ctx-60162a51 ctx-75a1b986) (logid:368908bb) unhandled
> exception executing api command: [Ljava.lang.String;@7ac2d249
> java.lang.NullPointerException
> at
>
> org.apache.cloudstack.storage.snapshot.StorageSystemSnapshotStrategy.canHandle(StorageSystemSnapshotStrategy.java:944)
> at
>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:72)
> at
>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl$3.canHandle(StorageStrategyFactoryImpl.java:69)
> at
>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.bestMatch(StorageStrategyFactoryImpl.java:95)
> at
>
> org.apache.cloudstack.storage.helper.StorageStrategyFactoryImpl.getSnapshotStrategy(StorageStrategyFactoryImpl.java:69)
> at
>
> org.apache.cloudstack.storage.snapshot.SnapshotObject.isRevertable(SnapshotObject.java:153)
> at
>
> com.cloud.api.ApiResponseHelper.createSnapshotResponse(ApiResponseHelper.java:569)
> at
>
> org.apache.cloudstack.api.command.user.snapshot.ListSnapshotsCmd.execute(ListSnapshotsCmd.java:117)
> at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:156)
> at com.cloud.api.ApiServer.queueCommand(ApiServer.java:764)
> at com.cloud.api.ApiServer.handleRequest(ApiServer.java:588)
> at
> com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:321)
> at com.cloud.api.ApiServlet$1.run(ApiServlet.java:134)
> at
>
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:55)
> at
>
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:102)
> at
>
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:52)
> at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:131)
> at com.cloud.api.ApiServlet.doGet(ApiServlet.java:93)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:645)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
> at
>
> org.eclipse.jetty.servlet.ServletHolder$NotAsyncServlet.service(ServletHolder.java:1386)
> at
> org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:755)
> at
> org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:547)
> at
>
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
> at
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:590)
> at
>
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> at
>
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235)
> at
>
> org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1610)
> at
>
> org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
> at
>
> org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1300)
> at
>
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
> at
> org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:485)
> at
>
> org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1580)
> at
>
> org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
> at
>
> org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1215)
> at
>
> org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
> at
>
> org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:767)
> at
>
> org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:146)
> at
>
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
> at org.eclipse.jetty.server.Server.handle(Server.java:500)
> at
> org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:383)
> at
> org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:547)
> at
> org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:375)
> at
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
> at
> org.eclipse.jetty.io
> .AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
> at org.eclipse.jetty.io
> .FillInterest.fillable(FillInterest.java:103)
> at
>
> org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
> at
> org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
> at
> org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
> at org.eclipse.jetty.io
> .FillInterest.fillable(FillInterest.java:103)
> at
> org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
> at
>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
> at
>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
> at
>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
> at
>
> org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
> at
>
> org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
> at
>
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
> at
>
> org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
> at java.base/java.lang.Thread.run(Thread.java:834)
>
--
Andrija Panić