MarkdownProcessingException: -559038737 exit code

[vorburger]

https://github.com/enola-dev/enola/actions/runs/4930857308/jobs/8812290180?pr=162 for (trivial!) #162 failed 😢 with:

./enola execmd -i /home/runner/work/enola/enola/docs/use/docgen/index.md ...
2023-05-09 22:05:26 INFO ch.vorburger.exec.ManagedProcess startPreparation Starting Program [/usr/bin/env, bash, -c, cd .././.././.. && ./enola docgen --model file:docs/use/library/model.textproto --diagram=mermaid >docs/use/docgen/docgen.md] (in working directory /home/runner/work/enola/enola/docs/use/docgen)
2023-05-09 22:05:26 INFO ch.vorburger.exec.ManagedProcess waitForExitMaxMs Thread is now going to wait max. 7000ms for process to terminate itself: Program [/usr/bin/env, bash, -c, cd .././.././.. && ./enola docgen --model file:docs/use/library/model.textproto --diagram=mermaid >docs/use/docgen/docgen.md] (in working directory /home/runner/work/enola/enola/docs/use/docgen)
2023-05-09 22:05:28 INFO ch.vorburger.exec.LoggingExecuteResultHandler onProcessComplete Program [/usr/bin/env, bash, -c, cd .././.././.. && ./enola docgen --model file:docs/use/library/model.textproto --diagram=mermaid >docs/use/docgen/docgen.md] (in working directory /home/runner/work/enola/enola/docs/use/docgen) just exited, with value 0
dev.enola.common.markdown.exec.MarkdownProcessingException: exec failed: cd .././.././.. && ./enola docgen --model file:docs/use/library/model.textproto --diagram=mermaid >docs/use/docgen/docgen.md

	at dev.enola.common.markdown.exec.ExecMD.exec(ExecMD.java:160)
	at dev.enola.common.markdown.exec.ExecMD.process(ExecMD.java:103)
	at dev.enola.common.markdown.exec.ExecMD.process(ExecMD.java:48)
	at dev.enola.common.markdown.exec.ExecMD.process(ExecMD.java:40)
	at dev.enola.cli.ExecMdCommand.call(ExecMdCommand.java:48)
	at dev.enola.cli.ExecMdCommand.call(ExecMdCommand.java:28)
	at picocli.CommandLine.executeUserObject(CommandLine.java:2041)
	at picocli.CommandLine.access$1500(CommandLine.java:148)
	at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2461)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2453)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2415)
	at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2273)
	at picocli.CommandLine$RunLast.execute(CommandLine.java:2417)
	at dev.enola.cli.LoggingMixin.executionStrategy(LoggingMixin.java:63)
	at picocli.CommandLine.execute(CommandLine.java:2170)
	at dev.enola.cli.CLI.execute(CLI.java:71)
	at dev.enola.cli.Enola.main(Enola.java:65)
Caused by: dev.enola.common.markdown.exec.MarkdownProcessingException: -559038737 exit code (use ```bash $? marker if that's expected): cd .././.././.. && ./enola docgen --model file:docs/use/library/model.textproto --diagram=mermaid >docs/use/docgen/docgen.md

	at dev.enola.common.markdown.exec.ExecMD.exec(ExecMD.java:149)
	... 16 more

Error: Process completed with exit code 123.

[vorburger]

A subsequent re-build of the same PR #162 without changes passed - so this is a flaky 😭 exec.

https://stackoverflow.com/questions/23370449/jvm-8-exit-code-559038737-0xdeadbeef points out that -559038737 is the INVALID_EXITVALUE = 0xdeadbeef of Apache Commons Exec (which is currently used internally; I also prepared have an alternative exec implementation - which is not yet used).

vorburger/ch.vorburger.exec#9 from (my) vorburger.exec (which the aforementioned current implementation is using) had a similar issue... but there it was a little bit more clear, with an IOException: Cannot run program "ansible-runner" (in directory "."): error=2, No such file or directory) which is somehow lost (swallowed?) here.

It would be good if (a) that IOException was logged, to be sure it's due to a No such file or directory, and (b) if the problem didn't occur in the first place... How can ./enola not exist - if we just built it?!

If this happens more often, one approach could be to finish the implementation of the alternative exec strategy, to see if that's better.

[vorburger]

Actually, no... the initial analysis above is wrong. This is a bug in Enola, maybe a concurency issue? Note how it first logs:

INFO LoggingExecuteResultHandler onProcessComplete Program [...] () just exited, with value 0

but then

-559038737 exit code

which is clearly inconsistent.

[vorburger]

#165 fixes the misleading diagnostics. It doesn't fix the error that happened on this build, but next time something much clearer will be logged. -- The root cause was that hack in VorburgerExecRunner... I'm leaving this issue open to remind myself to properly implement vorburger/ch.vorburger.exec#45, release that, bump to it, and remove that hack (and the fix for the hack which introduced by #165).

[vorburger]

It doesn't fix the error that happened on this build, but next time something much clearer will be logged.

Voilà, I just hit this again, this time locally, not on CI:

$ tools/docs/serve-build.bash

(...)

./enola execmd -i /home/vorburger/git/github.com/vorburger/enola/docs/use/get/index.md ...
2023-05-12 19:32:42 INFO ch.vorburger.exec.ManagedProcess startPreparation Starting Program [/usr/bin/env, bash, -c, cd .././.././.. && ./enola get --model file:docs/use/library/model.yaml demo.book/ABC/0-13-140731-7/1] (in working directory /home/vorburger/git/github.com/vorburger/enola/docs/use/get)
2023-05-12 19:32:43 INFO ch.vorburger.exec.ManagedProcess waitForExitMaxMs Thread is now going to wait max. 7000ms for process to terminate itself: Program [/usr/bin/env, bash, -c, cd .././.././.. && ./enola get --model file:docs/use/library/model.yaml demo.book/ABC/0-13-140731-7/1] (in working directory /home/vorburger/git/github.com/vorburger/enola/docs/use/get)
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: id {
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   ns: "demo"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   entity: "book"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   paths: "ABC"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   paths: "0-13-140731-7"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   paths: "1"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: }
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: ts {
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   seconds: 1683912764
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   nanos: 132575000
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: }
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: related {
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   key: "kind"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   value {
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:     ns: "demo"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:     entity: "book_kind"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:     paths: "0-13-140731-7"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   }
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: }
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: related {
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   key: "library"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   value {
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:     ns: "demo"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:     entity: "library"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:     paths: "ABC"
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:   }
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env: }
2023-05-12 19:32:44 INFO ch.vorburger.exec.SLF4jLogOutputStream processLine env:
2023-05-12 19:32:44 INFO ch.vorburger.exec.LoggingExecuteResultHandler onProcessComplete Program [/usr/bin/env, bash, -c, cd .././.././.. && ./enola get --model file:docs/use/library/model.yaml demo.book/ABC/0-13-140731-7/1] (in working directory /home/vorburger/git/github.com/vorburger/enola/docs/use/get) just exited, with value 0
dev.enola.common.markdown.exec.MarkdownProcessingException: exec failed: cd .././.././.. && ./enola get --model file:docs/use/library/model.yaml demo.book/ABC/0-13-140731-7/1

        at dev.enola.common.markdown.exec.ExecMD.exec(ExecMD.java:160)
        at dev.enola.common.markdown.exec.ExecMD.process(ExecMD.java:103)
        at dev.enola.common.markdown.exec.ExecMD.process(ExecMD.java:48)
        at dev.enola.common.markdown.exec.ExecMD.process(ExecMD.java:40)
        at dev.enola.cli.ExecMdCommand.call(ExecMdCommand.java:48)
        at dev.enola.cli.ExecMdCommand.call(ExecMdCommand.java:28)
        at picocli.CommandLine.executeUserObject(CommandLine.java:2041)
        at picocli.CommandLine.access$1500(CommandLine.java:148)
        at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2461)
        at picocli.CommandLine$RunLast.handle(CommandLine.java:2453)
        at picocli.CommandLine$RunLast.handle(CommandLine.java:2415)
        at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2273)
        at picocli.CommandLine$RunLast.execute(CommandLine.java:2417)
        at dev.enola.cli.LoggingMixin.executionStrategy(LoggingMixin.java:63)
        at picocli.CommandLine.execute(CommandLine.java:2170)
        at dev.enola.cli.CLI.execute(CLI.java:71)
        at dev.enola.cli.Enola.main(Enola.java:65)
Caused by: dev.enola.common.markdown.exec.MarkdownProcessingException: -559038737 exit code (use ```bash $? marker if that's expected): cd .././.././.. && ./enola get --model file:docs/use/library/model.yaml demo.book/ABC/0-13-140731-7/1

        at dev.enola.common.markdown.exec.ExecMD.exec(ExecMD.java:149)
        ... 16 more

xargs: sh: exited with status 255; aborting

Not reproducible, and works 2nd time. So a concurrency issue, after all? Missing volatile?

[vorburger]

Actually... this will happen in case of the (7s) timeout! But this error message is too confusing, and needs to be improved.