I added some debug logging to native and the Java classes and the
picture looks understandable now. Here the example from NIO and
TestCustomSsl:
- test testCustomTrustManagerNone creates OpenSSLEngine 7f560c39, ssl
4298850656 and con->pool 4309969128 from parent pool aprPool = c->pool
4306893544
- at the end of this test OpenSSLContext.destroy() runs and destroys
aprPool = c->pool 4306893544 and therefore also its child pools
including con->pool 4309969128
- later during testCustomSslImplementation the Finalizer kicks in for
the old OpenSSLEngine 7f560c39.
- The finalize() method frees the old ssl 4298850656, which was also
created in the earlier test
- Freeing that ssl in the native code destroys the con->pool 4309969128
which was already destroyed at the end of the first test
- kaboom.
24-Jan-2019 12:51:50.967 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testCustomTrustManagerNone]
24-Jan-2019 12:51:51.894 INFO [main]
org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR
based Apache Tomcat Native library [1.2.20] using APR version [1.6.5].
24-Jan-2019 12:51:51.896 INFO [main]
org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR
capabilities: IPv6 [true], sendfile [true], accept filters [false],
random [true].
24-Jan-2019 12:51:51.897 INFO [main]
org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL
configuration: useAprConnector [false], useOpenSSL [true]
24-Jan-2019 12:51:51.933 INFO [main]
org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL
successfully initialized [OpenSSL 1.0.2q 20 Nov 2018]
24-Jan-2019 12:51:53.418 INFO [main]
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-1"]
24-Jan-2019 12:51:53.537 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<clinit> Created temp
aprPool in static part of OpenSSLEngine 4306893544
24-Jan-2019 12:51:53.544 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<clinit> Created temp
SSLContext in static part of OpenSSLEngine 4306893664
Created con->pool 4307758744 from c->pool 4306893544
24-Jan-2019 12:51:53.551 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<clinit> Created temp
ssl in static part of OpenSSLEngine with con->pool 4307758744 and
c->pool 4306893544
24-Jan-2019 12:51:53.727 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<clinit> Freeing temp
ssl in static part of OpenSSLEngine with con->pool 4307758744 and
c->pool 4306893544
freeSSL destroying con->pool 430775874424-Jan-2019 12:51:53.729 SEVERE
[main] org.apache.tomcat.util.net.openssl.OpenSSLEngine.<clinit> Freeing
temp SSLContext in static part of OpenSSLEngine 4306893664
24-Jan-2019 12:51:53.731 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<clinit> Destroying
temp aprPool in static part of OpenSSLEngine 4306893544
24-Jan-2019 12:51:55.687 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.<init> Created
OpenSSLContext with aprPool 4306893544
24-Jan-2019 12:51:55.816 INFO [main]
org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a
shared selector for servlet write/read
24-Jan-2019 12:51:55.916 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service
[Tomcat]
24-Jan-2019 12:51:55.919 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
Engine: Apache Tomcat/8.5.X-rXX-dev
24-Jan-2019 12:51:56.406 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-1-36031"]
Created con->pool 4307758744 from c->pool 4306893544
24-Jan-2019 12:51:56.937 SEVERE
[https-openssl-nio-127.0.0.1-auto-1-exec-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<init> Created
OpenSSLEngine org.apache.tomcat.util.net.openssl.OpenSSLEngine@3753746,
ssl 4305791088 with con->pool 4307758744 and c->pool 4306893544
24-Jan-2019 12:51:56.940 SEVERE
[https-openssl-nio-127.0.0.1-auto-1-exec-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<init> Created
OpenSSLEngine org.apache.tomcat.util.net.openssl.OpenSSLEngine@3753746,
networkBIO 4305793296
Created con->pool 4309969128 from c->pool 4306893544
24-Jan-2019 12:51:58.394 SEVERE
[https-openssl-nio-127.0.0.1-auto-1-exec-8]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<init> Created
OpenSSLEngine org.apache.tomcat.util.net.openssl.OpenSSLEngine@7f560c39,
ssl 4298850656 with con->pool 4309969128 and c->pool 4306893544
24-Jan-2019 12:51:58.396 SEVERE
[https-openssl-nio-127.0.0.1-auto-1-exec-8]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<init> Created
OpenSSLEngine org.apache.tomcat.util.net.openssl.OpenSSLEngine@7f560c39,
networkBIO 4299567568
24-Jan-2019 12:51:58.689 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-1-36031"]
24-Jan-2019 12:51:58.703 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service
[Tomcat]
24-Jan-2019 12:51:58.787 INFO [main]
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-1-36031"]
24-Jan-2019 12:51:58.797 INFO [main]
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-1-36031"]
24-Jan-2019 12:51:58.803 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy Into
OpenSSLContext.destroy(), checking atomic...
24-Jan-2019 12:51:58.804 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy
OpenSSLContext.destroy() atomic checked
24-Jan-2019 12:51:58.805 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy
OpenSSLContext.destroy() destroying pool 4306893544
24-Jan-2019 12:51:58.855 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testCustomTrustManagerCA]
24-Jan-2019 12:51:58.867 INFO [main]
org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR
based Apache Tomcat Native library [1.2.20] using APR version [1.6.5].
24-Jan-2019 12:51:58.868 INFO [main]
org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR
capabilities: IPv6 [true], sendfile [true], accept filters [false],
random [true].
24-Jan-2019 12:51:58.869 INFO [main]
org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL
configuration: useAprConnector [false], useOpenSSL [true]
24-Jan-2019 12:51:58.876 INFO [main]
org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL
successfully initialized [OpenSSL 1.0.2q 20 Nov 2018]
24-Jan-2019 12:51:58.928 INFO [main]
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-2"]
24-Jan-2019 12:51:58.935 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.<init> Created
OpenSSLContext with aprPool 4309969128
24-Jan-2019 12:51:59.015 INFO [main]
org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a
shared selector for servlet write/read
24-Jan-2019 12:51:59.019 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service
[Tomcat]
24-Jan-2019 12:51:59.022 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
Engine: Apache Tomcat/8.5.X-rXX-dev
24-Jan-2019 12:51:59.202 INFO [main]
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-2-36035"]
Created con->pool 4304787480 from c->pool 4309969128
24-Jan-2019 12:51:59.363 SEVERE
[https-openssl-nio-127.0.0.1-auto-2-exec-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<init> Created
OpenSSLEngine org.apache.tomcat.util.net.openssl.OpenSSLEngine@5c79266,
ssl 4310084000 with con->pool 4304787480 and c->pool 4309969128
24-Jan-2019 12:51:59.367 SEVERE
[https-openssl-nio-127.0.0.1-auto-2-exec-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.<init> Created
OpenSSLEngine org.apache.tomcat.util.net.openssl.OpenSSLEngine@5c79266,
networkBIO 4303251712
24-Jan-2019 12:51:59.642 INFO [main]
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-2-36035"]
24-Jan-2019 12:51:59.645 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service
[Tomcat]
24-Jan-2019 12:51:59.666 INFO [main]
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-2-36035"]
24-Jan-2019 12:51:59.669 SEVERE
[https-openssl-nio-127.0.0.1-auto-2-ClientPoller-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown Into
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@5c79266, checking
destroyed?
24-Jan-2019 12:51:59.672 SEVERE
[https-openssl-nio-127.0.0.1-auto-2-ClientPoller-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@5c79266, calling
SSL.freeBIO() for 4303251712
24-Jan-2019 12:51:59.673 SEVERE
[https-openssl-nio-127.0.0.1-auto-2-ClientPoller-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@5c79266, calling
SSL.freeSSL() for 4310084000
freeSSL destroying con->pool 430478748024-Jan-2019 12:51:59.674 SEVERE
[https-openssl-nio-127.0.0.1-auto-2-ClientPoller-1]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@5c79266 zeroing fields
24-Jan-2019 12:51:59.683 INFO [main]
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler
["https-openssl-nio-127.0.0.1-auto-2-36035"]
24-Jan-2019 12:51:59.684 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy Into
OpenSSLContext.destroy(), checking atomic...
24-Jan-2019 12:51:59.685 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy
OpenSSLContext.destroy() atomic checked
24-Jan-2019 12:51:59.686 SEVERE [main]
org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy
OpenSSLContext.destroy() destroying pool 4309969128
24-Jan-2019 12:51:59.705 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testCustomSslImplementation]
24-Jan-2019 12:51:59.768 INFO [main]
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["https-jsse-nio-127.0.0.1-auto-3"]
24-Jan-2019 12:51:59.836 INFO [main]
org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a
shared selector for servlet write/read
24-Jan-2019 12:51:59.840 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service
[Tomcat]
24-Jan-2019 12:51:59.840 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
Engine: Apache Tomcat/8.5.X-rXX-dev
24-Jan-2019 12:52:00.118 INFO [localhost-startStop-1]
org.apache.catalina.startup.ContextConfig.getDefaultWebXmlFragment No
global web.xml found
24-Jan-2019 12:52:01.308 INFO [localhost-startStop-1]
org.apache.catalina.core.ApplicationContext.log ContextListener:
contextInitialized()
24-Jan-2019 12:52:01.312 INFO [localhost-startStop-1]
org.apache.catalina.core.ApplicationContext.log SessionListener:
contextInitialized()
24-Jan-2019 12:52:01.318 INFO [localhost-startStop-1]
org.apache.catalina.core.ApplicationContext.log ContextListener:
attributeAdded('StockTicker', 'async.Stockticker@32102196')
ContextListener:
attributeAdded('javax.websocket.server.ServerContainer',
'org.apache.tomcat.websocket.server.WsServerContainer@7bb65f0b')
24-Jan-2019 12:52:01.810 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.finalize Into
OpenSSLEngine.finalize(), calling super Finalizer
24-Jan-2019 12:52:01.812 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.finalize
OpenSSLEngine.finalize(), calling shutdown()
24-Jan-2019 12:52:01.813 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown Into
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@5c79266, checking
destroyed?
24-Jan-2019 12:52:01.815 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy Into
OpenSSLContext.destroy(), checking atomic...
24-Jan-2019 12:52:01.816 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.finalize Into
OpenSSLEngine.finalize(), calling super Finalizer
24-Jan-2019 12:52:01.817 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.finalize
OpenSSLEngine.finalize(), calling shutdown()
24-Jan-2019 12:52:01.817 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown Into
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@7f560c39, checking
destroyed?
24-Jan-2019 12:52:01.818 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@7f560c39, calling
SSL.freeBIO() for 4299567568
24-Jan-2019 12:52:01.818 SEVERE [Finalizer]
org.apache.tomcat.util.net.openssl.OpenSSLEngine.shutdown
OpenSSLEngine.shutdown() for
org.apache.tomcat.util.net.openssl.OpenSSLEngine@7f560c39, calling
SSL.freeSSL() for 4298850656
#
# A fatal error has been detected by the Java Runtime Environment:
#
# SIGBUS (0xa) at pc=0xfffffffea1a1dda0, pid=17803, tid=0x0000000000000007
#
# JRE version: Java(TM) SE Runtime Environment (8.0_201-b09) (build
1.8.0_201-b09)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.201-b09 mixed mode
solaris-sparc compressed oops)
# Problematic frame:
# C [libapr-1.so.0.6.5+0x1dda0] apr_pool_destroy+0x10
#
# Core dump written. Default location: /path/to/core or core.17803
#
# An error report file with more information is saved as:
# /path/to/hs_err_pid17803.log
[thread 56 also had an error]
#
# If you would like to submit a bug report, please visit:
# http://bugreport.java.com/bugreport/crash.jsp
#
Running org.apache.tomcat.util.net.TestCustomSsl
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0 sec
Test org.apache.tomcat.util.net.TestCustomSsl FAILED (crashed)
Regards,
Rainer
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
