Fullstack test neutron.tests.fullstack.test_dhcp_agent.TestDhcpAgentHA.test_reschedule_network_on_new_agent timeout

[Hongbin Lu]

Job: neutron-fullstack-*
Failed test: neutron.tests.fullstack.test_dhcp_agent.TestDhcpAgentHA.test_reschedule_network_on_new_agent(Linux bridge agent)
Sample failure: http://logs.openstack.org/88/555088/29/gate/neutron-fullstack-python36/34299ab/job-output.txt.gz

 {0} neutron.tests.fullstack.test_dhcp_agent.TestDhcpAgentHA.test_reschedule_network_on_new_agent(Linux bridge agent) [152.363616s] ... FAILED

 Captured traceback:
 ~~~~~~~~~~~~~~~~~~~
     b'Traceback (most recent call last):'
     b' File "/opt/stack/new/neutron/neutron/common/utils.py", line 641, in wait_until_true'
     b' eventlet.sleep(sleep)'
     b' File "/opt/stack/new/neutron/.tox/dsvm-fullstack-python35/lib/python3.5/site-packages/eventlet/greenthread.py", line 36, in sleep'
     b' hub.switch()'
     b' File "/opt/stack/new/neutron/.tox/dsvm-fullstack-python35/lib/python3.5/site-packages/eventlet/hubs/hub.py", line 297, in switch'
     b' return self.greenlet.switch()'
     b'eventlet.timeout.Timeout: 60 seconds'
     b''
     b'During handling of the above exception, another exception occurred:'
     b''
     b'Traceback (most recent call last):'
     b' File "/opt/stack/new/neutron/neutron/tests/base.py", line 151, in func'
     b' return f(self, *args, **kwargs)'
     b' File "/opt/stack/new/neutron/neutron/tests/fullstack/test_dhcp_agent.py", line 168, in test_reschedule_network_on_new_agent'
     b' self._wait_until_network_rescheduled(network_dhcp_agents[0])'
     b' File "/opt/stack/new/neutron/neutron/tests/fullstack/test_dhcp_agent.py", line 137, in _wait_until_network_rescheduled'
     b' common_utils.wait_until_true(_agent_rescheduled)'
     b' File "/opt/stack/new/neutron/neutron/common/utils.py", line 646, in wait_until_true'
     b' raise WaitTimeout(_("Timed out after %d seconds") % timeout)'
     b'neutron.common.utils.WaitTimeout: Timed out after 60 seconds'
     b''

Logstash: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22test_reschedule_network_on_new_agent%5C%22%20

[Armando Migliaccio (armando-migliaccio)]

Looks intermittent.

[Slawek Kaplonski (slaweq)]

It happens again. I saw it at least 3 times in last week.

Failure example http://logs.openstack.org/19/588319/22/check/neutron-fullstack/6dbc35c/logs/testr_results.html.gz

Logstash query http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22line%20168%2C%20in%20test_reschedule_network_on_new_agent%5C%22

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Change abandoned by Rodolfo Alonso Hernandez (<email address hidden>) on branch: master
Review: https://review.openstack.org/643079

[Slawek Kaplonski (slaweq)]

It happened again recently http://logs.openstack.org/87/658787/5/check/neutron-fullstack/7d35c49/testr_results.html.gz

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/660785

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/660785
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=b3404d900ef142637869e6e8999d29d712185e95
Submitter: Zuul
Branch: master

commit b3404d900ef142637869e6e8999d29d712185e95
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Wed May 22 16:47:17 2019 +0000

    Add debug information to AutoScheduler and BaseScheduler

    These new debug lines can be helpful to resolve the mentioned bug.
    Sometimes the DHCP agent does not reschedule and the log does not
    contain enough information to debug the problem.

    Spotted error during fullstack tests:
    Traceback (most recent call last):
    File "/opt/stack/new/neutron/neutron/tests/base.py", line 151, in func
      return f(self, *args, **kwargs)
    File "/opt/stack/new/neutron/neutron/tests/fullstack/test_dhcp_agent.py",
      line 168, in test_reschedule_network_on_new_agent
      self._wait_until_network_rescheduled(network_dhcp_agents[0])'
    File "/opt/stack/new/neutron/neutron/tests/fullstack/test_dhcp_agent.py",
      line 137, in _wait_until_network_rescheduled
      common_utils.wait_until_true(_agent_rescheduled)
    File "/opt/stack/new/neutron/neutron/common/utils.py", line 646,
      in wait_until_true
      raise WaitTimeout(_("Timed out after %d seconds") % timeout)
      neutron.common.utils.WaitTimeout: Timed out after 60 seconds

    Change-Id: I794e737c30f597519fba873e36f26b82b6f2c799
    Related-Bug: #1799555

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Hello:

We have found that in some cases, the DHCP agent [1] does not report to the Neutron server and the heartbeat is not updated. In those cases, when the Neutron server wants to reschedule the network from the dead DHCP agent to the second one, this second agent is reported as dead too. When the agent starts to send again the sync status, the server binds the network to this new DHCP agent [2].

In order to log this information, I'll propose a patch to record when an agent is declared as "inactive" because of the not updated heartbeat and what "_get_network_hostable_dhcp_agents" returns.

[1] http://logs.openstack.org/11/660611/19/check/neutron-fullstack/7d4f6c4/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Linux-bridge-agent_/neutron-dhcp-agent--2019-06-07--00-47-54-171494_log.txt.gz#_2019-06-07_00_49_35_268
[2] http://logs.openstack.org/11/660611/19/check/neutron-fullstack/7d4f6c4/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Linux-bridge-agent_/neutron-server--2019-06-07--00-47-45-692437_log.txt.gz#_2019-06-07_00_49_35_699

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/663903

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/663903
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=d01a1deca9a9ccc8c396da6ca88839fa0862dd65
Submitter: Zuul
Branch: master

commit d01a1deca9a9ccc8c396da6ca88839fa0862dd65
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jun 7 11:18:57 2019 +0000

    Add log information in agent schedulers

    Added log information about the hostable DHCP agents per network.
    Added log information when an agent is declared "down" because the
    heartbeat is too old.

    Those log messages are included according to [1].

    [1] https://bugs.launchpad.net/neutron/+bug/1799555/comments/8

    Change-Id: I7b30499a86e5ae5de49813dfca01788fd5fce139
    Related-Bug: #1799555

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Hello:

Again in [1] we can see the second DHCP is declared as dead, although this agent is still running in the server [2]. As we can see in [3][4], the agent had several hiccups. But I'm not sure if the hiccup happened in the DHCP agent or in the server. IMO, this happened in the server during the "report_state" process, maybe because the RPC call was attended too late. However, we can see the call was received in time [5].

Recommendations:
- Increase the "agent_down_time" parameter in those tests to 30 secs, to avoid problems with loaded servers during the test executions.
- Activate "log_agent_heartbeats" to see when the server updates the agent heartbeats.

[1] http://logs.openstack.org/41/663141/4/check/neutron-fullstack/2f1cda7/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_/neutron-server--2019-06-14--09-16-46-288014_log.txt.gz#_2019-06-14_09_18_53_011
[2] http://logs.openstack.org/41/663141/4/check/neutron-fullstack/2f1cda7/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_/neutron-dhcp-agent--2019-06-14--09-16-55-029864_log.txt.gz

[3] http://logs.openstack.org/41/663141/4/check/neutron-fullstack/2f1cda7/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_/neutron-dhcp-agent--2019-06-14--09-16-55-029864_log.txt.gz#_2019-06-14_09_17_51_850
[4] http://logs.openstack.org/41/663141/4/check/neutron-fullstack/2f1cda7/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_/neutron-dhcp-agent--2019-06-14--09-16-55-029864_log.txt.gz#_2019-06-14_09_18_42_472

[5] http://logs.openstack.org/41/663141/4/check/neutron-fullstack/2f1cda7/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_/neutron-server--2019-06-14--09-16-46-288014_log.txt.gz#_2019-06-14_09_18_22_504

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/665422

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/665426

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/665426
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=b76321f1d8864b013d15b236b1868a21ffb8b875
Submitter: Zuul
Branch: master

commit b76321f1d8864b013d15b236b1868a21ffb8b875
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jun 14 16:15:16 2019 +0000

    Add agent timestamp to "_log_heartbeat" method

    When an agent reports the state, the timestamp is sent along with the
    agent status. This timestamp now is logged if "log_agent_heartbeats" is
    activated.

    Change-Id: Ifc88dfb3041aa07b197f395172b69399796ba46a
    Related-Bug: #1799555

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/665422
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=d7c5ae8a0378fa50853e91241426b6470ffe7492
Submitter: Zuul
Branch: master

commit d7c5ae8a0378fa50853e91241426b6470ffe7492
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jun 14 15:50:39 2019 +0000

    Increase TestDhcpAgentHA.agent_down_time to 30 seconds

    Currently there is a delay (around 20 seconds) between the the agent
    update call and the server reply, due to the testing servers load. This
    time should be higher than the agent-server communication delay but
    still short enough to detect when the DHCP agent is dead during the
    active wait during the DHCP agent network rescheduling.

    "log_agent_heartbeats" is activated to add information about when the
    server has processed the agent report status call. This log will allow
    to check the different between the server updating time and the previous
    agent heartbeat timestamp.

    Change-Id: Icf9a8802585c908fd4a70d0508139a81d5ac90ee
    Related-Bug: #1799555

[Slawek Kaplonski (slaweq)]

Looks like we don't have those issues since https://review.opendev.org/665422 was merged. I will mark this bug as fixed now.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/stein
Review: https://review.opendev.org/680657

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/rocky
Review: https://review.opendev.org/680658

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/queens
Review: https://review.opendev.org/680659

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/680659
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=57725fc7d4513c37de597a4b86f8d6878e2be034
Submitter: Zuul
Branch: stable/queens

commit 57725fc7d4513c37de597a4b86f8d6878e2be034
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jun 14 15:50:39 2019 +0000

    Increase TestDhcpAgentHA.agent_down_time to 30 seconds

    Currently there is a delay (around 20 seconds) between the the agent
    update call and the server reply, due to the testing servers load. This
    time should be higher than the agent-server communication delay but
    still short enough to detect when the DHCP agent is dead during the
    active wait during the DHCP agent network rescheduling.

    "log_agent_heartbeats" is activated to add information about when the
    server has processed the agent report status call. This log will allow
    to check the different between the server updating time and the previous
    agent heartbeat timestamp.

    Conflicts:
        neutron/tests/fullstack/resources/config.py

    Change-Id: Icf9a8802585c908fd4a70d0508139a81d5ac90ee
    Related-Bug: #1799555
    (cherry picked from commit d7c5ae8a0378fa50853e91241426b6470ffe7492)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/680658
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=68077a4cc9af638256a272cda42b44346d90589d
Submitter: Zuul
Branch: stable/rocky

commit 68077a4cc9af638256a272cda42b44346d90589d
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jun 14 15:50:39 2019 +0000

    Increase TestDhcpAgentHA.agent_down_time to 30 seconds

    Currently there is a delay (around 20 seconds) between the the agent
    update call and the server reply, due to the testing servers load. This
    time should be higher than the agent-server communication delay but
    still short enough to detect when the DHCP agent is dead during the
    active wait during the DHCP agent network rescheduling.

    "log_agent_heartbeats" is activated to add information about when the
    server has processed the agent report status call. This log will allow
    to check the different between the server updating time and the previous
    agent heartbeat timestamp.

    Conflicts:
        neutron/tests/fullstack/resources/config.py

    Change-Id: Icf9a8802585c908fd4a70d0508139a81d5ac90ee
    Related-Bug: #1799555
    (cherry picked from commit d7c5ae8a0378fa50853e91241426b6470ffe7492)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/680657
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=5b07cb21e3d8abe15c6322616b0b8976b54aef8d
Submitter: Zuul
Branch: stable/stein

commit 5b07cb21e3d8abe15c6322616b0b8976b54aef8d
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Jun 14 15:50:39 2019 +0000

    Increase TestDhcpAgentHA.agent_down_time to 30 seconds

    Currently there is a delay (around 20 seconds) between the the agent
    update call and the server reply, due to the testing servers load. This
    time should be higher than the agent-server communication delay but
    still short enough to detect when the DHCP agent is dead during the
    active wait during the DHCP agent network rescheduling.

    "log_agent_heartbeats" is activated to add information about when the
    server has processed the agent report status call. This log will allow
    to check the different between the server updating time and the previous
    agent heartbeat timestamp.

    Conflicts:
        neutron/tests/fullstack/resources/config.py

    Change-Id: Icf9a8802585c908fd4a70d0508139a81d5ac90ee
    Related-Bug: #1799555
    (cherry picked from commit d7c5ae8a0378fa50853e91241426b6470ffe7492)

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Found this problem again in [1].

In the test logs [2] we can see:
- 2019-10-15 09:23:10.682: the first DHCP agent is killed. We can see this in the last DHCP_1 log timestamps [3]
- 2019-10-15 09:24:30.437: the active wait to have the first network reschedule ends and the test starts tearing down the environment.

Meanwhile:
- 2019-10-15 09:24:32.363: the neutron server starts rescheduling the network to the second host [4].

Although increasing the waiting time in a test is never a good solution, in this case this is what we should do: increase the timeout of the active wait in TestDhcpAgentHA._wait_until_network_rescheduled. We saw in the related test case execution how the network rescheduling was done 80 seconds before the first DHCP agent was killed. We can raise the waiting time to 120 seconds (a very conservative value).

[1] https://2f600b8d6843c7d64afe-bbbb707b755a08f42bfac9929d4d55b4.ssl.cf2.rackcdn.com/688439/3/check/neutron-fullstack/119e702/testr_results.html.gz
[2] https://2f600b8d6843c7d64afe-bbbb707b755a08f42bfac9929d4d55b4.ssl.cf2.rackcdn.com/688439/3/check/neutron-fullstack/119e702/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_.txt.gz
[3] https://2f600b8d6843c7d64afe-bbbb707b755a08f42bfac9929d4d55b4.ssl.cf2.rackcdn.com/688439/3/check/neutron-fullstack/119e702/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_/neutron-dhcp-agent--2019-10-15--09-22-40-070799_log.txt.gz
[4] https://2f600b8d6843c7d64afe-bbbb707b755a08f42bfac9929d4d55b4.ssl.cf2.rackcdn.com/688439/3/check/neutron-fullstack/119e702/controller/logs/dsvm-fullstack-logs/TestDhcpAgentHA.test_reschedule_network_on_new_agent_Open-vSwitch-agent_/neutron-server--2019-10-15--09-22-31-039056_log.txt.gz

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/689550

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/689550
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=d15ad2e481b9b888079d55ba46d73ca5b7253285
Submitter: Zuul
Branch: master

commit d15ad2e481b9b888079d55ba46d73ca5b7253285
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Oct 18 17:04:02 2019 +0000

    Increase waiting time for network rescheduling

    Increate waiting time in "test_reschedule_network_on_new_agent", when
    the network is being rescheduled from a dead DHCP agent to an running
    one.

    According to [1], 120 seconds could be a convervative and enough value
    to wait for this transition.

    [1] https://bugs.launchpad.net/neutron/+bug/1799555/comments/23

    Change-Id: I2fec6015b56fd1b5d21b75f7432c40b2110fe6bc
    Related-Bug: #1799555

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/train
Review: https://review.opendev.org/718210

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/stein
Review: https://review.opendev.org/718211

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/rocky
Review: https://review.opendev.org/718212

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: stable/queens
Review: https://review.opendev.org/718213

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/718210
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=92f1521353aa3ef5d229029c9aa38c409a8850f0
Submitter: Zuul
Branch: stable/train

commit 92f1521353aa3ef5d229029c9aa38c409a8850f0
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Oct 18 17:04:02 2019 +0000

    Increase waiting time for network rescheduling

    Increate waiting time in "test_reschedule_network_on_new_agent", when
    the network is being rescheduled from a dead DHCP agent to an running
    one.

    According to [1], 120 seconds could be a convervative and enough value
    to wait for this transition.

    [1] https://bugs.launchpad.net/neutron/+bug/1799555/comments/23

    Change-Id: I2fec6015b56fd1b5d21b75f7432c40b2110fe6bc
    Related-Bug: #1799555
    (cherry picked from commit d15ad2e481b9b888079d55ba46d73ca5b7253285)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/718212
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=89f5193f4a5f0a707474eb604bcfbba120db0d45
Submitter: Zuul
Branch: stable/rocky

commit 89f5193f4a5f0a707474eb604bcfbba120db0d45
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Oct 18 17:04:02 2019 +0000

    Increase waiting time for network rescheduling

    Increate waiting time in "test_reschedule_network_on_new_agent", when
    the network is being rescheduled from a dead DHCP agent to an running
    one.

    According to [1], 120 seconds could be a convervative and enough value
    to wait for this transition.

    [1] https://bugs.launchpad.net/neutron/+bug/1799555/comments/23

    Change-Id: I2fec6015b56fd1b5d21b75f7432c40b2110fe6bc
    Related-Bug: #1799555
    (cherry picked from commit d15ad2e481b9b888079d55ba46d73ca5b7253285)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/718213
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=f2298815a2c87b2539c16ea10cf86e9576e944f1
Submitter: Zuul
Branch: stable/queens

commit f2298815a2c87b2539c16ea10cf86e9576e944f1
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Oct 18 17:04:02 2019 +0000

    Increase waiting time for network rescheduling

    Increate waiting time in "test_reschedule_network_on_new_agent", when
    the network is being rescheduled from a dead DHCP agent to an running
    one.

    According to [1], 120 seconds could be a convervative and enough value
    to wait for this transition.

    [1] https://bugs.launchpad.net/neutron/+bug/1799555/comments/23

    Change-Id: I2fec6015b56fd1b5d21b75f7432c40b2110fe6bc
    Related-Bug: #1799555
    (cherry picked from commit d15ad2e481b9b888079d55ba46d73ca5b7253285)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/718211
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=5f8371357192b3e0cb2b6388fb17561bb1cd2212
Submitter: Zuul
Branch: stable/stein

commit 5f8371357192b3e0cb2b6388fb17561bb1cd2212
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Oct 18 17:04:02 2019 +0000

    Increase waiting time for network rescheduling

    Increate waiting time in "test_reschedule_network_on_new_agent", when
    the network is being rescheduled from a dead DHCP agent to an running
    one.

    According to [1], 120 seconds could be a convervative and enough value
    to wait for this transition.

    [1] https://bugs.launchpad.net/neutron/+bug/1799555/comments/23

    Change-Id: I2fec6015b56fd1b5d21b75f7432c40b2110fe6bc
    Related-Bug: #1799555
    (cherry picked from commit d15ad2e481b9b888079d55ba46d73ca5b7253285)