Uploaded image for project: 'ONOS'
  1. ONOS
  2. ONOS-2889

Rejected AppendRequest and IndexOutOfBoundsException on startup

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Minor
    • Resolution: Done
    • Affects Version/s: 1.3.0
    • Fix Version/s: 1.6.0
    • Component/s: None
    • Labels:
      None
    • Environment:

      1.3-rc3

    • Epic Link:
    • Sprint:
      Emu Sprint 1 (9/21-10/9)

      Description

      7 node cluster with fresh install. On startup one of the nodes has these exceptions:

      first instance

       337 2015-09-15 09:40:26,530 | WARN  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Rejected AppendRequest[term     =5, leader=onos://10.128.30.12:9876, logIndex=1, logTerm=5, entries=[0], firstIndex=false, commitIndex=null]: Request entry term does not match local log. Local log term is 3. Replying with AppendRes     ponse[status=OK, term=5, succeeded=false, logIndex=1]
       338 2015-09-15 09:40:26,534 | WARN  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Rejected AppendRequest[term     =5, leader=onos://10.128.30.12:9876, logIndex=1, logTerm=5, entries=[0], firstIndex=false, commitIndex=null]: Request entry term does not match local log. Local log term is 3. Replying with AppendRes     ponse[status=OK, term=5, succeeded=false, logIndex=1]
       339 2015-09-15 09:40:26,539 | INFO  | FelixStartLevel  | ConsistentApplicationIdStore     | 79 - org.onosproject.onos-core-dist - 1.3.0.SNAPSHOT | Started
       340 2015-09-15 09:40:26,540 | INFO  | FelixStartLevel  | ConsistentIdBlockStore           | 79 - org.onosproject.onos-core-dist - 1.3.0.SNAPSHOT | Started
       341 2015-09-15 09:40:26,545 | WARN  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Rejected AppendRequest[term     =5, leader=onos://10.128.30.12:9876, logIndex=1, logTerm=5, entries=[0], firstIndex=false, commitIndex=null]: Request entry term does not match local log. Local log term is 3. Replying with AppendRes     ponse[status=OK, term=5, succeeded=false, logIndex=1]
       342 2015-09-15 09:40:26,550 | WARN  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Synced entry does not match      local log, removing incorrect entries
       343 2015-09-15 09:40:26,551 | WARN  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | doAppendEntries
       344 java.lang.IndexOutOfBoundsException: Log index out of bounds
       345         at net.kuujo.copycat.util.internal.Assert.index(Assert.java:114)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       346         at net.kuujo.copycat.state.internal.SnapshottableLogManager.removeAfter(SnapshottableLogManager.java:190)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       347         at net.kuujo.copycat.raft.ActiveState.doAppendEntries(ActiveState.java:195)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       348         at net.kuujo.copycat.raft.ActiveState.handleAppend(ActiveState.java:86)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       349         at net.kuujo.copycat.raft.ActiveState.append(ActiveState.java:49)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       350         at net.kuujo.copycat.raft.FollowerState.append(FollowerState.java:157)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       351         at net.kuujo.copycat.raft.RaftContext$$Lambda$159/331159152.apply(Unknown Source)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       352         at net.kuujo.copycat.raft.RaftContext.lambda$wrapCall$21(RaftContext.java:562)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       353         at net.kuujo.copycat.raft.RaftContext$$Lambda$109/1173896349.run(Unknown Source)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       354         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_25]
       355         at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_25]
       356         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_25]
       357         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_25]
       358         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_25]
       359         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_25]
       360         at java.lang.Thread.run(Thread.java:745)[:1.8.0_25]
      

      and the second instance of this exception

       512 2015-09-15 09:40:35,448 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Heartbeat timed out in 3938      milliseconds
       513 2015-09-15 09:40:35,448 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Polling members [onos://10.     128.30.13:9876, onos://10.128.30.16:9876, onos://10.128.30.17:9876, onos://10.128.30.12:9876, onos://10.128.30.14:9876, onos://10.128.30.11:9876, onos://10.128.30.15:9876]
       514 2015-09-15 09:40:35,449 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Received accepted poll from      onos://10.128.30.16:9876
       515 2015-09-15 09:40:35,450 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Received rejected poll from      onos://10.128.30.17:9876
       516 2015-09-15 09:40:35,450 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Received rejected poll from      onos://10.128.30.14:9876
       517 2015-09-15 09:40:35,450 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Received rejected poll from      onos://10.128.30.15:9876
       518 2015-09-15 09:40:35,450 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Received rejected poll from      onos://10.128.30.11:9876
       519 2015-09-15 09:40:36,848 | WARN  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Synced entry does not match      local log, removing incorrect entries
       520 2015-09-15 09:40:36,848 | WARN  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | doAppendEntries
       521 java.lang.IndexOutOfBoundsException: Log index out of bounds
       522         at net.kuujo.copycat.util.internal.Assert.index(Assert.java:114)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       523         at net.kuujo.copycat.state.internal.SnapshottableLogManager.removeAfter(SnapshottableLogManager.java:190)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       524         at net.kuujo.copycat.raft.ActiveState.doAppendEntries(ActiveState.java:195)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       525         at net.kuujo.copycat.raft.ActiveState.handleAppend(ActiveState.java:86)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       526         at net.kuujo.copycat.raft.ActiveState.append(ActiveState.java:49)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       527         at net.kuujo.copycat.raft.FollowerState.append(FollowerState.java:157)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       528         at net.kuujo.copycat.raft.RaftContext$$Lambda$159/331159152.apply(Unknown Source)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       529         at net.kuujo.copycat.raft.RaftContext.lambda$wrapCall$21(RaftContext.java:562)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       530         at net.kuujo.copycat.raft.RaftContext$$Lambda$109/1173896349.run(Unknown Source)[71:org.onosproject.onlab-thirdparty:1.3.0.SNAPSHOT]
       531         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_25]
       532         at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_25]
       533         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_25]
       534         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_25]
       535         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_25]
       536         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_25]
       537         at java.lang.Thread.run(Thread.java:745)[:1.8.0_25]
       538 2015-09-15 09:40:41,070 | INFO  | copycat-p0-1     | FollowerState                    | 71 - org.onosproject.onlab-thirdparty - 1.3.0.SNAPSHOT | onos://10.128.30.16:9876 - Heartbeat timed out in 4222      milliseconds
      

        Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

            People

            Assignee:
            madan Madan Jampani
            Reporter:
            jhall Jon Hall
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: