-
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)
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