Issue with a job on Netbackup

[corsa-fr]

Hello,

I have an issue with a specific job on Netbackup 7.1.0.4

On the Activity Monitor in Netbackup Administration Console, I see this job in "begin writing" state but no kilobytes has been written!

This job contain about 5TO of data.

I think Netbackup made a image of this job before written on tape. But this image must be too big!

Have you an idea please? It is urgently because I have no backup of these data!

Thanks in advance

Best regards,

[MilesVScott]

If an image is larger than a physical tape NetBackup will logically finish on a new tape if one is available. Since the image is so big it may take some time for the backup to occur especially if you are using a snapshot.

How long has the backup been running? Also do you see anythnig in the detailed status indicating there is a problem?

[corsa-fr]

The job was started over 4 days!

I have no status indicating a problem.

In the detailed status I can see that the robot mounting the tape, positioning the tape to file....and then the last detailed is begin writing. That's all

Thank you

[Nicolai]

Cancel the job and restart it. I see from time to time that a client never start transfering data. When the job is re-started everything runs fine.

[corsa-fr]

Nicolai,

I have already cancel this job and restart it...

But it doesn't work

[MilesVScott]

What kind of files are included in the backup schedule? And what policy type is it?

[MilesVScott]

Also, do you have an estimation of how many files there are?

[Nathan_Kippen]

Are you restoring the entire tape?  What kind of backup was it?  NDMP, vstorage, synthetic, normal, etc...

Sometimes it can take awhile to position -- but not 4 days :)

[MilesVScott]

I dont think this is a restore. It sounds like it was a image staged to disk and duplicated to tape.

Is that correct corsa?

[Marianne]

We need more details....

OS on problematic client? 
What is being backed up - file system or database?
What is in Backup selection of the policy?
Is 'allow multiple data streams' selected in policy attributes?
Is this a new setup that has never worked before?
Can you see 'Connecting' and 'Connected' status in Job details? Please post all text in Job details.

Please also ensure that ll of these log folders exist:
On media server: bpbrm and bptm
(bpbrm will confirm connection to client, bptm if any was received)
On client: bpcd and bpbkar (if filesystem backup)
(bpcd will confirm connectivity with media server, bpbkar details of data sent to media server)

If you have these logs covering the time of 'start writing', please rename to reflect process name (e.g. bptm.txt) and  post as File attachments.

[corsa-fr]

Thanks for helping me.

The policy type is in NDMP.

This is not a restore but a backup from a file server on Netapp.

In fact, before this policy worked with the same parameter.

But since a few weeks, this policy does not work

I did not change parameter.

You can see the detailed status:

10/09/2012 8:13:57 AM - Info nbjm(pid=4412) starting backup job (jobid=118602) for client frnetapp01, policy po-file-frnetapp01_frs02_clients, schedule monthly 
10/09/2012 8:13:59 AM - Info bpbrm(pid=9588) frnetapp01 is the host to backup data from    
10/09/2012 8:13:59 AM - Info bpbrm(pid=9588) reading file list from client       
10/09/2012 8:13:59 AM - Info bpbrm(pid=9588) starting ndmpagent on client        
10/09/2012 8:13:59 AM - Info ndmpagent(pid=8860) Backup started          
10/09/2012 8:13:59 AM - Info bptm(pid=9424) start           
10/09/2012 8:13:59 AM - estimated 0 Kbytes needed
10/09/2012 8:13:59 AM - Info nbjm(pid=4412) started backup job for client frnetapp01, policy po-file-frnetapp01_frs02_clients, schedule monthly on storage unit frpp10-hcart-robot-tld-1
10/09/2012 8:13:59 AM - started process bpbrm (9588)
10/09/2012 8:13:59 AM - connecting
10/09/2012 8:13:59 AM - connected; connect time: 00:00:00
10/09/2012 8:14:00 AM - Info bptm(pid=9424) using 32 data buffers        
10/09/2012 8:14:00 AM - Info bptm(pid=9424) using 262144 data buffer size       
10/09/2012 8:14:00 AM - Info bptm(pid=9424) start backup          
10/09/2012 8:14:00 AM - Info bptm(pid=9424) Waiting for mount of media id D768L4 (copy 1) on server frpp10.
10/09/2012 8:14:00 AM - mounting D768L4
10/09/2012 8:15:06 AM - Info bptm(pid=9424) media id D768L4 mounted on drive index 2, drivepath {3,0,1,0}, drivename TLD001.lto4.d1, copy 1
10/09/2012 8:15:06 AM - mounted; mount time: 00:01:06
10/09/2012 8:15:10 AM - positioning D768L4 to file 1
10/09/2012 8:15:12 AM - positioned D768L4; position time: 00:00:02
10/09/2012 8:15:12 AM - begin writing

I tried this today: I have change the backup folder. I took a subfolder.

For example: In the \\frnetapp01\client folder, I have select this path \\frnetapp01\client\X

And with this change, the backup is successfuly

So if I selected a subfolder, the backup is done with the same policy!

Now, I am scanning the \\frnetapp01\client folder to know size and number of file.

Have you an idea?

Thank you very much

Best regards,

[Andy_Welburn]

I've copied this from a post I wrote a few years ago, there are several 'phases' an NDMP backup goes through before it starts writing to tape. With a large volume this can take wuite some time:

You say that it never starts writing - how long do you leave it?

There are several phases that the NDMP backup goes through:

Phase I and II: Build the map of files and directories and collect file history and attribute information

Phase III: Dump data to tape, specifically directory entries
Phase IV: Dump files
Phase V: Dump ACLs

Now depending on the make-up of the volume being backed up then each period could take some time.

e.g. from one of our NetApp NDMP save logs:

dmp Tue Feb 10 15:45:45 GMT /vol/data1/CS(0) Start (Level 0, NDMP)
dmp Tue Feb 10 15:45:45 GMT /vol/data1/CS(0) Options (b=63, u)
dmp Tue Feb 10 15:45:45 GMT /vol/data1/CS(0) Snapshot (weekly.0, Mon Feb  9 00:02:29 GMT)
dmp Tue Feb 10 15:46:13 GMT /vol/data1/CS(0) Tape_open (ndmp)
dmp Tue Feb 10 15:46:13 GMT /vol/data1/CS(0) Phase_change (I)
dmp Tue Feb 10 19:18:07 GMT /vol/data1/CS(0) Phase_change (II)
dmp Tue Feb 10 19:36:47 GMT /vol/data1/CS(0) Phase_change (III)
dmp Tue Feb 10 23:23:14 GMT /vol/data1/CS(0) Phase_change (IV)
dmp Wed Feb 11 19:14:48 GMT /vol/data1/CS(0) Phase_change (V)
dmp Wed Feb 11 20:44:07 GMT /vol/data1/CS(0) Tape_close (ndmp)
dmp Wed Feb 11 20:44:08 GMT /vol/data1/CS(0) End (1871102 MB)

So as you can see there are quite a few hours between the job starting & data actually being written to tape.

As far as the location of the logs - in our instance we have NFS mounted our NetApp "root" or vol0 areas on our master & for NetApp the above extract was taken from etc/log/backup

[Marianne]

Why UNC path if policy type is NDMP?

Please post policy config:

bppllist <policy-name> -U

[Andy_Welburn]

Why UNC path if policy type is NDMP?

Good point!

[corsa-fr]

This is a part of the log on my Netapp:

dmp Thu Oct 11 08:15:33 CES /vol/frs02_k/q_frs02_k/Clients(0) Start (Level 0, NDMP)
dmp Thu Oct 11 08:15:33 CES /vol/frs02_k/q_frs02_k/Clients(0) Options (b=0, u)
dmp Thu Oct 11 08:15:33 CES /vol/frs02_k/q_frs02_k/Clients(0) Snapshot (snapshot_for_backup.19078, Thu Oct 11 08:15:13 CES)
dmp Thu Oct 11 08:15:33 CES /vol/frs02_k/q_frs02_k/Clients(0) Tape_open (ndmp)
dmp Thu Oct 11 08:15:33 CES /vol/frs02_k/q_frs02_k/Clients(0) Phase_change (I)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Tape_close (ndmp)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Abort (0 MB)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (reg inodes: 4803 other inodes: 0 dirs: 49319 nt dirs: 36387 nt inodes: 7116 acls: 10422)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Phase 1 time: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Phase 3: directories dumped: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Phase 3: wafl directory blocks read: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Phase 3 throughput (MB sec): read 0 write 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Percent of phase3 time spent for: reading inos 0% dumping ino 0%)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Percent of phase3 dump time spent for: convert-wafl-dirs 0% lev0-ra 0%)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Phase 3 averages (usec): wafl load buf time 0 level 0 ra time 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Phase 4: inodes dumped: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Phase 4: wafl data blocks read: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Percent of phase4 time spent for: reading inos 0% dumping inos 0%)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (# buffers of filehistory sent dir: 0 node: 0 mixed: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (# times filehistory send was blocked dir: 0 node: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (# filehistory flush operations dir: 0 node: 1)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (# filehistory entries dir: 0 node: 0 )
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Dir to FH entry time stats (msec) numEntries: 0 min: -1 max: 0 avg: 0 tot: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Node to FH Entry time stats (msec) numEntries: 0 min: -1 max: 0 avg: 0 tot: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Dir FH to NDMP Entry Time Stats (msec) numEntries: 0 min: -1 max: 0 avg: 0 tot: 0)
dmp Thu Oct 11 08:26:15 CES /vol/frs02_k/q_frs02_k/Clients(0) Log_msg (Node FH to NDMP Entry Time Stats (msec) numEntries: 0 min: -1 max: 0 avg: 0 tot: 0)

You can see the bppllist <policy-name> -U command:

C:\Windows\system32>bppllist po-file-frnetapp01_frs02_clients -U
------------------------------------------------------------

Policy Name:       po-file-frnetapp01_frs02_clients

  Policy Type:         NDMP
  Active:              yes
  Effective date:      09/23/2008 14:26:07
  Mult. Data Streams:  yes
  Client Encrypt:      no
  Checkpoint:          no
  Policy Priority:     0
  Max Jobs/Policy:     Unlimited
  Disaster Recovery:   0
  Collect BMR info:    no
  Residence:           frpp10-hcart-robot-tld-0
  Volume Pool:         vp-daily-ret1m
  Server Group:        *ANY*
  Keyword:             (none specified)
  Data Classification:       -
  Residence is Storage Lifecycle Policy:    no
  Application Discovery:      no
  Discovery Lifetime:      0 seconds

  Granular Restore Info:  no
  Ignore Client Direct:  no
  HW/OS/Client:  NDMP          NDMP          frnetapp01

  Include:  /vol/frs02_k/q_frs02_k/Clients

  Schedule:          monthly
    Type:            Full Backup
    Maximum MPX:     1
    Synthetic:       0
    PFI Recovery:    0
    Retention Level: 10 (10 years)
    Number Copies:   1
    Fail on Error:   0
    Residence:       frpp10-hcart-robot-tld-0
    Volume Pool:     (same as policy volume pool)
    Server Group:    *ANY*
    Calendar sched: Enabled
      SPECIFIC DATE 0 - 11/30/2007
      SPECIFIC DATE 1 - 10/03/2008
      SPECIFIC DATE 2 - 04/30/2009
      SPECIFIC DATE 3 - 06/05/2009
      SPECIFIC DATE 4 - 07/03/2009
      SPECIFIC DATE 5 - 07/31/2009
      SPECIFIC DATE 6 - 08/28/2009
      SPECIFIC DATE 7 - 10/02/2009
      SPECIFIC DATE 8 - 11/27/2009
      SPECIFIC DATE 9 - 01/29/2010
      SPECIFIC DATE 10 - 02/26/2010
      SPECIFIC DATE 11 - 04/02/2010
      SPECIFIC DATE 12 - 04/30/2010
      SPECIFIC DATE 13 - 05/29/2010
      SPECIFIC DATE 14 - 07/03/2010
      SPECIFIC DATE 15 - 09/04/2010
      SPECIFIC DATE 16 - 10/02/2010
      SPECIFIC DATE 17 - 12/04/2010
      SPECIFIC DATE 18 - 01/29/2011
      SPECIFIC DATE 19 - 03/05/2011
      SPECIFIC DATE 20 - 03/26/2011
      SPECIFIC DATE 21 - 04/02/2011
      SPECIFIC DATE 22 - 05/07/2011
      SPECIFIC DATE 23 - 05/14/2011
      SPECIFIC DATE 24 - 06/04/2011
      SPECIFIC DATE 25 - 06/18/2011
      SPECIFIC DATE 26 - 07/09/2011
      SPECIFIC DATE 27 - 07/30/2011
      SPECIFIC DATE 28 - 08/27/2011
      SPECIFIC DATE 29 - 10/01/2011
      SPECIFIC DATE 30 - 10/29/2011
      SPECIFIC DATE 31 - 12/03/2011
      SPECIFIC DATE 32 - 02/04/2012
      SPECIFIC DATE 33 - 03/03/2012
      SPECIFIC DATE 34 - 03/31/2012
      SPECIFIC DATE 35 - 04/28/2012
      Last day of month
      EXCLUDE DATE 0 - 11/29/2007
      EXCLUDE DATE 1 - 04/29/2009
      EXCLUDE DATE 2 - 05/30/2009
      EXCLUDE DATE 3 - 06/29/2009
      EXCLUDE DATE 4 - 07/30/2009
      EXCLUDE DATE 5 - 08/30/2009
      EXCLUDE DATE 6 - 09/29/2009
      EXCLUDE DATE 7 - 11/29/2009
      EXCLUDE DATE 8 - 01/30/2010
      EXCLUDE DATE 9 - 02/27/2010
      EXCLUDE DATE 10 - 03/30/2010
      EXCLUDE DATE 11 - 04/29/2010
      EXCLUDE DATE 12 - 05/31/2010
      EXCLUDE DATE 13 - 06/30/2010
      EXCLUDE DATE 14 - 08/31/2010
      EXCLUDE DATE 15 - 09/30/2010
      EXCLUDE DATE 16 - 11/30/2010
      EXCLUDE DATE 17 - 01/31/2011
      EXCLUDE DATE 18 - 03/31/2011
      EXCLUDE DATE 19 - 04/02/2011
      EXCLUDE DATE 20 - 05/31/2011
      EXCLUDE DATE 21 - 06/04/2011
      EXCLUDE DATE 22 - 06/30/2011
      EXCLUDE DATE 23 - 07/31/2011
      EXCLUDE DATE 24 - 09/30/2011
      EXCLUDE DATE 25 - 10/31/2011
      EXCLUDE DATE 26 - 06/30/2012
      EXCLUDE DATE 27 - 07/31/2012
    Residence is Storage Lifecycle Policy:     0
    Daily Windows:
          Saturday   00:20:00  -->  Monday     07:00:00

  Schedule:          Weekly
    Type:            Full Backup
    Maximum MPX:     1
    Synthetic:       0
    PFI Recovery:    0
    Retention Level: 3 (1 month)
    Number Copies:   1
    Fail on Error:   0
    Residence:       (specific storage unit not required)
    Volume Pool:     vp-weekly-ret1m
    Server Group:    (same as specified for policy)
    Calendar sched: Enabled
      Saturday, Week 1
      Saturday, Week 2
      Saturday, Week 3
      Saturday, Week 4
      Saturday, Week 5
      EXCLUDE DATE 0 - 10/03/2008
      EXCLUDE DATE 1 - 10/31/2008
      EXCLUDE DATE 2 - 11/28/2008
      EXCLUDE DATE 3 - 01/30/2009
      EXCLUDE DATE 4 - 02/27/2009
      EXCLUDE DATE 5 - 05/01/2009
      EXCLUDE DATE 6 - 06/05/2009
      EXCLUDE DATE 7 - 07/03/2009
      EXCLUDE DATE 8 - 07/31/2009
      EXCLUDE DATE 9 - 08/28/2009
      EXCLUDE DATE 10 - 10/30/2009
      EXCLUDE DATE 11 - 11/27/2009
      EXCLUDE DATE 12 - 01/01/2010
      EXCLUDE DATE 13 - 01/29/2010
      EXCLUDE DATE 14 - 02/26/2010
      EXCLUDE DATE 15 - 04/02/2010
      EXCLUDE DATE 16 - 04/30/2010
      EXCLUDE DATE 17 - 05/29/2010
      EXCLUDE DATE 18 - 07/03/2010
      EXCLUDE DATE 19 - 07/31/2010
      EXCLUDE DATE 20 - 09/04/2010
      EXCLUDE DATE 21 - 10/02/2010
      EXCLUDE DATE 22 - 10/30/2010
      EXCLUDE DATE 23 - 11/06/2010
      EXCLUDE DATE 24 - 12/04/2010
      EXCLUDE DATE 25 - 01/01/2011
      EXCLUDE DATE 26 - 01/29/2011
      EXCLUDE DATE 27 - 03/05/2011
      EXCLUDE DATE 28 - 03/26/2011
      EXCLUDE DATE 29 - 05/07/2011
      EXCLUDE DATE 30 - 05/14/2011
      EXCLUDE DATE 31 - 06/18/2011
      EXCLUDE DATE 32 - 07/09/2011
      EXCLUDE DATE 33 - 08/27/2011
      EXCLUDE DATE 34 - 10/01/2011
      EXCLUDE DATE 35 - 12/03/2011
      EXCLUDE DATE 36 - 02/04/2012
      EXCLUDE DATE 37 - 03/03/2012
      EXCLUDE DATE 38 - 03/31/2012
      EXCLUDE DATE 39 - 04/28/2012
      EXCLUDE DATE 40 - 05/05/2012
      EXCLUDE DATE 41 - 05/19/2012
      EXCLUDE DATE 42 - 06/02/2012
      EXCLUDE DATE 43 - 06/30/2012
      EXCLUDE DATE 44 - 07/28/2012
      EXCLUDE DATE 45 - 09/01/2012
    Residence is Storage Lifecycle Policy:     0
    Daily Windows:

  Schedule:          Daily
    Type:            Differential Incremental Backup
    Maximum MPX:     1
    Synthetic:       0
    PFI Recovery:    0
    Retention Level: 3 (1 month)
    Number Copies:   1
    Fail on Error:   0
    Residence:       (specific storage unit not required)
    Volume Pool:     (same as policy volume pool)
    Server Group:    (same as specified for policy)
    Calendar sched: Enabled
      Monday, Week 1
      Tuesday, Week 1
      Wednesday, Week 1
      Thursday, Week 1
      Monday, Week 2
      Tuesday, Week 2
      Wednesday, Week 2
      Thursday, Week 2
      Monday, Week 3
      Tuesday, Week 3
      Wednesday, Week 3
      Thursday, Week 3
      Monday, Week 4
      Tuesday, Week 4
      Wednesday, Week 4
      Thursday, Week 4
      Monday, Week 5
      Tuesday, Week 5
      Wednesday, Week 5
      Thursday, Week 5
      EXCLUDE DATE 0 - 10/30/2008
      EXCLUDE DATE 1 - 12/30/2008
      EXCLUDE DATE 2 - 02/08/2009
      EXCLUDE DATE 3 - 02/09/2009
      EXCLUDE DATE 4 - 03/30/2009
      EXCLUDE DATE 5 - 04/30/2009
      EXCLUDE DATE 6 - 08/27/2009
      EXCLUDE DATE 7 - 08/30/2009
      EXCLUDE DATE 8 - 10/04/2009
      EXCLUDE DATE 9 - 11/26/2009
      EXCLUDE DATE 10 - 12/06/2009
      EXCLUDE DATE 11 - 12/30/2009
      EXCLUDE DATE 12 - 12/31/2009
      EXCLUDE DATE 13 - 02/25/2010
      EXCLUDE DATE 14 - 04/01/2010
      EXCLUDE DATE 15 - 04/29/2010
      EXCLUDE DATE 16 - 07/27/2010
      EXCLUDE DATE 17 - 07/30/2010
      EXCLUDE DATE 18 - 08/09/2010
      EXCLUDE DATE 19 - 09/10/2010
      EXCLUDE DATE 20 - 11/01/2010
      EXCLUDE DATE 21 - 11/02/2010
      EXCLUDE DATE 22 - 11/04/2010
      EXCLUDE DATE 23 - 12/06/2010
      EXCLUDE DATE 24 - 01/04/2011
      EXCLUDE DATE 25 - 01/18/2011
      EXCLUDE DATE 26 - 02/21/2011
      EXCLUDE DATE 27 - 04/26/2011
      EXCLUDE DATE 28 - 02/07/2012
      EXCLUDE DATE 29 - 02/08/2012
      EXCLUDE DATE 30 - 05/02/2012
      EXCLUDE DATE 31 - 05/03/2012
      EXCLUDE DATE 32 - 05/08/2012
      EXCLUDE DATE 33 - 05/29/2012
      EXCLUDE DATE 34 - 05/30/2012
      EXCLUDE DATE 35 - 05/31/2012
      EXCLUDE DATE 36 - 07/30/2012
      EXCLUDE DATE 37 - 08/01/2012
      EXCLUDE DATE 38 - 08/13/2012
      EXCLUDE DATE 39 - 10/01/2012
      EXCLUDE DATE 40 - 10/02/2012
      EXCLUDE DATE 41 - 10/03/2012
    Residence is Storage Lifecycle Policy:     0
    Daily Windows:

C:\Windows\system32>

If I do not use the UNC path, what can I use?

[Dharmendu_Maity]

Due to huge data size, the NBU not able to estimate the approximate data size. Backup will start once NBU can able to estimate the data size.

In your log it shows "10/09/2012 8:13:59 AM - estimated 0 Kbytes needed"

To resolve the issue, you need to take backup of subfolders instead of main parent folder.

[Nathan_Kippen]

This isn't UNC... you are backing it up directly from your filer.

Perhaps look at your ndmpd log on the filer .. not just the backup log it should reveal more of what is happening from the filer's perspective.

Filer> ndmpd debug file

Filer> ndmpd debug level 3

Look at /etc/log/ndmpdlog.yyyymmdd

It's also best to do netapp ndmp backups at a volume level or qtree level.  We use qtrees and quotas because it does give you size and file count information when running quota reports.