Open Stack

Hi,

On czwartek, 25 listopada 2021 10:41:14 CET Rodolfo Alonso Hernandez wrote:
> Hello Michal:
> 
> I think this thread is related to OVN. In any case, I've analyzed your logs
> from the Neutron point of view. Those are basically the key points in your
> logs: [1]. The Neutron server receives the request to create and bind a new
> port. Both the DHCP agent and the OVS agent provision the port
> (8a472e87-4a7a-4ad4-9fbb-fd9785136611).
> 
> Neutron server sends the "network-vif-plugged" event at 08:51:05.635 and
> receives the ACK from Nova at 08:51:05.704. Nova server creates the
> corresponding event for the instance on the compute0:
> 2021-11-25 08:51:05.692 23 INFO
> nova.api.openstack.compute.server_external_events
> [req-393fcb9a-5c68-4b0a-af1b-661e73d947cb 01a75e3a9a9148218916d3beafae2120
> 7d16babef0524b7dade9a59b0a3569e1 - default default] Creating event
> network-vif-plugged:8a472e87-4a7a-4ad4-9fbb-fd9785136611 for instance
> 09eff2ce-356f-430f-ab30-5de58f58d698 on compute0
> 
> Nova compute agent receives this server event:
> 2021-11-25 08:51:05.705 8 DEBUG nova.compute.manager
> [req-393fcb9a-5c68-4b0a-af1b-661e73d947cb 01a75e3a9a9148218916d3beafae2120
> 7d16babef0524b7dade9a59b0a3569e1 - default default] [instance:
> 09eff2ce-356f-430f-ab30-5de58f58d698] Processing event
> network-vif-plugged-8a472e87-4a7a-4ad4-9fbb-fd9785136611
> _process_instance_event
> /var/lib/kolla/venv/lib/python3.9/site-packages/nova/compute/manager.py:
10205
> 
> Further triagging and log analysis should be done by Nova folks to
> understand why Nova compute didn't boot this VM. I fail to understand some
> parts.

Thx Rodolfo. I also took a look at those logs (for server 09eff2ce-356f-430f-
ab30-5de58f58d698 which had port 0761ff2f-ff6a-40a5-85b7-c9b40386cbe0 but I 
can confirm what You found actually. Port was pretty quickly provisioned and 
it was reported to Nova. I don't know why Nova didn't unpause that vm.

Port creation in Nova:
2021-11-25 08:50:24.250 8 INFO os_vif [req-6eab0f2a-
d7f4-4251-96f4-177fc0c62212 647a328aef9b4a8b890f102d8f018576 
49231caa42f34da8a9d10229b5c7a5d8 - default default] Successfully plugged vif 
VIFOpenVSwitch(active=False,address=fa:16:3e:3d:cd:b9,bridge_name='br-
int',has_traffic_filtering=True,id=0761ff2f-ff6a-40a5-85b7-
c9b40386cbe0,network=Network(cb4e6be4-9bc7-4c34-95dd-
dfc3c8e9d93c),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=True,vif_name='tap0761ff2f-
ff')

Neutron finished provisioning of that port and sent notification to nova about 
34 seconds later:
2021-11-25 08:51:00.403 30 DEBUG neutron.plugins.ml2.rpc [req-
df864eb8-0c2e-48ca-a3e7-d90dc70e2aa0 - - - - -] Device 0761ff2f-
ff6a-40a5-85b7-c9b40386cbe0 up at agent ovs-agent-compute0 update_device_up /
var/lib/kolla/venv/lib/python3.9/site-packages/neutron/plugins/ml2/rpc.py:278
2021-11-25 08:51:00.503 29 DEBUG neutron.db.provisioning_blocks [req-
a5711e9f-9b15-4a1a-a58d-07952fb8ac34 - - - - -] Provisioning complete for port 
67b32ddf-dddd-439e-92be-6a89df49b4af triggered by entity L2. 
provisioning_complete /var/lib/kolla/venv/lib/python3.9/site-packages/neutron/
db/provisioning_blocks.py:139
2021-11-25 08:51:00.504 29 DEBUG neutron_lib.callbacks.manager [req-
a5711e9f-9b15-4a1a-a58d-07952fb8ac34 - - - - -] Notify callbacks 
['neutron.plugins.ml2.plugin.Ml2Plugin._port_provisioned-8372308'] for port, 
provisioning_complete _notify_loop /var/lib/kolla/venv/lib/python3.9/site-
packages/neutron_lib/callbacks/manager.py:192
2021-11-25 08:51:00.505 30 DEBUG neutron.db.provisioning_blocks [req-
df864eb8-0c2e-48ca-a3e7-d90dc70e2aa0 - - - - -] Provisioning for port 
0761ff2f-ff6a-40a5-85b7-c9b40386cbe0 completed by entity L2. 
provisioning_complete /var/lib/kolla/venv/lib/python3.9/site-packages/neutron/
db/provisioning_blocks.py:133
2021-11-25 08:51:00.515 30 DEBUG neutron.db.provisioning_blocks [req-
df864eb8-0c2e-48ca-a3e7-d90dc70e2aa0 - - - - -] Provisioning complete for port 
0761ff2f-ff6a-40a5-85b7-c9b40386cbe0 triggered by entity L2. 
provisioning_complete /var/lib/kolla/venv/lib/python3.9/site-packages/neutron/
db/provisioning_blocks.py:139
2021-11-25 08:51:00.516 30 DEBUG neutron_lib.callbacks.manager [req-
df864eb8-0c2e-48ca-a3e7-d90dc70e2aa0 - - - - -] Notify callbacks 
['neutron.plugins.ml2.plugin.Ml2Plugin._port_provisioned-8372308'] for port, 
provisioning_complete _notify_loop /var/lib/kolla/venv/lib/python3.9/site-
packages/neutron_lib/callbacks/manager.py:192
2021-11-25 08:51:00.701 30 DEBUG neutron_lib.callbacks.manager [req-
df864eb8-0c2e-48ca-a3e7-d90dc70e2aa0 - - - - -] Notify callbacks 
['neutron.plugins.ml2.plugin.SecurityGroupDbMixin._ensure_default_security_group_handler-7972195'] 
for port, before_update _notify_loop /var/lib/kolla/venv/lib/python3.9/site-
packages/neutron_lib/callbacks/manager.py:192
2021-11-25 08:51:00.746 30 DEBUG neutron.notifiers.nova [-] Sending events: 
[{'server_uuid': '09eff2ce-356f-430f-ab30-5de58f58d698', 'name': 'network-vif-
plugged', 'status': 'completed', 'tag': '0761ff2f-ff6a-40a5-85b7-
c9b40386cbe0'}] send_events /var/lib/kolla/venv/lib/python3.9/site-packages/
neutron/notifiers/nova.py:262
2021-11-25 08:51:00.762 30 DEBUG neutron.plugins.ml2.db [req-
df864eb8-0c2e-48ca-a3e7-d90dc70e2aa0 - - - - -] For port 0761ff2f-
ff6a-40a5-85b7-c9b40386cbe0, host compute0, got binding levels 
[PortBindingLevel(driver='openvswitch',host='compute0',level=0,port_id=0761ff2f-
ff6a-40a5-85b7-c9b40386cbe0,segment=NetworkSegment(ea3a27b6-
c3fa-40e3-9937-71b652cba855),segment_id=ea3a27b6-c3fa-40e3-9937-71b652cba855)] 
get_binding_level_objs /var/lib/kolla/venv/lib/python3.9/site-packages/
neutron/plugins/ml2/db.py:75
2021-11-25 08:51:00.818 30 INFO neutron.notifiers.nova [-] Nova event 
response: {'server_uuid': '09eff2ce-356f-430f-ab30-5de58f58d698', 'name': 
'network-vif-plugged', 'status': 'completed', 'tag': '0761ff2f-ff6a-40a5-85b7-
c9b40386cbe0', 'code': 200}

> 
> Regards.
> 
> [1]https://paste.opendev.org/show/811273/
> 
> On Thu, Nov 25, 2021 at 10:15 AM Michal Arbet <michal.arbet at ultimum.io>
> 
> wrote:
> > Hello,
> > 
> > In attachment you can find logs for compute0 and controller0 (other
> > computes and controllers were turned off for this test).
> > No OVN used, this stack is based on OVS.
> > 
> > Thank you,
> > Michal Arbet
> > Openstack Engineer
> > 
> > Ultimum Technologies a.s.
> > Na Poříčí 1047/26, 11000 Praha 1
> > Czech Republic
> > 
> > +420 604 228 897
> > michal.arbet at ultimum.io
> > *https://ultimum.io <https://ultimum.io/>*
> > 
> > LinkedIn <https://www.linkedin.com/company/ultimum-technologies> | Twitter
> > <https://twitter.com/ultimumtech> | Facebook
> > <https://www.facebook.com/ultimumtechnologies/timeline>
> > 
> > 
> > st 24. 11. 2021 v 15:59 odesílatel Rodolfo Alonso Hernandez <
> > 
> > ralonsoh at redhat.com> napsal:
> >> Hello Tony:
> >> 
> >> Do you have the Neutron server logs? Do you see the
> >> "PortBindingChassisUpdateEvent"? When a port is bound, a Port_Bound (SB)
> >> event is issued and captured in the Neutron server. That will trigger the
> >> port binding process and the "vif-plugged" event. This OVN SB event 
should
> >> call "set_port_status_up" and that should write "OVN reports status up 
for
> >> port: %s" in the logs.
> >> 
> >> Of course, this Neutron method will be called only if the logical switch
> >> port is UP.
> >> 
> >> Regards.
> >> 
> >> 
> >> On Tue, Nov 23, 2021 at 11:59 PM Tony Liu <tonyliu0592 at hotmail.com>
> >> 
> >> wrote:
> >>> Hi,
> >>> 
> >>> I see such problem from time to time. It's not consistently
> >>> reproduceable.
> >>> ======================
> >>> 2021-11-23 22:16:28.532 7 INFO nova.compute.manager
> >>> [req-50817b01-e7ae-4991-94fe-e4c5672c481b - - - - -] [instance:
> >>> 7021bf37-348d-4dfa-b0c5-6a251fceb6cd] During sync_power_state the 
instance
> >>> has a pending task (spawning). Skip.
> >>> 2021-11-23 22:21:28.342 7 WARNING nova.virt.libvirt.driver
> >>> [req-814c98a4-3fd9-4607-9abb-5fbe5cef8650 
3a4c320d64664d9cb6784b7ea52d618a
> >>> 21384fe21ebb4339b1a5f2a8f9000ea3 - default default] [instance:
> >>> 7021bf37-348d-4dfa-b0c5-6a251fceb6cd] Timeout waiting for
> >>> [('network-vif-plugged', '735d97a3-db7c-42ed-b3be-1596d4cc7f4b')] for
> >>> instance with vm_state building and task_state spawning.:
> >>> eventlet.timeout.Timeout: 300 seconds
> >>> ======================
> >>> The VIF/port is activated by OVN ovn-controller to ovn-sb. It seems
> >>> that, either Neutron didn't
> >>> capture the update or didn't send message back to nova-compute. Is there
> >>> any known fix for
> >>> this problem?
> >>> 
> >>> 
> >>> Thanks!
> >>> Tony


-- 
Slawek Kaplonski
Principal Software Engineer
Red Hat
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 488 bytes
Desc: This is a digitally signed message part.
URL: <http://lists.openstack.org/pipermail/openstack-discuss/attachments/20211125/d801c45c/attachment-0003.sig>