Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Remove forced delay for linux interface notifications #1742

Merged
merged 4 commits into from
Oct 13, 2020
Merged

Remove forced delay for linux interface notifications #1742

merged 4 commits into from
Oct 13, 2020

Conversation

ondrej-fabry
Copy link
Member

@ondrej-fabry ondrej-fabry commented Oct 13, 2020 •
edited
Loading

This PR is a fix for #1739

Agent log showing all received notifications for same config as in #1734:

+======================================================================================================================+
| #0 - NBTransaction                                                                                        FullResync |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 0
      - type: NB Transaction, Full Resync
      - values:

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations:
      <NONE>
x----------------------------------------------------------------------------------------------------------------------x
| #0 - NBTransaction                                                                                       took 39.8ms |
x----------------------------------------------------------------------------------------------------------------------x

INFO[0000] dispatcher: Transaction #0 successful! (took 40.1ms) 
DEBU[0000] resync: finished resync for orchestrator took 62ms 
INFO[0000] resync: Resync done (took: 82ms)             
INFO[0000] status-check: Agent plugin state update.      lastErr="<nil>" plugin=VPPAgent state=ok
INFO[0000] agent: Agent started with 39 plugins (took 240ms) 
DEBU[0003] dispatcher: Push data with 3 KV pairs (source: grpc) 
DEBU[0003] dispatcher:  - UPDATE: "config/vpp/v2/interfaces/afpacket1"  
DEBU[0003] dispatcher:  - UPDATE: "config/linux/interfaces/v2/interface/veth1"  
DEBU[0003] dispatcher:  - UPDATE: "config/linux/interfaces/v2/interface/veth2"  
+======================================================================================================================+
| #1 - NBTransaction                                                                                                   |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 1
      - type: NB Transaction
      - values:
          - key: config/linux/interfaces/v2/interface/veth1
            val: { name:"veth1"  type:VETH  host_if_name:"veth-1"  enabled:true  ip_addresses:"10.0.2.1/30"  veth:{peer_if_name:"veth2"} }
          - key: config/linux/interfaces/v2/interface/veth2
            val: { name:"veth2"  type:VETH  host_if_name:"veth-2"  enabled:true  ip_addresses:"10.0.3.1/30"  veth:{peer_if_name:"veth1"} }
          - key: config/vpp/v2/interfaces/afpacket1
            val: { name:"afpacket1"  type:AF_PACKET  enabled:true  ip_addresses:"192.168.99.1/30"  afpacket:{host_if_name:"veth-1"} }

WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-2101756059 
 (attrs: &{Index:10 MTU:1500 TxQLen:1000 Name:veth-2101756059 HardwareAddr:0e:5a:0e:53:f5:70 Flags:broadcast|multicast RawFlags:4098 ParentIndex:0 MasterIndex:0 Namespace:<nil> Alias: Statistics:0xc000806108 Promisc:0 Xdp:0xc00036fda0 EncapType:ether Protinfo:<nil> OperState:down NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:10 Flags:4098 Change:4294967295}} Header:{Len:1352 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238400}) 
WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-2118533678 
 (attrs: &{Index:11 MTU:1500 TxQLen:1000 Name:veth-2118533678 HardwareAddr:06:9d:85:f8:8c:9d Flags:broadcast|multicast RawFlags:4098 ParentIndex:10 MasterIndex:0 Namespace:<nil> Alias: Statistics:0xc000bf0108 Promisc:0 Xdp:0xc00036fde0 EncapType:ether Protinfo:<nil> OperState:down NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:11 Flags:4098 Change:4294967295}} Header:{Len:1352 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238700}) 
WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-2 
 (attrs: &{Index:11 MTU:1500 TxQLen:1000 Name:veth-2 HardwareAddr:06:9d:85:f8:8c:9d Flags:broadcast|multicast RawFlags:4098 ParentIndex:10 MasterIndex:0 Namespace:<nil> Alias:/vnf-agent/agent0/veth2/veth1 Statistics:0xc000c98124 Promisc:0 Xdp:0xc00036ff80 EncapType:ether Protinfo:<nil> OperState:down NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:11 Flags:4098 Change:0}} Header:{Len:1380 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238900}) 
WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-2 
 (attrs: &{Index:11 MTU:1500 TxQLen:1000 Name:veth-2 HardwareAddr:06:9d:85:f8:8c:9d Flags:up|broadcast|multicast RawFlags:4099 ParentIndex:10 MasterIndex:0 Namespace:<nil> Alias:/vnf-agent/agent0/veth2/veth1 Statistics:0xc000d34124 Promisc:0 Xdp:0xc00036ffe0 EncapType:ether Protinfo:<nil> OperState:lower-layer-down NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:11 Flags:4099 Change:1}} Header:{Len:1380 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238b00}) 
WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-1 
 (attrs: &{Index:10 MTU:1500 TxQLen:1000 Name:veth-1 HardwareAddr:0e:5a:0e:53:f5:70 Flags:broadcast|multicast RawFlags:4098 ParentIndex:11 MasterIndex:0 Namespace:<nil> Alias:/vnf-agent/agent0/veth1/veth2 Statistics:0xc0007d4124 Promisc:0 Xdp:0xc000a90040 EncapType:ether Protinfo:<nil> OperState:down NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:10 Flags:4098 Change:0}} Header:{Len:1380 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238100}) 
WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-1 
 (attrs: &{Index:10 MTU:1500 TxQLen:1000 Name:veth-1 HardwareAddr:0e:5a:0e:53:f5:70 Flags:up|broadcast|multicast RawFlags:69635 ParentIndex:11 MasterIndex:0 Namespace:<nil> Alias:/vnf-agent/agent0/veth1/veth2 Statistics:0xc0007e4124 Promisc:0 Xdp:0xc000a900a0 EncapType:ether Protinfo:<nil> OperState:lower-layer-down NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:10 Flags:69635 Change:1}} Header:{Len:1380 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238300}) 
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-13 09:35:43.271 +0000 UTC -> 2020-10-13 09:35:43.309 +0000 UTC, dur: 38ms):
      1. CREATE:
          - key: config/linux/interfaces/v2/interface/veth2
          - value: { name:"veth2"  type:VETH  host_if_name:"veth-2"  enabled:true  ip_addresses:"10.0.3.1/30"  veth:{peer_if_name:"veth1"} } 
      2. CREATE:
          - key: config/linux/interfaces/v2/interface/veth1
          - value: { name:"veth1"  type:VETH  host_if_name:"veth-1"  enabled:true  ip_addresses:"10.0.2.1/30"  veth:{peer_if_name:"veth2"} } 
      3. CREATE [PROPERTY]:
          - key: linux/interface/state/veth1/UP
          - value: <EMPTY> 
      4. CREATE [DERIVED]:
          - key: linux/interface/veth1/address/static/10.0.2.1/30
          - value: <EMPTY> 
      5. CREATE [PROPERTY]:
          - key: linux/interface/state/veth2/UP
          - value: <EMPTY> 
      6. CREATE [DERIVED]:
          - key: linux/interface/veth2/address/static/10.0.3.1/30
          - value: <EMPTY> 
      7. CREATE [NOOP IS-PENDING]:
          - key: config/vpp/v2/interfaces/afpacket1
          - value: { name:"afpacket1"  type:AF_PACKET  enabled:true  ip_addresses:"192.168.99.1/30"  afpacket:{host_if_name:"veth-1"} } 
x----------------------------------------------------------------------------------------------------------------------x
| #1 - NBTransaction                                                                                       took 38.1ms |
x----------------------------------------------------------------------------------------------------------------------x

+======================================================================================================================+
| #2 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 2
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/veth-2
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-13 09:35:43.31 +0000 UTC -> 2020-10-13 09:35:43.31 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/veth-2
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #2 - SBNotification                                                                                          took 0s |
x----------------------------------------------------------------------------------------------------------------------x

DEBU[0003] kvscheduler: Transaction 2 successful        
+======================================================================================================================+
| #3 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 3
      - type: SB Notification
      - values:
          - key: linux/interface/host-name/veth-1
            val: <EMPTY>

WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-1 
 (attrs: &{Index:10 MTU:1500 TxQLen:1000 Name:veth-1 HardwareAddr:0e:5a:0e:53:f5:70 Flags:up|broadcast|multicast RawFlags:69699 ParentIndex:11 MasterIndex:0 Namespace:<nil> Alias:/vnf-agent/agent0/veth1/veth2 Statistics:0xc000966124 Promisc:0 Xdp:0xc000a90280 EncapType:ether Protinfo:<nil> OperState:up NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:10 Flags:69699 Change:0}} Header:{Len:1380 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238500}) 
WARN[0003] linux-ifplugin.if-watcher:  ---> LINK NOTIFICATION: veth-2 
 (attrs: &{Index:11 MTU:1500 TxQLen:1000 Name:veth-2 HardwareAddr:06:9d:85:f8:8c:9d Flags:up|broadcast|multicast RawFlags:69699 ParentIndex:10 MasterIndex:0 Namespace:<nil> Alias:/vnf-agent/agent0/veth2/veth1 Statistics:0xc000be0124 Promisc:0 Xdp:0xc000a902e0 EncapType:ether Protinfo:<nil> OperState:up NetNsID:0 NumTxQueues:0 NumRxQueues:0 Vfs:[]})
 ({IfInfomsg:{IfInfomsg:{Family:0 _:0 Type:1 Index:11 Flags:69699 Change:0}} Header:{Len:1380 Type:16 Flags:0 Seq:0 Pid:0} Link:0xc000238800}) 
DEBU[0003] vpp-ifplugin.if-descriptor: publish add to ifplugin_ifstate{{afpacket1 false false vpp-interface-index} 0xc0002d7090} 
DEBU[0003] vpp-ifplugin: Interface 1 set to VRF 0       
o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-13 09:35:43.31 +0000 UTC -> 2020-10-13 09:35:43.389 +0000 UTC, dur: 79ms):
      1. CREATE [OBTAINED]:
          - key: linux/interface/host-name/veth-1
          - value: <EMPTY> 
      2. CREATE [WAS-PENDING]:
          - key: config/vpp/v2/interfaces/afpacket1
          - value: { name:"afpacket1"  type:AF_PACKET  enabled:true  ip_addresses:"192.168.99.1/30"  afpacket:{host_if_name:"veth-1"} } 
      3. CREATE [DERIVED]:
          - key: vpp/interface/afpacket1/vrf/0/ip-version/v4
          - value: <EMPTY> 
      4. CREATE [DERIVED]:
          - key: vpp/interface/afpacket1/address/static/192.168.99.1/30
          - value: <EMPTY> 
      5. CREATE [DERIVED]:
          - key: vpp/interface/afpacket1/has-IP-address
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #3 - SBNotification                                                                                      took 79.2ms |
x----------------------------------------------------------------------------------------------------------------------x

DEBU[0003] kvscheduler: Transaction 3 successful        
INFO[0003] dispatcher: Transaction #1 successful! (took 118ms) 
DEBU[0003] configurator.configurator: no pendings keys to wait for 
INFO[0003] configurator.configurator: finished waiting for done (took 75.014µs) 
DEBU[0003] configurator.configurator: config update finished with 4 results 
+======================================================================================================================+
| #4 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 4
      - type: SB Notification
      - values:
          - key: vpp/interface/afpacket1/link-state/DOWN
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-13 09:35:43.393 +0000 UTC -> 2020-10-13 09:35:43.393 +0000 UTC, dur: 0s):
      1. CREATE [OBTAINED]:
          - key: vpp/interface/afpacket1/link-state/DOWN
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #4 - SBNotification                                                                                       took 200µs |
x----------------------------------------------------------------------------------------------------------------------x

DEBU[0003] kvscheduler: Transaction 4 successful        
INFO[0005] status-check: Agent plugin state update.      lastErr="<nil>" plugin=etcd state=ok
DEBU[0009] vpp-ifplugin.if-state: updating interface states for 2 interfaces 
INFO[0009] status-check: Agent plugin state update.      lastErr="<nil>" plugin=vpp-ifplugin state=ok
DEBU[0009] status-check: Global interface state data added: internal_name:"local0" status:"DOWN" mac_address:"00:00:00:00:00:00"  
DEBU[0009] status-check: Global interface state data added: internal_name:"host-veth-1" index:1 status:"UP" mac_address:"02:fe:30:29:80:98"  
+======================================================================================================================+
| #5 - SBNotification                                                                                                  |
+======================================================================================================================+
  * transaction arguments:
      - seqNum: 5
      - type: SB Notification
      - values:
          - key: vpp/interface/afpacket1/link-state/DOWN
            val: <NIL>
          - key: vpp/interface/afpacket1/link-state/UP
            val: <EMPTY>

o----------------------------------------------------------------------------------------------------------------------o
  * executed operations (2020-10-13 09:35:49.147 +0000 UTC -> 2020-10-13 09:35:49.147 +0000 UTC, dur: 0s):
      1. DELETE [WAS-OBTAINED]:
          - key: vpp/interface/afpacket1/link-state/DOWN
          - value: <EMPTY> 
      2. CREATE [OBTAINED]:
          - key: vpp/interface/afpacket1/link-state/UP
          - value: <EMPTY> 
x----------------------------------------------------------------------------------------------------------------------x
| #5 - SBNotification                                                                                       took 200µs |
x----------------------------------------------------------------------------------------------------------------------x

DEBU[0009] kvscheduler: Transaction 5 successful

@ondrej-fabry
refactor: Improve logs when WaitDone enabled
c647233 
Signed-off-by: Ondrej Fabry <ofabry@cisco.com>
@ondrej-fabry
refactor: Log failure of getting namespace from name as warning
cfb7757 
Signed-off-by: Ondrej Fabry <ofabry@cisco.com>
@ondrej-fabry
refactor: Remove forced delay for linux interface notifications
01d565e 
Fixes: ligato#1739
Signed-off-by: Ondrej Fabry <ofabry@cisco.com>
@ondrej-fabry ondrej-fabry self-assigned this Oct 13, 2020
@codecov
Copy link

codecov bot commented Oct 13, 2020 •
edited
Loading

Codecov Report

Merging #1742 into master will decrease coverage by 1.48%.
The diff coverage is n/a.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #1742      +/-   ##
==========================================
- Coverage   57.13%   55.64%   -1.49%     
==========================================
  Files         618      379     -239     
  Lines       44673    27912   -16761     
==========================================
- Hits        25522    15532    -9990     
+ Misses      16192    10892    -5300     
+ Partials     2959     1488    -1471
Flag Coverage Δ
#e2e ?
#unittests 55.64% <ø> (ø)

Flags with carried forward coverage won't be shown. Click here to find out more.

milanlenco
milanlenco reviewed Oct 13, 2020
View reviewed changes
plugins/linux/ifplugin/descriptor/watcher.go
// delayNotification delays notification about enabled interface - typically
// interface is created in multiple stages and we do not want to notify scheduler
// about intermediate states.
func (w *InterfaceWatcher) delayNotification(ifName string) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't remember the exact scenario(s), but the reason for this was that newly created interface would send multiple UP/DOWN notifications, as if it was being created in multiple steps (causing dependent stuff to be created/deleted multiple times). Actually I think it is TAP that in VPP is being created through multiple syscalls. Anyway, let's get rid of the timeout and see if any issues appear (if yes, we can do this for example for VPP TAP, but not for VETH).
Btw. I don't think pendingIntfs map and running applyDelayedNotification as go routine is needed anymore. Also "applyDelayedNotification" is probably not a good name anymore.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't remember the exact scenario(s), but the reason for this was that newly created interface would send multiple UP/DOWN notifications, as if it was being created in multiple steps (causing dependent stuff to be created/deleted multiple times).

For simple case of VETHs+AFPACKET I see several notifications, most likely because of various things configured on the interfaces (alias, namespace, peer, ...) and these dont see to cause issues for me. Running more e2e tests to confirm this though.

Actually I think it is TAP that in VPP is being created through multiple syscalls.

Will run e2e tests for TAPs as well.

Anyway, let's get rid of the timeout and see if any issues appear (if yes, we can do this for example for VPP TAP, but not for VETH).

I think we will need to find a way to avoid sleeps/delays totally and somehow figure out which inter-states to ignore, because these sleeps make configuration of interfaces veeeery slow (see #1739)

Btw. I don't think pendingIntfs map and running applyDelayedNotification as go routine is needed anymore. Also "applyDelayedNotification" is probably not a good name anymore.

Will fix that before merge, just wanted travis to run tests on this.

@ondrej-fabry ondrej-fabry added the 🚧 WIP do not merge! work in progress! label Oct 13, 2020
@ondrej-fabry
refactor: Cleanup code in linux interface watcher
d3f72c7 
Signed-off-by: Ondrej Fabry <ofabry@cisco.com>
@ondrej-fabry ondrej-fabry removed the 🚧 WIP do not merge! work in progress! label Oct 13, 2020
@ondrej-fabry
Copy link
Member Author

Tests seem to be passing for both TAPs and VETHs.

@ondrej-fabry ondrej-fabry merged commit 6766786 into ligato:master Oct 13, 2020
@ondrej-fabry ondrej-fabry deleted the linux-watcher branch October 13, 2020 12:45
@ondrej-fabry ondrej-fabry linked an issue Oct 13, 2020 that may be closed by this pull request
Config update with wait done takes ~500ms #1739
Closed
@ondrej-fabry ondrej-fabry mentioned this pull request Oct 13, 2020
Closed
@ondrej-fabry ondrej-fabry added this to the v3.2.0 milestone Oct 13, 2020
NotSoFancyName pushed a commit to NotSoFancyName/vpp-agent that referenced this pull request Oct 13, 2020
@ondrej-fabry @NotSoFancyName
Remove forced delay for linux interface notifications (ligato#1742)
e4a77f2
@ondrej-fabry ondrej-fabry mentioned this pull request Oct 20, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@milanlenco milanlenco milanlenco approved these changes

Assignees

@ondrej-fabry ondrej-fabry

Labels
♻️ refactoring
Projects
None yet
Milestone
v3.2.0
Development

Successfully merging this pull request may close these issues.

Config update with wait done takes ~500ms
2 participants
@ondrej-fabry @milanlenco