search

SDL-Hercules-390 / hyperion

The SDL Hercules 4.x Hyperion version of the System/370, ESA/390, and z/Architecture Emulator
Other
249 stars 92 forks source link

Possible race in SCP command processing #18

Closed Fish-Git closed 6 years ago

Fish-Git commented 7 years ago

There is a possible race condition in SCP command processing.

I say "possible" since the manner in which it is currently behaving might be correct. Further research is required to determine whether the current behavior is correct or not.

When multiple SCP guest commands are issued in rapid succession (by leveraging the now fixed 'cmdsep' feature), it is possible for one or more subsequent commands to be skipped/missed (not processed) while the current command is being processed.

The following log file extract illustrates this behavior:

The above .rc file was used to trigger the behavior. The guest O/S used was z/VM 6.3, but other modern operating systems (such as z/OS) behave similarly.

The test was performed on a Windows 7 x64 host running commit 424ba73e3fad27e15833bb59e2d9289a7ca6b009 of Hyperion, dated Nov 11, 2017 (i.e. the cmdsep fix).

07:04:55 HHC01603I script "C:\Users\Fish\HercGUI\Configuration Files\scripts\cmdsep.rc.txt"
07:04:55 HHC02260I Script 1: begin processing file C:/Users/Fish/HercGUI/Configuration Files/scripts/cmdsep.rc.txt
07:04:55 HHC01603I msglvl -debug +emsgloc
07:04:55 HHC17012I MSGLEVEL = verbose nodebug emsgloc
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I * *********************************************************************
07:04:55 HHC01603I * *********************************************************************
07:04:55 HHC01603I * **********************     BEGIN TEST     ***************************
07:04:55 HHC01603I * *********************************************************************
07:04:55 HHC01603I * *********************************************************************
07:04:55 HHC01603I *
07:04:55 HHC01603I cmdsep ^
07:04:55 HHC02204I CMDSEP         set to ^
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I * -----------------------------------------------------------
07:04:55 HHC01603I *  Each command individually with slight pause between each,
07:04:55 HHC01603I *  so we can see what the correct response should look like.
07:04:55 HHC01603I * -----------------------------------------------------------
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC00160I SCP command: q e
07:04:55 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:55 07:04:55 Q E
07:04:55 07:04:55 PRT  000E DRAINED    SYSTEM   CLASS A
07:04:55 07:04:55 PRT  000E FORM STANDARD MANUAL SEP   NO3800  FILEFCB LIMIT NONE
07:04:55 07:04:55 PRT  000E NOFOLD  IMAGE IMAG3211 CHARS A11  FCB FCB1 INDEX 1  LPP 000
07:04:55 07:04:55 PRT  000E DEST OFF      DEST - NONE - DEST - NONE - DEST - NONE -
07:04:55 07:04:55 PRT  000E AFP
07:04:55 HHC02263I Script 1: processing resumed...
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC00160I SCP command: q cons
07:04:55 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:55 07:04:55 Q CONS
07:04:55 07:04:55 CONS 0009 ON SYSC         TERM START
07:04:55 07:04:55      0009 CL T NOCONT NOHOLD COPY 001    READY FORM STANDARD
07:04:55 07:04:55      0009 TO OPERATOR PRT DIST OPERATOR  FLASHC 000 DEST OFF
07:04:55 07:04:55      0009 FLASH       CHAR       MDFY       0 FCB       LPP OFF
07:04:55 07:04:55      0009 3215   NOEOF OPEN 0010 NOKEEP NOMSG NONAME
07:04:55 07:04:55      0009 SUBCHANNEL = 0005
07:04:55 HHC02263I Script 1: processing resumed...
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC00160I SCP command: q cplevel
07:04:55 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:55 07:04:55 Q CPLEVEL
07:04:55 07:04:55 z/VM Version 6 Release 3.0, service level 1302 (64-bit)
07:04:55 07:04:55 Generated at 08/07/13 11:42:58 PST
07:04:55 07:04:55 IPL at 11/12/17 06:43:01 PST
07:04:55 HHC02263I Script 1: processing resumed...
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC00160I SCP command: q dasd
07:04:55 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:55 07:04:55 Q DASD
07:04:55 07:04:55 DASD 0101 CP OWNED  VMCOM1   12
07:04:55 07:04:55 DASD 0201 CP SYSTEM 630RL1   9
07:04:55 07:04:55 DASD 0301 CP OWNED  M01RES   104
07:04:55 07:04:55 DASD 0901 CP OWNED  M01S01   0
07:04:55 07:04:55 DASD 0902 CP OWNED  M01P01   0
07:04:55 07:04:55 DASD 0903 CP SYSTEM M01W01   0
07:04:55 HHC02263I Script 1: processing resumed...
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC00160I SCP command: q osa
07:04:55 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:55 07:04:55 Q OSA
07:04:55 07:04:55 OSA  0600 ATTACHED TO TCPIP    0600 DEVTYPE OSA         CHPID F0 OSD
07:04:55 07:04:55 OSA  0601 ATTACHED TO TCPIP    0601 DEVTYPE OSA         CHPID F0 OSD
07:04:55 07:04:55 OSA  0602 ATTACHED TO TCPIP    0602 DEVTYPE OSA         CHPID F0 OSD
07:04:55 HHC02263I Script 1: processing resumed...
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC01603I *
07:04:55 HHC00160I SCP command: q set
07:04:55 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:55 07:04:55 Q SET
07:04:55 07:04:55 MSG ON  , WNG ON  , EMSG ON  , ACNT OFF, RUN ON
07:04:55 07:04:55 LINEDIT ON , TIMER OFF , ISAM OFF, ECMODE ON
07:04:55 07:04:55 ASSIST OFF           , PAGEX OFF, AUTOPOLL OFF
07:04:55 07:04:55 IMSG ON  , SMSG OFF , AFFINITY NONE   , NOTRAN OFF
07:04:55 07:04:55 VMSAVE OFF, 370E OFF
07:04:55 07:04:55 STBYPASS OFF   , STMULTI OFF   00/000
07:04:55 07:04:55 MIH OFF , VMCONIO OFF , CPCONIO OFF , SVCACCL OFF , CONCEAL OFF
07:04:55 07:04:55 MACHINE ESA, SVC76 CP, NOPDATA OFF, IOASSIST OFF
07:04:55 07:04:55 CCWTRAN ON, 370ACCOM OFF, TIMEBOMB IDLE
07:04:56 HHC02263I Script 1: processing resumed...
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC00160I SCP command: q stor
07:04:56 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:56 07:04:56 Q STOR
07:04:56 07:04:56 STORAGE = 5G CONFIGURED = 5G INC = 1M STANDBY = 0  RESERVED = 0
07:04:56 HHC02263I Script 1: processing resumed...
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC00160I SCP command: q sys
07:04:56 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:56 07:04:56 Q SYS
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0101 ATTACHED CPVOL  0012 VMCOM1
07:04:56 07:04:56 VMSERVP  0311 R/W      , VMSERVP  0310 R/W      , VMSERVP  0309 R/W
07:04:56 07:04:56 VMSERVP  0308 R/W      , VMSERVP  0307 R/W      , VMSERVP  0306 R/W
07:04:56 07:04:56 VMSERVP  0305 R/W      , VMSERVP  0304 R/W      , VMSERVP  0303 R/W
07:04:56 07:04:56 VMSERVP  0301 R/W      , VMSERVP  0302 R/W      , VMSERVP  0191 R/W
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0201 ATTACHED SYSTEM 0009 630RL1
07:04:56 07:04:56 DTCVSW1  0492 R/O      , DTCVSW2  0492 R/O      , TCPIP    0492 R/O
07:04:56 07:04:56 FTPSERVE 0492 R/O      , DTCVSW1  0491 R/O      , DTCVSW2  0491 R/O
07:04:56 07:04:56 TCPIP    0491 R/O      , FTPSERVE 0491 R/O      , EREP     0201 R/O
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0301 ATTACHED CPVOL  0104 M01RES
07:04:56 07:04:56 OPERATOR 0191 R/W      , OPERATOR 0192 R/O      , FTPSERVE 0191 R/W
07:04:56 07:04:56 TCPIP    0191 R/W      , VMSERVR  0307 R/W      , VMSERVR  0306 R/W
07:04:56 07:04:56 VMSERVR  0305 R/W      , DTCVSW1  0191 R/W      , VMSERVU  0305 R/W
07:04:56 07:04:56 VMSERVR  0304 R/W      , DTCVSW2  0191 R/W      , VMSERVU  0304 R/W
07:04:56 07:04:56 VMSERVR  0303 R/W      , DTCVSW2  0198 R/O      , DTCVSW1  0198 R/O
07:04:56 07:04:56 TCPIP    0198 R/O      , FTPSERVE 0198 R/O      , VMSERVU  0303 R/W
07:04:56 07:04:56 VMSERVR  0302 R/W      , DTCVSW2  0592 R/O      , DTCVSW1  0592 R/O
07:04:56 07:04:56 TCPIP    0592 R/O      , FTPSERVE 0592 R/O      , VMSERVU  0302 R/W
07:04:56 07:04:56 VMSERVR  0301 R/W      , DTCVSW2  0591 R/O      , DTCVSW1  0591 R/O
07:04:56 07:04:56 TCPIP    0591 R/O      , FTPSERVE 0591 R/O      , VMSERVU  0301 R/W
07:04:56 07:04:56 VMSERVR  0191 R/W      , VMSERVU  0191 R/W      , VMSERVS  0305 R/W
07:04:56 07:04:56 VMSERVS  0304 R/W      , VMSERVS  0303 R/W      , VMSERVS  0302 R/W
07:04:56 07:04:56 VMSERVS  0301 R/W      , VMSERVS  0191 R/W      , OPERSYMP 0191 R/W
07:04:56 07:04:56 OPERSYMP 0192 R/O      , VMSERVS  0193 R/O      , VMSERVU  0193 R/O
07:04:56 07:04:56 VMSERVR  0193 R/O      , VMSERVP  0193 R/O      , DISKACNT 0191 R/W
07:04:56 07:04:56 EREP     0191 R/W      , DISKACNT 0401 R/O      , OPERSYMP 0401 R/O
07:04:56 07:04:56 VMSERVS  0401 R/O      , VMSERVP  0401 R/O      , DTCVSW2  0401 R/O
07:04:56 07:04:56 VMSERVU  0401 R/O      , DTCVSW1  0401 R/O      , VMSERVR  0401 R/O
07:04:56 07:04:56 TCPIP    0401 R/O      , FTPSERVE 0401 R/O      , OPERATOR 0401 R/O
07:04:56 07:04:56 DISKACNT 0402 R/O      , OPERSYMP 0402 R/O      , VMSERVS  0402 R/O
07:04:56 07:04:56 VMSERVP  0402 R/O      , DTCVSW2  0402 R/O      , VMSERVU  0402 R/O
07:04:56 07:04:56 DTCVSW1  0402 R/O      , VMSERVR  0402 R/O      , TCPIP    0402 R/O
07:04:56 07:04:56 FTPSERVE 0402 R/O      , OPERATOR 0402 R/O      , DISKACNT 019E R/O
07:04:56 07:04:56 OPERSYMP 019E R/O      , VMSERVS  019E R/O      , VMSERVP  019E R/O
07:04:56 07:04:56 DTCVSW2  019E R/O      , VMSERVU  019E R/O      , DTCVSW1  019E R/O
07:04:56 07:04:56 VMSERVR  019E R/O      , TCPIP    019E R/O      , FTPSERVE 019E R/O
07:04:56 07:04:56 OPERATOR 019E R/O      , DISKACNT 019D R/O      , OPERSYMP 019D R/O
07:04:56 07:04:56 VMSERVS  019D R/O      , VMSERVP  019D R/O      , DTCVSW2  019D R/O
07:04:56 07:04:56 VMSERVU  019D R/O      , DTCVSW1  019D R/O      , VMSERVR  019D R/O
07:04:56 07:04:56 TCPIP    019D R/O      , FTPSERVE 019D R/O      , OPERATOR 019D R/O
07:04:56 07:04:56 EREP     0190 R/O      , DISKACNT 0190 R/O      , OPERSYMP 0190 R/O
07:04:56 07:04:56 VMSERVS  0190 R/O      , VMSERVP  0190 R/O      , DTCVSW2  0190 R/O
07:04:56 07:04:56 VMSERVU  0190 R/O      , DTCVSW1  0190 R/O      , VMSERVR  0190 R/O
07:04:56 07:04:56 TCPIP    0190 R/O      , FTPSERVE 0190 R/O      , OPERATOR 0190 R/O
07:04:56 07:04:56 SYSTEM   0003 R/O      , SYSTEM   0001 R/O
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0901 ATTACHED CPVOL  0000 M01S01
07:04:56 07:04:56 DASD MDISKS NOT FOUND
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0902 ATTACHED CPVOL  0000 M01P01
07:04:56 07:04:56 DASD MDISKS NOT FOUND
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0903 ATTACHED SYSTEM 0000 M01W01
07:04:56 07:04:56 DASD MDISKS NOT FOUND
07:04:56 HHC02263I Script 1: processing resumed...
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC00160I SCP command: q t
07:04:56 HHC02262I Script 1: processing paused for 150 milliseconds...
07:04:56 07:04:56 Q T
07:04:56 07:04:56 TIME IS 07:04:56 PST SUNDAY 11/12/17
07:04:56 07:04:56 CONNECT= 00:00:58 VIRTCPU= 000:00.00 TOTCPU= 000:00.06
07:04:56 HHC02263I Script 1: processing resumed...
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC01603I * -----------------------------------------------------------
07:04:56 HHC01603I *  Now do them all at once pausing slightly longer afterwards
07:04:56 HHC01603I * -----------------------------------------------------------
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC01603I *
07:04:56 HHC00160I SCP command: q e
07:04:56 HHC00160I SCP command: q cons
07:04:56 HHC00160I SCP command: q cplevel
07:04:56 HHC00160I SCP command: q dasd
07:04:56 HHC00160I SCP command: q osa
07:04:56 HHC00160I SCP command: q set
07:04:56 HHC00160I SCP command: q stor
07:04:56 HHC00160I SCP command: q sys
07:04:56 HHC00160I SCP command: q t
07:04:56 HHC02262I Script 1: processing paused for 1250 milliseconds...
07:04:56 07:04:56 Q E
07:04:56 07:04:56 PRT  000E DRAINED    SYSTEM   CLASS A
07:04:56 07:04:56 PRT  000E FORM STANDARD MANUAL SEP   NO3800  FILEFCB LIMIT NONE
07:04:56 07:04:56 PRT  000E NOFOLD  IMAGE IMAG3211 CHARS A11  FCB FCB1 INDEX 1  LPP 000
07:04:56 07:04:56 PRT  000E DEST OFF      DEST - NONE - DEST - NONE - DEST - NONE -
07:04:56 07:04:56 PRT  000E AFP
07:04:56 07:04:56 Q DASD
07:04:56 07:04:56 DASD 0101 CP OWNED  VMCOM1   12
07:04:56 07:04:56 DASD 0201 CP SYSTEM 630RL1   9
07:04:56 07:04:56 DASD 0301 CP OWNED  M01RES   104
07:04:56 07:04:56 DASD 0901 CP OWNED  M01S01   0
07:04:56 07:04:56 DASD 0902 CP OWNED  M01P01   0
07:04:56 07:04:56 DASD 0903 CP SYSTEM M01W01   0
07:04:56 07:04:56 Q SYS
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0101 ATTACHED CPVOL  0012 VMCOM1
07:04:56 07:04:56 VMSERVP  0311 R/W      , VMSERVP  0310 R/W      , VMSERVP  0309 R/W
07:04:56 07:04:56 VMSERVP  0308 R/W      , VMSERVP  0307 R/W      , VMSERVP  0306 R/W
07:04:56 07:04:56 VMSERVP  0305 R/W      , VMSERVP  0304 R/W      , VMSERVP  0303 R/W
07:04:56 07:04:56 VMSERVP  0301 R/W      , VMSERVP  0302 R/W      , VMSERVP  0191 R/W
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0201 ATTACHED SYSTEM 0009 630RL1
07:04:56 07:04:56 DTCVSW1  0492 R/O      , DTCVSW2  0492 R/O      , TCPIP    0492 R/O
07:04:56 07:04:56 FTPSERVE 0492 R/O      , DTCVSW1  0491 R/O      , DTCVSW2  0491 R/O
07:04:56 07:04:56 TCPIP    0491 R/O      , FTPSERVE 0491 R/O      , EREP     0201 R/O
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0301 ATTACHED CPVOL  0104 M01RES
07:04:56 07:04:56 OPERATOR 0191 R/W      , OPERATOR 0192 R/O      , FTPSERVE 0191 R/W
07:04:56 07:04:56 TCPIP    0191 R/W      , VMSERVR  0307 R/W      , VMSERVR  0306 R/W
07:04:56 07:04:56 VMSERVR  0305 R/W      , DTCVSW1  0191 R/W      , VMSERVU  0305 R/W
07:04:56 07:04:56 VMSERVR  0304 R/W      , DTCVSW2  0191 R/W      , VMSERVU  0304 R/W
07:04:56 07:04:56 VMSERVR  0303 R/W      , DTCVSW2  0198 R/O      , DTCVSW1  0198 R/O
07:04:56 07:04:56 TCPIP    0198 R/O      , FTPSERVE 0198 R/O      , VMSERVU  0303 R/W
07:04:56 07:04:56 VMSERVR  0302 R/W      , DTCVSW2  0592 R/O      , DTCVSW1  0592 R/O
07:04:56 07:04:56 TCPIP    0592 R/O      , FTPSERVE 0592 R/O      , VMSERVU  0302 R/W
07:04:56 07:04:56 VMSERVR  0301 R/W      , DTCVSW2  0591 R/O      , DTCVSW1  0591 R/O
07:04:56 07:04:56 TCPIP    0591 R/O      , FTPSERVE 0591 R/O      , VMSERVU  0301 R/W
07:04:56 07:04:56 VMSERVR  0191 R/W      , VMSERVU  0191 R/W      , VMSERVS  0305 R/W
07:04:56 07:04:56 VMSERVS  0304 R/W      , VMSERVS  0303 R/W      , VMSERVS  0302 R/W
07:04:56 07:04:56 VMSERVS  0301 R/W      , VMSERVS  0191 R/W      , OPERSYMP 0191 R/W
07:04:56 07:04:56 OPERSYMP 0192 R/O      , VMSERVS  0193 R/O      , VMSERVU  0193 R/O
07:04:56 07:04:56 VMSERVR  0193 R/O      , VMSERVP  0193 R/O      , DISKACNT 0191 R/W
07:04:56 07:04:56 EREP     0191 R/W      , DISKACNT 0401 R/O      , OPERSYMP 0401 R/O
07:04:56 07:04:56 VMSERVS  0401 R/O      , VMSERVP  0401 R/O      , DTCVSW2  0401 R/O
07:04:56 07:04:56 VMSERVU  0401 R/O      , DTCVSW1  0401 R/O      , VMSERVR  0401 R/O
07:04:56 07:04:56 TCPIP    0401 R/O      , FTPSERVE 0401 R/O      , OPERATOR 0401 R/O
07:04:56 07:04:56 DISKACNT 0402 R/O      , OPERSYMP 0402 R/O      , VMSERVS  0402 R/O
07:04:56 07:04:56 VMSERVP  0402 R/O      , DTCVSW2  0402 R/O      , VMSERVU  0402 R/O
07:04:56 07:04:56 DTCVSW1  0402 R/O      , VMSERVR  0402 R/O      , TCPIP    0402 R/O
07:04:56 07:04:56 FTPSERVE 0402 R/O      , OPERATOR 0402 R/O      , DISKACNT 019E R/O
07:04:56 07:04:56 OPERSYMP 019E R/O      , VMSERVS  019E R/O      , VMSERVP  019E R/O
07:04:56 07:04:56 DTCVSW2  019E R/O      , VMSERVU  019E R/O      , DTCVSW1  019E R/O
07:04:56 07:04:56 VMSERVR  019E R/O      , TCPIP    019E R/O      , FTPSERVE 019E R/O
07:04:56 07:04:56 OPERATOR 019E R/O      , DISKACNT 019D R/O      , OPERSYMP 019D R/O
07:04:56 07:04:56 VMSERVS  019D R/O      , VMSERVP  019D R/O      , DTCVSW2  019D R/O
07:04:56 07:04:56 VMSERVU  019D R/O      , DTCVSW1  019D R/O      , VMSERVR  019D R/O
07:04:56 07:04:56 TCPIP    019D R/O      , FTPSERVE 019D R/O      , OPERATOR 019D R/O
07:04:56 07:04:56 EREP     0190 R/O      , DISKACNT 0190 R/O      , OPERSYMP 0190 R/O
07:04:56 07:04:56 VMSERVS  0190 R/O      , VMSERVP  0190 R/O      , DTCVSW2  0190 R/O
07:04:56 07:04:56 VMSERVU  0190 R/O      , DTCVSW1  0190 R/O      , VMSERVR  0190 R/O
07:04:56 07:04:56 TCPIP    0190 R/O      , FTPSERVE 0190 R/O      , OPERATOR 0190 R/O
07:04:56 07:04:56 SYSTEM   0003 R/O      , SYSTEM   0001 R/O
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0901 ATTACHED CPVOL  0000 M01S01
07:04:56 07:04:56 DASD MDISKS NOT FOUND
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0902 ATTACHED CPVOL  0000 M01P01
07:04:56 07:04:56 DASD MDISKS NOT FOUND
07:04:56 07:04:56  
07:04:56 07:04:56 DASD 0903 ATTACHED SYSTEM 0000 M01W01
07:04:56 07:04:56 DASD MDISKS NOT FOUND
07:04:56 07:04:56 Q T
07:04:56 07:04:56 TIME IS 07:04:56 PST SUNDAY 11/12/17
07:04:56 07:04:56 CONNECT= 00:00:59 VIRTCPU= 000:00.00 TOTCPU= 000:00.07
07:04:57 HHC02263I Script 1: processing resumed...
07:04:57 HHC01603I *
07:04:57 HHC01603I *
07:04:57 HHC01603I *
07:04:57 HHC01603I cmdsep off
07:04:57 HHC02204I CMDSEP         set to OFF
07:04:57 HHC01603I *
07:04:57 HHC01603I * *********************************************************************
07:04:57 HHC01603I * *********************************************************************
07:04:57 HHC01603I * ***********************     END TEST     ****************************
07:04:57 HHC01603I * *********************************************************************
07:04:57 HHC01603I * *********************************************************************
07:04:57 HHC02264I Script 1: file C:/Users/Fish/HercGUI/Configuration Files/scripts/cmdsep.rc.txt processing ended

As you can see, several commands were skipped/missed (not processed by the guest).

As I explained, this may be correct behavior. I don't know. More research is needed.

I am simply creating this GitHub "Issue" for the benefit of others and so I don't forget to look into the "problem" in case it actually is a problem.

Fish-Git commented 6 years ago

Closing due to lack of comments/interest.