Skip to content

Commit c428d3b

Browse files
stephankrugggStephan Krug
andauthored
Add and improve logs in snapshot scheduling (#6925)
Co-authored-by: Stephan Krug <stephan.krug@scclouds.com.br>
1 parent d25521e commit c428d3b

2 files changed

Lines changed: 282 additions & 26 deletions

File tree

server/src/main/java/com/cloud/storage/snapshot/SnapshotSchedulerImpl.java

Lines changed: 65 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -264,45 +264,29 @@ protected void deleteExpiredVMSnapshots() {
264264
@DB
265265
protected void scheduleSnapshots() {
266266
String displayTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, _currentTimestamp);
267-
s_logger.debug("Snapshot scheduler.poll is being called at " + displayTime);
267+
s_logger.debug(String.format("Snapshot scheduler is being called at [%s].", displayTime));
268268

269269
final List<SnapshotScheduleVO> snapshotsToBeExecuted = _snapshotScheduleDao.getSchedulesToExecute(_currentTimestamp);
270-
s_logger.debug("Got " + snapshotsToBeExecuted.size() + " snapshots to be executed at " + displayTime);
270+
s_logger.debug(String.format("There are [%s] scheduled snapshots to be executed at [%s].", snapshotsToBeExecuted.size(), displayTime));
271271

272272
for (final SnapshotScheduleVO snapshotToBeExecuted : snapshotsToBeExecuted) {
273273
SnapshotScheduleVO tmpSnapshotScheduleVO = null;
274274
final long snapshotScheId = snapshotToBeExecuted.getId();
275275
final long policyId = snapshotToBeExecuted.getPolicyId();
276276
final long volumeId = snapshotToBeExecuted.getVolumeId();
277277
try {
278-
final VolumeVO volume = _volsDao.findById(volumeId);
279-
if (volume.getPoolId() == null) {
280-
// this volume is not attached
281-
continue;
282-
}
283-
Account volAcct = _acctDao.findById(volume.getAccountId());
284-
if (volAcct == null || volAcct.getState() == Account.State.DISABLED) {
285-
// this account has been removed, so don't trigger recurring snapshot
286-
if (s_logger.isDebugEnabled()) {
287-
s_logger.debug("Skip snapshot for volume " + volume.getUuid() + " since its account has been removed or disabled");
288-
}
278+
final VolumeVO volume = _volsDao.findByIdIncludingRemoved(snapshotToBeExecuted.getVolumeId());
279+
280+
if (!canSnapshotBeScheduled(snapshotToBeExecuted, volume)) {
289281
continue;
290282
}
291-
if (_snapshotPolicyDao.findById(policyId) == null) {
292-
_snapshotScheduleDao.remove(snapshotToBeExecuted.getId());
293-
}
294-
if (s_logger.isDebugEnabled()) {
295-
final Date scheduledTimestamp = snapshotToBeExecuted.getScheduledTimestamp();
296-
displayTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, scheduledTimestamp);
297-
s_logger.debug("Scheduling 1 snapshot for volume id " + volumeId + " (volume name:" +
298-
volume.getName() + ") for schedule id: " + snapshotToBeExecuted.getId() + " at " + displayTime);
299-
}
300283

301284
tmpSnapshotScheduleVO = _snapshotScheduleDao.acquireInLockTable(snapshotScheId);
302285
final Long eventId =
303286
ActionEventUtils.onScheduledActionEvent(User.UID_SYSTEM, volume.getAccountId(), EventTypes.EVENT_SNAPSHOT_CREATE, "creating snapshot for volume Id:" +
304287
volume.getUuid(), volumeId, ApiCommandResourceType.Volume.toString(), true, 0);
305288

289+
s_logger.trace(String.format("Mapping parameters required to generate a CreateSnapshotCmd for snapshot [%s].", snapshotToBeExecuted.getUuid()));
306290
final Map<String, String> params = new HashMap<String, String>();
307291
params.put(ApiConstants.VOLUME_ID, "" + volumeId);
308292
params.put(ApiConstants.POLICY_ID, "" + policyId);
@@ -319,24 +303,27 @@ protected void scheduleSnapshots() {
319303
}
320304
}
321305

306+
s_logger.trace(String.format("Generating a CreateSnapshotCmd for snapshot [%s] with parameters: [%s].", snapshotToBeExecuted.getUuid(), params.toString()));
322307
final CreateSnapshotCmd cmd = new CreateSnapshotCmd();
323308
ComponentContext.inject(cmd);
324309
_dispatcher.dispatchCreateCmd(cmd, params);
325310
params.put("id", "" + cmd.getEntityId());
326311
params.put("ctxStartEventId", "1");
327312

313+
final Date scheduledTimestamp = snapshotToBeExecuted.getScheduledTimestamp();
314+
displayTime = DateUtil.displayDateInTimezone(DateUtil.GMT_TIMEZONE, scheduledTimestamp);
315+
s_logger.debug(String.format("Scheduling snapshot [%s] for volume [%s] at [%s].", snapshotToBeExecuted.getUuid(), volume.getVolumeDescription(), displayTime));
328316
AsyncJobVO job = new AsyncJobVO("", User.UID_SYSTEM, volume.getAccountId(), CreateSnapshotCmd.class.getName(),
329317
ApiGsonHelper.getBuilder().create().toJson(params), cmd.getEntityId(),
330318
cmd.getApiResourceType() != null ? cmd.getApiResourceType().toString() : null, null);
331319
job.setDispatcher(_asyncDispatcher.getName());
332-
333320
final long jobId = _asyncMgr.submitAsyncJob(job);
321+
s_logger.debug(String.format("Scheduled snapshot [%s] for volume [%s] as job [%s].", snapshotToBeExecuted.getUuid(), volume.getVolumeDescription(), job.getUuid()));
334322

335323
tmpSnapshotScheduleVO.setAsyncJobId(jobId);
336324
_snapshotScheduleDao.update(snapshotScheId, tmpSnapshotScheduleVO);
337325
} catch (final Exception e) {
338-
// TODO Logging this exception is enough?
339-
s_logger.warn("Scheduling snapshot failed due to " + e.toString());
326+
s_logger.error(String.format("The scheduling of snapshot [%s] for volume [%s] failed due to [%s].", snapshotToBeExecuted.getUuid(), volumeId, e.toString()), e);
340327
} finally {
341328
if (tmpSnapshotScheduleVO != null) {
342329
_snapshotScheduleDao.releaseFromLockTable(snapshotScheId);
@@ -345,7 +332,59 @@ protected void scheduleSnapshots() {
345332
}
346333
}
347334

348-
private Date scheduleNextSnapshotJob(final SnapshotScheduleVO snapshotSchedule) {
335+
/**
336+
* 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.
337+
*
338+
* @param snapshotToBeScheduled the snapshot to be scheduled
339+
* @param volume the volume associated with the snapshot to be scheduled
340+
* @return <code>true</code> if the snapshot can be scheduled, and <code>false</code> otherwise.
341+
*/
342+
protected boolean canSnapshotBeScheduled(final SnapshotScheduleVO snapshotToBeScheduled, final VolumeVO volume) {
343+
if (volume.getRemoved() != null) {
344+
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 "
345+
+ "removed is an inconsistency; please, check your database.", snapshotToBeScheduled.getUuid(), volume.getVolumeDescription()));
346+
return false;
347+
}
348+
349+
if (volume.getPoolId() == null) {
350+
s_logger.debug(String.format("Skipping snapshot [%s] for volume [%s] because it is not attached to any storage pool.", snapshotToBeScheduled.getUuid(),
351+
volume.getVolumeDescription()));
352+
return false;
353+
}
354+
355+
if (isAccountRemovedOrDisabled(snapshotToBeScheduled, volume)) {
356+
return false;
357+
}
358+
359+
if (_snapshotPolicyDao.findById(snapshotToBeScheduled.getPolicyId()) == null) {
360+
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.",
361+
snapshotToBeScheduled.getPolicyId(), volume.getVolumeDescription()));
362+
_snapshotScheduleDao.remove(snapshotToBeScheduled.getId());
363+
}
364+
365+
s_logger.debug(String.format("Snapshot [%s] for volume [%s] can be executed.", snapshotToBeScheduled.getUuid(), volume.getVolumeDescription()));
366+
return true;
367+
}
368+
369+
protected boolean isAccountRemovedOrDisabled(final SnapshotScheduleVO snapshotToBeExecuted, final VolumeVO volume) {
370+
Account volAcct = _acctDao.findById(volume.getAccountId());
371+
372+
if (volAcct == null) {
373+
s_logger.debug(String.format("Skipping snapshot [%s] for volume [%s] because its account [%s] has been removed.", snapshotToBeExecuted.getUuid(),
374+
volume.getVolumeDescription(), volume.getAccountId()));
375+
return true;
376+
}
377+
378+
if (volAcct.getState() == Account.State.DISABLED) {
379+
s_logger.debug(String.format("Skipping snapshot [%s] for volume [%s] because its account [%s] is disabled.", snapshotToBeExecuted.getUuid(),
380+
volume.getVolumeDescription(), volAcct.getUuid()));
381+
return true;
382+
}
383+
384+
return false;
385+
}
386+
387+
protected Date scheduleNextSnapshotJob(final SnapshotScheduleVO snapshotSchedule) {
349388
if (snapshotSchedule == null) {
350389
return null;
351390
}
Lines changed: 217 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,217 @@
1+
// Licensed to the Apache Software Foundation (ASF) under one
2+
// or more contributor license agreements. See the NOTICE file
3+
// distributed with this work for additional information
4+
// regarding copyright ownership. The ASF licenses this file
5+
// to you under the Apache License, Version 2.0 (the
6+
// "License"); you may not use this file except in compliance
7+
// with the License. You may obtain a copy of the License at
8+
//
9+
// http://www.apache.org/licenses/LICENSE-2.0
10+
//
11+
// Unless required by applicable law or agreed to in writing,
12+
// software distributed under the License is distributed on an
13+
// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
14+
// KIND, either express or implied. See the License for the
15+
// specific language governing permissions and limitations
16+
// under the License.
17+
package com.cloud.storage.snapshot;
18+
19+
import com.cloud.storage.Snapshot;
20+
import com.cloud.storage.SnapshotPolicyVO;
21+
import com.cloud.storage.SnapshotScheduleVO;
22+
import com.cloud.storage.VolumeVO;
23+
import com.cloud.storage.dao.SnapshotPolicyDao;
24+
import com.cloud.storage.dao.SnapshotScheduleDao;
25+
import com.cloud.storage.dao.VolumeDao;
26+
import com.cloud.user.Account;
27+
import com.cloud.user.AccountVO;
28+
import com.cloud.user.dao.AccountDao;
29+
import org.junit.Assert;
30+
import org.junit.Test;
31+
import org.junit.runner.RunWith;
32+
import org.mockito.InjectMocks;
33+
import org.mockito.Mock;
34+
import org.mockito.Mockito;
35+
import org.mockito.Spy;
36+
import org.mockito.junit.MockitoJUnitRunner;
37+
import java.util.Date;
38+
39+
@RunWith(MockitoJUnitRunner.class)
40+
public class SnapshotSchedulerImplTest {
41+
42+
@Spy
43+
@InjectMocks
44+
SnapshotSchedulerImpl snapshotSchedulerImplSpy = new SnapshotSchedulerImpl();
45+
46+
@Mock
47+
SnapshotPolicyDao snapshotPolicyDaoMock;
48+
49+
@Mock
50+
SnapshotPolicyVO snapshotPolicyVoMock;
51+
52+
@Mock
53+
SnapshotScheduleDao snapshotScheduleDaoMock;
54+
55+
@Mock
56+
AccountDao accountDaoMock;
57+
58+
@Mock
59+
VolumeDao volumeDaoMock;
60+
61+
@Mock
62+
VolumeVO volumeVoMock;
63+
64+
@Mock
65+
AccountVO accountVoMock;
66+
67+
@Test
68+
public void scheduleNextSnapshotJobTestParameterIsNullReturnNull() {
69+
SnapshotScheduleVO snapshotScheduleVO = null;
70+
71+
Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO);
72+
73+
Assert.assertNull(result);
74+
}
75+
76+
@Test
77+
public void scheduleNextSnapshotJobTestIsManualPolicyIdReturnNull() {
78+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
79+
snapshotScheduleVO.setPolicyId(Snapshot.MANUAL_POLICY_ID);
80+
81+
Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO);
82+
83+
Assert.assertNull(result);
84+
}
85+
86+
@Test
87+
public void scheduleNextSnapshotJobTestPolicyIsNotNullDoNotCallExpunge() {
88+
Date expected = new Date();
89+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
90+
snapshotScheduleVO.setPolicyId(1l);
91+
92+
Mockito.doReturn(snapshotPolicyVoMock).when(snapshotPolicyDaoMock).findById(Mockito.anyLong());
93+
Mockito.doReturn(expected).when(snapshotSchedulerImplSpy).scheduleNextSnapshotJob(Mockito.any(SnapshotPolicyVO.class));
94+
95+
Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO);
96+
Assert.assertEquals(expected, result);
97+
98+
Mockito.verify(snapshotScheduleDaoMock, Mockito.never()).expunge(Mockito.anyLong());
99+
}
100+
101+
@Test
102+
public void scheduleNextSnapshotJobTestPolicyIsNullCallExpunge() {
103+
Date expected = new Date();
104+
SnapshotPolicyVO snapshotPolicyVO = null;
105+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
106+
snapshotScheduleVO.setPolicyId(1l);
107+
108+
Mockito.doReturn(snapshotPolicyVO).when(snapshotPolicyDaoMock).findById(Mockito.anyLong());
109+
Mockito.doReturn(true).when(snapshotScheduleDaoMock).expunge(Mockito.anyLong());
110+
Mockito.doReturn(expected).when(snapshotSchedulerImplSpy).scheduleNextSnapshotJob(snapshotPolicyVO);
111+
112+
Date result = snapshotSchedulerImplSpy.scheduleNextSnapshotJob(snapshotScheduleVO);
113+
Assert.assertEquals(expected, result);
114+
115+
Mockito.verify(snapshotScheduleDaoMock).expunge(Mockito.anyLong());
116+
}
117+
118+
@Test
119+
public void isAccountRemovedOrDisabledTestVolumeAccountIsNullReturnTrue() {
120+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
121+
122+
Mockito.doReturn(null).when(accountDaoMock).findById(Mockito.anyLong());
123+
124+
boolean result = snapshotSchedulerImplSpy.isAccountRemovedOrDisabled(snapshotScheduleVO, volumeVoMock);
125+
126+
Assert.assertTrue(result);
127+
}
128+
129+
@Test
130+
public void isAccountRemovedOrDisabledTestVolumeAccountStateIsDisabledReturnTrue() {
131+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
132+
133+
Mockito.doReturn(accountVoMock).when(accountDaoMock).findById(Mockito.anyLong());
134+
Mockito.doReturn(Account.State.DISABLED).when(accountVoMock).getState();
135+
136+
boolean result = snapshotSchedulerImplSpy.isAccountRemovedOrDisabled(snapshotScheduleVO, volumeVoMock);
137+
138+
Assert.assertTrue(result);
139+
}
140+
141+
@Test
142+
public void isAccountRemovedOrDisabledTestVolumeAccountStateIsNotNullNorDisabledReturnFalse() {
143+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
144+
145+
Mockito.doReturn(accountVoMock).when(accountDaoMock).findById(Mockito.anyLong());
146+
Mockito.doReturn(Account.State.ENABLED).when(accountVoMock).getState();
147+
148+
boolean result = snapshotSchedulerImplSpy.isAccountRemovedOrDisabled(snapshotScheduleVO, volumeVoMock);
149+
150+
Assert.assertFalse(result);
151+
}
152+
153+
@Test
154+
public void canSnapshotBeScheduledTestVolumeIsRemovedReturnFalse() {
155+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
156+
157+
Mockito.doReturn(new Date()).when(volumeVoMock).getRemoved();
158+
159+
boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock);
160+
161+
Assert.assertFalse(result);
162+
}
163+
164+
@Test
165+
public void canSnapshotBeScheduledTestVolumeIsNotAttachedToStoragePoolReturnFalse() {
166+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
167+
168+
Mockito.doReturn(null).when(volumeVoMock).getPoolId();
169+
170+
boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock);
171+
172+
Assert.assertFalse(result);
173+
}
174+
175+
@Test
176+
public void canSnapshotBeScheduledTestAccountIsRemovedOrDisabledReturnFalse() {
177+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
178+
179+
Mockito.doReturn(1l).when(volumeVoMock).getPoolId();
180+
Mockito.doReturn(true).when(snapshotSchedulerImplSpy).isAccountRemovedOrDisabled(Mockito.any(), Mockito.any());
181+
182+
boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock);
183+
184+
Assert.assertFalse(result);
185+
}
186+
187+
@Test
188+
public void canSnapshotBeScheduledTestSnapshotPolicyIsRemovedCallRemove() {
189+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
190+
191+
Mockito.doReturn(1l).when(volumeVoMock).getPoolId();
192+
Mockito.doReturn(false).when(snapshotSchedulerImplSpy).isAccountRemovedOrDisabled(Mockito.any(), Mockito.any());
193+
Mockito.doReturn(null).when(snapshotPolicyDaoMock).findById(Mockito.any());
194+
195+
boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock);
196+
197+
Assert.assertTrue(result);
198+
199+
Mockito.verify(snapshotScheduleDaoMock).remove(Mockito.anyLong());
200+
}
201+
202+
@Test
203+
public void canSnapshotBeScheduledTestSnapshotPolicyIsNotRemovedDoNotCallRemove() {
204+
SnapshotScheduleVO snapshotScheduleVO = new SnapshotScheduleVO();
205+
SnapshotPolicyVO snapshotPolicyVO = new SnapshotPolicyVO();
206+
207+
Mockito.doReturn(1l).when(volumeVoMock).getPoolId();
208+
Mockito.doReturn(false).when(snapshotSchedulerImplSpy).isAccountRemovedOrDisabled(Mockito.any(), Mockito.any());
209+
Mockito.doReturn(snapshotPolicyVO).when(snapshotPolicyDaoMock).findById(Mockito.any());
210+
211+
boolean result = snapshotSchedulerImplSpy.canSnapshotBeScheduled(snapshotScheduleVO, volumeVoMock);
212+
213+
Assert.assertTrue(result);
214+
215+
Mockito.verify(snapshotScheduleDaoMock, Mockito.never()).remove(Mockito.anyLong());
216+
}
217+
}

0 commit comments

Comments
 (0)