SnapManager 7.2 for Exchange Verification Error

SP-IT-Team · ‎2017-12-20

SnapManager for Exchange Version 7.2.0.1811

Hello,

We get an Verification Error after Backup for only a single LUN/Database of five LUNs/Databases. We are able to mount the Snapshot manually after.

Here some snippets out of the Log:

[23:05:24.781]  ***BACKUP VERIFICATION STATUS: mdb03

[23:05:24.781]  Databases verification successfully completed.

[23:05:24.781]  ***BACKUP VERIFICATION: mdb04

[23:05:24.781]  Start to verify the database in snapshot...
[23:05:29.359]  UpdateSelectedDestinationVolumesStatus Started
[23:05:29.359]  FullBackup job with JobID=1049 invoke Job Management for local integrity verification

[23:05:29.359]  SnapManager srvex01 concurrent job status at 19.12.2017 23:05:29 : 
[23:05:29.359]  =================================================================================================
[23:05:29.359]  SnapManager is creating full backup with JobID=1049.
[23:05:29.359]  SnapManager is running 0 backup integrity verification jobs.
[23:05:29.359]  This BackupVerification job with JobID=1053 is waiting in the queue at position 0.
[23:05:29.359]  =================================================================================================


[23:05:29.359]  BackupVerification Job of JobID 1053 starts to run on server srvex01.


[23:05:29.359]  The destination volume of the source Logical Disk H FlexClone State is Unknown and SnapMirror State is Unknown.
[23:05:36.375]  Mounting Snapshot [exchsnap__srvex01_12-19-2017_23.00.22__daily] for LUN H created from Computer SRVEX01
[23:05:36.375]  Mount point directory [C:\Program Files\NetApp\SnapManager for Exchange\SnapMgrMountPoint]
[23:05:37.906]  Snapshot will be mounted on subdirectory [MPDisk375]
[23:06:04.797]  [SnapDrive Error]:An attempt to map LUN '/vol/sdw_cl_vf_iscsi_srvex01_mdb04_0/qsrvex01_mdb04/srvex01_mdb04_H' to the igroup 'viaRPC.iqn.1991-05.com.microsoft:srvex01.xy.local'on the storage system 'vf_iscsi' failed. Error code: 9023. Error description: LUN already mapped to this group.
 (SnapDrive Error Code: 0xc0040339)
[23:06:04.797]  Unable to mount snapshot, abort verification.
[23:06:04.797]  [SnapDrive Error]:An attempt to map LUN '/vol/sdw_cl_vf_iscsi_srvex01_mdb04_0/qsrvex01_mdb04/srvex01_mdb04_H' to the igroup 'viaRPC.iqn.1991-05.com.microsoft:srvex01.xy.local'on the storage system 'vf_iscsi' failed. Error code: 9023. Error description: LUN already mapped to this group.



[23:06:04.797]  BackupVerification Job of JobID=1053 is finished with status Failed.

[23:06:04.797]  [SnapDrive Error]:An attempt to map LUN '/vol/sdw_cl_vf_iscsi_srvex01_mdb04_0/qsrvex01_mdb04/srvex01_mdb04_H' to the igroup 'viaRPC.iqn.1991-05.com.microsoft:srvex01.xy.local'on the storage system 'vf_iscsi' failed. Error code: 9023. Error description: LUN already mapped to this group.

[23:06:04.797]  [SnapDrive Error]:An attempt to map LUN '/vol/sdw_cl_vf_iscsi_srvex01_mdb04_0/qsrvex01_mdb04/srvex01_mdb04_H' to the igroup 'viaRPC.iqn.1991-05.com.microsoft:srvex01.xy.local'on the storage system 'vf_iscsi' failed. Error code: 9023. Error description: LUN already mapped to this group.

[23:06:05.188]  Verification failed. Error code: 0xc0040339, LUN: H:\
[23:06:05.188]  An autosupport message is sent on failure to the storage system of LUN [H:\].

[23:06:05.188]  ***BACKUP VERIFICATION STATUS: mdb04

[23:06:05.188]  Failed to verify physical integrity of the databases.

[23:26:23.137]  *****FULL BACKUP RESULT SUMMARY*****

[23:26:23.137]  Backup group set #1: 

[23:26:23.137]  Backup SG/DB [mdb01]: OK

[23:26:23.137]  Backup SG/DB [mdb02]: OK

[23:26:23.137]  Backup SG/DB [mdb03]: OK

[23:26:23.137]  Backup SG/DB [mdb04]: Backup OK, verification failed

[23:26:23.137]  Backup SG/DB [mdb05]: OK


[23:26:23.137]  *****BACKUP DETAIL SUMMARY*****

[23:26:23.137]  Backup group set #1: 

[23:26:23.137]  Backup SG/DB [mdb01] OK

[23:26:23.137]  Backup SG/DB [mdb02] OK

[23:26:23.137]  Backup SG/DB [mdb03] OK

[23:26:23.137]  Backup SG/DB [mdb04] Error: Failed to verify physical integrity of the databases.

[23:26:23.137]  Backup SG/DB [mdb05] OK

Thanks for any input.

Best Regards

matte · ‎2017-12-20

Hi

what do you have in H:

Do you have the Storage Layout that follow the requirments?

https://library.netapp.com/ecmdocs/ECMP1649948/html/GUID-17489902-B584-4C23-8B57-74FC77F7D3B6.html

If you are able to mount the snapshot later, when the bakup is finished this means that the error thrown by snapdrive is correct.

You need to check in the SME report or in the SD logs where and when the snapshot (LUN) is mapped.

SP-IT-Team · ‎2017-12-20

Hello,

H is the Drive letter of the database 4 (mdb04).

Yes the requirements should be met. We only have one database per lun. The transaction logs and snapdrive have each it's own drive.

I don't understand why only the mdb04 has this problem. Because all 5 databases have it's own Lun and are configured the same.

matte · ‎2017-12-20

From the log you poested SD is mounthng the snapshot exchsnap__srvex01_12-19-2017_23.00.22__daily

Snapshot copies are volume-wide, so you need to be sure that items on the same volume have compatible backup schedules

have you ever tried to backup and verify the database 04 on its own?

SP-IT-Team · ‎2017-12-20

This is the "Daily"-Job Shedule, which produced this error. This job backups all databases in the same job.

SMEJobLauncher.exe new-backup -Server 'SRVEX01' -ManagementGroup 'Daily' -RetainDays 14 -RetainUtmDays 2 -Verify  -VerificationServer 'srvex01' -UseMountPoint  -RemoteAdditionalCopyBackup $False

What do you mean with compatible Backup shedule? I do have only one Job.

If I do a backup of only the mdb04 it succeeds and the verification works too.

[14:51:30.195]  ---------- Starting backup/snapshot ----------------

[14:51:30.195]  Adding volumes to the snapshot set: 

[14:51:30.195]  Adding volume containing H:\ ... 
[14:51:32.258]  Successfully add volumes to snapshot set.
[14:51:32.258]  Adding volume containing J:\ ... 
[14:51:32.554]  Successfully add volumes to snapshot set.

[14:51:32.554]  ------------ Creating the snapshot -----------------

[14:51:32.554]  Starting asynchronous PrepareForBackup. Please wait...

[14:51:33.570]  Asynchronous PrepareForBackup finished.

[14:51:33.586]  Status after PrepareForBackup (13 writers)
[14:51:33.586]  Status for writer Task Scheduler Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer VSS Metadata Store Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer Performance Counters Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer System Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer ASR Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer Shadow Copy Optimization Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer Microsoft Exchange Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer Registry Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer IIS Config Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer COM+ REGDB Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer WMI Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer IIS Metabase Writer: STABLE(0x00000000)
[14:51:33.586]  Status for writer MSMQ Writer (MSMQ): STABLE(0x00000000)

[14:51:33.586]  Starting asynchronous DoSnapshotSet. Please wait...

[14:51:34.601]  Operation pending, please wait...(1)
[14:51:39.680]  Asynchronous DoSnapshotSet finished.

[14:51:39.695]  Status after DoSnapshotSet (13 writers)
[14:51:39.695]  Status for writer Task Scheduler Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer VSS Metadata Store Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer Performance Counters Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer System Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer ASR Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer Shadow Copy Optimization Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer Microsoft Exchange Writer: WAIT_FOR_BACKUP_COMPLETE(0x00000000)
[14:51:39.695]  Status for writer Registry Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer IIS Config Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer COM+ REGDB Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer WMI Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer IIS Metabase Writer: STABLE(0x00000000)
[14:51:39.695]  Status for writer MSMQ Writer (MSMQ): STABLE(0x00000000)
[14:51:39.695]  Snapshot set created


[14:51:40.023]  ------------ Saving backup metadata ---------------

[14:51:40.242]  Backup instance id matches metadata instance id.
[14:51:40.242]  Backup metadata file was saved to K:\sme_snapinfo_mdb04\EXCH__SRVEX01\SG__mdb04\12-20-2017_14.51.19\Vss__12-20-2017_14.51.19_{DAE83188-9FBD-48A9-819D-740FA44936C2}.xml.

[14:51:40.242]  Getting log generation from checkpoint file: mdb04...
[14:51:40.273]  Current checkpoint of [mdb04]: 0x0000861B
[14:51:40.273]  Getting log generation from live log directory: mdb04...
[14:51:40.273]  The highest numbered log generation of [mdb04] from live file system: 0x00008686.

[14:51:40.820]  Rename Snapshot for LUN H from {7cdbe15d-c57d-4fcf-8f28-7bd08f83f636}
[14:51:40.820]  To exchsnap__srvex01_12-20-2017_14.51.19
[14:51:41.383]  Rename snapshot successfully completed.

[14:51:41.383]  Rename Snapshot for LUN J from {7cdbe15d-c57d-4fcf-8f28-7bd08f83f636}
[14:51:41.383]  To exchsnap__srvex01_12-20-2017_14.51.19
[14:51:41.836]  Rename snapshot successfully completed.


[14:51:41.836]  ***BACKUP VERIFICATION: mdb04

[14:51:41.836]  Start to verify the database in snapshot...
[14:51:43.805]  UpdateSelectedDestinationVolumesStatus Started
[14:51:43.805]  FullBackup job with JobID=1055 invoke Job Management for local integrity verification

[14:51:43.805]  SnapManager srvex01 concurrent job status at 20.12.2017 14:51:43 : 
[14:51:43.805]  =================================================================================================
[14:51:43.805]  SnapManager is creating full backup with JobID=1055.
[14:51:43.805]  SnapManager is running 0 backup integrity verification jobs.
[14:51:43.805]  This BackupVerification job with JobID=1056 is waiting in the queue at position 0.
[14:51:43.805]  =================================================================================================


[14:51:43.820]  BackupVerification Job of JobID 1056 starts to run on server srvex01.


[14:51:43.820]  The destination volume of the source Logical Disk H FlexClone State is Unknown and SnapMirror State is Unknown.
[14:51:50.836]  Mounting Snapshot [exchsnap__srvex01_12-20-2017_14.51.19] for LUN H created from Computer SRVEX01
[14:51:50.836]  Mount point directory [C:\Program Files\NetApp\SnapManager for Exchange\SnapMgrMountPoint]
[14:51:52.367]  Snapshot will be mounted on subdirectory [MPDisk836]
[14:52:04.649]  This Snapshot is mounted as the drive [C:\Program Files\NetApp\SnapManager for Exchange\SnapMgrMountPoint\MPDisk836].
[14:52:04.649]  Mount Snapshot succeeded.
[14:52:04.649]  Change the "BitLockerWaitTime" Registry if the drive is Bitlock enabled

[14:52:04.649]  RUNNING DATABASE INTEGRITY VERIFICATION - [#1]


[14:52:04.649]  Running Integrity Verification using CheckSgFiles API

[14:52:04.680]  File: C:\Program Files\NetApp\SnapManager for Exchange\SnapMgrMountPoint\MPDisk836\mdb04\mdb04.edb

[14:52:04.711]                 Checksum Status ( complete)

          0    10   20   30   40   50   60   70   80   90  100
          |----|----|----|----|----|----|----|----|----|----|
          
                                                                                                                                                                ..................................................[14:54:32.199]  

995328 pages seen
0 bad checksums
0 correctable checksums
8654 uninitialized pages
0 wrong page numbers
0x1139204 highest dbtime (pgno 0xcf66f)

497664 reads performed
31104 MB read
147 seconds taken
211 MB/second
150798095 milliseconds used
303 milliseconds per read
1453 milliseconds for the slowest read
0 milliseconds for the fastest read

[14:54:32.215]  Operation completed successfully in 147.563 seconds.

[14:54:32.215]  Dismounting LUN [C:\Program Files\NetApp\SnapManager for Exchange\SnapMgrMountPoint\MPDisk836] of Snapshot [exchsnap__srvex01_12-20-2017_14.51.19]...
[14:54:43.168]  Dismount snapshot successfully completed.



[14:54:43.168]  BackupVerification Job of JobID=1056 is finished with status Completed.

[14:54:43.168]  Updating SnapInfo file at K:\sme_snapinfo_mdb04\EXCH__SRVEX01\SG__mdb04\12-20-2017_14.51.19\SnapInfo__12-20-2017_14.51.19.sme with Esefile Result=Success

[14:54:43.168]  Updating SnapInfo file at K:\sme_snapinfo_mdb04\EXCH__SRVEX01\SG__mdb04\12-20-2017_14.51.19\SnapInfo__12-20-2017_14.51.19.sme with Remote Esefile Result=Success


[14:54:43.168]  ***BACKUP VERIFICATION STATUS: mdb04

[14:54:43.168]  Databases verification successfully completed.

matte · ‎2017-12-20

Can you paste here also the coplete report of the backup with the failure? 🙂

we can checkl if and when SD mount the snapshot exchsnap__srvex01_12-19-2017_23.00.22__daily and if and when it dismount it..

SP-IT-Team · ‎2017-12-20

Here you go

SP-IT-Team · ‎2017-12-20

Here you go

SP-IT-Team · ‎2017-12-20

Strange... today it's mdb03 where the verification failed

[23:21:48.967]  Failed to backup storage group/database set.
[23:21:48.967]  ***SNAPMANAGER BACKUP SUBJOB ENDED AT: [12-20-2017_23.21.48]

[23:21:48.967]  ***SUBJOB #1: END OF BACKUP


[23:21:48.967]  *****FULL BACKUP RESULT SUMMARY*****

[23:21:48.967]  Backup group set #1: 

[23:21:48.967]  Backup SG/DB [mdb01]: OK

[23:21:48.967]  Backup SG/DB [mdb02]: OK

[23:21:48.967]  Backup SG/DB [mdb03]: Backup OK, verification failed

[23:21:48.967]  Backup SG/DB [mdb04]: OK

[23:21:48.967]  Backup SG/DB [mdb05]: OK


[23:21:48.967]  *****BACKUP DETAIL SUMMARY*****

[23:21:48.967]  Backup group set #1: 

[23:21:48.967]  Backup SG/DB [mdb01] OK

[23:21:48.967]  Backup SG/DB [mdb02] OK

[23:21:48.967]  Backup SG/DB [mdb03] Error: Failed to verify physical integrity of the databases.

[23:21:48.967]  Backup SG/DB [mdb04] OK

[23:21:48.967]  Backup SG/DB [mdb05] OK

SP-IT-Team · ‎2017-12-20

Attached the log which you requested

matte · ‎2017-12-21

That unfortunately does not help to understand the issue.

As you can see there is the snapshot unmount command

[23:05:01.921] Dismounting LUN [C:\Program Files\NetApp\SnapManager for Exchange\SnapMgrMountPoint\MPDisk420] of Snapshot [exchsnap__srvex01_12-19-2017_23.00.22__daily]...
[23:05:24.781] Dismount snapshot successfully completed.

and then another mount for the next verificaiton

23:05:36.375] Mounting Snapshot [exchsnap__srvex01_12-19-2017_23.00.22__daily] for LUN H created from Computer SRVEX01
[23:05:36.375] Mount point directory [C:\Program Files\NetApp\SnapManager for Exchange\SnapMgrMountPoint]

something happen in between..

which SD version are you using? is this in IMT with the other software? https://mysupport.netapp.com/matrix/#search

do you have MPIO enabled?

what do you see in the event viewer and in the sanpdrive logs at the same time of the failure?