kerravon86@yahoo.com.au [hercules-390]
2017-01-18 05:15:10 UTC
I run a slightly-modified Hercules 3.07 automatically
via Windows batch files.
I tried setting it up to automatically do lots of
runs to see if I could reproduce an anomaly
I had discovered previously.
I was successful. In about 1 in 78 runs, the
console appears to freeze. Here is what
the console looks like:
04.37.49 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP Command ==> CPU0000 PSW=078D0000803708B8 31.....P.. instcount=240,587,479
That was the first failure I documented.
The second looked very similar:
04.58.13 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP Command ==> CPU0000 PSW=078D1000800C437C 31.....P.. instcount=245,442,500
It looked like Hercules was freezing on
the tape mount, but when I inspected
the hercules.log (for the first failure),
it showed:
15:37:49 04.37.49 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEF234E K 402,MFTOPC,PVT,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEFACTRT - Stepname Procstep Program Retcode
15:37:49 04.37.49 JOB 1 MVSGCC S1 COMP GCC RC= 0000
15:37:49 04.37.49 JOB 1 IEF404I MVSGCC - ENDED - TIME=04.37.49
ie the job ended cleanly, and it
even got to the "quit" stage. Here
is the end of the hercules.log:
15:37:49 04.37.49 JOB 2 $HASP250 TERMHERC IS PURGED
15:37:49 HHCAO003I Firing command: 'script conf/termherc2.rc'
15:37:49 script conf/termherc2.rc
15:37:49 quit
15:37:49 HHCIN900I Begin Hercules shutdown
15:37:49 HHCIN901I Releasing configuration
But the Hercules integrated console
was never updated.
The sequence I normally expect after
a "quit" is:
15:58:08 04.58.08 JOB 2 $HASP250 TERMHERC IS PURGED
15:58:08 HHCAO003I Firing command: 'script conf/termherc2.rc'
15:58:08 script conf/termherc2.rc
15:58:08 quit
15:58:08 HHCIN900I Begin Hercules shutdown
15:58:08 HHCIN901I Releasing configuration
15:58:08 HHCCP008I CPU0000 thread ended: tid=00002390, pid=8160
15:58:08 HHCCF047I Subchannel 0:0000 detached
15:58:08 HHCTT003I Timer thread ended
15:58:08 HHCCF047I Subchannel 0:0001 detached
15:58:08 HHCCF047I Subchannel 0:0002 detached
15:58:08 HHCCF047I Subchannel 0:0003 detached
15:58:08 HHCCF047I Subchannel 0:0004 detached
15:58:08 HHCCD210I size free nbr st reads writes l2reads hits switches
15:58:08 HHCCD211I readaheads misses
15:58:08 HHCCD212I --------------------------------------------------------------------
15:58:08 HHCCD213I [*] 18648958 0% 20 1122 25 34 1037 2001
15:58:08 HHCCD214I 161 23
15:58:08 HHCCD215I dasd/mvsres.148
15:58:08 HHCCD216I [0] 15179178 0% 1 ro 942 0 17
15:58:08 HHCCD217I shadow/mvsres_*.148
15:58:08 HHCCD218I [1] 3469780 0% 19 180 25 17
15:58:08 HHCCF047I Subchannel 0:0005 detached
15:58:08 HHCCD210I size free nbr st reads writes l2reads hits switches
15:58:08 HHCCD212I --------------------------------------------------------------------
15:58:08 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
15:58:08 HHCCD215I dasd/sort01.131
(etc)
Does anyone recognize the problem?
If not, I will attempt to reproduce the
problem with a later version of Hercules.
I'll need to change my job a bit though,
since it relies on OMA extensions.
Full log of first failure below.
Thanks. Paul.
15:37:44 Hercules Version 3.07:380-4.x
15:37:44 (c)Copyright 1999-2010 by Roger Bowler, Jan Jaeger, and others
15:37:44 Built on Dec 7 2016 at 12:43:32
15:37:44 Build information:
15:37:44 Windows (MSVC) build for AMD64
15:37:44 Modes: S/370 S/380 ESA/390 z/Arch
15:37:44 Max CPU Engines: 8
15:37:44 Using fthreads instead of pthreads
15:37:44 Dynamic loading support
15:37:44 Using shared libraries
15:37:44 HTTP Server support
15:37:44 No SIGABEND handler
15:37:44 Regular Expressions support
15:37:44 Automatic Operator support
15:37:44 Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8
15:37:44 Running on PAUL-DELL Windows_NT-6.2 AMD64 MP=8
15:37:44 HHCHD018I Loadable module directory is hercules
15:37:44 Crypto module loaded (c) Copyright Bernard van der Helm, 2003-2010
15:37:44 Active: Message Security Assist
15:37:44 Message Security Assist Extension 1
15:37:44 Message Security Assist Extension 2
15:37:44 HHCPN210I Default Allowed AUTOMOUNT directory = "c:\mvs380\"
15:37:44 HHCHT001I HTTP listener thread started: tid=00001C94, pid=17944
15:37:44 HHCCF065I Hercules: tid=00002AE8, pid=17944, pgid=17944, priority=8
15:37:44 HHCCF066E Invalid HTTPROOT: "c:\herc380\html": No such file or directory
15:37:44 HHCSD004I Device 000C bound to socket 127.0.0.1:3505
15:37:44 HHCSD020I Socketdevice listener thread started: tid=0000204C, pid=17944
15:37:44 HHCCF083I conf/mvs380.conf Including conf/mvs380_DASD.conf at 122 .
15:37:44 HHCDA004I opening dasd/mvsres.148 readonly
15:37:44 HHCDA020I dasd/mvsres.148 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/sort01.131 readonly
15:37:44 HHCDA020I dasd/sort01.131 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort02.132 readonly
15:37:44 HHCDA020I dasd/sort02.132 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort03.133 readonly
15:37:44 HHCDA020I dasd/sort03.133 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort04.134 readonly
15:37:44 HHCDA020I dasd/sort04.134 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort05.135 readonly
15:37:44 HHCDA020I dasd/sort05.135 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort06.136 readonly
15:37:44 HHCDA020I dasd/sort06.136 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/work00.140 readonly
15:37:44 HHCDA020I dasd/work00.140 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA020I dasd/hasp00.152 cyls=404 heads=19 tracks=7676 trklen=13312
15:37:44 HHCDA020I dasd/page00.160 cyls=698 heads=12 tracks=8376 trklen=8704
15:37:44 HHCDA020I dasd/page01.161 cyls=698 heads=12 tracks=8376 trklen=8704
15:37:44 HHCDA020I dasd/page02.162 cyls=698 heads=12 tracks=8376 trklen=8704
15:37:44 HHCDA020I dasd/work01.170 cyls=962 heads=12 tracks=11544 trklen=35840
15:37:44 HHCDA004I opening dasd/work02.180 readonly
15:37:44 HHCDA020I dasd/work02.180 cyls=886 heads=15 tracks=13290 trklen=47616
15:37:44 HHCDA004I opening dasd/work03.190 readonly
15:37:44 HHCDA020I dasd/work03.190 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/mvscat.191 readonly
15:37:44 HHCDA020I dasd/mvscat.191 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/seasik.192 readonly
15:37:44 HHCDA020I dasd/seasik.192 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA020I dasd/mvssrc.193 cyls=2226 heads=15 tracks=33390 trklen=56832
15:37:44 HHCDA002E 01B4:File not found or invalid 'dasd/pub004.1b4'
15:37:44 HHCCF044E Initialization failed for device 01B4
15:37:44 HHCDA004I opening dasd/pub000.240 readonly
15:37:44 HHCDA020I dasd/pub000.240 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/mvsdlb.248 readonly
15:37:44 HHCDA020I dasd/mvsdlb.248 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/pub002.280 readonly
15:37:44 HHCDA020I dasd/pub002.280 cyls=1772 heads=15 tracks=26580 trklen=47616
15:37:44 HHCDA004I opening dasd/tmptmp.2b1 readonly
15:37:44 HHCDA020I dasd/tmptmp.2b1 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/xmit90.2b2 readonly
15:37:44 HHCDA020I dasd/xmit90.2b2 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/start1.150 readonly
15:37:44 HHCDA020I dasd/start1.150 cyls=808 heads=19 tracks=15352 trklen=13312
15:37:44 HHCDA004I opening dasd/spool0.151 readonly
15:37:44 HHCDA020I dasd/spool0.151 cyls=808 heads=19 tracks=15352 trklen=13312
15:37:44 HHCDA004I opening dasd/cbt000.340 readonly
15:37:44 HHCDA020I dasd/cbt000.340 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/cbt001.341 readonly
15:37:44 HHCDA020I dasd/cbt001.341 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/cbt002.342 readonly
15:37:44 HHCDA020I dasd/cbt002.342 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/cbtcat.343 readonly
15:37:44 HHCDA020I dasd/cbtcat.343 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/src000.348 readonly
15:37:44 HHCDA020I dasd/src000.348 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/src001.349 readonly
15:37:44 HHCDA020I dasd/src001.349 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/src002.34a readonly
15:37:44 HHCDA020I dasd/src002.34a cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/srccat.34b readonly
15:37:44 HHCDA020I dasd/srccat.34b cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/smp001.149 readonly
15:37:44 HHCDA020I dasd/smp001.149 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/smp002.14a readonly
15:37:44 HHCDA020I dasd/smp002.14a cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/smp003.14b readonly
15:37:44 HHCDA020I dasd/smp003.14b cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/smp004.14c readonly
15:37:44 HHCDA020I dasd/smp004.14c cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/js2sp0.700 readonly
15:37:44 HHCDA020I dasd/js2sp0.700 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/dlicat.138 readonly
15:37:44 HHCDA020I dasd/dlicat.138 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dlisys.139 readonly
15:37:44 HHCDA020I dasd/dlisys.139 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dli000.13a readonly
15:37:44 HHCDA020I dasd/dli000.13a cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dli001.13b readonly
15:37:44 HHCDA020I dasd/dli001.13b cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dli002.13c readonly
15:37:44 HHCDA020I dasd/dli002.13c cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/js3sp0.710 readonly
15:37:44 HHCDA020I dasd/js3sp0.710 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/js3res.711 readonly
15:37:44 HHCDA020I dasd/js3res.711 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCTE001I Console connection thread started: tid=00004790, pid=17944
15:37:44 HHCTE003I Waiting for console connection on port 3270
15:37:44 HHCTA066I 0400: option 'level' accepted.
15:37:44 HHCTA066I 0401: option 'level' accepted.
15:37:44 HHCTA066I 0402: option 'level' accepted.
15:37:44 HHCTA066I 0403: option 'level' accepted.
15:37:44 HHCCP002I CPU0000 thread started: tid=00001AE8, pid=17944, priority=0
15:37:44 HHCCP003I CPU0000 architecture mode S/380
15:37:44 HHCTT002I Timer thread started: tid=0000462C, pid=17944, priority=-20
15:37:44 HHCPN001I Control panel thread started: tid=00002AE8, pid=17944
15:37:44 HHCPN008I Script file processing started using file "conf/auto_run.rc"
15:37:44 HHCAO001I Hercules Automatic Operator thread started;
15:37:44 tid=00003358, pri=0, pid=17944
15:37:44 devlist
15:37:44 0:000C 3505 127.0.0.1:3505 sockdev ascii trunc eof
15:37:44 (no one currently connected)
15:37:44 0:000D 3525 pch/pch00d.txt ascii crlf
15:37:44 0:000E 1403 prt/prt00e.txt crlf noclear
15:37:44 0:000F 1403 prt/prt00f.txt crlf noclear
15:37:44 0:001F 3215 *syscons cmdpref(/)
15:37:44 0:00C0 3270
15:37:44 0:00C1 3270
15:37:44 0:00C2 3270
15:37:44 0:00C7 3287
15:37:44 0:010C 3505 jcl/dummy eof
15:37:44 0:0131 2314 dasd/sort01.131 [200 cyls] open
15:37:44 0:0132 2314 dasd/sort02.132 [200 cyls] open
15:37:44 0:0133 2314 dasd/sort03.133 [200 cyls] open
15:37:44 0:0134 2314 dasd/sort04.134 [200 cyls] open
15:37:44 0:0135 2314 dasd/sort05.135 [200 cyls] open
15:37:44 0:0136 2314 dasd/sort06.136 [200 cyls] open
15:37:44 0:0138 2314 dasd/dlicat.138 [200 cyls] open
15:37:44 0:0139 2314 dasd/dlisys.139 [200 cyls] open
15:37:44 0:013A 2314 dasd/dli000.13a [200 cyls] open
15:37:44 0:013B 2314 dasd/dli001.13b [200 cyls] open
15:37:44 0:013C 2314 dasd/dli002.13c [200 cyls] open
15:37:44 0:0140 3350 dasd/work00.140 [560 cyls] open
15:37:44 0:0148 3350 dasd/mvsres.148 [560 cyls] open
15:37:44 0:0149 3350 dasd/smp001.149 [560 cyls] open
15:37:44 0:014A 3350 dasd/smp002.14a [560 cyls] open
15:37:44 0:014B 3350 dasd/smp003.14b [560 cyls] open
15:37:44 0:014C 3350 dasd/smp004.14c [560 cyls] open
15:37:44 0:0150 3330 dasd/start1.150 [808 cyls] open
15:37:44 0:0151 3330 dasd/spool0.151 [808 cyls] open
15:37:44 0:0152 3330 dasd/hasp00.152 [404 cyls] open
15:37:44 0:0160 3340 dasd/page00.160 [698 cyls] open
15:37:44 0:0161 3340 dasd/page01.161 [698 cyls] open
15:37:44 0:0162 3340 dasd/page02.162 [698 cyls] open
15:37:44 0:0170 3375 dasd/work01.170 [962 cyls] open
15:37:44 0:01A0 3380 dasd/work02.180 [886 cyls] open
15:37:44 0:01B0 3390 dasd/work03.190 [1114 cyls] open
15:37:44 0:01B1 3390 dasd/mvscat.191 [1114 cyls] open
15:37:44 0:01B2 3390 dasd/seasik.192 [1114 cyls] open
15:37:44 0:01B3 3390 dasd/mvssrc.193 [2226 cyls] open
15:37:44 0:01C7 3287
15:37:44 0:0240 3350 dasd/pub000.240 [560 cyls] open
15:37:44 0:0248 3350 dasd/mvsdlb.248 [560 cyls] open
15:37:44 0:02A0 3380 dasd/pub002.280 [1772 cyls] open
15:37:44 0:02B1 3390 dasd/tmptmp.2b1 [1114 cyls] open
15:37:44 0:02B2 3390 dasd/xmit90.2b2 [1114 cyls] open
15:37:44 0:030E 1403 log/hardcopy.log crlf noclear
15:37:44 0:0340 3350 dasd/cbt000.340 [555 cyls] open
15:37:44 0:0341 3350 dasd/cbt001.341 [555 cyls] open
15:37:44 0:0342 3350 dasd/cbt002.342 [555 cyls] open
15:37:44 0:0343 3350 dasd/cbtcat.343 [555 cyls] open
15:37:44 0:0348 3350 dasd/src000.348 [555 cyls] open
15:37:44 0:0349 3350 dasd/src001.349 [555 cyls] open
15:37:44 0:034A 3350 dasd/src002.34a [555 cyls] open
15:37:44 0:034B 3350 dasd/srccat.34b [555 cyls] open
15:37:44 0:0400 3420 *
15:37:44 0:0401 3420 *
15:37:44 0:0402 3420 *
15:37:44 0:0403 3420 *
15:37:44 0:0700 3350 dasd/js2sp0.700 [555 cyls] open
15:37:44 0:0710 3350 dasd/js3sp0.710 [555 cyls] open
15:37:44 0:0711 3350 dasd/js3res.711 [555 cyls] open
15:37:44 logopt timestamp
15:37:44 HHCPN197I Log option set: TIMESTAMP
15:37:44 panrate 1000
15:37:44 # really need to wait for SVC120I, but if building MVS/380
15:37:44 # or some other stuffup with parms, need to trigger on an
15:37:44 # alternative. First one hit will clear targets.
15:37:44 # If we get a prompt for a device, cancel it
15:37:44 hao tgt IEF238D
15:37:44 HHCAO016I Target placed at index 0
15:37:44 hao cmd script conf/cancel.rc
15:37:44 HHCAO020I Command placed at index 0
15:37:44 hao tgt HASP395 DYNAMASK
15:37:44 HHCAO016I Target placed at index 1
15:37:44 hao cmd script conf/subjobs_slow.rc
15:37:44 HHCAO020I Command placed at index 1
15:37:44 hao tgt HASP373 SVC120I
15:37:44 HHCAO016I Target placed at index 2
15:37:44 hao cmd script conf/subjobs_fast.rc
15:37:44 HHCAO020I Command placed at index 2
15:37:44 hao tgt HASP436 REPLY
15:37:44 HHCAO016I Target placed at index 3
15:37:44 hao cmd script conf/replyy.rc
15:37:44 HHCAO020I Command placed at index 3
15:37:44 devinit 402 tapes/mftopc.het
15:37:44 HHCTA004I 0402: tapes/mftopc.het is a Hercules Emulated Tape file
15:37:44 HHCPN098I Device 0:0402 initialized
15:37:44 devinit 403 tapes/awstap.aws
15:37:44 HHCTA004I 0403: tapes/awstap.aws is a Hercules Emulated Tape file
15:37:44 HHCPN098I Device 0:0403 initialized
15:37:44 # co will give you a cold start of JES2 which is useful in
15:37:44 # automated runs
15:37:44 /(001F) r 00,clpa,cmd=co
15:37:44 #/r 00,clpa
15:37:44 ipl 148
15:37:44 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:45 IEA101A SPECIFY SYSTEM PARMS FOR MVS/380 1.2 v03.8 TK3+
15:37:45 HHCCD001I Readahead thread 1 started: tid=0000239C, pid=17944
15:37:45 HHCCD001I Readahead thread 2 started: tid=0000203C, pid=17944
15:37:45 HHCCD002I Writer thread 1 started: tid=00001BF8, pid=17944
15:37:45 HHCCD003I Garbage collector thread started: tid=00003AC0, pid=17944
15:37:45 IEA940I THE FOLLOWING PAGE DATA SETS ARE IN USE
15:37:45 PLPA ... SYS1.PAGELPA
15:37:45 COMMON . SYS1.PAGECSA
15:37:45 DUPLEX . SYS1.DUPLEX
15:37:45 LOCAL .. SYS1.PAGEL01
15:37:45 LOCAL .. SYS1.PAGEL02
15:37:45 LOCAL .. SYS1.PAGEL03
15:37:45 HHCCD002I Writer thread 2 started: tid=000036C4, pid=17944
15:37:46 IEE360I SMF NOW RECORDING ON SYS1.MANX ON MVSRES TIME=04.37.46
15:37:46 IGF992I MIH INIT COMPLETE, PRI=000300, SEC=000015
15:37:46 IEF677I WARNING MESSAGE(S) FOR JOB JES2 ISSUED
15:37:47 *00 $HASP436 REPLY Y OR N TO CONFIRM CHECKPOINT RECORD CHANGE
15:37:47 HHCAO003I Firing command: 'script conf/replyy.rc'
15:37:47 script conf/replyy.rc
15:37:47 /(001F) reply 00,y
15:37:47 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:47 IEE600I REPLY TO 00 IS;SUPPRESSED
15:37:47 $HASP493 JES2 COLD-START IS IN PROGRESS
15:37:47 $HASP412 MAXIMUM OF 1 READER(S) EXCEEDED
15:37:47 04.37.47 IEE041I THE SYSTEM LOG IS NOW ACTIVE
15:37:47 04.37.47 IEE302I 00E ONLINE
15:37:47 04.37.47 IEE302I 00F ONLINE
15:37:47 04.37.47 IEE313I 30E UNIT REF INVALID
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 IEE450I 04.37.47 UNIT STATUS 159
15:37:47 UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE
15:37:47 400 3400 O /REMOV 401 3400 O /REMOV
15:37:47 402 3400 O /REMOV
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP160 PRINTER1 INACTIVE - CLASS=AP
15:37:47 04.37.47 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:47 04.37.47 $HASP160 PUNCH1 INACTIVE - CLASS=B
15:37:47 04.37.47 STC 2 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 2 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 2 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 3 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 3 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 3 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 4 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 4 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 4 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 5 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 5 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 5 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 6 $HASP100 INIT ON STCINRDR
15:37:48 04.37.48 STC 6 $HASP373 INIT STARTED
15:37:48 04.37.48 STC 6 IEF403I INIT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 7 $HASP100 INIT ON STCINRDR
15:37:48 04.37.48 STC 7 $HASP373 INIT STARTED
15:37:48 04.37.48 STC 7 IEF403I INIT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 8 $HASP100 INIT ON STCINRDR
15:37:48 04.37.48 STC 8 $HASP373 INIT STARTED
15:37:48 04.37.48 STC 8 IEF403I INIT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 9 $HASP100 SVC120I ON STCINRDR
15:37:48 04.37.48 STC 9 $HASP373 SVC120I STARTED
15:37:48 HHCAO003I Firing command: 'script conf/subjobs_fast.rc'
15:37:48 script conf/subjobs_fast.rc
15:37:48 # Now we know that SVC120I has started. But due to some
15:37:48 # weird pausing, it may get locked out. So clear out
15:37:48 # other triggers and wait on this
15:37:48 hao clear
15:37:48 HHCAO022I All automatic operation rules cleared
15:37:48 hao tgt HASP250 SVC120I
15:37:48 HHCAO016I Target placed at index 0
15:37:48 hao cmd script conf/subjobs.rc
15:37:48 HHCAO020I Command placed at index 0
15:37:48 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:48 04.37.48 STC 9 IEF403I SVC120I - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 10 $HASP100 DYNABLDL ON STCINRDR
15:37:48 04.37.48 STC 10 $HASP373 DYNABLDL STARTED
15:37:48 04.37.48 STC 10 IEF403I DYNABLDL - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 11 $HASP100 DYNAMASK ON STCINRDR
15:37:48 04.37.48 STC 11 $HASP373 DYNAMASK STARTED
15:37:48 04.37.48 STC 11 IEF403I DYNAMASK - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 12 $HASP100 BSPPILOT ON STCINRDR
15:37:48 04.37.48 STC 12 $HASP373 BSPPILOT STARTED
15:37:48 04.37.48 STC 12 IEF403I BSPPILOT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 13 $HASP100 BSPSETPF ON STCINRDR
15:37:48 04.37.48 STC 13 $HASP373 BSPSETPF STARTED
15:37:48 04.37.48 STC 13 IEF403I BSPSETPF - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 14 $HASP100 LOGRECI ON STCINRDR
15:37:48 04.37.48 STC 14 $HASP373 LOGRECI STARTED
15:37:48 04.37.48 STC 14 IEF403I LOGRECI - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 15 $HASP100 NET ON STCINRDR
15:37:48 04.37.48 STC 15 $HASP373 NET STARTED
15:37:48 04.37.48 STC 15 IEF403I NET - STARTED - TIME=04.37.48
15:37:48 04.37.48 $HASP309 INIT 1 INACTIVE ******** C=A
15:37:48 04.37.48 $HASP309 INIT 2 INACTIVE ******** C=BA
15:37:48 04.37.48 $HASP309 INIT 3 INACTIVE ******** C=CBA
15:37:48 04.37.48 $HASP309 INIT 4 INACTIVE ******** C=SHB
15:37:48 04.37.48 $HASP309 INIT 5 INACTIVE ******** C=SBA
15:37:48 04.37.48 $HASP309 INIT 6 INACTIVE ******** C=S
15:37:48 04.37.48 $HASP309 INIT 7 INACTIVE ******** C=E
15:37:48 04.37.48 STC 9 BSPGM40I - 200 MiB MAINSIZE memory available
15:37:48 04.37.48 STC 9 BSPGM41I - 2 Partitions of 64 MiB each
15:37:48 04.37.48 STC 9 BSPGM78I SVC 120 EP=00FE3248; MVS/380
15:37:48 04.37.48 STC 9 IEF404I SVC120I - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 9 $HASP395 SVC120I ENDED
15:37:48 04.37.48 STC 9 $HASP150 SVC120I ON PRINTER2 45 LINES
15:37:48 04.37.48 STC 9 *$HASP190 SVC120I SETUP -- PRINTER2 -- F = 0001 -- C = 6 -- T = SN
15:37:48 04.37.48 $HASP000 OK
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 9 $HASP250 SVC120I IS PURGED
15:37:48 HHCAO003I Firing command: 'script conf/subjobs.rc'
15:37:48 script conf/subjobs.rc
15:37:48 hao clear
15:37:48 HHCAO022I All automatic operation rules cleared
15:37:48 # Every job gets an NL tape available as input, containing
15:37:48 # some binary of unknown contents, most likely needing to
15:37:48 # be read as RECFM=U, but RECFM=FB and even RECFM=V are also
15:37:48 # possible.
15:37:48 #
15:37:48 # The job also gets an SL tape available for output, and
15:37:48 # again, any type of content can be written to it, and
15:37:48 # with a bit of luck, hetget will be able to extract the
15:37:48 # data you are looking for.
15:37:48 #
15:37:48 # And finally the job gets an SL AWS tape available for
15:37:48 # input and/or output should you wish to construct a
15:37:48 # special tape. Tape must be called AWSTAP. User should
15:37:48 # back the tape up before submitting it, because it will
15:37:48 # be overwritten and anything could go wrong. AWS is
15:37:48 # expected to be exceptional use of this procedure anyway
15:37:48 #
15:37:48 # Only the NL tape needs an explicit mount. The SL tapes
15:37:48 # are premounted before IPL
15:37:48 hao tgt HASP250 MOUNT
15:37:48 HHCAO016I Target placed at index 0
15:37:48 hao cmd script conf/subjobs2.rc
15:37:48 HHCAO020I Command placed at index 0
15:37:48 /(001F) M 401,VOL=(NL,PCTOMF)
15:37:48 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:48 04.37.48 STC 16 $HASP100 MOUNT ON STCINRDR
15:37:48 04.37.48 STC 16 $HASP373 MOUNT STARTED
15:37:48 04.37.48 STC 16 IEF403I MOUNT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 16 *IEF233A M 401,PCTOMF,,MOUNT,401
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
15:37:48 04.37.48 STC 15 IST110I NETWORK SOLICITOR STARTED
15:37:48 04.37.48 STC 15 IST093I APPLJRP ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLPIES ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLPIAD ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLTSO ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLTEST ACTIVE
15:37:48 04.37.48 STC 10 DYNABLDL STARTED
15:37:48 04.37.48 STC 15 IST093I LCLMAJRP ACTIVE
15:37:48 04.37.48 STC 15 IST093I LCLMAJ00 ACTIVE
15:37:48 04.37.48 STC 17 $HASP100 TSO ON STCINRDR
15:37:48 04.37.48 STC 17 $HASP373 TSO STARTED
15:37:48 04.37.48 STC 17 IEF403I TSO - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 18 $HASP100 JRP ON STCINRDR
15:37:48 04.37.48 STC 18 $HASP373 JRP STARTED
15:37:48 04.37.48 STC 18 IEF403I JRP - STARTED - TIME=04.37.48
15:37:48 04.37.48 $HASP000 OK
15:37:48 04.37.48 $HASP000 OK
15:37:48 04.37.48 STC 15 IST020I VTAM INITIALIZATION COMPLETE
15:37:48 04.37.48 STC 15 IEA000I 0C0,IOE,05,0200,400000000001,,,NET ,04.37.48
15:37:48 04.37.48 STC 15 IEA000I 0C1,IOE,05,0200,400000000001,,,NET ,04.37.48
15:37:48 04.37.48 STC 15 IEA000I 0C2,IOE,05,0200,400000000001,,,NET ,04.37.48
15:37:48 04.37.48 STC 10 IEF404I DYNABLDL - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 10 $HASP395 DYNABLDL ENDED
15:37:48 04.37.48 STC 10 $HASP150 DYNABLDL ON PRINTER2 21 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 10 $HASP250 DYNABLDL IS PURGED
15:37:48 04.37.48 STC 11 DMSK00I DYNAMASK DONE ****
15:37:48 04.37.48 STC 11 DMSK06I START
15:37:48 04.37.48 STC 11 IEF404I DYNAMASK - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 11 $HASP395 DYNAMASK ENDED
15:37:48 04.37.48 STC 11 $HASP150 DYNAMASK ON PRINTER2 30 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 11 $HASP250 DYNAMASK IS PURGED
15:37:48 04.37.48 STC 13 BSPSP91I - Parms passed: NOREPLYU
15:37:48 04.37.48 STC 13 BSPSP93I - PFK definitions will be updated in memory
15:37:48 04.37.48 STC 13 BSPSP22I - Dataset processed: SYS1.PARMLIB
15:37:48 04.37.48 STC 13 BSPSP23I - on volume MVSRES
15:37:48 04.37.48 STC 13 BSPSP21I - Member being processed: SETPFK01
15:37:48 04.37.48 STC 13 +BSPSP98I - Member processed, LASTCC=0000
15:37:48 04.37.48 STC 13 +BSPSP21I - Member being processed: SETPFK02
15:37:48 04.37.48 STC 13 +BSPSP98I - Member processed, LASTCC=0000
15:37:48 04.37.48 STC 13 +BSPSP99I - End of processing, MAXRC=0000
15:37:48 04.37.48 STC 13 IEF404I BSPSETPF - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 13 $HASP395 BSPSETPF ENDED
15:37:48 04.37.48 STC 13 $HASP150 BSPSETPF ON PRINTER2 34 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 13 $HASP250 BSPSETPF IS PURGED
15:37:48 04.37.48 STC 14 IFC001I D=3350 N=0B F=01AB0000 L=01AC0005 S=01AB000002 DIP COMPLETE
15:37:48 04.37.48 STC 14 IEF404I LOGRECI - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 14 $HASP395 LOGRECI ENDED
15:37:48 04.37.48 STC 14 $HASP150 LOGRECI ON PRINTER2 20 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 14 $HASP250 LOGRECI IS PURGED
15:37:48 04.37.48 STC 16 IEF404I MOUNT - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 16 $HASP395 MOUNT ENDED
15:37:48 04.37.48 STC 16 $HASP150 MOUNT ON PRINTER2 18 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 16 $HASP250 MOUNT IS PURGED
15:37:48 HHCAO003I Firing command: 'script conf/subjobs2.rc'
15:37:48 script conf/subjobs2.rc
15:37:48 hao clear
15:37:48 HHCAO022I All automatic operation rules cleared
15:37:48 # If we get a prompt for a device, cancel it
15:37:48 hao tgt IEF238D
15:37:48 HHCAO016I Target placed at index 0
15:37:48 hao cmd script conf/cancel.rc
15:37:48 HHCAO020I Command placed at index 0
15:37:48 # If we get a prompt for a catalogue password, answer it
15:37:48 hao tgt IEC301A
15:37:48 HHCAO016I Target placed at index 1
15:37:48 hao cmd script conf/secret.rc
15:37:48 HHCAO020I Command placed at index 1
15:37:48 devinit 401 tapes/pctomf.tdf
15:37:48 HHCTA004I 0401: tapes/pctomf.tdf is a Optical Media Attachment (OMA) tape
15:37:48 HHCPN098I Device 0:0401 initialized
15:37:48 # When we see TERMHERC get purged, our job is done
15:37:48 hao tgt HASP373 TERMHERC
15:37:48 HHCAO016I Target placed at index 2
15:37:48 hao cmd script conf/termherc.rc
15:37:48 HHCAO020I Command placed at index 2
15:37:48 # Now submit the job
15:37:48 devinit 00c jcl/hercauto.jcl eof
15:37:48 HHCSD007I Device 000C unbound from socket 127.0.0.1:3505
15:37:48 HHCSD022I Socketdevice listener thread terminated
15:37:48 HHCPN098I Device 0:000C initialized
15:37:48 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:48 04.37.48 JOB 1 $HASP100 MVSGCC ON READER1
15:37:48 04.37.48 JOB 2 $HASP100 TERMHERC ON READER1
15:37:48 04.37.48 JOB 1 $HASP373 MVSGCC STARTED - INIT 3 - CLASS C - SYS BSP1
15:37:48 04.37.48 JOB 1 IEF403I MVSGCC - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 17 IKT007I TCAS ACCEPTING LOGONS
15:37:48 04.37.48 STC 17 IKT005I TCAS IS INITIALIZED
15:37:48 04.37.48 JOB 1 *IEF233A M 401,PCTOMF,,MVSGCC,COMP
15:37:49 04.37.49 STC 18 JRPI101 INITIALIZATION COMPLETE
15:37:49 04.37.49 STC 18 *01 JRP100I - ENTER ICLOSE TO SHUT DOWN
15:37:49 04.37.49 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEF234E K 402,MFTOPC,PVT,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEFACTRT - Stepname Procstep Program Retcode
15:37:49 04.37.49 JOB 1 MVSGCC S1 COMP GCC RC= 0000
15:37:49 04.37.49 JOB 1 IEF404I MVSGCC - ENDED - TIME=04.37.49
15:37:49 04.37.49 JOB 1 $HASP395 MVSGCC ENDED
15:37:49 04.37.49 JOB 1 $HASP150 MVSGCC ON PRINTER1 98 LINES
15:37:49 04.37.49 JOB 1 *$HASP190 MVSGCC SETUP -- PRINTER1 -- F = 0001 -- C = 6 -- T = SN
15:37:49 04.37.49 $HASP000 OK
15:37:49 04.37.49 $HASP160 PRINTER1 INACTIVE - CLASS=AP
15:37:49 04.37.49 JOB 1 $HASP250 MVSGCC IS PURGED
15:37:49 04.37.49 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
15:37:49 HHCAO003I Firing command: 'script conf/termherc.rc'
15:37:49 script conf/termherc.rc
15:37:49 # We do an unnecessary 2-stage terminate, first triggering
15:37:49 # on the start message, then triggering on the purged
15:37:49 # message, to overcome an apparent bug in hercules which
15:37:49 # causes it to sometimes trigger on the wrong jobname.
15:37:49 hao clear
15:37:49 HHCAO022I All automatic operation rules cleared
15:37:49 hao tgt HASP250 TERMHERC
15:37:49 HHCAO016I Target placed at index 0
15:37:49 hao cmd script conf/termherc2.rc
15:37:49 HHCAO020I Command placed at index 0
15:37:49 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:49 04.37.49 JOB 2 IEF403I TERMHERC - STARTED - TIME=04.37.49
15:37:49 04.37.49 JOB 2 IEFACTRT - Stepname Procstep Program Retcode
15:37:49 04.37.49 JOB 2 TERMHERC S1 IEBGENER RC= 0000
15:37:49 04.37.49 JOB 2 IEF404I TERMHERC - ENDED - TIME=04.37.49
15:37:49 04.37.49 JOB 2 $HASP395 TERMHERC ENDED
15:37:49 04.37.49 $HASP309 INIT 3 INACTIVE ******** C=CBA
15:37:49 04.37.49 JOB 2 $HASP150 TERMHERC ON PRINTER2 44 LINES
15:37:49 04.37.49 JOB 2 $HASP150 TERMHERC ON PRINTER1 1 LINE
15:37:49 04.37.49 $HASP160 PRINTER1 INACTIVE - CLASS=AP
15:37:49 04.37.49 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:49 04.37.49 JOB 2 $HASP250 TERMHERC IS PURGED
15:37:49 HHCAO003I Firing command: 'script conf/termherc2.rc'
15:37:49 script conf/termherc2.rc
15:37:49 quit
15:37:49 HHCIN900I Begin Hercules shutdown
15:37:49 HHCIN901I Releasing configuration
via Windows batch files.
I tried setting it up to automatically do lots of
runs to see if I could reproduce an anomaly
I had discovered previously.
I was successful. In about 1 in 78 runs, the
console appears to freeze. Here is what
the console looks like:
04.37.49 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP Command ==> CPU0000 PSW=078D0000803708B8 31.....P.. instcount=240,587,479
That was the first failure I documented.
The second looked very similar:
04.58.13 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP Command ==> CPU0000 PSW=078D1000800C437C 31.....P.. instcount=245,442,500
It looked like Hercules was freezing on
the tape mount, but when I inspected
the hercules.log (for the first failure),
it showed:
15:37:49 04.37.49 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEF234E K 402,MFTOPC,PVT,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEFACTRT - Stepname Procstep Program Retcode
15:37:49 04.37.49 JOB 1 MVSGCC S1 COMP GCC RC= 0000
15:37:49 04.37.49 JOB 1 IEF404I MVSGCC - ENDED - TIME=04.37.49
ie the job ended cleanly, and it
even got to the "quit" stage. Here
is the end of the hercules.log:
15:37:49 04.37.49 JOB 2 $HASP250 TERMHERC IS PURGED
15:37:49 HHCAO003I Firing command: 'script conf/termherc2.rc'
15:37:49 script conf/termherc2.rc
15:37:49 quit
15:37:49 HHCIN900I Begin Hercules shutdown
15:37:49 HHCIN901I Releasing configuration
But the Hercules integrated console
was never updated.
The sequence I normally expect after
a "quit" is:
15:58:08 04.58.08 JOB 2 $HASP250 TERMHERC IS PURGED
15:58:08 HHCAO003I Firing command: 'script conf/termherc2.rc'
15:58:08 script conf/termherc2.rc
15:58:08 quit
15:58:08 HHCIN900I Begin Hercules shutdown
15:58:08 HHCIN901I Releasing configuration
15:58:08 HHCCP008I CPU0000 thread ended: tid=00002390, pid=8160
15:58:08 HHCCF047I Subchannel 0:0000 detached
15:58:08 HHCTT003I Timer thread ended
15:58:08 HHCCF047I Subchannel 0:0001 detached
15:58:08 HHCCF047I Subchannel 0:0002 detached
15:58:08 HHCCF047I Subchannel 0:0003 detached
15:58:08 HHCCF047I Subchannel 0:0004 detached
15:58:08 HHCCD210I size free nbr st reads writes l2reads hits switches
15:58:08 HHCCD211I readaheads misses
15:58:08 HHCCD212I --------------------------------------------------------------------
15:58:08 HHCCD213I [*] 18648958 0% 20 1122 25 34 1037 2001
15:58:08 HHCCD214I 161 23
15:58:08 HHCCD215I dasd/mvsres.148
15:58:08 HHCCD216I [0] 15179178 0% 1 ro 942 0 17
15:58:08 HHCCD217I shadow/mvsres_*.148
15:58:08 HHCCD218I [1] 3469780 0% 19 180 25 17
15:58:08 HHCCF047I Subchannel 0:0005 detached
15:58:08 HHCCD210I size free nbr st reads writes l2reads hits switches
15:58:08 HHCCD212I --------------------------------------------------------------------
15:58:08 HHCCD213I [*] 35424 0% 1 1 0 1 0 1
15:58:08 HHCCD215I dasd/sort01.131
(etc)
Does anyone recognize the problem?
If not, I will attempt to reproduce the
problem with a later version of Hercules.
I'll need to change my job a bit though,
since it relies on OMA extensions.
Full log of first failure below.
Thanks. Paul.
15:37:44 Hercules Version 3.07:380-4.x
15:37:44 (c)Copyright 1999-2010 by Roger Bowler, Jan Jaeger, and others
15:37:44 Built on Dec 7 2016 at 12:43:32
15:37:44 Build information:
15:37:44 Windows (MSVC) build for AMD64
15:37:44 Modes: S/370 S/380 ESA/390 z/Arch
15:37:44 Max CPU Engines: 8
15:37:44 Using fthreads instead of pthreads
15:37:44 Dynamic loading support
15:37:44 Using shared libraries
15:37:44 HTTP Server support
15:37:44 No SIGABEND handler
15:37:44 Regular Expressions support
15:37:44 Automatic Operator support
15:37:44 Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8
15:37:44 Running on PAUL-DELL Windows_NT-6.2 AMD64 MP=8
15:37:44 HHCHD018I Loadable module directory is hercules
15:37:44 Crypto module loaded (c) Copyright Bernard van der Helm, 2003-2010
15:37:44 Active: Message Security Assist
15:37:44 Message Security Assist Extension 1
15:37:44 Message Security Assist Extension 2
15:37:44 HHCPN210I Default Allowed AUTOMOUNT directory = "c:\mvs380\"
15:37:44 HHCHT001I HTTP listener thread started: tid=00001C94, pid=17944
15:37:44 HHCCF065I Hercules: tid=00002AE8, pid=17944, pgid=17944, priority=8
15:37:44 HHCCF066E Invalid HTTPROOT: "c:\herc380\html": No such file or directory
15:37:44 HHCSD004I Device 000C bound to socket 127.0.0.1:3505
15:37:44 HHCSD020I Socketdevice listener thread started: tid=0000204C, pid=17944
15:37:44 HHCCF083I conf/mvs380.conf Including conf/mvs380_DASD.conf at 122 .
15:37:44 HHCDA004I opening dasd/mvsres.148 readonly
15:37:44 HHCDA020I dasd/mvsres.148 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/sort01.131 readonly
15:37:44 HHCDA020I dasd/sort01.131 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort02.132 readonly
15:37:44 HHCDA020I dasd/sort02.132 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort03.133 readonly
15:37:44 HHCDA020I dasd/sort03.133 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort04.134 readonly
15:37:44 HHCDA020I dasd/sort04.134 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort05.135 readonly
15:37:44 HHCDA020I dasd/sort05.135 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/sort06.136 readonly
15:37:44 HHCDA020I dasd/sort06.136 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/work00.140 readonly
15:37:44 HHCDA020I dasd/work00.140 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA020I dasd/hasp00.152 cyls=404 heads=19 tracks=7676 trklen=13312
15:37:44 HHCDA020I dasd/page00.160 cyls=698 heads=12 tracks=8376 trklen=8704
15:37:44 HHCDA020I dasd/page01.161 cyls=698 heads=12 tracks=8376 trklen=8704
15:37:44 HHCDA020I dasd/page02.162 cyls=698 heads=12 tracks=8376 trklen=8704
15:37:44 HHCDA020I dasd/work01.170 cyls=962 heads=12 tracks=11544 trklen=35840
15:37:44 HHCDA004I opening dasd/work02.180 readonly
15:37:44 HHCDA020I dasd/work02.180 cyls=886 heads=15 tracks=13290 trklen=47616
15:37:44 HHCDA004I opening dasd/work03.190 readonly
15:37:44 HHCDA020I dasd/work03.190 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/mvscat.191 readonly
15:37:44 HHCDA020I dasd/mvscat.191 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/seasik.192 readonly
15:37:44 HHCDA020I dasd/seasik.192 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA020I dasd/mvssrc.193 cyls=2226 heads=15 tracks=33390 trklen=56832
15:37:44 HHCDA002E 01B4:File not found or invalid 'dasd/pub004.1b4'
15:37:44 HHCCF044E Initialization failed for device 01B4
15:37:44 HHCDA004I opening dasd/pub000.240 readonly
15:37:44 HHCDA020I dasd/pub000.240 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/mvsdlb.248 readonly
15:37:44 HHCDA020I dasd/mvsdlb.248 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/pub002.280 readonly
15:37:44 HHCDA020I dasd/pub002.280 cyls=1772 heads=15 tracks=26580 trklen=47616
15:37:44 HHCDA004I opening dasd/tmptmp.2b1 readonly
15:37:44 HHCDA020I dasd/tmptmp.2b1 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/xmit90.2b2 readonly
15:37:44 HHCDA020I dasd/xmit90.2b2 cyls=1114 heads=15 tracks=16710 trklen=56832
15:37:44 HHCDA004I opening dasd/start1.150 readonly
15:37:44 HHCDA020I dasd/start1.150 cyls=808 heads=19 tracks=15352 trklen=13312
15:37:44 HHCDA004I opening dasd/spool0.151 readonly
15:37:44 HHCDA020I dasd/spool0.151 cyls=808 heads=19 tracks=15352 trklen=13312
15:37:44 HHCDA004I opening dasd/cbt000.340 readonly
15:37:44 HHCDA020I dasd/cbt000.340 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/cbt001.341 readonly
15:37:44 HHCDA020I dasd/cbt001.341 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/cbt002.342 readonly
15:37:44 HHCDA020I dasd/cbt002.342 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/cbtcat.343 readonly
15:37:44 HHCDA020I dasd/cbtcat.343 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/src000.348 readonly
15:37:44 HHCDA020I dasd/src000.348 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/src001.349 readonly
15:37:44 HHCDA020I dasd/src001.349 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/src002.34a readonly
15:37:44 HHCDA020I dasd/src002.34a cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/srccat.34b readonly
15:37:44 HHCDA020I dasd/srccat.34b cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/smp001.149 readonly
15:37:44 HHCDA020I dasd/smp001.149 cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/smp002.14a readonly
15:37:44 HHCDA020I dasd/smp002.14a cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/smp003.14b readonly
15:37:44 HHCDA020I dasd/smp003.14b cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/smp004.14c readonly
15:37:44 HHCDA020I dasd/smp004.14c cyls=560 heads=30 tracks=16800 trklen=19456
15:37:44 HHCDA004I opening dasd/js2sp0.700 readonly
15:37:44 HHCDA020I dasd/js2sp0.700 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/dlicat.138 readonly
15:37:44 HHCDA020I dasd/dlicat.138 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dlisys.139 readonly
15:37:44 HHCDA020I dasd/dlisys.139 cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dli000.13a readonly
15:37:44 HHCDA020I dasd/dli000.13a cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dli001.13b readonly
15:37:44 HHCDA020I dasd/dli001.13b cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/dli002.13c readonly
15:37:44 HHCDA020I dasd/dli002.13c cyls=200 heads=20 tracks=4000 trklen=7680
15:37:44 HHCDA004I opening dasd/js3sp0.710 readonly
15:37:44 HHCDA020I dasd/js3sp0.710 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCDA004I opening dasd/js3res.711 readonly
15:37:44 HHCDA020I dasd/js3res.711 cyls=555 heads=30 tracks=16650 trklen=19456
15:37:44 HHCTE001I Console connection thread started: tid=00004790, pid=17944
15:37:44 HHCTE003I Waiting for console connection on port 3270
15:37:44 HHCTA066I 0400: option 'level' accepted.
15:37:44 HHCTA066I 0401: option 'level' accepted.
15:37:44 HHCTA066I 0402: option 'level' accepted.
15:37:44 HHCTA066I 0403: option 'level' accepted.
15:37:44 HHCCP002I CPU0000 thread started: tid=00001AE8, pid=17944, priority=0
15:37:44 HHCCP003I CPU0000 architecture mode S/380
15:37:44 HHCTT002I Timer thread started: tid=0000462C, pid=17944, priority=-20
15:37:44 HHCPN001I Control panel thread started: tid=00002AE8, pid=17944
15:37:44 HHCPN008I Script file processing started using file "conf/auto_run.rc"
15:37:44 HHCAO001I Hercules Automatic Operator thread started;
15:37:44 tid=00003358, pri=0, pid=17944
15:37:44 devlist
15:37:44 0:000C 3505 127.0.0.1:3505 sockdev ascii trunc eof
15:37:44 (no one currently connected)
15:37:44 0:000D 3525 pch/pch00d.txt ascii crlf
15:37:44 0:000E 1403 prt/prt00e.txt crlf noclear
15:37:44 0:000F 1403 prt/prt00f.txt crlf noclear
15:37:44 0:001F 3215 *syscons cmdpref(/)
15:37:44 0:00C0 3270
15:37:44 0:00C1 3270
15:37:44 0:00C2 3270
15:37:44 0:00C7 3287
15:37:44 0:010C 3505 jcl/dummy eof
15:37:44 0:0131 2314 dasd/sort01.131 [200 cyls] open
15:37:44 0:0132 2314 dasd/sort02.132 [200 cyls] open
15:37:44 0:0133 2314 dasd/sort03.133 [200 cyls] open
15:37:44 0:0134 2314 dasd/sort04.134 [200 cyls] open
15:37:44 0:0135 2314 dasd/sort05.135 [200 cyls] open
15:37:44 0:0136 2314 dasd/sort06.136 [200 cyls] open
15:37:44 0:0138 2314 dasd/dlicat.138 [200 cyls] open
15:37:44 0:0139 2314 dasd/dlisys.139 [200 cyls] open
15:37:44 0:013A 2314 dasd/dli000.13a [200 cyls] open
15:37:44 0:013B 2314 dasd/dli001.13b [200 cyls] open
15:37:44 0:013C 2314 dasd/dli002.13c [200 cyls] open
15:37:44 0:0140 3350 dasd/work00.140 [560 cyls] open
15:37:44 0:0148 3350 dasd/mvsres.148 [560 cyls] open
15:37:44 0:0149 3350 dasd/smp001.149 [560 cyls] open
15:37:44 0:014A 3350 dasd/smp002.14a [560 cyls] open
15:37:44 0:014B 3350 dasd/smp003.14b [560 cyls] open
15:37:44 0:014C 3350 dasd/smp004.14c [560 cyls] open
15:37:44 0:0150 3330 dasd/start1.150 [808 cyls] open
15:37:44 0:0151 3330 dasd/spool0.151 [808 cyls] open
15:37:44 0:0152 3330 dasd/hasp00.152 [404 cyls] open
15:37:44 0:0160 3340 dasd/page00.160 [698 cyls] open
15:37:44 0:0161 3340 dasd/page01.161 [698 cyls] open
15:37:44 0:0162 3340 dasd/page02.162 [698 cyls] open
15:37:44 0:0170 3375 dasd/work01.170 [962 cyls] open
15:37:44 0:01A0 3380 dasd/work02.180 [886 cyls] open
15:37:44 0:01B0 3390 dasd/work03.190 [1114 cyls] open
15:37:44 0:01B1 3390 dasd/mvscat.191 [1114 cyls] open
15:37:44 0:01B2 3390 dasd/seasik.192 [1114 cyls] open
15:37:44 0:01B3 3390 dasd/mvssrc.193 [2226 cyls] open
15:37:44 0:01C7 3287
15:37:44 0:0240 3350 dasd/pub000.240 [560 cyls] open
15:37:44 0:0248 3350 dasd/mvsdlb.248 [560 cyls] open
15:37:44 0:02A0 3380 dasd/pub002.280 [1772 cyls] open
15:37:44 0:02B1 3390 dasd/tmptmp.2b1 [1114 cyls] open
15:37:44 0:02B2 3390 dasd/xmit90.2b2 [1114 cyls] open
15:37:44 0:030E 1403 log/hardcopy.log crlf noclear
15:37:44 0:0340 3350 dasd/cbt000.340 [555 cyls] open
15:37:44 0:0341 3350 dasd/cbt001.341 [555 cyls] open
15:37:44 0:0342 3350 dasd/cbt002.342 [555 cyls] open
15:37:44 0:0343 3350 dasd/cbtcat.343 [555 cyls] open
15:37:44 0:0348 3350 dasd/src000.348 [555 cyls] open
15:37:44 0:0349 3350 dasd/src001.349 [555 cyls] open
15:37:44 0:034A 3350 dasd/src002.34a [555 cyls] open
15:37:44 0:034B 3350 dasd/srccat.34b [555 cyls] open
15:37:44 0:0400 3420 *
15:37:44 0:0401 3420 *
15:37:44 0:0402 3420 *
15:37:44 0:0403 3420 *
15:37:44 0:0700 3350 dasd/js2sp0.700 [555 cyls] open
15:37:44 0:0710 3350 dasd/js3sp0.710 [555 cyls] open
15:37:44 0:0711 3350 dasd/js3res.711 [555 cyls] open
15:37:44 logopt timestamp
15:37:44 HHCPN197I Log option set: TIMESTAMP
15:37:44 panrate 1000
15:37:44 # really need to wait for SVC120I, but if building MVS/380
15:37:44 # or some other stuffup with parms, need to trigger on an
15:37:44 # alternative. First one hit will clear targets.
15:37:44 # If we get a prompt for a device, cancel it
15:37:44 hao tgt IEF238D
15:37:44 HHCAO016I Target placed at index 0
15:37:44 hao cmd script conf/cancel.rc
15:37:44 HHCAO020I Command placed at index 0
15:37:44 hao tgt HASP395 DYNAMASK
15:37:44 HHCAO016I Target placed at index 1
15:37:44 hao cmd script conf/subjobs_slow.rc
15:37:44 HHCAO020I Command placed at index 1
15:37:44 hao tgt HASP373 SVC120I
15:37:44 HHCAO016I Target placed at index 2
15:37:44 hao cmd script conf/subjobs_fast.rc
15:37:44 HHCAO020I Command placed at index 2
15:37:44 hao tgt HASP436 REPLY
15:37:44 HHCAO016I Target placed at index 3
15:37:44 hao cmd script conf/replyy.rc
15:37:44 HHCAO020I Command placed at index 3
15:37:44 devinit 402 tapes/mftopc.het
15:37:44 HHCTA004I 0402: tapes/mftopc.het is a Hercules Emulated Tape file
15:37:44 HHCPN098I Device 0:0402 initialized
15:37:44 devinit 403 tapes/awstap.aws
15:37:44 HHCTA004I 0403: tapes/awstap.aws is a Hercules Emulated Tape file
15:37:44 HHCPN098I Device 0:0403 initialized
15:37:44 # co will give you a cold start of JES2 which is useful in
15:37:44 # automated runs
15:37:44 /(001F) r 00,clpa,cmd=co
15:37:44 #/r 00,clpa
15:37:44 ipl 148
15:37:44 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:45 IEA101A SPECIFY SYSTEM PARMS FOR MVS/380 1.2 v03.8 TK3+
15:37:45 HHCCD001I Readahead thread 1 started: tid=0000239C, pid=17944
15:37:45 HHCCD001I Readahead thread 2 started: tid=0000203C, pid=17944
15:37:45 HHCCD002I Writer thread 1 started: tid=00001BF8, pid=17944
15:37:45 HHCCD003I Garbage collector thread started: tid=00003AC0, pid=17944
15:37:45 IEA940I THE FOLLOWING PAGE DATA SETS ARE IN USE
15:37:45 PLPA ... SYS1.PAGELPA
15:37:45 COMMON . SYS1.PAGECSA
15:37:45 DUPLEX . SYS1.DUPLEX
15:37:45 LOCAL .. SYS1.PAGEL01
15:37:45 LOCAL .. SYS1.PAGEL02
15:37:45 LOCAL .. SYS1.PAGEL03
15:37:45 HHCCD002I Writer thread 2 started: tid=000036C4, pid=17944
15:37:46 IEE360I SMF NOW RECORDING ON SYS1.MANX ON MVSRES TIME=04.37.46
15:37:46 IGF992I MIH INIT COMPLETE, PRI=000300, SEC=000015
15:37:46 IEF677I WARNING MESSAGE(S) FOR JOB JES2 ISSUED
15:37:47 *00 $HASP436 REPLY Y OR N TO CONFIRM CHECKPOINT RECORD CHANGE
15:37:47 HHCAO003I Firing command: 'script conf/replyy.rc'
15:37:47 script conf/replyy.rc
15:37:47 /(001F) reply 00,y
15:37:47 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:47 IEE600I REPLY TO 00 IS;SUPPRESSED
15:37:47 $HASP493 JES2 COLD-START IS IN PROGRESS
15:37:47 $HASP412 MAXIMUM OF 1 READER(S) EXCEEDED
15:37:47 04.37.47 IEE041I THE SYSTEM LOG IS NOW ACTIVE
15:37:47 04.37.47 IEE302I 00E ONLINE
15:37:47 04.37.47 IEE302I 00F ONLINE
15:37:47 04.37.47 IEE313I 30E UNIT REF INVALID
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 IEE450I 04.37.47 UNIT STATUS 159
15:37:47 UNIT TYPE STATUS VOLSER VOLSTATE UNIT TYPE STATUS VOLSER VOLSTATE
15:37:47 400 3400 O /REMOV 401 3400 O /REMOV
15:37:47 402 3400 O /REMOV
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP000 OK
15:37:47 04.37.47 $HASP160 PRINTER1 INACTIVE - CLASS=AP
15:37:47 04.37.47 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:47 04.37.47 $HASP160 PUNCH1 INACTIVE - CLASS=B
15:37:47 04.37.47 STC 2 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 2 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 2 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 3 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 3 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 3 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 4 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 4 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 4 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 5 $HASP100 INIT ON STCINRDR
15:37:47 04.37.47 STC 5 $HASP373 INIT STARTED
15:37:47 04.37.47 STC 5 IEF403I INIT - STARTED - TIME=04.37.47
15:37:47 04.37.47 STC 6 $HASP100 INIT ON STCINRDR
15:37:48 04.37.48 STC 6 $HASP373 INIT STARTED
15:37:48 04.37.48 STC 6 IEF403I INIT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 7 $HASP100 INIT ON STCINRDR
15:37:48 04.37.48 STC 7 $HASP373 INIT STARTED
15:37:48 04.37.48 STC 7 IEF403I INIT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 8 $HASP100 INIT ON STCINRDR
15:37:48 04.37.48 STC 8 $HASP373 INIT STARTED
15:37:48 04.37.48 STC 8 IEF403I INIT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 9 $HASP100 SVC120I ON STCINRDR
15:37:48 04.37.48 STC 9 $HASP373 SVC120I STARTED
15:37:48 HHCAO003I Firing command: 'script conf/subjobs_fast.rc'
15:37:48 script conf/subjobs_fast.rc
15:37:48 # Now we know that SVC120I has started. But due to some
15:37:48 # weird pausing, it may get locked out. So clear out
15:37:48 # other triggers and wait on this
15:37:48 hao clear
15:37:48 HHCAO022I All automatic operation rules cleared
15:37:48 hao tgt HASP250 SVC120I
15:37:48 HHCAO016I Target placed at index 0
15:37:48 hao cmd script conf/subjobs.rc
15:37:48 HHCAO020I Command placed at index 0
15:37:48 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:48 04.37.48 STC 9 IEF403I SVC120I - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 10 $HASP100 DYNABLDL ON STCINRDR
15:37:48 04.37.48 STC 10 $HASP373 DYNABLDL STARTED
15:37:48 04.37.48 STC 10 IEF403I DYNABLDL - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 11 $HASP100 DYNAMASK ON STCINRDR
15:37:48 04.37.48 STC 11 $HASP373 DYNAMASK STARTED
15:37:48 04.37.48 STC 11 IEF403I DYNAMASK - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 12 $HASP100 BSPPILOT ON STCINRDR
15:37:48 04.37.48 STC 12 $HASP373 BSPPILOT STARTED
15:37:48 04.37.48 STC 12 IEF403I BSPPILOT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 13 $HASP100 BSPSETPF ON STCINRDR
15:37:48 04.37.48 STC 13 $HASP373 BSPSETPF STARTED
15:37:48 04.37.48 STC 13 IEF403I BSPSETPF - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 14 $HASP100 LOGRECI ON STCINRDR
15:37:48 04.37.48 STC 14 $HASP373 LOGRECI STARTED
15:37:48 04.37.48 STC 14 IEF403I LOGRECI - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 15 $HASP100 NET ON STCINRDR
15:37:48 04.37.48 STC 15 $HASP373 NET STARTED
15:37:48 04.37.48 STC 15 IEF403I NET - STARTED - TIME=04.37.48
15:37:48 04.37.48 $HASP309 INIT 1 INACTIVE ******** C=A
15:37:48 04.37.48 $HASP309 INIT 2 INACTIVE ******** C=BA
15:37:48 04.37.48 $HASP309 INIT 3 INACTIVE ******** C=CBA
15:37:48 04.37.48 $HASP309 INIT 4 INACTIVE ******** C=SHB
15:37:48 04.37.48 $HASP309 INIT 5 INACTIVE ******** C=SBA
15:37:48 04.37.48 $HASP309 INIT 6 INACTIVE ******** C=S
15:37:48 04.37.48 $HASP309 INIT 7 INACTIVE ******** C=E
15:37:48 04.37.48 STC 9 BSPGM40I - 200 MiB MAINSIZE memory available
15:37:48 04.37.48 STC 9 BSPGM41I - 2 Partitions of 64 MiB each
15:37:48 04.37.48 STC 9 BSPGM78I SVC 120 EP=00FE3248; MVS/380
15:37:48 04.37.48 STC 9 IEF404I SVC120I - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 9 $HASP395 SVC120I ENDED
15:37:48 04.37.48 STC 9 $HASP150 SVC120I ON PRINTER2 45 LINES
15:37:48 04.37.48 STC 9 *$HASP190 SVC120I SETUP -- PRINTER2 -- F = 0001 -- C = 6 -- T = SN
15:37:48 04.37.48 $HASP000 OK
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 9 $HASP250 SVC120I IS PURGED
15:37:48 HHCAO003I Firing command: 'script conf/subjobs.rc'
15:37:48 script conf/subjobs.rc
15:37:48 hao clear
15:37:48 HHCAO022I All automatic operation rules cleared
15:37:48 # Every job gets an NL tape available as input, containing
15:37:48 # some binary of unknown contents, most likely needing to
15:37:48 # be read as RECFM=U, but RECFM=FB and even RECFM=V are also
15:37:48 # possible.
15:37:48 #
15:37:48 # The job also gets an SL tape available for output, and
15:37:48 # again, any type of content can be written to it, and
15:37:48 # with a bit of luck, hetget will be able to extract the
15:37:48 # data you are looking for.
15:37:48 #
15:37:48 # And finally the job gets an SL AWS tape available for
15:37:48 # input and/or output should you wish to construct a
15:37:48 # special tape. Tape must be called AWSTAP. User should
15:37:48 # back the tape up before submitting it, because it will
15:37:48 # be overwritten and anything could go wrong. AWS is
15:37:48 # expected to be exceptional use of this procedure anyway
15:37:48 #
15:37:48 # Only the NL tape needs an explicit mount. The SL tapes
15:37:48 # are premounted before IPL
15:37:48 hao tgt HASP250 MOUNT
15:37:48 HHCAO016I Target placed at index 0
15:37:48 hao cmd script conf/subjobs2.rc
15:37:48 HHCAO020I Command placed at index 0
15:37:48 /(001F) M 401,VOL=(NL,PCTOMF)
15:37:48 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:48 04.37.48 STC 16 $HASP100 MOUNT ON STCINRDR
15:37:48 04.37.48 STC 16 $HASP373 MOUNT STARTED
15:37:48 04.37.48 STC 16 IEF403I MOUNT - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 16 *IEF233A M 401,PCTOMF,,MOUNT,401
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAE IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
15:37:48 04.37.48 STC 15 IST025I BLDL FAILED FOR IEDIAK IN VTAMLIB
15:37:48 04.37.48 STC 15 IST110I NETWORK SOLICITOR STARTED
15:37:48 04.37.48 STC 15 IST093I APPLJRP ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLPIES ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLPIAD ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLTSO ACTIVE
15:37:48 04.37.48 STC 15 IST093I APPLTEST ACTIVE
15:37:48 04.37.48 STC 10 DYNABLDL STARTED
15:37:48 04.37.48 STC 15 IST093I LCLMAJRP ACTIVE
15:37:48 04.37.48 STC 15 IST093I LCLMAJ00 ACTIVE
15:37:48 04.37.48 STC 17 $HASP100 TSO ON STCINRDR
15:37:48 04.37.48 STC 17 $HASP373 TSO STARTED
15:37:48 04.37.48 STC 17 IEF403I TSO - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 18 $HASP100 JRP ON STCINRDR
15:37:48 04.37.48 STC 18 $HASP373 JRP STARTED
15:37:48 04.37.48 STC 18 IEF403I JRP - STARTED - TIME=04.37.48
15:37:48 04.37.48 $HASP000 OK
15:37:48 04.37.48 $HASP000 OK
15:37:48 04.37.48 STC 15 IST020I VTAM INITIALIZATION COMPLETE
15:37:48 04.37.48 STC 15 IEA000I 0C0,IOE,05,0200,400000000001,,,NET ,04.37.48
15:37:48 04.37.48 STC 15 IEA000I 0C1,IOE,05,0200,400000000001,,,NET ,04.37.48
15:37:48 04.37.48 STC 15 IEA000I 0C2,IOE,05,0200,400000000001,,,NET ,04.37.48
15:37:48 04.37.48 STC 10 IEF404I DYNABLDL - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 10 $HASP395 DYNABLDL ENDED
15:37:48 04.37.48 STC 10 $HASP150 DYNABLDL ON PRINTER2 21 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 10 $HASP250 DYNABLDL IS PURGED
15:37:48 04.37.48 STC 11 DMSK00I DYNAMASK DONE ****
15:37:48 04.37.48 STC 11 DMSK06I START
15:37:48 04.37.48 STC 11 IEF404I DYNAMASK - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 11 $HASP395 DYNAMASK ENDED
15:37:48 04.37.48 STC 11 $HASP150 DYNAMASK ON PRINTER2 30 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 11 $HASP250 DYNAMASK IS PURGED
15:37:48 04.37.48 STC 13 BSPSP91I - Parms passed: NOREPLYU
15:37:48 04.37.48 STC 13 BSPSP93I - PFK definitions will be updated in memory
15:37:48 04.37.48 STC 13 BSPSP22I - Dataset processed: SYS1.PARMLIB
15:37:48 04.37.48 STC 13 BSPSP23I - on volume MVSRES
15:37:48 04.37.48 STC 13 BSPSP21I - Member being processed: SETPFK01
15:37:48 04.37.48 STC 13 +BSPSP98I - Member processed, LASTCC=0000
15:37:48 04.37.48 STC 13 +BSPSP21I - Member being processed: SETPFK02
15:37:48 04.37.48 STC 13 +BSPSP98I - Member processed, LASTCC=0000
15:37:48 04.37.48 STC 13 +BSPSP99I - End of processing, MAXRC=0000
15:37:48 04.37.48 STC 13 IEF404I BSPSETPF - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 13 $HASP395 BSPSETPF ENDED
15:37:48 04.37.48 STC 13 $HASP150 BSPSETPF ON PRINTER2 34 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 13 $HASP250 BSPSETPF IS PURGED
15:37:48 04.37.48 STC 14 IFC001I D=3350 N=0B F=01AB0000 L=01AC0005 S=01AB000002 DIP COMPLETE
15:37:48 04.37.48 STC 14 IEF404I LOGRECI - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 14 $HASP395 LOGRECI ENDED
15:37:48 04.37.48 STC 14 $HASP150 LOGRECI ON PRINTER2 20 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 14 $HASP250 LOGRECI IS PURGED
15:37:48 04.37.48 STC 16 IEF404I MOUNT - ENDED - TIME=04.37.48
15:37:48 04.37.48 STC 16 $HASP395 MOUNT ENDED
15:37:48 04.37.48 STC 16 $HASP150 MOUNT ON PRINTER2 18 LINES
15:37:48 04.37.48 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:48 04.37.48 STC 16 $HASP250 MOUNT IS PURGED
15:37:48 HHCAO003I Firing command: 'script conf/subjobs2.rc'
15:37:48 script conf/subjobs2.rc
15:37:48 hao clear
15:37:48 HHCAO022I All automatic operation rules cleared
15:37:48 # If we get a prompt for a device, cancel it
15:37:48 hao tgt IEF238D
15:37:48 HHCAO016I Target placed at index 0
15:37:48 hao cmd script conf/cancel.rc
15:37:48 HHCAO020I Command placed at index 0
15:37:48 # If we get a prompt for a catalogue password, answer it
15:37:48 hao tgt IEC301A
15:37:48 HHCAO016I Target placed at index 1
15:37:48 hao cmd script conf/secret.rc
15:37:48 HHCAO020I Command placed at index 1
15:37:48 devinit 401 tapes/pctomf.tdf
15:37:48 HHCTA004I 0401: tapes/pctomf.tdf is a Optical Media Attachment (OMA) tape
15:37:48 HHCPN098I Device 0:0401 initialized
15:37:48 # When we see TERMHERC get purged, our job is done
15:37:48 hao tgt HASP373 TERMHERC
15:37:48 HHCAO016I Target placed at index 2
15:37:48 hao cmd script conf/termherc.rc
15:37:48 HHCAO020I Command placed at index 2
15:37:48 # Now submit the job
15:37:48 devinit 00c jcl/hercauto.jcl eof
15:37:48 HHCSD007I Device 000C unbound from socket 127.0.0.1:3505
15:37:48 HHCSD022I Socketdevice listener thread terminated
15:37:48 HHCPN098I Device 0:000C initialized
15:37:48 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:48 04.37.48 JOB 1 $HASP100 MVSGCC ON READER1
15:37:48 04.37.48 JOB 2 $HASP100 TERMHERC ON READER1
15:37:48 04.37.48 JOB 1 $HASP373 MVSGCC STARTED - INIT 3 - CLASS C - SYS BSP1
15:37:48 04.37.48 JOB 1 IEF403I MVSGCC - STARTED - TIME=04.37.48
15:37:48 04.37.48 STC 17 IKT007I TCAS ACCEPTING LOGONS
15:37:48 04.37.48 STC 17 IKT005I TCAS IS INITIALIZED
15:37:48 04.37.48 JOB 1 *IEF233A M 401,PCTOMF,,MVSGCC,COMP
15:37:49 04.37.49 STC 18 JRPI101 INITIALIZATION COMPLETE
15:37:49 04.37.49 STC 18 *01 JRP100I - ENTER ICLOSE TO SHUT DOWN
15:37:49 04.37.49 JOB 1 IEC705I TAPE ON 402,MFTOPC,SL,6250 BPI,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEF234E K 402,MFTOPC,PVT,MVSGCC,COMP
15:37:49 04.37.49 JOB 1 IEFACTRT - Stepname Procstep Program Retcode
15:37:49 04.37.49 JOB 1 MVSGCC S1 COMP GCC RC= 0000
15:37:49 04.37.49 JOB 1 IEF404I MVSGCC - ENDED - TIME=04.37.49
15:37:49 04.37.49 JOB 1 $HASP395 MVSGCC ENDED
15:37:49 04.37.49 JOB 1 $HASP150 MVSGCC ON PRINTER1 98 LINES
15:37:49 04.37.49 JOB 1 *$HASP190 MVSGCC SETUP -- PRINTER1 -- F = 0001 -- C = 6 -- T = SN
15:37:49 04.37.49 $HASP000 OK
15:37:49 04.37.49 $HASP160 PRINTER1 INACTIVE - CLASS=AP
15:37:49 04.37.49 JOB 1 $HASP250 MVSGCC IS PURGED
15:37:49 04.37.49 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
15:37:49 HHCAO003I Firing command: 'script conf/termherc.rc'
15:37:49 script conf/termherc.rc
15:37:49 # We do an unnecessary 2-stage terminate, first triggering
15:37:49 # on the start message, then triggering on the purged
15:37:49 # message, to overcome an apparent bug in hercules which
15:37:49 # causes it to sometimes trigger on the wrong jobname.
15:37:49 hao clear
15:37:49 HHCAO022I All automatic operation rules cleared
15:37:49 hao tgt HASP250 TERMHERC
15:37:49 HHCAO016I Target placed at index 0
15:37:49 hao cmd script conf/termherc2.rc
15:37:49 HHCAO020I Command placed at index 0
15:37:49 HHCPN013I EOF reached on SCRIPT file. Processing complete.
15:37:49 04.37.49 JOB 2 IEF403I TERMHERC - STARTED - TIME=04.37.49
15:37:49 04.37.49 JOB 2 IEFACTRT - Stepname Procstep Program Retcode
15:37:49 04.37.49 JOB 2 TERMHERC S1 IEBGENER RC= 0000
15:37:49 04.37.49 JOB 2 IEF404I TERMHERC - ENDED - TIME=04.37.49
15:37:49 04.37.49 JOB 2 $HASP395 TERMHERC ENDED
15:37:49 04.37.49 $HASP309 INIT 3 INACTIVE ******** C=CBA
15:37:49 04.37.49 JOB 2 $HASP150 TERMHERC ON PRINTER2 44 LINES
15:37:49 04.37.49 JOB 2 $HASP150 TERMHERC ON PRINTER1 1 LINE
15:37:49 04.37.49 $HASP160 PRINTER1 INACTIVE - CLASS=AP
15:37:49 04.37.49 $HASP160 PRINTER2 INACTIVE - CLASS=Z
15:37:49 04.37.49 JOB 2 $HASP250 TERMHERC IS PURGED
15:37:49 HHCAO003I Firing command: 'script conf/termherc2.rc'
15:37:49 script conf/termherc2.rc
15:37:49 quit
15:37:49 HHCIN900I Begin Hercules shutdown
15:37:49 HHCIN901I Releasing configuration