apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

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

apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
I am a test engineer (not a developer) and have been using MHVTL as part of an automated test environment for several months.  
 Has anyone seen following issue and if so is there a fix?  
I am running MHVTL vtltape: version 0.18.11 on Fedora core 13 (2.6.34.) and use a local tapecopy tool for ALL copies listed below.
Apparent problem:  blocks 117728 thru 325858 are 1024 block size when read from MHVTL tape rather than expected original 65536 block size.

Tape is a 21 Gb  NetBackup tape when copied to MHVTL then read back from MHVTL shows a data loss of 13 Gig:
Note that most NBU tapes copied and used with MHVTL are fine and do not have this issue.

/dev/nst0 [20100922 12:37:22.100]: opened as type 1 @ 325859
/dev/nst0 [20100922 12:37:22.100]: set verbose to 3
/dev/nst0 [20100922 12:37:22.100]: <<<<<< <<<<<< rewind
/dev/nst0 [20100922 12:37:22.109]: rec 1024 (400) @ 0
/dev/nst0 [20100922 12:37:22.114]: 1 block, 1,024 bytes @ 1
/dev/nst0 [20100922 12:37:22.117]: throughput = 0.1 MB/s
/dev/nst0 [20100922 12:37:22.117]: eof 1
/dev/nst0 [20100922 12:37:22.120]: rec 1024 (400) @ 2
/dev/nst0 [20100922 12:37:22.122]: rec 65536 (10000) @ 3
/dev/nst0 [20100922 12:41:48.215]: rec 45056 (b000) @ 117726
/dev/nst0 [20100922 12:41:48.216]: 117725 blocks, 7,715,140,608 bytes @ 117727
/dev/nst0 [20100922 12:41:48.217]: throughput = 29.0 MB/s
/dev/nst0 [20100922 12:41:48.217]: eof 2
/dev/nst0 [20100922 12:41:48.219]: rec 1024 (400) @ 117728
/dev/nst0 [20100922 12:47:04.652]: 208130 blocks, 213,125,120 bytes @ 325858
/dev/nst0 [20100922 12:47:04.653]: throughput = 0.7 MB/s
/dev/nst0 [20100922 12:47:04.653]: eof 3
7928266752 bytes copied in 582.55 seconds
/dev/nst0 [20100922 12:47:04.655]: total 325,856 blocks, 7,928,266,752 bytes, 0 skips @ 325859
/dev/nst0 [20100922 12:47:04.655]: close


Non-MHVTL results: (original blocks 117731 through 325858 are 65536 block size)

(a) original loaded into a tape drive and read before copy and…
(b) when original copied to a SEPATON VTL and then read back I get consistent  and correct block sizes:

AAC0006 [20101001 12:10:01.809]: opened as type 5 @ 0
AAC0006 [20101001 12:10:01.809]: set verbose to 3
AAC0006 [20101001 12:10:01.810]: <<<<<< <<<<<< rewind
AAC0006 [20101001 12:10:01.810]: rec 1024 (400)
AAC0006 [20101001 12:10:01.810]: 1 block, 1,024 bytes @ 1
AAC0006 [20101001 12:10:01.810]: throughput = 8.1 MB/s
AAC0006 [20101001 12:10:01.810]: eof 1
AAC0006 [20101001 12:10:01.810]: rec 1024 (400) @ 2
AAC0006 [20101001 12:10:01.811]: rec 65536 (10000) @ 3
AAC0006 [20101001 12:11:08.078]: rec 45056 (b000) @ 117726
AAC0006 [20101001 12:11:08.078]: 117725 blocks, 7,715,140,608 bytes @ 117727
AAC0006 [20101001 12:11:08.078]: throughput = 116.4 MB/s
AAC0006 [20101001 12:11:08.078]: eof 2
AAC0006 [20101001 12:11:08.078]: rec 1024 (400) @ 117728
AAC0006 [20101001 12:11:08.081]: rec 65536 (10000) @ 117731
AAC0006 [20101001 12:13:11.889]: 208130 blocks, 13,639,814,144 bytes @ 325858
AAC0006 [20101001 12:13:11.889]: throughput = 110.2 MB/s
AAC0006 [20101001 12:13:11.889]: eof 3
21354955776 bytes copied in 190.09 seconds
AAC0006 [20101001 12:13:11.899]: total 325,856 blocks, 21,354,955,776 bytes, 0 skips @ 325859

Appreciate any help. dlsk
nia
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

nia
Administrator
I am sure Mark will respond to this, but could be helpful if you can provide MHVTL VERBOSE 3 sys-log during the error.
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

ap2010
Also, did you use compression. Please try both with and without and see if you get the same results.
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
Here is the error info during readback: I'll check the compression option (enabled and set to 1)  and test with its alternate (off).
Note: no apparent errors when creating the MHVTL tape.
Note: I have the two (2) ~210 Meg logs created, one during MHVTL tape creation and the other during readback but don't think it wise to upload these unless requested. Thus the following snippet around the error.

================= MHVTL TAPE READBACK ERRORS  ========

Oct 18 19:34:38 vmapp03 vtltape[4513]: position_blocks_forw: filemark at 1
Oct 18 19:34:38 vmapp03 vtltape[4513]: position_blocks_forw: filemark at 117727
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_header: Reading header 117728 at offset 5779244040, type: DATA
Oct 18 19:34:38 vmapp03 vtltape[4513]: position_blocks_forw: Filemark encountered: block 117727
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: Sense buf: 0x617d60
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [80 00 01]
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: Sense buf: 0x617d60
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [20 00 00]
Oct 18 19:34:38 vmapp03 vtltape[4513]: mk_sense_short_block: Short block read: Requested: 65536, Read: 0, short by 65536 bytes
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: Sense buf: 0x617d60
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [80 00 01]
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: OP s/n: (1098890), sz: 0, sam_status: 2
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: [Key/ASC/ASCQ] [80 00 01]
Oct 18 19:34:38 vmapp03 vtltape[4513]: CDB (1098891) 4d 00 43 00 00 00 00 00 58 00
Oct 18 19:34:38 vmapp03 vtltape[4513]: processCommand: LOG SENSE (1098891) **
Oct 18 19:34:38 vmapp03 vtltape[4513]: resp_log_sense: LOG SENSE: Read error page
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: OP s/n: (1098891), sz: 88, sam_status: 0
Oct 18 19:34:38 vmapp03 vtltape[4513]: CDB (1098892) 4d 00 6e 00 00 00 00 01 44 00
Oct 18 19:34:38 vmapp03 vtltape[4513]: processCommand: LOG SENSE (1098892) **
Oct 18 19:34:38 vmapp03 vtltape[4513]: resp_log_sense: LOG SENSE: TapeAlert page
Oct 18 19:34:38 vmapp03 vtltape[4513]: resp_log_sense:  Returning TapeAlert flags: 0x0
Oct 18 19:34:38 vmapp03 vtltape[4513]: setTapeAlert: Setting TapeAlert flags 0x00000000 00000000
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: OP s/n: (1098892), sz: 324, sam_status: 0
Oct 18 19:34:38 vmapp03 vtltape[4513]: CDB (1098893) 08 00 10 00 00 00
Oct 18 19:34:38 vmapp03 vtltape[4513]: processCommand: READ_6 (1098893) : 1048576 bytes **
Oct 18 19:34:38 vmapp03 vtltape[4513]: readBlock: Request to read: 1048576 bytes
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_tape_block: Reading blk 117728
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_header: Reading header 117729 at offset 5779244169, type: DATA
Oct 18 19:34:38 vmapp03 vtltape[4513]: readBlock: Read 129 (129) bytes of compressed data, have 1024 bytes for result
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: Sense buf: 0x617d60
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [20 00 00]
Oct 18 19:34:38 vmapp03 vtltape[4513]: mk_sense_short_block: Short block read: Requested: 1048576, Read: 1024, short by 1047552 bytes
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: OP s/n: (1098893), sz: 1024, sam_status: 2
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: [Key/ASC/ASCQ] [20 00 00]
Oct 18 19:34:38 vmapp03 vtltape[4513]: CDB (1098894) 08 00 10 00 00 00
Oct 18 19:34:38 vmapp03 vtltape[4513]: processCommand: READ_6 (1098894) : 1048576 bytes **
Oct 18 19:34:38 vmapp03 vtltape[4513]: readBlock: Request to read: 1048576 bytes
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_tape_block: Reading blk 117729
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_header: Reading header 117730 at offset 5779244295, type: DATA
Oct 18 19:34:38 vmapp03 vtltape[4513]: readBlock: Read 126 (126) bytes of compressed data, have 1024 bytes for result
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: Sense buf: 0x617d60
Oct 18 19:34:38 vmapp03 vtltape[4513]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [20 00 00]
Oct 18 19:34:38 vmapp03 vtltape[4513]: mk_sense_short_block: Short block read: Requested: 1048576, Read: 1024, short by 1047552 bytes
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: OP s/n: (1098894), sz: 1024, sam_status: 2
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: [Key/ASC/ASCQ] [20 00 00]
Oct 18 19:34:38 vmapp03 vtltape[4513]: CDB (1098895) 08 00 00 04 00 00
Oct 18 19:34:38 vmapp03 vtltape[4513]: processCommand: READ_6 (1098895) : 1024 bytes **
Oct 18 19:34:38 vmapp03 vtltape[4513]: readBlock: Request to read: 1024 bytes
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_tape_block: Reading blk 117730
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_header: Reading header 117731 at offset 5779244417, type: DATA
Oct 18 19:34:38 vmapp03 vtltape[4513]: readBlock: Read 122 (122) bytes of compressed data, have 1024 bytes for result
Oct 18 19:34:38 vmapp03 vtltape[4513]: completeSCSICommand: OP s/n: (1098895), sz: 1024, sam_status: 0
Oct 18 19:34:38 vmapp03 vtltape[4513]: CDB (1098896) 08 00 00 04 00 00
Oct 18 19:34:38 vmapp03 vtltape[4513]: processCommand: READ_6 (1098896) : 1024 bytes **
Oct 18 19:34:38 vmapp03 vtltape[4513]: readBlock: Request to read: 1024 bytes
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_tape_block: Reading blk 117731
Oct 18 19:34:38 vmapp03 vtltape[4513]: read_header: Reading header 117732 at offset 5779255485, type: DATA
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
In reply to this post by ap2010
With compression disabled: Same loss of 13 Gig with block size of 1024 instead of 65536
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
Any chance of running 'dump_tape -f <barcode>' and supplying the output.

If the 'dump_tape' output reports lots of '1024' byte blocks where 64k blocks should be, can you please forward the verbose logs for the 'tape creation'..

Is the 'tape duplication' utility something you can send me, so I can reproduce the error(s) or is it a commercial tool ?

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

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
Ran the dump_tape -f  and captured the output. It shows the 1024 and 64k blocks in their proper positions. So it appears the MHVTL tape was created and contains the correct data and block sizes.

The "tape-dupilcation" utility is not a commercial tool but we are attempting to make a stripped down version available.
Meanwhile: here is what our local expert discovered after considering your response and after further investigation and testing:
================>
"It looks like we have tracked down what the issue is with the mhvtl package. The problem is when an sg (SCSI generic) read request is made to the mhvtl module with a block size less than the tape block size, mhvtl is not returning sense data with the ILI (Illegal Length Indicator) bit set. As for some background as to why this matters to us, the tapeutil program uses an adaptive block size heuristic to get the requested block size inline with the tape block size at any point in time. This is for performance reasons, since some physical tape drives become quite slow when the requested block size is larger than the written tape block size. Our tapeutil program depends on the tape driver returning sense/ILI when we guess too small in order to know when to start using a larger block size. In the case of NBU, each tape fragment (tape file) consists of some number of 1KB backupset records followed by the backupset stream records, which in this instance are 64KB in size. So the 1KB backupset records (3 in this case, since it's a multiplexed backup) force tapeutil to adapt to the 1KB length prior to seeing the 64KB blocks. Since the mhvtl module did not return the sense/ILI response, our heuristic assumed the tape block size really was 1KB so it saw no need to re-adapt."
<===============
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
Many thanks for the analysis.

It make perfect sense..

NetBackup (what I use) is concerned with short blocks. i.e. To detect 'NetBackup' media, attempts to read in a 64k block. It should receive only a 1k block. If it is different, it will reject the media as 'non-NetBackup'

I can't say I've ever looked (checked) the situation where the application requests a 1k block, and the tape drive has 64k available..

I'll investigate this potential area of the code and report back..

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

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
Is there a chance of testing this build against your 'tape copy' application to see if it behaves ?

It contains the following bug fixes:
- SPACE 0 block/filemark fix
- Suppress Illegal Length Indicator fix (to be tested)
- kernel module compile on 2.6.34
- Silence 'which setuidgid' test
- Only allow ERASE when located at BOT

mhvtl-2010-11-03-0.18.12Beta.tgz

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

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
Will do and get back to you.. Thanks.
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
Apologies for belated responses. Tested with this and subsequent releases including Nov-17th (18-12) and found fix to be effective.  Now when reading back these Netbackup tapes the correct  tape blocks/data are produced.

However... ever since this fix our application fails to detect the mhvtl medium changer. I've not sought help from this forum because Linux commands (outside our application)  such as lsscsi, mtx or even our own copy utilility recognize and use the medium changer/tapes as normal. Until I get some local help debugging this I'll likely go back to and earlier version of mhvtl.
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
There was a big code re-arrangement in the SMC code between 0.18-11 & -12 releases.

There should have been no functionality changes.

Any chance of
a) Testing the 0.18-13beta1 release which I uploaded  
http://mhvtl-linux-virtual-tape-library-community-forums.966029.n3.nabble.com/file/n2202515/mhvtl-2011-01-06-0.18.13beta1-git-0.18-13.tgz

If that fails,
Please make sure VERBOSE=3 in the /etc/mhvtl/mhvtl.conf, restart the vtl daemons and run your application so as the failure 'seen'.
I'm happy to look over the syslog generated to see what SCSI commands are being sent and therefore hopefully figure out what I'm doing wrong.

Obviously, any comments you can make with regards to timing and what your application should respond like will be useful.. So I can match expectations with log file entries.


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

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
Thank you sir:
Loaded version 18-13 and here are some fragments of what I thought to be relevant. Let me know what else i can supply. My appliance still fails with an error messages like this:

2011/01/06 16:08:25 [4337] tapeman/tapesched.c:11609: Failed to get inventory from MC [DID=2]: DID=2,INVALID Device is not supported or not properly initializedFailed to rescan inventory for MC [DID=2]

Comment: we acknowledge the "Device not supported" as something we've not handled properly in the past but was innocuous and did not affect real operations. The "not properly initialized" coincides with the new "bad" behavior. I believe......

Comment: Used L700 but later modified to use SPECTRA with same results.

[6:0:0:0]    mediumx STK      L700             550V  /dev/sch0  /dev/sg7
[6:0:1:0]    tape    IBM      ULT3580-TD5      550V  /dev/st0   /dev/sg3
[6:0:2:0]    tape    IBM      ULT3580-TD5      550V  /dev/st1   /dev/sg4
[6:0:3:0]    tape    IBM      ULT3580-TD4      550V  /dev/st2   /dev/sg5
[6:0:4:0]    tape    IBM      ULT3580-TD4      550V  /dev/st3   /dev/sg6

Comment: Fragment when started with VERBOSE=3

Jan  6 16:04:58 orinoco vtllibrary[3007]: main: vtllibrary: version 0.18.13beta1
Jan  6 16:04:58 orinoco vtllibrary[3007]: verbose: 3
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: VERSION: 5
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # VPD page format:
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # <page #> <Length> <x> <x+1>... <x+n>
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # NAA format is an 8 hex byte value seperated by ':'
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # Note: NAA is part of inquiry VPD 0x83
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: #
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # Each 'record' is separated by one (or more) blank lines.
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # Each 'record' starts at column 1
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # Serial num max len is 10.
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: # Compression: factor X enabled 0|1
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: #     Where X is zlib compression factor#0111 = Fastest compression
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: ##011#011#011#011#011#0119 = Best compression
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: #     enabled 0 == off, 1 == on
Jan  6 16:04:58 orinoco vtltape[2973]: CDB (267) 12 01 80 00 fe 00
Jan  6 16:04:58 orinoco vtltape[2973]: spc_inquiry: INQUIRY *** (267)
Jan  6 16:04:58 orinoco vtltape[2973]: spc_inquiry: Page code 0x80
Jan  6 16:04:58 orinoco vtltape[2973]: spc_inquiry: Found page 0x80
Jan  6 16:04:58 orinoco vtltape[2973]: completeSCSICommand: OP s/n: (267), sz: 14, sam_status: 0
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: Library: 10 CHANNEL: 00 TARGET: 00 LUN: 00
Jan  6 16:04:58 orinoco kernel: mhvtl: CDB (268) 6 bytes
Jan  6 16:04:58 orinoco kernel: 12 01 83 00 fe 00
Jan  6 16:04:58 orinoco vtllibrary[3007]: init_lu: Found Library 10, looking for 10
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  Vendor identification: STK
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  Product identification: L700
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  Product revision level: 550V
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  Unit serial number: XYZZY_A
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  NAA: 10:22:33:44:ab:00:00:00
Jan  6 16:04:58 orinoco vtllibrary[3007]: init_lu: Setting NAA: to 10:22:33:44:ab:00:00:00
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline: Drive: 11 CHANNEL: 00 TARGET: 01 LUN: 00
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  Library ID: 10 Slot: 01
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  Vendor identification: IBM
Jan  6 16:04:58 orinoco vtllibrary[3007]: readline:  Product identification: ULT3580-TD5
Jan  6 16:04:58 orinoco kernel: mhvtl: CDB (269) 6 bytes
Jan  6 16:04:58 orinoco kernel: 12 00 00 00 fe 00

*****  When application starts... this cycles repetitively.

Jan  6 16:09:46 orinoco vtltape[2973]: completeSCSICommand: OP s/n: (484), sz: 0, sam_status: 2
Jan  6 16:09:46 orinoco vtltape[2973]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco kernel: mhvtl: CDB (485) 6 bytes
Jan  6 16:09:51 orinoco kernel: 00 00 00 00 00 00
Jan  6 16:09:51 orinoco kernel: mhvtl: CDB (486) 6 bytes
Jan  6 16:09:51 orinoco kernel: 00 00 00 00 00 00
Jan  6 16:09:51 orinoco kernel: mhvtl: CDB (487) 6 bytes
Jan  6 16:09:51 orinoco kernel: 00 00 00 00 00 00
Jan  6 16:09:51 orinoco kernel: mhvtl: CDB (488) 6 bytes
Jan  6 16:09:51 orinoco kernel: 00 00 00 00 00 00
Jan  6 16:09:51 orinoco vtltape[2985]: CDB (485) 00 00 00 00 00 00
Jan  6 16:09:51 orinoco vtltape[2985]: processCommand: Test Unit Ready (485) : No
Jan  6 16:09:51 orinoco vtltape[2985]: mkSenseBuf: Sense buf: 0x617f80
Jan  6 16:09:51 orinoco vtltape[2985]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[2985]: completeSCSICommand: OP s/n: (485), sz: 0, sam_status: 2
Jan  6 16:09:51 orinoco vtltape[2985]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[3005]: CDB (486) 00 00 00 00 00 00
Jan  6 16:09:51 orinoco vtltape[3005]: processCommand: Test Unit Ready (486) : No
Jan  6 16:09:51 orinoco vtltape[3005]: mkSenseBuf: Sense buf: 0x617f80
Jan  6 16:09:51 orinoco vtltape[3005]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[3005]: completeSCSICommand: OP s/n: (486), sz: 0, sam_status: 2
Jan  6 16:09:51 orinoco vtltape[3005]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[2994]: CDB (487) 00 00 00 00 00 00
Jan  6 16:09:51 orinoco vtltape[2994]: processCommand: Test Unit Ready (487) : No
Jan  6 16:09:51 orinoco vtltape[2994]: mkSenseBuf: Sense buf: 0x617f80
Jan  6 16:09:51 orinoco vtltape[2994]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[2994]: completeSCSICommand: OP s/n: (487), sz: 0, sam_status: 2
Jan  6 16:09:51 orinoco vtltape[2994]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[2973]: CDB (488) 00 00 00 00 00 00
Jan  6 16:09:51 orinoco vtltape[2973]: processCommand: Test Unit Ready (488) : No
Jan  6 16:09:51 orinoco vtltape[2973]: mkSenseBuf: Sense buf: 0x617f80
Jan  6 16:09:51 orinoco vtltape[2973]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[2973]: completeSCSICommand: OP s/n: (488), sz: 0, sam_status: 2
Jan  6 16:09:51 orinoco vtltape[2973]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:56 orinoco kernel: mhvtl: CDB (489) 6 bytes
Jan  6 16:09:56 orinoco kernel: 00 00 00 00 00 00
Jan  6 16:09:56 orinoco kernel: mhvtl: CDB (490) 6 bytes
Jan  6 16:09:56 orinoco kernel: 00 00 00 00 00 00



Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
The snippet of syslog supplied looks "normal" and is expected operation.

i.e. This is repeated every so often (per vtltape process).
Jan  6 16:09:51 orinoco vtltape[2985]: CDB (485) 00 00 00 00 00 00
Jan  6 16:09:51 orinoco vtltape[2985]: processCommand: Test Unit Ready (485) : No
Jan  6 16:09:51 orinoco vtltape[2985]: mkSenseBuf: Sense buf: 0x617f80
Jan  6 16:09:51 orinoco vtltape[2985]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  6 16:09:51 orinoco vtltape[2985]: completeSCSICommand: OP s/n: (485), sz: 0, sam_status: 2
Jan  6 16:09:51 orinoco vtltape[2985]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]

A quick grep for Sense Key 3a 00
markh@mharvey02:~/src/mhvtl/usr> grep -i 3a00 *.h
scsi.h:#define E_MEDIUM_NOT_PRESENT             0x3a00

i.e. the application is polling the tape drives testing if they are ready. The tape drives are returning 'No Media'..
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
p.s.
There is no need to enable the debugging of the kernel module..

VTL_DEBUG=0

99.8% of the time, all this does is add extra noise to the syslog while providing no value to troubleshooting.

Turn off verbose logging on a running env: do "echo 0 > /sys/bus/pseudo/drivers/mhvtl/opts"
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
I turned off  kernel debugging :VTL_DEBUG=0. this is a test env so I usually stop and start mhvtl

I hope the following is sufficiently (and narrowly) targeted to Library detection by our application.

I captured mhvtl log (using tail) separately under three conditions:
(a) when starting mhvtl (service mhvtl start)
(b) upon starting our application... in parallel I also captured the corresponding fragment of our application tapemanager log
(c) With both mhvtl and our application running I did a forced re-discovery of the Library/Tapes (tmcli resetdevconfig) and captured the mhvtl log

I am only going to attach the logs for (b) above as I think this may be the most helpful. I noticed following msgs in the mhvtl log:
"Jan  7 11:30:35 orinoco vtllibrary[2465]: fill_element_page: Invalid type: 0 (valid values 1 - 4)"
AND:  from our application this error msg appears to coincide timewise:
"2011/01/07 11:30:35 [2667] util/sgcustom.c:299: /opt/ie/share/scsi-custom.json: errno 2: No such file or directory
/dev/sg7: io error when executing Read element status [b8 10 00 00 ff ff 00 00 00 08 00 00]
"
I can attach all the logs and more if you really want them. I also have a mhvtl-18-9 version that works and I can capture similar logs if needed. Here are the details with above info in context:

*****************MHVTL log On Application start:**************************
[root@orinoco tmp]# cat 3appstart-18.13beta1
Jan  7 11:29:04 orinoco vtllibrary[2465]: CDB (122) 12 01 80 00 fe 00
Jan  7 11:29:04 orinoco vtllibrary[2465]: spc_inquiry: INQUIRY *** (122)
Jan  7 11:29:04 orinoco vtllibrary[2465]: spc_inquiry: Page code 0x80
Jan  7 11:29:04 orinoco vtllibrary[2465]: spc_inquiry: Found page 0x80
Jan  7 11:29:04 orinoco vtllibrary[2465]: completeSCSICommand: OP s/n: (122), sz: 14, sam_status: 0
Jan  7 11:29:04 orinoco vtllibrary[2465]: CDB (123) 12 01 83 00 fe 00
Jan  7 11:29:04 orinoco vtllibrary[2465]: spc_inquiry: INQUIRY *** (123)
Jan  7 11:29:04 orinoco vtllibrary[2465]: spc_inquiry: Page code 0x83
Jan  7 11:29:04 orinoco vtllibrary[2465]: spc_inquiry: Found page 0x83
Jan  7 11:29:04 orinoco vtllibrary[2465]: completeSCSICommand: OP s/n: (123), sz: 54, sam_status: 0
Jan  7 11:30:35 orinoco licdaemon: notice: licdaemon is starting [pid 2537]
Jan  7 11:30:35 orinoco licdaemon: notice: Listening for control connections on port 7785
Jan  7 11:30:35 orinoco vtllibrary[2465]: CDB (124) 00 00 00 00 00 00
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_tur: ** Test Unit Ready : Returning =>  (124) Online **
Jan  7 11:30:35 orinoco vtllibrary[2465]: completeSCSICommand: OP s/n: (124), sz: 0, sam_status: 0
Jan  7 11:30:35 orinoco vtllibrary[2465]: CDB (125) 12 01 80 00 80 00
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_inquiry: INQUIRY *** (125)
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_inquiry: Page code 0x80
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_inquiry: Found page 0x80
Jan  7 11:30:35 orinoco vtllibrary[2465]: completeSCSICommand: OP s/n: (125), sz: 14, sam_status: 0
Jan  7 11:30:35 orinoco vtllibrary[2465]: CDB (126) 1a 08 1d 00 18 00
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_mode_sense: MODE SENSE (126) ***
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_mode_sense:  Mode Sense 6 byte version
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_mode_sense:  Page Control  : Current configuration(0x0)
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_mode_sense:  Page Code     : 0x1d
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_mode_sense:  Disable Block Descriptor => Yes
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_mode_sense:  Allocation len: 24
Jan  7 11:30:35 orinoco vtllibrary[2465]: spc_mode_sense: pcode: 0x1d
Jan  7 11:30:35 orinoco vtllibrary[2465]: find_pcode: Entered: pcode 0x1d
Jan  7 11:30:35 orinoco vtllibrary[2465]: find_pcode: Looking for 0x1d: found pcode 0x1d
Jan  7 11:30:35 orinoco vtllibrary[2465]: completeSCSICommand: OP s/n: (126), sz: 24, sam_status: 0
Jan  7 11:30:35 orinoco vtllibrary[2465]: CDB (127) b8 10 00 00 ff ff 01 00 00 08 00 00
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status: READ ELEMENT STATUS (127) **
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:  Element type(0) => All Elements
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Starting Element Address: 0
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Number of Elements      : 65535
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Allocation length       : 8
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Device ID: Yes, voltag: Yes
Jan  7 11:30:35 orinoco vtllibrary[2465]: fill_element_page: Invalid type: 0 (valid values 1 - 4)
Jan  7 11:30:35 orinoco vtllibrary[2465]: mkSenseBuf: Sense buf: 0x608640
Jan  7 11:30:35 orinoco vtllibrary[2465]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [05 24 00]
Jan  7 11:30:35 orinoco vtllibrary[2465]: completeSCSICommand: OP s/n: (127), sz: 0, sam_status: 2
Jan  7 11:30:35 orinoco vtllibrary[2465]: completeSCSICommand: [Key/ASC/ASCQ] [05 24 00]
Jan  7 11:30:35 orinoco vtllibrary[2465]: CDB (128) b8 10 00 00 ff ff 00 00 00 08 00 00
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status: READ ELEMENT STATUS (128) **
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:  Element type(0) => All Elements
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Starting Element Address: 0
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Number of Elements      : 65535
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Allocation length       : 8
Jan  7 11:30:35 orinoco vtllibrary[2465]: smc_read_element_status:   Device ID: No, voltag: Yes
Jan  7 11:30:35 orinoco vtllibrary[2465]: fill_element_page: Invalid type: 0 (valid values 1 - 4)
Jan  7 11:30:35 orinoco vtllibrary[2465]: mkSenseBuf: Sense buf: 0x608640
Jan  7 11:30:35 orinoco vtllibrary[2465]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [05 24 00]
Jan  7 11:30:35 orinoco vtllibrary[2465]: completeSCSICommand: OP s/n: (128), sz: 0, sam_status: 2
Jan  7 11:30:35 orinoco vtllibrary[2465]: completeSCSICommand: [Key/ASC/ASCQ] [05 24 00]
Jan  7 11:30:36 orinoco vtltape[2425]: CDB (129) 00 00 00 00 00 00
Jan  7 11:30:36 orinoco vtltape[2425]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:36 orinoco vtltape[2425]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:36 orinoco vtltape[2425]: completeSCSICommand: OP s/n: (129), sz: 0, sam_status: 2
Jan  7 11:30:36 orinoco vtltape[2425]: completeSCSICommand: [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:36 orinoco vtltape[2425]: CDB (130) 00 00 00 00 00 00
Jan  7 11:30:36 orinoco vtltape[2425]: processCommand: Test Unit Ready (130) : No
Jan  7 11:30:36 orinoco vtltape[2425]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:36 orinoco vtltape[2425]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:36 orinoco vtltape[2425]: completeSCSICommand: OP s/n: (130), sz: 0, sam_status: 2
Jan  7 11:30:36 orinoco vtltape[2425]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:36 orinoco vtltape[2425]: CDB (131) 12 01 80 00 80 00
Jan  7 11:30:36 orinoco vtltape[2425]: spc_inquiry: INQUIRY *** (131)
Jan  7 11:30:36 orinoco vtltape[2425]: spc_inquiry: Page code 0x80
Jan  7 11:30:36 orinoco vtltape[2425]: spc_inquiry: Found page 0x80
Jan  7 11:30:36 orinoco vtltape[2425]: completeSCSICommand: OP s/n: (131), sz: 14, sam_status: 0
Jan  7 11:30:36 orinoco vtltape[2440]: CDB (132) 00 00 00 00 00 00
Jan  7 11:30:36 orinoco vtltape[2440]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:36 orinoco vtltape[2440]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:36 orinoco vtltape[2440]: completeSCSICommand: OP s/n: (132), sz: 0, sam_status: 2
Jan  7 11:30:36 orinoco vtltape[2440]: completeSCSICommand: [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:36 orinoco vtltape[2440]: CDB (133) 00 00 00 00 00 00
Jan  7 11:30:36 orinoco vtltape[2440]: processCommand: Test Unit Ready (133) : No
Jan  7 11:30:36 orinoco vtltape[2440]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:36 orinoco vtltape[2440]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:36 orinoco vtltape[2440]: completeSCSICommand: OP s/n: (133), sz: 0, sam_status: 2
Jan  7 11:30:36 orinoco vtltape[2440]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:36 orinoco vtltape[2440]: CDB (134) 12 01 80 00 80 00
Jan  7 11:30:36 orinoco vtltape[2440]: spc_inquiry: INQUIRY *** (134)
Jan  7 11:30:36 orinoco vtltape[2440]: spc_inquiry: Page code 0x80
Jan  7 11:30:36 orinoco vtltape[2440]: spc_inquiry: Found page 0x80
Jan  7 11:30:36 orinoco vtltape[2440]: completeSCSICommand: OP s/n: (134), sz: 14, sam_status: 0
Jan  7 11:30:36 orinoco vtltape[2444]: CDB (135) 00 00 00 00 00 00
Jan  7 11:30:36 orinoco vtltape[2444]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:36 orinoco vtltape[2444]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:36 orinoco vtltape[2444]: completeSCSICommand: OP s/n: (135), sz: 0, sam_status: 2
Jan  7 11:30:36 orinoco vtltape[2444]: completeSCSICommand: [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:36 orinoco vtltape[2444]: CDB (136) 00 00 00 00 00 00
Jan  7 11:30:36 orinoco vtltape[2444]: processCommand: Test Unit Ready (136) : No
Jan  7 11:30:36 orinoco vtltape[2444]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:36 orinoco vtltape[2444]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:36 orinoco vtltape[2444]: completeSCSICommand: OP s/n: (136), sz: 0, sam_status: 2
Jan  7 11:30:36 orinoco vtltape[2444]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:36 orinoco vtltape[2444]: CDB (137) 12 01 80 00 80 00
Jan  7 11:30:36 orinoco vtltape[2444]: spc_inquiry: INQUIRY *** (137)
Jan  7 11:30:36 orinoco vtltape[2444]: spc_inquiry: Page code 0x80
Jan  7 11:30:36 orinoco vtltape[2444]: spc_inquiry: Found page 0x80
Jan  7 11:30:36 orinoco vtltape[2444]: completeSCSICommand: OP s/n: (137), sz: 14, sam_status: 0
Jan  7 11:30:37 orinoco vtltape[2451]: CDB (138) 00 00 00 00 00 00
Jan  7 11:30:37 orinoco vtltape[2451]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:37 orinoco vtltape[2451]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:37 orinoco vtltape[2451]: completeSCSICommand: OP s/n: (138), sz: 0, sam_status: 2
Jan  7 11:30:37 orinoco vtltape[2451]: completeSCSICommand: [Key/ASC/ASCQ] [06 29 00]
Jan  7 11:30:37 orinoco vtltape[2451]: CDB (139) 00 00 00 00 00 00
Jan  7 11:30:37 orinoco vtltape[2451]: processCommand: Test Unit Ready (139) : No
Jan  7 11:30:37 orinoco vtltape[2451]: mkSenseBuf: Sense buf: 0x617f80
Jan  7 11:30:37 orinoco vtltape[2451]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:37 orinoco vtltape[2451]: completeSCSICommand: OP s/n: (139), sz: 0, sam_status: 2
Jan  7 11:30:37 orinoco vtltape[2451]: completeSCSICommand: [Key/ASC/ASCQ] [02 3a 00]
Jan  7 11:30:37 orinoco vtltape[2451]: CDB (140) 12 01 80 00 80 00
Jan  7 11:30:37 orinoco vtltape[2451]: spc_inquiry: INQUIRY *** (140)
Jan  7 11:30:37 orinoco vtltape[2451]: spc_inquiry: Page code 0x80
Jan  7 11:30:37 orinoco vtltape[2451]: spc_inquiry: Found page 0x80
Jan  7 11:30:37 orinoco vtltape[2451]: completeSCSICommand: OP s/n: (140), sz: 14, sam_status: 0

*******************Application log on startup:************************
2011/01/07 11:25:48 [2047] tapeman/tapesched.c:10478: Starting MC Monitor Thread for [DID=2]
2011/01/07 11:25:48 [2048] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=3]
2011/01/07 11:25:48 [2049] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=4]
2011/01/07 11:25:48 [2050] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=5]
2011/01/07 11:25:48 [2051] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=6]
2011/01/07 11:25:48 [1835] tapeman/tapeman.c:190: tapeman (revision 3.3.0-4.2 [svn:r43827], built Jan  5 2011 @ 11:16:10) [pid 1835] is ready
2011/01/07 11:25:48 [1835] util/ctl.c:826: Listening for control connections on port 7778
Option: "tapeman"=0x0
2011/01/07 11:30:35 [2667] util/tmp.c:1809: tapeDB configuration cached: server=localhost, dbname=tapedb
2011/01/07 11:30:35 [2667] tapeman/tapesched.c:545: Starting tapedb integrity check...
2011/01/07 11:30:35 [2667] tapeman/tapesched.c:15062: tapedb integrity check for tapedb succeeded.
2011/01/07 11:30:35 [2667] tapeman/tapesched.c:554: tapedb integrity check succeeded.
2011/01/07 11:30:35 [2667] util/sgcustom.c:299: /opt/ie/share/scsi-custom.json: errno 2: No such file or directory
/dev/sg7: io error when executing Read element status [b8 10 00 00 ff ff 00 00 00 08 00 00]
/dev/sg7: status 02  Check Condition
/dev/sg7:  f0 00 05 00.00.00.00 58 00 00 00 00 24+00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
/dev/sg7: sense:  Fixed format, current;  Sense key: Illegal Request
/dev/sg7:  Additional sense: Invalid field in cdb
/dev/sg7:   Info fld=0x0 [0]
/dev/sg7: msg_status = 0x00 host_ = 0x0000 drv_ = 0x0008
/dev/sg7: DID_OK,DRIVER_SENSE,SUGGEST_OK
/dev/sg7: duration = 5 ms
/dev/sg7: info = 0x01
/dev/sg7: dxfer_len = 8 (0x8)
/dev/sg7: resid     = 0 (0x0) -> 8 (0x8)
2011/01/07 11:30:35 [2667] tapeman/tapelib.c:473: DID=2,INVALID Failed to read element status
2 3 DID=2,INVALID XYZZY_A    -> 0,0,0,0,
3 0 /dev/nst0 [6:0:1:0],IBM,ULT3580-TD5,550V XYZZY_A1   -> 0
4 0 /dev/nst1 [6:0:2:0],IBM,ULT3580-TD5,550V XYZZY_A2   -> 0
5 0 /dev/nst2 [6:0:3:0],IBM,ULT3580-TD4,550V XYZZY_A3   -> 0
6 0 /dev/nst3 [6:0:4:0],IBM,ULT3580-TD4,550V XYZZY_A4   -> 0
2011/01/07 11:30:37 [2846] tapeman/tapesched.c:10478: Starting MC Monitor Thread for [DID=2]
2011/01/07 11:30:37 [2848] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=4]
2011/01/07 11:30:37 [2667] tapeman/tapeman.c:190: tapeman (revision 3.3.0-4.2 [svn:r43827], built Jan  5 2011 @ 11:16:10) [pid 2667] is ready
2011/01/07 11:30:37 [2667] util/ctl.c:826: Listening for control connections on port 7778
2011/01/07 11:30:37 [2847] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=3]
2011/01/07 11:30:37 [2850] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=6]
2011/01/07 11:30:37 [2849] tapeman/tapesched.c:9886: Starting Drive Monitor Thread for [DID=5]
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
Many thanks.

Exactly what I was after..

There is enough information here for me to reproduce this error and provide a fix.

I really do need to rewrite the READ ELEMENT STATUS routine. One day...

Thanks for the bug report.
Cheers
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
Can you please check out this build for me please ?

It appears to do the right thing.

[root@rh5u4 mhvtl-0.18]# sg_raw -r 8 /dev/sg7 b8 10 00 00 ff ff 00 00 00 08 00 00
SCSI Status: Good

Sense Information:
sense buffer empty

Received 8 bytes of data:
 00     00 01 00 34 00 00 0a b0                             ...4....

mhvtl-2011-01-08-0.18.13beta2-git-0.18-13.tgz

Many thanks.
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

dlsk
Library is now recognized by application but the following issue is now evident ( with version 0.18.13beta2):
Note:I've verified the ability to successfully copy same image on working MHVTL version 0.18.9

On  using our local "copy" program I am getting an "i/o error" on write as follows:

Our application output:

/dev/nst0 [20110108 13:36:54.405]: opened as type 1
/dev/nst0 [20110108 13:36:54.405]: set verbose to 3
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.405]: <<<<<< <<<<<< rewind
/dev/nst0 [20110108 13:36:54.405]: <<<<<< <<<<<< rewind
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: rec 80 (50)
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: 4 blocks, 320 bytes @ 4
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: throughput = 2.8 MB/s
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: eof 1
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: rec 262144 (40000) @ 5
/dev/nst0 [20110108 13:37:23.737]: io error when executing Write(6) [0a 00 04 00 00 00] @ 3090
/dev/nst0 [20110108 13:37:23.737]: status 02  Check Condition
/dev/nst0 [20110108 13:37:23.737]:  f0 00 40 00.00.00.00 58 00 00 00 00 00+00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
/dev/nst0 [20110108 13:37:23.737]: sense:  Fixed format, current;  Sense key: No Sense
/dev/nst0 [20110108 13:37:23.737]:  Additional sense: No additional sense information
/dev/nst0 [20110108 13:37:23.737]:   Info fld=0x0 [0]  EOM
/dev/nst0 [20110108 13:37:23.737]: msg_status = 0x00 host_ = 0x0000 drv_ = 0x0008
/dev/nst0 [20110108 13:37:23.737]: DID_OK,DRIVER_SENSE,SUGGEST_OK
/dev/nst0 [20110108 13:37:23.737]: duration = 12 ms
/dev/nst0 [20110108 13:37:23.737]: info = 0x01
/dev/nst0 [20110108 13:37:23.737]: dxfer_len = 262144 (0x40000)
/dev/nst0 [20110108 13:37:23.737]: resid     = 0 (0x0) -> 262144 (0x40000)
808714560 bytes copied in 29.33 seconds
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:37:23.737]: total 3,211 blocks, 840,696,128 bytes, 0 skips @ 3212
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:37:23.737]: close
/dev/nst0 [20110108 13:37:23.737]: close

MHVTL log (VERBOSE=3)

Jan  8 13:37:23 orinoco vtltape[3014]: write_tape_block: Successfully wrote block: 3089
Jan  8 13:37:23 orinoco vtltape[3014]: completeSCSICommand: OP s/n: (6457), sz: 262144, sam_status: 0
Jan  8 13:37:23 orinoco vtltape[3014]: CDB (6458) 0a 00 04 00 00 00
Jan  8 13:37:23 orinoco vtltape[3014]: processCommand: WRITE_6: 262144 bytes (6458) **
Jan  8 13:37:23 orinoco vtltape[3014]: retrieve_CDB_data: retrieving 262144 bytes from kernel
Jan  8 13:37:23 orinoco vtltape[3014]: checkRestrictions: returning Writable
Jan  8 13:37:23 orinoco kernel: mhvtl: CDB (6458) 6 bytes
Jan  8 13:37:23 orinoco kernel: 0a 00 04 00 00 00
Jan  8 13:37:23 orinoco vtltape[3014]: writeBlock: Compression: Orig 262144, after comp: 262230, Compression factor: 1
Jan  8 13:37:23 orinoco vtltape[3014]: write_tape_block: Successfully wrote block: 3090
Jan  8 13:37:23 orinoco vtltape[3014]: writeBlock: End of Medium - Setting EOM flag
Jan  8 13:37:23 orinoco vtltape[3014]: mkSenseBuf: Sense buf: 0x617f80
Jan  8 13:37:23 orinoco vtltape[3014]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [40 00 00]
Jan  8 13:37:23 orinoco vtltape[3014]: completeSCSICommand: OP s/n: (6458), sz: 262144, sam_status: 2
Jan  8 13:37:23 orinoco vtltape[3014]: completeSCSICommand: [Key/ASC/ASCQ] [40 00 00]
[root@orinoco ~]#

Reply | Threaded
Open this post in threaded view
|

Re: apparent blocksize shift error when tape is copied to MHVTL then read back from MHVTL tape

Mark Harvey
Administrator
This looks like the virtual media hit END-OF-TAPE. Can you send thru a "dump_tape -v -f <virtual tape>"

Sent from my iPhone

On 09/01/2011, at 5:51, "dlsk [via MHVTL - Linux Virtual Tape Library - Community Forums]"<[hidden email]> wrote:

Library is now recognized by application but the following issue is now evident ( with version 0.18.13beta2):
Note:I've verified the ability to successfully copy same image on working MHVTL version 0.18.9

On  using our local "copy" program I am getting an "i/o error" on write as follows:

Our application output:

/dev/nst0 [20110108 13:36:54.405]: opened as type 1
/dev/nst0 [20110108 13:36:54.405]: set verbose to 3
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.405]: <<<<<< <<<<<< rewind
/dev/nst0 [20110108 13:36:54.405]: <<<<<< <<<<<< rewind
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: rec 80 (50)
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: 4 blocks, 320 bytes @ 4
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: throughput = 2.8 MB/s
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: eof 1
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:36:54.406]: rec 262144 (40000) @ 5
/dev/nst0 [20110108 13:37:23.737]: io error when executing Write(6) [0a 00 04 00 00 00] @ 3090
/dev/nst0 [20110108 13:37:23.737]: status 02  Check Condition
/dev/nst0 [20110108 13:37:23.737]:  f0 00 40 00.00.00.00 58 00 00 00 00 00+00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
/dev/nst0 [20110108 13:37:23.737]: sense:  Fixed format, current;  Sense key: No Sense
/dev/nst0 [20110108 13:37:23.737]:  Additional sense: No additional sense information
/dev/nst0 [20110108 13:37:23.737]:   Info fld=0x0 [0]  EOM
/dev/nst0 [20110108 13:37:23.737]: msg_status = 0x00 host_ = 0x0000 drv_ = 0x0008
/dev/nst0 [20110108 13:37:23.737]: DID_OK,DRIVER_SENSE,SUGGEST_OK
/dev/nst0 [20110108 13:37:23.737]: duration = 12 ms
/dev/nst0 [20110108 13:37:23.737]: info = 0x01
/dev/nst0 [20110108 13:37:23.737]: dxfer_len = 262144 (0x40000)
/dev/nst0 [20110108 13:37:23.737]: resid     = 0 (0x0) -> 262144 (0x40000)
808714560 bytes copied in 29.33 seconds
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:37:23.737]: total 3,211 blocks, 840,696,128 bytes, 0 skips @ 3212
/opt/mhvtl/_sepatontapes_/FS00008/tape [20110108 13:37:23.737]: close
/dev/nst0 [20110108 13:37:23.737]: close

MHVTL log (VERBOSE=3)

Jan  8 13:37:23 orinoco vtltape[3014]: write_tape_block: Successfully wrote block: 3089
Jan  8 13:37:23 orinoco vtltape[3014]: completeSCSICommand: OP s/n: (6457), sz: 262144, sam_status: 0
Jan  8 13:37:23 orinoco vtltape[3014]: CDB (6458) 0a 00 04 00 00 00
Jan  8 13:37:23 orinoco vtltape[3014]: processCommand: WRITE_6: 262144 bytes (6458) **
Jan  8 13:37:23 orinoco vtltape[3014]: retrieve_CDB_data: retrieving 262144 bytes from kernel
Jan  8 13:37:23 orinoco vtltape[3014]: checkRestrictions: returning Writable
Jan  8 13:37:23 orinoco kernel: mhvtl: CDB (6458) 6 bytes
Jan  8 13:37:23 orinoco kernel: 0a 00 04 00 00 00
Jan  8 13:37:23 orinoco vtltape[3014]: writeBlock: Compression: Orig 262144, after comp: 262230, Compression factor: 1
Jan  8 13:37:23 orinoco vtltape[3014]: write_tape_block: Successfully wrote block: 3090
Jan  8 13:37:23 orinoco vtltape[3014]: writeBlock: End of Medium - Setting EOM flag
Jan  8 13:37:23 orinoco vtltape[3014]: mkSenseBuf: Sense buf: 0x617f80
Jan  8 13:37:23 orinoco vtltape[3014]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [40 00 00]
Jan  8 13:37:23 orinoco vtltape[3014]: completeSCSICommand: OP s/n: (6458), sz: 262144, sam_status: 2
Jan  8 13:37:23 orinoco vtltape[3014]: completeSCSICommand: [Key/ASC/ASCQ] [40 00 00]
[root@orinoco ~]#




Regards from Australia
Mark Harvey
12