JDK-8305913 : com/sun/jdi/JdbLastErrorTest.java failed with "'lastError = 42' missing from stdout/stderr"
  • Type: Bug
  • Component: core-svc
  • Sub-Component: debugger
  • Affected Version: 21
  • Priority: P3
  • Status: Resolved
  • Resolution: Duplicate
  • OS: windows
  • CPU: x86_64
  • Submitted: 2023-04-12
  • Updated: 2023-05-03
  • Resolved: 2023-05-03
Related Reports
Duplicate :  
JDK-8307362 - Remove test com/sun/jdi/JdbLastErrorTest.java
Relates :  
JDK-8296646 - com/sun/jdi/JdbLastErrorTest.java test failure
Relates :  
JDK-8292302 - Windows GetLastError value overwritten by ThreadLocalStorage::thread
Sub Tasks
JDK-8305966 :  
ProblemList com/sun/jdi/JdbLastErrorTest.java on windows-x64 - Resolved
Description
The following test failed in the JDK21 CI:

com/sun/jdi/JdbLastErrorTest.java

Here's a snippet from the log file:

#section:main
----------messages:(7/301)----------
command: main JdbLastErrorTest
reason: User specified action: run main/othervm JdbLastErrorTest 
started: Wed Apr 12 11:00:29 UTC 2023
Mode: othervm [/othervm specified]
Additional options from @modules: --add-modules jdk.jdi
finished: Wed Apr 12 11:00:34 UTC 2023
elapsed time (seconds): 5.39
----------configuration:(3/38)----------
Boot Layer
  add modules: jdk.jdi

----------System.out:(22/2850)*----------
Command line: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+18-1481\\windows-x64.jdk\\jdk-21\\bin\\java.exe -cp C:\\sb\\prod\\1681297018\\testoutput\\test-support\\jtreg_open_test_jdk_tier3\\classes\\3\\com\\sun\\jdi\\JdbLastErrorTest.d;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+18-1481\\src.full\\open\\test\\jdk\\com\\sun\\jdi;C:\\sb\\prod\\1681297018\\testoutput\\test-support\\jtreg_open_test_jdk_tier3\\classes\\3\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+18-1481\\src.full\\open\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.1.1\\1\\bundles\\jtreg-7.1.1+1.zip\\jtreg\\lib\\jtreg.jar -Xmx768m -XX:MaxRAMPercentage=4.16667 -Dtest.boot.jdk=c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk\\19\\36\\bundles\\windows-x64\\jdk-19_windows-x64_bin.zip\\jdk-19 -Djava.io.tmpdir=c:\\sb\\prod\\1681297018\\testoutput\\test-support\\jtreg_open_test_jdk_tier3\\tmp -ea -esa --enable-preview -agentlib:jdwp=transport=dt_socket,server=y,suspend=y TestNativeLastError ]
[debuggee]:c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+18-1481\\windows-x64.jdk\\jdk-21\\bin\\java.exe -cp C:\\sb\\prod\\1681297018\\testoutput\\test-support\\jtreg_open_test_jdk_tier3\\classes\\3\\com\\sun\\jdi\\JdbLastErrorTest.d;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+18-1481\\src.full\\open\\test\\jdk\\com\\sun\\jdi;C:\\sb\\prod\\1681297018\\testoutput\\test-support\\jtreg_open_test_jdk_tier3\\classes\\3\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+18-1481\\src.full\\open\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.1.1\\1\\bundles\\jtreg-7.1.1+1.zip\\jtreg\\lib\\jtreg.jar -Xmx768m -XX:MaxRAMPercentage=4.16667 -Dtest.boot.jdk=c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk\\19\\36\\bundles\\windows-x64\\jdk-19_windows-x64_bin.zip\\jdk-19 -Djava.io.tmpdir=c:\\sb\\prod\\1681297018\\testoutput\\test-support\\jtreg_open_test_jdk_tier3\\tmp -ea -esa --enable-preview -agentlib:jdwp=transport=dt_socket,server=y,suspend=y TestNativeLastError
[debuggee] Listening for transport dt_socket at address: 64269
[jdb] Set uncaught java.lang.Throwable
[jdb] Set deferred uncaught java.lang.Throwable
[jdb] Initializing jdb ...
[jdb] 
[jdb] VM Started: > No frames on the current call stack
[jdb] 
[jdb] main[1] 
> run 
[debuggee] lastError = 0
[jdb] > 
[jdb] Exception occurred: java.lang.RuntimeException (uncaught)"thread=main", TestNativeLastError.testWindows(), line=70 bci=157
[jdb] 70                    throw new RuntimeException("failed, lastError = " + lastError);
[jdb] 
[jdb] main[1] 
=======================================
Exception thrown during test execution: 'lastError = 42' missing from stdout/stderr
=======================================
> quit
[debuggee] Listening for transport dt_socket at address: 64276
----------System.err:(35/2201)----------
[debuggee] WARNING: A restricted method in java.lang.foreign.Linker has been called
[debuggee] WARNING: java.lang.foreign.Linker::nativeLinker has been called by the unnamed module
[debuggee] WARNING: Use --enable-native-access=ALL-UNNAMED to avoid a warning for this module
[debuggee] iteration 0 got lastError = 0 (expected 42)
 stdout: [Listening for transport dt_socket at address: 64269
WARNING: A restricted method in java.lang.foreign.Linker has been called
WARNING: java.lang.foreign.Linker::nativeLinker has been called by the unnamed module
WARNING: Use --enable-native-access=ALL-UNNAMED to avoid a warning for this module
lastError = 0
iteration 0 got lastError = 0 (expected 42)];
 stderr: [Listening for transport dt_socket at address: 64269
WARNING: A restricted method in java.lang.foreign.Linker has been called
WARNING: java.lang.foreign.Linker::nativeLinker has been called by the unnamed module
WARNING: Use --enable-native-access=ALL-UNNAMED to avoid a warning for this module
lastError = 0
iteration 0 got lastError = 0 (expected 42)]
 exitValue = -1

[debuggee] Exception in thread "main" java.lang.RuntimeException: failed, lastError = 0
[debuggee] 	at TestNativeLastError.testWindows(JdbLastErrorTest.java:70)
[debuggee] 	at TestNativeLastError.main(JdbLastErrorTest.java:49)
java.lang.RuntimeException: 'lastError = 42' missing from stdout/stderr
	at jdk.test.lib.process.OutputAnalyzer.shouldMatch(OutputAnalyzer.java:340)
	at JdbLastErrorTest.runCases(JdbLastErrorTest.java:98)
	at lib.jdb.JdbTest.run(JdbTest.java:96)
	at JdbLastErrorTest.main(JdbLastErrorTest.java:81)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	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:1592)

JavaTest Message: Test threw exception: java.lang.RuntimeException: 'lastError = 42' missing from stdout/stderr
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException: 'lastError = 42' missing from stdout/stderr
----------rerun:(44/5718)*----------
Comments
Had considered "fixing" this with https://github.com/openjdk/jdk/pull/13481, but the test is not in-line with current Panama "last error" usage. Closing this as a duplicate of the change JDK-8307362 to say we should simply remove the test.
03-05-2023
Some example stacktraces from WinDbg, with routes into PcDescContainer::find_pc_desc_internal: 0:011> k # Child-SP RetAddr Call Site 00 000000cd`238f9078 00007ffd`a29b4f22 jvm!PcDescContainer::find_pc_desc_internal [s\open\src\hotspot\share\code\nmethod.cpp @ 2066] 01 (Inline Function) --------`-------- jvm!PcDescContainer::find_pc_desc+0x42 [s\open\src\hotspot\share\code\compiledMethod.hpp @ 136] 02 (Inline Function) --------`-------- jvm!CompiledMethod::find_pc_desc+0x5d [s\open\src\hotspot\share\code\compiledMethod.hpp @ 423] 03 (Inline Function) --------`-------- jvm!CompiledMethod::pc_desc_at+0x5d [s\open\src\hotspot\share\code\compiledMethod.hpp @ 235] 04 000000cd`238f9080 00007ffd`a29b3df3 jvm!vframeStreamCommon::fill_from_frame+0x2f2 [s\open\src\hotspot\share\runtime\vframe.inline.hpp @ 213] 05 000000cd`238f9180 00007ffd`a2f2f3b5 jvm!vframeStream::vframeStream+0x373 [s\open\src\hotspot\share\runtime\vframe.inline.hpp @ 131] 06 (Inline Function) --------`-------- jvm!SharedRuntime::find_callee_info+0x5f [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1096] 07 000000cd`238fb790 00007ffd`a2f2ee5b jvm!SharedRuntime::resolve_sub_helper+0x125 [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1408] 08 000000cd`238fdeb0 00007ffd`a2f2f8b2 jvm!SharedRuntime::resolve_helper+0x3b [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1280] 09 000000cd`238fdef0 00000280`13f4e806 jvm!SharedRuntime::resolve_virtual_call_C+0x32 [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1641] 0a 000000cd`238fdf40 00000008`003c9648 0x00000280`13f4e806 0b 000000cd`238fdf48 00007ffd`a2dcd311 0x00000008`003c9648 0c 000000cd`238fdf50 00000000`00000000 jvm!LinkInfo::LinkInfo+0xa1 [s\open\src\hotspot\share\interpreter\linkResolver.cpp @ 243] 0:011> k # Child-SP RetAddr Call Site 00 000000cd`238f7b58 00007ffd`a29b4f22 jvm!PcDescContainer::find_pc_desc_internal [s\open\src\hotspot\share\code\nmethod.cpp @ 2066] 01 (Inline Function) --------`-------- jvm!PcDescContainer::find_pc_desc+0x42 [s\open\src\hotspot\share\code\compiledMethod.hpp @ 136] 02 (Inline Function) --------`-------- jvm!CompiledMethod::find_pc_desc+0x5d [s\open\src\hotspot\share\code\compiledMethod.hpp @ 423] 03 (Inline Function) --------`-------- jvm!CompiledMethod::pc_desc_at+0x5d [s\open\src\hotspot\share\code\compiledMethod.hpp @ 235] 04 000000cd`238f7b60 00007ffd`a29b3df3 jvm!vframeStreamCommon::fill_from_frame+0x2f2 [s\open\src\hotspot\share\runtime\vframe.inline.hpp @ 213] 05 000000cd`238f7c60 00007ffd`a2f2f3b5 jvm!vframeStream::vframeStream+0x373 [s\open\src\hotspot\share\runtime\vframe.inline.hpp @ 131] 06 (Inline Function) --------`-------- jvm!SharedRuntime::find_callee_info+0x5f [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1096] 07 000000cd`238fa270 00007ffd`a2f2ee5b jvm!SharedRuntime::resolve_sub_helper+0x125 [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1408] 08 000000cd`238fc990 00007ffd`a2f2f0c0 jvm!SharedRuntime::resolve_helper+0x3b [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1280] 09 000000cd`238fc9d0 00000280`13f4eb06 jvm!SharedRuntime::resolve_static_call_C+0x50 [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1604] 0a 000000cd`238fdd30 00000000`00000001 0x00000280`13f4eb06 0b 000000cd`238fdd38 00000282`1e00c008 0x1 0c 000000cd`238fdd40 00000280`025c0201 0x00000282`1e00c008 0d 000000cd`238fdd48 00000000`20bf27b6 0x00000280`025c0201 0e 000000cd`238fdd50 00000000`0000027f 0x20bf27b6 0f 000000cd`238fdd58 00000000`00000000 0x27f 0:011> k # Child-SP RetAddr Call Site 00 000000cd`238f90e8 00007ffd`a29b4f22 jvm!PcDescContainer::find_pc_desc_internal [s\open\src\hotspot\share\code\nmethod.cpp @ 2066] 01 (Inline Function) --------`-------- jvm!PcDescContainer::find_pc_desc+0x42 [s\open\src\hotspot\share\code\compiledMethod.hpp @ 136] 02 (Inline Function) --------`-------- jvm!CompiledMethod::find_pc_desc+0x5d [s\open\src\hotspot\share\code\compiledMethod.hpp @ 423] 03 (Inline Function) --------`-------- jvm!CompiledMethod::pc_desc_at+0x5d [s\open\src\hotspot\share\code\compiledMethod.hpp @ 235] 04 000000cd`238f90f0 00007ffd`a29b3df3 jvm!vframeStreamCommon::fill_from_frame+0x2f2 [s\open\src\hotspot\share\runtime\vframe.inline.hpp @ 213] 05 000000cd`238f91f0 00007ffd`a2f2ca3c jvm!vframeStream::vframeStream+0x373 [s\open\src\hotspot\share\runtime\vframe.inline.hpp @ 131] 06 (Inline Function) --------`-------- jvm!SharedRuntime::find_callee_info+0x6a [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1096] 07 000000cd`238fb800 00007ffd`a2f2d5dd jvm!SharedRuntime::handle_ic_miss_helper+0xac [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1751] 08 000000cd`238fdf30 00000280`13f4e206 jvm!SharedRuntime::handle_wrong_method_ic_miss+0x2d [s\open\src\hotspot\share\runtime\sharedRuntime.cpp @ 1501] 09 000000cd`238fdf80 00000008`00116a00 0x00000280`13f4e206 0a 000000cd`238fdf88 00000000`09040904 0x00000008`00116a00 0b 000000cd`238fdf90 00000000`00000000 0x9040904
23-04-2023
[~kevinw]: > In WinDbg, I see SharedRuntime::resolve_static_call_C and resolve_virtual_call_C can end up in PcDescContainer::find_pc_desc_internal, among other callers. Could you share the complete stacktrace please. I need to see whether we need to rethink the ASGCT fix.
17-04-2023
Unfortunately Thread::current_in_asgct() can be called from a signal-handling context and so must use Thread::current_or_null_safe() which uses TLS as noted. I hadn't expected that code to be exercised from such common code paths as resolve_static_call_C etc - I don't like the overhead it imposes just to let AGCT be slightly less broken :(
15-04-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/13481 Date: 2023-04-14 19:23:05 +0000
14-04-2023
[~kevinw] - Very nice spelunking to associate the changes in JDK-8304725 with this new/old failure mode. It never ceases to amaze me how sometimes the fix that I told myself could not be the root cause turns out to be just that... I like the idea of a warm-up getLastError call. Please include an appropriate explanatory comment...
14-04-2023
In WinDbg, I see SharedRuntime::resolve_static_call_C and resolve_virtual_call_C can end up in PcDescContainer::find_pc_desc_internal, among other callers. And PcDescContainer::find_pc_desc_internal can now call Thread::current_in_asgct(), and that calls Thread::current_or_null_safe(). This accesses TLS and on Windows that clears the last error value. Originally in JDK-8292302 a change was undone that had made JavaThread::threadObj call Thread::current_or_null_safe, as the use of TLS upset this case of accessing last error in the app, and this made cases like this testcase work OK. This new Thread::current_in_asgct() case shows that the VM finds new ways to interfere with the last error value, or at least new VM code keeps wanting to call Thread::current. This testcase is kind of niche feature, so should protect itself from this. Currently, a warm-up getLastError call looks like a good change.
14-04-2023
Thanks for the extra testing Dan, that's great! 8304725 adds a call to Thread::current_in_asgct() which must use thread local storage and probably sets last error. If this is getting called, then it is similar to how we found the original issue. Locally I can make the test reliable with a single warm-up call to getLastError.invoke(); before the loop. When failing previously it was always the first iteration that failed, and that looks true now. (I am now getting 100 successful runs in a row with a warm-up call.) As the original problem affected the first iteration too, it may be an ongoing challenge to keep this running as things change, so the warm-up might be a reasonable change.
14-04-2023
[~kevinw] - I got 5/5 passes with jdk-21+18-1480 and 5/5 failures with jdk-21+18-1481. jdk-21+18-1481 only contains the fix for: JDK-8304725 AsyncGetCallTrace can cause SIGBUS on M1 I find it very hard to imagine why the fix for JDK-8304725 would cause this failure with a windows-x64 test.
14-04-2023
I'm reproducing it locally now, which I could not do before. If there's nothing I can exclude to make it reliable (again), then maybe that this can't be reliably tested. We know the whole idea of invoking native get-last-error directly with panama is at the edges of what we can expect to work. Despite the exclusions this test makes, maybe the problem should get promoted to "noreg-hard"...
14-04-2023
No idea what triggered this failure to start but most likely issue is an unexpected OS call happening after the one that is supposed to return the "42" and thus becoming the new "last error".
14-04-2023
OS and jtreg versions look the same between failure and good runs, and don't see a change in VM options either. The jdk-21+19-1495-tier3 sighting might be the first Win 11, but similarly we have a fail and a pass on different hosts with the same windows 10 version. Something makes us behave differently, but it might be luck. Will look if I can reproduce this at all, previously it wasn't possible.
13-04-2023
Here's a log file snippet from the jdk-21+19-1495-tier3 sighting: com/sun/jdi/JdbLastErrorTest.java ----------System.err:(35/2201)---------- [debuggee] WARNING: A restricted method in java.lang.foreign.Linker has been called [debuggee] WARNING: java.lang.foreign.Linker::nativeLinker has been called by the unnamed module [debuggee] WARNING: Use --enable-native-access=ALL-UNNAMED to avoid a warning for this module [debuggee] iteration 0 got lastError = 0 (expected 42) stdout: [Listening for transport dt_socket at address: 54255 WARNING: A restricted method in java.lang.foreign.Linker has been called WARNING: java.lang.foreign.Linker::nativeLinker has been called by the unnamed module WARNING: Use --enable-native-access=ALL-UNNAMED to avoid a warning for this module lastError = 0 iteration 0 got lastError = 0 (expected 42)]; stderr: [Listening for transport dt_socket at address: 54255 WARNING: A restricted method in java.lang.foreign.Linker has been called WARNING: java.lang.foreign.Linker::nativeLinker has been called by the unnamed module WARNING: Use --enable-native-access=ALL-UNNAMED to avoid a warning for this module lastError = 0 iteration 0 got lastError = 0 (expected 42)] exitValue = -1 [debuggee] Exception in thread "main" java.lang.RuntimeException: failed, lastError = 0 [debuggee] at TestNativeLastError.testWindows(JdbLastErrorTest.java:70) [debuggee] at TestNativeLastError.main(JdbLastErrorTest.java:49) java.lang.RuntimeException: 'lastError = 42' missing from stdout/stderr at jdk.test.lib.process.OutputAnalyzer.shouldMatch(OutputAnalyzer.java:340) at JdbLastErrorTest.runCases(JdbLastErrorTest.java:98) at lib.jdb.JdbTest.run(JdbTest.java:96) at JdbLastErrorTest.main(JdbLastErrorTest.java:81) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) 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:1592) JavaTest Message: Test threw exception: java.lang.RuntimeException: 'lastError = 42' missing from stdout/stderr JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.RuntimeException: 'lastError = 42' missing from stdout/stderr ----------rerun:(44/5718)*---------- I believe this is the first sighting on a non-win2019 test machine. This sighting was on a Windows_11_Enterprise test machine.
13-04-2023
Has anyone tried running an older binary (one the predates when these failures started) on these win2019 machines to see if the issue reproduces?
13-04-2023
The ProblemListing is integrated in jdk-21+19-1497 so we'll start to quiet down later today. Obviously the noise in the upper tiers will continue to play out... sigh... Does anybody know if something changed recently with the win2019 machines? [~ctornqvi] or [~tbell] - Do either of you know if something changed in the win2019 OCI images this week? First failure was in jdk-21+18-1481-tier3 on 2023.04.12.
13-04-2023
The test passed in jdk-21+18-1484-tier3 and that execution happened on a Windows_Server_2019_Standard machine.
12-04-2023
This failure has been spotted in three Tier3 job sets in a row so I've bumped the priority from P4 -> P3. All failures so far have been on win2019 machines.
12-04-2023