bpbkar32.exe don't write data.

Marcio_Almeida · ‎06-01-2012

Hi All,

What happens?

1 - The backup is started on the active monitor

2 - The backup starts

3 - On the client, bpbkar32.exe starts and port 13724 is listening.

4 - The backup status is to begin writing.

5 - There is no data copied.

What is strange?

1 - The backup does not copy anything.

2 - doors remain listening

3 - When I finish the backup (status 150), the bpbkar32.exe remains active on the client. It should not end well?

4 - In the log appears BPCD two IPs that are neither the client nor the media server.

Client IP: 10.8.6.149

Gateway: 10.8.6.56

IP: 10.8.6.69 -> I do not know where it came from this IP

IP: 10.8.6.91 -> I do not know where it came from that IP.

What has been done?

1 - Released all ports on the firewall. There is no firewall on the way out.

What I suspect?

1 - One way traffic is working, but on the way back is getting lost ...

I honestly do not know what to do and I hope my friends can help me!

Thank you!

JOB DETAILS

01/06/2012 09:08:04 - Info nbjm (pid=22950) starting backup job (jobid=353567) for client SAC1111, policy SAC1111, schedule Mensal
01/06/2012 09:08:04 - Info nbjm (pid=22950) requesting STANDARD_RESOURCE resources from RB for backup job (jobid=353567, request id:{712ABEF2-ABE2-11E1-9E0A-00144FEAACDB})
01/06/2012 09:08:04 - requesting resource STU_DISK_SAC0972_2
01/06/2012 09:08:04 - requesting resource sac0972.NBU_CLIENT.MAXJOBS.SAC1111
01/06/2012 09:08:04 - requesting resource sac0972.NBU_POLICY.MAXJOBS.SAC1111
01/06/2012 09:08:05 - granted resource sac0972.NBU_CLIENT.MAXJOBS.SAC1111
01/06/2012 09:08:05 - granted resource sac0972.NBU_POLICY.MAXJOBS.SAC1111
01/06/2012 09:08:05 - granted resource MediaID=@aaaa6;Path=/backup;MediaServer=sac0970
01/06/2012 09:08:05 - granted resource STU_DISK_SAC0972_2
01/06/2012 09:08:05 - estimated 0 kbytes needed
01/06/2012 09:08:05 - Info nbjm (pid=22950) started backup job for client SAC1111, policy SAC1111, schedule Mensal on storage unit STU_DISK_SAC0972_2
01/06/2012 09:08:05 - started process bpbrm (pid=7768)
01/06/2012 09:08:06 - Info bpbrm (pid=7768) SAC1111 is the host to backup data from
01/06/2012 09:08:09 - Info bpbrm (pid=7768) reading file list from client
01/06/2012 09:08:09 - connecting
01/06/2012 09:08:12 - Info bpbrm (pid=7768) starting bpbkar on client
01/06/2012 09:08:12 - connected; connect time: 0:00:00
01/06/2012 09:08:24 - Info bpbkar (pid=0) Backup started
01/06/2012 09:08:24 - Info bpbrm (pid=7768) bptm pid: 7834
01/06/2012 09:08:24 - Info bpbrm (pid=7768) from client SAC1111: TRV - BACKUP 1/6/2012 09:08:24 SAC1111 SAC1111 Mensal FULL
01/06/2012 09:08:25 - Info bptm (pid=7834) start
01/06/2012 09:08:25 - Info bptm (pid=7834) using 262144 data buffer size
01/06/2012 09:08:25 - Info bptm (pid=7834) using 32 data buffers
01/06/2012 09:08:27 - Info bptm (pid=7834) start backup
01/06/2012 09:08:28 - Info bptm (pid=7834) backup child process is pid 7848
01/06/2012 09:08:28 - begin writing

PS.: DONT WRITE DATA

BPBKAR32.EXE LOG

09:08:14.507: [7396.7248] <4> ov_log::OVInit: INF - Starting log file: C:\Arquivos de programas\Veritas\NetBackup\logs\BPBKAR\060112.LOG

09:08:14.507: [7396.7248] <4> ov_log::OVInit: GENERAL Log Level: 2
09:08:14.507: [7396.7248] <4> ov_log::OVInit: TCP Log Level: 3
09:08:14.507: [7396.7248] <4> ov_log::OVInit: INF - the log mutex: 1432
BPBKAR NetBackup Backup/Archive 6.5GA [Jan 4 2010]
Copyright 1993 - 2007 VERITAS Software Corporation
All Rights Reserved.

09:08:14.538: [7396.7248] <4> dtcp_initialize: TCP - WINSOCK.DLL Information:
09:08:14.554: [7396.7248] <4> dtcp_initialize: TCP - Version: 2.0
09:08:14.570: [7396.7248] <4> dtcp_initialize: TCP - Highest supported version: 2.2
09:08:14.601: [7396.7248] <4> dtcp_initialize: TCP - Description: WinSock 2.0
09:08:14.617: [7396.7248] <4> dtcp_initialize: TCP - System Status: Running
09:08:14.632: [7396.7248] <4> dtcp_initialize: TCP - Max Sockets: 0
09:08:14.648: [7396.7248] <2> WinMain: DAT - _pgmptr = 'C:\Arquivos de programas\Veritas\NetBackup\bin\bpbkar32.exe'
09:08:14.679: [7396.7248] <2> WinMain: DAT - lpCmdLine = '-r 2678400 -ru root -dt 0 -to 0 -clnt SAC1111 -class SAC1111 -sched Mensal -st FULL -bpstart_to 3600 -bpend_to 3600 -read_to 3600 -blks_per_buffer 512 -use_otm -fso -b SAC1111_1338552485 -kl 1 -WOFB_enabled -WOFB_fim 1 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb '
09:08:14.695: [7396.7248] <2> WinMain: DAT - INI: drive=C, dir=\Arquivos de programas\Veritas\NetBackup
09:08:14.726: [7396.7248] <2> WinMain: DAT - LOG: drive=C, dir=\Arquivos de programas\Veritas\NetBackup\logs
09:08:14.757: [7396.7248] <2> WinMain: DAT - EXE: drive=C, dir=\Arquivos de programas\Veritas\NetBackup\bin
09:08:14.773: [7396.7248] <2> date_debug: DAT - timezone: E. South America Standard Time, offset=10800, dst: Horario Brasileiro de Verao
09:08:14.804: [7396.7248] <2> date_debug: DAT - current time: 1338552494, 1/6/2012 09:08:14
09:08:14.820: [7396.7248] <2> date_debug: DAT - 01/01/94 UCT: 757382400, 31/12/1993 21:00:00
09:08:14.851: [7396.7248] <2> date_debug: DAT - 07/01/94 UCT: 773020800, 30/6/1994 21:00:00
09:08:14.882: [7396.7248] <2> WinMain: DAT - standard input handle = 744
09:08:14.898: [7396.7248] <2> WinMain: DAT - standard output handle = 1684
09:08:14.929: [7396.7248] <2> WinMain: DAT - standard error handle = 1652
09:08:14.960: [7396.7248] <2> dtcp_setsocksize: TCP - setsockopt success on SO_RCVBUF: (socket: 744) (size: 17408)
09:08:14.976: [7396.7248] <2> dtcp_setsocksize: TCP - setsockopt success on SO_SNDBUF: (socket: 744) (size: 17408)
09:08:15.007: [7396.7248] <2> dtcp_setsocksize: TCP - setsockopt success on SO_RCVBUF: (socket: 1684) (size: 17408)
09:08:15.023: [7396.7248] <2> dtcp_setsocksize: TCP - setsockopt success on SO_SNDBUF: (socket: 1684) (size: 17408)
09:08:15.054: [7396.7248] <2> dtcp_setsocksize: TCP - setsockopt success on SO_RCVBUF: (socket: 1652) (size: 16384)
09:08:15.070: [7396.7248] <2> dtcp_setsocksize: TCP - setsockopt success on SO_SNDBUF: (socket: 1652) (size: 16384)
09:08:15.101: [7396.7248] <4> tar_backup::V_SetupJobData: INF - dwJobData: ffffffff
09:08:15.132: [7396.7248] <4> tar_backup::V_SetupJobData: INF -     dwJob: ffffffff
09:08:15.163: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\admin
09:08:15.179: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\ALTPATH
09:08:15.195: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\backint
09:08:15.226: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\beds
09:08:15.242: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bmrd
09:08:15.273: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bmrsetup
09:08:15.304: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bparchive
09:08:15.335: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpbackup
09:08:15.367: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpbkar
09:08:15.382: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpbrm
09:08:15.398: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpbrmds
09:08:15.429: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpbrmvlt
09:08:15.445: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpcd
09:08:15.476: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpcompatd
09:08:15.507: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpcoord
09:08:15.523: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpdb2
09:08:15.554: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpdbjobs
09:08:15.570: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpdbm
09:08:15.585: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpdbsbdb2
09:08:15.601: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpdbsbora
09:08:15.632: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpdm
09:08:15.648: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpdynamicclient
09:08:15.695: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpfilter
09:08:15.710: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpfis
09:08:15.726: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpfsmap
09:08:15.757: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bphdb
09:08:15.773: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpinetd
09:08:15.788: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpinst
09:08:15.804: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpjava-msvc
09:08:15.835: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpjava-susvc
09:08:15.851: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpjava-usvc
09:08:15.867: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpjobd
09:08:15.882: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpkeyutil
09:08:15.913: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bplist
09:08:15.929: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpmount
09:08:15.945: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpnbat
09:08:15.960: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bporaexp
09:08:15.992: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bporaimp
09:08:16.007: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bppfi
09:08:16.023: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bprd
09:08:16.038: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpresolver
09:08:16.054: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bprestore
09:08:16.085: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpstsinfo
09:08:16.101: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpsynth
09:08:16.117: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bptm
09:08:16.132: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpVMreq
09:08:16.148: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\bpVMutil
09:08:16.179: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\dbclient
09:08:16.195: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\liveupdate
09:08:16.210: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\mtfrd
09:08:16.226: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbconsole
09:08:16.257: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbdb
09:08:16.273: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbfsd
09:08:16.304: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbftclnt
09:08:16.320: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbliveup
09:08:16.335: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbostpxy
09:08:16.351: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbproxy
09:08:16.367: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbvault
09:08:16.398: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\nbwin
09:08:16.413: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\ncf
09:08:16.429: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\ncfnbbrowse
09:08:16.460: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\patch
09:08:16.476: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\spps
09:08:16.492: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\sybackup
09:08:16.507: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\tar
09:08:16.538: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\user_ops
09:08:16.554: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\vault
09:08:16.585: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\vnetd
09:08:16.632: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\vopied
09:08:16.663: [7396.7248] <4> tar_backup_tfi::cleanupLogs: INF - Purging log files from: C:\Arquivos de programas\Veritas\NetBackup\logs\wingui
09:08:16.710: [7396.7248] <4> ncfLogConfiguration: INF - Module: libncf, Release: 7.0 , Build: 01/04/2010 17:30:00 CST (20100104)
09:08:16.757: [7396.7248] <4> ncfLogConfiguration: INF - Windows version: 5.2.3790, Platform: 2 (Service Pack 2), Service pack: 2.0, Suite: 274, Product type: 3
09:08:16.788: [7396.7248] <4> ncfLogConfiguration: INF - Process architecture: 0, Page size: 4096, Process type: 24, Process level: 586, Processor revision: 6
09:08:16.820: [7396.7248] <4> NcfString::logLocale: INF - Current code page: 1252 (ANSI - Latino I), Max. character width: 1, Substitution character: 3F 00 [?.], Unicode substitution character: 0x003f [?.]
09:08:16.851: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running as user 'SYSTEM@AUTORIDADE NT', primary group 'SYSTEM@AUTORIDADE NT'
09:08:16.882: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - New object owner 'Administradores@BUILTIN'
09:08:16.913: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Member of group 'SYSTEM@AUTORIDADE NT'
09:08:16.945: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Member of group 'Administradores@BUILTIN [SE_GROUP_ENABLED_BY_DEFAULT SE_GROUP_ENABLED SE_GROUP_OWNER]'
09:08:16.976: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Member of group 'Todos [SE_GROUP_MANDATORY SE_GROUP_ENABLED_BY_DEFAULT SE_GROUP_ENABLED]'
09:08:17.007: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Member of group 'Usu?rios autenticados@AUTORIDADE NT [SE_GROUP_MANDATORY SE_GROUP_ENABLED_BY_DEFAULT SE_GROUP_ENABLED]'
09:08:17.038: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeTcbPrivilege'
09:08:17.070: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeCreateGlobalPrivilege'
09:08:17.101: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeTakeOwnershipPrivilege'
09:08:17.132: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeCreatePagefilePrivilege'
09:08:17.163: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeLockMemoryPrivilege'
09:08:17.210: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeAssignPrimaryTokenPrivilege'
09:08:17.242: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeIncreaseQuotaPrivilege'
09:08:17.273: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeIncreaseBasePriorityPrivilege'
09:08:17.304: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeCreatePermanentPrivilege'
09:08:17.335: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeDebugPrivilege'
09:08:17.367: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeAuditPrivilege'
09:08:17.413: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeSecurityPrivilege'
09:08:17.445: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeSystemEnvironmentPrivilege'
09:08:17.492: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeChangeNotifyPrivilege'
09:08:17.523: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeBackupPrivilege'
09:08:17.554: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeRestorePrivilege'
09:08:17.585: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeShutdownPrivilege'
09:08:17.632: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeLoadDriverPrivilege'
09:08:17.663: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeProfileSingleProcessPrivilege'
09:08:17.710: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeSystemtimePrivilege'
09:08:17.742: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeUndockPrivilege'
09:08:17.773: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeManageVolumePrivilege'
09:08:17.804: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Running with privilege 'SeImpersonatePrivilege'
09:08:17.835: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable =C:=C:\Arquivos de programas\Veritas\NetBackup
09:08:17.867: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable ALLUSERSPROFILE=C:\Documents and Settings\All Users
09:08:17.898: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable ClusterLog=C:\WINDOWS\Cluster\cluster.log
09:08:17.929: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable CommonProgramFiles=C:\Arquivos de programas\Arquivos comuns
09:08:17.960: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable COMPUTERNAME=SAC1111
09:08:17.992: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable ComSpec=C:\WINDOWS\system32\cmd.exe
09:08:18.023: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable FP_NO_HOST_CHECK=NO
09:08:18.054: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable IS_NETBACKUP_DAEMON=YES
09:08:18.085: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable NUMBER_OF_PROCESSORS=24
09:08:18.117: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable OS=Windows_NT
09:08:18.148: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable OvAgentDir=C:\Documents and Settings\All Users\Dados de aplicativos\HP\HP BTO Software\
09:08:18.179: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable OvDataDir=C:\Documents and Settings\All Users\Dados de aplicativos\HP\HP BTO Software\
09:08:18.210: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable OvInstallDir=C:\Arquivos de programas\HP\HP BTO Software\
09:08:18.242: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable OVPERLLIB=C:\Arquivos de programas\HP\HP BTO Software\nonOV\Perl\a\lib
09:08:18.273: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable Path=C:\Arquivos de programas\HP\NCU;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\Arquivos de programas\HP\HP BTO Software\bin;C:\Arquivos de programas\HP\HP BTO Software\bin\OpC;C:\Arquivos de programas\HP\HP BTO Software\bin\;C:\Arquivos de programas\HP\HP BTO Software\lib\
09:08:18.320: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH
09:08:18.351: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable PROCESSOR_ARCHITECTURE=x86
09:08:18.382: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable PROCESSOR_IDENTIFIER=x86 Family 6 Model 44 Stepping 2, GenuineIntel
09:08:18.413: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable PROCESSOR_LEVEL=6
09:08:18.445: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable PROCESSOR_REVISION=2c02
09:08:18.476: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable ProgramFiles=C:\Arquivos de programas
09:08:18.507: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable SystemDrive=C:
09:08:18.538: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable SystemRoot=C:\WINDOWS
09:08:18.570: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable TEMP=C:\WINDOWS\TEMP
09:08:18.601: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable TMP=C:\WINDOWS\TEMP
09:08:18.632: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable USERPROFILE=C:\Documents and Settings\Default User
09:08:18.710: [7396.7248] <4> ImpersonatePlatform::logImpersonation: INF - Environment variable windir=C:\WINDOWS
09:08:18.757: [7396.7248] <4> dos_backup::V_PreProcessing: INF - backup privileges enabled, previous = 0
09:08:18.788: [7396.7248] <4> dos_backup::V_PreProcessing: INF - restore privileges enabled, previous = 0
09:08:18.820: [7396.7248] <4> dos_backup::V_PreProcessing: INF - security privileges enabled, previous = 0
09:08:18.835: [7396.7248] <4> dos_backup::V_PreProcessing: INF - tcb privileges enabled, previous = 0
09:08:18.851: [7396.7248] <4> dos_backup::V_PreProcessing: INF - create token privileges enabled, previous = 0
09:08:18.882: [7396.7248] <4> dos_backup::V_PreProcessing: INF - user name: root
09:08:18.898: [7396.7248] <4> dos_backup::V_PreProcessing: INF - no access token: scheduled backup
09:08:18.913: [7396.7248] <2> ov_log::V_GlobalLog: ERR - ubsDetermineExchangeVersion():RegQueryValueEx() failed - 0x2.
09:08:18.945: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEDS_Init() Enter InitFlags:0x0
09:08:18.976: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEDS BackupMethod(1)
09:08:19.007: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetRestoreForceRecovery(0)
09:08:19.038: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetNDMPAuthType(2)
09:08:19.054: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseLastLogNumber(0xfffffffe)
09:08:19.070: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetXchBackupMethod(1)
09:08:19.085: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetXchgNoLossRestore(1)
09:08:19.132: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseNoLossRestore(1)
09:08:19.148: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseConsistencyCheck(1)
09:08:19.163: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseContinueConsistencyCheck(1)
09:08:19.179: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSingleInstanceBackupForMessageAttachments(0)
09:08:19.195: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseBackupFromReplica(0)
09:08:19.226: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseDisMountBeforeRestore(0)
09:08:19.257: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseMountAfterRestore(0)
09:08:19.273: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseLastBackupSet(0)
09:08:19.288: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMS_SetProd(CMS_PROD_NBU)
09:08:19.304: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetAllowRedirAtFileLevel(1)
09:08:19.335: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseNoVff(1)
09:08:19.367: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseDontRemountAfter(0)
09:08:19.382: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEseEnableBeforeRestore(0)
09:08:19.398: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetPostponeEOL(3)
09:08:19.413: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetLoggingFunc(1)
09:08:19.429: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetRestoreSecurity(1)
09:08:19.460: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlDatabaseRecover(1)
09:08:19.492: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlRestStandBy(0)
09:08:19.507: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlReplaceDatabase(0)
09:08:19.523: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlAutoMaster(0)
09:08:19.538: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetPostRestDBCC(2)
09:08:19.570: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlDefaultDrive(67)
09:08:19.585: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlUseDefaultDrive(1)
09:08:19.617: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlAllToDefault(1)
09:08:19.632: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlUseDefaultInstanceDirectory(0)
09:08:19.663: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlPointInTimeRestore(0)
09:08:19.679: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlPointInTimeRestoreTime(0.000000)
09:08:19.695: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlLogMarkRestore(0)
09:08:19.726: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlLogMarkName(NULL)
09:08:19.742: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlLogMarkStopBefore(0)
09:08:19.757: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlLogMarkAfterTime(0)
09:08:19.788: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSqlLogMarkRestoreTime(0.000000)
09:08:19.804: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetRestoreXchgPrivate(1)
09:08:19.820: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetRestoreXchgPublic(1)
09:08:19.835: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsContOnDBCCError(0)
09:08:19.867: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsCommitRest(0)
09:08:19.882: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsPostRestDBCC(0)
09:08:19.898: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsPostBkupDBCC(0)
09:08:19.929: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsPreBkupDBCC(0)
09:08:19.945: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSharePointRestoreOverExisting(0)
09:08:19.960: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsVerRestoreOverExisting(0)
09:08:20.070: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsRestoreCurrentVer(0)
09:08:20.085: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsIgnoreLock(0)
09:08:20.101: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsPreserveIis(0)
09:08:20.132: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetSpsRestoreSecurity(0)
09:08:20.148: [7396.7248] <2> ov_log::V_GlobalLog: INF - (pBEC_Glue->bAllowFQDN(0)
09:08:20.163: [7396.7248] <2> ComputerNameMgr::setName: DBG - Changing computer name to SAC1111 (ComputerName.cpp:92)
09:08:20.210: [7396.7248] <2> ov_log::V_GlobalLog: INF - SetComputerName(SAC1111)
09:08:20.226: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEC_SetEnableGranularRestore(0)
09:08:20.242: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_InitFileSys
09:08:20.288: [7396.7248] <2> ov_log::V_GlobalLog: INF - VirtApi DLL WAS NOT LOADED, from VirtApi.dll!!
09:08:20.320: [7396.7248] <2> ov_log::V_GlobalLog: INF - LoadLibraryEx FAILED! RC = 126 (0x7e) - N?o foi poss?vel encontrar o m?dulo especificado.!!!
09:08:20.351: [7396.7248] <2> ov_log::V_GlobalLog: INF -   loaded bedsxese.dll
09:08:20.367: [7396.7248] <2> ov_log::V_GlobalLog: INF -   loaded bedsshadow.dll
09:08:20.382: [7396.7248] <2> ov_log::V_GlobalLog: INF -   loaded bedsnt5.dll
09:08:20.413: [7396.7248] <2> ov_log::V_GlobalLog: INF -   loaded bedsss.dll
09:08:20.445: [7396.7248] <2> ov_log::V_GlobalLog: INF - VirtApi DLL WAS NOT LOADED, from VirtApi.dll!!
09:08:20.460: [7396.7248] <2> ov_log::V_GlobalLog: INF - LoadLibraryEx FAILED! RC = 126 (0x7e) - N?o foi poss?vel encontrar o m?dulo especificado.!!!
09:08:20.492: [7396.7248] <2> ov_log::V_GlobalLog: INF -   loaded bedsadgran.dll
09:08:20.523: [7396.7248] <2> ov_log::V_GlobalLog: INF -   loaded bedssql2.dll
09:08:20.538: [7396.7248] <2> ov_log::V_GlobalLog: INF -   loaded bedsev.dll
09:08:20.570: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::SetLoggingLevel - Setting verbose level = 4.
09:08:20.585: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - entering
09:08:20.617: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - entering.
09:08:20.632: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::CEVInterface - entering.
09:08:20.679: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::CEVInterface - exiting.
09:08:20.695: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - Instance created successfully.
09:08:20.726: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - exiting.
09:08:20.742: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - entering.
09:08:20.773: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::SetEVVersion - entering.
09:08:20.788: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::SetEVVersion - Failed to open EV Install key (SOFTWARE\KVS\Enterprise Vault\Install).
09:08:20.804: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::SetEVVersion - Obtained the status: 1
09:08:20.835: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::SetEVVersion - Ev Version Information: Maj Ver = 0, Min ver = 0
09:08:20.867: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::SetEVVersion - exiting.
09:08:20.882: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - EV Instance could not be ascertained.
09:08:20.913: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - exiting.
09:08:20.929: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVVersion - entering.
09:08:20.945: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVVersion - exiting.
09:08:20.976: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - BEDSEV - A supported version of EV 8 and above found.
09:08:21.007: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - exiting
09:08:21.023: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::CreateEVDleAgent - entering.
09:08:21.038: [7396.7248] <2> ov_log::V_GlobalLog: INF - [AgentID:25] ... failed to load bedstrace.dll.
09:08:21.070: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleGen: Failure to create debug trace object at line number 102
09:08:21.085: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::CreateEVDleAgent - exiting.
09:08:21.117: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - entering
09:08:21.132: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - entering.
09:08:21.148: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - exiting.
09:08:21.163: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - entering.
09:08:21.195: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - exiting.
09:08:21.210: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - BEDSEV - Loading BEAO function table.
09:08:21.242: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - exiting
09:08:21.257: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::CreateBEAODleAgent - entering.
09:08:21.273: [7396.7248] <2> ov_log::V_GlobalLog: INF - [AgentID:2a] ... failed to load bedstrace.dll.
09:08:21.304: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleGen: Failure to create debug trace object at line number 102
09:08:21.320: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::CreateBEAODleAgent - Successfully created FS_DleBEAO object.
09:08:21.335: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::CreateBEAODleAgent - exiting.
09:08:21.351: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - entering
09:08:21.382: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - entering.
09:08:21.398: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - exiting.
09:08:21.413: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - entering.
09:08:21.429: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - exiting.
09:08:21.460: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetTable - exiting
09:08:21.476: [7396.7248] <2> ov_log::V_GlobalLog: INF - Initializing FSs
09:08:21.507: [7396.7248] <2> ov_log::V_GlobalLog: INF - IsIDRInProgressPriv: 0x0!
09:08:21.538: [7396.7248] <2> ov_log::V_GlobalLog: INF - IsIDRInProgressPriv: 0x0!
09:08:21.554: [7396.7248] <2> ov_log::V_GlobalLog: INF - Informational: Initializing the BeDiskFind library 'BEDiskFind.dll' in SHADOW::InitBeDiskFindHelperApis
09:08:21.570: [7396.7248] <2> ov_log::V_GlobalLog: INF - Status CODE (0x0000007E) loading BeDiskFind library 'BEDiskFind.dll' in SHADOW::InitBeDiskFindHelperApis
09:08:21.585: [7396.7248] <2> ov_log::V_GlobalLog: INF - Status CODE (0x0000007E) initializing BeDiskFind library in SHADOW::InitFsys
09:08:21.601: [7396.7248] <2> ov_log::V_GlobalLog: INF - Informational: Initializing the BeDisk library 'BeDisk.dll' in SHADOW::InitBeDiskHelperApis
09:08:21.632: [7396.7248] <2> ov_log::V_GlobalLog: INF - Status CODE (0x0000007E) loading BeDisk library 'BeDisk.dll' in SHADOW::InitBeDiskHelperApis
09:08:21.648: [7396.7248] <2> ov_log::V_GlobalLog: INF - Status CODE (0x0000007E) initializing BeDisk library in SHADOW::InitFsys
09:08:21.679: [7396.7248] <2> ov_log::V_GlobalLog: INF - first load attempt of esebcli2.dll failed: N?o foi poss?vel encontrar o m?dulo especificado.!!
09:08:21.757: [7396.7248] <2> ov_log::V_GlobalLog: INF - Looking for esebcli2.dll in sysetm path
09:08:21.788: [7396.7248] <2> ov_log::V_GlobalLog: INF - never found EseBcli2.dll
09:08:21.804: [7396.7248] <2> ov_log::V_GlobalLog: INF - esebcli2.dll not loaded
09:08:21.867: [7396.7248] <2> ov_log::V_GlobalLog: INF - *** MSExchangeIS failed to get binary path
09:08:21.898: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::InitFsys - entering.
09:08:21.929: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::InitFsys - Initialised COM in Multithreaded model
09:08:21.945: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVProdSpecBECSettings::InitInstance - Created Instance of CEVProdSpecBECSettings class.
09:08:21.960: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVProdSpecBECSettings::GetXMLCleanupState - BEC variable bXMLCleanup = (0).
09:08:21.976: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::InitFsys - exiting.
09:08:21.992: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::InitFsys - entering.
09:08:22.007: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::InitFsys - Initialised COM in Multithreaded model
09:08:22.038: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVProdSpecBECSettings::GetXMLCleanupState - BEC variable bXMLCleanup = (0).
09:08:22.054: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::InitFsys - exiting.
09:08:22.070: [7396.7248] <2> ov_log::V_GlobalLog: INF - Input Error (       0) for Type: (43)
09:08:22.085: [7396.7248] <2> ov_log::V_GlobalLog: INF - BEDS_Init() BEDS debgging will be enabled - dwDebugLevel = 2.
09:08:22.101: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetServerType for local machine
09:08:22.132: [7396.7248] <2> ov_log::V_GlobalLog: INF - Finding MNET entries using PunchDownWithWNetCalls()
09:08:22.163: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetServerType for local machine
09:08:22.179: [7396.7248] <2> ov_log::V_GlobalLog: INF - Device Shadow?Copy?Components Dle platform 2 major version 5 minor version 2 build 3790
09:08:22.210: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:DeviceName "System?State" in SystemState::CreateDLEs:376
09:08:22.226: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:Full Device Path "System?State" in SystemState::CreateDLEs:381
09:08:22.242: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:ADRO Agent is authorized for System?State.
09:08:22.288: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:Found 0 instances of Active Directory Applcation Mode in SystemState::GetADAMInstanceCount:1418
09:08:22.304: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:DeviceName "Active Directory Application Mode" in SystemState::CreateDLEs:376
09:08:22.320: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:Full Device Path "Active Directory Application Mode" in SystemState::CreateDLEs:381
09:08:22.351: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:ADRO Agent is authorized for Active Directory Application Mode.
09:08:22.367: [7396.7248] <2> ov_log::V_GlobalLog: INF - SQL2_FindDrives - the default SQL Service is not running on SAC1111.
09:08:22.382: [7396.7248] <2> ov_log::V_GlobalLog: INF - [FSYS:ESE07]   FindDrives ... This is not an Exchange Server (0) !
09:08:22.429: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::FindDrives - entering.
09:08:22.445: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVXMLWrapper::CEVXMLWrapper - entering.
09:08:22.460: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVXMLWrapper::CEVXMLWrapper - exiting.
09:08:22.492: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVXMLWrapper::Init - entering.
09:08:22.507: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVXMLWrapper::Refresh - entering.
09:08:22.538: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::GetInstance - entering.
09:08:22.570: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::CEVTopologyHandler - entering.
09:08:22.585: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::CEVTopologyHandler - exiting.
09:08:22.601: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::GetInstance - Instance created successfully.
09:08:22.617: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::Init - entering.
09:08:22.648: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::AreXSLFilesPresent - entering
09:08:22.679: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetXSLScriptPath - entering
09:08:22.695: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - entering
09:08:22.726: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - Found the Key Software\VERITAS\NetBackup\CurrentVersion.
09:08:22.757: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - "INI directory" value loaded at Software\VERITAS\NetBackup\CurrentVersion.
09:08:22.773: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - exiting
09:08:22.788: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetXSLScriptPath - exiting
09:08:22.820: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::AreXSLFilesPresent - EV XSL file (C:\Arquivos de programas\Veritas\\NetBackup\scripts\ev\EV80Advertise.xsl) found.
09:08:22.851: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::AreXSLFilesPresent - EV XSL file (C:\Arquivos de programas\Veritas\\NetBackup\scripts\ev\EV80Drives.xsl) found.
09:08:22.882: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVProdSpecBECSettings::GetAcclSupportState - BEC variable bAcclSupport = (0).
09:08:22.898: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::AreXSLFilesPresent - exiting
09:08:22.929: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::PrepareEVBeaoXML - entering.
09:08:22.960: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetXSLScriptPath - entering
09:08:22.976: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - entering
09:08:22.992: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - Found the Key Software\VERITAS\NetBackup\CurrentVersion.
09:08:23.023: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - "INI directory" value loaded at Software\VERITAS\NetBackup\CurrentVersion.
09:08:23.054: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetRAWSInstallPath - exiting
09:08:23.070: [7396.7248] <2> ov_log::V_GlobalLog: INF - CMiscUtils::GetXSLScriptPath - exiting
09:08:23.085: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::PrepareEVBeaoXML - AdvertiseXSLPath = (C:\Arquivos de programas\Veritas\\NetBackup\scripts\ev\EV80Advertise.xsl)
09:08:23.117: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::PrepareEVBeaoXML - DrivesXSLPath = (C:\Arquivos de programas\Veritas\\NetBackup\scripts\ev\EV80Drives.xsl)
09:08:23.132: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::PrepareEVBeaoXML - exiting.
09:08:23.163: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVProdSpecBECSettings::GetAcclSupportState - BEC variable bAcclSupport = (0).
09:08:23.179: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::Init - XMLWrapper Initialization Done.
09:08:23.195: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::Init - exiting.
09:08:23.226: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::GetInstance - exiting.
09:08:23.242: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::RequestAndLoadXML - entering for EV.
09:08:23.273: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - entering.
09:08:23.288: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - exiting.
09:08:23.320: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::RequestXML - entering.
09:08:23.335: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - entering.
09:08:23.367: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - exiting.
09:08:23.382: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::RequestXML - This EV version is not supported by Backup Exec.
09:08:23.398: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::RequestAndLoadXML - Failed to request XML. Low memory or Service may not be running.
09:08:23.429: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVTopologyHandler::RequestAndLoadXML - exiting.
09:08:23.445: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVXMLWrapper::Refresh - Could not request & load EV XML.
09:08:23.476: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVXMLWrapper::Refresh - exiting.
09:08:23.492: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVXMLWrapper::Init - exiting.
09:08:23.523: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::FindDrives - EV_FindDrives: RefreshTopology() failed.
09:08:23.554: [7396.7248] <2> ov_log::V_GlobalLog: INF - Status 0x00000001 returned calling FindDrives for file system 37 in DLE_UpdateList
09:08:23.570: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::FindDrives - entering.
09:08:23.585: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - entering.
09:08:23.617: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - exiting.
09:08:23.663: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - entering.
09:08:23.679: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - exiting.
09:08:23.695: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::FindDrives - BEAO is not installed on this machine. Not creating any DLEs.
09:08:23.710: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::FindDrives - exiting.
09:08:23.742: [7396.7248] <2> ov_log::V_GlobalLog: INF - Input Error (       0) for Type: (43)
09:08:23.757: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: C:
09:08:23.804: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Rede de cliente da Web
09:08:23.820: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Rede Microsoft Windows
09:08:23.835: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Servi?os de terminal da Microsoft
09:08:23.867: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Symantec SNAC Network Provider
09:08:23.882: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Shadow?Copy?Components
09:08:23.913: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: System?State
09:08:23.929: [7396.7248] <2> ov_log::V_GlobalLog: INF - DumpDleInfo() DLE Device Name: Active Directory Application Mode
09:08:23.945: [7396.7248] <2> ov_log::V_GlobalLog: INF - Comparing requested computer(SAC1111) and local computer(SAC1111)
09:08:23.976: [7396.7248] <2> BEDSContext::setProdID(): DBG - CMS_SetProd(1)
09:08:24.007: [7396.7248] <2> BEDSContext::_discover(): DBG - Computer Name SAC1111
09:08:24.023: [7396.7248] <2> BEDSContext::_discover(): DBG - Unable to resolve_key for Lotus Notes Plug-in
09:08:24.054: [7396.7248] <2> BEDSContext::_discover(): DBG - Unable to locate info for Oracle Plug-in
09:08:24.070: [7396.7248] <2> BEDSContext::_discover(): DBG - Unable to locate info for DB2 Plug-in
09:08:24.101: [7396.7248] <2> SubContextBEDS_Impl::_initialize(): DBG - BEDS is initialized!
09:08:24.117: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetServerType for local machine
09:08:24.148: [7396.7248] <2> ov_log::V_GlobalLog: INF - Finding MNET entries using PunchDownWithWNetCalls()
09:08:24.179: [7396.7248] <2> ov_log::V_GlobalLog: INF - GetServerType for local machine
09:08:24.195: [7396.7248] <2> ov_log::V_GlobalLog: INF - Device Shadow?Copy?Components Dle platform 2 major version 5 minor version 2 build 3790
09:08:24.226: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:DeviceName "System?State" in SystemState::CreateDLEs:376
09:08:24.242: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:Full Device Path "System?State" in SystemState::CreateDLEs:381
09:08:24.257: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:ADRO Agent is authorized for System?State.
09:08:24.288: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:Found 0 instances of Active Directory Applcation Mode in SystemState::GetADAMInstanceCount:1418
09:08:24.320: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:DeviceName "Active Directory Application Mode" in SystemState::CreateDLEs:376
09:08:24.335: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:Full Device Path "Active Directory Application Mode" in SystemState::CreateDLEs:381
09:08:24.351: [7396.7248] <2> ov_log::V_GlobalLog: INF -   AD:ADRO Agent is authorized for Active Directory Application Mode.
09:08:24.382: [7396.7248] <2> ov_log::V_GlobalLog: INF - SQL2_FindDrives - the default SQL Service is not running on SAC1111.
09:08:24.398: [7396.7248] <2> ov_log::V_GlobalLog: INF - [FSYS:ESE07]   FindDrives ... This is not an Exchange Server (0) !
09:08:24.429: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::FindDrives - entering.
09:08:24.445: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleEV::FindDrives - EV Agent not authorized.
09:08:24.460: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::FindDrives - entering.
09:08:24.476: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - entering.
09:08:24.507: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetInstance - exiting.
09:08:24.538: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - entering.
09:08:24.554: [7396.7248] <2> ov_log::V_GlobalLog: INF - CEVInterface::GetEVAppType - exiting.
09:08:24.570: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::FindDrives - BEAO is not installed on this machine. Not creating any DLEs.
09:08:24.585: [7396.7248] <2> ov_log::V_GlobalLog: INF - FS_DleBEAO::FindDrives - exiting.
09:08:24.617: [7396.7248] <2> ov_log::V_GlobalLog: INF - Input Error (       0) for Type: (43)
09:08:24.617: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : C:
09:08:24.679: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : Rede de cliente da Web
09:08:24.695: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : Rede Microsoft Windows
09:08:24.710: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : Servi?os de terminal da Microsoft
09:08:24.742: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : Symantec SNAC Network Provider
09:08:24.757: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : Shadow?Copy?Components
09:08:24.773: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : System?State
09:08:24.788: [7396.7248] <2> _dumpDLEInfo(): DBG - Device Name : Active Directory Application Mode
09:08:24.804: [7396.7248] <2> tar_backupt_tfi::create: TAR - Backup started at 1/6/2012 09:08:24
09:08:24.820: [7396.7248] <2> tar_base::V_vTarMsgW: INF - Inform when done
09:08:24.851: [7396.7248] <2> dtcp_write: TCP - success: send socket (1652), 23 of 23 bytes
09:08:24.867: [7396.7248] <2> tar_base::V_vTarMsgW: INF - Echo keepalives
09:08:24.867: [7396.7248] <2> dtcp_write: TCP - success: send socket (1652), 22 of 22 bytes
09:08:24.898: [7396.7248] <2> tar_base::V_vTarMsgW: INF - BACKUP START
09:08:24.913: [7396.7248] <2> dtcp_write: TCP - success: send socket (1652), 19 of 19 bytes
09:08:24.929: [7396.7248] <2> tar_base::V_vTarMsgW: TRV - BACKUP 1/6/2012 09:08:24 SAC1111 SAC1111 Mensal FULL
09:08:24.945: [7396.7248] <2> dtcp_write: TCP - success: send socket (1652), 60 of 60 bytes
09:08:24.976: [7396.7248] <2> dtcp_read: TCP - success: recv socket (744), 14 of 14 bytes
09:08:25.007: [7396.7248] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received
09:08:25.023: [7396.7248] <2> tar_backup_tfi::setupFileDirectives: TAR - Processing filename list
09:08:25.038: [7396.7248] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:08:25.070: [7396.7248] <2> dtcp_read: TCP - success: recv socket (744), 10 of 10 bytes
09:08:25.101: [7396.7248] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = C:\WCS-FTP
09:08:25.117: [7396.7248] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:08:25.132: [7396.7248] <2> dtcp_read: TCP - success: recv socket (744), 8 of 8 bytes
09:08:25.148: [7396.7248] <4> tar_base::startKeepaliveThread: INF - keepalive thread started
09:08:25.179: [7396.6112] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds
09:08:25.210: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:08:25.226: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:08:25.242: [7396.7248] <2> tar_backup_vxbsa::add: INF - called with 'C:\WCS-FTP'
09:08:25.273: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:08:25.288: [7396.7248] <4> dos_backup::V_VerifyFileSystem: INF - Verifying: C:\WCS-FTP
09:08:25.320: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:08:25.351: [7396.7248] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'C:\WCS-FTP' --> 10020002
09:08:25.382: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:08:25.413: [7396.7248] <2> ov_log::V_GlobalLog: INF - v_beds::V_FindFirst() ENTER Name:Shadow Copy Components Mode:0
09:08:25.429: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:08:25.460: [7396.7248] <2> ov_log::V_GlobalLog: INF - bedsShadowCopyInit():ENTER (Reason:2048)
09:08:25.507: [7396.7248] <2> ov_log::V_GlobalLog: INF - bedsShadowCopyInit():Found Resource DLE for 'Shadow?Copy?Components'
09:08:25.538: [7396.7248] <2> ov_log::V_GlobalLog: DBG - v_beds::V_FindFirst() Device:Shadow Copy Components Obj: Pattern:(null)
09:08:25.570: [7396.7248] <2> ov_log::V_GlobalLog: INF - Status E_NOINTERFACE (0x80004002) returned creating IVssBackupComponentsEx2 interface when initializing shadow copy
09:08:25.617: [7396.7248] <2> ov_log::V_GlobalLog: INF - Calling IVssBackupComponents::GatherWriterMetadata...
09:08:26.101: [7396.7248] <2> ov_log::V_GlobalLog: INF - ...completed IVssBackupComponents::GatherWriterMetadata
09:08:26.132: [7396.7248] <2> ov_log::V_GlobalLog: INF - brUtil::brUtil( img ) Constructor
09:08:26.163: [7396.7248] <2> ov_log::V_GlobalLog: INF - Successfully attached to Device 'Shadow?Copy?Components' BackupReason:0x800
09:09:25.460: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:09:25.492: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:09:25.507: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:09:25.523: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:09:25.538: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:09:25.570: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:10:25.585: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:10:25.617: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:10:25.648: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:10:25.663: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:10:25.695: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:10:25.726: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:11:25.742: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:11:25.773: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:11:25.788: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:11:25.804: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:11:25.835: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:11:25.851: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:12:25.867: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:12:25.867: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:12:25.898: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:12:25.929: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:12:25.945: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:12:25.960: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:13:25.976: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:13:25.992: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:13:26.007: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:13:26.038: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:13:26.054: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:13:26.070: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:14:26.085: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:14:26.101: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:14:26.132: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:14:26.148: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:14:26.163: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:14:26.179: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:15:26.226: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:15:26.242: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:15:26.257: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:15:26.288: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:15:26.320: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:15:26.351: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:16:26.382: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:16:26.398: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:16:26.413: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:16:26.445: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:16:26.476: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:16:26.492: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:17:26.523: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:17:26.554: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:17:26.585: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:17:26.601: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:17:26.632: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:17:26.663: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:18:26.695: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:18:26.710: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:18:26.726: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:18:26.757: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:18:26.788: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:18:26.820: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:19:26.851: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:19:26.898: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:19:26.929: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:19:26.992: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:19:27.007: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:19:27.038: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes
09:20:27.085: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 4 of 4 bytes
09:20:27.101: [7396.6112] <4> bpio::read_string: INF - read non-blocking message of length 1
09:20:27.148: [7396.6112] <2> dtcp_read: TCP - success: recv socket (744), 1 of 1 bytes
09:20:27.163: [7396.6112] <4> tar_backup::readServerMessage: INF - keepalive message received
09:20:27.179: [7396.6112] <4> tar_base::keepaliveThread: INF - sending keepalive
09:20:27.210: [7396.6112] <2> dtcp_write: TCP - success: send socket (1652), 1 of 1 bytes

BPINETD.LOG

09:07:05.663: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:08:05.492: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:05.523: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:05.554: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:05.570: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:05.585: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:05.617: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:05.632: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:05.679: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:05.695: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:05.710: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:05.726: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:05.757: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:08:05.773: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:05.788: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (744)
09:08:05.804: [1416.6400] <4> V_SpawnProcess: INF - accepted socket: 744
09:08:05.835: [1416.6400] <4> V_SpawnProcess: INF - VNETD process started
09:08:05.851: [1416.6400] <2> dtcp_close: TCP - success: close socket (744)
09:08:06.038: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:06.085: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.101: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.117: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.132: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.163: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.195: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:06.210: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.226: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.257: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.273: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.304: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.335: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (756)
09:08:06.351: [1416.6136] <4> V_SpawnProcess: INF - accepted socket: 756
09:08:06.382: [1416.6136] <4> V_SpawnProcess: INF - VNETD process started
09:08:06.413: [1416.6136] <2> dtcp_close: TCP - success: close socket (756)
09:08:06.726: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:06.757: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.773: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.788: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.835: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.851: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.882: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:06.898: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.929: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:06.945: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.960: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:06.992: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:07.007: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (732)
09:08:07.038: [1416.3732] <4> V_SpawnProcess: INF - accepted socket: 732
09:08:07.054: [1416.3732] <4> V_SpawnProcess: INF - VNETD process started
09:08:07.085: [1416.3732] <2> dtcp_close: TCP - success: close socket (732)
09:08:07.132: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:07.163: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:07.179: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:07.210: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:07.226: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:07.242: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:07.273: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:07.288: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:07.320: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:07.335: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:07.367: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:07.382: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:07.398: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (748)
09:08:07.429: [1416.2120] <4> V_SpawnProcess: INF - accepted socket: 748
09:08:07.460: [1416.2120] <4> V_SpawnProcess: INF - VNETD process started
09:08:07.492: [1416.2120] <2> dtcp_close: TCP - success: close socket (748)
09:08:09.351: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:09.382: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:09.398: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:09.445: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:09.460: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:09.476: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:09.492: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:09.538: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:09.554: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:09.570: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:09.601: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:09.617: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:09.648: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (736)
09:08:09.695: [1416.444] <4> V_SpawnProcess: INF - accepted socket: 736
09:08:09.851: [1416.444] <4> V_SpawnProcess: INF - VNETD process started
09:08:09.992: [1416.444] <2> dtcp_close: TCP - success: close socket (736)
09:08:10.101: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:10.132: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:10.163: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:10.195: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:10.210: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:10.242: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:10.257: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:10.288: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:10.304: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:10.335: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:10.351: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:10.367: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:10.382: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (760)
09:08:10.413: [1416.6944] <4> V_SpawnProcess: INF - accepted socket: 760
09:08:10.445: [1416.6944] <4> V_SpawnProcess: INF - VNETD process started
09:08:10.445: [1416.6944] <2> dtcp_close: TCP - success: close socket (760)
09:08:11.195: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:11.242: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.257: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.288: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.304: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.320: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.351: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:11.367: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.382: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.413: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.429: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.460: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.476: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (744)
09:08:11.492: [1416.1492] <4> V_SpawnProcess: INF - accepted socket: 744
09:08:11.523: [1416.1492] <4> V_SpawnProcess: INF - VNETD process started
09:08:11.538: [1416.1492] <2> dtcp_close: TCP - success: close socket (744)
09:08:11.726: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:11.773: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.788: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.804: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.835: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.867: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.882: [1416.1748] <2> dtcp_showoptions: TCP - socket (linger): iErr=0, optlen=4, onoff=0, linger=0
09:08:11.898: [1416.1748] <2> dtcp_showoptions: TCP - socket (oob inline): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.929: [1416.1748] <2> dtcp_showoptions: TCP - socket (keepalive): iErr=0, optlen=4, optval=1 (0x1)
09:08:11.945: [1416.1748] <2> dtcp_showoptions: TCP - socket (send timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.960: [1416.1748] <2> dtcp_showoptions: TCP - socket (recv timeout): iErr=0, optlen=4, optval=0 (0x0)
09:08:11.992: [1416.1748] <2> dtcp_showoptions: TCP - socket (debug): iErr=0, optlen=4, optval=0 (0x0)
09:08:12.023: [1416.1748] <2> dtcp_accept: TCP - success: accept socket (756)
09:08:12.038: [1416.7580] <4> V_SpawnProcess: INF - accepted socket: 756
09:08:12.054: [1416.7580] <4> V_SpawnProcess: INF - VNETD process started
09:08:12.085: [1416.7580] <2> dtcp_close: TCP - success: close socket (756)
09:09:05.773: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:10:05.788: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:11:05.835: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:12:05.867: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:13:05.913: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:14:05.929: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:15:05.945: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:16:05.976: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:17:05.992: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:18:06.007: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:19:06.054: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:20:06.085: [1416.1484] <4> ov_log::OVLoop: Timestamp
09:21:06.117: [1416.1484] <4> ov_log::OVLoop: Timestamp

VNETD.LOG

09:08:05.882 [5772.6044] <2> setup_debug_log: switched debug log file for VNETD
09:08:05.882 [5772.6044] <2> main: VERBOSE = 5
09:08:05.882 [5772.6044] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:05.882 [5772.6044] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:05.882 [5772.6044] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.45423 TO 10.8.6.149.13724 fd = 744
09:08:05.898 [5772.6044] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:06.038 [5772.6044] <2> ProcessRequests: .\vnetd.c.627: msg: Request VN_REQUEST_SERVICE_SOCKET(6)
09:08:06.038 [5772.6044] <2> process_service_socket: .\vnetd.c.1365: service_name: bpcd
09:08:06.038 [5772.6044] <2> process_service_socket_plus: .\vnetd.c.1410: service_name: bpcd
09:08:06.038 [5772.6044] <2> vtext_failure: ../../libvlibs/vtext.c.92: Function vtext_open failed: 7
09:08:06.038 [5772.6044] <2> vnet_read_service: ../../libvlibs/vnet_text.c.554: Function failed: 19 0x00000013
09:08:06.038 [5772.6044] <2> vnet_read_service_file: ../../libvlibs/vnet_text.c.477: Function failed: 19 0x00000013
09:08:06.038 [5772.6044] <2> process_service_socket_plus: .\vnetd.c.1429: vnet_read_service_file failed: 19 0x00000013
09:08:06.038 [5772.6044] <2> process_service_socket_plus: .\vnetd.c.1420: service_name: inetd_bpcd
09:08:06.038 [5772.6044] <2> launch_command: .\vnetd.c.2034: path: C:\Arquivos de programas\Veritas\NetBackup\bin\bpcd.exe
09:08:06.429 [6124.5716] <2> setup_debug_log: switched debug log file for VNETD
09:08:06.429 [6124.5716] <2> main: VERBOSE = 5
09:08:06.445 [6124.5716] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:06.445 [6124.5716] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:06.445 [6124.5716] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.45430 TO 10.8.6.149.13724 fd = 756
09:08:06.445 [6124.5716] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:06.585 [6124.5716] <2> ProcessRequests: .\vnetd.c.648: msg: Request VN_REQUEST_CONNECT_FORWARD_SOCKET(10)
09:08:06.585 [6124.5716] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1750: hash_str1: d3267fde89c5fb13ae998de8a2c45c7f
09:08:06.585 [6124.5716] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1751: hash_str2: 137b90b1b36c6aed52a0f39af3f9734b
09:08:06.585 [6124.5716] <2> process_connect_forward_socket: .\vnetd.c.1804: ipc_string: 2628
09:08:06.585 [6124.5716] <2> process_connect_forward_socket: .\vnetd.c.1817: hash_str1: d3267fde89c5fb13ae998de8a2c45c7f
09:08:06.585 [6124.5716] <2> vnet_send_network_socket: ../../libvlibs/vnet_vnetd.c.1544: hash_str2: 137b90b1b36c6aed52a0f39af3f9734b
09:08:06.585 [6124.5716] <2> ProcessRequests: .\vnetd.c.650: status: 0 0x00000000
09:08:06.585 [6124.5716] <2> main: .\vnetd.c.374: ProcessRequests returned: 0 0x00000000
09:08:07.117 [3128.1008] <2> setup_debug_log: switched debug log file for VNETD
09:08:07.117 [3128.1008] <2> main: VERBOSE = 5
09:08:07.117 [3128.1008] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:07.117 [3128.1008] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:07.117 [3128.1008] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.45447 TO 10.8.6.149.13724 fd = 732
09:08:07.117 [3128.1008] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:07.132 [3128.1008] <2> ProcessRequests: .\vnetd.c.627: msg: Request VN_REQUEST_SERVICE_SOCKET(6)
09:08:07.132 [3128.1008] <2> process_service_socket: .\vnetd.c.1365: service_name: bpcd
09:08:07.132 [3128.1008] <2> process_service_socket_plus: .\vnetd.c.1410: service_name: bpcd
09:08:07.132 [3128.1008] <2> vtext_failure: ../../libvlibs/vtext.c.92: Function vtext_open failed: 7
09:08:07.132 [3128.1008] <2> vnet_read_service: ../../libvlibs/vnet_text.c.554: Function failed: 19 0x00000013
09:08:07.132 [3128.1008] <2> vnet_read_service_file: ../../libvlibs/vnet_text.c.477: Function failed: 19 0x00000013
09:08:07.132 [3128.1008] <2> process_service_socket_plus: .\vnetd.c.1429: vnet_read_service_file failed: 19 0x00000013
09:08:07.132 [3128.1008] <2> process_service_socket_plus: .\vnetd.c.1420: service_name: inetd_bpcd
09:08:07.132 [3128.1008] <2> launch_command: .\vnetd.c.2034: path: C:\Arquivos de programas\Veritas\NetBackup\bin\bpcd.exe
09:08:07.523 [2308.6472] <2> setup_debug_log: switched debug log file for VNETD
09:08:07.523 [2308.6472] <2> main: VERBOSE = 5
09:08:07.523 [2308.6472] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:07.523 [2308.6472] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:07.523 [2308.6472] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.45454 TO 10.8.6.149.13724 fd = 748
09:08:07.523 [2308.6472] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:07.788 [2308.6472] <2> ProcessRequests: .\vnetd.c.648: msg: Request VN_REQUEST_CONNECT_FORWARD_SOCKET(10)
09:08:07.788 [2308.6472] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1750: hash_str1: e70d760e495d01e43daed1471ff53f86
09:08:07.788 [2308.6472] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1751: hash_str2: 2dfdb0d852ac7fd9c56bc65bf56a92e6
09:08:07.788 [2308.6472] <2> process_connect_forward_socket: .\vnetd.c.1804: ipc_string: 2630
09:08:07.788 [2308.6472] <2> process_connect_forward_socket: .\vnetd.c.1817: hash_str1: e70d760e495d01e43daed1471ff53f86
09:08:07.788 [2308.6472] <2> vnet_send_network_socket: ../../libvlibs/vnet_vnetd.c.1544: hash_str2: 2dfdb0d852ac7fd9c56bc65bf56a92e6
09:08:07.788 [2308.6472] <2> ProcessRequests: .\vnetd.c.650: status: 0 0x00000000
09:08:07.788 [2308.6472] <2> main: .\vnetd.c.374: ProcessRequests returned: 0 0x00000000
09:08:09.913 [7564.6932] <2> setup_debug_log: switched debug log file for VNETD
09:08:09.913 [7564.6932] <2> main: VERBOSE = 5
09:08:09.913 [7564.6932] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:09.913 [7564.6932] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:09.913 [7564.6932] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.46034 TO 10.8.6.149.13724 fd = 736
09:08:09.913 [7564.6932] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:10.101 [7564.6932] <2> ProcessRequests: .\vnetd.c.627: msg: Request VN_REQUEST_SERVICE_SOCKET(6)
09:08:10.101 [7564.6932] <2> process_service_socket: .\vnetd.c.1365: service_name: bpcd
09:08:10.101 [7564.6932] <2> process_service_socket_plus: .\vnetd.c.1410: service_name: bpcd
09:08:10.101 [7564.6932] <2> vtext_failure: ../../libvlibs/vtext.c.92: Function vtext_open failed: 7
09:08:10.101 [7564.6932] <2> vnet_read_service: ../../libvlibs/vnet_text.c.554: Function failed: 19 0x00000013
09:08:10.101 [7564.6932] <2> vnet_read_service_file: ../../libvlibs/vnet_text.c.477: Function failed: 19 0x00000013
09:08:10.101 [7564.6932] <2> process_service_socket_plus: .\vnetd.c.1429: vnet_read_service_file failed: 19 0x00000013
09:08:10.101 [7564.6932] <2> process_service_socket_plus: .\vnetd.c.1420: service_name: inetd_bpcd
09:08:10.101 [7564.6932] <2> launch_command: .\vnetd.c.2034: path: C:\Arquivos de programas\Veritas\NetBackup\bin\bpcd.exe
09:08:10.492 [6260.7836] <2> setup_debug_log: switched debug log file for VNETD
09:08:10.492 [6260.7836] <2> main: VERBOSE = 5
09:08:10.492 [6260.7836] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:10.492 [6260.7836] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:10.492 [6260.7836] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.46041 TO 10.8.6.149.13724 fd = 760
09:08:10.492 [6260.7836] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:10.757 [6260.7836] <2> ProcessRequests: .\vnetd.c.648: msg: Request VN_REQUEST_CONNECT_FORWARD_SOCKET(10)
09:08:10.757 [6260.7836] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1750: hash_str1: b8ee799855a2acd77ecf5a988b9879a8
09:08:10.757 [6260.7836] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1751: hash_str2: 10e03ffbf1fbb7eeaac8a39a80213a77
09:08:10.757 [6260.7836] <2> process_connect_forward_socket: .\vnetd.c.1804: ipc_string: 2632
09:08:10.757 [6260.7836] <2> process_connect_forward_socket: .\vnetd.c.1817: hash_str1: b8ee799855a2acd77ecf5a988b9879a8
09:08:10.757 [6260.7836] <2> vnet_send_network_socket: ../../libvlibs/vnet_vnetd.c.1544: hash_str2: 10e03ffbf1fbb7eeaac8a39a80213a77
09:08:10.757 [6260.7836] <2> ProcessRequests: .\vnetd.c.650: status: 0 0x00000000
09:08:10.757 [6260.7836] <2> main: .\vnetd.c.374: ProcessRequests returned: 0 0x00000000
09:08:11.570 [6224.7192] <2> setup_debug_log: switched debug log file for VNETD
09:08:11.570 [6224.7192] <2> main: VERBOSE = 5
09:08:11.570 [6224.7192] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:11.570 [6224.7192] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:11.585 [6224.7192] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.46076 TO 10.8.6.149.13724 fd = 744
09:08:11.585 [6224.7192] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:11.726 [6224.7192] <2> ProcessRequests: .\vnetd.c.627: msg: Request VN_REQUEST_SERVICE_SOCKET(6)
09:08:11.726 [6224.7192] <2> process_service_socket: .\vnetd.c.1365: service_name: bpcd
09:08:11.726 [6224.7192] <2> process_service_socket_plus: .\vnetd.c.1410: service_name: bpcd
09:08:11.726 [6224.7192] <2> vtext_failure: ../../libvlibs/vtext.c.92: Function vtext_open failed: 7
09:08:11.726 [6224.7192] <2> vnet_read_service: ../../libvlibs/vnet_text.c.554: Function failed: 19 0x00000013
09:08:11.726 [6224.7192] <2> vnet_read_service_file: ../../libvlibs/vnet_text.c.477: Function failed: 19 0x00000013
09:08:11.726 [6224.7192] <2> process_service_socket_plus: .\vnetd.c.1429: vnet_read_service_file failed: 19 0x00000013
09:08:11.726 [6224.7192] <2> process_service_socket_plus: .\vnetd.c.1420: service_name: inetd_bpcd
09:08:11.726 [6224.7192] <2> launch_command: .\vnetd.c.2034: path: C:\Arquivos de programas\Veritas\NetBackup\bin\bpcd.exe
09:08:12.117 [6204.7972] <2> setup_debug_log: switched debug log file for VNETD
09:08:12.117 [6204.7972] <2> main: VERBOSE = 5
09:08:12.117 [6204.7972] <2> main: .\vnetd.c.283: max_time: 120 0x00000078
09:08:12.117 [6204.7972] <2> logparams: C:\Arquivos de programas\Veritas\NetBackup\bin\VNETD.EXE
09:08:12.117 [6204.7972] <2> ProcessRequests: .\vnetd.c.566: msg: VNETD ACCEPT FROM 10.8.37.240.46106 TO 10.8.6.149.13724 fd = 756
09:08:12.117 [6204.7972] <2> vnet_version_accept: .\vnetd.c.1002: *actual_version: 5 0x00000005
09:08:12.288 [6204.7972] <2> ProcessRequests: .\vnetd.c.648: msg: Request VN_REQUEST_CONNECT_FORWARD_SOCKET(10)
09:08:12.288 [6204.7972] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1750: hash_str1: 79133a293e3690347b5acb343a5897c8
09:08:12.288 [6204.7972] <2> vnet_generate_hashes: ../../libvlibs/vnet_vnetd.c.1751: hash_str2: cca44de874fd77832a46a4fe035e62ef
09:08:12.288 [6204.7972] <2> process_connect_forward_socket: .\vnetd.c.1804: ipc_string: 2634
09:08:12.288 [6204.7972] <2> process_connect_forward_socket: .\vnetd.c.1817: hash_str1: 79133a293e3690347b5acb343a5897c8
09:08:12.288 [6204.7972] <2> vnet_send_network_socket: ../../libvlibs/vnet_vnetd.c.1544: hash_str2: cca44de874fd77832a46a4fe035e62ef
09:08:12.288 [6204.7972] <2> ProcessRequests: .\vnetd.c.650: status: 0 0x00000000
09:08:12.288 [6204.7972] <2> main: .\vnetd.c.374: ProcessRequests returned: 0 0x00000000

BPCD.LOGS

09:08:06.117 [6088.6080] <2> setup_debug_log: switched debug log file for bpcd
09:08:06.117 [6088.6080] <2> bpcd main: VERBOSE = 5
09:08:06.117 [6088.6080] <2> logparams: bpcd
09:08:06.117 [6088.6080] <2> bpcd main: Got socket for input 744
09:08:06.117 [6088.6080] <2> ReadKeyfile: keyfile C:\Arquivos de programas\Veritas\NetBackup\bin\keyfile.dat does not exist

09:08:06.117 [6088.6080] <2> process_requests: offset to GMT 10800
09:08:06.117 [6088.6080] <2> logconnections: BPCD ACCEPT FROM 10.8.37.240.45423 TO 10.8.6.149.13724
09:08:06.117 [6088.6080] <2> process_requests: setup_sockopts complete
09:08:06.117 [6088.6080] <2> bpcd peer_hostname: Connection from host sac0972.ac.correiosnet.int (10.8.37.240) port 45423
09:08:06.117 [6088.6080] <2> bpcd valid_server: comparing sac0972 and sac0972.ac.correiosnet.int
09:08:06.117 [6088.6080] <4> bpcd valid_server: hostname comparison succeeded
09:08:06.117 [6088.6080] <2> process_requests: output socket port number = 1
09:08:06.585 [6088.6080] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1257: hash_str1: d3267fde89c5fb13ae998de8a2c45c7f
09:08:06.585 [6088.6080] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1258: hash_str2: 137b90b1b36c6aed52a0f39af3f9734b
09:08:06.585 [6088.6080] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1771: hash_str1: d3267fde89c5fb13ae998de8a2c45c7f
09:08:06.585 [6088.6080] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1773: hash_str2: 137b90b1b36c6aed52a0f39af3f9734b
09:08:06.585 [6088.6080] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1799: hash_str: d3267fde89c5fb13ae998de8a2c45c7f
09:08:06.585 [6088.6080] <2> process_requests: Duplicated vnetd socket on stderr
09:08:06.585 [6088.6080] <2> process_requests: <---- NetBackup 7.0 0 ------------initiated
09:08:06.585 [6088.6080] <2> process_requests: VERBOSE = 5
09:08:06.585 [6088.6080] <2> process_requests: Not using VxSS authentication with sac0972.ac.correiosnet.int

Interface: 10.8.6.149 --- 0x10003
Endere?o IP           Endere?o f?sico       Tipo
10.8.6.56             00-09-0f-09-14-08     din?mico
10.8.6.69             00-21-5a-ae-67-4e     din?mico
10.8.6.91             00-22-64-c2-05-46     din?mico
10.8.6.146            00-22-64-9f-a4-24     din?mico
09:08:06.726 [6088.6080] <2> process_requests:
09:08:06.726 [6088.6080] <2> process_requests: BPCD_DISCONNECT_RQST
09:08:06.726 [6088.6080] <2> bpcd exit_bpcd: exit status 0 ----------->exiting
09:08:07.210 [6036.6028] <2> setup_debug_log: switched debug log file for bpcd
09:08:07.210 [6036.6028] <2> bpcd main: VERBOSE = 5
09:08:07.210 [6036.6028] <2> logparams: bpcd
09:08:07.210 [6036.6028] <2> bpcd main: Got socket for input 732
09:08:07.210 [6036.6028] <2> ReadKeyfile: keyfile C:\Arquivos de programas\Veritas\NetBackup\bin\keyfile.dat does not exist

09:08:07.210 [6036.6028] <2> process_requests: offset to GMT 10800
09:08:07.210 [6036.6028] <2> logconnections: BPCD ACCEPT FROM 10.8.37.240.45447 TO 10.8.6.149.13724
09:08:07.210 [6036.6028] <2> process_requests: setup_sockopts complete
09:08:07.210 [6036.6028] <2> bpcd peer_hostname: Connection from host sac0972.ac.correiosnet.int (10.8.37.240) port 45447
09:08:07.210 [6036.6028] <2> bpcd valid_server: comparing sac0972 and sac0972.ac.correiosnet.int
09:08:07.210 [6036.6028] <4> bpcd valid_server: hostname comparison succeeded
09:08:07.210 [6036.6028] <2> process_requests: output socket port number = 1
09:08:07.788 [6036.6028] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1257: hash_str1: e70d760e495d01e43daed1471ff53f86
09:08:07.788 [6036.6028] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1258: hash_str2: 2dfdb0d852ac7fd9c56bc65bf56a92e6
09:08:07.788 [6036.6028] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1771: hash_str1: e70d760e495d01e43daed1471ff53f86
09:08:07.788 [6036.6028] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1773: hash_str2: 2dfdb0d852ac7fd9c56bc65bf56a92e6
09:08:07.788 [6036.6028] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1799: hash_str: e70d760e495d01e43daed1471ff53f86
09:08:07.788 [6036.6028] <2> process_requests: Duplicated vnetd socket on stderr
09:08:07.788 [6036.6028] <2> process_requests: <---- NetBackup 7.0 0 ------------initiated
09:08:07.788 [6036.6028] <2> process_requests: VERBOSE = 5
09:08:07.788 [6036.6028] <2> process_requests: Not using VxSS authentication with sac0972.ac.correiosnet.int

Interface: 10.8.6.149 --- 0x10003
Endere?o IP           Endere?o f?sico       Tipo
10.8.6.56             00-09-0f-09-14-08     din?mico
10.8.6.69             00-21-5a-ae-67-4e     din?mico
10.8.6.91             00-22-64-c2-05-46     din?mico
10.8.6.146            00-22-64-9f-a4-24     din?mico
09:08:07.929 [6036.6028] <2> process_requests:
09:08:07.929 [6036.6028] <2> process_requests: BPCD_GET_VERSION_RQST
09:08:08.023 [6036.6028] <2> process_requests: BPCD_READ_HOST_CONFIG_RQST
09:08:08.148 [6036.6028] <2> process_requests: BPCD_GET_VERSION_RQST
09:08:08.257 [6036.6028] <2> process_requests: BPCD_GET_NB_VERSION_RQST
09:08:08.257 [6036.6028] <4> process_requests: Version string is NetBackup 7.0 700000 "C:\Arquivos de programas\Veritas\NetBackup\bin"
09:08:08.382 [6036.6028] <2> process_requests: BPCD_GET_PLATFORM_RQST
09:08:08.507 [6036.6028] <2> process_requests: BPCD_GET_UNAME_RQST
09:08:08.507 [6036.6028] <2> getUnameInfo: UNAME_SYSNAME = Windows2003
09:08:08.507 [6036.6028] <2> getUnameInfo: UNAME_NODENAME = SAC1111
09:08:08.507 [6036.6028] <2> getUnameInfo: UNAME_RELEASE = 5
09:08:08.507 [6036.6028] <2> getUnameInfo: UNAME_VERSION = 2
09:08:08.507 [6036.6028] <2> getUnameInfo: UNAME_MACHINE = Intel x86 - Intel Pentium Pro - Revision x2c02
09:08:08.507 [6036.6028] <2> getUnameInfo: END
09:08:08.617 [6036.6028] <2> process_requests: BPCD_GET_VERSION_RQST
09:08:08.742 [6036.6028] <2> process_requests: BPCD_READ_TEXT_FILE_RQST
09:08:08.742 [6036.6028] <2> read_text_file: .\bpcd_util.c.2278: file_id = 3
09:08:08.742 [6036.6028] <2> read_text_file: .\bpcd_util.c.2326: file_name = <C:\Arquivos de programas\Veritas\NetBackup\bin\version.txt>
09:08:08.742 [6036.6028] <2> read_text_file: .\bpcd_util.c.2350: v status = 0
09:08:08.742 [6036.6028] <2> read_text_file: .\bpcd_util.c.2353: n status = 0
09:08:08.742 [6036.6028] <2> read_text_file: .\bpcd_util.c.2401: v status = 0
09:08:08.742 [6036.6028] <2> read_text_file: .\bpcd_util.c.2404: n status = 0
09:08:08.867 [6036.6028] <2> process_requests: BPCD_READ_TEXT_FILE_RQST
09:08:08.867 [6036.6028] <2> read_text_file: .\bpcd_util.c.2278: file_id = 4
09:08:08.867 [6036.6028] <2> read_text_file: .\bpcd_util.c.2326: file_name = <C:\Arquivos de programas\Veritas\NetBackup\share\ciphers.txt>
09:08:08.867 [6036.6028] <2> read_text_file: .\bpcd_util.c.2350: v status = 0
09:08:08.867 [6036.6028] <2> read_text_file: .\bpcd_util.c.2353: n status = 0
09:08:08.867 [6036.6028] <2> read_text_file: .\bpcd_util.c.2401: v status = 0
09:08:08.867 [6036.6028] <2> read_text_file: .\bpcd_util.c.2404: n status = 0
09:08:08.976 [6036.6028] <2> process_requests: BPCD_OPEN_FOR_READ_RQST
09:08:08.976 [6036.6028] <2> process_requests: open for read file name = C:\Arquivos de programas\Veritas\NetBackup\bin\version.txt
09:08:08.976 [6036.6028] <2> process_requests: buffer length = 16383
09:08:08.976 [6036.6028] <2> process_requests: our open flags = 0x0
09:08:08.976 [6036.6028] <2> process_requests: client open flags = 0x8000
09:08:08.976 [6036.6028] <2> process_requests: file size = 109
09:08:08.976 [6036.6028] <2> process_requests: completed the write of the open file number 4 to the output socket
09:08:09.101 [6036.6028] <2> process_requests: BPCD_READ_RQST
09:08:09.101 [6036.6028] <2> process_requests: read request on file number 4
09:08:09.101 [6036.6028] <2> process_requests: read request of 16383 bytes
09:08:09.101 [6036.6028] <2> process_requests: read 109 bytes
09:08:09.101 [6036.6028] <2> process_requests: Before write of read_count = 109
09:08:09.101 [6036.6028] <2> process_requests: After write of read_count
09:08:09.101 [6036.6028] <2> process_requests: completed write of file info
09:08:09.226 [6036.6028] <2> process_requests: BPCD_CLOSE_FILE_RQST
09:08:09.335 [6036.6028] <2> process_requests: BPCD_DISCONNECT_RQST
09:08:09.335 [6036.6028] <2> bpcd exit_bpcd: exit status 0 ----------->exiting
09:08:10.179 [2940.6104] <2> setup_debug_log: switched debug log file for bpcd
09:08:10.179 [2940.6104] <2> bpcd main: VERBOSE = 5
09:08:10.179 [2940.6104] <2> logparams: bpcd
09:08:10.179 [2940.6104] <2> bpcd main: Got socket for input 736
09:08:10.179 [2940.6104] <2> ReadKeyfile: keyfile C:\Arquivos de programas\Veritas\NetBackup\bin\keyfile.dat does not exist

09:08:10.179 [2940.6104] <2> process_requests: offset to GMT 10800
09:08:10.179 [2940.6104] <2> logconnections: BPCD ACCEPT FROM 10.8.37.240.46034 TO 10.8.6.149.13724
09:08:10.179 [2940.6104] <2> process_requests: setup_sockopts complete
09:08:10.179 [2940.6104] <2> bpcd peer_hostname: Connection from host sac0972.ac.correiosnet.int (10.8.37.240) port 46034
09:08:10.179 [2940.6104] <2> bpcd valid_server: comparing sac0972 and sac0972.ac.correiosnet.int
09:08:10.179 [2940.6104] <4> bpcd valid_server: hostname comparison succeeded
09:08:10.179 [2940.6104] <2> process_requests: output socket port number = 1
09:08:10.757 [2940.6104] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1257: hash_str1: b8ee799855a2acd77ecf5a988b9879a8
09:08:10.757 [2940.6104] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1258: hash_str2: 10e03ffbf1fbb7eeaac8a39a80213a77
09:08:10.757 [2940.6104] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1771: hash_str1: b8ee799855a2acd77ecf5a988b9879a8
09:08:10.757 [2940.6104] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1773: hash_str2: 10e03ffbf1fbb7eeaac8a39a80213a77
09:08:10.757 [2940.6104] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1799: hash_str: b8ee799855a2acd77ecf5a988b9879a8
09:08:10.757 [2940.6104] <2> process_requests: Duplicated vnetd socket on stderr
09:08:10.757 [2940.6104] <2> process_requests: <---- NetBackup 7.0 0 ------------initiated
09:08:10.757 [2940.6104] <2> process_requests: VERBOSE = 5
09:08:10.757 [2940.6104] <2> process_requests: Not using VxSS authentication with sac0972.ac.correiosnet.int

Interface: 10.8.6.149 --- 0x10003
Endere?o IP           Endere?o f?sico       Tipo
10.8.6.56             00-09-0f-09-14-08     din?mico
10.8.6.69             00-21-5a-ae-67-4e     din?mico
10.8.6.91             00-22-64-c2-05-46     din?mico
10.8.6.146            00-22-64-9f-a4-24     din?mico
09:08:10.898 [2940.6104] <2> process_requests:
09:08:10.898 [2940.6104] <2> process_requests: BPCD_GET_VERSION_RQST
09:08:10.976 [2940.6104] <2> process_requests: BPCD_GET_CHARSET_RQST
09:08:10.976 [2940.6104] <16> process_requests: put_long of locale code succeeded. locale code is: 84
09:08:11.101 [2940.6104] <2> process_requests: BPCD_DISCONNECT_RQST
09:08:11.101 [2940.6104] <2> bpcd exit_bpcd: exit status 0 ----------->exiting
09:08:11.804 [2220.7528] <2> setup_debug_log: switched debug log file for bpcd
09:08:11.804 [2220.7528] <2> bpcd main: VERBOSE = 5
09:08:11.804 [2220.7528] <2> logparams: bpcd
09:08:11.804 [2220.7528] <2> bpcd main: Got socket for input 744
09:08:11.804 [2220.7528] <2> ReadKeyfile: keyfile C:\Arquivos de programas\Veritas\NetBackup\bin\keyfile.dat does not exist

09:08:11.804 [2220.7528] <2> process_requests: offset to GMT 10800
09:08:11.804 [2220.7528] <2> logconnections: BPCD ACCEPT FROM 10.8.37.240.46076 TO 10.8.6.149.13724
09:08:11.804 [2220.7528] <2> process_requests: setup_sockopts complete
09:08:11.804 [2220.7528] <2> bpcd peer_hostname: Connection from host sac0972.ac.correiosnet.int (10.8.37.240) port 46076
09:08:11.804 [2220.7528] <2> bpcd valid_server: comparing sac0972 and sac0972.ac.correiosnet.int
09:08:11.804 [2220.7528] <4> bpcd valid_server: hostname comparison succeeded
09:08:11.804 [2220.7528] <2> process_requests: output socket port number = 1
09:08:12.288 [2220.7528] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1257: hash_str1: 79133a293e3690347b5acb343a5897c8
09:08:12.288 [2220.7528] <2> vnet_receive_network_socket: ../../libvlibs/vnet_vnetd.c.1258: hash_str2: cca44de874fd77832a46a4fe035e62ef
09:08:12.288 [2220.7528] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1771: hash_str1: 79133a293e3690347b5acb343a5897c8
09:08:12.288 [2220.7528] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1773: hash_str2: cca44de874fd77832a46a4fe035e62ef
09:08:12.288 [2220.7528] <2> verify_hashes: ../../libvlibs/vnet_vnetd.c.1799: hash_str: 79133a293e3690347b5acb343a5897c8
09:08:12.288 [2220.7528] <2> process_requests: Duplicated vnetd socket on stderr
09:08:12.288 [2220.7528] <2> process_requests: <---- NetBackup 7.0 0 ------------initiated
09:08:12.288 [2220.7528] <2> process_requests: VERBOSE = 5
09:08:12.288 [2220.7528] <2> process_requests: Not using VxSS authentication with sac0972.ac.correiosnet.int

Interface: 10.8.6.149 --- 0x10003
Endere?o IP           Endere?o f?sico       Tipo
10.8.6.56             00-09-0f-09-14-08     din?mico
10.8.6.69             00-21-5a-ae-67-4e     din?mico
10.8.6.91             00-22-64-c2-05-46     din?mico
10.8.6.146            00-22-64-9f-a4-24     din?mico
09:08:12.429 [2220.7528] <2> process_requests:
09:08:12.429 [2220.7528] <2> process_requests: BPCD_GET_VERSION_RQST
09:08:12.523 [2220.7528] <2> process_requests: BPCD_GET_PLATFORM_RQST
09:08:12.648 [2220.7528] <2> process_requests: BPCD_FORK_CMD_RQST
09:08:12.648 [2220.7528] <2> process_requests: fork cmd = /usr/openv/netbackup/bin/bpbkar bpbkar -r 2678400 -ru root -dt 0 -to 0 -clnt SAC1111 -class SAC1111 -sched Mensal -st FULL -bpstart_to 3600 -bpend_to 3600 -read_to 3600 -blks_per_buffer 512 -use_otm -fso -b SAC1111_1338552485 -kl 1 -WOFB_enabled -WOFB_fim 1 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb
09:08:12.648 [2220.7528] <2> process_requests: filter type = -1
09:08:12.648 [2220.7528] <2> process_requests: Convert args to CreateProcess format
09:08:12.648 [2220.7528] <2> process_requests: Done converting args to CreateProcess format
09:08:12.648 [2220.7528] <2> process_requests: new fork cmd = C:\Arquivos de programas\Veritas\NetBackup\bin\bpbkar32.exe -r 2678400 -ru root -dt 0 -to 0 -clnt SAC1111 -class SAC1111 -sched Mensal -st FULL -bpstart_to 3600 -bpend_to 3600 -read_to 3600 -blks_per_buffer 512 -use_otm -fso -b SAC1111_1338552485 -kl 1 -WOFB_enabled -WOFB_fim 1 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb
09:08:12.648 [2220.7528] <2> process_requests: Before CreateProcess
09:08:12.648 [2220.7528] <2> process_requests: StdOutput assigned the value STDOUTSOCK
09:08:12.648 [2220.7528] <2> process_requests: final fork cmd = "C:\Arquivos de programas\Veritas\NetBackup\bin\bpbkar32.exe" -r 2678400 -ru root -dt 0 -to 0 -clnt SAC1111 -class SAC1111 -sched Mensal -st FULL -bpstart_to 3600 -bpend_to 3600 -read_to 3600 -blks_per_buffer 512 -use_otm -fso -b SAC1111_1338552485 -kl 1 -WOFB_enabled -WOFB_fim 1 -WOFB_usage 0 -WOFB_error 0 -ct 13 -use_ofb
09:08:12.648 [2220.7528] <2> process_requests: After CreateProcess, pid = 7396
09:08:12.648 [2220.7528] <2> bpcd exit_bpcd: exit status 0 ----------->exiting

- JOB DETAILS ATTACHED.

- Canceling the job, the bpbkar.exe does not end on the client machine.

- Time out client and media: 3600

rookie11 · ‎06-01-2012

increase verbosity to 5 then run bpbkar null test

http://www.symantec.com/business/support/index?page=content&id=TECH17541

bpbkar exe file might be corrupted

Marianne · ‎06-01-2012

Which OS (and version) on Client?

Which NBU version?
bpbkar shows version 6.5 but bpcd shows 7.0?
bpbkar: BPBKAR NetBackup Backup/Archive 6.5GA [Jan 4 2010]
bpcd: 09:08:10.757 [2940.6104] <2> process_requests: <---- NetBackup 7.0 0 ------------initiated

How long do you wait before you kill the job?
You only show a few seconds worth of job log.
bptm on the media server will only start writing when the first full buffer is received (using 262144 data buffer size).
What is the network buffer size on media server? And on client?

Have you checked that NetBackup Client Job tracker is killed and disabled? See: https://www-secure.symantec.com/connect/forums/windows-client-side-file-list

What snapshot method is used for Client snapshot? Verify that VSS is used, not VSP.

PS: Please post logs as attachments - large logs in body of post makes it difficult to read.

Handy NetBackup Links

Marcio_Almeida · ‎06-01-2012

The log verbosity is set to 5.

See Attached file.

Thansks.

Marcio_Almeida · ‎06-01-2012

NBU Version

Master - 7.1

Media (same Master) - 7.1

Client - 7.0 upgrade for 6.5 (I try 6.5, 6.5.4, 7.0 and 7.1)

Q: How long do you wait before you kill the job?
A: hours

What is the network buffer size on media server? And on client?

Client: 16kb

Media: ??? Not found.

Q:Have you checked that NetBackup Client Job tracker is killed and disabled

A: The job tracker is disable an not are run.

Q:What snapshot method is used for Client snapshot? Verify that VSS is used, not VSP.

A: The policy not use Snapshot. (See attached)

Q: PS: Please post logs as attachments - large logs in body of post makes it difficult to read.

Sorry!

Thanks!!!

Marianne · ‎06-01-2012

Windows Open File Backup (WOFB) is enabled by default for Windows-MS policies - even if Snapshot is not selected in policy.

We still don't have the answer to this question:

Which OS (and version) on Client?

Why do the logs for the SAME period show different NBU versions?
When you upgrade NBU, please ensure that there are no active NBU processes in Task Manager (like bpbkar32.exe and bpfis.exe).

Suggestion: Uninstall NBU from Client and do fresh install.

Handy NetBackup Links

Marcio_Almeida · ‎06-01-2012

Q: Which OS (and version) on Client?

A:

Client (SAC1111): Windows 2003 Server 32 bits - 7.1

Media (SAC0970): Solaris 10 Sparc - 7.1

Q:Why do the logs for the SAME period show different NBU versions?

A: I dont konw.

I installed with NetBackup version 7.1. I have taken due care not to leave any dirt. After installation, I made a new attempt to backup and the problem occurred again. Just do not understand why the process does not end with bpbkar32.exe job.

Marianne · ‎06-01-2012

The new logs show version 7.1.
We can see WOFB is enabled and VSS is used for snapshot:
-WOFB_enabled -WOFB_fim 1

We can see that backup starts at 11:51 and fails at 11:56:

11:51:22.764: [7784.6388] <2> tar_backup_vxbsa::add: INF - called with 'C:\WCS-FTP'
11:51:22.764: [7784.6388] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'C:\WCS-FTP' --> 10020002
11:56:22.727: [7784.3332] <16> dtcp_write: TCP - failure: send socket (1712) (TCP 10053: Software caused connection abort)
11:56:22.727: [7784.3332] <16> dtcp_write: TCP - failure: attempted to send 1 bytes
11:56:22.727: [7784.3332] <16> tar_base::keepaliveThread: INF - keepalive thread abnormal exit :14

Now this looks like the default Client Read Timeout on the media server of 300 (5minutes)
Did the backup also fail in Activity Monitor?
If not, we will need bpbrm and bptm logs on the media server.

Backup selection seems to be C:\WCS-FTP, right?
What kind of files in this folder?

As a start, let us get network and client out of the way and just test local read with bpbkar on the client:

Set logging level on client to 1.
rename current bpbkar log to <date>.old
Run the following from cmd:

cd <install_path>\veritas\netbackup\bin\
bpbkar32 -nocont C:\WCS-FTP 1> nul 2> nul

You will be returned to to command prompt. You should be able to see bpbkar32.exe running in Task Manager.
When finished reading, bpbkar32 process should terminate.

You should be able to see something similar to this in the bpbkar log (copied from TN http://www.symantec.com/docs/TECH17541 :(

tar_base::backup_finish: TAR - backup:                          15114 files
tar_base::backup_finish: TAR - backup:          file data:  995460990 bytes  13 gigabytes
tar_base::backup_finish: TAR - backup:         image data: 1033197568 bytes  13 gigabytes
tar_base::backup_finish: TAR - backup:       elapsed time:        649 secs     23099898 bps

We should also be able to see how much time elapsed between start of bpbkar until first file was actually read. This will determine if Client Read Timeout on media server should be increased.
It might be a good idea to increase timeout in any case to something like 900 (15 minutes).

If bpbkar starts reading files right away, you need to start troubleshooting network between client and media server.

Since client is W2003, I would personally start with disabling TCP Chimney on the client. See http://www.symantec.com/docs/TECH60844 for details.

If problem persists after all of this, please post a full set of logs for backup attempt:
On media server: bptm and bpbrm
On client: bpcd and bpbkar

Handy NetBackup Links

VOX

bpbkar32.exe don't write data.