Exceptions appearing in log #77

dkelsey · 2019-11-26T20:01:40Z

In exploring the state of CPF in our Delivery environment and OpenJDK11, I observed that the DLV instance, which is on OpenJDK11, had exceptions recorded in the startup logs.

Recording these here.

13-Nov-2019 02:06:01.812 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [pub#cpf-worker] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@785b665c]) and a value of type [java.lang.Class] (value [class oracle.sql.AnyDataFactory]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
13-Nov-2019 02:06:01.812 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [pub#cpf-worker] created a ThreadLocal with key of type [org.glassfish.grizzly.Writer$Reentrant$1] (value [org.glassfish.grizzly.Writer$Reentrant$1@303284d]) and a value of type [org.glassfish.grizzly.Writer.Reentrant] (value [org.glassfish.grizzly.Writer$Reentrant@7a55f71a]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
13-Nov-2019 02:06:01.812 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [pub#cpf-worker] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@599f178a]) and a value of type [org.glassfish.grizzly.ThreadCache.ObjectCache] (value [org.glassfish.grizzly.ThreadCache$ObjectCache@2300c37f]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
13-Nov-2019 02:06:01.812 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [pub#cpf-worker] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@39dbc612]) and a value of type [java.lang.Class] (value [class oracle.sql.TypeDescriptorFactory]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.

AND

13-Nov-2019 02:06:04.865 WARNING [main] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [pub#cpf] appears to have started a thread named [cpfJobScheduler-pool-thread-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 java.base@11.0.4/jdk.internal.misc.Unsafe.park(Native Method)
 java.base@11.0.4/java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
 java.base@11.0.4/java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(Unknown Source)
 java.base@11.0.4/java.util.concurrent.SynchronousQueue$TransferStack.transfer(Unknown Source)
 java.base@11.0.4/java.util.concurrent.SynchronousQueue.poll(Unknown Source)
 java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
 java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
 java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
 org.jeometry.common.logging.LoggingRunnable.run(LoggingRunnable.java:20)
 java.base@11.0.4/java.lang.Thread.run(Unknown Source)
13-Nov-2019 02:06:04.866 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [pub#cpf] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@517d14e8]) and a value of type [java.lang.Class] (value [class oracle.sql.TypeDescriptorFactory]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.
13-Nov-2019 02:06:04.866 SEVERE [main] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [pub#cpf] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@12c6ba1e]) and a value of type [java.lang.Class] (value [class oracle.sql.AnyDataFactory]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.

AND

13-Nov-2019 02:22:03.431 WARNING [main] org.apache.catalina.core.AprLifecycleListener.init The APR based Apache Tomcat Native library failed to load. The error reported was [no tcnative-1 in java.library.path: [/s00/jdk11/lib, /s00/lib, /s00/svn/lib, /lib, /lib, /usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no libtcnative-1 in java.library.path: [/s00/jdk11/lib, /s00/lib, /s00/svn/lib, /lib, /lib, /usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib](/s00/jdk11/lib:/s00/lib:/s00/svn/lib:/lib:/lib:/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib)]
        java.lang.UnsatisfiedLinkError: no tcnative-1 in java.library.path: [/s00/jdk11/lib, /s00/lib, /s00/svn/lib, /lib, /lib, /usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no libtcnative-1 in java.library.path: [/s00/jdk11/lib, /s00/lib, /s00/svn/lib, /lib, /lib, /usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib](/s00/jdk11/lib:/s00/lib:/s00/svn/lib:/lib:/lib:/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib)
                at org.apache.tomcat.jni.Library.<init>(Unknown Source)
                at org.apache.tomcat.jni.Library.initialize(Unknown Source)
                at org.apache.catalina.core.AprLifecycleListener.init(AprLifecycleListener.java:198)
                at org.apache.catalina.core.AprLifecycleListener.isAprAvailable(AprLifecycleListener.java:107)
                at org.apache.catalina.connector.Connector.<init>(Connector.java:80)
                at org.apache.catalina.startup.ConnectorCreateRule.begin(ConnectorCreateRule.java:64)
                at org.apache.tomcat.util.digester.Digester.startElement(Digester.java:1200)
                at java.xml/com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.startElement(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.parsers.AbstractXMLDocumentParser.emptyElement(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanStartElement(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(Unknown Source)
                at java.xml/com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
                at org.apache.tomcat.util.digester.Digester.parse(Digester.java:1458)
                at org.apache.catalina.startup.Catalina.load(Catalina.java:566)
                at org.apache.catalina.startup.Catalina.load(Catalina.java:607)
                at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
                at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
                at java.base/java.lang.reflect.Method.invoke(Unknown Source)
                at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:304)
                at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:474)

The text was updated successfully, but these errors were encountered:

dkelsey · 2019-11-26T20:02:27Z

catalina.2019-11-13.log.gz

dkelsey · 2019-11-26T20:04:09Z

@BK01 @mraross

dkelsey · 2019-11-26T20:06:52Z

Are these exception significant?
Is there a misconfiguration?

pauldaustin · 2019-11-26T22:26:33Z

For the last one (java.lang.UnsatisfiedLinkError: no tcnative-1 ) see the following. That's something in your tomcat instance and would likely apply to any app.

https://tomcat.apache.org/native-doc/

pauldaustin · 2019-11-27T21:27:38Z

I think I have figured out the other warnings in the logs.

Although I was shutting down some of the threads the context shutdown listener wasn't waiting for the threads to close. This caused the errors. There were also another couple of threads that weren't being stopped.

I've committed to my fork https://github.com/revolsys/cpf and am deploying to the delivery environment.

When we are ready to migrate then I'll update the bcgov/cpf repository via a pull request

dkelsey · 2019-11-27T23:56:21Z

I'll review https://tomcat.apache.org/native-doc/

dkelsey · 2019-11-29T04:46:41Z

@pauldaustin do you have APR enabled in your environment?

pauldaustin · 2019-12-02T23:18:21Z

@dkelsey No I haven't enabled it as I just have development systems

dkelsey · 2019-12-03T23:56:16Z

I had a chat with Leo and he stated that we are not using APR.
He said we use nio2 instead of APR.
I'm looking at how to deactivate APR.

dkelsey · 2019-12-04T00:12:58Z

In server.xml I commented out the APR listener and that worked.

  <!--APR library loader. Documentation at /docs/apr.html -->
  <!--
  <Listener className="org.apache.catalina.core.AprLifecycleListener" SSLEngine="on" />
  -->

After restarting there are no APR warnings.

dkelsey · 2019-12-04T00:25:49Z

Now I see a different warning in catalina.out.

NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by io.netty.util.internal.PlatformDependent0 (file:/apps/cpfcat/temp/cpf8236411159873083001jars/BGEO-1575417636409/16.jar) to field java.nio.Buffer.address
WARNING: Please consider reporting this to the maintainers of io.netty.util.internal.PlatformDependent0
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release

I've searched a little and found solutions that say update netty.

@ll911 do you have any suggestions?

Note: @pauldaustin If I find other exceptions/warning... I feel I should create a separate ticket. I'm happy to do that for this too. Your thoughts?

dkelsey · 2019-12-04T01:03:23Z

Chatting with Leo he pointed out it is the BGEO CPF Plugin.... so... I'll fix that.
To start, it has not been compiled with OpenJDK11.

dkelsey assigned pauldaustin Nov 26, 2019

dkelsey added bug question labels Nov 26, 2019

BK01 unassigned pauldaustin Nov 8, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Exceptions appearing in log #77

Exceptions appearing in log #77

dkelsey commented Nov 26, 2019

dkelsey commented Nov 26, 2019

dkelsey commented Nov 26, 2019

dkelsey commented Nov 26, 2019

pauldaustin commented Nov 26, 2019

pauldaustin commented Nov 27, 2019

dkelsey commented Nov 27, 2019

dkelsey commented Nov 29, 2019

pauldaustin commented Dec 2, 2019

dkelsey commented Dec 3, 2019

dkelsey commented Dec 4, 2019 •

edited

Loading

dkelsey commented Dec 4, 2019 •

edited

Loading

dkelsey commented Dec 4, 2019 •

edited

Loading

Exceptions appearing in log #77

Exceptions appearing in log #77

Comments

dkelsey commented Nov 26, 2019

AND

AND

dkelsey commented Nov 26, 2019

dkelsey commented Nov 26, 2019

dkelsey commented Nov 26, 2019

pauldaustin commented Nov 26, 2019

pauldaustin commented Nov 27, 2019

dkelsey commented Nov 27, 2019

dkelsey commented Nov 29, 2019

pauldaustin commented Dec 2, 2019

dkelsey commented Dec 3, 2019

dkelsey commented Dec 4, 2019 • edited Loading

dkelsey commented Dec 4, 2019 • edited Loading

dkelsey commented Dec 4, 2019 • edited Loading

dkelsey commented Dec 4, 2019 •

edited

Loading

dkelsey commented Dec 4, 2019 •

edited

Loading

dkelsey commented Dec 4, 2019 •

edited

Loading