phase 2 import fails to find images

Technically, NBU doesn't write anything ...all done by the OS ...

The logical-end-of data is just an empty backup header, no idea how this is missing, but as it's after the data, in theory, the data will be read ok, it might then error / cause some issue - I've never seen this personally, so I simply don't know the answer to that.

Generally (not always before I get jumped on) - providing all the tapes for the given backup(s) are available imports either work or they don't, and there is not always something that can be done to fix, when they don't.

You sound like you are very experienced, so without meaning to insult your intellegence, take a peep at this top TN 'just in case'...

http://www.symantec.com/docs/TECH72429

WHen searching for images to import, leave things set to 'All' as shown, and use a very big date range - if it still fails, we'll have to think again.

I presume here, the phase 1 completed with status 0 ?

Regards,

Martin

Martin:

Thanks for the response.  I mention the possibility of a missing end-of-backup record because I'm trying to import an image that NBU thinks failed.  We're having an issue with our NDMP backups where the entire image is written to tape (based on number of files and size of image), but some final ack somewhere is being missed, and the job errors out.  The image is making it to tape - otherwise I wouldn't be able to import it - but because of that missing final ack, it's possible that something isn't getting written.  If it's expecting an actual empty backup header, and not just an EOF, then that might be it.

I did see the technote, and I tried the GUI after the CLI failed.  Interestingly, I was able to do the stage 1 import again - not sure if that's right or not.  The image is only a day old, so I set the search time back two days, and left everything else default - which seems to be everything.  I also tried restricting the options with proper info.

The phase 1 imports said they finished successfully.

By the way - technically, the OS doesn't write anything - it's all done by the tape drive.  But neither the OS nor the tape drive will write anything without NBU initiating it; thus, NBU essentially writes to tape.

Bill

He he ... my favorite topic ...

"By the way - technically, the OS doesn't write anything - it's all done by the tape drive.  But neither the OS nor the tape drive will write anything without NBU initiating it; thus, NBU essentially writes to tape."

Yes, NBU passes the data to the OS and of course this has to happen.  However, when we look at tape issues in detail we have to consider that NBU is not writing anything to tape at all, the data flow is from NBU > OS > then to the tape drives via the tape driver OS drivers.    The reason is that in the vast majority of cases, if you try and troubleshoot a tape drive issue in NBU, you will never find the answer.  The vast majority, have a cause outside NBU.

Anyhow, back to the issue ...

NDMP - that could make a difference, not sure how the data is arranged for that.  Was this written by a media server, or, where the tape drives attached to the filer directly.

What I would do, is check in the catalog directly, see if the catalog files have been created :

/usr/openv/netbackup/db/images/<client>/<ctime>

or might be under 

/usr/openv/netbackup/db/images/<client>/<ctime>/tmp  (as only phase 1 run)

IF the files are not there, then that is why you do not find anything.  Maybe we have to consider why, but this will narrow it down a bit.

Martin

Hi Martin:

I see your point in regards to troubleshooting tape issues, although I've used the bptm logs a multitude of times to troubleshoot (and find) tape drive issues.  But we digress....

I found the catalog file under one of the images/host/ctime/tmp directories, which is heartening.  The ctime dir translates to Aug 3rd, which is interesting in that the backup was taken Aug 13.  The ctime in the image file is Aug 14.  I extended my import search back to Aug 1 to encompass the Aug 3 date, but I still get the same error (actually tried going back to 7/1 too...).

So if the image header file or whatever it is exists here, what is keeping phase 2 from picking it up?

Bill 

OK, the header file is create in tmp until the phase 2 is successful, then it would move up a level.

Can you post the file up here, maybe I can see something amiss.

Can you also post up a real header file from another ndmp backup that worked.

There will be differencies (as one is normal, the other partly imported) but it may assist me.

If I can't see anything, I'll see it one of the BL guys can assist with a quick look, that'll be tomorrow though.

Word of warning, a phase one import, that has not undergone phase2 , will expire in 7 days.  The tape, could then be overwritten.

Martin

Martin:

I've scrubbed the files and posted them below, as well as a diff.  I DO see differences which make me think I'm missing something from phase 1 - although maybe it's the fact that one is a full image and the other isn't.  The good one starts fragments at -1 - the "bad" one starts at 1, and doesn't show the other fragments that successfully imported in phase 1.  The bad one also has zeros for counters like kbytes, elapsed, expiration, num_files....  I also notice a bunch of white space at the end of the bad one.

root$ cat good
PROTOCOL_VERSION 9
START_TIME 0
END_TIME 0
SNAP_TIME 0
KBYTES 16469431
NUM_FRAGMENTS 2
COPIES 1
VERSION 8
CLIENT_TYPE 19
RETENTION_LEVEL 11
SCHEDULE_TYPE 0
COMPRESSION 0
ENCRYPTION 0
FILES_FILE_COMPRESSED 0
MPX 0
TIR_INFO 0
TIR_EXPIRATION 0
PRIMARY_COPY 1
IMAGE_TYPE 0
ELAPSED 2243
EXPIRATION 1345145245
NUM_FILES 531180
EXTENDED_SECURITY_INFO 0
REQUEST_PID 0
IND_FILE_RESTORE_FROM_RAW 0
IMAGE_DUMP_LEVEL 0
FILE_SYSTEM_ONLY 0
PREV_BLOCK_INCR_TIME 0
BLOCK_INCR_FULL_TIME 0
STREAM_NUMBER 0
CATARC 0
BACKUP_COPY 0
BACKUP_STATUS 0
JOB_ID 610554
NUM_RESUMES 0
RESUME_EXPIRATION 0
PFI_TYPE 0
IMAGE_ATTRIBUTE 0
SS_COMPLETED 0
NUM_DR_MEDIAS 0
# FRAG: c# f# K rem mt den fn id/path host bs off md dwo f_flags desc exp mpx rl chkpt rsm_nbr seq_no media_subtype keep_date copy_date i_unused1
FRAGMENT 1 -1 75447 0 2 14 20 234567 HOST 262144 511545 1344956308 4 0 *NULL* 0 0 0 0 0 0 1 0 0 0
FRAGMENT 1 1 16393984 0 2 14 19 234567 HOST 262144 447504 1344956308 4 0 *NULL* 1345145245 0 65547 0 0 0 1 0 1344974688 0
BACKUP_ID HOST_1344972445
CREATOR root
SCHED_LABEL TEST_FULL_NDMP
FILES_FILE POLICY_1344972445_FULL.f
FILES_FILE_SIZE 77257481
HISTO_INFO -1 -1 -1 -1 -1 -1 -1 -1 -1 -1
ESTIMATED_KBYTES 19763317
VM_TYPE 0
IS_SYNTHETIC 0
RUN_TIME 1344972445
LAST_BIRTHTIME 1344972445
CLIENT_CHARSET 0
SLP_VERSION 0
BMR_INFO 1
root$ #--------------------------------------
root$ cat bad
PROTOCOL_VERSION 9
START_TIME 0
END_TIME 0
SNAP_TIME 0
KBYTES 0
NUM_FRAGMENTS 1
COPIES 1
VERSION 8
CLIENT_TYPE 19
RETENTION_LEVEL 6
SCHEDULE_TYPE 0
COMPRESSION 0
ENCRYPTION 0
FILES_FILE_COMPRESSED 0
MPX 0
TIR_INFO 16
TIR_EXPIRATION 0
PRIMARY_COPY 1
IMAGE_TYPE 0
ELAPSED 0
EXPIRATION 0
NUM_FILES 0
EXTENDED_SECURITY_INFO 0
REQUEST_PID 0
IND_FILE_RESTORE_FROM_RAW 0
IMAGE_DUMP_LEVEL 0
FILE_SYSTEM_ONLY 0
PREV_BLOCK_INCR_TIME 0
BLOCK_INCR_FULL_TIME 0
STREAM_NUMBER 0
CATARC 0
BACKUP_COPY 0
BACKUP_STATUS 0
JOB_ID 610575
NUM_RESUMES 0
RESUME_EXPIRATION 0
PFI_TYPE 0
IMAGE_ATTRIBUTE 0
SS_CLASS_ID 196642441DD211B2A0E6E4D10B26C893
SS_COMPLETED 0
NUM_DR_MEDIAS 0
# FRAG: c# f# K rem mt den fn id/path host bs off md dwo f_flags desc exp mpx rl chkpt rsm_nbr seq_no media_subtype keep_date copy_date i_unused1
FRAGMENT 1 1 0 0 2 14 8 123456 MASTER 262144 9652733 1344864598 -1 0 *NULL* 1345672493 0 65542 0 0 0 0 0 0 0
BACKUP_ID HOST_1344981212
CREATOR root
SCHED_LABEL TAPE_FULL_W_C
KEYWORD C
FILES_FILE POLICY_1344981212_FULL.f
HISTO_INFO -1 -1 -1 -1 -1 -1 -1 -1 -1 -1
ESTIMATED_KBYTES 0
VM_TYPE 0
IS_SYNTHETIC 0
RUN_TIME 1344981212
LAST_BIRTHTIME 1344981212
CLIENT_CHARSET 0
SLP_VERSION 0
BMR_INFO 1
                                                                                                                                                                                                                                                                                                                                                                                                                                                    
root$ #--------------------------------------
root$ diff good bad
5,6c5,6
< KBYTES 16469431
< NUM_FRAGMENTS 2
---
> KBYTES 0
> NUM_FRAGMENTS 1
10c10
< RETENTION_LEVEL 11
---
> RETENTION_LEVEL 6
16c16
< TIR_INFO 0
---
> TIR_INFO 16
20,22c20,22
< ELAPSED 2243
< EXPIRATION 1345145245
< NUM_FILES 531180
---
> ELAPSED 0
> EXPIRATION 0
> NUM_FILES 0
34c34
< JOB_ID 610554
---
> JOB_ID 610575
38a39
> SS_CLASS_ID 196642441DD211B2A0E6E4D10B26C893
42,44c43,44
< FRAGMENT 1 -1 75447 0 2 14 20 234567 HOST 262144 511545 1344956308 4 0 *NULL* 0 0 0 0 0 0 1 0 0 0
< FRAGMENT 1 1 16393984 0 2 14 19 234567 HOST 262144 447504 1344956308 4 0 *NULL* 1345145245 0 65547 0 0 0 1 0 1344974688 0
< BACKUP_ID HOST_1344972445
---
> FRAGMENT 1 1 0 0 2 14 8 123456 MASTER 262144 9652733 1344864598 -1 0 *NULL* 1345672493 0 65542 0 0 0 0 0 0 0
> BACKUP_ID HOST_1344981212
46,48c46,48
< SCHED_LABEL TEST_FULL_NDMP
< FILES_FILE POLICY_1344972445_FULL.f
< FILES_FILE_SIZE 77257481
---
> SCHED_LABEL TAPE_FULL_W_C
> KEYWORD C
> FILES_FILE POLICY_1344981212_FULL.f
50c50
< ESTIMATED_KBYTES 19763317
---
> ESTIMATED_KBYTES 0
53,54c53,54
< RUN_TIME 1344972445
< LAST_BIRTHTIME 1344972445
---
> RUN_TIME 1344981212
> LAST_BIRTHTIME 1344981212
57a58
>                                                                                                                                                                                                                                                                                                                                                         

OK, so this is interesting.  I re-phase-1-imported the 2nd and 3rd tapes.  Yesterday I had done all three via the command line, then done the 1st one again through the GUI.  The tape listed in the FRAGMENT line was the first tape.  After doing the 2nd tape, the tmp file changed - COPIES was now 1, and the single FRAGMENT line was incremented to FRAG 3.  FRAG 2 and 3 are on the second tape.  Then after doing the 3rd (and last) tape again, COPIES was still 1, still a single FRAG line with the 3rd tape listed, but it said FRAG -1.  Still no love on the 2nd phase though....

Bill

Martin - just wondering if you've abandoned me....

Nope, sorry, snowed under with work ...

OK, on the bad copy of the header file I see this :

IMAGE_TYPE 0

I'm fairly sure that for an image that has successfully undergone phase1, this should be :

IMAGE_TYPE 1

If this would stop the image being found in phase 2 I don;t know, but it would be reasonable to suggest it would.

The rules are :

IMAGE_TYPE 0 = backup image that has never been imported (so must will be like this)

IMAGE_TYPE 1 = image that has been ONLY phase 1 imported

IMAGE_TYPE 2 = image that has been phase 2 imported

Can you post up the latest bad header file ...

Martin

So, interestingly, the header files on disk look different than they did last week, though the mtime hasn't updated.  Now that I know about these files I want to redo the whole phase 1 import and watch what happens here, since I was seeing changes last week.  Can I just remove the images/<host>/<ctime>/tmp files?  Or is there something in NBU to purge them?

Bill