Re: SnapManager for SQL Backup Fails with 0x80004005

Lee-KineticCU · ‎2014-09-28

Hello,

SMSQL had been running without problems on a server until yesterday when it started failing with 0x80004005. I cannot seem to discover what is causing the failure. I have tried restarting the server, running Configuration of SMSQL and even recreating the backup job but the same error keeps occuring. Below is from the backup log.

[15:15:38.691] [SERVERNAME] *** SnapManager for SQL Server Report

[15:15:38.696] [SERVERNAME] Getting SQL Server Database Information, please wait...
[15:15:38.718] [SERVERNAME] Creating thread for enumerating all databases from all nodes...
[15:15:38.718] [SERVERNAME] Waiting for the threads to finish enum all databases...
[15:15:38.729] [SERVERNAME] Get database and LUN information...
[15:15:38.730] [SERVERNAME] Getting virtual disks information...
[15:15:42.341] [SERVERNAME] Querying SQL Server instances installed...
[15:15:42.354] [SERVERNAME] Querying installed SQL Server instances on [SERVERNAME]...
[15:15:42.354] [SERVERNAME] Allocating ODBC environment handle...
[15:15:42.354] [SERVERNAME] Setting environment attribute...
[15:15:42.354] [SERVERNAME] Setting SQLBrowseConnect option...
[15:15:42.354] [SERVERNAME] SQLBrowseConnect...
[15:15:42.357] [SERVERNAME] Parsing SQLBrowseConnect server string...
[15:15:42.366] [SERVERNAME] Creating threads for enumerating databases of different SQL Server instances.
[15:15:42.366] [SERVERNAME] Waiting for the threads to finish enumerating databases.
[15:15:43.076] [SERVERNAME] [SMO] Connecting to SQL Server instance - SERVERNAME...
[15:15:43.076] [SERVERNAME] [SMO] Querying database information...
[15:15:43.239] [SERVERNAME] All threads finished enumerating databases.
[15:15:43.239] [SERVERNAME] Validating database configuration...
[15:15:43.240] [SERVERNAME] Setting database disk configuration...
[15:15:43.240] [SERVERNAME] Setting database locating on SQLRoot path...
[15:15:43.242] [SERVERNAME] Querying database disk volume configuration...
[15:15:43.242] [SERVERNAME] Getting SnapInfo directories configuration...

[15:15:43.244] [SERVERNAME] Checking dataset availability, connecting to SnapDrive...
[15:15:43.411] [SERVERNAME] Dataset feature is currently unavailable.
[15:15:43.411] [SERVERNAME] Getting SnapManager dataset info from...
[15:15:43.411] [SERVERNAME] Dataset info file has not yet created.
[15:15:43.413] [SERVERNAME] Getting SnapMirror Destinations Volumes...
[15:15:57.788] [SERVERNAME] Update selected destination volumes information for SQL Server SERVERNAME succeeded.
[15:15:57.789] [SERVERNAME] Get all destination volumes state successfully.
[15:15:57.838] [SERVERNAME] Sub-grouping databases...

[15:15:57.839] [SERVERNAME] Sub-Group #0:

[15:15:57.853] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (BPW)

[15:15:57.853] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (DYNAMICS)

[15:15:57.853] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (ManagementReporter)

[15:15:57.853] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (master)

[15:15:57.853] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (model)

[15:15:57.853] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (msdb)

[15:15:57.853] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (ReportServer)

[15:15:57.854] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (ReportServerTempDB)

[15:15:57.854] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (TEST)

[15:15:57.854] [SERVERNAME] Host server (SERVERNAME) Federated Group ID (-1) Instance Name (SERVERNAME) Database Name (TIC)

[15:15:57.854] [SERVERNAME] Sub-Group #1:

[15:15:57.854] [SERVERNAME] Federated backup(main): Backup Time Stamp: 09-28-2014_15.15.38
[15:15:57.854] [SERVERNAME] Starting backup for each federated groups.....

[15:15:57.858] [SERVERNAME] Retrieving database and LUN information...
[15:15:57.859] [SERVERNAME] Creating thread for remote backup group(-1) sub-group server(SERVERNAME) thread index(0).....

[15:15:57.860] [SERVERNAME] Waiting for the threads in group -1 to finish remote backup group...
[15:15:57.904] [SERVERNAME] Backup Time Stamp: 09-28-2014_15.15.57
[15:15:57.943] [SERVERNAME] Getting current backup set groups...

[15:15:58.076] [SERVERNAME] Full database backup
[15:15:58.076] [SERVERNAME] Maximum databases of concurrent backup: 35
[15:15:58.077] [SERVERNAME] Minimum databases per backupset: 35
[15:15:58.077] [SERVERNAME] Naming convention: Unique
[15:15:58.077] [SERVERNAME] Run transaction log backup after full database backup: Yes
[15:15:58.077] [SERVERNAME] Transaction logs will be truncated after backup: Yes
[15:15:58.079] [SERVERNAME] Transaction log backup will be backed up to SMSQL share for only databases belonging to Availability Group.
[15:15:58.079] [SERVERNAME] Keep the oldest 7 transaction log backups in SMSQL share.
[15:15:58.079] [SERVERNAME] Archive backup to SnapVault secondary: No
[15:15:58.079] [SERVERNAME] Keep the oldest 7 full backups.
[15:15:58.079] [SERVERNAME] Delete older SnapInfo snapshots: Yes
[15:15:58.079] [SERVERNAME] Keep 7 SnapInfo snapshots. (same as full)
[15:15:58.079] [SERVERNAME] Retain up-to-minute restore ability for the latest backups number of days: 1
[15:15:58.079] [SERVERNAME] Create snapshot of SnapInfo drive after backup: Yes (always done on full backups)
[15:15:58.079] [SERVERNAME] Leave database attached after DBCC: No
[15:15:58.079] [SERVERNAME] Run DBCC CHECKDB with Live Database Before Backup: No
[15:15:58.079] [SERVERNAME] Run DBCC CHECKDB with Live Database After Backup: No
[15:15:58.079] [SERVERNAME] Backup Management Group: Daily
[15:15:58.079] [SERVERNAME] Update SnapMirror after operation: Yes
[15:15:58.079] [SERVERNAME] Run Command before the operation: No
[15:15:58.079] [SERVERNAME] Run Command after the operation: No
[15:15:58.079] [SERVERNAME]
[15:15:58.080] [SERVERNAME] Backup Database 1: SERVERNAME : BPW
[15:15:58.080] [SERVERNAME] Backup Database 2: SERVERNAME : DYNAMICS
[15:15:58.080] [SERVERNAME] Backup Database 3: SERVERNAME : ManagementReporter
[15:15:58.080] [SERVERNAME] Backup Database 4: SERVERNAME : master
[15:15:58.080] [SERVERNAME] Backup Database 5: SERVERNAME : model
[15:15:58.080] [SERVERNAME] Backup Database 6: SERVERNAME : msdb
[15:15:58.080] [SERVERNAME] Backup Database 7: SERVERNAME : ReportServer
[15:15:58.080] [SERVERNAME] Backup Database 8: SERVERNAME : ReportServerTempDB
[15:15:58.080] [SERVERNAME] Backup Database 9: SERVERNAME : TEST
[15:15:58.080] [SERVERNAME] Backup Database 10: SERVERNAME : TIC

[15:15:58.081] [SERVERNAME] Backup database list:
[15:15:58.082] [SERVERNAME] 1 - SERVERNAME : master
[15:15:58.082] [SERVERNAME] 2 - SERVERNAME : model
[15:15:58.082] [SERVERNAME] 3 - SERVERNAME : msdb

[15:15:58.126] [SERVERNAME] CHECK SNAPMANAGER LICENSE ON LUN.
[15:15:58.129] [SERVERNAME] Querying LUN license: T...
[15:15:59.913] [SERVERNAME] Querying LUN license: S...

[15:16:01.685] [SERVERNAME] *** FULL DATABASE BACKUP

[15:16:01.686] [SERVERNAME] FULL DATABASE BACKUP [#1]

[15:16:01.686] [SERVERNAME] Full database backup location for database [master]:
[15:16:01.686] [SERVERNAME] T:\SMSQL_SnapInfo\SQL__SERVERNAME\DB__master\FG__\StreamFullBackup\09-28-2014_15.15.57__mast__Daily.FBK

[15:16:01.686] [SERVERNAME] Connecting to SQL Server SERVERNAME...
[15:16:01.719] [SERVERNAME] Starting full database backup for database [master]...
[15:16:01.824] [SERVERNAME] Database [SERVERNAME:master] Percent: 6 percent processed.6
[15:16:01.825] [SERVERNAME] Database [SERVERNAME:master] Percent: 10 percent processed.10
[15:16:01.825] [SERVERNAME] Database [SERVERNAME:master] Percent: 16 percent processed.16
[15:16:01.825] [SERVERNAME] Database [SERVERNAME:master] Percent: 21 percent processed.21
[15:16:01.834] [SERVERNAME] Database [SERVERNAME:master] Percent: 25 percent processed.25
[15:16:01.839] [SERVERNAME] Database [SERVERNAME:master] Percent: 31 percent processed.31
[15:16:01.846] [SERVERNAME] Database [SERVERNAME:master] Percent: 35 percent processed.35
[15:16:01.856] [SERVERNAME] Database [SERVERNAME:master] Percent: 40 percent processed.40
[15:16:01.870] [SERVERNAME] Database [SERVERNAME:master] Percent: 46 percent processed.46
[15:16:01.873] [SERVERNAME] Database [SERVERNAME:master] Percent: 50 percent processed.50
[15:16:01.877] [SERVERNAME] Database [SERVERNAME:master] Percent: 55 percent processed.55
[15:16:01.891] [SERVERNAME] Database [SERVERNAME:master] Percent: 61 percent processed.61
[15:16:01.895] [SERVERNAME] Database [SERVERNAME:master] Percent: 65 percent processed.65
[15:16:01.900] [SERVERNAME] Database [SERVERNAME:master] Percent: 71 percent processed.71
[15:16:01.910] [SERVERNAME] Database [SERVERNAME:master] Percent: 76 percent processed.76
[15:16:01.928] [SERVERNAME] Database [SERVERNAME:master] Percent: 80 percent processed.80
[15:16:01.935] [SERVERNAME] Database [SERVERNAME:master] Percent: 86 percent processed.86
[15:16:01.937] [SERVERNAME] Database [SERVERNAME:master] Percent: 91 percent processed.91
[15:16:01.941] [SERVERNAME] Database [SERVERNAME:master] Percent: 95 percent processed.95
[15:16:01.943] [SERVERNAME] Database [SERVERNAME:master] Percent: 100 percent processed.100
[15:16:02.011] [SERVERNAME] Database [SERVERNAME:master] BACKUP DATABASE successfully processed 378 pages in 0.208 seconds (14.193 MB/sec).
[15:16:02.012] [SERVERNAME] Full database backup of database [master] completed.

[15:16:02.031] [SERVERNAME] Setting operation result to registry...
[15:16:02.031] [SERVERNAME] Backup operation on SQL instance [SERVERNAME] database [master]

[15:16:02.039] [SERVERNAME] FULL DATABASE BACKUP [#2]

[15:16:02.039] [SERVERNAME] Full database backup location for database [model]:
[15:16:02.039] [SERVERNAME] T:\SMSQL_SnapInfo\SQL__SERVERNAME\DB__model\FG__\StreamFullBackup\09-28-2014_15.15.57__mode__Daily.FBK
[15:16:02.039] [SERVERNAME] Starting full database backup for database [model]...
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 9 percent processed.9
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 14 percent processed.14
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 18 percent processed.18
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 23 percent processed.23
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 28 percent processed.28
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 33 percent processed.33
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 37 percent processed.37
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 42 percent processed.42
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 47 percent processed.47
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 51 percent processed.51
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 56 percent processed.56
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 61 percent processed.61
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 66 percent processed.66
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 70 percent processed.70
[15:16:02.140] [SERVERNAME] Database [SERVERNAME:model] Percent: 75 percent processed.75
[15:16:02.156] [SERVERNAME] Database [SERVERNAME:model] Percent: 80 percent processed.80
[15:16:02.160] [SERVERNAME] Database [SERVERNAME:model] Percent: 89 percent processed.89
[15:16:02.168] [SERVERNAME] Database [SERVERNAME:model] Percent: 94 percent processed.94
[15:16:02.169] [SERVERNAME] Database [SERVERNAME:model] Percent: 99 percent processed.99
[15:16:02.180] [SERVERNAME] Database [SERVERNAME:model] Percent: 100 percent processed.100
[15:16:02.232] [SERVERNAME] Database [SERVERNAME:model] BACKUP DATABASE successfully processed 170 pages in 0.125 seconds (10.593 MB/sec).
[15:16:02.232] [SERVERNAME] Full database backup of database [model] completed.

[15:16:02.233] [SERVERNAME] Setting operation result to registry...
[15:16:02.233] [SERVERNAME] Backup operation on SQL instance [SERVERNAME] database [model]

[15:16:02.233] [SERVERNAME] FULL DATABASE BACKUP [#3]

[15:16:02.233] [SERVERNAME] Full database backup location for database [msdb]:
[15:16:02.233] [SERVERNAME] T:\SMSQL_SnapInfo\SQL__SERVERNAME\DB__msdb\FG__\StreamFullBackup\09-28-2014_15.15.57__msdb__Daily.FBK
[15:16:02.233] [SERVERNAME] Starting full database backup for database [msdb]...
[15:16:02.443] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 7 percent processed.7
[15:16:02.462] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 11 percent processed.11
[15:16:02.512] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 15 percent processed.15
[15:16:02.536] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 22 percent processed.22
[15:16:02.552] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 26 percent processed.26
[15:16:02.625] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 30 percent processed.30
[15:16:02.643] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 38 percent processed.38
[15:16:02.654] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 42 percent processed.42
[15:16:02.683] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 45 percent processed.45
[15:16:02.705] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 53 percent processed.53
[15:16:02.726] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 57 percent processed.57
[15:16:02.763] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 61 percent processed.61
[15:16:02.826] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 65 percent processed.65
[15:16:02.845] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 72 percent processed.72
[15:16:02.869] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 76 percent processed.76
[15:16:02.919] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 80 percent processed.80
[15:16:02.936] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 88 percent processed.88
[15:16:02.957] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 91 percent processed.91
[15:16:02.995] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 95 percent processed.95
[15:16:02.997] [SERVERNAME] Database [SERVERNAME:msdb] Percent: 100 percent processed.100
[15:16:03.025] [SERVERNAME] Database [SERVERNAME:msdb] BACKUP DATABASE successfully processed 3345 pages in 0.724 seconds (36.087 MB/sec).
[15:16:03.026] [SERVERNAME] Full database backup of database [msdb] completed.

[15:16:03.026] [SERVERNAME] Setting operation result to registry...
[15:16:03.026] [SERVERNAME] Backup operation on SQL instance [SERVERNAME] database [msdb]
[15:16:03.043] [SERVERNAME] *** TRANSACTION LOG BACKUP AFTER FULL DATABASE BACKUP

[15:16:03.044] [SERVERNAME] Transaction log backup for database [master] skipped (Simple Recovery Model).
[15:16:03.044] [SERVERNAME] Transaction log backup for database [model] skipped (Simple Recovery Model).
[15:16:03.044] [SERVERNAME] Transaction log backup for database [msdb] skipped (Simple Recovery Model).
[15:16:03.055] [SERVERNAME] SMSQL share for log backup was not configured, please run Configuration Wizard to set it up.
[15:16:03.055] [SERVERNAME]
[15:16:03.055] [SERVERNAME] *** BACKUP SNAPINFO DISK
[15:16:03.085] [SERVERNAME]
[15:16:03.086] [SERVERNAME] UPDATE MOST RECENT SNAPINFO DRIVE SNAPSHOT NAME

[15:16:03.087] [SERVERNAME] SNAPSHOT SNAPINFO DRIVE

[15:16:03.092] [SERVERNAME] Creating Snapshot of LUN(s):
[15:16:03.092] [SERVERNAME] LUN [T]
[15:16:03.092] [SERVERNAME] Snapshot name: sqlinfo__SERVERNAME_09-28-2014_15.15.57__daily
[15:16:10.137] [SERVERNAME] Snapshot SnapInfo drive(s) successfully completed.

[15:16:10.164] [SERVERNAME] *** DELETE THE OLDEST STREAM BASED BACKUP DATA SETS
[15:16:10.164] [SERVERNAME]
[15:16:10.164] [SERVERNAME] *** DELETING PREVIOUS BACKUPS: master

[15:16:10.164] [SERVERNAME] Querying stream based full database backup for [master]...
[15:16:10.192] [SERVERNAME] Current time: 9/28/2014 3:15:57 PM
[15:16:10.193] [SERVERNAME] Backups older than [1440] minutes ago will be deleted.
[15:16:10.212] [SERVERNAME] There are only [1] full database backup sets for master. 7 backups are selected to retain.
[15:16:10.212] [SERVERNAME] No full database backup of [master] will be deleted.
[15:16:10.212] [SERVERNAME]
[15:16:10.212] [SERVERNAME] *** DELETING PREVIOUS BACKUPS: model

[15:16:10.212] [SERVERNAME] Querying stream based full database backup for [model]...
[15:16:10.212] [SERVERNAME] Current time: 9/28/2014 3:15:57 PM
[15:16:10.212] [SERVERNAME] Backups older than [1440] minutes ago will be deleted.
[15:16:10.212] [SERVERNAME] There are only [1] full database backup sets for model. 7 backups are selected to retain.
[15:16:10.212] [SERVERNAME] No full database backup of [model] will be deleted.
[15:16:10.212] [SERVERNAME]
[15:16:10.212] [SERVERNAME] *** DELETING PREVIOUS BACKUPS: msdb

[15:16:10.212] [SERVERNAME] Querying stream based full database backup for [msdb]...
[15:16:10.213] [SERVERNAME] Current time: 9/28/2014 3:15:57 PM
[15:16:10.213] [SERVERNAME] Backups older than [1440] minutes ago will be deleted.
[15:16:10.213] [SERVERNAME] There are only [1] full database backup sets for msdb. 7 backups are selected to retain.
[15:16:10.213] [SERVERNAME] No full database backup of [msdb] will be deleted.
[15:16:10.235] [SERVERNAME]
[15:16:10.235] [SERVERNAME] *** DELETING LOG SNAPINFO DISK SNAPSHOT

[15:16:10.236] [SERVERNAME] Get log snapshot list from LUN [T]: ...
[15:16:14.814] [SERVERNAME] Federated backup(VDI): Setting abort [backup start ready] event to the driving server [SERVERNAME] for host [SERVERNAME]...
[15:16:14.819] [SERVERNAME] Federated backup(VDI): Setting abort [prepare for snapshot] event to the driving server [SERVERNAME] for host [SERVERNAME]...
[15:16:14.819] [SERVERNAME] Federated backup(VDI): Setting abort [ready for snapshot] event to the driving server [SERVERNAME] for host [SERVERNAME]...
[15:16:14.819] [SERVERNAME] Federated backup(VDI): Setting abort [go create snapshot] event to the driving server [SERVERNAME] for host [SERVERNAME]...
[15:16:14.819] [SERVERNAME] Federated backup(VDI): Setting abort [ready for marking log] event to the driving server [SERVERNAME] for host [SERVERNAME]...
[15:16:14.819] [SERVERNAME] All threads finished remote backup groups.

[15:16:14.825] [SERVERNAME]
[15:16:14.825] [SERVERNAME] #1 : Backup Group: Server - [SERVERNAME]: Failed with error 0x80004005
[15:16:14.825] [SERVERNAME] Backup Group: Failed with error 0x80004005
[15:16:14.840] [SERVERNAME] Preparing for sending filer AutoSupport...

[15:16:14.840] [SERVERNAME] **** BACKUP RESULT DETAILS ****
#1 : Backup Group: Server - [SERVERNAME]: Failed with error 0x80004005

[15:16:14.840] [SERVERNAME] **** BACKUP RESULT SUMMARY ****
Backup Group: Failed with error 0x80004005
[15:16:14.840] [SERVERNAME]

oweinmann · ‎2014-11-04

Just ran into the same issue. Did you ever get this one solved?

Lee-KineticCU · ‎2014-11-04

I did find a solution. I ended opening a ticket with support. During their prelimiary questions for discovery of this issue, they asked if I was able to see the snapshots in SnapDrive. When I went to SnapDrive I was able to see the snapshots but I also saw something else. One of the Snapshots in Snapdrive had a status of random numbers followed by "deleting" (####deleting). So I tried to go through the SnapManager for SQL MMC and "Delete Backups" however when I would even use the "Delete Preview" option it was throwing an error. I could only assuming that the SnapShot with the ####deleting status was casuing the problem. Since this backup should have been dropped anyways, I went ahead and deleted it using SnapDrive.

I then kicked off the backup and it completed successfully.

I am guessing that at some point after 9/27, that something happened during our backup that prevented the 9/27 backup from being deleted. Each time we ran the backup, when trying to delete previous backups it would fail since this entry was stuck in a deleting state.

I didn't take a "before" screenshot of SnapDrive but I did attach an editted screenshot that shows what it looked like in Snapdrive.