SnapDrive Windows & Exchange backup timeouts

jasonpugsley — Thu, 05 Jun 2025 05:32:31 GMT

This is probably directed at the engineering team responsible for SnapDrive and SME but it might be interesting to others.

We've had an issue for a while with Exchange backups failing. An Exchange backup must occur within a 10 second window after the mailbox databases have had their I/O frozen.

When we check the windows application event log you can see that the backup failed because it took longer than 10 seconds, for example:

"Data ONTAP VSS hardware provider has completed CommitSnapshots for SnapshotSetId {699697d1-b950-47d8-9dfe-075b3fab74f6} in 10172 milliseconds. Since it takes more than 10 seconds, this can fail the current shadow copy."

I think I've tracked down the problem and it's not the duration of the actual snapshot but of a set of LUN attribute settings that get applied to the LUNs after the snapshot.

In another example below you can see the snapshot runs from 23:30:54.924 to 23:30:58.924, and then from 23:30:58.924 'lun-set-attribute' is called several times for each LUN through to 23:31:08.737

07/12-23:30:54.924     PID:2696     TID:23216     SnapCreateHelper.cpp@351          CreateMultivolSnapShotThreadProc - Begin
07/12-23:30:54.924     PID:2696     TID:23216     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:30:54.924     PID:2696     TID:23216     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:30:54.924     PID:2696     TID:23216     filer.cpp@16339          The 'snapshot-multicreate' ZAPI is being called.
07/12-23:30:54.924     PID:2696     TID:23216     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:30:58.924     PID:2696     TID:23216     filer.cpp@16416          CFilerRollingRock::zapi_snapshot_multicreate finished.
07/12-23:30:58.924     PID:2696     TID:23216     SnapCreateHelper.cpp@436          CreateMultivolSnapShotThreadProc End
07/12-23:30:58.924     PID:2696     TID:7920     EventLog.cpp@344          Start NeedMuteEvent(): dwEventID 190 dwNumStrings 3 enumEvtMuteGrp -1
07/12-23:30:58.924     PID:2696     TID:7920     EventLog.cpp@438          End NeedMuteEvent(): dwEventID 190 dwNumStrings 3 enumEvtMuteGrp -1 bRet=00
07/12-23:30:58.924     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:30:58.924     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:30:58.924     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:30:58.924     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:30:59.236     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:30:59.236     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:30:59.236     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:30:59.236     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:30:59.549     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:30:59.549     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:30:59.549     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:30:59.549     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:30:59.861     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:30:59.861     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:30:59.861     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:30:59.861     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:00.158     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:00.158     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:00.158     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:00.158     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:00.502     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:00.502     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:00.502     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:00.502     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:00.861     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:00.861     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:00.861     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:00.861     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:01.158     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:01.158     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:01.158     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:01.158     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:01.486     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:01.486     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:01.486     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:01.486     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:01.783     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:01.783     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:01.783     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:01.783     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:02.080     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:02.080     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:02.080     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:02.080     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:02.377     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:02.377     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:02.377     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:02.377     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:02.674     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:02.674     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:02.674     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:02.674     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:03.018     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:03.018     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:03.018     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:03.018     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:03.315     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:03.315     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:03.315     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:03.315     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:03.627     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:03.627     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:03.627     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:03.627     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:03.924     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:03.924     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:03.924     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:03.924     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:04.221     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:04.221     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:04.221     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:04.221     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:04.533     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:04.533     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:04.533     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:04.533     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:04.830     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:04.830     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:04.830     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:04.830     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:05.143     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:05.143     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:05.143     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:05.143     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:05.455     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:05.455     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:05.455     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:05.455     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:05.768     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:05.768     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:05.768     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:05.768     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:06.065     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:06.065     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:06.065     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:06.065     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:06.361     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:06.361     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:06.361     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:06.361     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:06.643     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:06.643     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:06.643     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:06.643     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:06.955     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:06.955     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:06.955     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:06.955     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:07.252     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:07.252     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:07.252     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:07.252     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:07.549     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:07.549     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:07.549     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:07.549     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:07.846     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:07.846     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:07.846     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:07.846     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:08.127     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:08.127     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:08.127     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:08.127     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:08.440     PID:2696     TID:12496     filer.cpp@1143          CFiler::static_setup_zapi_connection(HTTPS,corp\svc-snapdrv-ex,443): start.
07/12-23:31:08.440     PID:2696     TID:12496     filer.cpp@1168          CFiler::static_setup_zapi_connection: end.
07/12-23:31:08.440     PID:2696     TID:12496     filer.cpp@6184          The 'lun-set-attribute' ZAPI is being called.
07/12-23:31:08.440     PID:2696     TID:12496     filer.cpp@11326          CFilerRollingRock1::NA_SERVER_INVOKE_WRAPPER - start
07/12-23:31:08.737     PID:2696     TID:12496     SnapShot.cpp@8279          Finish CSnapShot::CreateSnapShotInternal_PerFiler
07/12-23:31:08.737     PID:2696     TID:12496     SnapShot.cpp@8526          CSnapShot::CreateSnapShot1 - End
07/12-23:31:08.737     PID:2696     TID:12496     Sychronize.h@108          Mutex::Release called
07/12-23:31:08.737     PID:2696     TID:12496     Sychronize.h@118          Mutex::Release finished execution
07/12-23:31:08.737     PID:2696     TID:12496     SWSvc.cpp@2431          CServiceModule::ReleaseVolumeCache
07/12-23:31:08.737     PID:2696     TID:12496     host_volume_info.cpp@1170          exit_volume_list_vector: Clear m_volume_list_vector.
07/12-23:31:08.737     PID:2696     TID:12496     SWSvc.cpp@2336          CServiceModule::ReleaseZapiCache
07/12-23:31:08.737     PID:2696     TID:12496     filer.h@3222          exit_volume_list_map: Clear m_volume_list_map.

Each round-trip ZAPI call takes about a quarter of a second. With 32 ZAPI calls (4 per LUN, 8 LUNs) that's around 8-10 seconds just to set LUN attributes.

The time varies with each backup and depends on things such as how busy the cluster is.

I don't have a 'quiet' time that I can schedule backups for - our clusters are pretty busy at most parts of the day. I also don't want to split our backup sets into ever smaller groups of mailbox databases but this is the only option I have right now.

In the meantime, can I suggest the SME and SnapDrive team look at adding a feature request to change the way this works?

Here are some of my ideas:

Move the 'lun-set-attribute' out of the critical path for the backup so it doesn't hold up sending Exchange a success result for the snapshot.
Modify ZAPI and SnapDrive to add a 'lun-set-attributes' call so multiple attributes can be set with just one call.
Update SnapDrive so it reuses HTTP sessions - I know the filer web server used to close the session after each request-response pair but in newer versions sessions can be long lived. Don't close a session until it has been idle for at least 1 second (maybe longer). This would avoid the time wasted in setting up new HTTPS sessions for every single ZAPI call that gets made.

Regards,

Jason

topic SnapDrive Windows & Exchange backup timeouts in Data Protection

SnapDrive Windows & Exchange backup timeouts