Expired backup image on disk are note deleted via cleanup process

[felix_nguyen]

Hi,

we have two independent NBU landscape (each consisting of 1x master / 1x media). Both landscapes are configured in the same way and have the same NBU version installed. Services are also running under the same account and the permissions set on the folder for the basic disk are also the same.

I checked the logs in the log folder bpdbm for errors but found nothing interesting.

But I am encountering the issue that expired backup images on basic disk aren't deleted after "bpexpdate -backupid xyz -d 0" and after the clean up process in one of our NBU landscape. This issue doesn't occure in the other NBU landscape.

Can you please advise?

Regards

Felix

[Marianne]

Your description differs from the subject.

In the subject line you say that "Expired backup image on tape are note deleted"

In the body of the post you then talk about  basic disk.

Which one is it?

To troubleshoot image cleanup on disk, you need bpdm log on the media server.
bpdbm will log image info, not disk cleanup.

[felix_nguyen]

You are absolutely right. My issue is occuring on disk based storage units.

[Marianne]

Then check bpdm log on the media server as per my previous post.

[felix_nguyen]

I checked the bpdm logs and there were no error messages or anything pointing to a problem.

The cleanup process itself completes successfully according to the activity console.

Do I have to search for a certain log entry which isn't suspicious?

.

[Marianne]

Check details tab of Image Cleanup job to find the time that this image was removed.

Check same period in bpdm log.

You may need to increase logging levels for bpdbm on the master and bpdm on the media server.

You can also try to issue 'nbdelete -allvolumes' on the master and then check logs on the master and media server.

[felix_nguyen]

I increase the logging level on master and media server and checked the logs but the only suspicious line is:

db_error_add_to_file: initial volume D:\FS: Kbytes total capacity: 2341861372, used space: 30224820, free space: 2311636552

And I am not sure what that line should tell me besides the capacity and space details of the volume.

[Marianne]

That line does not indicate a problem.

Are you 100% sure that the images have indeed expired?

Can you show us in bpdbm log or in Image Cleanup job one image-id that has expired / cleaned up and not subsequently deleted from disk?

[felix_nguyen]

I am pretty sure that the image has been expired because I executed the command "bpexpdate -backupid xyz -d 0".

Bpdbm log:

11:27:54.491 [5820.3140] <2> image_db: Q_IMAGE_UPDATE_AND_CHGEXP
11:27:54.491 [5820.3140] <2> DbmOdbcConnect::DbmOdbcConnect: ENTERING
11:27:54.491 [5820.3140] <2> read_legacy_touch_file: Found C:\Program Files\Veritas\NetBackupDB\data\vxdbms.conf; requested from (vxdbms_conf.cpp.1529).
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::initialize_odbc: Connecting with <DRIVER=NB SQL Anywhere;PROWS=1000;PBUF=8m;CS=utf8;UID=DBM_MAIN;PWD=***************;LINKS=shmem,tcpip{PORT=13785};ServerName=NB_MASTER_SERVER;DBN=NBDB;CON=DBM_5820_1>
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::setIsolationLevel: (-1) Isolation Level=<32> (SNAPSHOT)
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (-1.1) Executing "SELECT @@SPID" Bindings <>
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (-1.1) ConnectionId = '3746'
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::set_connection_id: -1 -> 3746
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.1) Created
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::isConnected: (3746.1) Executing "SELECT 'connection_test'" Bindings <>
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::isConnected: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.1) Exiting
11:27:54.772 [5820.3140] <2> persistent_queries: Q_IMAGE_CHGEXP
11:27:54.772 [5820.3140] <2> ImageQueryBase::init: Query retry <10>, delay <10> sec
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::setIsolationLevel: (3746) Isolation Level=<4> (REPEATABLE_READ)
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::beginTransaction: (3746) transaction started
11:27:54.772 [5820.3140] <2> ImageExpdateBackupId::ImageExpdateBackupId: Entering
11:27:54.772 [5820.3140] <2> ImageExpdateBackupId::executeQuery: Entering
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.2) Created
11:27:54.772 [5820.3140] <2> build_DBM_Unique_Image_Info(imageRec): Entering
11:27:54.772 [5820.3140] <2> parse_backup_id: parsing backupid = SYSTEM_TO_BACKUP_1469697963
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.3) Created
11:27:54.772 [5820.3140] <2> queryMachineKey: (3746.3) Executing "SELECT machine.ParentKey FROM EMM_Main.EMM_MachineAlias mAlias WITH (READUNCOMMITTED) JOIN (SELECT MachineKey, ParentKey FROM EMM_Main.EMM_Machine WITH (READUNCOMMITTED)) AS machine on machine.MachineKey = mAlias.MachineKey WHERE mAlias.MachineNbuType IN (3, 5) AND UPPER(mAlias.MachineAliasName) = UPPER(?) FOR READ ONLY" Bindings <'MASTER_SERVER.euro.pilkington.net'>
11:27:54.772 [5820.3140] <2> queryMachineKey: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> queryMachineKey: (3746.3) key for MASTER_SERVER.euro.pilkington.net MachineType 3 = '1000002'
11:27:54.772 [5820.3140] <2> getMasterServerKey: Got machine key 1000002 for master server MASTER_SERVER.euro.pilkington.net
11:27:54.772 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.3) Exiting
11:27:54.772 [5820.3140] <2> DbmImage::get_image_key: Entering
11:27:54.772 [5820.3140] <2> DbmImage::get_DBM_ImageKey: (3746.2) Executing "SELECT ImageKey FROM DBM_Main.DBM_Image Image WITH (XLOCK) LEFT OUTER JOIN DBM_Main.DBM_ClientAlias Alias ON Alias.ClientKey = Image.ClientKey WHERE (Image.MasterServerKey = ?) AND ((Alias.MasterServerKey = Image.MasterServerKey) OR (Alias.MasterServerKey IS NULL)) AND ((Alias.ClientAliasName = LOWER(?)) OR (Alias.ClientAliasName IS NULL AND Image.ClientMachineName = ?)) AND (BackupTime = ?) AND (ViewID = ?)" Bindings <1000002, 'SYSTEM_TO_BACKUP', 'SYSTEM_TO_BACKUP', 1469697963, 0>
11:27:54.772 [5820.3140] <2> DbmImage::get_DBM_ImageKey: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> DbmImage::get_DBM_ImageKey: (3746.2) imageKey = '50696'
11:27:54.772 [5820.3140] <2> get_DBM_Image(PK): Entering
11:27:54.772 [5820.3140] <2> get_DBM_Image(PK): (3746.2) Executing "SELECT...FROM DBM_Main.DBM_Image AS Image WITH (XLOCK) WHERE ImageKey = ?" Bindings <50696>
11:27:54.772 [5820.3140] <2> get_DBM_Image(PK): SQL_SUCCESS
11:27:54.772 [5820.3140] <2> fetch_DBM_Image: (3746.2) Fetched Image: ImageKey=50696, MasterServerKey=1000002, PreviousBackupImageKey=0, ParentImageKey=0, CatArcImageKey=0, FullBackupImageKey=0, CSScheduleKey=0, ClientMachineName='SYSTEM_TO_BACKUP', ClientKey=11, PolicyName='Test', BackupTime=1469697963, ViewID=0, ScheduleType=0, ClientType=13, ProtocolVersion=13, StartTime=0, EndTime=0, SnapTime=0, KiloBytes=1532, NumberFragments=1, NumberCopies=1, NumberSnapshotDevices=0, ImageVersion=12, RetentionLevel=10, Compression=0, Encryption=0, FilesFileCompressed=0, Mpx=0, TirInfo=0, TirExpiration=0, PrimaryCopy=1, ImageType=0, ElapsedTime=47, Expiration=1469784363, NumberFiles=1, ExtSecInfo=0, RequestPID=0, IndividualFileRestoreFromRaw=0, ImageDumpLevel=0, FileSystemOnly=0, PrevBlkIncrTime=0, BlkIncrFullTime=0, StreamNumber=0, BackupCopy=0, BackupStatus=0, JobID=66230, NumResumes=0, ResumeExpiration=0, PfiType=0, ImageAttribute=0, Creator='roo
11:27:54.772 [5820.3140] <2> fetch_DBM_Image: t', ScheduleName='Full', ProxyClient='', KeywordPhrase='', FilesFile='Test_1469697963_FULL.f', FilesFileSize=820, SoftwareVersion='', ObjectDescriptor='', EstimatedKiloBytes=0, VmType=0, IsSynthetic=0, RunTime=1469697963, LastBirthTime=1469697963, ClientCharacterSet=1, BmrInfo=1, OriginMasterServer='', OriginMasterServerID='0x00000000000000000000000000000000', StorageServiceName='', StorageServiceState=0, StorageServiceIndexOffset=0, TimeInProcess=0, ClassificationID='', StorageServiceVersionNumber=0, RequiredExpirationDate=0, ImportFromReplicaTime=0, IrEnabled=0, IsQuiesced=1, SLPOperationsMask=255, IsScheduled=1, HasDependees=0, HasDependents=0, ValidationCount=0, ExpirationCount=0, IndexingStatus=0, NumChildren=0, ImageFlags=0, StorageServiceIsInactive=0, DumpHost='', KiloBytesDataTransferred=0
11:27:54.772 [5820.3140] <2> image_copy_to_expdate: Checking backupid SYSTEM_TO_BACKUP_1469697963, copy 1 for expiration, slp_managed= 0, slp_complete = 1, no_validation= 0, newdate= 0, callmm t
11:27:54.772 [5820.3140] <2> expdate_image: Entering
11:27:54.772 [5820.3140] <2> duplication_in_progress: C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\Test_1469697963_FULL.cpy does not exist
11:27:54.772 [5820.3140] <2> get_PEM_Policy_DiscoveryClient: Entering
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.4) Created
11:27:54.772 [5820.3140] <2> getMasterServerKey: Cached Key 1000002 for master server MASTER_SERVER.euro.pilkington.net
11:27:54.772 [5820.3140] <2> get_PEM_Policy_DiscoveryClient: (3746.4) Executing "SELECT P.DiscoveryClient FROM PEM_Main.PEM_Policy P JOIN PEM_Main.PEM_Discovery D ON D.PolicyKey = P.PolicyKey JOIN PEM_Main.PEM_CSSchedule C ON C.DiscoveryKey = D.DiscoveryKey JOIN DBM_Image I on I.CSScheduleKey = C.CSScheduleKey JOIN DBM_ClientAlias CA ON I.ClientKey = CA.ClientKey WHERE CA.MasterServerKey = I.MasterServerKey AND CA.ClientAliasName = LOWER('SYSTEM_TO_BACKUP') AND I.BackupTime = 1469697963 AND I.MasterServerKey = 1000002" Bindings <>
11:27:54.772 [5820.3140] <2> get_PEM_Policy_DiscoveryClient: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> get_PEM_Policy_DiscoveryClient: (3746.4) No more data for query
11:27:54.772 [5820.3140] <2> get_PEM_Policy_DiscoveryClient: Image not found in DBM_Image with MasterServerKey = 1000002 ClientMachineName = SYSTEM_TO_BACKUP BackupTime = 1469697963
11:27:54.772 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.4) Exiting
11:27:54.772 [5820.3140] <2> delete_copy: Entering
11:27:54.772 [5820.3140] <2> DbmImageCopy::get_copy_fragment_list_by_image_key: Entering
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.5) Created
11:27:54.772 [5820.3140] <2> DbmImageCopy::get_copy_fragment_list_by_image_key: (3746.5) Executing "SELECT...FROM DBM_MAIN.DBM_ImageCopy Copy WITH (XLOCK) WHERE Copy.ImageKey = ? AND Copy.CopyNumber = ? ORDER BY CopyNumber" Bindings <50696, 1>
11:27:54.772 [5820.3140] <2> DbmImageCopy::get_copy_fragment_list_by_image_key: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> fetch_DBM_ImageCopy: (3746.5) Fetched Copy: ImageCopyKey=40866, ImageKey=50696, CopyNumber=1, SLPIndex=0, CopyType=0, ExpireTime=1469784363, MpxState=0, RetentionLevel=65546, CopyDate=1469698010, DataFormat=1, KMSKeyTag='', TryToKeepTime=0, Residence='', CopyState=0, JobID=66230, ExpirationType=0, RetryCount=0, LastRetryTime=0, LifecycleDestinationTag='', SLPSourceIndex=0, DeferredDuplicationTime=0, ExpireLifecycleTime=0, IsReplica=0, MirrorParent=0, Hold=0, Resumable=0, ValidationCount=0, ExpirationCount=0
11:27:54.772 [5820.3140] <2> fetch_DBM_ImageCopy: (3746.5) No more data for query
11:27:54.772 [5820.3140] <2> DbmImageFragment::get_fragment_list_by_image_copy_key: Entering
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.6) Created
11:27:54.772 [5820.3140] <2> DbmImageFragment::get_fragment_list_by_image_copy_key: (3746.6) Executing "SELECT...FROM DBM_Main.DBM_ImageFragment Frag WITH (XLOCK) WHERE Frag.ImageCopyKey = ? ORDER BY FragmentNumber" Bindings <40866>
11:27:54.772 [5820.3140] <2> DbmImageFragment::get_fragment_list_by_image_copy_key: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> fetch_DBM_ImageFragments: (.6) Fragment {IFK=60641, IK=50696, ICK=40866, CN=1, FN=1, RC=0, MID='D:\FS', MSK=1000004, SUT=0, SST=1, FS=1, FSZ=1568768, FID='D:\FS\SYSTEM_TO_BACKUP_1469697963_C1_F1', D=0, FN=0, BS=262144, O=0, MD=0, DWO=-1, FF=0, MD='MEDIA_SERVER.euro.pilkington.net', FCP=0, MSN=0, ME='', SCMH=''}
11:27:54.772 [5820.3140] <2> fetch_DBM_ImageFragments: (.6) No more fragments
11:27:54.772 [5820.3140] <2> DbmImageFragment::get_fragment_list_by_image_copy_key: fragmentCount = 1
11:27:54.772 [5820.3140] <2> DbmImageCopy::get_copy_fragment_list_by_image_key: copyCount = 1, realCopyCount = 1, rc = 0
11:27:54.772 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.6) Exiting
11:27:54.772 [5820.3140] <2> change_fragment_to_be_deleted_state: Entering: isLastUnexpiredCopy= 1
11:27:54.772 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.7) Created
11:27:54.772 [5820.3140] <2> DiskDeleteableEx: diskDeleteable is yes for copy 1, frag 1, stutype 0, stusubtype 1, pfi 0, mediadesc MEDIA_SERVER.euro.pilkington.net, do not delete flag false
11:27:54.772 [5820.3140] <2> insert_DBM_DeletedImageFragment: Entering
11:27:54.772 [5820.3140] <2> insert_DBM_DeletedImageFragment: (3746.7) Executing "INSERT INTO DBM_Main.DBM_DeletedImageFragment (MasterServerKey, ClientMachineName, PolicyName, BackupTime, ScheduleType, ClientType, CopyNumber, FragmentNumber, ResumeCount, MediaID, FragmentID, MediaDescription, CopyExpireTime, CopyDataFormat, CopyExpirationType, MediaServerKey, StorageUnitType, StuSubType, DeleteHeader, SnapshotClientMountHost, ImportMetaDataKey, FragmentSize ) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)" Bindings <1000002, 'SYSTEM_TO_BACKUP', 'Test', 1469697963, 0, 13, 1, 1, 0, 'D:\FS', 'D:\FS\SYSTEM_TO_BACKUP_1469697963_C1_F1', 'MEDIA_SERVER.euro.pilkington.net', 1469698074, 1, 0, 1000004, 0, 1, 1, '', 0, 1568768>
11:27:54.772 [5820.3140] <2> insert_DBM_DeletedImageFragment: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> insert_DBM_DeletedImageFragment: MasterServerKey = < 1000002 > ClientMachineName = < SYSTEM_TO_BACKUP > PolicyName = < Test > BackupTime = < 1469697963 > ScheduleType = < 0 > ClientType = < 13 > CopyNumber = < 1 > FragmentNumber = < 1 > ResumeCount = < 0 > MediaID = < D:\FS > FragmentID = < D:\FS\SYSTEM_TO_BACKUP_1469697963_C1_F1 > MediaDescription = < MEDIA_SERVER.euro.pilkington.net > CopyExpireTime = < 1469698074 > CopyDataFormat = < 1 > CopyExpirationType = < 0 > MediaServerKey = < 1000004 > StorageUnitType = < 0 > StuSubType = < 1 > DeleteHeader = < 1 > SnapshotClientMountHost = <  > FragmentSize = < 1568768 >
11:27:54.772 [5820.3140] <2> insert_DBM_DeletedImageFragment: (3746.7) Executing "SELECT @@Identity" Bindings <>
11:27:54.772 [5820.3140] <2> insert_DBM_DeletedImageFragment: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> insert_DBM_DeletedImageFragment: (3746.7) DeletedImageFragmentKey = '1719'
11:27:54.772 [5820.3140] <2> delete_DBM_ImageFragment(PK): Entering
11:27:54.772 [5820.3140] <2> delete_DBM_ImageFragment(PK): (3746.7) Executing "DELETE FROM DBM_Main.DBM_ImageFragment WHERE ImageFragmentKey = ?" Bindings <60641>
11:27:54.772 [5820.3140] <2> delete_DBM_ImageFragment(PK): SQL_SUCCESS
11:27:54.772 [5820.3140] <2> delete_DBM_ImageCopy(PK): (3746.5) Executing "DELETE FROM DBM_Main.DBM_ImageReplicationDestination WHERE DBM_ImageReplicationDestination.ImageCopyKey = ?" Bindings <40866>
11:27:54.772 [5820.3140] <2> delete_DBM_ImageCopy(PK): SQL_NO_DATA_FOUND
11:27:54.772 [5820.3140] <2> delete_DBM_ImageCopy(PK): (3746.5) Executing "DELETE FROM DBM_Main.DBM_ImageCopy WHERE ImageCopyKey = ?" Bindings <40866>
11:27:54.772 [5820.3140] <2> delete_DBM_ImageCopy(PK): SQL_SUCCESS
11:27:54.772 [5820.3140] <2> delete_DBM_ImageCopy(PK): Success deleting ImageCopyKey = 40866
11:27:54.772 [5820.3140] <2> reconcile_image_with_deleted_copies: Entering
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: Entering
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: (3746.2) Executing "SELECT COUNT(*) FROM DBM_Main.DBM_ImageCopy WHERE ImageKey = ?  FOR READ ONLY" Bindings <50696>
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: (3746.2) Copy Count = '0'
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: (3746.2) Executing "SELECT COUNT(*) FROM DBM_Main.DBM_ImageFragment WHERE ImageKey = ?  FOR READ ONLY" Bindings <50696>
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: (3746.2) Fragment Count = '0'
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: (3746.2) Executing "SELECT COUNT(*) FROM DBM_Main.DBM_SnapReplica WHERE ImageKey = ?  FOR READ ONLY" Bindings <50696>
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> calculate_copy_fragment_snapdev_counts: (3746.2) Snapdev Count = '0'
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::commitTransaction: (3746) success - view count 3
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::beginTransaction: (3746) transaction started
11:27:54.772 [5820.3140] <2> delete_image_from_catalog_real: ImageKey <50696>
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::commitTransaction: (3746) success - view count 3
11:27:54.772 [5820.3140] <2> DbmOdbcConnect::beginTransaction: (3746) transaction started
11:27:54.772 [5820.3140] <2> DbmImage::lock_image_hierarchy: (3746.2) Executing "SELECT ImageKey FROM DBM_Main.DBM_Image WITH (XLOCK) WHERE ImageKey = 50696" Bindings <>

[felix_nguyen]

11:27:54.772 [5820.3140] <2> DbmImage::lock_image_hierarchy: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> DbmImage::lock_image_hierarchy: (3746.2) imageKey = '50696'
11:27:54.772 [5820.3140] <2> DbmImage::lock_image_hierarchy: (3746.2) Executing "SELECT ImageKey FROM DBM_Main.DBM_Image WITH (XLOCK) WHERE ParentImageKey = 50696" Bindings <>
11:27:54.772 [5820.3140] <2> DbmImage::lock_image_hierarchy: SQL_SUCCESS
11:27:54.772 [5820.3140] <2> DbmImage::lock_image_hierarchy: (3746.2) No more data for query
11:27:54.772 [5820.3140] <2> DbmImage::lock_image_hierarchy: Locked all parent/child images
11:27:54.772 [5820.3140] <2> get_DBM_Image(PK): Entering
11:27:54.772 [5820.3140] <2> get_DBM_Image(PK): (3746.2) Executing "SELECT...FROM DBM_Main.DBM_Image AS Image WITH (XLOCK) WHERE ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> get_DBM_Image(PK): SQL_SUCCESS
11:27:54.788 [5820.3140] <2> fetch_DBM_Image: (3746.2) Fetched Image: ImageKey=50696, MasterServerKey=1000002, PreviousBackupImageKey=0, ParentImageKey=0, CatArcImageKey=0, FullBackupImageKey=0, CSScheduleKey=0, ClientMachineName='SYSTEM_TO_BACKUP', ClientKey=11, PolicyName='Test', BackupTime=1469697963, ViewID=0, ScheduleType=0, ClientType=13, ProtocolVersion=13, StartTime=0, EndTime=0, SnapTime=0, KiloBytes=1532, NumberFragments=1, NumberCopies=1, NumberSnapshotDevices=0, ImageVersion=12, RetentionLevel=10, Compression=0, Encryption=0, FilesFileCompressed=0, Mpx=0, TirInfo=0, TirExpiration=0, PrimaryCopy=1, ImageType=0, ElapsedTime=47, Expiration=1469784363, NumberFiles=1, ExtSecInfo=0, RequestPID=0, IndividualFileRestoreFromRaw=0, ImageDumpLevel=0, FileSystemOnly=0, PrevBlkIncrTime=0, BlkIncrFullTime=0, StreamNumber=0, BackupCopy=0, BackupStatus=0, JobID=66230, NumResumes=0, ResumeExpiration=0, PfiType=0, ImageAttribute=0, Creator='roo
11:27:54.788 [5820.3140] <2> fetch_DBM_Image: t', ScheduleName='Full', ProxyClient='', KeywordPhrase='', FilesFile='Test_1469697963_FULL.f', FilesFileSize=820, SoftwareVersion='', ObjectDescriptor='', EstimatedKiloBytes=0, VmType=0, IsSynthetic=0, RunTime=1469697963, LastBirthTime=1469697963, ClientCharacterSet=1, BmrInfo=1, OriginMasterServer='', OriginMasterServerID='0x00000000000000000000000000000000', StorageServiceName='', StorageServiceState=0, StorageServiceIndexOffset=0, TimeInProcess=0, ClassificationID='', StorageServiceVersionNumber=0, RequiredExpirationDate=0, ImportFromReplicaTime=0, IrEnabled=0, IsQuiesced=1, SLPOperationsMask=255, IsScheduled=1, HasDependees=0, HasDependents=0, ValidationCount=0, ExpirationCount=0, IndexingStatus=0, NumChildren=0, ImageFlags=0, StorageServiceIsInactive=0, DumpHost='', KiloBytesDataTransferred=0
11:27:54.788 [5820.3140] <2> delete_image_files: Entering
11:27:54.788 [5820.3140] <2> lock_file_by_path: Acquired db_Imglock(WRITE) 660 in C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\Test_1469697963_FULL.lck
11:27:54.788 [5820.3140] <2> delete_image_files: Deleting C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\Test_1469697963_FULL.f
11:27:54.788 [5820.3140] <2> db_ImgUnlock: db_ImgUnlock(660) unlocked
11:27:54.788 [5820.3140] <2> delete_image_files: Didn't find C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\Test_1469697963_FULL.f.nblbc
11:27:54.788 [5820.3140] <2> delete_image_files: Didn't find C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\Test_1469697963_FULL.f.ctrl
11:27:54.788 [5820.3140] <2> delete_image_files: Didn't find C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\Test_1469697963_FULL
11:27:54.788 [5820.3140] <2> image_path_tmp_r:
11:27:54.788 [5820.3140] <2> delete_image_files: Didn't find C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\tmp\Test_1469697963_FULL.cpy
11:27:54.788 [5820.3140] <2> image_path_tmp_r:
11:27:54.788 [5820.3140] <2> delete_image_files: Didn't find C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\tmp\Test_1469697963_FULL
11:27:54.788 [5820.3140] <2> delete_image_files: Didn't find C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\Test_1469697963_FULL
11:27:54.788 [5820.3140] <2> image_path_tmp_r:
11:27:54.788 [5820.3140] <2> delete_image_files: Didn't find C:\Program Files\Veritas\NetBackup\db\images\SYSTEM_TO_BACKUP\1469000000\tmp\Test_1469697963_FULL.imprt
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): Entering
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "IF EXISTS (SELECT 1 FROM DBM_Main.DBM_Image WITH (READUNCOMMITTED) WHERE PreviousBackupImageKey = 50696 OR ParentImageKey = 50696 OR CatArcImageKey = 50696 OR FullBackupImageKey = 50696 ) THEN SELECT 1 ELSE SELECT 0 ENDIF" Bindings <>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_SUCCESS
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Image is referenced = '0'
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_DRCriticalPolicy FROM DBM_Main.DBM_DRMedia WHERE DBM_DRCriticalPolicy.DRMediaKey = DBM_DRMedia.DRMediaKey AND DBM_DRMedia.ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_DRMedia WHERE DBM_DRMedia.ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_ImageReplicationDestination WHERE DBM_ImageReplicationDestination.ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_SnapReplica WHERE DBM_SnapReplica.ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_ImageFragment WHERE ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_ImageCopy WHERE ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_VMwareImage WHERE ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_XbsaImage WHERE ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "SELECT isnull(CSScheduleKey, 0) AS CSScheduleKey FROM DBM_Main.DBM_Image WHERE ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_SUCCESS
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) CSScheduleKey = '0'
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): (3746.2) Executing "DELETE FROM DBM_Main.DBM_Image WHERE ImageKey = ?" Bindings <50696>
11:27:54.788 [5820.3140] <2> delete_DBM_Image(PK): SQL_SUCCESS
11:27:54.788 [5820.3140] <2> log_image_event_in_NBDB: Entering
11:27:54.788 [5820.3140] <2> getMasterServerKey: Cached Key 1000002 for master server MASTER_SERVER.euro.pilkington.net
11:27:54.788 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.8) Created
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: (3746.8) Executing "UPDATE DBM_MAIN.DBM_ImageChangeLog SET CreatedDateTime = CAST(CURRENT UTC TIMESTAMP AS TIMESTAMP) , OperationID = 3 WHERE (MasterServerKey = 1000002) AND (ClientMachineName = 'SYSTEM_TO_BACKUP') AND (BackupTime = 1469697963) AND (ClientType = 13) AND (OperationID = 2)" Bindings <>
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: (3746.8) Executing "UPDATE DBM_MAIN.DBM_ImageChangeLog SET CreatedDateTime = CAST(CURRENT UTC TIMESTAMP AS TIMESTAMP)  WHERE (MasterServerKey = 1000002) AND (ClientMachineName = 'SYSTEM_TO_BACKUP') AND (BackupTime = 1469697963) AND (ClientType = 13) AND (OperationID = 3)" Bindings <>
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> insert_DBM_ImageChangeLog: Entering
11:27:54.788 [5820.3140] <2> insert_DBM_ImageChangeLog: (3746.8) Executing "INSERT INTO DBM_MAIN.DBM_ImageChangeLog (MasterServerKey, ClientMachineName, BackupTime, ClientType, OperationID) VALUES (1000002, 'SYSTEM_TO_BACKUP', 1469697963, 13, 3)" Bindings <>
11:27:54.788 [5820.3140] <2> insert_DBM_ImageChangeLog: SQL_SUCCESS
11:27:54.788 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.8) Exiting
11:27:54.788 [5820.3140] <2> log_image_event_in_NBDB: Entering
11:27:54.788 [5820.3140] <2> getMasterServerKey: Cached Key 1000002 for master server MASTER_SERVER.euro.pilkington.net
11:27:54.788 [5820.3140] <2> DbmOdbcView::DbmOdbcView: (3746.9) Created
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: (3746.9) Executing "UPDATE DBM_MAIN.DBM_ImageChangeLog SET CreatedDateTime = CAST(CURRENT UTC TIMESTAMP AS TIMESTAMP) , OperationID = 3 WHERE (MasterServerKey = 1000002) AND (ClientMachineName = 'SYSTEM_TO_BACKUP') AND (BackupTime = 1469697963) AND (ClientType = 13) AND (OperationID = 2)" Bindings <>
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: SQL_NO_DATA_FOUND
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: (3746.9) Executing "UPDATE DBM_MAIN.DBM_ImageChangeLog SET CreatedDateTime = CAST(CURRENT UTC TIMESTAMP AS TIMESTAMP)  WHERE (MasterServerKey = 1000002) AND (ClientMachineName = 'SYSTEM_TO_BACKUP') AND (BackupTime = 1469697963) AND (ClientType = 13) AND (OperationID = 3)" Bindings <>
11:27:54.788 [5820.3140] <2> update_DBM_ImageChangeLog: SQL_SUCCESS
11:27:54.788 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.9) Exiting
11:27:54.788 [5820.3140] <2> DbmOdbcConnect::commitTransaction: (3746) success - view count 3
11:27:54.788 [5820.3140] <2> Orb::init: Enabling ORBNativeCharCodeSet UTF-8(Orb.cpp:716)
11:27:54.788 [5820.3140] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -ORBSvcConfDirective "static Resource_Factory '-ORBNativeCharCodeSet UTF-8'" -ORBSvcConfDirective "static PBXIOP_Factory '-enable_keepalive'" -ORBSvcConfDirective "static EndpointSelectorFactory ''" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory PBXIOP_Factory'" -ORBSvcConfDirective "static Resource_Factory '-ORBProtocolFactory IIOP_Factory'" -ORBDefaultInitRef '' -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_CLIENT_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:927)
11:27:54.788 [5820.3140] <2> Orb::init: caching EndpointSelectorFactory(Orb.cpp:941)
11:27:54.788 [5820.3140] <2> vnet_get_pref_netconnection: [vnet_addrinfo.c:4720] Local [strong] check, using interface  ANY
11:27:54.803 [5820.3140] <2> DbmOdbcConnect::beginTransaction: (3746) transaction started
11:27:54.803 [5820.3140] <2> expdate_image: expdate_image sendNotification(image) returns 0
11:27:54.803 [5820.3140] <2> DbmOdbcConnect::commitTransaction: (3746) success - view count 3
11:27:54.803 [5820.3140] <2> DbmOdbcConnect::beginTransaction: (3746) transaction started
11:27:54.803 [5820.3140] <2> image_copy_to_expdate: changing expiration time for backupid SYSTEM_TO_BACKUP_1469697963, copy 1 to 0 (forced= no): status= 0
11:27:54.803 [5820.3140] <4> db_error_add_to_file: successfully modified backupid SYSTEM_TO_BACKUP_1469697963
11:27:54.803 [5820.3140] <4> ImageExpdateBackupId::executeQuery: successfully modified backupid SYSTEM_TO_BACKUP_1469697963
11:27:54.803 [5820.3140] <2> ImageExpdateBackupId::~ImageExpdateBackupId: Exiting
11:27:54.803 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.2) Exiting
11:27:54.803 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.5) Exiting
11:27:54.803 [5820.3140] <2> DbmOdbcView::~DbmOdbcView: (3746.7) Exiting
11:27:54.803 [5820.3140] <2> DbmOdbcConnect::commitTransaction: (3746) success - view count 0
11:27:54.803 [5820.3140] <2> persistent_queries: request complete: exit status 0  ; query type: 87
11:27:54.819 [5820.3140] <2> read_next_image: calling db_IMAGEreceive() for next image
11:27:54.819 [5820.3140] <2> isDONE: reply DONE 0 <?xml version="1.0" encoding="utf-8"?><StatusMsgDoc><StatusMsg NBUStatus="0" Severity="0" VXULoid="271" VXULtid="0"><MsgString>the&#32;requested&#32;operation&#32;was&#32;successfully&#32;completed</MsgString></StatusMsg></StatusMsgDoc>
11:27:54.819 [5820.3140] <2> read_next_image: db_IMAGEreceive() received 'done' message
11:27:54.819 [5820.3140] <2> DbmOdbcConnect::~DbmOdbcConnect: (3746) Exiting
11:27:54.834 [5820.3140] <2> process_request: request complete: exit status 0  ; query type: 91

[Marianne]

So, is there nothing in bpdm log on MEDIA_SERVER.euro.pilkington.net at more or less 11:27 with a request from the master server to delete D:\FS\SYSTEM_TO_BACKUP_1469697963_C1_F1 ?

Is this file still on the disk?

Can you compare bpdm log on this media server with another media server where image removal is working fine?

[felix_nguyen]

No there is no line where something like "delete_image_disk_sts_impl: file..." is mentioned in the logs where I have the problem.

The other media server shows some lines where it is clear that it delete the backup images on the basic disk.

Unfortunately I don't know why is doesn't do that on the media server (the one with the issue).

[Marianne]

Time to log a Support call with Veritas....

[felix_nguyen]

I have had logged a support call but was hoping that I get some nice tipps in community discussions. :)