8 Replies Latest reply on Jul 5, 2012 6:16 PM by dex80526

    Failed to prepare view exceptions

    dex80526

      I saw lot (re-curring) cache view exceptions (below) when I start up a 3 node cluster.

      I am running ISPN 5.1.3 final with replication mode, and jgroup-tcp config.

       

      I did not rember seeing  this with 5.1.1.  Is this related to changes to 5.1.3?

       

      What is the root cause? and what should I do to track this down?

       

      thanks,

       

      =======================================

       

      2012-04-10/12:13:45.714/MDT

      [CacheViewInstaller-3,portal1.net-1609] ERROR

      org.infinispan.cacheviews.CacheViewsManagerImpl[263] - ISPN000172: Failed

      to prepare view CacheView{viewId=832,

      members=[portal1.net-1609, portal2.net-11982]}

      for cache  ispn-cipherkey, rolling back to view CacheView{viewId=831,

      members=[portal1.net-1609]}

      java.util.concurrent.ExecutionException: org.infinispan.CacheException:

      java.lang.IllegalStateException: Cannot prepare new view

      CacheView{viewId=832, members=[portal1.net-1609,

      portal2.net-11982]} on cache ispn-cipherkey, we have already

      committed view CacheView{viewId=844, members=[]}

              at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:262)

              at java.util.concurrent.FutureTask.get(FutureTask.java:119)

              at

      org.infinispan.cacheviews.CacheViewsManagerImpl.clusterPrepareView(CacheViewsManagerImpl.java:318)

              at

      org.infinispan.cacheviews.CacheViewsManagerImpl.clusterInstallView(CacheViewsManagerImpl.java:249)

              at

      org.infinispan.cacheviews.CacheViewsManagerImpl$ViewInstallationTask.call(CacheViewsManagerImpl.java:875)

              at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)

              at java.util.concurrent.FutureTask.run(FutureTask.java:166)

              at

      java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)

              at

      java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

              at java.lang.Thread.run(Thread.java:722)

      Caused by: org.infinispan.CacheException: java.lang.IllegalStateException:

      Cannot prepare new view CacheView{viewId=832,

      members=[portal1.net-1609, portal2.net-11982]}

      on cache ispn-cipherkey, we have already committed view

      CacheView{viewId=844, members=[]}

              at org.infinispan.util.Util.rewrapAsCacheException(Util.java:524)

              at

      org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.invokeRemoteCommand(CommandAwareRpcDispatcher.java:172)

              at

      org.infinispan.remoting.transport.jgroups.JGroupsTransport.invokeRemotely(JGroupsTransport.java:488)

              at

      org.infinispan.cacheviews.CacheViewsManagerImpl$2.call(CacheViewsManagerImpl.java:302)

              at

      org.infinispan.cacheviews.CacheViewsManagerImpl$2.call(CacheViewsManagerImpl.java:299)

              ... 5 more

      Caused by: java.lang.IllegalStateException: Cannot prepare new view

      CacheView{viewId=832, members=[portal1.net-1609,

      portal2.net-11982]} on cache ispn-cipherkey, we have already

      committed view CacheView{viewId=844, members=[]}

              at

      org.infinispan.cacheviews.CacheViewInfo.prepareView(CacheViewInfo.java:107)

              at

      org.infinispan.cacheviews.CacheViewsManagerImpl.handlePrepareView(CacheViewsManagerImpl.java:481)

              at

      org.infinispan.commands.control.CacheViewControlCommand.perform(CacheViewControlCommand.java:125)

              at

      org.infinispan.remoting.InboundInvocationHandlerImpl.handle(InboundInvocationHandlerImpl.java:95)

              at

      org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:221)

              at

      org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:201)

              at

      org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:456)

              at

      org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:363)

              at

      org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:238)

              at

      org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:543)

              at org.jgroups.JChannel.up(JChannel.java:716)

              at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1026)

              at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)

              at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)

              at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)

              at org.jgroups.protocols.pbcast.GMS.up(GMS.java:882)

              at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:244)

              at org.jgroups.protocols.UNICAST2.handleDataReceived(UNICAST2.java:759)

              at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:365)

              at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:595)

              at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)

              at org.jgroups.protocols.FD.up(FD.java:273)

              at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:282)

              at org.jgroups.protocols.MERGE2.up(MERGE2.java:205)

              at org.jgroups.protocols.Discovery.up(Discovery.java:359)

              at org.jgroups.protocols.TP.passMessageUp(TP.java:1174)

              at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1722)

              at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1704)

              ... 3 more

      2012-04-10/12:13:46.715/MDT

        • 1. Re: Failed to prepare view exceptions
          dan.berindei

          Dex, could you create a JIRA and post some logs with TRACE enabled for org.infinispan?

          We had a similar bug during 5.1.0 betas(https://issues.jboss.org/browse/ISPN-1571), but we didn't see anything similar happening in 5.1.3.FINAL.

          • 2. Re: Failed to prepare view exceptions
            dex80526

            I created the bug for this (ISPN-1996).

            • 3. Re: Failed to prepare view exceptions
              dan.berindei

              Dex, are you still able to reproduce this?

              • 4. Re: Failed to prepare view exceptions
                dex80526

                I have not seen this for while. I'll keep an eye on this. I'll update this when I see it again.

                • 5. Re: Failed to prepare view exceptions
                  eric2

                  I just saw that error in our production enviornment (JBoss 7.1.1) using infinispan 5.1.2

                   

                  15:49:28,621 ERROR [org.infinispan.cacheviews.CacheViewsManagerImpl] (CacheViewInstaller-2,app01/attask) ISPN000172: Failed to prepare view CacheView{viewId=3, members=[app01/attask]} for cache  SESSION, rolling back to view CacheView{viewId=2, members=[]}: java.util.concurrent.ExecutionException: java.lang.IllegalStateException: Trying to block write commands but they are already blocked for view 57

                            at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:232) [rt.jar:1.6.0_30]

                            at java.util.concurrent.FutureTask.get(FutureTask.java:91) [rt.jar:1.6.0_30]

                            at org.infinispan.cacheviews.CacheViewsManagerImpl.clusterPrepareView(CacheViewsManagerImpl.java:322)

                            at org.infinispan.cacheviews.CacheViewsManagerImpl.clusterInstallView(CacheViewsManagerImpl.java:250)

                            at org.infinispan.cacheviews.CacheViewsManagerImpl$ViewInstallationTask.call(CacheViewsManagerImpl.java:876)

                            at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [rt.jar:1.6.0_30]

                            at java.util.concurrent.FutureTask.run(FutureTask.java:138) [rt.jar:1.6.0_30]

                            at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_30]

                            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_30]

                            at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_30]

                  Caused by: java.lang.IllegalStateException: Trying to block write commands but they are already blocked for view 57

                            at org.infinispan.statetransfer.StateTransferLockImpl.blockNewTransactions(StateTransferLockImpl.java:233)

                            at org.infinispan.statetransfer.DistributedStateTransferTask.doPerformStateTransfer(DistributedStateTransferTask.java:107)

                            at org.infinispan.statetransfer.BaseStateTransferTask.performStateTransfer(BaseStateTransferTask.java:93)

                            at org.infinispan.statetransfer.BaseStateTransferManagerImpl.prepareView(BaseStateTransferManagerImpl.java:330)

                            at org.infinispan.cacheviews.CacheViewsManagerImpl.handlePrepareView(CacheViewsManagerImpl.java:486)

                            at org.infinispan.cacheviews.CacheViewsManagerImpl$3.call(CacheViewsManagerImpl.java:313)

                            ... 5 more

                  • 6. Re: Failed to prepare view exceptions
                    dan.berindei

                    Eric, we have an issue in JIRA for this (https://issues.jboss.org/browse/ISPN-1996), but we don't have enough information to find the root cause yet.

                     

                    I won't ask you to enable trace logging in production, but could you upload the logs you have from all your nodes? The error you posted looks like it happened after the cluster was already in a bad shape ("view 57"), we need to see how the problems started. Your Infinispan and JGroups configuration would also be useful.

                    • 7. Re: Failed to prepare view exceptions
                      eric2

                      <subsystem xmlns="urn:jboss:domain:infinispan:1.2" default-cache-container="cluster">

                                  <cache-container name="cluster" aliases="ha-partition" default-cache="default">

                                      <transport lock-timeout="60000"/>

                                      <replicated-cache name="default" mode="SYNC" batching="true">

                                          <locking isolation="REPEATABLE_READ"/>

                                      </replicated-cache>

                                  </cache-container>

                                  <cache-container name="web" aliases="standard-session-cache" default-cache="dist">

                                      <transport lock-timeout="60000"/>

                                      <distributed-cache name="dist" virtual-nodes="2" mode="ASYNC" batching="true">

                                          <file-store shared="false"/>

                                          <state-transfer chunk-size="2500000"/>

                                      </distributed-cache>

                                      <distributed-cache name="http-session-local-root" virtual-nodes="2" mode="ASYNC" batching="true">

                                          <file-store path="ROOT" shared="false"/>

                                          <          -transfer chunk-size="2500000"/>

                                      </distributed-cache>

                                  </cache-container>

                                  <cache-container name="ejb" aliases="sfsb sfsb-cache" default-cache="repl">

                                      <transport lock-timeout="60000"/>

                                      <replicated-cache name="repl" mode="ASYNC" batching="true">

                                          <eviction strategy="LRU"/>

                                          <file-store shared="false"/>

                                      </replicated-cache>

                                      <replicated-cache name="remote-connector-client-mappings" mode="SYNC" batching="true"/>

                                      <distributed-cache name="dist" mode="ASYNC" batching="true">

                                          <eviction strategy="LRU"/>

                                          <file-store shared="false"/>

                                      </distributed-cache>

                                  </cache-container>

                                  <cache-container name="attask" jndi-name="java:jboss/infinispan/attask" start="EAGER">

                                      <transport lock-timeout="60000"/>

                                      <distributed-cache name="SESSION" virtual-nodes="2" mode="ASYNC" start="EAGER" batching="true">

                                          <eviction strategy="LRU" max-entries="132000"/>

                                          <expiration max-idle="28800000" lifespan="-1" interval="60000"/>

                                          <state-transfer chunk-size="2500000"/>

                                          <file-store shared="false"/>

                                      </distributed-cache>

                                      <distributed-cache name="RECENT_UPDATES" virtual-nodes="2" mode="ASYNC" start="EAGER" batching="true" owners="1">

                                          <eviction strategy="LRU" max-entries="32768"/>

                                          <expiration max-idle="-1" lifespan="1800000" interval="60000"/>

                                          <state-transfer chunk-size="2500000"/>

                                          <file-store shared="false"/>

                                      </distributed-cache>

                                      <distributed-cache name="AGGREGATE_REPORT" virtual-nodes="2" mode="ASYNC" start="EAGER" batching="true" owners="1">

                                          <eviction strategy="LRU" max-entries="32768"/>

                                          <expiration max-idle="-1" lifespan="16200000" interval="60000"/>

                                          <state-transfer chunk-size="2500000"/>

                                          <file-store shared="false"/>

                                      </distributed-cache>

                                  </cache-container>

                              </subsystem>

                              <subsystem xmlns="urn:jboss:domain:jaxrs:1.0"/>

                              <subsystem xmlns="urn:jboss:domain:jca:1.1">

                                  <archive-validation enabled="true" fail-on-error="true" fail-on-warn="false"/>

                                  <bean-validation enabled="false"/>

                                  <default-workmanager>

                                      <short-running-threads>

                                          <core-threads count="50"/>

                                          <queue-length count="50"/>

                                          <max-threads count="50"/>

                                          <keepalive-time time="10" unit="seconds"/>

                                      </short-running-threads>

                                      <long-running-threads>

                                          <core-threads count="50"/>

                                          <queue-length count="50"/>

                                          <max-threads count="50"/>

                                          <keepalive-time time="10" unit="seconds"/>

                                      </long-running-threads>

                                  </default-workmanager>

                                  <cached-connection-manager/>

                              </subsystem>

                              <subsystem xmlns="urn:jboss:domain:jdr:1.0"/>

                              <subsystem xmlns="urn:jboss:domain:jgroups:1.1" default-stack="udp">

                                  <stack name="udp">

                                      <transport type="UDP" socket-binding="jgroups-udp" diagnostics-socket-binding="jgroups-diagnostics"/>

                                      <protocol type="PING"/>

                                      <protocol type="MERGE2"/>

                                      <protocol type="FD_SOCK" socket-binding="jgroups-udp-fd"/>

                                      <protocol type="FD"/>

                                      <protocol type="VERIFY_SUSPECT"/>

                                      <protocol type="BARRIER"/>

                                      <protocol type="pbcast.NAKACK"/>

                                      <protocol type="UNICAST2"/>

                                      <protocol type="pbcast.STABLE"/>

                                      <protocol type="pbcast.GMS"/>

                                      <protocol type="UFC"/>

                                      <protocol type="MFC"/>

                                      <protocol type="FRAG2"/>

                                  </stack>

                                  <stack name="tcp">

                                      <transport type="TCP" socket-binding="jgroups-tcp" diagnostics-socket-binding="jgroups-diagnostics"/>

                                      <protocol type="MPING" socket-binding="jgroups-mping"/>

                                      <protocol type="MERGE2"/>

                                      <protocol type="FD_SOCK" socket-binding="jgroups-tcp-fd"/>

                                      <protocol type="FD"/>

                                      <protocol type="VERIFY_SUSPECT"/>

                                      <protocol type="BARRIER"/>

                                      <protocol type="pbcast.NAKACK"/>

                                      <protocol type="UNICAST2"/>

                                      <protocol type="pbcast.STABLE"/>

                                      <protocol type="pbcast.GMS"/>

                                      <protocol type="UFC"/>

                                      <protocol type="MFC"/>

                                      <protocol type="FRAG2"/>

                                  </stack>

                              </subsystem>

                       

                       

                      The logs are huge, is there a way to upload a zip file of all the logs?

                      • 8. Re: Failed to prepare view exceptions
                        dex80526

                        We ran into this in our product environment before.

                         

                        We changed the garbage collection option to use CMP since we have  a large JVM heap  Since then, we have not seen the issue (at least, we do not need to restart once a week as before).

                         

                        Try the garbage collection tunning if you have not.