Tomcat doesn't run on openjdk8-fedora

[nyh]

After fixing issues #601 and #878, tomcat still doesn't run with openjdk8-fedora. If I run

scripts/build image=openjdk8-fedora,tomcat
scripts/run.py

The result looks something like that (abridged):

OSv v0.24-366-ga70cbd0
eth0: 192.168.122.15
java.so: Starting JVM app using: io/osv/isolated/RunIsolatedJvmApp
java.so: Setting Java system classloader to IsolatingOsvSystemClassLoader and logging manager to IsolatingLogManager
...
Exception was caught while running -cp /usr/tomcat/bin/bootstrap.jar:/usr/tomcat/bin/tomcat-juli.jar -Djava.util.logging.config.file=/usr/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dcatalina.base=/usr/tomcat -Dcatalina.home=/usr/tomcat -Djava.io.tmpdir=/usr/tomcat/temp org.apache.catalina.startup.Bootstrap start exception: io.osv.isolated.ContextFailedException: java.lang.InternalError
io.osv.isolated.ContextFailedException: java.lang.InternalError
	at io.osv.isolated.Context.join(Context.java:63)
	at io.osv.isolated.IsolatedJvm.runSync(IsolatedJvm.java:159)
	at io.osv.isolated.MultiJarLoader$RunOnThread.run(MultiJarLoader.java:130)
Caused by: java.lang.InternalError
	at sun.security.ec.SunEC.initialize(Native Method)
	at sun.security.ec.SunEC.access$000(SunEC.java:49)
	at sun.security.ec.SunEC$1.run(SunEC.java:61)
	at sun.security.ec.SunEC$1.run(SunEC.java:58)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.security.ec.SunEC.<clinit>(SunEC.java:58)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:221)
	at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:206)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:206)
	at sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:187)
	at sun.security.jca.ProviderList.loadAll(ProviderList.java:282)
	at sun.security.jca.ProviderList.removeInvalid(ProviderList.java:299)
	at sun.security.jca.Providers.getFullProviderList(Providers.java:173)
	at java.security.Security.getProviders(Security.java:485)
	at org.apache.catalina.core.JreMemoryLeakPreventionListener.lifecycleEvent(JreMemoryLeakPreventionListener.java:393)
	at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
	at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90)
	at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:402)
	at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:99)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:576)
	at org.apache.catalina.startup.Catalina.load(Catalina.java:599)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:310)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:484)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at io.osv.Jvm.runMain(Jvm.java:119)
	at io.osv.isolated.IsolatedJvm.access$400(IsolatedJvm.java:30)
	at io.osv.isolated.IsolatedJvm$3.run(IsolatedJvm.java:116)

It seems to me that the relevant part of this trace is:

	at sun.security.ec.SunEC.initialize(Native Method)
	at sun.security.ec.SunEC.access$000(SunEC.java:49)
	at sun.security.ec.SunEC$1.run(SunEC.java:61)
	at sun.security.ec.SunEC$1.run(SunEC.java:58)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.security.ec.SunEC.<clinit>(SunEC.java:58)

Which would mean there is a problem in this internal Java method (so I'll need to look at its code next)... However, there are many lines above implying this might have something to do with the "isolation" stuff. @wkozaczuk have you ever seen something like this?

[wkozaczuk]

Nadav, I have not seen it but can you try to build and run it in non-isolated mode: scripts/build image=java-non-isolated,openjdk8-fedora,tomcat Waldek PS. I need to create a Wiki page that better documents all ways that Java apps can be built and what the difference is.

…

On Thu, Jun 8, 2017 at 8:43 AM, nyh ***@***.***> wrote: After fixing issues #601 <#601> and #878 <#878>, tomcat still doesn't run with openjdk8-fedora. If I run scripts/build image=openjdk8-fedora,tomcat scripts/run.py The result looks something like that (abridged): OSv v0.24-366-ga70cbd0 eth0: 192.168.122.15 java.so: Starting JVM app using: io/osv/isolated/RunIsolatedJvmApp java.so: Setting Java system classloader to IsolatingOsvSystemClassLoader and logging manager to IsolatingLogManager ... Exception was caught while running -cp /usr/tomcat/bin/bootstrap.jar:/usr/tomcat/bin/tomcat-juli.jar -Djava.util.logging.config.file=/usr/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dcatalina.base=/usr/tomcat -Dcatalina.home=/usr/tomcat -Djava.io.tmpdir=/usr/tomcat/temp org.apache.catalina.startup.Bootstrap start exception: io.osv.isolated.ContextFailedException: java.lang.InternalError io.osv.isolated.ContextFailedException: java.lang.InternalError at io.osv.isolated.Context.join(Context.java:63) at io.osv.isolated.IsolatedJvm.runSync(IsolatedJvm.java:159) at io.osv.isolated.MultiJarLoader$RunOnThread.run(MultiJarLoader.java:130) Caused by: java.lang.InternalError at sun.security.ec.SunEC.initialize(Native Method) at sun.security.ec.SunEC.access$000(SunEC.java:49) at sun.security.ec.SunEC$1.run(SunEC.java:61) at sun.security.ec.SunEC$1.run(SunEC.java:58) at java.security.AccessController.doPrivileged(Native Method) at sun.security.ec.SunEC.<clinit>(SunEC.java:58) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at java.lang.Class.newInstance(Class.java:442) at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:221) at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:206) at java.security.AccessController.doPrivileged(Native Method) at sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:206) at sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:187) at sun.security.jca.ProviderList.loadAll(ProviderList.java:282) at sun.security.jca.ProviderList.removeInvalid(ProviderList.java:299) at sun.security.jca.Providers.getFullProviderList(Providers.java:173) at java.security.Security.getProviders(Security.java:485) at org.apache.catalina.core.JreMemoryLeakPreventionListener.lifecycleEvent(JreMemoryLeakPreventionListener.java:393) at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117) at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90) at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:402) at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:99) at org.apache.catalina.startup.Catalina.load(Catalina.java:576) at org.apache.catalina.startup.Catalina.load(Catalina.java:599) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:310) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:484) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at io.osv.Jvm.runMain(Jvm.java:119) at io.osv.isolated.IsolatedJvm.access$400(IsolatedJvm.java:30) at io.osv.isolated.IsolatedJvm$3.run(IsolatedJvm.java:116) It seems to me that the relevant part of this trace is: at sun.security.ec.SunEC.initialize(Native Method) at sun.security.ec.SunEC.access$000(SunEC.java:49) at sun.security.ec.SunEC$1.run(SunEC.java:61) at sun.security.ec.SunEC$1.run(SunEC.java:58) at java.security.AccessController.doPrivileged(Native Method) at sun.security.ec.SunEC.<clinit>(SunEC.java:58) Which would mean there is a problem in this internal Java method (so I'll need to look at its code next)... However, there are many lines above implying this might have something to do with the "isolation" stuff. @wkozaczuk <https://github.com/wkozaczuk> have you ever seen something like this? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#880>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFDSIctT3tKOOobsQUyYOoDOnRjzbGO5ks5sB-x4gaJpZM4N0BAN> .

[wkozaczuk]

I looked at the java code sun.security.ec.SunEC and this line that is part of the static initializer section of this class is a culprit: System.loadLibrary <http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/7-b147/java/lang/System.java#System.loadLibrary%28java.lang.String%29> ("sunec"); // check for native library This means that libsunec.so is missing or is not in the right place. I noticed that you tried to add libsunec.so in this commit - cloudius-systems/osv-apps@44b9b61 . Waldek On Thu, Jun 8, 2017 at 8:57 AM, Waldek Kozaczuk <jwkozaczuk@gmail.com> wrote:

…

Nadav, I have not seen it but can you try to build and run it in non-isolated mode: scripts/build image=java-non-isolated,openjdk8-fedora,tomcat Waldek PS. I need to create a Wiki page that better documents all ways that Java apps can be built and what the difference is. On Thu, Jun 8, 2017 at 8:43 AM, nyh ***@***.***> wrote: > After fixing issues #601 > <#601> and #878 > <#878>, tomcat still > doesn't run with openjdk8-fedora. If I run > > scripts/build image=openjdk8-fedora,tomcat > scripts/run.py > > The result looks something like that (abridged): > > OSv v0.24-366-ga70cbd0 > eth0: 192.168.122.15 > java.so: Starting JVM app using: io/osv/isolated/RunIsolatedJvmApp > java.so: Setting Java system classloader to IsolatingOsvSystemClassLoader and logging manager to IsolatingLogManager > ... > Exception was caught while running -cp /usr/tomcat/bin/bootstrap.jar:/usr/tomcat/bin/tomcat-juli.jar -Djava.util.logging.config.file=/usr/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dcatalina.base=/usr/tomcat -Dcatalina.home=/usr/tomcat -Djava.io.tmpdir=/usr/tomcat/temp org.apache.catalina.startup.Bootstrap start exception: io.osv.isolated.ContextFailedException: java.lang.InternalError > io.osv.isolated.ContextFailedException: java.lang.InternalError > at io.osv.isolated.Context.join(Context.java:63) > at io.osv.isolated.IsolatedJvm.runSync(IsolatedJvm.java:159) > at io.osv.isolated.MultiJarLoader$RunOnThread.run(MultiJarLoader.java:130) > Caused by: java.lang.InternalError > at sun.security.ec.SunEC.initialize(Native Method) > at sun.security.ec.SunEC.access$000(SunEC.java:49) > at sun.security.ec.SunEC$1.run(SunEC.java:61) > at sun.security.ec.SunEC$1.run(SunEC.java:58) > at java.security.AccessController.doPrivileged(Native Method) > at sun.security.ec.SunEC.<clinit>(SunEC.java:58) > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) > at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) > at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) > at java.lang.reflect.Constructor.newInstance(Constructor.java:423) > at java.lang.Class.newInstance(Class.java:442) > at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:221) > at sun.security.jca.ProviderConfig$2.run(ProviderConfig.java:206) > at java.security.AccessController.doPrivileged(Native Method) > at sun.security.jca.ProviderConfig.doLoadProvider(ProviderConfig.java:206) > at sun.security.jca.ProviderConfig.getProvider(ProviderConfig.java:187) > at sun.security.jca.ProviderList.loadAll(ProviderList.java:282) > at sun.security.jca.ProviderList.removeInvalid(ProviderList.java:299) > at sun.security.jca.Providers.getFullProviderList(Providers.java:173) > at java.security.Security.getProviders(Security.java:485) > at org.apache.catalina.core.JreMemoryLeakPreventionListener.lifecycleEvent(JreMemoryLeakPreventionListener.java:393) > at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117) > at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90) > at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:402) > at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:99) > at org.apache.catalina.startup.Catalina.load(Catalina.java:576) > at org.apache.catalina.startup.Catalina.load(Catalina.java:599) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:498) > at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:310) > at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:484) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:498) > at io.osv.Jvm.runMain(Jvm.java:119) > at io.osv.isolated.IsolatedJvm.access$400(IsolatedJvm.java:30) > at io.osv.isolated.IsolatedJvm$3.run(IsolatedJvm.java:116) > > It seems to me that the relevant part of this trace is: > > at sun.security.ec.SunEC.initialize(Native Method) > at sun.security.ec.SunEC.access$000(SunEC.java:49) > at sun.security.ec.SunEC$1.run(SunEC.java:61) > at sun.security.ec.SunEC$1.run(SunEC.java:58) > at java.security.AccessController.doPrivileged(Native Method) > at sun.security.ec.SunEC.<clinit>(SunEC.java:58) > > Which would mean there is a problem in this internal Java method (so I'll > need to look at its code next)... However, there are many lines above > implying this might have something to do with the "isolation" stuff. > @wkozaczuk <https://github.com/wkozaczuk> have you ever seen something > like this? > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > <#880>, or mute the thread > <https://github.com/notifications/unsubscribe-auth/AFDSIctT3tKOOobsQUyYOoDOnRjzbGO5ks5sB-x4gaJpZM4N0BAN> > . >

[nyh]

That commit was about adding some of the prerequisites of libsunsec.so - when I saw that libsunsec.so was being loaded, and calling non-existant functions because ts prerequisite libraries weren't found. But maybe my commit to clean up the directory link ruined things?
Anyway, I'm surprised at your finding, because the trace:

	at sun.security.ec.SunEC.initialize(Native Method)
	at sun.security.ec.SunEC.access$000(SunEC.java:49)

suggested to me that what failed was the native method - i.e., libsunec.so was successfully loaded but then its initialization function failed. But I probably misunderstood this. Anyway, need to look at the OpenJDK 8 code, not OpenJDK 7.

[nyh]

Turns out the faulting initialize() code comes from a Fedora-specific patch, it's not in the original openjdk code. The library itself loads well, it's just the initialize() call which is failing:

--- openjdk/jdk/src/share/classes/sun/security/ec/SunEC.java    Wed Jan 27 03:45
:06 2016 +0000
+++ openjdk/jdk/src/share/classes/sun/security/ec/SunEC.java    Wed Jan 27 04:02
:27 2016 +0000
@@ -58,6 +58,7 @@
             AccessController.doPrivileged(new PrivilegedAction<Void>() {
                 public Void run() {
                     System.loadLibrary("sunec"); // check for native library
+                    initialize();
                     return null;
                 }
             });

I'm continuing to investigate.

[nyh]

The initialize() function (see Fedora's pr2815.patch) does

+JNIEXPORT void
+JNICALL Java_sun_security_ec_SunEC_initialize
+  (JNIEnv *env, jclass UNUSED(clazz))
+{
+#ifdef SYSTEM_NSS
+    if (SECOID_Init() != SECSuccess) {
+       ThrowException(env, INTERNAL_ERROR);
+    }
+#endif
+}

This SECOID_Init() is libnss stuff. I have no idea what it's supposed to do. Continuing to investigate :-)

[nyh]

Wow, this bug is really frustrating.
I ran SECOID_Init() myself in the same image, and it works (returns 0, i.e., SECSuccess).
When I print out the functions being resolved, I notice that when Java calls this initialize() function, somehow (I'm not sure exactly how), NSS_Init() gets called as well. It seems to me now that it is that function that fails (and somehow causes SECOID_Init() to fail). I also notice this failure happens right after a dladdr() which fails to find the requested symbol, I am guessing maybe one of the modules /usr/lib64/libnss* are not installed - although I can't explain why I don't see any error messages.
I also suspected that NSS_Init() might be failing because we installed antique version of ca-certificates, but updating it to the latest ca-certificates package did not help, unfortunately.
I also can't explain why my own call of SECOID_Init() succeeded, but Java's ended up calling NSS_Init() and failing...
What a mess...

[wkozaczuk]

I was trying to reproduce and I get this error when building: rm -rf install mkdir -p install/usr ln -s lib install/usr/lib64 rpm2cpio upstream/java-1.8.0-openjdk-headless-1.8.0.131-2.b12.fc27.x86_64.rpm | (cd install && cpio -id) 212935 blocks # Move the versioned java directory to the generic "java" name, but # keep a link at the versioned name: mv install/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.131-2.b12.fc27.x86_64 install/usr/lib/jvm/java ln -sf java install/usr/lib/jvm/java-1.8.0-openjdk-1.8.0.131-2.b12.fc27.x86_64 rm -rf install/usr/lib/jvm/java/jre/lib/security/cacerts rm -rf install/usr/lib/jvm/java/jre/lib/audio/* rpm2cpio upstream/tzdata-java-2017b-1.fc27.noarch.rpm | (cd install && cpio -id) 846 blocks rpm2cpio upstream/nspr-4.14.0-2.fc27.x86_64.rpm | (cd install && cpio -id) cpio: Can't write over symlinks: ./usr/lib64/libnspr4.so Makefile:47: recipe for target 'module' failed make: *** [module] Error 1 Traceback (most recent call last): File "scripts/module.py", line 272, in <module> args.func(args) File "scripts/module.py", line 227, in build make_modules(modules, args) File "scripts/module.py", line 124, in make_modules raise Exception('make failed for ' + module.name) Exception: make failed for openjdk8-fedora ./scripts/build failed: jdkbase=$jdkbase ARCH=$arch mode=$mode OSV_BASE=$SRC OSV_BUILD_PATH=$OSV_BUILD_PATH scripts/module.py $j_arg build -c $modules $usrskel_arg BTW I was able to successfully build and run tomcat against full open jdk 8 zulu. I will be sending a patch soon. Waldek

…

On Fri, Jun 9, 2017 at 12:37 PM, nyh ***@***.***> wrote: Wow, this bug is really frustrating. I ran SECOID_Init() myself in the same image, and it works (returns 0, i.e., SECSuccess). When I print out the functions being resolved, I notice that when Java calls this initialize() function, somehow (I'm not sure exactly how), NSS_Init() gets called as well. It seems to me now that it is *that* function that fails (and somehow causes SECOID_Init() to fail). I also notice this failure happens right after a dladdr() which fails to find the requested symbol, I am guessing maybe one of the modules /usr/lib64/libnss* are not installed - although I can't explain why I don't see any error messages. I also suspected that NSS_Init() might be failing because we installed antique version of ca-certificates, but updating it to the latest ca-certificates package did not help, unfortunately. I also can't explain why my own call of SECOID_Init() succeeded, but Java's ended up calling NSS_Init() and failing... What a mess... — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#880 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFDSIUQ3gzqh40C5XngdZF-U0TS0Zn4Aks5sCXTcgaJpZM4N0BAN> .

[nyh]

Same problem when trying to run apache-derby with openjdk8-fedora:

scripts/build image=openjdk8-fedora,apache-derby

[wkozaczuk]

Fixed by cloudius-systems/osv-apps@682f9da