Hangs up when trying to shutdown MVS

[wrljet]

The sysgen.py process randomly hangs up when trying to shutdown MVS.

This happens at random places throughout the process. Different place each of the four runs I tried.

Basically I am unable to get a clean run.

This is on a Debian 12 x86_64 VM.

I've run this with both SDL-Hercules (develop branch, 4.8.0.11173-SDL-DEV-gbbfb973d)
and Aethra Hercules (develop branch, 4.7.0.11133-Aethra-g55f16b55).

An example log shows:

12:26:52,372 root DEBUG [HERCLOG] / $HASP373 MVS01    STARTED - INIT  3 - CLASS S - SYS MVSC
12:26:52,373 root DEBUG [HERCLOG] / IEF403I MVS01 - STARTED - TIME=11.26.52
12:26:52,573 root DEBUG [DIAG] MIPS=   0.32
12:26:53,64 root DEBUG [HERCLOG] / IEFACTRT IDCAMS01/IDCAMS  /00:00:00.27/00:00:00.70/00000/MVS01
12:26:53,65 root DEBUG [HERCLOG] / IEF404I MVS01 - ENDED - TIME=11.26.53
12:26:53,70 root DEBUG [HERCLOG] / $HASP395 MVS01    ENDED
12:26:53,70 root DEBUG [HERCLOG] / $HASP309    INIT  3 INACTIVE ******** C=S
12:26:53,76 root DEBUG [HERCLOG] / $HASP150 MVS01    ON PRINTER1       192 LINES
12:26:53,76 root DEBUG [DIAG] MIPS=  14.15
12:26:53,87 root DEBUG [HERCLOG] / $HASP160 PRINTER1 INACTIVE - CLASS=A
12:26:53,104 root DEBUG [HERCLOG] / $HASP250 MVS01    IS PURGED
12:26:53,110 root DEBUG [HERCLOG] / $HASP099 ALL AVAILABLE FUNCTIONS COMPLETE
12:26:53,116 root DEBUG Checking MVS01 job results
12:26:53,117 root DEBUG [MAXCC] Jobname: MVS01    Procname:          Stepname: IDCAMS01 Exit Code: 0000    
12:26:53,117 root DEBUG Sending Hercules Command: /$p jes2
12:26:53,117 root DEBUG Waiting for string to appear in hercules log: IEF404I JES2 - ENDED - 
12:26:53,117 root DEBUG [HERCLOG] HHC00013I '/' input entered for console 0:0009: "$p jes2"
12:26:53,130 root DEBUG [HERCLOG] $p jes2
12:26:53,130 root DEBUG [HERCLOG] / IEF404I INIT - ENDED - TIME=11.26.53
12:26:53,130 root DEBUG [HERCLOG] / $HASP395 INIT     ENDED
12:26:53,131 root DEBUG [HERCLOG] / IEF404I INIT - ENDED - TIME=11.26.53
12:26:53,131 root DEBUG [HERCLOG] / $HASP395 INIT     ENDED
12:26:53,141 root DEBUG [HERCLOG] / IEF404I INIT - ENDED - TIME=11.26.53
12:26:53,158 root DEBUG [HERCLOG] / $HASP395 INIT     ENDED
12:26:53,164 root DEBUG [HERCLOG] / IEE043I A SYSTEM LOG DATA SET HAS BEEN QUEUED TO SYSOUT CLASS A
12:26:53,164 root DEBUG [HERCLOG] / IEE037I LOG NOT ACTIVE
12:26:54,626 root DEBUG [DIAG] MIPS=   6.15
12:26:55,651 root DEBUG [DIAG] MIPS=   0.00
12:26:56,627 root DEBUG [DIAG] MIPS=   0.02
12:26:57,623 root DEBUG [DIAG] MIPS=   0.00

Here's another example from another run:

17:34:26,222 root DEBUG [HERCLOG] HHC00013I '/' input entered for console 0:001F: "$p jes2"
17:34:26,227 root DEBUG [HERCLOG] $p jes2
17:34:26,227 root DEBUG [HERCLOG] / $HASP395 INIT     ENDED
17:34:26,233 root DEBUG [HERCLOG] / $HASP395 INIT     ENDED
17:34:26,238 root DEBUG [HERCLOG] / $HASP395 INIT     ENDED
17:34:26,244 root DEBUG [HERCLOG] / IEE043I A SYSTEM LOG DATA SET HAS BEEN QUEUED TO SYSOUT CLASS A
17:34:26,244 root DEBUG [HERCLOG] / IEE037I LOG NOT ACTIVE
17:34:26,245 root DEBUG [HERCLOG] /2000 21.34.26 CONSOLE   IEE142I  01F NOW RECEIVING HARDCOPY
17:34:26,250 root DEBUG [HERCLOG] /4000 21.34.26           IEE043I A SYSTEM LOG DATA SET HAS BEEN QUEUED TO SYSOUT CLASS A
17:34:26,250 root DEBUG [HERCLOG] /4000 21.34.26           IEE037I LOG NOT ACTIVE
17:34:26,251 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF142I JES2 JES2 - STEP WAS EXECUTED - COND CODE 0000
17:34:26,251 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   SYS1.PROCLIB                                 KEPT
17:34:26,251 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   VOL SER NOS= START1.
17:34:26,251 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   SYS1.HASPCKPT                                KEPT
17:34:26,252 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   VOL SER NOS= SPOOL0.
17:34:26,252 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   SYS1.HASPACE                                 KEPT
17:34:26,252 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   VOL SER NOS= SPOOL0.
17:34:26,252 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   SYS1.HASPACE                                 KEPT
17:34:26,252 root DEBUG Sending Hercules Command: /z eod
17:34:26,252 root DEBUG Waiting for string to appear in hercules log: IEE334I HALT     EOD SUCCESSFUL
17:34:26,258 root DEBUG [HERCLOG] HHC00013I '/' input entered for console 0:001F: "z eod"
17:34:26,261 root DEBUG [HERCLOG] z eod
17:34:26,263 root DEBUG [HERCLOG] /0000 21.34.26           IEF196I IEF285I   VOL SER NOS= SPOOL1.
17:34:27,758 root DEBUG [DIAG] MIPS=   5.46
17:34:28,761 root DEBUG [DIAG] MIPS=   0.0

I assume it is this code waiting for the xxx?

   def shutdown_mvs(self, cust=False):
        self.send_oper('$p jes2')
        if cust:
            self.wait_for_string('IEF404I JES2 - ENDED - ')
        else:
            self.wait_for_string('IEF196I IEF285I   VOL SER NOS= SPOOL0.')
        self.send_oper('z eod')
        self.wait_for_string('IEE334I HALT     EOD SUCCESSFUL')
        self.send_oper('quiesce')
        self.wait_for_string("disabled wait state")
        self.send_herc('stop')

Bill

[wrljet]

I have fiddled with it some more and come up with a kludgy fix.
... developing ...

[mainframed]

I made some changes as it looks like a hercules log message changed. Was just able to build it successfully on this container: https://hub.docker.com/r/mainframed767/hercules which was built today running:

HHC00109E set_thread_priority( 5 ) failed: Operation not permitted
HHC00007I Previous message from function 'impl' at impl.c(1173)
HHC00110W Defaulting all threads to priority 1
HHC00007I Previous message from function 'impl' at impl.c(1177)
HHC02342S Configuration file 'hercules.cnf' not found: No such file or directory
HHC00007I Previous message from function 'process_args' at impl.c(2020)
HHC01413I Hercules version 4.8.0.11177-SDL-DEV-g2247c7b8
HHC01414I (C) Copyright 1999-2024 by Roger Bowler, Jan Jaeger, and others
HHC01417I Built for you with Hercules-Helper (version: v0.9.14-107-g1c08d4b)
HHC01415I Build date: May 26 2024 at 17:04:27
HHC01407S Usage: hercules [--help[=SHORT|LONG|VERSION|BUILD]] -f config-filename|"none" [-o logfile-name] [-r rcfile-name] [-d] [-b logo-filename] [-s sym=val] [-t [factor]] [-p dyn-load-dir] [[-l dynmod-to-load]...] [> logfile]
HHC00007I Previous message from function 'arghelp' at impl.c(794)
HHC02343S Terminating due to 1 argument errors
HHC00007I Previous message from function 'impl' at impl.c(1208)
HHC01420I Begin Hercules shutdown
HHC01423I Calling termination routines
HHC01424I All termination routines complete
HHC01425I Hercules shutdown complete
HHC01412I Hercules terminated

[wrljet]

I'll give it a try.

[wrljet]

Oh, BTW, I know this is a breach of GitHub etiquette, but unrelated to this issue, here's a one line change I found useful:

Adding the dirs_exist_ok=True param.

@@ -2168,7 +2172,8 @@ class sysgen:
         Path(running_folder+"MVSCE/punchcards").mkdir(parents=True, exist_ok=True)
 
         self.print("Copying scripts to {}".format(Path(running_folder+"MVSCE/SCRIPTS").resolve()))
-        shutil.copytree(Path('SCRIPTS').resolve(), Path(running_folder+"MVSCE/SCRIPTS").resolve())
+        # WRL overwrite existing target directory
+        shutil.copytree(Path('SCRIPTS').resolve(), Path(running_folder+"MVSCE/SCRIPTS").resolve(), dirs_exist_ok=True)
 
         up = "| {:9} | {:8}|\n"

[wrljet]

This fixes the hangups for me:

diff --git a/sysgen.py b/sysgen.py
index f23ab3a..cd6749f 100755
--- a/sysgen.py
+++ b/sysgen.py
@@ -1819,6 +1819,10 @@ class sysgen:
             self.wait_for_string('IEF404I JES2 - ENDED - ')
         else:
             self.wait_for_string('IEF196I IEF285I   VOL SER NOS= SPOOL0.')
+
+        # WRL Give MVS / JES2 time to catch up
+        time.sleep(5)
+
         self.send_oper('z eod')
         self.wait_for_string('IEE334I HALT     EOD SUCCESSFUL')

[mainframed]

Do you mind making a pull request for both changes (you can do it as one pull request)?

[wrljet]

Sure, I can try to do that. (I'm not that handy with GitHub. )

I don't know if 5 seconds is way too long, or how the speed of the host system affects this. It does get called quite a few times through the entire SYSGEN process.