Tape Backup Ending in a 150 - term req'd by admin

[Denda]

NB 7.0.1 on W2K8

Client 7.0.1 on W2K3

All tape backups are ending in a 150 - term req'd by admin.  I know no admin is req'g termination since I am it!  here is the history...

Had to restore from tape for another server from long ago and had to create a 6.5.4 master to restore that tape (could not get 7.0.1 to import the tape to restore from current environment - another discussion for another time).  Restore went fine, now trying to get my 7.0.1 environment back to normal and am rec'g these 150 errors on all tape backups.  The backup starts but then 1/2 way through the backup, it terminates.  Here is the bpbkar log from the client...  Any advice would be greatly appreciated...

11:56:35.291 AM: [5724.2440] <4> ov_log::OVInit: INF - Starting log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\051611.LOG

11:56:35.291 AM: [5724.2440] <4> ov_log::OVInit: GENERAL Log Level: 0
11:56:35.291 AM: [5724.2440] <4> ov_log::OVInit: TCP Log Level: 0
11:56:35.291 AM: [5724.2440] <4> ov_log::OVInit: INF - the log mutex: 608
BPBKAR  NetBackup Backup/Archive  7.0GA  [Jul 21 2010]
Copyright © 1993 - 2010 Symantec Corporation, All Rights Reserved.
All Rights Reserved.

11:56:35.306 AM: [5724.2440] <2> WinMain: DAT - _pgmptr = 'C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe'
11:56:35.306 AM: [5724.2440] <2> WinMain: DAT - lpCmdLine = '-r 2678400 -ru root -dt 0 -to 0 -clnt hcisqlqa01 -class Tape_Weekly_Backup_SQLServer_Exceptions -sched Weekly_Full -st FULL -bpstart_to 300 -bpend_to 300 -read_to 1800 -blks_per_buffer 128 -use_otm -fso -Z -b hcisqlqa01_1305561392 -kl 28 -WOFB_enabled -WOFB_fim 1 -WOFB_usage 0 -WOFB_error 1 -ct 13 -use_ofb '
11:56:35.306 AM: [5724.2440] <2> date_debug: DAT - timezone: Eastern Standard Time, offset=18000, dst: Eastern Daylight Time
11:56:35.306 AM: [5724.2440] <2> date_debug: DAT - current time: 1305561395, 5/16/2011 11:56:35 AM
11:56:35.306 AM: [5724.2440] <2> date_debug: DAT - 01/01/94 UCT:  757382400, 12/31/1993 8:00:00 PM
11:56:35.306 AM: [5724.2440] <2> date_debug: DAT - 07/01/94 UCT:  773020800, 6/30/1994 8:00:00 PM
11:56:35.306 AM: [5724.2440] <2> WinMain: DAT - standard input handle = 516
11:56:35.306 AM: [5724.2440] <2> WinMain: DAT - standard output handle = 780
11:56:35.306 AM: [5724.2440] <2> WinMain: DAT - standard error handle = 724
11:56:35.306 AM: [5724.2440] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
11:56:35.306 AM: [5724.2440] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
11:56:35.322 AM: [5724.2440] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
11:56:35.322 AM: [5724.2440] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
11:56:35.337 AM: [5724.2440] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
11:56:35.337 AM: [5724.2440] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
11:56:35.337 AM: [5724.2440] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
11:56:35.337 AM: [5724.2440] <4> dos_backup::V_PreProcessing: INF - user name: root
11:56:35.337 AM: [5724.2440] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
11:56:35.337 AM: [5724.2440] <2> ov_log::V_GlobalLog: WRN - ubsDetermineExchangeVersion(): RegOpenKeyEx() failed for HKLM\SOFTWARE\MICROSOFT\ExchangeServer\v14\Setup - 0x2.
11:56:35.337 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: D:
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: P:
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: R:
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: T:
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Z:
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Terminal Services
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Microsoft Windows Network
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Web Client Network
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: HCISQLQA01
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Shadow?Copy?Components
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
11:56:35.384 AM: [5724.2440] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
11:56:35.478 AM: [5724.2440] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received
11:56:35.478 AM: [5724.2440] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = P:\
11:56:35.478 AM: [5724.2440] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = P:\
11:56:35.478 AM: [5724.2440] <2> tar_base::V_vTarMsgW: INF - File data will be compressed when appropriate
11:56:35.478 AM: [5724.6136] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds
11:56:35.494 AM: [5724.2440] <2> tar_backup_vxbsa::add: INF - called with 'P:\'
11:56:35.494 AM: [5724.2440] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'P:\' --> 10020002
11:56:36.119 AM: [5724.2440] <8> backup_create: WRN - Unable to create temporary directory, C:\Program Files\Veritas\\NetBackup\Temp.
11:56:36.119 AM: [5724.2440] <4> tar_backup_tfi::UpdateExcludeListWithVHD: INF - UpdateExludeListWithVHD begin
11:56:36.634 AM: [5724.2440] <2> tar_base::V_vTarMsgW: INF - Enabling volume snapshots for (P:), please wait...
11:56:36.634 AM: [5724.2440] <4> V_DetermineMountInfo: INF - Checking Volume \\?\Volume{c2db4ea8-a6d3-11de-b7eb-001b214164fd}\ for ''
11:56:36.634 AM: [5724.2440] <4> V_DetermineMountInfo: INF -   Adding NTFS Volume P:\ ==> \\?\Volume{c2db4ea8-a6d3-11de-b7eb-001b214164fd}\
11:56:36.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ======================================================================
11:56:36.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Attempting to create snapshots for 'P:'
11:56:36.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - CREATE request: C:\Program Files\Veritas\NetBackup\bin\bpfis create -owner NBU -fso -WOFB -fim VSS -id hcisqlqa01_1305561392 P:\
11:56:40.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_AddMappings: INF - V_Snapshot_AddMappings input parameters:
 source path = "P:\"
 snap path = "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy454\"
 mount path = "(null)"
11:56:40.634 AM: [5724.2440] <4> V_Snapshot::V_GetSourceVolume: INF - source = "P:\"
 snapshot = "\\?\GLOBALROOT\Device\HarddiskVolumeShadowCopy454\"
11:56:40.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_AddMappings: INF - Volume Snapshot Mapping: \\?\Volume{c2db4ea8-a6d3-11de-b7eb-001b214164fd}\ --> GLOBALROOT\Device\HarddiskVolumeShadowCopy454
11:56:40.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_ParseBpfisOutput: INF - Snapshot creation, FIS_ID: hcisqlqa01_1305561392
11:56:40.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot creation was successful
11:56:40.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - Snapshot provider: VSS
11:56:40.634 AM: [5724.2440] <4> V_Snapshot::V_Snapshot_CreateSnapshot: INF - ======================================================================
11:56:40.634 AM: [5724.2440] <2> tar_base::V_vTarMsgW: INF - Volume snapshots enabled
11:56:40.744 AM: [5724.2440] <2> ov_log::V_GlobalLogEx: INF - file_access (constructor): 0 non-NTFS volumes
12:03:05.832 PM: [5724.2440] <16> tar_tfi::processException:
An Exception of type [SocketWriteException] has occured at:
  Module: @(#) $Source: src/ncf/tfi/lib/TransporterRemote.cpp,v $ $Revision: 1.51 $ , Function: TransporterRemote::write[2](), Line: 307
  Module: @(#) $Source: src/ncf/tfi/lib/Packer.cpp,v $ $Revision: 1.85 $ , Function: Packer::getBuffer(), Line: 659
  Module: tar_tfi::getBuffer, Function: H:\701\src\cl\clientpc\util\tar_tfi.cpp, Line: 296
  Local Address: [0.0.0.0]:0
  Remote Address: [0.0.0.0]:0
  OS Error: 10054 (An existing connection was forcibly closed by the remote host.
)
  Expected bytes: 32768

12:03:05.832 PM: [5724.2440] <2> tar_base::V_vTarMsgW: FTL - socket write failed
12:03:05.832 PM: [5724.2440] <4> tar_backup::backup_done_state: INF - number of file directives not found: 0
12:03:05.832 PM: [5724.2440] <4> tar_backup::backup_done_state: INF -     number of file directives found: 1
12:03:05.832 PM: [5724.6136] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
12:03:05.832 PM: [5724.2440] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
12:03:05.832 PM: [5724.2440] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 24: socket write failed
12:03:05.832 PM: [5724.2440] <4> tar_backup::backup_done_state: INF - Not waiting for server status
12:03:05.832 PM: [5724.2440] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
12:03:05.832 PM: [5724.2440] <4> V_Snapshot::V_Snapshot_Destroy: INF - Attempting to destroy volume snapshots: bpfis delete -id hcisqlqa01_1305561392
12:03:08.832 PM: [5724.2440] <4> V_Snapshot::V_Snapshot_Destroy: INF - Snapshot Destroy EXIT STATUS 0: the requested operation was successfully completed
12:03:08.832 PM: [5724.2440] <4> OVStopCmd: INF - EXIT - status = 0
12:03:08.832 PM: [5724.2440] <2> tar_base::V_Close: closing...
12:03:08.832 PM: [5724.2440] <4> dos_backup::tfs_reset: INF - Snapshot deletion start
12:03:08.832 PM: [5724.2440] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): enter - InitFlags:0x00000101
12:03:08.832 PM: [5724.2440] <2> ov_log::V_GlobalLog: INF - BEDS_Term(): ubs specifics: 0x001d0000
12:03:14.848 PM: [5724.2440] <4> OVShutdown: INF - Finished process
12:03:14.848 PM: [5724.2440] <4> WinMain: INF - Exiting C:\Program Files\Veritas\NetBackup\bin\bpbkar32.exe
12:03:16.848 PM: [5724.2440] <4> ov_log::OVClose: INF - Closing log file: C:\Program Files\Veritas\NetBackup\logs\BPBKAR\051611.LOG
 

Thank You!

[Marianne]

OS Error: 10054 (An existing connection was forcibly closed by the remote host.)

Please post the following logs as attachments:  bpbrm and bptm logs on media server.

[Denda]

Thanks Marianne 

[Marianne]

Please see this TN: http://www.symantec.com/docs/TECH50484

STATUS CODE 150: Backups fail with a NetBackup Status Code 150 (termination requested by administrator), despite no administrator intervention, after a client is moved from an old master server to a new master server.

....

Reason:
The old master server will ask for a report drive on the media server and finds out that a job is running and is not listed in his EMM database. It will send an abort signal to the media server to cancel the job.

Resolution:
When the client was moved to the new master server, the master server was successfully added to the client server list of servers, and set as the current master server.  The old master server, however, remained in the client's server list.  By removing the old master server from the client's server list, backups were able to complete successfully.

[Denda]

already saw that post and the clients server list does not have the old master in there at all, just the new guy.. :o(

[Kernel_Panic]

Found Chimney Offload and Autotune enabled on the Media server and client. These features are found to cause unexpected socket drops during network load for backups. Disable these features on the servers involved to resolve the problem. 

- Run this command to check if those features are enabled 
  netsh int tcp show global 

- Disable the features by running these commands 
  netsh int tcp set global autotuning=disabled 
  netsh int tcp set global chimney=disabled 

[Denda]

Hmm.. thanks but I cannot get the command to work as is..

I can get as far as

netsh interface show

but from there I cannot figure out how to get the rest of the command to work properly.  Sorry..

[Marianne · Accepted solution]

I find it odd that the problem started after you "had to create a 6.5.4 master to restore that tape "

Sounds to me as if the other master is still referenced 'somewhere' in your config, as described in TECH50484.

[Denda]

The old master server is not in the clients server list, where else could I check?

[Denda]

OK - was able to get it to work on the one server that is a W2K8 server however I still cannot get it to work for the W2K3 servers... However.. it did not fix the issue...

[Denda]

What I did find was that the media server that is connected to the tape library, still had the old 6.5.4 server as an add'l server that it can communicate with, even though is was not set as the master server.  I deleted that entry and am testing now, have actually gotten much farther than before.  Keeping my fingers crossed. Will report back with result.

[Denda]

BAckup is now working correctly.  Now for me to figure out why I cannot import 6.5.4 tapes into 7.0.1.  I will post another thread.

[Marianne]

Seems I was right after all about the old master still being referenced 'somewhere' in your config....

Thanks for the confirmation.

[Yogesh9881]

You should mark as a solution to Marianne van den Berg & not yourself.