yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1707160] Re: test_create_port_in_allowed_allocation_pools test fails on ironic grenade

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Ihar Hrachyshka <1707160@xxxxxxxxxxxxxxxxxx>
Date: Wed, 02 Aug 2017 19:17:23 -0000
Reply-to: Bug 1707160 <1707160@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
OK, I still see this failing on a neutron api request here:
http://logs.openstack.org/01/489701/1/check/gate-grenade-dsvm-ironic-
ubuntu-xenial/50785e5/logs/testr_results.html.gz

In neutron-server log, we see first NotFound ERROR message from the
missing fanout exchange (that's not an issue per se, and I sent a patch
to downgrade the message to DEBUG [1]); then the request handler
attempts to fanout another event to agents; then request is locked for
~115 seconds to end with:

2017-08-01 22:50:59.696 1787 ERROR oslo.messaging._drivers.impl_rabbit [req-765ebd21-ee44-4db2-85f8-f6b7e52cdf19 tempest-RoutersTest-175057974 tempest-RoutersTest-175057974] [fdb10a5b-b3c8-436c-ba74-193c721329bb] AMQP server on 104.130.216.130:5672 is unreachable: timed out. Trying again in 1 seconds. Client port: None: timeout: timed out
2017-08-01 22:51:00.715 1787 INFO oslo.messaging._drivers.impl_rabbit [req-765ebd21-ee44-4db2-85f8-f6b7e52cdf19 tempest-RoutersTest-175057974 tempest-RoutersTest-175057974] [fdb10a5b-b3c8-436c-ba74-193c721329bb] Reconnected to AMQP server on 104.130.216.130:5672 via [amqp] client with port 51878.

When we look at rabbitmq logs around the time of failure we see:

=ERROR REPORT==== 1-Aug-2017::22:49:05 ===
Channel error on connection <0.3221.0> (104.130.216.130:43578 -> 104.130.216.130:5672, vhost: '/', user: 'stackrabbit'), channel 1:
{amqp_error,not_found,
            "no exchange 'q-agent-notifier-port-delete_fanout' in vhost '/'",
            'basic.publish'}

=WARNING REPORT==== 1-Aug-2017::22:50:59 ===
closing AMQP connection <0.3221.0> (104.130.216.130:43578 -> 104.130.216.130:5672):
connection_closed_abruptly

I suspect that after NotFound is raised, oslo.messaging channels get
into a state that doesn't allow to send any more messages, and only
connection reset restores connectivity.

[1] https://review.openstack.org/#/c/490139/

** Changed in: neutron
       Status: Fix Released => Confirmed

** Changed in: neutron
    Milestone: None => pike-3

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1707160

Title:
  test_create_port_in_allowed_allocation_pools test fails on ironic
  grenade

Status in neutron:
  Confirmed
Status in OpenStack Compute (nova):
  New

Bug description:
  Here is an example of a job at
  http://logs.openstack.org/58/487458/6/check/gate-grenade-dsvm-ironic-
  ubuntu-xenial/d8f187e/console.html#_2017-07-28_09_33_52_031224

  2017-07-28 09:33:52.027473 | Captured pythonlogging:
  2017-07-28 09:33:52.027484 | ~~~~~~~~~~~~~~~~~~~~~~~
  2017-07-28 09:33:52.027539 |     2017-07-28 09:15:48,746 9778 INFO     [tempest.lib.common.rest_client] Request (PortsTestJSON:test_create_port_in_allowed_allocation_pools): 201 POST http://149.202.183.40:9696/v2.0/networks 0.342s
  2017-07-28 09:33:52.027604 |     2017-07-28 09:15:48,746 9778 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
  2017-07-28 09:33:52.027633 |             Body: {"network": {"name": "tempest-PortsTestJSON-test-network-1596805013"}}
  2017-07-28 09:33:52.027728 |         Response - Headers: {u'date': 'Fri, 28 Jul 2017 09:15:48 GMT', u'x-openstack-request-id': 'req-0502025a-db49-4f1f-b30d-c38b8098b79e', u'content-type': 'application/json', u'content-length': '582', 'content-location': 'http://149.202.183.40:9696/v2.0/networks', 'status': '201', u'connection': 'close'}
  2017-07-28 09:33:52.027880 |             Body: {"network":{"status":"ACTIVE","router:external":false,"availability_zone_hints":[],"availability_zones":[],"description":"","subnets":[],"shared":false,"tenant_id":"5c851bb85bef4b008714ef04d1fe3671","created_at":"2017-07-28T09:15:48Z","tags":[],"ipv6_address_scope":null,"mtu":1450,"updated_at":"2017-07-28T09:15:48Z","admin_state_up":true,"revision_number":2,"ipv4_address_scope":null,"is_default":false,"port_security_enabled":true,"project_id":"5c851bb85bef4b008714ef04d1fe3671","id":"b8a3fb1c-86a4-4518-8c3a-dd12db585659","name":"tempest-PortsTestJSON-test-network-1596805013"}}
  2017-07-28 09:33:52.027936 |     2017-07-28 09:15:49,430 9778 INFO     [tempest.lib.common.rest_client] Request (PortsTestJSON:test_create_port_in_allowed_allocation_pools): 201 POST http://149.202.183.40:9696/v2.0/subnets 0.682s
  2017-07-28 09:33:52.027998 |     2017-07-28 09:15:49,431 9778 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
  2017-07-28 09:33:52.028054 |             Body: {"subnet": {"ip_version": 4, "allocation_pools": [{"end": "10.1.0.14", "start": "10.1.0.2"}], "network_id": "b8a3fb1c-86a4-4518-8c3a-dd12db585659", "gateway_ip": "10.1.0.1", "cidr": "10.1.0.0/28"}}
  2017-07-28 09:33:52.028135 |         Response - Headers: {u'date': 'Fri, 28 Jul 2017 09:15:49 GMT', u'x-openstack-request-id': 'req-1a50b739-8683-4aaa-ba4a-6e9daf73f1c8', u'content-type': 'application/json', u'content-length': '594', 'content-location': 'http://149.202.183.40:9696/v2.0/subnets', 'status': '201', u'connection': 'close'}
  2017-07-28 09:33:52.030085 |             Body: {"subnet":{"service_types":[],"description":"","enable_dhcp":true,"tags":[],"network_id":"b8a3fb1c-86a4-4518-8c3a-dd12db585659","tenant_id":"5c851bb85bef4b008714ef04d1fe3671","created_at":"2017-07-28T09:15:49Z","dns_nameservers":[],"updated_at":"2017-07-28T09:15:49Z","gateway_ip":"10.1.0.1","ipv6_ra_mode":null,"allocation_pools":[{"start":"10.1.0.2","end":"10.1.0.14"}],"host_routes":[],"revision_number":0,"ip_version":4,"ipv6_address_mode":null,"cidr":"10.1.0.0/28","project_id":"5c851bb85bef4b008714ef04d1fe3671","id":"be974b50-e56b-44a8-86a9-6bcc345f9d55","subnetpool_id":null,"name":""}}
  2017-07-28 09:33:52.030176 |     2017-07-28 09:15:50,616 9778 INFO     [tempest.lib.common.rest_client] Request (PortsTestJSON:test_create_port_in_allowed_allocation_pools): 201 POST http://149.202.183.40:9696/v2.0/ports 1.185s
  2017-07-28 09:33:52.030232 |     2017-07-28 09:15:50,617 9778 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
  2017-07-28 09:33:52.030259 |             Body: {"port": {"network_id": "b8a3fb1c-86a4-4518-8c3a-dd12db585659"}}
  2017-07-28 09:33:52.030369 |         Response - Headers: {u'date': 'Fri, 28 Jul 2017 09:15:50 GMT', u'x-openstack-request-id': 'req-6b57ff81-c874-4e97-8183-bd57c7e8de81', u'content-type': 'application/json', u'content-length': '691', 'content-location': 'http://149.202.183.40:9696/v2.0/ports', 'status': '201', u'connection': 'close'}
  2017-07-28 09:33:52.030596 |             Body: {"port":{"status":"DOWN","created_at":"2017-07-28T09:15:49Z","description":"","allowed_address_pairs":[],"tags":[],"network_id":"b8a3fb1c-86a4-4518-8c3a-dd12db585659","tenant_id":"5c851bb85bef4b008714ef04d1fe3671","extra_dhcp_opts":[],"admin_state_up":true,"updated_at":"2017-07-28T09:15:50Z","name":"","device_owner":"","revision_number":3,"mac_address":"fa:16:3e:a4:39:53","binding:vnic_type":"normal","port_security_enabled":true,"project_id":"5c851bb85bef4b008714ef04d1fe3671","fixed_ips":[{"subnet_id":"be974b50-e56b-44a8-86a9-6bcc345f9d55","ip_address":"10.1.0.4"}],"id":"a873e67a-a171-4860-9f47-be50dc061b10","security_groups":["107c3ae4-4c9f-4851-935f-5602c35270dc"],"device_id":""}}
  2017-07-28 09:33:52.030660 |     2017-07-28 09:15:51,354 9778 INFO     [tempest.lib.common.rest_client] Request (PortsTestJSON:_run_cleanups): 204 DELETE http://149.202.183.40:9696/v2.0/ports/a873e67a-a171-4860-9f47-be50dc061b10 0.735s
  2017-07-28 09:33:52.030736 |     2017-07-28 09:15:51,354 9778 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
  2017-07-28 09:33:52.030747 |             Body: None
  2017-07-28 09:33:52.030824 |         Response - Headers: {u'date': 'Fri, 28 Jul 2017 09:15:51 GMT', u'x-openstack-request-id': 'req-018a5b4a-cb5e-4dc1-b807-e3223b1fc83a', u'content-length': '0', 'content-location': 'http://149.202.183.40:9696/v2.0/ports/a873e67a-a171-4860-9f47-be50dc061b10', 'status': '204', u'connection': 'close'}
  2017-07-28 09:33:52.030835 |             Body: 
  2017-07-28 09:33:52.030918 |     2017-07-28 09:16:51,390 9778 WARNING  [urllib3.connectionpool] Retrying (Retry(total=9, connect=None, read=None, redirect=5, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='149.202.183.40', port=9696): Read timed out. (read timeout=60)",)': /v2.0/subnets/be974b50-e56b-44a8-86a9-6bcc345f9d55
  2017-07-28 09:33:52.030974 |     2017-07-28 09:16:51,508 9778 INFO     [tempest.lib.common.rest_client] Request (PortsTestJSON:_run_cleanups): 404 DELETE http://149.202.183.40:9696/v2.0/subnets/be974b50-e56b-44a8-86a9-6bcc345f9d55 60.153s
  2017-07-28 09:33:52.031023 |     2017-07-28 09:16:51,508 9778 DEBUG    [tempest.lib.common.rest_client] Request - Headers: {'X-Auth-Token': '<omitted>', 'Accept': 'application/json', 'Content-Type': 'application/json'}
  2017-07-28 09:33:52.031047 |             Body: None
  2017-07-28 09:33:52.031161 |         Response - Headers: {u'date': 'Fri, 28 Jul 2017 09:16:51 GMT', u'x-openstack-request-id': 'req-86d01b29-c1b1-4396-a0a8-c360c78dcbd5', u'content-type': 'application/json', u'content-length': '136', 'content-location': 'http://149.202.183.40:9696/v2.0/subnets/be974b50-e56b-44a8-86a9-6bcc345f9d55', 'status': '404', u'connection': 'close'}
  2017-07-28 09:33:52.031224 |             Body: {"NeutronError": {"message": "Subnet be974b50-e56b-44a8-86a9-6bcc345f9d55 could not be found.", "type": "SubnetNotFound", "detail": ""}}

  
  Seems like there is some kind of race here, this failure should not be related to ironic.

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1707160/+subscriptions
References

[Bug 1707160] [NEW] test_create_port_in_allowed_allocation_pools test fails on ironic grenade
From: Vladyslav Drok, 2017-07-28