0 Replies Latest reply on Sep 12, 2013 10:48 AM by Viren Balaut

    Issue in Infinispan Cluster join on linux

    Viren Balaut Newbie

      I am having application which is internally creating REPL cache using EmbeddedCache manager. I am using jgroups-udp with default setting...

      When I am trying to run on windows, its working fine and cluster is able to form.

       

      But when I am trying the same code on linux machine, cluster is not forming.

      I have tried this setting -Djava.net.preferIPv4Stack=true but seems to be no luck. I have verified that there is no firewall which is blocking....


      Can you suggesst some way to find out exact issue and resolve that...

       

      tomcat 1 log
      ----------------------------------------------------------------------
      2013-09-12 07:51:24,480|main|INFO |com.enlighta.cluster.cache.AbstractCacheManager.<init>(AbstractCacheManager.java:61) - Trying to create infinispan cache programatically.
      2013-09-12 07:51:24,885|main|DEBUG|org.infinispan.util.ModuleProperties.resolveModuleLifecycles(ModuleProperties.java:50) - Loading lifecycle SPI class: org.infinispan.query.impl.LifecycleManager@3352d4
      2013-09-12 07:51:24,994|main|DEBUG|org.infinispan.util.ModuleProperties.loadModuleCommandHandlers(ModuleProperties.java:79) - Loading module command extension SPI class: org.infinispan.query.QueryModuleCommandExtensions@6e8deccd
      2013-09-12 07:51:25,026|main|DEBUG|org.infinispan.marshall.core.JBossMarshaller.inject(JBossMarshaller.java:50) - Using JBoss Marshalling
      2013-09-12 07:51:25,150|main|DEBUG|org.infinispan.manager.DefaultCacheManager.start(DefaultCacheManager.java:688) - Started cache manager ISPN on null
      2013-09-12 07:51:25,166|main|INFO |com.enlighta.cluster.cache.ClusterCacheService.<init>(ClusterCacheService.java:38) - Trying to create MAP of caches so it can be used by components..
      2013-09-12 07:51:25,369|main|INFO |org.infinispan.remoting.transport.jgroups.JGroupsTransport.start(JGroupsTransport.java:182) - ISPN000078: Starting JGroups Channel
      2013-09-12 07:51:25,852|main|WARN |org.jgroups.stack.Configurator.resolveAndAssignField(Configurator.java:1134) - [JGRP00014] TP.discard_incompatible_packets has been deprecated: incompatible packets are discarded anyway
      2013-09-12 07:51:25,852|main|WARN |org.jgroups.stack.Configurator.resolveAndAssignField(Configurator.java:1134) - [JGRP00014] TP.enable_bundling has been deprecated: will be ignored as bundling is on by default
      2013-09-12 07:51:25,899|main|WARN |org.jgroups.stack.Configurator.resolveAndInvokePropertyMethod(Configurator.java:1087) - [JGRP00014] UNICAST.setTimeout has been deprecated: not used anymore
      2013-09-12 07:51:26,086|main|DEBUG|org.jgroups.stack.Configurator.setDefaultValues(Configurator.java:823) - set property UDP.bind_addr to default value /fe80:0:0:0:d572:3236:54a6:1ff0%13
      2013-09-12 07:51:26,086|main|DEBUG|org.jgroups.stack.Configurator.setDefaultValues(Configurator.java:823) - set property UDP.diagnostics_addr to default value /ff0e:0:0:0:0:0:75:75
      2013-09-12 07:51:26,227|main|DEBUG|org.jgroups.protocols.FRAG2.up(FRAG2.java:173) - received CONFIG event: {bind_addr=/fe80:0:0:0:d572:3236:54a6:1ff0%13}
      2013-09-12 07:51:26,258|main|DEBUG|org.jgroups.protocols.UDP.createSockets(UDP.java:323) - sockets will use interface fe80:0:0:0:d572:3236:54a6:1ff0%13
      2013-09-12 07:51:26,508|main|DEBUG|org.jgroups.protocols.UDP.createSockets(UDP.java:393) - socket information:
      mcast_addr=ff0e:0:0:0:0:0:e406:708:46655, bind_addr=/fe80:0:0:0:d572:3236:54a6:1ff0%13, ttl=2
      sock: bound to fe80:0:0:0:d572:3236:54a6:1ff0%13:62204, receive buffer size=20000000, send buffer size=640000
      mcast_sock: bound to fe80:0:0:0:d572:3236:54a6:1ff0%13:46655, send buffer size=640000, receive buffer size=25000000
      2013-09-12 07:51:26,523|main|DEBUG|org.jgroups.protocols.pbcast.GMS.down(GMS.java:924) - address=taru_laptop-45266, cluster=ISPN, physical address=fe80:0:0:0:d572:3236:54a6:1ff0%13:62204
      2013-09-12 07:51:56,584|main|DEBUG|org.jgroups.protocols.pbcast.NAKACK.setDigest(NAKACK.java:1216) -
      [taru_laptop-45266 setDigest()]
      existing digest:  []
      new digest:       taru_laptop-45266: [0 (0)]
      resulting digest: taru_laptop-45266: [0 (0)]
      2013-09-12 07:51:56,584|main|DEBUG|org.jgroups.protocols.pbcast.GMS.installView(GMS.java:595) - taru_laptop-45266: installing [taru_laptop-45266|0] [taru_laptop-45266]
      2013-09-12 07:51:56,584|main|DEBUG|org.jgroups.protocols.pbcast.STABLE.resume(STABLE.java:206) - resuming message garbage collection
      2013-09-12 07:51:56,584|main|DEBUG|org.jgroups.protocols.FD_SOCK.down(FD_SOCK.java:328) - VIEW_CHANGE received: [taru_laptop-45266]
      2013-09-12 07:51:56,584|main|DEBUG|org.infinispan.remoting.transport.jgroups.JGroupsTransport.viewAccepted(JGroupsTransport.java:617) - New view accepted: [taru_laptop-45266|0] [taru_laptop-45266]
      2013-09-12 07:51:56,584|main|INFO |org.infinispan.remoting.transport.jgroups.JGroupsTransport.viewAccepted(JGroupsTransport.java:644) - ISPN000094: Received new cluster view: [taru_laptop-45266|0] [taru_laptop-45266]
      2013-09-12 07:51:56,600|main|INFO |com.enlighta.cluster.JMSClientListener.observeViewChanged(JMSClientListener.java:34) - View Changed : EventImpl{type=VIEW_CHANGED, newMembers=[taru_laptop-45266], oldMembers=null, localAddress=taru_laptop-45266, viewId=0, subgroupsMerged=null, mergeView=false}
      2013-09-12 07:51:56,600|main|DEBUG|org.jgroups.protocols.pbcast.STABLE.resume(STABLE.java:206) - resuming message garbage collection
      2013-09-12 07:51:56,600|main|DEBUG|org.jgroups.protocols.pbcast.ClientGmsImpl.becomeSingletonMember(ClientGmsImpl.java:336) - created group (first member). My view is [taru_laptop-45266|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl

      *** After tomcat 2 comes up.. here is view change message

       

      2013-09-12 07:52:34,488|ViewHandler,taru_laptop-45266|DEBUG|org.jgroups.protocols.pbcast.STABLE.suspend(STABLE.java:190) - suspending message garbage collection
      2013-09-12 07:52:34,488|ViewHandler,taru_laptop-45266|DEBUG|org.jgroups.protocols.pbcast.STABLE.startResumeTask(STABLE.java:519) - resume task started, max_suspend_time=33000
      2013-09-12 07:52:34,488|Incoming-1,taru_laptop-45266|DEBUG|org.jgroups.protocols.pbcast.NAKACK.setDigest(NAKACK.java:1216) -
      [taru_laptop-45266 setDigest()]
      existing digest:  taru_laptop-45266: [1 (1)]
      new digest:       taru_laptop-45266: [0 (0)], taru_laptop-12830: [0 (0)]
      resulting digest: taru_laptop-12830: [0 (0)], taru_laptop-45266: [1 (1)]
      2013-09-12 07:52:34,488|Incoming-1,taru_laptop-45266|DEBUG|org.jgroups.protocols.pbcast.GMS.installView(GMS.java:595) - taru_laptop-45266: installing [taru_laptop-45266|1] [taru_laptop-45266, taru_laptop-12830]
      2013-09-12 07:52:34,503|Incoming-1,taru_laptop-45266|DEBUG|org.jgroups.protocols.FD_SOCK.down(FD_SOCK.java:328) - VIEW_CHANGE received: [taru_laptop-45266, taru_laptop-12830]
      2013-09-12 07:52:34,503|FD_SOCK pinger,taru_laptop-45266|DEBUG|org.jgroups.protocols.FD_SOCK.run(FD_SOCK.java:386) - ping_dest is taru_laptop-12830, pingable_mbrs=[taru_laptop-45266, taru_laptop-12830]

       

       

      tomcat 2 log
      ------------------------------------------------------------
      2013-09-12 07:52:33,162|main|INFO |org.infinispan.remoting.transport.jgroups.JGroupsTransport.start(JGroupsTransport.java:182) - ISPN000078: Starting JGroups Channel
      2013-09-12 07:52:33,614|main|WARN |org.jgroups.stack.Configurator.resolveAndAssignField(Configurator.java:1134) - [JGRP00014] TP.discard_incompatible_packets has been deprecated: incompatible packets are discarded anyway
      2013-09-12 07:52:33,614|main|WARN |org.jgroups.stack.Configurator.resolveAndAssignField(Configurator.java:1134) - [JGRP00014] TP.enable_bundling has been deprecated: will be ignored as bundling is on by default
      2013-09-12 07:52:33,661|main|WARN |org.jgroups.stack.Configurator.resolveAndInvokePropertyMethod(Configurator.java:1087) - [JGRP00014] UNICAST.setTimeout has been deprecated: not used anymore
      2013-09-12 07:52:33,864|main|DEBUG|org.jgroups.stack.Configurator.setDefaultValues(Configurator.java:823) - set property UDP.bind_addr to default value /fe80:0:0:0:d572:3236:54a6:1ff0%13
      2013-09-12 07:52:33,864|main|DEBUG|org.jgroups.stack.Configurator.setDefaultValues(Configurator.java:823) - set property UDP.diagnostics_addr to default value /ff0e:0:0:0:0:0:75:75
      2013-09-12 07:52:33,989|main|DEBUG|org.jgroups.protocols.FRAG2.up(FRAG2.java:173) - received CONFIG event: {bind_addr=/fe80:0:0:0:d572:3236:54a6:1ff0%13}
      2013-09-12 07:52:34,020|main|DEBUG|org.jgroups.protocols.UDP.createSockets(UDP.java:323) - sockets will use interface fe80:0:0:0:d572:3236:54a6:1ff0%13
      2013-09-12 07:52:34,332|main|DEBUG|org.jgroups.protocols.UDP.createSockets(UDP.java:393) - socket information:
      mcast_addr=ff0e:0:0:0:0:0:e406:708:46655, bind_addr=/fe80:0:0:0:d572:3236:54a6:1ff0%13, ttl=2
      sock: bound to fe80:0:0:0:d572:3236:54a6:1ff0%13:61344, receive buffer size=20000000, send buffer size=640000
      mcast_sock: bound to fe80:0:0:0:d572:3236:54a6:1ff0%13:46655, send buffer size=640000, receive buffer size=25000000
      2013-09-12 07:52:34,347|main|DEBUG|org.jgroups.protocols.pbcast.GMS.down(GMS.java:924) - address=taru_laptop-12830, cluster=ISPN, physical address=fe80:0:0:0:d572:3236:54a6:1ff0%13:61344
      2013-09-12 07:52:34,410|main|DEBUG|org.jgroups.protocols.pbcast.ClientGmsImpl.determineCoord(ClientGmsImpl.java:298) - election results: {taru_laptop-45266=1}
      2013-09-12 07:52:34,410|main|DEBUG|org.jgroups.protocols.pbcast.ClientGmsImpl.joinInternal(ClientGmsImpl.java:133) - sending JOIN(taru_laptop-12830) to taru_laptop-45266
      2013-09-12 07:52:34,987|main|DEBUG|org.jgroups.protocols.pbcast.NAKACK.setDigest(NAKACK.java:1216) -
      [taru_laptop-12830 setDigest()]
      existing digest:  []
      new digest:       taru_laptop-45266: [0 (0)], taru_laptop-12830: [0 (0)]
      resulting digest: taru_laptop-12830: [0 (0)], taru_laptop-45266: [0 (0)]
      2013-09-12 07:52:34,987|main|DEBUG|org.jgroups.protocols.pbcast.GMS.installView(GMS.java:595) - taru_laptop-12830: installing [taru_laptop-45266|1] [taru_laptop-45266, taru_laptop-12830]
      2013-09-12 07:52:35,003|main|DEBUG|org.jgroups.protocols.FD_SOCK.down(FD_SOCK.java:328) - VIEW_CHANGE received: [taru_laptop-45266, taru_laptop-12830]
      2013-09-12 07:52:35,003|FD_SOCK pinger,taru_laptop-12830|DEBUG|org.jgroups.protocols.FD_SOCK.run(FD_SOCK.java:386) - ping_dest is taru_laptop-45266, pingable_mbrs=[taru_laptop-45266, taru_laptop-12830]
      2013-09-12 07:52:35,003|main|DEBUG|org.infinispan.remoting.transport.jgroups.JGroupsTransport.viewAccepted(JGroupsTransport.java:617) - New view accepted: [taru_laptop-45266|1] [taru_laptop-45266, taru_laptop-12830]
      2013-09-12 07:52:35,003|main|INFO |org.infinispan.remoting.transport.jgroups.JGroupsTransport.viewAccepted(JGroupsTransport.java:644) - ISPN000094: Received new cluster view: [taru_laptop-45266|1] [taru_laptop-45266, taru_laptop-12830]
      2013-09-12 07:52:35,018|main|INFO |com.enlighta.cluster.JMSClientListener.observeViewChanged(JMSClientListener.java:34) - View Changed : EventImpl{type=VIEW_CHANGED, newMembers=[taru_laptop-45266, taru_laptop-12830], oldMembers=null, localAddress=taru_laptop-12830, viewId=1, subgroupsMerged=null, mergeView=false}
      2013-09-12 07:52:35,018|main|INFO |org.infinispan.remoting.transport.jgroups.JGroupsTransport.startJGroupsChannelIfNeeded(JGroupsTransport.java:220) - ISPN000079: Cache local address is taru_laptop-12830, physical addresses are [fe80:0:0:0:d572:3236:54a6:1ff0%13:61344]
      2013-09-12

       

       

       

       

      Here is the logs where tomcat nodes start on linux server and they are not able to join cluster.

       

      tomcat 1 logs
      -----------------------------------------------------------------------------------

          2013-09-12 07:39:31,785|main|INFO  - ISPN000078: Starting JGroups Channel
          2013-09-12 07:39:31,903|main|WARN  - [JGRP00014] TP.discard_incompatible_packets has been deprecated: incompatible packets are discarded anyway
           2013-09-12 07:39:31,903|main|WARN  - [JGRP00014] TP.enable_bundling has been deprecated: will be ignored as bundling is on by default
          2013-09-12 07:39:31,925|main|WARN  - [JGRP00014] UNICAST.setTimeout has been deprecated: not used anymore
           2013-09-12 07:39:31,971|main|DEBUG - set property UDP.bind_addr to default value /192.168.0.5
          2013-09-12 07:39:31,971|main|DEBUG - set property UDP.diagnostics_addr to default value /224.0.75.75
           2013-09-12 07:39:31,997|main|DEBUG - received CONFIG event: {bind_addr=/192.168.0.5}
          2013-09-12 07:39:32,007|main|DEBUG - sockets will use interface 192.168.0.5
          2013-09-12 07:39:32,008|main|WARN  - [JGRP00015] the send buffer of socket DatagramSocket was set to 640KB, but the OS only allocated 212.99KB. This might lead to performance problems. Please set your max send buffer in the OS correctly (e.g. net.core.wmem_max on Linux)
          2013-09-12 07:39:32,008|main|WARN  - [JGRP00015] the receive buffer of socket DatagramSocket was set to 20MB, but the OS only allocated 212.99KB. This might lead to per
           formance problems. Please set your max receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
          2013-09-12 07:39:32,009|main|WARN  - [JGRP00015] the send buffer of socket MulticastSocket was set to 640KB, but the OS only allocated 212.99KB. This might lead to perf
           ormance problems. Please set your max send buffer in the OS correctly (e.g. net.core.wmem_max on Linux)
          2013-09-12 07:39:32,009|main|WARN  - [JGRP00015] the receive buffer of socket MulticastSocket was set to 25MB, but the OS only allocated 212.99KB. This might lead to pe
           rformance problems. Please set your max receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
          2013-09-12 07:39:32,010|main|DEBUG - socket information:
          mcast_addr=228.6.7.8:46655, bind_addr=/192.168.0.5, ttl=2
           sock: bound to 192.168.0.5:33562, receive buffer size=212992, send buffer size=212992
          mcast_sock: bound to 192.168.0.5:46655, send buffer size=212992, receive buffer size=212992
           2013-09-12 07:39:32,012|main|DEBUG - address=localhost-45145, cluster=ISPN, physical address=192.168.0.5:33562
          2013-09-12 07:40:02,030|main|DEBUG -
          [localhost-45145 setDigest()]
           existing digest:  []
          new digest:       localhost-45145: [0 (0)]
          resulting digest: localhost-45145: [0 (0)]
          2013-09-12 07:40:02,031|main|DEBUG - localhost-45145: installing [localhost-45145|0] [localhost-45145]
           2013-09-12 07:40:02,033|main|DEBUG - resuming message garbage collection
          2013-09-12 07:40:02,034|main|DEBUG - VIEW_CHANGE received: [localhost-45145]
          2013-09-12 07:40:02,035|main|DEBUG - New view accepted: [localhost-45145|0] [localhost-45145]
           2013-09-12 07:40:02,036|main|INFO  - ISPN000094: Received new cluster view: [localhost-45145|0] [localhost-45145]
          2013-09-12 07:40:02,038|main|INFO  - View Changed : EventImpl{type=VIEW_CHANGED, newMembers=[localhost-45145], oldMembers=null, localAddress=localhost-45145, viewId=0,
           subgroupsMerged=null, mergeView=false}
          2013-09-12 07:40:02,038|main|DEBUG - resuming message garbage collection
          2013-09-12 07:40:02,039|main|DEBUG - created group (first member). My view is [localhost-45145|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl
           2013-09-12 07:40:02,039|main|INFO  - ISPN000079: Cache local address is localhost-45145, physical addresses are [192.168.0.5:33562]

       

       

       

      tomcat 2 log

       

      ----------------------------------------------------------------------------------------------------


      2013-09-12 07:38:39,740|main|INFO  - Trying to create MAP of caches so it can be used by components..
      2013-09-12 07:38:39,816|main|INFO  - ISPN000078: Starting JGroups Channel
      2013-09-12 07:38:39,931|main|WARN  - [JGRP00014] TP.discard_incompatible_packets has been deprecated: incompatible packets are discarded anyway
      2013-09-12 07:38:39,932|main|WARN  - [JGRP00014] TP.enable_bundling has been deprecated: will be ignored as bundling is on by default
      2013-09-12 07:38:39,953|main|WARN  - [JGRP00014] UNICAST.setTimeout has been deprecated: not used anymore
      2013-09-12 07:38:39,998|main|DEBUG - set property UDP.bind_addr to default value /192.168.0.5
      2013-09-12 07:38:39,998|main|DEBUG - set property UDP.diagnostics_addr to default value /224.0.75.75
      2013-09-12 07:38:40,025|main|DEBUG - received CONFIG event: {bind_addr=/192.168.0.5}
      2013-09-12 07:38:40,034|main|DEBUG - sockets will use interface 192.168.0.5
      2013-09-12 07:38:40,036|main|WARN  - [JGRP00015] the send buffer of socket DatagramSocket was set to 640KB, but the OS only allocated 212.99KB. This might lead to perfo
      rmance problems. Please set your max send buffer in the OS correctly (e.g. net.core.wmem_max on Linux)
      2013-09-12 07:38:40,036|main|WARN  - [JGRP00015] the receive buffer of socket DatagramSocket was set to 20MB, but the OS only allocated 212.99KB. This might lead to per
      formance problems. Please set your max receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
      2013-09-12 07:38:40,037|main|WARN  - [JGRP00015] the send buffer of socket MulticastSocket was set to 640KB, but the OS only allocated 212.99KB. This might lead to perf
      ormance problems. Please set your max send buffer in the OS correctly (e.g. net.core.wmem_max on Linux)
      2013-09-12 07:38:40,037|main|WARN  - [JGRP00015] the receive buffer of socket MulticastSocket was set to 25MB, but the OS only allocated 212.99KB. This might lead to pe
      rformance problems. Please set your max receive buffer in the OS correctly (e.g. net.core.rmem_max on Linux)
      2013-09-12 07:38:40,038|main|DEBUG - socket information:
      mcast_addr=228.6.7.8:46655, bind_addr=/192.168.0.5, ttl=2
      sock: bound to 192.168.0.5:46484, receive buffer size=212992, send buffer size=212992
      mcast_sock: bound to 192.168.0.5:46655, send buffer size=212992, receive buffer size=212992
      2013-09-12 07:38:40,040|main|DEBUG - address=localhost-28168, cluster=ISPN, physical address=192.168.0.5:46484
      2013-09-12 07:39:10,056|main|DEBUG -
      [localhost-28168 setDigest()]
      existing digest:  []
      new digest:       localhost-28168: [0 (0)]
      resulting digest: localhost-28168: [0 (0)]
      2013-09-12 07:39:10,056|main|DEBUG - localhost-28168: installing [localhost-28168|0] [localhost-28168]
      2013-09-12 07:39:10,057|main|DEBUG - resuming message garbage collection
      2013-09-12 07:39:10,058|main|DEBUG - VIEW_CHANGE received: [localhost-28168]
      2013-09-12 07:39:10,060|main|DEBUG - New view accepted: [localhost-28168|0] [localhost-28168]
      2013-09-12 07:39:10,061|main|INFO  - ISPN000094: Received new cluster view: [localhost-28168|0] [localhost-28168]
      2013-09-12 07:39:10,063|main|INFO  - View Changed : EventImpl{type=VIEW_CHANGED, newMembers=[localhost-28168], oldMembers=null, localAddress=localhost-28168, viewId=0,

       

      subgroupsMerged=null, mergeView=false}

      2013-09-12 07:39:10,063|main|DEBUG - resuming message garbage collection

      2013-09-12 07:39:10,064|main|DEBUG - created group (first member). My view is [localhost-28168|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl

      2013-09-12 07:39:10,065|main|INFO  - ISPN000079: Cache local address is localhost-28168, physical addresses are [192.168.0.5:46484]

      2013-09-12 07:39:10,065|main|DEBUG - Waiting on view being accepted