This is related to the fix applied for SCSI error HHC00205E for each SCSI drive #97

Built the modified version but hit another problem. The SCSI errors HHC00205E 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#

(Hercules log):

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 gets checked and tape dismounted but 480 is not requested 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

(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 //

(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 gets checked and tape dismounted but 480 is not requested by job HERC01TT !?)

Your guest was likely attempting to read the VOL1 label to find the right drive (or to remember which drive had which volser mounted on it).

[...]

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

Which causes auto-scsimount to kick in, as we can see:

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)

/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'

I think I might have seen this before, but I'll have to check. I think my former client experienced the same thing (or something very similar) when he'd submit JCL to try and initialize a brand new tape (with absolutely no data on it yet, i.e. a "blank" tape).

As I recall the problem was his JCL wasn't quite right thereby causing his guest (z/OS) to try and read the VOL1 label (which is what's happening with you). As I recall we just needed to make a small change to his JCL so that it didn't do that. So that it instead simply went straight to the "Are you sure this is the correct tape/drive? Reply with <whatever> to proceed or <something else> to cancel" message.

(I'll have to look around my system to see if I can find my notes. Hopefully I still have them.)

In the mean time please do the following:

Answer for me please, are these brand new "blank" tapes with no data on them? Or are they old tapes known to have valid data? (specifically, known to be Standard Labeled with a VOL1 label, etc?)
Please try your test again, but this time enable CCW tracing on all drives:

t+480 t+481 t+482

Then post the results here. I'm hoping the CCW traces might provide some additional clues. In the mean time I'll try looking for my notes regarding the proper JCL to use.

BTW, what guest are you using? An older MVS? Or a modern z/OS?

Yes, the O/S is MVS3.8J "tk4", and yes, the tapes have the correct internal labels.

In fact, this exact batch job will run on "Hercules version 4.00 Built on Feb 5 2015 at 16:48:19", but it hits the original problem reported in issue #97 (SCSI error HHC00205E for each SCSI drive). The job does eventually complete though. Here are the details:

Status of tape drives before Hercules is started:

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=-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

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 00007f7b950a0700, prio 15, name Processor CP00 started
HHC00811I Processor CP00: architecture mode z/Arch
HHC00100I Thread id 00007f7b94f9f700, 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 00007f7b952a3700, prio  4, name HTTP server started
HHC02204I scsimount      set to YES
HHC01801E HTTP server: invalid root directory: HTTP/: No such file or directory
HHC00101I Thread id 00007f7b952a3700, 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 00007f7b952a3700, 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 00007f7b951a2700, prio  4, name Console connection started
HHC01024I Waiting for console connections on port 3270
HHC00100I Thread id 00007fdd8027a700, prio 2147483647, name SCSI-TAPE status monitor started
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
HHC02204I log newlogfile

13:42:35 HHC01603I logopt time
13:42:35 HHC02204I logopt         set to TIMESTAMP
13:42:52 HHC01603I t+480
13:42:52 HHC02204I CCW trace for 0:0480 set to on
13:42:55 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:42:57 HHC01603I t+481
13:42:57 HHC02204I CCW trace for 0:0481 set to on
13:43:01 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:01 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:01 HHC01603I t+482
13:43:01 HHC02204I CCW trace for 0:0482 set to on
13:43:06 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:06 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:07 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:12 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:12 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:12 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:17 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:17 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:18 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:19 HHC01603I ipl 148
:13:43:19 HHC00107I Starting thread cckd_ra(), active=0, started=0, max=2
13:43:19 HHC00100I Thread id 00007f7b8effb700, prio  8, name Read-ahead thread-1 started
13:43:19 HHC00107I Starting thread cckd_ra() from cckd_ra(), active=1, started=1, max=2
13:43:19 HHC00100I Thread id 00007f7b8eefa700, prio  8, name Read-ahead thread-2 started
13:43:20 HHC01315I 0:0480 CHAN: ccw 03000000 20000001
13:43:20 HHC01312I 0:0480 CHAN: stat 0200, count 0001
13:43:20 HHC01313I 0:0480 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:43:20 HHC01314I 0:0480 CHAN: sense INTREQ EOC WRI
13:43:20 HHC01316I 0:0480 CHAN: csw 00, stat 0200, count 0001, ccw 1EA3C0
13:43:20 HHC01315I 0:0480 CHAN: ccw 04FF4390 20000018
13:43:20 HHC01320I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation started
13:43:20 HHC01321I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:43:20 HHC01315I 0:0480 CHAN: ccw 04FF4390 20000018
13:43:20 HHC01312I 0:0480 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:43:20 HHC01316I 0:0480 CHAN: csw 00, stat 0C00, count 0000, ccw 00D9F0
13:43:20 HHC01315I 0:0481 CHAN: ccw 03000000 20000001
13:43:20 HHC01312I 0:0481 CHAN: stat 0200, count 0001
13:43:20 HHC01313I 0:0481 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:43:20 HHC01314I 0:0481 CHAN: sense INTREQ EOC WRI
13:43:20 HHC01316I 0:0481 CHAN: csw 00, stat 0200, count 0001, ccw 1EA3C0
13:43:20 HHC01315I 0:0481 CHAN: ccw 04FF4390 20000018
13:43:20 HHC01320I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation started
13:43:20 HHC01321I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:43:20 HHC01315I 0:0481 CHAN: ccw 04FF4390 20000018
13:43:20 HHC01312I 0:0481 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:43:20 HHC01316I 0:0481 CHAN: csw 00, stat 0C00, count 0000, ccw 00DA08
13:43:20 HHC01315I 0:0482 CHAN: ccw 03000000 20000001
13:43:20 HHC01312I 0:0482 CHAN: stat 0200, count 0001
13:43:20 HHC01313I 0:0482 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:43:20 HHC01314I 0:0482 CHAN: sense INTREQ EOC WRI
13:43:20 HHC01316I 0:0482 CHAN: csw 00, stat 0200, count 0001, ccw 1EA3C0
13:43:20 HHC01315I 0:0482 CHAN: ccw 04FF4390 20000018
13:43:20 HHC01320I 0:0482 CHAN: start I/O S/370 conversion to asynchronous operation started
13:43:20 HHC01321I 0:0482 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:43:20 HHC01315I 0:0482 CHAN: ccw 04FF4390 20000018
13:43:20 HHC01312I 0:0482 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:43:20 HHC01316I 0:0482 CHAN: csw 00, stat 0C00, count 0000, ccw 00DA20
13:43:20 /IEA101A SPECIFY SYSTEM PARAMETERS FOR RELEASE 03.8 .VS2

The status for 480 and 481 is not correct. They are online with a tape mounted. Only 482 is not online:

13:43:20 HHC00010A Enter input for console 0:0009
13:43:23 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:23 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:23 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:28 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:28 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:29 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:34 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:34 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:34 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:39 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:43:39 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:43:40 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:07 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:44:07 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:07 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:08 HHC01315I 0:0480 CHAN: ccw 03FF9911 30000001
13:44:08 HHC01312I 0:0480 CHAN: stat 0200, count 0001
13:44:08 HHC01313I 0:0480 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:44:08 HHC01314I 0:0480 CHAN: sense INTREQ EOC WRI
13:44:08 HHC01316I 0:0480 CHAN: csw 00, stat 0200, count 0001, ccw FF9918
13:44:08 HHC01315I 0:0480 CHAN: ccw 04FF4588 20000018
13:44:08 HHC01320I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation started
13:44:08 HHC01321I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:44:08 HHC01315I 0:0480 CHAN: ccw 04FF4588 20000018
13:44:08 HHC01312I 0:0480 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:44:08 HHC01316I 0:0480 CHAN: csw 00, stat 0C00, count 0000, ccw 00D9F0
13:44:12 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:44:12 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:13 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:18 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:44:18 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:18 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:34 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:44:35 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:44:35 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:24 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:45:24 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:24 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:29 /v 480-482,online
13:45:29 HHC01315I 0:0481 CHAN: ccw 03FE3AC1 30000001
13:45:29 HHC01312I 0:0481 CHAN: stat 0200, count 0001
13:45:29 HHC01313I 0:0481 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:45:29 HHC01314I 0:0481 CHAN: sense INTREQ EOC WRI
13:45:29 HHC01316I 0:0481 CHAN: csw 00, stat 0200, count 0001, ccw FDBAC8
13:45:29 HHC01315I 0:0481 CHAN: ccw 04FF42E8 20000018
13:45:29 HHC01320I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation started
13:45:29 HHC01321I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:45:29 HHC01315I 0:0481 CHAN: ccw 04FF42E8 20000018
13:45:29 HHC01312I 0:0481 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:45:29 HHC01316I 0:0481 CHAN: csw 00, stat 0C00, count 0000, ccw 00DA08
13:45:29 HHC01315I 0:0482 CHAN: ccw 03FE3AC1 30000001
13:45:29 HHC01312I 0:0482 CHAN: stat 0200, count 0001
13:45:29 HHC01313I 0:0482 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:45:29 HHC01314I 0:0482 CHAN: sense INTREQ EOC WRI
13:45:29 HHC01316I 0:0482 CHAN: csw 00, stat 0200, count 0001, ccw FDBAC8
13:45:29 HHC01315I 0:0482 CHAN: ccw 04FF42E8 20000018
13:45:29 HHC01320I 0:0482 CHAN: start I/O S/370 conversion to asynchronous operation started
13:45:29 HHC01321I 0:0482 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:45:29 HHC01315I 0:0482 CHAN: ccw 04FF42E8 20000018
13:45:29 HHC01312I 0:0482 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:45:29 HHC01316I 0:0482 CHAN: csw 00, stat 0C00, count 0000, ccw 00DA20
13:45:29 /13.45.29           IEE450I 13.45.29 UNIT STATUS 460
13:45:29 / UNIT TYPE STATUS  VOLSER VOLSTATE   UNIT TYPE STATUS  VOLSER VOLSTATE
13:45:29 / 480  3400 O                  /REMOV 481  3400 O                  /REMOV
13:45:29 / 482  3400 O                  /REMOV
13:45:29 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:45:30 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:30 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:40 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:45:41 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:41 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:51 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:45:52 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:52 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:57 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:45:57 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:45:57 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:02 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:03 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:03 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:08 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:08 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:08 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:11 /13.46.11           LGN001I TSO logon in progress at VTAM terminal CUU0C0
13:46:14 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:14 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:14 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:15 /13.46.14 TSU   45  $HASP100 HERC01   ON TSOINRDR
13:46:15 /13.46.14 TSU   45  $HASP373 HERC01   STARTED
13:46:15 /13.46.14 TSU   45  IEF125I HERC01 - LOGGED ON - TIME=13.46.14
13:46:19 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:19 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:20 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:25 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:25 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:25 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:26 HHC01603I scsimount
13:46:26 HHC02203I scsimount     : 5
13:46:26 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status closed, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:26 HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
13:46:26 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status closed, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:26 HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
13:46:26 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status closed, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:26 HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
13:46:30 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:30 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:31 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:58 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:46:58 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:46:58 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:47:03 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE

Batch job HERC01TT starting:

13:47:03 /13.47.03 JOB   84  $HASP100 HERC01TT ON INTRDR
13:47:03 /13.47.03 JOB   84  $HASP373 HERC01TT STARTED - INIT  1 - CLASS A - SYS TK4-
13:47:03 /13.47.03 JOB   84  IEF403I HERC01TT - STARTED - TIME=13.47.03
13:47:03 HHC01315I 0:0480 CHAN: ccw 03048DA0 70000001
13:47:03 HHC01312I 0:0480 CHAN: stat 0200, count 0001
13:47:03 HHC01313I 0:0480 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:47:03 HHC01314I 0:0480 CHAN: sense INTREQ EOC WRI
13:47:03 HHC01316I 0:0480 CHAN: csw 10, stat 0200, count 0001, ccw 00D9F0
13:47:03 HHC01315I 0:0480 CHAN: ccw 04FF4438 20000018
13:47:03 HHC01320I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation started
13:47:03 HHC01321I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:47:03 HHC01315I 0:0480 CHAN: ccw 04FF4438 20000018
13:47:03 HHC01312I 0:0480 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:47:03 HHC01316I 0:0480 CHAN: csw 00, stat 0C00, count 0000, ccw 00D9F0
13:47:03 HHC01315I 0:0481 CHAN: ccw 03048DA0 70000001
13:47:03 HHC01312I 0:0481 CHAN: stat 0200, count 0001
13:47:03 HHC01313I 0:0481 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:47:03 HHC01314I 0:0481 CHAN: sense INTREQ EOC WRI
13:47:03 HHC01316I 0:0481 CHAN: csw 10, stat 0200, count 0001, ccw 00DA08
13:47:03 HHC01315I 0:0481 CHAN: ccw 04FF4A20 20000018
13:47:03 HHC01320I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation started
13:47:03 HHC01321I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:47:03 HHC01315I 0:0481 CHAN: ccw 04FF4A20 20000018
13:47:03 HHC01312I 0:0481 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:47:03 HHC01316I 0:0481 CHAN: csw 00, stat 0C00, count 0000, ccw 00DA08
13:47:03 HHC01315I 0:0482 CHAN: ccw 03048DA0 70000001
13:47:03 HHC01312I 0:0482 CHAN: stat 0200, count 0001
13:47:03 HHC01313I 0:0482 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:47:03 HHC01314I 0:0482 CHAN: sense INTREQ EOC WRI
13:47:03 HHC01316I 0:0482 CHAN: csw 10, stat 0200, count 0001, ccw 00DA20
13:47:03 HHC01315I 0:0482 CHAN: ccw 04FF40F0 20000018
13:47:03 HHC01320I 0:0482 CHAN: start I/O S/370 conversion to asynchronous operation started
13:47:03 HHC01321I 0:0482 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:47:03 HHC01315I 0:0482 CHAN: ccw 04FF40F0 20000018
13:47:03 HHC01312I 0:0482 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
13:47:03 HHC01316I 0:0482 CHAN: csw 00, stat 0C00, count 0000, ccw 00DA20

Job HERC01TT wants tape on 481. It is mounted and ready, but not seen BY MVS:

13:47:03 /13.47.03 JOB   84 *IEC501A M 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE
13:47:03 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:47:04 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:47:09 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:47:09 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:47:09 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:31 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:48:32 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:32 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:36 HHC01603I scsimount
13:48:36 HHC02203I scsimount     : 5
13:48:36 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status closed, sstat 0x00010000: OFF-LINE NO-TAPE
13:48:36 HHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2
13:48:36 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status closed, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:36 HHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1
13:48:36 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status closed, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:36 HHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0
13:48:37 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:48:37 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:37 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:42 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: OFF-LINE NO-TAPE
13:48:43 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:43 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE

Nothing happens until drive 480 is made ready (online button pushed). Then:

13:48:48 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x41810000: ON-LINE READY LOAD-POINT
13:48:49 HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x41810000: ON-LINE READY LOAD-POINT
13:48:49 HHC92702D Tape /dev/nst2: finish_scsitape_open mt_gstat 0x41810000 BOT ONLINE D_6250 IM_REP_EN
13:48:49 HHC01305I 0:0480 CHAN: attention
13:48:49 HHC01316I 0:0480 CHAN: csw 00, stat 0400, count 0000, ccw 000000
13:48:49 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:49 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:54 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x41010000: ON-LINE READY LOAD-POINT
13:48:55 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x41010000: ON-LINE READY LOAD-POINT
13:48:55 HHC92702D Tape /dev/nst1: finish_scsitape_open mt_gstat 0x41010000 BOT ONLINE IM_REP_EN
13:48:55 HHC01305I 0:0481 CHAN: attention
13:48:55 HHC01316I 0:0481 CHAN: csw 00, stat 0400, count 0000, ccw 000000
13:48:55 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:55 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:55 HHC01315I 0:0481 CHAN: ccw 08FF40F8 00000000
13:48:55 HHC01315I 0:0481 CHAN: ccw 07000000 20400050
13:48:55 HHC01312I 0:0481 CHAN: stat 0C00, count 0050
13:48:55 HHC01316I 0:0481 CHAN: csw 00, stat 0C00, count 0050, ccw FF4100
13:48:55 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:55 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:55 HHC01315I 0:0481 CHAN: ccw 08FF4A28 00000000
13:48:55 HHC01315I 0:0481 CHAN: ccw 0269DAF8 00000050

Then the outstanding MOUNT message is satisfied, and MVS tries to read the tape label, but it looks like there is a malformed SCSI read command so the label is not read into memory, resulting in the MVS LBL ERR 481 message and things go south from there:

13:48:55 HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function read_tape(): Invalid argument
13:48:56 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:48:57 HHC00243W 0:0481 Tape status retrieval timeout
13:48:57 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x41010000: ON-LINE READY LOAD-POINT
13:48:57 HHC01312I 0:0481 CHAN: stat 0E40, count 0050=>00000000 00000008 00000000 00000610 ................
13:48:57 HHC01313I 0:0481 CHAN: sense 084800C0 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000
13:48:57 HHC01314I 0:0481 CHAN: sense DCK ITF NRF
13:48:57 HHC01316I 0:0481 CHAN: csw 50, stat 0E40, count 0050, ccw FF4A30
13:48:57 HHC01315I 0:0481 CHAN: ccw 04FF4588 20000018
13:48:57 HHC01320I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation started
13:48:57 HHC01321I 0:0481 CHAN: start I/O S/370 conversion to asynchronous operation successful
13:48:57 HHC01315I 0:0481 CHAN: ccw 04FF4588 20000018
13:48:57 HHC01312I 0:0481 CHAN: stat 0C00, count 0000=>084800C0 00C00300 00000000 00800100 ...{.{..........
13:48:57 HHC01316I 0:0481 CHAN: csw 00, stat 0C00, count 0000, ccw 00DA08
13:48:57 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:57 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:57 HHC01315I 0:0481 CHAN: ccw 08FF40F8 00000000
13:48:57 HHC01315I 0:0481 CHAN: ccw 03000000 20400001
13:48:57 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:57 HHC01316I 0:0481 CHAN: csw 50, stat 0C00, count 0001, ccw FF4100

MVS is complaining the tape has a bad label, but that is not true:

13:48:57 /13.48.57 JOB   84  IEC512I LBL ERR 481,      ,NL,SL0690,SL,HERC01TT,GENERATE
13:48:57 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:57 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:57 HHC01315I 0:0481 CHAN: ccw 08FF40F8 00000000
13:48:57 HHC01315I 0:0481 CHAN: ccw 0469DC80 20000018
13:48:58 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x41010000: ON-LINE READY LOAD-POINT
13:48:58 HHC01312I 0:0481 CHAN: stat 0C00, count 0000=>00480000 00C00300 00000000 00800100 .....{..........
13:48:58 HHC01316I 0:0481 CHAN: csw 50, stat 0C00, count 0000, ccw FF4100
13:48:58 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:58 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:58 HHC01315I 0:0481 CHAN: ccw 08FF4440 00000000
13:48:58 HHC01315I 0:0481 CHAN: ccw 37000000 20400050
13:48:58 HHC01312I 0:0481 CHAN: stat 0C00, count 0050
13:48:58 HHC01316I 0:0481 CHAN: csw 50, stat 0C00, count 0050, ccw FF4448
13:48:58 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:58 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:58 HHC01315I 0:0481 CHAN: ccw 08FF4590 00000000
13:48:58 HHC01315I 0:0481 CHAN: ccw 03000000 20400001
13:48:58 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:58 HHC01316I 0:0481 CHAN: csw 50, stat 0C00, count 0001, ccw FF4598
13:48:58 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:58 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:58 HHC01315I 0:0481 CHAN: ccw 08FF48D8 00000000
13:48:58 HHC01315I 0:0481 CHAN: ccw 0469DC80 20000018
13:48:59 HHC00211I 0:0481 Tape file /dev/nst1, type scsi status opened, sstat 0x01010000: ON-LINE READY
13:48:59 HHC01312I 0:0481 CHAN: stat 0C00, count 0000=>00400000 00C00300 00000000 00800100 . ...{..........
13:48:59 HHC01316I 0:0481 CHAN: csw 50, stat 0C00, count 0000, ccw FF48E0
13:48:59 HHC01315I 0:0481 CHAN: ccw D3048DA0 70000001
13:48:59 HHC01312I 0:0481 CHAN: stat 0C00, count 0001
13:48:59 HHC01315I 0:0481 CHAN: ccw 08FF40F8 00000000
13:48:59 HHC01315I 0:0481 CHAN: ccw 07000000 20400050
13:48:59 HHC01312I 0:0481 CHAN: stat 0C00, count 0050
13:48:59 HHC01316I 0:0481 CHAN: csw 50, stat 0C00, count 0050, ccw FF4100

MVS asks if we want to write new labels. We don't want to do that:

13:48:59 /13.48.59 JOB   84 *IEC704A L 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE
13:48:59 /13.48.59 JOB   84 *00 IEC704A REPLY 'VOLSER,OWNER INFORMATION','M'OR'U'

incidentally, the tape on 482 continues to be mounted and online, but notice the status seems to be changing:

13:49:01 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x00040000: OFF-LINE NO-TAPE
13:49:06 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x41010000: ON-LINE READY LOAD-POINT
13:49:07 HHC00211I 0:0482 Tape file /dev/nst0, type scsi status opened, sstat 0x41010000: ON-LINE READY LOAD-POINT
13:49:07 HHC92702D Tape /dev/nst0: finish_scsitape_open mt_gstat 0x41010000 BOT ONLINE IM_REP_EN
13:49:07 HHC01305I 0:0482 CHAN: attention
13:49:07 HHC01316I 0:0482 CHAN: csw 00, stat 0400, count 0000, ccw 000000
13:49:22 HHC01603I scsimount
13:49:22 HHC02203I scsimount     : 5
13:49:22 HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2
13:49:22 HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1
13:49:22 HHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0
13:49:33 HHC01603I stop
13:49:33 HHC00834I Processor CP00: manual state selected
root@debian8:/home/ken/hyp/hyperion-master#

FYI: temporarily busy with something else. Will review your new test results and report back as soon as I am able. Patience please. Thanks!

No problem, thank you.

@kensmyth: I'm seeing a potential problem that might explain the HHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function read_tape(): Invalid argument error you are experiencing, but I'm not sure.

Would you do me a favor please and perform the following quick test on each of your tape drives and post the results.

Starting with each tape drive in the mounted and ready/online state:

mt  -f /dev/nstx  status
mt  -f /dev/nstx  rew
dd  if=/dev/nstx  conv=ascii  ibs=65535
mt  -f /dev/nstx  rew
dd  if=/dev/nstx  conv=ascii  ibs=2m
mt  -f /dev/nstx  rew

(where 'x' is of course 0, 1 or 2)

Thanks!

p.s. It might not hurt to try other ibs= values as well, such as 128k, 256k, etc. Thanks!

dd conv=ascii uses an ancient and utterly useless translation. ymmv.

dd conv=ascii uses an ancient and utterly useless translation. ymmv.

What do you suggest then? I don't want dd output dumped to the console (terminal session) in its raw form! And I'm purposely avoiding piping the output into some other program too, since I want to be certain whatever error message(s) might be issued is related to the dd command itself.

But since I'm not a Nix person I admit I may be doing things the wrong way, so PLEASE, by all means, advise me! Provide me with some advice regarding what command/options I should be using! Thanks!

@jphartmann: FYI I got my information from the following IBM web page:

Reading tape labels using device driver tools

so you might want to let them know about it too. ;-)

You did well, Fish.

For a simple command, dd is the only game in town. There is tr, which does transliterations, but I'd be hard pressed to offer a simple command. There is the iconv stuff, but that is heavy going too.

For simple 7-bit ASCII in the US dd might be adequate.

Gents, I'm sure tape labels are not the problem here.

root@debian8:/home/ken/hyp# mt -f /dev/nst0 rewind
root@debian8:/home/ken/hyp# mt -f /dev/nst1 rewind

root@debian8:/home/ken/hyp# 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# 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# dd if=/dev/nst0 of=nst0
0+3 records in
0+1 records out
240 bytes (240 B) copied, 0.644078 s, 0.4 kB/s

root@debian8:/home/ken/hyp# dd if=/dev/nst1 of=nst1
0+3 records in
0+1 records out
240 bytes (240 B) copied, 0.642025 s, 0.4 kB/s

The linux "dd" cmd, it will read in everything up to the 1st tapemark and cram it into a single file on disk. That's what happened here, the three existing tape labels, VOL1/HDR1/HDR2 are concatenated into a single linux file. These 2 tapes were previously used successfully with the HERC01TT job shown, that's what they have good labels.

Here are the dd files on disk, 240 bytes, (3) 80 byte labels VOL1, HDR1 and HDR2 in ebcdic:

root@debian8:/home/ken/hyp# ls -l
-rw-r--r--  1 root root     240 May 15 09:23 nst0
-rw-r--r--  1 root root     240 May 15 09:23 nst1
root@debian8:/home/ken/hyp# 

root@debian8:/home/ken/hyp# xxd -E nst0
0000000: e5d6 d3f1 e2d3 f0f6 f9f1 f040 4040 4040  VOL1SL06910     
0000010: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000020: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000030: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000040: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000050: c8c4 d9f1 f04b c8c5 d9c3 f0f1 e3e3 4be3  HDR10.HERC01TT.T
0000060: c5d4 d7f0 f1e2 d3f0 f6f9 f1f0 f0f0 f1f0  EMP01SL069100010
0000070: f0f0 f140 4040 4040 4040 f1f6 f1f2 f540  001       16125 
0000080: f0f0 f0f0 f0f0 f0f0 f0f0 f0f0 c9c2 d440  000000000000IBM 
0000090: d6e2 61e5 e240 f3f7 f040 4040 4040 4040  OS/VS 370       
00000a0: c8c4 d9f2 c6f2 f5f6 f0f0 f0f0 f2f5 f6f4  HDR2F25600002564
00000b0: f0c8 c5d9 c3f0 f1e3 e361 e3c1 d7c5 c3d6  0HERC01TT/TAPECO
00000c0: d7e8 4040 4040 c240 4040 f3f0 f0f0 f140  PY    B   30001 
00000d0: 4040 4040 4040 4040 4040 4040 4040 4040                  
00000e0: 4040 4040 4040 4040 4040 4040 4040 4040                  
root@debian8:/home/ken/hyp# 

root@debian8:/home/ken/hyp# xxd -E nst1
0000000: e5d6 d3f1 e2d3 f0f6 f9f0 f040 4040 4040  VOL1SL06900     
0000010: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000020: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000030: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000040: 4040 4040 4040 4040 4040 4040 4040 4040                  
0000050: c8c4 d9f1 f04b c8c5 d9c3 f0f1 e3e3 4be3  HDR10.HERC01TT.T
0000060: c5d4 d7f0 f0e2 d3f0 f6f9 f0f0 f0f0 f1f0  EMP00SL069000010
0000070: f0f0 f140 4040 4040 4040 f1f6 f1f2 f540  001       16125 
0000080: f0f0 f0f0 f0f0 f0f0 f0f0 f0f0 c9c2 d440  000000000000IBM 
0000090: d6e2 61e5 e240 f3f7 f040 4040 4040 4040  OS/VS 370       
00000a0: c8c4 d9f2 c6f2 f5f6 f0f0 f0f0 f2f5 f6f4  HDR2F25600002564
00000b0: f0c8 c5d9 c3f0 f1e3 e361 c7c5 d5c5 d9c1  0HERC01TT/GENERA
00000c0: e3c5 4040 4040 c240 4040 f3f0 f0f0 f140  TE    B   30001 
00000d0: 4040 4040 4040 4040 4040 4040 4040 4040                  
00000e0: 4040 4040 4040 4040 4040 4040 4040 4040                  
root@debian8:/home/ken/hyp#

@kensmyth: That's not the point, Ken.

The test I asked you to do was to determine whether or not your tape drives supported read requests for block sizes greater than 64K-1.

Please note the ibs= (input block size) argument on the dd commands I asked you to do:

mt  -f /dev/nstx  status
mt  -f /dev/nstx  rew
dd  if=/dev/nstx  conv=ascii  ibs=65535
mt  -f /dev/nstx  rew
dd  if=/dev/nstx  conv=ascii  ibs=2m
mt  -f /dev/nstx  rew

The problem you are currently experiencing is invalid argument on Hercules's read_tape command:

rc = read_tape (dev->fd, buf, MAX_BLKLEN);

and MAX_BLKLEN is currently #defined as:

#define MAX_BLKLEN     2097152 /* Maximum blocksize = 2MB   */

I'm wondering if maybe the tape drive you are trying to use might not support such large read requests.

Due to your "illogical" (for lack of a better term) tape device configuration file statements:

0480 3420 /dev/nst2 # DEC TSZ07 9-track drive via a fc/SCSI bridge 0481 3420 /dev/nst1 # StorageTek 9840 fiber channel drive emul 3490 0482 3420 /dev/nst0 # StorageTek 9840 fiber channel drive emul 3490

(where Hercules device 480 is defined to /dev/nst2 instead of the /dev/nst0 that one would expect, and device 482 defined to /dev/nst0 instead of /dev/nst2 that one would again expect), I'm left wondering whether the problem you are currently experiencing might not be due to your attempt to use the wrong tape drive, a tape drive that might not accept such large read requests, hence leading to the invalid argument error.

Please run the tests I asked so we can know for sure, and also double check your Hercules device statements to be sure they're correct. I think you may have them switched around, which might explain the unusual behavior regarding Hercules seemingly trying to access the "wrong tape drive" (when in fact it's only doing what you told it to do).

Thanks.

Yes, I know the device assignments are counter intuitive, the /dev/nstx get assigned by Linux in order of discovery and WWN. I have them assigned in Herc the way they are to match the way they are physically in the rack, left to right. Back to blksize though, no mainframe tape drives support a 2m size read/write blksize to my knowledge.

3420 9 Track, max = 32760 3480 & 3490 cartridge max = 65535 3590 cartridge max = 262,144

As far as the drives I'm dealing with here:

481 /dev/nst1 (physically 3480 using as 3420) max 262144 482 /dev/nst0 (physically 3480 using as 3420) max 262144 480 /dev/nst2 (physically 9 track open reel) max 65536 (double that of a real 3420)

Below I can set the blksize of each drive to its limit, but if I try limit+1 it is rejected with "invalid argument":

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

root@debian8:/home/ken/hyp# mt -f /dev/nst1 setblk 262144
root@debian8:/home/ken/hyp# mt -f /dev/nst1 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 262144 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# mt -f /dev/nst1 setblk 262145
/dev/nst1: Invalid argument

root@debian8:/home/ken/hyp# mt -f /dev/nst2 setblk 65536
root@debian8:/home/ken/hyp# mt -f /dev/nst2 status
SCSI 2 tape drive:
File number=0, block number=0, partition=0.
Tape block size 65536 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# 

root@debian8:/home/ken/hyp# mt -f /dev/nst2 setblk 65537
/dev/nst2: Invalid argument

Your dd test confirms the same:

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

root@debian8:/home/ken/hyp# dd if=/dev/nst0 conv=ascii ibs=65535
A–aMÝ…ì©-+]Gþ|\œË ‚ß÷ho2¢Þß»:ÏéŠ•„_5AEQˆN¹V¬˜›

root@debian8:/home/ken/hyp# dd if=/dev/nst0 conv=ascii ibs=2097152
dd: error reading  ˜/dev/nst0": Invalid argument
0+0 records in
0+0 records out
0 bytes (0 B) copied, 0.000117962 s, 0.0 kB/s

The apparent issue where 480 is being checked when not allocated to the job HERC01TT is probably a different issue which can wait, I may be able to clarify after SCSI problems are eliminated.

Thanks!

Thank you! Your report confirms my suspicion.

Now the question becomes how in the world did your original HERC01TT Tape Test job ever work?

You reported earlier:

In fact, this exact batch job will run on "Hercules version 4.00 Built on Feb 5 2015 at 16:48:19", but it hits the original problem reported in issue #97 (SCSI error HHC00205E for each SCSI drive). The job does eventually complete though.

Yet, the change that set MAX_BLKLEN to 2MB was made way back in September of 2013!, not after Feb 5 2015! (which is the version that you claim works okay)

Hence my continued confusion.

I'm not a Nix person but I'm sure there is some way to clone a specific commit of a given repository. I would personally like to see confirmation that the Feb 5 2015 version of Hyperion is able to run your HERC01TT Tape Test job to successful completion because in all honesty I can't see how it possibly could!

Now I can change (and will change) Hercules to eliminate the max block size issue to eliminate our current invalid argument problem, but even after I do that it still won't explain how in the world your HERC01TT Tape Test job managed to somehow (according to you!) run successfully with the MAX_BLKLEN bug still in place in the version you supposedly used!

Thus my desire for you to provide proof of your claim. :)

Please pull (or clone or whatever you need to do) the Feb 2015 version of Hyperion and rebuild it and try your HERC01TT job again. I'd like to see whether or not it does indeed run to successful completion.(*)

Thanks!

(*) I'm betting it won't. I'm betting that once it gets past the scsimount issue it will fail with the exact same invalid argument problem. (Unless you change something of course.)

OK, I just re-ran the job under the older version. One of the frustrating things about the original SCSI error problem (scsi: error in function ioctl_tape(MTSETBLK)) is that it doesn't seem to happen consistently.

(I started Herc with the drives ready and tapes mounted on all 3 drives, the 481 & 482 drives were "offline" to MVS when IPL'd. MVS asks for the drives and I reply to bring them online. The job then runs to completion, the first "scsi: error in function ioctl_tape(MTSETBLK)" occurs after the job finishes this time, after the tapes on 481 and 482 have rewound & unloaded)

root@debian8:/home/ken/tk4# ./mvs HHC01413I Hercules version 4.00 HHC01414I (c) Copyright 1999-2012 by Roger Bowler, Jan Jaeger, and others HHC01415I Built on Feb 5 2015 at 16:48:19 HHC01416I Build information: 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 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 With CCKD BZIP2 support HHC01417I With 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 With National Language Support HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 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 HHC01413I Hercules version 4.00 HHC01414I (c) Copyright 1999-2012 by Roger Bowler, Jan Jaeger, and others HHC01415I Built on Feb 5 2015 at 16:48:19 HHC01416I Build information: 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 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 With CCKD BZIP2 support HHC01417I With 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 With National Language Support HHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 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 HHC00150I Crypto module loaded (c) Copyright 2003-2011 by Bernard van der Helm HHC00151I Activated facility: Message Security Assist HHC00151I Activated facility: Message Security Assist Extension 1, 2, 3 and 4 HHC00100I Thread id 7FE8C094C700, prio 15, name Processor CP00 started HHC00100I Thread id 7FE8C084B700, prio -20, name Timer started HHC00811I Processor CP00: architecture mode z/Arch HHC00136W Error in function setenv(): cannot set CUU: Not thread safe--setting disabled HHC01802I HTTP server using root directory /home/ken/tk4/hercules/httproot/ HHC01807I HTTP server signaled to start HHC00100I Thread id 7FE8C0B4F700, prio 4, name HTTP server started HHC01802I HTTP server using root directory /home/ken/tk4/hercules/httproot/ HHC01803I HTTP server waiting for requests on port 8038 HHC01042I 0:000C COMM: device bound to socket 3505 HHC00100I Thread id 7FE8C0A4E700, prio 0, name Socket device listener started HHC00221I 0:0480 Tape file /dev/nst2, type scsi: format type SCSI attached tape drive HHC00100I Thread id 7FE8C013A700, prio 0, name SCSI-TAPE mount monitor started HHC00221I 0:0481 Tape file /dev/nst1, type scsi: format type SCSI attached tape drive HHC00221I 0:0482 Tape file /dev/nst0, type scsi: format type SCSI attached tape drive HHC01437I Config file[50] conf/tk4-.cnf: including file conf/intcons.cnf HHC00100I Thread id 7FE8B29D4700, prio 4, name Console connection started HHC01437I Config file[77] conf/tk4-.cnf: including file conf/tk4-default.cnf :: :: HHC01603I HHC01603I \ **** **\ * || HHC01603I * * * * * * ||| HHC01603I * * * * * * |||| HHC01603I * * * * || || HHC01603I \ |l ,,,---,, * * * || || HHC01603I \ ZZZzz /,'.-'`' -. ;-;;, ** || || HHC01603I * |,4- ) )-,. ,( ( ''-' || || HHC01603I '---''(/--'`-')) * * * || || |||||||||| HHC01603I * * * * ||||||||||| HHC01603I * The MVS 3.8j * * * || HHC01603I * Tur(n)key System * * * || HHC01603I * ** **\ * |||||| HHC01603I HHC01603I * TK3 created by Volker Bandke vbandke@bsp-gmbh.com HHC01603I * TK4- update by Juergen Winkelmann winkelmann@id.ethz.ch HHC01603I * see TK4-.CREDITS for complete credits HHC01603I HHC02264I Script 5: file scripts/tk4-.rc processing ended HHC01018I 0:0010 COMM: client 192.168.10.200 devtype 3270: connected HHC00008I /v 010,console,auth=all 14.08.47 IEE349I CONSOLES CONSOLE/ALT COND AUTH ID AREA ROUTCD 010/011 A ALL 01 Z,A 1-13,15-16 HHC01018I 0:00C0 COMM: client 192.168.10.200 devtype 3270: connected 14.09.10 LGN001I TSO logon in progress at VTAM terminal CUU0C0 14.09.12 TSU 39 $HASP100 HERC01 ON TSOINRDR 14.09.12 TSU 39 $HASP373 HERC01 STARTED 14.09.12 TSU 39 IEF125I HERC01 - LOGGED ON - TIME=14.09.12

14.10.26 JOB 83 $HASP100 HERC01TT ON INTRDR 14.10.26 JOB 83 $HASP373 HERC01TT STARTED - INIT 1 - CLASS A - SYS TK4- 14.10.26 JOB 83 IEF403I HERC01TT - STARTED - TIME=14.10.26 (14.10.29 JOB 83 IEF244I HERC01TT GENERATE - UNABLE TO ALLOCATE 1 UNIT(S) AT LEAST 1 OFFLINE UNIT(S) NEEDED. 14.10.29 JOB 83 IEF489I HERC01TT - 1 UNIT(S) NEEDED FOR OUTDS 14.10.29 JOB 83 IEF247I HERC01TT - 481 OFFLINE 14.10.29 JOB 83 00 IEF238D HERC01TT - REPLY DEVICE NAME OR 'CANCEL'. 14.10.47 IEE600I REPLY TO 00 IS;481 14.10.52 JOB 83 IEC705I TAPE ON 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE 14.11.09 JOB 83 IEF244I HERC01TT TAPECOPY - UNABLE TO ALLOCATE 1 UNIT(S) AT LEAST 1 OFFLINE UNIT(S) NEEDED. 14.11.09 JOB 83 IEF489I HERC01TT - 1 UNIT(S) NEEDED FOR SYSUT2 14.11.09 JOB 83 IEF247I HERC01TT - 482 OFFLINE 14.11.09 JOB 83 01 IEF238D HERC01TT - REPLY DEVICE NAME OR 'CANCEL'. 14.11.18 IEE600I REPLY TO 01 IS;482 14.11.18 JOB 83 IEF233A M 482,SL0691,,HERC01TT,TAPECOPY 14.11.24 JOB 83 IEC705I TAPE ON 482,SL0691,SL,6250 BPI,HERC01TT,TAPECOPY 14.12.26 JOB 83 IEF234E K 481,SL0690,PVT,HERC01TT,COMPARE 14.12.31 JOB 83 IEF234E K 482,SL0691,PVT,HERC01TT,COMPARE 14.12.37 JOB 83 IEF404I HERC01TT - ENDED - TIME=14.12.37 14.12.37 JOB 83 $HASP395 HERC01TT ENDED 14.12.37 $HASP309 INIT 1 INACTIVE *****\ C=A 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 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

(notice that MVS has recognized that there is a tape mounted on 480 volser=000001, which is correct operation and I assume it is a result of the scsimount process)

HHC00008I /d u,,,480,3 14.38.34 IEE450I 14.38.34 UNIT STATUS 503 UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE 480 3400 O 000001 /REMOV 481 3400 O /REMOV 482 3400 O /REMOV 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

This is another example running under the old version, not tapes are mounted when Herc starts here, A lot of the extraneous messages have been removed ::

root@debian8:/home/ken/tk4# ./mvs HHC01413I Hercules version 4.00 HHC01414I (c) Copyright 1999-2012 by Roger Bowler, Jan Jaeger, and others HHC01415I Built on Feb 5 2015 at 16:48:19 :: HHC00221I 0:0480 Tape file /dev/nst2, type scsi: format type SCSI attached tape drive HHC00100I Thread id 7FDAC0C9A700, prio 0, name SCSI-TAPE mount monitor started HHC00221I 0:0481 Tape file /dev/nst1, type scsi: format type SCSI attached tape drive HHC00221I 0:0482 Tape file /dev/nst0, type scsi: format type SCSI attached tape drive :: HHC00100I Thread id 7FDAA11C7700, prio 0, name SCSI-TAPE status monitor started ::

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: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: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:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor HHC01018I 0:0010 COMM: client 192.168.10.200 devtype 3270: connected

HHC00008I /d u,,,480,3 16.04.22 IEE450I 16.04.22 UNIT STATUS 440 UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE 480 3400 O /REMOV 481 3400 OFFLINE 482 3400 OFFLINE

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 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 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 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 HHC00008I /v 481-482,online 16.15.53 IEE450I 16.15.53 UNIT STATUS 446 UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE 481 3400 O /REMOV 482 3400 O /REMOV HHC00008I /d u,,,480,3 16.16.10 IEE450I 16.16.10 UNIT STATUS 448 UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE 480 3400 O /REMOV 481 3400 O /REMOV 482 3400 O /REMOV HHC00205E 0:0481 Tape file /dev/nst1, 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 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 :: 16.21.23 JOB 85 $HASP100 HERC01TT ON INTRDR 16.21.23 JOB 85 $HASP373 HERC01TT STARTED - INIT 1 - CLASS A - SYS TK4- 16.21.23 JOB 85 IEF403I HERC01TT - STARTED - TIME=16.21.23

(there are still no tapes mounted/ready at this point, but looks like a rewind is attempted on 480 but again this drive is not being allocated by the job, only 481-482)

HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctltape(MTREW): Bad file descriptor 16.21.23 JOB 85 IEA000I 480,EQC,07,0E00,,,,HERC01TT,16.21.23 16.21.23 JOB 85 IEA000I 480,,,,1040000000C003600000000000800100010000FFFF000000,0000 16.21.24 JOB 85 IEA000I 480,EQC,,0E00,,,,HERC01TT,16.21.24 16.21.24 JOB 85 IEA000I 480,,,,1040000000C003600000000000800100010000FFFF000000,0000 16.21.25 JOB 85 IEA000I 480,EQC,_,0E00,,,,HERC01TT,16.21.25 16.21.25 JOB 85 IEA000I 480,,,,1040000000C003600000000000800100010000FFFF000000,0000 16.21.25 JOB 85 IEF503I INCORRECT VOLUME LABEL OR I/O ERROR 16.21.26 JOB 85 IEF234E D 480 16.21.27 JOB 85 IEA000I 480,EQC,*,0E00,,,,HERC01TT,16.21.27 16.21.27 JOB 85 IEA000I 480,,,,1040000000C003600000000000800100010000FFFF000000,0000

16.21.27 JOB 85 *IEC501A M 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE 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 16.22.39 JOB 85 IEC705I TAPE ON 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE

16.22.56 JOB 85 *IEF233A M 482,SL0691,,HERC01TT,TAPECOPY 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 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 active for drive 0:0482 = /dev/nst0

(the mount is not recognized until the scsi error for that drive appears: )

HHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function ioctl_tape(MTSETBLK): Bad file descriptor 16.24.46 JOB 85 IEC705I TAPE ON 482,SL0691,SL,6250 BPI,HERC01TT,TAPECOPY 16.25.48 JOB 85 IEF234E K 481,SL0690,PVT,HERC01TT,COMPARE 16.25.54 JOB 85 IEF234E K 482,SL0691,PVT,HERC01TT,COMPARE 16.26.00 JOB 85 IEF404I HERC01TT - ENDED - TIME=16.26.00 16.26.00 JOB 85 $HASP395 HERC01TT ENDED

(job then finished normally)

16.26.00 $HASP309 INIT 1 INACTIVE **** C=A 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 16.28.21 STC 566 $HASP150 MF1 ON PRINTER1 214 LINES 16.28.21 $HASP160 PRINTER1 INACTIVE - CLASS=A 16.28.21 STC 566 IRB101I MF/1 REPORT AVAILABLE FOR PRINTING 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

HHC01415I Built on Feb 5 2015 at 16:48:19

Which tells me you did not do as I asked.

I don't want you to perform your test using whatever version you happen to still have that happens to have been Built on Feb 5 2015. I want you to build a new version, today, but using Hyperion source code from Feb 5 2015.

In other words pull or clone or whatever the Nix command is to extract the Hyperion source code from Feb 5 2015 and then build that. Today. I want to see on the Hercules log that Hyperion was built today. I want to see:

HHC01415I Built on May 16 2016 at ...

It would also help to enable CCW tracing on all drives too:

t+480
t+481
t+482

Basically what I'm getting at here is that I'm not convinced that your "Built on Feb 5 2015" version is actually the Feb 5 2015 version of Hyperion. I suspect it is a much older (pre-Sep 2013) version of Hyperion that just happened to have been built on Feb 5 2015.

The reason I suspect that is because, as I explained, it was at that time that MAX_BLKLEN was changed to 2MB, which is what's causing your invalid argument error. Thus every version of Hyperion -- after Sep 2013 -- should cause the same invalid argument error.

Only versions of Hyperion before Sep 2013 should run correctly.

Thus your "Feb 2015" version should also be getting invalid argument. Since it doesn't however (as you have shown), that is telling me that things are not as they seem. That is telling me that your "Built on Feb 2015" version is actually a version that was built using source code from before Sep 2013.

Yes, it was built on Feb 2015, but we don't know with any certainty what actual source code was used. My conjecture is that pre-Sep 2013 source code was used. I mean, I could just as easily use Hyperion source code from 2001 and build it today, so that the "Built on" date appears with today's date. Thus the "Built on" date doesn't tell us much and thus I'm not trusting the "Built on Feb 2015" message since I can't be sure what source code was used to build Hyperion on that particular date.

I am strongly suspecting your "Built on Feb 2015" version is actually a much older version. If it was actually a Feb 2015 version of Hyperion built on that same day, then it should be getting the same invalid argument error we are seeing today. The fact that it's not is proof to me that things are not as they seem.

Now since Hyperion doesn't yet include the git commit hash in its version string, we still can't trust the "Built on" date to tell us anything definitive, but I'm trusting you Ken. I'm trusting you to be competent enough to be able to do as I ask. I'm trusting you to be able to pull the Hyperion source code from Feb 2015 and build and run your same test using that.

As I stated in my previous reply, I strongly suspect it too will encounter the same invalid argument error once it gets past the scsimount problem.

FYI: I'm still looking into how best to fix the current invalid argument error, so that problem will be fixed before too long too. Once it is, you should be good to go.

But your claim that your job ran fine using the Feb 2015 version of Hyperion is simply not believable. Something else very strange is going on and I very much want to understand what it is. I very much want to solve this mystery. I want to understand what's going on.

Will you help me?

Please?

Hi Fish

I saw from the log that Ken is running TK4-. So, I just cross checked, what I have in the current version of TK4- for Linux 64-bit systems:

HHC01603I version
HHC01413I Hercules version 4.00
HHC01414I (c) Copyright 1999-2012 by Roger Bowler, Jan Jaeger, and others
HHC01415I Built on Feb  5 2015 at 16:48:19

So, that’s the same version Ken is using. That means in fact, that he is using the TK4- specific variant of Hercules, which happens to have been built on Feb 5, 2015. However, the TK4- specific variant of Hercules is based on a Sandhawk download from Nov 30, 2012, which clearly is before the September 2013 MAX_BLKLEN change you mention.

I hope that helps with further analyzing the problem.

Cheers Jürgen

P.S.: Starting with the next update, the TK4- specific version of Hercules will mention “TK4-“ in the build string to avoid such confusion in the future.

THANK YOU, Jürgen! You have confirmed my suspicion and cleared my confusion!

Ken? There is no need to run the tests I requested. The mystery has been solved.

I will be posting a fix for the invalid argument (MAX_BLKLEN) issue shortly.

Also: FYI:

IBM System Storage Tape Drive 3592 SCSI Reference (GA32-0968-02)

The device supports a minimum logical block length of 1 and a maximum logical block length is 2,097,152 bytes (200000h). Any block length between the limits is also supported.

That's where the 2MB came from.

Even though most tape drives except perhaps the 3592 support such a large block size, Hyperion was changed to be able ti support such devices. I just didn't implement it correctly and you were the first one to trip over it.

Yes, Jürgen is correct, my "old" version is his TK4-. Fish, excuse me for not comprehending what you asked for last time. I really don't speak 'C' or git. It was even a bit of a struggle to compile the fix version you provided.

As far as tape blocksize goes, I guess it depends on what the user's purpose is in using the external drive. If you looking to use the device as aux Hercules storage and cram as much data onto it as possible then the SCSI limits could be exploited. On the other hand, if you are looking mainly for straight interoperability with a mainframe (my interest), it would make sense to use the blocksize limits of the device being emulated, 3420, 3480, 3490 etc. For example, when running TK4- MVS with 3420s it makes no sense to read/write above 32k blocks. Just my 2 cents. Thanks.

@kensmyth I have committed what I hope is a fix for your invalid argument problem (i.e. the whole purpose of creating this GitHub Issue!).

Please pull current Hyperion, re-build, and re-test.

Thanks!

On the other hand, if you are looking mainly for straight interoperability with a mainframe (my interest), it would make sense to use the blocksize limits of the device being emulated, 3420, 3480, 3490 etc.

Quite right.

But Hyperion (not sure about Spinhawk) was designed to be able to emulate 3420's etc, on real SCSI 3590's for example, and the code that's reading from the real SCSI tape drive doesn't know (nor does it care) what device type is being emulated.

The other code in Hyperion's tape drive emulation logic cares of course, but not the low level "read a block of data from this here real SCSI tape drive" function doesn't. :)

( Issue waiting to be closed pending confirmation of fix by @kensmyth )

Some big progress with the latest changes - no more SCSI errors occur. However there remains the strange symptom where a tape drive, not requested by the batch job has to be made ready before the MVS mount is accepted on the allocated tape drive. The job allocates 481 & 482, but 480 must be made ready with a tape mounted. The job does run to completion.

Log follows:

root@debian8:/home/ken/hyp/hyperion-master# ./hercules -f config1
HHC01413I Hercules version 4.0.0.0 (4.0.0.0)
HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
HHC01415I Build date: May 18 2016 at 21:44:04
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
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 00007f914afe1700, 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
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 00007f914afe1700, 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 00007f914e040700, prio  0, name Control panel started 
HHC00100I Thread id 00007f9148f8a700, prio 2147483647, name SCSI-TAPE status monitor started
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  
HHC01603I t+480  
HHC02204I CCW trace for 0:0480 set to on 
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
/d u,,,480,3  
/22.50.47  IEE450I 22.50.47 UNIT STATUS 457 
/ UNIT TYPE STATUS  VOLSER VOLSTATEUNIT TYPE STATUS  VOLSER VOLSTATE
/ 480  3400 O/REMOV 481  3400 OFFLINE 
/ 482  3400 OFFLINE 
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
/v 481-482,online
/22.50.56  IEE450I 22.50.56 UNIT STATUS 460 
/ UNIT TYPE STATUS  VOLSER VOLSTATEUNIT TYPE STATUS  VOLSER VOLSTATE
/ 481  3400 O/REMOV 482  3400 O/REMOV 
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN

NO TAPE DRIVES ARE READY, NO TAPES MOUNTED AT THIS POINT

HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC01603I scsimount 
HHC02203I scsimount  : 5  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status closed, sstat 0x00010000: IM_REP_EN  
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  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC02915I client 3 COMM: Connection received
HHC02914I 0:00C0 COMM: client 3 negotiations complete; ttype = 'IBM-3278-2-E'
HHC01018I 0:00C0 COMM: client 192.168.10.200 devtype 3270: connected
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
/22.52.55  LGN001I TSO logon in progress at VTAM terminal CUU0C0 
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
/22.52.58 TSU38  $HASP100 HERC01ON TSOINRDR 
/22.52.58 TSU38  $HASP373 HERC01STARTED  
/22.52.58 TSU38  IEF125I HERC01 - LOGGED ON - TIME=22.52.58
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
/22.53.27 JOB67  $HASP100 HERC01TT ON INTRDR
/22.53.28 JOB67  $HASP373 HERC01TT STARTED - INIT  1 - CLASS A - SYS TK4- 
/22.53.28 JOB67  IEF403I HERC01TT - STARTED - TIME=22.53.28

JOB STARTS, ALLOCATES DRIVE 481, HOWEVER DRIVE 480 IS TOUCHED ?

HHC01315I 0:0480 CHAN: ccw 03048DA0 70000001
HHC01312I 0:0480 CHAN: stat 0200, count 0001
HHC01313I 0:0480 CHAN: sense 40220000 00C00300 00000000 00800100 010000FF FF000000 00000000 00000000 
HHC01314I 0:0480 CHAN: sense INTREQ EOC WRI 
HHC01316I 0:0480 CHAN: csw 10, stat 0200, count 0001, ccw 00D9F0 
HHC01315I 0:0480 CHAN: ccw 04FF4390 20000018
HHC01320I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation started
HHC01321I 0:0480 CHAN: start I/O S/370 conversion to asynchronous operation successful
HHC01315I 0:0480 CHAN: ccw 04FF4390 20000018
HHC01312I 0:0480 CHAN: stat 0C00, count 0000=>40220000 00C00300 00000000 00800100  ....{..........
HHC01316I 0:0480 CHAN: csw 00, stat 0C00, count 0000, ccw 00D9F0

MOUNT MESSAGE APPEARS FOR DRIVE 481

/22.53.28 JOB67 *IEC501A M 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE 
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN

TAPE IS NOW MOUNTED ON 481, BUT MVS MOUNT IS STILL PENDING

HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x41810000: BOT ONLINE D_6250 IM_REP_EN  
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x41810000: BOT ONLINE D_6250 IM_REP_EN

PUTTING DRIVE 480 ONLINE WITH A TAPE THEN CAUSES 481 MVS MOUNT TO BE RECOGNIZED ?!

HHC92702D Tape /dev/nst2: finish_scsitape_open mt_gstat 0x41810000 BOT ONLINE D_6250 IM_REP_EN 
HHC01305I 0:0480 CHAN: attention
HHC01316I 0:0480 CHAN: csw 00, stat 0400, count 0000, ccw 000000 
HHC92702D Tape /dev/nst1: finish_scsitape_open mt_gstat 0x41010000 BOT ONLINE IM_REP_EN  
/22.56.23 JOB67  IEC705I TAPE ON 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE
HHC01315I 0:0480 CHAN: ccw 03048DA0 70000001
HHC01312I 0:0480 CHAN: stat 0C00, count 0001
HHC01315I 0:0480 CHAN: ccw 08FF44E8 00000000
HHC01315I 0:0480 CHAN: ccw 03000000 20400001
HHC01312I 0:0480 CHAN: stat 0C00, count 0001
HHC01316I 0:0480 CHAN: csw 10, stat 0C00, count 0001, ccw FF44F0 
HHC01315I 0:0480 CHAN: ccw 03048DA0 70000001
HHC01312I 0:0480 CHAN: stat 0C00, count 0001
HHC01315I 0:0480 CHAN: ccw 08FF4980 00000000
HHC01315I 0:0480 CHAN: ccw 07000000 20400001
HHC01312I 0:0480 CHAN: stat 0C00, count 0001
HHC01316I 0:0480 CHAN: csw 10, stat 0C00, count 0001, ccw FF4988 
HHC01315I 0:0480 CHAN: ccw 03048DA0 70000001
HHC01312I 0:0480 CHAN: stat 0C00, count 0001
HHC01315I 0:0480 CHAN: ccw 08FF40F8 00000000
HHC01315I 0:0480 CHAN: ccw 0268BF3C 20000050
HHC01312I 0:0480 CHAN: stat 0C00, count 0000=>E5D6D3F1 F0F0F0F0 F0F1F040 40404040 VOL10000010  
HHC01316I 0:0480 CHAN: csw 10, stat 0C00, count 0000, ccw FF4100 
HHC01315I 0:0480 CHAN: ccw 03048DA0 70000001
HHC01312I 0:0480 CHAN: stat 0C00, count 0001
HHC01315I 0:0480 CHAN: ccw 08FF4050 00000000
HHC01315I 0:0480 CHAN: ccw 07000000 20400001
HHC01312I 0:0480 CHAN: stat 0C00, count 0001
HHC01316I 0:0480 CHAN: csw 10, stat 0C00, count 0001, ccw FF4058 
/22.56.52 JOB67 *IEF233A M 482,SL0691,,HERC01TT,TAPECOPY

TAPE IS NOW MOUNTED ON 482, AND IS RECOGNIZED CORRECTLY

/23.00.14 JOB67  IEC705I TAPE ON 482,SL0691,SL,6250 BPI,HERC01TT,TAPECOPY 
/23.01.32 JOB67  IEF234E K 481,SL0690,PVT,HERC01TT,COMPARE 
/23.01.38 JOB67  IEF234E K 482,SL0691,PVT,HERC01TT,COMPARE 
/23.01.44 JOB67  IEF404I HERC01TT - ENDED - TIME=23.01.44  
/23.01.44 JOB67  $HASP395 HERC01TT ENDED 
/23.01.44  $HASP309 INIT  1 INACTIVE ******** C=A

JOB ENDS NORMALLY

Excellent!

It appears the problem has been resolved!

However there remains the strange symptom where a tape drive, not requested by the batch job has to be made ready before the MVS mount is accepted on the allocated tape drive. The job allocates 481 & 482, but 480 must be made ready with a tape mounted.

This is something your MVS guest is doing and has nothing to do with Hercules. I'm not an MVS person (I grew up with DOS/VSE, and VM/SP, not MVS) but it seems MVS wants to know the VOLSER (if any) of each tape drive that is defined "online" to it (i.e. for each tape drive that is not "varied offline").

And drive 480 is "online" to MVS:

/d u,,,480,3  
/22.50.47  IEE450I 22.50.47 UNIT STATUS 457 
/ UNIT TYPE STATUS  VOLSER VOLSTATEUNIT TYPE STATUS  VOLSER VOLSTATE
/ 480  3400 O/REMOV 481  3400 OFFLINE 
/ 482  3400 OFFLINE

"O/REMOV" means the drive is "online" (i.e. not varied offline), 481 and 482 however are both "offline" to MVS (481 3400 OFFLINE, and 482 3400 OFFLINE), so it will never try to access them until you first vary them online.

MVS is probably trying to "find" the tape drive that has your job's requested VOLSER on it so it can properly allocate the required resources for your job (but that's just a guess; I'm not an MVS person).

I suspect if you re-run your test again but this time starting with drive 480 is the "offline to MVS" state (i.e. 480 3400 OFFLINE), and drives 481 and 482 in the "online to MVS" state (481 3400 O/REMOV, and 482 3400 O/REMOV), your job will likely run immediately to completion with no MVS mount request at all (but again, that's just a guess).

Bottom line: your remaining "drive 480 issue" is a "user error" problem (i.e. something either you or your guest are doing) and not a Hercules issue. Therefore since all outstanding Hercules issues appear to have now been resolved, I am going to go ahead close this GitHub Issue.

If you discover a new issue (problem) with Hercules/Hyperion, please create a new GitHub Issue for it and we'll look into it.

Thank you for your patience and help Ken!

Good luck!

Enjoy your personal mainframe. :)

I agree that the SCSI error issue is solved.

But I don’t agree that the 480 anomaly is guest related. The 480 is “online” after IPL because that is the way it has been “gen’d” in MVS. Notice that we manually varied 481-482 online before starting the job. So when the job begins, all 3 drives are in the same online status – MVS online status that is. MVS device online is not the same as online & ready (ie. tape mounted). If MVS sees a drive become ready it will try and read a label to see what there. That is likely what is being shown in the CCW traces for 480.

/d u,,,480,3 /22.50.47 IEE450I 22.50.47 UNIT STATUS 457 / UNIT TYPE STATUS VOLSER VOLSTATEUNIT TYPE STATUS VOLSER VOLSTATE / 480 3400 O/REMOV 481 3400 OFFLINE / 482 3400 OFFLINE HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN
HHC00211I 0:0480 Tape file /dev/nst2, type scsi status opened, sstat 0x00010000: IM_REP_EN
/v 481-482,online /22.50.56 IEE450I 22.50.56 UNIT STATUS 460 / UNIT TYPE STATUS VOLSER VOLSTATEUNIT TYPE STATUS VOLSER VOLSTATE / 481 3400 O/REMOV 482 3400 O/REMOV

I will run different scenarios and see if there any other clues to what is happening here. If I can narrow it down I’ll open a new issue.

Different subject, for what it’s worth…. Had a problem with the ‘make’ step:

ERROR occurred during make:

hatomic.h:88:10: error: missing binary operator before token "("

if 2 == ATOMIC_CHAR_LOCK_FREE && !defined(DISABLE_IAF2)

I changed the line in the header file to read:

if 2 == __GCC_ATOMIC_CHAR_LOCK_FREE && !defined(DISABLE_IAF2)

Then it ran, but like I said I am not a “C” maven, just a lowly assembler guy.

Thanks for your diligence in solving my SCSI problems!

Following Error occurred while initiating REAR OBDR Backup

Please Hel Me to set My Device Status - /dev/nst0 - BOT ONLINE IM_REP_EN

/usr/share/rear/lib/_input-output-functions.sh: line 328: type: sedutil-cli: not found 2021-08-14 22:57:55.953203894 Including prep/NETFS/default/400_automatic_exclude_recreate.sh 2021-08-14 22:57:55.957783259 Including prep/OBDR/default/400_check_tape_drive.sh drive type = 114 drive status = 1509949440 sense key error = 0 residue count = 0 file number = 0 block number = 0 2021-08-14 22:57:55.968471199 ERROR: Tape in device '//dev/nst0' is not online. ===== Stack trace ===== Trace 0: /usr/sbin/rear:544 main Trace 1: /usr/share/rear/lib/mkbackup-workflow.sh:9 WORKFLOW_mkbackup Trace 2: /usr/share/rear/lib/framework-functions.sh:101 SourceStage Trace 3: /usr/share/rear/lib/framework-functions.sh:49 Source Trace 4: /usr/share/rear/prep/OBDR/default/400_check_tape_drive.sh:23 source Trace 5: /usr/share/rear/lib/_input-output-functions.sh:458 StopIfError Message: Tape in device '//dev/nst0' is not online. === End stack trace === 2021-08-14 22:57:55.973644821 Exiting rear mkbackup (PID 118328) and its descendant processes 2021-08-14 22:57:56.994473245 rear,118328 /usr/sbin/rear -d -v mkbackup -rear,118759 /usr/sbin/rear -d -v mkbackup -pstree,118760 -Aplau 118328 /usr/share/rear/lib/_input-output-functions.sh: line 157: kill: (118764) - No such process 2021-08-14 22:57:57.014085058 Running exit tasks 2021-08-14 22:57:57.015415175 Exit task 'rmdir -v /tmp/rear.zppmQ2BHhrocBKE/outputfs >&2' rmdir: removing directory, '/tmp/rear.zppmQ2BHhrocBKE/outputfs' 2021-08-14 22:57:57.017308193 Exit task 'cleanup_build_area_and_end_program' 2021-08-14 22:57:57.018538345 Finished in 2 seconds 2021-08-14 22:57:57.019723200 You should also rm -Rf /tmp/rear.zppmQ2BHhrocBKE 2021-08-14 22:57:57.020933198 End of program reached 2021-08-14 22:57:57.022100792 Exit task '(( EXIT_FAIL_MESSAGE )) && echo 'rear mkbackup failed, check /var/log/rear/rear-drapprd6.log for details' 1>&8' 2021-08-14 22:57:57.023335925 Exit task 'exec 8>&-' 2021-08-14 22:57:57.024514357 Exit task 'exec 7>&-' 2021-08-14 22:57:57.025688857 Exit task 'exec 6<&-' 2021-08-14 22:57:57.026874263 Exit task ''

hercules-390 / hyperion

SCSI error in function read_tape(): Invalid argument - #107

This is related to the fix applied for SCSI error HHC00205E for each SCSI drive #97

if 2 == ATOMIC_CHAR_LOCK_FREE && !defined(DISABLE_IAF2)

if 2 == __GCC_ATOMIC_CHAR_LOCK_FREE && !defined(DISABLE_IAF2)