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

Intents sometimes get stuck in INSTALLING phase when recompiled due to switch disconnect

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Major
    • Resolution: Done
    • Affects Version/s: 1.1.0, 1.2.0
    • Fix Version/s: 1.2.0
    • Component/s: None
    • Labels:
    • Environment:

      commit cbe6de3bb90daf5a72462f6dc29739915cff2871

    • Epic Link:
    • Sprint:
      Cardinal Sprint 4 (5/4-5/15), Cardinal Sprint 5 (5/18-5/22)

      Description

      If a switch that is being used to satisfy a Host Intent is disconnected sometimes the intents will get stuck in the INSTALLING phase and no corresponding flows will be installed on the switch. I have only seen this happen in a multinode cluster.

      In the attached logs, Intent "0x500003" gets stuck in INSTALLING state after device "of:0000000000005000" is stopped at around 2015-03-03 10:01:36,979. In these logs, I have set the following log levels:

      onos> log:list
      Logger                                      | Level
      ---------------------------------------------------
      ROOT                                        | INFO
      com.hazelcast.cluster.impl.MulticastService | ERROR
      net.kuujo.copycat                           | INFO
      org.apache.sshd                             | WARN
      org.onosproject.net.flow.impl               | TRACE
      org.onosproject.net.intent.impl             | TRACE
      

      In see no logs from InstallerRegistry after the IntentManager starts execution.

      Here is a section from ONOS3( partition leader with the given intent) around the time of the recompile

      2015-03-03 10:01:36,806 | INFO  | event-dispatch-0 | LinkManager                      | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Link DefaultLink{src=ConnectPoint{elementId=of:0000000000001000, portNumber=3}, dst=ConnectPoint{elementId=of:0000000000005000, portNumber=3}, type=DIRECT, state=ACTIVE, durable=false} removed/vanished
      2015-03-03 10:01:36,820 | INFO  | nos-topo-build-4 | TopologyManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Topology DefaultTopology{time=434130104863750, computeCost=424570, clusters=1, devices=27, links=52} changed
      2015-03-03 10:01:36,820 | DEBUG | tent-flowtracker | ObjectiveTracker                 | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | recompile triggered by LinkDown LinkKey{src=ConnectPoint{elementId=of:0000000000005000, portNumber=2}, dst=ConnectPoint{elementId=of:0000000000002000, portNumber=2}} [0x500003]
      2015-03-03 10:01:36,820 | DEBUG | tent-flowtracker | ObjectiveTracker                 | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | recompile triggered by LinkDown LinkKey{src=ConnectPoint{elementId=of:0000000000005000, portNumber=3}, dst=ConnectPoint{elementId=of:0000000000001000, portNumber=3}} []
      2015-03-03 10:01:36,820 | DEBUG | tent-flowtracker | ObjectiveTracker                 | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | recompile triggered by LinkDown LinkKey{src=ConnectPoint{elementId=of:0000000000005000, portNumber=4}, dst=ConnectPoint{elementId=of:0000000000006000, portNumber=2}} [0x500003]
      2015-03-03 10:01:36,820 | DEBUG | tent-flowtracker | ObjectiveTracker                 | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | recompile triggered by LinkDown LinkKey{src=ConnectPoint{elementId=of:0000000000006000, portNumber=2}, dst=ConnectPoint{elementId=of:0000000000005000, portNumber=4}} [0x500003]
      2015-03-03 10:01:36,820 | DEBUG | tent-flowtracker | ObjectiveTracker                 | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | recompile triggered by LinkDown LinkKey{src=ConnectPoint{elementId=of:0000000000002000, portNumber=2}, dst=ConnectPoint{elementId=of:0000000000005000, portNumber=2}} [0x500003]
      2015-03-03 10:01:36,820 | DEBUG | tent-flowtracker | ObjectiveTracker                 | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | recompile triggered by LinkDown LinkKey{src=ConnectPoint{elementId=of:0000000000001000, portNumber=3}, dst=ConnectPoint{elementId=of:0000000000005000, portNumber=3}} []
      2015-03-03 10:01:36,821 | WARN  | t-pending-notify | BoundedThreadPool                | 73 - org.onosproject.onlab-misc - 1.1.0.SNAPSHOT | queue size: 0 jobs, submitted: 0.04563292872136533 jobs/s, taken: 0.04563292872136533 jobs/s
      2015-03-03 10:01:36,823 | INFO  | ew I/O worker #5 | DistributedMastershipStore       | 161 - org.onosproject.onos-core-dist - 1.1.0.SNAPSHOT | 10.128.30.13 trying to pass mastership for of:0000000000005000 to 10.128.30.16
      2015-03-03 10:01:36,830 | DEBUG | tent-op-batching | IntentManager                    | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Execute 1 operation(s).
      2015-03-03 10:01:36,831 | TRACE | tent-op-batching | IntentManager                    | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Execute operations: [IntentData{key=0x500003, state=INSTALL_REQ, version=WallClockTimestamp{unixTimestamp=1425405696820}, intent=HostToHostIntent{id=0x500003, key=0x500003, appId=DefaultApplicationId{id=0, name=org.onosproject.cli}, resources=[], selector=DefaultTrafficSelector{criteria=[]}, treatment=DefaultTrafficTreatment{instructions=[]}, constraints=[LinkTypeConstraint{inclusive=false, types=[OPTICAL]}], one=00:00:00:00:00:11/-1, two=00:00:00:00:00:1B/-1}, installables=null}]
      2015-03-03 10:01:36,845 | WARN  | t-current-notify | BoundedThreadPool                | 73 - org.onosproject.onlab-misc - 1.1.0.SNAPSHOT | queue size: 0 jobs, submitted: 0.030447424909038318 jobs/s, taken: 0.030447424909038318 jobs/s
      2015-03-03 10:01:36,846 | DEBUG | of-event-stats-2 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000909c70f6c, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:0B}, ETH_SRC{mac=00:00:00:00:00:15}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696842}, state=REMOVED} removed
      2015-03-03 10:01:36,846 | DEBUG | f-event-stats-25 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000809c70828, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:15}, ETH_SRC{mac=00:00:00:00:00:0B}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696842}, state=REMOVED} removed
      2015-03-03 10:01:36,849 | DEBUG | of-event-stats-0 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000d09c71e70, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:0D}, ETH_SRC{mac=00:00:00:00:00:17}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696844}, state=REMOVED} removed
      2015-03-03 10:01:36,850 | DEBUG | of-event-stats-9 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000c09c7172c, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:17}, ETH_SRC{mac=00:00:00:00:00:0D}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696843}, state=REMOVED} removed
      2015-03-03 10:01:36,858 | WARN  | ntLoopGroup-15-3 | NettyMessagingService            | 163 - org.onosproject.onlab-netty - 1.1.0.SNAPSHOT | Received a reply for message id:[8185].  from Endpoint{ip=10.128.30.16, port=9876}. But was unable to locate the request handle
      2015-03-03 10:01:36,910 | DEBUG | f-event-stats-13 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000b09c716ee, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:0C}, ETH_SRC{mac=00:00:00:00:00:16}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696901}, state=REMOVED} removed
      2015-03-03 10:01:36,911 | DEBUG | of-event-stats-8 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000370149522, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:13}, ETH_SRC{mac=00:00:00:00:00:09}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696902}, state=REMOVED} removed
      2015-03-03 10:01:36,912 | DEBUG | f-event-stats-19 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000a09c70faa, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:16}, ETH_SRC{mac=00:00:00:00:00:0C}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696902}, state=REMOVED} removed
      2015-03-03 10:01:36,912 | DEBUG | f-event-stats-20 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=100058c5eb5e7, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:11}, ETH_SRC{mac=00:00:00:00:00:1B}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696902}, state=REMOVED} removed
      2015-03-03 10:01:36,912 | DEBUG | f-event-stats-29 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000472896342, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:12}, ETH_SRC{mac=00:00:00:00:00:08}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696903}, state=REMOVED} removed
      2015-03-03 10:01:36,912 | DEBUG | f-event-stats-23 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=100079e1695ee, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:19}, ETH_SRC{mac=00:00:00:00:00:0F}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696903}, state=REMOVED} removed
      2015-03-03 10:01:36,912 | DEBUG | of-event-stats-4 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=10006ad2293bc, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:1A}, ETH_SRC{mac=00:00:00:00:00:10}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696904}, state=REMOVED} removed
      2015-03-03 10:01:36,912 | DEBUG | of-event-stats-1 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=10008ad229b00, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:10}, ETH_SRC{mac=00:00:00:00:00:1A}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696904}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | f-event-stats-22 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=10007ad228bfc, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:0E}, ETH_SRC{mac=00:00:00:00:00:18}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696903}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | of-event-stats-3 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=100059e167064, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:14}, ETH_SRC{mac=00:00:00:00:00:0A}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696903}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | f-event-stats-12 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=10005ad2284b8, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:18}, ETH_SRC{mac=00:00:00:00:00:0E}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696903}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | f-event-stats-15 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=100069e1677a8, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:0A}, ETH_SRC{mac=00:00:00:00:00:14}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696903}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | f-event-stats-11 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=100048c5eaea3, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:1B}, ETH_SRC{mac=00:00:00:00:00:11}, IN_PORT{port=2}], treatment=N/A, table type=DEFAULT, created=1425405696903}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | f-event-stats-21 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000572896a86, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:08}, ETH_SRC{mac=00:00:00:00:00:12}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696902}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | f-event-stats-31 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=1000470149c66, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:09}, ETH_SRC{mac=00:00:00:00:00:13}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696902}, state=REMOVED} removed
      2015-03-03 10:01:36,913 | DEBUG | f-event-stats-26 | FlowRuleManager                  | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Flow DefaultFlowEntry{rule=DefaultFlowEntry{id=100089e169d32, deviceId=of:0000000000006000, priority=123, selector=[ETH_DST{mac=00:00:00:00:00:0F}, ETH_SRC{mac=00:00:00:00:00:19}, IN_PORT{port=4}], treatment=N/A, table type=DEFAULT, created=1425405696904}, state=REMOVED} removed
      2015-03-03 10:01:36,937 | INFO  | ew I/O worker #6 | GossipDeviceStore                | 161 - org.onosproject.onos-core-dist - 1.1.0.SNAPSHOT | Notifying peers of a port status update topology event for providerId: ProviderId{scheme=of, id=org.onosproject.provider.openflow, ancillary=false} and deviceId: of:0000000000006000
      2015-03-03 10:01:36,938 | INFO  | ew I/O worker #6 | DeviceManager                    | 159 - org.onosproject.onos-core-net - 1.1.0.SNAPSHOT | Device of:0000000000006000 port 2 status changed
      

        Attachments

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

          Activity

            People

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

              Dates

              Created:
              Updated:
              Resolved: