Forum Discussion

marcusb12's avatar
marcusb12
Level 3
4 years ago

ERR - Unable to NFS mount the required file system.

Hi,

We are trying to do an exchange GRT backup. Exchange 2019, Windows Server 2019 and a Media Server running RHEL with Netbackup 8.2 Clients.

In doing so our backups are only partially successful with the following error:

02/11/2020 2:49:49 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Unable to NFS mount the required file system.
02/11/2020 2:50:59 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 2:51:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB001\Logs_1604288407\
02/11/2020 2:51:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 2:53:09 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 2:53:47 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB002\Logs_1604288407\
02/11/2020 2:53:47 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 3:00:57 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 3:01:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB003\Logs_1604288407\
02/11/2020 3:01:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 3:04:27 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 3:05:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB004\Logs_1604288407\
02/11/2020 3:05:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 3:06:08 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 3:06:47 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB005\Logs_1604288407\
02/11/2020 3:06:47 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 3:07:18 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 3:07:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB006\Logs_1604288407\
02/11/2020 3:07:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 3:08:16 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 3:08:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB007\Logs_1604288407\
02/11/2020 3:08:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 3:09:16 PM - Info bpbrm (pid=3513266) DB_BACKUP_STATUS is 0
02/11/2020 3:09:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Error encountered while attempting to get additional files for Microsoft Information Store:\MYDB008\Logs_1604288407\
02/11/2020 3:09:46 PM - Error bpbrm (pid=3513266) from client <mydag>: ERR - Exchange granular restore from this image may not work.
02/11/2020 3:09:47 PM - Info bptm (pid=3513457) waited for full buffer 10933 times, delayed 32049 times
02/11/2020 3:09:48 PM - Info bptm (pid=3513457) EXITING with status 0 <----------
02/11/2020 3:09:48 PM - Info bpbrm (pid=3513266) validating image for client <mydag>
02/11/2020 3:09:48 PM - Info bpbkar (pid=36536) done. status: 1: the requested operation was partially successful
02/11/2020 3:09:48 PM - end writing; write time: 0:21:01
The requested operation was partially successful  (1)

I have followed the instructions in this document: https://www.veritas.com/content/support/en_US/article.100000686 and when doing so receive the following error:

C:\Program Files\Veritas\NetBackup\bin>nbfs mount -server mymediaserver-cred <cred> *
connect to mymediaserver failed
EXIT_STATUS=25

Any ideas?

  • Fixed by opening the following ports inbound on the media server AWS security group:

    1556 - Netbackup

    7394 - Netbackup NBFSD

    111 - Netbackup GRT

11 Replies

    • marcusb12's avatar
      marcusb12
      Level 3

      Hi Marianne,

      Yep the clients have Client for NFS installed.

  • Assuming you have NFS configured on the Exchange server and media server per the documentation, I would look for the nbfsd log on the media server. This is a difficult log to read. Try to line up timestamps and look for requests received and results returned. Either you'll find an error, or you'll find that the request doesn't make it to nbfsd. In the latter case, get your system admins involved to troubleshoot NFS.

    • marcusb12's avatar
      marcusb12
      Level 3

      Hi Lowell,

      Thanks for the tip - i've had a look but can't seem to recognise any errors in there.

       

      cat root.110320_00001.log
      09:46:04.189 [3603068] <2> debuglog: <2> common_init: nbfsd: starting...  @(#) NetBackup_8.2  mymediaserver  (2019062501, 1604357164 201103.094604)
      09:46:04.189 [3603068] <2> debuglog: <2> common_init: nbfsd: unix - Linux, mymediaserver, 4.18.0-193.14.3.el8_2.x86_64, #1 SMP Mon Jul 20 15:02:29 UTC 2020, x86_64
      09:46:04.189 [3603068] <2> logparams: nbfsd -d -v 5 -j 4 -B client01_123456789
      09:46:04.190 [3603068] <2> debuglog: <2> ivfs_parse_use_options: bid client01_123456789, type , options
      09:46:04.190 [3603068] <2> debuglog: <2> ivfs_parse_use_options: generic use type
      09:46:04.190 [3603068] <2> debuglog: <2> ivfs_parse_use_options: returning useinfo 0x25a6f90 -
      09:46:04.190 [3603068] <2> debuglog: <2> setup_pmap_method: IPV6_NBFSD is enabled. Selecting RPCB methods
      09:46:04.190 [3603068] <2> debuglog: <2> init_bpconf_str : tested for nbfsd_codepage
      09:46:04.190 [3603068] <2> debuglog: <2> init_bpconf_bool: tested for nbfsd_diag_mode
      09:46:04.190 [3603068] <2> debuglog: <2> init_touchfiles: initial daemon timeout values - idle 10, inactivity 60
      09:46:04.190 [3603068] <2> debuglog: <2> selfcheck_xdr: 32: 00001112 21222324 31323334 35363738 41424344 45464748 51525354 00006162
      09:46:04.190 [3603068] <2> debuglog: <2> main: nbfsd port: 7394
      09:46:04.191 [3603068] <2> debuglog: <4> my_rpcb_dump: done: rv 0, num_found 0/12
      09:46:04.191 [3603068] <2> debuglog: <2> swprc_init: NFS max fileop datasize is 32768
      09:46:04.191 [3603068] <2> debuglog: <2> swprc_init: NFS max dirop  datesize is 32768
      09:46:04.191 [3603068] <2> debuglog: <2> swprc_init: selecting embedded RPC environment
      09:46:04.191 [3603068] <2> debuglog: <2> rpc_init: FD_SETSIZE 1024
      09:46:04.191 [3603068] <2> debuglog: <2> rpc_update_fdset: nfds 0, max 1
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_add_xp: adding ADDR=(none) 0  S=5 FAM=10 TCP=1 B=1 HIST=0/0 XP=0x25a8d80
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_update_fdset: nfds 1, max 6
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_reg_prog: registered prog 100005, ver 1 on 0x25a8d80 as 0x444094
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_reg_prog: registered prog 100005, ver 3 on 0x25a8d80 as 0x444094
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_reg_prog: registered prog 100003, ver 3 on 0x25a8d80 as 0x4453e2
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_add_xp: adding ADDR=(none) 0  S=6 FAM=10 TCP=0 B=1 HIST=0/10 XP=0x25a8e80
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_update_fdset: nfds 2, max 7
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_reg_prog: registered prog 100005, ver 1 on 0x25a8e80 as 0x444094
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_reg_prog: registered prog 100005, ver 3 on 0x25a8e80 as 0x444094
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_reg_prog: registered prog 100003, ver 3 on 0x25a8e80 as 0x4453e2
      09:46:04.192 [3603068] <2> debuglog: <2> rpc_init: done
      09:46:04.192 [3603068] <2> debuglog: <4> main: using IVFS
      09:46:04.192 [3603068] <2> debuglog: <2> mount_init: preloaded 100 export names
      09:46:04.192 [3603068] <2> debuglog: <2> ivfs_init_once: ivfs log mask set of 0x3e
      09:46:04.192 [3603068] <2> debuglog: <4> ivfs_init_once: instance id 0xbe6b086 0xf416bed2
      09:46:04.192 [3603068] <2> debuglog: <2> remove_tempdir: tempdir is /usr/openv/tmp/nbfsd_ivfs_tempfiles
      09:46:04.192 [3603068] <2> debuglog: <2> remove_tempdir: no tempdir to remove
      09:46:04.192 [3603068] <2> debuglog: <2> create_tempdir: created tempdir - /usr/openv/tmp/nbfsd_ivfs_tempfiles
      09:46:04.192 [3603068] <2> debuglog: <2> NEW_xmiglist: setting on-demand image blk cache size to 20 MB
      09:46:04.192 [3603068] <2> debuglog: <2> vfs::vfs: new vfs 0x25bcff0
      09:46:04.192 [3603068] <2> debuglog: <2> vfs::_ialloc: new vino 0x25c5140, vfs 0x25bcff0, inum 1, name (root)
      09:46:04.192 [3603068] <2> debuglog: <2> vfs::_init_rootdir: new root vip 0x25c5140, vfs 0x25bcff0
      09:46:04.192 [3603068] <2> debuglog: <2> vfs::_ialloc: new vino 0x25c5270, vfs 0x25bcff0, inum 10, name backups
      09:46:04.192 [3603068] <2> debuglog: <2> vfs::_ialloc: new vino 0x25c5490, vfs 0x25bcff0, inum 11, name inprogress
      09:46:04.192 [3603068] <2> debuglog: <2> vfs::_ialloc: new vino 0x25c56b0, vfs 0x25bcff0, inum 12, name aif
      09:46:04.192 [3603068] <2> debuglog: <4> ivfs_init_once: image options set to 0103
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:   VFS VFS { vfs 0x25bcff0, dev 1, options 0, nextinum 13, root 0x25c5140, temppath /usr/openv/tmp/nbfsd_ivfs_tempfiles }
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:       DIR VINO { vino 0x25c5140, vfs 0x25bcff0, DIR, inum 1/1, size 8192, parent (nil), name (root) }  /
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:           VINO { vino 0x25c5270, vfs 0x25bcff0, DIR, inum 1/10, size 8192, parent 0x25c5140, name backups }  backups
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:           VINO { vino 0x25c5490, vfs 0x25bcff0, DIR, inum 1/11, size 8192, parent 0x25c5140, name inprogress }  inprogress
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:           VINO { vino 0x25c56b0, vfs 0x25bcff0, DIR, inum 1/12, size 8192, parent 0x25c5140, name aif }  aif
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:           DIR VINO { vino 0x25c5270, vfs 0x25bcff0, DIR, inum 1/10, size 8192, parent 0x25c5140, name backups }  /backups
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:           DIR VINO { vino 0x25c5490, vfs 0x25bcff0, DIR, inum 1/11, size 8192, parent 0x25c5140, name inprogress }  /inprogress
      09:46:04.192 [3603068] <2> debuglog: <2> dirdump:           DIR VINO { vino 0x25c56b0, vfs 0x25bcff0, DIR, inum 1/12, size 8192, parent 0x25c5140, name aif }  /aif
      09:46:04.192 [3603068] <2> debuglog: <2> cred_decode_and_register: decode successful: issue 1604357164, pid 3603068, tmo 10, job_id 4, bid client01_123456789, media , use
      09:46:04.192 [3603068] <2> debuglog: <2> ivfs_parse_use_options: bid client01_123456789, type , options
      09:46:04.192 [3603068] <2> debuglog: <2> ivfs_parse_use_options: generic use type
      09:46:04.192 [3603068] <2> debuglog: <2> ivfs_parse_use_options: returning useinfo 0x25c6e30 -
      09:46:04.192 [3603068] <2> debuglog: <2> cred_decode_and_register: accepted new cred: acp 0x25c6f00
      09:46:04.192 [3603068] <2> debuglog: <2> cred_add_new_clientname: added new client client01 to the list
      09:46:04.192 [3603068] <2> debuglog: <2> ivfs_cred_add: client01_123456789 (0 0)
      09:46:04.192 [3603068] <2> debuglog: <2> cred_dump1: ACP 0x25c6f00:  0 0 0  (nil) (nil)    0 0    1604357164 1604357164 1604357164 (0)  4  (none)  client01_123456789  (none)  (none)
      09:46:04.192 [3603068] <2> debuglog: <4> cred_dump: 1 creds (1604357164)
      09:46:55.327 [3603068] <2> debuglog: <4> handle_signal: signal 2 caught
      09:46:55.327 [3603068] <2> debuglog: <4> daemon_exit: exiting 2
      09:46:55.327 [3603068] <2> debuglog: <2> imglist::~imglist: this 0x25bcfc0
      09:46:55.327 [3603068] <2> debuglog: <2> remove_tempdir: tempdir is /usr/openv/tmp/nbfsd_ivfs_tempfiles
      09:46:55.327 [3603068] <2> debuglog: <2> remove_tempdir: removed tempdir - /usr/openv/tmp/nbfsd_ivfs_tempfiles
      09:46:55.327 [3603068] <2> debuglog: <2> nbufs_user_tmpdir_cleanup: entering ...
      09:46:55.327 [3603068] <2> debuglog: <2> nbufs_user_tmpdir_cleanup: no leftover user tmp files to remove
      09:46:55.327 [3603068] <2> debuglog: <2> remove_remaining_staging_files: entering ...
      09:46:55.327 [3603068] <2> debuglog: <2> daemon_exit: removed file </usr/openv/netbackup/bin/nbfsd_key>
      09:46:55.327 [3603068] <2> debuglog: <4> daemon_exit: NBFSD EXIT_STATUS 2
  • I realised that the NFS client was stopped on the media server. After starting that, the log looks better but i'm still getting the same errors.

    • marcusb12's avatar
      marcusb12
      Level 3

      Actually when I follow the comands in this document: https://www.veritas.com/content/support/en_US/article.100000686

      I can never mount the drive, it gets stuck at this point indefinitely.

      C:\Program Files\Veritas\NetBackup\bin>nbfs mount -server mymediaserver -cred BBCB97CF22B6C74CFA2738BC3C4F69E8CF7F31ECC069D672239D977B2FB3E2B288872549C0EC2F0FD83B540AA109000E373FCF7E1549FE8366D43A91BA4412BB *
      BASEDIR=
      MNTPATH=/NBUFS_A_EA9CC093F145072D_001
      MOUNTPOINT=

      Which looks like this on the media server:

      16:45:36.605 [3637197] <2> debuglog: <2> common_init: nbfsd: starting...  @(#) NetBackup_8.2  mymediaserver (2019062501, 1604382336 201103.164536)
      16:45:36.605 [3637197] <2> debuglog: <2> common_init: nbfsd: unix - Linux, mymediaserver, 4.18.0-193.14.3.el8_2.x86_64, #1 SMP Mon Jul 20 15:02:29 UTC 2020, x86_64
      16:45:36.605 [3637197] <2> logparams: nbfsd -d -v 5 -j 5 -B client02_123456789
      16:45:36.605 [3637197] <2> debuglog: <2> ivfs_parse_use_options: bid client02_123456789, type , options
      16:45:36.605 [3637197] <2> debuglog: <2> ivfs_parse_use_options: generic use type
      16:45:36.605 [3637197] <2> debuglog: <2> ivfs_parse_use_options: returning useinfo 0x3000f90 -
      16:45:36.605 [3637197] <2> debuglog: <2> read_shared_memory: Failed to get shared memory segment
      16:45:37.606 [3637197] <2> debuglog: <2> cred_load_keyfile: read nbfsd_key file
      16:45:57.125 [3636296] <8> vnet_get_user_credential_path: [vnet_vxss.c:1620] status 35 0x23
      16:45:57.125 [3636296] <8> vnet_check_user_certificate: [vnet_vxss_helper.c:4122] vnet_get_user_credential_path failed 35 0x23
      16:45:57.125 [3636296] <2> ConnectionCache::connectAndCache: Acquiring new connection for host forge, query type 81
      16:45:57.125 [3636296] <2> logconnections: BPDBM CONNECT FROM 10.66.4.50.43739 TO 10.66.4.50.13721 fd = 10
      16:45:57.130 [3636296] <2> closeConnection: Caching connection for query type 81 for reuse
      16:45:57.130 [3636296] <2> debuglog: <16> imgrec::refresh: failed to get image record for client02_123456789 (227)
      16:45:57.130 [3636296] <2> debuglog: <16> imgrec::refresh: THROWING 22 failed to get image record
      • Lowell_Palecek's avatar
        Lowell_Palecek
        Level 6

        Is this a DAG? If so, do you have the DAG name mapped to your Exchange server names in the Distributed Application Restore Mapping? This is a host configuration setting for the master server.

        The most recent error you're getting from your nbfsd mount attempt says that the master server is not providing the client about the backup image. Look in the bprd log to find out why. Bprd is the request daemon on the master server. I think the request is bpclimagelist. I am running a GRT backup to confirm it.