Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Errors in log when 3rd repo connects to cluster #8

Closed
andreaskring opened this issue Jun 18, 2019 · 16 comments
Closed

Errors in log when 3rd repo connects to cluster #8

andreaskring opened this issue Jun 18, 2019 · 16 comments
Labels
bug Something isn't working

Comments

@andreaskring
Copy link
Collaborator

I have set up 4 repos on AWS with Ansible. The repos were started up one at the time starting with repo1, but when I got to repo3 i got a lot of errors in the log:

18-Jun-2019 15:04:41.408 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 82906 ms
2019-06-18 15:05:36,316  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery accepted incoming connection [rmtAddr=/172.31.42.224, rmtPort=54261]
 2019-06-18 15:05:36,329  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery spawning a new thread for connection [rmtAddr=/172.31.42.224, rmtPort=54261]
 2019-06-18 15:05:36,329  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-sock-reader-#5%repositoryGrid%] Started serving remote node connection [rmtAddr=/172.31.42.224:54261, rmtPort=54261]
 2019-06-18 15:05:36,356  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-sock-reader-#5%repositoryGrid%] Finished serving remote node connection [rmtAddr=/172.31.42.224:54261, rmtPort=54261
 [15:05:36] Joining node doesn't have encryption data [node=12b7775d-a278-4c31-9237-1576e904ed9e]
2019-06-18 15:05:36,396  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-msg-worker-#2%repositoryGrid%] New next node [newNext=TcpDiscoveryNode [id=12b7775d-a278-4c31-9237-1576e904ed9e, addrs=[172.31.42.224], sockAddrs=[repo2/172.31.42.224:47110], discPort=47110, order=0, intOrder=2, lastExchangeTime=1560863136340, loc=false, ver=2.7.5#20190603-sha1:be4f2a15, isClient=false]]
 2019-06-18 15:05:36,528  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery accepted incoming connection [rmtAddr=/172.31.42.224, rmtPort=41605]
 2019-06-18 15:05:36,528  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery spawning a new thread for connection [rmtAddr=/172.31.42.224, rmtPort=41605]
 2019-06-18 15:05:36,528  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-sock-reader-#6%repositoryGrid%] Started serving remote node connection [rmtAddr=/172.31.42.224:41605, rmtPort=41605]
 2019-06-18 15:05:36,534  INFO  [managers.discovery.GridDiscoveryManager] [disco-event-worker-#35%repositoryGrid%] Added new node to topology: TcpDiscoveryNode [id=12b7775d-a278-4c31-9237-1576e904ed9e, addrs=[172.31.42.224], sockAddrs=[repo2/172.31.42.224:47110], discPort=47110, order=2, intOrder=2, lastExchangeTime=1560863136340, loc=false, ver=2.7.5#20190603-sha1:be4f2a15, isClient=false]
 [15:05:36] Topology snapshot [ver=2, locNode=ca02fd41, servers=2, clients=0, state=ACTIVE, CPUs=4, offheap=32.0GB, heap=8.0GB]
2019-06-18 15:05:36,538  INFO  [managers.discovery.GridDiscoveryManager] [disco-event-worker-#35%repositoryGrid%] Topology snapshot [ver=2, locNode=ca02fd41, servers=2, clients=0, state=ACTIVE, CPUs=4, offheap=32.0GB, heap=8.0GB]
 2019-06-18 15:05:36,539  INFO  [ignite.lifecycle.SpringIgniteLifecycleBean] [disco-event-worker-#35%repositoryGrid%] Node 12b7775d-a278-4c31-9237-1576e904ed9e (on [172.31.42.224]) joined the Ignite instance repositoryGrid
 2019-06-18 15:05:36,539  INFO  [ignite.lifecycle.SpringIgniteLifecycleBean] [disco-event-worker-#35%repositoryGrid%] Ignite instance repositoryGrid currently has 2 active nodes on addresses [172.31.44.230, 172.31.42.224]
 2019-06-18 15:05:48,038  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 428 Web Scripts (+0 failed), 584 URLs
 2019-06-18 15:05:48,038  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 1 Package Description Documents (+0 failed) 
 2019-06-18 15:05:48,038  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 0 Schema Description Documents (+0 failed) 
 2019-06-18 15:05:48,968  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 428 Web Scripts (+0 failed), 584 URLs
 2019-06-18 15:05:48,968  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 1 Package Description Documents (+0 failed) 
 2019-06-18 15:05:48,968  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 0 Schema Description Documents (+0 failed) 
 2019-06-18 15:07:40,221  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery accepted incoming connection [rmtAddr=/172.31.44.64, rmtPort=50259]
 2019-06-18 15:07:40,221  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery spawning a new thread for connection [rmtAddr=/172.31.44.64, rmtPort=50259]
 2019-06-18 15:07:40,222  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-sock-reader-#7%repositoryGrid%] Started serving remote node connection [rmtAddr=/172.31.44.64:50259, rmtPort=50259]
 2019-06-18 15:07:40,246  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-sock-reader-#7%repositoryGrid%] Finished serving remote node connection [rmtAddr=/172.31.44.64:50259, rmtPort=50259
 [15:07:40] Joining node doesn't have encryption data [node=d2e10fe6-c017-4174-83ef-4d450f3a40a2]
2019-06-18 15:07:40,275  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-sock-reader-#6%repositoryGrid%] Finished serving remote node connection [rmtAddr=/172.31.42.224:41605, rmtPort=41605
 2019-06-18 15:07:40,429  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery accepted incoming connection [rmtAddr=/172.31.44.64, rmtPort=45243]
 2019-06-18 15:07:40,429  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-srvr-#3%repositoryGrid%] TCP discovery spawning a new thread for connection [rmtAddr=/172.31.44.64, rmtPort=45243]
 2019-06-18 15:07:40,429  INFO  [ignite.discovery.CredentialsAwareTcpDiscoverySpi] [tcp-disco-sock-reader-#8%repositoryGrid%] Started serving remote node connection [rmtAddr=/172.31.44.64:45243, rmtPort=45243]
 2019-06-18 15:07:40,433  INFO  [managers.discovery.GridDiscoveryManager] [disco-event-worker-#35%repositoryGrid%] Added new node to topology: TcpDiscoveryNode [id=d2e10fe6-c017-4174-83ef-4d450f3a40a2, addrs=[172.31.44.64], sockAddrs=[repo3/172.31.44.64:47110], discPort=47110, order=3, intOrder=3, lastExchangeTime=1560863260246, loc=false, ver=2.7.5#20190603-sha1:be4f2a15, isClient=false]
 [15:07:40] Topology snapshot [ver=3, locNode=ca02fd41, servers=3, clients=0, state=ACTIVE, CPUs=6, offheap=48.0GB, heap=12.0GB]
2019-06-18 15:07:40,434  INFO  [managers.discovery.GridDiscoveryManager] [disco-event-worker-#35%repositoryGrid%] Topology snapshot [ver=3, locNode=ca02fd41, servers=3, clients=0, state=ACTIVE, CPUs=6, offheap=48.0GB, heap=12.0GB]
 2019-06-18 15:07:40,434  INFO  [ignite.lifecycle.SpringIgniteLifecycleBean] [disco-event-worker-#35%repositoryGrid%] Node d2e10fe6-c017-4174-83ef-4d450f3a40a2 (on [172.31.44.64]) joined the Ignite instance repositoryGrid
 2019-06-18 15:07:40,434  INFO  [ignite.lifecycle.SpringIgniteLifecycleBean] [disco-event-worker-#35%repositoryGrid%] Ignite instance repositoryGrid currently has 3 active nodes on addresses [172.31.44.230, 172.31.42.224, 172.31.44.64]
 2019-06-18 15:07:40,588  ERROR [internal.binary.BinaryContext] [sys-#57%repositoryGrid%] Failed to deserialize object [typeName=o.a.i.util.deque.FastSizeDeque]
 class org.apache.ignite.binary.BinaryObjectException: Failed to read field [name=deque]
	at org.apache.ignite.internal.binary.BinaryFieldAccessor.read(BinaryFieldAccessor.java:192)
	at org.apache.ignite.internal.binary.BinaryClassDescriptor.read(BinaryClassDescriptor.java:875)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize0(BinaryReaderExImpl.java:1764)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize(BinaryReaderExImpl.java:1716)
	at org.apache.ignite.internal.binary.GridBinaryMarshaller.deserialize(GridBinaryMarshaller.java:313)
	at org.apache.ignite.internal.binary.BinaryMarshaller.unmarshal0(BinaryMarshaller.java:102)
	at org.apache.ignite.marshaller.AbstractNodeNameAwareMarshaller.unmarshal(AbstractNodeNameAwareMarshaller.java:82)
	at org.apache.ignite.internal.util.IgniteUtils.unmarshal(IgniteUtils.java:10141)
	at org.apache.ignite.internal.processors.continuous.GridContinuousProcessor$7.onMessage(GridContinuousProcessor.java:269)
	at org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1569)
	at org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1197)
	at org.apache.ignite.internal.managers.communication.GridIoManager.access$4200(GridIoManager.java:127)
	at org.apache.ignite.internal.managers.communication.GridIoManager$9.run(GridIoManager.java:1093)
	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)
Caused by: class org.apache.ignite.binary.BinaryObjectException: Failed to unmarshal object with optimized marshaller
	at org.apache.ignite.internal.binary.BinaryUtils.doReadOptimized(BinaryUtils.java:1765)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize0(BinaryReaderExImpl.java:1964)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize(BinaryReaderExImpl.java:1716)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.readField(BinaryReaderExImpl.java:1984)
	at org.apache.ignite.internal.binary.BinaryFieldAccessor$DefaultFinalClassAccessor.read0(BinaryFieldAccessor.java:703)
	at org.apache.ignite.internal.binary.BinaryFieldAccessor.read(BinaryFieldAccessor.java:188)
	... 15 more
Caused by: class org.apache.ignite.IgniteCheckedException: Failed to deserialize object with given class loader: [clsLdr=ParallelWebappClassLoader
  context: alfresco
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@3da9affb
, err=Failed to deserialize object [typeName=java.util.concurrent.ConcurrentLinkedDeque]]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedMarshaller.unmarshal0(OptimizedMarshaller.java:237)
	at org.apache.ignite.marshaller.AbstractNodeNameAwareMarshaller.unmarshal(AbstractNodeNameAwareMarshaller.java:94)
	at org.apache.ignite.internal.binary.BinaryUtils.doReadOptimized(BinaryUtils.java:1762)
	... 20 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=java.util.concurrent.ConcurrentLinkedDeque]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedMarshaller.unmarshal0(OptimizedMarshaller.java:228)
	... 22 more
Caused by: java.io.IOException: java.lang.reflect.InvocationTargetException
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:607)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:954)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 25 more
Caused by: java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:604)
	... 27 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=org.apache.ignite.internal.GridEventConsumeHandler$EventWrapper]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at java.util.concurrent.ConcurrentLinkedDeque.readObject(ConcurrentLinkedDeque.java:1543)
	... 32 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=org.apache.ignite.events.DiscoveryEvent]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.internal.GridEventConsumeHandler$EventWrapper.readExternal(GridEventConsumeHandler.java:558)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readExternalizable(OptimizedObjectInputStream.java:555)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:949)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 35 more
Caused by: java.io.IOException: Failed to deserialize field [name=node]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readFields(OptimizedObjectInputStream.java:526)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:611)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:954)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 41 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=org.apache.ignite.spi.discovery.tcp.internal.TcpDiscoveryNode]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readFields(OptimizedObjectInputStream.java:519)
	... 44 more
Caused by: java.io.IOException: Unexpected error occurred during unmarshalling of an instance of the class: org.apache.ignite.internal.processors.cache.CacheMetricsSnapshot. Check that all nodes are running the same version of Ignite and that all nodes have GridOptimizedMarshaller configured with identical optimized classes lists, if any (see setClassNames and setClassNamesPath methods). If your serialized classes implement java.io.Externalizable interface, verify that serialization logic is correct.
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:364)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.spi.discovery.tcp.internal.TcpDiscoveryNode.readExternal(TcpDiscoveryNode.java:616)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readExternalizable(OptimizedObjectInputStream.java:555)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:949)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 47 more
2019-06-18 15:07:40,592  ERROR [processors.continuous.GridContinuousProcessor] [sys-#57%repositoryGrid%] Failed to process message (ignoring): GridContinuousMessage [type=MSG_EVT_NOTIFICATION, routineId=398c5446-951f-4c88-b31e-20bf2b3aea67, data=null, futId=null]
 class org.apache.ignite.IgniteCheckedException: Failed to deserialize object [typeName=org.apache.ignite.util.deque.FastSizeDeque]
	at org.apache.ignite.internal.util.IgniteUtils.unmarshal(IgniteUtils.java:10147)
	at org.apache.ignite.internal.processors.continuous.GridContinuousProcessor$7.onMessage(GridContinuousProcessor.java:269)
	at org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1569)
	at org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1197)
	at org.apache.ignite.internal.managers.communication.GridIoManager.access$4200(GridIoManager.java:127)
	at org.apache.ignite.internal.managers.communication.GridIoManager$9.run(GridIoManager.java:1093)
	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)
Caused by: class org.apache.ignite.binary.BinaryObjectException: Failed to deserialize object [typeName=org.apache.ignite.util.deque.FastSizeDeque]
	at org.apache.ignite.internal.binary.BinaryClassDescriptor.read(BinaryClassDescriptor.java:914)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize0(BinaryReaderExImpl.java:1764)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize(BinaryReaderExImpl.java:1716)
	at org.apache.ignite.internal.binary.GridBinaryMarshaller.deserialize(GridBinaryMarshaller.java:313)
	at org.apache.ignite.internal.binary.BinaryMarshaller.unmarshal0(BinaryMarshaller.java:102)
	at org.apache.ignite.marshaller.AbstractNodeNameAwareMarshaller.unmarshal(AbstractNodeNameAwareMarshaller.java:82)
	at org.apache.ignite.internal.util.IgniteUtils.unmarshal(IgniteUtils.java:10141)
	... 8 more
Caused by: class org.apache.ignite.binary.BinaryObjectException: Failed to read field [name=deque]
	at org.apache.ignite.internal.binary.BinaryFieldAccessor.read(BinaryFieldAccessor.java:192)
	at org.apache.ignite.internal.binary.BinaryClassDescriptor.read(BinaryClassDescriptor.java:875)
	... 14 more
Caused by: class org.apache.ignite.binary.BinaryObjectException: Failed to unmarshal object with optimized marshaller
	at org.apache.ignite.internal.binary.BinaryUtils.doReadOptimized(BinaryUtils.java:1765)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize0(BinaryReaderExImpl.java:1964)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.deserialize(BinaryReaderExImpl.java:1716)
	at org.apache.ignite.internal.binary.BinaryReaderExImpl.readField(BinaryReaderExImpl.java:1984)
	at org.apache.ignite.internal.binary.BinaryFieldAccessor$DefaultFinalClassAccessor.read0(BinaryFieldAccessor.java:703)
	at org.apache.ignite.internal.binary.BinaryFieldAccessor.read(BinaryFieldAccessor.java:188)
	... 15 more
Caused by: class org.apache.ignite.IgniteCheckedException: Failed to deserialize object with given class loader: [clsLdr=ParallelWebappClassLoader
  context: alfresco
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@3da9affb
, err=Failed to deserialize object [typeName=java.util.concurrent.ConcurrentLinkedDeque]]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedMarshaller.unmarshal0(OptimizedMarshaller.java:237)
	at org.apache.ignite.marshaller.AbstractNodeNameAwareMarshaller.unmarshal(AbstractNodeNameAwareMarshaller.java:94)
	at org.apache.ignite.internal.binary.BinaryUtils.doReadOptimized(BinaryUtils.java:1762)
	... 20 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=java.util.concurrent.ConcurrentLinkedDeque]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedMarshaller.unmarshal0(OptimizedMarshaller.java:228)
	... 22 more
Caused by: java.io.IOException: java.lang.reflect.InvocationTargetException
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:607)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:954)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 25 more
Caused by: java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:604)
	... 27 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=org.apache.ignite.internal.GridEventConsumeHandler$EventWrapper]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at java.util.concurrent.ConcurrentLinkedDeque.readObject(ConcurrentLinkedDeque.java:1543)
	... 32 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=org.apache.ignite.events.DiscoveryEvent]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.internal.GridEventConsumeHandler$EventWrapper.readExternal(GridEventConsumeHandler.java:558)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readExternalizable(OptimizedObjectInputStream.java:555)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:949)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 35 more
Caused by: java.io.IOException: Failed to deserialize field [name=node]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readFields(OptimizedObjectInputStream.java:526)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readSerializable(OptimizedObjectInputStream.java:611)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:954)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 41 more
Caused by: java.io.IOException: Failed to deserialize object [typeName=org.apache.ignite.spi.discovery.tcp.internal.TcpDiscoveryNode]
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:350)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readFields(OptimizedObjectInputStream.java:519)
	... 44 more
Caused by: java.io.IOException: Unexpected error occurred during unmarshalling of an instance of the class: org.apache.ignite.internal.processors.cache.CacheMetricsSnapshot. Check that all nodes are running the same version of Ignite and that all nodes have GridOptimizedMarshaller configured with identical optimized classes lists, if any (see setClassNames and setClassNamesPath methods). If your serialized classes implement java.io.Externalizable interface, verify that serialization logic is correct.
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:364)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObjectOverride(OptimizedObjectInputStream.java:198)
	at java.io.ObjectInputStream.readObject(ObjectInputStream.java:425)
	at org.apache.ignite.spi.discovery.tcp.internal.TcpDiscoveryNode.readExternal(TcpDiscoveryNode.java:616)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readExternalizable(OptimizedObjectInputStream.java:555)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedClassDescriptor.read(OptimizedClassDescriptor.java:949)
	at org.apache.ignite.internal.marshaller.optimized.OptimizedObjectInputStream.readObject0(OptimizedObjectInputStream.java:346)
	... 47 more
2019-06-18 15:07:51,694  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 428 Web Scripts (+0 failed), 584 URLs
 2019-06-18 15:07:51,694  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 1 Package Description Documents (+0 failed) 
 2019-06-18 15:07:51,694  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 0 Schema Description Documents (+0 failed) 
 2019-06-18 15:07:52,333  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 428 Web Scripts (+0 failed), 584 URLs
 2019-06-18 15:07:52,333  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 1 Package Description Documents (+0 failed) 
 2019-06-18 15:07:52,333  INFO  [extensions.webscripts.DeclarativeRegistry] [asynchronouslyRefreshedCacheThreadPool1] Registered 0 Schema Description Documents (+0 failed) 

Looking in the "Grids" section on the Ignite admin page it actually says that Topology=3 and Modes=3

Have you seen these errors before?

@andreaskring
Copy link
Collaborator Author

The same error shows up again when repo4 is connected to the cluster

@AFaust
Copy link
Collaborator

AFaust commented Jun 18, 2019 via email

@andreaskring
Copy link
Collaborator Author

Yes - I'm pretty sure since all the instances have been set up with the same Ansible script, but I will double check that I have not made some stupid Ansible config mistake. I will get back to you.

@andreaskring
Copy link
Collaborator Author

andreaskring commented Jun 18, 2019

Hmm - as far as I can see, Ansible looks ok and all the repos are using the same AMPs. I did an md5sum of the AMPs installed on the 4 servers, and this was the (identical) output from all of them:

root@repo3:/mnt# md5sum /opt/tomcat/amps/*
0d5f3f9daa9065b40badc8b267bb82d0  /opt/tomcat/amps/aldica-repo-ignite-1.0.0.0-SNAPSHOT.amp
5ad1d550a1f95ac3862f38d5322b835b  /opt/tomcat/amps/alfresco-aos-module-1.2.2.amp
1b776e2473e2a9de60af5e865031e31b  /opt/tomcat/amps/de.acosix.alfresco.utility.core.repo-1.0.3.1.amp
1f1fce814e5d9ec30599bbd159c14f58  /opt/tomcat/amps/support-tools-repo-1.1.0.0-20190603.144418-6.amp

And since the version of Ignite is determined by the AMPs this must also be the same on all the servers. The aldica properties in alfresco-global.properties are also the same (apart from the stuff that should differ such as IP-addresses and IDs etc.)

@andreaskring
Copy link
Collaborator Author

andreaskring commented Jun 18, 2019

I will try to perform this test tomorrow: make a permutation of the start order of the repos, i.e. I can try to start them in the order repo1, repo3, repo2, repo4. If this fails when the repo3 is started then there must be something wrong with repo3. If the error do not occur until repo2 is started then we must assume that the problem is somewhere in the module.

@andreaskring
Copy link
Collaborator Author

andreaskring commented Jun 19, 2019

The test described have been performed, i.e. the repos (only the first three) was started in the order repo1, repo3, repo2. Starting up repo1 and repo3 worked fine and there were no errors in the log, but when repo2 was started, the same errors as yesterday showed up. So I guess this means that repo3 is fine and it is safe to assume that all the repos are configured in the same way. The problem apparently arises when the third repo is connected to the cluster (regardless of which repo is used as the third repo).

@andreaskring
Copy link
Collaborator Author

I tried to run a load test with 4 nodes in the cluster dispite the above errors just to see what happened. The result was that the 4 nodes performed inferior to the case with just two nodes, so the issue is affecting performance.

@andreaskring andreaskring added the bug Something isn't working label Jun 20, 2019
@AFaust
Copy link
Collaborator

AFaust commented Jun 20, 2019

I have expanded my local Docker-based test to include 3 repository nodes, started each of them up in turn and checked their logs. When checking each new node, they did not show any error in the logs. But the primary / first node did indeed show an error message about deserialization. Interestingly, I had done the same test with the current state of my commercial module, and it did not show errors as far as I can remember. Not all of the recent changes in aldica have been ported back to the commercial module since that one has been mostly frozen due to ongoing customer acceptance tests.

@andreaskring
Copy link
Collaborator Author

Ok - I experienced the same, i.e. the logs of the new nodes look fine, and the error reported only showed up in the primary node. Do you have time to investigate the issue further?

I'm also trying to look into it, but I must admit that my aldica/Ignite skills currently are sufficient :-)

I don't know what the best debugging strategy is... all the errors are coming from Ignite itself, so it is hard to see from where in aldica the problem is arising.

@andreaskring
Copy link
Collaborator Author

Typo - I meant my aldica/Ignite skills currently are not sufficient :-)

@AFaust
Copy link
Collaborator

AFaust commented Jun 20, 2019

Ok, so this looks related to Ignite event handling and the need to handle discovery events, especially when dealing with potential address translation scenarios (Docker / virtualised network). Since we can never know if a server with such mapping information might join at some time, we always register listeners for these events. Our code itself is also not the cause of the issue, it just seems to trigger it. That is also the reason why it only happens for more than 2 servers. When the 3rd server joins the data grid, the discovery event for the join needs to be sent from the primary / 1st node to all other nodes already in the data grid, which means to the 2nd node. Before the 3rd server joins, there is no need for the event to be sent.

Searching Ignite JIRA for some of the details in the long stack trace, I found IGNITE-11352 which addresses a binary incompatibility in CacheMetricsSnapshot. This class is reported in our stack trace at the lowest level / as the last "Caused by" exception. That JIRA issue has already marked as resolved for the next 2.8 release. I am going to try performing a test with a SNAPSHOT of Ignite to see if that fix for IGNITE-11352 also fixes our issue.

@andreaskring
Copy link
Collaborator Author

andreaskring commented Jun 20, 2019

Thank you for your fast response! Good news that the problem is not in aldica and that the JIRA issue has been marked as resolved. It will be interesting to see the outcome of your test with the snapshot version of Ignite - let's hope that their fix works.

@AFaust
Copy link
Collaborator

AFaust commented Jun 20, 2019

I tested with a 2.8 SNAPSHOT built locally from current Ignite master, and there is no more exception in any log when the 3rd server joins the data grid.

@AFaust
Copy link
Collaborator

AFaust commented Jun 20, 2019

We can avoid this exception until 2.8 comes out by disabling statistics on all the caches created by aldica. This would mean we can no longer provide details about cache hits / misses, ratios and average duration of cache operations in the admin console tool.

@andreaskring
Copy link
Collaborator Author

andreaskring commented Jun 21, 2019

This is great news! I'm very happy to hear that it is working with the latest Ignite master. Good idea with the temporary solution to disable the statistics until 2.8 is released. I will build and install the latest version of aldica and continue with the load tests.

@AFaust
Copy link
Collaborator

AFaust commented Jun 29, 2019

Closing as issue has been addressed via workaround for the current Ignite release.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants