'Illegal access' error


(s0r1n) #1

A docker with Apache, Tomcat and Elasticsearch images starts and runs without issue. But after restart with docker-compose down/up , the following error occurs:

30-Nov-2018 14:49:58.857 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.5.35
30-Nov-2018 14:49:59.289 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/usr/local/tomcat/webapps/fuseki.war]
30-Nov-2018 14:50:31.033 INFO [localhost-startStop-1] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
30-Nov-2018 14:50:55.757 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.startInternal One or more listeners failed to start. Full details will be found in the appropriate container log file
30-Nov-2018 14:50:55.860 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.startInternal Context [/fuseki] startup failed due to previous errors
30-Nov-2018 14:50:56.063 WARNING [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [fuseki] appears to have started a thread named [elasticsearch[_client_][[timer]]] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
  java.lang.Thread.sleep(Native Method)
  org.elasticsearch.threadpool.ThreadPool$EstimatedTimeThread.run(ThreadPool.java:498)
30-Nov-2018 14:50:56.080 WARNING [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [fuseki] appears to have started a thread named [elasticsearch[_client_][scheduler][T#1]] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
  sun.misc.Unsafe.park(Native Method)
  java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
  java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
  java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
  java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
  java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
  java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
  java.lang.Thread.run(Thread.java:748)
30-Nov-2018 14:50:56.104 WARNING [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [fuseki] appears to have started a thread named [elasticsearch[_client_][transport_client_boss][T#1]] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
  sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
  sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
  sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
  sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
  sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
  io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:746)
  io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:391)
  io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
  java.lang.Thread.run(Thread.java:748)
30-Nov-2018 14:50:56.106 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [fuseki] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@1ec7c10]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@45226f45]) 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.
30-Nov-2018 14:50:56.120 SEVERE [localhost-startStop-1] org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [fuseki] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@1ec7c10]) and a value of type [io.netty.util.internal.InternalThreadLocalMap] (value [io.netty.util.internal.InternalThreadLocalMap@1593114a]) 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.
30-Nov-2018 14:50:56.248 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/usr/local/tomcat/webapps/fuseki.war] has finished in [56,952] ms
30-Nov-2018 14:50:56.268 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/examples]
30-Nov-2018 14:50:58.528 INFO [elasticsearch[_client_][scheduler][T#1]] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
...

to be continued... (up to 7000 chars allowed)


(s0r1n) #2

...

  java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.
         at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading(WebappClassLoaderBase.java:1348)
         at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1336)
         at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1195)
         at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1156)
         at org.elasticsearch.common.util.concurrent.ThreadContext.preserveContext(ThreadContext.java:273)
         at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.wrapRunnable(EsThreadPoolExecutor.java:159)
         at org.elasticsearch.common.util.concurrent.EsThreadPoolExecutor.execute(EsThreadPoolExecutor.java:89)
         at org.elasticsearch.threadpool.ThreadPool$ThreadedRunnable.run(ThreadPool.java:455)
         at org.elasticsearch.threadpool.ThreadPool$LoggingRunnable.run(ThreadPool.java:419)
         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
         at java.lang.Thread.run(Thread.java:748)

What is the root cause of this issue, is this related to Elasticsearch? How to fix it?
Thx in advance!


(Ryan Ernst) #3

Why are you running Elasticsearch in Tomcat? This means you are running embedded in another java application, which is not supported.


(s0r1n) #4

This configuration works on a regular server well, the problem occur with docker only,
Do you mean this configuration with docker is not supported?


(Ryan Ernst) #5

I mean running inside Tomcat, whether in docker or not, is unsupported. I'm not sure what the issue is here, but I suggest you run Elasticsearch as a server directly, not inside Tomcat.


(s0r1n) #6

Actually the Elasticsearch server runs directly in his own container. Fuseki runs in Tomcat deployed as war file (as Elasticsearch client).

The "Illegal access" error is reproducible, after a couple of restarts (with down/up) the Tomcat container will fail to start up.
Here the beginning the error should be relevant for the root cause. (In the initial description were the Catalina errors only)

> tomcat_1_df8edafe67b3 | [2018-12-06 09:21:44] TransportClientNodesService INFO  failed to connect to node [{#transport#-1}{jxrazWOgRNy6RTX2wN4qZg}{elasticsearch}{192.168.96.2:9300}], removed from nodes list
> tomcat_1_df8edafe67b3 | ConnectTransportException[[][192.168.96.2:9300] connect_timeout[30s]]; nested: AnnotatedConnectException[Connection refused: elasticsearch/192.168.96.2:9300];
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.transport.netty4.Netty4Transport.connectToChannels(Netty4Transport.java:370)
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.transport.TcpTransport.openConnection(TcpTransport.java:495)
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.transport.TcpTransport.connectToNode(TcpTransport.java:460)
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.transport.TransportService.connectToNode(TransportService.java:318)
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.client.transport.TransportClientNodesService$SimpleNodeSampler.doSample(TransportClientNodesService.java:408)
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.client.transport.TransportClientNodesService$NodeSampler.sample(TransportClientNodesService.java:354)
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.client.transport.TransportClientNodesService.addTransportAddresses(TransportClientNodesService.java:195)
> tomcat_1_df8edafe67b3 |         at org.elasticsearch.client.transport.TransportClient.addTransportAddresses(TransportClient.java:325)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.query.text.es.TextIndexES.<init>(TextIndexES.java:145)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.query.text.es.TextESDatasetFactory.createESIndex(TextESDatasetFactory.java:53)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.query.text.es.assembler.TextIndexESAssembler.open(TextIndexESAssembler.java:113)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.query.text.es.assembler.TextIndexESAssembler.open(TextIndexESAssembler.java:40)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerGroup$PlainAssemblerGroup.openBySpecificType(AssemblerGroup.java:157)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerGroup$PlainAssemblerGroup.open(AssemblerGroup.java:144)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerGroup$ExpandingAssemblerGroup.open(AssemblerGroup.java:93)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerBase.open(AssemblerBase.java:39)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerBase.open(AssemblerBase.java:35)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.query.text.assembler.TextDatasetAssembler.open(TextDatasetAssembler.java:62)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.query.text.assembler.TextDatasetAssembler.open(TextDatasetAssembler.java:42)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerGroup$PlainAssemblerGroup.openBySpecificType(AssemblerGroup.java:157)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerGroup$PlainAssemblerGroup.open(AssemblerGroup.java:144)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerGroup$ExpandingAssemblerGroup.open(AssemblerGroup.java:93)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerBase.open(AssemblerBase.java:39)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.assembler.assemblers.AssemblerBase.open(AssemblerBase.java:35)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.build.FusekiConfig.getDataset(FusekiConfig.java:272)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.build.FusekiConfig.buildDataServiceCustom(FusekiConfig.java:225)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.build.FusekiConfig.buildDataAccessPoint(FusekiConfig.java:217)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.build.FusekiConfig.servicesAndDatasets(FusekiConfig.java:126)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.webapp.FusekiSystem.processServerConfigFile(FusekiSystem.java:285)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.webapp.FusekiSystem.initServerConfiguration(FusekiSystem.java:260)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.webapp.FusekiSystem.initializeDataAccessPoints(FusekiSystem.java:225)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.webapp.FusekiServerListener.serverInitialization(FusekiServerListener.java:98)
> tomcat_1_df8edafe67b3 |         at org.apache.jena.fuseki.webapp.FusekiServerListener.contextInitialized(FusekiServerListener.java:56)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4792)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5256)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:754)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:730)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:985)
> tomcat_1_df8edafe67b3 |         at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1857)
> tomcat_1_df8edafe67b3 |         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> tomcat_1_df8edafe67b3 |         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> tomcat_1_df8edafe67b3 |         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> tomcat_1_df8edafe67b3 |         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

(s0r1n) #7
> tomcat_1_df8edafe67b3 |         at java.lang.Thread.run(Thread.java:748)
> tomcat_1_df8edafe67b3 | Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: elasticsearch/192.168.96.2:9300
> tomcat_1_df8edafe67b3 |         at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
> tomcat_1_df8edafe67b3 |         at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
> tomcat_1_df8edafe67b3 |         at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:346)
> tomcat_1_df8edafe67b3 |         at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:340)
> tomcat_1_df8edafe67b3 |         at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:630)
> tomcat_1_df8edafe67b3 |         at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:527)
> tomcat_1_df8edafe67b3 |         at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:481)
> tomcat_1_df8edafe67b3 |         at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:441)
> tomcat_1_df8edafe67b3 |         at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
> tomcat_1_df8edafe67b3 |         ... 1 more
> tomcat_1_df8edafe67b3 | [2018-12-06 09:21:44] Server     ERROR Exception in initialization: caught: An exception occurred while trying to open/load the Assembler configuration.
> ...

Anyway the node jxrazWOgRNy6RTX2wN4qZg doesn't exist on the list:

[elasticsearch@ab3bc4d4f5d7 ~]$ ls -lrt /usr/share/elasticsearch/data/nodes/0/indices/
total 64
drwxrwxr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 xJ-9rAtvRde_eO2ECHNDkQ
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 UM1p2uxxRtafB4r8B3PwXQ
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 bNEw0izlQU-NkpP9NvtZQQ
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 0DH4Pel0TNymEimmpS-gAQ
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 EWlEddldQSGs4Xm_81tveA
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 St-A8bU5TciNV4WQvDDlgA
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 tqQKv9DwTgqVnYS8Z2r1Lw
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 mXJch2VGRcu9GOCY-WcfSg
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 IX4g7s9QTgqPmlJtDHXjog
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 -LZWdbIvT6GqSvsn8_YWpg
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 D57DOZlQQImLjXsJutVPow
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 j0xfwI_8Rd2Gg1Lx6mSLiA
drwxrwxr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 XfT8v2gHQ4Kcw6Pt-cjRZw
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 UenwsjdIT6iLegNKDVIWIA
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 _jnFEKaZSi6SIXfdKIGWSg
drwxr-xr-x 4 elasticsearch elasticsearch 4096 Dec  6 08:20 2y_12Q2WScSN6ePUrMmy-g

The error occurs when Tomcat App-Manager is opened or refreshed, not during the container start. The Tomcat container will still run despite the error, but the Fuseki application.

Due to the timeout it seems to be a network issue between the containers, but the connection looks fine. The Elasticsearch had (during this error) the internal IP 192.168.96.2 as expected.
From Tomcat container is possible to get data over 9200 respectively 9300 ports, for example:

 root@ddf71d10c222:/usr/local/tomcat# wget http://elasticsearch:9200
 --2018-12-06 09:58:35--  http://elasticsearch:9200/
 Resolving elasticsearch (elasticsearch)... 192.168.96.2
 Connecting to elasticsearch (elasticsearch)|192.168.96.2|:9200... connected.
 HTTP request sent, awaiting response... 200 OK
 Length: 351 [application/json]
 Saving to: ‘index.html’
 
 index.html                                    100%[================================================================================================>]     351  --.-KB/s    in 0s

Do you have any clue why this error occurs?

As a separate topic, the Elasticsearch container generates specific indexes named like:
.watches
.triggered_watches
.monitoring-alerts-6
.watcher-history-6- ( .watcher-history-6-2018.12.03, .watcher-history-6-2018.12.04...)
.monitoring-es-6- (.monitoring-es-6--2018.12.03, .monitoring-es-6-2018.12.04...)

They may be useful for Logstash or Kibana, but how is possible to avoid them?