8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)" #10831

plummercj · 2022-10-24T05:29:26Z

Various debugger tests (mainly JCK vm/jdwp tests) are failing with:

FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)

Sometimes instead of SetTag the message says GetTag or signature. This is a new issue caused by JDK-8295375, which changed the debug agent CLASS_PREPARE event handling that is used for class tracking. It moved it from the main debug agent JVMTIEnv to a JVMTIEnv that already existed for class tracking purposes to deal with OBJECT_FREE events. Because of this, synchronizing around VMDEATH was lost, so it's possible for the CLASS_PREPARE event to be received just before VMDEATH, but then VMDEATH completes before the CLASS_PREPARE callback can complete. This results in WRONG_PHASE errors when making some JVMTI calls.

The easiest fix is for the code in classTrack_addPreparedClass() to check for JVMTI_ERROR_WRONG_PHASE, and if it gets it then just return. It should also assert that gData->vmDead is true when this happens. This is needed in 3 places where JVMTI is called.

The purist fix would be to somehow synchronize with VMDEATH, either with the same locking done by the main event handling code (for example, use BEGIN_CALLBACK and END_CALLBACK), or by having the class tracking JVMTIEnv also enable VMDEATH events. The VMDEATH callback block would disable the CLASS_PREPARE events, and also block until any currently executing CLASS_PREPARE callback has exited. I think this is overkill, and also adds locking overhead to the CLASS_PREPARE callback, so I'm going with the simpler solution of allowing WRONG_PHASE.

Progress

Change must be properly reviewed (1 review required, with at least 1 Reviewer)
Change must not contain extraneous whitespace
Commit message must refer to an issue

Issues

JDK-8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)"
JDK-8295815: misc JDI tests failed with "JDWP exit error JVMTI_ERROR_WRONG_PHASE(112)"

Reviewers

Serguei Spitsyn (@sspitsyn - Reviewer)
Alex Menkov (@alexmenkov - Reviewer)
Daniel D. Daugherty (@dcubed-ojdk - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk pull/10831/head:pull/10831
$ git checkout pull/10831

Update a local copy of the PR:
$ git checkout pull/10831
$ git pull https://git.openjdk.org/jdk pull/10831/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 10831

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

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/10831.diff

bridgekeeper · 2022-10-24T05:30:57Z

👋 Welcome back cjplummer! 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 · 2022-10-24T05:33:40Z

@plummercj 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.

mlbridge · 2022-10-24T05:36:49Z

Webrevs

00: Full (faef3283)

sspitsyn · 2022-10-24T21:06:18Z

src/jdk.jdwp.agent/share/native/libjdwp/classTrack.c

    if (error != JVMTI_ERROR_NONE) {
        EXIT_ERROR(error,"signature");
    }

-    if (gdata && gdata->assertOn) {
+    if (gdata->assertOn) {


Just a question.
Why the check for non-NULL gdata was removed?
Is it because gdate is always non-NULL?

It's created during the OnLoad and never freed, so it can never be null once this callback is setup.

sspitsyn

This workaround looks okay to me.
I hope it solves the problem observed with the JCK tests.
In fact, we sometimes keep forgetting to run JCK tests. 👍
Thanks,
Serguei

openjdk · 2022-10-24T21:11:28Z

@plummercj 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:

8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)"
8295815: misc JDI tests failed with "JDWP exit error JVMTI_ERROR_WRONG_PHASE(112)"

Reviewed-by: sspitsyn, amenkov, dcubed

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 35 new commits pushed to the master branch:

d393e05: 8294989: ResourceBundle naming convention issue in JdbcRowSetResourceBundle.java
0caea81: 8295895: build error after JDK-8279366
ee0dec8: 8295838: Document why we do not print Code Cache Roots phase in G1 logging
ef60608: 8295732: Directly embed TruncatedSeqs in G1Analytics
3e49f8f: 8295839: G1: Single threaded phases (within parallel phases) report as using multiple threads in logs
427f506: 8279366: CDS should allow alternative locations for JAR files in classpath
3a873d3: 8295808: GrowableArray should support capacity management
6289600: 8295810: cleanup debug agent removeThread() api
5c4d99a: 8295118: G1: Clear CLD claim marks concurrently
af2de97: 8287754: Update jib GNU make dependency on Windows to latest cygwin build
... and 25 more: https://git.openjdk.org/jdk/compare/aad81f2eba5a77a028a58a767fd4afc11b4dd528...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.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

plummercj · 2022-10-24T21:51:23Z

I hope it solves the problem observed with the JCK tests.
In fact, we sometimes keep forgetting to run JCK tests. 👍

Yes, but it's also turning up with some JDI tests. I did a lot of testing, and have done a bunch since for other changes I'm working on, and this never turned up. I did get it to turn up once yesterday after doing about 100 jck runs. However, it seems to be turning up a lot more than that in our CI runs. I'm not sure why.

plummercj · 2022-10-25T02:41:23Z

Thanks for the review Serguei!

Can I get one more review please. The failures are getting rather noisy, so I'd like to get this fix pushed. Thanks.

dcubed-ojdk · 2022-10-25T14:14:09Z

If you think that this fix will resolved both JDK-8295815 and JDK-8295816, then
please do an "/issue JDK-8295815" to add that bug to this PR. JDK-8295816
tracks the JCK failures and JDK-8295815 tracks the JDI failures.

plummercj · 2022-10-25T16:57:32Z

/issue JDK-8295815

openjdk · 2022-10-25T16:58:23Z

@plummercj
Adding additional issue to issue list: 8295815: misc JDI tests failed with "JDWP exit error JVMTI_ERROR_WRONG_PHASE(112)".

dcubed-ojdk

Thanks for adding is_wrong_phase() with the comments about
why it is okay. The deletion of the 'gdata != NULL' check also
caught my eye, but I'm getting more and more convinced that
it's okay to catch this kind of "can't happen" error via the deref
of the pointer that shouldn't be NULL...

Thumbs up.

plummercj · 2022-10-25T22:13:18Z

Thanks for the reviews!

/integrate

openjdk · 2022-10-25T22:14:47Z

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

e0c2930: 8295282: Use Zicboz/cbo.zero to zero-out memory on RISC-V
d393e05: 8294989: ResourceBundle naming convention issue in JdbcRowSetResourceBundle.java
0caea81: 8295895: build error after JDK-8279366
ee0dec8: 8295838: Document why we do not print Code Cache Roots phase in G1 logging
ef60608: 8295732: Directly embed TruncatedSeqs in G1Analytics
3e49f8f: 8295839: G1: Single threaded phases (within parallel phases) report as using multiple threads in logs
427f506: 8279366: CDS should allow alternative locations for JAR files in classpath
3a873d3: 8295808: GrowableArray should support capacity management
6289600: 8295810: cleanup debug agent removeThread() api
5c4d99a: 8295118: G1: Clear CLD claim marks concurrently
... and 26 more: https://git.openjdk.org/jdk/compare/aad81f2eba5a77a028a58a767fd4afc11b4dd528...master

Your commit was automatically rebased without conflicts.

openjdk · 2022-10-25T22:14:59Z

@plummercj Pushed as commit fec6174.

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

Allow WRONG_PHASE when class tracking gets a CLASS_PREPARE event.

faef328

openjdk bot changed the title ~~8295816~~ 8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)" Oct 24, 2022

openjdk bot added the rfr Pull request is ready for review label Oct 24, 2022

openjdk bot added the serviceability serviceability-dev@openjdk.org label Oct 24, 2022

sspitsyn reviewed Oct 24, 2022

View reviewed changes

sspitsyn approved these changes Oct 24, 2022

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Oct 24, 2022

alexmenkov approved these changes Oct 25, 2022

View reviewed changes

dcubed-ojdk approved these changes Oct 25, 2022

View reviewed changes

openjdk bot added the integrated Pull request has been integrated label Oct 25, 2022

openjdk bot closed this Oct 25, 2022

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Oct 25, 2022

8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)" #10831

8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)" #10831

plummercj commented Oct 24, 2022 •

edited by openjdk bot

bridgekeeper bot commented Oct 24, 2022

openjdk bot commented Oct 24, 2022

mlbridge bot commented Oct 24, 2022

sspitsyn Oct 24, 2022

plummercj Oct 24, 2022

sspitsyn left a comment

openjdk bot commented Oct 24, 2022 •

edited

plummercj commented Oct 24, 2022

plummercj commented Oct 25, 2022

dcubed-ojdk commented Oct 25, 2022

plummercj commented Oct 25, 2022

openjdk bot commented Oct 25, 2022

dcubed-ojdk left a comment

plummercj commented Oct 25, 2022

openjdk bot commented Oct 25, 2022

openjdk bot commented Oct 25, 2022

8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)" #10831

8295816: jdwp jck tests failing with "FATAL ERROR in native method: JDWP SetTag, jvmtiError=JVMTI_ERROR_WRONG_PHASE(112)" #10831

Conversation

plummercj commented Oct 24, 2022 • edited by openjdk bot

Progress

Issues

Reviewers

Reviewing

bridgekeeper bot commented Oct 24, 2022

openjdk bot commented Oct 24, 2022

mlbridge bot commented Oct 24, 2022

Webrevs

sspitsyn Oct 24, 2022

Choose a reason for hiding this comment

plummercj Oct 24, 2022

Choose a reason for hiding this comment

sspitsyn left a comment

Choose a reason for hiding this comment

openjdk bot commented Oct 24, 2022 • edited

plummercj commented Oct 24, 2022

plummercj commented Oct 25, 2022

dcubed-ojdk commented Oct 25, 2022

plummercj commented Oct 25, 2022

openjdk bot commented Oct 25, 2022

dcubed-ojdk left a comment

Choose a reason for hiding this comment

plummercj commented Oct 25, 2022

openjdk bot commented Oct 25, 2022

openjdk bot commented Oct 25, 2022

plummercj commented Oct 24, 2022 •

edited by openjdk bot

openjdk bot commented Oct 24, 2022 •

edited