8276208: vmTestbase/nsk/jdb/repeat/repeat001/repeat001.java fails with "AssertionError: Unexpected output"

[jakobcornell]

This will fix a few issues with the tests added in #5290:

• intermittent failures
• tests should use failure method to report problems rather than throwing AssertionError

---

Progress

• Change must not contain extraneous whitespace
• Commit message must refer to an issue
• Change must be properly reviewed

Issue

• JDK-8276208: vmTestbase/nsk/jdb/repeat/repeat001/repeat001.java fails with "AssertionError: Unexpected output"

Reviewers

• Chris Plummer (@plummercj - Reviewer)
• Ioi Lam (@iklam - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/6182/head:pull/6182
$ git checkout pull/6182

Update a local copy of the PR:
$ git checkout pull/6182
$ git pull https://git.openjdk.java.net/jdk pull/6182/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 6182

View PR using the GUI difftool:
$ git pr show -t 6182

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/6182.diff

[bridgekeeper]

👋 Welcome back jakobcornell! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

[openjdk]

@jakobcornell The following label will be automatically applied to this pull request:

• serviceability

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

[jakobcornell]

I'm not sure whether this is expected to be a platform-specific bug, but I've been assuming it is since I've never seen the failure on my Linux system.

I started with the Windows failure and noticed that the JDB loop mechanism doesn't seem to be working:

Sending command: 2 2 up
reply[0]: End of stack.
reply[1]: main[1]

That would seem to be the cause of the "Unexpected output" error, but I can't reproduce the behavior manually on the x86-64 Windows system I have access to. With repeat on:

main[1] 2 2 up
End of stack.
main[1] End of stack.
main[1] End of stack.
main[1] End of stack.
main[1]

I wonder if Daniel can provide any more information that might enable me to reproduce the issue for debugging. If not, I don't think I can diagnose the issue. Another question I have is whether anybody has attempted to find the point the bug was introduced by backporting the test to earlier versions of the JDK. I think that would essentially mean reducing the test to 2 2 up or similar, since the repeat command is brand new.

I'm assuming the Mach 5 failure has the same underlying cause; I could try virtualizing Linux on PowerPC to try to reproduce that one, but that seems likely to take a lot of time and unlikely to turn up anything useful.

[mlbridge]

Webrevs

• 01: Full - Incremental (8359ab8b)
• 00: Full (817884d9)

[jakobcornell]

This isn't ready for review; I'm just marking it such to enable integration with the mailing list.

[plummercj]

Dan did reproduce the "Unexpected Output" failure on linux. I'm trying to reproduce now, including linux, windows, and macosx. I want to first get a better idea of how frequently it reproduces. Keep in mind that there were extra VM flags applied on all the runs that failed. Try running with the following:

-Xcomp -XX:+CreateCoredumpOnCrash -ea -esa -XX:CompileThreshold=100 -XX:+UnlockExperimentalVMOptions -server -XX:+TieredCompilation -XX:-DoEscapeAnalysis

Most of these are probably unnecessary or aren't even impacting how VM is run (ie -Xcomp probably makes -XX:CompileThreshold=100 not do anything). If anything, -Xcomp might be making a difference.

[plummercj]

I did 20 runs each on linux, mac, and windows. I got 4 "Unexpected output" failures, 3 on mac and 1 on windows. I applied the fix to use failure(), and it seems this failure is also due to the 2 2 up command not working right:

Sending command: repeat on
reply[0]: main[1] 
Sending command: repeat 
reply[0]: Repeat is on
reply[1]: main[1] 
Sending command: print 0
reply[0]:  0 = 0
reply[1]: main[1] 
Sending command: 
reply[0]: main[1] 
Sending command: 2 2 up 
reply[0]: End of stack.
reply[1]: main[1] 
# ERROR: Unexpected output
The following stacktrace is for failure analysis.
nsk.share.TestFailure: Unexpected output
	at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:432)
	at nsk.share.Log.complain(Log.java:403)
	at nsk.share.jdb.JdbTest.failure(JdbTest.java:74)
	at nsk.jdb.repeat.repeat001.repeat001.runCasesNoCleanup(repeat001.java:142)
	at nsk.jdb.repeat.repeat001.repeat001.runCases(repeat001.java:87)
	at nsk.share.jdb.JdbTest.runTest(JdbTest.java:149)
	at nsk.jdb.repeat.repeat001.repeat001.run(repeat001.java:77)
	at nsk.jdb.repeat.repeat001.repeat001.main(repeat001.java:71)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:833)
Sending command: 
reply[0]: End of stack.
reply[1]: main[1] End of stack.
reply[2]: main[1] End of stack.
reply[3]: main[1] End of stack.
reply[4]: main[1] 
# ERROR: Repeated command didn't repeat correctly

[plummercj]

I'm pretty sure the problem is with how you are calling jdb.receiveReplyFor("2 2 " + JdbCommand.up). receiveReplyFor() is only going to wait for 1 prompt to be returned. I think usually they are all returned together, so usually you get all 4 prompts, but sometimes they get split up. The way to fix this is to use jdb.receiveReplyFor("2 2 " + JdbCommand.up, true, 4) since you want to wait for 4 prompts.

...and you also need to fix the empty command that follows since it repeats the "2 2" command : jdb.receiveReplyFor("", true, 4)

[jakobcornell]

That certainly does make sense, although it makes me wonder how this ever passed in the first place. Maybe there's a bug somewhere in the JDB output processing code that made the failure intermittent. In any case, it should be resolved now. Thanks for doing the heavy lifting on investigation and debugging here.

I did have another question related to these tests. I used a record class in the implementation of the list003 test and I since learned that that's a preview feature. Should I rework the test to avoid using record classes in case the feature is dropped later?

[mlbridge]

Mailing list message from David Holmes on serviceability-dev:

On 2/11/2021 11:07 am, Jakob Cornell wrote:

On Mon, 1 Nov 2021 04:39:27 GMT, Jakob Cornell <duke at openjdk.java.net> wrote:

This will fix a few issues with the tests added in #5290:

- [x] intermittent failures
- [x] tests should use `failure` method to report problems rather than throwing `AssertionError`

That certainly does make sense, although it makes me wonder how this ever passed in the first place. Maybe there's a bug somewhere in the JDB output processing code that made the failure intermittent. In any case, it should be resolved now. Thanks for doing the heavy lifting on investigation and debugging here.

I did have another question related to these tests. I used a record class in the implementation of the `list003` test and I since learned that that's a preview feature. Should I rework the test to avoid using record classes in case the feature is dropped later?

Records were a preview feature in JDK 14 and 15, but are a full feature
since JDK 16.

David

[jakobcornell]

Oh good. I haven't been following recent releases very closely. So this is ready for review then.

[plummercj]

That certainly does make sense, although it makes me wonder how this ever passed in the first place. Maybe there's a bug somewhere in the JDB output processing code that made the failure intermittent.

It depends a bit on how the underlying I/O bundles up the reply packets, and how quickly they are read, but probably more the latter than the former. Basically the jdb process is sending a bunch of replies, and the test process usually doesn't start reading the replies until after they have all been sent, so it gets them all with one read. But if the test process is quick enough, then it might do the read before all the replies have been sent.

[openjdk]

@jakobcornell This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8276208: vmTestbase/nsk/jdb/repeat/repeat001/repeat001.java fails with "AssertionError: Unexpected output"

Reviewed-by: cjplummer, iklam

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 29 new commits pushed to the master branch:

• 2b02b6f: 8274942: AssertionError at jdk.compiler/com.sun.tools.javac.util.Assert.error(Assert.java:155)
• bb92fb0: 8274930: sun/tools/jps/TestJps.java can fail with long VM arguments string
• 6a04899: 8275840: Add test to java/nio/channels/Channels/TransferTo.java to test transfer sizes > 2GB
• 01105d6: 8276367: ProblemList vmTestbase/nsk/jvmti/RedefineClasses/StressRedefineWithoutBytecodeCorruption/TestDescription.java
• 8fc16f1: 8275729: Qualified method names in CodeHeap Analytics
• fa4ce82: 8276260: (se) Remove java/nio/channels/Selector/Wakeup.java from ProblemList (win)
• 495c828: 8276188: Clarify "default charset" descriptions in String class
• cd778f5: 8202667: java/awt/Debug/DumpOnKey/DumpOnKey.java times out on Windows
• b889f2a: 8276175: codestrings.validate_vm gtest still broken on ppc64 after JDK-8276046
• 5b4e398: 8275766: (tz) Update Timezone Data to 2021e
• ... and 19 more: https://git.openjdk.java.net/jdk/compare/bf2e9ee9d321ed289466b2410f12ad10504d01a2...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@plummercj, @iklam) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

[dcubed-ojdk]

@iklam - Can you review this fix? You were one of the original reviewers on:
JDK-8271356 Modify jdb to treat an empty command as a repeat of the previous command

Thanks!

[iklam]

LGTM

[jakobcornell]

/integrate

[openjdk]

@jakobcornell
Your change (at version 8359ab8) is now ready to be sponsored by a Committer.

[plummercj]

/sponsor

[openjdk]

Going to push as commit c7f070f.
Since your change was applied there have been 41 commits pushed to the master branch:

• 684edbb: 8273922: (fs) UserDefinedFileAttributeView doesn't handle file names that are just under the MAX_PATH limit (win)
• 7115892: 8276401: Use blessed modifier order in java.net.http
• 0ef8cbe: 8276385: Re-run blessed-modifier-order script on java.desktop and jdk.accessibility
• 724bf3b: 8275604: Zero: Reformat opclabels_data
• 61cb4bc: 8276036: The value of full_count in the message of insufficient codecache is wrong
• 8731846: 8276556: ProblemList java/nio/channels/FileChannel/LargeGatheringWrite.java on windows-x64
• be1ca2b: 8276298: G1: Remove unused G1SegmentedArrayBufferList::add
• a316c06: 8275730: Relax memory constraint on MultiThreadedRefCounter
• 6150633: 8276348: Use blessed modifier order in java.base
• 465d350: 8276157: C2: Compiler stack overflow during escape analysis on Linux x86_32
• ... and 31 more: https://git.openjdk.java.net/jdk/compare/bf2e9ee9d321ed289466b2410f12ad10504d01a2...master

Your commit was automatically rebased without conflicts.

[openjdk]

@plummercj @jakobcornell Pushed as commit c7f070f.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.