Restore Problem with Data Protector

classic Classic list List threaded Threaded
10 messages Options
Reply | Threaded
Open this post in threaded view
|

Restore Problem with Data Protector

Satei
Hello

I use HP Data Protector 6.20 with a Filebased Jukebox, so I want to give MHVTL a try because of the compression.
My Backup run perfectly but not the restore.

Here from the Data Protector.
I tryed it with and without compression.
Different Backups give different blocks out, but every time the restore failed.
[Warning] From: VRDA@XXX "F: [Archiv]"  Time: 24.10.2012 07:40:11
	Missing of data block detected, expecting block 40196 !

[Critical] From: VRDA@XXX "F: [Archiv]"  Time: 24.10.2012 07:40:11
	Missing of data block detected, expecting block 40196 !

[Critical] From: VRDA@XXX "F: [Archiv]"  Time: 24.10.2012 07:40:11
	Error reading next backup record ! 

[Warning] From: VRDA@XXX "F: [Archiv]"  Time: 24.10.2012 07:40:11
	Restore terminated with errors ! 

I use MHVTL 1.4-4 on CentOS 6.3 with 2.6.32-279.9.1.el6.x86_64.

Here are some logs, I cannot find anything unusual.
Hope someone can help me.

Thanks in advance.

Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 38900th contiguous READ_6 request (24259797) (delay 30650)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 38950th contiguous READ_6 request (24259847) (delay 31050)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39000th contiguous READ_6 request (24259897) (delay 31050)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39050th contiguous READ_6 request (24259947) (delay 28250)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39100th contiguous READ_6 request (24259997) (delay 31450)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39150th contiguous READ_6 request (24260047) (delay 30650)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39200th contiguous READ_6 request (24260097) (delay 29850)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39250th contiguous READ_6 request (24260147) (delay 30650)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39300th contiguous READ_6 request (24260197) (delay 27050)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39350th contiguous READ_6 request (24260247) (delay 30650)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39400th contiguous READ_6 request (24260297) (delay 29050)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39450th contiguous READ_6 request (24260347) (delay 29850)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39500th contiguous READ_6 request (24260397) (delay 31450)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39550th contiguous READ_6 request (24260447) (delay 29850)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39600th contiguous READ_6 request (24260497) (delay 28650)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39650th contiguous READ_6 request (24260547) (delay 31050)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39700th contiguous READ_6 request (24260597) (delay 29850)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39750th contiguous READ_6 request (24260647) (delay 29850)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39800th contiguous READ_6 request (24260697) (delay 31450)
Oct 24 07:40:10 XXX vtltape[23053]: processCommand(): 39850th contiguous READ_6 request (24260747) (delay 30250)
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 39900th contiguous READ_6 request (24260797) (delay 27450)
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 39950th contiguous READ_6 request (24260847) (delay 32250)
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 40000th contiguous READ_6 request (24260897) (delay 30650)
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 40050th contiguous READ_6 request (24260947) (delay 28250)
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 40100th contiguous READ_6 request (24260997) (delay 30250)
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 40150th contiguous READ_6 request (24261047) (delay 28250)
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 40200th contiguous READ_6 request (24261097) (delay 30250)
Oct 24 07:40:48 XXX vtltape[23053]: CDB (24261108) (delay 172805): 4d 00 71 00 00 00 00 00 40 00
Oct 24 07:40:48 XXX vtltape[23053]: ssc_log_sense(): LOG SENSE (24261108) ** :  Tape Capacity page
Oct 24 07:40:48 XXX vtltape[23053]: CDB (24261109) (delay 405): 01 00 00 00 00 00
Oct 24 07:40:48 XXX vtltape[23053]: ssc_rewind(): Rewinding (24261109) **
Oct 24 07:40:48 XXX vtltape[23053]: rewind_tape(): Media is writable
Oct 24 07:40:48 XXX vtltape[23053]: CDB (24261110) (delay 405): 4d 00 2e 00 00 00 00 01 44 00
Oct 24 07:40:48 XXX vtltape[23053]: ssc_log_sense(): LOG SENSE (24261110) ** :  TapeAlert page
Oct 24 07:40:48 XXX vtltape[23053]: CDB (24261114) (delay 10005): a2 20 00 20 00 00 00 00 00 ff 00 00
Oct 24 07:40:48 XXX vtltape[23053]: ssc_spin(): Security Protocol In (24261114) **
Oct 24 07:40:48 XXX vtltape[23053]: CDB (24261115) (delay 2005): 1b 00 00 00 00 00
Oct 24 07:40:48 XXX vtltape[23053]: ssc_load_unload(): Unloading tape (24261115) **
Oct 24 07:40:48 XXX vtltape[23053]: processMessageQ(): Sender id: 70, msg : unload
Oct 24 07:40:48 XXX vtltape[23053]: processMessageQ(): Library requested tape unload


dump_tape -f QUT001L4
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40190, data 2633637888
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40191, data 2633703424
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40192, data 2633768960
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40193, data 2633834496
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40194, data 2633900032
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40195, data 2633965568
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40196, data 2634031104
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40197, data 2634096640
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40198, data 2634162176
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40199, data 2634227712


Library: 70 CHANNEL: 2 TARGET: 00 LUN: 00
 Vendor identification: IBM
 Product identification: 03584L32
 Product revision level: 4.02
 Unit serial number: 70000070
 NAA: 70:11:22:33:ab:6:00:00

Drive: 71 CHANNEL: 2 TARGET: 00 LUN: 01
 Library ID: 70 Slot: 01
 Vendor identification: IBM
 Product identification: ULT3580-TD4
 Product revision level: 252D
 Unit serial number: 70000071
 NAA: 70:11:22:33:ab:6:00:01
 Compression: factor 9 enabled 0

Drive: 72 CHANNEL: 2 TARGET: 00 LUN: 2
 Library ID: 70 Slot: 2
 Vendor identification: IBM
 Product identification: ULT3580-TD4
 Product revision level: 252D
 Unit serial number: 70000072
 NAA: 70:11:22:33:ab:6:00:2
 Compression: factor 9 enabled 0

Drive1:
Drive2:

MAP 1:
MAP 2:
MAP 3:
MAP 4:
MAP 5:

Picker 1:

Slot 1: QUT001L4
Slot 2: QUT002L4
Slot 3: QUT003L4
Slot 4: QUT004L4
Slot 5: QUT005L4
Slot 6: QUT006L4
Slot 7: QUT007L4
Slot 8: QUT008L4
Slot 9: QUT009L4
Slot 10: QUT010L4
Slot 11: QUT011L4
Slot 12: QUT012L4
Slot 13: QUT013L4
Slot 14: QUT014L4
Slot 15: QUT015L4
Slot 16: QUT016L4
Slot 17: QUT017L4
Slot 18: QUT018L4
Slot 19: QUT019L4
Slot 20: CLN020L3

Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Mark Harvey
Administrator
Apologies, normally I get email notification of new posts..

I missed this one somehow.

I'll review tomorrow and reply in a little more detail.
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Satei
Somebody have a clue here?

Regards
Bodo
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Mark Harvey
Administrator
Looking at the information supplied:

Error message:
[Warning] From: VRDA@XXX "F: [Archiv]"  Time: 24.10.2012 07:40:11
        Missing of data block detected, expecting block 40196 !
So we're looking for block 40196 (+/- one)

Read data from virtual media without any errors reported:
Oct 24 07:40:11 XXX vtltape[23053]: processCommand(): 40200th contiguous READ_6 request (24261097) (delay 30250)
This log message indicates successfully reading blocks 40150 -> 40199..

This is unexpected.. After all the backup application gave up on block 40196.. I wonder why it kept issuing read_6 commands past where it thought there was no data ?

A dump of the virtual media around the suspect area checks out OK:
dump_tape -f QUT001L4
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40190, data 2633637888
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40191, data 2633703424
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40192, data 2633768960
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40193, data 2633834496
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40194, data 2633900032
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40195, data 2633965568
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40196, data 2634031104
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40197, data 2634096640
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40198, data 2634162176
Hdr:              data(0b), sz  65536/65536 , Blk No.: 40199, data 2634227712
Drive config looks good - Using zlib compression at highest compression ratio
Drive: 71 CHANNEL: 2 TARGET: 00 LUN: 01
 Library ID: 70 Slot: 01
 Vendor identification: IBM
 Product identification: ULT3580-TD4
 Product revision level: 252D
 Unit serial number: 70000071
 NAA: 70:11:22:33:ab:6:00:01
 Compression: factor 9 enabled 0

Drive: 72 CHANNEL: 2 TARGET: 00 LUN: 2
 Library ID: 70 Slot: 2
 Vendor identification: IBM
 Product identification: ULT3580-TD4
 Product revision level: 252D
 Unit serial number: 70000072
 NAA: 70:11:22:33:ab:6:00:2
 Compression: factor 9 enabled 0
I can only assume the backup application disabled compression before writing.. Otherwise the tape_dump would have shown compressed-data blocks.

 ==
Conclusion.
There is nothing in the mhvtl logs to indicate any particular error or cause.
Several items to not match up, however can be explained away (e.g. mhVTL set to use best compression, yet data is uncompressed)
The "Why did the backup application keep issuing 'read_6' SCSI commands after it logged that there was no more data" is more confusing - But I've never seen Data Protector in action, so I can't really comment if this is normal.

Can I please ask for the following tests (and logs) to help narrow down what is occurring.

1. Set 'VERBOSE = 3' in /etc/mhvtl/mhvtl.conf and re-start mhvtl daemons..
2. Run a short backup.
3. Run the 'dump_tape -f <media id>' against the tape used by Data Protector
4. Run a new backup to the same '<media id>' (i.e. append to the tape)
5. Run the 'dump_tape -f <media id>' against the tape used by Data Protector
6. Supply the outputs of the two 'dump_tape' sessions and the syslog (/var/log/messages) for the whole period of time from point 1 - now.

Perhaps Data Protector is writing some data (e.g. filemarks) which is being overwritten by the subsequent backup. When Data Protector reads a block (waiting for an expected error due to a filemark DP knows should be there), and doesn't find it, the above DP error is generated.

However to confirm this, I will need the above procedure and logs..
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Satei
Thanks for the help, I sure can give you some logs, but for the test shown above the compression was disables (enabled 0).
First it was enabled with factor 9, but due to the errors I disabled it for another test.
I don't know where I put the logs from the first test, but there was "Hdr: zlib" or so.
Do you still want the test or another?

Regards
Bodo
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Mark Harvey
Administrator
I thought the logs & dump data was most likely from different times/runs. If you could run two backups with the dump_tape at end if both runs & mhvtl verbose set to 3, that will be great. Hopefully something will show up. 

Sent from my iPhone

On 21/11/2012, at 17:25, "Satei [via MHVTL - Linux Virtual Tape Library - Community Forums]" <[hidden email]> wrote:

Thanks for the help, I sure can give you some logs, but for the test shown above the compression was disables (enabled 0).
First it was enabled with factor 9, but due to the errors I disabled it for another test.
I don't know where I put the logs from the first test, but there was "Hdr: zlib" or so.
Do you still want the test or another?

Regards
Bodo


To start a new topic under MHVTL - Linux Virtual Tape Library - Community Forums, email [hidden email]
To unsubscribe from MHVTL - Linux Virtual Tape Library - Community Forums, click here.
NAML
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Satei
OK I tryed first 2 Small Backups 1 ISO with 163MB.
Backup/Restore everything worked great.

Than another file, 4,33GB and restore:
[Warning] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 11:14:47
        Missing of data block detected, expecting block 40085 !

[Critical] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 11:14:47
        Missing of data block detected, expecting block 40085 !

[Critical] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 11:14:47
        Error reading next backup record !

[Warning] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 11:14:47
        Restore terminated with errors !

[Warning] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 11:14:47
        Nothing restored.

Tested the restore a second time, same error.

Than I fired the same Job (4,33GB) 2x and restore are OK.

Another "Tape" same Job, 5x Backup/Restore OK!
The 6. Time the error was there again:

[Warning] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 13:15:33
        Missing of data block detected, expecting block 32482 !

[Critical] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 13:15:33
        Missing of data block detected, expecting block 32482 !

[Critical] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 13:15:33
        Error reading next backup record !

[Warning] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 13:15:33
        Restore terminated with errors !

[Warning] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 13:15:33
        Nothing restored.

Also verified it a second time, If there is an error it come every time.

OK what LOG files do you need?
I don't think that you can read anything in the dump_tape logs.

So I post you the last messages Log:
Nov 21 13:15:26 XXX vtltape[7440]: ssc_read_6(): READ_6 (1509048) : 65536 bytes **
Nov 21 13:15:26 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:26 XXX vtltape[7440]: read_tape_block(): Reading blk 308276, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: read_header(): Reading header 308277 at offset 20201545728, type: DATA, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1509048), sz: 65536, sam_status: 0
Nov 21 13:15:26 XXX vtltape[7440]: CDB (1509049) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:26 XXX vtltape[7440]: ssc_read_6(): READ_6 (1509049) : 65536 bytes **
Nov 21 13:15:26 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:26 XXX vtltape[7440]: read_tape_block(): Reading blk 308277, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: read_header(): Reading header 308278 at offset 20201611264, type: DATA, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1509049), sz: 65536, sam_status: 0
Nov 21 13:15:26 XXX vtltape[7440]: CDB (1509050) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:26 XXX vtltape[7440]: ssc_read_6(): READ_6 (1509050) : 65536 bytes **
Nov 21 13:15:26 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:26 XXX vtltape[7440]: read_tape_block(): Reading blk 308278, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: read_header(): Reading header 308279 at offset 20201676800, type: DATA, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1509050), sz: 65536, sam_status: 0
Nov 21 13:15:26 XXX vtltape[7440]: CDB (1509051) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:26 XXX vtltape[7440]: ssc_read_6(): READ_6 (1509051) : 65536 bytes **
Nov 21 13:15:26 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:26 XXX vtltape[7440]: read_tape_block(): Reading blk 308279, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: read_header(): Reading header 308280 at offset 20201742336, type: DATA, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1509051), sz: 65536, sam_status: 0
Nov 21 13:15:26 XXX vtltape[7440]: CDB (1509052) (delay 2005): 08 00 01 00 00 00
Nov 21 13:15:26 XXX vtltape[7440]: ssc_read_6(): READ_6 (1509052) : 65536 bytes **
Nov 21 13:15:26 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:26 XXX vtltape[7440]: read_tape_block(): Reading blk 308280, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: read_header(): Reading header 308281 at offset 20201807872, type: DATA, size: 65536
Nov 21 13:15:26 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1509052), sz: 65536, sam_status: 0
Nov 21 13:15:26 XXX vtltape[7440]: CDB (1509053) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517001) (delay 1605): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517001) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316229, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316230 at offset 20722753536, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517001), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517002) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517002) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316230, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316231 at offset 20722819072, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517002), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517003) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517003) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316231, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316232 at offset 20722884608, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517003), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517004) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517004) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316232, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316233 at offset 20722950144, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517004), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517005) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517005) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316233, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316234 at offset 20723015680, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517005), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517006) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517006) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316234, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316235 at offset 20723081216, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517006), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517007) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517007) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316235, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316236 at offset 20723146752, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517007), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517008) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517008) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316236, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316237 at offset 20723212288, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517008), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517009) (delay 2005): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517009) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316237, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316238 at offset 20723277824, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517009), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517010) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517010) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316238, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316239 at offset 20723343360, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517010), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517011) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517011) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316239, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316240 at offset 20723408896, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517011), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517012) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517012) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316240, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316241 at offset 20723474432, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517012), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517013) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517013) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316241, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316242 at offset 20723539968, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517013), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517014) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517014) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316242, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316243 at offset 20723605504, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517014), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517015) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517015) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316243, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316244 at offset 20723671040, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517015), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517016) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517016) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316244, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316245 at offset 20723736576, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517016), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517017) (delay 2005): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517017) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316245, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316246 at offset 20723802112, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517017), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517018) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517018) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316246, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316247 at offset 20723867648, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517018), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517019) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517019) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316247, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316248 at offset 20723933184, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517019), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517020) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517020) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316248, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316249 at offset 20723998720, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517020), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517021) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517021) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316249, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316250 at offset 20724064256, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517021), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517022) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517022) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316250, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316251 at offset 20724129792, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517022), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517023) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517023) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316251, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316252 at offset 20724195328, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517023), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517024) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517024) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316252, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316253 at offset 20724260864, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517024), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517025) (delay 2405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517025) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316253, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316254 at offset 20724326400, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517025), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517026) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517026) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316254, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316255 at offset 20724391936, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517026), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517027) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517027) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316255, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316256 at offset 20724457472, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517027), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517028) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517028) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316256, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316257 at offset 20724523008, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517028), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517029) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517029) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316257, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316258 at offset 20724588544, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517029), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517030) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517030) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316258, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316259 at offset 20724654080, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517030), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517031) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517031) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316259, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316260 at offset 20724719616, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517031), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517032) (delay 5): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517032) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316260, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316261 at offset 20724785152, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517032), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517033) (delay 2005): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517033) : 65536 bytes **
Nov 21 13:15:32 XXX vtltape[7440]: readBlock(): Request to read: 65536 bytes, SILI: 0
Nov 21 13:15:32 XXX vtltape[7440]: read_tape_block(): Reading blk 316261, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: read_header(): Reading header 316262 at offset 20724850688, type: DATA, size: 65536
Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517033), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517034) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517034) : 65536 bytes **
Nov 21 13:16:10 XXX vtltape[7440]: CDB (1518582) (delay 172805): 4d 00 71 00 00 00 00 00 40 00
Nov 21 13:16:10 XXX vtltape[7440]: ssc_log_sense(): LOG SENSE (1518582) ** :  Tape Capacity page
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Looking for: log page 0x30
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Tape Usage (0x30)
Nov 21 13:16:10 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1518582), sz: 96, sam_status: 0
Nov 21 13:16:10 XXX vtltape[7440]: CDB (1518583) (delay 405): 01 00 00 00 00 00
Nov 21 13:16:10 XXX vtltape[7440]: ssc_rewind(): Rewinding (1518583) **
Nov 21 13:16:10 XXX vtltape[7440]: read_header(): Reading header 0 at offset 0, type: DATA, size: 8192
Nov 21 13:16:10 XXX vtltape[7440]: rewind_tape(): Media is writable
Nov 21 13:16:10 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1518583), sz: 0, sam_status: 0
Nov 21 13:16:10 XXX vtltape[7440]: CDB (1518584) (delay 405): 4d 00 2e 00 00 00 00 01 44 00
Nov 21 13:16:10 XXX vtltape[7440]: ssc_log_sense(): LOG SENSE (1518584) ** :  TapeAlert page
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Looking for: log page 0x2e
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Tape Alert (0x2e)
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Looking for: log page 0x2e
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Tape Alert (0x2e)
Nov 21 13:16:10 XXX vtltape[7440]: update_TapeAlert(): Setting TapeAlert flags 0x00000000 00000000
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Looking for: log page 0x0c
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Sequential Access (0x0c)
Nov 21 13:16:10 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1518584), sz: 324, sam_status: 0
Nov 21 13:16:10 XXX vtltape[7440]: CDB (1518588) (delay 8805): a2 20 00 20 00 00 00 00 00 ff 00 00
Nov 21 13:16:10 XXX vtltape[7440]: ssc_spin(): Security Protocol In (1518588) **
Nov 21 13:16:10 XXX vtltape[7440]: lookup_sp_specific(): Lookup 32
Nov 21 13:16:10 XXX vtltape[7440]: resp_spin_page_20(): Data Encryption Status page
Nov 21 13:16:10 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1518588), sz: 24, sam_status: 0
Nov 21 13:16:10 XXX vtltape[7440]: CDB (1518589) (delay 405): 1b 00 00 00 00 00
Nov 21 13:16:10 XXX vtltape[7440]: ssc_load_unload(): Unloading tape (1518589) **
Nov 21 13:16:10 XXX vtltape[7440]: updateMAM(): updateMAM(0)
Nov 21 13:16:10 XXX vtltape[7440]: clear_ult_WORM(): +++ Trace mode pages at 0x626680 +++
Nov 21 13:16:10 XXX vtltape[7440]: lookup_pcode(): Looking for: Page/subpage (1d/00)
Nov 21 13:16:10 XXX vtltape[7440]: lookup_pcode(): Found "Medium Configuration" -> Page/subpage (1d/00)
Nov 21 13:16:10 XXX vtltape[7440]: clear_WORM(): l: 0x626680, m: 0xf56600, m->pcodePointer: 0xf56640
Nov 21 13:16:10 XXX vtltape[7440]: ult_media_load(): +++ Trace +++ unload
Nov 21 13:16:10 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1518589), sz: 0, sam_status: 0
Nov 21 13:16:10 XXX vtltape[7440]: processMessageQ(): Sender id: 70, msg : unload
Nov 21 13:16:10 XXX vtltape[7440]: unloadTape(): Tape not mounted
Nov 21 13:16:10 XXX vtltape[7440]: processMessageQ(): Library requested tape unload

Hope that helps.

Thanks
Bodo
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Mark Harvey
Administrator
Thanks for the info..

DP error is:
[Critical] From: VRDA@BACK "F: [Archiv]"  Time: 21.11.2012 13:15:33
        Missing of data block detected, expecting block 32482 !
yet, there is nothing in the syslog for this time and the data indicates the position on tape was only around block 316261 just one second before (13:15:32)..

Any chance syslog was dropping entries (rate limited) ?

The scsi serial number jumped quite a bit without any entries recorded in syslog - 1517034 and next one logged is 1518582 which further indicates the syslog is being rate limited (or just can't keep up)..

Nov 21 13:15:32 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1517033), sz: 65536, sam_status: 0
Nov 21 13:15:32 XXX vtltape[7440]: CDB (1517034) (delay 405): 08 00 01 00 00 00
Nov 21 13:15:32 XXX vtltape[7440]: ssc_read_6(): READ_6 (1517034) : 65536 bytes **
<----> Missing completion of read_6 / serial number 1517034
Nov 21 13:16:10 XXX vtltape[7440]: CDB (1518582) (delay 172805): 4d 00 71 00 00 00 00 00 40 00
Nov 21 13:16:10 XXX vtltape[7440]: ssc_log_sense(): LOG SENSE (1518582) ** :  Tape Capacity page
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Looking for: log page 0x30
Nov 21 13:16:10 XXX vtltape[7440]: lookup_log_pg(): Tape Usage (0x30)
Nov 21 13:16:10 XXX vtltape[7440]: completeSCSICommand(): OP s/n: (1518582), sz: 96, sam_status: 0

Perhaps re-try the restore with mhvtl set to log level 2 - hopefully that will limit the amount of data sent to syslog but still log enough to identify what is going wrong.

I would love to see the dump_data of the media involved with the '2 small backups' which were successful. This would give me a reference to what is 'good' for Data Protector.
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Mark Harvey
Administrator
Any chance of testing with latest release (1.4-5) ?

I fixed a bug handling the last block and hence media written with earlier releases could contains one block too many..

Cheers
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Restore Problem with Data Protector

Stoyan
This post was updated on .
Hello and happy new 2013!
I used to provide consultancy for Omniback/Data Protector and MHVTL helped me a lot back then.
On the topic in hand - DP uses Raima DB (the Internal Database), a list of error codes can be found on Raima's website (sorry - my DP - related stuff is long gone), BUT - here I see 2 things, that may cause the error:
1 - we'll need some outputs - if you use Media Agent on your MHVTL box, get me '/opt/omni/lbin/devbra -dev',
also, get some logs - /var/opt/omni - missing block can be caused (in 6.x), by a veeery annoying bug with the shared memory allocation, in which case, you'll have to do 'mv /var/opt/omni/tmp /var/opt/omni/tmp.old' and restart the service, to reload the settings, or you'll have to do Tape Verification - this you can do through the GUI, so the records in the IDB will be refreshed - verification will read the catalog blocks and compare it to the available record.
Have you done IDB backup? If yes - good, if no - go and make one - it is veeeeeery handy.
Why did you choose IBM tapes to use for the emulation - DP works fine with them, but I would use Ultrium.
Have you messed around with block sizes?
Also, do a 'df -h', and check the available space on the Windows - just in case :)
I'm setting up an alert, so I'll be able to follow up the thread.
All best,
   Stoyan