Forum Discussion

Telegram_Sam's avatar
14 years ago
Solved

NBu 7.1.0.2 - Backup job hangs at "Begin Writing". No error!

to a problem with a Windows 2003 R2 Standard (32-bit) client.  The Netbackup servers are all Windows 2008 R2 Standard (64-bit).

I installed the new client (7.1.0.2) client and ran a test backup of the C:\COMPAQ folder.  This was done on a number of servers and all were successful except for one.  the job starts and waits at the "begin writing" stage.

Here is a copy of the BPTM log from the Media Server...

13:04:05.264 [2108.2376] <2> bptm: INITIATING (VERBOSE = 0): -w -pid 1900 -c CLIENT_1 -dpath PureDiskVolume -stunit Mhd_Storage_Dedupe -cl ZZ_MHD_Windows -bt 1325768634 -b CLIENT_1_1325768634 -st 0 -cj 1 -reqid -1323976156 -jm -brm -hostname CLIENT_1 -ru root -rclnt CLIENT_1 -rclnthostname CLIENT_1 -rl 3 -rp 2419200 -sl Weekly -ct 13 -maxfrag 51200 -tir -eari 0 -mediasvr NBU_MEDIA_SRVR_1 -no_callback -connect_options 0x01010100 -jobid 89050 -jobgrpid 89050 -masterversion 710000 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_1803126823_1900_5140 -blks_per_buffer 512
13:04:05.420 [2108.2376] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:05.420 [2108.2376] <2> job_connect: SO_KEEPALIVE set on socket 908 for client NBU_MSTR_SRVR.company.com
13:04:05.420 [2108.2376] <2> logconnections: BPJOBD CONNECT FROM nnn.nnn.nnn.144.57222 TO nnn.nnn.nnn.143.1556 fd = 908
13:04:05.420 [2108.2376] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
13:04:05.420 [2108.2376] <2> job_connect: Connected to the host NBU_MSTR_SRVR.company.com contype 10 jobid <89050> socket <908>
13:04:05.420 [2108.2376] <2> job_connect: Connected on port 57222
13:04:05.420 [2108.2376] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2926: 0: name2 is empty: 0 0x00000000
13:04:05.420 [2108.2376] <4> bptm: emmserver_name = NBU_MSTR_SRVR.company.com
13:04:05.420 [2108.2376] <4> bptm: emmserver_port = 1556
13:04:05.451 [2108.2376] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -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 EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(../Orb.cpp:824)
13:04:05.466 [2108.2376] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)
13:04:05.466 [2108.2376] <2> nbjm_media_request: Passing job control to NBJM, type WRITE/1
13:04:05.466 [2108.2376] <2> nbjm_media_request: old_media_id = , media_id = NULL
13:04:05.466 [2108.2376] <2> Orb::init: Created anon service name: NB_2108_1580679132(../Orb.cpp:696)
13:04:05.466 [2108.2376] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_2108_1580679132(../Orb.cpp:713)
13:04:05.466 [2108.2376] <2> Orb::init: initializing ORB Default_DAEMON_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -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_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_2108_1580679132 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(../Orb.cpp:824)
13:04:05.466 [2108.2376] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)
13:04:05.466 [2108.2376] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6646: 0: fopen() failed: 2 0x00000002
13:04:05.466 [2108.2376] <2> file_to_addrinfo: ../../libvlibs/vnet_addrinfo.c.6647: 0: fopen() failed: D:\Program Files\Veritas\NetBackup\var\host_cache\10a\36c2db0a+0,1,0,0,1,0+fe80;;3017;43a8;4d88;f68f%20.txt
13:04:05.482 [2108.2376] <2> RequestInitialResources: returning
13:04:05.482 [2108.2376] <2> parse_resource_strings: MEDIADB 1 885900 *NULL* 0 *NULL* 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
13:04:05.482 [2108.2376] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
13:04:05.482 [2108.2376] <2> parse_resource_strings: VOLUME 1 *NULL* 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 0 0 {00000000-0000-0000-0000-000000000000} 0
13:04:05.482 [2108.2376] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
13:04:05.482 [2108.2376] <2> parse_resource_strings: DRIVE 3 *NULL* 0 *NULL* *NULL* 0 0 0 0 0 0 0 0 *NULL* *NULL* *NULL* *NULL* 0 0 0 1 0 0
13:04:05.482 [2108.2376] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
13:04:05.482 [2108.2376] <2> parse_resource_strings: STORAGE 1 Mhd_Storage_Dedupe 0 51200 0 6 0 2 NBU_MEDIA_SRVR_1 NBU_MEDIA_SRVR_1 *NULL*
13:04:05.482 [2108.2376] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
13:04:05.482 [2108.2376] <2> parse_resource_strings: DISKGROUP 0 8 PureDisk 6 NBU_MEDIA_SRVR_2 17 NBU_MEDIA_SRVR_2storagepool
13:04:05.482 [2108.2376] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
13:04:05.482 [2108.2376] <2> parse_resource_strings: DISKVOLUME 0 6 @aaaac 14 PureDiskVolume 0
13:04:05.482 [2108.2376] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
13:04:05.482 [2108.2376] <2> parse_resource_strings: DISKMOUNTPOINT 0 14 PureDiskVolume
13:04:05.482 [2108.2376] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
13:04:05.482 [2108.2376] <2> nbjm_media_request: Job control returned to BPTM
13:04:05.482 [2108.2376] <2> dsmlibp_emmserver: .\dsmlib_common.cpp: 151 sev 4 EMM server set to NBU_MSTR_SRVR.company.com
13:04:05.482 [2108.2376] <2> dsmlibp_masterserver: .\dsmlib_common.cpp: 174 sev 4 Master server set to NBU_MSTR_SRVR.company.com
13:04:05.482 [2108.2376] <2> dsmlibp_connect_dsm: .\dsmlib_common.cpp: 256 sev 4 Connecting to DiskServiceMgr on NBU_MSTR_SRVR.company.com
13:04:05.482 [2108.2376] <2> dsmlibp_get_orb: .\dsmlib_common.cpp: 51 sev 4 Using dsmlib private orb
13:04:05.482 [2108.2376] <2> Orb::init: initializing ORB Default_CLIENT_Orb with: Unknown -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -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:824)
13:04:05.482 [2108.2376] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)
13:04:05.482 [2108.2376] <2> dsmlibp_connect_dsm: .\dsmlib_common.cpp: 264 sev 4 Connecting to NBDSMFSM using orb 00000000029B36B0
13:04:05.498 [2108.2376] <2> dsmlibp_register_factories: .\dsmlib_common.cpp: 330 sev 4 Registerd Framework OBV factories with orb 00000000029B36B0
13:04:05.498 [2108.2376] <2> dsmlibp_register_factories: .\dsmlib_common.cpp: 338 sev 4 Registerd DiskServiceMgr OBV factories with orb 00000000029B36B0
13:04:05.498 [2108.2376] <2> dsm_get_diskvolumeinfo_by_mediaid: .\dsmlib_diskgroup.cpp: 1410 sev 2 diskvolume media ID = @aaaac
13:04:05.498 [2108.2376] <2> dsm_get_diskvolumeinfo_by_mediaid: .\dsmlib_diskgroup.cpp: 1413 sev 2 Calling dsm->getDiskVolumeInfoByMediaId()
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 464 sev 2 diskvolume.name = PureDiskVolume
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 472 sev 2 diskvolume.id = PureDiskVolume
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 478 sev 2 diskvolumeinfo.total_capacity = 28999854055424
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 482 sev 2 diskvolumeinfo.free_space = 20011792777216
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::master, property.value=NBU_MSTR_SRVR
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::flags, property.value=14
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 549 sev 2 diskvolumeinfo.nbu_state = conv_fn(1)
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::fileSystemType, property.value=0
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::fileSystemOrdinal, property.value=0
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 564 sev 2 diskvolumeinfo.max_write_mounts = 1
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 569 sev 2 diskvolumeinfo.num_write_mounts = 1
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::maxReferenceWriters, property.value=2147483647
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 554 sev 2 diskvolumeinfo.max_read_mounts = 0
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 559 sev 2 diskvolumeinfo.num_read_mounts = 0
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::maxReferenceReaders, property.value=0
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::freeSpace, property.value=20011792777216
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::freePhysicalSpace, property.value=20011792777216
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 511 sev 2 diskvolumeinfo.potential_free_space = 0
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 516 sev 2 diskvolumeinfo.committed_space = 2900140476416
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 521 sev 2 diskvolumeinfo.precommitted_space = 2900140476416
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 531 sev 2 diskvolumeinfo.system_tag = Unknown
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 526 sev 2 diskvolumeinfo.disk_media_id = @aaaac
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::activeReadStreams, property.value=0
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::activeWriteStreams, property.value=2
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::createdTime, property.value=1302098521
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::lastModifiedTime, property.value=1325768634
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::totalPhysicalCapacity, property.value=28999854055424
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::totalCapacity, property.value=28999854055424
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::majorEventSyncToken, property.value=1325768634
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::minorEventSyncToken, property.value=68203
13:04:05.498 [2108.2376] <2> dsml_extract_diskvolumeinfo: .\dsmlib_popext.cpp: 574 sev 2 property.name=DSM::diskGroupName, property.value=NBU_MEDIA_SRVR_2storagepool
13:04:05.529 [2108.2376] <2> dsm_get_diskvolumeinfo_by_mediaid: .\dsmlib_diskgroup.cpp: 1436 sev 2 diskvolumeinfo.diskgroup.name = NBU_MEDIA_SRVR_2storagepool
13:04:05.529 [2108.2376] <2> dsm_get_diskvolumeinfo_by_mediaid: .\dsmlib_diskgroup.cpp: 1448 sev 2 diskvolumeinfo.diskgroup.master_server = NBU_MSTR_SRVR
13:04:05.529 [2108.2376] <2> dsm_get_diskvolumeinfo_by_mediaid: .\dsmlib_diskgroup.cpp: 1459 sev 2 diskvolumeinfo.diskgroup.server_type = PureDisk
13:04:05.529 [2108.2376] <2> io_init: bpbrm_handle = 1440, buffer address = 0x11f0000
13:04:05.529 [2108.2376] <2> io_init: found index: 0
13:04:05.529 [2108.2376] <2> io_init: using 262144 data buffer size
13:04:05.529 [2108.2376] <2> io_init: CINDEX 0, sched Kbytes for monitoring = 40000
13:04:05.529 [2108.2376] <2> io_set_recvbuf: setting receive network buffer to 1049600 bytes
13:04:05.529 [2108.2376] <2> io_init: using 30 data buffers
13:04:05.529 [2108.2376] <2> io_init: child delay = 10, parent delay = 15 (milliseconds)
13:04:05.529 [2108.2376] <2> create_shared_memory: Created "Global\NetBackup Media Manager SHM Path 1803132221 2108" shared memory file.
13:04:05.529 [2108.2376] <2> create_shared_memory: shm_size = 7865048, buffer address = 0x0000000002DF0000, buf control = 0x0000000003570000, ready ptr = 0x00000000035702D0
13:04:07.323 [2108.2376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host NBU_MSTR_SRVR.company.com, query type 21
13:04:07.323 [2108.2376] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:07.323 [2108.2376] <2> logconnections: BPDBM CONNECT FROM nnn.nnn.nnn.144.57240 TO nnn.nnn.nnn.143.1556 fd = 1712
13:04:07.370 [2108.2376] <2> db_end: Need to collect reply
13:04:07.370 [2108.2376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host NBU_MSTR_SRVR.company.com, query type 1
13:04:07.385 [2108.2376] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:07.385 [2108.2376] <2> logconnections: BPDBM CONNECT FROM nnn.nnn.nnn.144.57241 TO nnn.nnn.nnn.143.1556 fd = 1724
13:04:07.416 [2108.2376] <2> db_end: Need to collect reply
13:04:07.416 [2108.2376] <4> report_client: VBRC 2 2108 1 CLIENT_1_1325768634 13 ZZ_MHD_Windows 0 Weekly 0 1 1
13:04:07.416 [2108.2376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host NBU_MSTR_SRVR.company.com, query type 81
13:04:07.416 [2108.2376] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:07.416 [2108.2376] <2> logconnections: BPDBM CONNECT FROM nnn.nnn.nnn.144.57242 TO nnn.nnn.nnn.143.1556 fd = 1724
13:04:07.650 [2108.2376] <2> db_end: Need to collect reply
13:04:07.650 [2108.2376] <2> bp_sts_get_lsu: entry PureDiskVolume
13:04:08.025 [2108.2376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host NBU_MSTR_SRVR.company.com, query type 81
13:04:08.040 [2108.2376] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:08.040 [2108.2376] <2> logconnections: BPDBM CONNECT FROM nnn.nnn.nnn.144.57244 TO nnn.nnn.nnn.143.1556 fd = 1712
13:04:08.274 [2108.2376] <2> db_end: Need to collect reply
13:04:08.274 [2108.2376] <4> write_disk_header: Data Classification & Storage Lifecycle action 4
13:04:08.274 [2108.2376] <2> construct_sts_isid: master_server NBU_MSTR_SRVR.company.com, client CLIENT_1, backup_time 1325768634, copy_number 1, stream_number 0, fragment_number 0, resume_number 0, spl_name NULL
13:04:09.866 [2108.2376] <2> construct_sts_isid: master_server NBU_MSTR_SRVR.company.com, client CLIENT_1, backup_time 1325768634, copy_number 1, stream_number 0, fragment_number 1, resume_number 0, spl_name NULL
13:04:10.396 [2108.2376] <2> io_open_disk: file CLIENT_1_1325768634_C1_F1 successfully opened
13:04:10.396 [2108.2376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host NBU_MSTR_SRVR.company.com, query type 77
13:04:10.412 [2108.2376] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:10.412 [2108.2376] <2> logconnections: BPDBM CONNECT FROM nnn.nnn.nnn.144.57247 TO nnn.nnn.nnn.143.1556 fd = 1736
13:04:10.443 [2108.2376] <2> db_end: Need to collect reply
13:04:10.692 [2108.2376] <2> write_backup: backup child process is pid 4152.3840
13:04:10.692 [2108.2376] <2> ConnectionCache::connectAndCache: Acquiring new connection for host NBU_MSTR_SRVR.company.com, query type 1
13:04:10.708 [2108.2376] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:10.708 [2108.2376] <2> logconnections: BPDBM CONNECT FROM nnn.nnn.nnn.144.57248 TO nnn.nnn.nnn.143.1556 fd = 1736
13:04:10.724 [4152.3840] <2> bptm: INITIATING (VERBOSE = 0): -w -pid 1900 -c CLIENT_1 -dpath PureDiskVolume -stunit Mhd_Storage_Dedupe -cl ZZ_MHD_Windows -bt 1325768634 -b CLIENT_1_1325768634 -st 0 -cj 1 -reqid -1323976156 -jm -brm -hostname CLIENT_1 -ru root -rclnt CLIENT_1 -rclnthostname CLIENT_1 -rl 3 -rp 2419200 -sl Weekly -ct 13 -maxfrag 51200 -tir -eari 0 -mediasvr NBU_MEDIA_SRVR_1 -no_callback -connect_options 0x01010100 -jobid 89050 -jobgrpid 89050 -masterversion 710000 -bpbrm_shm_id Global\NetBackup_BPBRM_SHM_Path_1803126823_1900_5140 -blks_per_buffer 512 -mmfill 2108 0 262144 30 10 1803132221 0 1325768634 0 ZZ_MHD_Windows CLIENT_1 CLIENT_1_1325768634
13:04:10.739 [2108.2376] <2> db_end: Need to collect reply
13:04:10.739 [2108.2376] <4> write_backup: begin writing backup id CLIENT_1_1325768634, copy 1, fragment 1, destination path PureDiskVolume
13:04:10.739 [2108.2376] <2> signal_parent: set bpbrm media ready event (pid = 1900)
13:04:10.739 [2108.2376] <2> write_data: twin_index: 0 active: 1 dont_process: 0 wrote_backup_hdr: 0 finished_buff: 0 saved_cindex: -1 twin_is_disk 1 delay_brm: 0
13:04:10.739 [2108.2376] <2> write_data: Total Kbytes transferred 0
13:04:10.880 [4152.3840] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:04:10.880 [4152.3840] <2> job_connect: SO_KEEPALIVE set on socket 928 for client NBU_MSTR_SRVR.company.com
13:04:10.880 [4152.3840] <2> logconnections: BPJOBD CONNECT FROM nnn.nnn.nnn.144.57249 TO nnn.nnn.nnn.143.1556 fd = 928
13:04:10.880 [4152.3840] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
13:04:10.880 [4152.3840] <2> job_connect: Connected to the host NBU_MSTR_SRVR.company.com contype 10 jobid <89050> socket <928>
13:04:10.880 [4152.3840] <2> job_connect: Connected on port 57249
13:04:10.880 [4152.3840] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2926: 0: name2 is empty: 0 0x00000000
13:04:10.880 [4152.3840] <4> bptm: emmserver_name = NBU_MSTR_SRVR.company.com
13:04:10.880 [4152.3840] <4> bptm: emmserver_port = 1556
13:04:10.911 [4152.3840] <2> Orb::init: initializing ORB EMMlib_Orb with: dbstunitq -ORBSvcConfDirective "-ORBDottedDecimalAddresses 0" -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 EMMlib_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(../Orb.cpp:824)
13:04:10.926 [4152.3840] <2> Orb::init: caching EndpointSelectorFactory(../Orb.cpp:839)
13:04:10.926 [4152.3840] <2> setup_mm_child: [2108] child using 30 data buffers
13:04:10.926 [4152.3840] <2> setup_mm_child: [2108] child buffer size is 262144
13:04:10.926 [4152.3840] <2> setup_mm_child: [2108] buffer address = 0x2750000, buf control = 0x2ed0000I

I will be looking forward to your response.

 

GI

  • Thats good - looks like a timeout of some sort - this one obviously has more to do when creating its snapshot or just struggles!

    Keep us updated and dont forget to mark a solution when you are happy that you have a result to your question

  • The delay when is says "begin writing" is actually whilst it prepares its snapshot and / or file list.

    It looks like you are using client side de-dupe in this case

    I would first look to see if the client has any issues in relation to its snapshots (use "vssadmin list writers" to see if they are all stable)

    Also check how it is doing for free disk space, CPU and Memory usage during the preparation stage - it may be struggling with the client side de-dupe process.

    Monitor it during this stage using Task Manager and check the Application and System Event viewer to see if something is going on

    Also setup \netbackup\logs\bpfis\ to monitor the snapshot side of things

    Hope this helps - get back to us with your findings

  • Thanks for your response Mark.

    A quick update...

    After returning from lunch the job has completed without any issues except that for all other servers with the same test took around 2 minutes to complete.  This server took 32 minutes!

    I will monitor it and report the news.

  • Thats good - looks like a timeout of some sort - this one obviously has more to do when creating its snapshot or just struggles!

    Keep us updated and dont forget to mark a solution when you are happy that you have a result to your question

  • Seems to be working OK.  The Client is an EV server and currrently it is backing up succesfully.  thanks for your help.