MVS anomalies

classic Classic list List threaded Threaded
54 messages Options
123
Reply | Threaded
Open this post in threaded view
|

MVS anomalies

Hercules390 - Mvs mailing list
I have been running thousands (literally) of
automated runs of MVS which include IPLing,
running IEFBR14 as a batch job, then
quitting (dropping power).

All was going "fine" until finally it froze
during a run. It froze because the printer
output did not get printed and purged,
which is the trigger to quit. Based on
this output of a good run:

17:55:33 06.55.33 JOB    1 *$HASP190 HERC01A  SETUP -- PRINTER1 -- F = 0001 -- C = 6    -- T = SN
17:55:33 06.55.33           $HASP000 OK
17:55:33 06.55.33 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1

my guess is that BSPPILOT is
automatically seeing that "setup
printer" message and automatically
issuing a $sprt1 or $sprinter1 or
whatever is required to get the
printer to continue printing.

In my bad run (full log below) I
instead see:

04:52:56 17.52.56 JOB    1 *$HASP190 HERC01A  SETUP -- PRINTER1 -- F = 0001 -- C = 6    -- T = SN
04:52:56 17.52.56 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1

Looking further in the log, I see
an error about DUMPFULL:

04:52:55 17.52.55 STC   19  $HASP100 DUMPFULL ON STCINRDR
04:52:55 17.52.55 STC   19  IEF452I DUMPFULL JOB NOT RUN - JCL ERROR
04:52:55 17.52.55 STC   19  $HASP396 DUMPFULL TERMINATED

I don't know why that is being started
or why it doesn't exist on my system.

I also see this:

04:52:55 17.52.55 STC   12 *IEA994A ALL SYS1.DUMP DATA SETS ARE FULL AND NO SVC DUMPS CAN BE TAKEN
04:52:55 17.52.55 STC   12  IEC909I 212-03,BSPPILOT,BSPPILOT,SYSDCB
04:52:55 17.52.55 STC   12  IEF450I BSPPILOT BSPPILOT - ABEND S212 U0000 - TIME=17.52.55
04:52:55 17.52.55 STC   12  IEF404I BSPPILOT - ENDED - TIME=17.52.55
04:52:55 17.52.55 STC   12  $HASP395 BSPPILOT ENDED

which would seem to explain why
BSPPILOT is not answering things -
because it has ended. In a good
run, BSPPILOT stays up forever.

Another thing I have noticed in
prior runs, not this exact run, is
that there is some VTOC conversion
thing happening:

04:52:45 17.52.45 STC   19  IEF403I SMFDAILY - STARTED - TIME=17.52.45
04:52:45 17.52.45 JOB    2  IEF403I TERMHERC - STARTED - TIME=17.52.45
04:52:45 17.52.45 STC   19  IEC604I VTOC CONVERT ROUTINE ENTERED ON 1B1,MVSCAT,DIRF
04:52:45 17.52.45 JOB    2  IEFACTRT - Stepname  Procstep  Program   Retcode
04:52:45 17.52.45 JOB    2  TERMHERC   S1                  IEBGENER  RC= 0000
04:52:45 17.52.45 JOB    2  IEF404I TERMHERC - ENDED - TIME=17.52.45
04:52:45 17.52.45 JOB    2  $HASP395 TERMHERC ENDED

That didn't use to happen.

My system is still up and running,
with the run below, so I am able
to enter any diagnostic commands,
and check printer output etc. Here
is some printer 2 (not 1) output:


                                                J E S 2   J O B   L O G


17.52.54 STC   12  $HASP373 BSPPILOT STARTED
17.52.54 STC   12  IEF403I BSPPILOT - STARTED - TIME=17.52.54
17.52.55 STC   12  S DUMPFULL
17.52.55 STC   12 *IEA994A ALL SYS1.DUMP DATA SETS ARE FULL AND NO SVC DUMPS CAN BE TAKEN
17.52.55 STC   12  IEC909I 212-03,BSPPILOT,BSPPILOT,SYSDCB
17.52.55 STC   12  IEF450I BSPPILOT BSPPILOT - ABEND S212 U0000 - TIME=17.52.55
17.52.55 STC   12  IEF404I BSPPILOT - ENDED - TIME=17.52.55
17.52.55 STC   12  $HASP395 BSPPILOT ENDED


Any suggestions? My goal is to
bulletproof Hercules & MVS so
that I can run thousands of fast,
automated runs, and have 0
errors due to timing or whatever.

Given that this is all automated I
am expecting consistent results.

Thanks. Paul.




04:52:46 Hercules Version 3.07:380-4.x
04:52:46 (c)Copyright 1999-2010 by Roger Bowler, Jan Jaeger, and others
04:52:46 Built on Dec  7 2016 at 12:43:32
04:52:46 Build information:
04:52:46   Windows (MSVC) build for AMD64
04:52:46   Modes: S/370 S/380 ESA/390 z/Arch
04:52:46   Max CPU Engines: 8
04:52:46   Using fthreads instead of pthreads
04:52:46   Dynamic loading support
04:52:46   Using shared libraries
04:52:46   HTTP Server support
04:52:46   No SIGABEND handler
04:52:46   Regular Expressions support
04:52:46   Automatic Operator support
04:52:46   Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8
04:52:46 Running on PAUL-DELL Windows_NT-6.2 AMD64 MP=8
04:52:46 HHCHD018I Loadable module directory is hercules
04:52:46 Crypto module loaded (c) Copyright Bernard van der Helm, 2003-2010
04:52:46   Active: Message Security Assist
04:52:46           Message Security Assist Extension 1
04:52:46           Message Security Assist Extension 2
04:52:46 HHCPN210I Default Allowed AUTOMOUNT directory = "c:\mvs380\"
04:52:46 HHCCF065I Hercules: tid=0000316C, pid=15616, pgid=15616, priority=8
04:52:46 HHCHT001I HTTP listener thread started: tid=0000315C, pid=15616
04:52:46 HHCHT013I Using HTTPROOT directory "c:\herc380\html\"
04:52:46 HHCHT006I Waiting for HTTP requests on port 8081
04:52:46 HHCSD004I Device 000C bound to socket 127.0.0.1:3505
04:52:46 HHCSD020I Socketdevice listener thread started: tid=00004548, pid=15616
04:52:46 HHCCF083I conf/mvs380.conf Including conf/mvs380_DASD.conf at 123 .
04:52:46 HHCDA004I opening dasd/mvsres.148 readonly
04:52:46 HHCDA020I dasd/mvsres.148 cyls=560 heads=30 tracks=16800 trklen=19456
04:52:46 HHCDA004I opening dasd/sort01.131 readonly
04:52:46 HHCDA020I dasd/sort01.131 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:46 HHCDA004I opening dasd/sort02.132 readonly
04:52:46 HHCDA020I dasd/sort02.132 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:46 HHCDA004I opening dasd/sort03.133 readonly
04:52:46 HHCDA020I dasd/sort03.133 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:46 HHCDA004I opening dasd/sort04.134 readonly
04:52:46 HHCDA020I dasd/sort04.134 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:46 HHCDA004I opening dasd/sort05.135 readonly
04:52:46 HHCDA020I dasd/sort05.135 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:46 HHCDA004I opening dasd/sort06.136 readonly
04:52:46 HHCDA020I dasd/sort06.136 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:46 HHCDA004I opening dasd/work00.140 readonly
04:52:46 HHCDA020I dasd/work00.140 cyls=560 heads=30 tracks=16800 trklen=19456
04:52:46 HHCDA020I dasd/hasp00.152 cyls=404 heads=19 tracks=7676 trklen=13312
04:52:46 HHCDA020I dasd/page00.160 cyls=698 heads=12 tracks=8376 trklen=8704
04:52:46 HHCDA020I dasd/page01.161 cyls=698 heads=12 tracks=8376 trklen=8704
04:52:46 HHCDA020I dasd/page02.162 cyls=698 heads=12 tracks=8376 trklen=8704
04:52:46 HHCDA020I dasd/work01.170 cyls=962 heads=12 tracks=11544 trklen=35840
04:52:46 HHCDA004I opening dasd/work02.180 readonly
04:52:46 HHCDA020I dasd/work02.180 cyls=886 heads=15 tracks=13290 trklen=47616
04:52:46 HHCDA004I opening dasd/work03.190 readonly
04:52:46 HHCDA020I dasd/work03.190 cyls=1114 heads=15 tracks=16710 trklen=56832
04:52:46 HHCDA004I opening dasd/mvscat.191 readonly
04:52:46 HHCDA020I dasd/mvscat.191 cyls=1114 heads=15 tracks=16710 trklen=56832
04:52:46 HHCDA004I opening dasd/seasik.192 readonly
04:52:46 HHCDA020I dasd/seasik.192 cyls=1114 heads=15 tracks=16710 trklen=56832
04:52:46 HHCDA020I dasd/mvssrc.193 cyls=2226 heads=15 tracks=33390 trklen=56832
04:52:46 HHCDA002E 01B4:File not found or invalid 'dasd/pub004.1b4'
04:52:46 HHCCF044E Initialization failed for device 01B4
04:52:46 HHCDA004I opening dasd/pub000.240 readonly
04:52:46 HHCDA020I dasd/pub000.240 cyls=560 heads=30 tracks=16800 trklen=19456
04:52:46 HHCDA004I opening dasd/mvsdlb.248 readonly
04:52:46 HHCDA020I dasd/mvsdlb.248 cyls=560 heads=30 tracks=16800 trklen=19456
04:52:46 HHCDA004I opening dasd/pub002.280 readonly
04:52:46 HHCDA020I dasd/pub002.280 cyls=1772 heads=15 tracks=26580 trklen=47616
04:52:46 HHCDA004I opening dasd/tmptmp.2b1 readonly
04:52:47 HHCDA020I dasd/tmptmp.2b1 cyls=1114 heads=15 tracks=16710 trklen=56832
04:52:47 HHCDA004I opening dasd/xmit90.2b2 readonly
04:52:47 HHCDA020I dasd/xmit90.2b2 cyls=1114 heads=15 tracks=16710 trklen=56832
04:52:47 HHCDA004I opening dasd/start1.150 readonly
04:52:47 HHCDA020I dasd/start1.150 cyls=808 heads=19 tracks=15352 trklen=13312
04:52:47 HHCDA004I opening dasd/spool0.151 readonly
04:52:47 HHCDA020I dasd/spool0.151 cyls=808 heads=19 tracks=15352 trklen=13312
04:52:47 HHCDA004I opening dasd/cbt000.340 readonly
04:52:47 HHCDA020I dasd/cbt000.340 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/cbt001.341 readonly
04:52:47 HHCDA020I dasd/cbt001.341 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/cbt002.342 readonly
04:52:47 HHCDA020I dasd/cbt002.342 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/cbtcat.343 readonly
04:52:47 HHCDA020I dasd/cbtcat.343 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/src000.348 readonly
04:52:47 HHCDA020I dasd/src000.348 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/src001.349 readonly
04:52:47 HHCDA020I dasd/src001.349 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/src002.34a readonly
04:52:47 HHCDA020I dasd/src002.34a cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/srccat.34b readonly
04:52:47 HHCDA020I dasd/srccat.34b cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/smp001.149 readonly
04:52:47 HHCDA020I dasd/smp001.149 cyls=560 heads=30 tracks=16800 trklen=19456
04:52:47 HHCDA004I opening dasd/smp002.14a readonly
04:52:47 HHCDA020I dasd/smp002.14a cyls=560 heads=30 tracks=16800 trklen=19456
04:52:47 HHCDA004I opening dasd/smp003.14b readonly
04:52:47 HHCDA020I dasd/smp003.14b cyls=560 heads=30 tracks=16800 trklen=19456
04:52:47 HHCDA004I opening dasd/smp004.14c readonly
04:52:47 HHCDA020I dasd/smp004.14c cyls=560 heads=30 tracks=16800 trklen=19456
04:52:47 HHCDA004I opening dasd/js2sp0.700 readonly
04:52:47 HHCDA020I dasd/js2sp0.700 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/dlicat.138 readonly
04:52:47 HHCDA020I dasd/dlicat.138 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:47 HHCDA004I opening dasd/dlisys.139 readonly
04:52:47 HHCDA020I dasd/dlisys.139 cyls=200 heads=20 tracks=4000 trklen=7680
04:52:47 HHCDA004I opening dasd/dli000.13a readonly
04:52:47 HHCDA020I dasd/dli000.13a cyls=200 heads=20 tracks=4000 trklen=7680
04:52:47 HHCDA004I opening dasd/dli001.13b readonly
04:52:47 HHCDA020I dasd/dli001.13b cyls=200 heads=20 tracks=4000 trklen=7680
04:52:47 HHCDA004I opening dasd/dli002.13c readonly
04:52:47 HHCDA020I dasd/dli002.13c cyls=200 heads=20 tracks=4000 trklen=7680
04:52:47 HHCDA004I opening dasd/js3sp0.710 readonly
04:52:47 HHCDA020I dasd/js3sp0.710 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCDA004I opening dasd/js3res.711 readonly
04:52:47 HHCDA020I dasd/js3res.711 cyls=555 heads=30 tracks=16650 trklen=19456
04:52:47 HHCTE001I Console connection thread started: tid=00004520, pid=15616
04:52:47 HHCTE003I Waiting for console connection on port 3270
04:52:47 HHCTA066I 0400: option 'level' accepted.
04:52:47 HHCTA066I 0401: option 'level' accepted.
04:52:47 HHCTA066I 0402: option 'level' accepted.
04:52:47 HHCTA066I 0403: option 'level' accepted.
04:52:47 HHCCP002I CPU0000 thread started: tid=00003264, pid=15616, priority=0
04:52:47 HHCCP003I CPU0000 architecture mode S/380
04:52:47 HHCPN001I Control panel thread started: tid=0000316C, pid=15616
04:52:47 HHCTT002I Timer thread started: tid=00000BEC, pid=15616, priority=-20
04:52:47 HHCPN008I Script file processing started using file "conf/auto_run.rc"
04:52:47 devlist
04:52:47 0:000C 3505 127.0.0.1:3505 sockdev ascii trunc eof
04:52:47      (no one currently connected)
04:52:47 0:000D 3525 pch/pch00d.txt ascii crlf
04:52:47 0:000E 1403 prt/prt00e.txt crlf noclear
04:52:47 0:000F 1403 prt/prt00f.txt crlf noclear
04:52:47 0:001F 3215 *syscons cmdpref(/)
04:52:47 0:00C0 3270  
04:52:47 0:00C1 3270  
04:52:47 0:00C2 3270  
04:52:47 0:00C7 3287  
04:52:47 0:010C 3505 jcl/dummy eof
04:52:47 0:0131 2314 dasd/sort01.131 [200 cyls] open
04:52:47 0:0132 2314 dasd/sort02.132 [200 cyls] open
04:52:47 0:0133 2314 dasd/sort03.133 [200 cyls] open
04:52:47 0:0134 2314 dasd/sort04.134 [200 cyls] open
04:52:47 0:0135 2314 dasd/sort05.135 [200 cyls] open
04:52:47 0:0136 2314 dasd/sort06.136 [200 cyls] open
04:52:47 0:0138 2314 dasd/dlicat.138 [200 cyls] open
04:52:47 HHCAO001I Hercules Automatic Operator thread started;
04:52:47           tid=00005008, pri=0, pid=15616
04:52:47 0:0139 2314 dasd/dlisys.139 [200 cyls] open
04:52:47 0:013A 2314 dasd/dli000.13a [200 cyls] open
04:52:47 0:013B 2314 dasd/dli001.13b [200 cyls] open
04:52:47 0:013C 2314 dasd/dli002.13c [200 cyls] open
04:52:47 0:0140 3350 dasd/work00.140 [560 cyls] open
04:52:47 0:0148 3350 dasd/mvsres.148 [560 cyls] open
04:52:47 0:0149 3350 dasd/smp001.149 [560 cyls] open
04:52:47 0:014A 3350 dasd/smp002.14a [560 cyls] open
04:52:47 0:014B 3350 dasd/smp003.14b [560 cyls] open
04:52:47 0:014C 3350 dasd/smp004.14c [560 cyls] open
04:52:47 0:0150 3330 dasd/start1.150 [808 cyls] open
04:52:47 0:0151 3330 dasd/spool0.151 [808 cyls] open
04:52:47 0:0152 3330 dasd/hasp00.152 [404 cyls] open
04:52:47 0:0160 3340 dasd/page00.160 [698 cyls] open
04:52:47 0:0161 3340 dasd/page01.161 [698 cyls] open
04:52:47 0:0162 3340 dasd/page02.162 [698 cyls] open
04:52:47 0:0170 3375 dasd/work01.170 [962 cyls] open
04:52:47 0:01A0 3380 dasd/work02.180 [886 cyls] open
04:52:47 0:01B0 3390 dasd/work03.190 [1114 cyls] open
04:52:47 0:01B1 3390 dasd/mvscat.191 [1114 cyls] open
04:52:47 0:01B2 3390 dasd/seasik.192 [1114 cyls] open
04:52:47 0:01B3 3390 dasd/mvssrc.193 [2226 cyls] open
04:52:47 0:01C7 3287  
04:52:47 0:0240 3350 dasd/pub000.240 [560 cyls] open
04:52:47 0:0248 3350 dasd/mvsdlb.248 [560 cyls] open
04:52:47 0:02A0 3380 dasd/pub002.280 [1772 cyls] open
04:52:47 0:02B1 3390 dasd/tmptmp.2b1 [1114 cyls] open
04:52:47 0:02B2 3390 dasd/xmit90.2b2 [1114 cyls] open
04:52:47 0:030E 1403 log/hardcopy.log crlf noclear
04:52:47 0:0340 3350 dasd/cbt000.340 [555 cyls] open
04:52:47 0:0341 3350 dasd/cbt001.341 [555 cyls] open
04:52:47 0:0342 3350 dasd/cbt002.342 [555 cyls] open
04:52:47 0:0343 3350 dasd/cbtcat.343 [555 cyls] open
04:52:47 0:0348 3350 dasd/src000.348 [555 cyls] open
04:52:47 0:0349 3350 dasd/src001.349 [555 cyls] open
04:52:47 0:034A 3350 dasd/src002.34a [555 cyls] open
04:52:47 0:034B 3350 dasd/srccat.34b [555 cyls] open
04:52:47 0:0400 3420 *
04:52:47 0:0401 3420 *
04:52:47 0:0402 3420 *
04:52:47 0:0403 3420 *
04:52:47 0:0700 3350 dasd/js2sp0.700 [555 cyls] open
04:52:47 0:0710 3350 dasd/js3sp0.710 [555 cyls] open
04:52:47 0:0711 3350 dasd/js3res.711 [555 cyls] open
04:52:47 logopt timestamp
04:52:47 HHCPN197I Log option set: TIMESTAMP
04:52:47 panrate 1000
04:52:47 # really need to wait for SVC120I, but if building MVS/380
04:52:47 # or some other stuffup with parms, need to trigger on an
04:52:47 # alternative. First one hit will clear targets.
04:52:47 # If we get a prompt for a device, cancel it
04:52:47 hao tgt IEF238D
04:52:47 HHCAO016I Target placed at index 0
04:52:47 hao cmd script conf/cancel.rc
04:52:47 HHCAO020I Command placed at index 0
04:52:47 hao tgt HASP395 DYNAMASK
04:52:47 HHCAO016I Target placed at index 1
04:52:47 hao cmd script conf/subjobs_slow.rc
04:52:47 HHCAO020I Command placed at index 1
04:52:47 hao tgt HASP373 SVC120I
04:52:47 HHCAO016I Target placed at index 2
04:52:47 hao cmd script conf/subjobs_fast.rc
04:52:47 HHCAO020I Command placed at index 2
04:52:47 hao tgt HASP436 REPLY
04:52:47 HHCAO016I Target placed at index 3
04:52:47 hao cmd script conf/replyy.rc
04:52:47 HHCAO020I Command placed at index 3
04:52:47 devinit 402 tapes/mftopc.het
04:52:47 HHCTA004I 0402: tapes/mftopc.het is a Hercules Emulated Tape file
04:52:47 HHCPN098I Device 0:0402 initialized
04:52:47 devinit 403 tapes/awstap.aws
04:52:47 HHCTA004I 0403: tapes/awstap.aws is a Hercules Emulated Tape file
04:52:47 HHCPN098I Device 0:0403 initialized
04:52:47 # co will give you a cold start of JES2 which is useful in
04:52:47 # automated runs
04:52:47 /(001F) r 00,clpa,cmd=co
04:52:47 #/r 00,clpa
04:52:47 ipl 148
04:52:47 HHCPN013I EOF reached on SCRIPT file. Processing complete.
04:52:47 IEA101A SPECIFY SYSTEM PARMS FOR MVS/380 1.2 v03.8 TK3+
04:52:47 HHCCD001I Readahead thread 1 started: tid=00003DB0, pid=15616
04:52:47 HHCCD001I Readahead thread 2 started: tid=00004AA8, pid=15616
04:52:47 HHCCD002I Writer thread 1 started: tid=000021CC, pid=15616
04:52:47 HHCCD003I Garbage collector thread started: tid=000049AC, pid=15616
04:52:47 IEA940I THE FOLLOWING PAGE DATA SETS ARE IN USE
04:52:47  PLPA ... SYS1.PAGELPA
04:52:47  COMMON . SYS1.PAGECSA
04:52:47  DUPLEX . SYS1.DUPLEX
04:52:47  LOCAL .. SYS1.PAGEL01
04:52:47  LOCAL .. SYS1.PAGEL02
04:52:47  LOCAL .. SYS1.PAGEL03
04:52:47 HHCCD002I Writer thread 2 started: tid=00004A28, pid=15616
04:52:51 *IEE362A SMF ENTER DUMP FOR SYS1.MANY ON MVSRES
04:52:51  IEE360I SMF NOW RECORDING ON SYS1.MANX ON MVSRES TIME=17.52.51
04:52:51  IGF992I  MIH INIT COMPLETE, PRI=000300, SEC=000015
04:52:52  IEF677I WARNING MESSAGE(S) FOR JOB JES2     ISSUED
04:52:52 *00 $HASP436 REPLY Y OR N TO CONFIRM CHECKPOINT RECORD CHANGE
04:52:52 HHCAO003I Firing command: 'script conf/replyy.rc'
04:52:52 script conf/replyy.rc
04:52:52 /(001F) reply 00,y
04:52:52 HHCPN013I EOF reached on SCRIPT file. Processing complete.
04:52:52  IEE600I REPLY TO 00 IS;SUPPRESSED
04:52:52  $HASP493 JES2 COLD-START IS IN PROGRESS
04:52:53  $HASP412 MAXIMUM OF 1   READER(S)  EXCEEDED
04:52:53 17.52.53           IEE041I THE SYSTEM LOG IS NOW ACTIVE
04:52:53 17.52.53           IEE302I 00E      ONLINE
04:52:53 17.52.53           IEE302I 00F      ONLINE
04:52:53 17.52.53           IEE313I 30E     UNIT REF INVALID
04:52:53 17.52.53           IEE450I 17.52.53 UNIT STATUS 160
04:52:53  UNIT TYPE STATUS  VOLSER VOLSTATE   UNIT TYPE STATUS  VOLSER VOLSTATE
04:52:53  400  3400 O                  /REMOV 401  3400 O                  /REMOV
04:52:53  402  3400 O                  /REMOV
04:52:54 17.52.53           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP000 OK
04:52:54 17.52.54           $HASP160 PRINTER1 INACTIVE - CLASS=AP
04:52:54 17.52.54           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:54 17.52.54           $HASP160 PUNCH1   INACTIVE - CLASS=B
04:52:54 17.52.54 STC    2  $HASP100 INIT     ON STCINRDR
04:52:54 17.52.54 STC    2  $HASP373 INIT     STARTED
04:52:54 17.52.54 STC    2  IEF403I INIT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC    3  $HASP100 INIT     ON STCINRDR
04:52:54 17.52.54 STC    3  $HASP373 INIT     STARTED
04:52:54 17.52.54 STC    3  IEF403I INIT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC    4  $HASP100 INIT     ON STCINRDR
04:52:54 17.52.54 STC    4  $HASP373 INIT     STARTED
04:52:54 17.52.54 STC    4  IEF403I INIT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC    5  $HASP100 INIT     ON STCINRDR
04:52:54 17.52.54 STC    5  $HASP373 INIT     STARTED
04:52:54 17.52.54 STC    5  IEF403I INIT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC    6  $HASP100 INIT     ON STCINRDR
04:52:54 17.52.54 STC    6  $HASP373 INIT     STARTED
04:52:54 17.52.54 STC    6  IEF403I INIT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC    7  $HASP100 INIT     ON STCINRDR
04:52:54 17.52.54 STC    7  $HASP373 INIT     STARTED
04:52:54 17.52.54 STC    7  IEF403I INIT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC    8  $HASP100 INIT     ON STCINRDR
04:52:54 17.52.54 STC    8  $HASP373 INIT     STARTED
04:52:54 17.52.54 STC    8  IEF403I INIT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC    9  $HASP100 SVC120I  ON STCINRDR
04:52:54 17.52.54 STC    9  $HASP373 SVC120I  STARTED
04:52:54 HHCAO003I Firing command: 'script conf/subjobs_fast.rc'
04:52:54 script conf/subjobs_fast.rc
04:52:54 # Now we know that SVC120I has started. But due to some
04:52:54 # weird pausing, it may get locked out. So clear out
04:52:54 # other triggers and wait on this
04:52:54 hao clear
04:52:54 HHCAO022I All automatic operation rules cleared
04:52:54 hao tgt HASP250 SVC120I
04:52:54 HHCAO016I Target placed at index 0
04:52:54 hao cmd script conf/subjobs.rc
04:52:54 HHCAO020I Command placed at index 0
04:52:54 HHCPN013I EOF reached on SCRIPT file. Processing complete.
04:52:54 17.52.54 STC    9  IEF403I SVC120I - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC   10  $HASP100 DYNABLDL ON STCINRDR
04:52:54 17.52.54 STC   10  $HASP373 DYNABLDL STARTED
04:52:54 17.52.54 STC   10  IEF403I DYNABLDL - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC   11  $HASP100 DYNAMASK ON STCINRDR
04:52:54 17.52.54 STC   11  $HASP373 DYNAMASK STARTED
04:52:54 17.52.54 STC   11  IEF403I DYNAMASK - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC   12  $HASP100 BSPPILOT ON STCINRDR
04:52:54 17.52.54 STC   12  $HASP373 BSPPILOT STARTED
04:52:54 17.52.54 STC   12  IEF403I BSPPILOT - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC   13  $HASP100 BSPSETPF ON STCINRDR
04:52:54 17.52.54 STC   13  $HASP373 BSPSETPF STARTED
04:52:54 17.52.54 STC   13  IEF403I BSPSETPF - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC   14  $HASP100 LOGRECI  ON STCINRDR
04:52:54 17.52.54 STC   14  $HASP373 LOGRECI  STARTED
04:52:54 17.52.54 STC   14  IEF403I LOGRECI - STARTED - TIME=17.52.54
04:52:54 17.52.54 STC   15  $HASP100 NET      ON STCINRDR
04:52:54 17.52.54 STC   15  $HASP373 NET      STARTED
04:52:54 17.52.54 STC   15  IEF403I NET - STARTED - TIME=17.52.54
04:52:54 17.52.54           $HASP309    INIT  1 INACTIVE ******** C=A
04:52:54 17.52.54           $HASP309    INIT  2 INACTIVE ******** C=BA
04:52:54 17.52.54           $HASP309    INIT  3 INACTIVE ******** C=CBA
04:52:54 17.52.54           $HASP309    INIT  4 INACTIVE ******** C=SHB
04:52:54 17.52.54           $HASP309    INIT  5 INACTIVE ******** C=SBA
04:52:54 17.52.54           $HASP309    INIT  6 INACTIVE ******** C=S
04:52:54 17.52.54           $HASP309    INIT  7 INACTIVE ******** C=E
04:52:54 17.52.54 STC    9  BSPGM40I -   200 MiB MAINSIZE memory available
04:52:54 17.52.54 STC    9  BSPGM41I -     2 Partitions of    64 MiB each
04:52:54 17.52.54 STC    9  BSPGM78I SVC 120 EP=00FE31A8; MVS/380
04:52:54 17.52.54 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
04:52:54 17.52.54 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
04:52:54 17.52.54 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
04:52:54 17.52.54 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
04:52:54 17.52.54 STC   15  IST025I  BLDL FAILED FOR IEDIAK   IN VTAMLIB
04:52:54 17.52.54 STC   15  IST025I  BLDL FAILED FOR IEDIAK   IN VTAMLIB
04:52:54 17.52.54 STC    9  IEF404I SVC120I - ENDED - TIME=17.52.54
04:52:54 17.52.54 STC    9  $HASP395 SVC120I  ENDED
04:52:55 17.52.54 STC    9  $HASP150 SVC120I  ON PRINTER2        45 LINES
04:52:55 17.52.55 STC    9 *$HASP190 SVC120I  SETUP -- PRINTER2 -- F = 0001 -- C = 6    -- T = SN
04:52:55 17.52.55           $HASP000 OK
04:52:55 17.52.55           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:55 17.52.55 STC    9  $HASP250 SVC120I  IS PURGED
04:52:55 HHCAO003I Firing command: 'script conf/subjobs.rc'
04:52:55 script conf/subjobs.rc
04:52:55 hao clear
04:52:55 HHCAO022I All automatic operation rules cleared
04:52:55 # Every job gets an NL tape available as input, containing
04:52:55 # some binary of unknown contents, most likely needing to
04:52:55 # be read as RECFM=U, but RECFM=FB and even RECFM=V are also
04:52:55 # possible.
04:52:55 #
04:52:55 # The job also gets an SL tape available for output, and
04:52:55 # again, any type of content can be written to it, and
04:52:55 # with a bit of luck, hetget will be able to extract the
04:52:55 # data you are looking for.
04:52:55 #
04:52:55 # And finally the job gets an SL AWS tape available for
04:52:55 # input and/or output should you wish to construct a
04:52:55 # special tape. Tape must be called AWSTAP. User should
04:52:55 # back the tape up before submitting it, because it will
04:52:55 # be overwritten and anything could go wrong. AWS is
04:52:55 # expected to be exceptional use of this procedure anyway
04:52:55 #
04:52:55 # Only the NL tape needs an explicit mount. The SL tapes
04:52:55 # are premounted before IPL
04:52:55 hao tgt HASP250 MOUNT
04:52:55 HHCAO016I Target placed at index 0
04:52:55 hao cmd script conf/subjobs2.rc
04:52:55 HHCAO020I Command placed at index 0
04:52:55 /(001F) M 401,VOL=(NL,PCTOMF)
04:52:55 HHCPN013I EOF reached on SCRIPT file. Processing complete.
04:52:55 17.52.55 STC   16  $HASP100 MOUNT    ON STCINRDR
04:52:55 17.52.55 STC   16  $HASP373 MOUNT    STARTED
04:52:55 17.52.55 STC   16  IEF403I MOUNT - STARTED - TIME=17.52.55
04:52:55 17.52.55 STC   16 *IEF233A M 401,PCTOMF,,MOUNT,401
04:52:55 17.52.55 STC   15  IST110I  NETWORK SOLICITOR STARTED
04:52:55 17.52.55 STC   15  IST093I  APPLJRP  ACTIVE
04:52:55 17.52.55 STC   15  IST093I  APPLPIES ACTIVE
04:52:55 17.52.55 STC   15  IST093I  APPLPIAD ACTIVE
04:52:55 17.52.55 STC   15  IST093I  APPLTSO  ACTIVE
04:52:55 17.52.55 STC   15  IST093I  APPLTEST ACTIVE
04:52:55 17.52.55 STC   15  IST093I  LCLMAJRP ACTIVE
04:52:55 17.52.55 STC   10  DYNABLDL STARTED
04:52:55 17.52.55 STC   15  IST093I  LCLMAJ00 ACTIVE
04:52:55 17.52.55 STC   17  $HASP100 TSO      ON STCINRDR
04:52:55 17.52.55 STC   17  $HASP373 TSO      STARTED
04:52:55 17.52.55 STC   17  IEF403I TSO - STARTED - TIME=17.52.55
04:52:55 17.52.55 STC   18  $HASP100 JRP      ON STCINRDR
04:52:55 17.52.55 STC   18  $HASP373 JRP      STARTED
04:52:55 17.52.55 STC   18  IEF403I JRP - STARTED - TIME=17.52.55
04:52:55 17.52.55           $HASP000 OK
04:52:55 17.52.55           $HASP000 OK
04:52:55 17.52.55 STC   15  IST020I  VTAM INITIALIZATION COMPLETE
04:52:55 17.52.55 STC   15  IEA000I 0C0,IOE,05,0200,400000000001,,,NET     ,17.52.55
04:52:55 17.52.55 STC   15  IEA000I 0C1,IOE,05,0200,400000000001,,,NET     ,17.52.55
04:52:55 17.52.55 STC   15  IEA000I 0C2,IOE,05,0200,400000000001,,,NET     ,17.52.55
04:52:55 17.52.55 STC   10  IEF404I DYNABLDL - ENDED - TIME=17.52.55
04:52:55 17.52.55 STC   10  $HASP395 DYNABLDL ENDED
04:52:55 17.52.55 STC   10  $HASP150 DYNABLDL ON PRINTER2        21 LINES
04:52:55 17.52.55           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:55 17.52.55 STC   10  $HASP250 DYNABLDL IS PURGED
04:52:55 17.52.55 STC   11  DMSK00I DYNAMASK DONE ****
04:52:55 17.52.55 STC   11  DMSK06I  START
04:52:55 17.52.55 STC   11  IEF404I DYNAMASK - ENDED - TIME=17.52.55
04:52:55 17.52.55 STC   11  $HASP395 DYNAMASK ENDED
04:52:55 17.52.55 STC   11  $HASP150 DYNAMASK ON PRINTER2        30 LINES
04:52:55 17.52.55           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:55 17.52.55 STC   11  $HASP250 DYNAMASK IS PURGED
04:52:55 17.52.55 STC   19  $HASP100 DUMPFULL ON STCINRDR
04:52:55 17.52.55 STC   19  IEF452I DUMPFULL JOB NOT RUN - JCL ERROR
04:52:55 17.52.55 STC   19  $HASP396 DUMPFULL TERMINATED
04:52:55 17.52.55 STC   19  $HASP150 DUMPFULL ON PRINTER2         8 LINES
04:52:55 17.52.55           IEE122I START COMMAND JCL ERROR
04:52:55 17.52.55           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:55 17.52.55 STC   19  $HASP250 DUMPFULL IS PURGED
04:52:55 17.52.55 STC   12 *IEA994A ALL SYS1.DUMP DATA SETS ARE FULL AND NO SVC DUMPS CAN BE TAKEN
04:52:55 17.52.55 STC   12  IEC909I 212-03,BSPPILOT,BSPPILOT,SYSDCB
04:52:55 17.52.55 STC   12  IEF450I BSPPILOT BSPPILOT - ABEND S212 U0000 - TIME=17.52.55
04:52:55 17.52.55 STC   12  IEF404I BSPPILOT - ENDED - TIME=17.52.55
04:52:55 17.52.55 STC   12  $HASP395 BSPPILOT ENDED
04:52:55 17.52.55 STC   12  $HASP150 BSPPILOT ON PRINTER2        16 LINES
04:52:55 17.52.55           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:55 17.52.55 STC   12  $HASP250 BSPPILOT IS PURGED
04:52:55 17.52.55 STC   13  BSPSP91I - Parms passed: NOREPLYU
04:52:55 17.52.55 STC   13  BSPSP93I - PFK definitions will be updated in memory
04:52:55 17.52.55 STC   13  BSPSP22I - Dataset processed: SYS1.PARMLIB
04:52:55 17.52.55 STC   13  BSPSP23I - on volume MVSRES
04:52:55 17.52.55 STC   13  BSPSP21I - Member being processed: SETPFK01
04:52:55 17.52.55 STC   13  +BSPSP98I - Member processed, LASTCC=0000
04:52:55 17.52.55 STC   13  +BSPSP21I - Member being processed: SETPFK02
04:52:55 17.52.55 STC   13  +BSPSP98I - Member processed, LASTCC=0000
04:52:55 17.52.55 STC   13  +BSPSP99I - End of processing, MAXRC=0000
04:52:56 17.52.56 STC   13  IEF404I BSPSETPF - ENDED - TIME=17.52.56
04:52:56 17.52.56 STC   13  $HASP395 BSPSETPF ENDED
04:52:56 17.52.56 STC   13  $HASP150 BSPSETPF ON PRINTER2        34 LINES
04:52:56 17.52.56           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:56 17.52.56 STC   13  $HASP250 BSPSETPF IS PURGED
04:52:56 17.52.56 STC   14  IFC001I  D=3350 N=0B F=01AB0000 L=01AC0005 S=01AB000002 DIP COMPLETE
04:52:56 17.52.56 STC   14  IEF404I LOGRECI - ENDED - TIME=17.52.56
04:52:56 17.52.56 STC   14  $HASP395 LOGRECI  ENDED
04:52:56 17.52.56 STC   14  $HASP150 LOGRECI  ON PRINTER2        20 LINES
04:52:56 17.52.56           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:56 17.52.56 STC   14  $HASP250 LOGRECI  IS PURGED
04:52:56 17.52.56 STC   16  IEF404I MOUNT - ENDED - TIME=17.52.56
04:52:56 17.52.56 STC   16  $HASP395 MOUNT    ENDED
04:52:56 17.52.56 STC   16  $HASP150 MOUNT    ON PRINTER2        18 LINES
04:52:56 17.52.56           $HASP160 PRINTER2 INACTIVE - CLASS=Z
04:52:56 17.52.56 STC   16  $HASP250 MOUNT    IS PURGED
04:52:56 HHCAO003I Firing command: 'script conf/subjobs2.rc'
04:52:56 script conf/subjobs2.rc
04:52:56 hao clear
04:52:56 HHCAO022I All automatic operation rules cleared
04:52:56 # If we get a prompt for a device, cancel it
04:52:56 hao tgt IEF238D
04:52:56 HHCAO016I Target placed at index 0
04:52:56 hao cmd script conf/cancel.rc
04:52:56 HHCAO020I Command placed at index 0
04:52:56 # If we get a prompt for a catalogue password, answer it
04:52:56 hao tgt IEC301A
04:52:56 HHCAO016I Target placed at index 1
04:52:56 hao cmd script conf/secret.rc
04:52:56 HHCAO020I Command placed at index 1
04:52:56 devinit 401 tapes/pctomf.tdf
04:52:56 HHCTA004I 0401: tapes/pctomf.tdf is a Optical Media Attachment (OMA) tape
04:52:56 HHCPN098I Device 0:0401 initialized
04:52:56 # When we see TERMHERC get purged, our job is done
04:52:56 hao tgt HASP373 TERMHERC
04:52:56 HHCAO016I Target placed at index 2
04:52:56 hao cmd script conf/termherc.rc
04:52:56 HHCAO020I Command placed at index 2
04:52:56 # Now submit the job
04:52:56 devinit 00c jcl/hercauto.jcl eof
04:52:56 HHCSD007I Device 000C unbound from socket 127.0.0.1:3505
04:52:56 HHCSD022I Socketdevice listener thread terminated
04:52:56 HHCPN098I Device 0:000C initialized
04:52:56 HHCPN013I EOF reached on SCRIPT file. Processing complete.
04:52:56 17.52.56 JOB    1  $HASP100 HERC01A  ON READER1
04:52:56 17.52.56 JOB    2  $HASP100 TERMHERC ON READER1
04:52:56 17.52.56 JOB    1  $HASP373 HERC01A  STARTED - INIT  3 - CLASS C - SYS BSP1
04:52:56 17.52.56 JOB    1  IEF403I HERC01A - STARTED - TIME=17.52.56
04:52:56 17.52.56 STC   17  IKT007I TCAS ACCEPTING LOGONS
04:52:56 17.52.56 STC   17  IKT005I TCAS IS INITIALIZED
04:52:56 17.52.56 STC   18  JRPI101 INITIALIZATION COMPLETE
04:52:56 17.52.56 STC   18 *01 JRP100I - ENTER ICLOSE TO SHUT DOWN
04:52:56 17.52.56 JOB    1  IEFACTRT - Stepname  Procstep  Program   Retcode
04:52:56 17.52.56 JOB    1  HERC01A    IEFBR14             IEFBR14   RC= 0000
04:52:56 17.52.56 JOB    1  IEF404I HERC01A - ENDED - TIME=17.52.56
04:52:56 17.52.56 JOB    1  $HASP395 HERC01A  ENDED
04:52:56 17.52.56 JOB    1  $HASP150 HERC01A  ON PRINTER1        30 LINES
04:52:56 17.52.56 JOB    1 *$HASP190 HERC01A  SETUP -- PRINTER1 -- F = 0001 -- C = 6    -- T = SN
04:52:56 17.52.56 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1
04:52:56 HHCAO003I Firing command: 'script conf/termherc.rc'
04:52:56 script conf/termherc.rc
04:52:56 # We do an unnecessary 2-stage terminate, first triggering
04:52:56 # on the start message, then triggering on the purged
04:52:56 # message, to overcome an apparent bug in hercules which
04:52:56 # causes it to sometimes trigger on the wrong jobname.
04:52:56 hao clear
04:52:56 HHCAO022I All automatic operation rules cleared
04:52:56 hao tgt HASP250 TERMHERC
04:52:56 HHCAO016I Target placed at index 0
04:52:56 hao cmd script conf/termherc2.rc
04:52:56 HHCAO020I Command placed at index 0
04:52:56 HHCPN013I EOF reached on SCRIPT file. Processing complete.
04:52:56 17.52.56 JOB    2  IEF403I TERMHERC - STARTED - TIME=17.52.56
04:52:56 17.52.56 JOB    2  IEFACTRT - Stepname  Procstep  Program   Retcode
04:52:56 17.52.56 JOB    2  TERMHERC   S1                  IEBGENER  RC= 0000
04:52:56 17.52.56          *IEE362A SMF ENTER DUMP FOR SYS1.MANX ON MVSRES
04:52:56 17.52.56           IEE361I SMF DATA LOST - SYS1.MANY NOT AVAILABLE TIME=17.52.56
04:52:56 17.52.56 JOB    2  IEF404I TERMHERC - ENDED - TIME=17.52.56
04:52:56 17.52.56 JOB    2  $HASP395 TERMHERC ENDED
04:52:56 17.52.56           $HASP309    INIT  3 INACTIVE ******** C=CBA
04:52:56 17.52.56 JOB    2  $HASP150 TERMHERC ON PRINTER2        44 LINES
04:52:56 17.52.56           $HASP160 PRINTER2 INACTIVE - CLASS=Z

Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
On 3/11/2017 3:01 AM, [hidden email] [H390-MVS] wrote:
> 17:55:33 06.55.33 JOB    1 *$HASP190 HERC01A  SETUP -- PRINTER1 -- F = 0001 -- C = 6    -- T = SN
> 17:55:33 06.55.33           $HASP000 OK
> 17:55:33 06.55.33 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1

One way to handle this is to define the printers to bypass setup (unless
you really want it):

PRINTER1       CLASS=CHXDGM,SEP,AUTO,DSPLTCEL,NOPAUSE,UNIT=00E,DRAIN,  +
                UCS=NONE,FCB=6



> Looking further in the log, I see
> an error about DUMPFULL:
>
> 04:52:55 17.52.55 STC   19  $HASP100 DUMPFULL ON STCINRDR
> 04:52:55 17.52.55 STC   19  IEF452I DUMPFULL JOB NOT RUN - JCL ERROR
> 04:52:55 17.52.55 STC   19  $HASP396 DUMPFULL TERMINATED
DUMPFULL was missing in the original tk3 also. Basically it should be a
three-step IEBGENER to copy a null data set to the three SYS1.DUMP0n files.

No idea why BLDL/FIND is bombing. I've never seen that on my system.


Gerhard Postpischil
Bradford, VT

---
This email has been checked for viruses by AVG.
http://www.avg.com

Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
 - - - In [hidden email], <gerhardp@...> wrote:
- - - beginning snipped - - -
> DUMPFULL was missing in the original tk3 also. Basically it should be a
>three-step IEBGENER to copy a null data set to the three SYS1.DUMP0n files.

No it shouldn't.

Why do you want to collect unwanted dumps in data sets just
to blow them away just to get more unwanted dumps.
Each dump locks up the system while being written to the
DUMP data sets.

Leave the dump data sets full until you actually want a dump.

As for the FIND/BLDL issue, did you IPL over a
PDS compress-in-place?
Then you should restore from back-up.

As for the DIRF bit, did you IPL when a VTOC was being updated?
VTOC free space, format 5 DSCB, has been cleaned up but some
data set VTOC record may be wrong, missing, or not deleted?

The SVC X'12' error and VTOC showing an incomplete DASDM
update could also be from physical disk errors but I doubt it.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
I have noticed another anomaly (JRP
abending) in other runs:

02:08:10 15.08.10 STC   19  IEC604I VTOC CONVERT ROUTINE ENTERED ON 1B1,MVSCAT,DIRF
02:08:10 15.08.10 STC   18  JRP400E JRP400 ABENDING
02:08:10 15.08.10 STC   18  IST804I  VTAM CLOSE IN PROCESS FOR JRP      OPENED BY JRP      UNKNOWN
02:08:10 15.08.10 STC   15  IST400I  TERMINATION IN PROGRESS FOR APPLID JRP
02:08:10 15.08.10 STC   15  IST805I  VTAM CLOSE COMPLETE FOR JRP
02:08:10 15.08.10 STC   18  IEF450I JRP JRP - ABEND S000 U0043 - TIME=15.08.10
02:08:10 15.08.10 STC   18  IEF404I JRP - ENDED - TIME=15.08.10
02:08:10 15.08.10 STC   18  $HASP395 JRP      ENDED

(full log below)


Note that this seems to have started in the
middle of automated runs:

2017-03-11  02:07            58,749 prt00f-2017-03-11_-2075238.txt
2017-03-11  02:08            58,749 prt00f-2017-03-11_-2075703.txt
2017-03-11  02:08            58,749 prt00f-2017-03-11_-2080174.txt
2017-03-11  02:08           222,990 prt00f-2017-03-11_-2080626.txt
2017-03-11  02:08           222,990 prt00f-2017-03-11_-2081083.txt
2017-03-11  02:08           222,990 prt00f-2017-03-11_-2081537.txt

not something I have done.


From the printer:


                              RTM2WA SUMMARY
                              --------------

+1C     COMPLETION CODE          8000002B
+8C     ABENDING PROGRAM NAME      N/A
+94     ABENDING PROGRAM ADDR    00000000

+3C     REGS AT TIME OF ERROR    80000000 8000002B 000B4180 00000010 000B4180 00024820 00FD11C8 000B4A80   (0-7)
+5C                              000B4A90 000B885C 000B4A90 00000000 400B6E5C 000B8800 400B55D8 00000000   (8-F)
+7C     EC PSW AT TIME OF ERROR  078D1000 000B6FCA 0002000D 00000000
+DC     SDWACOMP                 00000000


BFN. Paul.




02:08:06 Hercules Version 3.07:380-4.x
02:08:06 (c)Copyright 1999-2010 by Roger Bowler, Jan Jaeger, and others
02:08:06 Built on Dec  7 2016 at 12:43:32
02:08:06 Build information:
02:08:06   Windows (MSVC) build for AMD64
02:08:06   Modes: S/370 S/380 ESA/390 z/Arch
02:08:06   Max CPU Engines: 8
02:08:06   Using fthreads instead of pthreads
02:08:06   Dynamic loading support
02:08:06   Using shared libraries
02:08:06   HTTP Server support
02:08:06   No SIGABEND handler
02:08:06   Regular Expressions support
02:08:06   Automatic Operator support
02:08:06   Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8
02:08:06 Running on PAUL-DELL Windows_NT-6.2 AMD64 MP=8
02:08:06 HHCHD018I Loadable module directory is hercules
02:08:06 Crypto module loaded (c) Copyright Bernard van der Helm, 2003-2010
02:08:06   Active: Message Security Assist
02:08:06           Message Security Assist Extension 1
02:08:06           Message Security Assist Extension 2
02:08:06 HHCPN210I Default Allowed AUTOMOUNT directory = "c:\mvs380\"
02:08:06 HHCCF065I Hercules: tid=00003FAC, pid=19064, pgid=19064, priority=8
02:08:06 HHCHT001I HTTP listener thread started: tid=00005694, pid=19064
02:08:06 HHCHT013I Using HTTPROOT directory "c:\herc380\html\"
02:08:06 HHCHT006I Waiting for HTTP requests on port 8081
02:08:06 HHCSD004I Device 000C bound to socket 127.0.0.1:3505
02:08:06 HHCSD020I Socketdevice listener thread started: tid=00002D44, pid=19064
02:08:06 HHCCF083I conf/mvs380.conf Including conf/mvs380_DASD.conf at 123 .
02:08:06 HHCDA004I opening dasd/mvsres.148 readonly
02:08:06 HHCDA020I dasd/mvsres.148 cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA004I opening dasd/sort01.131 readonly
02:08:06 HHCDA020I dasd/sort01.131 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/sort02.132 readonly
02:08:06 HHCDA020I dasd/sort02.132 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/sort03.133 readonly
02:08:06 HHCDA020I dasd/sort03.133 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/sort04.134 readonly
02:08:06 HHCDA020I dasd/sort04.134 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/sort05.135 readonly
02:08:06 HHCDA020I dasd/sort05.135 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/sort06.136 readonly
02:08:06 HHCDA020I dasd/sort06.136 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/work00.140 readonly
02:08:06 HHCDA020I dasd/work00.140 cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA020I dasd/hasp00.152 cyls=404 heads=19 tracks=7676 trklen=13312
02:08:06 HHCDA020I dasd/page00.160 cyls=698 heads=12 tracks=8376 trklen=8704
02:08:06 HHCDA020I dasd/page01.161 cyls=698 heads=12 tracks=8376 trklen=8704
02:08:06 HHCDA020I dasd/page02.162 cyls=698 heads=12 tracks=8376 trklen=8704
02:08:06 HHCDA020I dasd/work01.170 cyls=962 heads=12 tracks=11544 trklen=35840
02:08:06 HHCDA004I opening dasd/work02.180 readonly
02:08:06 HHCDA020I dasd/work02.180 cyls=886 heads=15 tracks=13290 trklen=47616
02:08:06 HHCDA004I opening dasd/work03.190 readonly
02:08:06 HHCDA020I dasd/work03.190 cyls=1114 heads=15 tracks=16710 trklen=56832
02:08:06 HHCDA004I opening dasd/mvscat.191 readonly
02:08:06 HHCDA020I dasd/mvscat.191 cyls=1114 heads=15 tracks=16710 trklen=56832
02:08:06 HHCDA004I opening dasd/seasik.192 readonly
02:08:06 HHCDA020I dasd/seasik.192 cyls=1114 heads=15 tracks=16710 trklen=56832
02:08:06 HHCDA020I dasd/mvssrc.193 cyls=2226 heads=15 tracks=33390 trklen=56832
02:08:06 HHCDA002E 01B4:File not found or invalid 'dasd/pub004.1b4'
02:08:06 HHCCF044E Initialization failed for device 01B4
02:08:06 HHCDA004I opening dasd/pub000.240 readonly
02:08:06 HHCDA020I dasd/pub000.240 cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA004I opening dasd/mvsdlb.248 readonly
02:08:06 HHCDA020I dasd/mvsdlb.248 cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA004I opening dasd/pub002.280 readonly
02:08:06 HHCDA020I dasd/pub002.280 cyls=1772 heads=15 tracks=26580 trklen=47616
02:08:06 HHCDA004I opening dasd/tmptmp.2b1 readonly
02:08:06 HHCDA020I dasd/tmptmp.2b1 cyls=1114 heads=15 tracks=16710 trklen=56832
02:08:06 HHCDA004I opening dasd/xmit90.2b2 readonly
02:08:06 HHCDA020I dasd/xmit90.2b2 cyls=1114 heads=15 tracks=16710 trklen=56832
02:08:06 HHCDA004I opening dasd/start1.150 readonly
02:08:06 HHCDA020I dasd/start1.150 cyls=808 heads=19 tracks=15352 trklen=13312
02:08:06 HHCDA004I opening dasd/spool0.151 readonly
02:08:06 HHCDA020I dasd/spool0.151 cyls=808 heads=19 tracks=15352 trklen=13312
02:08:06 HHCDA004I opening dasd/cbt000.340 readonly
02:08:06 HHCDA020I dasd/cbt000.340 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/cbt001.341 readonly
02:08:06 HHCDA020I dasd/cbt001.341 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/cbt002.342 readonly
02:08:06 HHCDA020I dasd/cbt002.342 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/cbtcat.343 readonly
02:08:06 HHCDA020I dasd/cbtcat.343 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/src000.348 readonly
02:08:06 HHCDA020I dasd/src000.348 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/src001.349 readonly
02:08:06 HHCDA020I dasd/src001.349 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/src002.34a readonly
02:08:06 HHCDA020I dasd/src002.34a cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/srccat.34b readonly
02:08:06 HHCDA020I dasd/srccat.34b cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/smp001.149 readonly
02:08:06 HHCDA020I dasd/smp001.149 cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA004I opening dasd/smp002.14a readonly
02:08:06 HHCDA020I dasd/smp002.14a cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA004I opening dasd/smp003.14b readonly
02:08:06 HHCDA020I dasd/smp003.14b cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA004I opening dasd/smp004.14c readonly
02:08:06 HHCDA020I dasd/smp004.14c cyls=560 heads=30 tracks=16800 trklen=19456
02:08:06 HHCDA004I opening dasd/js2sp0.700 readonly
02:08:06 HHCDA020I dasd/js2sp0.700 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/dlicat.138 readonly
02:08:06 HHCDA020I dasd/dlicat.138 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/dlisys.139 readonly
02:08:06 HHCDA020I dasd/dlisys.139 cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/dli000.13a readonly
02:08:06 HHCDA020I dasd/dli000.13a cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/dli001.13b readonly
02:08:06 HHCDA020I dasd/dli001.13b cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/dli002.13c readonly
02:08:06 HHCDA020I dasd/dli002.13c cyls=200 heads=20 tracks=4000 trklen=7680
02:08:06 HHCDA004I opening dasd/js3sp0.710 readonly
02:08:06 HHCDA020I dasd/js3sp0.710 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCDA004I opening dasd/js3res.711 readonly
02:08:06 HHCDA020I dasd/js3res.711 cyls=555 heads=30 tracks=16650 trklen=19456
02:08:06 HHCTE001I Console connection thread started: tid=000056F8, pid=19064
02:08:06 HHCTE003I Waiting for console connection on port 3270
02:08:06 HHCTA066I 0400: option 'level' accepted.
02:08:06 HHCTA066I 0401: option 'level' accepted.
02:08:06 HHCTA066I 0402: option 'level' accepted.
02:08:06 HHCTA066I 0403: option 'level' accepted.
02:08:06 HHCCP002I CPU0000 thread started: tid=00001FFC, pid=19064, priority=0
02:08:06 HHCCP003I CPU0000 architecture mode S/380
02:08:06 HHCPN001I Control panel thread started: tid=00003FAC, pid=19064
02:08:06 HHCTT002I Timer thread started: tid=00003B60, pid=19064, priority=-20
02:08:06 HHCPN008I Script file processing started using file "conf/auto_run.rc"
02:08:06 devlist
02:08:06 0:000C 3505 127.0.0.1:3505 sockdev ascii trunc eof
02:08:06      (no one currently connected)
02:08:06 0:000D 3525 pch/pch00d.txt ascii crlf
02:08:06 0:000E 1403 prt/prt00e.txt crlf noclear
02:08:06 0:000F 1403 prt/prt00f.txt crlf noclear
02:08:06 0:001F 3215 *syscons cmdpref(/)
02:08:06 0:00C0 3270  
02:08:06 0:00C1 3270  
02:08:06 0:00C2 3270  
02:08:06 0:00C7 3287  
02:08:06 0:010C 3505 jcl/dummy eof
02:08:06 0:0131 2314 dasd/sort01.131 [200 cyls] open
02:08:06 0:0132 2314 dasd/sort02.132 [200 cyls] open
02:08:06 0:0133 2314 dasd/sort03.133 [200 cyls] open
02:08:06 0:0134 2314 dasd/sort04.134 [200 cyls] open
02:08:06 0:0135 2314 dasd/sort05.135 [200 cyls] open
02:08:06 0:0136 2314 dasd/sort06.136 [200 cyls] open
02:08:06 0:0138 2314 dasd/dlicat.138 [200 cyls] open
02:08:06 0:0139 2314 dasd/dlisys.139 [200 cyls] open
02:08:06 0:013A 2314 dasd/dli000.13a [200 cyls] open
02:08:06 0:013B 2314 dasd/dli001.13b [200 cyls] open
02:08:06 0:013C 2314 dasd/dli002.13c [200 cyls] open
02:08:06 0:0140 3350 dasd/work00.140 [560 cyls] open
02:08:06 0:0148 3350 dasd/mvsres.148 [560 cyls] open
02:08:06 0:0149 3350 dasd/smp001.149 [560 cyls] open
02:08:06 0:014A 3350 dasd/smp002.14a [560 cyls] open
02:08:06 0:014B 3350 dasd/smp003.14b [560 cyls] open
02:08:06 0:014C 3350 dasd/smp004.14c [560 cyls] open
02:08:06 0:0150 3330 dasd/start1.150 [808 cyls] open
02:08:06 0:0151 3330 dasd/spool0.151 [808 cyls] open
02:08:06 0:0152 3330 dasd/hasp00.152 [404 cyls] open
02:08:06 0:0160 3340 dasd/page00.160 [698 cyls] open
02:08:06 0:0161 3340 dasd/page01.161 [698 cyls] open
02:08:06 0:0162 3340 dasd/page02.162 [698 cyls] open
02:08:06 0:0170 3375 dasd/work01.170 [962 cyls] open
02:08:06 0:01A0 3380 dasd/work02.180 [886 cyls] open
02:08:06 0:01B0 3390 dasd/work03.190 [1114 cyls] open
02:08:06 0:01B1 3390 dasd/mvscat.191 [1114 cyls] open
02:08:06 0:01B2 3390 dasd/seasik.192 [1114 cyls] open
02:08:06 0:01B3 3390 dasd/mvssrc.193 [2226 cyls] open
02:08:06 0:01C7 3287  
02:08:06 0:0240 3350 dasd/pub000.240 [560 cyls] open
02:08:06 0:0248 3350 dasd/mvsdlb.248 [560 cyls] open
02:08:06 0:02A0 3380 dasd/pub002.280 [1772 cyls] open
02:08:06 0:02B1 3390 dasd/tmptmp.2b1 [1114 cyls] open
02:08:06 0:02B2 3390 dasd/xmit90.2b2 [1114 cyls] open
02:08:06 0:030E 1403 log/hardcopy.log crlf noclear
02:08:06 0:0340 3350 dasd/cbt000.340 [555 cyls] open
02:08:06 HHCAO001I Hercules Automatic Operator thread started;
02:08:06           tid=00000DE0, pri=0, pid=19064
02:08:06 0:0341 3350 dasd/cbt001.341 [555 cyls] open
02:08:06 0:0342 3350 dasd/cbt002.342 [555 cyls] open
02:08:06 0:0343 3350 dasd/cbtcat.343 [555 cyls] open
02:08:06 0:0348 3350 dasd/src000.348 [555 cyls] open
02:08:06 0:0349 3350 dasd/src001.349 [555 cyls] open
02:08:06 0:034A 3350 dasd/src002.34a [555 cyls] open
02:08:06 0:034B 3350 dasd/srccat.34b [555 cyls] open
02:08:06 0:0400 3420 *
02:08:06 0:0401 3420 *
02:08:06 0:0402 3420 *
02:08:06 0:0403 3420 *
02:08:06 0:0700 3350 dasd/js2sp0.700 [555 cyls] open
02:08:06 0:0710 3350 dasd/js3sp0.710 [555 cyls] open
02:08:06 0:0711 3350 dasd/js3res.711 [555 cyls] open
02:08:06 logopt timestamp
02:08:06 HHCPN197I Log option set: TIMESTAMP
02:08:06 panrate 1000
02:08:06 # really need to wait for SVC120I, but if building MVS/380
02:08:06 # or some other stuffup with parms, need to trigger on an
02:08:06 # alternative. First one hit will clear targets.
02:08:06 # If we get a prompt for a device, cancel it
02:08:06 hao tgt IEF238D
02:08:06 HHCAO016I Target placed at index 0
02:08:06 hao cmd script conf/cancel.rc
02:08:06 HHCAO020I Command placed at index 0
02:08:06 hao tgt HASP395 DYNAMASK
02:08:06 HHCAO016I Target placed at index 1
02:08:06 hao cmd script conf/subjobs_slow.rc
02:08:06 HHCAO020I Command placed at index 1
02:08:06 hao tgt HASP373 SVC120I
02:08:06 HHCAO016I Target placed at index 2
02:08:06 hao cmd script conf/subjobs_fast.rc
02:08:06 HHCAO020I Command placed at index 2
02:08:06 hao tgt HASP436 REPLY
02:08:06 HHCAO016I Target placed at index 3
02:08:06 hao cmd script conf/replyy.rc
02:08:06 HHCAO020I Command placed at index 3
02:08:06 devinit 402 tapes/mftopc.het
02:08:06 HHCTA004I 0402: tapes/mftopc.het is a Hercules Emulated Tape file
02:08:06 HHCPN098I Device 0:0402 initialized
02:08:06 devinit 403 tapes/awstap.aws
02:08:06 HHCTA004I 0403: tapes/awstap.aws is a Hercules Emulated Tape file
02:08:06 HHCPN098I Device 0:0403 initialized
02:08:06 # co will give you a cold start of JES2 which is useful in
02:08:06 # automated runs
02:08:06 /(001F) r 00,clpa,cmd=co
02:08:06 #/r 00,clpa
02:08:06 ipl 148
02:08:06 HHCPN013I EOF reached on SCRIPT file. Processing complete.
02:08:06 IEA101A SPECIFY SYSTEM PARMS FOR MVS/380 1.2 v03.8 TK3+
02:08:06 HHCCD001I Readahead thread 1 started: tid=00004CC0, pid=19064
02:08:06 HHCCD001I Readahead thread 2 started: tid=00000C78, pid=19064
02:08:06 HHCCD002I Writer thread 1 started: tid=00003174, pid=19064
02:08:06 HHCCD003I Garbage collector thread started: tid=000007A0, pid=19064
02:08:06 IEA940I THE FOLLOWING PAGE DATA SETS ARE IN USE
02:08:06  PLPA ... SYS1.PAGELPA
02:08:06  COMMON . SYS1.PAGECSA
02:08:06  DUPLEX . SYS1.DUPLEX
02:08:06  LOCAL .. SYS1.PAGEL01
02:08:06  LOCAL .. SYS1.PAGEL02
02:08:06  LOCAL .. SYS1.PAGEL03
02:08:06 HHCCD002I Writer thread 2 started: tid=00004954, pid=19064
02:08:08 *IEE362A SMF ENTER DUMP FOR SYS1.MANY ON MVSRES
02:08:08  IEE360I SMF NOW RECORDING ON SYS1.MANX ON MVSRES TIME=15.08.08
02:08:08  IGF992I  MIH INIT COMPLETE, PRI=000300, SEC=000015
02:08:08  IEF677I WARNING MESSAGE(S) FOR JOB JES2     ISSUED
02:08:08 *00 $HASP436 REPLY Y OR N TO CONFIRM CHECKPOINT RECORD CHANGE
02:08:08 HHCAO003I Firing command: 'script conf/replyy.rc'
02:08:08 script conf/replyy.rc
02:08:08 /(001F) reply 00,y
02:08:08 HHCPN013I EOF reached on SCRIPT file. Processing complete.
02:08:08  IEE600I REPLY TO 00 IS;SUPPRESSED
02:08:08  $HASP493 JES2 COLD-START IS IN PROGRESS
02:08:09  $HASP412 MAXIMUM OF 1   READER(S)  EXCEEDED
02:08:09 15.08.09           IEE041I THE SYSTEM LOG IS NOW ACTIVE
02:08:09 15.08.09           IEE302I 00E      ONLINE
02:08:09 15.08.09           IEE302I 00F      ONLINE
02:08:09 15.08.09           IEE313I 30E     UNIT REF INVALID
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           IEE450I 15.08.09 UNIT STATUS 161
02:08:09  UNIT TYPE STATUS  VOLSER VOLSTATE   UNIT TYPE STATUS  VOLSER VOLSTATE
02:08:09  400  3400 O                  /REMOV 401  3400 O                  /REMOV
02:08:09  402  3400 O                  /REMOV
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP160 PRINTER1 INACTIVE - CLASS=AP
02:08:09 15.08.09           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:09 15.08.09           $HASP160 PUNCH1   INACTIVE - CLASS=B
02:08:09 15.08.09 STC    2  $HASP100 INIT     ON STCINRDR
02:08:09 15.08.09 STC    2  $HASP373 INIT     STARTED
02:08:09 15.08.09 STC    2  IEF403I INIT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC    3  $HASP100 INIT     ON STCINRDR
02:08:09 15.08.09 STC    3  $HASP373 INIT     STARTED
02:08:09 15.08.09 STC    3  IEF403I INIT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC    4  $HASP100 INIT     ON STCINRDR
02:08:09 15.08.09 STC    4  $HASP373 INIT     STARTED
02:08:09 15.08.09 STC    4  IEF403I INIT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC    5  $HASP100 INIT     ON STCINRDR
02:08:09 15.08.09 STC    5  $HASP373 INIT     STARTED
02:08:09 15.08.09 STC    5  IEF403I INIT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC    6  $HASP100 INIT     ON STCINRDR
02:08:09 15.08.09 STC    6  $HASP373 INIT     STARTED
02:08:09 15.08.09 STC    6  IEF403I INIT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC    7  $HASP100 INIT     ON STCINRDR
02:08:09 15.08.09 STC    7  $HASP373 INIT     STARTED
02:08:09 15.08.09 STC    7  IEF403I INIT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC    8  $HASP100 INIT     ON STCINRDR
02:08:09 15.08.09 STC    8  $HASP373 INIT     STARTED
02:08:09 15.08.09 STC    8  IEF403I INIT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC    9  $HASP100 SVC120I  ON STCINRDR
02:08:09 15.08.09 STC    9  $HASP373 SVC120I  STARTED
02:08:09 HHCAO003I Firing command: 'script conf/subjobs_fast.rc'
02:08:09 script conf/subjobs_fast.rc
02:08:09 # Now we know that SVC120I has started. But due to some
02:08:09 # weird pausing, it may get locked out. So clear out
02:08:09 # other triggers and wait on this
02:08:09 hao clear
02:08:09 HHCAO022I All automatic operation rules cleared
02:08:09 hao tgt HASP250 SVC120I
02:08:09 HHCAO016I Target placed at index 0
02:08:09 hao cmd script conf/subjobs.rc
02:08:09 HHCAO020I Command placed at index 0
02:08:09 HHCPN013I EOF reached on SCRIPT file. Processing complete.
02:08:09 15.08.09 STC    9  IEF403I SVC120I - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   10  $HASP100 DYNABLDL ON STCINRDR
02:08:09 15.08.09 STC   10  $HASP373 DYNABLDL STARTED
02:08:09 15.08.09 STC   10  IEF403I DYNABLDL - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   11  $HASP100 DYNAMASK ON STCINRDR
02:08:09 15.08.09 STC   11  $HASP373 DYNAMASK STARTED
02:08:09 15.08.09 STC   11  IEF403I DYNAMASK - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   12  $HASP100 BSPPILOT ON STCINRDR
02:08:09 15.08.09 STC   12  $HASP373 BSPPILOT STARTED
02:08:09 15.08.09 STC   12  IEF403I BSPPILOT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   13  $HASP100 BSPSETPF ON STCINRDR
02:08:09 15.08.09 STC   13  $HASP373 BSPSETPF STARTED
02:08:09 15.08.09 STC   13  IEF403I BSPSETPF - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   14  $HASP100 LOGRECI  ON STCINRDR
02:08:09 15.08.09 STC   14  $HASP373 LOGRECI  STARTED
02:08:09 15.08.09 STC   14  IEF403I LOGRECI - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   15  $HASP100 NET      ON STCINRDR
02:08:09 15.08.09           $HASP309    INIT  1 INACTIVE ******** C=A
02:08:09 15.08.09 STC   15  $HASP373 NET      STARTED
02:08:09 15.08.09 STC   15  IEF403I NET - STARTED - TIME=15.08.09
02:08:09 15.08.09           $HASP309    INIT  2 INACTIVE ******** C=BA
02:08:09 15.08.09           $HASP309    INIT  3 INACTIVE ******** C=CBA
02:08:09 15.08.09           $HASP309    INIT  4 INACTIVE ******** C=SHB
02:08:09 15.08.09           $HASP309    INIT  5 INACTIVE ******** C=SBA
02:08:09 15.08.09           $HASP309    INIT  6 INACTIVE ******** C=S
02:08:09 15.08.09           $HASP309    INIT  7 INACTIVE ******** C=E
02:08:09 15.08.09 STC    9  BSPGM40I -   200 MiB MAINSIZE memory available
02:08:09 15.08.09 STC    9  BSPGM41I -     2 Partitions of    64 MiB each
02:08:09 15.08.09 STC    9  BSPGM78I SVC 120 EP=00FE3248; MVS/380
02:08:09 15.08.09 STC    9  IEF404I SVC120I - ENDED - TIME=15.08.09
02:08:09 15.08.09 STC    9  $HASP395 SVC120I  ENDED
02:08:09 15.08.09 STC    9  $HASP150 SVC120I  ON PRINTER2        45 LINES
02:08:09 15.08.09 STC    9 *$HASP190 SVC120I  SETUP -- PRINTER2 -- F = 0001 -- C = 6    -- T = SN
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:09 15.08.09 STC    9  $HASP250 SVC120I  IS PURGED
02:08:09 HHCAO003I Firing command: 'script conf/subjobs.rc'
02:08:09 script conf/subjobs.rc
02:08:09 hao clear
02:08:09 HHCAO022I All automatic operation rules cleared
02:08:09 # Every job gets an NL tape available as input, containing
02:08:09 # some binary of unknown contents, most likely needing to
02:08:09 # be read as RECFM=U, but RECFM=FB and even RECFM=V are also
02:08:09 # possible.
02:08:09 #
02:08:09 # The job also gets an SL tape available for output, and
02:08:09 # again, any type of content can be written to it, and
02:08:09 # with a bit of luck, hetget will be able to extract the
02:08:09 # data you are looking for.
02:08:09 #
02:08:09 # And finally the job gets an SL AWS tape available for
02:08:09 # input and/or output should you wish to construct a
02:08:09 # special tape. Tape must be called AWSTAP. User should
02:08:09 # back the tape up before submitting it, because it will
02:08:09 # be overwritten and anything could go wrong. AWS is
02:08:09 # expected to be exceptional use of this procedure anyway
02:08:09 #
02:08:09 # Only the NL tape needs an explicit mount. The SL tapes
02:08:09 # are premounted before IPL
02:08:09 hao tgt HASP250 MOUNT
02:08:09 HHCAO016I Target placed at index 0
02:08:09 hao cmd script conf/subjobs2.rc
02:08:09 HHCAO020I Command placed at index 0
02:08:09 /(001F) M 401,VOL=(NL,PCTOMF)
02:08:09 HHCPN013I EOF reached on SCRIPT file. Processing complete.
02:08:09 15.08.09 STC   16  $HASP100 MOUNT    ON STCINRDR
02:08:09 15.08.09 STC   16  $HASP373 MOUNT    STARTED
02:08:09 15.08.09 STC   16  IEF403I MOUNT - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   16 *IEF233A M 401,PCTOMF,,MOUNT,401
02:08:09 15.08.09 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
02:08:09 15.08.09 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
02:08:09 15.08.09 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
02:08:09 15.08.09 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
02:08:09 15.08.09 STC   15  IST025I  BLDL FAILED FOR IEDIAK   IN VTAMLIB
02:08:09 15.08.09 STC   15  IST025I  BLDL FAILED FOR IEDIAK   IN VTAMLIB
02:08:09 15.08.09 STC   15  IST110I  NETWORK SOLICITOR STARTED
02:08:09 15.08.09 STC   15  IST093I  APPLJRP  ACTIVE
02:08:09 15.08.09 STC   15  IST093I  APPLPIES ACTIVE
02:08:09 15.08.09 STC   15  IST093I  APPLPIAD ACTIVE
02:08:09 15.08.09 STC   15  IST093I  APPLTSO  ACTIVE
02:08:09 15.08.09 STC   15  IST093I  APPLTEST ACTIVE
02:08:09 15.08.09 STC   10  DYNABLDL STARTED
02:08:09 15.08.09 STC   15  IST093I  LCLMAJRP ACTIVE
02:08:09 15.08.09 STC   15  IST093I  LCLMAJ00 ACTIVE
02:08:09 15.08.09 STC   17  $HASP100 TSO      ON STCINRDR
02:08:09 15.08.09 STC   17  $HASP373 TSO      STARTED
02:08:09 15.08.09 STC   17  IEF403I TSO - STARTED - TIME=15.08.09
02:08:09 15.08.09 STC   18  $HASP100 JRP      ON STCINRDR
02:08:09 15.08.09 STC   18  $HASP373 JRP      STARTED
02:08:09 15.08.09 STC   18  IEF403I JRP - STARTED - TIME=15.08.09
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09           $HASP000 OK
02:08:09 15.08.09 STC   15  IST020I  VTAM INITIALIZATION COMPLETE
02:08:09 15.08.09 STC   15  IEA000I 0C0,IOE,05,0200,400000000001,,,NET     ,15.08.09
02:08:09 15.08.09 STC   15  IEA000I 0C1,IOE,05,0200,400000000001,,,NET     ,15.08.09
02:08:09 15.08.09 STC   15  IEA000I 0C2,IOE,05,0200,400000000001,,,NET     ,15.08.09
02:08:09 15.08.09 STC   10  IEF404I DYNABLDL - ENDED - TIME=15.08.09
02:08:09 15.08.09 STC   10  $HASP395 DYNABLDL ENDED
02:08:09 15.08.09 STC   10  $HASP150 DYNABLDL ON PRINTER2        21 LINES
02:08:09 15.08.09           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:09 15.08.09 STC   10  $HASP250 DYNABLDL IS PURGED
02:08:09 15.08.09 STC   11  DMSK00I DYNAMASK DONE ****
02:08:09 15.08.09 STC   11  DMSK06I  START
02:08:09 15.08.09 STC   11  IEF404I DYNAMASK - ENDED - TIME=15.08.09
02:08:09 15.08.09 STC   11  $HASP395 DYNAMASK ENDED
02:08:09 15.08.09 STC   11  $HASP150 DYNAMASK ON PRINTER2        30 LINES
02:08:09 15.08.09           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:09 15.08.09 STC   11  $HASP250 DYNAMASK IS PURGED
02:08:09 15.08.09 STC   13  BSPSP91I - Parms passed: NOREPLYU
02:08:09 15.08.09 STC   13  BSPSP93I - PFK definitions will be updated in memory
02:08:09 15.08.09 STC   13  BSPSP22I - Dataset processed: SYS1.PARMLIB
02:08:09 15.08.09 STC   13  BSPSP23I - on volume MVSRES
02:08:09 15.08.09 STC   13  BSPSP21I - Member being processed: SETPFK01
02:08:09 15.08.09 STC   13  +BSPSP98I - Member processed, LASTCC=0000
02:08:09 15.08.09 STC   13  +BSPSP21I - Member being processed: SETPFK02
02:08:09 15.08.09 STC   13  +BSPSP98I - Member processed, LASTCC=0000
02:08:09 15.08.09 STC   13  +BSPSP99I - End of processing, MAXRC=0000
02:08:09 15.08.09 STC   13  IEF404I BSPSETPF - ENDED - TIME=15.08.09
02:08:09 15.08.09 STC   13  $HASP395 BSPSETPF ENDED
02:08:10 15.08.10 STC   13  $HASP150 BSPSETPF ON PRINTER2        34 LINES
02:08:10 15.08.10           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:10 15.08.10 STC   13  $HASP250 BSPSETPF IS PURGED
02:08:10 15.08.10 STC   14  IFC001I  D=3350 N=0B F=01AB0000 L=01AC0005 S=01AB000002 DIP COMPLETE
02:08:10 15.08.10 STC   14  IEF404I LOGRECI - ENDED - TIME=15.08.10
02:08:10 15.08.10 STC   14  $HASP395 LOGRECI  ENDED
02:08:10 15.08.10 STC   14  $HASP150 LOGRECI  ON PRINTER2        20 LINES
02:08:10 15.08.10           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:10 15.08.10 STC   14  $HASP250 LOGRECI  IS PURGED
02:08:10 15.08.10 STC   16  IEF404I MOUNT - ENDED - TIME=15.08.10
02:08:10 15.08.10 STC   16  $HASP395 MOUNT    ENDED
02:08:10 15.08.10 STC   16  $HASP150 MOUNT    ON PRINTER2        18 LINES
02:08:10 15.08.10           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:10 15.08.10 STC   16  $HASP250 MOUNT    IS PURGED
02:08:10 HHCAO003I Firing command: 'script conf/subjobs2.rc'
02:08:10 script conf/subjobs2.rc
02:08:10 hao clear
02:08:10 HHCAO022I All automatic operation rules cleared
02:08:10 # If we get a prompt for a device, cancel it
02:08:10 hao tgt IEF238D
02:08:10 HHCAO016I Target placed at index 0
02:08:10 hao cmd script conf/cancel.rc
02:08:10 HHCAO020I Command placed at index 0
02:08:10 # If we get a prompt for a catalogue password, answer it
02:08:10 hao tgt IEC301A
02:08:10 HHCAO016I Target placed at index 1
02:08:10 hao cmd script conf/secret.rc
02:08:10 HHCAO020I Command placed at index 1
02:08:10 devinit 401 tapes/pctomf.tdf
02:08:10 HHCTA004I 0401: tapes/pctomf.tdf is a Optical Media Attachment (OMA) tape
02:08:10 HHCPN098I Device 0:0401 initialized
02:08:10 # When we see TERMHERC get purged, our job is done
02:08:10 hao tgt HASP373 TERMHERC
02:08:10 HHCAO016I Target placed at index 2
02:08:10 hao cmd script conf/termherc.rc
02:08:10 HHCAO020I Command placed at index 2
02:08:10 # Now submit the job
02:08:10 devinit 00c jcl/hercauto.jcl eof
02:08:10 HHCSD007I Device 000C unbound from socket 127.0.0.1:3505
02:08:10 HHCSD022I Socketdevice listener thread terminated
02:08:10 HHCPN098I Device 0:000C initialized
02:08:10 HHCPN013I EOF reached on SCRIPT file. Processing complete.
02:08:10 15.08.10 JOB    1  $HASP100 HERC01A  ON READER1
02:08:10 15.08.10 JOB    2  $HASP100 TERMHERC ON READER1
02:08:10 15.08.10 JOB    1  $HASP373 HERC01A  STARTED - INIT  3 - CLASS C - SYS BSP1
02:08:10 15.08.10 JOB    1  IEF403I HERC01A - STARTED - TIME=15.08.10
02:08:10 15.08.10 STC   17  IKT007I TCAS ACCEPTING LOGONS
02:08:10 15.08.10 STC   17  IKT005I TCAS IS INITIALIZED
02:08:10 15.08.10 JOB    1  IEFACTRT - Stepname  Procstep  Program   Retcode
02:08:10 15.08.10 JOB    1  HERC01A    IEFBR14             IEFBR14   RC= 0000
02:08:10 15.08.10 JOB    1  IEF404I HERC01A - ENDED - TIME=15.08.10
02:08:10 15.08.10 JOB    1  $HASP395 HERC01A  ENDED
02:08:10 15.08.10 JOB    1  $HASP150 HERC01A  ON PRINTER1        21 LINES
02:08:10 15.08.10 JOB    1 *$HASP190 HERC01A  SETUP -- PRINTER1 -- F = 0001 -- C = 6    -- T = SN
02:08:10 15.08.10           $HASP000 OK
02:08:10 15.08.10 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1
02:08:10 HHCAO003I Firing command: 'script conf/termherc.rc'
02:08:10 script conf/termherc.rc
02:08:10 # We do an unnecessary 2-stage terminate, first triggering
02:08:10 # on the start message, then triggering on the purged
02:08:10 # message, to overcome an apparent bug in hercules which
02:08:10 # causes it to sometimes trigger on the wrong jobname.
02:08:10 hao clear
02:08:10 HHCAO022I All automatic operation rules cleared
02:08:10 hao tgt HASP250 TERMHERC
02:08:10 HHCAO016I Target placed at index 0
02:08:10 hao cmd script conf/termherc2.rc
02:08:10 HHCAO020I Command placed at index 0
02:08:10 HHCPN013I EOF reached on SCRIPT file. Processing complete.
02:08:10 15.08.10 JOB    2  IEF403I TERMHERC - STARTED - TIME=15.08.10
02:08:10 15.08.10           $HASP160 PRINTER1 INACTIVE - CLASS=AP
02:08:10 15.08.10 JOB    1  $HASP250 HERC01A  IS PURGED
02:08:10 15.08.10          *IEE362A SMF ENTER DUMP FOR SYS1.MANX ON MVSRES
02:08:10 15.08.10           IEE361I SMF DATA LOST - SYS1.MANY NOT AVAILABLE TIME=15.08.10
02:08:10 15.08.10 STC   19  $HASP100 SMFDAILY ON STCINRDR
02:08:10 15.08.10 STC   19  $HASP373 SMFDAILY STARTED
02:08:10 15.08.10 STC   19  IEF403I SMFDAILY - STARTED - TIME=15.08.10
02:08:10 15.08.10 STC   19  IEC604I VTOC CONVERT ROUTINE ENTERED ON 1B1,MVSCAT,DIRF
02:08:10 15.08.10 STC   18  JRP400E JRP400 ABENDING
02:08:10 15.08.10 STC   18  IST804I  VTAM CLOSE IN PROCESS FOR JRP      OPENED BY JRP      UNKNOWN
02:08:10 15.08.10 STC   15  IST400I  TERMINATION IN PROGRESS FOR APPLID JRP
02:08:10 15.08.10 STC   15  IST805I  VTAM CLOSE COMPLETE FOR JRP
02:08:10 15.08.10 STC   18  IEF450I JRP JRP - ABEND S000 U0043 - TIME=15.08.10
02:08:10 15.08.10 STC   18  IEF404I JRP - ENDED - TIME=15.08.10
02:08:10 15.08.10 STC   18  $HASP395 JRP      ENDED
02:08:10 15.08.10 STC   18  $HASP150 JRP      ON PRINTER2     1,661 LINES
02:08:10 15.08.10           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:10 15.08.10 STC   18  $HASP250 JRP      IS PURGED
02:08:10 15.08.10 JOB    2  IEFACTRT - Stepname  Procstep  Program   Retcode
02:08:10 15.08.10 JOB    2  TERMHERC   S1                  IEBGENER  RC= 0000
02:08:10 15.08.10 JOB    2  IEF404I TERMHERC - ENDED - TIME=15.08.10
02:08:10 15.08.10 JOB    2  $HASP395 TERMHERC ENDED
02:08:10 15.08.10           $HASP309    INIT  3 INACTIVE ******** C=CBA
02:08:10 15.08.10 JOB    2  $HASP150 TERMHERC ON PRINTER1         1 LINE
02:08:10 15.08.10 JOB    2  $HASP150 TERMHERC ON PRINTER2        44 LINES
02:08:10 15.08.10           $HASP160 PRINTER1 INACTIVE - CLASS=AP
02:08:10 15.08.10           $HASP160 PRINTER2 INACTIVE - CLASS=Z
02:08:10 15.08.10 JOB    2  $HASP250 TERMHERC IS PURGED
02:08:10 HHCAO003I Firing command: 'script conf/termherc2.rc'
02:08:10 script conf/termherc2.rc
02:08:10 # we put in an unnecessary "stopall" to prevent Hercules
02:08:10 # (3.07 and 3.12 at least) from randomly hanging in the
02:08:10 # "quit" command in about 5% of runs.
02:08:10 # It is still unclear why Hercules is hanging
02:08:10 stopall
02:08:10 quit
02:08:10 HHCIN900I Begin Hercules shutdown
02:08:10 HHCIN901I Releasing configuration
02:08:10 HHCCP008I CPU0000 thread ended: tid=00001FFC, pid=19064
02:08:10 HHCTT003I Timer thread ended
02:08:10 HHCCF047I Subchannel 0:0000 detached
02:08:10 HHCCF047I Subchannel 0:0001 detached
02:08:10 HHCCF047I Subchannel 0:0002 detached
02:08:10 HHCCF047I Subchannel 0:0003 detached
02:08:10 HHCCF047I Subchannel 0:0004 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD211I                                                  readaheads   misses
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   19358135   5%   17       1123      24      35    1015     1981
02:08:10 HHCCD214I                                                         160       28
02:08:10 HHCCD215I dasd/mvsres.148
02:08:10 HHCCD216I [0]   15179178   0%    1 ro     943       0      17
02:08:10 HHCCD217I shadow/mvsres_*.148
02:08:10 HHCCD218I [1]    4178957  20%   16        180      24      18
02:08:10 HHCCF047I Subchannel 0:0005 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/sort01.131
02:08:10 HHCCD216I [0]      34336   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/sort01_*.131
02:08:10 HHCCD218I [1]       1088   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0006 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/sort02.132
02:08:10 HHCCD216I [0]      34336   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/sort02_*.132
02:08:10 HHCCD218I [1]       1088   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0007 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/sort03.133
02:08:10 HHCCD216I [0]      34336   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/sort03_*.133
02:08:10 HHCCD218I [1]       1088   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0008 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/sort04.134
02:08:10 HHCCD216I [0]      34336   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/sort04_*.134
02:08:10 HHCCD218I [1]       1088   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0009 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/sort05.135
02:08:10 HHCCD216I [0]      34336   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/sort05_*.135
02:08:10 HHCCD218I [1]       1088   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:000A detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/sort06.136
02:08:10 HHCCD216I [0]      34336   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/sort06_*.136
02:08:10 HHCCD218I [1]       1088   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:000B detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   52422417   2%   77          1       0       2       0        1
02:08:10 HHCCD215I dasd/work00.140
02:08:10 HHCCD216I [0]     141963   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/work00_*.140
02:08:10 HHCCD218I [1]   52280454   2%   76          0       0       1
02:08:10 HHCCF047I Subchannel 0:000C detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    5023930   3%    5          1       0       1       0        1
02:08:10 HHCCD215I dasd/hasp00.152
02:08:10 HHCCD216I [0]    5023930   3%    5 rw       1       0       1
02:08:10 HHCCF047I Subchannel 0:000D detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD211I                                                  readaheads   misses
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   14431543  39%  529       1864    1368       8    1141     2374
02:08:10 HHCCD214I                                                         631       73
02:08:10 HHCCD215I dasd/page00.160
02:08:10 HHCCD216I [0]   14431543  39%  529 rw    1864    1368       8
02:08:10 HHCCF047I Subchannel 0:000E detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD211I                                                  readaheads   misses
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    4016734  16%   13         46     430      31      36       56
02:08:10 HHCCD214I                                                          26        2
02:08:10 HHCCD215I dasd/page01.161
02:08:10 HHCCD216I [0]    4016734  16%   13 rw      46     430      31
02:08:10 HHCCF047I Subchannel 0:000F detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD211I                                                  readaheads   misses
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    3833787  18%   34         40      35       1      34       52
02:08:10 HHCCD214I                                                          22        1
02:08:10 HHCCD215I dasd/page02.162
02:08:10 HHCCD216I [0]    3833787  18%   34 rw      40      35       1
02:08:10 HHCCF047I Subchannel 0:0010 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   57202932   1%  102          1       0       1       0        1
02:08:10 HHCCD215I dasd/work01.170
02:08:10 HHCCD216I [0]   57202932   1%  102 rw       1       0       1
02:08:10 HHCCF047I Subchannel 0:0011 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   66815692   2%  425          1       0       2       0        1
02:08:10 HHCCD215I dasd/work02.180
02:08:10 HHCCD216I [0]     113799   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/work02_*.180
02:08:10 HHCCD218I [1]   66701893   2%  424          0       0       1
02:08:10 HHCCF047I Subchannel 0:0012 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   56476534   2%  264          1       0       2       0        1
02:08:10 HHCCD215I dasd/work03.190
02:08:10 HHCCD216I [0]     142257   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/work03_*.190
02:08:10 HHCCD218I [1]   56334277   2%  263          0       0       1
02:08:10 HHCCF047I Subchannel 0:0013 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD211I                                                  readaheads   misses
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   17037777   9%   17         34       0       5      31       47
02:08:10 HHCCD214I                                                          19        3
02:08:10 HHCCD215I dasd/mvscat.191
02:08:10 HHCCD216I [0]    3658727   0%    1 ro      25       0       3
02:08:10 HHCCD217I shadow/mvscat_*.191
02:08:10 HHCCD218I [1]   13379050  11%   16          9       0       2
02:08:10 HHCCF047I Subchannel 0:0014 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]  103500159  17% 1297          1       0       2       0        1
02:08:10 HHCCD215I dasd/seasik.192
02:08:10 HHCCD216I [0]   16164960   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/seasik_*.192
02:08:10 HHCCD218I [1]   87335199  20% 1297          0       0       1
02:08:10 HHCCF047I Subchannel 0:0015 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]  168333900   4% 5454          1       0       1       0        1
02:08:10 HHCCD215I dasd/mvssrc.193
02:08:10 HHCCD216I [0]  168333900   4% 5454 rw       1       0       1
02:08:10 HHCCF047I Subchannel 0:0016 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD211I                                                  readaheads   misses
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   44516465   2%   22         33       0       8      24       51
02:08:10 HHCCD214I                                                           6        4
02:08:10 HHCCD215I dasd/pub000.240
02:08:10 HHCCD216I [0]    7591138   3%    1 ro      13       0       4
02:08:10 HHCCD217I shadow/pub000_*.240
02:08:10 HHCCD218I [1]   36925327   2%   21         20       0       4
02:08:10 HHCCF047I Subchannel 0:0017 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   25717706   0%    6          5       2       5       1        6
02:08:10 HHCCD215I dasd/mvsdlb.248
02:08:10 HHCCD216I [0]   25471539   0%    1 ro       3       0       3
02:08:10 HHCCD217I shadow/mvsdlb_*.248
02:08:10 HHCCD218I [1]     246167  38%    5          2       2       2
02:08:10 HHCCF047I Subchannel 0:0018 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]  100064666   8%  539          1       0       2       0        1
02:08:10 HHCCD215I dasd/pub002.280
02:08:10 HHCCD216I [0]    2171954  29%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/pub002_*.280
02:08:10 HHCCD218I [1]   97892712   8%  538          0       0       1
02:08:10 HHCCF047I Subchannel 0:0019 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]     143545   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/tmptmp.2b1
02:08:10 HHCCD216I [0]     142257   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/tmptmp_*.2b1
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:001A detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]     143545   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/xmit90.2b2
02:08:10 HHCCD216I [0]     142257   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/xmit90_*.2b2
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:001B detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    6099280   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/start1.150
02:08:10 HHCCD216I [0]    6098016   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/start1_*.150
02:08:10 HHCCD218I [1]       1264   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:001C detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    4595678   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/spool0.151
02:08:10 HHCCD216I [0]    4594414   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/spool0_*.151
02:08:10 HHCCD218I [1]       1264   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:001D detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   50622559   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/cbt000.340
02:08:10 HHCCD216I [0]   50621271   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/cbt000_*.340
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:001E detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   53836805   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/cbt001.341
02:08:10 HHCCD216I [0]   53835517   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/cbt001_*.341
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:001F detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   46082980   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/cbt002.342
02:08:10 HHCCD216I [0]   46081692   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/cbt002_*.342
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0020 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   27241782   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/cbtcat.343
02:08:10 HHCCD216I [0]   27240494   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/cbtcat_*.343
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0021 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   46003602   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/src000.348
02:08:10 HHCCD216I [0]   46002314   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/src000_*.348
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0022 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   45707725   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/src001.349
02:08:10 HHCCD216I [0]   45706437   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/src001_*.349
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0023 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   44403653   0%    0          1       0       1       0        1
02:08:10 HHCCD215I dasd/src002.34a
02:08:10 HHCCD216I [0]   44402365   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/src002_*.34a
02:08:10 HHCCD218I [1]       1288   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:0024 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    6321674   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/srccat.34b
02:08:10 HHCCD216I [0]    6310767   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/srccat_*.34b
02:08:10 HHCCD218I [1]      10907   7%    1          0       0       0
02:08:10 HHCCF047I Subchannel 0:0025 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    1118801  11%    2          1       0       2       0        1
02:08:10 HHCCD215I dasd/smp001.149
02:08:10 HHCCD216I [0]     774654   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/smp001_*.149
02:08:10 HHCCD218I [1]     344147  38%    2          0       0       1
02:08:10 HHCCF047I Subchannel 0:0026 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    1621663  24%   12          1       0       2       0        1
02:08:10 HHCCD215I dasd/smp002.14a
02:08:10 HHCCD216I [0]     856740   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/smp002_*.14a
02:08:10 HHCCD218I [1]     764923  51%   12          0       0       1
02:08:10 HHCCF047I Subchannel 0:0027 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    1077383  19%    3          1       0       2       0        1
02:08:10 HHCCD215I dasd/smp003.14b
02:08:10 HHCCD216I [0]     592555   0%    0 ro       1       0       1
02:08:10 HHCCD217I shadow/smp003_*.14b
02:08:10 HHCCD218I [1]     484828  42%    3          0       0       1
02:08:10 HHCCF047I Subchannel 0:0028 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    3437923  36%    4          1       0       2       0        1
02:08:10 HHCCD215I dasd/smp004.14c
02:08:10 HHCCD216I [0]    2916431  35%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/smp004_*.14c
02:08:10 HHCCD218I [1]     521492  41%    3          0       0       1
02:08:10 HHCCF047I Subchannel 0:0029 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD211I                                                  readaheads   misses
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]   11902899  19%  115        137     126       6     789      893
02:08:10 HHCCD214I                                                          35       14
02:08:10 HHCCD215I dasd/js2sp0.700
02:08:10 HHCCD216I [0]     142291   0%    1 ro       0       0       1
02:08:10 HHCCD217I shadow/js2sp0_*.700
02:08:10 HHCCD218I [1]   11760608  19%  114        137     126       5
02:08:10 HHCCF047I Subchannel 0:002A detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]     715081   0%    1          1       0       2       0        1
02:08:10 HHCCD215I dasd/dlicat.138
02:08:10 HHCCD216I [0]      36630   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/dlicat_*.138
02:08:10 HHCCD218I [1]     678451   0%    0          0       0       1
02:08:10 HHCCF047I Subchannel 0:002B detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]     880289   0%    1          1       0       2       0        1
02:08:10 HHCCD215I dasd/dlisys.139
02:08:10 HHCCD216I [0]      36630   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/dlisys_*.139
02:08:10 HHCCD218I [1]     843659   0%    0          0       0       1
02:08:10 HHCCF047I Subchannel 0:002C detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      43495   0%    1          1       0       2       0        1
02:08:10 HHCCD215I dasd/dli000.13a
02:08:10 HHCCD216I [0]      36630   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/dli000_*.13a
02:08:10 HHCCD218I [1]       6865   0%    0          0       0       1
02:08:10 HHCCF047I Subchannel 0:002D detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      46911   0%    1          1       0       2       0        1
02:08:10 HHCCD215I dasd/dli001.13b
02:08:10 HHCCD216I [0]      36630   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/dli001_*.13b
02:08:10 HHCCD218I [1]      10281   0%    0          0       0       1
02:08:10 HHCCF047I Subchannel 0:002E detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]      37718   0%    1          1       0       1       0        1
02:08:10 HHCCD215I dasd/dli002.13c
02:08:10 HHCCD216I [0]      36630   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/dli002_*.13c
02:08:10 HHCCD218I [1]       1088   0%    0          0       0       0
02:08:10 HHCCF047I Subchannel 0:002F detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]    1233964   0%    1          1       0       2       0        1
02:08:10 HHCCD215I dasd/js3sp0.710
02:08:10 HHCCD216I [0]     141965   0%    1 ro       1       0       1
02:08:10 HHCCD217I shadow/js3sp0_*.710
02:08:10 HHCCD218I [1]    1091999   0%    0          0       0       1
02:08:10 HHCCF047I Subchannel 0:0030 detached
02:08:10 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
02:08:10 HHCCD212I --------------------------------------------------------------------
02:08:10 HHCCD213I [*]     951745   0%    2          1       0       2       0        1
02:08:10 HHCCD215I dasd/js3res.711
02:08:10 HHCCD216I [0]     142093   0%    2 ro       1       0       1
02:08:10 HHCCD217I shadow/js3res_*.711
02:08:10 HHCCD218I [1]     809652   0%    0          0       0       1
02:08:10 HHCCD011I Readahead thread 1 stopping: tid=00004CC0, pid=19064
02:08:10 HHCCD011I Readahead thread 2 stopping: tid=00000C78, pid=19064
02:08:10 HHCCD013I Garbage collector thread stopping: tid=000007A0, pid=19064
02:08:10 HHCCD012I Writer thread 2 stopping: tid=00004954, pid=19064
02:08:10 HHCCD012I Writer thread 1 stopping: tid=00003174, pid=19064
02:08:10 HHCCF047I Subchannel 0:0031 detached
02:08:10 HHCCF047I Subchannel 0:0032 detached
02:08:10 HHCCF047I Subchannel 0:0033 detached
02:08:10 HHCCF047I Subchannel 0:0034 detached
02:08:10 HHCCF047I Subchannel 0:0035 detached
02:08:10 HHCCF047I Subchannel 0:0036 detached
02:08:10 HHCCF047I Subchannel 0:0037 detached
02:08:10 HHCTE004I Console connection thread terminated
02:08:10 HHCCF047I Subchannel 0:0038 detached
02:08:10 HHCCF047I Subchannel 0:0039 detached
02:08:10 HHCCF047I Subchannel 0:003A detached
02:08:10 HHCCF047I Subchannel 0:003B detached
02:08:10 HHCCF047I Subchannel 0:003C detached
02:08:10 HHCIN902I Configuration release complete
02:08:10 HHCIN903I Calling termination routines
02:08:10 HHCHD900I Begin shutdown sequence
02:08:10 HHCHD901I Calling panel_cleanup
02:08:10 HHCHD902I panel_cleanup complete
02:08:10 HHCHD901I Calling console_shutdown
02:08:10 HHCHD902I console_shutdown complete
02:08:10 HHCHD901I Calling term_sockdev
02:08:10 HHCHD902I term_sockdev complete
02:08:10 HHCHD901I Calling hdl_term
02:08:10 HHCHD950I Begin HDL termination sequence
02:08:10 HHCHD951I Calling module *Hercules cleanup routine
02:08:10 HHCHD952I Module *Hercules cleanup complete
02:08:10 HHCHD959I HDL Termination sequence complete
02:08:10 HHCHD902I hdl_term complete
02:08:10 HHCHD901I Calling logger_term
02:08:10 HHCLG014I logger thread terminating
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
And another anomaly of SMFDAILY
ending with a JCL error from an
older run (which I no longer have
corresponding printer output for):

17:55:33 06.55.33 STC   19  $HASP100 SMFDAILY ON STCINRDR
17:55:33 06.55.33 STC   19  $HASP373 SMFDAILY STARTED
17:55:33 06.55.33 STC   19  IEF403I SMFDAILY - STARTED - TIME=06.55.33
17:55:33 06.55.33 JOB    2  IEF403I TERMHERC - STARTED - TIME=06.55.33
17:55:33 06.55.33 STC   19  IEF453I SMFDAILY - JOB FAILED - JCL ERROR - TIME=06.55.33
17:55:33 06.55.33 STC   19  $HASP395 SMFDAILY ENDED
17:55:33 06.55.33 STC   19  $HASP150 SMFDAILY ON PRINTER2        25 LINES
17:55:33 06.55.33           IEE132I START COMMAND DEVICE ALLOCATION ERROR
17:55:33 06.55.33           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:33 06.55.33 STC   19  $HASP250 SMFDAILY IS PURGED

(full log below).

The problem seems to have gone away
by itself. All recent runs have it starting,
but not finishing.

Note that I haven't made any change
myself to explain these different results.

BFN. Paul.




17:55:29 Hercules Version 3.07:380-4.x
17:55:29 (c)Copyright 1999-2010 by Roger Bowler, Jan Jaeger, and others
17:55:29 Built on Dec  7 2016 at 12:43:32
17:55:29 Build information:
17:55:29   Windows (MSVC) build for AMD64
17:55:29   Modes: S/370 S/380 ESA/390 z/Arch
17:55:29   Max CPU Engines: 8
17:55:29   Using fthreads instead of pthreads
17:55:29   Dynamic loading support
17:55:29   Using shared libraries
17:55:29   HTTP Server support
17:55:29   No SIGABEND handler
17:55:29   Regular Expressions support
17:55:29   Automatic Operator support
17:55:29   Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8
17:55:29 Running on PAUL-DELL Windows_NT-6.2 AMD64 MP=8
17:55:29 HHCHD018I Loadable module directory is hercules
17:55:29 Crypto module loaded (c) Copyright Bernard van der Helm, 2003-2010
17:55:29   Active: Message Security Assist
17:55:29           Message Security Assist Extension 1
17:55:29           Message Security Assist Extension 2
17:55:29 HHCPN210I Default Allowed AUTOMOUNT directory = "c:\mvs380\"
17:55:29 HHCCF065I Hercules: tid=00001918, pid=19268, pgid=19268, priority=8
17:55:29 HHCHT001I HTTP listener thread started: tid=000039E4, pid=19268
17:55:29 HHCHT013I Using HTTPROOT directory "c:\herc380\html\"
17:55:29 HHCHT006I Waiting for HTTP requests on port 8081
17:55:29 HHCSD004I Device 000C bound to socket 127.0.0.1:3505
17:55:29 HHCSD020I Socketdevice listener thread started: tid=0000210C, pid=19268
17:55:29 HHCCF083I conf/mvs380.conf Including conf/mvs380_DASD.conf at 123 .
17:55:29 HHCDA004I opening dasd/mvsres.148 readonly
17:55:29 HHCDA020I dasd/mvsres.148 cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA004I opening dasd/sort01.131 readonly
17:55:29 HHCDA020I dasd/sort01.131 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/sort02.132 readonly
17:55:29 HHCDA020I dasd/sort02.132 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/sort03.133 readonly
17:55:29 HHCDA020I dasd/sort03.133 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/sort04.134 readonly
17:55:29 HHCDA020I dasd/sort04.134 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/sort05.135 readonly
17:55:29 HHCDA020I dasd/sort05.135 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/sort06.136 readonly
17:55:29 HHCDA020I dasd/sort06.136 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/work00.140 readonly
17:55:29 HHCDA020I dasd/work00.140 cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA020I dasd/hasp00.152 cyls=404 heads=19 tracks=7676 trklen=13312
17:55:29 HHCDA020I dasd/page00.160 cyls=698 heads=12 tracks=8376 trklen=8704
17:55:29 HHCDA020I dasd/page01.161 cyls=698 heads=12 tracks=8376 trklen=8704
17:55:29 HHCDA020I dasd/page02.162 cyls=698 heads=12 tracks=8376 trklen=8704
17:55:29 HHCDA020I dasd/work01.170 cyls=962 heads=12 tracks=11544 trklen=35840
17:55:29 HHCDA004I opening dasd/work02.180 readonly
17:55:29 HHCDA020I dasd/work02.180 cyls=886 heads=15 tracks=13290 trklen=47616
17:55:29 HHCDA004I opening dasd/work03.190 readonly
17:55:29 HHCDA020I dasd/work03.190 cyls=1114 heads=15 tracks=16710 trklen=56832
17:55:29 HHCDA004I opening dasd/mvscat.191 readonly
17:55:29 HHCDA020I dasd/mvscat.191 cyls=1114 heads=15 tracks=16710 trklen=56832
17:55:29 HHCDA004I opening dasd/seasik.192 readonly
17:55:29 HHCDA020I dasd/seasik.192 cyls=1114 heads=15 tracks=16710 trklen=56832
17:55:29 HHCDA020I dasd/mvssrc.193 cyls=2226 heads=15 tracks=33390 trklen=56832
17:55:29 HHCDA002E 01B4:File not found or invalid 'dasd/pub004.1b4'
17:55:29 HHCCF044E Initialization failed for device 01B4
17:55:29 HHCDA004I opening dasd/pub000.240 readonly
17:55:29 HHCDA020I dasd/pub000.240 cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA004I opening dasd/mvsdlb.248 readonly
17:55:29 HHCDA020I dasd/mvsdlb.248 cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA004I opening dasd/pub002.280 readonly
17:55:29 HHCDA020I dasd/pub002.280 cyls=1772 heads=15 tracks=26580 trklen=47616
17:55:29 HHCDA004I opening dasd/tmptmp.2b1 readonly
17:55:29 HHCDA020I dasd/tmptmp.2b1 cyls=1114 heads=15 tracks=16710 trklen=56832
17:55:29 HHCDA004I opening dasd/xmit90.2b2 readonly
17:55:29 HHCDA020I dasd/xmit90.2b2 cyls=1114 heads=15 tracks=16710 trklen=56832
17:55:29 HHCDA004I opening dasd/start1.150 readonly
17:55:29 HHCDA020I dasd/start1.150 cyls=808 heads=19 tracks=15352 trklen=13312
17:55:29 HHCDA004I opening dasd/spool0.151 readonly
17:55:29 HHCDA020I dasd/spool0.151 cyls=808 heads=19 tracks=15352 trklen=13312
17:55:29 HHCDA004I opening dasd/cbt000.340 readonly
17:55:29 HHCDA020I dasd/cbt000.340 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/cbt001.341 readonly
17:55:29 HHCDA020I dasd/cbt001.341 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/cbt002.342 readonly
17:55:29 HHCDA020I dasd/cbt002.342 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/cbtcat.343 readonly
17:55:29 HHCDA020I dasd/cbtcat.343 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/src000.348 readonly
17:55:29 HHCDA020I dasd/src000.348 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/src001.349 readonly
17:55:29 HHCDA020I dasd/src001.349 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/src002.34a readonly
17:55:29 HHCDA020I dasd/src002.34a cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/srccat.34b readonly
17:55:29 HHCDA020I dasd/srccat.34b cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/smp001.149 readonly
17:55:29 HHCDA020I dasd/smp001.149 cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA004I opening dasd/smp002.14a readonly
17:55:29 HHCDA020I dasd/smp002.14a cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA004I opening dasd/smp003.14b readonly
17:55:29 HHCDA020I dasd/smp003.14b cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA004I opening dasd/smp004.14c readonly
17:55:29 HHCDA020I dasd/smp004.14c cyls=560 heads=30 tracks=16800 trklen=19456
17:55:29 HHCDA004I opening dasd/js2sp0.700 readonly
17:55:29 HHCDA020I dasd/js2sp0.700 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/dlicat.138 readonly
17:55:29 HHCDA020I dasd/dlicat.138 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/dlisys.139 readonly
17:55:29 HHCDA020I dasd/dlisys.139 cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/dli000.13a readonly
17:55:29 HHCDA020I dasd/dli000.13a cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/dli001.13b readonly
17:55:29 HHCDA020I dasd/dli001.13b cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/dli002.13c readonly
17:55:29 HHCDA020I dasd/dli002.13c cyls=200 heads=20 tracks=4000 trklen=7680
17:55:29 HHCDA004I opening dasd/js3sp0.710 readonly
17:55:29 HHCDA020I dasd/js3sp0.710 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCDA004I opening dasd/js3res.711 readonly
17:55:29 HHCDA020I dasd/js3res.711 cyls=555 heads=30 tracks=16650 trklen=19456
17:55:29 HHCTE001I Console connection thread started: tid=00001120, pid=19268
17:55:29 HHCTE003I Waiting for console connection on port 3270
17:55:29 HHCTA066I 0400: option 'level' accepted.
17:55:29 HHCTA066I 0401: option 'level' accepted.
17:55:29 HHCTA066I 0402: option 'level' accepted.
17:55:29 HHCTA066I 0403: option 'level' accepted.
17:55:29 HHCCP002I CPU0000 thread started: tid=00001EEC, pid=19268, priority=0
17:55:29 HHCCP003I CPU0000 architecture mode S/380
17:55:29 HHCPN001I Control panel thread started: tid=00001918, pid=19268
17:55:29 HHCTT002I Timer thread started: tid=000056B4, pid=19268, priority=-20
17:55:29 HHCPN008I Script file processing started using file "conf/auto_run.rc"
17:55:29 HHCAO001I Hercules Automatic Operator thread started;
17:55:29           tid=00003E68, pri=0, pid=19268
17:55:29 devlist
17:55:29 0:000C 3505 127.0.0.1:3505 sockdev ascii trunc eof
17:55:29      (no one currently connected)
17:55:29 0:000D 3525 pch/pch00d.txt ascii crlf
17:55:29 0:000E 1403 prt/prt00e.txt crlf noclear
17:55:29 0:000F 1403 prt/prt00f.txt crlf noclear
17:55:29 0:001F 3215 *syscons cmdpref(/)
17:55:29 0:00C0 3270  
17:55:29 0:00C1 3270  
17:55:29 0:00C2 3270  
17:55:29 0:00C7 3287  
17:55:29 0:010C 3505 jcl/dummy eof
17:55:29 0:0131 2314 dasd/sort01.131 [200 cyls] open
17:55:29 0:0132 2314 dasd/sort02.132 [200 cyls] open
17:55:29 0:0133 2314 dasd/sort03.133 [200 cyls] open
17:55:29 0:0134 2314 dasd/sort04.134 [200 cyls] open
17:55:29 0:0135 2314 dasd/sort05.135 [200 cyls] open
17:55:29 0:0136 2314 dasd/sort06.136 [200 cyls] open
17:55:29 0:0138 2314 dasd/dlicat.138 [200 cyls] open
17:55:29 0:0139 2314 dasd/dlisys.139 [200 cyls] open
17:55:29 0:013A 2314 dasd/dli000.13a [200 cyls] open
17:55:29 0:013B 2314 dasd/dli001.13b [200 cyls] open
17:55:29 0:013C 2314 dasd/dli002.13c [200 cyls] open
17:55:29 0:0140 3350 dasd/work00.140 [560 cyls] open
17:55:29 0:0148 3350 dasd/mvsres.148 [560 cyls] open
17:55:29 0:0149 3350 dasd/smp001.149 [560 cyls] open
17:55:29 0:014A 3350 dasd/smp002.14a [560 cyls] open
17:55:29 0:014B 3350 dasd/smp003.14b [560 cyls] open
17:55:29 0:014C 3350 dasd/smp004.14c [560 cyls] open
17:55:29 0:0150 3330 dasd/start1.150 [808 cyls] open
17:55:29 0:0151 3330 dasd/spool0.151 [808 cyls] open
17:55:29 0:0152 3330 dasd/hasp00.152 [404 cyls] open
17:55:29 0:0160 3340 dasd/page00.160 [698 cyls] open
17:55:29 0:0161 3340 dasd/page01.161 [698 cyls] open
17:55:29 0:0162 3340 dasd/page02.162 [698 cyls] open
17:55:29 0:0170 3375 dasd/work01.170 [962 cyls] open
17:55:29 0:01A0 3380 dasd/work02.180 [886 cyls] open
17:55:29 0:01B0 3390 dasd/work03.190 [1114 cyls] open
17:55:29 0:01B1 3390 dasd/mvscat.191 [1114 cyls] open
17:55:29 0:01B2 3390 dasd/seasik.192 [1114 cyls] open
17:55:29 0:01B3 3390 dasd/mvssrc.193 [2226 cyls] open
17:55:29 0:01C7 3287  
17:55:29 0:0240 3350 dasd/pub000.240 [560 cyls] open
17:55:29 0:0248 3350 dasd/mvsdlb.248 [560 cyls] open
17:55:29 0:02A0 3380 dasd/pub002.280 [1772 cyls] open
17:55:29 0:02B1 3390 dasd/tmptmp.2b1 [1114 cyls] open
17:55:29 0:02B2 3390 dasd/xmit90.2b2 [1114 cyls] open
17:55:29 0:030E 1403 log/hardcopy.log crlf noclear
17:55:29 0:0340 3350 dasd/cbt000.340 [555 cyls] open
17:55:29 0:0341 3350 dasd/cbt001.341 [555 cyls] open
17:55:29 0:0342 3350 dasd/cbt002.342 [555 cyls] open
17:55:29 0:0343 3350 dasd/cbtcat.343 [555 cyls] open
17:55:29 0:0348 3350 dasd/src000.348 [555 cyls] open
17:55:29 0:0349 3350 dasd/src001.349 [555 cyls] open
17:55:29 0:034A 3350 dasd/src002.34a [555 cyls] open
17:55:29 0:034B 3350 dasd/srccat.34b [555 cyls] open
17:55:29 0:0400 3420 *
17:55:29 0:0401 3420 *
17:55:29 0:0402 3420 *
17:55:29 0:0403 3420 *
17:55:29 0:0700 3350 dasd/js2sp0.700 [555 cyls] open
17:55:29 0:0710 3350 dasd/js3sp0.710 [555 cyls] open
17:55:29 0:0711 3350 dasd/js3res.711 [555 cyls] open
17:55:29 logopt timestamp
17:55:29 HHCPN197I Log option set: TIMESTAMP
17:55:29 panrate 1000
17:55:29 # really need to wait for SVC120I, but if building MVS/380
17:55:29 # or some other stuffup with parms, need to trigger on an
17:55:29 # alternative. First one hit will clear targets.
17:55:29 # If we get a prompt for a device, cancel it
17:55:29 hao tgt IEF238D
17:55:29 HHCAO016I Target placed at index 0
17:55:29 hao cmd script conf/cancel.rc
17:55:29 HHCAO020I Command placed at index 0
17:55:29 hao tgt HASP395 DYNAMASK
17:55:29 HHCAO016I Target placed at index 1
17:55:29 hao cmd script conf/subjobs_slow.rc
17:55:29 HHCAO020I Command placed at index 1
17:55:29 hao tgt HASP373 SVC120I
17:55:29 HHCAO016I Target placed at index 2
17:55:29 hao cmd script conf/subjobs_fast.rc
17:55:29 HHCAO020I Command placed at index 2
17:55:29 hao tgt HASP436 REPLY
17:55:29 HHCAO016I Target placed at index 3
17:55:29 hao cmd script conf/replyy.rc
17:55:29 HHCAO020I Command placed at index 3
17:55:29 devinit 402 tapes/mftopc.het
17:55:29 HHCTA004I 0402: tapes/mftopc.het is a Hercules Emulated Tape file
17:55:29 HHCPN098I Device 0:0402 initialized
17:55:29 devinit 403 tapes/awstap.aws
17:55:29 HHCTA004I 0403: tapes/awstap.aws is a Hercules Emulated Tape file
17:55:29 HHCPN098I Device 0:0403 initialized
17:55:29 # co will give you a cold start of JES2 which is useful in
17:55:29 # automated runs
17:55:29 /(001F) r 00,clpa,cmd=co
17:55:29 #/r 00,clpa
17:55:29 ipl 148
17:55:29 HHCPN013I EOF reached on SCRIPT file. Processing complete.
17:55:29 IEA101A SPECIFY SYSTEM PARMS FOR MVS/380 1.2 v03.8 TK3+
17:55:29 HHCCD001I Readahead thread 1 started: tid=000015AC, pid=19268
17:55:29 HHCCD001I Readahead thread 2 started: tid=00001A28, pid=19268
17:55:29 HHCCD002I Writer thread 1 started: tid=00001B98, pid=19268
17:55:29 HHCCD003I Garbage collector thread started: tid=00001F18, pid=19268
17:55:29 IEA940I THE FOLLOWING PAGE DATA SETS ARE IN USE
17:55:29  PLPA ... SYS1.PAGELPA
17:55:29  COMMON . SYS1.PAGECSA
17:55:29  DUPLEX . SYS1.DUPLEX
17:55:29  LOCAL .. SYS1.PAGEL01
17:55:29  LOCAL .. SYS1.PAGEL02
17:55:29  LOCAL .. SYS1.PAGEL03
17:55:29 HHCCD002I Writer thread 2 started: tid=00003CA4, pid=19268
17:55:31 *IEE362A SMF ENTER DUMP FOR SYS1.MANY ON MVSRES
17:55:31  IEE360I SMF NOW RECORDING ON SYS1.MANX ON MVSRES TIME=06.55.31
17:55:31  IGF992I  MIH INIT COMPLETE, PRI=000300, SEC=000015
17:55:31  IEF677I WARNING MESSAGE(S) FOR JOB JES2     ISSUED
17:55:31 *00 $HASP436 REPLY Y OR N TO CONFIRM CHECKPOINT RECORD CHANGE
17:55:31 HHCAO003I Firing command: 'script conf/replyy.rc'
17:55:31 script conf/replyy.rc
17:55:31 /(001F) reply 00,y
17:55:31 HHCPN013I EOF reached on SCRIPT file. Processing complete.
17:55:31  IEE600I REPLY TO 00 IS;SUPPRESSED
17:55:31  $HASP493 JES2 COLD-START IS IN PROGRESS
17:55:32  $HASP412 MAXIMUM OF 1   READER(S)  EXCEEDED
17:55:32 06.55.32           IEE041I THE SYSTEM LOG IS NOW ACTIVE
17:55:32 06.55.32           IEE302I 00E      ONLINE
17:55:32 06.55.32           IEE302I 00F      ONLINE
17:55:32 06.55.32           IEE313I 30E     UNIT REF INVALID
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           IEE450I 06.55.32 UNIT STATUS 160
17:55:32  UNIT TYPE STATUS  VOLSER VOLSTATE   UNIT TYPE STATUS  VOLSER VOLSTATE
17:55:32  400  3400 O                  /REMOV 401  3400 O                  /REMOV
17:55:32  402  3400 O                  /REMOV
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP160 PRINTER1 INACTIVE - CLASS=AP
17:55:32 06.55.32           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:32 06.55.32           $HASP160 PUNCH1   INACTIVE - CLASS=B
17:55:32 06.55.32 STC    2  $HASP100 INIT     ON STCINRDR
17:55:32 06.55.32 STC    2  $HASP373 INIT     STARTED
17:55:32 06.55.32 STC    2  IEF403I INIT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC    3  $HASP100 INIT     ON STCINRDR
17:55:32 06.55.32 STC    3  $HASP373 INIT     STARTED
17:55:32 06.55.32 STC    3  IEF403I INIT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC    4  $HASP100 INIT     ON STCINRDR
17:55:32 06.55.32 STC    4  $HASP373 INIT     STARTED
17:55:32 06.55.32 STC    4  IEF403I INIT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC    5  $HASP100 INIT     ON STCINRDR
17:55:32 06.55.32 STC    5  $HASP373 INIT     STARTED
17:55:32 06.55.32 STC    5  IEF403I INIT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC    6  $HASP100 INIT     ON STCINRDR
17:55:32 06.55.32 STC    6  $HASP373 INIT     STARTED
17:55:32 06.55.32 STC    6  IEF403I INIT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC    7  $HASP100 INIT     ON STCINRDR
17:55:32 06.55.32 STC    7  $HASP373 INIT     STARTED
17:55:32 06.55.32 STC    7  IEF403I INIT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC    8  $HASP100 INIT     ON STCINRDR
17:55:32 06.55.32 STC    8  $HASP373 INIT     STARTED
17:55:32 06.55.32 STC    8  IEF403I INIT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC    9  $HASP100 SVC120I  ON STCINRDR
17:55:32 06.55.32 STC    9  $HASP373 SVC120I  STARTED
17:55:32 HHCAO003I Firing command: 'script conf/subjobs_fast.rc'
17:55:32 script conf/subjobs_fast.rc
17:55:32 # Now we know that SVC120I has started. But due to some
17:55:32 # weird pausing, it may get locked out. So clear out
17:55:32 # other triggers and wait on this
17:55:32 hao clear
17:55:32 HHCAO022I All automatic operation rules cleared
17:55:32 hao tgt HASP250 SVC120I
17:55:32 HHCAO016I Target placed at index 0
17:55:32 hao cmd script conf/subjobs.rc
17:55:32 HHCAO020I Command placed at index 0
17:55:32 HHCPN013I EOF reached on SCRIPT file. Processing complete.
17:55:32 06.55.32 STC    9  IEF403I SVC120I - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   10  $HASP100 DYNABLDL ON STCINRDR
17:55:32 06.55.32 STC   10  $HASP373 DYNABLDL STARTED
17:55:32 06.55.32 STC   10  IEF403I DYNABLDL - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   11  $HASP100 DYNAMASK ON STCINRDR
17:55:32 06.55.32 STC   11  $HASP373 DYNAMASK STARTED
17:55:32 06.55.32 STC   11  IEF403I DYNAMASK - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   12  $HASP100 BSPPILOT ON STCINRDR
17:55:32 06.55.32 STC   12  $HASP373 BSPPILOT STARTED
17:55:32 06.55.32 STC   12  IEF403I BSPPILOT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   13  $HASP100 BSPSETPF ON STCINRDR
17:55:32 06.55.32 STC   13  $HASP373 BSPSETPF STARTED
17:55:32 06.55.32 STC   13  IEF403I BSPSETPF - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   14  $HASP100 LOGRECI  ON STCINRDR
17:55:32 06.55.32 STC   14  $HASP373 LOGRECI  STARTED
17:55:32 06.55.32 STC   14  IEF403I LOGRECI - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   15  $HASP100 NET      ON STCINRDR
17:55:32 06.55.32           $HASP309    INIT  1 INACTIVE ******** C=A
17:55:32 06.55.32 STC   15  $HASP373 NET      STARTED
17:55:32 06.55.32 STC   15  IEF403I NET - STARTED - TIME=06.55.32
17:55:32 06.55.32           $HASP309    INIT  2 INACTIVE ******** C=BA
17:55:32 06.55.32           $HASP309    INIT  3 INACTIVE ******** C=CBA
17:55:32 06.55.32           $HASP309    INIT  4 INACTIVE ******** C=SHB
17:55:32 06.55.32           $HASP309    INIT  5 INACTIVE ******** C=SBA
17:55:32 06.55.32           $HASP309    INIT  6 INACTIVE ******** C=S
17:55:32 06.55.32           $HASP309    INIT  7 INACTIVE ******** C=E
17:55:32 06.55.32 STC    9  BSPGM40I -   200 MiB MAINSIZE memory available
17:55:32 06.55.32 STC    9  BSPGM41I -     2 Partitions of    64 MiB each
17:55:32 06.55.32 STC    9  BSPGM78I SVC 120 EP=00FE32A8; MVS/380
17:55:32 06.55.32 STC    9  IEF404I SVC120I - ENDED - TIME=06.55.32
17:55:32 06.55.32 STC    9  $HASP395 SVC120I  ENDED
17:55:32 06.55.32 STC    9  $HASP150 SVC120I  ON PRINTER2        45 LINES
17:55:32 06.55.32 STC    9 *$HASP190 SVC120I  SETUP -- PRINTER2 -- F = 0001 -- C = 6    -- T = SN
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:32 06.55.32 STC    9  $HASP250 SVC120I  IS PURGED
17:55:32 HHCAO003I Firing command: 'script conf/subjobs.rc'
17:55:32 script conf/subjobs.rc
17:55:32 hao clear
17:55:32 HHCAO022I All automatic operation rules cleared
17:55:32 # Every job gets an NL tape available as input, containing
17:55:32 # some binary of unknown contents, most likely needing to
17:55:32 # be read as RECFM=U, but RECFM=FB and even RECFM=V are also
17:55:32 # possible.
17:55:32 #
17:55:32 # The job also gets an SL tape available for output, and
17:55:32 # again, any type of content can be written to it, and
17:55:32 # with a bit of luck, hetget will be able to extract the
17:55:32 # data you are looking for.
17:55:32 #
17:55:32 # And finally the job gets an SL AWS tape available for
17:55:32 # input and/or output should you wish to construct a
17:55:32 # special tape. Tape must be called AWSTAP. User should
17:55:32 # back the tape up before submitting it, because it will
17:55:32 # be overwritten and anything could go wrong. AWS is
17:55:32 # expected to be exceptional use of this procedure anyway
17:55:32 #
17:55:32 # Only the NL tape needs an explicit mount. The SL tapes
17:55:32 # are premounted before IPL
17:55:32 hao tgt HASP250 MOUNT
17:55:32 HHCAO016I Target placed at index 0
17:55:32 hao cmd script conf/subjobs2.rc
17:55:32 HHCAO020I Command placed at index 0
17:55:32 /(001F) M 401,VOL=(NL,PCTOMF)
17:55:32 HHCPN013I EOF reached on SCRIPT file. Processing complete.
17:55:32 06.55.32 STC   16  $HASP100 MOUNT    ON STCINRDR
17:55:32 06.55.32 STC   16  $HASP373 MOUNT    STARTED
17:55:32 06.55.32 STC   16  IEF403I MOUNT - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   16 *IEF233A M 401,PCTOMF,,MOUNT,401
17:55:32 06.55.32 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
17:55:32 06.55.32 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
17:55:32 06.55.32 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
17:55:32 06.55.32 STC   15  IST025I  BLDL FAILED FOR IEDIAE   IN VTAMLIB
17:55:32 06.55.32 STC   15  IST025I  BLDL FAILED FOR IEDIAK   IN VTAMLIB
17:55:32 06.55.32 STC   15  IST025I  BLDL FAILED FOR IEDIAK   IN VTAMLIB
17:55:32 06.55.32 STC   10  DYNABLDL STARTED
17:55:32 06.55.32 STC   15  IST110I  NETWORK SOLICITOR STARTED
17:55:32 06.55.32 STC   15  IST093I  APPLJRP  ACTIVE
17:55:32 06.55.32 STC   15  IST093I  APPLPIES ACTIVE
17:55:32 06.55.32 STC   15  IST093I  APPLPIAD ACTIVE
17:55:32 06.55.32 STC   15  IST093I  APPLTSO  ACTIVE
17:55:32 06.55.32 STC   15  IST093I  APPLTEST ACTIVE
17:55:32 06.55.32 STC   10  IEF404I DYNABLDL - ENDED - TIME=06.55.32
17:55:32 06.55.32 STC   10  $HASP395 DYNABLDL ENDED
17:55:32 06.55.32 STC   10  $HASP150 DYNABLDL ON PRINTER2        21 LINES
17:55:32 06.55.32           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:32 06.55.32 STC   10  $HASP250 DYNABLDL IS PURGED
17:55:32 06.55.32 STC   15  IST093I  LCLMAJRP ACTIVE
17:55:32 06.55.32 STC   15  IST093I  LCLMAJ00 ACTIVE
17:55:32 06.55.32 STC   17  $HASP100 TSO      ON STCINRDR
17:55:32 06.55.32 STC   17  $HASP373 TSO      STARTED
17:55:32 06.55.32 STC   17  IEF403I TSO - STARTED - TIME=06.55.32
17:55:32 06.55.32 STC   18  $HASP100 JRP      ON STCINRDR
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32 STC   18  $HASP373 JRP      STARTED
17:55:32 06.55.32 STC   18  IEF403I JRP - STARTED - TIME=06.55.32
17:55:32 06.55.32           $HASP000 OK
17:55:32 06.55.32 STC   15  IST020I  VTAM INITIALIZATION COMPLETE
17:55:32 06.55.32 STC   15  IEA000I 0C0,IOE,05,0200,400000000001,,,NET     ,06.55.32
17:55:32 06.55.32 STC   15  IEA000I 0C1,IOE,05,0200,400000000001,,,NET     ,06.55.32
17:55:32 06.55.32 STC   15  IEA000I 0C2,IOE,05,0200,400000000001,,,NET     ,06.55.32
17:55:32 06.55.32 STC   11  DMSK00I DYNAMASK DONE ****
17:55:32 06.55.32 STC   11  DMSK06I  START
17:55:32 06.55.32 STC   11  IEF404I DYNAMASK - ENDED - TIME=06.55.32
17:55:32 06.55.32 STC   11  $HASP395 DYNAMASK ENDED
17:55:33 06.55.33 STC   11  $HASP150 DYNAMASK ON PRINTER2        30 LINES
17:55:33 06.55.33           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:33 06.55.33 STC   11  $HASP250 DYNAMASK IS PURGED
17:55:33 06.55.33 STC   13  BSPSP91I - Parms passed: NOREPLYU
17:55:33 06.55.33 STC   13  BSPSP93I - PFK definitions will be updated in memory
17:55:33 06.55.33 STC   13  BSPSP22I - Dataset processed: SYS1.PARMLIB
17:55:33 06.55.33 STC   13  BSPSP23I - on volume MVSRES
17:55:33 06.55.33 STC   13  BSPSP21I - Member being processed: SETPFK01
17:55:33 06.55.33 STC   13  +BSPSP98I - Member processed, LASTCC=0000
17:55:33 06.55.33 STC   13  +BSPSP21I - Member being processed: SETPFK02
17:55:33 06.55.33 STC   13  +BSPSP98I - Member processed, LASTCC=0000
17:55:33 06.55.33 STC   13  +BSPSP99I - End of processing, MAXRC=0000
17:55:33 06.55.33 STC   13  IEF404I BSPSETPF - ENDED - TIME=06.55.33
17:55:33 06.55.33 STC   13  $HASP395 BSPSETPF ENDED
17:55:33 06.55.33 STC   13  $HASP150 BSPSETPF ON PRINTER2        34 LINES
17:55:33 06.55.33           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:33 06.55.33 STC   13  $HASP250 BSPSETPF IS PURGED
17:55:33 06.55.33 STC   14  IFC001I  D=3350 N=0B F=01AB0000 L=01AC0005 S=01AB000002 DIP COMPLETE
17:55:33 06.55.33 STC   14  IEF404I LOGRECI - ENDED - TIME=06.55.33
17:55:33 06.55.33 STC   14  $HASP395 LOGRECI  ENDED
17:55:33 06.55.33 STC   14  $HASP150 LOGRECI  ON PRINTER2        20 LINES
17:55:33 06.55.33           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:33 06.55.33 STC   14  $HASP250 LOGRECI  IS PURGED
17:55:33 06.55.33 STC   16  IEF404I MOUNT - ENDED - TIME=06.55.33
17:55:33 06.55.33 STC   16  $HASP395 MOUNT    ENDED
17:55:33 06.55.33 STC   16  $HASP150 MOUNT    ON PRINTER2        18 LINES
17:55:33 06.55.33           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:33 06.55.33 STC   16  $HASP250 MOUNT    IS PURGED
17:55:33 HHCAO003I Firing command: 'script conf/subjobs2.rc'
17:55:33 script conf/subjobs2.rc
17:55:33 hao clear
17:55:33 HHCAO022I All automatic operation rules cleared
17:55:33 # If we get a prompt for a device, cancel it
17:55:33 hao tgt IEF238D
17:55:33 HHCAO016I Target placed at index 0
17:55:33 hao cmd script conf/cancel.rc
17:55:33 HHCAO020I Command placed at index 0
17:55:33 # If we get a prompt for a catalogue password, answer it
17:55:33 hao tgt IEC301A
17:55:33 HHCAO016I Target placed at index 1
17:55:33 hao cmd script conf/secret.rc
17:55:33 HHCAO020I Command placed at index 1
17:55:33 devinit 401 tapes/pctomf.tdf
17:55:33 HHCTA004I 0401: tapes/pctomf.tdf is a Optical Media Attachment (OMA) tape
17:55:33 HHCPN098I Device 0:0401 initialized
17:55:33 # When we see TERMHERC get purged, our job is done
17:55:33 hao tgt HASP373 TERMHERC
17:55:33 HHCAO016I Target placed at index 2
17:55:33 hao cmd script conf/termherc.rc
17:55:33 HHCAO020I Command placed at index 2
17:55:33 # Now submit the job
17:55:33 devinit 00c jcl/hercauto.jcl eof
17:55:33 HHCSD022I Socketdevice listener thread terminated
17:55:33 HHCSD007I Device 000C unbound from socket 127.0.0.1:3505
17:55:33 HHCPN098I Device 0:000C initialized
17:55:33 HHCPN013I EOF reached on SCRIPT file. Processing complete.
17:55:33 06.55.33 JOB    1  $HASP100 HERC01A  ON READER1
17:55:33 06.55.33 JOB    2  $HASP100 TERMHERC ON READER1
17:55:33 06.55.33 JOB    1  $HASP373 HERC01A  STARTED - INIT  3 - CLASS C - SYS BSP1
17:55:33 06.55.33 JOB    1  IEF403I HERC01A - STARTED - TIME=06.55.33
17:55:33 06.55.33 STC   17  IKT007I TCAS ACCEPTING LOGONS
17:55:33 06.55.33 STC   17  IKT005I TCAS IS INITIALIZED
17:55:33 06.55.33 STC   18  JRPI101 INITIALIZATION COMPLETE
17:55:33 06.55.33 STC   18 *01 JRP100I - ENTER ICLOSE TO SHUT DOWN
17:55:33 06.55.33 JOB    1  IEFACTRT - Stepname  Procstep  Program   Retcode
17:55:33 06.55.33 JOB    1  HERC01A    IEFBR14             IEFBR14   RC= 0000
17:55:33 06.55.33 JOB    1  IEF404I HERC01A - ENDED - TIME=06.55.33
17:55:33 06.55.33 JOB    1  $HASP395 HERC01A  ENDED
17:55:33 06.55.33 JOB    1  $HASP150 HERC01A  ON PRINTER1        21 LINES
17:55:33 06.55.33 JOB    1 *$HASP190 HERC01A  SETUP -- PRINTER1 -- F = 0001 -- C = 6    -- T = SN
17:55:33 06.55.33           $HASP000 OK
17:55:33 06.55.33 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1
17:55:33 HHCAO003I Firing command: 'script conf/termherc.rc'
17:55:33 script conf/termherc.rc
17:55:33 # We do an unnecessary 2-stage terminate, first triggering
17:55:33 # on the start message, then triggering on the purged
17:55:33 # message, to overcome an apparent bug in hercules which
17:55:33 # causes it to sometimes trigger on the wrong jobname.
17:55:33 hao clear
17:55:33 HHCAO022I All automatic operation rules cleared
17:55:33 hao tgt HASP250 TERMHERC
17:55:33 HHCAO016I Target placed at index 0
17:55:33 hao cmd script conf/termherc2.rc
17:55:33 HHCAO020I Command placed at index 0
17:55:33 HHCPN013I EOF reached on SCRIPT file. Processing complete.
17:55:33 06.55.33           $HASP160 PRINTER1 INACTIVE - CLASS=AP
17:55:33 06.55.33 JOB    1  $HASP250 HERC01A  IS PURGED
17:55:33 06.55.33          *IEE362A SMF ENTER DUMP FOR SYS1.MANX ON MVSRES
17:55:33 06.55.33           IEE361I SMF DATA LOST - SYS1.MANY NOT AVAILABLE TIME=06.55.33
17:55:33 06.55.33 STC   19  $HASP100 SMFDAILY ON STCINRDR
17:55:33 06.55.33 STC   19  $HASP373 SMFDAILY STARTED
17:55:33 06.55.33 STC   19  IEF403I SMFDAILY - STARTED - TIME=06.55.33
17:55:33 06.55.33 JOB    2  IEF403I TERMHERC - STARTED - TIME=06.55.33
17:55:33 06.55.33 STC   19  IEF453I SMFDAILY - JOB FAILED - JCL ERROR - TIME=06.55.33
17:55:33 06.55.33 STC   19  $HASP395 SMFDAILY ENDED
17:55:33 06.55.33 STC   19  $HASP150 SMFDAILY ON PRINTER2        25 LINES
17:55:33 06.55.33           IEE132I START COMMAND DEVICE ALLOCATION ERROR
17:55:33 06.55.33           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:33 06.55.33 STC   19  $HASP250 SMFDAILY IS PURGED
17:55:33 06.55.33 JOB    2  IEFACTRT - Stepname  Procstep  Program   Retcode
17:55:33 06.55.33 JOB    2  TERMHERC   S1                  IEBGENER  RC= 0000
17:55:33 06.55.33 JOB    2  IEF404I TERMHERC - ENDED - TIME=06.55.33
17:55:33 06.55.33 JOB    2  $HASP395 TERMHERC ENDED
17:55:33 06.55.33           $HASP309    INIT  3 INACTIVE ******** C=CBA
17:55:33 06.55.33 JOB    2  $HASP150 TERMHERC ON PRINTER1         1 LINE
17:55:33 06.55.33 JOB    2  $HASP150 TERMHERC ON PRINTER2        44 LINES
17:55:33 06.55.33           $HASP160 PRINTER1 INACTIVE - CLASS=AP
17:55:33 06.55.33           $HASP160 PRINTER2 INACTIVE - CLASS=Z
17:55:33 06.55.33 JOB    2  $HASP250 TERMHERC IS PURGED
17:55:33 HHCAO003I Firing command: 'script conf/termherc2.rc'
17:55:33 script conf/termherc2.rc
17:55:33 # we put in an unnecessary "stopall" to prevent Hercules
17:55:33 # (3.07 and 3.12 at least) from randomly hanging in the
17:55:33 # "quit" command in about 5% of runs.
17:55:33 # It is still unclear why Hercules is hanging
17:55:33 stopall
17:55:33 quit
17:55:33 HHCIN900I Begin Hercules shutdown
17:55:33 HHCIN901I Releasing configuration
17:55:33 HHCCP008I CPU0000 thread ended: tid=00001EEC, pid=19268
17:55:33 HHCCF047I Subchannel 0:0000 detached
17:55:33 HHCCF047I Subchannel 0:0001 detached
17:55:33 HHCTT003I Timer thread ended
17:55:33 HHCCF047I Subchannel 0:0002 detached
17:55:33 HHCCF047I Subchannel 0:0003 detached
17:55:33 HHCCF047I Subchannel 0:0004 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD211I                                                  readaheads   misses
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   18725015   1%  101       1121      24      35    1031     1997
17:55:33 HHCCD214I                                                         158       23
17:55:33 HHCCD215I dasd/mvsres.148
17:55:33 HHCCD216I [0]   15179178   0%    1 ro     943       0      17
17:55:33 HHCCD217I shadow/mvsres_*.148
17:55:33 HHCCD218I [1]    3545837   6%  100        178      24      18
17:55:33 HHCCF047I Subchannel 0:0005 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/sort01.131
17:55:33 HHCCD216I [0]      34336   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/sort01_*.131
17:55:33 HHCCD218I [1]       1088   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0006 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/sort02.132
17:55:33 HHCCD216I [0]      34336   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/sort02_*.132
17:55:33 HHCCD218I [1]       1088   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0007 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/sort03.133
17:55:33 HHCCD216I [0]      34336   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/sort03_*.133
17:55:33 HHCCD218I [1]       1088   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0008 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/sort04.134
17:55:33 HHCCD216I [0]      34336   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/sort04_*.134
17:55:33 HHCCD218I [1]       1088   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0009 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/sort05.135
17:55:33 HHCCD216I [0]      34336   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/sort05_*.135
17:55:33 HHCCD218I [1]       1088   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:000A detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      35424   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/sort06.136
17:55:33 HHCCD216I [0]      34336   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/sort06_*.136
17:55:33 HHCCD218I [1]       1088   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:000B detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   52422417   2%   77          1       0       2       0        1
17:55:33 HHCCD215I dasd/work00.140
17:55:33 HHCCD216I [0]     141963   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/work00_*.140
17:55:33 HHCCD218I [1]   52280454   2%   76          0       0       1
17:55:33 HHCCF047I Subchannel 0:000C detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    5023930   3%    5          1       0       1       0        1
17:55:33 HHCCD215I dasd/hasp00.152
17:55:33 HHCCD216I [0]    5023930   3%    5 rw       1       0       1
17:55:33 HHCCF047I Subchannel 0:000D detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD211I                                                  readaheads   misses
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   14386194  39%  500       1827    1368       8    1156     2356
17:55:33 HHCCD214I                                                         627       64
17:55:33 HHCCD215I dasd/page00.160
17:55:33 HHCCD216I [0]   14386194  39%  500 rw    1827    1368       8
17:55:33 HHCCF047I Subchannel 0:000E detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD211I                                                  readaheads   misses
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    3616366   8%   19         46     251      32      35       56
17:55:33 HHCCD214I                                                          25        2
17:55:33 HHCCD215I dasd/page01.161
17:55:33 HHCCD216I [0]    3616366   8%   19 rw      46     251      32
17:55:33 HHCCF047I Subchannel 0:000F detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD211I                                                  readaheads   misses
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    3280871   5%   32         42      35       1      29       53
17:55:33 HHCCD214I                                                          18        0
17:55:33 HHCCD215I dasd/page02.162
17:55:33 HHCCD216I [0]    3280871   5%   32 rw      42      35       1
17:55:33 HHCCF047I Subchannel 0:0010 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   57202932   1%  102          1       0       1       0        1
17:55:33 HHCCD215I dasd/work01.170
17:55:33 HHCCD216I [0]   57202932   1%  102 rw       1       0       1
17:55:33 HHCCF047I Subchannel 0:0011 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   66815692   2%  425          1       0       2       0        1
17:55:33 HHCCD215I dasd/work02.180
17:55:33 HHCCD216I [0]     113799   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/work02_*.180
17:55:33 HHCCD218I [1]   66701893   2%  424          0       0       1
17:55:33 HHCCF047I Subchannel 0:0012 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   56476534   2%  264          1       0       2       0        1
17:55:33 HHCCD215I dasd/work03.190
17:55:33 HHCCD216I [0]     142257   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/work03_*.190
17:55:33 HHCCD218I [1]   56334277   2%  263          0       0       1
17:55:33 HHCCF047I Subchannel 0:0013 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD211I                                                  readaheads   misses
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   17037777   9%   17         17       1       5      15       31
17:55:33 HHCCD214I                                                           2        0
17:55:33 HHCCD215I dasd/mvscat.191
17:55:33 HHCCD216I [0]    3658727   0%    1 ro       8       0       3
17:55:33 HHCCD217I shadow/mvscat_*.191
17:55:33 HHCCD218I [1]   13379050  11%   16          9       1       2
17:55:33 HHCCF047I Subchannel 0:0014 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]  103500159  17% 1297          1       0       2       0        1
17:55:33 HHCCD215I dasd/seasik.192
17:55:33 HHCCD216I [0]   16164960   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/seasik_*.192
17:55:33 HHCCD218I [1]   87335199  20% 1297          0       0       1
17:55:33 HHCCF047I Subchannel 0:0015 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]  168333900   4% 5454          1       0       1       0        1
17:55:33 HHCCD215I dasd/mvssrc.193
17:55:33 HHCCD216I [0]  168333900   4% 5454 rw       1       0       1
17:55:33 HHCCF047I Subchannel 0:0016 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD211I                                                  readaheads   misses
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   44516465   2%   22         33       0       8      36       63
17:55:33 HHCCD214I                                                           6        5
17:55:33 HHCCD215I dasd/pub000.240
17:55:33 HHCCD216I [0]    7591138   3%    1 ro      13       0       4
17:55:33 HHCCD217I shadow/pub000_*.240
17:55:33 HHCCD218I [1]   36925327   2%   21         20       0       4
17:55:33 HHCCF047I Subchannel 0:0017 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   25623324   0%    1          5       2       5       1        6
17:55:33 HHCCD215I dasd/mvsdlb.248
17:55:33 HHCCD216I [0]   25471539   0%    1 ro       3       0       3
17:55:33 HHCCD217I shadow/mvsdlb_*.248
17:55:33 HHCCD218I [1]     151785   0%    0          2       2       2
17:55:33 HHCCF047I Subchannel 0:0018 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]  100064666   8%  539          1       0       2       0        1
17:55:33 HHCCD215I dasd/pub002.280
17:55:33 HHCCD216I [0]    2171954  29%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/pub002_*.280
17:55:33 HHCCD218I [1]   97892712   8%  538          0       0       1
17:55:33 HHCCF047I Subchannel 0:0019 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]     143545   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/tmptmp.2b1
17:55:33 HHCCD216I [0]     142257   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/tmptmp_*.2b1
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:001A detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]     143545   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/xmit90.2b2
17:55:33 HHCCD216I [0]     142257   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/xmit90_*.2b2
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:001B detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    6099280   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/start1.150
17:55:33 HHCCD216I [0]    6098016   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/start1_*.150
17:55:33 HHCCD218I [1]       1264   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:001C detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    4595678   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/spool0.151
17:55:33 HHCCD216I [0]    4594414   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/spool0_*.151
17:55:33 HHCCD218I [1]       1264   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:001D detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   50622559   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/cbt000.340
17:55:33 HHCCD216I [0]   50621271   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/cbt000_*.340
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:001E detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   53836805   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/cbt001.341
17:55:33 HHCCD216I [0]   53835517   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/cbt001_*.341
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:001F detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   46082980   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/cbt002.342
17:55:33 HHCCD216I [0]   46081692   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/cbt002_*.342
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0020 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   27241782   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/cbtcat.343
17:55:33 HHCCD216I [0]   27240494   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/cbtcat_*.343
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0021 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   46003602   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/src000.348
17:55:33 HHCCD216I [0]   46002314   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/src000_*.348
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0022 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   45707725   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/src001.349
17:55:33 HHCCD216I [0]   45706437   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/src001_*.349
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0023 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]   44403653   0%    0          1       0       1       0        1
17:55:33 HHCCD215I dasd/src002.34a
17:55:33 HHCCD216I [0]   44402365   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/src002_*.34a
17:55:33 HHCCD218I [1]       1288   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:0024 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    6321674   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/srccat.34b
17:55:33 HHCCD216I [0]    6310767   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/srccat_*.34b
17:55:33 HHCCD218I [1]      10907   7%    1          0       0       0
17:55:33 HHCCF047I Subchannel 0:0025 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    1118801  11%    2          1       0       2       0        1
17:55:33 HHCCD215I dasd/smp001.149
17:55:33 HHCCD216I [0]     774654   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/smp001_*.149
17:55:33 HHCCD218I [1]     344147  38%    2          0       0       1
17:55:33 HHCCF047I Subchannel 0:0026 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    1621663  24%   12          1       0       2       0        1
17:55:33 HHCCD215I dasd/smp002.14a
17:55:33 HHCCD216I [0]     856740   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/smp002_*.14a
17:55:33 HHCCD218I [1]     764923  51%   12          0       0       1
17:55:33 HHCCF047I Subchannel 0:0027 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    1077383  19%    3          1       0       2       0        1
17:55:33 HHCCD215I dasd/smp003.14b
17:55:33 HHCCD216I [0]     592555   0%    0 ro       1       0       1
17:55:33 HHCCD217I shadow/smp003_*.14b
17:55:33 HHCCD218I [1]     484828  42%    3          0       0       1
17:55:33 HHCCF047I Subchannel 0:0028 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    3437923  36%    4          1       0       2       0        1
17:55:33 HHCCD215I dasd/smp004.14c
17:55:33 HHCCD216I [0]    2916431  35%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/smp004_*.14c
17:55:33 HHCCD218I [1]     521492  41%    3          0       0       1
17:55:33 HHCCF047I Subchannel 0:0029 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD211I                                                  readaheads   misses
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    9892282   2%  124        117     111       6     787      874
17:55:33 HHCCD214I                                                          32       10
17:55:33 HHCCD215I dasd/js2sp0.700
17:55:33 HHCCD216I [0]     142291   0%    1 ro       0       0       1
17:55:33 HHCCD217I shadow/js2sp0_*.700
17:55:33 HHCCD218I [1]    9749991   2%  123        117     111       5
17:55:33 HHCCF047I Subchannel 0:002A detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]     715081   0%    1          1       0       2       0        1
17:55:33 HHCCD215I dasd/dlicat.138
17:55:33 HHCCD216I [0]      36630   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/dlicat_*.138
17:55:33 HHCCD218I [1]     678451   0%    0          0       0       1
17:55:33 HHCCF047I Subchannel 0:002B detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]     880289   0%    1          1       0       2       0        1
17:55:33 HHCCD215I dasd/dlisys.139
17:55:33 HHCCD216I [0]      36630   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/dlisys_*.139
17:55:33 HHCCD218I [1]     843659   0%    0          0       0       1
17:55:33 HHCCF047I Subchannel 0:002C detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      43495   0%    1          1       0       2       0        1
17:55:33 HHCCD215I dasd/dli000.13a
17:55:33 HHCCD216I [0]      36630   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/dli000_*.13a
17:55:33 HHCCD218I [1]       6865   0%    0          0       0       1
17:55:33 HHCCF047I Subchannel 0:002D detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      46911   0%    1          1       0       2       0        1
17:55:33 HHCCD215I dasd/dli001.13b
17:55:33 HHCCD216I [0]      36630   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/dli001_*.13b
17:55:33 HHCCD218I [1]      10281   0%    0          0       0       1
17:55:33 HHCCF047I Subchannel 0:002E detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]      37718   0%    1          1       0       1       0        1
17:55:33 HHCCD215I dasd/dli002.13c
17:55:33 HHCCD216I [0]      36630   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/dli002_*.13c
17:55:33 HHCCD218I [1]       1088   0%    0          0       0       0
17:55:33 HHCCF047I Subchannel 0:002F detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]    1233964   0%    1          1       0       2       0        1
17:55:33 HHCCD215I dasd/js3sp0.710
17:55:33 HHCCD216I [0]     141965   0%    1 ro       1       0       1
17:55:33 HHCCD217I shadow/js3sp0_*.710
17:55:33 HHCCD218I [1]    1091999   0%    0          0       0       1
17:55:33 HHCCF047I Subchannel 0:0030 detached
17:55:33 HHCCD210I           size free  nbr st   reads  writes l2reads    hits switches
17:55:33 HHCCD212I --------------------------------------------------------------------
17:55:33 HHCCD213I [*]     951745   0%    2          1       0       2       0        1
17:55:33 HHCCD215I dasd/js3res.711
17:55:33 HHCCD216I [0]     142093   0%    2 ro       1       0       1
17:55:33 HHCCD217I shadow/js3res_*.711
17:55:33 HHCCD218I [1]     809652   0%    0          0       0       1
17:55:33 HHCCD011I Readahead thread 1 stopping: tid=000015AC, pid=19268
17:55:33 HHCCD011I Readahead thread 2 stopping: tid=00001A28, pid=19268
17:55:33 HHCCD013I Garbage collector thread stopping: tid=00001F18, pid=19268
17:55:33 HHCCD012I Writer thread 2 stopping: tid=00003CA4, pid=19268
17:55:33 HHCCD012I Writer thread 1 stopping: tid=00001B98, pid=19268
17:55:33 HHCCF047I Subchannel 0:0031 detached
17:55:33 HHCCF047I Subchannel 0:0032 detached
17:55:33 HHCCF047I Subchannel 0:0033 detached
17:55:33 HHCCF047I Subchannel 0:0034 detached
17:55:33 HHCCF047I Subchannel 0:0035 detached
17:55:33 HHCCF047I Subchannel 0:0036 detached
17:55:33 HHCTE004I Console connection thread terminated
17:55:33 HHCCF047I Subchannel 0:0037 detached
17:55:33 HHCCF047I Subchannel 0:0038 detached
17:55:33 HHCCF047I Subchannel 0:0039 detached
17:55:33 HHCCF047I Subchannel 0:003A detached
17:55:33 HHCCF047I Subchannel 0:003B detached
17:55:33 HHCCF047I Subchannel 0:003C detached
17:55:33 HHCIN902I Configuration release complete
17:55:33 HHCIN903I Calling termination routines
17:55:33 HHCHD900I Begin shutdown sequence
17:55:33 HHCHD901I Calling panel_cleanup
17:55:33 HHCHD902I panel_cleanup complete
17:55:33 HHCHD901I Calling console_shutdown
17:55:33 HHCHD902I console_shutdown complete
17:55:33 HHCHD901I Calling term_sockdev
17:55:33 HHCHD902I term_sockdev complete
17:55:33 HHCHD901I Calling hdl_term
17:55:33 HHCHD950I Begin HDL termination sequence
17:55:33 HHCHD951I Calling module *Hercules cleanup routine
17:55:33 HHCHD952I Module *Hercules cleanup complete
17:55:33 HHCHD959I HDL Termination sequence complete
17:55:33 HHCHD902I hdl_term complete
17:55:33 HHCHD901I Calling logger_term
17:55:33 HHCLG014I logger thread terminating
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
On 3/11/2017 9:59 AM, [hidden email] [H390-MVS] wrote:

> And another anomaly of SMFDAILY
> ending with a JCL error from an
> older run (which I no longer have
> corresponding printer output for):
>
> 17:55:33 06.55.33 STC   19  $HASP100 SMFDAILY ON STCINRDR
> 17:55:33 06.55.33 STC   19  $HASP373 SMFDAILY STARTED
> 17:55:33 06.55.33 STC   19  IEF403I SMFDAILY - STARTED - TIME=06.55.33
> 17:55:33 06.55.33 JOB    2  IEF403I TERMHERC - STARTED - TIME=06.55.33
> 17:55:33 06.55.33 STC   19  IEF453I SMFDAILY - JOB FAILED - JCL ERROR - TIME=06.55.33
> 17:55:33 06.55.33 STC   19  $HASP395 SMFDAILY ENDED
> 17:55:33 06.55.33 STC   19  $HASP150 SMFDAILY ON PRINTER2        25 LINES

SMFDAILY attempts to allocate a new GDG member to move the SMF data
into. Depending on when your system crashes, this could allocate, but
not catalog the GDS, causing the next run to fail on a duplicate data
set name. Either delete the errant copy yourself, or change the SMFDAILY
JCL to use a better alternative (e.g., allocate an entire volume, and
use DISP=MOD).

Gerhard Postpischil
Bradford, VT

---
This email has been checked for viruses by AVG.
http://www.avg.com

Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
 - - - In [hidden email], <kerravon86@...> wrote:
> And another anomaly of SMFDAILY
>ending with a JCL error from an
>older run (which I no longer have
>corresponding printer output for):
- - - remainder snipped - - -

What was the JCL error?

Suggest that you do a PDS VERIFY : all corrupt PDSes.
Possible SYS1.PROCLIB, SYS1.PARMLIB, SYS2.PROCLIB,
SYS2,LINKLIB, etc.

Do not do a stopall or quit while a disk VTOC is being updated.
Do not do a stopall or quit while a PDS is adding a new extent.
Consider a normal non-Paul shut down.

Be glad that the DIRF bit is catching some of the errors.
If VTOC updates are done out-of-order, it can result in grief.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
On 3/11/2017 7:20 AM, [hidden email] [H390-MVS] wrote:
>   - - - In [hidden email], <gerhardp@...> wrote:
> - - - beginning snipped - - -
>> DUMPFULL was missing in the original tk3 also. Basically it should be a
>> three-step IEBGENER to copy a null data set to the three SYS1.DUMP0n files.
>
> No it shouldn't.

Paul uses Hercules/MVS as a convenience, without ever keeping the system
up, and caring even less for reading dumps.

In my case I run it manually. Usually after processing one dump. I've
found that many dumps are duplicates of the problem with the first dump.


> The SVC X'12' error and VTOC showing an incomplete DASDM
> update could also be from physical disk errors but I doubt it.
I'm running the latest available Hercules 3.07, and run automatically
scheduled PDS compresses, and every so often one of these gets an I/O
error - when the PDS is examined, it's correct.

Gerhard Postpischil
Bradford, VT

---
This email has been checked for viruses by AVG.
http://www.avg.com

Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
---In [hidden email], <kerravon86@...> wrote :

> 04:52:55 17.52.55 STC 12 IEC909I 212-03,BSPPILOT,BSPPILOT,SYSDCB
> 04:52:55 17.52.55 STC 12 IEF450I BSPPILOT BSPPILOT - ABEND S212 U0000 - TIME=17.52.55

Ok, I logged on to TSO and checked
the format of how BSPPILOT is
started in JES2PARM, which is this:

S BSPPILOT,PARM=NOWTO

For good measure I did a couple of
pds verify's, output below.

I then ran BSPPILOT again, and it
did not report an error:

C:\mvs380\log>grep BSPPILOT hercules.log
04:52:54 17.52.54 STC   12  $HASP100 BSPPILOT ON STCINRDR
04:52:54 17.52.54 STC   12  $HASP373 BSPPILOT STARTED
04:52:54 17.52.54 STC   12  IEF403I BSPPILOT - STARTED - TIME=17.52.54
04:52:55 17.52.55 STC   12  IEC909I 212-03,BSPPILOT,BSPPILOT,SYSDCB
04:52:55 17.52.55 STC   12  IEF450I BSPPILOT BSPPILOT - ABEND S212 U0000 - TIME=17.52.55
04:52:55 17.52.55 STC   12  IEF404I BSPPILOT - ENDED - TIME=17.52.55
04:52:55 17.52.55 STC   12  $HASP395 BSPPILOT ENDED
04:52:55 17.52.55 STC   12  $HASP150 BSPPILOT ON PRINTER2        16 LINES
04:52:55 17.52.55 STC   12  $HASP250 BSPPILOT IS PURGED
17:15:30 06.15.30 STC   20  $HASP100 BSPPILOT ON STCINRDR
17:15:30 06.15.30 STC   20  $HASP373 BSPPILOT STARTED
17:15:30 06.15.30 STC   20  IEF403I BSPPILOT - STARTED - TIME=06.15.30

C:\mvs380\log>


So, the S212 abend appears to be random.

I will continue my experiments.

BFN. Paul.




pds 'sys1.proclib'
 PDS -- VERSION 8.5.25

 DISP UNIT OPT RECFM LRECL BLKSIZE   ALLOCTRK FREETRK SECONDARY FREEDIR
 SHR  3350 C   FB       80   19040   1X   180     167     1 CYL      65

 ENTER OPTION -- DSN=SYS1.PROCLIB,VOL=SER=MVSRES  MEM=
verify :

 END OF DATA SET

     1,343 LOGICAL RECORDS WERE INPUT
        70 PHYSICAL BLOCKS WERE INPUT
    13,120 CHARACTERS IN THE LARGEST PHYSICAL BLOCK
     1,535 CHARACTERS PER AVERAGE PHYSICAL BLOCK
         3 TRACKS COULD BE REGAINED BY COMPRESSING THIS DATA SET
        70 MEMBERS WERE CHECKED


 70 MEMBERS COUNTED; CUMULATIVE SIZE IS 1,343 RECORDS

pds 'sys1.parmlib'
 PDS -- VERSION 8.5.25

 DISP UNIT OPT RECFM LRECL BLKSIZE   ALLOCTRK FREETRK SECONDARY FREEDIR
 SHR  3350 C   F        80      80   1X   180     142     0 CYL      33

 ENTER OPTION -- DSN=SYS1.PARMLIB,VOL=SER=MVSRES  MEM=
verify :

 END OF DATA SET

     2,032 LOGICAL RECORDS WERE INPUT
     2,032 PHYSICAL BLOCKS WERE INPUT
        80 CHARACTERS IN THE LARGEST PHYSICAL BLOCK
        80 CHARACTERS PER AVERAGE PHYSICAL BLOCK
         8 TRACKS COULD BE REGAINED BY COMPRESSING THIS DATA SET
        67 MEMBERS WERE CHECKED


 67 MEMBERS COUNTED; CUMULATIVE SIZE IS 2,032 RECORDS

Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
Next anomaly.

I did a startmvs for a change, so I
didn't quit so fast, so that any
hidden long-running task had a
chance to terminate before I
pulled the electricity plug.

I was hoping the strange JRP
abends that were appended to
prt00f.txt, even though JRP
had stopped abending, would
go away. They did go away,
but a new problem became
visible.

I went back to my automated
runmvs, and prt00f.txt is still
screwy, but in a different way.

As you can see from here:

C:\mvs380\prt>grep HASP373 prt00f.txt
08.09.31 STC    9  $HASP373 SVC120I  STARTED
08.09.31 STC   10  $HASP373 DYNABLDL STARTED
08.09.31 STC   11  $HASP373 DYNAMASK STARTED
08.09.31 STC   13  $HASP373 BSPSETPF STARTED
08.09.31 STC   14  $HASP373 LOGRECI  STARTED
08.09.31 STC   16  $HASP373 MOUNT    STARTED
08.09.32 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1
08.05.25 STC   12  $HASP373 BSPPILOT STARTED
08.05.25 STC   15  $HASP373 NET      STARTED
08.05.26 STC   18  $HASP373 JRP      STARTED
08.07.52 STC   28  $HASP373 SVC120I  STARTED
08.07.52 STC   29  $HASP373 DYNABLDL STARTED
08.07.52 STC   30  $HASP373 DYNAMASK STARTED
08.07.52 STC   32  $HASP373 BSPSETPF STARTED
08.07.52 STC   33  $HASP373 LOGRECI  STARTED


I am getting double the output. E.g. you
can see that SVC120I shows two starts.
Not only that, but the second start has
a timestamp that is *before* the first.

I can't think of anything in computer
science that puts an older date later
than a newer date.

Note that this was the result of a second
automated runmvs, allowing the first one
to clean up anything strange.

As you can see from the log, SVC120I
etc are only started once in the run:

C:\mvs380\log>grep HASP373 hercules.log
19:09:28 hao tgt HASP373 SVC120I
19:09:31 08.09.31 STC    2  $HASP373 INIT     STARTED
19:09:31 08.09.31 STC    3  $HASP373 INIT     STARTED
19:09:31 08.09.31 STC    4  $HASP373 INIT     STARTED
19:09:31 08.09.31 STC    5  $HASP373 INIT     STARTED
19:09:31 08.09.31 STC    6  $HASP373 INIT     STARTED
19:09:31 08.09.31 STC    7  $HASP373 INIT     STARTED
19:09:31 08.09.31 STC    8  $HASP373 INIT     STARTED
19:09:31 08.09.31 STC    9  $HASP373 SVC120I  STARTED
19:09:31 08.09.31 STC   10  $HASP373 DYNABLDL STARTED
19:09:31 08.09.31 STC   11  $HASP373 DYNAMASK STARTED
19:09:31 08.09.31 STC   12  $HASP373 BSPPILOT STARTED
19:09:31 08.09.31 STC   13  $HASP373 BSPSETPF STARTED
19:09:31 08.09.31 STC   14  $HASP373 LOGRECI  STARTED
19:09:31 08.09.31 STC   15  $HASP373 NET      STARTED
19:09:31 08.09.31 STC   16  $HASP373 MOUNT    STARTED
19:09:31 08.09.31 STC   17  $HASP373 TSO      STARTED
19:09:31 08.09.31 STC   18  $HASP373 JRP      STARTED
19:09:32 hao tgt HASP373 TERMHERC
19:09:32 08.09.32 JOB    1  $HASP373 HERC01A  STARTED - INIT  3 - CLASS C - SYS BSP1
19:09:32 08.09.32 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1
19:09:32 08.09.32 STC   19  $HASP373 SMFDAILY STARTED

C:\mvs380\log>


My printer definitions do look a bit strange:

# Use this for Unix
#
#000E 1403 prt/prt00e.txt
#000F 1403 prt/prt00f.txt
#
# Use this for Windows
#
# The CRLF is for proper Windows line termination
# The NOCLEAR causes append instead of overwriting
#
#000E 1403 prt/prt00e-$(TStamp).txt crlf noclear
000E 1403 prt/prt00e.txt           crlf noclear
#000F 1403 prt/prt00f-$(TStamp).txt crlf noclear
000F 1403 prt/prt00f.txt           crlf noclear


ie that "noclear" looks a bit odd.

In runmvs, I have this:

del prt\prt00e.txt

but there is no explicit delete for prt00f.txt


I've got a theory. Perhaps what
is happening is that in an older
run I had more data, pushing
SVC120I etc further down in the
file. And open for append is not
working, it is instead writing from
the beginning (overwriting the
old data at the top), and when it has
finished, the crap after that is left
intact instead of being deleted.

I think this is the expected behavior
if a file is opened with "r+" instead
of "a".

I have looked at the Hercules code
and it seems that if "noclear" is
specified, then "notrunc" is set, and
this code:

(printer.c)
/*-------------------------------------------------------------------*/
/* Subroutine to open the printer file or pipe                       */
/*-------------------------------------------------------------------*/
static int
open_printer (DEVBLK *dev)
{
pid_t           pid;                    /* Child process identifier  */
char            pathname[MAX_PATH];     /* file path in host format  */
int             open_flags;             /* File open flags           */
#if !defined( _MSVC_ )
int             pipefd[2];              /* Pipe descriptors          */
int             rc;                     /* Return code               */
#endif

    /* Regular open if 1st char of filename is not vertical bar */
    if (!dev->ispiped)
    {
        int fd;

        /* Socket printer? */
        if (dev->bs)
            return (dev->fd < 0 ? -1 : 0);

        /* Normal printer */
        hostpath(pathname, dev->filename, sizeof(pathname));
        open_flags = O_BINARY | O_WRONLY | O_CREAT /* | O_SYNC */;
        if (dev->notrunc != 1)
        {
            open_flags |= O_TRUNC;
        }
        fd = open (pathname, open_flags,
                    S_IRUSR | S_IWUSR | S_IRGRP);


is doing an open() instead of fopen()
so who knows what that does.

I assume this is some sort of
underlying Windows or Hercules
bug, but I can bypass it by just
deleting prt00f.txt in runmvs.bat
the same as I do with prt00e.txt.

BFN. Paul.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
---In [hidden email], <kerravon86@...> wrote :

> I am getting double the output. E.g. you
> can see that SVC120I shows two starts.

Here is some more data:

C:\mvs380\prt>grep HASP373 prt00f-2017-03-12_19074957.txt
08.05.26 STC   19  $HASP373 SMFDAILY STARTED
08.05.26 STC   17  $HASP373 TSO      STARTED
08.05.25 STC   12  $HASP373 BSPPILOT STARTED
08.05.25 STC   15  $HASP373 NET      STARTED
08.05.26 STC   18  $HASP373 JRP      STARTED
08.07.52 STC   28  $HASP373 SVC120I  STARTED
08.07.52 STC   29  $HASP373 DYNABLDL STARTED
08.07.52 STC   30  $HASP373 DYNAMASK STARTED
08.07.52 STC   32  $HASP373 BSPSETPF STARTED
08.07.52 STC   33  $HASP373 LOGRECI  STARTED

C:\mvs380\prt>grep HASP373 prt00f-2017-03-12_19090581.txt
08.09.08 STC    9  $HASP373 SVC120I  STARTED
08.09.09 STC   10  $HASP373 DYNABLDL STARTED
08.09.09 STC   11  $HASP373 DYNAMASK STARTED
08.09.09 STC   13  $HASP373 BSPSETPF STARTED
08.09.09 STC   14  $HASP373 LOGRECI  STARTED
08.09.09 STC   16  $HASP373 MOUNT    STARTED
08.09.09 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1
08.05.25 STC   12  $HASP373 BSPPILOT STARTED
08.05.25 STC   15  $HASP373 NET      STARTED
08.05.26 STC   18  $HASP373 JRP      STARTED
08.07.52 STC   28  $HASP373 SVC120I  STARTED
08.07.52 STC   29  $HASP373 DYNABLDL STARTED
08.07.52 STC   30  $HASP373 DYNAMASK STARTED
08.07.52 STC   32  $HASP373 BSPSETPF STARTED
08.07.52 STC   33  $HASP373 LOGRECI  STARTED

C:\mvs380\prt>grep HASP373 prt00f-2017-03-12_19092838.txt
08.09.31 STC    9  $HASP373 SVC120I  STARTED
08.09.31 STC   10  $HASP373 DYNABLDL STARTED
08.09.31 STC   11  $HASP373 DYNAMASK STARTED
08.09.31 STC   13  $HASP373 BSPSETPF STARTED
08.09.31 STC   14  $HASP373 LOGRECI  STARTED
08.09.31 STC   16  $HASP373 MOUNT    STARTED
08.09.32 JOB    2  $HASP373 TERMHERC STARTED - INIT  3 - CLASS C - SYS BSP1
08.05.25 STC   12  $HASP373 BSPPILOT STARTED
08.05.25 STC   15  $HASP373 NET      STARTED
08.05.26 STC   18  $HASP373 JRP      STARTED
08.07.52 STC   28  $HASP373 SVC120I  STARTED
08.07.52 STC   29  $HASP373 DYNABLDL STARTED
08.07.52 STC   30  $HASP373 DYNAMASK STARTED
08.07.52 STC   32  $HASP373 BSPSETPF STARTED
08.07.52 STC   33  $HASP373 LOGRECI  STARTED

C:\mvs380\prt>


so you can see how SMFDAILY in the
first file has managed to make the file
bigger than normal.

and startmvs.bat has this:

if EXIST log\hercules.log erase log\hercules.log
if EXIST prt\prt00e.txt   erase prt\prt00e.txt
if EXIST prt\prt00f.txt   erase prt\prt00f.txt

which explains how that managed
to reset things.

BFN. Paul.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
On 12/03/2017 08:28, [hidden email] [H390-MVS] wrote:

<SNIP>

>
> pds 'sys1.proclib'
> PDS -- VERSION 8.5.25
>
> DISP UNIT OPT RECFM LRECL BLKSIZE ALLOCTRK FREETRK SECONDARY FREEDIR
> SHR 3350 C FB 80 19040 1X 180 167 1 CYL 65
>
> ENTER OPTION -- DSN=SYS1.PROCLIB,VOL=SER=MVSRES MEM=
> verify :
>
> END OF DATA SET
>
> 1,343 LOGICAL RECORDS WERE INPUT
> 70 PHYSICAL BLOCKS WERE INPUT
> 13,120 CHARACTERS IN THE LARGEST PHYSICAL BLOCK
> 1,535 CHARACTERS PER AVERAGE PHYSICAL BLOCK
> 3 TRACKS COULD BE REGAINED BY COMPRESSING THIS DATA SET
> 70 MEMBERS WERE CHECKED
>
> 70 MEMBERS COUNTED; CUMULATIVE SIZE IS 1,343 RECORDS
>
Hi Paul - this was new to me so I thought to try it and got, on
SYS1.PROCLIB, this

  ** VERIFY   GTF-ORIG  X'C7E3C660D6D9C9C7'   NON-STANDARD MEMBER NAME

  ** VERIFY   TP-TRACE  X'E3D760E3D9C1C3C5'   NON-STANDARD MEMBER NAME

Presumably the dash in the name? Does it matter?

Many thanks
Bill
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
On 12/03/17 08:36, [hidden email] [H390-MVS] wrote:

>
>
> Next anomaly.
>
> I did a startmvs for a change, so I
> didn't quit so fast, so that any
> hidden long-running task had a
> chance to terminate before I
> pulled the electricity plug.
>
> I was hoping the strange JRP
> abends that were appended to
> prt00f.txt, even though JRP
> had stopped abending, would
> go away. They did go away,
> but a new problem became
> visible.
>
> I went back to my automated
> runmvs, and prt00f.txt is still
> screwy, but in a different way.
>
> As you can see from here:
>
> C:\mvs380\prt>grep HASP373 prt00f.txt
> 08.09.31 STC 9 $HASP373 SVC120I STARTED
> 08.09.31 STC 10 $HASP373 DYNABLDL STARTED
> 08.09.31 STC 11 $HASP373 DYNAMASK STARTED
> 08.09.31 STC 13 $HASP373 BSPSETPF STARTED
> 08.09.31 STC 14 $HASP373 LOGRECI STARTED
> 08.09.31 STC 16 $HASP373 MOUNT STARTED
> 08.09.32 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
> 08.05.25 STC 12 $HASP373 BSPPILOT STARTED
> 08.05.25 STC 15 $HASP373 NET STARTED
> 08.05.26 STC 18 $HASP373 JRP STARTED
> 08.07.52 STC 28 $HASP373 SVC120I STARTED
> 08.07.52 STC 29 $HASP373 DYNABLDL STARTED
> 08.07.52 STC 30 $HASP373 DYNAMASK STARTED
> 08.07.52 STC 32 $HASP373 BSPSETPF STARTED
> 08.07.52 STC 33 $HASP373 LOGRECI STARTED
>
> I am getting double the output. E.g. you
> can see that SVC120I shows two starts.
> Not only that, but the second start has
> a timestamp that is *before* the first.
>
> I can't think of anything in computer
> science that puts an older date later
> than a newer date.

You're not trying very hard then. JES2 schedules it's output by priority not
by date.

> Note that this was the result of a second
> automated runmvs, allowing the first one
> to clean up anything strange.
>
> As you can see from the log, SVC120I
> etc are only started once in the run:
>
> C:\mvs380\log>grep HASP373 hercules.log
> 19:09:28 hao tgt HASP373 SVC120I
> 19:09:31 08.09.31 STC 2 $HASP373 INIT STARTED
> 19:09:31 08.09.31 STC 3 $HASP373 INIT STARTED
> 19:09:31 08.09.31 STC 4 $HASP373 INIT STARTED
> 19:09:31 08.09.31 STC 5 $HASP373 INIT STARTED
> 19:09:31 08.09.31 STC 6 $HASP373 INIT STARTED
> 19:09:31 08.09.31 STC 7 $HASP373 INIT STARTED
> 19:09:31 08.09.31 STC 8 $HASP373 INIT STARTED
> 19:09:31 08.09.31 STC 9 $HASP373 SVC120I STARTED
> 19:09:31 08.09.31 STC 10 $HASP373 DYNABLDL STARTED
> 19:09:31 08.09.31 STC 11 $HASP373 DYNAMASK STARTED
> 19:09:31 08.09.31 STC 12 $HASP373 BSPPILOT STARTED
> 19:09:31 08.09.31 STC 13 $HASP373 BSPSETPF STARTED
> 19:09:31 08.09.31 STC 14 $HASP373 LOGRECI STARTED
> 19:09:31 08.09.31 STC 15 $HASP373 NET STARTED
> 19:09:31 08.09.31 STC 16 $HASP373 MOUNT STARTED
> 19:09:31 08.09.31 STC 17 $HASP373 TSO STARTED
> 19:09:31 08.09.31 STC 18 $HASP373 JRP STARTED
> 19:09:32 hao tgt HASP373 TERMHERC
> 19:09:32 08.09.32 JOB 1 $HASP373 HERC01A STARTED - INIT 3 - CLASS C - SYS BSP1
> 19:09:32 08.09.32 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
> 19:09:32 08.09.32 STC 19 $HASP373 SMFDAILY STARTED

But you're comparing apples with kangaroos again. The contents of the log
data you have printed are for one IPL of MVS. The jobs that are printed are
jobs that exist on the spool when JES2 is scheduling it's output.

The two different methods you use to automate MVS are leaving the JES2
queues in differing states.

> C:\mvs380\log>
>
> My printer definitions do look a bit strange:
>
> # Use this for Unix
> #
> #000E 1403 prt/prt00e.txt
> #000F 1403 prt/prt00f.txt
> #
> # Use this for Windows
> #
> # The CRLF is for proper Windows line termination
> # The NOCLEAR causes append instead of overwriting
> #
> #000E 1403 prt/prt00e-$(TStamp).txt crlf noclear
> 000E 1403 prt/prt00e.txt crlf noclear
> #000F 1403 prt/prt00f-$(TStamp).txt crlf noclear
> 000F 1403 prt/prt00f.txt crlf noclear
>
> ie that "noclear" looks a bit odd.
>
> In runmvs, I have this:
>
> del prt\prt00e.txt
>
> but there is no explicit delete for prt00f.txt
>
> I've got a theory. Perhaps what
> is happening is that in an older
> run I had more data, pushing
> SVC120I etc further down in the
> file. And open for append is not
> working, it is instead writing from
> the beginning (overwriting the
> old data at the top), and when it has
> finished, the crap after that is left
> intact instead of being deleted.
>
> I think this is the expected behavior
> if a file is opened with "r+" instead
> of "a".
>
> I have looked at the Hercules code
> and it seems that if "noclear" is
> specified, then "notrunc" is set, and
> this code:
>
> (printer.c)
> /*----------------------------------------------------------*/
> /* Subroutine to open the printer file or pipe */
> /*----------------------------------------------------------*/
> static int
> open_printer (DEVBLK *dev)
> {
> pid_t pid; /* Child process identifier */
> char pathname[MAX_PATH]; /* file path in host format */
> int open_flags; /* File open flags */
> #if !defined( _MSVC_ )
> int pipefd[2]; /* Pipe descriptors */
> int rc; /* Return code */
> #endif
>
> /* Regular open if 1st char of filename is not vertical bar */
> if (!dev->ispiped)
> {
> int fd;
>
> /* Socket printer? */
> if (dev->bs)
> return (dev->fd < 0 ? -1 : 0);
>
> /* Normal printer */
> hostpath(pathname, dev->filename, sizeof(pathname));
> open_flags = O_BINARY | O_WRONLY | O_CREAT /* | O_SYNC */;
> if (dev->notrunc != 1)
> {
> open_flags |= O_TRUNC;
> }
> fd = open (pathname, open_flags,
> S_IRUSR | S_IWUSR | S_IRGRP);
>
> is doing an open() instead of fopen()
> so who knows what that does.
>
> I assume this is some sort of
> underlying Windows or Hercules
> bug, but I can bypass it by just
> deleting prt00f.txt in runmvs.bat
> the same as I do with prt00e.txt.

And this explains the different JES2 STC sequence numbers how?

> BFN. Paul.

Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
---In [hidden email], <fski12@...> wrote :

>> I can't think of anything in computer
>> science that puts an older date later
>> than a newer date.

> You're not trying very hard then. JES2
> schedules it's output by priority not
> by date.

Yes, and I also remembered 2 other
shocking things:

1. Posts to Yahoo Groups do not always
appear in the same order they were
submitted.

2. Facebook chat (from memory), as
of recent times, will get the keystrokes
I enter in the wrong order.

It is unbelievable that the computer
industry in 2017 still can't even manage
something as basic as that.

> But you're comparing apples with kangaroos again. The contents of the log
> data you have printed are for one IPL of MVS. The jobs that are printed are
> jobs that exist on the spool when JES2 is scheduling it's output.

I am doing a cold start of JES2.

> The two different methods you use to automate MVS are leaving the JES2
> queues in differing states.

startmvs had the effect of cleaning
prt00f.txt

multiple runmvs commands reused
the same prt00f.txt, and all runs
kept the same junk from the previous
startmvs command which happened
to be longer.

>> I assume this is some sort of
>> underlying Windows or Hercules
>> bug, but I can bypass it by just
>> deleting prt00f.txt in runmvs.bat
>> the same as I do with prt00e.txt.

> And this explains the different JES2 STC
> sequence numbers how?

>> 08.09.31 STC 9 $HASP373 SVC120I STARTED
>> 08.07.52 STC 28 $HASP373 SVC120I STARTED

The startmvs run does not do a cold
start of JES2, so junk from the
previous run still remains, forcing
numbers to be bumped up.

It seems pretty clear to me that I have
diagnosed correctly. Hercules or
Windows is not appending as intended,
but instead partially overwriting the
previous file, with new data being
written starting at the start of the
file.

Maybe the open() function needs an
O_APPEND or something like that.

BFN. Paul.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
---In [hidden email], <kerravon86@...> wrote :

> I have noticed another anomaly (JRP
> abending) in other runs:

It's not "other runs", it's just a single run.
I was confused by the strange output on
prt00f.txt which I believe I have diagnosed
in another message.

Anyway, I assume that no-one is interested
in debugging an abend of a presumably old
version of JRP, however, the randomness
of this may be indicative of an underlying
MVS or Hercules bug, which also e.g.
saw bsppilot get an abend in an unrelated run.

Regardless, I have uploaded the dump from
the JRP abend:

https://groups.yahoo.com/neo/groups/H390-MVS/files/jrpabend.zip

BFN. Paul.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
---In [hidden email], <somitcw@...> wrote :

>> And another anomaly of SMFDAILY
>> ending with a JCL error from an
>> older run (which I no longer have
>> corresponding printer output for):

> What was the JCL error?

While doing unrelated work, the problem
reappeared, and this time I have the
output:


^L                                                J E S 2   J O B   L O G


09.28.35 STC   56  $HASP373 SMFDAILY STARTED
09.28.35 STC   56  IEF403I SMFDAILY - STARTED - TIME=09.28.35
09.28.35 STC   56  IEF453I SMFDAILY - JOB FAILED - JCL ERROR - TIME=09.28.35
09.28.35 STC   56  $HASP395 SMFDAILY ENDED


------ JES2 JOB STATISTICS ------


 13 MAR 17 JOB EXECUTION DATE


         2 CARDS READ


        25 SYSOUT PRINT RECORDS


         0 SYSOUT PUNCH RECORDS


      0.00 MINUTES EXECUTION TIME

^L    1     //SMFDAILY JOB MSGLEVEL=1                                               STC   56
    2     //STARTING EXEC SMFDAILY,MAN=X
    3     XXSMFDAILY PROC MAN=X
    4     XXDUMP    EXEC PGM=IFASMFDP,REGION=4096K
    5     XXSYSPRINT DD  SYSOUT=*
    6     XXDUMPIN   DD  DISP=SHR,DSN=SYS1.MAN&MAN
    7     XXDUMPOUT  DD  DISP=(,CATLG),
          XX             DSN=SMF.DAILY.DATA(+1),
          XX             UNIT=3390,VOL=SER=MVSCAT,
          XX             SPACE=(TRK,(50,10),RLSE)
    8     XXSYSIN    DD  DISP=SHR,DSN=SYS2.SYSINLIB(SMFDAILY)

^L STMT NO. MESSAGE
-
    6     IEF653I SUBSTITUTION JCL - DISP=SHR,DSN=SYS1.MANX
IEF253I SMFDAILY SMFDAILY DUMPOUT - DUPLICATE NAME ON DIRECT ACCESS VOLUME
IEF272I SMFDAILY SMFDAILY - STEP WAS NOT EXECUTED.
IEF285I   JES2.STC00056.SO0101                         SYSOUT
IEF285I   SYS1.MANX                                    KEPT
IEF285I   VOL SER NOS= MVSRES.



I checked the volume MVSCAT
and found this:

SMF.DAILY.DATA             74.168 00.000 UND  VBS  32756 32760   0     0  N/A
   SMF.DAILY.DATA.G0001V00    74.168 74.168 PS   VBS  32756 32760   1     7    0
   SMF.DAILY.DATA.G0002V00    12.116 12.116 PS   VBS  32756 32760   1    10    0
   SMF.DAILY.DATA.G0003V00    14.229 14.229 PS   VBS  32756 32760   3    70    0
   SMF.DAILY.DATA.G0004V00    14.229 14.229 PS   VBS  32756 32760   3    70    0
   SMF.DAILY.DATA.G0005V00    14.234 14.234 PS   VBS  32756 32760   3    70    0
...
SMF.DAILY.DATA.G0028V00    16.316 16.316 PS   VBS  32756 32760   3    69    0
   SMF.DAILY.DATA.G0029V00    16.331 16.331 PS   VBS  32756 32760   3    69    0
   SMF.DAILY.DATA.G0030V00    16.331 16.331 PS   VBS  32756 32760   4    71    0
   SMF.DAILY.DATA.G0031V00    17.018 00.000 UND  VBS  32756 32760   1    50   49

That last entry looks strange.

But there are no gaps in the numbers.


Doing a display by catalog instead
of volume, there also aren't any gaps,
but it falls short:

  SMF.DAILY.DATA.G0022V00    MVSCAT 16.010 PS   VBS  32756 32760   3    70    0
   SMF.DAILY.DATA.G0023V00    MVSCAT 16.011 PS   VBS  32756 32760   3    70    0
   SMF.DAILY.DATA.G0024V00    MVSCAT 16.014 PS   VBS  32756 32760   3    70    0
   SMF.DAILY.DATA.G0025V00    MVSCAT 16.234 PS   VBS  32756 32760   3    69    0
   SMF.DAILY.DATA.G0026V00    MVSCAT 16.260 PS   VBS  32756 32760   3    70    0
   SMF.DAILY.DATA.G0027V00    MVSCAT 16.274 PS   VBS  32756 32760   3    70    0
   SMF.DAILY.DATA.G0028V00    MVSCAT 16.316 PS   VBS  32756 32760   3    69    0
   SMF.DAILY.DATA.G0029V00    MVSCAT 16.331 PS   VBS  32756 32760   3    69    0
   SMF.DAILY.DATA.G0030V00    MVSCAT 16.331 PS   VBS  32756 32760   4    71    0

ie number 31 is missing.


So I think that explains the error to
some degree, and corresponds to
what Gerhard said about it.

BFN. Paul.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
Hello!
I could say "Because I arranged that!". But in this case, lets stop
blaming each other, otherwise wrap it up in two weeks please.
-----
Gregg C Levine [hidden email]
"This signature fought the Time Wars, time and again."


On Mon, Mar 13, 2017 at 5:38 AM, [hidden email] [H390-MVS]
<[hidden email]> wrote:

> ---In [hidden email], <somitcw@...> wrote :
>
>>> And another anomaly of SMFDAILY
>>> ending with a JCL error from an
>>> older run (which I no longer have
>>> corresponding printer output for):
>
>> What was the JCL error?
>
> While doing unrelated work, the problem
> reappeared, and this time I have the
> output:
>
>
> ^L                                                J E S 2   J O B   L O G
>
>
> 09.28.35 STC   56  $HASP373 SMFDAILY STARTED
> 09.28.35 STC   56  IEF403I SMFDAILY - STARTED - TIME=09.28.35
> 09.28.35 STC   56  IEF453I SMFDAILY - JOB FAILED - JCL ERROR - TIME=09.28.35
> 09.28.35 STC   56  $HASP395 SMFDAILY ENDED
>
>
> ------ JES2 JOB STATISTICS ------
>
>
>  13 MAR 17 JOB EXECUTION DATE
>
>
>          2 CARDS READ
>
>
>         25 SYSOUT PRINT RECORDS
>
>
>          0 SYSOUT PUNCH RECORDS
>
>
>       0.00 MINUTES EXECUTION TIME
>
> ^L    1     //SMFDAILY JOB MSGLEVEL=1                                               STC   56
>     2     //STARTING EXEC SMFDAILY,MAN=X
>     3     XXSMFDAILY PROC MAN=X
>     4     XXDUMP    EXEC PGM=IFASMFDP,REGION=4096K
>     5     XXSYSPRINT DD  SYSOUT=*
>     6     XXDUMPIN   DD  DISP=SHR,DSN=SYS1.MAN&MAN
>     7     XXDUMPOUT  DD  DISP=(,CATLG),
>           XX             DSN=SMF.DAILY.DATA(+1),
>           XX             UNIT=3390,VOL=SER=MVSCAT,
>           XX             SPACE=(TRK,(50,10),RLSE)
>     8     XXSYSIN    DD  DISP=SHR,DSN=SYS2.SYSINLIB(SMFDAILY)
>
> ^L STMT NO. MESSAGE
> -
>     6     IEF653I SUBSTITUTION JCL - DISP=SHR,DSN=SYS1.MANX
> IEF253I SMFDAILY SMFDAILY DUMPOUT - DUPLICATE NAME ON DIRECT ACCESS VOLUME
> IEF272I SMFDAILY SMFDAILY - STEP WAS NOT EXECUTED.
> IEF285I   JES2.STC00056.SO0101                         SYSOUT
> IEF285I   SYS1.MANX                                    KEPT
> IEF285I   VOL SER NOS= MVSRES.
>
>
>
> I checked the volume MVSCAT
> and found this:
>
> SMF.DAILY.DATA             74.168 00.000 UND  VBS  32756 32760   0     0  N/A
>    SMF.DAILY.DATA.G0001V00    74.168 74.168 PS   VBS  32756 32760   1     7    0
>    SMF.DAILY.DATA.G0002V00    12.116 12.116 PS   VBS  32756 32760   1    10    0
>    SMF.DAILY.DATA.G0003V00    14.229 14.229 PS   VBS  32756 32760   3    70    0
>    SMF.DAILY.DATA.G0004V00    14.229 14.229 PS   VBS  32756 32760   3    70    0
>    SMF.DAILY.DATA.G0005V00    14.234 14.234 PS   VBS  32756 32760   3    70    0
> ...
> SMF.DAILY.DATA.G0028V00    16.316 16.316 PS   VBS  32756 32760   3    69    0
>    SMF.DAILY.DATA.G0029V00    16.331 16.331 PS   VBS  32756 32760   3    69    0
>    SMF.DAILY.DATA.G0030V00    16.331 16.331 PS   VBS  32756 32760   4    71    0
>    SMF.DAILY.DATA.G0031V00    17.018 00.000 UND  VBS  32756 32760   1    50   49
>
> That last entry looks strange.
>
> But there are no gaps in the numbers.
>
>
> Doing a display by catalog instead
> of volume, there also aren't any gaps,
> but it falls short:
>
>   SMF.DAILY.DATA.G0022V00    MVSCAT 16.010 PS   VBS  32756 32760   3    70    0
>    SMF.DAILY.DATA.G0023V00    MVSCAT 16.011 PS   VBS  32756 32760   3    70    0
>    SMF.DAILY.DATA.G0024V00    MVSCAT 16.014 PS   VBS  32756 32760   3    70    0
>    SMF.DAILY.DATA.G0025V00    MVSCAT 16.234 PS   VBS  32756 32760   3    69    0
>    SMF.DAILY.DATA.G0026V00    MVSCAT 16.260 PS   VBS  32756 32760   3    70    0
>    SMF.DAILY.DATA.G0027V00    MVSCAT 16.274 PS   VBS  32756 32760   3    70    0
>    SMF.DAILY.DATA.G0028V00    MVSCAT 16.316 PS   VBS  32756 32760   3    69    0
>    SMF.DAILY.DATA.G0029V00    MVSCAT 16.331 PS   VBS  32756 32760   3    69    0
>    SMF.DAILY.DATA.G0030V00    MVSCAT 16.331 PS   VBS  32756 32760   4    71    0
>
> ie number 31 is missing.
>
>
> So I think that explains the error to
> some degree, and corresponds to
> what Gerhard said about it.
>
> BFN. Paul.
>
>
> ------------------------------------
> Posted by: [hidden email]
> ------------------------------------
>
>
> ------------------------------------
>
> Yahoo Groups Links
>
>
>
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
- - - In [hidden email], <kerravon86@...> wrote:
- - - old notes snipped - - -
> While doing unrelated work, the problem
>reappeared, and this time I have the
>output:
- - - remainder snipped - - -

Just do an RPF option =3.4 and catalog the data set.

Also, you may want to stop quitting Hercules while
SMFDAILY is running or allocate the new data set in
a previous separate step with volser and actual
device type so the catalog is quicker.
//  UNIT=3390,VOL=SER=MVSCAT
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
---In [hidden email], <somitcw@...> wrote :

> Also, you may want to stop quitting Hercules while
> SMFDAILY is running

Actually, I'm happy with it immediately
ending now. For the same reason I
like your suggestion of keeping all
3 dump datasets full. :-)

BFN. Paul.
Reply | Threaded
Open this post in threaded view
|

Re: MVS anomalies

Hercules390 - Mvs mailing list
In reply to this post by Hercules390 - Mvs mailing list
 - - - In [hidden email], <kerravon86@...> wrote:
- - - beginning snipped - - -
> Regardless, I have uploaded the dump from the JRP abend:
> https://groups.yahoo.com/neo/groups/H390-MVS/files/jrpabend.zip 
> BFN. Paul.

Why not look are the source for JRP400 ?

WRTRCD   DS    0H
*   WRITE RECORD
*        WTO   'JRP400I: WRITING SMF RECORD...'
         L     R11,=F'0'            SET GOOD RETURN CODE
         SMFWTM SMFBFR              WRITE THE SMF RECORD
         LR    R3,R15               SAVE THE RETURN CODE
         LTR   R15,R15              DID THE WRITE WORK?
         BZ    EXIT                  YES - GO EXIT
         WTO   'JRP400E JRP400 ABENDING'
         ABEND 043,DUMP               TERMINATE THE PROGRAM

A program that abends because your SMF is hosed is questionable.

A program that puts out a message saying that it will abend and
says that it will not give you a reasonable clue as to why is worse.
123