From c428d3bb3410129433dc36b0efd57735d018d733 Mon Sep 17 00:00:00 2001 From: Stephan Krug Date: Tue, 19 Sep 2023 03:54:52 -0300 Subject: [PATCH] Add and improve logs in snapshot scheduling (#6925) Co-authored-by: Stephan Krug --- .../snapshot/SnapshotSchedulerImpl.java | 91 +++++--- .../snapshot/SnapshotSchedulerImplTest.java | 217 ++++++++++++++++++ 2 files changed, 282 insertions(+), 26 deletions(-) create mode 100644 server/src/test/java/com/cloud/storage/snapshot/SnapshotSchedulerImplTest.java diff --git a/server/src/main/java/com/cloud/storage/snapshot/SnapshotSchedulerImpl.java b/server/src/main/java/com/cloud/storage/snapshot/SnapshotSchedulerImpl.java index a9c402c86be..3c40911e0f3 100644 --- a/server/src/main/java/com/cloud/storage/snapshot/SnapshotSchedulerImpl.java +++ b/server/src/main/java/com/cloud/storage/snapshot/SnapshotSchedulerImpl.java @@ -264,10 +264,10 @@ public class SnapshotSchedulerImpl extends ManagerBase implements SnapshotSchedu @DB protected void scheduleSnapshots() { String displayTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, _currentTimestamp); - s_logger.debug("Snapshot scheduler.poll is being called at " + displayTime); + s_logger.debug(String.format("Snapshot scheduler is being called at [%s].", displayTime)); final List snapshotsToBeExecuted = _snapshotScheduleDao.getSchedulesToExecute(_currentTimestamp); - s_logger.debug("Got " + snapshotsToBeExecuted.size() + " snapshots to be executed at " + displayTime); + s_logger.debug(String.format("There are [%s] scheduled snapshots to be executed at [%s].", snapshotsToBeExecuted.size(), displayTime)); for (final SnapshotScheduleVO snapshotToBeExecuted : snapshotsToBeExecuted) { SnapshotScheduleVO tmpSnapshotScheduleVO = null; @@ -275,34 +275,18 @@ public class SnapshotSchedulerImpl extends ManagerBase implements SnapshotSchedu final long policyId = snapshotToBeExecuted.getPolicyId(); final long volumeId = snapshotToBeExecuted.getVolumeId(); try { - final VolumeVO volume = _volsDao.findById(volumeId); - if (volume.getPoolId() == null) { - // this volume is not attached + final VolumeVO volume = _volsDao.findByIdIncludingRemoved(snapshotToBeExecuted.getVolumeId()); + + if (!canSnapshotBeScheduled(snapshotToBeExecuted, volume)) { continue; } - Account volAcct = _acctDao.findById(volume.getAccountId()); - if (volAcct == null || volAcct.getState() == Account.State.DISABLED) { - // this account has been removed, so don't trigger recurring snapshot - if (s_logger.isDebugEnabled()) { - s_logger.debug("Skip snapshot for volume " + volume.getUuid() + " since its account has been removed or disabled"); - } - continue; - } - if (_snapshotPolicyDao.findById(policyId) == null) { - _snapshotScheduleDao.remove(snapshotToBeExecuted.getId()); - } - if (s_logger.isDebugEnabled()) { - final Date scheduledTimestamp = snapshotToBeExecuted.getScheduledTimestamp(); - displayTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, scheduledTimestamp); - s_logger.debug("Scheduling 1 snapshot for volume id " + volumeId + " (volume name:" + - volume.getName() + ") for schedule id: " + snapshotToBeExecuted.getId() + " at " + displayTime); - } tmpSnapshotScheduleVO = _snapshotScheduleDao.acquireInLockTable(snapshotScheId); final Long eventId = ActionEventUtils.onScheduledActionEvent(User.UID_SYSTEM, volume.getAccountId(), EventTypes.EVENT_SNAPSHOT_CREATE, "creating snapshot for volume Id:" + volume.getUuid(), volumeId, ApiCommandResourceType.Volume.toString(), true, 0); + s_logger.trace(String.format("Mapping parameters required to generate a CreateSnapshotCmd for snapshot [%s].", snapshotToBeExecuted.getUuid())); final Map params = new HashMap(); params.put(ApiConstants.VOLUME_ID, "" + volumeId); params.put(ApiConstants.POLICY_ID, "" + policyId); @@ -319,24 +303,27 @@ public class SnapshotSchedulerImpl extends ManagerBase implements SnapshotSchedu } } + s_logger.trace(String.format("Generating a CreateSnapshotCmd for snapshot [%s] with parameters: [%s].", snapshotToBeExecuted.getUuid(), params.toString())); final CreateSnapshotCmd cmd = new CreateSnapshotCmd(); ComponentContext.inject(cmd); _dispatcher.dispatchCreateCmd(cmd, params); params.put("id", "" + cmd.getEntityId()); params.put("ctxStartEventId", "1"); + final Date scheduledTimestamp = snapshotToBeExecuted.getScheduledTimestamp(); + displayTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, scheduledTimestamp); + s_logger.debug(String.format("Scheduling snapshot [%s] for volume [%s] at [%s].", snapshotToBeExecuted.getUuid(), volume.getVolumeDescription(), displayTime)); AsyncJobVO job = new AsyncJobVO("", User.UID_SYSTEM, volume.getAccountId(), CreateSnapshotCmd.class.getName(), ApiGsonHelper.getBuilder().create().toJson(params), cmd.getEntityId(), cmd.getApiResourceType() != null ? cmd.getApiResourceType().toString() : null, null); job.setDispatcher(_asyncDispatcher.getName()); - final long jobId = _asyncMgr.submitAsyncJob(job); + s_logger.debug(String.format("Scheduled snapshot [%s] for volume [%s] as job [%s].", snapshotToBeExecuted.getUuid(), volume.getVolumeDescription(), job.getUuid())); tmpSnapshotScheduleVO.setAsyncJobId(jobId); _snapshotScheduleDao.update(snapshotScheId, tmpSnapshotScheduleVO); } catch (final Exception e) { - // TODO Logging this exception is enough? - s_logger.warn("Scheduling snapshot failed due to " + e.toString()); + s_logger.error(String.format("The scheduling of snapshot [%s] for volume [%s] failed due to [%s].", snapshotToBeExecuted.getUuid(), volumeId, e.toString()), e); } finally { if (tmpSnapshotScheduleVO != null) { _snapshotScheduleDao.releaseFromLockTable(snapshotScheId); @@ -345,7 +332,59 @@ public class SnapshotSchedulerImpl extends ManagerBase implements SnapshotSchedu } } - private Date scheduleNextSnapshotJob(final SnapshotScheduleVO snapshotSchedule) { + /** + * Verifies if a snapshot for a volume can be scheduled or not based on volume and account status, and removes it from the snapshot scheduler if its policy was removed. + * + * @param snapshotToBeScheduled the snapshot to be scheduled + * @param volume the volume associated with the snapshot to be scheduled + * @return true if the snapshot can be scheduled, and false otherwise. + */ + protected boolean canSnapshotBeScheduled(final SnapshotScheduleVO snapshotToBeScheduled, final VolumeVO volume) { + if (volume.getRemoved() != null) { + s_logger.warn(String.format("Skipping snapshot [%s] for volume [%s] because it has been removed. Having a snapshot scheduled for a volume that has been " + + "removed is an inconsistency; please, check your database.", snapshotToBeScheduled.getUuid(), volume.getVolumeDescription())); + return false; + } + + if (volume.getPoolId() == null) { + s_logger.debug(String.format("Skipping snapshot [%s] for volume [%s] because it is not attached to any storage pool.", snapshotToBeScheduled.getUuid(), + volume.getVolumeDescription())); + return false; + } + + if (isAccountRemovedOrDisabled(snapshotToBeScheduled, volume)) { + return false; + } + + if (_snapshotPolicyDao.findById(snapshotToBeScheduled.getPolicyId()) == null) { + s_logger.debug(String.format("Snapshot's policy [%s] for volume [%s] has been removed; therefore, this snapshot will be removed from the snapshot scheduler.", + snapshotToBeScheduled.getPolicyId(), volume.getVolumeDescription())); + _snapshotScheduleDao.remove(snapshotToBeScheduled.getId()); + } + + s_logger.debug(String.format("Snapshot [%s] for volume [%s] can be executed.", snapshotToBeScheduled.getUuid(), volume.getVolumeDescription())); + return true; + } + + protected boolean isAccountRemovedOrDisabled(final SnapshotScheduleVO snapshotToBeExecuted, final VolumeVO volume) { + Account volAcct = _acctDao.findById(volume.getAccountId()); + + if (volAcct == null) { + s_logger.debug(String.format("Skipping snapshot [%s] for volume [%s] because its account [%s] has been removed.", snapshotToBeExecuted.getUuid(), + volume.getVolumeDescription(), volume.getAccountId())); + return true; + } + + if (volAcct.getState() == Account.State.DISABLED) { + s_logger.debug(String.format("Skipping snapshot [%s] for volume [%s] because its account [%s] is disabled.", snapshotToBeExecuted.getUuid(), + volume.getVolumeDescription(), volAcct.getUuid())); + return true; + } + + return false; + } + + protected Date scheduleNextSnapshotJob(final SnapshotScheduleVO snapshotSchedule) { if (snapshotSchedule == null) { return null; } diff --git a/server/src/test/java/com/cloud/storage/snapshot/SnapshotSchedulerImplTest.java b/server/src/test/java/com/cloud/storage/snapshot/SnapshotSchedulerImplTest.java new file mode 100644 index 00000000000..36e0f5d3b80 --- /dev/null +++ b/server/src/test/java/com/cloud/storage/snapshot/SnapshotSchedulerImplTest.java @@ -0,0 +1,217 @@ +// Licensed to the Apache Software Foundation (ASF) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The ASF licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. +package com.cloud.storage.snapshot; + +import com.cloud.storage.Snapshot; +import com.cloud.storage.SnapshotPolicyVO; +import com.cloud.storage.SnapshotScheduleVO; +import com.cloud.storage.VolumeVO; +import com.cloud.storage.dao.SnapshotPolicyDao; +import com.cloud.storage.dao.SnapshotScheduleDao; +import com.cloud.storage.dao.VolumeDao; +import com.cloud.user.Account; +import com.cloud.user.AccountVO; +import com.cloud.user.dao.AccountDao; +import org.junit.Assert; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.mockito.InjectMocks; +import org.mockito.Mock; +import org.mockito.Mockito; +import org.mockito.Spy; +import org.mockito.junit.MockitoJUnitRunner; +import java.util.Date; + +@RunWith(MockitoJUnitRunner.class) +public class SnapshotSchedulerImplTest { + + @Spy + @InjectMocks + SnapshotSchedulerImpl snapshotSchedulerImplSpy = new SnapshotSchedulerImpl(); + + @Mock + SnapshotPolicyDao snapshotPolicyDaoMock; + + @Mock + SnapshotPolicyVO snapshotPolicyVoMock; + + @Mock + SnapshotScheduleDao snapshotScheduleDaoMock; + + @Mock + AccountDao accountDaoMock; + + @Mock + VolumeDao volumeDaoMock; + + @Mock + VolumeVO volumeVoMock; + + @Mock + AccountVO accountVoMock; + + @Test + public void scheduleNextSnapshotJobTestParameterIsNullReturnNull() { + SnapshotScheduleVO snapshotScheduleVO = null; + + Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO); + + Assert.assertNull(result); + } + + @Test + public void scheduleNextSnapshotJobTestIsManualPolicyIdReturnNull() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + snapshotScheduleVO.setPolicyId(Snapshot.MANUAL_POLICY_ID); + + Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO); + + Assert.assertNull(result); + } + + @Test + public void scheduleNextSnapshotJobTestPolicyIsNotNullDoNotCallExpunge() { + Date expected = new Date(); + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + snapshotScheduleVO.setPolicyId(1l); + + Mockito.doReturn(snapshotPolicyVoMock).when(snapshotPolicyDaoMock).findById(Mockito.anyLong()); + Mockito.doReturn(expected).when(snapshotSchedulerImplSpy).scheduleNextSnapshotJob(Mockito.any(SnapshotPolicyVO.class)); + + Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO); + Assert.assertEquals(expected, result); + + Mockito.verify(snapshotScheduleDaoMock, Mockito.never()).expunge(Mockito.anyLong()); + } + + @Test + public void scheduleNextSnapshotJobTestPolicyIsNullCallExpunge() { + Date expected = new Date(); + SnapshotPolicyVO snapshotPolicyVO = null; + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + snapshotScheduleVO.setPolicyId(1l); + + Mockito.doReturn(snapshotPolicyVO).when(snapshotPolicyDaoMock).findById(Mockito.anyLong()); + Mockito.doReturn(true).when(snapshotScheduleDaoMock).expunge(Mockito.anyLong()); + Mockito.doReturn(expected).when(snapshotSchedulerImplSpy).scheduleNextSnapshotJob(snapshotPolicyVO); + + Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO); + Assert.assertEquals(expected, result); + + Mockito.verify(snapshotScheduleDaoMock).expunge(Mockito.anyLong()); + } + + @Test + public void isAccountRemovedOrDisabledTestVolumeAccountIsNullReturnTrue() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + + Mockito.doReturn(null).when(accountDaoMock).findById(Mockito.anyLong()); + + boolean result = snapshotSchedulerImplSpy.isAccountRemovedOrDisabled(snapshotScheduleVO, volumeVoMock); + + Assert.assertTrue(result); + } + + @Test + public void isAccountRemovedOrDisabledTestVolumeAccountStateIsDisabledReturnTrue() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + + Mockito.doReturn(accountVoMock).when(accountDaoMock).findById(Mockito.anyLong()); + Mockito.doReturn(Account.State.DISABLED).when(accountVoMock).getState(); + + boolean result = snapshotSchedulerImplSpy.isAccountRemovedOrDisabled(snapshotScheduleVO, volumeVoMock); + + Assert.assertTrue(result); + } + + @Test + public void isAccountRemovedOrDisabledTestVolumeAccountStateIsNotNullNorDisabledReturnFalse() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + + Mockito.doReturn(accountVoMock).when(accountDaoMock).findById(Mockito.anyLong()); + Mockito.doReturn(Account.State.ENABLED).when(accountVoMock).getState(); + + boolean result = snapshotSchedulerImplSpy.isAccountRemovedOrDisabled(snapshotScheduleVO, volumeVoMock); + + Assert.assertFalse(result); + } + + @Test + public void canSnapshotBeScheduledTestVolumeIsRemovedReturnFalse() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + + Mockito.doReturn(new Date()).when(volumeVoMock).getRemoved(); + + boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock); + + Assert.assertFalse(result); + } + + @Test + public void canSnapshotBeScheduledTestVolumeIsNotAttachedToStoragePoolReturnFalse() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + + Mockito.doReturn(null).when(volumeVoMock).getPoolId(); + + boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock); + + Assert.assertFalse(result); + } + + @Test + public void canSnapshotBeScheduledTestAccountIsRemovedOrDisabledReturnFalse() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + + Mockito.doReturn(1l).when(volumeVoMock).getPoolId(); + Mockito.doReturn(true).when(snapshotSchedulerImplSpy).isAccountRemovedOrDisabled(Mockito.any(), Mockito.any()); + + boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock); + + Assert.assertFalse(result); + } + + @Test + public void canSnapshotBeScheduledTestSnapshotPolicyIsRemovedCallRemove() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + + Mockito.doReturn(1l).when(volumeVoMock).getPoolId(); + Mockito.doReturn(false).when(snapshotSchedulerImplSpy).isAccountRemovedOrDisabled(Mockito.any(), Mockito.any()); + Mockito.doReturn(null).when(snapshotPolicyDaoMock).findById(Mockito.any()); + + boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock); + + Assert.assertTrue(result); + + Mockito.verify(snapshotScheduleDaoMock).remove(Mockito.anyLong()); + } + + @Test + public void canSnapshotBeScheduledTestSnapshotPolicyIsNotRemovedDoNotCallRemove() { + SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO(); + SnapshotPolicyVO snapshotPolicyVO = new SnapshotPolicyVO(); + + Mockito.doReturn(1l).when(volumeVoMock).getPoolId(); + Mockito.doReturn(false).when(snapshotSchedulerImplSpy).isAccountRemovedOrDisabled(Mockito.any(), Mockito.any()); + Mockito.doReturn(snapshotPolicyVO).when(snapshotPolicyDaoMock).findById(Mockito.any()); + + boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock); + + Assert.assertTrue(result); + + Mockito.verify(snapshotScheduleDaoMock, Mockito.never()).remove(Mockito.anyLong()); + } +}