ssh.exec_command, exit_status not always properly reported?

[Frode Nordahl]

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 <email address hidden>[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

[Paras Babbar (pbabbar)]

Hi Frode,

I am trying to understand the problem here , do you mean if the empty string is returned the function should raised an exception saying it's empty string even though the command receive successful exit status?

This is the function on client side which is returning the output data from exec_command https://github.com/openstack/tempest/blob/8877c4e8919a150992941d0cc6a49227ec863fcc/tempest/lib/common/ssh.py#L205

So I think you mean if empty string was returned then we should raise an exception here in the out_data that empty string was returned?

Thanks

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/713154

[Paras Babbar (pbabbar)]

Hi Frode,

I tried playing around with your request and then realized that we can't create value error exception for no output returned command as there were command we execute that doesn't return any output data so if we do this request that affect those commands as well like this one linux_client.exec_command("sync") that won't be returning any output string . So If you have any other views on this request , please do share otherwise I would like to close this bug as 'not a bug'.

Thanks

Paras Babbar

[Martin Kopec (mkopec)]

Based on the previous comment and no feedback provided since then, I'm moving this to Invalid. Feel free to reopen if you still encounter the issue.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Paras Babbar (<email address hidden>) on branch: master
Review: https://review.opendev.org/713154