[Bug 1581171] Re: cinder at master amulet test often fails the pause action test

Thu May 12 20:24:39 UTC 2016

In another reproduction (with additional timestamp debug bits added to
the test) of this errored pause test, here is some interesting timing
info:

## Timestamps from tests
2016-05-12 20:11:24,131 test_910_pause_and_resume DEBUG: Checking pause and resume actions...
2016-05-12 20:11:24,134 test_910_pause_and_resume INFO: Waiting on extended status checks...
2016-05-12 20:11:24,135 _auto_wait_for_status INFO: Waiting for extended status on units...
2016-05-12 20:11:24,137 _auto_wait_for_status DEBUG: Default extended status wait match:  contains READY (case-insensitive)
2016-05-12 20:11:24,137 _auto_wait_for_status DEBUG: Excluding services from extended status match: ['mysql']
2016-05-12 20:11:24,138 _auto_wait_for_status DEBUG: Waiting up to 1800s for extended status on services: ['cinder', 'glance', 'keystone', 'rabbitmq-server']
2016-05-12 20:11:24,727 _auto_wait_for_status INFO: OK
2016-05-12 20:11:24,728 test_910_pause_and_resume DEBUG: Unit name: cinder/6
2016-05-12 20:11:24,729 test_910_pause_and_resume DEBUG: Checking for active status on cinder/6
2016-05-12 20:11:38,170 test_910_pause_and_resume DEBUG: Running pause action on cinder/6
Running command: juju action do --format=json cinder/6 pause

2016-05-12 20:11:38,998 test_910_pause_and_resume DEBUG: Waiting on action 1f3e7042-bbb7-4025-82d8-1ca3f6254653
Traceback (most recent call last):
  File "/tmp/bundletester-V7qqmq/cinder/tests/gate-basic-trusty-liberty", line 11, in <module>
    deployment.run_tests()
  File "/tmp/bundletester-V7qqmq/cinder/tests/charmhelpers/contrib/amulet/deployment.py", line 95, in run_tests
    getattr(self, test)()
  File "/tmp/bundletester-V7qqmq/cinder/tests/basic_deployment.py", line 780, in test_910_pause_and_resume
    "Pause action failed at {}".format(datetime.datetime.now())
AssertionError: Pause action failed at 2016-05-12 20:11:49.244020

## SIGTERM Timestamps from cinder logs
ubuntu at juju-beis0-machine-31:/var/log/cinder$ grep SIG *
cinder-api.log:2016-05-12 20:03:07.062 14524 INFO oslo_service.service [-] Caught SIGTERM, stopping children
cinder-api.log:2016-05-12 20:12:21.951 32034 INFO oslo_service.service [-] Caught SIGTERM, stopping children
cinder-scheduler.log:2016-05-12 20:03:07.454 14576 INFO oslo_service.service [req-42bbdc02-be8c-437c-a087-5006710eef11 - - - - -] Caught SIGTERM, exiting
cinder-scheduler.log:2016-05-12 20:12:22.396 32089 INFO oslo_service.service [req-70ae4130-3d76-46a9-98a6-91a14fa47afa - - - - -] Caught SIGTERM, exiting
cinder-volume.log:2016-05-12 20:03:07.216 14630 INFO oslo_service.service [req-9f77de11-e5a6-42d5-a436-7cb2c900fd29 - - - - -] Caught SIGTERM, stopping children
cinder-volume.log:2016-05-12 20:12:22.118 32058 INFO oslo_service.service [req-c43b791d-e062-4148-b23c-5cdfe55ebb79 - - - - -] Caught SIGTERM, stopping children

ubuntu at juju-beis0-machine-31:/var/log$ ps aux | grep cinder
root      3396  0.2  1.5 349744 24344 ?        Ssl  20:01   0:02 /var/lib/juju/tools/unit-cinder-6/jujud unit --data-dir /var/lib/juju --unit-name cinder/6 --debug
ubuntu    4517  0.0  0.0  10460   936 pts/0    S+   20:21   0:00 grep --color=auto cinder
ubuntu at juju-beis0-machine-31:/var/log$ ps aux | grep oslo
ubuntu    4519  0.0  0.0  10460   932 pts/0    S+   20:21   0:00 grep --color=auto oslo

## To summarize:
20:11:38  Test issues pause action
20:11:49  Test declares failure (based on juju action fetch returning non-zero)
20:12:22  Services are stopped

** Summary changed:

- cinder at master trusty-mitaka amulet test often fails the pause action test
+ cinder at master amulet test often fails the pause action test

** Description changed:

- cinder at master trusty-mitaka amulet test often fails the pause action
- test
+ cinder at master amulet test often fails the pause action test
+ 
+ Observed and reproduced on trusty-liberty, trusty-mitaka test combos.

  ## Unit status
- cinder/0          blocked        idle        1.25.5  1                10.5.1.105     Services should be paused but these services running: cinder-api, cinder-volume, cinder-scheduler, Paused. Use 'resume' action to resume normal service. 
+ cinder/0          blocked        idle        1.25.5  1                10.5.1.105     Services should be paused but these services running: cinder-api, cinder-volume, cinder-scheduler, Paused. Use 'resume' action to resume normal service.

  ## Amulet failure (trusty-mitaka, cinder at master 2016 May 12)
  2016-05-12 18:11:56,004 test_910_pause_and_resume DEBUG: Checking pause and resume actions...
  Running command: juju action do --format=json cinder/0 pause

  Traceback (most recent call last):
-   File "/tmp/bundletester-QVbeQC/cinder/tests/gate-basic-trusty-mitaka", line 11, in <module>
-     deployment.run_tests()
-   File "/tmp/bundletester-QVbeQC/cinder/tests/charmhelpers/contrib/amulet/deployment.py", line 95, in run_tests
-     getattr(self, test)()
-   File "/tmp/bundletester-QVbeQC/cinder/tests/basic_deployment.py", line 773, in test_910_pause_and_resume
-     assert self._wait_on_action(action_id), "Pause action failed."
+   File "/tmp/bundletester-QVbeQC/cinder/tests/gate-basic-trusty-mitaka", line 11, in <module>
+     deployment.run_tests()
+   File "/tmp/bundletester-QVbeQC/cinder/tests/charmhelpers/contrib/amulet/deployment.py", line 95, in run_tests
+     getattr(self, test)()
+   File "/tmp/bundletester-QVbeQC/cinder/tests/basic_deployment.py", line 773, in test_910_pause_and_resume
+     assert self._wait_on_action(action_id), "Pause action failed."
  AssertionError: Pause action failed.

  PASS: 1 ERROR: 1 Total: 2 (869.865811 sec)

  ## Juju status
  http://pastebin.ubuntu.com/16380414/

-- 
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to cinder in Juju Charms Collection.
Matching subscriptions: charm-bugs
https://bugs.launchpad.net/bugs/1581171

Title:
  cinder at master amulet test often fails the pause action test

Status in cinder package in Juju Charms Collection:
  New

Bug description:
  cinder at master amulet test often fails the pause action test

  Observed and reproduced on trusty-liberty, trusty-mitaka test combos.

  ## Unit status
  cinder/0          blocked        idle        1.25.5  1                10.5.1.105     Services should be paused but these services running: cinder-api, cinder-volume, cinder-scheduler, Paused. Use 'resume' action to resume normal service.

  ## Amulet failure (trusty-mitaka, cinder at master 2016 May 12)
  2016-05-12 18:11:56,004 test_910_pause_and_resume DEBUG: Checking pause and resume actions...
  Running command: juju action do --format=json cinder/0 pause

  Traceback (most recent call last):
    File "/tmp/bundletester-QVbeQC/cinder/tests/gate-basic-trusty-mitaka", line 11, in <module>
      deployment.run_tests()
    File "/tmp/bundletester-QVbeQC/cinder/tests/charmhelpers/contrib/amulet/deployment.py", line 95, in run_tests
      getattr(self, test)()
    File "/tmp/bundletester-QVbeQC/cinder/tests/basic_deployment.py", line 773, in test_910_pause_and_resume
      assert self._wait_on_action(action_id), "Pause action failed."
  AssertionError: Pause action failed.

  PASS: 1 ERROR: 1 Total: 2 (869.865811 sec)

  ## Juju status
  http://pastebin.ubuntu.com/16380414/

To manage notifications about this bug go to:
https://bugs.launchpad.net/charms/+source/cinder/+bug/1581171/+subscriptions