3394209 - PIT recovery issue with Cohesity

Restore of full backup works with Cohesity, but the Point In Time (PIT) recovery hangs and the TenantDB is not in GREEN state.

Following error in the trace:

[14511]{-1}[-1/-1] 2023-06-17 19:35:34.478787 a Backup           BackupDestBackint_Executor.cpp(00186) : Exit void Backup::BackupDestBackint_Executor::waitForBackintTermination(Backup::BackupDestBackint_Job&, uint64_t)(4usec)
[14511]{-1}[-1/-1] 2023-06-17 19:35:34.478789 i Backup           BackupExe_BackintHandlerImpl.cpp(00047) : ~BackupExe_BackintHandlerImpl: backint terminated
[14511]{-1}[-1/-1] 2023-06-17 19:35:34.478881 a Backup           BackupMgr_Client.cpp(00862) : Enter virtual void Backup::BackupMgr_Client::sendRequest(const Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)
[31590]{-1}[-1/-1] 2023-06-17 19:35:34.479374 a Backup           BackupMgr_Manager.cpp(00503) : Enter virtual void Backup::BackupMgr_Manager::handleRequest(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)
Arg request = (S)SenderHost=sothdXXX0101|SenderPort=30103|TextMessage=2023-06-17 19:35:34.478 backint terminated:
  pid: 33389
  exit code: 0
  output:
  #SOFTWAREID "1.04" "Cohesity DataProtect 6.6 for SAP HANA"
  #RESTORED 1687003444474522_764225954 "/usr/sap/XXX/SYS/global/hdb/backint/DB_XXX/log_backup_3_0_5394780385344_5394780575104"
  #RESTORED 1687012028905289_1200559192 "/usr/sap/XXX/SYS/global/hdb/backint/DB_XXX/log_backup_3_0_5394780848768_5394780848832"
  #RESTORED 1687012897081574_1940334891 "/usr/sap/XXX/SYS/global/hdb/backint/DB_XXX/log_backup_3_0_5394780848832_5394781185344"
  #RESTORED 1687018452419615_400478964 "/usr/sap/XXX/SYS/global/hdb/backint/DB_XXX/log_backup_3_0_5394781185344_5394781185408"
|(I)Method=23|SenderDatabaseId=3|SenderService=1|VolumeID=3|
[31590]{-1}[-1/-1] 2023-06-17 19:35:34.479585 a Backup           BackupMgr_Manager.cpp(00651) : Return (I)ReturnCode=0|
[31590]{-1}[-1/-1] 2023-06-17 19:35:34.479589 a Backup           BackupMgr_Manager.cpp(00651) : Exit virtual void Backup::BackupMgr_Manager::handleRequest(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)(215usec)
[14511]{-1}[-1/-1] 2023-06-17 19:35:34.479885 a Backup           BackupMgr_Client.cpp(00862) : Exit virtual void Backup::BackupMgr_Client::sendRequest(const Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)(1004usec)
[14511]{-1}[-1/-1] 2023-06-17 19:35:34.480016 a Backup           BackupExe_SimpleExecutor.cpp(00431) : Exit virtual void Backup::BackupExe_SimpleExecutor::executeRestore(DataAccess::RedoLogPosition, Backup::BackupExe_JobRestoreGlobalParams&, Backup::Executor::BackupType, Backup::Executor::RecoveryResults&)(44837245usec)
[14511]{-1}[-1/-1] 2023-06-17 19:35:34.480245 d Backup           BackupRecoverLogHandler.cpp(00402) : after everything has been done: finish the redo
[14511]{-1}[-1/-1] 2023-06-17 19:35:34.480249 a Backup           BackupExe_SimpleExecutor.cpp(00639) : Enter void Backup::BackupExe_SimpleExecutor::waitForFinishLogRecovery()
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143258 a Backup           BackupExe_LogRecoveryCallback.cpp(00069) : Enter virtual void Backup::BackupExe_LogRecoveryCallback::recoveryPointInTimeReached(DataAccess::RedoLogPosition, const ltt::map<unsigned int, long unsigned int>&, uint64_t, DataAccess::LogRecoveryCallback::PointInTimeReason)
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143283 d Backup           BackupExe_LogRecoveryCallback.cpp(00071) : Point in time reached LogPos = 0x4e812042580 Time = 2023-06-17 13:59:42.293159 reason = point in time reached
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143301 d Backup           BackupExe_LogRecoveryCallback.cpp(00078) : Slave position reached: 0x38c9a2084 at volume 2
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143348 a Backup           BackupMgr_Client.cpp(00862) : Enter virtual void Backup::BackupMgr_Client::sendRequest(const Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143696 a Backup           BackupMgr_Manager.cpp(00503) : Enter virtual void Backup::BackupMgr_Manager::handleRequest(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)
Arg request = (S)SenderHost=sothdXXX0101|SenderPort=30103|(I)Method=9|NextReason=0|NextSlaveCount=1|NextSlaveVolume_0=2|SenderDatabaseId=3|SenderService=1|VolumeID=3|(L)NextReachedPosition=5394781185408|NextSlavePos_0=15243812996|NextTimestamp=1687003182293159|
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143729 a Backup           BackupMgr_Manager.cpp(02927) : Enter void Backup::BackupMgr_Manager::lrcGetNextTarget(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143744 a Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00447) : Enter void Backup::BackupMgr_LogReplayCoordinator::getNextTargetForMaster(DataAccess::LogRecoveryCallback::PointInTimeReason, DataAccess::RedoLogPosition, uint64_t, const ltt::map<unsigned int, long unsigned int>&, Backup::BackupMgrClient_LRCGetNextTargetResponse&)
Arg this = 0x00007f6ea4970b80
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143749 d Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00449) : LRC::getNextTargetForMaster volume: 3, reachedPos: 5394781185408, reachedTime: 1687003182293, Reason: point in time reached
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143754 i Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00473) : Save next slave position 15243812996 for volume 2
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143756 d Backup           BackupMgrLRC_VolumeInfo.hpp(00098) : Setting next target redo log position for volume ID 2 to 15243812996 (current: 15243807747)
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143757 d Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00534) : LRC::getNextTargetForMaster volume: 3, Setting m_finishReplay to 1 because EndTime or LogPos reached. Reason: point in time reached reachedPosition: 5394781185408 youngestMasterPosition: 5394781185408 endOfLogOnSlave: 0
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143764 a Backup           BackupMgrLRC_LogReplayCoordinator.hpp(00318) : Enter void Backup::BackupMgr_LogReplayCoordinator::finalTargetsAvailable()
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143779 a Backup           BackupMgrLRC_LogReplayCoordinator.hpp(00318) : Exit void Backup::BackupMgr_LogReplayCoordinator::finalTargetsAvailable()(15usec)
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143781 a Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00447) : Exit void Backup::BackupMgr_LogReplayCoordinator::getNextTargetForMaster(DataAccess::LogRecoveryCallback::PointInTimeReason, DataAccess::RedoLogPosition, uint64_t, const ltt::map<unsigned int, long unsigned int>&, Backup::BackupMgrClient_LRCGetNextTargetResponse&)(37usec)
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143782 a Backup           BackupMgr_Manager.cpp(02927) : Exit void Backup::BackupMgr_Manager::lrcGetNextTarget(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)(53usec)
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143785 a Backup           BackupMgr_Manager.cpp(00651) : Return (I)ReturnCode=0|(L)NextTargetTimestamp=1687003182293|(B)FinishReplay=1|
[31734]{-1}[-1/-1] 2023-06-17 19:35:35.143787 a Backup           BackupMgr_Manager.cpp(00651) : Exit virtual void Backup::BackupMgr_Manager::handleRequest(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)(91usec)
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143841 a Backup           BackupMgrLRC_LogReplayCoordinator.hpp(00313) : Exit virtual void Backup::BackupMgr_LogReplayCoordinator::waitForFinalTargets()(39432485usec)
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143850 a Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00190) : Enter virtual DataAccess::RedoLogPosition Backup::BackupMgr_LogReplayCoordinator::getTarget(DataAccess::VolumeID)
Arg this = 0x00007f6ea4970b80
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143856 a Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00190) : Exit virtual DataAccess::RedoLogPosition Backup::BackupMgr_LogReplayCoordinator::getTarget(DataAccess::VolumeID)(6usec)
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143858 d Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00600) : LRC::getNextTargetForSlave volume: 2, next target: 15243812996
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143867 a Backup           BackupMgrLRC_LogReplayCoordinator.cpp(00580) : Exit void Backup::BackupMgr_LogReplayCoordinator::getNextTargetForSlave(DataAccess::LogRecoveryCallback::PointInTimeReason, DataAccess::RedoLogPosition, uint64_t, DataAccess::VolumeID, Backup::BackupMgrClient_LRCGetNextTargetResponse&)(39432518usec)
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143871 a Backup           BackupMgr_Manager.cpp(02927) : Exit void Backup::BackupMgr_Manager::lrcGetNextTarget(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)(39432528usec)
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143874 a Backup           BackupMgr_Manager.cpp(00651) : Return (I)ReturnCode=0|(L)NextTarget=15243812996|(B)FinishReplay=0|
[16899]{-1}[-1/-1] 2023-06-17 19:35:35.143879 a Backup           BackupMgr_Manager.cpp(00651) : Exit virtual void Backup::BackupMgr_Manager::handleRequest(Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)(39432544usec)
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143905 a Backup           BackupMgr_Client.cpp(00862) : Exit virtual void Backup::BackupMgr_Client::sendRequest(const Backup::BackupMgr_Request&, Backup::BackupMgr_Response&)(557usec)
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143919 d Backup           BackupExe_LogRecoveryCallback.cpp(00156) : Calling startFinishLogRecoveryJob
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143922 a Backup           BackupExe_SimpleExecutor.cpp(00680) : Enter void Backup::BackupExe_SimpleExecutor::startFinishLogRecoveryJob()
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143963 a Backup           BackupExe_SimpleExecutor.cpp(00680) : Exit void Backup::BackupExe_SimpleExecutor::startFinishLogRecoveryJob()(41usec)
[32261]{-1}[-1/-1] 2023-06-17 19:35:35.143971 a Backup           BackupExe_LogRecoveryCallback.cpp(00069) : Exit virtual void Backup::BackupExe_LogRecoveryCallback::recoveryPointInTimeReached(DataAccess::RedoLogPosition, const ltt::map<unsigned int, long unsigned int>&, uint64_t, DataAccess::LogRecoveryCallback::PointInTimeReason)(713usec)
[31801]{-1}[-1/-1] 2023-06-17 19:35:35.144047 a Backup           BackupExe_SimpleExecutor.cpp(00690) : Enter void Backup::BackupExe_SimpleExecutor::finishLogRecovery()
[31801]{-1}[-1/-1] 2023-06-17 19:35:35.144065 i PersistenceManag PersistenceManagerSPI.cpp(01162) : Notify RedoHandler listener about new state: 0
[31801]{-1}[-1/-1] 2023-06-17 19:35:35.144081 i CSARedo          RedoMerge.cpp(02933) : Cancel ongoing merges that are not ready to be committed

[31801]{-1}[-1/-1] 2023-06-17 19:35:35.144086 i PersistenceManag PersistenceManagerSPI.cpp(01182) : Notification of RedoHandler listener finished
[31801]{-1}[-1/-1] 2023-06-17 19:35:35.144103 i Logger           RecoveryHandlerImpl.cpp(01910) : Finishing log recovery, waiting for in-process and in-load segments
[32280]{-1}[-1/-1] 2023-06-17 19:35:35.144152 i Logger           RecoveryHandlerImpl.cpp(03144) : LogRecovery:  no further point in time, stopping (pointInTime=0x0, pos=0x4e812042580 reason=point in time reached)
[32280]{-1}[-1/-1] 2023-06-17 19:35:35.144187 w Logger           RecoveryHandlerImpl.cpp(02681) : Log ends at 0x4e812042580, cannot recover until 0x0 (inexact)
[32280]{-1}[-1/-1] 2023-06-17 19:35:35.144401 i Logger           RecoveryHandlerImpl.cpp(04290) : Signaling finish wait barrier
[31801]{-1}[-1/-1] 2023-06-17 19:35:35.144741 i Logger           RecoveryHandlerImpl.cpp(01913) : Finish wait barrier signaled
[31801]{-1}[-1/-1] 2023-06-17 19:35:35.145073 i Logger           RecoveryHandlerImpl.cpp(01941) : Wait for recovery queue threads
[32275]{-1}[-1/-1] 2023-06-17 19:35:35.146387 a Backup           BackupExe_LogRecoveryCallback.cpp(00069) : Enter virtual void Backup::BackupExe_LogRecoveryCallback::recoveryPointInTimeReached(DataAccess::RedoLogPosition, const ltt::map<unsigned int, long unsigned int>&, uint64_t, DataAccess::LogRecoveryCallback::PointInTimeReason)
[32275]{-1}[-1/-1] 2023-06-17 19:35:35.146393 d Backup           BackupExe_LogRecoveryCallback.cpp(00071) : Point in time reached LogPos = 0x4e812042580 Time = 2023-06-17 13:59:42.293159 reason = end of log
[32275]{-1}[-1/-1] 2023-06-17 19:35:35.146406 d Backup           BackupExe_LogRecoveryCallback.cpp(00078) : Slave position reached: 0x38c9a2084 at volume 2
[32275]{-1}[-1/-1] 2023-06-17 19:35:35.146407 d Backup           BackupExe_LogRecoveryCallback.cpp(00085) : pointInTimeReached-callback ignored because isFinishReplay has been set before
[32275]{-1}[-1/-1] 2023-06-17 19:35:35.146409 a Backup           BackupExe_LogRecoveryCallback.cpp(00069) : Exit virtual void Backup::BackupExe_LogRecoveryCallback::recoveryPointInTimeReached(DataAccess::RedoLogPosition, const ltt::map<unsigned int, long unsigned int>&, uint64_t, DataAccess::LogRecoveryCallback::PointInTimeReason)(22usec)
[31801]{-1}[-1/-1] 2023-06-17 19:35:35.150168 i Logger           RecoveryHandlerImpl.cpp(01948) : Recovery finished at log position 0x4e812042580

SAP HANA DB Version 2.0

point-in-time , KBA , HAN-DB-BAC , SAP HANA Backup & Recovery , Problem