Solved: nameless job

Hamzah · ‎12-23-2023

Dears,

Need help in identifying this job

We have this job runs every few days and keep running till we cancel it, it has no name but a job ID,

NetBackup version 8.2

Windows cluster 2016

the jobs detailed status pasted below,

Oct 17, 2023 8:08:39 PM - Info bptm (pid=24192) waited for empty buffer 246084 times, delayed 276048 times

Oct 17, 2023 8:08:39 PM - positioning J71544 to file 13

Oct 17, 2023 8:08:39 PM - positioned J71544; position time: 0:00:00

Oct 17, 2023 8:08:39 PM - begin reading

Oct 17, 2023 10:22:54 PM - Info bptm (pid=24192) waited for empty buffer 274738 times, delayed 297377 times

Oct 17, 2023 10:22:54 PM - end reading; read time: 2:14:15

Oct 17, 2023 10:22:54 PM - positioning J71544 to file 14

Oct 17, 2023 10:22:54 PM - positioned J71544; position time: 0:00:00

Oct 17, 2023 10:22:54 PM - begin reading

Oct 18, 2023 12:36:06 AM - Info bptm (pid=24192) waited for empty buffer 255246 times, delayed 289891 times

Oct 18, 2023 12:36:06 AM - end reading; read time: 2:13:12

Oct 18, 2023 12:36:06 AM - positioning J71544 to file 15

Oct 18, 2023 12:36:06 AM - positioned J71544; position time: 0:00:00

Oct 18, 2023 12:36:06 AM - begin reading

Oct 18, 2023 2:44:42 AM - Info bptm (pid=24192) waited for empty buffer 278977 times, delayed 300485 times

Oct 18, 2023 2:44:42 AM - end reading; read time: 2:08:36

Oct 18, 2023 2:44:42 AM - positioning J71544 to file 16

Oct 18, 2023 2:44:42 AM - positioned J71544; position time: 0:00:00

Oct 18, 2023 2:44:42 AM - begin reading

Oct 18, 2023 4:47:24 AM - Info bptm (pid=24192) waited for empty buffer 250872 times, delayed 275736 times

Oct 18, 2023 4:47:24 AM - end reading; read time: 2:02:42

Oct 18, 2023 4:47:24 AM - positioning J71544 to file 17

Oct 18, 2023 4:47:24 AM - positioned J71544; position time: 0:00:00

Oct 18, 2023 4:47:24 AM - begin reading

Oct 18, 2023 5:15:23 AM - current media J71599 complete, requesting next media Any

Oct 18, 2023 5:15:23 AM - current media -- complete, awaiting next media Any. Waiting for resources. 

          Reason: Drives are in use, Media server: jo00-nbk03, 

          Robot Type(Number): TLD(6), Media ID: N/A, Drive Name: N/A, 

          Volume Pool: duplication3-tapes, Storage Unit: jo00-nbk01-hcart-robot-tld-6, Drive Scan Host: N/A, 

          Disk Pool: N/A, Disk Volume: N/A

Oct 18, 2023 5:17:29 AM - current media -- complete, awaiting next media Any. Waiting for resources. 

          Reason: Media is in use, Media server: jo00-nbk03, 

          Robot Type(Number): TLD(6), Media ID: N/A, Drive Name: N/A, 

          Volume Pool: duplication3-tapes, Storage Unit: jo00-nbk01-hcart-robot-tld-6, Drive Scan Host: N/A, 

          Disk Pool: N/A, Disk Volume: N/A

Oct 18, 2023 7:10:38 AM - Info bptm (pid=20028) Waiting for mount of media id J71599 (copy 2) on server jo00-nbk01.

Oct 18, 2023 7:10:38 AM - started process bptm (pid=20028)

Oct 18, 2023 7:10:38 AM - mounting J71599

Oct 18, 2023 7:10:38 AM - Info bptm (pid=20028) INF - Waiting for mount of media id J71599 on server jo00-nbk01 for writing.

Oct 18, 2023 7:10:38 AM - granted resource  J71599

Oct 18, 2023 7:10:38 AM - granted resource  Drive221

Oct 18, 2023 7:10:38 AM - granted resource  jo00-nbk01-hcart-robot-tld-6

Oct 18, 2023 7:11:27 AM - Info bptm (pid=20028) media id J71599 mounted on drive index 221, drivepath {7,0,7,0}, drivename Drive221, copy 2

Oct 18, 2023 7:11:27 AM - Info bptm (pid=20028) INF - Waiting for positioning of media id J71599 on server jo00-nbk01 for writing.

Oct 18, 2023 7:41:47 AM - current media J71599 complete, requesting next media Any

Oct 18, 2023 7:41:47 AM - current media -- complete, awaiting next media Any. Waiting for resources. 

          Reason: Drives are in use, Media server: jo00-nbk03, 

          Robot Type(Number): TLD(6), Media ID: N/A, Drive Name: N/A, 

          Volume Pool: duplication3-tapes, Storage Unit: jo00-nbk01-hcart-robot-tld-6, Drive Scan Host: N/A, 

          Disk Pool: N/A, Disk Volume: N/A

Oct 18, 2023 7:43:25 AM - current media -- complete, awaiting next media Any. Waiting for resources. 

          Reason: Media is in use, Media server: jo00-nbk03, 

          Robot Type(Number): TLD(6), Media ID: N/A, Drive Name: N/A, 

          Volume Pool: duplication3-tapes, Storage Unit: jo00-nbk01-hcart-robot-tld-6, Drive Scan Host: N/A, 

          Disk Pool: N/A, Disk Volume: N/A

Oct 18, 2023 11:05:58 AM - current media -- complete, awaiting next media Any. Waiting for resources. 

          Reason: Media server is currently not connected to master server, Media server: jo00-nbk03, 

          Robot Type(Number): TLD(6), Media ID: N/A, Drive Name: N/A, 

          Volume Pool: duplication3-tapes, Storage Unit: jo00-nbk01-hcart-robot-tld-6, Drive Scan Host: N/A, 

          Disk Pool: N/A, Disk Volume: N/A

Oct 18, 2023 11:15:00 AM - current media -- complete, awaiting next media Any. Waiting for resources. 

          Reason: Media is in use, Media server: jo00-nbk03, 

          Robot Type(Number): TLD(6), Media ID: N/A, Drive Name: N/A, 

          Volume Pool: duplication3-tapes, Storage Unit: jo00-nbk01-hcart-robot-tld-6, Drive Scan Host: N/A, 

          Disk Pool: N/A, Disk Volume: N/A

Oct 18, 2023 12:19:41 PM - granted resource  J71626

Oct 18, 2023 12:19:41 PM - granted resource  Drive220

Oct 18, 2023 12:19:41 PM - granted resource  jo00-nbk01-hcart-robot-tld-6

Oct 18, 2023 12:19:42 PM - Info bptm (pid=20028) media id J71626 mounted on drive index 220, drivepath {6,0,9,0}, drivename Drive220, copy 2

Oct 18, 2023 12:19:42 PM - Info bptm (pid=20028) INF - Waiting for positioning of media id J71626 on server jo00-nbk01 for writing.

Oct 18, 2023 1:57:41 PM - Info bptm (pid=24192) waited for empty buffer 359963 times, delayed 1960404 times

Oct 18, 2023 1:57:41 PM - end reading; read time: 9:10:17

Oct 18, 2023 1:57:41 PM - positioning J71544 to file 18

Oct 18, 2023 1:57:41 PM - positioned J71544; position time: 0:00:00

Oct 18, 2023 1:57:41 PM - begin reading

Oct 18, 2023 4:36:14 PM - Info bptm (pid=24192) waited for empty buffer 377853 times, delayed 390237 times

Oct 18, 2023 4:36:14 PM - end reading; read time: 2:38:33

Oct 18, 2023 4:36:14 PM - positioning J71544 to file 19

Oct 18, 2023 4:36:14 PM - positioned J71544; position time: 0:00:00

Oct 18, 2023 4:36:14 PM - begin reading

Oct 18, 2023 5:13:23 PM - Info bptm (pid=24192) waited for empty buffer 86264 times, delayed 88900 times

Oct 18, 2023 5:13:23 PM - end reading; read time: 0:37:09

Oct 18, 2023 5:13:23 PM - Info bptm (pid=24192) Waiting for mount of media id J71547 (copy 1) on server JO00-NBK01.

Oct 18, 2023 5:13:23 PM - started process bptm (pid=24192)

Oct 18, 2023 5:13:23 PM - mounting J71547

Oct 18, 2023 5:13:23 PM - Info bptm (pid=24192) INF - Waiting for mount of media id J71547 on server JO00-NBK01 for reading.

Oct 18, 2023 5:13:23 PM - current media J71544 complete, requesting next media Drive217:J71547

Oct 18, 2023 5:13:23 PM - granted resource  J71547

Oct 18, 2023 5:13:23 PM - granted resource  Drive213

Oct 18, 2023 5:13:51 PM - mounted J71547; mount time: 0:00:28

Oct 18, 2023 5:13:51 PM - Info bptm (pid=24192) J71547

Oct 18, 2023 5:13:51 PM - Info bptm (pid=24192) INF - Waiting for positioning of media id J71547 on server JO00-NBK01 for reading.

Oct 18, 2023 5:13:51 PM - positioning J71547 to file 1

Oct 18, 2023 5:13:51 PM - positioned J71547; position time: 0:00:00

Oct 18, 2023 5:13:51 PM - begin reading

Oct 18, 2023 7:55:06 PM - Info bptm (pid=24192) waited for empty buffer 373954 times, delayed 392326 times

Oct 18, 2023 7:55:06 PM - end reading; read time: 2:41:15

Oct 18, 2023 7:55:06 PM - positioning J71547 to file 2

Oct 18, 2023 7:55:06 PM - positioned J71547; position time: 0:00:00

Oct 18, 2023 7:55:06 PM - begin reading

Oct 18, 2023 10:31:12 PM - Info bptm (pid=24192) waited for empty buffer 413360 times, delayed 424429 times

Oct 18, 2023 10:31:12 PM - end reading; read time: 2:36:06

Oct 18, 2023 10:31:12 PM - positioning J71547 to file 3

Oct 18, 2023 10:31:12 PM - positioned J71547; position time: 0:00:00

Oct 18, 2023 10:31:12 PM - begin reading

Oct 19, 2023 1:09:30 AM - Info bptm (pid=24192) waited for empty buffer 390542 times, delayed 402798 times

Oct 19, 2023 1:09:30 AM - end reading; read time: 2:38:18

Oct 19, 2023 1:09:30 AM - positioning J71547 to file 4

Oct 19, 2023 1:09:30 AM - positioned J71547; position time: 0:00:00

Oct 19, 2023 1:09:30 AM - begin reading

Oct 19, 2023 3:35:33 AM - Info bptm (pid=24192) waited for empty buffer 357286 times, delayed 373167 times

Oct 19, 2023 3:35:33 AM - end reading; read time: 2:26:03

Oct 19, 2023 3:35:33 AM - positioning J71547 to file 5

Oct 19, 2023 3:35:33 AM - positioned J71547; position time: 0:00:00

Oct 19, 2023 3:35:33 AM - begin reading

Oct 19, 2023 5:53:41 AM - current media J71626 complete, requesting next media Any

Oct 19, 2023 5:56:47 AM - Info bptm (pid=20028) EXITING with status 96 <----------

Oct 19, 2023 5:56:47 AM - Info bptm (pid=24192) EXITING with status 0 <----------

Oct 19, 2023 5:56:47 AM - Error nbjm (pid=27972) NBU status: 96, EMM status: No media is available

client process aborted  (50)

StoneRam-Simon · ‎12-27-2023

Your last log entry above as Oct 19th, the job was killed (status 150) on the Dec 19th...
It does look like duplication, as it is reading form one image and writing to a new media... You filled up the existing tape, and then ran out of tapes, in the current volume pool, and had no more tapes in scratch (or no scratch pool) so after sitting waiting for new media for over 24 hours it failed with a status 96 ...

Not sure if the screen shot from Activity monitor is for the same job.. but if it is its been stuck for a long time before it was killed...

View solution in original post

StefanosM · ‎12-24-2023

please post the details of the start of the job. Or the job details start with bptm info?

also a print screen of the job overview and job hierarchy

Nicolai · ‎12-27-2023

hi @Hamzah

It looks like a restore job to me , the job activity log says "reading". Maybe a duplicate job, but I cannot say for sure since the beginning of text is missing.

StoneRam-Simon · ‎12-27-2023

Your last log entry above as Oct 19th, the job was killed (status 150) on the Dec 19th...
It does look like duplication, as it is reading form one image and writing to a new media... You filled up the existing tape, and then ran out of tapes, in the current volume pool, and had no more tapes in scratch (or no scratch pool) so after sitting waiting for new media for over 24 hours it failed with a status 96 ...

Not sure if the screen shot from Activity monitor is for the same job.. but if it is its been stuck for a long time before it was killed...

VOX

nameless job