tempest.scenario test_resize_server_confirm failed in grenade

[ChangBo Guo(gcb)]

Timeout exception was raised :

Traceback (most recent call last):
  File "tempest/scenario/test_server_advanced_ops.py", line 58, in test_resize_server_confirm
    'VERIFY_RESIZE')
  File "tempest/scenario/manager.py", line 304, in status_timeout
    not_found_exception=not_found_exception)
  File "tempest/scenario/manager.py", line 361, in _status_timeout
    raise exceptions.TimeoutException(message)
TimeoutException: Request timed out
Details: Timed out waiting for thing 9dddd676-942e-44aa-9e75-f23e9b163536 to become VERIFY_RESIZE

[ChangBo Guo(gcb) (glongwave)]

This is the log link: http://logs.openstack.org/60/54660/3/gate/gate-grenade-devstack-vm/2cf0c59/testr_results.html.gz

[Joe Gordon (jogo)]

http://logstash.openstack.org/#eyJzZWFyY2giOiJcImZhaWxlZCB0byByZWFjaCBWRVJJRllfUkVTSVpFIHN0YXR1cyB3aXRoaW4gdGhlIHJlcXVpcmVkIHRpbWUgKDE5NiBzKS4gQ3VycmVudCBzdGF0dXM6IEFDVElWRS5cIiBBTkQgZmlsZW5hbWU6XCJjb25zb2xlLmh0bWxcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiYWxsIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTM4NDk4NTM1MjkwMywibW9kZSI6IiIsImFuYWx5emVfZmllbGQiOiIifQ==

"failed to reach VERIFY_RESIZE status within the required time (196 s). Current status: ACTIVE." AND filename:"console.html"

[Matt Riedemann (mriedem)]

Here is the logstash query:

http://logstash.openstack.org/#eyJzZWFyY2giOiJcImZhaWxlZCB0byByZWFjaCBWRVJJRllfUkVTSVpFIHN0YXR1cyB3aXRoaW4gdGhlIHJlcXVpcmVkIHRpbWUgKDE5NiBzKS4gQ3VycmVudCBzdGF0dXM6IEFDVElWRS5cIiBBTkQgZmlsZW5hbWU6XCJjb25zb2xlLmh0bWxcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiYWxsIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTM4NDk4NTM1MjkwMywibW9kZSI6IiIsImFuYWx5emVfZmllbGQiOiIifQ==

Looks like it started showing up in the gate on 11/17. I wanted to think it was this:

https://github.com/openstack/nova/commit/7861cf47b834e1934503d78323b88aca901ac36f

But that merged on the 18th.

[Matt Riedemann (mriedem)]

Joe Gordon has a test patch here: https://review.openstack.org/#/c/57540/

[Joe Gordon (jogo)]

It looks like happens in V3 most of the time, disabling v3 tests fur now

[Joe Gordon (jogo)]

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiIEZpbGUgXFxcInRlbXBlc3QvYXBpL2NvbXB1dGUvdjMvc2VydmVycy90ZXN0X3NlcnZlcl9hY3Rpb25zLnB5XFxcIiwgbGluZSAxNjQsIGluIHRlc3RfcmVzaXplX3NlcnZlcl9jb25maXJtXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6ImFsbCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjEzODQ5ODY1NjY0MDksIm1vZGUiOiIiLCJhbmFseXplX2ZpZWxkIjoiIn0=

[Matt Riedemann (mriedem)]

Tempest turned on v3 testing on 11/16, the day before we started seeing these failures in logstash:

https://github.com/openstack/tempest/commit/e985ca887b2157a0d550e9bcf2137d4114cd77b0

From IRC: (4:38:13 PM) cyeoh: jog0: ok, its possible that the extra level of parallelisation testing that we get by doing V3 is exposing more bugs

[Matt Riedemann (mriedem)]

Attempt at ruling out the v3 tests as the cause of the failure (or contributing to it showing up):

https://review.openstack.org/#/c/57357/

[Joe Gordon (jogo)]

Confirmed that this isn't a v3 only bug, but disabling v3 tests, which were recently added will at least help stabilize gate.

[Joe Gordon (jogo)]

Unrelated to https://review.openstack.org/#/c/56288/, tried a revert to confirm

[Chris Behrens (cbehrens)]

Resize requests go API -> Conductor now (and then to compute after a host is picked). Conductor is querying the scheduler to find a host, but the scheduler is returning 0 hosts... because it doesn't think the only host has enough ram. Conductor is catching NoValidHost and resetting the instance to ACTIVE:

[conductor log]
2013-11-19 00:32:35.978 WARNING nova.scheduler.utils [req-6fadae22-a3de-45ef-bb01-6e292a957559
                     ServerActionsV3TestJSON-tempest-1506209772-user
                     ServerActionsV3TestJSON-tempest-1506209772-tenant] Failed to compute_task_migrate_server: No
                     valid host was found.
2013-11-19 00:32:35.982 WARNING nova.scheduler.utils [req-6fadae22-a3de-45ef-bb01-6e292a957559 ServerActionsV3TestJSON-tempest-1506209772-user ServerActionsV3TestJSON-tempest-1506209772-tenant] [instance: aaff758e-d6a3-4802-b7f9-0a983d1a36a2] Setting instance to ACTIVE state.

[scheduler log]
2013-11-19 00:32:35.969 DEBUG nova.filters [req-6fadae22-a3de-45ef-bb01-6e292a957559 ServerActionsV3TestJSON-tempest-1506209772-user ServerActionsV3TestJSON-tempest-1506209772-tenant] Filter RetryFilter returned 1 host(s) get_filtered_objects /opt/stack/new/nova/nova/filters.py:88
2013-11-19 00:32:35.969 DEBUG nova.filters [req-6fadae22-a3de-45ef-bb01-6e292a957559 ServerActionsV3TestJSON-tempest-1506209772-user ServerActionsV3TestJSON-tempest-1506209772-tenant] Filter AvailabilityZoneFilter returned 1 host(s) get_filtered_objects /opt/stack/new/nova/nova/filters.py:88
2013-11-19 00:32:35.970 DEBUG nova.scheduler.filters.ram_filter [req-6fadae22-a3de-45ef-bb01-6e292a957559 ServerActionsV3TestJSON-tempest-1506209772-user ServerActionsV3TestJSON-tempest-1506209772-tenant] (devstack-precise-hpcloud-az3-675414, devstack-precise-hpcloud-az3-675414) ram:-2254 disk:205824 io_ops:0 instances:7 does not have 2048 MB usable ram, it only has 1739.0 MB usable ram. host_passes /opt/stack/new/nova/nova/scheduler/filters/ram_filter.py:60
2013-11-19 00:32:35.970 INFO nova.filters [req-6fadae22-a3de-45ef-bb01-6e292a957559 ServerActionsV3TestJSON-tempest-1506209772-user ServerActionsV3TestJSON-tempest-1506209772-tenant] Filter RamFilter returned 0 hosts
2013-11-19 00:32:35.970 DEBUG nova.openstack.common.rpc.amqp [req-6fadae22-a3de-45ef-bb01-6e292a957559 ServerActionsV3TestJSON-tempest-1506209772-user ServerActionsV3TestJSON-tempest-1506209772-tenant] Expected exception during message handling (No valid host was found. ) _process_data /opt/stack/new/nova/nova/openstack/common/rpc/amqp.py:472

^^^

[Joe Gordon (jogo)]

We are seeing this in grenade because it is trying to resize up to a tiny instance which is too big. Also we are running grenade in parallel now, which makes this worse.

[Christopher Yeoh (cyeoh-0)]

From: http://logs.openstack.org/77/55077/3/gate/gate-grenade-devstack-vm/a3ace3b/logs/new/screen-n-api.txt.gz

We are attempting to resize from tiny to small

2013-11-19 16:59:00.660 DEBUG nova.compute.api [req-de6871ef-87e7-49d3-98dc-a5352a7dc85f ServerActionsV3TestJSON-tempest-681486203-user ServerActionsV3TestJSON-tempest-681486203-tenant] [instance: 180b7d2c-c4a7-4aaa-bd3b-09f6548731bf] Old instance type m1.tiny, new instance type m1.small resize /opt/stack/new/nova/nova/compute/api.py:22852013-11-19 16:59:00.660 DEBUG nova.compute.api [req-de6871ef-87e7-49d3-98dc-a5352a7dc85f ServerActionsV3TestJSON-tempest-681486203-user ServerActionsV3TestJSON-tempest-681486203-tenant] [instance: 180b7d2c-c4a7-4aaa-bd3b-09f6548731bf] Old instance type m1.tiny, new instance type m1.small resize /opt/stack/new/nova/nova/compute/api.py:2285

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/57357
Committed: http://github.com/openstack/tempest/commit/277d3785d02e547f9866c1973a610a3a25d2e194
Submitter: Jenkins
Branch: master

commit 277d3785d02e547f9866c1973a610a3a25d2e194
Author: Joe Gordon <email address hidden>
Date: Tue Nov 19 18:55:42 2013 -0800

    Disable V3 tests

    Partial-Bug: #1252170

    We are seeing bug 1252170 happen in the v3 tests a lot. Its uncleari f
    this is V3 issue or another issue, but disabling these tests is a short
    term measure to get the gate working again.

    Change-Id: Ia79efa2618f4dc8cad8ae23e2ba462f22a4263f3

[Joe Gordon (jogo)]

Fixed in grenade: https://review.openstack.org/#/c/57572/