Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8314060

nsk/jdi/ExceptionEvent/_itself_/exevent008 failed with "Connection for PipeIO Listener Thread at port 50998 wasn't accepted in 300000ms"

XMLWordPrintable

    • x86_64
    • os_x

      The following test failed in the JDK21 CI:

      vmTestbase/nsk/jdi/ExceptionEvent/_itself_/exevent008/TestDescription.java

      Here's a snippet from the log file:

      #section:main
      ----------messages:(6/1080)----------
      command: main nsk.jdi.ExceptionEvent._itself_.exevent008 -verbose -arch=mac-x64 -waittime=5 -debugee.vmkind=java -transport.address=dynamic -debugee.vmkeys="-XX:MaxRAMPercentage=4.16667 -Dtest.boot.jdk=/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk/20/36/bundles/macos-x64/jdk-20_macos-x64_bin.tar.gz/jdk-20.jdk/Contents/Home -Djava.io.tmpdir=/System/Volumes/Data/mesos/work_dir/slaves/cd627e65-f015-4fb1-a1d2-b6c9b8127f98-S127009/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/8573e6af-779e-4d0c-9312-746d1c9f54db/runs/99db2830-cbe9-4460-8774-9704949dc665/testoutput/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_nsk_jdi/tmp -XX:+UseSerialGC -Xcomp"
      reason: User specified action: run main/othervm nsk.jdi.ExceptionEvent._itself_.exevent008 -verbose -arch=${os.family}-${os.simpleArch} -waittime=5 -debugee.vmkind=java -transport.address=dynamic -debugee.vmkeys="${test.vm.opts} ${test.java.opts}"
      started: Mon Aug 07 13:10:12 GMT 2023
      Mode: othervm [/othervm specified]
      finished: Mon Aug 07 13:16:07 GMT 2023
      elapsed time (seconds): 354.587
      ----------configuration:(0/0)----------
      ----------System.out:(211/9133)*----------
      binder> VirtualMachineManager: version 21.0
      binder> Finding connector: default
      binder> LaunchingConnector:
      binder> name: com.sun.jdi.CommandLineLaunch
      binder> description: Launches target using Sun Java VM command line and attaches to it
      binder> transport: com.sun.tools.jdi.SunCommandLineLauncher$2@68233f61
      binder> Connector arguments:
      binder> main=nsk.jdi.ExceptionEvent._itself_.exevent008t \u0000-verbose\u0000 \u0000-arch=mac-x64\u0000 \u0000-waittime=5\u0000 \u0000-debugee.vmkind=java\u0000 \u0000-transport.address=dynamic\u0000 \u0000-debugee.vmkeys="-XX:MaxRAMPercentage=4.16667 -Dtest.boot.jdk=/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk/20/36/bundles/macos-x64/jdk-20_macos-x64_bin.tar.gz/jdk-20.jdk/Contents/Home -Djava.io.tmpdir=/System/Volumes/Data/mesos/work_dir/slaves/cd627e65-f015-4fb1-a1d2-b6c9b8127f98-S127009/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/8573e6af-779e-4d0c-9312-746d1c9f54db/runs/99db2830-cbe9-4460-8774-9704949dc665/testoutput/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_nsk_jdi/tmp -XX:+UseSerialGC -Xcomp"\u0000 \u0000-pipe.port=50998\u0000
      binder> includevirtualthreads=y
      binder> quote=\u0000
      binder> home=/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk-21+34-2497/macosx-x64-debug.jdk/jdk-21/fastdebug
      binder> vmexec=java
      binder> suspend=true
      binder> options=-XX:MaxRAMPercentage=4.16667 -Dtest.boot.jdk=/System/Volumes/Data/mesos/work_dir/jib-master/install/jdk/20/36/bundles/macos-x64/jdk-20_macos-x64_bin.tar.gz/jdk-20.jdk/Contents/Home -Djava.io.tmpdir=/System/Volumes/Data/mesos/work_dir/slaves/cd627e65-f015-4fb1-a1d2-b6c9b8127f98-S127009/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/8573e6af-779e-4d0c-9312-746d1c9f54db/runs/99db2830-cbe9-4460-8774-9704949dc665/testoutput/test-support/jtreg_open_test_hotspot_jtreg_vmTestbase_nsk_jdi/tmp -XX:+UseSerialGC -Xcomp
      binder> Launching debugee
      binder> Waiting for VM initialized
      Initial VMStartEvent received: VMStartEvent in thread main
      Resuming debuggee
      IOPipe> Caught InterruptedIOException. Wait start time: 1691413860760, exception was thrown at: 1691414160966, wait time: 300206, actual timeout: 300000
      # ERROR: IOPipe> Caught InterruptedIOException while listening for PipeIO Listener Thread connection at port 50998:
      # ERROR: java.net.SocketTimeoutException: Accept timed out
      The following stacktrace is for failure analysis.
      nsk.share.TestFailure: IOPipe> Caught InterruptedIOException while listening for PipeIO Listener Thread connection at port 50998: java.net.SocketTimeoutException: Accept timed out
      at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:431)
      at nsk.share.Log.complain(Log.java:402)
      at nsk.share.Log$Logger.complain(Log.java:747)
      at nsk.share.jpda.BasicSocketConnection.accept(SocketConnection.java:173)
      at nsk.share.jpda.SocketConnection.accept(SocketConnection.java:453)
      at nsk.share.jpda.SocketIOPipe$ListenerThread.run(SocketIOPipe.java:228)
      # ERROR: binder> Debugee VM has not exited correctly: trying to kill it
      The following stacktrace is for failure analysis.
      nsk.share.TestFailure: binder> Debugee VM has not exited correctly: trying to kill it
      at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:431)
      at nsk.share.Log.complain(Log.java:402)
      at nsk.share.jpda.DebugeeProcess.complain(DebugeeProcess.java:458)
      at nsk.share.jpda.DebugeeProcess.close(DebugeeProcess.java:438)
      at nsk.share.jpda.DebugeeProcess.cleanup(DebugeeProcess.java:467)
      at nsk.share.Finalizable.finalizeAtExit(Finalizable.java:50)
      at nsk.share.Finalizer$FinalizerThread.run(Finalizer.java:122)
      ------------ Try to print debuggee threads before killing process ------------
      Threads: [instance of java.lang.Thread(name='main', id=1), instance of java.lang.ref.Reference$ReferenceHandler(name='Reference Handler', id=698), instance of java.lang.ref.Finalizer$FinalizerThread(name='Finalizer', id=699), instance of java.lang.Thread(name='Signal Dispatcher', id=700), instance of java.lang.Thread(name='Notification Thread', id=701), instance of jdk.internal.misc.InnocuousThread(name='Common-Cleaner', id=29), instance of jdk.internal.misc.InnocuousThread(name='Cleaner-0', id=702), instance of jdk.internal.misc.InnocuousThread(name='Cleaner-1', id=703)]
      Total threads: 8

      Thread: main
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 22
      Frames:
      sun.nio.ch.SocketDispatcher.read0, line: -1
      sun.nio.ch.SocketDispatcher.read, line: 47
      sun.nio.ch.NioSocketImpl.tryRead, line: 256
      sun.nio.ch.NioSocketImpl.implRead, line: 307
      sun.nio.ch.NioSocketImpl.read, line: 346
      sun.nio.ch.NioSocketImpl$1.read, line: 796
      java.net.Socket$SocketInputStream.read, line: 1099
      java.io.ObjectInputStream$PeekInputStream.read, line: 2915
      java.io.ObjectInputStream$PeekInputStream.readFully, line: 2931
      java.io.ObjectInputStream$BlockDataInputStream.readShort, line: 3428
      java.io.ObjectInputStream.readStreamHeader, line: 985
      java.io.ObjectInputStream.<init>, line: 416
      nsk.share.jpda.SocketConnection.makeSocketStreams, line: 639
      nsk.share.jpda.BasicSocketConnection.onConnected, line: 350
      nsk.share.jpda.SocketConnection.onConnected, line: 559
      nsk.share.jpda.BasicSocketConnection.continueAttach, line: 278
      nsk.share.jpda.SocketConnection.continueAttach, line: 453
      nsk.share.jpda.SocketIOPipe.connect, line: 288
      nsk.share.jpda.IOPipe.connect, line: 99
      nsk.share.jpda.SocketIOPipe.println, line: 178
      nsk.jdi.ExceptionEvent._itself_.exevent008t.communication, line: 80
      nsk.jdi.ExceptionEvent._itself_.exevent008t.main, line: 41

       resume thread


      Thread: Reference Handler
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 3
      Frames:
      java.lang.ref.Reference.waitForReferencePendingList, line: -1
      java.lang.ref.Reference.processPendingReferences, line: 246
      java.lang.ref.Reference$ReferenceHandler.run, line: 208

       resume thread


      Thread: Finalizer
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 7
      Frames:
      java.lang.Object.wait0, line: -1
      java.lang.Object.wait, line: 366
      java.lang.Object.wait, line: 339
      java.lang.ref.NativeReferenceQueue.await, line: 48
      java.lang.ref.ReferenceQueue.remove0, line: 158
      java.lang.ref.NativeReferenceQueue.remove, line: 89
      java.lang.ref.Finalizer$FinalizerThread.run, line: 173

       resume thread


      Thread: Signal Dispatcher
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 0

       resume thread


      Thread: Notification Thread
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 0

       resume thread


      Thread: Common-Cleaner
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 10
      Frames:
      jdk.internal.misc.Unsafe.park, line: -1
      java.util.concurrent.locks.LockSupport.parkNanos, line: 269
      java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await, line: 1847
      java.lang.ref.ReferenceQueue.await, line: 71
      java.lang.ref.ReferenceQueue.remove0, line: 143
      java.lang.ref.ReferenceQueue.remove, line: 218
      jdk.internal.ref.CleanerImpl.run, line: 140
      java.lang.Thread.runWith, line: 1596
      java.lang.Thread.run, line: 1583
      jdk.internal.misc.InnocuousThread.run, line: 186

       resume thread


      Thread: Cleaner-0
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 10
      Frames:
      jdk.internal.misc.Unsafe.park, line: -1
      java.util.concurrent.locks.LockSupport.parkNanos, line: 269
      java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await, line: 1847
      java.lang.ref.ReferenceQueue.await, line: 71
      java.lang.ref.ReferenceQueue.remove0, line: 143
      java.lang.ref.ReferenceQueue.remove, line: 218
      jdk.internal.ref.CleanerImpl.run, line: 140
      java.lang.Thread.runWith, line: 1596
      java.lang.Thread.run, line: 1583
      jdk.internal.misc.InnocuousThread.run, line: 186

       resume thread


      Thread: Cleaner-1
      Is suspended: false
      Is at breakpoint: false

       suspend thread to get its stack

      Stack frame count: 10
      Frames:
      jdk.internal.misc.Unsafe.park, line: -1
      java.util.concurrent.locks.LockSupport.parkNanos, line: 269
      java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await, line: 1847
      java.lang.ref.ReferenceQueue.await, line: 71
      java.lang.ref.ReferenceQueue.remove0, line: 143
      java.lang.ref.ReferenceQueue.remove, line: 218
      jdk.internal.ref.CleanerImpl.run, line: 140
      java.lang.Thread.runWith, line: 1596
      java.lang.Thread.run, line: 1583
      jdk.internal.misc.InnocuousThread.run, line: 186

       resume thread

      ----------------------------------------------------------------------
      binder> Killing debuggee by forcing target VM to exit
      binder> Debugee VM successfully forced to exit
      Killing debugee VM process


      #>
      #> SUMMARY: Following errors occured
      #> during test execution:
      #>
      # ERROR: IOPipe> Caught InterruptedIOException while listening for PipeIO Listener Thread connection at port 50998:
      # ERROR: java.net.SocketTimeoutException: Accept timed out
      # ERROR: binder> Debugee VM has not exited correctly: trying to kill it
      ----------System.err:(9/633)----------
      nsk.share.Failure: Connection for PipeIO Listener Thread at port 50998 wasn't accepted in 300000ms
      at nsk.share.jpda.BasicSocketConnection.accept(SocketConnection.java:174)
      at nsk.share.jpda.SocketConnection.accept(SocketConnection.java:453)
      at nsk.share.jpda.SocketIOPipe$ListenerThread.run(SocketIOPipe.java:228)

      JavaTest Message: Test threw exception: nsk.share.Failure: Connection for PipeIO Listener Thread at port 50998 wasn't accepted in 300000ms
      JavaTest Message: shutting down test

      STATUS:Failed.`main' threw exception: nsk.share.Failure: Connection for PipeIO Listener Thread at port 50998 wasn't accepted in 300000ms
      ----------rerun:(36/8931)*----------


      Near the end of the stdout log section is this sequence:

      Stack frame count: 10
      Frames:
      jdk.internal.misc.Unsafe.park, line: -1
      java.util.concurrent.locks.LockSupport.parkNanos, line: 269
      java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await, line: 1847
      java.lang.ref.ReferenceQueue.await, line: 71
      java.lang.ref.ReferenceQueue.remove0, line: 143
      java.lang.ref.ReferenceQueue.remove, line: 218
      jdk.internal.ref.CleanerImpl.run, line: 140
      java.lang.Thread.runWith, line: 1596
      java.lang.Thread.run, line: 1583
      jdk.internal.misc.InnocuousThread.run, line: 186

       resume thread

      ----------------------------------------------------------------------
      binder> Killing debuggee by forcing target VM to exit
      binder> Debugee VM successfully forced to exit
      Killing debugee VM process

      I find myself wondering if the debugger ran off the end of the test
      and that's why it was "Killing debuggee by forcing target VM to exit"
      and the same time that the debugger thread was trying to exit.

      Do we have a debugger/debuggee race here?

      Also why would we be trying to open a new PipeIO at what is
      probably the end of the test?

            Unassigned Unassigned
            dcubed Daniel Daugherty
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated: