JDK-8298043 : jdk/jfr/api/consumer/recordingstream/TestStop.java failed with "Expected outer stream to have 3 events"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: jfr
  • Affected Version: 20
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: linux
  • CPU: x86_64
  • Submitted: 2022-12-02
  • Updated: 2024-06-10
  • Resolved: 2022-12-05
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 20
20 b27Fixed
Related Reports
Relates :  
JDK-8333929 - jdk/jfr/api/consumer/recordingstream/TestStop.java failed with "Expected outer stream to have 3 events"
Relates :  
JDK-8304732 - jdk/jfr/api/consumer/recordingstream/TestStop.java failed again with "Expected outer stream to have 3 events"
Sub Tasks
JDK-8298054 :  
ProblemList jdk/jfr/api/consumer/recordingstream/TestStop.java - Resolved
Description
The following test failed in the JDK20 CI:

jdk/jfr/api/consumer/recordingstream/TestStop.java

Here's a snippet from the log file:

#section:main
----------messages:(7/369)----------
command: main jdk.jfr.api.consumer.recordingstream.TestStop
reason: User specified action: run main/othervm jdk.jfr.api.consumer.recordingstream.TestStop 
started: Fri Dec 02 14:19:47 UTC 2022
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules jdk.jfr,java.management
finished: Fri Dec 02 14:19:47 UTC 2022
elapsed time (seconds): 0.618
----------configuration:(3/51)----------
Boot Layer
  add modules: jdk.jfr java.management

----------System.out:(62/2409)----------
RecordingStream outer:
[jdk.jfr.api.consumer.recordingstream.TestStop$MarkEvent {
  startTime = 14:19:47.853 (2022-12-02)
  duration = 0.209 ms
  id = "a"
  eventThread = "MainThread" (javaThreadId = 21)
  stackTrace = [
    jdk.jfr.api.consumer.recordingstream.TestStop.testNestedStop() line: 118
    jdk.jfr.api.consumer.recordingstream.TestStop.main(String[]) line: 57
    jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 104
    java.lang.reflect.Method.invoke(Object, Object[]) line: 578
    com.sun.javatest.regtest.agent.MainWrapper$MainThread.run() line: 125
  ]
}

, jdk.jfr.api.consumer.recordingstream.TestStop$MarkEvent {
  startTime = 14:19:47.876 (2022-12-02)
  duration = 0.0435 ms
  id = "b"
  eventThread = "MainThread" (javaThreadId = 21)
  stackTrace = [
    jdk.jfr.api.consumer.recordingstream.TestStop.testNestedStop() line: 127
    jdk.jfr.api.consumer.recordingstream.TestStop.main(String[]) line: 57
    jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 104
    java.lang.reflect.Method.invoke(Object, Object[]) line: 578
    com.sun.javatest.regtest.agent.MainWrapper$MainThread.run() line: 125
  ]
}

, jdk.jfr.api.consumer.recordingstream.TestStop$MarkEvent {
  startTime = 14:19:47.890 (2022-12-02)
  duration = 0.0450 ms
  id = "c"
  eventThread = "MainThread" (javaThreadId = 21)
  stackTrace = [
    jdk.jfr.api.consumer.recordingstream.TestStop.testNestedStop() line: 133
    jdk.jfr.api.consumer.recordingstream.TestStop.main(String[]) line: 57
    jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 104
    java.lang.reflect.Method.invoke(Object, Object[]) line: 578
    com.sun.javatest.regtest.agent.MainWrapper$MainThread.run() line: 125
  ]
}

]
RecordingStream inner:
[jdk.jfr.api.consumer.recordingstream.TestStop$MarkEvent {
  startTime = 14:19:47.876 (2022-12-02)
  duration = 0.0435 ms
  id = "b"
  eventThread = "MainThread" (javaThreadId = 21)
  stackTrace = [
    jdk.jfr.api.consumer.recordingstream.TestStop.testNestedStop() line: 127
    jdk.jfr.api.consumer.recordingstream.TestStop.main(String[]) line: 57
    jdk.internal.reflect.DirectMethodHandleAccessor.invoke(Object, Object[]) line: 104
    java.lang.reflect.Method.invoke(Object, Object[]) line: 578
    com.sun.javatest.regtest.agent.MainWrapper$MainThread.run() line: 125
  ]
}

]
Outer count: 3
Inner count: 1
----------System.err:(12/775)----------
java.lang.AssertionError: Expected outer stream to have 3 events
	at jdk.jfr.api.consumer.recordingstream.TestStop.testNestedStop(TestStop.java:153)
	at jdk.jfr.api.consumer.recordingstream.TestStop.main(TestStop.java:57)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125)
	at java.base/java.lang.Thread.run(Thread.java:1599)

JavaTest Message: Test threw exception: java.lang.AssertionError: Expected outer stream to have 3 events
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.AssertionError: Expected outer stream to have 3 events
----------rerun:(38/8002)*----------
Comments
Changeset: 9827b75c Author: Erik Gahlin <egahlin@openjdk.org> Date: 2022-12-05 20:40:35 +0000 URL: https://git.openjdk.org/jdk/commit/9827b75c451100d2d5f3e068a8758468fd9189e0
05-12-2022
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/11517 Date: 2022-12-05 17:29:30 +0000
05-12-2022
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/11495 Date: 2022-12-03 04:02:59 +0000
03-12-2022
[~egahlin] and I updated the bug at the same time and my update erased the "Cause Known" setting so I'm putting it back.
03-12-2022
I understand why it happens. It's a race that results in the value becoming 1 or 2 most of the time. Together with a test bug, this was able to pass testing. Doesn't look too hard to fix, a couple of hours, but if it becomes a nuisance we can problem list it.
03-12-2022
The test is broken. Should be: if (outerCount.get() != 3) { throw new AssertionError("Expected outer stream to have 3 events"); } I don't understand how this happened, but seems like a product bug and a test bug at the same time. Similar problem exists in TestStop for RemoteRecordingStream.
02-12-2022