I am using Queens release and VM's tap interfaces are plugged into ovs br-int.
I'm watching a case when openflow entries are not totally removed when I stop my VM (name='my-vm').
It is only reproducable when there is some another activity on a node for different VMs: in my case I attach new network to another VM (name='vm-other')
ovs-agent logs in attach.
I managed to simulate the issue using next steps:
1) grep by mac current openflow entries for my-vm:
Note: "-netdev tap,fd=28", so, net device is passed to qemu as handle and AFAIU tap interface is auto removed (by kernel) when qemu process exits.
3) SIGSTOP libvirtd to emulate port deletion delay that is performed by libvirtd when guest is stopped
(I believe libvirtd removes port when quest is stopped in the way like 'ovs-vsctl --timeout=5 -- --if-exists del-port taped0487c9-23')
# kill -SIGSTOP 24553
#
4) Kill the quest:
# kill -9 3934
#
Ovs agent logs right after killing:
2018-12-14 17:18:26.600 7 DEBUG neutron.agent.linux.async_process [-] Output received from [ovsdb-client monitor tcp:127.0.0.1:6640 Interface name,ofport,external_ids --format=json]: {"data":[["568b058e-382a-4c50-a185-45807107190b","old",null,163,null],["","new","taped0487c9-23",-1,["map",[["attached-mac","fa:16:3e:ec:d3:45"],["iface-id","ed0487c9-23b2-4bea-9a17-567b7f52d7fc"],["iface-status","active"],["vm-id","89fccc31-96a6-47ce-abd1-e40fba7274e6"]]]]],"headings":["row","action","name","ofport","external_ids"]} _read_stdout /usr/lib/python2.7/site-packages/neutron/agent/linux/async_process.py:239
Really:
# ovs-vsctl --columns name,ofport,error find Interface name='taped0487c9-23'
name : "taped0487c9-23"
ofport : -1
error : "could not open network device taped0487c9-23 (No such device)"
# ip a s taped0487c9-23
Device "taped0487c9-23" does not exist.
#
5) emulate parallel guest device adding (i.e. inforce rpc_loop to process ports):
# ip tuntap add dev my-tap mode tap
# ovs-vsctl add-port br-int my-tap
#
Right after adding rpc_loop starts to process ports and there is warning in logs:
2018-12-14 17:21:12.520 7 WARNING neutron.agent.common.ovs_lib [req-338406ef-81c5-4268-9463-f2e9435892ee - - - - -] ofport: -1 for VIF: ed0487c9-23b2-4bea-9a17-567b7f52d7fc is not a positive integer
Final flow: recirc_id=0x9b0,eth,tcp,reg5=0xa3,reg6=0x9,in_port=12,vlan_tci=0x0000,dl_src=fa:16:3e:05:95:a1,dl_dst=fa:16:3e:ec:d3:45,nw_src=10.94.152.196,nw_dst=10.94.152.212,nw_tos=0,nw_ecn=0,nw_ttl=0,tp_src=0,tp_dst=0,tcp_flags=0
Megaflow: recirc_id=0x9b0,ct_state=+new-est-rel-rpl+trk,eth,tcp,in_port=12,dl_dst=fa:16:3e:ec:d3:45,nw_frag=no
Datapath actions: ct(commit,zone=9)
#
If then migrate my-vm (in stopped state) to another node, then other-vm from current node lost connectivity to my-vm due to egress traffic from vm-other is going to 'Nonexistent output port'.
I am using Queens release and VM's tap interfaces are plugged into ovs br-int.
I'm watching a case when openflow entries are not totally removed when I stop my VM (name='my-vm').
It is only reproducable when there is some another activity on a node for different VMs: in my case I attach new network to another VM (name='vm-other')
ovs-agent logs in attach.
I managed to simulate the issue using next steps:
1) grep by mac current openflow entries for my-vm:
# ovs-ofctl dump-flows br-int | grep fa:16:3e:ec:d3:45 0xf4d7d970f5382 f3d, duration=93.162s, table=60, n_packets=146, n_bytes=21001, idle_age=4, priority= 90,dl_vlan= 9,dl_dst= fa:16:3e: ec:d3:45 actions= load:0xa3- >NXM_NX_ REG5[], load:0x9- >NXM_NX_ REG6[], strip_vlan, resubmit( ,81) 0xf4d7d970f5382 f3d, duration=93.162s, table=71, n_packets=2, n_bytes=84, idle_age=4, priority= 95,arp, reg5=0xa3, in_port= 163,dl_ src=fa: 16:3e:ec: d3:45,arp_ spa=10. 94.152. 212 actions=NORMAL 0xf4d7d970f5382 f3d, duration=93.162s, table=71, n_packets=28, n_bytes=2448, idle_age=9, priority= 65,ip,reg5= 0xa3,in_ port=163, dl_src= fa:16:3e: ec:d3:45, nw_src= 10.94.152. 212 actions= ct(table= 72,zone= NXM_NX_ REG6[0. .15]) 0xf4d7d970f5382 f3d, duration=93.162s, table=71, n_packets=0, n_bytes=0, idle_age=93, priority= 65,ipv6, reg5=0xa3, in_port= 163,dl_ src=fa: 16:3e:ec: d3:45,ipv6_ src=fe80: :f816:3eff: feec:d345 actions= ct(table= 72,zone= NXM_NX_ REG6[0. .15]) 0xf4d7d970f5382 f3d, duration=93.162s, table=73, n_packets=0, n_bytes=0, idle_age=3401, priority= 100,reg6= 0x9,dl_ dst=fa: 16:3e:ec: d3:45 actions= load:0xa3- >NXM_NX_ REG5[], resubmit( ,81)
cookie=
cookie=
cookie=
cookie=
cookie=
#
2) # ps ax | grep libvirt qemu-kvm -name guest=instance- 00000012, debug-threads= on -S -object secret, id=masterKey0, format= raw,file= /var/lib/ libvirt/ qemu/domain- 131-instance- 00000012/ master- key.aes -machine pc-i440fx- vz7.8.0, accel=kvm, usb=off, dump-guest- core=off -cpu Westmere- IBRS,vme= on,ss=on, pcid=on, x2apic= on,tsc- deadline= on,hypervisor= on,arat= on,tsc_ adjust= on,ssbd= on,stibp= on,pdpe1gb= on,rdtscp= on,aes= off,+kvmclock -m 512 -realtime mlock=off -smp 1,sockets= 1,cores= 1,threads= 1 -numa node,nodeid= 0,cpus= 0,mem=512 -uuid 89fccc31- 96a6-47ce- abd1-e40fba7274 e6 -smbios type=1, manufacturer= Virtuozzo Infrastructure Platform, product= OpenStack Compute, version= 17.0.6- 1.vl7,serial= 71f55add- ef93-4ec2- a4dd-ab8098b631 2d,uuid= 89fccc31- 96a6-47ce- abd1-e40fba7274 e6,family= Virtual Machine -no-user-config -nodefaults -chardev socket, id=charmonitor, path=/var/ lib/libvirt/ qemu/domain- 131-instance- 00000012/ monitor. sock,server, nowait -mon chardev= charmonitor, id=monitor, mode=control -rtc base=utc -global kvm-pit. lost_tick_ policy= discard -no-shutdown -boot strict=on -device nec-usb- x,id=usb, bus=pci. 0,addr= 0x4 -device virtio- scsi-pci, id=scsi0, bus=pci. 0,addr= 0x5 -device virtio- serial- pci,id= virtio- serial0, bus=pci. 0,addr= 0x6 -drive file=/mnt/ vstorage/ vols/datastores /cinder/ volume- e30d1874- d68e-4578- bf89-aa599e8383 c7/volume- e30d1874- d68e-4578- bf89-aa599e8383 c7,format= qcow2,if= none,id= drive-scsi0- 0-0-0,cache= none,l2- cache-size= 128M,discard= unmap,aio= native -device scsi-hd, bus=scsi0. 0,channel= 0,scsi- id=0,lun= 0,drive= drive-scsi0- 0-0-0,id= scsi0-0- 0-0,bootindex= 1,logical_ block_size= 512,physical_ block_size= 4096,serial= e30d1874- d68e-4578- bf89-aa599e8383 c7 -netdev tap,fd= 28,id=hostnet0, vhost=on, vhostfd= 30 -device virtio- net-pci, host_mtu= 1500,netdev= hostnet0, id=net0, mac=fa: 16:3e:ec: d3:45,bus= pci.0,addr= 0x3 -chardev pty,id= charserial0, logfile= /mnt/vstorage/ vols/datastores /nova/instances /89fccc31- 96a6-47ce- abd1-e40fba7274 e6/console. log,logappend= on -device isa-serial, chardev= charserial0, id=serial0 -chardev socket, id=charchannel0 ,path=/ var/lib/ libvirt/ qemu/org. qemu.guest_ agent.0. instance- 00000012. sock,server, nowait -device virtserialport, bus=virtio- serial0. 0,nr=1, chardev= charchannel0, id=channel0, name=org. qemu.guest_ agent.0 -chardev socket, id=charchannel1 ,path=/ var/lib/ libvirt/ qemu/org. qemu.guest_ agent.1. instance- 00000012. sock,server, nowait -device virtserialport, bus=virtio- serial0. 0,nr=2, chardev= charchannel1, id=channel1, name=org. qemu.guest_ agent.1 -device usb-tablet, id=input0, bus=usb. 0,port= 1 -vnc 10.10.1.237:0 -device VGA,id= video0, vgamem_ mb=16,bus= pci.0,addr= 0x2 -device virtio- balloon- pci,id= balloon0, bus=pci. 0,addr= 0x7 -device vmcoreinfo -device pvpanic,ioport=1285 -msg timestamp=on
4887 pts/6 S+ 0:00 grep --color=auto libvirt
3934 ? Sl 0:18 /usr/libexec/
24553 ? Ssl 11:44 /usr/sbin/libvirtd --listen
Note: "-netdev tap,fd=28", so, net device is passed to qemu as handle and AFAIU tap interface is auto removed (by kernel) when qemu process exits.
3) SIGSTOP libvirtd to emulate port deletion delay that is performed by libvirtd when guest is stopped
(I believe libvirtd removes port when quest is stopped in the way like 'ovs-vsctl --timeout=5 -- --if-exists del-port taped0487c9-23')
# kill -SIGSTOP 24553
#
4) Kill the quest:
# kill -9 3934
#
Ovs agent logs right after killing:
2018-12-14 17:18:26.600 7 DEBUG neutron. agent.linux. async_process [-] Output received from [ovsdb-client monitor tcp:127.0.0.1:6640 Interface name,ofport, external_ ids --format=json]: {"data" :[["568b058e- 382a-4c50- a185-4580710719 0b","old" ,null,163, null],[ "","new" ,"taped0487c9- 23",-1, ["map", [["attached- mac","fa: 16:3e:ec: d3:45"] ,["iface- id","ed0487c9- 23b2-4bea- 9a17-567b7f52d7 fc"],[" iface-status" ,"active" ],["vm- id","89fccc31- 96a6-47ce- abd1-e40fba7274 e6"]]]] ],"headings" :["row" ,"action" ,"name" ,"ofport" ,"external_ ids"]} _read_stdout /usr/lib/ python2. 7/site- packages/ neutron/ agent/linux/ async_process. py:239
Really: c9-23'
# ovs-vsctl --columns name,ofport,error find Interface name='taped0487
name : "taped0487c9-23"
ofport : -1
error : "could not open network device taped0487c9-23 (No such device)"
# ip a s taped0487c9-23
Device "taped0487c9-23" does not exist.
#
5) emulate parallel guest device adding (i.e. inforce rpc_loop to process ports):
# ip tuntap add dev my-tap mode tap
# ovs-vsctl add-port br-int my-tap
#
Right after adding rpc_loop starts to process ports and there is warning in logs: agent.common. ovs_lib [req-338406ef- 81c5-4268- 9463-f2e9435892 ee - - - - -] ofport: -1 for VIF: ed0487c9- 23b2-4bea- 9a17-567b7f52d7 fc is not a positive integer
2018-12-14 17:21:12.520 7 WARNING neutron.
Part of openflow entries are deleted but not all:
# ovs-ofctl dump-flows br-int | grep fa:16:3e:ec:d3:45 0xf4d7d970f5382 f3d, duration=905.467s, table=60, n_packets=176, n_bytes=23641, idle_age=367, priority= 90,dl_vlan= 9,dl_dst= fa:16:3e: ec:d3:45 actions= load:0xa3- >NXM_NX_ REG5[], load:0x9- >NXM_NX_ REG6[], strip_vlan, resubmit( ,81) 0xf4d7d970f5382 f3d, duration=905.467s, table=73, n_packets=0, n_bytes=0, idle_age=4213, priority= 100,reg6= 0x9,dl_ dst=fa: 16:3e:ec: d3:45 actions= load:0xa3- >NXM_NX_ REG5[], resubmit( ,81)
cookie=
cookie=
#
Continue libvirtd:
# kill -SIGCONT 24553
#
2018-12-14 17:24:58.557 7 DEBUG neutron. agent.linux. async_process [-] Output received from [ovsdb-client monitor tcp:127.0.0.1:6640 Interface name,ofport, external_ ids --format=json]: {"data" :[["568b058e- 382a 45807107190b" ,"delete" ,"taped0487c9- 23",-1, ["map", [["attached- mac","fa: 16:3e:ec: d3:45"] ,["iface- id","ed0487c9- 23b2-4bea- 9a17-567b7f52d7 fc"],[" iface-status" ,"active" ],["vm- id","89fccc31- 96a6-47ce- a 6"]]]]] ,"headings" :["row" ,"action" ,"name" ,"ofport" ,"external_ ids"]} _read_stdout /usr/lib/ python2. 7/site- packages/ neutron/ agent/linux/ async_process. py:239
-4c50-a185-
bd1-e40fba7274e
But flows are still here: 0xf4d7d970f5382 f3d, duration=1030.412s, table=60, n_packets=176, n_bytes=23641, idle_age=492, priority= 90,dl_vlan= 9,dl_dst= fa:16:3e: ec:d3:45 actions= load:0xa3- >NXM_NX_ REG5[], load:0x9- >NXM_NX_ REG6[], strip_vlan, resubmit( ,81) 0xf4d7d970f5382 f3d, duration=1030.412s, table=73, n_packets=0, n_bytes=0, idle_age=4338, priority= 100,reg6= 0x9,dl_ dst=fa: 16:3e:ec: d3:45 actions= load:0xa3- >NXM_NX_ REG5[], resubmit( ,81)
# ovs-ofctl dump-flows br-int | grep fa:16:3e:ec:d3:45
cookie=
cookie=
#
Trace result for stopped VM:
# ovs-appctl ofproto/trace br-int in_port= 12,tcp, dl_src= fa:16:3e: 05:95:a1, dl_dst= fa:16:3e: ec:d3:45, nw_src= 10.94.152. 196,nw_ dst=10. 94.152. 212 +new-est, ip,reg5= 0xc, priority 74, cookie 0xf4d7d970f5382f3d dl_dst= fa:16:3e: ec:d3:45, priority 100, cookie 0xf4d7d970f5382f3d field:0xa3- >reg5 +trk,reg5= 0xa3, priority 80, cookie 0xf4d7d970f5382f3d +new-est, ip,reg5= 0xa3, priority 74, cookie 0xf4d7d970f5382f3d commit, zone=NXM_ NX_REG6[ 0..15])
<cut>
bridge("br-int")
----------------
thaw
Resuming from table 72
72. ct_state=
resubmit(,73)
73. reg6=0x9,
set_
resubmit(,81)
81. ct_state=
resubmit(,82)
82. ct_state=
ct(
drop
output:163
>> Nonexistent output port
resubmit(,92)
92. priority 0, cookie 0xf4d7d970f5382f3d
drop
Final flow: recirc_ id=0x9b0, eth,tcp, reg5=0xa3, reg6=0x9, in_port= 12,vlan_ tci=0x0000, dl_src= fa:16:3e: 05:95:a1, dl_dst= fa:16:3e: ec:d3:45, nw_src= 10.94.152. 196,nw_ dst=10. 94.152. 212,nw_ tos=0,nw_ ecn=0,nw_ ttl=0,tp_ src=0,tp_ dst=0,tcp_ flags=0 id=0x9b0, ct_state= +new-est- rel-rpl+ trk,eth, tcp,in_ port=12, dl_dst= fa:16:3e: ec:d3:45, nw_frag= no
Megaflow: recirc_
Datapath actions: ct(commit,zone=9)
#
If then migrate my-vm (in stopped state) to another node, then other-vm from current node lost connectivity to my-vm due to egress traffic from vm-other is going to 'Nonexistent output port'.
The issue looks like also actual for master.