hi all,
after countless hours of testing, i have to address the community; hopefully, you can help.
we're running a BE 2012 SP4 w/ HF217347 on Win2K8 R2 x64 and have several issues.
today the topic is a RALUS client that backs up just fine for about two hours.
all sorts of small and huge (>30GB) files.. no problem. but then.. all of the sudden, this happens:
1c81700 Thu Mar 10 09:57:33 2016 : ====> VX_CloseDir
1c81700 Thu Mar 10 09:57:33 2016 : vx_stat_by_name: Getting stat of /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333
1c81700 Thu Mar 10 09:57:33 2016 : vx_open_by_name: Opening object name : /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333, openflags : B
1c81700 Thu Mar 10 09:57:33 2016 : vx_open_by_name: new handle =0x7fc7f019fd90
1c81700 Thu Mar 10 09:57:33 2016 : vx_read_ext: vfmObjCtl: ret_val : 0X0
1c81700 Thu Mar 10 09:57:33 2016 : vx_read_ext: file_extstat.ext_filevers : 1
1c81700 Thu Mar 10 09:57:33 2016 : ====> VX_OpenObj returning 0
1c81700 Thu Mar 10 09:57:33 2016 : ReadObject: Beginning of EA cur_stream_len 293
1c81700 Thu Mar 10 09:57:33 2016 : ReadObject: Beginning of EA cur_stream_len 293
1c81700 Thu Mar 10 09:57:33 2016 : ReadObject: real eof - offset 293
1c81700 Thu Mar 10 09:57:33 2016 : VX_SetupWorkPath: dss_cur_dir is not valid
1c81700 Thu Mar 10 09:57:33 2016 : VX_SetupWorkPath: req size is 168
1c81700 Thu Mar 10 09:57:33 2016 : VX_SetupWorkPath: req size after strsize(sname) is 168
1c81700 Thu Mar 10 09:57:33 2016 : VX_SetupWorkPath: path is /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333.
1c81700 Thu Mar 10 09:57:33 2016 : vx_stat_by_name: Getting stat of /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333
1c81700 Thu Mar 10 09:57:33 2016 : Versioned dir dblk osinfo type, os_spec_size=72 dirInfoSize=72
1c81700 Thu Mar 10 09:57:33 2016 : Unix_SetInfo: dir (srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333), native (NULL)-(0) setting uid=33 gid=33 type=2 mode=16877
1c81700 Thu Mar 10 09:57:33 2016 : VX_GetObjInfo: os info not complete: val 1
1c81700 Thu Mar 10 09:57:33 2016 : ====> VX_OpenObj
1c81700 Thu Mar 10 09:57:33 2016 : Versioned file dblk osinfo, os_spec_size=72
1c81700 Thu Mar 10 09:57:33 2016 : vx_stat_by_name: Getting stat of /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333/dynamicsax.img
1c81700 Thu Mar 10 09:57:33 2016 : OpenFileUnix: bec_flags=1, Mode : 20
1c81700 Thu Mar 10 09:57:33 2016 : FileIsNFS ustat(): stat=0 f_tfree=163956562 f_tinode=163956562 f_fname=[0][0][0]
1c81700 Thu Mar 10 09:57:33 2016 : FileIsNFS: Is false for /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333/dynamicsax.img
1c81700 Thu Mar 10 09:57:33 2016 : FileIsNFS statvfs(): stat=0 vbuf.f_files=165347328 f_ffree=163956562 f_fsid=-1985997220
1c81700 Thu Mar 10 09:57:33 2016 : File system f_type=0xef53, <ext3>
1c81700 Thu Mar 10 09:57:33 2016 : vx_open_by_name: Opening object name : /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333/dynamicsax.img, openflags : 200B
1c81700 Thu Mar 10 09:57:33 2016 : vx_open_by_name: new handle =0x7fc7f019fd90
1c81700 Thu Mar 10 09:57:33 2016 : vx_read_ext: vfmObjCtl: ret_val : 0X0
1c81700 Thu Mar 10 09:57:33 2016 : vx_read_ext: file_extstat.ext_filevers : 1
1c81700 Thu Mar 10 09:57:33 2016 : ====> VX_OpenObj returning 0
1029700 Thu Mar 10 10:13:16 2016 : Socket error mvrRet = 110
1c81700 Thu Mar 10 10:13:16 2016 : TF_GetNextTapeRequest( ) Error = E00084F9
1c81700 Thu Mar 10 10:13:17 2016 : VX_SetupWorkPath: dss_cur_dir is not valid
1c81700 Thu Mar 10 10:13:17 2016 : VX_SetupWorkPath: req size is 168
1c81700 Thu Mar 10 10:13:17 2016 : VX_SetupWorkPath: req size after strsize(sname) is 183
1c81700 Thu Mar 10 10:13:17 2016 : VX_SetupWorkPath: path is /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333/dynamicsax.img.
1c81700 Thu Mar 10 10:13:17 2016 : vx_stat_by_name: Getting stat of /srv/[deleted]/Microsoft_Dynamics_AX_2012_R2_Standard.d1455026333/dynamicsax.img
1c81700 Thu Mar 10 10:13:17 2016 : Versioned file dblk osinfo, os_spec_size=72
1c81700 Thu Mar 10 10:13:17 2016 : Unix_SetInfo: file (dynamicsax.img), native (NULL)-(0) setting uid=33 gid=33 type=1 mode(inp)=33188, mode(out)=33188
1c81700 Thu Mar 10 10:13:17 2016 : ====> VX_FindClose
1c81700 Thu Mar 10 10:13:17 2016 : ====> VX_CloseDir
1c81700 Thu Mar 10 10:13:17 2016 : Updating drive \\drive\[ROOT]/. JournalId: 0x0. LastUsn: 0x0
1c81700 Thu Mar 10 10:13:17 2016 : UpdateTime: : (0x 1d17a9c78c33180) 10 Mar 2016, 7:14:23.0
1c81700 Thu Mar 10 10:13:17 2016 + engine/ndmp/loops/BackupDirector.h (518):
1c81700 Thu Mar 10 10:13:17 2016 | Post-processing files
1c81700 Thu Mar 10 10:13:17 2016 + engine/ndmp/loops/BackupDirector.h (531):
1c81700 Thu Mar 10 10:13:17 2016 | Finished executing Backup Director call operator
1c81700 Thu Mar 10 10:13:17 2016 : TF_GetNextTapeRequest( ): Recalled in Error State
1c81700 Thu Mar 10 10:13:17 2016 : TF_GetNextTapeRequest( ): Recalled in Error State
1c81700 Thu Mar 10 10:13:17 2016 : TF_CloseSet()
1c81700 Thu Mar 10 10:13:17 2016 : Fatal error in channel.
as you can see, while trying to back up 'dynamicsax.img', the connection stalls somehow and after ~15 mins
hits a timeout: Socket error mvrRet = 110 :(
what we've tried:
- disabled IPv6
- disabled AV software on BE server (there's no AV on Linux)
- increased the range of dynamic ports from 25 to 50 (just for good luck)
- kept a permanent line open to both servers (SSH and RDP) to make sure, no interruption occures
is there any way for me to find out why the connection times out? any way to find out what exactly goes on prior to the timeout?
