Symptoms

This is the error seen in the Cyber Recovery Manager user interface. Failed to run task recoverappPPDM. PPDM recovery timed out. The Cyber Recovery Manager apps.log shows the polling for the PARTIALLY_OPERATIONAL response code from PowerProtect Data Manager. Cyber Recovery Manager never gets that response code, and the recovery eventually fails with a timeout. [2024-04-17 16:06:25.804] [DEBUG] [apps] [jobs.go:426 Log()] : [JobID: 661fc9f71f9f4001896b078f JobName: recoverapp_5BC605 Task: recoverappPPDM] recovery Task Name: 60- Poll for Recovery Status [2024-04-17 16:06:25.938] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status [2024-04-17 16:06:55.995] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is PENDING [2024-04-17 16:07:26.080] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE [2024-04-17 16:07:26.100] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status [2024-04-17 16:07:56.155] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE_RUNNING [2024-04-17 16:07:56.171] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status [2024-04-17 16:08:26.230] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE_COMPLETED [2024-04-17 16:08:26.246] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status [2024-04-17 16:08:56.301] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE_COMPLETED [2024-04-17 16:08:56.321] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status [2024-04-17 16:09:26.378] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE_COMPLETED [2024-04-17 16:09:26.395] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status ... [2024-04-17 17:05:34.772] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE_COMPLETED [2024-04-17 17:05:34.791] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status [2024-04-17 17:06:04.851] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE_COMPLETED [2024-04-17 17:06:04.869] [INFO] [apps] [ppdmUtils.go:552 PollForPPDMRecoveryStatus()] : Waiting for 30s to check PPDM recovery status [2024-04-17 17:06:34.924] [INFO] [apps] [ppdmUtils.go:586 PollForPPDMRecoveryStatus()] : PPDM recovery status is RESTORE_COMPLETED [2024-04-17 17:06:34.942] [ERROR] [apps] [ppdmUtils.go:548 PollForPPDMRecoveryStatus()] : PPDM recovery timed out [2024-04-17 17:06:34.942] [DEBUG] [apps] [ppdmUtils.go:549 PollForPPDMRecoveryStatus()] : Exiting The PowerProtect Data Manager serverdr.log shows the PowerProtect Data Manager time jump back by one hour during the recovery. The time before jumping back is also out of sync with the Cyber Recovery Manager time. 2024-04-17T15:07:36.726Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.d.s.c.RequestStateChangeHandler.handle(60)] - requestStateChangeHandler - Current node.status : RESTORE_COMPLETED 2024-04-17T15:07:36.726Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.d.s.c.RequestStateChangeHandler.handle(65)] - requestStateChange adding restrictions to message 2024-04-17T15:07:36.727Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.d.s.c.RequestStateChangeHandler.handle(87)] - requestStateChange by sending notification request status=RESTORE_COMPLETED 2024-04-17T15:07:36.729Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.d.s.c.RequestStateChangeHandler.handle(89)] - requestStateChange after return from convertAndSend request status=RESTORE_COMPLETED 2024-04-17T15:07:36.729Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.d.s.SystemManagerDao.switchToRecoverCompletedState(271)] - Real switchToRecoverCompletedState done 2024-04-17T15:07:36.729Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.s.i.RestoreServiceImpl.updateRestoreStatus(455)] - Updating restore progress status SUCCESSFUL, error : null 2024-04-17T15:07:36.729Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.s.i.RestoreServiceImpl.processRestore(395)] - Cleaning global restore values 2024-04-17T15:07:36.730Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.s.i.RestoreServiceImpl.processRestore(397)] - Unlocking Maintenance 2024-04-17T15:07:36.730Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.s.i.RestoreServiceImpl.processRestore(399)] - Create Restore Initiate Audit Log 2024-04-17T15:07:36.730Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.d.ServerDisasterRecoveryDao.createRestoreInitiatedAuditLog(1253)] - Creating restore initiated audit log 2024-04-17T15:07:36.733Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.c.d.ServerDisasterRecoveryDao.createRestoreInitiatedAuditLog(1264)] - messageArgs [ "2024-04-17T06:34:32.215894007+0000" ] 2024-04-17T15:07:36.794Z INFO [] [datacomponentrestore-1] [][][][][] [c.e.d.e.c.s.a.DefaultAuditLogResourceModifierAndDecorator.getMessageWithArgs(212)] - messageTemplate: 'System restore has been initiated. The data changes after will be lost.', messageArgs: [ 2024-04-17T15:07:36.804Z INFO [] [datacomponentrestore-1] [][AUDIT][][][] [c.e.d.e.c.s.a.DefaultAuditLogResourceModifierAndDecorator.printAuditLog(251)] - Source: null; Audit Type: SERVER_DR; Details: System restore has been initiated. The data changes after 2024-04-17T06:34:32.2 15894007+0000 will be lost.; Changed By: null; Changed At: Apr 17, 2024 08:07:36 AM; Object Changed: Server Disaster Recovery Restore; Previous Value: null; New Values: null; Note: null 2024-04-17T15:07:37.227Z INFO [] [not.a.Spring.bean-8] [][][][TRACE_ID:b494975c8b80c84f][] [c.e.b.p.l.h.TimezoneChangeNotificationHandler.handleMessage(53)] - Received time zone change notification. 2024-04-17T14:08:26.125Z INFO [] [AsyncResolver-bootstrap-executor-0] [][][][][] [c.n.d.s.r.a.ConfigClusterResolver.getClusterEndpoints(43)] - Resolving eureka endpoints via configuration 2024-04-17T14:08:27.708Z INFO [] [scheduling-1] [][][][][] [c.e.d.e.c.s.c.s.i.HealthCheckServiceImpl.tmUnmanagedTaskCleaner(145)] - Scheduled Unmanaged Task Cleaner Triggered. Current Schedule Time :In Either In Seconds 900 : Or In Minues 15.0 : Task Cancelation Window : 10800 Seconds or 180.0 Minutes 2024-04-17T14:08:27.708Z INFO [] [scheduling-1] [][][][][] [c.e.d.e.c.s.c.u.RestUtils.getAllServerDrTasks(164)] - Extracting all ServerDr tasks 2024-04-17T14:08:27.719Z INFO [] [scheduling-1] [][][][][] [c.e.d.e.c.s.c.u.RestUtils.serverdrQuery(178)] - Generating Serverdr query with Workflow scheduled backups 2024-04-17T14:08:27.910Z INFO [] [scheduling-1] [][][][][] [c.e.d.e.c.s.c.u.RestUtils.getAllServerDrTasks(170)] - Extracted 5 Tasks 2024-04-17T14:08:27.910Z INFO [] [scheduling-1] [][][][][] [c.e.d.e.c.s.c.s.i.HealthCheckServiceImpl.tmUnmanagedTaskCleaner(155)] - Currently Running Or Queued Tasks Count : 5

Cause

The vault ESXi time was ahead of Network Time Protocol (NTP) time by 1 hour. When PowerProtect Data Manager starts, it gets the time from the ESXi. During recovery, the time would synchronize with NTP so the time goes to 1 hour ago, which breaks the recovery.

Resolution

Ensure that the time is synchronized across all vault components before starting the recovery.

Support Cases