cancel
Showing results for 
Search instead for 
Did you mean: 

Info bpbkar32(pid=6172) done. status: 52: timed out waiting for media manager to mount volume

soeheinhtut
Level 4

Please help to check below failed job and how can i resolved and prevent in future?

image.png

==========================================================================================

12/21/2019 2:41:33 AM - Info nbjm(pid=4068) starting backup job (jobid=23613) for client abcoai-bkup01p, policy DATA-ACC-lto-17, schedule Full
12/21/2019 2:41:33 AM - Info nbjm(pid=4068) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=23613, request id:{771DE47C-20ED-4A45-BC58-C194575575CD})
12/21/2019 2:41:33 AM - requesting resource abcoai-LTO-OA
12/21/2019 2:41:33 AM - requesting resource abcoai-bkmg01p.NBU_CLIENT.MAXJOBS.abcoai-bkup01p
12/21/2019 2:41:33 AM - requesting resource abcoai-bkmg01p.NBU_POLICY.MAXJOBS.DATA-ACC-lto-17
12/21/2019 2:41:33 AM - granted resource abcoai-bkmg01p.NBU_CLIENT.MAXJOBS.abcoai-bkup01p
12/21/2019 2:41:33 AM - granted resource abcoai-bkmg01p.NBU_POLICY.MAXJOBS.DATA-ACC-lto-17
12/21/2019 2:41:33 AM - granted resource CBMA17
12/21/2019 2:41:33 AM - granted resource HP.ULTRIUM6-SCSI.001
12/21/2019 2:41:33 AM - granted resource abcoai-LTO-OA
12/21/2019 2:41:33 AM - estimated 0 Kbytes needed
12/21/2019 2:41:33 AM - Info nbjm(pid=4068) started backup (backupid=abcoai-bkup01p_1576872693) job for client abcoai-bkup01p, policy DATA-ACC-lto-17, schedule Full on storage unit abcoai-LTO-OA
12/21/2019 2:41:46 AM - started process bpbrm (7888)
12/21/2019 2:42:04 AM - Info bpbrm(pid=7888) abcoai-bkup01p is the host to backup data from
12/21/2019 2:42:09 AM - Info bpbrm(pid=7888) reading file list for client
12/21/2019 2:42:09 AM - connecting
12/21/2019 2:42:23 AM - Info bpbrm(pid=7888) starting bpbkar32 on client
12/21/2019 2:42:23 AM - Info bpbkar32(pid=6172) Backup started
12/21/2019 2:42:23 AM - Info bpbkar32(pid=6172) change time comparison:<disabled>
12/21/2019 2:42:23 AM - Info bpbkar32(pid=6172) archive bit processing:<enabled>
12/21/2019 2:42:23 AM - connected; connect time: 0:00:14
12/21/2019 2:42:23 AM - Info bptm(pid=7720) start
12/21/2019 2:42:45 AM - Info bptm(pid=7720) using 65536 data buffer size
12/21/2019 2:42:45 AM - Info bptm(pid=7720) setting receive network buffer to 263168 bytes
12/21/2019 2:42:45 AM - Info bptm(pid=7720) using 30 data buffers
12/21/2019 2:42:59 AM - Info bptm(pid=7720) start backup
12/21/2019 2:42:59 AM - Info bptm(pid=7720) Waiting for mount of media id CBMA17 (copy 1) on server abcoai-bkup01p.
12/21/2019 2:42:59 AM - mounting CBMA17
12/21/2019 2:44:14 AM - Info bptm(pid=7720) media id CBMA17 mounted on drive index 1, drivepath {4,0,0,0}, drivename HP.ULTRIUM6-SCSI.001, copy 1
12/21/2019 2:44:19 AM - mounted; mount time: 0:01:20
12/21/2019 2:44:23 AM - positioning CBMA17 to file 1
12/21/2019 2:47:12 AM - positioned CBMA17; position time: 0:02:49
12/21/2019 2:47:12 AM - begin writing
12/21/2019 2:52:28 AM - Info bpbkar32(pid=6172) done. status: 52: timed out waiting for media manager to mount volume
12/21/2019 2:52:28 AM - end writing; write time: 0:05:16
timed out waiting for media manager to mount volume(52)

31 REPLIES 31

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

I believe this is another type of timeout, not a media mount timeout.
We see that the media was mounted, positioned and even 'begin writing'. The tape was waiting for data to arrive from the client.

Please tell us what all the timeout values are on master, media server, client.
It looks like a timeout value of 5 minutes (300) kicked in and incorrectly reported the error as media mount timeout.

To troubleshoot, you need the following logs:
On media server: bptm and bpbrm
On the client: bpbkar

These log folders do not exist by default, they need to be created.
I suggest that you increase logging level to 3 on media server and client.

Pls, check the below capture and logs. Thanks for your time

04.png

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

I see network errors in bptm log - so, status 52 is incorrect error message. 

It seems that it should have been Client Read timeout, but because all timeouts are the same, this old NBU version reported on the wrong timeout. 

We really need the client bpbkar log as well to see generation of datastream and what was sent to media server, plus higher level bpbrm and bptm logs - this will show us every time data buffer and metadata is received from the client.

Please increase media mount timeout to something like 15 minutes, and Client read timeout to 10 minutes (600).
Increase logging level to 3 for media server and client. 

Please try to upload logs as .txt files, as this makes it easier to open files online. 

For this failed job, Client and Media Server is same and didn't see bpbkar log file. Need to create bpbkar?

Pls let me know any impacts, if i change media mount timeout and client read timeout.

 

 

 

 

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

The bpbkar folder needs to be created. 

The impact of changing Client Read Timeout means that you give the client more time to generate data stream and send to the media server. You really need bpbkar log to see what is happening with data generation on the client - higher than the default of level 0. I have suggested level 3. 

Changing media mount timeout to a longer period will give the media server more time to mount and position the tape and also ensure that this timeout does not mask the real problem. The default for this timeout is 0 (no timeout). 

bpbkar folder created manually and changed global logging level to max(5) but didn't get the log with maximum

pls help how to verify the logs setting and pls check below bpbkar logs after change

==================================================================

08:55:13.445 [6808.3348] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\022620.log

08:55:13.445 [6808.3348] <4> ov_log::OVInit: GENERAL Log Level (Effective): 0
08:55:13.445 [6808.3348] <4> ov_log::OVInit: TCP Log Level (Effective): 0
08:55:13.445 [6808.3348] <8> OVLog: BPBKAR NetBackup Backup/Archive 7.6GA [Jul 6 2014]

08:55:13.445 [6808.3348] <8> OVLog: Copyright © 1993 - 2014 Symantec Corporation, All Rights Reserved.
All Rights Reserved.


08:55:13.445 [6808.3348] <2> WinMain: BPBKAR_VERBOSE Debug log level: Actual=0, Effective=0
08:55:13.445 [6808.3348] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe'
08:55:13.445 [6808.3348] <2> WinMain: DAT - lpCmdLine = '-r 2147483647 -ru root -dt 0 -to 300 -bpstart_time 1582684166 -clnt cbmoai-bkup01p -class DATA-ACC-lto-05 -sched Full -st FULL -bpstart_to 300 -bpend_to 300 -read_to 300 -blks_per_buffer 128 -use_otm -fso -Z -b cbmoai-bkup01p_1582683863 -kl 28 -WOFB_enabled -WOFB_fim 0 -WOFB_usage 0 -WOFB_error 0 -ct 13 -shm -use_ofb '
08:55:13.445 [6808.3348] <2> date_debug: DAT - timezone: Myanmar Standard Time, offset=-23400, dst: NONE
08:55:13.445 [6808.3348] <2> date_debug: DAT - current time: 1582683913, 2/26/2020 8:55:13 AM
08:55:13.445 [6808.3348] <2> date_debug: DAT - 01/01/94 UCT: 757382400, 1/1/1994 6:30:00 AM
08:55:13.445 [6808.3348] <2> date_debug: DAT - 07/01/94 UCT: 773020800, 7/1/1994 6:30:00 AM
08:55:13.445 [6808.3348] <2> WinMain: DAT - standard input handle = 988
08:55:13.445 [6808.3348] <2> WinMain: DAT - standard input handle is NOT resilient socket.
08:55:13.445 [6808.3348] <2> WinMain: DAT - standard output handle = 352
08:55:13.445 [6808.3348] <2> WinMain: DAT - standard output handle is NOT resilient socket.
08:55:13.445 [6808.3348] <2> WinMain: DAT - standard error handle = 464
08:55:13.445 [6808.3348] <2> WinMain: DAT - standard error handle is NOT resilient socket.
08:55:13.445 [6808.3348] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
08:55:13.445 [6808.3348] <4> tar_backup::V_SetupJobData: INF - dwJob: ffffffff
08:55:13.445 [6808.3348] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
08:55:13.445 [6808.3348] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
08:55:13.445 [6808.3348] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
08:55:13.445 [6808.3348] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
08:55:13.445 [6808.3348] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
08:55:13.445 [6808.3348] <4> dos_backup::V_PreProcessing: INF - user name: root
08:55:13.445 [6808.3348] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
08:55:13.445 [6808.3348] <2> ov_log::V_GlobalLog: WRN - ubsVerifyMIS():Microsoft Exchange Information Store is not installed.
08:55:13.445 [6808.3348] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
08:55:13.476 [6808.3348] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
08:55:13.601 [6808.3348] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
08:55:13.601 [6808.3348] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: EFI>System>Partition
08:55:13.601 [6808.3348] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
08:55:13.601 [6808.3348] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network

update: bpbkar debug log change to max(5), pls let me know it is enough to troubleshoot the backup error

Total logs size is only 234KB.

08:53:42.256 [3776.4004] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\030320.log

08:53:42.256 [3776.4004] <4> ov_log::OVInit: GENERAL Log Level (Effective): 2
08:53:42.256 [3776.4004] <4> ov_log::OVInit: TCP Log Level (Effective): 2
08:53:42.256 [3776.4004] <8> OVLog: BPBKAR NetBackup Backup/Archive 7.6GA [Jul 6 2014]

08:53:42.256 [3776.4004] <8> OVLog: Copyright © 1993 - 2014 Symantec Corporation, All Rights Reserved.
All Rights Reserved.


08:53:42.256 [3776.4004] <4> dtcp_initialize: TCP - WINSOCK.DLL Information:
08:53:42.256 [3776.4004] <4> dtcp_initialize: TCP - Version: 2.0
08:53:42.256 [3776.4004] <4> dtcp_initialize: TCP - Highest supported version: 2.2
08:53:42.256 [3776.4004] <4> dtcp_initialize: TCP - Description: WinSock 2.0
08:53:42.256 [3776.4004] <4> dtcp_initialize: TCP - System Status: Running
08:53:42.256 [3776.4004] <4> dtcp_initialize: TCP - Max Sockets: 0
08:53:42.256 [3776.4004] <2> WinMain: BPBKAR_VERBOSE Debug log level: Actual=5, Effective=5

 

meida logging.png

Logging set to max (5) but verbosity set:0 Pls help how to fix it

00:03:34.190 [7008.7872] <2> initialize: fd values STDOUTSOCK=352 STDERRSOCK=488
00:03:34.190 [7008.7872] <4> RedirectNBLoggerToLegacyLog: Setting up redirection of VxUL messages to legacy log
00:03:34.206 [7008.7872] <4> RedirectNBLoggerToLegacyLog: Verbosity from VxUL configuration: 0
00:03:34.206 [7008.7872] <4> RedirectNBLoggerToLegacyLog: logmsg verbosity set: 0

 

Possibly some confusion here - the bpbkar log file (and directory) live on the client where the backup is happening. You appear to have set this up on the media server (but I could be wrong - if so ignore me).

Backup client and media is same pls check below job, some time this job fail with below error

bpbkar32(pid=6172) done. status: 52: timed out waiting for media manager to mount volume


bkjob.PNG

In which case wait until it fails again, then examine the bpbkar logs (or upload them - if you do, try to reduce the size by only including the logs from just before to just after the backup starts and fails).

hello all, how can I check bptm logging didn't get with high verbose untile set to max(5) while bpbkar and bpbrm are fine. thanks everyone

sdo
Moderator
Moderator
Partner    VIP    Certified

It will appear that sometimes bptm will not refresh its own view of its own settings until the last tape writing job has finished.  I mean, some of the time in a tape environment, then shorter living child worker bptm processes which do the actual backup work will be fired by longer living parent bptm processes, and the way the application is written means that these child worker processes inherit their log settings from their parent jobs.  So, make sure all tape jobs to the same storage unit, that your test job is writing to,  are finished before retesting.

Pls let me know, How long I need to wait to refresh bptm logs, 

Currently, I create the folder manually, pls suggest me should I need to run "mklogdir.bat" 

sdo
Moderator
Moderator
Partner    VIP    Certified

There is no easy way of knowing how long to wait for the next new fresh parent instance of bptm to start.  If you need bptm to restart sooner, then your options are:

1) stop all tape related backup  and duplication jobs, and restart any stopped jobs

2) stop and restart the NetBackup Server application (be it a Master/Media or Media)

3) reboot the server

Any three of the above will achieve the desired result of forcing a new bptm process (for the next backup or duplication job) to pick up its new log level setting because it will be a new process.

.

No there shouldn't be any need to run mklogdir just yet.

I already restart service with bpdown /f /v and bpup /f /v but log didn't change.

pls suggest me. Thanks

sdo
Moderator
Moderator
Partner    VIP    Certified

You might have had a stuck bptm process and not known it.

The way that I would restart NetBackup Server is like this:

rem pre-check what is running...
bpps

rem take NetBackup down...
bpdown -f -v

rem check nothing is now running...
bpps
rem if anything is still running, keep re-running bpdown -f -v
rem if anything still will not stop cleanly, then you may have to kill processes...
rem ...but this can be very dangerous if you kill the wrong processes on a Master Server...
rem ...and so do not kill anything on a Master Server unless you know what you are doing...

rem re-check...
bpps

rem when nothing is running, restart NetBackup...
bpup -f -v

rem re-check all processes are there...
bpps

.

Or just have done with it and reboot the media server.

I already reboot the Media server but the result still the same, pls help to check below the capture of media server what services do I need to start manually. Thanks

08.png

Marianne
Moderator
Moderator
Partner    VIP    Accredited Certified

You need to check for bptm processes running on the media server.

bptm and bpbrm will ONLY run when active backups are running on the media server. 

If no bptm processes are running, rename today's log file(s). 

When the next backup starts, the new bptm log should reflect the logging level that you have set in Host Properties.