Uploaded image for project: 'VOLTHA'
  1. VOLTHA
  2. VOL-4495

In "Test Disable and Delete OLT for DT" the LLDP flow is not removed on device delete

    XMLWordPrintable

    Details

    • 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]
      

        Attachments

        1. rw-core.log
          1.85 MB
        2. openonu.log
          3.56 MB
        3. openolt.log
          4.48 MB
        4. onos.olt.log.clean
          72 kB
        5. onos.log
          609 kB
        6. ofagent.log
          2.30 MB
        7. log.html
          1.52 MB
        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

            People

            Assignee:
            teone Matteo Scandolo
            Reporter:
            teone Matteo Scandolo
            Watchers:
            1 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Gerrit Reviews

                There are no open Gerrit changes