Intermittent failure of Hercules to successfully launch the print to pipe subprocess

[wpappas]

Hercules intermittently fails to successfully launch a print to pipe sub process. This is not specific to the guest OS Hercules is running as it occurs pre-IPL.

Relevant configuration command: "attach 000E 3203 "|prtspool ./prt00e prt2pdf"" or something similar.
When the above fails the console does not report the pid, i.e. no "0:000E Printer: pipe receiver with pid xxxxx starting" but will say something like " 0:000E Printer: pipe receiver with pid xxxxx terminating" on detach. It will also report "Error 4 running "<name>": Program interrupted" on shutdown and leave dangling processes running on the system.

Hercules version 4.8.0.11474-SDL-gf7c6a3db running on Linux.

If I had a sure fire way to make this happen consistently I would report it, but unfortunately it is hit or miss.

[wpappas]

OK -- here is an interesting update. Once the command fails it will continue failing unless I format the command as "attach 000E 3203 "| prtspool ./prt00e prt2pdf"" (note the added space between the pipe and the command). Then it seems to magically work!

[Fish-Git]

Configuration file?
Log file?
Procedure to reproduce for ourselves?

• SUBMITTING PROBLEM REPORTS (i.e. "How to Ask for Help")

[wpappas]

Configuration file can be pretty spartan since it's only the attaching of the spool pipe that is acting up. Let me try to come up with a fairly simple configuration that tends to reproduce this more regularly and then I'll post all the goods, but I do think the relevant info as to what Herc is doing was captured in my initial post. Namely:

1. No Herc console reply of "0:000E Printer: pipe receiver with pid xxxxx starting" on attach
2. The Herc console does reply " 0:000E Printer: pipe receiver with pid xxxxx terminating" on detach though
3. On shutdown we get a "Error 4 running "<name>": Program interrupted"

All of this happens pre IPL of any actual guest OS.

[agadsby]

My guess is that a previously started version of Hercules running against the same TCP ports is still running. This would create the intermittent behaviour you are seeing. Check using a netstat if the port is free before starting Hercules or after a failed IPL - if busy you have the reason. Andy

[wpappas]

My guess is that a previously started version of Hercules running against the same TCP ports is still running. This would create the intermittent behaviour you are seeing. Check using a netstat if the port is free before starting Hercules or after a failed IPL - if busy you have the reason. Andy

Print to pipe does not bind to any TCP port, so I do not think that is happening. You were probably thinking of print to socket.

[wpappas]

Configuration file? Log file? Procedure to reproduce for ourselves?

• SUBMITTING PROBLEM REPORTS (i.e. "How to Ask for Help")

OK, attached is a simple configuration file and the console log. You'll see in the log that Herc only created the print thread for device 000F. Although the log does not show it, Herc does not shutdown properly leaves a process running on the system after exit

• console.log
• hercules.cnf.txt

[Fish-Git]

Your log file is incomplete. Please remove the LOG console.log statement from your configuration file, and use the -o option on your command line instead.:

• https://sdl-hercules-390.github.io/html/hercinst.html#arguments

Then re-post your log file so we can see ALL of it.

[wpappas]

Your log file is incomplete. Please remove the LOG console.log statement from your configuration file, and use the -o option on your command line instead.:

* https://sdl-hercules-390.github.io/html/hercinst.html#arguments

Then re-post your log file so we can see ALL of it.

Sure thing. Attached.

• console.log

[Fish-Git]

Sure thing. Attached.

• console.log

Thank you.

[wpappas]

Sure thing. Attached.

• console.log

Thank you.

You'll see in the log that this time Herc only started the pipe for 00E. The process left running after exit is what Herc thinks it was terminating for 00F (47006) if that helps.

[Fish-Git]

Well, from what I'm seeing, both print to pipe sub processes ARE being created, as clearly evidenced by the two shutdown messages:

23:52:05 HHC01107I 0:000E Printer: pipe receiver with pid 47004 terminating
23:52:05 HHC01107I 0:000F Printer: pipe receiver with pid 47006 terminating

Both of their creations are not being logged however.

I am only seeing the first one being logged. The second one, for some as-yet unknown reason, is not being properly logged. I see only one HHC01106I starting... instead of two, but I'm seeing two (i.e. BOTH) of the HHC01107I terminating... messages.

I don't know what is causing it since you're using Linux which uses fork for such things, and fork is a complete mystery to me, just as Hercules's dupplicating of files descriptors during such forking is, so I unfortunately don't know how to fix your problem.   :-(

But you could try something for me to see if it's maybe timing related. Try inserting a pause 1 statement between your two printer device statements, i.e:

000E    3203    "| tail -f >/dev/null"
pause 1
000F    3203    "| tail -f >/dev/null"

Try that and let us know whether or not that maybe causes both "starting" messages to get logged.

Thanks.

[wpappas]

Well, from what I'm seeing, both print to pipe sub processes ARE being created, as clearly evidenced by the two shutdown messages:

23:52:05 HHC01107I 0:000E Printer: pipe receiver with pid 47004 terminating
23:52:05 HHC01107I 0:000F Printer: pipe receiver with pid 47006 terminating

Both of their creations are not being logged however.

They are NOT both being created as is evidenced by the fact the the system only shows one "tail -f" process running after Herc startup.

I'll run with the pause to see if that changes anything. Also the "zombie" process left after shutdown indicates that somehow Herc lost control of what it tried to spawn.

UPDATE -- on the first test with pause, both pipes were logged as being created, and were in fact actually created,