Stacktrace should use the classloader name instead of "app//" #11452

Thihup · 2020-12-11T14:41:16Z

Currently generating the Stacktrace with the extended flag enabled, I guess it should show the classloader name.
However, there's a fixed string "app//"[1]. Probably this was used to get parity with the RI but is not according to the examples of the Javadoc [2].

[1] https://github.com/eclipse/openj9/blob/master/jcl/src/java.base/share/classes/com/ibm/oti/util/Util.java#L304
[2] https://docs.oracle.com/en/java/javase/15/docs/api/java.base/java/lang/StackTraceElement.html#toString()

tajila · 2021-01-05T14:30:54Z

@sharon-wang can you please take a look at this

sharon-wang · 2021-01-05T16:59:18Z

Sure!

sharon-wang · 2021-01-05T22:43:47Z

Running with the example program provided in #4998 (comment),

import java.lang.management.*;

public class DumpThreads {
        public static void main(String[] args) throws Throwable {
                ThreadMXBean tb = ManagementFactory.getThreadMXBean();
                ThreadInfo[] tis = tb.dumpAllThreads(true, true);
                for (ThreadInfo ti : tis) {
                        System.out.println(ti);
                }
        }
}

I am seeing similar behaviour between openj9 and the RI:

OpenJ9

	at java.management/com.ibm.java.lang.management.internal.ThreadMXBeanImpl.dumpAllThreadsImpl(Native Method)
	at java.management/com.ibm.java.lang.management.internal.ThreadMXBeanImpl.dumpAllThreadsCommon(ThreadMXBeanImpl.java:676)
	at java.management/com.ibm.java.lang.management.internal.ThreadMXBeanImpl.dumpAllThreads(ThreadMXBeanImpl.java:659)
	at app//DumpThreads.main(DumpThreads.java:6)

RI

	at java.management@16-ea/sun.management.ThreadImpl.dumpThreads0(Native Method)
	at java.management@16-ea/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:521)
	at java.management@16-ea/sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:509)
	at app//DumpThreads.main(DumpThreads.java:6)

StackTraceElement.toString() has the following format (with some caveats):

     [1]                [2]
<CLASSLOADER>/<MODULE_NAME_AND_VERSION>/<FULLY_QUALIFIED_METHOD_NAME>(<FILE_NAME>:<LINE_NUMBER>)

The caveat relevant to this issue is:

If the class loader is a built-in class loader or is not named then the first element and its following "/" are omitted as shown in "acme@2.1/org.acme.Lib.test(Lib.java:80)". If the first element is omitted and the module is an unnamed module, the second element and its following "/" are also omitted as shown in "MyClass.mash(MyClass.java:9)".

DumpThreads.java

is loaded by the AppClassLoader aka the System class loader, which is one of Java's built-in class loaders
- so, we should omit the first element ([1] CLASSLOADER) and its following "/"
is part of an unnamed module since it is not declared in a package
- so, we should also omit the second element ([2] MODULE_NAME_AND_VERSION) and its following "/"

Based on this, it would seem to me that the correct format would be:

DumpThreads.main(DumpThreads.java:6)

instead of the currently seen format by both OpenJ9 and the RI:

app//DumpThreads.main(DumpThreads.java:6)

Adding module-info for DumpThreads.java, giving it module name testModule and package name test, makes it part of a named module. Running it as a named module gives the following output:

OpenJ9

testModule/test.DumpThreads.main(DumpThreads.java:11)

RI

app/testModule/test.DumpThreads.main(DumpThreads.java:11)

I think OpenJ9 has the correct output here. We now have a named module, so testModule is correctly outputted. However we're still loading from the AppClassLoader which is a built-in classloader, so the classloader should be omitted, but the RI is still including it.

sharon-wang · 2021-01-05T22:48:44Z

@Thihup In your program, does the class fit the description of being loaded by the AppClassloader and not being part of a named module?

Thihup · 2021-01-05T22:57:34Z

From what I can tell from using both Hotspot and OpenJ9 the following happens:

If I'm using a named classloader, the name of the classloader doesn't show in the stack trace. The ClassLoader constructor has an overload which allows setting the classloader name. Most applications doesn't set it because this overload only came in JDK 9.
If I'm using a named module, it doesn't show the module version
Actually, I've never seen "app//" in normal usage, IIRC it only shows in the JConsole, but never in the stacktrace printed by the program
Yes, most of my programs are loaded by the AppClassLoader and are not part of a named module, basically any jar we run with -jar. It is only part of a named module if I start using -p lib -m module.name

Thihup · 2021-01-05T23:01:14Z

The trick is in the comment of the Javadoc:
The toString method may return two different values on two StackTraceElement instances that are equal, for example one created via the constructor, and one obtained from Throwable or StackWalker.StackFrame, where an implementation may choose to omit some element in the returned string.

Via JConsole IIRC in Hotspot they show all the information, but in normal usage, they only show the module name without version for JDK classes.
So its common to see something like in a stacktrace of Hotspot:

        at guice.servlet@4.0-gb2/com.google.inject.servlet.GuiceServletContextListener.contextInitialized(GuiceServletContextListener.java:47)
        at gitblit@1.9.1/com.gitblit.servlet.GitblitContext.contextInitialized(GitblitContext.java:145)
        at cloud.piranha.webapp.impl@21.1.0-SNAPSHOT/cloud.piranha.webapp.impl.DefaultWebApplication.lambda$initializeInitializers$13(DefaultWebApplication.java:1413)
        at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1625)
        at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)

Thihup · 2021-01-05T23:07:09Z

I'll try come up with an example of the named classloader

Thihup · 2021-01-05T23:27:44Z

Here you go:

import java.net.URLClassLoader;
import java.net.URL;

public class NamedClassLoaderTest {
    public static void main(String[] args) throws Exception {
        var cl = new URLClassLoader("cl.name", new URL[]{new URL("file:///jakarta-servlet-api.jar")}, null);
        var servletRequestWrapper = cl.loadClass("jakarta.servlet.http.Cookie");
        servletRequestWrapper.getDeclaredConstructor(String.class, String.class).newInstance
(new Object[]{null, null});
    } 
}

You will need this jar: jakarta-servlet-api.zip

Stacktrace from Hotspot:

Exception in thread "main" java.lang.reflect.InvocationTargetException
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:64)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:481)
        at NamedClassLoaderTest.main(NamedClassLoaderTest.java:10)
Caused by: java.lang.IllegalArgumentException: Name cannot be null
        at cl.name//jakarta.servlet.http.Cookie.checkValidName(Cookie.java:111)
        at cl.name//jakarta.servlet.http.Cookie.<init>(Cookie.java:99)
        ... 6 more

Stacktrace from OpenJ9:

Exception in thread "main" java.lang.reflect.InvocationTargetException
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:64)
        at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
        at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:481)
        at NamedClassLoaderTest.main(NamedClassLoaderTest.java:10)
Caused by: java.lang.IllegalArgumentException: Name cannot be null
        at jakarta.servlet.http.Cookie.checkValidName(Cookie.java:111)
        at jakarta.servlet.http.Cookie.<init>(Cookie.java:99)
        ... 6 more

Thihup · 2021-01-05T23:32:33Z

If you try to print the classloader name, you will see it is app:

System.out.println(NamedClassLoaderTest.class.getClassLoader().getName()); // => app

But they don't show it in the stacktrace, maybe only in JConsole.

Hope I've gathered enough information.

sharon-wang · 2021-01-06T06:47:54Z

Thanks @Thihup, this is great!

I see the issue is that we don't provide the classloader name at all. The only time we "happen" to provide it, is via the hardcoded app//.

We'll need some changes to printStackTraceElement() to include the classloader based on the doc

If a class is defined in an unnamed module then the second element is omitted as shown in "com.foo.loader//com.foo.bar.App.run(App.java:12)".

If the class loader is a built-in class loader or is not named then the first element and its following "/" are omitted as shown in "acme@2.1/org.acme.Lib.test(Lib.java:80)". If the first element is omitted and the module is an unnamed module, the second element and its following "/" are also omitted as shown in "MyClass.mash(MyClass.java:9)".

We already have some conditional handling for including the module version which goes in line with

The toString method may return two different values on two StackTraceElement instances that are equal, for example one created via the constructor, and one obtained from Throwable or StackWalker.StackFrame, where an implementation may choose to omit some element in the returned string.

We currently don't have info about the classloader other than its name in StackTraceElement. Currently, we have Object source in StackTraceElement, but this doesn't give us enough information. I'll have a look into how we can expose classloader info to be used for printStackTraceElement().

pshipton · 2021-01-06T15:39:52Z

Disregarding the suggestion in the title, FYI #11447 seems related to this.

sharon-wang · 2021-01-08T02:48:46Z

Opened #11601 to include the classloader in the stack trace.

With these changes, OpenJ9 now gives the following output for the example program in #11452 (comment):

Exception in thread "main" java.lang.reflect.InvocationTargetException
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
	at Main.main(Main.java:10)
Caused by: java.lang.IllegalArgumentException: Cookie name must not be null or empty
	at cl.name//jakarta.servlet.http.Cookie.<init>(Cookie.java:126)
	... 5 more

RI Output:

Exception in thread "main" java.lang.reflect.InvocationTargetException
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:78)
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:480)
	at Main.main(Main.java:10)
Caused by: java.lang.IllegalArgumentException: Cookie name must not be null or empty
	at cl.name//jakarta.servlet.http.Cookie.<init>(Cookie.java:126)
	... 6 more

Thihup added the userRaised label Dec 11, 2020

Thihup changed the title ~~Stacktrace should use the classloader name not "app//"~~ Stacktrace should use the classloader name instead of "app//" Dec 11, 2020

pshipton added the comp:vm label Dec 11, 2020

pshipton added this to the Release 0.25 (Java 16) milestone Dec 11, 2020

pshipton assigned sharon-wang Jan 5, 2021

sharon-wang mentioned this issue Jan 8, 2021

Include classloader name and module version in stack trace #11601

Merged

sharon-wang mentioned this issue Jan 8, 2021

Show module version in stack trace #11447

Closed

pshipton closed this as completed in #11601 Jan 27, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stacktrace should use the classloader name instead of "app//" #11452

Stacktrace should use the classloader name instead of "app//" #11452

Thihup commented Dec 11, 2020

tajila commented Jan 5, 2021

sharon-wang commented Jan 5, 2021

sharon-wang commented Jan 5, 2021

sharon-wang commented Jan 5, 2021

Thihup commented Jan 5, 2021 •

edited

Loading

Thihup commented Jan 5, 2021 •

edited

Loading

Thihup commented Jan 5, 2021

Thihup commented Jan 5, 2021

Thihup commented Jan 5, 2021 •

edited

Loading

sharon-wang commented Jan 6, 2021

pshipton commented Jan 6, 2021

sharon-wang commented Jan 8, 2021

Stacktrace should use the classloader name instead of "app//" #11452

Stacktrace should use the classloader name instead of "app//" #11452

Comments

Thihup commented Dec 11, 2020

tajila commented Jan 5, 2021

sharon-wang commented Jan 5, 2021

sharon-wang commented Jan 5, 2021

sharon-wang commented Jan 5, 2021

Thihup commented Jan 5, 2021 • edited Loading

Thihup commented Jan 5, 2021 • edited Loading

Thihup commented Jan 5, 2021

Thihup commented Jan 5, 2021

Thihup commented Jan 5, 2021 • edited Loading

sharon-wang commented Jan 6, 2021

pshipton commented Jan 6, 2021

sharon-wang commented Jan 8, 2021

Thihup commented Jan 5, 2021 •

edited

Loading

Thihup commented Jan 5, 2021 •

edited

Loading

Thihup commented Jan 5, 2021 •

edited

Loading