Issue with Snapmanger for sql server backup job

ANISH5225 · ‎2014-12-29

Hi ,

I have an issue with a Snapmanger for sql server backup job.The snapmanager and server event viewer logs related to this issue can be seen below below.

Snapshot retention is set for 31 days on the concerned volume.
New snapshots are getting created without issues.
Oldest snapshot deletion is happening without issues for M: lun.
Snapshot deletion failing for L: lun. The reason being deletion is attempted twice on the same snapshot- once for M: lun and once for L: lun.
Everything was running fine till a few days ago. Issue started after a recent upgrade of SnapManager for SQL Server and Snapdrive on the server(upgraded to ver7.1 and ver 7 respectively).

Software versions are:
Snapmanager for SQL Server --Ver 7.1.0.2024_140603_0415
Snapdrive -- Ver 7.0.3
SQL server -- Ver 11.0

DOT version: NetApp Release 8.1.4P5 7-Mode

Can someone please give me a clue on what could be wrong?

Snapmanager Logs
[22:00:22.094] [ABCMDMP009] Ready to prepare to create snapshot...
[22:00:22.094] [ABCMDMP009]
[22:00:22.094] [ABCMDMP009] SNAPSHOT DATABASE
[22:00:22.094] [ABCMDMP009] Preparing Snapshot to Drive:
[22:00:22.094] [ABCMDMP009] LUN [M], LUN [L]
[22:00:22.094] [ABCMDMP009] Snapshot Name: sqlsnap__abcmdmp009__recent
[22:00:22.095] [ABCMDMP009] Begin to create snapshot...
[22:00:23.066] [ABCMDMP009] SnapDrive is ready to create snapshot.
[22:00:23.072] [ABCMDMP009] Create Snapshot Now [ABCMDMP009\ABCMS011 : ABC_WSS_Content_Medialab]...
[22:00:23.072] [ABCMDMP009] Create Snapshot Now [ABCMDMP009\ABCMS011 : Backup_Restore_Test_DB]...
[22:00:23.072] [ABCMDMP009] All VDI backup threads completed snapshot preparation and databases IO are frozen for snapshot.
[22:00:23.073] [ABCMDMP009] SnapManager are ready to create snapshot...
[22:00:23.783] [ABCMDMP009] Snapshot virtual disk [M, L] for database [Backup_Restore_Test_DB] successfully completed.
[22:00:23.783] [ABCMDMP009] Snapshot virtual disk [L, M] for database [ABC_WSS_Content_Medialab] successfully completed.
22:00:28.446] [ABCMDMP009] Snapshot drive/share(s) successfully completed.
[22:00:28.455] [ABCMDMP009] Current time: 12/28/2014 10:00:12 PM
[22:00:28.455] [ABCMDMP009] Backups older than [44640] minutes ago will be deleted.
[22:00:28.455] [ABCMDMP009] Backups older than [11/27/2014 10:00:12 PM] will be deleted.
[22:00:28.455] [ABCMDMP009] Preparing LUN 'L:\', for SDAPI operation...
[22:00:28.794] [ABCMDMP009] Preparing LUN 'M:\', for SDAPI operation...

[22:00:29.036] [ABCMDMP009] Querying backup data sets for LUN: M...
[22:00:30.760] [ABCMDMP009] There are [38] backup data sets for database [Backup_Restore_Test_DB] with backup management group [Daily].
[22:00:30.761] [ABCMDMP009] There are [38] backup data sets for database [ABC_WSS_Content_Medialab] with backup management group [Daily].
[22:00:30.761] [ABCMDMP009]
[22:00:30.761] [ABCMDMP009] *** DELETE THE OLDEST BACKUP DATA SETS
[22:00:30.761] [ABCMDMP009] Starting to delete the oldest backup sets...
[22:00:30.761] [ABCMDMP009]
[22:00:30.761] [ABCMDMP009] ***DELETING SNAPSHOTS...

[22:00:30.761] [ABCMDMP009] The following snapshot for LUN [M, L] will not be deleted:
[22:00:30.761] [ABCMDMP009] #1 - sqlsnap__ABCMDMP009__recent
[22:00:30.761] [ABCMDMP009] #2 - sqlsnap__ABCMDMP009_12-27-2014_22.00.11__Daily
[22:00:30.761] [ABCMDMP009] #3 - sqlsnap__ABCMDMP009_12-26-2014_22.00.09__Daily
[22:00:30.761] [ABCMDMP009] #4 - sqlsnap__ABCMDMP009_12-25-2014_22.00.09__Daily
[22:00:30.761] [ABCMDMP009] #5 - sqlsnap__ABCMDMP009_12-24-2014_22.00.14__Daily
[22:00:30.761] [ABCMDMP009] #6 - sqlsnap__ABCMDMP009_12-23-2014_22.00.12__Daily
[22:00:30.761] [ABCMDMP009] #7 - sqlsnap__ABCMDMP009_12-22-2014_22.00.13__Daily
[22:00:30.761] [ABCMDMP009] #8 - sqlsnap__ABCMDMP009_12-21-2014_22.00.13__Daily
[22:00:30.761] [ABCMDMP009] #9 - sqlsnap__ABCMDMP009_12-20-2014_22.00.11__Daily
[22:00:30.761] [ABCMDMP009] #10 - sqlsnap__ABCMDMP009_12-20-2014_10.57.54__Daily
[22:00:30.761] [ABCMDMP009] #11 - sqlsnap__ABCMDMP009_12-19-2014_22.01.26__Daily
[22:00:30.761] [ABCMDMP009] #12 - sqlsnap__ABCMDMP009_12-18-2014_22.00.12__Daily
[22:00:30.761] [ABCMDMP009] #13 - sqlsnap__ABCMDMP009_12-17-2014_22.00.10__Daily
[22:00:30.761] [ABCMDMP009] #14 - sqlsnap__ABCMDMP009_12-16-2014_22.00.09__Daily
[22:00:30.761] [ABCMDMP009] #15 - sqlsnap__ABCMDMP009_12-15-2014_22.00.13__Daily
[22:00:30.761] [ABCMDMP009] #16 - sqlsnap__ABCMDMP009_12-14-2014_22.00.13__Daily
[22:00:30.761] [ABCMDMP009] #17 - sqlsnap__ABCMDMP009_12-13-2014_22.00.14__Daily
[22:00:30.761] [ABCMDMP009] #18 - sqlsnap__ABCMDMP009_12-12-2014_22.00.11__Daily
[22:00:30.761] [ABCMDMP009] #19 - sqlsnap__ABCMDMP009_12-11-2014_22.00.14__Daily
[22:00:30.761] [ABCMDMP009] #20 - sqlsnap__ABCMDMP009_12-10-2014_22.00.14__Daily
[22:00:30.761] [ABCMDMP009] #21 - sqlsnap__ABCMDMP009_12-09-2014_22.00.09__Daily
[22:00:30.761] [ABCMDMP009] #22 - sqlsnap__ABCMDMP009_12-08-2014_22.00.17__Daily
[22:00:30.761] [ABCMDMP009] #23 - sqlsnap__ABCMDMP009_12-08-2014_04.38.37__Daily
[22:00:30.761] [ABCMDMP009] #24 - sqlsnap__ABCMDMP009_12-08-2014_04.31.28__Daily
[22:00:30.761] [ABCMDMP009] #25 - sqlsnap__ABCMDMP009_12-07-2014_22.00.14__Daily
[22:00:30.761] [ABCMDMP009] #26 - sqlsnap__ABCMDMP009_12-06-2014_22.00.14__Daily
[22:00:30.761] [ABCMDMP009] #27 - sqlsnap__ABCMDMP009_12-05-2014_22.01.48__Daily
[22:00:30.761] [ABCMDMP009] #28 - sqlsnap__ABCMDMP009_12-04-2014_22.00.12__Daily
[22:00:30.761] [ABCMDMP009] #29 - sqlsnap__ABCMDMP009_12-04-2014_15.14.01__Daily
[22:00:30.761] [ABCMDMP009] #30 - sqlsnap__ABCMDMP009_12-04-2014_15.02.52__Daily
[22:00:30.761] [ABCMDMP009] #31 - sqlsnap__ABCMDMP009_12-03-2014_22.00.14__Daily
[22:00:30.761] [ABCMDMP009] #32 - sqlsnap__ABCMDMP009_12-02-2014_22.00.13__Daily
[22:00:30.761] [ABCMDMP009] #33 - sqlsnap__ABCMDMP009_12-01-2014_22.00.17__Daily
[22:00:30.761] [ABCMDMP009] #34 - sqlsnap__ABCMDMP009_11-30-2014_22.00.11__Daily
[22:00:30.761] [ABCMDMP009] #35 - sqlsnap__ABCMDMP009_11-29-2014_22.00.11__Daily
[22:00:30.761] [ABCMDMP009] #36 - sqlsnap__ABCMDMP009_11-28-2014_22.01.30__Daily
[22:00:30.761] [ABCMDMP009] #37 - sqlsnap__ABCMDMP009_11-28-2014_04.07.54__Daily
[22:00:30.761] [ABCMDMP009] #38 - sqlsnap__ABCMDMP009_11-27-2014_22.00.19__Daily
[22:00:30.761] [ABCMDMP009] Get snapshot list from LUN M:...

[22:00:30.770] [ABCMDMP009] DELETING BACKUP - [#1]
[22:00:30.770] [ABCMDMP009] Deleting snapshot [sqlsnap__abcmdmp009_11-26-2014_22.00.14__daily]...
[22:00:30.770] [ABCMDMP009] Preparing LUN 'M:\', for SDAPI operation...
[22:00:32.911] [ABCMDMP009] Get snapshot list from LUN L:...

[22:00:32.923] [ABCMDMP009] DELETING BACKUP - [#1]
[22:00:32.923] [ABCMDMP009] Deleting snapshot [sqlsnap__abcmdmp009_11-26-2014_22.00.14__daily]...
[22:00:32.923] [ABCMDMP009] Preparing LUN 'L:\', for SDAPI operation...
[22:00:33.146] [ABCMDMP009] SDSnapshotDelete failed Reason: The target LUN in Snapshot copy is inconsistent or does not exist and cannot be deleted.

[22:00:33.147] [ABCMDMP009] SDAPI failed to delete snapshot.

From Server (ABCMDMP009) eventviewer

12/28/2014 10:00:20 PM
SnapManager for SQL Server started online full snapshot based database backup.

12/28/2014 10:00:21 PM
The Snapshot copy (sqlsnap__abcmdmp009__recent) of the LUN was renamed to (sqlsnap__abcmdmp009_12-27-2014_22.00.11__daily).
LUN Name = abcmdmp009_m.lun
Storage Path = /vol/abcmdmp009_ntfs_03/shp_sqldat
Protocol Type =
Storage System Name = abcesnp122

12/28/2014 10:00:22 PM
SnapDrive is ready to create Snapshot copy (sqlsnap__abcmdmp009__recent) of LUN(s).

12/28/2014 10:00:23 PM
Snapshot (sqlsnap__abcmdmp009__recent) of LUN(s) on storage system (abcesnp122) volume (abcmdmp009_ntfs_03) was successfully created.

12/28/2014 10:00:23 PM
Creation of snapshot named 'sqlsnap__abcmdmp009__recent' of LUN M, L: of database 'Backup_Restore_Test_DB' on SQL Server'ABCMDMP009\ABCMS011' completed successfully.

12/28/2014 10:00:23 PM
Creation of snapshot named 'sqlsnap__abcmdmp009__recent' of LUN L, M: of database 'ABC_WSS_Content_Medialab' on SQL Server'ABCMDMP009\ABCMS011' completed successfully.

12/28/2014 10:00:32 PM
The Snapshot copy (sqlsnap__abcmdmp009_11-26-2014_22.00.14__daily) of the LUN (M:\) on storage system (abcesnp122) volume (abcmdmp009_ntfs_03) was deleted

12/28/2014 10:00:33 PM
Failed to delete the Snapshot copy (sqlsnap__abcmdmp009_11-26-2014_22.00.14__daily) of the LUN (L:\) on storage system (abcesnp122) volume (abcmdmp009_ntfs_03).
Error code : The target LUN in Snapshot copy is inconsistent or does not exist and cannot be deleted.

12/28/2014 10:00:33 PM
Failed to delete the oldest snapshot full database backups.
Error Code: 0x80004005
Unspecified error

dmauro · ‎2014-12-29

Hi,

the error appears to be:

"SDSnapshotDelete failed Reason: The target LUN in Snapshot copy is inconsistent or does not exist and cannot be deleted"

So, I would check whether the snapshot sqlsnap__abcmdmp009_11-26-2014_22.00.14__daily really does not exist anymore in the volume hosting the lun L:\; that would mean that SMSQL still has metadata about that snapshot, but the snapshot is no longer present on the volume (perhaps because the autodelete feature in Ontap deleted it or someone deleted it manually).

In that case a manual clean up is required. Ideally try using the SMSQL delete backup wizard first and ensure you select all options appropriately; if you have no luck in removing the metadata (snapinfo directories about those snapshots) you will need to manually delete the folders, but that's your last stage, as you should be able to use the delete wizard correctly: here is an example for SME but screenshots apply also to SMSQL:

Please see attachment.

hope that helps,

Domenico

ANISH5225 · ‎2014-12-29

Hi Domenico,

Thanks for your reply..

I just did a quick check on the delete settings that you mentioned and found no issues there..

But from the logs, what I understood is that a second deletion is attemped on a snapshot which was already deleted a few of seconds ago. Ofcourse this second attempt fails as the snapshot dosent exist anymore.

This behaviour can be seen from the SMSQL logs at timestamps [22:00:30.770] and [22:00:32.923] and from the server eventviewer logs at 12/28/2014 10:00:32 PM and 12/28/2014 10:00:33 PM.

Thank You

Anish

dmauro · ‎2014-12-29

SMSQL tries to delete snapshot sqlsnap__abcmdmp009_11-26-2014_22.00.14__daily from volume hosting lun M:\ first, then it tries to delete snapshot sqlsnap__abcmdmp009_11-26-2014_22.00.14__daily from volume hosting lun L:\;

it sounds like your problem is that you have M:\ and L:\ on same storage system volume, hence you can only have one snapshot created or deleted with a given name.

If two databases were sharing same backup, (snapshot), deleting one backup (snapshot) for one db will delete backup for all databases.

This is expected behavior. If this is your case, I advice you to backup all databases sharing the same storage system volume at once.

If this is not your case, I advice you to file a support case.

I hope that helps,

Domenico