-
Type:
Bug
-
Status: Resolved (View Workflow)
-
Priority:
High
-
Resolution: Done
-
Affects Version/s: VOLTHA v2.9
-
Fix Version/s: VOLTHA v2.9
-
Labels:
-
Story Points:3
-
Epic Link:
-
Sprint:VOLTHA 2.9 - Release sprint
- Flows stuck in `PENDING_REMOVE`
This was run using the new testcase `Flow Deletion After Adapter Restart` and this patch in the app: https://gerrit.opencord.org/c/olt/+/29674
The `openonu-adapter` was restarted at `23:14:37.948`.
The Subscriber was removed at `23:14:46.464`.
In ONOS the flow-delete was correctly sent:
default/voltha-infra-onos-classic-0[onos-classic]: 23:14:46.464 INFO [Olt] Un-provisioning subscriber on of:00000a0a0a0a0a0a/256[BBSM000a0001-1] default/voltha-infra-onos-classic-0[onos-classic]: 23:14:46.919 TRACE [OltFlowService] Status during DHCP flow check OltPortStatus {defaultEapolStatus=NONE, subscriberFlowsStatus=ADDED, dhcpStatus=ADDED} for port of:00000a0a0a0a0a0a/256[BBSM000a0001-1] and service hsia default/voltha-infra-onos-classic-0[onos-classic]: 23:14:46.922 INFO [OltFlowService] Removing EAPOL flows for subscriber BBSM000a0001-1 on of:00000a0a0a0a0a0a/256[BBSM000a0001-1] and service hsia default/voltha-infra-onos-classic-0[onos-classic]: 23:14:46.924 INFO [OltFlowService] Removing Data plane flows for subscriber BBSM000a0001-1 on of:00000a0a0a0a0a0a/256[BBSM000a0001-1] and service hsia
There are two flows that are acknowledged as removed:
# NNI to table1 (downstream dataplane) default/voltha-infra-onos-classic-0[onos-classic]: 23:14:46.949 TRACE [OltFlowService] flow event RULE_REMOVED on cp of:00000a0a0a0a0a0a/16777216[nni-16777216]: DefaultFlowEntry{rule=DefaultFlowEntry Unknown macro: {id=ad0000385b6fca, deviceId=of} , state=PENDING_REMOVE, life=0, liveType=UNKNOWN, packets=0, bytes=0, errCode=-1, errType=-1, lastSeen=1639091686681} # UNI table 1 to NNI (upstream dataplane) default/voltha-infra-onos-classic-0[onos-classic]: 23:14:51.673 TRACE [OltFlowService] flow event RULE_REMOVED on cp of:00000a0a0a0a0a0a/256[BBSM000a0001-1]: DefaultFlowEntry{rule=DefaultFlowEntry Unknown macro: {id=ad00001a8cdc6b, deviceId=of} , state=PENDING_REMOVE, life=0, liveType=UNKNOWN, packets=0, bytes=0, errCode=-1, errType=-1, lastSeen=1639091686681}
These flows are never acknowledged as removed and thus are stuck in PENDING_REMOVE in ONOS:
# Subscriber DHCP PENDING_REMOVE, bytes=0, packets=0, table=0, priority=10000, selector=[IN_PORT:256, ETH_TYPE:ipv4, IP_PROTO:17, UDP_SRC:68, UDP_DST:67], treatment=[immediate=[OUTPUT:CONTROLLER, VLAN_ID:900], meter=METER:20, metadata=METADATA:4000000014/0] # upstream dataplane (UNI to table1) PENDING_REMOVE, bytes=0, packets=0, table=0, priority=1000, selector=[IN_PORT:256, VLAN_VID:0], treatment=[immediate=[VLAN_ID:900], transition=TABLE:1, meter=METER:20, metadata=METADATA:384004001000000/0] # downstream dataplane (NNI table 1 to UNI) PENDING_REMOVE, bytes=0, packets=0, table=1, priority=1000, selector=[IN_PORT:16777216, METADATA:100, VLAN_VID:900], treatment=[immediate=[VLAN_ID:0, OUTPUT:256], meter=METER:21, metadata=METADATA:4000000000/0]
The same 3 flows are found in the logical device flows:
ID TABLEID PRIORITY COOKIE INPORT VLANID ETHTYPE IPPROTO UDPSRC UDPDST METADATA SETVLANID OUTPUT GOTOTABLE WRITEMETADATA METERID 13058172224409743451 0 1000 ~f82360ac 256 0 900 1 0x0384004001000000 20 5192934158447259775 0 10000 ~5717e4e4 256 0x0800 17 68 67 900 CONTROLLER 0x0000004000000014 20 3578831406278971018 1 1000 ~bfb3e095 16777216 900 0x0000000000000100 0 256 0x0000004000000000 21
In the device flows we only see the DHCP flow on the OLT (unluckily the test does not collect `voltctl device flows` for the ONUs):
ID TABLEID PRIORITY COOKIE INPORT VLANID ETHTYPE IPPROTO UDPSRC UDPDST TUNNELID OUTPUT WRITEMETADATA METERID 2047597234271039895 0 10000 ~5717e4e4 536870912 900 0x0800 17 68 67 256 CONTROLLER 0x0000004000000014 20
When I check in the VOLTHA logs tracking down one of them I see the message `adapters-not-ready` and then nothing:
default/voltha-voltha-rw-core-767ccdff4b-dplfx[voltha]: {"level":"debug","ts":"2021-12-09T23:14:46.930Z","caller":"flowdecomposition/flow_decomposer.go:515","msg":"process-olt-and-onu-upstream-non-controller-bound-uni-cast-flowsmap[flows:id:13058172224409743451 priority:1000 flags:1 cookie:48695175134011564 match:<type:OFPMT_OXM oxm_fields:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<port:256 > > oxm_fields:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<type:OFPXMT_OFB_VLAN_VID vlan_vid:4096 > > > instructions:<type:4 actions:<actions:<type:OFPAT_SET_FIELD set_field:<field:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<type:OFPXMT_OFB_VLAN_VID vlan_vid:4996 > > > > > > instructions:<type:1 goto_table:<table_id:1 > > instructions:<type:2 write_metadata:<metadata:253327753934274560 > > instructions:<type:6 meter:<meter_id:20 > > ]","instanceId":"voltha-voltha-rw-core-767ccdff4b-dplfx","op-id":"6c3b15d6b8fb58e7","op-name":"openflow-flow-delete-strict","task-id":"45505f87403edf90","task-name":"/voltha.VolthaService/UpdateLogicalDeviceFlowTable"} default/voltha-voltha-rw-core-767ccdff4b-dplfx[voltha]: {"level":"warn","ts":"2021-12-09T23:14:46.930Z","caller":"device/logical_agent_flow.go:460","msg":"adapters-not-ready","instanceId":"voltha-voltha-rw-core-767ccdff4b-dplfx","op-id":"6c3b15d6b8fb58e7","op-name":"openflow-flow-delete-strict","task-id":"45505f87403edf90","task-name":"/voltha.VolthaService/UpdateLogicalDeviceFlowTable","logical-device-id":"3392b083-b675-4246-a693-21cfa4b9fa97","flow":{"13058172224409743451":{"id":13058172224409743451,"priority":1000,"flags":1,"cookie":48695175134011564,"match":{"type":1,"oxm_fields":[{"oxm_class":32768,"Field":{"OfbField":{"Value":{"Port":256},"Mask":null}}},{"oxm_class":32768,"Field":{"OfbField":{"type":6,"Value":{"VlanVid":4096},"Mask":null}}}]},"instructions":[{"type":4,"Data":{"Actions":{"actions"[{"type":25,"Action":{"SetField":{"field":{"oxm_class":32768,"Field":{"OfbField":{"type":6,"Value":{"VlanVid":4996},"Mask":null}}}}}}]}}},{"type":1,"Data":{"GotoTable":{"table_id":1}}},{"type":2,"Data":{"WriteMetadata":{"metadata":253327753934274560}}},{"type":6,"Data":{"Meter":{"meter_id":20}}}]}},"error":"rpc error: code = Unavailable desc = adapter-connection-down-for-e77f801c-fb40-47d4-9e51-df79b0f45314","stacktrace":"github.com/opencord/voltha-go/rw_core/core/device.(*LogicalAgent).flowDeleteStrict\n\t/go/src/rw_core/core/device/logical_agent_flow.go:460\ngithub.com/opencord/voltha-go/rw_core/core/device.(*LogicalAgent).updateFlowTable\n\t/go/src/rw_core/core/device/logical_agent_flow.go:64\ngithub.com/opencord/voltha-go/rw_core/core/device.(*LogicalManager).UpdateLogicalDeviceFlowTable\n\t/go/src/rw_core/core/device/logical_manager.go:520\ngithub.com/opencord/voltha-protos/v5/go/voltha._VolthaService_UpdateLogicalDeviceFlowTable_Handler.func1\n\t/go/src/vendor/github.com/opencord/voltha-protos/v5/go/voltha/voltha.pb.go:1849\ngithub.com/opencord/voltha-lib-go/v7/pkg/grpc.mkServerInterceptor.func1\n\t/go/src/vendor/github.com/opencord/voltha-lib-go/v7/pkg/grpc/server.go:158\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1\n\t/go/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:25\ngithub.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing.UnaryServerInterceptor.func1\n\t/go/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing/server_interceptors.go:38\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1\n\t/go/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:25\ngithub.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1\n\t/go/src/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34\ngithub.com/opencord/voltha-protos/v5/go/voltha._VolthaService_UpdateLogicalDeviceFlowTable_Handler\n\t/go/src/vendor/github.com/opencord/voltha-protos/v5/go/voltha/voltha.pb.go:1851\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/src/vendor/google.golang.org/grpc/server.go:1007\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/src/vendor/google.golang.org/grpc/server.go:1287\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.1\n\t/go/src/vendor/google.golang.org/grpc/server.go:722"}
OfAgent sees the flowDeleteStrict for that flow only once:
default/voltha-voltha-ofagent-77b48cb877-twg7l[ofagent]: {"level":"debug","ts":"2021-12-09T23:14:46.929Z","caller":"openflow/flowMod.go:345","msg":"handleFlowDeleteStrict called","instanceId":"voltha-voltha-ofagent-77b48cb877-twg7l","op-name":"openflow-flow-delete-strict","op-id":"6c3b15d6b8fb58e7","device-id":"3392b083-b675-4246-a693-21cfa4b9fa97","flow":{"Version":4,"Type":14,"Length":72,"Xid":178,"Cookie":48695175134011564,"CookieMask":0,"TableId":0,"Command":4,"IdleTimeout":0,"HardTimeout":0,"Priority":1000,"BufferId":4294967295,"OutPort":4294967295,"OutGroup":4294967295,"Flags":{"SendFlowRem":true},"Match":{"Type":1,"Length":18,"OxmList":[{"Type":"in_port","Value":256},{"Type":"vlan_vid","Value":4096}]},"Instructions":null}} default/voltha-voltha-ofagent-77b48cb877-twg7l[ofagent]: {"level":"debug","ts":"2021-12-09T23:14:46.929Z","caller":"openflow/flowMod.go:466","msg":"FlowDeleteStrict being sent to Voltha%!(EXTRA log.Fields=map[device-id:3392b083-b675-4246-a693-21cfa4b9fa97 flow-update:{3392b083-b675-4246-a693-21cfa4b9fa97 cookie:48695175134011564 command:OFPFC_DELETE_STRICT priority:1000 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:256 > > oxm_fields:<oxm_class:OFPXMC_OPENFLOW_BASIC ofb_field:<type:OFPXMT_OFB_VLAN_VID vlan_vid:4096 > > > 178 {} [] 0}])","instanceId":"voltha-voltha-ofagent-77b48cb877-twg7l","op-id":"6c3b15d6b8fb58e7","op-name":"openflow-flow-delete-strict"}
*Since the deletion is not acknowledged, ONOS should retry deleting it!*