AttachInterfacesTestXML.test_add_remove_fixed_ip BadRequest

[Michael H Wilson]

This looks to be a new bug, see http://logs.openstack.org/93/99393/4/check/check-tempest-dsvm-neutron/1392e22/console.html

2014-06-17 19:47:54.665 |
2014-06-17 19:47:54.665 | ==============================
2014-06-17 19:47:54.665 | Failed 3 tests - output below:
2014-06-17 19:47:54.665 | ==============================
2014-06-17 19:47:54.665 |
2014-06-17 19:47:54.665 | tempest.api.compute.servers.test_attach_interfaces.AttachInterfacesTestXML.test_add_remove_fixed_ip[gate,smoke]
2014-06-17 19:47:54.665 | ---------------------------------------------------------------------------------------------------------------
2014-06-17 19:47:54.665 |
2014-06-17 19:47:54.665 | Captured traceback:
2014-06-17 19:47:54.665 | ~~~~~~~~~~~~~~~~~~~
2014-06-17 19:47:54.665 | Traceback (most recent call last):
2014-06-17 19:47:54.666 | File "tempest/api/compute/servers/test_attach_interfaces.py", line 133, in test_add_remove_fixed_ip
2014-06-17 19:47:54.666 | server, ifs = self._create_server_get_interfaces()
2014-06-17 19:47:54.666 | File "tempest/api/compute/servers/test_attach_interfaces.py", line 48, in _create_server_get_interfaces
2014-06-17 19:47:54.666 | resp, server = self.create_test_server(wait_until='ACTIVE')
2014-06-17 19:47:54.666 | File "tempest/api/compute/base.py", line 247, in create_test_server
2014-06-17 19:47:54.666 | raise ex
2014-06-17 19:47:54.666 | BadRequest: Bad request
2014-06-17 19:47:54.666 | Details: {'message': 'The server could not comply with the request since it is either malformed or otherwise incorrect.', 'code': '400'}
2014-06-17 19:47:54.666 |
2014-06-17 19:47:54.666 |
2014-06-17 19:47:54.666 | Captured pythonlogging:
2014-06-17 19:47:54.666 | ~~~~~~~~~~~~~~~~~~~~~~~
2014-06-17 19:47:54.667 | 2014-06-17 19:15:13,993 Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 200 POST http://127.0.0.1:5000/v2.0/tokens
2014-06-17 19:47:54.667 | 2014-06-17 19:15:14,431 Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 202 POST http://127.0.0.1:8774/v2/97b84e38f795456d8c63a64526f8e8b5/servers 0.437s
2014-06-17 19:47:54.667 | 2014-06-17 19:15:14,534 Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 200 GET http://127.0.0.1:8774/v2/97b84e38f795456d8c63a64526f8e8b5/servers/94bb0663-1b9e-4098-bedf-9c7d4fc6f8c9 0.101s
2014-06-17 19:47:54.667 | 2014-06-17 19:15:15,663 Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 200 GET http://127.0.0.1:8774/v2/97b84e38f795456d8c63a64526f8e8b5/servers/94bb0663-1b9e-4098-bedf-9c7d4fc6f8c9 0.126s
2014-06-17 19:47:54.667 | 2014-06-17 19:15:15,665 State transition "BUILD/scheduling" ==> "ERROR/None" after 1 second wait
2014-06-17 19:47:54.667 | 2014-06-17 19:15:15,782 Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 400 POST http://127.0.0.1:8774/v2/97b84e38f795456d8c63a64526f8e8b5/servers/94bb0663-1b9e-4098-bedf-9c7d4fc6f8c9/action 0.116s
2014-06-17 19:47:54.667 | 2014-06-17 19:15:16,103 Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 204 DELETE http://127.0.0.1:8774/v2/97b84e38f795456d8c63a64526f8e8b5/servers/94bb0663-1b9e-4098-bedf-9c7d4fc6f8c9 0.320s
2014-06-17 19:47:54.667 |
2014-06-17 19:47:54.667 |
2014-06-17 19:47:54.667 | tempest.api.compute.servers.test_attach_interfaces.AttachInterfacesTestXML.test_create_list_show_delete_interfaces[gate,smoke]
2014-06-17 19:47:54.667 | ------------------------------------------------------------------------------------------------------------------------------
2014-06-17 19:47:54.668 |
2014-06-17 19:47:54.668 | Captured traceback:
2014-06-17 19:47:54.668 | ~~~~~~~~~~~~~~~~~~~
2014-06-17 19:47:54.668 | Traceback (most recent call last):
2014-06-17 19:47:54.668 | File "tempest/api/compute/servers/test_attach_interfaces.py", line 111, in test_create_list_show_delete_interfaces
2014-06-17 19:47:54.668 | server, ifs = self._create_server_get_interfaces()
2014-06-17 19:47:54.668 | File "tempest/api/compute/servers/test_attach_interfaces.py", line 48, in _create_server_get_interfaces
2014-06-17 19:47:54.668 | resp, server = self.create_test_server(wait_until='ACTIVE')
2014-06-17 19:47:54.668 | File "tempest/api/compute/base.py", line 247, in create_test_server
2014-06-17 19:47:54.668 | raise ex
2014-06-17 19:47:54.668 | BadRequest: Bad request
2014-06-17 19:47:54.668 | Details: {'message': 'The server could not comply with the request since it is either malformed or otherwise incorrect.', 'code': '400'}

[David Kranz (david-kranz)]

The proximate cause of these errors is that at the time this bug was reported, we tried to grab the console in an erroneous way that causes a 400. This issue was fixed and I would just close this as another random "server failed to boot" issue except that right before the failed server create, there are a lot of errors in the nova cpu log:

http://logs.openstack.org/93/99393/4/check/check-tempest-dsvm-neutron/1392e22/logs/screen-n-cpu.txt.gz?level=ERROR

I tried to search for some of these errors but many normal runs produce them as well. So I am opening this to nova in case there is meaning in these errors that a nova expert can see.

[Sean Dague (sdague)]

2014-06-17 19:15:15.725 DEBUG nova.api.openstack.wsgi [req-5d3b75e5-c6c9-4b55-b9f8-050824bcaff7 AttachInterfacesTestXML-933666172 AttachInterfacesTestXML-1000817649] Action: 'action', body: <?xml version="1.0" encoding="UTF-8"?>
<os-getConsoleOutput length="" xmlns="http://docs.openstack.org/compute/api/v1.1"/> _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:940
2014-06-17 19:15:15.725 DEBUG nova.api.openstack.wsgi [req-5d3b75e5-c6c9-4b55-b9f8-050824bcaff7 AttachInterfacesTestXML-933666172 AttachInterfacesTestXML-1000817649] Calling method '<bound method ConsoleOutputController.get_console_output of <nova.api.openstack.compute.contrib.console_output.ConsoleOutputController object at 0x4a5e610>>' (Content-type='application/xml', Accept='application/xml') _process_stack /opt/stack/new/nova/nova/api/openstack/wsgi.py:945
2014-06-17 19:15:15.725 DEBUG nova.openstack.common.policy [req-5d3b75e5-c6c9-4b55-b9f8-050824bcaff7 AttachInterfacesTestXML-933666172 AttachInterfacesTestXML-1000817649] Rule compute_extension:console_output will be now enforced enforce /opt/stack/new/nova/nova/openstack/common/policy.py:288
2014-06-17 19:15:15.779 DEBUG nova.openstack.common.policy [req-5d3b75e5-c6c9-4b55-b9f8-050824bcaff7 AttachInterfacesTestXML-933666172 AttachInterfacesTestXML-1000817649] Rule compute:get will be now enforced enforce /opt/stack/new/nova/nova/openstack/common/policy.py:288
2014-06-17 19:15:15.780 INFO nova.api.openstack.wsgi [req-5d3b75e5-c6c9-4b55-b9f8-050824bcaff7 AttachInterfacesTestXML-933666172 AttachInterfacesTestXML-1000817649] HTTP exception thrown: Length in request body must be an integer value
2014-06-17 19:15:15.780 DEBUG nova.api.openstack.wsgi [req-5d3b75e5-c6c9-4b55-b9f8-050824bcaff7 AttachInterfacesTestXML-933666172 AttachInterfacesTestXML-1000817649] Returning 400 to user: The server could not comply with the request since it is either malformed or otherwise incorrect. __call__ /opt/stack/new/nova/nova/api/openstack/wsgi.py:1209

The issue is because console length was sent as a non int. So this is actually currently a tempest bug because the code to get the console over XML is sending invalid xml body to Nova.

[Sean Dague (sdague)]

Comment #2 is from nova-api log in that file

[Sean Dague (sdague)]

This is actually a tempest bug. The tempest tests assume that the attach is synchronous, but it is not: it returns a 202. So it needs to go into a wait period looking for the attach to actually succeed before it bails out. Basically it's not actually waiting long enough for the neutron port attach to work.

[David Kranz (david-kranz)]

I read these logs slightly differently. I don't think the test ever got to the attach call, based on looking at the code that was present on June 17 and the fact that addFIxedIp only shows up once: in the JSON version of this test. In the old code, we call _console_dump when a server unexpectedly goes to ERROR. Further, in that June 17 code, there is a bug in the XML get_console code where it does not handle length of None. In the current code we no longer dump the console in this case, and the XML console bug was fixed.

Given this in the console

2014-06-17 19:15:15.665 10882 INFO tempest.common.waiters [-] State transition "BUILD/scheduling" ==> "ERROR/None" after 1 second wait
2014-06-17 19:15:15.782 10882 INFO tempest.common.rest_client [req-5d3b75e5-c6c9-4b55-b9f8-050824bcaff7 None] Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 400 POST http://127.0.0.1:8774/v2/97b84e38f795456d8c63a64526f8e8b5/servers/94bb0663-1b9e-4098-bedf-9c7d4fc6f8c9/action 0.116s
2014-06-17 19:15:16.103 10882 INFO tempest.common.rest_client [req-fd7aab03-cb8a-44a6-b8e7-aed5ae2f3618 None] Request (AttachInterfacesTestXML:test_add_remove_fixed_ip): 204 DELETE http://127.0.0.1:8774/v2/97b84e38f795456d8c63a64526f8e8b5/servers/94bb0663-1b9e-4098-bedf-9c7d4fc6f8c9 0.320s

doesn't that mean that the create failed, we got an error trying to dump console in the wait error handler, and then a DELETE happened?

I am not denying that there is a race around the call to attach but I don't see this test run as triggering it and don't quite understand exactly where you see a race in the code.

[Joseph Lanoux (joseph-lanoux)]

XML has been removed from Tempest.