test_lock_unlock_server: failed to reach ACTIVE status and task state "None" within the required time

[Dolph Mathews]

 Traceback (most recent call last):
   File "tempest/api/compute/servers/test_server_actions.py", line 419, in test_lock_unlock_server
     self.servers_client.wait_for_server_status(self.server_id, 'ACTIVE')
   File "tempest/services/compute/xml/servers_client.py", line 371, in wait_for_server_status
     raise_on_error=raise_on_error)
   File "tempest/common/waiters.py", line 89, in wait_for_server_status
    raise exceptions.TimeoutException(message)
 TimeoutException: Request timed out
 Details: Server c73d5bba-4f88-4279-8de6-9c66844e72e2 failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: SHUTOFF. Current task state: None.

Source: http://logs.openstack.org/47/70647/3/gate/gate-tempest-dsvm-full/b8607e6/console.html

[Dolph Mathews (dolph)]

logstash query: https://review.openstack.org/#/c/71357/

[Masayuki Igawa (igawa)]

This is similar to this bug:
 Timeout in test_rescued_vm_add_remove_security_group
https://bugs.launchpad.net/tempest/+bug/1255511

[John Garbutt (johngarbutt)]

Looks like a tempest test issue, but marking it as high, as it affects our gate.

[John Garbutt (johngarbutt)]

Similar issue/fix to this one?
https://bugs.launchpad.net/nova/+bug/1277027

[Joe Gordon (jogo)]

This is too vague of a bug, too many things can cause this type of error

[Ken'ichi Ohmichi (oomichi)]

I faced this problem and it is duplicated with 1254872 because of the cause.
The log is http://logs.openstack.org/97/71197/2/gate/gate-tempest-dsvm-full/7498458/logs/

[Attila Fazekas (afazekas)]

http://logs.openstack.org/85/75385/2/gate/gate-tempest-dsvm-postgres-full/2e4c8ff/console.html
 Details: Server c33b2ea4-df9d-491d-bb86-51bfda12536a failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: SUSPENDED. Current task state: None.

Request for resume:
http://logs.openstack.org/85/75385/2/gate/gate-tempest-dsvm-postgres-full/2e4c8ff/console.html#_2014-03-12_23_29_43_452
request id: req-0e7f3ab7-6925-41ba-ba18-3ce06c5d6342

Request reached the n-cpu:
http://logs.openstack.org/85/75385/2/gate/gate-tempest-dsvm-postgres-full/2e4c8ff/logs/screen-n-cpu.txt.gz#_2014-03-12_23_11_06_076
http://logs.openstack.org/85/75385/2/gate/gate-tempest-dsvm-postgres-full/2e4c8ff/logs/screen-n-cpu.txt.gz#_2014-03-12_23_11_06_096

n-cpu frequently forget to finish or report completeness of an actions, regardless to the action. So I do not create new bug with 'resume' action.

[Christian Schwede (cschwede)]

Error line is similar, but this time in create_test_server:

http://logs.openstack.org/56/84456/16/check/check-tempest-dsvm-postgres-full/e2a52ba/console.html

 2014-04-03 07:28:10.681 | ======================================================================
 2014-04-03 07:28:10.681 | FAIL: setUpClass (tempest.api.compute.floating_ips.test_floating_ips_actions_negative.FloatingIPsNegativeTestJSON)
 2014-04-03 07:28:10.681 | setUpClass (tempest.api.compute.floating_ips.test_floating_ips_actions_negative.FloatingIPsNegativeTestJSON)
 2014-04-03 07:28:10.681 | ----------------------------------------------------------------------
 2014-04-03 07:28:10.681 | _StringException: Traceback (most recent call last):
 2014-04-03 07:28:10.681 | File "tempest/api/compute/floating_ips/test_floating_ips_actions_negative.py", line 36, in setUpClass
 2014-04-03 07:28:10.681 | resp, server = cls.create_test_server(wait_until='ACTIVE')
 2014-04-03 07:28:10.681 | File "tempest/api/compute/base.py", line 160, in create_test_server
 2014-04-03 07:28:10.681 | raise ex
 2014-04-03 07:28:10.681 | TimeoutException: Request timed out
 2014-04-03 07:28:10.681 | Details: Server fb667f44-8e02-4dcd-8a38-4dacddbd4f21 failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: BUILD. Current task state: None.

[Ihar Hrachyshka (ihar-hrachyshka)]

Similar failure for tempest.api.compute.v3.servers.test_servers_negative.ServersNegativeV3Test at [1]:

Details: Server 55d88258-9be1-4db6-96f0-753ac501cf48 failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: SUSPENDED. Current task state: resuming.
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base Traceback (most recent call last):
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base File "tempest/api/compute/base.py", line 106, in server_check_teardown
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base 'ACTIVE')
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base File "tempest/services/compute/v3/json/servers_client.py", line 170, in wait_for_server_status
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base raise_on_error=raise_on_error)
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base File "tempest/common/waiters.py", line 89, in wait_for_server_status
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base raise exceptions.TimeoutException(message)
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base TimeoutException: Request timed out
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base Details: Server 55d88258-9be1-4db6-96f0-753ac501cf48 failed to reach ACTIVE status and task state "None" within the required time (196 s). Current status: SUSPENDED. Current task state: resuming.
2014-05-02 23:15:33.477 18339 TRACE tempest.api.compute.base

[1]: https://review.openstack.org/#/c/91067/

[Dolph Mathews (dolph)]

Investigating a recent incident of this, I found the following suspicious lines in libvirtd.txt, but that file is not ingested by logstash, so I can't run investigative queries on it, much less an e-r query.

50:2014-07-12 06:25:07.088+0000: 13236: error : virCommandWait:2399 : internal error: Child process (/usr/lib/libvirt/virt-aa-helper -R -u libvirt-54452dc4-cf93-4299-9fcd-021a204ebd43) unexpected exit status 1: virt-aa-helper: error: profile does not exist
52:2014-07-12 06:25:07.089+0000: 13236: error : AppArmorRestoreSecurityAllLabel:560 : internal error: could not remove profile for 'libvirt-54452dc4-cf93-4299-9fcd-021a204ebd43'
53:2014-07-12 06:25:13.186+0000: 13239: error : virCommandWait:2399 : internal error: Child process (/usr/lib/libvirt/virt-aa-helper -p 0 -c -u libvirt-54452dc4-cf93-4299-9fcd-021a204ebd43) unexpected exit status 1: virt-aa-helper: error: apparmor_parser exited with error
55:2014-07-12 06:25:13.186+0000: 13239: error : AppArmorGenSecurityLabel:451 : internal error: cannot load AppArmor profile 'libvirt-54452dc4-cf93-4299-9fcd-021a204ebd43'

source: logs.openstack.org/43/106543/1/check/check-tempest-dsvm-postgres-full/8abfb25/logs/libvirtd.txt.gz

[David Kranz (david-kranz)]

Searching for

failed to reach ACTIVE status and task state "None"

shows a lot of different bug tickets. This does not seem like a tempest bug.

[Joe Gordon (jogo)]

not seeing any hits for the query message:"Current status: SHUTOFF. Current task state: None." outside of the experimental queue so looks like this isn't an issue anymore.