Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SCSI error HHC00205E for each SCSI drive #97

Closed
kensmyth opened this issue Apr 5, 2016 · 11 comments
Closed

SCSI error HHC00205E for each SCSI drive #97

kensmyth opened this issue Apr 5, 2016 · 11 comments
Assignees

Comments

@kensmyth
Copy link

kensmyth commented Apr 5, 2016

(Environment: Debian 8.3 Linux, Hyperion 4.00, hardware HP DL380g5)

With SCSIMOUNT active, an error occurs ~every 2 minutes as each SCSI drive is checked. It would seem that a SETBLK command is being issued but a drive will not accept that if it is not-ready. Seems like a STATUS command would make more sense here as it is accepted even if a drive is in a not-ready condition. If the tape drive is made ready, the errors stop.


With SCSIMOUNT off, these errors occur when a tape is rewound/offline'd by the MVS guest.

14:32:47 HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:34:47 HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:36:49 HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:38:49 HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:40:50 HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:42:51 HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor

Hercules startup log:

14:22:37 HHC01413I Hercules version 4.00
14:22:37 HHC01414I (c) Copyright 1999-2012 by Roger Bowler, Jan Jaeger, and others
14:22:37 HHC01415I Built on Feb  5 2015 at 16:48:19
14:22:37 HHC01416I Build information:
14:22:37 HHC01417I Modes: S/370 ESA/390 z/Arch
14:22:37 HHC01417I Max CPU Engines: 8
14:22:37 HHC01417I Using   setresuid() for setting privileges
14:22:37 HHC01417I Using   POSIX threads Threading Model
14:22:37 HHC01417I Using   Error-Checking Mutex Locking Model
14:22:37 HHC01417I With    Dynamic loading support
14:22:37 HHC01417I Using   shared libraries
14:22:37 HHC01417I With    External GUI support
14:22:37 HHC01417I With    IPV6 support
14:22:37 HHC01417I With    HTTP Server support
14:22:37 HHC01417I With    sqrtl support
14:22:37 HHC01417I With    SIGABEND handler
14:22:37 HHC01417I With    CCKD BZIP2 support
14:22:37 HHC01417I With    HET BZIP2 support
14:22:37 HHC01417I With    ZLIB support
14:22:37 HHC01417I With    Regular Expressions support
14:22:37 HHC01417I Without Object REXX support
14:22:37 HHC01417I Without Regina REXX support
14:22:37 HHC01417I With    Automatic Operator support
14:22:37 HHC01417I With    National Language Support
14:22:37 HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8
14:22:37 HHC01417I Running on debian8 Linux-3.16.0-4-amd64. #1 SMP Debian 3.16.7-ckt11-1+deb8u6 (2015-11-09), x86_64 MP=4
14:22:37 HHC00150I Crypto module loaded (c) Copyright 2003-2011 by Bernard van der Helm
14:22:37 HHC00151I Activated facility: Message Security Assist
14:22:37 HHC00151I Activated facility: Message Security Assist Extension 1, 2, 3 and 4
14:22:37 HHC00100I Thread id 7F8C2D315700, prio 15, name Processor CP00 started
14:22:37 HHC00100I Thread id 7F8C2D214700, prio -20, name Timer started
14:22:37 HHC00811I Processor CP00: architecture mode z/Arch
14:22:37 HHC00136W Error in function setenv(): cannot set CUU: Not thread safe--setting disabled
14:22:37 HHC01802I HTTP server using root directory /home/ken/tk4/hercules/httproot/
14:22:37 HHC01807I HTTP server signaled to start
14:22:37 HHC00100I Thread id 7F8C2D518700, prio  4, name HTTP server started
14:22:37 HHC01042I 0:000C COMM: device bound to socket 3505
14:22:37 HHC00221I 0:0480 Tape file /dev/nst2, type scsi: format type SCSI attached tape drive
14:22:37 HHC00100I Thread id 7F8C2C10F700, prio  0, name SCSI-TAPE mount monitor started
14:22:37 HHC00221I 0:0481 Tape file /dev/nst1, type scsi: format type SCSI attached tape drive
14:22:37 HHC00221I 0:0482 Tape file /dev/nst0, type scsi: format type SCSI attached tape drive
14:22:37 HHC01437I Config file[50] conf/tk4-.cnf: including file conf/extcons.cnf
14:22:37 HHC00100I Thread id 7F8C2D417700, prio  0, name Socket device listener started
14:22:37 HHC01802I HTTP server using root directory /home/ken/tk4/hercules/httproot/
14:22:37 HHC01803I HTTP server waiting for requests on port 8038
14:22:37 HHC01437I Config file[76] conf/tk4-.cnf: including file conf/tk4-_default.cnf
14:22:37 HHC00971I 0:0610 CTC: connect to 127.0.0.1:18610 failed, starting server
14:22:37 HHC00100I Thread id 7F8C1F5CA700, prio  4, name Console connection started
14:22:37 HHC00971I 0:0611 CTC: connect to 127.0.0.1:18611 failed, starting server
14:22:37 HHC01024I Waiting for console connections on port 3270
:
14:22:39 HHC01603I *
14:22:39 HHC01603I *                           ************   ****  *****          ||
14:22:39 HHC01603I *                           **   **   **    **    **           |||
14:22:39 HHC01603I *                           **   **   **    **   **           ||||
14:22:39 HHC01603I *                                **         **  **           || ||
14:22:39 HHC01603I *        |l      _,,,---,,_      **         ** **           ||  ||
14:22:39 HHC01603I * ZZZzz /,'.-'`'    -.  ;-;;,    **         ****           ||   ||
14:22:39 HHC01603I *      |,4-  ) )-,_. ,( (  ''-'  **         *****         ||    ||
14:22:39 HHC01603I *     '---''(_/--'  `-')_)       **         **  **       ||     ||    ||||||||||
14:22:39 HHC01603I *                                **         **   **      |||||||||||
14:22:39 HHC01603I *       The MVS 3.8j             **         **    **            ||
14:22:39 HHC01603I *     Tur(n)key System           **         **     **           ||
14:22:39 HHC01603I *                              ******      ****     ***       ||||||
14:22:39 HHC01603I *
14:22:39 HHC01603I *            TK3 created by Volker Bandke       vbandke@bsp-gmbh.com
14:22:39 HHC01603I *            TK4- update by Juergen Winkelmann  winkelmann@id.ethz.ch
14:22:39 HHC01603I *                     see TK4-.CREDITS for complete credits
14:22:39 HHC01603I *
14:22:39 HHC02264I Script 1: file scripts/tk4-.rc processing ended
14:22:42 HHC00100I Thread id 7F8C1C47C700, prio  0, name SCSI-TAPE status monitor started
14:24:44 HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:26:44 HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:28:17 HHC01603I scsimount
14:28:17 HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
14:28:17 HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
14:28:17 HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
14:28:45 HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:29:05 HHC01603I scsimount
14:29:05 HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
14:29:05 HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
14:29:05 HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
14:30:46 HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:31:47 HHC01603I scsimount
14:31:47 HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
14:31:47 HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
14:31:47 HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
14:32:47 HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:34:47 HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:36:49 HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:38:49 HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:40:50 HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
14:42:51 HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor

Hercules configuration file:

#**********************************************************************
#***                                                                ***
#*** File:    tk4-.cnf                                              ***
#***                                                                ***
#*** Purpose: Hercules configuration file for MVS 3.8j TK4-         ***
#***                                                                ***
#*** Updated: 2014/12/22                                            ***
#***                                                                ***
#**********************************************************************
CPUSERIAL 000611
CPUMODEL 3033
MAINSIZE ${MAINSIZE:=16}
XPNDSIZE 0
CNSLPORT ${CNSLPORT:=3270}
HTTP PORT ${HTTPPORT:=8038}
HTTP ROOT hercules/httproot
HTTP START
NUMCPU ${NUMCPU:=1}
MAXCPU ${MAXCPU:=1}
TZOFFSET -0600
ARCHMODE S/370
OSTAILOR QUIET
DIAG8CMD ENABLE ECHO
SCSIMOUNT YES
# .-----------------------------Device number
# |    .------------------------Device type
# |    |   .--------------------File name
# |    |   |
# V    V   V
#--- ---- --------------------
#
# unit record devices
#
0002 3211 prt/prt002.txt ${TK4CRLF}
000E 1403 prt/prt00e.txt ${TK4CRLF}
000C 3505 ${RDRPORT:=3505} sockdev ascii trunc eof
000D 3525 pch/pch00d.txt ascii
#
0480 3420 /dev/nst2     #SCSI DEC TSZ07 9-track
0481 3420 /dev/nst1     #SCSI STK 9840 emul 3490
0482 3420 /dev/nst0     #SCSI STK 9840 emul 3490
@Fish-Git
Copy link
Contributor

Interesting!

Given that the only place where we do a MTSETBLK ioctl call is in the finish_scsitape_open function (which itself is only called if/when a tape is supposedly mounted), it would seem that the blocking-mode re-open of the tape drive is failing for some unknown reason. (See the first 3 statements of the finish_scsitape_open function where we close the device and then re-open it again but this time without the O_NONBLOCK flag).

Further, it would seem our scsimount logic is also either very sick (some race condition somewhere perhaps?) or else something else running on the host is perhaps interfering with it. Notice the results of the several scsimount commands you entered: each issuance reports completely contradictory results from the previous time!

The first time it says scsimount is not active for /dev/nst0 (implying there is a tape mounted) but is active on /dev/nst1 and /dev/nst2 (implying neither has a tape mounted). Later on, it reports it's not active on /dev/nst2 but is now active on /dev/nst0 and /dev/nst1! And the third time is yet again completely different from the first two! (WTF?!)

Something very weird is obviously going on somewhere!   :(

Do you have some type of "Storage Manager" product installed on this box perhaps? Some type of software that is wanting/expecting to be "in control of" your tape drives? If so, try disabling it. I know that on Windows such software will cause scsimount to misbehave. Perhaps the same thing is happening with you?

What type of tape drives do you have? What brand/model? We might need to add some additional "smarts" to our open/scsimount logic. Right now we're relying on the GMT_DR_OPEN status flag to tell us whether there's a tape mounted or not (i.e. whether the tape drive is "ready" or not). Perhaps the particular brand/model tape drive you're using returns different status bits that we need to test?

In any case there's nothing more I can do or even suggest. Sorry!

Just tun off whatever Tape Storage Manager software you might have (if any) and try again. <shrug>

@Fish-Git
Copy link
Contributor

When the problem occurs and your scsimount commands begin reporting conflicting/contradictory results, you might try turning auto-scsimount off for a minute or three, and then turn it back on again. See help scsimount for more information.

@kensmyth
Copy link
Author

kensmyth commented Apr 20, 2016

Some additional information:

There is no storage manager software on this system. Tape drives are fibre channel attached (scsi over fiber channel).

/dev/nst0 is a StorageTek 9840 fiber channel drive
/dev/nst1 is a StorageTek 9840 fiber channel drive
/dev/nst2 is a DEC TSZ07 9-track drive via a fc/SCSI bridge

To rule out that the errors had anything to do with the fiber channel HBA or fabric I connected the TZ07 drive directly via SCSI interface but see the same problem. Could it be that the SETBLK is rejected at the Linux tape driver because the drive is ‘not ready’?

Here is how the tape drives respond on Linux without Herc running:

(*** with Drives in 'NOT READY' condition ***)

root@debian8:/home/ken# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x0 (default).
Soft error count since last status=0
General status bits on (10000):
IM_REP_EN

root@debian8:/home/ken# mt -f /dev/nst1 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x0 (default).
Soft error count since last status=0
General status bits on (10000):
IM_REP_EN

root@debian8:/home/ken# mt -f /dev/nst2 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x0 (default).
Soft error count since last status=0
General status bits on (10000):
IM_REP_EN

(set blocksize results in I/O error)

root@debian8:/home/ken# mt -f /dev/nst0 setblk 0
/dev/nst0: Input/output error
root@debian8:/home/ken# mt -f /dev/nst1 setblk 0
/dev/nst1: Input/output error
root@debian8:/home/ken# mt -f /dev/nst2 setblk 0
/dev/nst2: Input/output error
root@debian8:/home/ken#

(*** with Drives in READY condition ***)

root@debian8:/home/ken# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x42 (LTO-2).
Soft error count since last status=0
General status bits on (41010000):
BOT ONLINE IM_REP_EN
root@debian8:/home/ken#

root@debian8:/home/ken# mt -f /dev/nst1 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x42 (LTO-2).
Soft error count since last status=0
General status bits on (41010000):
BOT ONLINE IM_REP_EN

root@debian8:/home/ken# mt -f /dev/nst2 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x3 (GCR (6250 bpi)).
Soft error count since last status=0
General status bits on (41810000):
BOT ONLINE D_6250 IM_REP_EN
root@debian8:/home/ken#

(set variable block size is accepted)

root@debian8:/home/ken# mt -f /dev/nst0 setblk 0
root@debian8:/home/ken# mt -f /dev/nst1 setblk 0
root@debian8:/home/ken# mt -f /dev/nst2 setblk 0
root@debian8:/home/ken#

@Fish-Git
Copy link
Contributor

Fish-Git commented Apr 20, 2016

Thank you for that, Ken.

It is still unclear to me what you mean by the drives being "ready" or "not ready" however.

Does "ready" mean the drive is simply online and accessible? Or does it mean a tape is mounted on the drive?

This is what I hate about SCSI tape handling across host operating systems. There's apparently no consistency.   :(

According to SCSI Tape Driver documentation on kernel.org, the GMT_DR_OPEN flag is supposed to be the (standard?) way to tell whether a tape is mounted or not:

The following ioctl uses the structure mtget to return the status:
MTIOCGET Returns some status information.
        The file number and block number within file are returned. The
        block is -1 when it can't be determined (e.g., after MTBSF).
        The drive type is either MTISSCSI1 or MTISSCSI2.
        The number of recovered errors since the previous status call
        is stored in the lower word of the field mt_erreg.
        The current block size and the density code are stored in the field
        mt_dsreg (shifts for the subfields are MT_ST_BLKSIZE_SHIFT and
        MT_ST_DENSITY_SHIFT).
    The GMT_xxx status bits reflect the drive status. GMT_DR_OPEN
    is set if there is no tape in the drive. GMT_EOD means either
    end of recorded data or end of tape. GMT_EOT means end of tape.

However, according to Hewlett Packard's documentation (pages 95-96), the GMT_DR_OPEN flag is not used at all. Instead, it uses the GMT_ONLINE flag.

But even that is ambiguous.

In the mainframe world, whether or not a tape drive is ready and whether or not a tape is mounted are two completely different statuses, both of which need to be reported separately to us. Does HP's GMT_ONLINE flag imply there is a tape mounted? Or does it just mean the drive is "online" and accessible? We must be able to tell the difference!

Kern Sibbald lamented about the same issues back in 2005 in the "Tape drive handling on FreeBSD" thread:

> > Actually, I am really shocked how poor the "Unix" tape interface is (this
> > has
> > nothing to do with FreeBSD in particular). There is no standard way to
> > set tape drive options, there is no standard way to figure out if a tape
> > drive exists and what options it has set for it (blocking, two eof,
> > density, compression, ...). Probably most annoying, there is no standard
> > way to know
> > if a tape is mounted or not.

Based on what I'm seeing in this Hercules issue it doesn't appear that things have improved all that much since.

He does however go on to suggest a possible workaround:

OK, here are a couple of real possibilities (at least from my point of view):

1. I believe that one can modify the FreeBSD tape API to become more 
compatible with Solaris and Linux without breaking any programs -- simply use 
their "trick" of allowing an open() in all cases to succeed if O_NONBLOCK is 
set.  I think this is an ugly kludge, but that is how they do it. If there is 
no tape in the drive, then return a file descriptor with no read and no write 
permission, and modify them when a tape is mounted.

I must have missed that in my earlier research from years ago. Perhaps all I need to do is add some additional code to also check the permissions associated with the returned file descriptor (however one does that on *Nix) upon being returned a status where the GMT_DR_OPEN flag is not set (implying a tape is mounted). Only if both conditions are true -- GMT_DR_OPEN flag is clear and file descriptor has "read" permission -- should we then consider a tape to be mounted.

Or... maybe we need to define a new code block in hostopts.h for Hewlett Packard systems with a new #define flag indicating what detection method we should use to detect when a tape is mounted?

Or... Maybe we need to define a new special option for HP tape drives? (or other manufacturers, brands or models whose tape drivers don't use GMT_DR_OPEN?)

It's clear to me now what was going on in your original test: because the status that your HP system was returning didn't have the GMT_DR_OPEN flag set, scsimount thought a tape was mounted. But when it re-opened it again in blocking mode this time (finish_scsitape_open function) and went to set variable length blocks (MTSETBLK ioctl call), it failed, causing the scsimount thread to be re-activated for that drive again. Each drive was having the scsimount thread started, ended, started, and ended again -- over and over and over -- all because HP doesn't use the GMT_DR_OPEN flag.

(sigh)

What a mess.   :(

@kensmyth
Copy link
Author

kensmyth commented Apr 21, 2016

Sorry for inconsistent terminology, by READY I mean tape mounted and the ONLINE led lit. I will add some more detail with and without automount enabled. Thanks

@Fish-Git
Copy link
Contributor

I'd also like to see some additional mt -f /dev/nst0 status displays for the case where a tape is NOT mounted, but the drive IS online.

In other words, I'd like to see separate mt -f /dev/nst0 status displays for the following four cases:

  • Drive NOT ready, tape NOT mounted.
  • Drive NOT ready, tape IS mounted.
  • Drive IS ready, but tape NOT mounted.
  • Drive IS ready and tape IS mounted too.

Ideally we should see four different sets of statuses, but I'm going to pessimistically guess we probably won't.   :(

@kensmyth
Copy link
Author

kensmyth commented Apr 21, 2016

To continue with the ready/online subject. If the drive is powered-up and connected to the host via FC or SCSI, it is online in the sense that the host can query it for status. In the classical mainframe and mincomputer sense it is online when a tape is mounted and the "ONLINE" button has been pressed. You can't get "ONLINE" to light-up if there is not a tape mounted & ready. The additional mt status results below.

We have 2nd and 3rd generation tape drives here, the ONLINE status bit seems consistent. I would suggest that the STATUS inquiry be used to test that bit to see if as tape is mounted. If ONLINE is set, then issue BLKSIZE 0 to set variable length block mode on the drive (if necessary).

  • Drive NOT ready, tape NOT mounted.

root@debian8:/home/ken# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x0 (default).
Soft error count since last status=0
General status bits on (10000):
IM_REP_EN

  • Drive NOT ready, tape IS mounted.

not possible on 9840 drive

  • Drive IS ready, but tape NOT mounted.

not possible on 9840 drive

  • Drive IS ready and tape IS mounted too.

root@debian8:/home/ken# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x42 (LTO-2).
Soft error count since last status=0
General status bits on (41010000):
BOT ONLINE IM_REP_EN

  • Drive NOT ready, tape NOT mounted.

root@debian8:/home/ken# mt -f /dev/nst2 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x0 (default).
Soft error count since last status=0
General status bits on (10000):
IM_REP_EN

  • Drive NOT ready, tape IS mounted.

root@debian8:/home/ken# mt -f /dev/nst2 status
SCSI 2 tape drive:
File number=-1, block number=-1, partition=0.
Tape block size 0 bytes. Density code 0x0 (default).
Soft error count since last status=0
General status bits on (10000):
IM_REP_EN

  • Drive IS ready, but tape NOT mounted.

not possible on TSZ07 drive

  • Drive IS ready and tape IS mounted too.

root@debian8:/home/ken# mt -f /dev/nst2 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x3 (GCR (6250 bpi)).
Soft error count since last status=0
General status bits on (41810000):
BOT ONLINE D_6250 IM_REP_EN

@kensmyth kensmyth reopened this Apr 21, 2016
@kensmyth
Copy link
Author

Closed this in error

@kensmyth
Copy link
Author

Herc started with "SCSIMOUNT NO" and MVS 3.8J has been IPL'd
Drives have no tape mounted.......

HHC01603I scsimount
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
HHC01603I scsimount yes
HHC00100I Thread id 7FFA55FDF700, prio 4, name SCSI-TAPE mount monitor started
HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
HHC01603I scsimount
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC01603I scsimount
HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC01603I scsimount
HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC01603I scsimount
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
:
HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor
HHC01603I scsimount
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0

(tapes are mounted and ONLINE now)

HHC01603I scsimount
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
HHC01603I scsimount
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
HHC01603I scsimount
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0

@Fish-Git Fish-Git self-assigned this Apr 22, 2016
Fish-Git added a commit that referenced this issue May 1, 2016
New option "--online" to test GMT_ONLINE bit for SCSI tape mounts. Also new "-d" (debug) option to enable display of status bits during open process. Refer to updated documentation for further details.

This hopefully closes issue #97.
@Fish-Git
Copy link
Contributor

Fish-Git commented May 1, 2016

@kensmyth: Commit a68c119 (scsitape enhancements to fix for issue #97) should hopefully resolve this issue without impacting existing behavior for others. Please give it a try and let me know:

  1. Whether it resolves your problem.
  2. If it doesn't, whether it makes matters better or worse.

(Note: if it doesn't then please re-open this issue.)

Briefly, in order for this change to address your problem you need to add a new driver option to your Hercules configuration file device statement called --online, e.g.:

0480 3420 /dev/nst2 --online -d     #SCSI DEC TSZ07 9-track
0481 3420 /dev/nst1 --online -d     #SCSI STK 9840 emul 3490
0482 3420 /dev/nst0 --online -d     #SCSI STK 9840 emul 3490

The -d option enables debugging logic that will display the tape status flags during the open process. Once you are satisfied that everything is working correct you may remove it. It's not needed. Only the --online option is significant for you.

For more information please refer to the updated configuration file documentation for tape drives.

Thanks.

@Fish-Git Fish-Git closed this as completed May 1, 2016
srorso pushed a commit to srorso/hyperion that referenced this issue May 4, 2016
New option "--online" to test GMT_ONLINE bit for SCSI tape mounts. Also new "-d" (debug) option to enable display of status bits during open process. Refer to updated documentation for further details.

This hopefully closes issue hercules-390#97.
@kensmyth
Copy link
Author

kensmyth commented May 4, 2016

Built the modified version but hit another problem. SCSI errors HHC000205E are gone, but now seeing type scsi: error in function read_tape(): Invalid argument. Please see below:
 
(status of tape drives from linux before starting Herc)

root@debian8:/home/ken/hyp/hyperion-master# mt -f /dev/nst0 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x42 (LTO-2).
Soft error count since last status=0
General status bits on (41010000):
 BOT ONLINE IM_REP_EN

root@debian8:/home/ken/hyp/hyperion-master# mt -f /dev/nst1 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x42 (LTO-2).
Soft error count since last status=0
General status bits on (41010000):
 BOT ONLINE IM_REP_EN

root@debian8:/home/ken/hyp/hyperion-master# mt -f /dev/nst2 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 0 bytes. Density code 0x3 (GCR (6250 bpi)).
Soft error count since last status=0
General status bits on (41810000):
 BOT ONLINE D_6250 IM_REP_EN
root@debian8:/home/ken/hyp/hyperion-master#

(start Hercules)

root@debian8:/home/ken/hyp/hyperion-master# ./hercules -f config1
HHC01413I Hercules version 4.0
HHC01414I (C) Copyright 1999-2015 by Roger Bowler, Jan Jaeger, and others
HHC01415I Build date: May  3 2016 at 13:44:54
HHC01417I Built with: GCC 4.9.2
HHC01417I Build type: GNU/Linux x86_64 host architecture build
HHC01417I Modes: S/370 ESA/390 z/Arch
HHC01417I Max CPU Engines: 8
HHC01417I Using   setresuid() for setting privileges
HHC01417I Using   POSIX threads Threading Model
HHC01417I Using   Error-Checking Mutex Locking Model
HHC01417I With    Syncio support
HHC01417I With    Shared Devices support
HHC01417I With    Dynamic loading support
HHC01417I Using   shared libraries
HHC01417I With    External GUI support
HHC01417I With    IPV6 support
HHC01417I With    HTTP Server support
HHC01417I With    sqrtl support
HHC01417I With    SIGABEND handler
HHC01417I Without CCKD BZIP2 support
HHC01417I Without HET BZIP2 support
HHC01417I With    ZLIB support
HHC01417I With    Regular Expressions support
HHC01417I Without Object REXX support
HHC01417I Without Regina REXX support
HHC01417I With    Automatic Operator support
HHC01417I Without National Language Support
HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 hatomics=C11
HHC01417I Running on: debian8 (Linux-3.16.0-4-amd64 x86_64) MP=4
HHC01508I HDL: loadable module directory is /usr/local/lib/hercules
HHC00100I Thread id 00007f8d7e808700, prio 15, name Processor CP00 started
HHC00811I Processor CP00: architecture mode z/Arch
HHC00100I Thread id 00007f8d7e707700, prio -20, name Timer started
HHC02204I cpuserial      set to 000611
HHC02204I cpumodel       set to 3033
HHC17003I MAIN     storage is 16M (mainsize); storage is not locked
HHC17003I EXPANDED storage is 0 (xpndsize); storage is not locked
HHC02204I port           set to port=8038 noauth
HHC01801E HTTP server: invalid root directory: HTTP/: No such file or directory
HHC02204I root           set to HTTP/
HHC01807I HTTP server signaled to start
HHC02204I numcpu         set to 1
HHC02204I maxcpu         set to 1
HHC02204I tzoffset       set to -0500
HHC00811I Processor CP00: architecture mode S/370
HHC02204I archmode       set to S/370
HHC00100I Thread id 00007f8d7ea0b700, prio  4, name HTTP server started
HHC01801E HTTP server: invalid root directory: HTTP/: No such file or directory
HHC02204I scsimount      set to YES
HHC00101I Thread id 00007f8d7ea0b700, prio  4, name HTTP server ended
HHC01200E 0:000C Card: error in function access(): No such file or directory
HHC01463E 0:000C device initialization failed
HHC00221I 0:0480 Tape file /dev/nst2, type scsi: format type SCSI attached tape drive
HHC00222I 0:0480 Tape file /dev/nst2, type scsi: option --online accepted
HHC00222I 0:0480 Tape file /dev/nst2, type scsi: option -d accepted
HHC00100I Thread id 00007f8d7ea0b700, prio 2147483647, name SCSI-TAPE mount monitor started
HHC00221I 0:0481 Tape file /dev/nst1, type scsi: format type SCSI attached tape drive
HHC00222I 0:0481 Tape file /dev/nst1, type scsi: option --online accepted
HHC00222I 0:0481 Tape file /dev/nst1, type scsi: option -d accepted
HHC00221I 0:0482 Tape file /dev/nst0, type scsi: format type SCSI attached tape drive
HHC00222I 0:0482 Tape file /dev/nst0, type scsi: option --online accepted
HHC00222I 0:0482 Tape file /dev/nst0, type scsi: option -d accepted
HHC00100I Thread id 00007f8d7e90a700, prio  4, name Console connection started
HHC01024I Waiting for console connections on port 3270
HHC00414I 0:0152 CKD file dasd/hasp00.152: cyls 411 heads 19 tracks 7809 trklen 13312
:
HHC00414I 0:0190 CKD file dasd/work03.190: cyls 1114 heads 15 tracks 16710 trklen 56832
HHC00100I Thread id 00007f8d81a69700, prio  0, name Control panel started
:
HHC01603I scsimount
HHC02203I scsimount     : 5
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
/15.06.15           LGN001I TSO logon in progress at VTAM terminal CUU0C0
/15.06.17 TSU   41  $HASP100 HERC01   ON TSOINRDR
/15.06.17 TSU   41  $HASP373 HERC01   STARTED 
/15.06.17 TSU   41  IEF125I HERC01 - LOGGED ON - TIME=15.06.17
/15.06.50 JOB   80  $HASP100 HERC01TT ON INTRDR
/15.06.50 JOB   80  $HASP373 HERC01TT STARTED - INIT  1 - CLASS A - SYS TK4-
/15.06.50 JOB   80  IEF403I HERC01TT - STARTED - TIME=15.06.50  

(job HERC01TT wants to allocate drives 481 & 482)

HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function read_tape(): Invalid argument 
/15.06.50 JOB   80  IEF503I INCORRECT VOLUME LABEL OR I/O ERROR 
/15.06.50 JOB   80  IEF234E D 480 

(drive 480 get checked and tape dismounted, 480 is not assigned by job HERC01TT ?)

HHC01603I scsimount 
HHC02203I scsimount     : 5
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0 
HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function read_tape(): Invalid argument                                           
/15.07.07 JOB   80  IEF503I INCORRECT VOLUME LABEL OR I/O ERROR 
/15.07.07 JOB   80  IEF234E D 481
HHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function read_tape(): Invalid argument
/15.07.15 JOB   80  IEF503I INCORRECT VOLUME LABEL OR I/O ERROR
/15.07.15 JOB   80  IEF234E D 482
/15.07.21 JOB   80 *IEC501A M 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE  

(MVS tries to check the tape labels and decides they are not correct (probably b/c scsi read error, then dismounts them))

HHC01603I scsimount    
HHC02203I scsimount     : 5   
HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0  

(after tapes are reloaded and ready)

HHC92702D Tape /dev/nst2: finish_scsitape_open mt_gstat 0x41810000 BOT ONLINE D_6250 IM_REP_EN
HHC92702D Tape /dev/nst1: finish_scsitape_open mt_gstat 0x41010000 BOT ONLINE IM_REP_EN
HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function read_tape(): Invalid argument
/15.08.54 JOB   80  IEC512I LBL ERR 481,      ,NL,SL0690,SL,HERC01TT,GENERATE
/15.08.56 JOB   80 *IEC704A L 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE
/15.08.56 JOB   80 *00 IEC704A REPLY 'VOLSER,OWNER INFORMATION','M'OR'U'
HHC92702D Tape /dev/nst0: finish_scsitape_open mt_gstat 0x41010000 BOT ONLINE IM_REP_EN  

(nothing else happens)

HHC01603I scsimount 
HHC02203I scsimount     : 5 
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
HHC01603I stop                                                                                                                             
HHC00834I Processor CP00: manual state selected                                                                                            
herc =====>                            

(JCL for the job HERC01TT that was running, this normally runs to completion on older Herc 4.00 after timeouts with SCSI errors HHC00205E )

000001 //HERC01TT JOB 'TAPE TEST',CLASS=A,MSGCLASS=X,NOTIFY=HERC01,
000002 // REGION=6M,TIME=1440
000003 //*
000004 //GENERATE EXEC PGM=IEBDG
000005 //SYSPRINT DD SYSOUT=*
000006 //OUTDS DD DISP=(NEW,PASS),DSN=&&TEMP00,
000007 // VOL=SER=SL0690,UNIT=(481,,DEFER),
000008 // DCB=(RECFM=FB,LRECL=256,BLKSIZE=25600)
000009 //SYSIN DD *
000010 DSD OUTPUT=(OUTDS)
000011 FD NAME=FIELD1,LENGTH=256,FORMAT=RA
000012 CREATE QUANTITY=1234567,NAME=(FIELD1)
000013 END
000014 //*
000015 //TAPECOPY EXEC PGM=IEBGENER
000016 //SYSIN DD DUMMY
000017 //SYSPRINT DD SYSOUT=*
000018 //SYSUT1 DD DISP=(OLD,PASS),DSN=&&TEMP00,
000019 // VOL=SER=SL0690,UNIT=481
000020 //SYSUT2 DD DISP=(NEW,PASS),DSN=&&TEMP01,
000021 // VOL=SER=SL0691,UNIT=482
000022 //*
000023 //COMPARE EXEC PGM=IEBCOMPR
000024 //SYSIN DD DUMMY
000025 //SYSPRINT DD SYSOUT=*
000026 //SYSUT1 DD DISP=(OLD,DELETE),DSN=&&TEMP00,
000027 // VOL=SER=SL0690,UNIT=481
000028 //SYSUT2 DD DISP=(OLD,DELETE),DSN=&&TEMP01,
000029 // VOL=SER=SL0691,UNIT=482
000030 //                                                             

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants