failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: BUILD. Current task state: spawning.

[Joshua Harlow]

Running test_reset_network_inject_network_info see a failure where unable to reach ACTIVE state.

http://logs.openstack.org/71/91171/11/gate/gate-tempest-dsvm-full/8cf415d/console.html

2014-05-07 03:33:22.910 | {3} tempest.api.compute.v3.admin.test_servers.ServersAdminV3Test.test_reset_network_inject_network_info [196.920138s] ... FAILED
2014-05-07 03:33:22.910 |
2014-05-07 03:33:22.910 | Captured traceback:
2014-05-07 03:33:22.910 | ~~~~~~~~~~~~~~~~~~~
2014-05-07 03:33:22.910 | Traceback (most recent call last):
2014-05-07 03:33:22.910 | File "tempest/api/compute/v3/admin/test_servers.py", line 170, in test_reset_network_inject_network_info
2014-05-07 03:33:22.910 | resp, server = self.create_test_server(wait_until='ACTIVE')
2014-05-07 03:33:22.910 | File "tempest/api/compute/base.py", line 233, in create_test_server
2014-05-07 03:33:22.910 | raise ex
2014-05-07 03:33:22.910 | TimeoutException: Request timed out
2014-05-07 03:33:22.910 | Details: Server 4491ab2f-2228-4d3f-b364-77d0276c18da failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: BUILD. Current task state: spawning.

[clayg (clay-gerrard)]

So I see a lot of these status timeout messages, and there's a number of bugs open, the most popular of course being:

https://code.launchpad.net/bugs/1254890

How should we be grouping or classifying them? Are they all the same issue? What should we be looking for?

I hit one in 'tempest.api.compute.v3.servers.test_servers.ServersV3Test.test_create_specify_keypair'

... that like this bug report was:

failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: BUILD. Current task state: spawning.

http://logs.openstack.org/85/91685/2/gate/gate-tempest-dsvm-full/c83e2e3/console.html#_2014-05-09_06_34_10_221

I always keep thinking it's a libvirt thing:

http://logs.openstack.org/85/91685/2/gate/gate-tempest-dsvm-full/c83e2e3/logs/libvirtd.txt.gz#_2014-05-09_06_12_09_582

Those errors in libvirt where it says failed to read from the monitor do seem to bubble out as errors in n-cpu:

http://logs.openstack.org/85/91685/2/gate/gate-tempest-dsvm-full/c83e2e3/logs/screen-n-cpu.txt.gz?level=ERROR

What else can we look to?

[Attila Fazekas (afazekas)]

In this case http://logs.openstack.org/32/97532/3/check/check-tempest-dsvm-postgres-full/0ca8157/console.html

It is very likely the https://github.com/openstack/nova/blob/c07626012e35c03da37ea3ed1b5ddf2dea352522/nova/compute/manager.py#L1754 is reached ('Instance spawned successfully', ), but the
https://github.com/openstack/nova/blob/c07626012e35c03da37ea3ed1b5ddf2dea352522/nova/compute/manager.py#L1789 is not.

http://logs.openstack.org/32/97532/3/check/check-tempest-dsvm-postgres-full/0ca8157/logs/screen-n-cpu.txt.gz#_2014-06-10_00_28_03_644
2014-06-10 00:28:03.644 32494 INFO nova.virt.libvirt.driver [-] [instance: f4ef7a2f-641f-463a-a922-009bed8284ed] Instance spawned successfully.
2014-06-10 00:28:03.663 DEBUG nova.compute.manager [req-bb4f648f-4b18-4f0d-9155-584ba7391b02 ServersAdminTestJSON-407950993 ServersAdminTestJSON-821753686] [instance: f4ef7a2f-641f-463a-a922-009bed8284ed] Checking state _get_power_state /opt/stack/new/nova/nova/compute/manager.py:1067

[Dolph Mathews (dolph)]

elastic-recheck query: https://review.openstack.org/#/c/102932/

[Lance Bragstad (lbragstad)]

I've hit this a few times. Here are some logs were we're hitting it in Keystone:

http://logs.openstack.org/84/86484/27/check/check-tempest-dsvm-full/3b0cff8/console.html#_2014-06-25_22_03_45_800

[Joe Gordon (jogo)]

It looks like this may be a libvirt bug, if so I am fairly sure we have a duplicate of this somewhere