| 2020-02-29 10:25:46 |
Frode Nordahl |
description |
While debugging a check failure [0] I would expect curl called through ssh.exec_command to report an error (curl: (32) Broken pipe, or something similar), but evidently it did not.
Could there be an issue with the propagation of error return from ssh.exec_command?
The sequence of events:
The compute.servers.test_device_tagging test calls curl through ssh.exec_command [1]
Nova metadata API successfully responds to a request to metadata:
Feb 29 00:13:30.071709 ubuntu-bionic-ovh-bhs1-0014902633 devstack@n-api-meta.service[12675]: [pid: 12678|app: 0|req: 1/1] 158.69.65.38 () {40 vars in 699 bytes} [Sat Feb 29 00:12:57 2020] GET /openstack/latest/meta_data.json => generated 2163 bytes in 32872 msecs (HTTP/1.1 200) 3 headers in 92 bytes (1 switches on core 0)
Neutron metadata proxy successfully receives the request from Nova, but gets a broken pipe while writing to the client:
Feb 29 00:13:30.074089 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: DEBUG neutron.agent.metadata.agent [-] <Response [200]> {{(pid=9562) _proxy_request /opt/stack/neutron/neutron/agent/metadata/agent.py:213}}
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: INFO eventlet.wsgi.server [-] Traceback (most recent call last):
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/wsgi.py", line 597, in handle_one_response
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: write(b''.join(towrite))
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/wsgi.py", line 538, in write
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: wfile.flush()
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/lib/python3.6/socket.py", line 604, in write
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: return self._sock.send(b)
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/greenio/base.py", line 397, in send
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: return self._send_loop(self.fd.send, data, flags)
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/greenio/base.py", line 384, in _send_loop
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: return send_method(data, *args)
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: BrokenPipeError: [Errno 32] Broken pipe
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]:
Feb 29 00:13:30.097994 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: INFO eventlet.wsgi.server [-] 10.1.0.12,<local> "GET /openstack/latest/meta_data.json HTTP/1.1" status: 200 len: 0 time: 35.6563795
Test failure indicates that no exception was raised on the back of the command execution but a empty string was returned:
2020-02-29 00:13:50.565659 | controller | Traceback (most recent call last):
2020-02-29 00:13:50.565673 | controller | File "/opt/stack/tempest/tempest/common/utils/__init__.py", line 89, in wrapper
2020-02-29 00:13:50.565687 | controller | return f(*func_args, **func_kwargs)
2020-02-29 00:13:50.565701 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 383, in test_tagged_attachment
2020-02-29 00:13:50.565714 | controller | self.verify_device_metadata)
2020-02-29 00:13:50.565727 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 88, in verify_metadata_from_api
2020-02-29 00:13:50.565754 | controller | CONF.compute.build_interval):
2020-02-29 00:13:50.565770 | controller | File "/opt/stack/tempest/tempest/lib/common/utils/test_utils.py", line 107, in call_until_true
2020-02-29 00:13:50.565784 | controller | if func(*args, **kwargs):
2020-02-29 00:13:50.573611 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 81, in get_and_verify_metadata
2020-02-29 00:13:50.573655 | controller | return verify_method(md_json)
2020-02-29 00:13:50.573671 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 313, in verify_device_metadata
2020-02-29 00:13:50.573685 | controller | md_dict = json.loads(md_json)
2020-02-29 00:13:50.573698 | controller | File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/oslo_serialization/jsonutils.py", line 264, in loads
2020-02-29 00:13:50.573713 | controller | return json.loads(encodeutils.safe_decode(s, encoding), **kwargs)
2020-02-29 00:13:50.573727 | controller | File "/usr/lib/python3.6/json/__init__.py", line 354, in loads
2020-02-29 00:13:50.573740 | controller | return _default_decoder.decode(s)
2020-02-29 00:13:50.573753 | controller | File "/usr/lib/python3.6/json/decoder.py", line 339, in decode
2020-02-29 00:13:50.573765 | controller | obj, end = self.raw_decode(s, idx=_w(s, 0).end())
2020-02-29 00:13:50.573778 | controller | File "/usr/lib/python3.6/json/decoder.py", line 357, in raw_decode
2020-02-29 00:13:50.573791 | controller | raise JSONDecodeError("Expecting value", s, err.value) from None
2020-02-29 00:13:50.573858 | controller | json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
0: https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_ac1/701377/12/check/tempest-integrated-networking/ac13425/
1: https://github.com/openstack/tempest/blob/7dae461504b4c7b9bb5b5575dd759a60bdc9d546/tempest/api/compute/servers/test_device_tagging.py#L79 |
While debugging a check failure [0] I would expect curl called through ssh.exec_command to report an error (curl: (32) Broken pipe, curl: (52) Empty reply from server or something similar), but evidently it did not.
Could there be an issue with the propagation of error return from ssh.exec_command?
The sequence of events:
The compute.servers.test_device_tagging test calls curl through ssh.exec_command [1]
Nova metadata API successfully responds to a request to metadata:
Feb 29 00:13:30.071709 ubuntu-bionic-ovh-bhs1-0014902633 devstack@n-api-meta.service[12675]: [pid: 12678|app: 0|req: 1/1] 158.69.65.38 () {40 vars in 699 bytes} [Sat Feb 29 00:12:57 2020] GET /openstack/latest/meta_data.json => generated 2163 bytes in 32872 msecs (HTTP/1.1 200) 3 headers in 92 bytes (1 switches on core 0)
Neutron metadata proxy successfully receives the request from Nova, but gets a broken pipe while writing to the client:
Feb 29 00:13:30.074089 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: DEBUG neutron.agent.metadata.agent [-] <Response [200]> {{(pid=9562) _proxy_request /opt/stack/neutron/neutron/agent/metadata/agent.py:213}}
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: INFO eventlet.wsgi.server [-] Traceback (most recent call last):
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/wsgi.py", line 597, in handle_one_response
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: write(b''.join(towrite))
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/wsgi.py", line 538, in write
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: wfile.flush()
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/lib/python3.6/socket.py", line 604, in write
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: return self._sock.send(b)
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/greenio/base.py", line 397, in send
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: return self._send_loop(self.fd.send, data, flags)
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: File "/usr/local/lib/python3.6/dist-packages/eventlet/greenio/base.py", line 384, in _send_loop
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: return send_method(data, *args)
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: BrokenPipeError: [Errno 32] Broken pipe
Feb 29 00:13:30.082479 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]:
Feb 29 00:13:30.097994 ubuntu-bionic-ovh-bhs1-0014902633 neutron-metadata-agent[9085]: INFO eventlet.wsgi.server [-] 10.1.0.12,<local> "GET /openstack/latest/meta_data.json HTTP/1.1" status: 200 len: 0 time: 35.6563795
Test failure indicates that no exception was raised on the back of the command execution but a empty string was returned:
2020-02-29 00:13:50.565659 | controller | Traceback (most recent call last):
2020-02-29 00:13:50.565673 | controller | File "/opt/stack/tempest/tempest/common/utils/__init__.py", line 89, in wrapper
2020-02-29 00:13:50.565687 | controller | return f(*func_args, **func_kwargs)
2020-02-29 00:13:50.565701 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 383, in test_tagged_attachment
2020-02-29 00:13:50.565714 | controller | self.verify_device_metadata)
2020-02-29 00:13:50.565727 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 88, in verify_metadata_from_api
2020-02-29 00:13:50.565754 | controller | CONF.compute.build_interval):
2020-02-29 00:13:50.565770 | controller | File "/opt/stack/tempest/tempest/lib/common/utils/test_utils.py", line 107, in call_until_true
2020-02-29 00:13:50.565784 | controller | if func(*args, **kwargs):
2020-02-29 00:13:50.573611 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 81, in get_and_verify_metadata
2020-02-29 00:13:50.573655 | controller | return verify_method(md_json)
2020-02-29 00:13:50.573671 | controller | File "/opt/stack/tempest/tempest/api/compute/servers/test_device_tagging.py", line 313, in verify_device_metadata
2020-02-29 00:13:50.573685 | controller | md_dict = json.loads(md_json)
2020-02-29 00:13:50.573698 | controller | File "/opt/stack/tempest/.tox/tempest/lib/python3.6/site-packages/oslo_serialization/jsonutils.py", line 264, in loads
2020-02-29 00:13:50.573713 | controller | return json.loads(encodeutils.safe_decode(s, encoding), **kwargs)
2020-02-29 00:13:50.573727 | controller | File "/usr/lib/python3.6/json/__init__.py", line 354, in loads
2020-02-29 00:13:50.573740 | controller | return _default_decoder.decode(s)
2020-02-29 00:13:50.573753 | controller | File "/usr/lib/python3.6/json/decoder.py", line 339, in decode
2020-02-29 00:13:50.573765 | controller | obj, end = self.raw_decode(s, idx=_w(s, 0).end())
2020-02-29 00:13:50.573778 | controller | File "/usr/lib/python3.6/json/decoder.py", line 357, in raw_decode
2020-02-29 00:13:50.573791 | controller | raise JSONDecodeError("Expecting value", s, err.value) from None
2020-02-29 00:13:50.573858 | controller | json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
0: https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_ac1/701377/12/check/tempest-integrated-networking/ac13425/
1: https://github.com/openstack/tempest/blob/7dae461504b4c7b9bb5b5575dd759a60bdc9d546/tempest/api/compute/servers/test_device_tagging.py#L79 |
|
