4

I have the following:-

  1. sharepoint farm 2013 on-premises.
  2. i have the following back.bat file:-

"%SYSTEMROOT%\system32\windowspowershell\v1.0\powershell.exe" -Command Start-Process "$PSHOME\powershell.exe" -Verb RunAs -ArgumentList "'%~dp0\backup.ps1'"

  1. and the following backup.ps1 file which is being referenced from the above .bat file. and the .ps1 file will be doing a farm backup:-

Add-PSSnapin "Microsoft.SharePoint.PowerShell"

Remove-Item -recurse c:\Back*

Backup-SPFarm -Directory \***\Back -BackupMethod full -BackupThreads 10 -Force

  1. now using the windows task scheduler, i create a task which will run the above .bat file.

now i have noted when the tasks started a new folder is created under the c:\back folder and the backup folder contain many .bak files with sizes such as 500 MB,150 MB, etc.. but for more than 40 minutes the backup task is not doing anything, and when i checked the spbackup file i find that it hangs on the following stage:-

Waiting for second phase backup for index SPd1f9d427e849.

here is the latest lines inside the spbackup file:-

[25/07/2017 17:03:55] Progress: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] 84 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] 91 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] 98 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 14 percent complete.
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] SQL Server Message: Processed 112 pages for database 'Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0', file 'Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0' on file 2.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] 100 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 28 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 42 percent complete.
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] SQL Server Message: Processed 2 pages for database 'Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0', file 'Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0_log' on file 2.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 56 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 70 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 84 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 98 percent complete.
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] SQL Server Message: Processed 56 pages for database 'Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae', file 'Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae' on file 2.
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_AnalyticsReportingStoreDB_e3be102b34884efbb8fada7b1169d759] SQL Server Message: BACKUP DATABASE WITH DIFFERENTIAL successfully processed 41 pages in 0.063 seconds (5.084 MB/sec).
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_AnalyticsReportingStoreDB_e3be102b34884efbb8fada7b1169d759] SQL command completed at: 25/07/2017 17:03:55.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] 100 percent complete.
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] SQL Server Message: Processed 1 pages for database 'Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae', file 'Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae_log' on file 2.
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] SQL Server Message: BACKUP DATABASE WITH DIFFERENTIAL successfully processed 57 pages in 0.038 seconds (11.718 MB/sec).
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_LinksStoreDB_5777fdbc964c4ab28cb7b4a29f84fbae] SQL command completed at: 25/07/2017 17:03:55.
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] SQL Server Message: BACKUP DATABASE WITH DIFFERENTIAL successfully processed 114 pages in 0.114 seconds (7.756 MB/sec).
[25/07/2017 17:03:55] Verbose: [Search_Service_Application_CrawlStoreDB_bf83ad956c814b1fae127f1ce44962d0] SQL command completed at: 25/07/2017 17:03:55.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 8 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 11 percent complete.
[25/07/2017 17:03:55] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 20 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 26 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 31 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 37 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 40 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 46 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 52 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 55 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 61 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 66 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 72 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 75 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 87 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 90 percent complete.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 95 percent complete.
[25/07/2017 17:03:56] Verbose: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] SQL Server Message: Processed 272 pages for database 'Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d', file 'Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d' on file 2.
[25/07/2017 17:03:56] Progress: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] 100 percent complete.
[25/07/2017 17:03:56] Verbose: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] SQL Server Message: Processed 4 pages for database 'Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d', file 'Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d_log' on file 2.
[25/07/2017 17:03:56] Verbose: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] SQL Server Message: BACKUP DATABASE WITH DIFFERENTIAL successfully processed 276 pages in 0.105 seconds (20.489 MB/sec).
[25/07/2017 17:03:56] Verbose: [Search_Service_Application_DB_37e97f6ff2624e0fa193eac35ae8f97d] SQL command completed at: 25/07/2017 17:03:56.
[25/07/2017 17:03:56] Verbose: [IndexController] Waiting for second phase backup for index SPd1f9d427e849.

so can anyone adivce what is causing this problem? second question. what i can do now? is there any harm if i force the task to end (if there is not any harm , how i can end the task?)? or it is better to wait till the backup fails or raise a timeout ?

here is how my backup folder looks like:- enter image description here

here is the current running tasks inside the task manager:- enter image description here

After around 2 hours the backup completed with 12 errors, here is part of the errors :-

[25/07/2017 18:50:07] Verbose: [IndexController] Aborting backup job for index SPd1f9d427e849.
[25/07/2017 18:50:07] Verbose: [Search Service Application] Resuming crawls and feeding.
[25/07/2017 18:52:38] Verbose: [Search Service Application] Resuming crawls and feeding completed in 2.5 minutes.
[25/07/2017 18:52:38] Verbose: [Search Service Application] Resuming master merge.
[25/07/2017 18:55:08] Verbose: [Search Service Application] Resuming master mergex completed in 2.5 minutes.
[25/07/2017 18:55:09] FatalError: Object Search Service Application failed in event OnBackup. For more information, see the spbackup.log or sprestore.log file located in the backup directory.
    FaultException: Management called failed with System.InvalidOperationException: 'Second phase backup job SPd1f9d427e849->\\******1\Back\spbr0000\ does not exist. (The job is still in the first phase.)' at    at Microsoft.Ceres.SearchCore.IndexController.BackupService.ProgressSecondPhase(String handle)
   at Microsoft.Ceres.SearchCore.IndexController.IndexControllerManagementAgent.WrapCall[T](Func`2 original)
[25/07/2017 18:55:09] Debug: 
Server stack trace: 
   at System.ServiceModel.Channels.ServiceChannel.HandleReply(ProxyOperationRuntime operation, ProxyRpc& rpc)
   at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
   at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
   at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)

Exception rethrown at [0]: 
   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
   at Microsoft.Ceres.SearchCore.Admin.IIndexControllerManagementAgent.ProgressSecondPhase(String handle)
   at Microsoft.Office.Server.Search.Administration.BRIndexComponent.RetryWhileNoEndPoint[T](Func`2 action, SPBackupRestoreInformation args, Guid ssaId, TimeSpan retryTimeout)
   at Microsoft.Office.Server.Search.Administration.BRIndexComponent.RetryWhileNoEndPoint[T](Func`2 action, SPBackupRestoreInformation args, Guid ssaId, TimeSpan retryTimeout)
   at Microsoft.Office.Server.Search.Administration.BRIndexComponent.<>c__DisplayClass13`1.<RetryWhileNoEndPoint>b__12()
   at Microsoft.SharePoint.SPSecurity.<>c__DisplayClass5.<RunWithElevatedPrivileges>b__3()
   at Microsoft.SharePoint.Utilities.SecurityContext.RunAsProcess(CodeToRunElevated secureCode)
   at Microsoft.SharePoint.SPSecurity.RunWithElevatedPrivileges(WaitCallback secureCode, Object param)
   at Microsoft.SharePoint.SPSecurity.RunWithElevatedPrivileges(CodeToRunElevated secureCode)
   at Microsoft.Office.Server.Search.Administration.BRIndexComponent.RetryWhileNoEndPoint[T](Func`2 action, SPBackupRestoreInformation args, Guid ssaId)
   at Microsoft.Office.Server.Search.Administration.BRIndexComponent.WaitPhaseComplete(SPBackupInformation args, Func`2 getProgress, Int32 sleepTime)
   at Microsoft.Office.Server.Search.Administration.BRIndexComponent.WaitSecondPhaseBackupComplete(SPBackupInformation args)
   at Microsoft.Office.Server.Search.Administration.TwoPhaseBackupHelper.WaitSecondPhaseBackupCompleteChildren(SPBackupInformation args)
   at Microsoft.Office.Server.Search.Administration.SearchServiceApplication.OnBackup(SPBackupInformation args)
  • 1
    is your search crawl is running? – Waqas Sarwar MVP Jul 25 '17 at 18:32
  • @WaqasSarwarMVP now i have the incremental crawl running each 15 minutes .. but on other farms i have the same settings , and i have never face any problem when doing backup-spfarm ... so are you saying that while doing backup-spfarm the search should not be running ? but i have been doing backup-spfarm on many farms over the years and i have never stop the search during the backup process.. can u adivce more on ur point please? – john Gu Jul 25 '17 at 20:12
  • @WaqasSarwarMVP now after 2 hours the backup completed with 12 errors!! – john Gu Jul 25 '17 at 20:17
  • 1
    i am not saying stop the search service but i know if search crawl is running then it cause issue with backups – Waqas Sarwar MVP Jul 25 '17 at 20:17
  • 1
    is the crawl running at that time? that what i am seeing – Waqas Sarwar MVP Jul 25 '17 at 20:22
4

from the error, what it looks like you are search crawl is running. if an active crawl is crawling the content then backup job will struggle to perform a backup.

Please make sure that search crawls are idle before backup job started.

read this here: https://blogs.technet.microsoft.com/sharepointsearch/2016/05/20/search-ssa-backup-is-failing-sp2013/

also https://technet.microsoft.com/en-us/library/ee748635.aspx

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.