Modify library logic to support autoloader tape auto-eject on unload?

[Tim Jones]

Hi Mark,

I've just noticed a difference in the current code between build and installation on the 3.XX kernel versus the 4.XX kernel.  On the 3.x kernel, issuing a library unload call with a tape loaded in a drive results in the tape being properly unloaded.  However, on the 4.x kernel, if I don't explicitly send a REWIND with the offline flag set to the drive before telling the library to unload (so that the drive is reporting as empty (DR_OPEN)) results in the layer going into a hung state.  After the expiration of the standard timeout value the app gets a success from the library, but further attempts to communication with the library fail.

Same version of mtx and mt-st on both system (I build from source).

Anything that I can provide to help track this down?

[Mark Harvey]

Any chance of the syslog with the hang ?

That way, I have the sequence of scsi op codes (verbose 1 is fine)

Something wrong with sequence of messages sent to/from library and tape drive

Sent from my iPhone

On 27 Apr 2019, at 09:57, Tim Jones [via mhVTL - A Linux Virtual Tape Library] <[hidden email]> wrote:

Hi Mark,

I've just noticed a difference in the current code between build and installation on the 3.XX kernel versus the 4.XX kernel.  On the 3.x kernel, issuing a library unload call with a tape loaded in a drive results in the tape being properly unloaded.  However, on the 4.x kernel, if I don't explicitly send a REWIND with the offline flag set to the drive before telling the library to unload (so that the drive is reporting as empty (DR_OPEN)) results in the layer going into a hung state.  After the expiration of the standard timeout value the app gets a success from the library, but further attempts to communication with the library fail.

Same version of mtx and mt-st on both system (I build from source).

Anything that I can provide to help track this down?

---

If you reply to this email, your message will be added to the discussion below:

http://mhvtl-a-linux-virtual-tape-library.966029.n3.nabble.com/Modify-library-logic-to-support-autoloader-tape-auto-eject-on-unload-tp4026257.html

To start a new topic under mhVTL - A Linux Virtual Tape Library, email [hidden email]
To unsubscribe from mhVTL - A Linux Virtual Tape Library, click here.
NAML

[Tim Jones]

Here it is - looks like a core dump - looking for the core file now:

Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: CDB (27) (delay 1000005): 12 00 00 00 38 00
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: spc_inquiry(): INQUIRY ** (27)
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: CDB (28) (delay 405): 1a 08 1d 00 88 00
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: spc_mode_sense(): MODE SENSE 6 (28) **
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: CDB (29) (delay 405): b8 12 00 00 00 00 00 00 54 7c 00 00
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: spc_illegal_op(): UNSUPPORTED OP CODE **
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: return_sense(): [Key/ASC/ASCQ] [05 20 00] 0xc0 0000
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: CDB (30) (delay 405): b8 02 00 00 00 00 00 00 54 7c 00 00
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: spc_illegal_op(): UNSUPPORTED OP CODE **
Apr 27 11:14:59 linux64 /usr/bin/vtltape[954]: return_sense(): [Key/ASC/ASCQ] [05 20 00] 0xc0 0000
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: CDB (31) (delay 1000005): 12 00 00 00 38 00
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: spc_inquiry(): INQUIRY ** (31)
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: CDB (32) (delay 405): 1a 08 1d 00 88 00
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: spc_mode_sense(): MODE SENSE 6 (32) **
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: CDB (33) (delay 405): b8 12 00 20 00 08 00 00 03 70 00 00
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: smc_read_element_status(): READ ELEMENT STATUS (33) **
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: CDB (34) (delay 405): b8 14 01 e0 00 01 00 00 03 70 00 00
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: smc_read_element_status(): READ ELEMENT STATUS (34) **
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: CDB (35) (delay 405): b8 11 00 01 00 01 00 00 03 70 00 00
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: smc_read_element_status(): READ ELEMENT STATUS (35) **
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: CDB (36) (delay 805): a5 00 00 01 00 20 01 e0 00 00 00 00
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: smc_move_medium(): MOVE MEDIUM (36) **
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: smc_move_medium(): Moving from slot 32 to slot 480 using transport 1, Invert media: no
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: is_drive_empty(): 10: Sending "mount_state" to snd_id 11
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: processMessageQ(): 11: Received message "mount_state" from snd_id 10
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: send_msg_and_log(): 11: Replying to snd_id 10 with "Not occupied"
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: is_drive_empty(): 10: Received "Not occupied" from snd_id 11
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: move_slot2drive(): About to send cmd: 'lload E01001L5' to drive 1
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: processMessageQ(): 11: Received message "lload E01001L5" from snd_id 10
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: loadTape(): Media type 'LTO5' loaded with S/No. : E01001L5_1556320839
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: rewind_tape(): Media is writable
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: return_sense(): [Key/ASC/ASCQ] [06 28 00]
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: loadTape(): Media is writable
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: loadTape(): Setting MediumDensityCode to LTO5 (0x58) Media type: 0x00
Apr 27 11:15:18 linux64 /usr/bin/vtltape[954]: send_msg_and_log(): 11: Replying to snd_id 10 with "Loaded OK: E01001L5"
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: check_tape_load(): 10: Received "Loaded OK: E01001L5" from snd_id 11
Apr 27 11:15:18 linux64 /usr/bin/vtllibrary[953]: move_cart(): Setting src slot access true
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: CDB (37) (delay 145205): 00 00 00 00 00 00
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: ssc_tur(): Test Unit Ready (37) ** : Yes
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: CDB (38) (delay 405): 05 00 00 00 00 00
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: ssc_read_block_limits(): READ BLOCK LIMITS (38) **
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: CDB (39) (delay 405): 1a 00 00 00 0c 00
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: spc_mode_sense(): MODE SENSE 6 (39) **
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: CDB (40) (delay 405): 01 00 00 00 00 00
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: ssc_rewind(): REWINDING (40) **
Apr 27 11:15:25 linux64 /usr/bin/vtltape[954]: rewind_tape(): Media is writable
Apr 27 11:15:25 linux64 kernel: [49010.386838] st 7:0:1:0: [st0] Block limits 4 - 2097152 bytes.
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: CDB (41) (delay 92005): 00 00 00 00 00 00
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: ssc_tur(): Test Unit Ready (41) ** : Yes
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: CDB (42) (delay 405): 05 00 00 00 00 00
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: ssc_read_block_limits(): READ BLOCK LIMITS (42) **
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: CDB (43) (delay 405): 1a 00 00 00 0c 00
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: spc_mode_sense(): MODE SENSE 6 (43) **
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: CDB (44) (delay 405): 11 01 7f ff ff 00
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: ssc_space_6(): SPACE (44) ** forward 8388607 filemarks
Apr 27 11:15:36 linux64 /usr/bin/vtltape[954]: return_sense(): [Key/ASC/ASCQ] [08 00 05]
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: CDB (45) (delay 134805): 12 00 00 00 38 00
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: spc_inquiry(): INQUIRY ** (45)
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: CDB (46) (delay 405): 1a 08 1d 00 88 00
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: spc_mode_sense(): MODE SENSE 6 (46) **
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: CDB (47) (delay 405): b8 12 00 20 00 08 00 00 03 70 00 00
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: smc_read_element_status(): READ ELEMENT STATUS (47) **
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: CDB (48) (delay 405): b8 14 01 e0 00 01 00 00 03 70 00 00
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: smc_read_element_status(): READ ELEMENT STATUS (48) **
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: CDB (49) (delay 405): b8 11 00 01 00 01 00 00 03 70 00 00
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: smc_read_element_status(): READ ELEMENT STATUS (49) **
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: CDB (50) (delay 805): a5 00 00 01 01 e0 00 20 00 00 00 00
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: smc_move_medium(): MOVE MEDIUM (50) **
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: smc_move_medium(): Moving from slot 480 to slot 32 using transport 1, Invert media: no
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: is_drive_empty(): 10: Sending "mount_state" to snd_id 11
Apr 27 11:15:41 linux64 /usr/bin/vtltape[954]: processMessageQ(): 11: Received message "mount_state" from snd_id 10
Apr 27 11:15:41 linux64 /usr/bin/vtltape[954]: send_msg_and_log(): 11: Replying to snd_id 10 with "occupied"
Apr 27 11:15:41 linux64 vtllibrary[953]: *** buffer overflow detected ***: /usr/bin/vtllibrary terminated
Apr 27 11:15:41 linux64 /usr/bin/vtllibrary[953]: is_drive_empty(): 10: Received "occupied" from snd_id 11
Apr 27 11:15:41 linux64 systemd[1]: [e-mail]: Main process exited, code=dumped, status=6/ABRT
Apr 27 11:15:41 linux64 systemd[1]: [e-mail]: Failed with result 'core-dump'.

[Tim Jones]

For anyone tracking this on, the available code as of 05/02/2019 resolves this for the 4.x and 5.x kernels.

Kudos to Mark for the effort!

Tim