[VOL-4495] In "Test Disable and Delete OLT for DT" the LLDP flow is not removed on device delete - OpenCORD JIRA

XML

Word

Printable

Details

Type: Bug
Status: Resolved (View Workflow)
Priority: High
Resolution: Fixed
Affects Version/s: VOLTHA v2.9
Fix Version/s: VOLTHA v2.9
Component/s: onos-olt, openolt-adapter, rw-core
Labels:
- onf

Story Points:
3
Sprint:
VOLTHA 2.9 - Release sprint

Description

When the OLT is disabled and then removed the LLDP flow removal fails with:

infra/voltha-infra-onos-classic-0[onos-classic]: 15:21:03.002 DEBUG [OltPipeline] Applying batch FlowRuleOperations{stages=[[FlowRuleO    peration{rule=DefaultFlowRule{id=d000000f6b278, deviceId=of:0000a82bb536786c, priority=10000, selector=[IN_PORT:16777216, ETH_TYPE:lld    p], treatment=DefaultTrafficTreatment{immediate=[OUTPUT:CONTROLLER], deferred=[], transition=None, meter=[], cleared=false, StatTrigge    r=null, metadata=null}, tableId=0, created=1638112862990}, type=REMOVE}]]}

infra/voltha-infra-onos-classic-0[onos-classic]: 15:21:19.689 ERROR [OltFlowService] Falied to remove LLDP filter on of:0000a82bb53678    6c/16777216[nni-16777216] because INSTALLATIONTIMEOUT

but VOLTHA core doesn't receive the `flow-delete-strict` request until 3 minutes after the timeout expired:

voltha/voltha-voltha-rw-core-768f58f694-nk9v9[voltha]: {"level":"debug","ts":"2021-11-28T15:24:38.160Z","caller":"device/logical_agent_flow.go:404","msg":"flow-delete-strict","instanceId":"voltha-voltha-rw-core-768f58f694-nk9v9","op-id":"0d6e984b7a380632","op-name":"openflow-flow-delete-strict","task-id":"5a30c2b2c25b18ea","task-name":"/voltha.VolthaService/UpdateLogicalDeviceFlowTable","mod":"cookie:3659174713406072 command:OFPFC_DELETE_STRICT priority:10000 buffer_id:4294967295 out_port:4294967295 out_group:4294967295 flags:1 match:<type:OFPMT_OXM oxm_fields:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<port:16777216 > > oxm_fields:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<type:OFPXMT_OFB_ETH_TYPE eth_type:35020 > > > "}

At that point the device has been recreated but the flow is not there (as expected), thus the removal fails.

voltha/voltha-voltha-rw-core-768f58f694-nk9v9[voltha]: {"level":"error","ts":"2021-11-28T15:24:38.163Z","caller":"grpc/client.go:225","msg":"received-error","instanceId":"voltha-voltha-rw-core-768f58f694-nk9v9","op-id":"0d6e984b7a380632","op-name":"openflow-flow-delete-strict","task-id":"5a30c2b2c25b18ea","task-name":"/voltha.VolthaService/UpdateLogicalDeviceFlowTable","error":"rpc error: code = Unknown desc = errors-installing-flows-groups, errors:[not-found: [{\"device-id\":\"0d301fca-ae60-4481-9bb4-98cec071a2bf\",\"flow\":{\"id\":6416862919329787925,\"priority\":10000,\"cookie\":3659174713406072,\"match\":{\"type\":1,\"oxm_fields\":[{\"oxm_class\":32768,\"Field\":{\"OfbField\":{\"Value\":{\"Port\":16777216},\"Mask\":null}}},{\"oxm_class\":32768,\"Field\":{\"OfbField\":{\"type\":5,\"Value\":{\"EthType\":35020},\"Mask\":null}}}]},\"instructions\":[{\"type\":4,\"Data\":{\"Actions\":{\"actions\":[{\"Action\":{\"Output\":{\"port\":4294967293}}}]}}}]},\"intf-id\":0,\"onu-id\":0,\"target\":\"tp-id\",\"uni-id\":0}]: not-found: [{\"flow\":{\"id\":6416862919329787925,\"priority\":10000,\"cookie\":3659174713406072,\"match\":{\"type\":1,\"oxm_fields\":[{\"oxm_class\":32768,\"Field\":{\"OfbField\":{\"Value\":{\"Port\":16777216},\"Mask\":null}}},{\"oxm_class\":32768,\"Field\":{\"OfbField\":{\"type\":5,\"Value\":{\"EthType\":35020},\"Mask\":null}}}]},\"instructions\":[{\"type\":4,\"Data\":{\"Actions\":{\"actions\":[{\"Action\":{\"Output\":{\"port\":4294967293}}}]}}}]},\"target\":\"metadata\"}]]","context":"context.Background.WithValue(type opentracing.contextKey, val 0d6e984b7a380632:5a30c2b2c25b18ea:6efbb166dc6058f0:0).WithValue(type utils.contextKey, val UpdateLogicalDeviceFlowTable).WithDeadline(2021-11-28 15:25:08.161524567 +0000 UTC m=+2504.624474377 [29.998271442s])","endpoint":"voltha-voltha-adapter-openolt-api.voltha.svc:50060","stacktrace":"github.com/opencord/voltha-lib-go/v7/pkg/grpc.(*Client).clientInterceptor\n\t/go/src/vendor/github.com/opencord/voltha-lib-go/v7/pkg/grpc/client.go:225\ngoogle.golang.org/grpc.(*ClientConn).Invoke\n\t/go/src/vendor/google.golang.org/grpc/call.go:35\ngithub.com/opencord/voltha-protos/v5/go/adapter_service.(*adapterServiceClient).UpdateFlowsIncrementally\n\t/go/src/vendor/github.com/opencord/voltha-protos/v5/go/adapter_service/adapter_service.pb.go:283\ngithub.com/opencord/voltha-go/rw_core/core/device.(*Agent).sendIncrementalFlows\n\t/go/src/rw_core/core/device/agent_flow.go:208"}

It appears that OfAgent closes the connection to ONOS a second before the LLDP is removed:

voltha/voltha-voltha-ofagent-5b5d5db88c-wc5zc[ofagent]: {"level":"debug","ts":"2021-11-28T15:21:02.890Z","caller":"openflow/connection.go:228","msg":"closing-of-connection","instanceId":"voltha-voltha-ofagent-5b5d5db88c-wc5zc","device-id":"5e2f308d-0d8f-468b-9193-67c51da39c01"}

ONOS pushes the LLDP flow again at:

infra/voltha-infra-onos-classic-0[onos-classic]: 15:24:16.382 DEBUG [OltPipeline] Adding pair to batch: (DefaultFilteringObjective{id=    -207660788, type=PERMIT, op=ADD, priority=10000, key=IN_PORT:16777216, conditions=[ETH_TYPE:lldp], meta=DefaultTrafficTreatment{immedi    ate=[OUTPUT:CONTROLLER], deferred=[], transition=None, meter=[], cleared=false, StatTrigger=null, metadata=null}, appId=DefaultApplica    tionId{id=13, name=org.opencord.olt}, permanent=true, timeout=0, annotations={}},DefaultFlowRule{id=d000000f6b278, deviceId=of:0000a82    bb536786c, priority=10000, selector=[IN_PORT:16777216, ETH_TYPE:lldp], treatment=DefaultTrafficTreatment{immediate=[OUTPUT:CONTROLLER]    , deferred=[], transition=None, meter=[], cleared=false, StatTrigger=null, metadata=null}, tableId=0, created=1638113056381})

and VOLTHA installs it

voltha/voltha-voltha-rw-core-768f58f694-nk9v9[voltha]: {"level":"debug","ts":"2021-11-28T15:24:16.477Z","caller":"device/logical_agent_flow.go:77","msg":"flow-add","instanceId":"voltha-voltha-rw-core-768f58f694-nk9v9","op-name":"openflow-flow-add","task-id":"34c61572a1c71e49","task-name":"/voltha.VolthaService/UpdateLogicalDeviceFlowTable","op-id":"68c0a07cfd480005","flow":"cookie:3659174713406072 priority:10000 buffer_id:4294967295 out_port:4294967295 out_group:4294967295 flags:1 match:<type:OFPMT_OXM oxm_fields:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<port:16777216 > > oxm_fields:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<type:OFPXMT_OFB_ETH_TYPE eth_type:35020 > > > instructions:<type:4 actions:<actions:<output:<port:4294967293 > > > > "}

voltha/voltha-voltha-rw-core-768f58f694-nk9v9[voltha]: {"level":"info","ts":"2021-11-28T15:24:16.499Z","caller":"device/agent_device_update.go:46","msg":"logDeviceUpdate-success","instanceId":"voltha-voltha-rw-core-768f58f694-nk9v9","op-id":"68c0a07cfd480005","op-name":"openflow-flow-add","task-id":"34c61572a1c71e49","task-name":"/voltha.VolthaService/UpdateLogicalDeviceFlowTable","rpc":"UpdateLogicalDeviceFlowTable","device-id":"0d301fca-ae60-4481-9bb4-98cec071a2bf","requested-by":"NB","state-change":"","status":"OPERATION_SUCCESS","description":"","error":null}

But at the end of the test the flow is still reported as `PENDING_REMOVE` in ONOS:

deviceId=of:0000a82bb536786c, flowRuleCount=9
    PENDING_REMOVE, bytes=0, packets=0, table=0, priority=10000, selector=[IN_PORT:16777216, ETH_TYPE:lldp], treatment=[immediate=[OUTPUT:CONTROLLER]]
    ADDED, bytes=0, packets=0, table=0, priority=1000, selector=[IN_PORT:256, VLAN_VID:Any], treatment=[transition=TABLE:1, meter=METER:5, metadata=METADATA:1000004001000000/0]
    ADDED, bytes=0, packets=0, table=0, priority=1000, selector=[IN_PORT:655616, VLAN_VID:Any], treatment=[transition=TABLE:1, meter=METER:4, metadata=METADATA:1000004001000000/0]
    ADDED, bytes=0, packets=0, table=0, priority=1000, selector=[IN_PORT:16777216, VLAN_VID:22], treatment=[immediate=[VLAN_POP], transition=TABLE:1, meter=METER:6, metadata=METADATA:1000004000000100/0]
    ADDED, bytes=0, packets=0, table=0, priority=1000, selector=[IN_PORT:16777216, VLAN_VID:11], treatment=[immediate=[VLAN_POP], transition=TABLE:1, meter=METER:4, metadata=METADATA:10000040000a0100/0]
    ADDED, bytes=0, packets=0, table=1, priority=1000, selector=[IN_PORT:16777216, METADATA:100, VLAN_VID:Any], treatment=[immediate=[OUTPUT:256], meter=METER:6, metadata=METADATA:4000000000/0]
    ADDED, bytes=0, packets=0, table=1, priority=1000, selector=[IN_PORT:655616, VLAN_VID:Any], treatment=[immediate=[VLAN_PUSH:vlan, VLAN_ID:11, OUTPUT:16777216], meter=METER:4, metadata=METADATA:4000000000/0]
    ADDED, bytes=0, packets=0, table=1, priority=1000, selector=[IN_PORT:256, VLAN_VID:Any], treatment=[immediate=[VLAN_PUSH:vlan, VLAN_ID:22, OUTPUT:16777216], meter=METER:5, metadata=METADATA:4000000000/0]
    ADDED, bytes=0, packets=0, table=1, priority=1000, selector=[IN_PORT:16777216, METADATA:a0100, VLAN_VID:Any], treatment=[immediate=[OUTPUT:655616], meter=METER:4, metadata=METADATA:4000000000/0]