Open Stack

Dear colleagues,

trying to launch Amphorae, getting the following error in logs:

Amphora agent returned unexpected result code 500 with response
{'message': 'Error plugging VIP', 'details': 'SIOCADDRT: Network is
unreachable\nFailed to bring up eth1.\n'}

While details below, questions are here:
- whether it's enough to assign roles as explained below to special
project for Octavia?
- whether it can be issue with image, created by diskimage_create.sh?
- any recommendation on where to search for the problem.

Thank you.

My environment is:
- Openstack Rocky
- Octavia 4.0
- amphora instance runs in special project "octavia", where users
octavia, nova and neutron have admin role
- amphora image prepared using original git repo process and elements
without modification:
* git clone <octavia>
* cd octavia
* diskimage-create/diskimage-create.sh
* openstack image create [ ... ] --tag amphora

After created, amphora instance successfully connects to management
network and can be accessed by controller:

2019-05-05 20:46:06.851 18234 DEBUG
octavia.amphorae.drivers.haproxy.rest_api_driver [-] Connected to
amphora. Response: <Response [200]> request
/opt/openstack/lib/python3.6/site-packages/octavia/amphorae/drivers/haproxy/rest_api_driver.py:486
2019-05-05 20:46:06.852 18234 DEBUG
octavia.controller.worker.tasks.amphora_driver_tasks [-] Successfuly
connected to amphora 5bec4c09-a209-4e73-a66e-e4fc0fb8ded5:
{'ipvsadm_version': '1:1.28-3', 'api_version': '0.5', 'haproxy_version':
'1.6.3-1ubuntu0.2', 'hostname':
'amphora-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5', 'keepalived_version':
'1:1.2.24-1ubuntu0.16.04.1'} execute
/opt/openstack/lib/python3.6/site-packages/octavia/controller/worker/tasks/amphora_driver_tasks.py:372
[ ... ]
2019-05-05 20:46:06.990 18234 DEBUG
octavia.controller.worker.tasks.network_tasks [-] Plumbing VIP for
amphora id: 5bec4c09-a209-4e73-a66e-e4fc0fb8ded5 execute
/opt/openstack/lib/python3.6/site-packages/octavia/controller/worker/tasks/network_tasks.py:382
2019-05-05 20:46:07.003 18234 DEBUG octavia.network.drivers.neutron.base
[-] Neutron extension security-group found enabled
_check_extension_enabled
/opt/openstack/lib/python3.6/site-packages/octavia/network/drivers/neutron/base.py:66
2019-05-05 20:46:07.013 18234 DEBUG octavia.network.drivers.neutron.base
[-] Neutron extension dns-integration found enabled
_check_extension_enabled
/opt/openstack/lib/python3.6/site-packages/octavia/network/drivers/neutron/base.py:66
2019-05-05 20:46:07.025 18234 DEBUG octavia.network.drivers.neutron.base
[-] Neutron extension qos found enabled _check_extension_enabled
/opt/openstack/lib/python3.6/site-packages/octavia/network/drivers/neutron/base.py:66
2019-05-05 20:46:07.044 18234 DEBUG octavia.network.drivers.neutron.base
[-] Neutron extension allowed-address-pairs found enabled
_check_extension_enabled
/opt/openstack/lib/python3.6/site-packages/octavia/network/drivers/neutron/base.py:66
2019-05-05 20:46:08.406 18234 DEBUG
octavia.network.drivers.neutron.allowed_address_pairs [-] Created vip
port: b0398cc8-6d52-4f12-9f1f-1141b0f10751 for amphora:
5bec4c09-a209-4e73-a66e-e4fc0fb8ded5 _plug_amphora_vip
/opt/openstack/lib/python3.6/site-packages/octavia/network/drivers/neutron/allowed_address_pairs.py:97
[ ... ]
2019-05-05 20:46:15.405 18234 DEBUG
octavia.network.drivers.neutron.allowed_address_pairs [-] Retrieving
network details for amphora 5bec4c09-a209-4e73-a66e-e4fc0fb8ded5
_get_amp_net_configs
/opt/openstack/lib/python3.6/site-packages/octavia/network/drivers/neutron/allowed_address_pairs.py:596
[ ... ]
2019-05-05 20:46:15.837 18234 DEBUG
octavia.amphorae.drivers.haproxy.rest_api_driver [-] Post-VIP-Plugging
with vrrp_ip 10.0.2.13 vrrp_port b0398cc8-6d52-4f12-9f1f-1141b0f10751
post_vip_plug
/opt/openstack/lib/python3.6/site-packages/octavia/amphorae/drivers/haproxy/rest_api_driver.py:233
2019-05-05 20:46:15.838 18234 DEBUG
octavia.amphorae.drivers.haproxy.rest_api_driver [-] request url
plug/vip/10.0.2.24 request
/opt/openstack/lib/python3.6/site-packages/octavia/amphorae/drivers/haproxy/rest_api_driver.py:462
2019-05-05 20:46:15.838 18234 DEBUG
octavia.amphorae.drivers.haproxy.rest_api_driver [-] request url
https://172.16.252.35:9443/0.5/plug/vip/10.0.2.24 request
/opt/openstack/lib/python3.6/site-packages/octavia/amphorae/drivers/haproxy/rest_api_driver.py:465
2019-05-05 20:46:16.089 18234 DEBUG
octavia.amphorae.drivers.haproxy.rest_api_driver [-] Connected to
amphora. Response: <Response [500]> request
/opt/openstack/lib/python3.6/site-packages/octavia/amphorae/drivers/haproxy/rest_api_driver.py:486
2019-05-05 20:46:16.090 18234 ERROR
octavia.amphorae.drivers.haproxy.exceptions [-] Amphora agent returned
unexpected result code 500 with response {'message': 'Error plugging
VIP', 'details': 'SIOCADDRT: Network is unreachable\nFailed to bring up
eth1.\n'}

During the process, NEUTRON logs contains the following records that
indicate the following (note "status=DOWN" in neutron-dhcp-agent; later
immediately before to be deleted, it will shed 'ACTIVE'):

May  5 20:46:13 ardbeg neutron-dhcp-agent: 2019-05-05 20:46:13.857 1804
INFO neutron.agent.dhcp.agent [req-07833602-9579-403b-a264-76fd3ee408ee
a18f38c780074c6280dde5edad159666 41a02a69918849509f4102b04f8a7de9 - - -]
Trigger reload_allocations for port admin_state_up=True,
allowed_address_pairs=[{u'ip_address': u'10.0.2.24', u'mac_address':
u'72:d0:1c:4c:94:91'}], binding:host_id=ardbeg, binding:profile=,
binding:vif_details=datapath_type=system, ovs_hybrid_plug=False,
port_filter=True, binding:vif_type=ovs, binding:vnic_type=normal,
created_at=2019-05-05T20:46:07Z, description=,
device_id=f1bce6e9-be5b-464b-8f64-686f36e9de1f,
device_owner=compute:nova, dns_assignment=[{u'hostname':
u'amphora-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5', u'ip_address':
u'10.0.2.13', u'fqdn':
u'amphora-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5.loqal.'}], dns_domain=,
dns_name=amphora-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5,
extra_dhcp_opts=[], fixed_ips=[{u'subnet_id':
u'24b10886-3d53-4aee-bdc6-f165b242ae4f', u'ip_address': u'10.0.2.13'}],
id=b0398cc8-6d52-4f12-9f1f-1141b0f10751, mac_address=72:d0:1c:4c:94:91,
name=octavia-lb-vrrp-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5,
network_id=b24d2830-eec6-4abd-82f2-ac71c8ecbf40,
port_security_enabled=True, project_id=41a02a69918849509f4102b04f8a7de9,
qos_policy_id=None, revision_number=5,
security_groups=[u'6df53a15-6afc-4c99-b464-03de4f546b4f'], status=DOWN,
tags=[], tenant_id=41a02a69918849509f4102b04f8a7de9,
updated_at=2019-05-05T20:46:13Z
May  5 20:46:14 ardbeg neutron-openvswitch-agent: 2019-05-05
20:46:14.185 31542 INFO
neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent
[req-a4425cdb-afc1-4f6a-9ef9-c8706e3285d6 - - - - -] Port
b0398cc8-6d52-4f12-9f1f-1141b0f10751 updated. Details: {'profile': {},
'network_qos_policy_id': None, 'qos_policy_id': None,
'allowed_address_pairs': [{'ip_address':
AuthenticIPNetwork('10.0.2.24'), 'mac_address':
EUI('72:d0:1c:4c:94:91')}], 'admin_state_up': True, 'network_id':
'b24d2830-eec6-4abd-82f2-ac71c8ecbf40', 'segmentation_id': 437,
'fixed_ips': [{'subnet_id': '24b10886-3d53-4aee-bdc6-f165b242ae4f',
'ip_address': '10.0.2.13'}], 'device_owner': u'compute:nova',
'physical_network': None, 'mac_address': '72:d0:1c:4c:94:91', 'device':
u'b0398cc8-6d52-4f12-9f1f-1141b0f10751', 'port_security_enabled': True,
'port_id': 'b0398cc8-6d52-4f12-9f1f-1141b0f10751', 'network_type':
u'vxlan', 'security_groups': [u'6df53a15-6afc-4c99-b464-03de4f546b4f']}
May  5 20:46:14 ardbeg neutron-openvswitch-agent: 2019-05-05
20:46:14.197 31542 INFO neutron.agent.securitygroups_rpc
[req-a4425cdb-afc1-4f6a-9ef9-c8706e3285d6 - - - - -] Preparing filters
for devices set([u'b0398cc8-6d52-4f12-9f1f-1141b0f10751'])

Note Nova returns response 200/completed:

May  5 20:46:14 controller-l neutron-server: 2019-05-05 20:46:14.326
20981 INFO neutron.notifiers.nova [-] Nova event response: {u'status':
u'completed', u'tag': u'b0398cc8-6d52-4f12-9f1f-1141b0f10751', u'name':
u'network-changed', u'server_uuid':
u'f1bce6e9-be5b-464b-8f64-686f36e9de1f', u'code': 200}

and "openstack server show" shows both NICs are attached to the amphorae:

$ openstack server show f1bce6e9-be5b-464b-8f64-686f36e9de1f

+-------------------------------------+------------------------------------------------------------+
| Field                               | Value                                                      |
+-------------------------------------+------------------------------------------------------------+
[ ... ]
| addresses                           | octavia-net=172.16.252.35; u1000-p1000-xbone=10.0.2.13     |
+-------------------------------------+------------------------------------------------------------+

Later Octavia worker reports the following:

2019-05-05 20:46:16.124 18234 DEBUG
octavia.controller.worker.controller_worker [-] Task
'STANDALONE-octavia-plug-net-subflow-octavia-amp-post-vip-plug'
(f105ced1-72c6-4116-b582-599a21cdee36) transitioned into state
'REVERTING' from state 'FAILURE' _task_receiver
/opt/openstack/lib/python3.6/site-packages/taskflow/listeners/logging.py:194
2019-05-05 20:46:16.127 18234 WARNING
octavia.controller.worker.controller_worker [-] Task
'STANDALONE-octavia-plug-net-subflow-octavia-amp-post-vip-plug'
(f105ced1-72c6-4116-b582-599a21cdee36) transitioned into state
'REVERTED' from state 'REVERTING' with result 'None'
2019-05-05 20:46:16.141 18234 DEBUG
octavia.controller.worker.controller_worker [-] Task
'STANDALONE-octavia-plug-net-subflow-reload-amp-after-plug-vip'
(c4d6222e-2508-4a9c-9514-e7f9bcf84e31) transitioned into state
'REVERTING' from state 'SUCCESS' _task_receiver
/opt/openstack/lib/python3.6/site-packages/taskflow/listeners/logging.py:194
2019-05-05 20:46:16.142 18234 WARNING
octavia.controller.worker.controller_worker [-] Task
'STANDALONE-octavia-plug-net-subflow-reload-amp-after-plug-vip'
(c4d6222e-2508-4a9c-9514-e7f9bcf84e31) transitioned into state
'REVERTED' from state 'REVERTING' with result 'None'
2019-05-05 20:46:16.146 18234 DEBUG
octavia.controller.worker.controller_worker [-] Task
'STANDALONE-octavia-plug-net-subflow-ocatvia-amp-update-vip-data'
(2e1d1a04-282d-43b7-8c4f-fe31e75804ea) transitioned into state
'REVERTING' from state 'SUCCESS' _task_receiver
/opt/openstack/lib/python3.6/site-packages/taskflow/listeners/logging.py:194
2019-05-05 20:46:16.148 18234 WARNING
octavia.controller.worker.controller_worker [-] Task
'STANDALONE-octavia-plug-net-subflow-ocatvia-amp-update-vip-data'
(2e1d1a04-282d-43b7-8c4f-fe31e75804ea) transitioned into state
'REVERTED' from state 'REVERTING' with result 'None'
2019-05-05 20:46:16.173 18234 DEBUG
octavia.controller.worker.controller_worker [-] Task
'STANDALONE-octavia-plug-net-subflow-octavia-amp-plug-vip'
(c63a5bed-f531-4ed3-83d2-bce72e835932) transitioned into state
'REVERTING' from state 'SUCCESS' _task_receiver
/opt/openstack/lib/python3.6/site-packages/taskflow/listeners/logging.py:194
2019-05-05 20:46:16.174 18234 WARNING
octavia.controller.worker.tasks.network_tasks [-] Unable to plug VIP for
amphora id 5bec4c09-a209-4e73-a66e-e4fc0fb8ded5 load balancer id
e01c6ff5-179a-4ed5-ae5d-1d00d6c584b8

and Neutron then deletes port but NOTE that immediately before deletion
port reported by neutron-dhcp-agent as ACTIVE:

May  5 20:46:17 ardbeg neutron-dhcp-agent: 2019-05-05 20:46:17.080 1804
INFO neutron.agent.dhcp.agent [req-835e5b91-28e5-44b9-a463-d04a0323294f
a18f38c780074c6280dde5edad159666 41a02a69918849509f4102b04f8a7de9 - - -]
Trigger reload_allocations for port admin_state_up=True,
allowed_address_pairs=[], binding:host_id=ardbeg, binding:profile=,
binding:vif_details=datapath_type=system, ovs_hybrid_plug=False,
port_filter=True, binding:vif_type=ovs, binding:vnic_type=normal,
created_at=2019-05-05T20:46:07Z, description=,
device_id=f1bce6e9-be5b-464b-8f64-686f36e9de1f,
device_owner=compute:nova, dns_assignment=[{u'hostname':
u'amphora-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5', u'ip_address':
u'10.0.2.13', u'fqdn':
u'amphora-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5.loqal.'}], dns_domain=,
dns_name=amphora-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5,
extra_dhcp_opts=[], fixed_ips=[{u'subnet_id':
u'24b10886-3d53-4aee-bdc6-f165b242ae4f', u'ip_address': u'10.0.2.13'}],
id=b0398cc8-6d52-4f12-9f1f-1141b0f10751, mac_address=72:d0:1c:4c:94:91,
name=octavia-lb-vrrp-5bec4c09-a209-4e73-a66e-e4fc0fb8ded5,
network_id=b24d2830-eec6-4abd-82f2-ac71c8ecbf40,
port_security_enabled=True, project_id=41a02a69918849509f4102b04f8a7de9,
qos_policy_id=None, revision_number=8,
security_groups=[u'ba20352e-95b9-4c97-a688-59d44e3aa8cf'],
status=ACTIVE, tags=[], tenant_id=41a02a69918849509f4102b04f8a7de9,
updated_at=2019-05-05T20:46:16Z
May  5 20:46:17 controller-l neutron-server: 2019-05-05 20:46:17.086
20981 INFO neutron.wsgi [req-835e5b91-28e5-44b9-a463-d04a0323294f
a18f38c780074c6280dde5edad159666 41a02a69918849509f4102b04f8a7de9 -
default default] 10.0.10.31 "PUT
/v2.0/ports/b0398cc8-6d52-4f12-9f1f-1141b0f10751 HTTP/1.1" status: 200 
len: 1395 time: 0.6318841
May  5 20:46:17 controller-l neutron-server: 2019-05-05 20:46:17.153
20981 INFO neutron.wsgi [req-37ee0da3-8dcc-4fb8-9cd3-91c5a8dcedef
a18f38c780074c6280dde5edad159666 41a02a69918849509f4102b04f8a7de9 -
default default] 10.0.10.31 "GET
/v2.0/ports/b0398cc8-6d52-4f12-9f1f-1141b0f10751 HTTP/1.1" status: 200 
len: 1395 time: 0.0616651
May  5 20:46:18 controller-l neutron-server: 2019-05-05 20:46:18.179
20981 INFO neutron.wsgi [req-8896542e-5dcb-4e6d-9379-04cd88c4035b
a18f38c780074c6280dde5edad159666 41a02a69918849509f4102b04f8a7de9 -
default default] 10.0.10.31 "DELETE
/v2.0/ports/b0398cc8-6d52-4f12-9f1f-1141b0f10751 HTTP/1.1" status: 204 
len: 149 time: 1.0199890

Thank you.

--
Volodymyr Litovka
   "Vision without Execution is Hallucination." -- Thomas Edison

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack-discuss/attachments/20190506/f85bbeee/attachment-0001.html>