kerravon86@yahoo.com.au [hercules-390]
2017-03-19 22:24:48 UTC
This is the first time I have noticed this
problem, and it's extremely rare. Hasn't
occurred before in the previous approx.
30,000 automated runs.
I expect that at the moment a script is
triggered, that all following output to
the terminal should be buffered so
that if the script sets up a new trigger,
that trigger cannot be bypassed due
to timing sensitivities.
That does not appear to be the case,
and results differ due to a race
condition. See below. Test done with
Hercules 4.0 rc0:
C:\download>dir Hercules-4.0.0-rc0-win-x86.zip
Volume in drive C is OS
Volume Serial Number is DE22-8195
Directory of C:\download
2017-01-18 22:11 5,085,085 Hercules-4.0.0-rc0-win-x86.zip
1 File(s) 5,085,085 bytes
0 Dir(s) 63,491,186,688 bytes free
C:\download>
(so much for the claim that I'm not
hammering Hercules - I'm discovering
rare problems due to the massive
thrashing).
This is the line:
09:05:14 /22.05.14 JOB 2 $HASP250 TERMHERC IS PURGED
that was meant to trigger this:
09:05:15 HHC01603I hao tgt HASP250 TERMHERC
BFN. Paul.
09:05:03 HHC01413I Hercules version 4.0.0.0 (4.0.0.0)
09:05:03 HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
09:05:03 HHC01415I Build date: Dec 16 2016 at 14:14:30
09:05:03 HHC01417I Built with: Microsoft Visual C 190024215 1
09:05:03 HHC01417I Build type: Windows MSVC i386 host architecture build
09:05:03 HHC01417I Modes: S/370 ESA/390 z/Arch
09:05:03 HHC01417I Max CPU Engines: 32
09:05:03 HHC01417I Using Fish threads Threading Model
09:05:03 HHC01417I Using Error-Checking Mutex Locking Model
...
09:05:14 /22.05.14 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
09:05:14 HHC00081I Match at index 02, executing command script conf/termherc.rc
09:05:14 HHC01603I script conf/termherc.rc
09:05:14 /22.05.14 JOB 2 IEF403I TERMHERC - STARTED - TIME=22.05.14
09:05:14 /22.05.14 $HASP160 PRINTER1 INACTIVE - CLASS=AP
09:05:14 /22.05.14 JOB 1 $HASP250 HERC01A IS PURGED
09:05:14 /22.05.14 *IEE362A SMF ENTER DUMP FOR SYS1.MANX ON MVSRES
09:05:14 /22.05.14 IEE361I SMF DATA LOST - SYS1.MANY NOT AVAILABLE TIME=22.05.14
09:05:14 /22.05.14 STC 18 $HASP100 SMFDAILY ON STCINRDR
09:05:14 /22.05.14 STC 16 IKT007I TCAS ACCEPTING LOGONS
09:05:14 /22.05.14 STC 16 IKT005I TCAS IS INITIALIZED
09:05:14 /22.05.14 STC 18 $HASP373 SMFDAILY STARTED
09:05:14 /22.05.14 STC 18 IEF403I SMFDAILY - STARTED - TIME=22.05.14
09:05:14 /22.05.14 STC 18 IEF453I SMFDAILY - JOB FAILED - JCL ERROR - TIME=22.05.14
09:05:14 /22.05.14 STC 18 $HASP395 SMFDAILY ENDED
09:05:14 /22.05.14 STC 18 $HASP150 SMFDAILY ON PRINTER2 25 LINES
09:05:14 /22.05.14 IEE132I START COMMAND DEVICE ALLOCATION ERROR
09:05:14 /22.05.14 $HASP160 PRINTER2 INACTIVE - CLASS=Z
09:05:14 /22.05.14 STC 18 $HASP250 SMFDAILY IS PURGED
09:05:14 /22.05.14 JOB 2 IEFACTRT - Stepname Procstep Program Retcode
09:05:14 /22.05.14 JOB 2 TERMHERC S1 IEBGENER RC= 0000
09:05:14 /22.05.14 JOB 2 IEF404I TERMHERC - ENDED - TIME=22.05.14
09:05:14 /22.05.14 JOB 2 $HASP395 TERMHERC ENDED
09:05:14 /22.05.14 $HASP309 INIT 3 INACTIVE ******** C=CBA
09:05:14 /22.05.14 JOB 2 $HASP150 TERMHERC ON PRINTER1 1 LINE
09:05:14 /22.05.14 JOB 2 $HASP150 TERMHERC ON PRINTER2 44 LINES
09:05:14 /22.05.14 $HASP160 PRINTER1 INACTIVE - CLASS=AP
09:05:14 /22.05.14 $HASP160 PRINTER2 INACTIVE - CLASS=Z
09:05:14 /22.05.14 JOB 2 $HASP250 TERMHERC IS PURGED
09:05:14 /22.05.14 STC 17 JRP400E JRP400 ABENDING
09:05:14 /22.05.14 STC 17 IST804I VTAM CLOSE IN PROCESS FOR JRP OPENED BY JRP UNKNOWN
09:05:14 /22.05.14 STC 14 IST400I TERMINATION IN PROGRESS FOR APPLID JRP
09:05:14 /22.05.14 STC 14 IST805I VTAM CLOSE COMPLETE FOR JRP
09:05:14 /22.05.14 STC 17 IEF450I JRP JRP - ABEND S000 U0043 - TIME=22.05.14
09:05:14 /22.05.14 STC 17 IEF404I JRP - ENDED - TIME=22.05.14
09:05:14 /22.05.14 STC 17 $HASP395 JRP ENDED
09:05:14 /22.05.14 STC 17 $HASP150 JRP ON PRINTER2 1,756 LINES
09:05:15 HHC02260I Script 6: begin processing file conf/termherc.rc
09:05:15 HHC01603I hao clear
09:05:15 HHC00080I All HAO rules are cleared
09:05:15 HHC01603I hao tgt HASP250 TERMHERC
09:05:15 HHC00077I The target was placed at index 0
09:05:15 HHC01603I hao cmd script conf/termherc2.rc
09:05:15 HHC00077I The command was placed at index 0
09:05:15 HHC02264I Script 6: file conf/termherc.rc processing ended
09:05:15 /22.05.15 $HASP160 PRINTER2 INACTIVE - CLASS=Z
09:05:15 /22.05.15 STC 17 $HASP250 JRP IS PURGED
09:08:48 /m 401,VOL=(NL,PCTOMF)
09:08:48 /22.08.48 STC 19 $HASP100 MOUNT ON STCINRDR
09:08:48 /22.08.48 STC 19 $HASP373 MOUNT STARTED
09:08:48 /22.08.48 STC 19 IEF403I MOUNT - STARTED - TIME=22.08.48
09:08:48 /22.08.48 STC 19 *IEF233A M 401,PCTOMF,,MOUNT,401
09:08:48 /22.08.48 STC 19 IEE135I ERROR - REQUESTED DEVICE RESERVED
problem, and it's extremely rare. Hasn't
occurred before in the previous approx.
30,000 automated runs.
I expect that at the moment a script is
triggered, that all following output to
the terminal should be buffered so
that if the script sets up a new trigger,
that trigger cannot be bypassed due
to timing sensitivities.
That does not appear to be the case,
and results differ due to a race
condition. See below. Test done with
Hercules 4.0 rc0:
C:\download>dir Hercules-4.0.0-rc0-win-x86.zip
Volume in drive C is OS
Volume Serial Number is DE22-8195
Directory of C:\download
2017-01-18 22:11 5,085,085 Hercules-4.0.0-rc0-win-x86.zip
1 File(s) 5,085,085 bytes
0 Dir(s) 63,491,186,688 bytes free
C:\download>
(so much for the claim that I'm not
hammering Hercules - I'm discovering
rare problems due to the massive
thrashing).
This is the line:
09:05:14 /22.05.14 JOB 2 $HASP250 TERMHERC IS PURGED
that was meant to trigger this:
09:05:15 HHC01603I hao tgt HASP250 TERMHERC
BFN. Paul.
09:05:03 HHC01413I Hercules version 4.0.0.0 (4.0.0.0)
09:05:03 HHC01414I (C) Copyright 1999-2016 by Roger Bowler, Jan Jaeger, and others
09:05:03 HHC01415I Build date: Dec 16 2016 at 14:14:30
09:05:03 HHC01417I Built with: Microsoft Visual C 190024215 1
09:05:03 HHC01417I Build type: Windows MSVC i386 host architecture build
09:05:03 HHC01417I Modes: S/370 ESA/390 z/Arch
09:05:03 HHC01417I Max CPU Engines: 32
09:05:03 HHC01417I Using Fish threads Threading Model
09:05:03 HHC01417I Using Error-Checking Mutex Locking Model
...
09:05:14 /22.05.14 JOB 2 $HASP373 TERMHERC STARTED - INIT 3 - CLASS C - SYS BSP1
09:05:14 HHC00081I Match at index 02, executing command script conf/termherc.rc
09:05:14 HHC01603I script conf/termherc.rc
09:05:14 /22.05.14 JOB 2 IEF403I TERMHERC - STARTED - TIME=22.05.14
09:05:14 /22.05.14 $HASP160 PRINTER1 INACTIVE - CLASS=AP
09:05:14 /22.05.14 JOB 1 $HASP250 HERC01A IS PURGED
09:05:14 /22.05.14 *IEE362A SMF ENTER DUMP FOR SYS1.MANX ON MVSRES
09:05:14 /22.05.14 IEE361I SMF DATA LOST - SYS1.MANY NOT AVAILABLE TIME=22.05.14
09:05:14 /22.05.14 STC 18 $HASP100 SMFDAILY ON STCINRDR
09:05:14 /22.05.14 STC 16 IKT007I TCAS ACCEPTING LOGONS
09:05:14 /22.05.14 STC 16 IKT005I TCAS IS INITIALIZED
09:05:14 /22.05.14 STC 18 $HASP373 SMFDAILY STARTED
09:05:14 /22.05.14 STC 18 IEF403I SMFDAILY - STARTED - TIME=22.05.14
09:05:14 /22.05.14 STC 18 IEF453I SMFDAILY - JOB FAILED - JCL ERROR - TIME=22.05.14
09:05:14 /22.05.14 STC 18 $HASP395 SMFDAILY ENDED
09:05:14 /22.05.14 STC 18 $HASP150 SMFDAILY ON PRINTER2 25 LINES
09:05:14 /22.05.14 IEE132I START COMMAND DEVICE ALLOCATION ERROR
09:05:14 /22.05.14 $HASP160 PRINTER2 INACTIVE - CLASS=Z
09:05:14 /22.05.14 STC 18 $HASP250 SMFDAILY IS PURGED
09:05:14 /22.05.14 JOB 2 IEFACTRT - Stepname Procstep Program Retcode
09:05:14 /22.05.14 JOB 2 TERMHERC S1 IEBGENER RC= 0000
09:05:14 /22.05.14 JOB 2 IEF404I TERMHERC - ENDED - TIME=22.05.14
09:05:14 /22.05.14 JOB 2 $HASP395 TERMHERC ENDED
09:05:14 /22.05.14 $HASP309 INIT 3 INACTIVE ******** C=CBA
09:05:14 /22.05.14 JOB 2 $HASP150 TERMHERC ON PRINTER1 1 LINE
09:05:14 /22.05.14 JOB 2 $HASP150 TERMHERC ON PRINTER2 44 LINES
09:05:14 /22.05.14 $HASP160 PRINTER1 INACTIVE - CLASS=AP
09:05:14 /22.05.14 $HASP160 PRINTER2 INACTIVE - CLASS=Z
09:05:14 /22.05.14 JOB 2 $HASP250 TERMHERC IS PURGED
09:05:14 /22.05.14 STC 17 JRP400E JRP400 ABENDING
09:05:14 /22.05.14 STC 17 IST804I VTAM CLOSE IN PROCESS FOR JRP OPENED BY JRP UNKNOWN
09:05:14 /22.05.14 STC 14 IST400I TERMINATION IN PROGRESS FOR APPLID JRP
09:05:14 /22.05.14 STC 14 IST805I VTAM CLOSE COMPLETE FOR JRP
09:05:14 /22.05.14 STC 17 IEF450I JRP JRP - ABEND S000 U0043 - TIME=22.05.14
09:05:14 /22.05.14 STC 17 IEF404I JRP - ENDED - TIME=22.05.14
09:05:14 /22.05.14 STC 17 $HASP395 JRP ENDED
09:05:14 /22.05.14 STC 17 $HASP150 JRP ON PRINTER2 1,756 LINES
09:05:15 HHC02260I Script 6: begin processing file conf/termherc.rc
09:05:15 HHC01603I hao clear
09:05:15 HHC00080I All HAO rules are cleared
09:05:15 HHC01603I hao tgt HASP250 TERMHERC
09:05:15 HHC00077I The target was placed at index 0
09:05:15 HHC01603I hao cmd script conf/termherc2.rc
09:05:15 HHC00077I The command was placed at index 0
09:05:15 HHC02264I Script 6: file conf/termherc.rc processing ended
09:05:15 /22.05.15 $HASP160 PRINTER2 INACTIVE - CLASS=Z
09:05:15 /22.05.15 STC 17 $HASP250 JRP IS PURGED
09:08:48 /m 401,VOL=(NL,PCTOMF)
09:08:48 /22.08.48 STC 19 $HASP100 MOUNT ON STCINRDR
09:08:48 /22.08.48 STC 19 $HASP373 MOUNT STARTED
09:08:48 /22.08.48 STC 19 IEF403I MOUNT - STARTED - TIME=22.08.48
09:08:48 /22.08.48 STC 19 *IEF233A M 401,PCTOMF,,MOUNT,401
09:08:48 /22.08.48 STC 19 IEE135I ERROR - REQUESTED DEVICE RESERVED