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? |
Administrator
|
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:
Regards from Australia
Mark Harvey |
This post was updated on .
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]: vtllibrary@10.service: Main process exited, code=dumped, status=6/ABRT Apr 27 11:15:41 linux64 systemd[1]: vtllibrary@10.service: Failed with result 'core-dump'. |
Free forum by Nabble | Edit this page |