13:54:02.476 [2180.5928] <2> bptm: instance - 5387046
13:54:02.476 [2180.5928] <2> bptm: INITIATING (VERBOSE = 5): -mcontents -cmd -ev 15832S -raw -jobid 1360769 -cmd_lc_messages C -cmd_lc_time C 
13:54:02.476 [2180.5928] <2> bptm: Event Global\NetBackup Terminate Event, pid: 2180 created.
13:54:02.476 [2180.5928] <2> bptm: PORT_STATUS = 0x00000000
13:54:02.476 [2180.5928] <2> hosts_equal: The second name is empty
13:54:02.476 [2180.5928] <2> hosts_equal: Comparing hosts <headapp012s> and <headapp012s>
13:54:02.476 [2180.5928] <2> hosts_equal: names are the same
13:54:02.476 [2180.5928] <2> hosts_equal: Comparing hosts <headapp012s> and <headapp012s>
13:54:02.476 [2180.5928] <2> hosts_equal: names are the same
13:54:02.476 [2180.5928] <4> bptm: emmserver_name = headapp012s
13:54:02.476 [2180.5928] <4> bptm: emmserver_port = 1556
13:54:02.492 [2180.5928] <2> emmlib_initialize: (-) Connection attempt #<0> 
13:54:02.492 [2180.5928] <2> emmlib_initializeEx: (-) Connecting to the Server <headapp012s> Port <1556>, App <dbstunitq> OrbOpt <No extra otions>
13:54:02.507 [2180.5928] <2> Orb::setDebugLevelFromVxul: Orb logging configuration level set to 0(Orb.cpp:2284)
13:54:02.507 [2180.5928] <2> EndpointSelectorFactory::EndpointSelectorFactory: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2075)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D3BC (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfigHolder::BpConfigHolder: +++ ENTERING +++ : obj = 014F538C (BpConf.cpp:34)
13:54:02.507 [2180.5928] <2> BpConfigHolder::reload: +++ ENTERING +++ : obj = 014F538C (BpConf.cpp:46)
13:54:02.507 [2180.5928] <2> BpConfigHolder::reload: --- EXITING --- : obj = 014F538C (BpConf.cpp:46)
13:54:02.507 [2180.5928] <2> BpConfigHolder::BpConfigHolder: --- EXITING --- : obj = 014F538C (BpConf.cpp:34)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D3BC (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D3BC (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D3BC (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::EndpointSelector_R2: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1075)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D2E0 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D2E0 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: tardy lookup log time value set to 5 seconds(Endpoint_Selector.cpp:1169)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: USE_VXSS = PROHIBITED(Endpoint_Selector.cpp:1180)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D2E0 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D2E0 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D330 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D330 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> vnet_pcache_init_table: ../../libvlibs/vnet_private.c.240: 0: starting cache size: 200 0x000000c8
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1248: 0: file cache has expired name: headapp012s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1249: 0: file cache has expired service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1317: 0: found via getaddrinfo name: headapp012s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1319: 0: found via getaddrinfo service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp219s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp156s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::cachedHostLookup: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1917)
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp156s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> ConnectList::search: host 10.80.0.83 not found in cache(ConnectList.cpp:142)
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: 10.80.0.83
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3951: 0: Local [strong] check, using interface : ANY
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::cachedHostLookup: Hostname headapp156s has 1 usable endpoints(Endpoint_Selector.cpp:1997)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::cachedHostLookup: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1917)
13:54:02.507 [2180.5928] <2> ConnectList::addHost: added hostname headapp156s(ConnectList.cpp:65)
13:54:02.507 [2180.5928] <2> ConnectList::addHost: added hostname 10.80.0.83(ConnectList.cpp:65)
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc001c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc002c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc004c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc005c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc003v
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc004v
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc005v
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1272: 0: in failed file cache: 11001 0x00002af9
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1273: 0: in failed file cache name: headtst048s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1274: 0: in failed file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headsql005s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp080s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: virtapp127s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1272: 0: in failed file cache: 11001 0x00002af9
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1273: 0: in failed file cache name: headapp013s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1274: 0: in failed file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headapp013s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc001c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc002c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005c
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc003v
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004v
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005v
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headtst048s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:54:02.507 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headsql005s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp080s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp170s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc043v
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D330 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D330 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::EndpointSelector_R2: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1075)
13:54:02.507 [2180.5928] <2> EndpointSelectorFactory::EndpointSelectorFactory: Endpoint Selector model: 7.1 Flags: 0(Endpoint_Selector.cpp:2122)
13:54:02.507 [2180.5928] <2> EndpointSelectorFactory::EndpointSelectorFactory: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2075)
13:54:02.507 [2180.5928] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: +++ ENTERING +++ : obj = 014FA798 (Endpoint_Selector.cpp:2176)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D3B4 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D3B4 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D3B4 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D3B4 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::EndpointSelector_R2: +++ ENTERING +++ : obj = 014FE358 (Endpoint_Selector.cpp:1075)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014FE358 (Endpoint_Selector.cpp:1125)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D2D8 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D2D8 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: tardy lookup log time value set to 5 seconds(Endpoint_Selector.cpp:1169)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: USE_VXSS = PROHIBITED(Endpoint_Selector.cpp:1180)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D2D8 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D2D8 (BpConf.cpp:90)
13:54:02.507 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014FE358 (Endpoint_Selector.cpp:1125)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:80)
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.507 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp219s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp156s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::cachedHostLookup: +++ ENTERING +++ : obj = 014FE358 (Endpoint_Selector.cpp:1917)
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp156s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> ConnectList::search: host 10.80.0.83 found GOOD(ConnectList.cpp:116)
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.0.83
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3951: 0: Local [strong] check, using interface : ANY
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::cachedHostLookup: Hostname headapp156s has 1 usable endpoints(Endpoint_Selector.cpp:1997)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::cachedHostLookup: --- EXITING --- : obj = 014FE358 (Endpoint_Selector.cpp:1917)
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc001c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc002c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc003v
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004v
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005v
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headtst048s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headsql005s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp080s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: virtapp127s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headapp013s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headapp013s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc001c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc002c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005c
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc003v
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004v
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005v
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headtst048s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:54:02.523 [2180.5928] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headsql005s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp080s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp170s
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc043v
13:54:02.523 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::EndpointSelector_R2: --- EXITING --- : obj = 014FE358 (Endpoint_Selector.cpp:1075)
13:54:02.523 [2180.5928] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: Endpoint Selector model: 7.1 Flags: 0 [Ignoring BPCONF server list](Endpoint_Selector.cpp:2225)
13:54:02.523 [2180.5928] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: --- EXITING --- : obj = 014FA798 (Endpoint_Selector.cpp:2176)
13:54:02.523 [2180.5928] <2> checkService: found service: 26BC336C(Orb.cpp:433)
13:54:02.523 [2180.5928] <2> checkService: found service: 26BC3344(Orb.cpp:433)
13:54:02.523 [2180.5928] <2> Orb::getConfig: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:333)
13:54:02.523 [2180.5928] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> Orb::getConfig: --- EXITING --- : obj = 014F7F90 (Orb.cpp:333)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> Orb::init: initializing 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'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'"(Orb.cpp:569)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D378 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D378 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D378 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D378 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D8BC (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D8BC (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D8BC (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D8BC (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> Orb::init: added args has value of: (Orb.cpp:704)
13:54:02.523 [2180.5928] <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'" -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:759)
13:54:02.523 [2180.5928] <2> NBEvaluatorFactory::init: +++ ENTERING +++ : obj = 014F92A0 (SecureEvaluator.cpp:468)
13:54:02.523 [2180.5928] <2> NBEvaluatorFactory::init: --- EXITING --- : obj = 014F92A0 (SecureEvaluator.cpp:468)
13:54:02.523 [2180.5928] <2> NBOrbInitializer::pre_init: +++ ENTERING +++ : obj = 014FD078 (NBOrbInitializer.cpp:44)
13:54:02.523 [2180.5928] <2> NBOrbInitializer::pre_init: --- EXITING --- : obj = 014FD078 (NBOrbInitializer.cpp:44)
13:54:02.523 [2180.5928] <2> NBOrbInitializer::post_init: +++ ENTERING +++ : obj = 014FD078 (NBOrbInitializer.cpp:52)
13:54:02.523 [2180.5928] <2> NBOrbInitializer::post_init: Adding interceptors(NBOrbInitializer.cpp:73)
13:54:02.523 [2180.5928] <2> NBIORInterceptor::NBIORInterceptor: +++ ENTERING +++ : obj = 0150BCC8 (NBIORInterceptor.cpp:42)
13:54:02.523 [2180.5928] <2> NBIORInterceptor::NBIORInterceptor: --- EXITING --- : obj = 0150BCC8 (NBIORInterceptor.cpp:42)
13:54:02.523 [2180.5928] <2> NBIORInterceptor::name: +++ ENTERING +++ : obj = 0150BCC8 (NBIORInterceptor.cpp:55)
13:54:02.523 [2180.5928] <2> NBIORInterceptor::name: --- EXITING --- : obj = 0150BCC8 (NBIORInterceptor.cpp:55)
13:54:02.523 [2180.5928] <2> NBOrbInitializer::post_init: --- EXITING --- : obj = 014FD078 (NBOrbInitializer.cpp:52)
13:54:02.523 [2180.5928] <2> Orb::init: Set Client Restriction(Orb.cpp:782)
13:54:02.523 [2180.5928] <2> Orb::getConfig: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:333)
13:54:02.523 [2180.5928] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> Orb::getConfig: --- EXITING --- : obj = 014F7F90 (Orb.cpp:333)
13:54:02.523 [2180.5928] <2> Orb::setClientRestriction: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1998)
13:54:02.523 [2180.5928] <2> Orb::setClientRestriction: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1998)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1428)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 300(Orb.cpp:1436)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1428)
13:54:02.523 [2180.5928] <2> Orb::activate: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1161)
13:54:02.523 [2180.5928] <2> Orb::activate: Client Orb called activate; Ignored(Orb.cpp:1166)
13:54:02.523 [2180.5928] <2> Orb::activate: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1161)
13:54:02.523 [2180.5928] <2> Orb::setOrbConnectTimeout: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1409)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1428)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 60(Orb.cpp:1436)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1428)
13:54:02.523 [2180.5928] <2> Orb::setOrbConnectTimeout: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1409)
13:54:02.523 [2180.5928] <2> emmlib_initializeEx: (-) Setting connect timeout to <60> sec
13:54:02.523 [2180.5928] <2> Orb::setOrbRequestTimeout: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1418)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1428)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: setting ORB request timeout policy: tv = 1800(Orb.cpp:1436)
13:54:02.523 [2180.5928] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1428)
13:54:02.523 [2180.5928] <2> Orb::setOrbRequestTimeout: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1418)
13:54:02.523 [2180.5928] <2> emmlib_initializeEx: (-) Setting request timeout to <1800> sec
13:54:02.523 [2180.5928] <2> Orb::connectToObject: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1053)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D738 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D738 (BpConf.cpp:80)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D738 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D738 (BpConf.cpp:90)
13:54:02.523 [2180.5928] <2> ConnectList::addHost: added hostname headapp012s(ConnectList.cpp:65)
13:54:02.523 [2180.5928] <2> Orb::connectToObject: Connection attempt #1 mW:60 rW:0(Orb.cpp:1097)
13:54:02.523 [2180.5928] <2> Orb::createInsecureObjectRef: +++ ENTERING +++ : obj = 014F7F90 (Orb.cpp:1363)
13:54:02.523 [2180.5928] <2> Orb::createInsecureObjectRef: corbaloc being used is: corbaloc:pbxiop:headapp012s:1556:EMM/EMMServer(Orb.cpp:1371)
13:54:02.523 [2180.5928] <2> Orb::createInsecureObjectRef: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1363)
13:54:02.523 [2180.5928] <2> Orb::connectToObjectOnce: attempt to create insecure connection(Orb.cpp:960)
13:54:02.523 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.523 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 1 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.523 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::forward: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1298)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::forward: Adding 1 forward profiles(Endpoint_Selector.cpp:1300)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::forward: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1298)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.523 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.523 [2180.5928] <2> Orb::connectToObjectOnce: connection created(Orb.cpp:978)
13:54:02.523 [2180.5928] <2> Orb::connectToObject: --- EXITING --- : obj = 014F7F90 (Orb.cpp:1053)
13:54:02.523 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.523 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.523 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.523 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.538 [2180.5928] <4> CreateConnectionID: (-) Using existing uninitialized Connection ID 0
13:54:02.538 [2180.5928] <4> emmlib_initializeEx: (0) Successfully initialized EMM session
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: veritas_pbx
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: 10.80.3.63
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.538 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: vnetd
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: bpjobd
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:02.538 [2180.5928] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1140: 0: connect in progress: 1 0x00000001
13:54:02.538 [2180.5928] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:54:02.538 [2180.5928] <2> do_pbx_service: ../../libvlibs/vnet_connect.c.1724: 0: via PBX: bpjobd CONNECT FROM 10.80.0.83.3589 TO 10.80.3.63.1556 fd = 1244
13:54:02.538 [2180.5928] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1307: 0: connect: async CONNECT FROM 10.80.0.83.3589 TO 10.80.3.63.1556 fd = 1244
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> job_connect: SO_KEEPALIVE set on socket 1244 for client headapp012s
13:54:02.538 [2180.5928] <2> logconnections: BPJOBD CONNECT FROM 10.80.0.83.3589 TO 10.80.3.63.1556 fd = 1244
13:54:02.538 [2180.5928] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
13:54:02.538 [2180.5928] <2> job_connect: Connected to the host headapp012s contype 10 jobid <1360769> socket <1244>
13:54:02.538 [2180.5928] <2> job_connect: Connected on port 3589
13:54:02.538 [2180.5928] <2> set_job_details: Tfile (1360769): PROCESS 1313412842 2180 bptm

13:54:02.538 [2180.5928] <2> ConnectionCache::connectAndCache: Acquiring new connection for host headapp012s, query type 21
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: veritas_pbx
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: vnetd
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: bpdbm
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:02.538 [2180.5928] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1140: 0: connect in progress: 1 0x00000001
13:54:02.538 [2180.5928] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:54:02.538 [2180.5928] <2> do_pbx_service: ../../libvlibs/vnet_connect.c.1724: 0: via PBX: bpdbm CONNECT FROM 10.80.0.83.3590 TO 10.80.3.63.1556 fd = 1216
13:54:02.538 [2180.5928] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1307: 0: connect: async CONNECT FROM 10.80.0.83.3590 TO 10.80.3.63.1556 fd = 1216
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.538 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.538 [2180.5928] <2> logconnections: BPDBM CONNECT FROM 10.80.0.83.3590 TO 10.80.3.63.1556 fd = 1216
13:54:02.538 [2180.5928] <2> vnet_check_vxss_client_magic_with_info: ../../libvlibs/vnet_vxss_helper.c.878: 0: Ignoring VxSS authentication: 2 0x00000002
13:54:02.695 [2180.5928] <2> db_end: Need to collect reply
13:54:02.695 [2180.5928] <2> load_media: OPERATION 13, READ_SUBOP 0, ImportMount 0
13:54:02.695 [2180.5928] <2> nbjm_media_request: Passing job control to NBJM, type READ/6
13:54:02.695 [2180.5928] <2> nbjm_media_request: old_media_id = , media_id = 15832S
13:54:02.695 [2180.5928] <2> RequestInitialResources: starting
13:54:02.695 [2180.5928] <2> RequestInitialResources: started
13:54:02.695 [2180.5928] <2> Evictor::Evictor(): +++ ENTERING +++ : obj = 0167C524 (Evictor.cpp:198)
13:54:02.695 [2180.5928] <2> Evictor::Evictor(): --- EXITING --- : obj = 0167C524 (Evictor.cpp:198)
13:54:02.695 [2180.5928] <2> Orb::Orb: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:289)
13:54:02.695 [2180.5928] <2> Orb::Orb: --- EXITING --- : obj = 0167C248 (Orb.cpp:289)
13:54:02.695 [2180.5928] <2> Orb::init: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:440)
13:54:02.695 [2180.5928] <2> checkService: found service: 26BC336C(Orb.cpp:433)
13:54:02.695 [2180.5928] <2> checkService: found service: 26BC3344(Orb.cpp:433)
13:54:02.695 [2180.5928] <2> Orb::getConfig: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:333)
13:54:02.695 [2180.5928] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126D00 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126D00 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126D00 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126D00 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> Orb::getConfig: --- EXITING --- : obj = 0167C248 (Orb.cpp:333)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126C18 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126C18 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126C18 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126C18 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> Orb::init: substituting orb name of: Default_DAEMON_Orb(Orb.cpp:550)
13:54:02.695 [2180.5928] <2> Orb::init: initializing 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'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'"(Orb.cpp:569)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126C68 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126C68 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126C68 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126C68 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> Orb::init: Created anon service name: NB_2180_-1546713291(Orb.cpp:630)
13:54:02.695 [2180.5928] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_2180_-1546713291(Orb.cpp:648)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 001271AC (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 001271AC (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 001271AC (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 001271AC (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> Orb::init: added args has value of: (Orb.cpp:704)
13:54:02.695 [2180.5928] <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'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_2180_-1546713291 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:759)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::pre_init: +++ ENTERING +++ : obj = 014FD078 (NBOrbInitializer.cpp:44)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::pre_init: --- EXITING --- : obj = 014FD078 (NBOrbInitializer.cpp:44)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::pre_init: +++ ENTERING +++ : obj = 01503108 (NBOrbInitializer.cpp:44)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::pre_init: --- EXITING --- : obj = 01503108 (NBOrbInitializer.cpp:44)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::post_init: +++ ENTERING +++ : obj = 014FD078 (NBOrbInitializer.cpp:52)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::post_init: --- EXITING --- : obj = 014FD078 (NBOrbInitializer.cpp:52)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::post_init: +++ ENTERING +++ : obj = 01503108 (NBOrbInitializer.cpp:52)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::post_init: Adding interceptors(NBOrbInitializer.cpp:73)
13:54:02.695 [2180.5928] <2> NBIORInterceptor::NBIORInterceptor: +++ ENTERING +++ : obj = 016E6C70 (NBIORInterceptor.cpp:42)
13:54:02.695 [2180.5928] <2> NBIORInterceptor::NBIORInterceptor: --- EXITING --- : obj = 016E6C70 (NBIORInterceptor.cpp:42)
13:54:02.695 [2180.5928] <2> NBIORInterceptor::name: +++ ENTERING +++ : obj = 016E6C70 (NBIORInterceptor.cpp:55)
13:54:02.695 [2180.5928] <2> NBIORInterceptor::name: --- EXITING --- : obj = 016E6C70 (NBIORInterceptor.cpp:55)
13:54:02.695 [2180.5928] <2> NBOrbInitializer::post_init: --- EXITING --- : obj = 01503108 (NBOrbInitializer.cpp:52)
13:54:02.695 [2180.5928] <2> Orb::init: Set Client Restriction(Orb.cpp:782)
13:54:02.695 [2180.5928] <2> Orb::getConfig: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:333)
13:54:02.695 [2180.5928] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126D00 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126D00 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126D00 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126D00 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> Orb::getConfig: --- EXITING --- : obj = 0167C248 (Orb.cpp:333)
13:54:02.695 [2180.5928] <2> Orb::setClientRestriction: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:1998)
13:54:02.695 [2180.5928] <2> Orb::setClientRestriction: --- EXITING --- : obj = 0167C248 (Orb.cpp:1998)
13:54:02.695 [2180.5928] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:1428)
13:54:02.695 [2180.5928] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 300(Orb.cpp:1436)
13:54:02.695 [2180.5928] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 0167C248 (Orb.cpp:1428)
13:54:02.695 [2180.5928] <2> Orb::activate: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:1161)
13:54:02.695 [2180.5928] <2> NBEvaluatorFactory::make_evaluator(): +++ ENTERING +++ : obj = 014F92A0 (SecureEvaluator.cpp:486)
13:54:02.695 [2180.5928] <2> NBEvaluatorFactory::make_evaluator(): --- EXITING --- : obj = 014F92A0 (SecureEvaluator.cpp:486)
13:54:02.695 [2180.5928] <2> NBEvaluatorFactory::make_credential_evaluator(): +++ ENTERING +++ : obj = 014F92A0 (SecureEvaluator.cpp:506)
13:54:02.695 [2180.5928] <2> NBEvaluatorFactory::make_credential_evaluator(): --- EXITING --- : obj = 014F92A0 (SecureEvaluator.cpp:506)
13:54:02.695 [2180.5928] <2> NBIORInterceptor::establish_components: +++ ENTERING +++ : obj = 016E6C70 (NBIORInterceptor.cpp:72)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126278 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126278 (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: 127.0.0.1
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp219s
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 127.0.0.1
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp156s
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 127.0.0.1
13:54:02.695 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.695 [2180.5928] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2215: 0: matched as locals: headapp156s
13:54:02.695 [2180.5928] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2216: 0: matched as locals: 127.0.0.1
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126278 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126278 (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> init_cache: ../../libvlibs/vnet_hosts.c.1046: 0: host_cache_size: 200 0x000000c8
13:54:02.695 [2180.5928] <2> init_cache: ../../libvlibs/vnet_hosts.c.1047: 0: cache_time: 3600 0x00000e10
13:54:02.695 [2180.5928] <2> init_cache: ../../libvlibs/vnet_hosts.c.1061: 0: host_failed_cache_size: 40 0x00000028
13:54:02.695 [2180.5928] <2> init_cache: ../../libvlibs/vnet_hosts.c.1062: 0: cache_time: 3600 0x00000e10
13:54:02.695 [2180.5928] <2> NBIORInterceptor::establish_components: Encoding IP Address [10.80.0.83] in IOR(NBIORInterceptor.cpp:166)
13:54:02.695 [2180.5928] <2> NBIORInterceptor::establish_components: --- EXITING --- : obj = 016E6C70 (NBIORInterceptor.cpp:72)
13:54:02.695 [2180.5928] <2> Orb::activate: --- EXITING --- : obj = 0167C248 (Orb.cpp:1161)
13:54:02.695 [2180.5928] <2> Orb::init: --- EXITING --- : obj = 0167C248 (Orb.cpp:440)
13:54:02.695 [2180.5928] <2> Orb::connectToObject: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:1053)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126F6C (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126F6C (BpConf.cpp:80)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126F6C (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126F6C (BpConf.cpp:90)
13:54:02.695 [2180.5928] <2> Orb::connectToObject: Connection attempt #1 mW:30 rW:0(Orb.cpp:1097)
13:54:02.695 [2180.5928] <2> Orb::createInsecureObjectRef: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:1363)
13:54:02.695 [2180.5928] <2> Orb::createInsecureObjectRef: corbaloc being used is: corbaloc:pbxiop:headapp012s:1556:nbjm/JOBINST(Orb.cpp:1371)
13:54:02.695 [2180.5928] <2> Orb::createInsecureObjectRef: --- EXITING --- : obj = 0167C248 (Orb.cpp:1363)
13:54:02.695 [2180.5928] <2> Orb::connectToObjectOnce: attempt to create insecure connection(Orb.cpp:960)
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 1 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.695 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::forward: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1298)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::forward: Adding 1 forward profiles(Endpoint_Selector.cpp:1300)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::forward: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1298)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.695 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> Orb::connectToObjectOnce: connection created(Orb.cpp:978)
13:54:02.695 [2180.5928] <2> Orb::connectToObject: --- EXITING --- : obj = 0167C248 (Orb.cpp:1053)
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.695 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> packageInitialResourceRequest: started
13:54:02.695 [2180.5928] <2> packageInitialResourceRequest: retVal =	0
13:54:02.695 [2180.5928] <2> RequestInitialResources: setting up callback and calling requestResources
13:54:02.695 [2180.5928] <2> Orb::createObjectRef: +++ ENTERING +++ : obj = 0167C248 (Orb.cpp:2191)
13:54:02.695 [2180.5928] <2> Orb::createObjectRef: creating object reference(Orb.cpp:2193)
13:54:02.695 [2180.5928] <2> Orb::createObjectRef: --- EXITING --- : obj = 0167C248 (Orb.cpp:2191)
13:54:02.695 [2180.5928] <2> logResourceReq: req.versionId : 1
13:54:02.695 [2180.5928] <2> logResourceReq: req.jobId : 1360769
13:54:02.695 [2180.5928] <2> logResourceReq: req.startedViaJobManager : false
13:54:02.695 [2180.5928] <2> logResourceReq: req.consumer : true
13:54:02.695 [2180.5928] <2> logResourceReq: InitialMediaSelect - 
13:54:02.695 [2180.5928] <2> logResourceReq: 	reqNum : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.mediaId : 15832S
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.mediaKey : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.mediaServer : headapp156s
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.userReservationId : 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.assignedTime : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.client : 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.usageType : 6
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.mustBeNdmp : false
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.driveName : 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.drivePath : 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.mediaPool : 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.robotNumber : -1
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.slotNumber : -1
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.density : -1
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.ndmpControlHost : 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.failIfNoMedia : true
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.externalFile : 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mreq.exp 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	     mediaType : -1
13:54:02.695 [2180.5928] <2> logMediaRequest: 	     mediaSubType : -1
13:54:02.695 [2180.5928] <2> logMediaRequest: 	exp.capabilities 
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isNdmp : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isTirRestore : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isFlashbackupRestore : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isBlockMapRead : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isCatalogBackup : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isGcsCatalogBackup : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        preferVtlToDirectAttachedTape : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isVMWare : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	        isLifeCycle : 0
13:54:02.695 [2180.5928] <2> logMediaRequest:     useFt : 0
13:54:02.695 [2180.5928] <2> logMediaRequest:     failIfNoFt : 0
13:54:02.695 [2180.5928] <2> logMediaRequest:     isGranularExchange : 0
13:54:02.695 [2180.5928] <2> logMediaRequest:     requestFlags : 0
13:54:02.695 [2180.5928] <2> logMediaRequest: 	mediaServerAffinityID : 0
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.695 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.695 [2180.5928] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.695 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.695 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.695 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.710 [2180.5928] <2> InsecureServerEvaluator::allow_peer: +++ ENTERING +++ : obj = 014F9308 (SecureEvaluator.cpp:229)
13:54:02.710 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126370 (BpConf.cpp:80)
13:54:02.710 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126370 (BpConf.cpp:80)
13:54:02.710 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126370 (BpConf.cpp:90)
13:54:02.710 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126370 (BpConf.cpp:90)
13:54:02.710 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 001262A8 (BpConf.cpp:80)
13:54:02.710 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 001262A8 (BpConf.cpp:80)
13:54:02.710 [2180.5928] <2> VxSSNetParse::isInServerListCached: config changed, invalidated cache(VxSSNetParse.cpp:167)
13:54:02.710 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 001262A8 (BpConf.cpp:90)
13:54:02.710 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 001262A8 (BpConf.cpp:90)
13:54:02.710 [2180.5928] <2> VxSSNetParse::isInServerListCached: cache expired, invalidated cache(VxSSNetParse.cpp:185)
13:54:02.710 [2180.5928] <2> VxSSNetParse::isInServerList: Started (VxSSNetParse.cpp:222)
13:54:02.710 [2180.5928] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 001260EC (BpConf.cpp:80)
13:54:02.710 [2180.5928] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 001260EC (BpConf.cpp:80)
13:54:02.710 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:02.710 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.710 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:02.710 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:02.710 [2180.5928] <2> VxSSNetParse::isInServerList: Ended (server list)(VxSSNetParse.cpp:245)
13:54:02.710 [2180.5928] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 001260EC (BpConf.cpp:90)
13:54:02.710 [2180.5928] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 001260EC (BpConf.cpp:90)
13:54:02.710 [2180.5928] <2> VxSSNetParse::isInServerListCached: added to cache(VxSSNetParse.cpp:205)
13:54:02.710 [2180.5928] <2> InsecureServerEvaluator::allow_peer: Allowing peer to connect(SecureEvaluator.cpp:373)
13:54:02.710 [2180.5928] <2> InsecureServerEvaluator::allow_peer: --- EXITING --- : obj = 014F9308 (SecureEvaluator.cpp:229)
13:54:02.710 [2180.5928] <2> resourcesAvailable: m_allocationSeq.length() == 1
13:54:02.710 [2180.5928] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
13:54:02.710 [2180.5928] <2> resourcesAvailable: MEDIADB 1 567097 15832S 4009483 ------ 6 1301907443 1302451415 1327743604 1313412525 1342166651 24 24 8 30 0 8 1024 0 4576145 0
13:54:02.710 [2180.5928] <2> resourcesAvailable: VOLUME 1 15832S 4009483 15832S i2k-january FUJIFILM 098O308874 6 8 6 135 0 {00000000-0000-0000-0000-000000000000} 0
13:54:02.710 [2180.5928] <2> resourcesAvailable: DRIVE 3 I6K003 2001222 HU1941758D {6,0,6,3} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
13:54:02.710 [2180.5928] <2> resourcesAvailable: STORAGE 1 *NULL* 0 0 0 0 0 0 headapp156s headapp156s *NULL*
13:54:02.710 [2180.5928] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
13:54:02.710 [2180.5928] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
13:54:02.710 [2180.5928] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
13:54:02.710 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:02.710 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:02.710 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.710 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:02.710 [2180.5928] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
13:54:02.710 [2180.5928] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
13:54:02.710 [2180.5928] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
13:54:02.710 [2180.5928] <2> packageInitialResourceRequestResult: 	matched MediaAllocation to a initialMediaSelect
13:54:02.710 [2180.5928] <2> packageInitialResourceRequestResult: retVal =	0
13:54:02.710 [2180.5928] <2> RequestInitialResources: retVal = 0	emmStatus = 0
13:54:02.710 [2180.5928] <2> RequestInitialResources: returning
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 567097 15832S 4009483 ------ 6 1301907443 1302451415 1327743604 1313412525 1342166651 24 24 8 30 0 8 1024 0 4576145 0], length 127
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 15832S 4009483 15832S i2k-january FUJIFILM 098O308874 6 8 6 135 0 {00000000-0000-0000-0000-000000000000} 0], length 115
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 I6K003 2001222 HU1941758D {6,0,6,3} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0], length 108
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 *NULL* 0 0 0 0 0 0 headapp156s headapp156s *NULL*], length 59
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
13:54:02.710 [2180.5928] <2> populateBptmOpaqueStrings: retVal  = 0
13:54:02.710 [2180.5928] <2> parse_resource_strings: MEDIADB 1 567097 15832S 4009483 ------ 6 1301907443 1302451415 1327743604 1313412525 1342166651 24 24 8 30 0 8 1024 0 4576145 0
13:54:02.710 [2180.5928] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
13:54:02.710 [2180.5928] <2> parse_resource_strings: VOLUME 1 15832S 4009483 15832S i2k-january FUJIFILM 098O308874 6 8 6 135 0 {00000000-0000-0000-0000-000000000000} 0
13:54:02.710 [2180.5928] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
13:54:02.710 [2180.5928] <2> parse_resource_strings: DRIVE 3 I6K003 2001222 HU1941758D {6,0,6,3} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
13:54:02.710 [2180.5928] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
13:54:02.710 [2180.5928] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 headapp156s headapp156s *NULL*
13:54:02.710 [2180.5928] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
13:54:02.710 [2180.5928] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
13:54:02.710 [2180.5928] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
13:54:02.710 [2180.5928] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
13:54:02.710 [2180.5928] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
13:54:02.710 [2180.5928] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
13:54:02.710 [2180.5928] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
13:54:02.710 [2180.5928] <2> nbjm_media_request: Job control returned to BPTM
13:54:02.710 [2180.5928] <2> drivename_open: Called with Create 1, file I6K003
13:54:02.710 [2180.5928] <2> drivename_checklock: Called
13:54:02.710 [2180.5928] <2> drivename_lock: lock established
13:54:02.710 [2180.5928] <2> drivename_write: Called with mode 3
13:54:02.710 [2180.5928] <2> drivename_unlock: unlocked
13:54:02.710 [2180.5928] <2> drivename_checklock: Called
13:54:02.710 [2180.5928] <2> drivename_lock: lock established
13:54:02.710 [2180.5928] <2> mount_open_media: Waiting for mount of media id 15832S (copy 1) on server headapp156s.
13:54:02.710 [2180.5928] <2> set_job_details: Tfile (1360769): PROCESS 1313412842 2180 bptm

13:54:02.710 [2180.5928] <2> set_job_details: Tfile (1360769): MOUNTING 1313412842 15832S

13:54:02.710 [2180.5928] <2> openNTDevice: config_path: {6,0,6,3}, serial_num: HU1941758D
13:54:02.710 [2180.5928] <2> get_drive_path: SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi&rev_h62z#6&2c7fee11&0&000603#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
13:54:02.710 [2180.5928] <2> check_serial_num: serial number match for drive with SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, drive serial number HU1941758D, expected serial number HU1941758D
13:54:02.726 [2180.5928] <2> manage_drive_before_load: SCSI RESERVE
13:54:02.726 [2180.5928] <2> manage_drive_before_load: report_attr, fl1 0x00000001, fl2 0x00000000
13:54:03.538 [2180.5928] <2> tapelib: wait_for_ltid, Mount, timeout 0
13:54:51.535 [2180.5928] <2> openTpreqFile: tpreq_file: D:\Veritas\NetBackup\db\media\tpreq\drive_I6K003, serial_num: HU1941758D
13:54:51.535 [2180.5928] <2> get_drive_path: SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi&rev_h62z#6&2c7fee11&0&000603#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
13:54:51.535 [2180.5928] <2> check_serial_num: serial number match for drive with SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, drive serial number HU1941758D, expected serial number HU1941758D
13:54:51.551 [2180.5928] <2> init_tape: \\.\Tape6 (SCSI coordinates {6,0,6,3}) configured with blocksize 0
13:54:51.551 [2180.5928] <2> init_tape: \\.\Tape6 (SCSI coordinates {6,0,6,3}) has compression enabled
13:54:51.551 [2180.5928] <2> io_open: SCSI RESERVE (D:\Veritas\NetBackup\db\media\tpreq\drive_I6K003)
13:54:51.801 [2180.5928] <2> manage_drive_attributes: report_attr, fl1 0x00030429, fl2 0x0000000c
13:54:51.801 [2180.5928] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [098O308874]
13:54:51.801 [2180.5928] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.0.1]
13:54:51.801 [2180.5928] <2> manage_drive_attributes: DateLabeled [201104040857], Barcode [15832S], Owninghost [headapp156s]
13:54:51.801 [2180.5928] <2> manage_drive_attributes: MediaPool [i2k-january], MediaLabel [MEDIA=15832S;]
13:54:51.801 [2180.5928] <2> manage_drive_attributes: encryption status: nexus scope 0, key scope 0
13:54:51.801 [2180.5928] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 0, key instance 0
13:54:51.801 [2180.5928] <2> openTpreqFile: tpreq_file: D:\Veritas\NetBackup\db\media\tpreq\drive_I6K003, serial_num: HU1941758D
13:54:51.801 [2180.5928] <2> get_drive_path: SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi&rev_h62z#6&2c7fee11&0&000603#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
13:54:51.801 [2180.5928] <2> check_serial_num: serial number match for drive with SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, drive serial number HU1941758D, expected serial number HU1941758D
13:54:51.816 [2180.5928] <2> init_tape: \\.\Tape6 (SCSI coordinates {6,0,6,3}) configured with blocksize 0
13:54:51.832 [2180.5928] <2> init_tape: \\.\Tape6 (SCSI coordinates {6,0,6,3}) has compression enabled
13:54:52.066 [2180.5928] <2> manage_drive_attributes: report_attr, fl1 0x00030429, fl2 0x0000000c
13:54:52.066 [2180.5928] <2> manage_drive_attributes: Matching medium manufacturer [FUJIFILM], sn [098O308874]
13:54:52.066 [2180.5928] <2> manage_drive_attributes: Host Attributes: Vendor [SYMANTEC], Name [NetBackup BPTM], Version [7.0.1]
13:54:52.066 [2180.5928] <2> manage_drive_attributes: DateLabeled [201104040857], Barcode [15832S], Owninghost [headapp156s]
13:54:52.066 [2180.5928] <2> manage_drive_attributes: MediaPool [i2k-january], MediaLabel [MEDIA=15832S;]
13:54:52.066 [2180.5928] <2> manage_drive_attributes: encryption status: nexus scope 0, key scope 0
13:54:52.066 [2180.5928] <2> manage_drive_attributes: encryp mode 0x0, decryp mode 0x0, algorithm index 0, key instance 0
13:54:52.066 [2180.5928] <2> io_open: file D:\Veritas\NetBackup\db\media\tpreq\drive_I6K003 successfully opened (mode 0)
13:54:52.066 [2180.5928] <2> set_job_details: Tfile (1360769): MOUNTED 1313412892 15832S

13:54:52.066 [2180.5928] <2> load_media: media id 15832S mounted on drive index 10
13:54:52.066 [2180.5928] <4> emmlib_UpdateMediaDB: (0) Update MediaDb record 15832S
13:54:52.066 [2180.5928] <2> emmlib_UpdateMediaDB: (0) 
	partner_id = , kbytes = 1342166651, NumberOfImages = 24, ValidImages = 24
	num_restores = 0, status = 8, hsize = 1024, ssize = 0
	l_offset = 4576145, psize = 0, retention_level = 8
13:54:52.066 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:52.066 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:52.066 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:52.066 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:52.066 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:52.066 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:52.066 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:52.082 [2180.5928] <4> emmlib_UpdateMediaDB: (0) UPDATE_EMM_MEDIA_ONE returned 0
13:54:52.082 [2180.5928] <2> io_read_media_header: drive index 10, reading media header, buflen = 65536, buff = 0x01729508, copy 1
13:54:52.082 [2180.5928] <2> io_ioctl: command (5)MTREW 1 from (bptm.c.8050) on drive index 10
13:54:58.800 [2180.5928] <2> io_read_media_header: ReadFile() failed, read 0 bytes, The media is write protected. (19)
13:54:58.800 [2180.5928] <2> set_job_details: Tfile (1360769): LOG 1313412898 16 bptm 2180 tapemark or blank tape encountered reading media header, drive index 10

13:54:58.800 [2180.5928] <2> ConnectionCache::connectAndCache: Acquiring new connection for host headapp012s, query type 1
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: veritas_pbx
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:58.800 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: vnetd
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:58.800 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: bpdbm
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:58.800 [2180.5928] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:54:58.800 [2180.5928] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1140: 0: connect in progress: 1 0x00000001
13:54:58.800 [2180.5928] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:54:58.800 [2180.5928] <2> do_pbx_service: ../../libvlibs/vnet_connect.c.1724: 0: via PBX: bpdbm CONNECT FROM 10.80.0.83.3608 TO 10.80.3.63.1556 fd = 1020
13:54:58.800 [2180.5928] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1307: 0: connect: async CONNECT FROM 10.80.0.83.3608 TO 10.80.3.63.1556 fd = 1020
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:54:58.800 [2180.5928] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:54:58.800 [2180.5928] <2> logconnections: BPDBM CONNECT FROM 10.80.0.83.3608 TO 10.80.3.63.1556 fd = 1020
13:54:58.800 [2180.5928] <2> vnet_check_vxss_client_magic_with_info: ../../libvlibs/vnet_vxss_helper.c.878: 0: Ignoring VxSS authentication: 2 0x00000002
13:54:58.925 [2180.5928] <2> db_end: Need to collect reply
13:54:58.925 [2180.5928] <16> io_read_media_header: tapemark or blank tape encountered reading media header, drive index 10
13:54:58.925 [2180.5928] <2> check_error_history: just tpunmount: called from bptm line 2394, EXIT_Status = 85
13:54:58.925 [2180.5928] <2> io_close: closing D:\Veritas\NetBackup\db\media\tpreq\drive_I6K003, from bptm.c.16038
13:54:58.925 [2180.5928] <2> drivename_write: Called with mode 1
13:54:58.925 [2180.5928] <2> drivename_unlock: unlocked
13:54:58.925 [2180.5928] <2> drivename_checklock: Called
13:54:58.925 [2180.5928] <2> drivename_lock: lock established
13:54:58.925 [2180.5928] <2> drivename_unlock: unlocked
13:54:58.925 [2180.5928] <2> drivename_close: Called for file I6K003
13:54:58.925 [2180.5928] <2> tpunmount: NOP: MEDIA_DONE 0 1360769 0 15832S 4009483 0 {00E425A0-243F-4866-9117-FA17ED91A5CA}
13:54:58.925 [2180.5928] <2> bptm: Calling tpunmount for media 15832S
13:54:58.925 [2180.5928] <2> send_MDS_msg: MEDIA_DONE 0 1360769 0 15832S 4009483 0 {00E425A0-243F-4866-9117-FA17ED91A5CA}
13:54:58.925 [2180.5928] <2> JobInst::sendIrmMsg: starting
13:54:58.925 [2180.5928] <2> packageBptmResourceDoneMsg: msg (MEDIA_DONE 0 1360769 0 15832S 4009483 0 {00E425A0-243F-4866-9117-FA17ED91A5CA})
13:54:58.925 [2180.5928] <2> packageBptmResourceDoneMsg: keyword MEDIA_DONE version 0 jobid 1360769 copyNum 0 mediaId 15832S mediaKey 4009483 unloadDelay 0 allocId {00E425A0-243F-4866-9117-FA17ED91A5CA}
13:54:58.925 [2180.5928] <2> packageBptmResourceDoneMsg: returns 0
13:54:58.925 [2180.5928] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1125)
13:54:58.925 [2180.5928] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F94D8 (Endpoint_Selector.cpp:2136)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:54:58.925 [2180.5928] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1561)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1343)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1271)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:58.925 [2180.5928] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F9550 (Endpoint_Selector.cpp:1321)
13:54:58.941 [2180.5928] <2> JobInst::sendIrmMsg: returning
13:54:58.941 [2180.5928] <2> bptm: EXITING with status 85 <----------
13:54:58.941 [2180.5928] <2> bptm: Global\NetBackup Terminate Event, pid: 2180 closed.

13:55:09.034 [4364.7536] <2> bptm: instance - 5453609
13:55:09.034 [4364.7536] <2> bptm: INITIATING (VERBOSE = 5): -unload -dn I6K003 -dp {6,0,6,3} -dk 2001222 -m 15832S -mk 4009483 -mds 16 -alocid 567097 -jobid -1312947852 -jm 
13:55:09.034 [4364.7536] <2> bptm: Event Global\NetBackup Terminate Event, pid: 4364 created.
13:55:09.034 [4364.7536] <2> bptm: PORT_STATUS = 0x00000000
13:55:09.034 [4364.7536] <2> hosts_equal: The second name is empty
13:55:09.034 [4364.7536] <2> hosts_equal: Comparing hosts <headapp012s> and <headapp012s>
13:55:09.034 [4364.7536] <2> hosts_equal: names are the same
13:55:09.034 [4364.7536] <2> hosts_equal: Comparing hosts <headapp012s> and <headapp012s>
13:55:09.034 [4364.7536] <2> hosts_equal: names are the same
13:55:09.034 [4364.7536] <4> bptm: emmserver_name = headapp012s
13:55:09.034 [4364.7536] <4> bptm: emmserver_port = 1556
13:55:09.049 [4364.7536] <2> emmlib_initialize: (-) Connection attempt #<0> 
13:55:09.049 [4364.7536] <2> emmlib_initializeEx: (-) Connecting to the Server <headapp012s> Port <1556>, App <dbstunitq> OrbOpt <No extra otions>
13:55:09.049 [4364.7536] <2> Orb::setDebugLevelFromVxul: Orb logging configuration level set to 0(Orb.cpp:2284)
13:55:09.049 [4364.7536] <2> EndpointSelectorFactory::EndpointSelectorFactory: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2075)
13:55:09.049 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D3BC (BpConf.cpp:80)
13:55:09.049 [4364.7536] <2> BpConfigHolder::BpConfigHolder: +++ ENTERING +++ : obj = 014F7F84 (BpConf.cpp:34)
13:55:09.049 [4364.7536] <2> BpConfigHolder::reload: +++ ENTERING +++ : obj = 014F7F84 (BpConf.cpp:46)
13:55:09.049 [4364.7536] <2> BpConfigHolder::reload: --- EXITING --- : obj = 014F7F84 (BpConf.cpp:46)
13:55:09.049 [4364.7536] <2> BpConfigHolder::BpConfigHolder: --- EXITING --- : obj = 014F7F84 (BpConf.cpp:34)
13:55:09.049 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D3BC (BpConf.cpp:80)
13:55:09.049 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D3BC (BpConf.cpp:90)
13:55:09.049 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D3BC (BpConf.cpp:90)
13:55:09.049 [4364.7536] <2> EndpointSelector_R2::EndpointSelector_R2: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1075)
13:55:09.049 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.049 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D2E0 (BpConf.cpp:80)
13:55:09.049 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D2E0 (BpConf.cpp:80)
13:55:09.049 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: tardy lookup log time value set to 5 seconds(Endpoint_Selector.cpp:1169)
13:55:09.049 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: USE_VXSS = PROHIBITED(Endpoint_Selector.cpp:1180)
13:55:09.049 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D2E0 (BpConf.cpp:90)
13:55:09.049 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D2E0 (BpConf.cpp:90)
13:55:09.049 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.049 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D330 (BpConf.cpp:80)
13:55:09.049 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D330 (BpConf.cpp:80)
13:55:09.049 [4364.7536] <2> vnet_pcache_init_table: ../../libvlibs/vnet_private.c.240: 0: starting cache size: 200 0x000000c8
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp219s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp156s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::cachedHostLookup: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1917)
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp156s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> ConnectList::search: host 10.80.0.83 not found in cache(ConnectList.cpp:142)
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: 10.80.0.83
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3951: 0: Local [strong] check, using interface : ANY
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::cachedHostLookup: Hostname headapp156s has 1 usable endpoints(Endpoint_Selector.cpp:1997)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::cachedHostLookup: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1917)
13:55:09.065 [4364.7536] <2> ConnectList::addHost: added hostname headapp156s(ConnectList.cpp:65)
13:55:09.065 [4364.7536] <2> ConnectList::addHost: added hostname 10.80.0.83(ConnectList.cpp:65)
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc001c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc002c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc004c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc005c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc003v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc004v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc005v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1272: 0: in failed file cache: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1273: 0: in failed file cache name: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1274: 0: in failed file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headsql005s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp080s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: virtapp127s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1272: 0: in failed file cache: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1273: 0: in failed file cache name: headapp013s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1274: 0: in failed file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headapp013s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc001c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc002c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc003v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headsql005s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp080s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp170s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headexc043v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D330 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D330 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::EndpointSelector_R2: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1075)
13:55:09.065 [4364.7536] <2> EndpointSelectorFactory::EndpointSelectorFactory: Endpoint Selector model: 7.1 Flags: 0(Endpoint_Selector.cpp:2122)
13:55:09.065 [4364.7536] <2> EndpointSelectorFactory::EndpointSelectorFactory: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2075)
13:55:09.065 [4364.7536] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: +++ ENTERING +++ : obj = 014FE378 (Endpoint_Selector.cpp:2176)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D3B4 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D3B4 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D3B4 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D3B4 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::EndpointSelector_R2: +++ ENTERING +++ : obj = 014FE3A8 (Endpoint_Selector.cpp:1075)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014FE3A8 (Endpoint_Selector.cpp:1125)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D2D8 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D2D8 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: tardy lookup log time value set to 5 seconds(Endpoint_Selector.cpp:1169)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: USE_VXSS = PROHIBITED(Endpoint_Selector.cpp:1180)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D2D8 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D2D8 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014FE3A8 (Endpoint_Selector.cpp:1125)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp219s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp156s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::cachedHostLookup: +++ ENTERING +++ : obj = 014FE3A8 (Endpoint_Selector.cpp:1917)
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp156s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> ConnectList::search: host 10.80.0.83 found GOOD(ConnectList.cpp:116)
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.0.83
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3951: 0: Local [strong] check, using interface : ANY
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::cachedHostLookup: Hostname headapp156s has 1 usable endpoints(Endpoint_Selector.cpp:1997)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::cachedHostLookup: --- EXITING --- : obj = 014FE3A8 (Endpoint_Selector.cpp:1917)
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc001c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc002c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc003v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headsql005s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp080s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: virtapp127s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headapp013s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headapp013s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc001c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc002c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005c
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc003v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc004v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc005v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1221: 0: in failed cache: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1222: 0: in failed cache name: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1223: 0: in failed cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.978: 0: vnet_cached_getaddrinfo_and_update() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.314: 0: vnet_cached_getaddrinfo() failed: 6 0x00000006
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.315: 0: vnet_cached_getaddrinfo() failed: 11001 0x00002af9
13:55:09.065 [4364.7536] <2> vnet_is_local_host: ../../libvlibs/vnet_addrinfo.c.316: 0: vnet_cached_getaddrinfo() failed: headtst048s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headsql005s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp080s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp170s
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headexc043v
13:55:09.065 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> EndpointSelector_R2::EndpointSelector_R2: --- EXITING --- : obj = 014FE3A8 (Endpoint_Selector.cpp:1075)
13:55:09.065 [4364.7536] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: Endpoint Selector model: 7.1 Flags: 0 [Ignoring BPCONF server list](Endpoint_Selector.cpp:2225)
13:55:09.065 [4364.7536] <2> InsecureEndpointSelectorFactory::InsecureEndpointSelectorFactory: --- EXITING --- : obj = 014FE378 (Endpoint_Selector.cpp:2176)
13:55:09.065 [4364.7536] <2> checkService: found service: 26BC336C(Orb.cpp:433)
13:55:09.065 [4364.7536] <2> checkService: found service: 26BC3344(Orb.cpp:433)
13:55:09.065 [4364.7536] <2> Orb::getConfig: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:333)
13:55:09.065 [4364.7536] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> Orb::getConfig: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:333)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D328 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D328 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> Orb::init: initializing 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'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb EMMlib_Orb'"(Orb.cpp:569)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D378 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D378 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D378 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D378 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D8BC (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D8BC (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D8BC (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D8BC (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> Orb::init: added args has value of: (Orb.cpp:704)
13:55:09.065 [4364.7536] <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'" -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:759)
13:55:09.065 [4364.7536] <2> NBEvaluatorFactory::init: +++ ENTERING +++ : obj = 014F9328 (SecureEvaluator.cpp:468)
13:55:09.065 [4364.7536] <2> NBEvaluatorFactory::init: --- EXITING --- : obj = 014F9328 (SecureEvaluator.cpp:468)
13:55:09.065 [4364.7536] <2> NBOrbInitializer::pre_init: +++ ENTERING +++ : obj = 014FD0F8 (NBOrbInitializer.cpp:44)
13:55:09.065 [4364.7536] <2> NBOrbInitializer::pre_init: --- EXITING --- : obj = 014FD0F8 (NBOrbInitializer.cpp:44)
13:55:09.065 [4364.7536] <2> NBOrbInitializer::post_init: +++ ENTERING +++ : obj = 014FD0F8 (NBOrbInitializer.cpp:52)
13:55:09.065 [4364.7536] <2> NBOrbInitializer::post_init: Adding interceptors(NBOrbInitializer.cpp:73)
13:55:09.065 [4364.7536] <2> NBIORInterceptor::NBIORInterceptor: +++ ENTERING +++ : obj = 0150BD28 (NBIORInterceptor.cpp:42)
13:55:09.065 [4364.7536] <2> NBIORInterceptor::NBIORInterceptor: --- EXITING --- : obj = 0150BD28 (NBIORInterceptor.cpp:42)
13:55:09.065 [4364.7536] <2> NBIORInterceptor::name: +++ ENTERING +++ : obj = 0150BD28 (NBIORInterceptor.cpp:55)
13:55:09.065 [4364.7536] <2> NBIORInterceptor::name: --- EXITING --- : obj = 0150BD28 (NBIORInterceptor.cpp:55)
13:55:09.065 [4364.7536] <2> NBOrbInitializer::post_init: --- EXITING --- : obj = 014FD0F8 (NBOrbInitializer.cpp:52)
13:55:09.065 [4364.7536] <2> Orb::init: Set Client Restriction(Orb.cpp:782)
13:55:09.065 [4364.7536] <2> Orb::getConfig: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:333)
13:55:09.065 [4364.7536] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:80)
13:55:09.065 [4364.7536] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D410 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D410 (BpConf.cpp:90)
13:55:09.065 [4364.7536] <2> Orb::getConfig: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:333)
13:55:09.065 [4364.7536] <2> Orb::setClientRestriction: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1998)
13:55:09.065 [4364.7536] <2> Orb::setClientRestriction: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1998)
13:55:09.065 [4364.7536] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1428)
13:55:09.065 [4364.7536] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 300(Orb.cpp:1436)
13:55:09.065 [4364.7536] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1428)
13:55:09.065 [4364.7536] <2> Orb::activate: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1161)
13:55:09.065 [4364.7536] <2> Orb::activate: Client Orb called activate; Ignored(Orb.cpp:1166)
13:55:09.065 [4364.7536] <2> Orb::activate: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1161)
13:55:09.065 [4364.7536] <2> Orb::setOrbConnectTimeout: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1409)
13:55:09.065 [4364.7536] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1428)
13:55:09.065 [4364.7536] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 60(Orb.cpp:1436)
13:55:09.065 [4364.7536] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1428)
13:55:09.081 [4364.7536] <2> Orb::setOrbConnectTimeout: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1409)
13:55:09.081 [4364.7536] <2> emmlib_initializeEx: (-) Setting connect timeout to <60> sec
13:55:09.081 [4364.7536] <2> Orb::setOrbRequestTimeout: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1418)
13:55:09.081 [4364.7536] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1428)
13:55:09.081 [4364.7536] <2> Orb::setOrbTimeoutPolicy: setting ORB request timeout policy: tv = 1800(Orb.cpp:1436)
13:55:09.081 [4364.7536] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1428)
13:55:09.081 [4364.7536] <2> Orb::setOrbRequestTimeout: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1418)
13:55:09.081 [4364.7536] <2> emmlib_initializeEx: (-) Setting request timeout to <1800> sec
13:55:09.081 [4364.7536] <2> Orb::connectToObject: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1053)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 0012D738 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 0012D738 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 0012D738 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 0012D738 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> ConnectList::addHost: added hostname headapp012s(ConnectList.cpp:65)
13:55:09.081 [4364.7536] <2> Orb::connectToObject: Connection attempt #1 mW:60 rW:0(Orb.cpp:1097)
13:55:09.081 [4364.7536] <2> Orb::createInsecureObjectRef: +++ ENTERING +++ : obj = 014F6DF0 (Orb.cpp:1363)
13:55:09.081 [4364.7536] <2> Orb::createInsecureObjectRef: corbaloc being used is: corbaloc:pbxiop:headapp012s:1556:EMM/EMMServer(Orb.cpp:1371)
13:55:09.081 [4364.7536] <2> Orb::createInsecureObjectRef: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1363)
13:55:09.081 [4364.7536] <2> Orb::connectToObjectOnce: attempt to create insecure connection(Orb.cpp:960)
13:55:09.081 [4364.7536] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.081 [4364.7536] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 1 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.081 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::forward: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1298)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::forward: Adding 1 forward profiles(Endpoint_Selector.cpp:1300)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::forward: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1298)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.081 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.081 [4364.7536] <2> Orb::connectToObjectOnce: connection created(Orb.cpp:978)
13:55:09.081 [4364.7536] <2> Orb::connectToObject: --- EXITING --- : obj = 014F6DF0 (Orb.cpp:1053)
13:55:09.081 [4364.7536] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.081 [4364.7536] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.081 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.081 [4364.7536] <4> CreateConnectionID: (-) Using existing uninitialized Connection ID 0
13:55:09.081 [4364.7536] <4> emmlib_initializeEx: (0) Successfully initialized EMM session
13:55:09.081 [4364.7536] <2> send_brm_msg: PID of bpxm = 4364
13:55:09.081 [4364.7536] <2> nbjm_media_request: Passing job control to NBJM, type UNLOAD/6
13:55:09.081 [4364.7536] <2> nbjm_media_request: old_media_id = NULL, media_id = 15832S
13:55:09.081 [4364.7536] <2> RequestInitialResources: starting
13:55:09.081 [4364.7536] <2> RequestInitialResources: started
13:55:09.081 [4364.7536] <2> Evictor::Evictor(): +++ ENTERING +++ : obj = 0150DB8C (Evictor.cpp:198)
13:55:09.081 [4364.7536] <2> Evictor::Evictor(): --- EXITING --- : obj = 0150DB8C (Evictor.cpp:198)
13:55:09.081 [4364.7536] <2> Orb::Orb: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:289)
13:55:09.081 [4364.7536] <2> Orb::Orb: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:289)
13:55:09.081 [4364.7536] <2> Orb::init: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:440)
13:55:09.081 [4364.7536] <2> checkService: found service: 26BC336C(Orb.cpp:433)
13:55:09.081 [4364.7536] <2> checkService: found service: 26BC3344(Orb.cpp:433)
13:55:09.081 [4364.7536] <2> Orb::getConfig: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:333)
13:55:09.081 [4364.7536] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00127308 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00127308 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00127308 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00127308 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> Orb::getConfig: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:333)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00127220 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00127220 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00127220 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00127220 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> Orb::init: substituting orb name of: Default_DAEMON_Orb(Orb.cpp:550)
13:55:09.081 [4364.7536] <2> Orb::init: initializing 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'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'"(Orb.cpp:569)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00127270 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00127270 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00127270 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00127270 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> Orb::init: Created anon service name: NB_4364_817506827(Orb.cpp:630)
13:55:09.081 [4364.7536] <2> Orb::init: endpointvalue is : pbxiop://1556:NB_4364_817506827(Orb.cpp:648)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 001277B4 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 001277B4 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 001277B4 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 001277B4 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> Orb::init: added args has value of: (Orb.cpp:704)
13:55:09.081 [4364.7536] <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'" -ORBSvcConfDirective "static PBXIOP_Evaluator_Factory '-orb Default_DAEMON_Orb'" -ORBSvcConfDirective "static Resource_Factory '-ORBConnectionCacheMax 1024 '" -ORBEndpoint pbxiop://1556:NB_4364_817506827 -ORBSvcConf nul -ORBSvcConfDirective "static Server_Strategy_Factory '-ORBMaxRecvGIOPPayloadSize 268435456'"(Orb.cpp:759)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::pre_init: +++ ENTERING +++ : obj = 014FD0F8 (NBOrbInitializer.cpp:44)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::pre_init: --- EXITING --- : obj = 014FD0F8 (NBOrbInitializer.cpp:44)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::pre_init: +++ ENTERING +++ : obj = 01503168 (NBOrbInitializer.cpp:44)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::pre_init: --- EXITING --- : obj = 01503168 (NBOrbInitializer.cpp:44)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::post_init: +++ ENTERING +++ : obj = 014FD0F8 (NBOrbInitializer.cpp:52)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::post_init: --- EXITING --- : obj = 014FD0F8 (NBOrbInitializer.cpp:52)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::post_init: +++ ENTERING +++ : obj = 01503168 (NBOrbInitializer.cpp:52)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::post_init: Adding interceptors(NBOrbInitializer.cpp:73)
13:55:09.081 [4364.7536] <2> NBIORInterceptor::NBIORInterceptor: +++ ENTERING +++ : obj = 016E60D8 (NBIORInterceptor.cpp:42)
13:55:09.081 [4364.7536] <2> NBIORInterceptor::NBIORInterceptor: --- EXITING --- : obj = 016E60D8 (NBIORInterceptor.cpp:42)
13:55:09.081 [4364.7536] <2> NBIORInterceptor::name: +++ ENTERING +++ : obj = 016E60D8 (NBIORInterceptor.cpp:55)
13:55:09.081 [4364.7536] <2> NBIORInterceptor::name: --- EXITING --- : obj = 016E60D8 (NBIORInterceptor.cpp:55)
13:55:09.081 [4364.7536] <2> NBOrbInitializer::post_init: --- EXITING --- : obj = 01503168 (NBOrbInitializer.cpp:52)
13:55:09.081 [4364.7536] <2> Orb::init: Set Client Restriction(Orb.cpp:782)
13:55:09.081 [4364.7536] <2> Orb::getConfig: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:333)
13:55:09.081 [4364.7536] <2> Orb::getConfig: No service entry for pbx. Using default port 1556(Orb.cpp:354)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00127308 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00127308 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> Orb::getConfig: cluster_name and required_interface not defined, using ANY(Orb.cpp:403)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00127308 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00127308 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> Orb::getConfig: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:333)
13:55:09.081 [4364.7536] <2> Orb::setClientRestriction: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:1998)
13:55:09.081 [4364.7536] <2> Orb::setClientRestriction: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:1998)
13:55:09.081 [4364.7536] <2> Orb::setOrbTimeoutPolicy: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:1428)
13:55:09.081 [4364.7536] <2> Orb::setOrbTimeoutPolicy: setting ORB connection timeout policy: tv = 300(Orb.cpp:1436)
13:55:09.081 [4364.7536] <2> Orb::setOrbTimeoutPolicy: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:1428)
13:55:09.081 [4364.7536] <2> Orb::activate: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:1161)
13:55:09.081 [4364.7536] <2> NBEvaluatorFactory::make_evaluator(): +++ ENTERING +++ : obj = 014F9328 (SecureEvaluator.cpp:486)
13:55:09.081 [4364.7536] <2> NBEvaluatorFactory::make_evaluator(): --- EXITING --- : obj = 014F9328 (SecureEvaluator.cpp:486)
13:55:09.081 [4364.7536] <2> NBEvaluatorFactory::make_credential_evaluator(): +++ ENTERING +++ : obj = 014F9328 (SecureEvaluator.cpp:506)
13:55:09.081 [4364.7536] <2> NBEvaluatorFactory::make_credential_evaluator(): --- EXITING --- : obj = 014F9328 (SecureEvaluator.cpp:506)
13:55:09.081 [4364.7536] <2> NBIORInterceptor::establish_components: +++ ENTERING +++ : obj = 016E60D8 (NBIORInterceptor.cpp:72)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126880 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126880 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: 127.0.0.1
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp219s
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 127.0.0.1
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp156s
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 127.0.0.1
13:55:09.081 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.081 [4364.7536] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2215: 0: matched as locals: headapp156s
13:55:09.081 [4364.7536] <2> vnet_same_host: ../../libvlibs/vnet_addrinfo.c.2216: 0: matched as locals: 127.0.0.1
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126880 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126880 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> init_cache: ../../libvlibs/vnet_hosts.c.1046: 0: host_cache_size: 200 0x000000c8
13:55:09.081 [4364.7536] <2> init_cache: ../../libvlibs/vnet_hosts.c.1047: 0: cache_time: 3600 0x00000e10
13:55:09.081 [4364.7536] <2> init_cache: ../../libvlibs/vnet_hosts.c.1061: 0: host_failed_cache_size: 40 0x00000028
13:55:09.081 [4364.7536] <2> init_cache: ../../libvlibs/vnet_hosts.c.1062: 0: cache_time: 3600 0x00000e10
13:55:09.081 [4364.7536] <2> NBIORInterceptor::establish_components: Encoding IP Address [10.80.0.83] in IOR(NBIORInterceptor.cpp:166)
13:55:09.081 [4364.7536] <2> NBIORInterceptor::establish_components: --- EXITING --- : obj = 016E60D8 (NBIORInterceptor.cpp:72)
13:55:09.081 [4364.7536] <2> Orb::activate: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:1161)
13:55:09.081 [4364.7536] <2> Orb::init: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:440)
13:55:09.081 [4364.7536] <2> Orb::connectToObject: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:1053)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00127574 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00127574 (BpConf.cpp:80)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00127574 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00127574 (BpConf.cpp:90)
13:55:09.081 [4364.7536] <2> Orb::connectToObject: Connection attempt #1 mW:30 rW:0(Orb.cpp:1097)
13:55:09.081 [4364.7536] <2> Orb::createInsecureObjectRef: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:1363)
13:55:09.081 [4364.7536] <2> Orb::createInsecureObjectRef: corbaloc being used is: corbaloc:pbxiop:headapp012s:1556:nbjm/JOBINST(Orb.cpp:1371)
13:55:09.081 [4364.7536] <2> Orb::createInsecureObjectRef: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:1363)
13:55:09.081 [4364.7536] <2> Orb::connectToObjectOnce: attempt to create insecure connection(Orb.cpp:960)
13:55:09.081 [4364.7536] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.081 [4364.7536] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 1 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.081 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.081 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::forward: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1298)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::forward: Adding 1 forward profiles(Endpoint_Selector.cpp:1300)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::forward: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1298)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.096 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> Orb::connectToObjectOnce: connection created(Orb.cpp:978)
13:55:09.096 [4364.7536] <2> Orb::connectToObject: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:1053)
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.096 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> packageInitialResourceRequest: started
13:55:09.096 [4364.7536] <2> packageInitialResourceRequest: retVal =	0
13:55:09.096 [4364.7536] <2> RequestInitialResources: setting up callback and calling requestResources
13:55:09.096 [4364.7536] <2> Orb::createObjectRef: +++ ENTERING +++ : obj = 0150D8B0 (Orb.cpp:2191)
13:55:09.096 [4364.7536] <2> Orb::createObjectRef: creating object reference(Orb.cpp:2193)
13:55:09.096 [4364.7536] <2> Orb::createObjectRef: --- EXITING --- : obj = 0150D8B0 (Orb.cpp:2191)
13:55:09.096 [4364.7536] <2> logResourceReq: req.versionId : 1
13:55:09.096 [4364.7536] <2> logResourceReq: req.jobId : -1312947852
13:55:09.096 [4364.7536] <2> logResourceReq: req.startedViaJobManager : true
13:55:09.096 [4364.7536] <2> logResourceReq: req.consumer : true
13:55:09.096 [4364.7536] <2> logResourceReq: InitialMediaSelect - 
13:55:09.096 [4364.7536] <2> logResourceReq: 	reqNum : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.mediaId : 15832S
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.mediaKey : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.mediaServer : headapp156s
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.userReservationId : 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.assignedTime : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.client : 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.usageType : 6
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.mustBeNdmp : false
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.driveName : I6K003
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.drivePath : 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.mediaPool : 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.robotNumber : -1
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.slotNumber : -1
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.density : -1
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.ndmpControlHost : 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.failIfNoMedia : true
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.externalFile : 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mreq.exp 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	     mediaType : -1
13:55:09.096 [4364.7536] <2> logMediaRequest: 	     mediaSubType : -1
13:55:09.096 [4364.7536] <2> logMediaRequest: 	exp.capabilities 
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isNdmp : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isTirRestore : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isFlashbackupRestore : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isBlockMapRead : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isCatalogBackup : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isGcsCatalogBackup : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        preferVtlToDirectAttachedTape : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isVMWare : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	        isLifeCycle : 0
13:55:09.096 [4364.7536] <2> logMediaRequest:     useFt : 0
13:55:09.096 [4364.7536] <2> logMediaRequest:     failIfNoFt : 0
13:55:09.096 [4364.7536] <2> logMediaRequest:     isGranularExchange : 0
13:55:09.096 [4364.7536] <2> logMediaRequest:     requestFlags : 0
13:55:09.096 [4364.7536] <2> logMediaRequest: 	mediaServerAffinityID : 0
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.096 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> RequestInitialResources: BpxmiV->requestResourcesWithTimeout returns 0
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.096 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> InsecureServerEvaluator::allow_peer: +++ ENTERING +++ : obj = 014F9390 (SecureEvaluator.cpp:229)
13:55:09.096 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 00126978 (BpConf.cpp:80)
13:55:09.096 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 00126978 (BpConf.cpp:80)
13:55:09.096 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 00126978 (BpConf.cpp:90)
13:55:09.096 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 00126978 (BpConf.cpp:90)
13:55:09.096 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 001268B0 (BpConf.cpp:80)
13:55:09.096 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 001268B0 (BpConf.cpp:80)
13:55:09.096 [4364.7536] <2> VxSSNetParse::isInServerListCached: config changed, invalidated cache(VxSSNetParse.cpp:167)
13:55:09.096 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 001268B0 (BpConf.cpp:90)
13:55:09.096 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 001268B0 (BpConf.cpp:90)
13:55:09.096 [4364.7536] <2> VxSSNetParse::isInServerListCached: cache expired, invalidated cache(VxSSNetParse.cpp:185)
13:55:09.096 [4364.7536] <2> VxSSNetParse::isInServerList: Started (VxSSNetParse.cpp:222)
13:55:09.096 [4364.7536] <2> BpConfReader::BpConfReader: +++ ENTERING +++ : obj = 001266F4 (BpConf.cpp:80)
13:55:09.096 [4364.7536] <2> BpConfReader::BpConfReader: --- EXITING --- : obj = 001266F4 (BpConf.cpp:80)
13:55:09.096 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:55:09.096 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:09.096 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: 10.80.3.63
13:55:09.096 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: NULL
13:55:09.096 [4364.7536] <2> VxSSNetParse::isInServerList: Ended (server list)(VxSSNetParse.cpp:245)
13:55:09.096 [4364.7536] <2> BpConfReader::~BpConfReader: +++ ENTERING +++ : obj = 001266F4 (BpConf.cpp:90)
13:55:09.096 [4364.7536] <2> BpConfReader::~BpConfReader: --- EXITING --- : obj = 001266F4 (BpConf.cpp:90)
13:55:09.096 [4364.7536] <2> VxSSNetParse::isInServerListCached: added to cache(VxSSNetParse.cpp:205)
13:55:09.096 [4364.7536] <2> InsecureServerEvaluator::allow_peer: Allowing peer to connect(SecureEvaluator.cpp:373)
13:55:09.096 [4364.7536] <2> InsecureServerEvaluator::allow_peer: --- EXITING --- : obj = 014F9390 (SecureEvaluator.cpp:229)
13:55:09.096 [4364.7536] <2> resourcesAvailable: m_allocationSeq.length() == 1
13:55:09.096 [4364.7536] <2> resourcesAvailable: thisAllocation->mdar.Bsr.BptmStrings.length() == 7
13:55:09.096 [4364.7536] <2> resourcesAvailable: MEDIADB 1 567097 15832S 4009483 ------ 6 1301907443 1302451415 1327743604 1313412525 1342166651 24 24 8 30 0 8 1024 0 4576145 0
13:55:09.096 [4364.7536] <2> resourcesAvailable: VOLUME 1 15832S 4009483 15832S i2k-january FUJIFILM 098O308874 6 8 6 135 0 {00000000-0000-0000-0000-000000000000} 0
13:55:09.096 [4364.7536] <2> resourcesAvailable: DRIVE 3 I6K003 2001222 HU1941758D {6,0,6,3} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
13:55:09.096 [4364.7536] <2> resourcesAvailable: STORAGE 1 *NULL* 0 0 0 0 0 0 headapp156s headapp156s *NULL*
13:55:09.096 [4364.7536] <2> resourcesAvailable: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
13:55:09.096 [4364.7536] <2> resourcesAvailable: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
13:55:09.096 [4364.7536] <2> resourcesAvailable: DISKMOUNTPOINT 0 6 *NULL*
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: +++ ENTERING +++ : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::updateConfMembers: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1125)
13:55:09.096 [4364.7536] <2> EndpointSelectorFactory::get_selector: --- EXITING --- : obj = 014F9560 (Endpoint_Selector.cpp:2136)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: Evaluating 2 endpoints(Endpoint_Selector.cpp:1356)
13:55:09.096 [4364.7536] <2> ConnectList::search: host headapp012s found GOOD(ConnectList.cpp:116)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: insecure invocation->perform_call(...) to host headapp012s SUCCESS(Endpoint_Selector.cpp:1712)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::performCallUsingEndpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1561)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::endpoint_from_profile: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1343)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::select_endpoint: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1271)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: +++ ENTERING +++ : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> EndpointSelector_R2::success: --- EXITING --- : obj = 014F95D8 (Endpoint_Selector.cpp:1321)
13:55:09.096 [4364.7536] <2> packageInitialResourceRequestResult: totalNumberOfAllocations == 1
13:55:09.096 [4364.7536] <2> packageInitialResourceRequestResult: m_allocationSeq.length=1
13:55:09.096 [4364.7536] <2> packageInitialResourceRequestResult: found MediaAllocation : reqNum == 0
13:55:09.096 [4364.7536] <2> packageInitialResourceRequestResult: 	matched MediaAllocation to a initialMediaSelect
13:55:09.096 [4364.7536] <2> packageInitialResourceRequestResult: retVal =	0
13:55:09.096 [4364.7536] <2> RequestInitialResources: retVal = 0	emmStatus = 0
13:55:09.096 [4364.7536] <2> RequestInitialResources: returning
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: packaging bptm string [MEDIADB 1 567097 15832S 4009483 ------ 6 1301907443 1302451415 1327743604 1313412525 1342166651 24 24 8 30 0 8 1024 0 4576145 0], length 127
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: packaging bptm string [VOLUME 1 15832S 4009483 15832S i2k-january FUJIFILM 098O308874 6 8 6 135 0 {00000000-0000-0000-0000-000000000000} 0], length 115
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: packaging bptm string [DRIVE 3 I6K003 2001222 HU1941758D {6,0,6,3} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0], length 108
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: packaging bptm string [STORAGE 1 *NULL* 0 0 0 0 0 0 headapp156s headapp156s *NULL*], length 59
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: packaging bptm string [DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*], length 38
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: packaging bptm string [DISKVOLUME 0 6 *NULL* 6 *NULL* 0], length 32
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: packaging bptm string [DISKMOUNTPOINT 0 6 *NULL*], length 25
13:55:09.096 [4364.7536] <2> populateBptmOpaqueStrings: retVal  = 0
13:55:09.096 [4364.7536] <2> parse_resource_strings: MEDIADB 1 567097 15832S 4009483 ------ 6 1301907443 1302451415 1327743604 1313412525 1342166651 24 24 8 30 0 8 1024 0 4576145 0
13:55:09.096 [4364.7536] <2> parse_resource_strings: Parsed message type 15, version 1, 21 parameters
13:55:09.096 [4364.7536] <2> parse_resource_strings: VOLUME 1 15832S 4009483 15832S i2k-january FUJIFILM 098O308874 6 8 6 135 0 {00000000-0000-0000-0000-000000000000} 0
13:55:09.096 [4364.7536] <2> parse_resource_strings: Parsed message type 16, version 1, 14 parameters
13:55:09.096 [4364.7536] <2> parse_resource_strings: DRIVE 3 I6K003 2001222 HU1941758D {6,0,6,3} -1 -1 -1 -1 -1 -1 -1 -1 *NULL* *NULL* *NULL* *NULL* 1 16 0 1 0 0
13:55:09.096 [4364.7536] <2> parse_resource_strings: Parsed message type 17, version 3, 23 parameters
13:55:09.096 [4364.7536] <2> parse_resource_strings: STORAGE 1 *NULL* 0 0 0 0 0 0 headapp156s headapp156s *NULL*
13:55:09.096 [4364.7536] <2> parse_resource_strings: Parsed message type 18, version 1, 11 parameters
13:55:09.096 [4364.7536] <2> parse_resource_strings: DISKGROUP 0 6 *NULL* 6 *NULL* 6 *NULL*
13:55:09.096 [4364.7536] <2> parse_resource_strings: Parsed message type 21, version 0, 7 parameters
13:55:09.096 [4364.7536] <2> parse_resource_strings: DISKVOLUME 0 6 *NULL* 6 *NULL* 0
13:55:09.096 [4364.7536] <2> parse_resource_strings: Parsed message type 22, version 0, 6 parameters
13:55:09.096 [4364.7536] <2> parse_resource_strings: DISKMOUNTPOINT 0 6 *NULL*
13:55:09.096 [4364.7536] <2> parse_resource_strings: Parsed message type 23, version 0, 3 parameters
13:55:09.096 [4364.7536] <2> nbjm_media_request: Job control returned to BPTM
13:55:09.096 [4364.7536] <2> drivename_open: Called with Create 1, file I6K003
13:55:09.096 [4364.7536] <2> drivename_checklock: Called
13:55:09.096 [4364.7536] <2> drivename_lock: lock established
13:55:09.096 [4364.7536] <4> create_tpreq_file: {6,0,6,3}
13:55:09.096 [4364.7536] <2> drivename_write: Called with mode 2
13:55:09.096 [4364.7536] <2> drivename_unlock: unlocked
13:55:09.096 [4364.7536] <2> drivename_checklock: Called
13:55:09.096 [4364.7536] <2> drivename_lock: lock established
13:55:09.096 [4364.7536] <2> openNTDevice: config_path: {6,0,6,3}, serial_num: HU1941758D
13:55:09.096 [4364.7536] <2> get_drive_path: SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi&rev_h62z#6&2c7fee11&0&000603#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
13:55:09.112 [4364.7536] <2> check_serial_num: serial number match for drive with SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, drive serial number HU1941758D, expected serial number HU1941758D
13:55:09.112 [4364.7536] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
13:55:09.112 [4364.7536] <2> really_tpunmount: tpunmount'ing D:\Veritas\NetBackup\db\media\tpreq\drive_I6K003
13:55:09.518 [4364.7536] <2> tapelib: wait_for_ltid, UnMount, timeout 2400
13:55:38.516 [4364.7536] <2> ConnectionCache::connectAndCache: Acquiring new connection for host headapp012s, query type 1
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: veritas_pbx
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:38.516 [4364.7536] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: vnetd
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:38.516 [4364.7536] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1259: 0: found in file cache name: headapp012s
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1260: 0: found in file cache service: bpdbm
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: 10.80.3.63
13:55:38.516 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:38.516 [4364.7536] <2> get_pref_netconnection: ../../libvlibs/vnet_addrinfo.c.3963: 0: using interface : ANY
13:55:38.516 [4364.7536] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1140: 0: connect in progress: 1 0x00000001
13:55:38.532 [4364.7536] <2> vnet_pbxConnect: pbxConnectEx Succeeded
13:55:38.532 [4364.7536] <2> do_pbx_service: ../../libvlibs/vnet_connect.c.1724: 0: via PBX: bpdbm CONNECT FROM 10.80.0.83.3627 TO 10.80.3.63.1556 fd = 1036
13:55:38.532 [4364.7536] <2> vnet_async_connect: ../../libvlibs/vnet_connect.c.1307: 0: connect: async CONNECT FROM 10.80.0.83.3627 TO 10.80.3.63.1556 fd = 1036
13:55:38.532 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1121: 0: found in cache name: headapp012s
13:55:38.532 [4364.7536] <2> vnet_cached_getaddrinfo: ../../libvlibs/vnet_addrinfo.c.1122: 0: found in cache service: NULL
13:55:38.532 [4364.7536] <2> logconnections: BPDBM CONNECT FROM 10.80.0.83.3627 TO 10.80.3.63.1556 fd = 1036
13:55:38.532 [4364.7536] <2> vnet_check_vxss_client_magic_with_info: ../../libvlibs/vnet_vxss_helper.c.878: 0: Ignoring VxSS authentication: 2 0x00000002
13:55:38.657 [4364.7536] <2> db_end: Need to collect reply
13:55:38.657 [4364.7536] <4> report_resource_done: VBRD 1 4364 0 I6K003 15832S
13:55:38.657 [4364.7536] <2> openNTDevice: config_path: {6,0,6,3}, serial_num: HU1941758D
13:55:38.657 [4364.7536] <2> get_drive_path: SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, pnp_path \\?\scsi#sequential&ven_hp&prod_ultrium_4-scsi&rev_h62z#6&2c7fee11&0&000603#{53f5630b-b6bf-11d0-94f2-00a0c91efb8b}
13:55:38.657 [4364.7536] <2> check_serial_num: serial number match for drive with SCSI coordinates {6,0,6,3}, dos_path \\.\Tape6, drive serial number HU1941758D, expected serial number HU1941758D
13:55:38.657 [4364.7536] <2> process_tapealert: TapeAlert returned 0x00000000 0x00000000 (from tapealert_and_release)
13:55:38.657 [4364.7536] <2> tapealert_and_release: report_attr, fl1 0x00000001, fl2 0x00000000
13:55:38.672 [4364.7536] <2> tapealert_and_release: SCSI RELEASE
13:55:38.672 [4364.7536] <2> drivename_unlock: unlocked
13:55:38.672 [4364.7536] <2> drivename_close: Called for file I6K003
13:55:38.672 [4364.7536] <2> drivename_remove: Called
13:55:38.672 [4364.7536] <2> main: Sending [EXIT STATUS 0] to NBJM
13:55:38.672 [4364.7536] <2> bptm: EXITING with status 0 <----------
13:55:38.672 [4364.7536] <2> bptm: Global\NetBackup Terminate Event, pid: 4364 closed.