Netbackup version 9.1.0.1 on Netbackup appliance 5240 version 4.1.0.1
NDMP backup is running over the network to disk on the appliance, then gets duplicated out to tape later. This is a very large backup and had been running 186 hours at the time of the failure.
We have a "status 150: termination requested by administrator" failure on an NDMP backup. I assumed the other admin did it, he assumed I did it. But neither of us issued a termination.
In the log that I pasted below, I see a bptm error that it could not update the image database to add completed fragment. That is immediately followed by "received abort request from bptm". Could that generate a 150, even though no one explicitly cancelled it?
Mar 10, 2023 5:30:03 PM - Info nbjm (pid=36707) starting backup job (jobid=4928200) for client emedny_nas, policy NYX_PRD_NASPRD_HX_hxDOC, schedule Full_6months_1year
Mar 10, 2023 5:30:03 PM - Info nbjm (pid=36707) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=4928200, request id:{19F581DC-BF93-11ED-845A-0788DD0C0754})
Mar 10, 2023 5:30:03 PM - requesting resource stu_disk_nyxalbnbu001
Mar 10, 2023 5:30:03 PM - requesting resource nyxalbnbu001.NBU_CLIENT.MAXJOBS.emedny_nas
Mar 10, 2023 5:30:03 PM - granted resource nyxalbnbu001.NBU_CLIENT.MAXJOBS.emedny_nas
Mar 10, 2023 5:30:03 PM - granted resource MediaID=@aaaad;DiskVolume=PureDiskVolume;DiskPool=dp_disk_nyxalbnbu001;Path=PureDiskVolume;StorageServer=nyxalbnbu001;MediaServer=nyxalbnbu001
Mar 10, 2023 5:30:03 PM - granted resource stu_disk_nyxalbnbu001
Mar 10, 2023 5:30:19 PM - estimated 68677574774 kbytes needed
Mar 10, 2023 5:30:19 PM - Info nbjm (pid=36707) started backup (backupid=emedny_nas_1678487418) job for client emedny_nas, policy NYX_PRD_NASPRD_HX_hxDOC, schedule Full_6months_1year on storage unit stu_disk_nyxalbnbu001
Mar 10, 2023 5:30:20 PM - started process bpbrm (pid=275946)
Mar 10, 2023 5:30:21 PM - Info bpbrm (pid=275946) emedny_nas is the host to backup data from
Mar 10, 2023 5:30:21 PM - Info bpbrm (pid=275946) reading file list for client
Mar 10, 2023 5:30:21 PM - Info bpbrm (pid=275946) starting ndmpagent on client
Mar 10, 2023 5:30:21 PM - Info ndmpagent (pid=275961) Backup started
Mar 10, 2023 5:30:21 PM - Info bpbrm (pid=275946) bptm pid: 275963
Mar 10, 2023 5:30:21 PM - Info ndmpagent (pid=275961) PATH(s) found in file list = 1
Mar 10, 2023 5:30:21 PM - connecting
Mar 10, 2023 5:30:21 PM - connected; connect time: 0:00:00
Mar 10, 2023 5:30:22 PM - Info ndmpagent (pid=275961) PATH[1 of 1]: /NASPRD_HX/vol5/hxDOC
Mar 10, 2023 5:30:22 PM - Info bptm (pid=275963) start
Mar 10, 2023 5:30:22 PM - Info bptm (pid=275963) using 30 data buffers
Mar 10, 2023 5:30:22 PM - Info bptm (pid=275963) using 262144 data buffer size
Mar 10, 2023 5:30:23 PM - Info bptm (pid=275963) start backup
Mar 10, 2023 5:30:27 PM - begin writing
Mar 10, 2023 5:30:28 PM - Info ndmpagent (pid=275961) NDMP Remote disk
Mar 10, 2023 5:30:29 PM - Info ndmpagent (pid=275961) emedny_nas: Session identifier for Backup : 25081
Mar 10, 2023 5:30:29 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: creating "/NASPRD_HX/vol5/../snapshot_for_backup.1306" snapshot.
Mar 10, 2023 5:30:29 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Using Full Quota Tree Dump
Mar 10, 2023 5:30:30 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Using snapshot_for_backup.1306 snapshot
Mar 10, 2023 5:30:30 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Date of this level 0 dump snapshot: Fri Mar 10 17:49:17 2023.
Mar 10, 2023 5:30:30 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Date of last level 0 dump: the epoch.
Mar 10, 2023 5:30:30 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Dumping /NASPRD_HX/vol5/hxDOC to NDMP connection
Mar 10, 2023 5:30:30 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: mapping (Pass I)[regular files]
Mar 10, 2023 5:53:42 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Reference time for next incremental dump is : Fri Mar 10 17:45:49 2023.
Mar 10, 2023 5:56:52 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: mapping (Pass II)[directories]
Mar 10, 2023 6:00:42 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: estimated 60901780892 KB.
Mar 10, 2023 6:00:42 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: dumping (Pass III) [directories]
Mar 10, 2023 6:01:52 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Fri Mar 10 18:20:40 2023 : We have written 1039157 KB.
Mar 10, 2023 6:06:52 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Fri Mar 10 18:25:40 2023 : We have written 4923406 KB.
Mar 10, 2023 6:11:52 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Fri Mar 10 18:30:40 2023 : We have written 8492798 KB.
..... and many more "we have written" messages .....
Mar 18, 2023 12:18:11 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Sat Mar 18 12:36:58 2023 : We have written 41113871743 KB.
Mar 18, 2023 12:23:11 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Sat Mar 18 12:41:58 2023 : We have written 41146131220 KB.
Mar 18, 2023 12:29:04 PM - Warning bptm (pid=275963) cannot update image database to add completed fragment, error = cannot connect on socket
Mar 18, 2023 12:30:33 PM - Info ndmpagent (pid=275961) Received ABORT request from bptm
Mar 18, 2023 12:30:33 PM - Error ndmpagent (pid=275961) NDMP backup failed, path = /NASPRD_HX/vol5/hxDOC
Mar 18, 2023 12:30:33 PM - Error ndmpagent (pid=275961) emedny_nas: DUMP: Error: Write to socket failed
Mar 18, 2023 12:30:33 PM - Error ndmpagent (pid=275961) emedny_nas: DUMP: Error: DUMP IS ABORTED
Mar 18, 2023 12:30:33 PM - Info ndmpagent (pid=275961) emedny_nas: DUMP: Deleting "/NASPRD_HX/vol5/../snapshot_for_backup.1306" snapshot.
Mar 18, 2023 12:30:33 PM - Error ndmpagent (pid=275961) emedny_nas: DATA: Operation terminated (for /NASPRD_HX/vol5/hxDOC).
Mar 18, 2023 12:30:35 PM - Info bptm (pid=275963) EXITING with status 25 <----------
Mar 18, 2023 12:30:35 PM - Info nyxalbnbu001 (pid=275963) StorageServer=PureDisk:nyxalbnbu001; Report=PDDO Stats (multi-threaded stream used) for (nyxalbnbu001): scanned: 41169971455 KB, CR sent: 32843919228 KB, CR sent over FC: 0 KB, dedup: 20.2%, cache hits: 553727 (0.1%), rebased: 303865 (0.1%), where dedup space saving:16.1%, compression space saving:4.2%
Mar 18, 2023 12:30:46 PM - Info ndmpagent (pid=0) done. status: 150: termination requested by administrator
Mar 18, 2023 12:30:46 PM - end writing; write time: 186:00:19
termination requested by administrator (150)
