search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.27k stars 720 forks source link

OpenJDK LoggerInterfaceTest Bad e.callStack[1].getMethodName() <unknown method> #13875

Open pshipton opened 2 years ago

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/137 - osx1014-x86-2 jdk_lang_1 -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:-UseCompressedOops java/lang/System/Logger/interface/LoggerInterfaceTest.java

02:05:59  STDOUT:
02:05:59  
02:05:59  logger.isLoggable(Level)
02:05:59    Got expected logger.isLoggable(Level.WARNING): true
02:05:59    Got expected logger.isLoggable(Level.INFO): false
02:05:59  
02:05:59  logger.log(Level, Object)
02:05:59    logger.log(ALL, (Object)null)
02:05:59      Got expected exception: java.lang.NullPointerException
02:05:59    logger.log(ALL, new Throwing())
02:05:59      Got expected e: null
02:05:59    logger.log(TRACE, (Object)null)
02:05:59      Got expected exception: java.lang.NullPointerException
02:05:59    logger.log(TRACE, new Throwing())
02:05:59      Got expected e: null
02:05:59    logger.log(DEBUG, (Object)null)
02:05:59      Got expected exception: java.lang.NullPointerException
02:05:59    logger.log(DEBUG, new Throwing())
02:05:59      Got expected e: null
02:05:59    logger.log(INFO, (Object)null)
02:05:59      Got expected exception: java.lang.NullPointerException
02:05:59    logger.log(INFO, new Throwing())
02:05:59      Got expected e: null
02:05:59    logger.log(WARNING, (Object)null)
02:05:59      Got expected exception: java.lang.NullPointerException
02:05:59    logger.log(WARNING, new NotTrowing("baz"))
02:05:59      Got expected e: non null
02:05:59      Got expected e.level: WARNING
02:05:59      Got expected e.msg: baz[1]
02:05:59      Got expected e.bundle: null
02:05:59      Got expected e.params: null
02:05:59      Got expected e.thrown: null
02:05:59      Got expected e.bundle: null
02:05:59      Got expected e.callStack[0].getMethodName(): log
02:05:59      Got expected e.callStack[0].getClassName() : LoggerInterfaceTest$LoggerImpl
02:05:59  STDERR:
02:05:59  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
02:05:59     expected: log
02:05:59       actual: <unknown method>
02:05:59    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
02:05:59    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
pshipton commented 2 years ago

@tajila fyi

tajila commented 2 years ago

Grinder passed 10/10 https://openj9-jenkins.osuosl.org/job/Grinder/350/tapResults/ meaning that it is an intermittent isssue.

I'm inclined to think that this is unrelated to the <unkownclass> issues we were seeing earlier

gacholio commented 2 years ago

This may be a class unloading issue - Throwable stack traces are not GC roots, so they do not prevent unloading.

JasonFengJ9 commented 2 years ago

Observed at JDK17 0.29.1 internal build job/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_Personal/83/consoleFull (mac11x64rt05)

09:10:32  OpenJDK Runtime Environment (build 17.0.1-internal+0-adhoc.jenkins.BuildJDK17x86-64macPersonal)
09:10:32  Eclipse OpenJ9 VM (build v0.29.1-release-9a13b0bc7e6, JRE 17 Mac OS X amd64-64-Bit Compressed References 20211127_108 (JIT enabled, AOT enabled)
09:10:32  OpenJ9   - 9a13b0bc7e6
09:10:32  OMR      - 3f2734d26ac
09:10:32  JCL      - 1a202978976 based on jdk-17.0.1+12)

09:20:20  variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode650
09:20:20  JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:-UseCompressedOops 

09:26:55  --------------------------------------------------
09:26:55  TEST: java/lang/System/Logger/interface/LoggerInterfaceTest.java

09:26:55  STDERR:
09:26:55  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
09:26:55     expected: log
09:26:55       actual: <unknown method>
09:26:55    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
09:26:55    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
09:26:55    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
09:26:55    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
09:26:55    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
09:26:55    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
09:26:55    at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
09:26:55    at java.base/java.lang.Thread.run(Thread.java:884)
09:26:55  
09:26:55  JavaTest Message: Test threw exception: java.lang.RuntimeException
09:26:55  JavaTest Message: shutting down test
09:26:55  
09:26:55  
09:26:55  TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Bad e.callStack[1].getMethodName(): expected: log actual: <unknown method>
09:26:55  --------------------------------------------------
09:27:53  Test results: passed: 783; failed: 1
09:28:00  Report written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_Personal/jvmtest/openjdk/report/html/report.html
09:28:00  Results written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_Personal/aqa-tests/TKG/output_16380223946181/jdk_lang_1/work
09:28:00  Error: Some tests failed or other problems occurred.
09:28:00  
09:28:00  jdk_lang_1_FAILED

fyi @pshipton

gacholio commented 2 years ago

I doubt the log method has been unloaded.

pshipton commented 2 years ago

Trying more grinders https://openj9-jenkins.osuosl.org/job/Grinder/410/

pshipton commented 2 years ago

I ran 5 iterations on 4 machines and repeated the failure at least once, on osx1014-x86-1

gacholio commented 2 years ago

If it's repeatable, someone should gather cores on the exception throw, if it's not already too late.

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Grinder/413/

pshipton commented 2 years ago

The problem was reproduced twice in https://openj9-jenkins.osuosl.org/job/Grinder_iteration_0/38/consoleFull - osx1014-x86-2 However there was a timeout trying to archive the results. I'll try again.

22:21:28  Error occurred for request PUT /artifactory/ci-openj9/Test/Grinder_iteration_0/38/openjdk_test_output.tar.gz;build.parentNumber=413;build.parentName=Grinder;build.timestamp=1638298747762;build.name=Grinder_iteration_0;build.number=38 HTTP/1.1. Received status code 504 and message: Gateway Time-out.
14:26:19  JVMDUMP039I Processing dump event "throw", detail "java/lang/RuntimeException" at 2021/11/30 14:26:12 - please wait.
14:26:19  JVMDUMP032I JVM requested System dump using '/Users/jenkins/workspace/Grinder_iteration_0/aqa-tests/TKG/output_16383001171888/jdk_lang_1/work/scratch/4/core.20211130.142612.26760.0001.dmp' in response to an event
14:26:19  JVMDUMP010I System dump written to /Users/jenkins/workspace/Grinder_iteration_0/aqa-tests/TKG/output_16383001171888/jdk_lang_1/work/scratch/4/core.20211130.142612.26760.0001.dmp
14:26:19  JVMDUMP013I Processed dump event "throw", detail "java/lang/RuntimeException".

https://openj9-jenkins.osuosl.org/job/Grinder/414/

gacholio commented 2 years ago

Can you point me to the source for the test? It may be that the error is thrown after the stack has been collapsed.

tajila commented 2 years ago

https://github.com/ibmruntimes/openj9-openjdk-jdk17/blob/b3c19a59602b6817a7bcf0dbe4fd993f4142a272/test/jdk/java/lang/System/Logger/interface/LoggerInterfaceTest.java

tajila commented 2 years ago

Line 200 is the failing check

gacholio commented 2 years ago

Yeah the grinders aren't going to be useful. We need to see where the frame came from and stop there.

gacholio commented 2 years ago

The frames are coming from Throwable.getStackTrace(). If possible, modify the test to record the Throwable in the Logger instance and we could look at that.

gacholio commented 2 years ago

@vijaysun-omr @mpirvu Two questions:

1) If a class is unloaded, is the metadata for relevant compilations also discarded from the data cache?

2) If a method is recompiled, presumably the metadata is NOT reclaimed. True?

gacholio commented 2 years ago

@pshipton How about seeing if the test fails with -Xint?

pshipton commented 2 years ago

So far it's only reproduced by running the entire jdk_lang_1 suite. It didn't reproduce in the last 6 iterations I ran. Running this suite with -Xint could take a very long time. First I'll see if I can reproduce it by running just the failing test.

mpirvu commented 2 years ago
  1. Yes, on class unloading the metadata is discarded from the data cache
  2. When a method is recompiled, the metadata is not deleted, but adjusted to reflect the fact that the method is now smaller (we reclaim part of the method body and leave a stub behind to be able to patch caller sites)
pshipton commented 2 years ago

Modified the test https://github.com/pshipton/openj9-openjdk-jdk11/commit/4aa538520c6 and running a grinder using this. https://openj9-jenkins.osuosl.org/job/Grinder/421 https://openj9-jenkins.osuosl.org/job/Grinder/422 https://openj9-jenkins.osuosl.org/job/Grinder/423 https://openj9-jenkins.osuosl.org/job/Grinder/424 https://openj9-jenkins.osuosl.org/job/Grinder/425 https://openj9-jenkins.osuosl.org/job/Grinder/426 https://openj9-jenkins.osuosl.org/job/Grinder/427 https://openj9-jenkins.osuosl.org/job/Grinder/436

pshipton commented 2 years ago

I ran just the failing test 50 times each on the two machines seen previously failing, but it didn't reproduce. I'm not hopeful just running the single test will reproduce it as it starts a new JVM every time.

gacholio commented 2 years ago

  1. Yes, on class unloading the metadata is discarded from the data cache

    1. When a method is recompiled, the metadata is not deleted, but adjusted to reflect the fact that the method is now smaller (we reclaim part of the method body and leave a stub behind to be able to patch caller sites)

So, when a method is recompiled, the older method (which may still be running on a stack) will be able to find metadata, but if a class is unloaded, the metadata will not be found.

Having said this, the log method that's not being found isn't likely to have been unloaded.

The same will be true in the interpreter - if a class is unloaded, the stack trace will contain either unknown or incorrect data (if the unloaded memory is reused for subsequent classes, the lookup will find incorrect information).

gacholio commented 2 years ago

@mpirvu re: making the range smaller - do you first ensure that the method you're modifying isn't running on any stack? If not, running methods may well fail the metadata lookup (not to mention if the memory is re-used, we'll crash all over the place).

mpirvu commented 2 years ago

do you first ensure that the method you're modifying isn't running on any stack?

Yes. The reclamation is done during a GC cycle after making sure no thread is running the code we are about to delete. The process is described in this doc: https://github.com/eclipse-openj9/openj9/blob/master/doc/compiler/runtime/MetadataReclamation.md

pshipton commented 2 years ago

So far in 50 iterations the problem has not reoccurred with the modified test. I'll try more iterations tomorrow.

pshipton commented 2 years ago

I got a reproduction and transferred the core to /team/triage/13875

The JVM used is https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Build_JDK11_x86-64_mac_Nightly/162/OpenJ9-JDK11-x86-64_mac-20211130-011454.tar.gz

pshipton commented 2 years ago 
    Java stack frames: 
     bp: 0x00007ff1fb24a058  method: void LoggerInterfaceTest.assertEquals(Object, Object, String, String)  source: LoggerInterfaceTest.java:572
      objects: <no objects in this frame>
     bp: 0x00007ff1fb24a118  method: void LoggerInterfaceTest.main(String[])  source: LoggerInterfaceTest.java:202
      objects: 0x32cea060 0x32cf2298 0x32d12198 0x32cea2d0 0x32d2a078 0x32d7aa50

!J9Object 0x0000000032D7AA50 {
    struct J9Class* clazz = !j9class 0x7FF1FB24C700 // LoggerInterfaceTest$LoggerImpl$LogEvent
    Object flags = 0x00000000;
    J lockword = 0x0000000000000000 (offset = 0) (java/lang/Object) <hidden>
    Ljava/lang/System$Logger$Level; level = !fj9object 0x32cea2d0 (offset = 8) (LoggerInterfaceTest$LoggerImpl$LogEvent)
    Ljava/util/ResourceBundle; bundle = !fj9object 0x0 (offset = 16) (LoggerInterfaceTest$LoggerImpl$LogEvent)
    Ljava/lang/String; msg = !fj9object 0x32d7a368 (offset = 24) (LoggerInterfaceTest$LoggerImpl$LogEvent)
    Ljava/lang/Throwable; thrown = !fj9object 0x0 (offset = 32) (LoggerInterfaceTest$LoggerImpl$LogEvent)
    [Ljava/lang/Object; params = !fj9object 0x0 (offset = 40) (LoggerInterfaceTest$LoggerImpl$LogEvent)
    [Ljava/lang/StackTraceElement; callStack = !fj9object 0x32d7a940 (offset = 48) (LoggerInterfaceTest$LoggerImpl$LogEvent)
    Ljava/lang/Throwable; throwable = !fj9object 0x32d7a478 (offset = 56) (LoggerInterfaceTest$LoggerImpl$LogEvent)
}

// e.callStack[1]:
!J9Object 0x0000000032D7A680 {
    struct J9Class* clazz = !j9class 0x12C3C200 // java/lang/StackTraceElement
    Object flags = 0x00000000;
    J lockword = 0x0000000000000000 (offset = 0) (java/lang/Object) <hidden>
    Ljava/lang/String; moduleName = !fj9object 0x0 (offset = 8) (java/lang/StackTraceElement)
    Ljava/lang/String; moduleVersion = !fj9object 0x0 (offset = 16) (java/lang/StackTraceElement)
    Ljava/lang/String; classLoaderName = !fj9object 0x0 (offset = 24) (java/lang/StackTraceElement)
    Z includeClassLoaderName = 0x00000000 (offset = 64) (java/lang/StackTraceElement)
    Z includeModuleVersion = 0x00000000 (offset = 68) (java/lang/StackTraceElement)
    Ljava/lang/String; declaringClass = !fj9object 0x0 (offset = 32) (java/lang/StackTraceElement)
    Ljava/lang/String; methodName = !fj9object 0x0 (offset = 40) (java/lang/StackTraceElement)
    Ljava/lang/String; fileName = !fj9object 0x0 (offset = 48) (java/lang/StackTraceElement)
    I lineNumber = 0x00000000 (offset = 72) (java/lang/StackTraceElement)
    Ljava/lang/Object; source = !fj9object 0x0 (offset = 56) (java/lang/StackTraceElement)
}

Throwable:
!J9Object 0x0000000032D7A478 {
    struct J9Class* clazz = !j9class 0x12C3F600 // java/lang/Exception
    Object flags = 0x00000000;
    J lockword = 0x0000000000000000 (offset = 0) (java/lang/Object) <hidden>
    Ljava/lang/String; detailMessage = !fj9object 0x0 (offset = 8) (java/lang/Throwable)
    Ljava/lang/Object; walkback = !fj9object 0x32d7a4b8 (offset = 16) (java/lang/Throwable)
    Ljava/lang/Throwable; cause = !fj9object 0x32d7a478 (offset = 24) (java/lang/Throwable)
    [Ljava/lang/StackTraceElement; stackTrace = !fj9object 0x32d7a5c8 (offset = 32) (java/lang/Throwable)
    Ljava/util/List; suppressedExceptions = !fj9object 0x12ebea58 (offset = 40) (java/lang/Throwable)
    Z disableWritableStackTrace = 0x00000000 (offset = 48) (java/lang/Throwable)
}
gacholio commented 2 years ago 
> !fj9object 0x32d7a4b8 
!J9IndexableObject 0x0000000032D7A4B8 {
    struct J9Class* clazz = !j9arrayclass 0x1299BD00   // [J
    Object flags = 0x00000000;
    U_32 size = 0x00000009;
    [0] = 140677277285772, 0x00007ff1fb23fd8c, 0.00000000F
    [1] = 1289091115, 0x000000004cd5f82b, 0.00000000F
    [2] = 140677277224259, 0x00007ff1fb230d43, 0.00000000F
    [3] = 996815821, 0x000000003b6a33cd, 0.00000000F
    [4] = 1283863024, 0x000000004c8631f0, 0.00000000F
    [5] = 1283863650, 0x000000004c863462, 0.00000000F
    [6] = 1282623089, 0x000000004c734671, 0.00000000F
    [7] = 1600575998, 0x000000005f66d9fe, 0.00000000F
    [8] = 1282494401, 0x000000004c714fc1, 0.00000000F
}
> !jitmetadatafrompc 0x00007ff1fb23fd8c
> 
> !findmethodfrompc 0x00007ff1fb23fd8c
Searching for PC=0x00007FF1FB23FD8C in VM=0x00007FF1FB00B820...
!j9method 0x00007FF1FB241128 LoggerInterfaceTest$LoggerImpl.log(Ljava/lang/System$Logger$Level;Ljava/util/ResourceBundle;Ljava/lang/String;[Ljava/lang/Object;)V
Bytecode PC offset = 0x000000000000001C

So the log frame is in the walkback array correctly, it seems.

gacholio commented 2 years ago

The code which decodes the PC into the various fields is: https://github.com/eclipse-openj9/openj9/blob/0f92184aec12c9963f3efd588a2f91ed258e287d/runtime/vm/exceptiondescribe.c#L333-L390

gacholio commented 2 years ago

To end up with nothing, either the ROM or RAM class was not found. This is not an anon class, so the RAM class peek should work. The test does not appear to be using shared classes. The class has not been replaced by HCR.

gacholio commented 2 years ago

Both the RAM and ROM class appear in the !allclasses output.

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/175

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/192

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/218

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/277

JasonFengJ9 commented 2 years ago

An internal build(osxrt1)

java version "17.0.5" 2022-10-18
IBM Semeru Runtime Certified Edition 17.0.5+2 (build 17.0.5+2)
Eclipse OpenJ9 VM 17.0.5+2 (build master-c14fe746e, JRE 17 Mac OS X amd64-64-Bit Compressed References 20221017_221 (JIT enabled, AOT enabled)
OpenJ9   - c14fe746e
OMR      - 938f0686f
JCL      - c45b90503 based on jdk-17.0.5+2)

[2022-08-27T16:25:45.365Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode650
[2022-08-27T16:25:45.365Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:-UseCompressedOops 

[2022-08-27T16:33:46.646Z] TEST: java/lang/System/Logger/interface/LoggerInterfaceTest.java

[2022-08-27T16:33:46.648Z] STDERR:
[2022-08-27T16:33:46.648Z] java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
[2022-08-27T16:33:46.648Z]   expected: log
[2022-08-27T16:33:46.648Z]     actual: <unknown method>
[2022-08-27T16:33:46.648Z]  at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
[2022-08-27T16:33:46.648Z]  at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
[2022-08-27T16:33:46.648Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-08-27T16:33:46.648Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2022-08-27T16:33:46.648Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-08-27T16:33:46.648Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2022-08-27T16:33:46.648Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2022-08-27T16:33:46.648Z]  at java.base/java.lang.Thread.run(Thread.java:857)
[2022-08-27T16:33:46.648Z] 
[2022-08-27T16:33:46.648Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2022-08-27T16:33:46.648Z] JavaTest Message: shutting down test
[2022-08-27T16:33:46.648Z] 
[2022-08-27T16:33:46.648Z] 
[2022-08-27T16:33:46.648Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Bad e.callStack[1].getMethodName(): expected: log actual: <unknown method>
[2022-08-27T16:33:46.648Z] --------------------------------------------------
[2022-08-27T16:34:56.809Z] Test results: passed: 789; failed: 1
[2022-08-27T16:34:56.809Z] Report written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16616175446632/jdk_lang_1/report/html/report.html
[2022-08-27T16:34:56.809Z] Results written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16616175446632/jdk_lang_1/work
[2022-08-27T16:34:56.809Z] Error: Some tests failed or other problems occurred.
[2022-08-27T16:34:56.809Z] 
[2022-08-27T16:34:56.809Z] jdk_lang_1_FAILED
JasonFengJ9 commented 2 years ago

An internal build(mac11x64rt05)

openjdk version "17.0.5" 2022-10-18
IBM Semeru Runtime Open Edition 17.0.5.0-m1 (build 17.0.5+5)
Eclipse OpenJ9 VM 17.0.5.0-m1 (build v0.35.0-release-1de4f14ba, JRE 17 Mac OS X amd64-64-Bit Compressed References 20221017_265 (JIT enabled, AOT enabled)
OpenJ9   - 1de4f14ba
OMR      - 938f0686f
JCL      - 37e17cdb684 based on jdk-17.0.5+5)

[2022-09-08T06:24:58.601Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode650
[2022-09-08T06:24:58.601Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:-UseCompressedOops 

[2022-09-08T06:31:54.280Z] STDERR:
[2022-09-08T06:31:54.280Z] java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
[2022-09-08T06:31:54.280Z]   expected: log
[2022-09-08T06:31:54.280Z]     actual: <unknown method>
[2022-09-08T06:31:54.280Z]  at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
[2022-09-08T06:31:54.280Z]  at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
[2022-09-08T06:31:54.280Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-09-08T06:31:54.280Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2022-09-08T06:31:54.280Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-09-08T06:31:54.280Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2022-09-08T06:31:54.281Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2022-09-08T06:31:54.281Z]  at java.base/java.lang.Thread.run(Thread.java:857)
[2022-09-08T06:31:54.281Z] 
[2022-09-08T06:31:54.281Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2022-09-08T06:31:54.281Z] JavaTest Message: shutting down test
[2022-09-08T06:31:54.281Z] 
[2022-09-08T06:31:54.281Z] 
[2022-09-08T06:31:54.281Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Bad e.callStack[1].getMethodName(): expected: log actual: <unknown method>
[2022-09-08T06:31:54.281Z] --------------------------------------------------
[2022-09-08T06:33:04.895Z] Test results: passed: 789; failed: 1
[2022-09-08T06:33:04.895Z] Report written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16626182976237/jdk_lang_1/report/html/report.html
[2022-09-08T06:33:04.895Z] Results written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16626182976237/jdk_lang_1/work
[2022-09-08T06:33:04.895Z] Error: Some tests failed or other problems occurred.
[2022-09-08T06:33:04.895Z] 
[2022-09-08T06:33:04.895Z] jdk_lang_1_FAILED
JasonFengJ9 commented 1 year ago

Internal build(win16x64rt3-10)

java version "17.0.6" 2023-01-17
IBM Semeru Runtime Certified Edition 17.0.6+4 (build 17.0.6+4)
Eclipse OpenJ9 VM 17.0.6+4 (build master-8206cebaa, JRE 17 Windows Server 2016 amd64-64-Bit Compressed References 20230117_276 (JIT enabled, AOT enabled)
OpenJ9   - 8206cebaa
OMR      - dc42afa38
JCL      - af194de7fa based on jdk-17.0.6+4)

[2022-11-26T16:07:32.577Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode650
[2022-11-26T16:07:32.949Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -XX:-UseCompressedOops 

[2022-11-26T16:14:36.937Z] TEST: java/lang/System/Logger/interface/LoggerInterfaceTest.java

[2022-11-26T16:14:36.938Z] STDERR:
[2022-11-26T16:14:36.938Z] java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
[2022-11-26T16:14:36.938Z]   expected: log
[2022-11-26T16:14:36.938Z]     actual: <unknown method>
[2022-11-26T16:14:36.938Z]  at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
[2022-11-26T16:14:36.938Z]  at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
[2022-11-26T16:14:36.938Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-11-26T16:14:36.938Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2022-11-26T16:14:36.938Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-11-26T16:14:36.938Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2022-11-26T16:14:36.938Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2022-11-26T16:14:36.938Z]  at java.base/java.lang.Thread.run(Thread.java:857)
[2022-11-26T16:14:36.938Z] 
[2022-11-26T16:14:36.938Z] JavaTest Message: Test threw exception: java.lang.RuntimeException

[2022-11-26T16:14:36.938Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Bad e.callStack[1].getMethodName(): expected: log actual: <unknown method>
[2022-11-26T16:14:36.938Z] --------------------------------------------------
[2022-11-26T16:16:01.338Z] Test results: passed: 789; failed: 1
[2022-11-26T16:16:01.338Z] Report written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16694788514704/jdk_lang_1/report/html/report.html
[2022-11-26T16:16:01.338Z] Results written to /Users/jenkins/workspace/Test_openjdk17_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16694788514704/jdk_lang_1/work
[2022-11-26T16:16:01.338Z] Error: Some tests failed or other problems occurred.
[2022-11-26T16:16:01.338Z] 
[2022-11-26T16:16:01.338Z] jdk_lang_1_FAILED

JDK17 x86-64_mac

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/511

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/514/

JasonFengJ9 commented 1 year ago

JDK11 x86-64_mac

java version "11.0.20" 2023-07-18
IBM Semeru Runtime Certified Edition 11.0.20+2 (build 11.0.20+2)
Eclipse OpenJ9 VM 11.0.20+2 (build master-1b94cba4c, JRE 11 Mac OS X amd64-64-Bit Compressed References 20230526_564 (JIT enabled, AOT enabled)
OpenJ9   - 1b94cba4c
OMR      - 779c51b95
JCL      - b111539de8 based on jdk-11.0.20+2)

[2023-05-27T01:42:49.696Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage Mode501
[2023-05-27T01:42:49.696Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:-JITServerTechPreviewMessage -Xjit -Xgcpolicy:balanced -Xnocompressedrefs 

[2023-05-27T01:47:51.250Z] TEST: java/lang/System/Logger/interface/LoggerInterfaceTest.java

[2023-05-27T01:47:51.251Z] STDERR:
[2023-05-27T01:47:51.251Z] java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
[2023-05-27T01:47:51.251Z]   expected: log
[2023-05-27T01:47:51.251Z]     actual: <unknown method>
[2023-05-27T01:47:51.251Z]  at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
[2023-05-27T01:47:51.251Z]  at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
[2023-05-27T01:47:51.251Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2023-05-27T01:47:51.251Z]  at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[2023-05-27T01:47:51.251Z]  at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2023-05-27T01:47:51.251Z]  at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[2023-05-27T01:47:51.251Z]  at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
[2023-05-27T01:47:51.251Z]  at java.base/java.lang.Thread.run(Thread.java:839)
[2023-05-27T01:47:51.251Z] 
[2023-05-27T01:47:51.251Z] JavaTest Message: Test threw exception: java.lang.RuntimeException
[2023-05-27T01:47:51.251Z] JavaTest Message: shutting down test
[2023-05-27T01:47:51.251Z] 
[2023-05-27T01:47:51.251Z] 
[2023-05-27T01:47:51.251Z] TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Bad e.callStack[1].getMethodName(): expected: log actual: <unknown method>
[2023-05-27T01:47:51.251Z] --------------------------------------------------
[2023-05-27T01:48:40.232Z] Test results: passed: 727; failed: 1
[2023-05-27T01:48:43.469Z] Report written to /Users/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16851517685650/jdk_lang_j9_0/report/html/report.html
[2023-05-27T01:48:43.469Z] Results written to /Users/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_testList_0/aqa-tests/TKG/output_16851517685650/jdk_lang_j9_0/work
[2023-05-27T01:48:43.469Z] Error: Some tests failed or other problems occurred.
[2023-05-27T01:48:43.469Z] -----------------------------------
[2023-05-27T01:48:43.469Z] jdk_lang_j9_0_FAILED
pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_OMR/16 jdk_lang_j9_0 java/lang/System/Logger/interface/LoggerInterfaceTest.java

06:21:58  STDERR:
06:21:58  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
06:21:58     expected: log
06:21:58       actual: <unknown method>
06:21:58    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
06:21:58    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_x86-64_mac_Nightly/76/ jdk_lang_1 java/lang/System/Logger/interface/LoggerInterfaceTest.java

20:02:36  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
20:02:36     expected: log
20:02:36       actual: <unknown method>
20:02:36    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
20:02:36    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly/549/ jdk_lang_j9_0 java/lang/System/Logger/interface/LoggerInterfaceTest.java

00:17:54  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
00:17:54     expected: log
00:17:54       actual: <unknown method>
00:17:54    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
00:17:54    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly_testList_1/5/ jdk_lang_j9_0 java/lang/System/Logger/interface/LoggerInterfaceTest.java

01:25:27  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
01:25:27     expected: log
01:25:27       actual: <unknown method>
01:25:27    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
01:25:27    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Release_testList_1/4 jdk_lang_j9_0 java/lang/System/Logger/interface/LoggerInterfaceTest.java

06:47:48  STDERR:
06:47:48  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
06:47:48     expected: log
06:47:48       actual: <unknown method>
06:47:48    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
06:47:48    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly_testList_1/24/ jdk_lang_j9_0 java/lang/System/Logger/interface/LoggerInterfaceTest.java

03:36:04  java.lang.RuntimeException: Bad e.callStack[1].getMethodName():
03:36:04     expected: log
03:36:04       actual: <unknown method>
03:36:04    at LoggerInterfaceTest.assertEquals(LoggerInterfaceTest.java:570)
03:36:04    at LoggerInterfaceTest.main(LoggerInterfaceTest.java:200)
pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly_testList_1/26/ jdk_lang_j9_0

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_Nightly_testList_1/27/ jdk_lang_j9_0

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_x86-64_mac_OMR_testList_1/16 jdk_lang_j9_0