Bug 63875 - Tomcat 8.5.46, APR/libtcnative crashes
Summary: Tomcat 8.5.46, APR/libtcnative crashes
Status: RESOLVED INVALID
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Connectors (show other bugs)
Version: unspecified
Hardware: PC Linux
: P2 major (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-10-23 05:56 UTC by sachin.pipal1
Modified: 2019-11-21 20:39 UTC (History)
1 user (show)



Attachments
hs_err_pid6113 log (103.60 KB, text/plain)
2019-10-23 05:59 UTC, sachin.pipal1
Details
hs_err_pid14911 log (162.86 KB, text/plain)
2019-10-23 06:01 UTC, sachin.pipal1
Details
JVM log on tomcat9 (150.58 KB, text/plain)
2019-10-25 07:33 UTC, sachin.pipal1
Details
runlog on tomcat9 (8.83 KB, text/plain)
2019-10-25 07:34 UTC, sachin.pipal1
Details
application log on tomcat9 (14.25 KB, text/plain)
2019-10-25 07:34 UTC, sachin.pipal1
Details

Note You need to log in before you can comment on or make changes to this bug.
Description sachin.pipal1 2019-10-23 05:56:50 UTC
Hello,

Tomcat 8.5.46 crash randomly.Please find the attached logs regaring the same.

Please find below inline APR,openssl version.
Apache Tomcat/8.5.46
Loaded APR based Apache Tomcat Native library [1.2.21].
APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true].
OpenSSL successfully initialized [OpenSSL 1.0.2s  28 May 2019]


2019-10-22 17:22:51.313, INFO, org.apache.coyote.http11.Http11NioProtocolorg.apache.coyote.AbstractProtocol init
 - Initializing ProtocolHandler ["http-nio-auto-1"]
2019-10-22 17:22:51.342, INFO, org.apache.tomcat.util.net.NioSelectorPoolorg.apache.tomcat.util.net.NioSelectorPool getSharedSelector
 - Using a shared selector for servlet write/read
2019-10-22 17:22:51.364, INFO, org.apache.catalina.core.StandardServiceorg.apache.catalina.core.StandardService startInternal
 - Starting service [Tomcat]
2019-10-22 17:22:51.364, INFO, org.apache.catalina.core.StandardEngineorg.apache.catalina.core.StandardEngine startInternal
 - Starting Servlet Engine: Apache Tomcat/8.5.46
2019-10-22 17:22:52.109, INFO, org.apache.catalina.startup.ContextConfigorg.apache.catalina.startup.ContextConfig getDefaultWebXmlFragment
 - No global web.xml found
2019-10-22 17:22:52.478, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:52.792, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/M]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:52.814, INFO, org.apache.coyote.http11.Http11NioProtocolorg.apache.coyote.AbstractProtocol start
 - Starting ProtocolHandler ["http-nio-auto-1-45763"]
2019-10-22 17:22:52.863, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1.1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-22 17:22:52.863, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-22 17:22:52.889, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener lifecycleEvent
 - An older version [1.2.21] of the APR based Apache Tomcat Native library is installed, while Tomcat recommends a minimum version of [1.2.23]
2019-10-22 17:22:52.890, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener lifecycleEvent
 - Loaded APR based Apache Tomcat Native library [1.2.21] using APR version [1.7.0].
2019-10-22 17:22:52.890, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener lifecycleEvent
 - APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
2019-10-22 17:22:52.890, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener lifecycleEvent
 - APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
2019-10-22 17:22:52.897, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener initializeSSL
 - OpenSSL successfully initialized [OpenSSL 1.0.2s  28 May 2019]
2019-10-22 17:22:52.901, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.http11.AbstractHttp11Protocol configureUpgradeProtocol
 - The ["https-openssl-nio2-7093"] connector has been configured to support negotiation to [h2] via ALPN
2019-10-22 17:22:52.902, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.AbstractProtocol init
 - Initializing ProtocolHandler ["https-openssl-nio2-7093"]
2019-10-22 17:22:52.973, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.AbstractProtocol start
 - Starting ProtocolHandler ["https-openssl-nio2-7093"]
2019-10-22 17:22:52.977, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1.1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-22 17:22:52.978, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-22 17:22:52.978, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.http11.AbstractHttp11Protocol configureUpgradeProtocol
 - The ["https-openssl-nio2-7092"] connector has been configured to support negotiation to [h2] via ALPN
2019-10-22 17:22:52.980, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.AbstractProtocol init
 - Initializing ProtocolHandler ["https-openssl-nio2-7092"]
2019-10-22 17:22:52.988, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.AbstractProtocol start
 - Starting ProtocolHandler ["https-openssl-nio2-7092"]
2019-10-22 17:22:52.991, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1.1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-22 17:22:52.991, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-22 17:22:52.992, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.http11.AbstractHttp11Protocol configureUpgradeProtocol
 - The ["https-openssl-nio2-7090"] connector has been configured to support negotiation to [h2] via ALPN
2019-10-22 17:22:52.992, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.AbstractProtocol init
 - Initializing ProtocolHandler ["https-openssl-nio2-7090"]
2019-10-22 17:22:53.002, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.AbstractProtocol start
 - Starting ProtocolHandler ["https-openssl-nio2-7090"]
2019-10-22 17:22:53.075, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/rest]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:53.076, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/rest3]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:53.076, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/rest2]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:54.073, INFO, org.apache.catalina.core.StandardContextorg.apache.catalina.core.StandardContext reload
 - Reloading Context with name [/rest2] has started
2019-10-22 17:22:54.073, INFO, org.apache.catalina.core.StandardContextorg.apache.catalina.core.StandardContext reload
 - Reloading Context with name [/rest] has started
2019-10-22 17:22:54.073, INFO, org.apache.catalina.core.StandardContextorg.apache.catalina.core.StandardContext reload
 - Reloading Context with name [/rest3] has started
2019-10-22 17:22:54.119, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/rest]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:54.133, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/rest2]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:54.133, INFO, org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/rest3]org.apache.catalina.core.ApplicationContext log
 - No Spring WebApplicationInitializer types detected on classpath
2019-10-22 17:22:54.504, INFO, org.apache.catalina.core.StandardContextorg.apache.catalina.core.StandardContext reload
 - Reloading Context with name [/rest3] is completed
2019-10-22 17:22:54.551, INFO, org.apache.catalina.core.StandardContextorg.apache.catalina.core.StandardContext reload
 - Reloading Context with name [/rest] is completed
2019-10-22 17:22:54.557, INFO, org.apache.catalina.core.StandardContextorg.apache.catalina.core.StandardContext reload
 - Reloading Context with name [/rest2] is completed
Comment 1 sachin.pipal1 2019-10-23 05:59:35 UTC
Created attachment 36855 [details]
hs_err_pid6113 log

Problematic frame:
# C  [libtcnative-1.so+0x20d99a]  apr_pool_cleanup_kill+0x3a
Comment 2 sachin.pipal1 2019-10-23 06:01:11 UTC
Created attachment 36856 [details]
hs_err_pid14911 log

# Problematic frame:
# C  [libtcnative-1.so+0x14d462]  X509_VERIFY_PARAM_free+0x12
Comment 3 Mark Thomas 2019-10-23 06:38:07 UTC
Both those crashes are during shutdown of the NIO2 connector when it is using OpenSSL for TLS.

It would be worth trying an upgrade to 8.5.47 and Tomcat Native 1.2.23 although I don't see anything in the changelog that obviously matches this issue.
Comment 4 Michael Osipov 2019-10-23 08:57:34 UTC
(In reply to Mark Thomas from comment #3)
> Both those crashes are during shutdown of the NIO2 connector when it is
> using OpenSSL for TLS.
> 
> It would be worth trying an upgrade to 8.5.47 and Tomcat Native 1.2.23
> although I don't see anything in the changelog that obviously matches this
> issue.

I wonder whether the APR connector would crash here too.
Comment 5 Remy Maucherat 2019-10-23 12:23:13 UTC
It would be useful to test Tomcat 9 with NIO.
The stack indicates a crash on stop only, are the context reloads related to it ?
Comment 6 sachin.pipal1 2019-10-25 07:31:18 UTC
(In reply to Remy Maucherat from comment #5)
> It would be useful to test Tomcat 9 with NIO.
> The stack indicates a crash on stop only, are the context reloads related to
> it ?

Tested with tomcat 9.0.27 with NIO2
Loaded APR based Apache Tomcat Native library [1.2.23] using APR version [1.7.0].
OpenSSL successfully initialized [OpenSSL 1.1.1c  28 May 2019]
Please find the attached logs.(hs_err_pid27914,SERVER2.server.runlog,SERVER2.System.0)
Context reload are of during deployment of the webapp.




2019-10-25 14:35:16.602, SEVERE, module.Communication.HTTP - sachin inside3 getSSLHostConfig _default_
2019-10-25 14:35:16.602, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1.1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-25 14:35:16.602, WARNING, org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.SSLHostConfig setProtocols
 - The protocol [TLSv1] was added to the list of protocols on the SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
2019-10-25 14:35:16.609, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener lifecycleEvent
 - Loaded APR based Apache Tomcat Native library [1.2.23] using APR version [1.7.0].
2019-10-25 14:35:16.609, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener lifecycleEvent
 - APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
2019-10-25 14:35:16.609, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener lifecycleEvent
 - APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
2019-10-25 14:35:16.613, INFO, org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.AprLifecycleListener initializeSSL
 - OpenSSL successfully initialized [OpenSSL 1.1.1c  28 May 2019]
2019-10-25 14:35:16.620, INFO, org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.http11.AbstractHttp11Protocol configureUpgradeProtocol
 - The ["https-openssl-nio2-6090"] connector has been configured to support negotiation to [h2] via ALPN
Comment 7 sachin.pipal1 2019-10-25 07:33:09 UTC
Created attachment 36858 [details]
JVM log on tomcat9
Comment 8 sachin.pipal1 2019-10-25 07:34:06 UTC
Created attachment 36859 [details]
runlog on tomcat9
Comment 9 sachin.pipal1 2019-10-25 07:34:40 UTC
Created attachment 36860 [details]
application log on tomcat9
Comment 10 sachin.pipal1 2019-10-25 07:36:22 UTC
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.202-b08 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# C  [libtcnative-1.so+0x2c61be]  apr_pool_cleanup_kill+0x3a
#



Stack: [0x00007f91865ec000,0x00007f91866ed000],  sp=0x00007f91866eb110,  free space=1020k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  [libtcnative-1.so+0x2c61be]  apr_pool_cleanup_kill+0x3a
C  [libtcnative-1.so+0x2c632c]  apr_pool_cleanup_run+0x2b
j  org.apache.tomcat.jni.SSLContext.free(J)I+0
j  org.apache.tomcat.util.net.openssl.OpenSSLContext.destroy()V+25
j  org.apache.tomcat.util.net.AbstractEndpoint.releaseSSLContext(Lorg/apache/tomcat/util/net/SSLHostConfig;)V+50
j  org.apache.tomcat.util.net.AbstractEndpoint.destroySsl()V+43
j  org.apache.tomcat.util.net.Nio2Endpoint.unbind()V+16
j  org.apache.tomcat.util.net.AbstractEndpoint.destroy()V+11
j  org.apache.coyote.AbstractProtocol.destroy()V+48
j  org.apache.catalina.connector.Connector.destroyInternal()V+11
j  org.apache.catalina.util.LifecycleBase.destroy()V+239
j  cmg.protocols.http.EmbeddedTomcat.stopService(Ljava/lang/String;)V+97
j  cmg.protocols.http.TomcatController.removeConnector(Ljava/lang/String;)Z+4
j  cmg.stdapp.restservices.frontend.RestWebServicesFE.deactivate()V+31
j  cmg.services.ConfigurableNodeImpl.stop(Lcom/ericsson/cm/common/configurationmanagement/javabeans/online/ConfigId;ZZZ)Z+146
j  cmg.communicationmanager.controller.NodeConfigurationHandler.handleManagerRequest(Lcom/ericsson/cm/common/messagingframework/javabeans/Message;)V+1032
j  cmg.communicationmanager.controller.ManagerRequestHandler$RequestHandlerThread.run()V+299
J 4767 C1 java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V (225 bytes) @ 0x00007f9205dedeb4 [0x00007f9205dece80+0x1034]
Comment 11 sachin.pipal1 2019-10-25 07:36:49 UTC
(In reply to sachin.pipal1 from comment #6)
> (In reply to Remy Maucherat from comment #5)
> > It would be useful to test Tomcat 9 with NIO.
> > The stack indicates a crash on stop only, are the context reloads related to
> > it ?
> 
> Tested with tomcat 9.0.27 with NIO2
> Loaded APR based Apache Tomcat Native library [1.2.23] using APR version
> [1.7.0].
> OpenSSL successfully initialized [OpenSSL 1.1.1c  28 May 2019]
> Please find the attached
> logs.(hs_err_pid27914,SERVER2.server.runlog,SERVER2.System.0)
> Context reload are of during deployment of the webapp.
> 
> 
> 
> 
> 2019-10-25 14:35:16.602, WARNING,
> org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.
> SSLHostConfig setProtocols
>  - The protocol [TLSv1.1] was added to the list of protocols on the
> SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
> 2019-10-25 14:35:16.602, WARNING,
> org.apache.tomcat.util.net.SSLHostConfigorg.apache.tomcat.util.net.
> SSLHostConfig setProtocols
>  - The protocol [TLSv1] was added to the list of protocols on the
> SSLHostConfig named [_default_]. Check if a +/- prefix is missing.
> 2019-10-25 14:35:16.609, INFO,
> org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.
> AprLifecycleListener lifecycleEvent
>  - Loaded APR based Apache Tomcat Native library [1.2.23] using APR version
> [1.7.0].
> 2019-10-25 14:35:16.609, INFO,
> org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.
> AprLifecycleListener lifecycleEvent
>  - APR capabilities: IPv6 [true], sendfile [true], accept filters [false],
> random [true].
> 2019-10-25 14:35:16.609, INFO,
> org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.
> AprLifecycleListener lifecycleEvent
>  - APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
> 2019-10-25 14:35:16.613, INFO,
> org.apache.catalina.core.AprLifecycleListenerorg.apache.catalina.core.
> AprLifecycleListener initializeSSL
>  - OpenSSL successfully initialized [OpenSSL 1.1.1c  28 May 2019]
> 2019-10-25 14:35:16.620, INFO,
> org.apache.coyote.http11.Http11Nio2Protocolorg.apache.coyote.http11.
> AbstractHttp11Protocol configureUpgradeProtocol
>  - The ["https-openssl-nio2-6090"] connector has been configured to support
> negotiation to [h2] via ALPN
Comment 12 Remy Maucherat 2019-10-29 08:35:46 UTC
Ok, so this is clearly embedded (don't see why it would make a difference yet) and it crashes on shutdown.

Can you also test NIO (the default connector) with Tomcat 9 ?
Also can you give details about your use (we need to be able to reproduce the crash) ?
Comment 13 sachin.pipal1 2019-10-31 11:29:00 UTC
(In reply to Remy Maucherat from comment #12)
> Ok, so this is clearly embedded (don't see why it would make a difference
> yet) and it crashes on shutdown.
> 
> Can you also test NIO (the default connector) with Tomcat 9 ?
> Also can you give details about your use (we need to be able to reproduce
> the crash) ?


Same error encountered with  tomcat 9 +NIO.

We are using embedded tomcat and deploying multiple restful services over HTTP2 protcol.Tomcat crashes randomly within 10 -12 minutes while stopping/starting the one of the multiple deployed rest web application and getting Libtcnative crashes error in log.
Comment 14 sachin.pipal1 2019-11-01 04:18:11 UTC
(In reply to sachin.pipal1 from comment #13)
> (In reply to Remy Maucherat from comment #12)
> > Ok, so this is clearly embedded (don't see why it would make a difference
> > yet) and it crashes on shutdown.
> > 
> > Can you also test NIO (the default connector) with Tomcat 9 ?
> > Also can you give details about your use (we need to be able to reproduce
> > the crash) ?
> 
> 
> Same error encountered with  tomcat 9 +NIO.
> 
> We are using embedded tomcat and deploying multiple restful services over
> HTTP2 protcol.Tomcat crashes randomly within 10 -12 minutes while
> stopping the one of the multiple deployed rest web application and
> getting Libtcnative crashes error in log.
Comment 15 Remy Maucherat 2019-11-01 08:42:51 UTC
We got and read your latest comment with the additional testing.
However, pinging developers for updates is not acceptable behavior. Please don't do this again.
Comment 16 Mark Thomas 2019-11-07 16:34:19 UTC
I have tried, and failed, to recreate this. Please provide the simplest possible test case that re-creates the issue.
Comment 17 sachin.pipal1 2019-11-14 03:54:02 UTC
Marking resolved this issue, as the issue was with the custom code while creating the AprLifeccycleListner the reference was getting overridden.

Thanks to all who supported during the time.

Thanks
Sachin
Comment 18 Christopher Schultz 2019-11-14 04:16:02 UTC
Was this caused by custom native code of custom Java code?

I would argue that, unless you went into the C stack/heap with a hatchet, (ab)using the tcnative code shouldn't cause a JVM crash. Exceptions, dropped connections, etc., sure. But the tcnative code should be protecting itself against improper usage.

Can you please share your custom code surrounding your use of AprLifecycleListener? Maybe there really is a bug, here.
Comment 19 Remy Maucherat 2019-11-21 20:39:56 UTC
Since this was using embedded with a crash only on shutdown, and given comment 17, I would say the issue was some sort of misuse of the AprLifecycleListener or the handling of the native library. The debug given didn't show an issue with the SSL context close (all it does is prevent a crash caused by a double free).