library door open?

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

library door open?

sbcedservice
Hi Mark,

With one of the recent release (now I'm using 1.4.7-268c2bc) I'm having some trouble
when the backup sw -ArcServe- (or manually) tries to format/erase a tape containing a big backup.

this is my mhvtl settings:

MHVTL_CONFIG_PATH=/etc/mhvtl
CAPACITY=1228800
VERBOSE=3
VTL_DEBUG=0

device.conf:

VERSION: 5


Library: 50 CHANNEL: 4 TARGET: 03 LUN: 00
 Vendor identification: IBM
 Product identification: ULT3582-TL
 Product revision level: 205B
 Unit serial number: 10000050
 NAA: 50:11:22:33:ab:4:03:00

Drive: 51 CHANNEL: 4 TARGET: 03 LUN: 01
 Library ID: 50 Slot: 01
 Vendor identification: IBM
 Product identification: ULT3580-TD5
 Product revision level: A3K6
 Unit serial number: 10000051
 NAA: 50:11:22:33:ab:4:03:01
 Compression: factor 1 enabled 0
 Compression type: lzo



Library: 70 CHANNEL: 5 TARGET: 05 LUN: 00
 Vendor identification: IBM
 Product identification: ULT3582-TL
 Product revision level: 205B
 Unit serial number: 10000070
 NAA: 70:11:22:33:ab:5:05:00
 Home directory: /opt/mhvtl
 Backoff: 400

Drive: 71 CHANNEL: 5 TARGET: 05 LUN: 01
 Library ID: 70 Slot: 01
 Vendor identification: IBM
 Product identification: ULT3580-TD5
 Product revision level: A3K6
 Unit serial number: 10000071
 NAA: 70:11:22:33:ab:5:05:01
 Compression: factor 1 enabled 0
 Compression type: lzo
 Backoff: 400

Drive: 72 CHANNEL: 5 TARGET: 05 LUN: 2
 Library ID: 70 Slot: 2
 Vendor identification: IBM
 Product identification: ULT3580-TD5
 Product revision level: A3K6
 Unit serial number: 10000072
 NAA: 70:11:22:33:ab:5:05:2
 Compression: factor 1 enabled 0
 Compression type: lzo
 Backoff: 400


On 1 tape (UBM002L5 - SUNDAY) I have a backup of more than 500GB:

sbservice@sbvtl2:/opt/mhvtl/UBM002L5$ ls -la
total 552368344
drwxrwx---  2 vtl vtl         4096 2012-09-23 00:25 .
drwxr-xr-x 41 vtl vtl         4096 2013-05-13 12:04 ..
-rw-rw----  1 vtl vtl 561240371200 2013-05-12 09:53 data
-rw-rw----  1 vtl vtl   4384692736 2013-05-12 09:53 indx
-rw-rw----  1 vtl vtl         1552 2013-05-12 09:53 meta

This tape now, according to rotating rules, is in scratch status, but we cannot reuse because the format/erase action fails with this error:
E6956 The operation has failed because the library door is open:
1. Clear any obstructions from the library door.
2. Close the library door.
3. If the problem persists, call the library supplier helpline.

The same operation on different (smaller) tapes on the same unit works without problems.

Here is th ArcServe tape log on manual erase:

[05/22 09:25:58 0f28  3 DM               2] RPCGetServerContext: Context is local[SBBK00]
[05/22 09:25:58 0f28  3 UI               1] RPCSetServerContext(): Context is already set to Server [SBBK00] hJob[041D9210]
[05/22 09:25:58 0f28  3 DM               2]      LDN:22 ...in ChangerEraseSlotRange
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 Erase range of slots.
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 Erasing Slot[1]
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:58 0f28  3 DM               2]      LDN:22 ...in GetChangerSpanningDrives
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 There are [1] free drives to use.
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 There is at least one spanning drive, but not needed.
[05/22 09:25:58 0f28  3 DM               2]      LDN:22 ...in ChgGetAndLockAllPossibleChangerDrives
[05/22 09:25:58 0f28  3 DM               2]      LDN:22 ...in ChgGetAndLockBestChangerDrives: Searching for tapes in drives.
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 Could not lock a Best Drive.
[05/22 09:25:58 0f28  3 DM               2]      LDN:22 ...in ChgGetAndLockAllEmptyChangerDrives: Searching for any empty Library drive
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 offset[0] Drive[21] is enabled but not empty and is associated with group: [FS]
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 All Drives are disabled by user
[05/22 09:25:58 0f28  3 DM               2]      LDN:22 ...in ChgGetAndLockAllAnyChangerDrives
[05/22 09:25:58 0f28  3 DM               2] Attempting to Lock device [21] timeout=[0]
[05/22 09:25:58 0f28  3 DM               2] Successfully Locked device [21]
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 Locked Drive[21] - Total number of free drives now [0]
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 Found any Library drive offset[0] LDN:21 TInDrive group [FS]
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 Found and Locked[1] drives...
[05/22 09:25:58 0f28  2 DM               2]      LDN:22 ChgGetAndLockAllPossibleChangerDrives: Locked all Drives Requested
[05/22 09:25:58 0f28  3 DM               2] ...in ChangerTestUnitReady
[05/22 09:25:58 0f28  2 DM               2] =>ABSL:1042 [TEST UNIT READY ] 00 40 00 00 00 00 00 00 00 80 tt[5]
[05/22 09:25:59 13b4  3 DM               2] RPCSetServerContext(): Context is already set to Server [SBBK00] hJob[041D9770]
[05/22 09:25:59 13b4  3 DM               2] GetXCB 9255: ulTime[773272656]
[05/22 09:25:59 13b4  3 DM               2] GetXCB 9255: ulTime[773272671]
[05/22 09:25:59 13b4  3 DM               2] GetXCB 9255: ulTime[773272687]
[05/22 09:25:59 13b4  3 DM               2] GetXCB 9255: ulTime[773272703]
[05/22 09:25:59 13b4  3 DM               2] GetXCB 9255: ulTime[773272718]
[05/22 09:25:59 13b4  3 DM               2] GetXCB 9255: ulTime[773272734]
[05/22 09:25:59 13b4  3 DM               2] DEVICE_QUERY_EXTENDED_CAPS ulCapFlags0[458753], ulCapFlags1[128]
[05/22 09:25:59 13b4  3 DM               2] DEVICE_QUERY_EXTENDED_CAPS SERVER NAME[SBBK00]
[05/22 09:25:59 0f28  3 DM               2]      LDN:22 ...in CheckAndEraseTapeInDrive
[05/22 09:25:59 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:59 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 ...in ChgCheckSlotStatus
[05/22 09:25:59 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 ChgReadElementStatusStorage: Starting Element[401] # of Elements[1]
[05/22 09:25:59 0f28  2 DM               2] =>ABSL:1042 [READ ELEMENT STAT] b8 12 04 01 00 01 00 00 00 6e tt[20]
[05/22 09:25:59 0f28  2 DM               2] ---------------Read Element Status HEX DUMP----------------
[05/22 09:25:59 0f28  2 DM               2] Hexdump Starts --------------------
[05/22 09:25:59 0f28  2 DM               2] 04 01 00 01 00 00 00 3c 02 80 00 34 00 00 00 34   .......<...4...4
[05/22 09:25:59 0f28  2 DM               2] 04 01 09 00 00 00 00 00 00 01 00 00 55 42 4d 30   ............UBM0
[05/22 09:25:59 0f28  2 DM               2] 30 32 4c 35 20 20 20 20 20 20 20 20 20 20 20 20   02L5            
[05/22 09:25:59 0f28  2 DM               2] 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20                  
[05/22 09:25:59 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:25:59 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:25:59 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 20 20   ..............  
[05/22 09:25:59 0f28  2 DM               2] 20 20 20 20 00 00 00 00 04 02 09 00 00 00 00 00       ............
[05/22 09:25:59 0f28  2 DM               2]
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 ChgReadElementStatusStorage: Reporting [1] Elements...
[05/22 09:25:59 0f28  3 DM               2] ChangerFreeMemory()
[05/22 09:25:59 0f28  3 DM               2] ChangerFreeMemory()
[05/22 09:25:59 0f28  3 DM               2] ChangerFreeMemory()
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 ...in ChgCheckSlotStatus
[05/22 09:25:59 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 ChgReadElementStatusStorage: Starting Element[401] # of Elements[1]
[05/22 09:25:59 0f28  2 DM               2] =>ABSL:1042 [READ ELEMENT STAT] b8 12 04 01 00 01 00 00 00 6e tt[20]
[05/22 09:25:59 0f28  2 DM               2] ---------------Read Element Status HEX DUMP----------------
[05/22 09:25:59 0f28  2 DM               2] Hexdump Starts --------------------
[05/22 09:25:59 0f28  2 DM               2] 04 01 00 01 00 00 00 3c 02 80 00 34 00 00 00 34   .......<...4...4
[05/22 09:25:59 0f28  2 DM               2] 04 01 09 00 00 00 00 00 00 01 00 00 55 42 4d 30   ............UBM0
[05/22 09:25:59 0f28  2 DM               2] 30 32 4c 35 20 20 20 20 20 20 20 20 20 20 20 20   02L5            
[05/22 09:25:59 0f28  2 DM               2] 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20                  
[05/22 09:25:59 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:25:59 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:25:59 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 20 20   ..............  
[05/22 09:25:59 0f28  2 DM               2] 20 20 20 20 00 00 00 00 04 02 09 00 00 00 00 00       ............
[05/22 09:25:59 0f28  2 DM               2]
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 ChgReadElementStatusStorage: Reporting [1] Elements...
[05/22 09:25:59 0f28  3 DM               2] ChangerFreeMemory()
[05/22 09:25:59 0f28  3 DM               2] ChgGetSlotFlags(): Slot[01], SlotFlag[0x18000823], ChgLDN[0]
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 Tape in Slot[1] will use Drive[21]
[05/22 09:25:59 0f28  2 DM               2]      LDN:22 ChangerEraseOneThread created ThreadID[E48]
[05/22 09:25:59 0f28  2 DM               2] >>WaitForAllThreads<<
[05/22 09:25:59 0e48  3                   ]      LDN:22 ...in ChangerEraseOneThread for LDN[21] Slot[1]
[05/22 09:25:59 0e48  2                   ]      LDN:21 ...in ChgInsertTapeIntoTapeDrive: Moving from Slot[1] to Drive[21]
[05/22 09:25:59 0e48  3                   ]      LDN:22 ChgMoveMedium: From address:[401] to address:[1] Flip:[0] MovingOut?[1].
[05/22 09:25:59 0e48  2                   ]      LDN:22 Moving Tape from Slot[1] to Library Drive[21]
[05/22 09:25:59 0e48  2                   ]      LDN:22 There is a tape from Slot address:[407] already in Drive address:[1]
[05/22 09:25:59 0e48  2                   ] =>ABSL:1041 [UNLOAD TAPE     ] 1b 00 00 00 00 00 00 01 44 00 tt[30]
[05/22 09:25:59 0e48  2                   ]      LDN:22 Moving tape from drive to slot address:[407]
[05/22 09:25:59 0e48  3                   ]      LDN:22 Start _ChgMoveMedium: Source[1] Dest[407]
[05/22 09:25:59 0e48  2                   ]      LDN:22 MOVE->: TapeName[WEDNESDAY] RID[19F9] Seq[1] BarCode[UBM008L5] Slot[7]
[05/22 09:25:59 0e48  2                   ]      LDN:22 MOVE->: From Drive[21] ABSL[1041] S/N[10000051  ] Element[0x0001]
[05/22 09:25:59 0e48  2                   ]      LDN:22 MOVE->: To Slot[7] Element[0x0407]
[05/22 09:25:59 0e48  3                   ] LDN: [22] Locking Library in _ChgMoveMedium; Flag: [0x12]
[05/22 09:25:59 0e48  2                   ] =>ABSL:1042 [MOVE MEDIUM     ] a5 40 02 c0 00 01 04 07 00 00 tt[20]
[05/22 09:25:59 0e48  3                   ]      LDN:22 ...in ChgCheckElementType
[05/22 09:25:59 0e48  3                   ]      LDN:22 ...in ChgCheckElementType
[05/22 09:25:59 0e48  2                   ] Serial number update on drive[21] ABSL[1041], newSN is NULL, previousSN[UBM008L5]: Tape is moved out from the drive.
[05/22 09:25:59 0e48  3                   ]      LDN:22 ClearSem in _ChgMoveMedium; Flag: [0x10]
[05/22 09:25:59 0e48  3                   ]      LDN:22 ...in ChgRecordTapeInDrive
[05/22 09:25:59 0e48  3                   ]      LDN:22 RecordTapeInDrive(OUT): Offset:0 DEA:1 SEA:1031 Invert:0 Group:[FS]
[05/22 09:25:59 0e48  3                   ]      LDN:22 ...in ChgCheckIfTapeInAnyChangerDrive
[05/22 09:25:59 0e48  3                   ]  ChgCheckIfTapeInAnyChangerDrive: locked device[22] after 0 retry  
[05/22 09:25:59 0e48  3                   ]      LDN:22 Moving tape from Element [401] to Element [1]
[05/22 09:25:59 0e48  3                   ]      LDN:22 Start _ChgMoveMedium: Source[401] Dest[1]
[05/22 09:25:59 0e48  2                   ]      LDN:22 MOVE->: TapeName[SUNDAY] RID[E208] Seq[1] BarCode[UBM002L5] Slot[1]
[05/22 09:25:59 0e48  2                   ]      LDN:22 MOVE->: From Slot[1] Element[0x0401]
[05/22 09:25:59 0e48  2                   ]      LDN:22 MOVE->: To Drive[21] ABSL[1041] S/N[10000051  ] Element[0x0001]
[05/22 09:25:59 0e48  3                   ] LDN: [22] Locking Library in _ChgMoveMedium; Flag: [0x12]
[05/22 09:25:59 0e48  2                   ] =>ABSL:1042 [MOVE MEDIUM     ] a5 40 02 c0 04 01 00 01 00 00 tt[20]
[05/22 09:25:59 0e48  3                   ] =>ABSL:1042 <MOVE MEDIUM> - Returning status[2]
[05/22 09:25:59 0e48  3                   ] Sense Data allready returned.
[05/22 09:25:59 0e48  2                   ] =>ABSL:1042 [REQUEST SENSE   ] 03 00 00 00 40 00 00 01 00 00
[05/22 09:25:59 0e48  2                   ]             <MOVE MEDIUM         >, Sense Data as Follows:
[05/22 09:25:59 0e48  2                   ]          SENSE ABSL:1042      f0 00 04 00 00 00 00 58 00 00 00 00 04
[05/22 09:25:59 0e48  2                   ]       EX SENSE ABSL:1042      03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[05/22 09:25:59 0e48  2                   ]          SENSE ABSL:1042      Hardware Error [04]
[05/22 09:25:59 0e48  2                   ]       EX SENSE ABSL:1042      Logical Unit Not Ready, Manual Intervention Required [04, 03]
[05/22 09:25:59 0e48  3                   ]      LDN:22 ClearSem in _ChgMoveMedium; Flag: [0x10]
[05/22 09:25:59 0e48  2                   ]      LDN:22 Door has been opened.
[05/22 09:25:59 0e48  2                   ] ASWriteToASLog: ERROR[6956] [The operation has failed because the library door is open:
1. Clear any obstructions from the library door.
2. Close the library door.
3. If the problem persists, call the library supplier helpline.]
[05/22 09:26:00 0f28  3 DM               2]      LDN:22 ...in ChgGetOriginalHomeSlot: for LDN[21]
[05/22 09:26:00 0f28  3 DM               2]      LDN:22 ...in ChgDriveElementStatus
[05/22 09:26:00 0f28  3 DM               2] ChangerAllocateMemory()
[05/22 09:26:00 0f28  2 DM               2] =>ABSL:1042 [READ ELEMENT STAT] b8 44 00 01 00 01 00 00 00 80 tt[20]
[05/22 09:26:00 0f28  2 DM               2] ---------------Read Element Status HEX DUMP----------------
[05/22 09:26:00 0f28  2 DM               2] Hexdump Starts --------------------
[05/22 09:26:00 0f28  2 DM               2] 00 01 00 01 00 00 00 18 04 00 00 10 00 00 00 10   ................
[05/22 09:26:00 0f28  2 DM               2] 00 01 08 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:26:00 0f28  2 DM               2] 30 32 4c 35 20 20 20 20 20 20 20 20 20 20 20 20   02L5            
[05/22 09:26:00 0f28  2 DM               2] 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20                  
[05/22 09:26:00 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:26:00 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:26:00 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 20 20   ..............  
[05/22 09:26:00 0f28  2 DM               2] 20 20 20 20 00 00 00 00 04 02 09 00 00 00 00 00       ............
[05/22 09:26:00 0f28  2 DM               2]
[05/22 09:26:00 0f28  2 DM               2] -------------- Read Element Status HEX DUMP ----------------
[05/22 09:26:00 0f28  2 DM               2] Hexdump Starts --------------------
[05/22 09:26:00 0f28  2 DM               2] 00 01 00 01 00 00 00 18 04 00 00 10 00 00 00 10   ................
[05/22 09:26:00 0f28  2 DM               2] 00 01 08 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:26:00 0f28  2 DM               2] 30 32 4c 35 20 20 20 20 20 20 20 20 20 20 20 20   02L5            
[05/22 09:26:00 0f28  2 DM               2] 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20                  
[05/22 09:26:00 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:26:00 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
[05/22 09:26:00 0f28  2 DM               2] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 20 20   ..............  
[05/22 09:26:00 0f28  2 DM               2] 20 20 20 20 00 00 00 00 04 02 09 00 00 00 00 00       ............
[05/22 09:26:00 0f28  2 DM               2]
[05/22 09:26:00 0f28  2 DM               2]      LDN:22 Element[0x0001] Source Element[0x0000] Valid?[0x00]
[05/22 09:26:00 0f28  2 DM               2]      LDN:22 Couldn't get information about media in Drive[0x0001]
[05/22 09:26:00 0f28  2 DM               2]      LDN:22 Drive[0x0001] may be EMPTY!
[05/22 09:26:00 0f28  3 DM               2] ChangerFreeMemory()
[05/22 09:26:00 0f28  2 DM               2]      LDN:22 Return Library Drive Associated Group:[]
[05/22 09:26:00 0f28  2 DM               2]      LDN:22 Return Library Drive Set Drive[21] with Group:[]
[05/22 09:26:00 0f28  3 DM               2] Attempting to UnLock device [21]
[05/22 09:26:00 0f28  3 DM               2] Successfully UnLocked device [21]
[05/22 09:26:00 0f28  2 DM               2]      LDN:22 Unlock Drive[21] Total number of free drives 1
[05/22 09:26:00 0f28  2 DM               2] Updating RaidChangerList Thread 3880....
[05/22 09:26:00 05c0  2                   ] =>ABSL:0010 [TEST UNIT READY ] 00 00 00 00 00 00 00 00 00 00 tt[5]
[05/22 09:26:00 0d10  2                   ] =>ABSL:0000 [TEST UNIT READY ] 00 00 00 00 00 00 00 00 00 00 tt[5]
[05/22 09:26:04 13b4  3 DM               2] RPCSetServerContext(): Context is already set to Server [SBBK00] hJob[041D9770]
[05/22 09:26:04 13b4  3 DM               2] GetXCB 9255: ulTime[773277765]
[05/22 09:26:04 13b4  3 DM               2] GetXCB 9255: ulTime[773277781]
[05/22 09:26:04 13b4  3 DM               2] GetXCB 9255: ulTime[773277796]
[05/22 09:26:04 13b4  3 DM               2] GetXCB 9255: ulTime[773277812]
[05/22 09:26:04 13b4  3 DM               2] GetXCB 9255: ulTime[773277828]
[05/22 09:26:04 13b4  3 DM               2] GetXCB 9255: ulTime[773277828]
[05/22 09:26:04 13b4  3 DM               2] DEVICE_QUERY_EXTENDED_CAPS ulCapFlags0[458753], ulCapFlags1[128]
[05/22 09:26:04 13b4  3 DM               2] DEVICE_QUERY_EXTENDED_CAPS SERVER NAME[SBBK00]
[05/22 09:26:04 0f28  2 DM               2] UpdateRaidChangerList Thread 3880 Returning....
[05/22 09:26:04 0f28  2 DM               2] ASWriteToASLogWithJobID: JobID[0] [8021] [Failed to erase media in slot:1 (EC=CONTROLLER FAILURE or HARDWARE ERROR)[Device:22][IBM     ULT3582-TL      ]]
[05/22 09:26:04 0f28  1 DM               2] E8021 Failed to erase media in slot. JobID:0, ChangerLDN:22, Slot[1], ret[167][CONTROLLER FAILURE or HARDWARE ERROR]


And the vtl syslog

May 22 09:25:59 sbvtl2 tgtd: iscsi_scsi_cmd_rx_start(1623) 1 0 0 0 0 0 49bb1b01
May 22 09:25:59 sbvtl2 tgtd: iscsi_task_queue(1568) 11bbb49 11bbb49 1
May 22 09:25:59 sbvtl2 tgtd: target_cmd_queue(1101) 0xec1ed0 0 2
May 22 09:25:59 sbvtl2 tgtd: target_cmd_perform_passthrough(1174) 0xec1ed0 0 2 PT
May 22 09:25:59 sbvtl2 tgtd: target_cmd_perform_passthrough(1182) 49bb1b01 0 (nil) (nil) 0 0 0 0 4
May 22 09:25:59 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:25:59 sbvtl2 vtllibrary[1134]: CDB (26274259) (delay 1000005): 00 40 00 00 00 00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: spc_tur(): ** Test Unit Ready : Returning =>  (26274259) Online **
May 22 09:25:59 sbvtl2 vtllibrary[1134]: completeSCSICommand(): OP s/n: (26274259), sz: 0, sam_status: 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: CDB (26274260) (delay 805): b8 12 04 01 00 01 00 00 00 6e 00 00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status(): READ ELEMENT STATUS (26274260) **
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():  Element type(2) => Storage
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Starting Element Address: 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Number of Elements      : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Allocation length       : 110 (0x006e)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Device ID: No, voltag: Yes
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Query 1 element starting from addr: 1025 of type: (2) Storage
May 22 09:25:59 sbvtl2 vtllibrary[1134]: num_available_elements(): Determing 1 element of type Storage starting at 1025, returning 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Available count: 1, type: 2
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_page_hdr(): Element Status Page Header: 02 80 00 34 00 00 00 34
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_descriptor(): Slot location: 1025, DVCID: 0, VOLTAG: 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_descriptor(): Returning 52 (0x34) bytes
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Count: 1, max_count: 1, slot: 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: num_available_elements(): Determing 1 element of type Storage starting at 1025, returning 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr(): Building READ ELEMENT STATUS Header struct
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Starting slot: 1025, number of configured slots: 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Element Status Data HEADER: 04 01 00 01 00 00 00 3c
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Decoded:
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   First element Address    : 1025 (0x401)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   Number elements reported : 1 (0x01)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   Total byte count         : 60 (0x003c)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Status Data
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   First element reported       : 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Number of elements available : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Byte count of report         : 60
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Status Page
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Element Type code            : 2 (Storage)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Primary Vol Tag              : Yes
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Alt Vol Tag                  : No
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Element descriptor length    : 52
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Byte count of descriptor data: 52
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Descriptor(s) : Num of Elements 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Debug.... i = 0, len = 52
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Element Address             : 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Status                      : 0x09
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Medium type                 : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Voltag info...
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Identification Descriptor
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Code Set                     : 0x00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Identifier type              : 0x00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Identifier length            : 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status(): Element count: 1, Elem byte count: 60 (0x003c), alloc_len: 110, returning 68
May 22 09:25:59 sbvtl2 vtllibrary[1134]: completeSCSICommand(): OP s/n: (26274260), sz: 68, sam_status: 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: CDB (26274261) (delay 805): b8 12 04 01 00 01 00 00 00 6e 00 00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status(): READ ELEMENT STATUS (26274261) **
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():  Element type(2) => Storage
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Starting Element Address: 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Number of Elements      : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Allocation length       : 110 (0x006e)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Device ID: No, voltag: Yes
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Query 1 element starting from addr: 1025 of type: (2) Storage
May 22 09:25:59 sbvtl2 vtllibrary[1134]: num_available_elements(): Determing 1 element of type Storage starting at 1025, returning 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Available count: 1, type: 2
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_page_hdr(): Element Status Page Header: 02 80 00 34 00 00 00 34
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_descriptor(): Slot location: 1025, DVCID: 0, VOLTAG: 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_descriptor(): Returning 52 (0x34) bytes
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Count: 1, max_count: 1, slot: 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: num_available_elements(): Determing 1 element of type Storage starting at 1025, returning 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr(): Building READ ELEMENT STATUS Header struct
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Starting slot: 1025, number of configured slots: 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Element Status Data HEADER: 04 01 00 01 00 00 00 3c
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Decoded:
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   First element Address    : 1025 (0x401)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   Number elements reported : 1 (0x01)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   Total byte count         : 60 (0x003c)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Status Data
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   First element reported       : 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Number of elements available : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Byte count of report         : 60
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Status Page
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Element Type code            : 2 (Storage)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Primary Vol Tag              : Yes
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Alt Vol Tag                  : No
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Element descriptor length    : 52
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Byte count of descriptor data: 52
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Descriptor(s) : Num of Elements 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Debug.... i = 0, len = 52
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Element Address             : 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Status                      : 0x09
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Medium type                 : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Voltag info...
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Identification Descriptor
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Code Set                     : 0x00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Identifier type              : 0x00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Identifier length            : 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status(): Element count: 1, Elem byte count: 60 (0x003c), alloc_len: 110, returning 68
May 22 09:25:59 sbvtl2 vtllibrary[1134]: completeSCSICommand(): OP s/n: (26274261), sz: 68, sam_status: 0
May 22 09:25:59 sbvtl2 vtltape[1111]: CDB (26274262) (delay 1000005): 1b 00 00 00 00 00
May 22 09:25:59 sbvtl2 vtltape[1111]: ssc_load_unload(): Unloading tape (26274262) **
May 22 09:25:59 sbvtl2 vtltape[1111]: updateMAM(): updateMAM(unload)
May 22 09:25:59 sbvtl2 vtltape[1111]: clear_ult_WORM(): +++ Trace mode pages at 0x627520 +++
May 22 09:25:59 sbvtl2 vtltape[1111]: lookup_pcode(): Looking for: Page/subpage (1d/00)
May 22 09:25:59 sbvtl2 vtltape[1111]: lookup_pcode(): Found "Medium Configuration" -> Page/subpage (1d/00)
May 22 09:25:59 sbvtl2 vtltape[1111]: clear_WORM(): l: 0x627520, m: 0x13685c0, m->pcodePointer: 0x1368600
May 22 09:25:59 sbvtl2 vtltape[1111]: ult_media_load(): +++ Trace +++ unload
May 22 09:25:59 sbvtl2 vtltape[1111]: completeSCSICommand(): OP s/n: (26274262), sz: 0, sam_status: 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: CDB (26274263) (delay 11605): a5 40 02 c0 00 01 04 07 00 00 00 00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_move_medium(): MOVE MEDIUM (26274263) **
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_move_medium(): Moving from slot 1 to slot 1031 using transport 704, Invert media: no
May 22 09:25:59 sbvtl2 vtllibrary[1134]: valid_slot(): Drive slot 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: valid_slot(): Found drive id: 51
May 22 09:25:59 sbvtl2 vtllibrary[1134]: valid_slot(): Storage slot 1031
May 22 09:25:59 sbvtl2 vtllibrary[1134]: is_map_slot(): slot type 2: NOT A MAP
May 22 09:25:59 sbvtl2 vtllibrary[1134]: completeSCSICommand(): OP s/n: (26274263), sz: 0, sam_status: 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: CDB (26274264) (delay 805): a5 40 02 c0 04 01 00 01 00 00 00 00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_move_medium(): MOVE MEDIUM (26274264) **
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_move_medium(): Moving from slot 1025 to slot 1 using transport 704, Invert media: no
May 22 09:25:59 sbvtl2 vtllibrary[1134]: valid_slot(): Storage slot 1025
May 22 09:25:59 sbvtl2 vtllibrary[1134]: valid_slot(): Drive slot 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: valid_slot(): Found drive id: 51
May 22 09:25:59 sbvtl2 vtllibrary[1134]: move_slot2drive(): About to send cmd: 'lload UBM002L5' to drive 1
May 22 09:25:59 sbvtl2 vtltape[1111]: processMessageQ(): Sender id: 50, msg : unload
May 22 09:25:59 sbvtl2 vtltape[1111]: unloadTape(): Tape not mounted
May 22 09:25:59 sbvtl2 vtltape[1111]: processMessageQ(): Library requested tape unload
May 22 09:25:59 sbvtl2 vtltape[1111]: processMessageQ(): Sender id: 50, msg : lload UBM002L5
May 22 09:25:59 sbvtl2 vtltape[1111]: load_tape(): Opening media: UBM002L5
May 22 09:25:59 sbvtl2 vtltape[1111]: read_header(): Reading header 8563852 at offset 561240342528, type: DATA, size: 65536
May 22 09:25:59 sbvtl2 vtltape[1111]: ERROR: load_tape(): pcl UBM002L5 file /opt/mhvtl/UBM002L5/data is not the correct length, expected 561240408064, actual 561240371200
May 22 09:25:59 sbvtl2 vtltape[1111]: loadTape(): Media load failed.. Unsupported format
May 22 09:25:59 sbvtl2 vtltape[1111]: lookup_log_pg(): Looking for: log page 0x2e
May 22 09:25:59 sbvtl2 vtltape[1111]: lookup_log_pg(): Tape Alert (0x2e)
May 22 09:25:59 sbvtl2 vtltape[1111]: update_TapeAlert(): Setting TapeAlert flags 0x00000000 00000800
May 22 09:25:59 sbvtl2 vtltape[1111]: lookup_log_pg(): Looking for: log page 0x0c
May 22 09:25:59 sbvtl2 vtltape[1111]: lookup_log_pg(): Sequential Access (0x0c)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: check_tape_load(): Received "Load failed: UBM002L5" from message Q
May 22 09:25:59 sbvtl2 vtllibrary[1134]: ERROR: move_slot2drive(): Load of UBM002L5 into drive 1 failed
May 22 09:25:59 sbvtl2 vtllibrary[1134]: mkSenseBuf(): SENSE [Key/ASC/ASCQ] [04 04 03]
May 22 09:25:59 sbvtl2 vtllibrary[1134]: completeSCSICommand(): OP s/n: (26274264), sz: 0, sam_status: 2
May 22 09:25:59 sbvtl2 vtllibrary[1134]: completeSCSICommand(): [Key/ASC/ASCQ] [04 04 03]
May 22 09:25:59 sbvtl2 vtllibrary[1134]: CDB (26274265) (delay 12805): b8 44 00 01 00 01 00 00 00 80 00 00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status(): READ ELEMENT STATUS (26274265) **
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():  Element type(4) => Drive
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Starting Element Address: 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Number of Elements      : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Allocation length       : 128 (0x0080)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status():   Device ID: No, voltag: No
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Query 1 element starting from addr: 1 of type: (4) Drive
May 22 09:25:59 sbvtl2 vtllibrary[1134]: num_available_elements(): Determing 1 element of type Drive starting at 1, returning 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Available count: 1, type: 4
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_page_hdr(): Element Status Page Header: 04 00 00 10 00 00 00 10
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_descriptor(): Slot location: 1, DVCID: 0, VOLTAG: 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_descriptor(): Returning 16 (0x10) bytes
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_page(): Count: 1, max_count: 1, slot: 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: num_available_elements(): Determing 1 element of type Drive starting at 1, returning 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr(): Building READ ELEMENT STATUS Header struct
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Starting slot: 1, number of configured slots: 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Element Status Data HEADER: 00 01 00 01 00 00 00 18
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():  Decoded:
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   First element Address    : 1 (0x01)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   Number elements reported : 1 (0x01)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: fill_element_status_data_hdr():   Total byte count         : 24 (0x0018)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Status Data
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   First element reported       : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Number of elements available : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Byte count of report         : 24
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Status Page
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Element Type code            : 4 (Drive)
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Primary Vol Tag              : No
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Alt Vol Tag                  : No
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Element descriptor length    : 16
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status():   Byte count of descriptor data: 16
May 22 09:25:59 sbvtl2 vtllibrary[1134]: decode_element_status(): Element Descriptor(s) : Num of Elements 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Debug.... i = 0, len = 16
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Element Address             : 1
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Status                      : 0x08
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Medium type                 : 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():  Identification Descriptor
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Code Set                     : 0x00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Identifier type              : 0x00
May 22 09:25:59 sbvtl2 vtllibrary[1134]: dump_element_desc():   Identifier length            : 0
May 22 09:25:59 sbvtl2 vtllibrary[1134]: smc_read_element_status(): Element count: 1, Elem byte count: 24 (0x0018), alloc_len: 128, returning 32
May 22 09:25:59 sbvtl2 vtllibrary[1134]: completeSCSICommand(): OP s/n: (26274265), sz: 32, sam_status: 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1913) found a task 49bb1b01 0 0 0
May 22 09:26:00 sbvtl2 tgtd: __cmd_done_passthrough(1278) (nil) (nil) 0 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_scsi_cmd_rx_start(1623) 1 b8 0 0 112 0 4abb1b01
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_queue(1568) 11bbb4a 11bbb4a 1
May 22 09:26:00 sbvtl2 tgtd: target_cmd_queue(1101) 0xec1ed0 b8 2
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1174) 0xec1ed0 b8 2 PT
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1182) 4abb1b01 b8 (nil) 0xec3000 0 0 110 0 4
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1913) found a task 4abb1b01 110 0 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_data_rsp_build(1119) 68 68 0 655364abb1b01
May 22 09:26:00 sbvtl2 tgtd: __cmd_done_passthrough(1278) (nil) 0xec3000 0 110
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_scsi_cmd_rx_start(1623) 1 b8 0 0 112 0 4bbb1b01
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_queue(1568) 11bbb4b 11bbb4b 1
May 22 09:26:00 sbvtl2 tgtd: target_cmd_queue(1101) 0xec1ed0 b8 2
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1174) 0xec1ed0 b8 2 PT
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1182) 4bbb1b01 b8 (nil) 0xec3000 0 0 110 0 4
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1913) found a task 4bbb1b01 110 0 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_data_rsp_build(1119) 68 68 0 655364bbb1b01
May 22 09:26:00 sbvtl2 tgtd: __cmd_done_passthrough(1278) (nil) 0xec3000 0 110
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_scsi_cmd_rx_start(1623) 1 1b 0 0 0 0 4cbb1b01
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_queue(1568) 11bbb4c 11bbb4c 1
May 22 09:26:00 sbvtl2 tgtd: target_cmd_queue(1101) 0xec1ed0 1b 1
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1174) 0xec1ed0 1b 1 PT
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1182) 4cbb1b01 1b (nil) (nil) 0 0 0 0 4
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1913) found a task 4cbb1b01 0 0 0
May 22 09:26:00 sbvtl2 tgtd: __cmd_done_passthrough(1278) (nil) (nil) 0 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_scsi_cmd_rx_start(1623) 1 a5 0 0 0 0 4dbb1b01
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_queue(1568) 11bbb4d 11bbb4d 1
May 22 09:26:00 sbvtl2 tgtd: target_cmd_queue(1101) 0xec1ed0 a5 2
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1174) 0xec1ed0 a5 2 PT
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1182) 4dbb1b01 a5 (nil) (nil) 0 0 0 0 4
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1913) found a task 4dbb1b01 0 0 0
May 22 09:26:00 sbvtl2 tgtd: __cmd_done_passthrough(1278) (nil) (nil) 0 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_scsi_cmd_rx_start(1623) 1 a5 0 0 0 0 4ebb1b01
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_queue(1568) 11bbb4e 11bbb4e 1
May 22 09:26:00 sbvtl2 tgtd: target_cmd_queue(1101) 0xec1ed0 a5 2
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1174) 0xec1ed0 a5 2 PT
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1182) 4ebb1b01 a5 (nil) (nil) 0 0 0 0 4
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1913) found a task 4ebb1b01 0 0 0
May 22 09:26:00 sbvtl2 tgtd: __cmd_done_passthrough(1278) (nil) (nil) 0 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_scsi_cmd_rx_start(1623) 1 b8 0 0 128 0 4fbb1b01
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_queue(1568) 11bbb4f 11bbb4f 1
May 22 09:26:00 sbvtl2 tgtd: target_cmd_queue(1101) 0xec1ed0 b8 2
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1174) 0xec1ed0 b8 2 PT
May 22 09:26:00 sbvtl2 tgtd: target_cmd_perform_passthrough(1182) 4fbb1b01 b8 (nil) 0xec3000 0 0 128 0 4
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1913) found a task 4fbb1b01 128 0 0
May 22 09:26:00 sbvtl2 tgtd: iscsi_data_rsp_build(1119) 32 32 0 655364fbb1b01
May 22 09:26:00 sbvtl2 tgtd: __cmd_done_passthrough(1278) (nil) 0xec3000 0 128
May 22 09:26:00 sbvtl2 tgtd: iscsi_task_tx_start(1938) no more data


Let me know if you need some more.

Regards
Reply | Threaded
Open this post in threaded view
|

Re: library door open?

Mark Harvey
Administrator
Many thanks for the excellent report..

The following couple of lines appear to be the root cause.

May 22 09:25:59 sbvtl2 vtltape[1111]: read_header(): Reading header 8563852 at offset 561240342528, type: DATA, size: 65536
May 22 09:25:59 sbvtl2 vtltape[1111]: ERROR: load_tape(): pcl UBM002L5 file /opt/mhvtl/UBM002L5/data is not the correct length, expected 561240408064, actual 561240371200
May 22 09:25:59 sbvtl2 vtltape[1111]: loadTape(): Media load failed.. Unsupported format


I don't have any answers at the moment but will look into this..
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: library door open?

sbcedservice
Probably it's not a vtl error.

I've found a "disk full" condition on sunday .......


Thanks
Reply | Threaded
Open this post in threaded view
|

Re: library door open?

Mark Harvey
Administrator
I'm working on a patch to help limit 'damage' from a disk full condition...

I need to do some sanity testing and the post here for further testing & comment.
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: library door open?

Mark Harvey
Administrator

I've posted a patch which should help in disk full conditions.
http://mhvtl-a-linux-virtual-tape-library.966029.n3.nabble.com/patch-to-make-media-files-more-resilient-to-disk-full-conditions-td4025456.html

testers welcome.

It will be included in the next release 1.4-8 (once the patch has had some more testing)
Regards from Australia
Mark Harvey