[SRIOV] Agent is reporting "resources_synced=True" when restarted and placement is down

[Rodolfo Alonso]

In fullstack test "test_configurations_are_synced_towards_placement", the Placement process is stopped, a new network is added and the L2 agent is restarted (SRIOV in this case).

The agent should sync the resources using the placement API, but because the Placement process is down, the server should report "resources_synced=False" until the placement report is received.

In [1] can be seen that the first reply from the server, informing about the agent with the new configuration (new network), the flag is True ("resources_synced": true):
2019-12-13 09:59:09.251 5513 DEBUG neutronclient.client [-] RESP: 200 {'Content-Type': 'application/json', 'Content-Length': '860', 'X-Openstack-Request-Id': 'req-363fc0e2-c3ae-4995-853b-cfbba9f2beb2', 'Date': 'Fri, 13 Dec 2019 09:59:09 GMT', 'Connection': 'keep-alive'} {"agents": [{"id": "158dea82-07e4-47d8-a65a-849e6de5e981", "agent_type": "NIC Switch agent", "binary": "neutron-sriov-nic-agent", "topic": "N/A", "host": "host-a677ed52", "admin_state_up": true, "created_at": "2019-12-13 09:58:39", "started_at": "2019-12-13 09:58:58", "heartbeat_timestamp": "2019-12-13 09:58:58", "description": null, "resources_synced": true, "availability_zone": null, "alive": true, "configurations": {"device_mappings": {"physnet1": ["ens590a255c847e", "ens61730c512d2e"], "physnetnew": ["ens74c23d91936f"]}, "extensions": [], "resource_provider_bandwidths": {"ens590a255c847e": {"egress": 1000, "ingress": 1000}, "ens61730c512d2e": {"egress": 1000, "ingress": 1000}, "ens74c23d91936f": {"egress": 1000, "ingress": 1000}}, "resource_provider_inventory_defaults": {"allocation_ratio": 1.0, "min_unit": 1, "step_size": 1, "reserved": 0}}}]} http_log_resp /home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/lib/python3.6/site-packages/neutronclient/common/utils.py:204

Logs: https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_1de/697251/7/check/neutron-fullstack/1deb02b/testr_results.html.gz

[1] https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_1de/697251/7/check/neutron-fullstack/1deb02b/controller/logs/dsvm-fullstack-logs/TestPlacementBandwidthReport.test_configurations_are_synced_towards_placement_NIC-Switch-agent_.txt.gz

[YAMAMOTO Takashi (yamamoto)]

the test decided to fail and started killing the neutron server at:

2019-12-13 09:59:32.058 5513 DEBUG neutron.agent.common.async_process [-] Halting async process [/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/bin/neutron-server --log-dir /opt/stack/logs/dsvm-fullstack-logs/TestPlacementBandwidthReport.test_configurations_are_synced_towards_placement_NIC-Switch-agent_ --log-file neutron-server--2019-12-13--09-58-26-449940.log --config-file /tmp/tmptz3q23or/tmpodugwxcl/neutron.conf --config-file /tmp/tmptz3q23or/tmpodugwxcl/ml2_conf.ini]. stop /home/zuul/src/opendev.org/openstack/neutron/neutron/agent/common/async_process.py:135

while the server noticed resources_synced=False at:

2019-12-13 09:59:34.268 14875 WARNING neutron.services.placement_report.plugin [req-f5af49ea-fb5c-496a-bcfc-4d37004763f0 - - - - -] Synchronization of resources of agent type NIC Switch agent at host host-a677ed52 to placement failed.: keystoneauth1.exceptions.http.HttpError: HTTP Error (HTTP 0)

maybe for some reasons the placement plugin is taking too longer to fail than expected?

[Bence Romsics (bence-romsics)]

This sounds like a bug for me, I put it on my todo list.

[Bence Romsics (bence-romsics)]

I had a bit of time to look at this. I don't get it fully yet, but anyway I found something strange I wanted record and share here. I don't think the agent was actually restarted.

Have a look at this before and after the 'Process stopped/started' lines:

$ wget -q -O- https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_1de/697251/7/check/neutron-fullstack/1deb02b/controller/logs/dsvm-fullstack-logs/TestPlacementBandwidthReport.test_configurations_are_synced_towards_placement_NIC-Switch-agent_.txt.gz | zcat | egrep 'resources_synced|Process .*: neutron-sriov-nic-agent' | head

2019-12-13 09:58:34.221 5513 DEBUG neutron.tests.fullstack.resources.process [-] Process started: neutron-sriov-nic-agent start /home/zuul/src/opendev.org/openstack/neutron/neutron/tests/fullstack/resources/process.py:74
2019-12-13 09:58:44.785 5513 DEBUG neutronclient.client [-] RESP: 200 {'Content-Type': 'application/json', 'Content-Length': '771', 'X-Openstack-Request-Id': 'req-004406ad-2459-4b88-beb8-ecce40d80135', 'Date': 'Fri, 13 Dec 2019 09:58:44 GMT', 'Connection': 'keep-alive'} {"agents": [{"id": "158dea82-07e4-47d8-a65a-849e6de5e981", "agent_type": "NIC Switch agent", "binary": "neutron-sriov-nic-agent", "topic": "N/A", "host": "host-a677ed52", "admin_state_up": true, "created_at": "2019-12-13 09:58:39", "started_at": "2019-12-13 09:58:39", "heartbeat_timestamp": "2019-12-13 09:58:39", "description": null, "resources_synced": true, "availability_zone": null, "alive": true, "configurations": {"device_mappings": {"physnet1": ["ens590a255c847e", "ens61730c512d2e"]}, "extensions": [], "resource_provider_bandwidths": {"ens590a255c847e": {"egress": 1000, "ingress": 1000}, "ens61730c512d2e": {"egress": 1000, "ingress": 1000}}, "resource_provider_inventory_defaults": {"allocation_ratio": 1.0, "min_unit": 1, "step_size": 1, "reserved": 0}}}]} http_log_resp /home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/lib/python3.6/site-packages/neutronclient/common/utils.py:204
2019-12-13 09:58:44.802 5513 DEBUG neutronclient.client [-] RESP: 200 {'Content-Type': 'application/json', 'Content-Length': '771', 'X-Openstack-Request-Id': 'req-0c7fef64-e9d7-4e6e-8a35-99421381b62c', 'Date': 'Fri, 13 Dec 2019 09:58:44 GMT', 'Connection': 'keep-alive'} {"agents": [{"id": "158dea82-07e4-47d8-a65a-849e6de5e981", "agent_type": "NIC Switch agent", "binary": "neutron-sriov-nic-agent", "topic": "N/A", "host": "host-a677ed52", "admin_state_up": true, "created_at": "2019-12-13 09:58:39", "started_at": "2019-12-13 09:58:39", "heartbeat_timestamp": "2019-12-13 09:58:39", "description": null, "resources_synced": true, "availability_zone": null, "alive": true, "configurations": {"device_mappings": {"physnet1": ["ens590a255c847e", "ens61730c512d2e"]}, "extensions": [], "resource_provider_bandwidths": {"ens590a255c847e": {"egress": 1000, "ingress": 1000}, "ens61730c512d2e": {"egress": 1000, "ingress": 1000}}, "resource_provider_inventory_defaults": {"allocation_ratio": 1.0, "min_unit": 1, "step_size": 1, "reserved": 0}}}]} http_log_resp /home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/lib/python3.6/site-packages/neutronclient/common...

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Thanks Bence for your time debugging this problem.

[Lajos Katona (lajos-katona)]

After reexamining this failure with rubasov, we collected the following things.
1.) A logstash query as the old links are not working now:
http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22test_configurations_are_synced_towards_placement%5C%22%20AND%20build_name%3A%5C%22neutron-fullstack%5C%22%20AND%20build_status%3A%5C%22FAILURE%5C%22

2.) I the case of a successful run, the started_at field in the agent report changes after a few iterations to the time after the restart. In this case under the log folder (i.e.: controller/logs/dsvm-fullstack-logs/TestPlacementBandwidthReport.test_configurations_are_synced_towards_placement_NIC-Switch-agent_/) there are 2 logs for the agent, one related to the agent before the restart and for after the restart.
In the failing case the started_at remains the same, and there is only 1 agent log file in the log folder.

3.) In both cases the start of the new agent process seems to be successful, see a failing case:

2020-01-15 10:09:18.985 5633 DEBUG neutron.agent.common.async_process [-] Launching async process [/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/bin/neutron-sriov-nic-agent --log-dir /opt/stack/logs/dsvm-fullstack-logs/TestPlacementBandwidthReport.test_configurations_are_synced_towards_placement_NIC-Switch-agent_ --log-file neutron-sriov-nic-agent--2020-01-15--10-09-18-984586.log --config-file /tmp/tmp8kcs8kod/tmpfl9b37bi/neutron.conf --config-file /tmp/tmp8kcs8kod/tmpfl9b37bi/sriov_agent.ini]. start /home/zuul/src/opendev.org/openstack/neutron/neutron/agent/common/async_process.py:112
2020-01-15 10:09:18.985 5633 DEBUG neutron.agent.linux.utils [-] Running command: ['/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/bin/neutron-sriov-nic-agent', '--log-dir', '/opt/stack/logs/dsvm-fullstack-logs/TestPlacementBandwidthReport.test_configurations_are_synced_towards_placement_NIC-Switch-agent_', '--log-file', 'neutron-sriov-nic-agent--2020-01-15--10-09-18-984586.log', '--config-file', '/tmp/tmp8kcs8kod/tmpfl9b37bi/neutron.conf', '--config-file', '/tmp/tmp8kcs8kod/tmpfl9b37bi/sriov_agent.ini'] create_process /home/zuul/src/opendev.org/openstack/neutron/neutron/agent/linux/utils.py:87
2020-01-15 10:09:19.115 5633 DEBUG neutron.agent.linux.utils [-] Found cmdline ['/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/bin/python3', '/home/zuul/src/opendev.org/openstack/neutron/.tox/dsvm-fullstack/bin/neutron-sriov-nic-agent', '--log-dir', '/opt/stack/logs/dsvm-fullstack-logs/TestPlacementBandwidthReport.test_configurations_are_synced_towards_placement_NIC-Switch-agent_', '--log-file', 'neutron-sriov-nic-agent--2020-01-15--10-09-18-984586.log', '--config-file', '/tmp/tmp8kcs8kod/tmpfl9b37bi/neutron.conf', '--config-file', '/tmp/tmp8kcs8kod/tmpfl9b37bi/sriov_agent.ini'] for process with PID 9205. get_cmdline_from_pid /home/zuul/src/opendev.org/openstack/neutron/neutron/agent/linux/utils.py:343
2020-01-15 10:09:19.118 5633 DEBUG neutron.tests.fullstack.resources.process [-] Process started: neutron-sriov-nic-agent start /home/zuul/src/opendev.org/openstack/neutron/neutron/tests/fullstack/resources/process.py:74

So even PID is there...

[Lajos Katona (lajos-katona)]

The same happens with OVS agent also sporadically, example search:
https://opensearch.logs.openstack.org/_dashboards/app/discover/?security_tenant=global#/?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-30d,to:now))&_a=(columns:!(build_status,build_name),filters:!(),index:'94869730-aea8-11ec-9e6a-83741af3fdcd',interval:auto,query:(language:kuery,query:'message:%22line%20244,%20in%20test_configurations_are_synced_towards_placement%22'),sort:!())

Links to logs:
* https://7a456b090239dc19e21e-66179e131883a8ab832a0afb9e9b5999.ssl.cf5.rackcdn.com/869388/1/check/neutron-fullstack-with-uwsgi/d4f2039/

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/neutron/+/870956

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/870956
Committed: https://opendev.org/openstack/neutron/commit/0ae432e71712be671ec93dded3245513b6810cd0
Submitter: "Zuul (22348)"
Branch: master

commit 0ae432e71712be671ec93dded3245513b6810cd0
Author: elajkat <email address hidden>
Date: Wed Jan 18 14:30:44 2023 +0100

    Fullstack: Wait placement process fixtrue to really stop

    It seems that in test test_configurations_are_synced_towards_placement
    when the fake placement process is stopped it can take longer and
    the test restarts the agent before it is really dead.
    In this case neutron-server can report the status and the agent's
    'resources_synced' field is True when the tests checks it.

    A simple workaround for this can be to check if the AsyncProcess
    class' _is_running property is False.

    Closes-Bug: #1856319
    Change-Id: Ia4c25110ee5a7b7539407d3531f559555fec50cc

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/zed
Review: https://review.opendev.org/c/openstack/neutron/+/872878

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/872878
Committed: https://opendev.org/openstack/neutron/commit/4d983d2fea7605859609f00220a6cf1d3ffc3950
Submitter: "Zuul (22348)"
Branch: stable/zed

commit 4d983d2fea7605859609f00220a6cf1d3ffc3950
Author: elajkat <email address hidden>
Date: Wed Jan 18 14:30:44 2023 +0100

    Fullstack: Wait placement process fixtrue to really stop

    It seems that in test test_configurations_are_synced_towards_placement
    when the fake placement process is stopped it can take longer and
    the test restarts the agent before it is really dead.
    In this case neutron-server can report the status and the agent's
    'resources_synced' field is True when the tests checks it.

    A simple workaround for this can be to check if the AsyncProcess
    class' _is_running property is False.

    Closes-Bug: #1856319
    Change-Id: Ia4c25110ee5a7b7539407d3531f559555fec50cc
    (cherry picked from commit 0ae432e71712be671ec93dded3245513b6810cd0)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/yoga
Review: https://review.opendev.org/c/openstack/neutron/+/873279

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/xena
Review: https://review.opendev.org/c/openstack/neutron/+/873962

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/873962
Committed: https://opendev.org/openstack/neutron/commit/a26f20fe950c88e5e5540a095de365b56691803e
Submitter: "Zuul (22348)"
Branch: stable/xena

commit a26f20fe950c88e5e5540a095de365b56691803e
Author: elajkat <email address hidden>
Date: Wed Jan 18 14:30:44 2023 +0100

    Fullstack: Wait placement process fixtrue to really stop

    It seems that in test test_configurations_are_synced_towards_placement
    when the fake placement process is stopped it can take longer and
    the test restarts the agent before it is really dead.
    In this case neutron-server can report the status and the agent's
    'resources_synced' field is True when the tests checks it.

    A simple workaround for this can be to check if the AsyncProcess
    class' _is_running property is False.

    Closes-Bug: #1856319
    Change-Id: Ia4c25110ee5a7b7539407d3531f559555fec50cc
    (cherry picked from commit 0ae432e71712be671ec93dded3245513b6810cd0)
    (cherry picked from commit 4d983d2fea7605859609f00220a6cf1d3ffc3950)

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/873279
Committed: https://opendev.org/openstack/neutron/commit/54501e7a24145aff318a6b5b1fa8b762a0e6b664
Submitter: "Zuul (22348)"
Branch: stable/yoga

commit 54501e7a24145aff318a6b5b1fa8b762a0e6b664
Author: elajkat <email address hidden>
Date: Wed Jan 18 14:30:44 2023 +0100

    Fullstack: Wait placement process fixtrue to really stop

    It seems that in test test_configurations_are_synced_towards_placement
    when the fake placement process is stopped it can take longer and
    the test restarts the agent before it is really dead.
    In this case neutron-server can report the status and the agent's
    'resources_synced' field is True when the tests checks it.

    A simple workaround for this can be to check if the AsyncProcess
    class' _is_running property is False.

    Closes-Bug: #1856319
    Change-Id: Ia4c25110ee5a7b7539407d3531f559555fec50cc
    (cherry picked from commit 0ae432e71712be671ec93dded3245513b6810cd0)
    (cherry picked from commit 4d983d2fea7605859609f00220a6cf1d3ffc3950)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/wallaby
Review: https://review.opendev.org/c/openstack/neutron/+/874499

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/neutron/+/874499
Committed: https://opendev.org/openstack/neutron/commit/0f0cd189d5e771c1d9687872242031c6b0441b93
Submitter: "Zuul (22348)"
Branch: stable/wallaby

commit 0f0cd189d5e771c1d9687872242031c6b0441b93
Author: elajkat <email address hidden>
Date: Wed Jan 18 14:30:44 2023 +0100

    Fullstack: Wait placement process fixtrue to really stop

    It seems that in test test_configurations_are_synced_towards_placement
    when the fake placement process is stopped it can take longer and
    the test restarts the agent before it is really dead.
    In this case neutron-server can report the status and the agent's
    'resources_synced' field is True when the tests checks it.

    A simple workaround for this can be to check if the AsyncProcess
    class' _is_running property is False.

    Closes-Bug: #1856319
    Change-Id: Ia4c25110ee5a7b7539407d3531f559555fec50cc
    (cherry picked from commit 0ae432e71712be671ec93dded3245513b6810cd0)
    (cherry picked from commit 4d983d2fea7605859609f00220a6cf1d3ffc3950)
    (cherry picked from commit a26f20fe950c88e5e5540a095de365b56691803e)

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron wallaby-eom release.