New users to Hazelcast

103 views
Skip to first unread message

nemer...@gmail.com

unread,
Jul 17, 2016, 5:53:52 AM7/17/16
to Hazelcast
We're new users to Hazelcast so we're not sure what we should be seeing upon startup.

We're using 3.5.4 on two nodes. We're experiencing a lot of log entries when our application kicks in but I don't really know how to interpret this.

So, hazelcast is already running on Node 1. This is the output to catalina.out (tomcat) when we start on Node 2:

INFO: Loading configuration /usr/tomcat1/conf/hazelcast.xml from System property 'hazelcast.config'

Jul 16, 2016 6:54:25 PM com.hazelcast.config.XmlConfigLocator

INFO: Using configuration file at /usr/tomcat1/conf/hazelcast.xml

Warning: Could not get charToByteConverterClass!

Jul 16, 2016 6:54:25 PM com.hazelcast.instance.DefaultAddressPicker

INFO: [LOCAL] [tomcat1] [3.5.4] Interfaces is disabled, trying to pick one address from TCP-IP config addresses: [10.0.0.56, 10.0.0.55]

Jul 16, 2016 6:54:25 PM com.hazelcast.instance.DefaultAddressPicker

INFO: [LOCAL] [tomcat1] [3.5.4] Prefer IPv4 stack is true.

Jul 16, 2016 6:54:25 PM com.hazelcast.instance.DefaultAddressPicker

INFO: [LOCAL] [tomcat1] [3.5.4] Picked Address[10.0.0.56]:5700, using socket ServerSocket[addr=/0:0:0:0:0:0:0:0,localport=5700], bind any local is true

Jul 16, 2016 6:54:25 PM com.hazelcast.spi.OperationService

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Backpressure is disabled

Jul 16, 2016 6:54:25 PM com.hazelcast.spi.impl.operationexecutor.classic.ClassicOperationExecutor

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Starting with 4 generic operation threads and 8 partition operation threads.

Jul 16, 2016 6:54:25 PM com.hazelcast.system

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Hazelcast 3.5.4 (20151125 - 56676b2) starting at Address[10.0.0.56]:5700

Jul 16, 2016 6:54:25 PM com.hazelcast.system

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Copyright (c) 2008-2015, Hazelcast, Inc. All Rights Reserved.

Jul 16, 2016 6:54:25 PM com.hazelcast.instance.Node

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Creating TcpIpJoiner

Jul 16, 2016 6:54:25 PM com.hazelcast.core.LifecycleService

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Address[10.0.0.56]:5700 is STARTING

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Connecting to /10.0.0.56:5701, timeout: 0, bind-any: true

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Connecting to /10.0.0.55:5700, timeout: 0, bind-any: true

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Connecting to /10.0.0.56:5702, timeout: 0, bind-any: true

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Connecting to /10.0.0.55:5701, timeout: 0, bind-any: true

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Could not connect to: /10.0.0.56:5701. Reason: SocketException[Connection refused to address /10.0.0.56:5701]

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Connecting to /10.0.0.55:5702, timeout: 0, bind-any: true

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Could not connect to: /10.0.0.56:5702. Reason: SocketException[Connection refused to address /10.0.0.56:5702]

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Could not connect to: /10.0.0.55:5701. Reason: SocketException[Connection refused to address /10.0.0.55:5701]

Jul 16, 2016 6:54:25 PM com.hazelcast.cluster.impl.TcpIpJoiner

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Address[10.0.0.56]:5701 is added to the blacklist.

Jul 16, 2016 6:54:25 PM com.hazelcast.cluster.impl.TcpIpJoiner

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Address[10.0.0.55]:5701 is added to the blacklist.

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.SocketConnector

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Could not connect to: /10.0.0.55:5702. Reason: SocketException[Connection refused to address /10.0.0.55:5702]

Jul 16, 2016 6:54:25 PM com.hazelcast.cluster.impl.TcpIpJoiner

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Address[10.0.0.56]:5702 is added to the blacklist.

Jul 16, 2016 6:54:25 PM com.hazelcast.cluster.impl.TcpIpJoiner

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Address[10.0.0.55]:5702 is added to the blacklist.

Jul 16, 2016 6:54:25 PM com.hazelcast.nio.tcp.TcpIpConnectionManager

INFO: [10.0.0.56]:5700 [tomcat1] [3.5.4] Established socket connection between /10.0.0.56:33009


Then we call our application, which is using a simple IMap to open a lock across the cluster. We now see this appear in the logs:


WARNING: [10.0.0.56]:5700 [tomcat1] [3.5.4] No Invocation found for response: ErrorResponse{callId=0, urgent=true, cause=com.hazelcast.nio.serialization.HazelcastSerializationException: java.lang.IllegalStateException: Can't overwrite cause with java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [java.util.HashMap]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.}

Jul 16, 2016 6:54:26 PM com.hazelcast.spi.OperationService

WARNING: [10.0.0.56]:5700 [tomcat1] [3.5.4] No Invocation found for response: ErrorResponse{callId=0, urgent=true, cause=com.hazelcast.nio.serialization.HazelcastSerializationException: java.lang.IllegalStateException: Can't overwrite cause with java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [java.util.HashMap]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.}

Jul 16, 2016 6:54:27 PM com.hazelcast.spi.OperationService

WARNING: [10.0.0.56]:5700 [tomcat1] [3.5.4] No Invocation found for response: ErrorResponse{callId=0, urgent=true, cause=com.hazelcast.nio.serialization.HazelcastSerializationException: java.lang.IllegalStateException: Can't overwrite cause with java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [java.util.HashMap]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.}

Jul 16, 2016 6:54:28 PM com.hazelcast.spi.OperationService


On the other server, the log starts to fill repeatedly with this:


Jul 16, 2016 6:54:46 PM com.hazelcast.spi.impl.operationexecutor.classic.ClassicOperationExecutor

SEVERE: [10.0.0.55]:5700 [tomcat1] [3.5.4] Failed to process packet: Packet{header=17, isResponse=false, isOperation=true, isEvent=false, partitionId=-1, conn=Connection [/10.0.0.55:5700 -> /10.0.0.56:33009], endpoint=Address[10.0.0.56]:5700, live=true, type=MEMBER} on hz._hzInstance_1_tomcat1.generic-operation.thread-2

com.hazelcast.nio.serialization.HazelcastSerializationException: java.lang.IllegalStateException: Can't overwrite cause with java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [java.util.HashMap]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.

        at com.hazelcast.nio.serialization.SerializationServiceImpl.handleException(SerializationServiceImpl.java:380)

        at com.hazelcast.nio.serialization.SerializationServiceImpl.readObject(SerializationServiceImpl.java:331)

        at com.hazelcast.nio.serialization.ByteArrayObjectDataInput.readObject(ByteArrayObjectDataInput.java:489)

        at com.hazelcast.cluster.impl.ConfigCheck.readData(ConfigCheck.java:215)

        at com.hazelcast.cluster.impl.JoinMessage.readData(JoinMessage.java:80)

        at com.hazelcast.cluster.impl.operations.MasterDiscoveryOperation.readInternal(MasterDiscoveryOperation.java:46)

        at com.hazelcast.spi.Operation.readData(Operation.java:491)

        at com.hazelcast.nio.serialization.DataSerializer.read(DataSerializer.java:111)

        at com.hazelcast.nio.serialization.DataSerializer.read(DataSerializer.java:39)

        at com.hazelcast.nio.serialization.StreamSerializerAdapter.read(StreamSerializerAdapter.java:41)

        at com.hazelcast.nio.serialization.SerializationServiceImpl.toObject(SerializationServiceImpl.java:276)

        at com.hazelcast.spi.impl.NodeEngineImpl.toObject(NodeEngineImpl.java:200)

        at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:300)

        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.processPacket(OperationThread.java:142)

        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.process(OperationThread.java:115)

        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.doRun(OperationThread.java:101)

        at com.hazelcast.spi.impl.operationexecutor.classic.OperationThread.run(OperationThread.java:76)

Caused by: java.lang.IllegalStateException: Can't overwrite cause with java.lang.IllegalStateException: Illegal access: this web application instance has been stopped already. Could not load [java.util.HashMap]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.

        at java.lang.Throwable.initCause(Throwable.java:457)

        at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1316)

        at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1196)

        at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1157)

        at com.hazelcast.nio.ClassLoaderUtil.tryLoadClass(ClassLoaderUtil.java:125)

        at com.hazelcast.nio.ClassLoaderUtil.loadClass(ClassLoaderUtil.java:98)

        at com.hazelcast.nio.IOUtil$1.resolveClass(IOUtil.java:113)

        at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1613)

        at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1518)

        at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1774)

        at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1351)

        at java.io.ObjectInputStream.readObject(ObjectInputStream.java:371)

        at com.hazelcast.nio.serialization.DefaultSerializers$ObjectSerializer.read(DefaultSerializers.java:201)

        at com.hazelcast.nio.serialization.StreamSerializerAdapter.read(StreamSerializerAdapter.java:41)

        at com.hazelcast.nio.serialization.SerializationServiceImpl.readObject(SerializationServiceImpl.java:325)

        ... 15 more

Caused by: java.lang.ClassNotFoundException

        at org.apache.catalina.loader.WebappClassLoaderBase.checkStateForClassLoading(WebappClassLoaderBase.java:1315)

        ... 28 more


Our changes to the default config file are as follows:


    <network>

        <port auto-increment="true" port-count="20">5700</port>

        <outbound-ports>

            <ports>33000-33009</ports>

        </outbound-ports>

        <join>

            <multicast enabled="false" />

            <tcp-ip enabled="true">

                <member>10.0.0.55</member>

                <member>10.0.0.56</member>

            </tcp-ip>

        </join>

        <ssl enabled="false"/>

        <socket-interceptor enabled="false"/>

        <symmetric-encryption enabled="false">

            <algorithm>PBEWithMD5AndDES</algorithm>

            <salt>***</salt>

            <password>***</password>

            <iteration-count>19</iteration-count>

        </symmetric-encryption>

    </network>


My question....what's going on?


Vassilis Bekiaris

unread,
Jul 18, 2016, 2:14:45 AM7/18/16
to Hazelcast, nemer...@gmail.com
Hi,

you should see something like this log entry to make sure hazelcast is started:

INFO: [192.168.2.4]:5701 [dev] [3.5.4] Address[192.168.2.4]:5701 is STARTED

The format may be different depending on your logging configuration (JDK, SLF4j etc). You should see this some time after you the "is STARTING" message that is visible in your logs. On startup, the TCP IP cluster joiner will attempt to locate and establish connections with other nodes based on your configuration, so it tries to locate running instances on 10.0.0.55 & 10.0.0.56 (the addresses configured in TCP IP network config section) using ports starting from 5700 and attempting to auto-increment.

The stack traces you provided indicate that the webapp you attempt to deploy on Tomcat was not started properly. My interpretation of the stack trace you provided is that Hazelcast attempts to execute an operation; during execution the class loader is requested to load java.util.HashMap however Tomcat webapp's class loader refuses to load the class as it finds the webapp has already been shutdown ("Illegal access: this web application instance has been stopped already."). I would suggest you to look in tomcat's log files and try to locate the root cause why your webapp is not deployed on tomcat.

Finally, version 3.5.4 is quite a bit out-of-date; current stable release is 3.6.4, if you are able to do so and not bound by other constraints I would suggest you to go with the latest stable version.

Cheers!
Vassilis
Reply all
Reply to author
Forward
0 new messages