Fullstack native tests sometimes fail with an OVS agent failing to start with 'Address already in use' error

[Assaf Muller]

Example failure:
test_connectivity(VLANs,Native) fails with this error:

http://paste.openstack.org/show/488585/

wait_until_env_is_up is timing out, which typically means that the expected number of agents failed to start. Indeed in this particular example I saw this line being output repeatedly in neutron-server.log:

[29/Feb/2016 04:16:31] "GET /v2.0/agents.json HTTP/1.1" 200 1870 0.005458

Fullstack calls GET on agents to determine if the expected amount of agents were started and are successfully reporting back to neutron-server.

We then see that one of the three OVS agents crashed with this TRACE:
http://paste.openstack.org/show/488586/

This happens only with the native tests using the Ryu library.

[Assaf Muller (amuller)]

http://logs.openstack.org/19/283919/3/check/gate-neutron-dsvm-fullstack/799e208/

[Dariusz Smigiel (smigiel-dariusz)]

build_name:"gate-neutron-dsvm-fullstack" AND message:"eventlet.timeout.Timeout" AND build_status:"FAILURE" (137) count per 1h | (137 hits)

[Dariusz Smigiel (smigiel-dariusz)]

First timestamp, where this problem occurs is found at: 2016-02-20T14:19:57.123+00:00
http://logs.openstack.org/74/282874/1/check/gate-neutron-dsvm-fullstack/0afd424/console.html and it's connected with this patchset: https://review.openstack.org/#/c/282874/

[Dariusz Smigiel (smigiel-dariusz)]

Failure ratio for this issue is very low. There are over 1.3 mln successes in last 10 days.

[YAMAMOTO Takashi (yamamoto)]

looking at http://logs.openstack.org/19/283919/3/check/gate-neutron-dsvm-fullstack/799e208/ ,
it seems that the following two are trying to use the same port. (39375)

http://logs.openstack.org/19/283919/3/check/gate-neutron-dsvm-fullstack/799e208/logs/TestOvsConnectivitySameNetwork.test_connectivity_GRE-and-l2pop,Native_/neutron-server--2016-02-29--04-14-39-567038.log.txt.gz#_2016-02-29_04_15_06_995

http://logs.openstack.org/19/283919/3/check/gate-neutron-dsvm-fullstack/799e208/logs/TestOvsConnectivitySameNetwork.test_connectivity_VLANs,Native_/neutron-openvswitch-agent--2016-02-29--04-15-36-988117.log.txt.gz#_2016-02-29_04_15_38_095

[IWAMOTO Toshihiro (iwamoto)]

Hi Yamamoto-san,

your analysis might be true, but by the time the l2-agent is started, the neutron-server's child in question seems to have exited.
I'm slightly confused.

Also, it's a bit unfortunate that 2 processes picked the same port number from ~64k choices. Seeding the RNG with process ID might help. ;)

[Dariusz Smigiel (smigiel-dariusz)]

This problem occurs, when two different agents are using the same bridge id.
One of agents deletes bridge, second tries and throws an error.
http://paste.openstack.org/show/490264/
http://paste.openstack.org/show/490265/

[Assaf Muller (amuller)]

@Darek, the error you pasted is with the linux bridge tests, this about is about the OVS agent.

[Dariusz Smigiel (smigiel-dariusz)]

@Assaf, true. I probably focused too much on error, and didn't realize that's about OVS not LinuxBridge :/
I'll look on this again.

[Armando Migliaccio (armando-migliaccio)]

The sooner we make this job voting the better.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/292392

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/292392
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=bb567e9b32bf58cb5f74149f1f5cb9cb656e565e
Submitter: Jenkins
Branch: master

commit bb567e9b32bf58cb5f74149f1f5cb9cb656e565e
Author: Ihar Hrachyshka <email address hidden>
Date: Mon Mar 14 14:35:31 2016 +0100

    Reset RNG seed with current time and pid for each test started

    This will hopefully fix fullstack failures where different process
    fixtures running in parallel test processes and relying on the same
    random.choice() generator seeded by the same initial value could pick up
    the same value as a service free port, and spawn their respective
    resources using the same port.

    Which made one of those unlucky services to fail.

    Change-Id: I13cfa9392fd138c5e1b1b7d397b9ea91b2a47ed2
    Closes-Bug: #1551288

[Thierry Carrez (ttx)]

This issue was fixed in the openstack/neutron 8.0.0.0rc1 release candidate.

[IWAMOTO Toshihiro (iwamoto)]

I tried to find RNG problem with this bug a while ago with no success.
What I saw instead was "Address already in use" errors with no offending simultaneous listen()s (judging from log files).
I suspected conflicts with ephemeral ports but didn't investigate further.

How many get_free_namespace_port calls happen in a test run? Apparent port conflict may be happening somewhat often. (see [1])

[1] https://en.wikipedia.org/wiki/Birthday_problem

[Assaf Muller (amuller)]

Still seeing instances of this bug. I have a deterministic solution coming up.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/298056

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/298578

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/298056
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=03999961ac620249950d8bca628719e9c14c4382
Submitter: Jenkins
Branch: master

commit 03999961ac620249950d8bca628719e9c14c4382
Author: Assaf Muller <email address hidden>
Date: Thu Mar 24 22:14:07 2016 -0400

    Add fullstack cross-process port/ip address fixtures

    We've had a series of bugs with resources that need
    to be unique on the system across test runner
    processes. Ports are used by neutron-server and the
    OVS agent when run in native openflow mode. The function
    that generates ports looks up random unused ports and
    starts the service. However, it is raceful: By the time the
    port is found to be unused and the service is started,
    another test runner can pick the same random port.
    With close to 65536 ports to choose from, the chance
    for collision is low, but given enough test runs, it's
    happened a non-trivial amount of times, and given that
    a voting job needs a very low false-negative rate, we
    need a more robust solution. The same applies to IP
    addresses that are used by the OVS agent in tunneling
    mode, and for the LB agent in all modes. With IP addresses,
    we don't check if the IP address is used, we simply
    pick a random address from a large pool, and again
    we've seen a non-trivial amount of test failures.

    The bugs referenced below had simple, short term solutions
    applied but the bugs remain remain. This patch is a correct,
    long term solution that doesn't rely on chance.

    This patch adds a resource allocator that uses the disk
    to persist allocations. Access to the disk is guarded
    via a file lock. IP address, networks and ports fixtures
    use an allocator internally.

    Closes-Bug: #1551288
    Closes-Bug: #1561248
    Closes-Bug: #1560277
    Change-Id: I46c0ca138b806759128462f8d44a5fab96a106d3

[IWAMOTO Toshihiro (iwamoto)]

http://logstash.openstack.org/#dashboard/file/logstash.json?query=build_name%3A%5C%22gate-neutron-dsvm-fullstack%5C%22%20AND%20message%3A%5C%22self.wait_until_env_is_up()%5C%22%20AND%20build_status%3A%5C%22FAILURE%5C%22

build_name:"gate-neutron-dsvm-fullstack" AND message:"self.wait_until_env_is_up()" AND build_status:"FAILURE" (14) build_name:"gate-neutron-dsvm-fullstack" AND message:"Finished: SUCCESS" AND build_status:"SUCCESS" (169) count per 1h | (183 hits)

ovs-native port listen failures rate to successful runs is about 1:12 in these 7 days.

[IWAMOTO Toshihiro (iwamoto)]

I'm suspecting an ephemeral port is interfering listening.

An ovs agent fails to listen on 55490.

http://logs.openstack.org/84/314384/1/check/gate-neutron-dsvm-fullstack/55b0414/logs/dsvm-fullstack-logs/TestOvsConnectivitySameNetwork.test_connectivity_VLANs,openflow-native_ovsdb-cli_/neutron-openvswitch-agent--2016-05-10--01-22-54-151783.txt.gz#_2016-05-10_01_22_58_528

The only other occurence of port 55490, while it's 7 seconds off.

http://logs.openstack.org/84/314384/1/check/gate-neutron-dsvm-fullstack/55b0414/logs/dsvm-fullstack-logs/TestOvsConnectivitySameNetwork.test_connectivity_GRE-and-l2pop,openflow-cli_ovsdb-native_/neutron-server--2016-05-10--01-22-27-779228.txt.gz#_2016-05-10_01_22_50_510

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/319807

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/323800

[IWAMOTO Toshihiro (iwamoto)]

FYI, The following query lists neutron server start up failures. These failures happen almost as often as ovs agent start up failures.
Let's see if https://review.openstack.org/323800 works.

http://logstash.openstack.org/#/dashboard/file/logstash.json?query=build_name:\%22gate-neutron-dsvm-fullstack\%22%20AND%20message:\%22self.wait_until_env_is_up%28%29\%22%20AND%20build_status:\%22FAILURE\%22

[IWAMOTO Toshihiro (iwamoto)]

Wrong link. Please use the following instead.

http://logstash.openstack.org/#dashboard/file/logstash.json?query=build_name%3A%5C%22gate-neutron-dsvm-fullstack%5C%22%20AND%20message%3A%5C%22neutron_cfg_fixture%5C%22%20AND%20build_status%3A%5C%22FAILURE%5C%22

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/323800
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=9319b1a8366e00ec2ea9a763b5c3558649758f51
Submitter: Jenkins
Branch: master

commit 9319b1a8366e00ec2ea9a763b5c3558649758f51
Author: IWAMOTO Toshihiro <email address hidden>
Date: Wed Jun 1 20:17:34 2016 +0900

    Fix get_free_namespace_port to actually avoid used ports

    ss output is a string. It needs to be converted to int before a set
    operation. The function seems to have been broken from the beginning
    (commit e3fa0112).

    Change-Id: I0d10360ae8807b3688d36912b42fa2a140c45e04
    Closes-Bug: #1551288

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 9.0.0.0b1 development milestone.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/325767

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/325770

[IWAMOTO Toshihiro (iwamoto)]

Seems certainly better with my last commit but there are still "address already in use" errors:

http://logs.openstack.org/57/320657/7/check/gate-neutron-dsvm-fullstack/247a04f/logs/
http://logs.openstack.org/17/324617/6/check/gate-neutron-dsvm-fullstack/15d4054/logs/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/325767
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=adc7418c3eb253ca4bb9731b97ab69b4e14550ad
Submitter: Jenkins
Branch: stable/mitaka

commit adc7418c3eb253ca4bb9731b97ab69b4e14550ad
Author: IWAMOTO Toshihiro <email address hidden>
Date: Wed Jun 1 20:17:34 2016 +0900

    Fix get_free_namespace_port to actually avoid used ports

    ss output is a string. It needs to be converted to int before a set
    operation. The function seems to have been broken from the beginning
    (commit e3fa0112).

    Change-Id: I0d10360ae8807b3688d36912b42fa2a140c45e04
    Closes-Bug: #1551288
    (cherry picked from commit 9319b1a8366e00ec2ea9a763b5c3558649758f51)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/325770
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=bbdd53a84f1ebafb9dbf57e79cafba4767dc3ebc
Submitter: Jenkins
Branch: stable/liberty

commit bbdd53a84f1ebafb9dbf57e79cafba4767dc3ebc
Author: IWAMOTO Toshihiro <email address hidden>
Date: Wed Jun 1 20:17:34 2016 +0900

    Fix get_free_namespace_port to actually avoid used ports

    ss output is a string. It needs to be converted to int before a set
    operation. The function seems to have been broken from the beginning
    (commit e3fa0112).

    Change-Id: I0d10360ae8807b3688d36912b42fa2a140c45e04
    Closes-Bug: #1551288
    (cherry picked from commit 9319b1a8366e00ec2ea9a763b5c3558649758f51)

[IWAMOTO Toshihiro (iwamoto)]

A few more errors. All of them fail listening on port >32768. (cf. https://review.openstack.org/#/c/319807/ )

http://logs.openstack.org/26/326926/5/check/gate-neutron-dsvm-fullstack/28ce1da/logs/dsvm-fullstack-logs/TestOvsConnectivitySameNetwork.test_connectivity_VXLAN,openflow-cli_ovsdb-native_/neutron-server--2016-06-11--00-04-31-197882.txt.gz
http://logs.openstack.org/57/320657/8/check/gate-neutron-dsvm-fullstack/97c3cd6/logs/dsvm-fullstack-logs/TestOvsConnectivitySameNetwork.test_connectivity_VXLAN,openflow-native_ovsdb-cli_/neutron-openvswitch-agent--2016-06-10--14-21-21-883629.txt.gz
http://logs.openstack.org/27/326927/4/check/gate-neutron-dsvm-fullstack/aaad105/logs/dsvm-fullstack-logs/TestOvsConnectivitySameNetwork.test_connectivity_VXLAN,openflow-native_ovsdb-native_/neutron-openvswitch-agent--2016-06-10--17-46-44-285138.txt.gz

[OpenStack Infra (hudson-openstack)]

Change abandoned by Armando Migliaccio (<email address hidden>) on branch: master
Review: https://review.openstack.org/298578
Reason: This review is > 4 weeks without comment, and failed Jenkins the last time it was checked. We are abandoning this for now. Feel free to reactivate the review by pressing the restore button and leaving a 'recheck' comment to get fresh test results.

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 9.0.0.0b2 development milestone.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/319807
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=91a983f40ad4448235272e24f678a230f32385d7
Submitter: Jenkins
Branch: master

commit 91a983f40ad4448235272e24f678a230f32385d7
Author: IWAMOTO Toshihiro <email address hidden>
Date: Mon May 23 18:35:05 2016 +0900

    Avoid allocating ports from ip_local_port_range

    Ports within ip_local_port_range can be used by the local side
    of connections. Avoid using them as there should be no downside
    from using narrower port range thanks to ExclusiveResource
    allocators.

    Change-Id: I30e8e40073117e63bf9a99f13000d83a87e64f29
    Closes-Bug: #1551288

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 7.1.2 release.

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/neutron 8.2.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 9.0.0.0b3 development milestone.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Armando Migliaccio (<email address hidden>) on branch: master
Review: https://review.openstack.org/298578
Reason: This review is > 4 weeks without comment, and failed Jenkins the last time it was checked. We are abandoning this for now. Feel free to reactivate the review by pressing the restore button and leaving a 'recheck' comment to get fresh test results.