Hello All,
I am stuck with a Lotus notes backup issue since 2 weeks now. I have already opened a case with symantec and they do not seem to know the answer as well.
Here is a description:
1. File level backup works fine.
2. Lotus notes paramters (notes.ini and nserver.exe) already configured on client host properties.
3. Notes backup fails with error 42. It also says connection reset by peer.
4. On bpbrm failed to get KEEP_ALIVE
5. on bpbkar "nblnagent main(): ERR - failed to load LN library: C:\Program files\IBM\Lotus\Domino\nnotes.dll: Errno: 193 (nnotes.dll)
Troubleshooting done:
1. Have run user backup to check reverse lookup, works fine.
2. Checked hostname resolution works fine.
3. rebooted and reinstalled the client. reinstalled the patch 6.5.3
Config info:
1. Master: Solaris 10
2. Client : Windows 2003 x64
3. Lotus Domino 8 (32 bit)
4. NBU Version on master and client : 6.5.3
This is happening on two Lotus domino servers.
bpbkar log:
3:33:14.515 PM: [4700.4924] <2> Environment::_initialize_BE(): All DLEs initialized (01248260)!
3:33:14.515 PM: [4700.4924] <2> BEDS_DumpDLEInfo(): Device Name : C:
3:33:14.515 PM: [4700.4924] <2> BEDS_DumpDLEInfo(): Device Name : D:
3:33:14.515 PM: [4700.4924] <2> BEDS_DumpDLEInfo(): Device Name : Microsoft Terminal Services
3:33:14.515 PM: [4700.4924] <2> BEDS_DumpDLEInfo(): Device Name : Microsoft Windows Network
3:33:14.515 PM: [4700.4924] <2> BEDS_DumpDLEInfo(): Device Name : Web Client Network
3:33:14.515 PM: [4700.4924] <2> BEDS_DumpDLEInfo(): Device Name : Shadow?Copy?Components
3:33:14.515 PM: [4700.4924] <2> tar_backupt_tfi::create: TAR - Backup started at 7/17/2009 3:33:14 PM
3:33:14.515 PM: [4700.4924] <2> tar_base::V_vTarMsgW: INF - Inform when done
3:33:14.515 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 23 of 23 bytes
3:33:14.515 PM: [4700.4924] <2> tar_base::V_vTarMsgW: INF - Echo keepalives
3:33:14.515 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 22 of 22 bytes
3:33:14.515 PM: [4700.4924] <2> tar_base::V_vTarMsgW: INF - BACKUP START
3:33:14.515 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 19 of 19 bytes
3:33:14.515 PM: [4700.4924] <2> tar_base::V_vTarMsgW: TRV - BACKUP 7/17/2009 3:33:14 PM SGKDHMCD01_BKP Lotus Test FULL
3:33:14.515 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 66 of 66 bytes
3:33:14.562 PM: [4700.4924] <2> dtcp_read: TCP - success: recv socket (540), 14 of 14 bytes
3:33:14.562 PM: [4700.4924] <2> tar_backup::V_SetupProcessContinue: TAR - CONTINUE BACKUP received
3:33:14.562 PM: [4700.4924] <2> tar_backup_tfi::setupFileDirectives: TAR - Processing filename list
3:33:14.562 PM: [4700.4924] <2> dtcp_read: TCP - success: recv socket (540), 4 of 4 bytes
3:33:14.562 PM: [4700.4924] <2> dtcp_read: TCP - success: recv socket (540), 33 of 33 bytes
3:33:14.562 PM: [4700.4924] <2> tar_backup_tfi::setupFileDirectives: TAR - backup filename = C:\Program Files\IBM\Lotus\Domino
3:33:14.562 PM: [4700.4924] <2> dtcp_read: TCP - success: recv socket (540), 4 of 4 bytes
3:33:14.562 PM: [4700.4924] <2> dtcp_read: TCP - success: recv socket (540), 8 of 8 bytes
3:33:14.562 PM: [4700.4924] <4> tar_base::startKeepaliveThread: INF - keepalive thread started
3:33:14.562 PM: [4700.1508] <4> tar_base::keepaliveThread: INF - keepalive thread is active with an interval of 60 seconds
3:33:14.562 PM: [4700.1508] <4> tar_base::keepaliveThread: INF - sending keepalive
3:33:14.562 PM: [4700.1508] <2> dtcp_write: TCP - success: send socket (840), 1 of 1 bytes
3:33:14.577 PM: [4700.4924] <4> V_LNBackup_Init: INF - V_LNBackup_Init <Enter>
3:33:14.577 PM: [4700.4924] <4> UpdatePath(): INF - Path updated with Lotus Program Dir 'C:\Program Files\IBM\Lotus\Domino'
3:33:14.577 PM: [4700.4924] <2> NBLN_Initialize(): INF - <Enter>
3:33:14.577 PM: [4700.4924] <2> NBLN_Initialize(): INF - <Exit> Lotus Context Initialized
3:33:14.577 PM: [4700.4924] <4> NBLN_SetDebugLog(): INF - <Enter> Debug Log Path: 'BPBKAR'
3:33:14.577 PM: [4700.4924] <4> V_LNBackup_SetLotusInfo: INF - V_LNBackup_SetLotusInfo <Enter> INI_Path:C:\Program Files\IBM\Lotus\Domino
3:33:14.577 PM: [4700.4924] <4> NBLN_SetLotusInfo(): INF - <Enter> NotesIniPath:C:\Program Files\IBM\Lotus\Domino
3:33:14.577 PM: [4700.4924] <4> dos_backup::V_VerifyLotus: INF - Replaced: C:\Program Files\IBM\Lotus\Domino with Lotus Notes:\C:\Program Files\IBM\Lotus\Domino
3:33:14.577 PM: [4700.4924] <4> dos_backup::V_VerifyFileList: INF - UBS Local Type for 'Lotus Notes:\C:\Program Files\IBM\Lotus\Domino' --> 00120000
3:33:14.577 PM: [4700.4924] <4> NBLN_Connect(): INF - <Enter> NotesIniPath:'C:\Program Files\IBM\Lotus\Domino'
3:33:14.577 PM: [4700.4924] <4> NBLN_StartAgent(): INF - nblnagent debug log path: 'BPBKAR'
3:33:14.577 PM: [4700.4924] <4> NBLN_StartAgent(): INF - nblnagent command: '"C:\Program Files\Veritas\NetBackup\bin\nblnagent.exe" "C:\Program Files\Veritas\NetBackup\Logs\BPBKAR" 2'
3:33:14.577 PM: [2760.6648] <16> nblnagent main(): ERR - failed to load LN library: C:\Program Files\IBM\Lotus\Domino\nnotes.dll: Errno:193 (nnotes.dll)
3:33:14.577 PM: [2760.6648] <4> nblnagent LNAPI_stopServer(): INF - stopping nblnagent
3:33:14.577 PM: [2760.6648] <4> nblnagent LNAPI_stopServer(): INF - terminated normally
3:33:14.577 PM: [4700.4924] <16> getWORD(): ERR - ReadFile FAILED, Errno=109
3:33:14.577 PM: [4700.4924] <2> LN_stopClient(): INF - Stopping Client
3:33:14.577 PM: [4700.4924] <4> NBLN_Connect(): INF - Path to Notes.ini='=C:\Program Files\IBM\Lotus\Domino' passing to NotesInitExtended().
3:33:14.577 PM: [4700.4924] <16> NBLN_Connect(): ERR - NotesInitExtended() Failed (ErrorCode: 0xFFFF)
3:33:14.577 PM: [4700.4924] <4> Packer::open(): INF - Started Backup...
3:33:14.577 PM: [4700.4924] <4> Transporter::setThrottlingParameters(): INF - Throttling parameters set in Transporter
3:33:14.577 PM: [4700.4924] <4> backup_create: INF - NetBackup Temp Directory: 'C:\Program Files\Veritas\\NetBackup\Temp'
3:33:14.577 PM: [4700.4924] <2> tar_base::V_vTarMsgW: INF - Estimate:-1 -1
3:33:14.577 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 21 of 21 bytes
3:33:14.577 PM: [4700.4924] <2> NBLN_GetTransLogStyle(): INF - <Enter>
3:33:14.577 PM: [4700.4924] <4> tar_base::V_vTarMsgW: INF - tar message received from dos_backup::tfs_startdir
3:33:14.577 PM: [4700.4924] <2> tar_base::V_vTarMsgW: TRV - object not found for file system backup: Lotus Notes:\C:\Program Files\IBM\Lotus\Domino
3:33:14.577 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 94 of 94 bytes
3:33:14.577 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 65 of 65 bytes
3:33:14.577 PM: [4700.4924] <4> tar_backup::backup_add_last_entry_state: INF - catalog message: Dfi - 0 0 0 -1 23 292 user other 0 0 0 0 /VRTS_IMAGE_SIZE_RECORD
3:33:14.577 PM: [4700.4924] <4> Packer::padBuffer(): INF - Padding (1024) bytes with pad value = (0x00000000).
3:33:14.593 PM: [4700.4924] <2> tar_base::backup_finish: TAR - backup: 0 files
3:33:14.593 PM: [4700.4924] <2> tar_base::backup_finish: TAR - backup: file data: 0 bytes
3:33:14.593 PM: [4700.4924] <2> tar_base::backup_finish: TAR - backup: image data: 1024 bytes
3:33:14.593 PM: [4700.4924] <2> tar_base::backup_finish: TAR - backup: elapsed time: 1 secs 1024 bps
3:33:14.609 PM: [4700.4924] <2> tar_base::V_vTarMsgW: INF - Total Size:0
3:33:14.609 PM: [4700.4924] <2> dtcp_write: TCP - success: send socket (840), 19 of 19 bytes
3:33:14.609 PM: [4700.4924] <4> tar_backup::backup_done_state: INF - number of file directives not found: 1
3:33:14.609 PM: [4700.4924] <4> tar_backup::backup_done_state: INF - number of file directives found: 0
3:33:14.609 PM: [4700.4924] <2> tar_base::V_vTarMsgW: INF - Client completed sending data for backup
3:33:14.609 PM: [4700.4924] <4> tar_base::stopKeepaliveThread: INF - waiting for keepalive thread to exit ...
3:33:14.609 PM: [4700.1508] <4> tar_base::keepaliveThread: INF - keepalive thread terminating (reason: WAIT_OBJECT_0)
3:33:14.609 PM: [4700.4924] <4> tar_base::stopKeepaliveThread: INF - keepalive thread has exited. (reason: WAIT_OBJECT_0)
3:33:14.609 PM: [4700.4924] <2> tar_base::V_vTarMsgW: INF - EXIT STATUS 71: none of the files in the file list exist
And here is the bpbrm log:
17:23:27.383 [8796] <2> bpbrm main: INITIATING (VERBOSE = 1): version NetBackup 6.5 2008103100
17:23:27.384 [8796] <2> logparams: -backup -S SGKDHBS101 -c SGKDHMCD01_BKP -ct 25 -ru root -cl Lotus_Test -sched T -bt 1247649806 -dt 0 -st 0 -b SGKDHMCD01_BK
P_1247649806 -mediasvr SGKDHBS101 -jobid 13779 -jobgrpid 13779 -masterversion 650000 -maxfrag 524288 -reqid -1247385615 -mt 0 -to 1966020 -stunit Disk_Test -r
l 1 -rp 1209600 -p /tmp/nbu_backups -mst 1 -flags 0 -use_ofb -use_otm -jm -secure 1 -kl 28 -rg root -fso -connect_options 16974338
17:23:27.389 [8796] <2> init_cache: vnet_hosts.c.990: host_cache_size: 200 0x000000c8
17:23:27.389 [8796] <2> init_cache: vnet_hosts.c.991: cache_time: 3600 0x00000e10
17:23:27.389 [8796] <2> init_cache: vnet_hosts.c.1003: host_failed_cache_size: 40 0x00000028
17:23:27.389 [8796] <2> init_cache: vnet_hosts.c.1004: cache_time: 3600 0x00000e10
17:23:27.390 [8796] <2> init_cache: vnet_hosts.c.990: host_cache_size: 200 0x000000c8
17:23:27.390 [8796] <2> init_cache: vnet_hosts.c.991: cache_time: 3600 0x00000e10
17:23:27.390 [8796] <2> init_cache: vnet_hosts.c.1003: host_failed_cache_size: 40 0x00000028
17:23:27.390 [8796] <2> init_cache: vnet_hosts.c.1004: cache_time: 3600 0x00000e10
17:23:27.404 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
17:23:27.404 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpcd
17:23:27.485 [8796] <2> logconnections: BPCD CONNECT FROM 10.122.28.72.61770 TO 10.122.28.24.13724
17:23:27.487 [8796] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.179: msg: VNETD CONNECT FROM 10.122.28.72.61771 TO 10.122.28.24.13724 fd = 8
17:23:27.499 [8796] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.532: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
17:23:27.704 [8796] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.549: ipc_string: 4999
17:23:27.763 [8796] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
17:23:27.763 [8796] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
17:23:27.903 [8796] <2> bpbrm main: send_3_0_client_params = 1
17:23:27.903 [8796] <2> bpbrm main: backup_cmd = /usr/openv/netbackup/bin/bpbkar bpbkar -r 1209600 -ru root -dt 0 -to 1966020 -clnt SGKDHMCD01_BKP -class Lotu
s_Test -sched T -st FULL -bpstart_to 32767 -bpend_to 32767 -read_to 300 -blks_per_buffer 1024 -use_otm -fso -b SGKDHMCD01_BKP_1247649806 -kl 28 -ct 25
17:23:27.916 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
17:23:27.916 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpcd
17:23:28.033 [8796] <2> logconnections: BPCD CONNECT FROM 10.122.28.72.61774 TO 10.122.28.24.13724
17:23:28.034 [8796] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.179: msg: VNETD CONNECT FROM 10.122.28.72.61775 TO 10.122.28.24.13724 fd = 8
17:23:28.046 [8796] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.532: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
17:23:28.250 [8796] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.549: ipc_string: 1027
17:23:28.303 [8796] <2> bpbrm start_bpcd_stat: DATA_SOCK from bpcr = 7
17:23:28.303 [8796] <2> bpbrm start_bpcd_stat: NAME_SOCK from bpcr = 8
17:23:28.438 [8796] <2> bpcr_get_version_rqst: bpcd version: 06530000
17:23:28.493 [8796] <2> bpcr_get_platform_rqst: Server client platform length = 7
17:23:28.493 [8796] <2> bpcr_check_for_use_ofb_support: bpcd platform win_x64
17:23:28.494 [8796] <2> bpbrm main: received bpcd success message
17:23:28.592 [8796] <2> get_readline_type: Returning BPBRM_READ_INFORM_WHEN_DONE
17:23:28.643 [8796] <2> bpbrm main: from client SGKDHMCD01_BKP: read client start message
17:23:28.643 [8796] <2> bpbrm spawn_child: /usr/openv/netbackup/bin/bptm bptm -w -c SGKDHMCD01_BKP -dpath /tmp/nbu_backups -stunit Disk_Test -cl Lotus_Test -b
t 1247649806 -b SGKDHMCD01_BKP_1247649806 -st 0 -cj 1 -reqid -1247385615 -jm -brm -hostname SGKDHMCD01_BKP -ru root -rclnt SGKDHMCD01_BKP -rclnthostname SGKDH
MCD01_BKP -rl 1 -rp 1209600 -sl T -ct 25 -maxfrag 524288 -v -mediasvr SGKDHBS101 -no_callback -connect_options 0x01010100 -jobid 13779 -jobgrpid 13779 -master
version 650000 -bpbrm_shm_id 150995028 -blks_per_buffer 1024
17:23:28.647 [8796] <2> bpbrm write_continue_backup: wrote CONTINUE BACKUP on COMM_SOCK <7>
17:23:28.648 [8796] <2> write_file_names: buffering file name 'd:\lotus\domino\data' for output
17:23:28.648 [8796] <2> write_file_names: successfully wrote buffer to COMM_SOCK
17:23:28.648 [8796] <2> bpbrm main: wrote CONTINUE on COMM_SOCK
17:23:28.650 [8796] <4> bpbrm main: from client SGKDHMCD01_BKP: TRV - BACKUP 7/15/2009 5:23:28 PM SGKDHMCD01_BKP Lotus_Test T FULL
17:23:28.651 [8796] <2> db_error_add_to_file: dberrorq.c:midnite = 1247587200
17:23:28.695 [8796] <2> bpbrm main: ESTIMATE -1 -1 SGKDHMCD01_BKP_1247649806
17:23:28.695 [8796] <4> bpbrm main: from client SGKDHMCD01_BKP: TRV - object not found for file system backup: Lotus Notes:\D:\lotus\domino\data
17:23:28.695 [8796] <2> db_error_add_to_file: dberrorq.c:midnite = 1247587200
17:23:28.709 [8796] <2> bpbrm main: client SGKDHMCD01_BKP EXIT STATUS = 71: none of the files in the file list exist
17:23:28.710 [8796] <2> bpbrm kill_child_process: start
17:23:28.710 [8796] <2> bpbrm wait_for_child: start
17:23:32.445 [8796] <2> bpbrm mm_sig: received ready signal from media manager
17:23:35.522 [8796] <2> bpbrm wait_for_child: child exit_status = 42 signal_status = 0
17:23:35.522 [8796] <2> inform_client_of_status: INF - Server status = 42
17:23:35.523 [8796] <2> put_long: (11) network write() error: Broken pipe (32); socket = 7
17:23:35.523 [8796] <16> inform_client_of_status: could not send server status message
17:23:35.576 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
17:23:35.577 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpjobd
17:23:35.579 [8796] <2> job_connect: SO_KEEPALIVE set on socket 9 for client SGKDHBS101
17:23:35.579 [8796] <2> logconnections: BPJOBD CONNECT FROM 10.122.28.72.61855 TO 10.122.28.72.13724
17:23:35.579 [8796] <2> job_authenticate_connection: ignoring VxSS authentication check for now...
17:23:35.580 [8796] <2> job_connect: Connected to the host SGKDHBS101 contype 10 jobid <13779> socket <9>
17:23:35.580 [8796] <2> job_connect: Connected on port 61855
17:23:35.582 [8796] <2> job_monitoring_exex: ACK disconnect
17:23:35.582 [8796] <2> job_disconnect: Disconnected
17:23:35.582 [8796] <2> db_error_add_to_file: dberrorq.c:midnite = 1247587200
17:23:35.600 [8796] <2> inform_client_of_status: Could not set linger value on socket. Errno = 22: Invalid argument
17:23:35.600 [8796] <2> bpbrm Exit: attempting to send mail to root on SGKDHMCD01_BKP
17:23:35.613 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2043: VN_REQUEST_SERVICE_SOCKET: 6 0x00000006
17:23:35.613 [8796] <2> vnet_vnetd_service_socket: vnet_vnetd.c.2057: service: bpcd
17:23:35.798 [8796] <2> logconnections: BPCD CONNECT FROM 10.122.28.72.61856 TO 10.122.28.24.13724
17:23:35.799 [8796] <2> vnet_connect_to_vnetd_extra: vnet_vnetd.c.179: msg: VNETD CONNECT FROM 10.122.28.72.61860 TO 10.122.28.24.13724 fd = 9
17:23:35.811 [8796] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.532: VN_REQUEST_CONNECT_FORWARD_SOCKET: 10 0x0000000a
17:23:36.019 [8796] <2> vnet_vnetd_connect_forward_socket_begin: vnet_vnetd.c.549: ipc_string: 1040
17:23:36.073 [8796] <2> bpbrm Exit: OUT_SOCK from bpcr = 7
17:23:36.073 [8796] <2> bpbrm Exit: IN_SOCK from bpcr = 9
17:23:36.141 [8796] <2> bpcr_get_version_rqst: bpcd version: 06530000
17:23:36.193 [8796] <2> bpcr_get_version_rqst: bpcd version: 06530000
17:23:36.313 [8796] <2> bpcr_get_version_rqst: bpcd version: 06530000
17:23:36.374 [8796] <2> bpbrm Exit: client backup EXIT STATUS 42: network read failed
Any help would be appreciated!!
Thanks
Sumeet