jpackage tests may potentially deadlock

XMLWordPrintable

    • Type: Bug
    • Resolution: Unresolved
    • Priority: P3
    • 27
    • Affects Version/s: 17, 21, 25, 26
    • Component/s: tools
    • Fix Understood
    • generic
    • generic

      Running tests for JDK-8373710 fix cause consistent WinResourceTest timeouts:

      ---
      [23:05:00.037] Parsing [--jpt-run=WinResourceTest]...
      [23:05:00.082] WinResourceTest -> [public void WinResourceTest.test() throws java.io.IOException]
      [23:05:00.111] Create: WinResourceTest(main.wxs, Using custom package resource [Main WiX project file]).test
      [23:05:00.112] Create: WinResourceTest(overrides.wxi, Using custom package resource [Overrides WiX project file]).test
      [23:05:00.119] [ RUN ] WinResourceTest(main.wxs, Using custom package resource [Main WiX project file]).test
      [23:05:00.441] TRACE: Bundler msi enabled
      [23:05:00.441] TRACE: Bundler exe enabled
      [23:05:00.451] TRACE: Actions: [[initialize], [create], [unpack], [verify-install], [finalize]]
      [23:05:00.478] TRACE: Create [test.69e03869\resources\main.wxs] text file...
      [23:05:00.478] TRACE: any string that is an invalid WiX source file
      [23:05:00.482] TRACE: Done
      [23:05:00.507] TRACE: exec: Execute tool provider [javac -d test.69e03869\jar-workdir --release 11 src.full\open\test\jdk\tools\jpackage\apps\Hello.java](6); discard out+err...
      [23:05:01.240] TRACE: exec: Done. Exit code: 0
      [23:05:01.243] TRACE: assertEquals(0): Check command tool provider [javac -d test.69e03869\jar-workdir --release 11 src.full\open\test\jdk\tools\jpackage\apps\Hello.java](6) exited with 0 code
      [23:05:01.245] TRACE: exec: Execute tool provider [jar -c -f test.69e03869\input\hello.jar -C test.69e03869\jar-workdir .](7); discard out+err...
      [23:05:01.293] TRACE: exec: Done. Exit code: 0
      [23:05:01.293] TRACE: assertEquals(0): Check command tool provider [jar -c -f test.69e03869\input\hello.jar -C test.69e03869\jar-workdir .](7) exited with 0 code
      [23:05:01.297] TRACE: Init fake runtime in [test.69e03869\fake_runtime] directory
      [23:05:01.305] TRACE: Files in [test.69e03869\resources] resource dir:
      [23:05:01.306] TRACE: [main.wxs]
      [23:05:01.306] TRACE: Done
      [23:05:01.317] TRACE: exec: Execute [jdk-27\bin\jpackage.exe --input test.69e03869\input --dest test.69e03869\output --name WinResourceTest --type msi --main-jar hello.jar --main-class Hello --win-console --resource-dir test.69e03869\resources --runtime-image test.69e03869\fake_runtime -J-Djlink.debug=true --verbose](20); save out+err; inherit out+err...
      [23:28:59.845] Timeout signalled after 1440 seconds
      ---

      A fragment of the main thread dump:
      ---
                   "java.base\/java.io.FileInputStream.readBytes(Native Method)",
                    "java.base\/java.io.FileInputStream.read(FileInputStream.java:281)",
                    "java.base\/java.lang.Process$PipeInputStream.read(Process.java:1116)",
                    "java.base\/java.io.BufferedInputStream.read1(BufferedInputStream.java:328)",
                    "java.base\/java.io.BufferedInputStream.read(BufferedInputStream.java:388)",
                    "java.base\/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:279)",
                    "java.base\/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:322)",
                    "java.base\/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:186)",
                    "java.base\/java.io.InputStreamReader.read(InputStreamReader.java:183)",
                    "java.base\/java.io.BufferedReader.fill(BufferedReader.java:166)",
                    "java.base\/java.io.BufferedReader.readLine(BufferedReader.java:333)",
                    "java.base\/java.io.BufferedReader.readLine(BufferedReader.java:400)",
                    "java.base\/java.io.BufferedReader$1.hasNext(BufferedReader.java:575)",
                    "java.base\/java.util.Iterator.forEachRemaining(Iterator.java:132)",
                    "java.base\/java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1939)",
                    "java.base\/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:570)",
                    "java.base\/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:560)",
                    "java.base\/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:635)",
                    "java.base\/java.util.stream.AbstractPipeline.evaluateToArrayNode(AbstractPipeline.java:291)",
                    "java.base\/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:652)",
                    "java.base\/java.util.stream.ReferencePipeline.toArray(ReferencePipeline.java:658)",
                    "java.base\/java.util.stream.ReferencePipeline.toList(ReferencePipeline.java:663)",
                    "jdk.jpackage.test.Executor.processProcessStream(Executor.java:514)",
                    "jdk.jpackage.test.Executor.runExecutable(Executor.java:469)",
                    "jdk.jpackage.test.Executor.lambda$executeWithoutExitCodeCheck$0(Executor.java:284)",
                    "jdk.jpackage\/jdk.jpackage.internal.util.function.ThrowingSupplier.lambda$toSupplier$0(ThrowingSupplier.java:37)",
                    "jdk.jpackage.test.Executor.executeWithoutExitCodeCheck(Executor.java:288)",
                    "jdk.jpackage.test.Executor.execute(Executor.java:292)",
                    "jdk.jpackage.test.JPackageCommand.execute(JPackageCommand.java:987)",
                    "jdk.jpackage.test.JPackageCommand.execute(JPackageCommand.java:934)",
                    "jdk.jpackage.test.PackageTest$Handler.processAction(PackageTest.java:729)",
                    "jdk.jpackage.test.PackageTest$PackageTypePipeline.accept(PackageTest.java:579)",
                    "jdk.jpackage.test.PackageTest$PackageTypePipeline.accept(PackageTest.java:512)",
                    "java.base\/java.util.ImmutableCollections$List12.forEach(ImmutableCollections.java:680)",
                    "jdk.jpackage.test.PackageTest.lambda$runActions$1(PackageTest.java:486)",
                    "java.base\/java.util.ArrayList.forEach(ArrayList.java:1612)",
                    "jdk.jpackage.test.PackageTest.lambda$runActions$0(PackageTest.java:485)",
                    "java.base\/java.lang.Iterable.forEach(Iterable.java:75)",
                    "jdk.jpackage.test.PackageTest.runActions(PackageTest.java:484)",
                    "jdk.jpackage.test.RunnablePackageTest.run(RunnablePackageTest.java:58)",
                    "WinResourceTest.test(WinResourceTest.java:103)",
      ---

      jdk.jpackage.test.Executor.runExecutable() calls jdk.jpackage.test.Executor.processProcessStream() to read the started subprocess's output streams [1]. processProcessStream() is called sequentially for stdout, then for stderr, before Process.waitFor() is called. This is wrong. Instead, stdout and stderr should be pumped concurrently. Surprisingly, this bug has been sitting unnoticed for quite a long time and didn't manifest even in sporadic hangs.

      Minor change to jpackage's error reporting in JDK-8373710 revealed the issue. After changing Executor.runExecutable() to pump a subprocess's output streams concurrently, the timeouts in the WinResourceTest test were resolved.

      The issue doesn't impact jpackage as it uses different code to process output from subprocesses. Only tests are affected.

      [1] https://github.com/openjdk/jdk/blob/9862f8f0d351448803f8930333d5a7286e6c3565/test/jdk/tools/jpackage/helpers/jdk/jpackage/test/Executor.java#L469

            Assignee:
            Alexey Semenyuk
            Reporter:
            Alexey Semenyuk
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated: