yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1552622] [NEW] Unexpected API Error in nova quotas update

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Juha Kosonen <juha.kosonen@xxxxxxxxx>
Date: Thu, 03 Mar 2016 09:15:25 -0000
Reply-to: Bug 1552622 <1552622@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

When executing following Rally scenario Quotas.nova_update_and_delete, a
single iteration occasionally fails. Seems to relate to simultaneous
update/delete actions since when the concurrency is set to 1, the
failure doesn't appear.

...
--------------------------------------------------------------------------------
 Preparing input task
--------------------------------------------------------------------------------

Input task is:
{
    "Quotas.nova_update_and_delete": [
        {
            "args": {
                "max_quota": 1024
            },
            "runner": {
                "type": "constant",
                "times": 10,
                "concurrency": 2
            },
            "context": {
                "users": {
                    "tenants": 3,
                    "users_per_tenant": 2
                }
            }
        }
    ]
}

Task syntax is correct :)
2016-03-03 18:19:37.318 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation.
2016-03-03 18:19:37.364 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation of scenarios names.
2016-03-03 18:19:37.367 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation of scenarios names.
2016-03-03 18:19:37.368 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation of syntax.
2016-03-03 18:19:37.373 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation of syntax.
2016-03-03 18:19:37.374 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation of semantic.
2016-03-03 18:19:37.374 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation check cloud.
2016-03-03 18:19:37.592 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation check cloud.
2016-03-03 18:19:37.598 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Enter context: `users`
2016-03-03 18:19:37.953 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Enter context: `users`
2016-03-03 18:19:38.077 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Exit context: `users`
2016-03-03 18:19:39.714 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Exit context: `users`
2016-03-03 18:19:39.715 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation of semantic.
2016-03-03 18:19:39.715 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation.
Task config is valid :)
--------------------------------------------------------------------------------
 Task  0c401631-b728-49b9-90d1-7a5791ba44a2: started
--------------------------------------------------------------------------------

Benchmarking... This can take a while...

To track task status use:

	rally task status
	or
	rally task detailed

Using task: 0c401631-b728-49b9-90d1-7a5791ba44a2
2016-03-03 18:19:39.723 26488 INFO rally.api [-] Benchmark Task 0c401631-b728-49b9-90d1-7a5791ba44a2 on Deployment 1b2cade4-1bce-46db-ac55-339b3f6a8f91
2016-03-03 18:19:39.725 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Benchmarking.
2016-03-03 18:19:39.768 26488 INFO rally.task.engine [-] Running benchmark with key: 
{
  "kw": {
    "runner": {
      "type": "constant", 
      "concurrency": 2, 
      "times": 10
    }, 
    "args": {
      "max_quota": 1024
    }, 
    "context": {
      "users": {
        "users_per_tenant": 2, 
        "tenants": 3
      }
    }
  }, 
  "name": "Quotas.nova_update_and_delete", 
  "pos": 0
}
2016-03-03 18:19:39.774 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Enter context: `users`
2016-03-03 18:19:40.370 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Enter context: `users`
2016-03-03 18:19:40.384 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 0 START
2016-03-03 18:19:40.386 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 1 START
2016-03-03 18:19:40.839 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 1 END: OK
2016-03-03 18:19:40.843 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 2 START
2016-03-03 18:19:40.845 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 0 END: OK
2016-03-03 18:19:40.849 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 3 START
2016-03-03 18:19:41.223 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 2 END: Error ClientException: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
<class 'nova.exception.ProjectQuotaNotFound'> (HTTP 500) (Request-ID: req-89a2a915-e9f0-4a8d-bcbb-45a3d58381d0)
2016-03-03 18:19:41.223 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 3 END: OK
2016-03-03 18:19:41.225 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 5 START
2016-03-03 18:19:41.226 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 4 START
2016-03-03 18:19:41.680 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 4 END: OK
2016-03-03 18:19:41.683 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 6 START
2016-03-03 18:19:41.734 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 5 END: OK
2016-03-03 18:19:41.737 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 7 START
2016-03-03 18:19:42.092 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 6 END: OK
2016-03-03 18:19:42.095 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 8 START
2016-03-03 18:19:42.269 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 7 END: OK
2016-03-03 18:19:42.272 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 9 START
2016-03-03 18:19:42.462 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 8 END: OK
2016-03-03 18:19:42.710 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 9 END: OK
2016-03-03 18:19:42.719 26488 INFO rally.plugins.openstack.context.cleanup [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  admin resources cleanup
2016-03-03 18:19:43.946 26488 INFO rally.plugins.openstack.context.cleanup [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: admin resources cleanup
2016-03-03 18:19:43.946 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Exit context: `users`
2016-03-03 18:19:46.803 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Exit context: `users`
2016-03-03 18:19:47.925 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Benchmarking.

--------------------------------------------------------------------------------
Task 0c401631-b728-49b9-90d1-7a5791ba44a2: finished
--------------------------------------------------------------------------------

test scenario Quotas.nova_update_and_delete
args position 0
args values:
{
  "runner": {
    "type": "constant", 
    "concurrency": 2, 
    "times": 10
  }, 
  "args": {
    "max_quota": 1024
  }, 
  "context": {
    "users": {
      "project_domain": "default", 
      "users_per_tenant": 2, 
      "tenants": 3, 
      "resource_management_workers": 30, 
      "user_domain": "default"
    }
  }
}
+-------------------------------------------------------------------------------------------+
|                                   Response Times (sec)                                    |
+----------------------+-------+--------+--------+--------+-------+-------+---------+-------+
| action               | min   | median | 90%ile | 95%ile | max   | avg   | success | count |
+----------------------+-------+--------+--------+--------+-------+-------+---------+-------+
| quotas.update_quotas | 0.294 | 0.347  | 0.41   | 0.421  | 0.432 | 0.354 | 100.0%  | 10    |
| quotas.delete_quotas | 0.021 | 0.119  | 0.142  | 0.15   | 0.158 | 0.092 | 90.0%   | 10    |
| total                | 0.367 | 0.452  | 0.513  | 0.522  | 0.532 | 0.444 | 90.0%   | 10    |
+----------------------+-------+--------+--------+--------+-------+-------+---------+-------+
Load duration: 2.34418392181
Full duration: 7.03046512604

HINTS:
* To plot HTML graphics with this data, run:
	rally task report 0c401631-b728-49b9-90d1-7a5791ba44a2 --out output.html

* To generate a JUnit report, run:
	rally task report 0c401631-b728-49b9-90d1-7a5791ba44a2 --junit --out output.xml

* To get raw JSON output of task results, run:
	rally task results 0c401631-b728-49b9-90d1-7a5791ba44a2

** Affects: nova
     Importance: Undecided
         Status: New

** Attachment added: "n-api.log"
   https://bugs.launchpad.net/bugs/1552622/+attachment/4587338/+files/n-api.log

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1552622

Title:
  Unexpected API Error in nova quotas update

Status in OpenStack Compute (nova):
  New

Bug description:
  When executing following Rally scenario Quotas.nova_update_and_delete,
  a single iteration occasionally fails. Seems to relate to simultaneous
  update/delete actions since when the concurrency is set to 1, the
  failure doesn't appear.

  ...
  --------------------------------------------------------------------------------
   Preparing input task
  --------------------------------------------------------------------------------

  Input task is:
  {
      "Quotas.nova_update_and_delete": [
          {
              "args": {
                  "max_quota": 1024
              },
              "runner": {
                  "type": "constant",
                  "times": 10,
                  "concurrency": 2
              },
              "context": {
                  "users": {
                      "tenants": 3,
                      "users_per_tenant": 2
                  }
              }
          }
      ]
  }

  Task syntax is correct :)
  2016-03-03 18:19:37.318 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation.
  2016-03-03 18:19:37.364 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation of scenarios names.
  2016-03-03 18:19:37.367 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation of scenarios names.
  2016-03-03 18:19:37.368 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation of syntax.
  2016-03-03 18:19:37.373 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation of syntax.
  2016-03-03 18:19:37.374 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation of semantic.
  2016-03-03 18:19:37.374 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Task validation check cloud.
  2016-03-03 18:19:37.592 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation check cloud.
  2016-03-03 18:19:37.598 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Enter context: `users`
  2016-03-03 18:19:37.953 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Enter context: `users`
  2016-03-03 18:19:38.077 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Exit context: `users`
  2016-03-03 18:19:39.714 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Exit context: `users`
  2016-03-03 18:19:39.715 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation of semantic.
  2016-03-03 18:19:39.715 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Task validation.
  Task config is valid :)
  --------------------------------------------------------------------------------
   Task  0c401631-b728-49b9-90d1-7a5791ba44a2: started
  --------------------------------------------------------------------------------

  Benchmarking... This can take a while...

  To track task status use:

  	rally task status
  	or
  	rally task detailed

  Using task: 0c401631-b728-49b9-90d1-7a5791ba44a2
  2016-03-03 18:19:39.723 26488 INFO rally.api [-] Benchmark Task 0c401631-b728-49b9-90d1-7a5791ba44a2 on Deployment 1b2cade4-1bce-46db-ac55-339b3f6a8f91
  2016-03-03 18:19:39.725 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Benchmarking.
  2016-03-03 18:19:39.768 26488 INFO rally.task.engine [-] Running benchmark with key: 
  {
    "kw": {
      "runner": {
        "type": "constant", 
        "concurrency": 2, 
        "times": 10
      }, 
      "args": {
        "max_quota": 1024
      }, 
      "context": {
        "users": {
          "users_per_tenant": 2, 
          "tenants": 3
        }
      }
    }, 
    "name": "Quotas.nova_update_and_delete", 
    "pos": 0
  }
  2016-03-03 18:19:39.774 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Enter context: `users`
  2016-03-03 18:19:40.370 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Enter context: `users`
  2016-03-03 18:19:40.384 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 0 START
  2016-03-03 18:19:40.386 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 1 START
  2016-03-03 18:19:40.839 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 1 END: OK
  2016-03-03 18:19:40.843 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 2 START
  2016-03-03 18:19:40.845 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 0 END: OK
  2016-03-03 18:19:40.849 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 3 START
  2016-03-03 18:19:41.223 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 2 END: Error ClientException: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
  <class 'nova.exception.ProjectQuotaNotFound'> (HTTP 500) (Request-ID: req-89a2a915-e9f0-4a8d-bcbb-45a3d58381d0)
  2016-03-03 18:19:41.223 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 3 END: OK
  2016-03-03 18:19:41.225 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 5 START
  2016-03-03 18:19:41.226 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 4 START
  2016-03-03 18:19:41.680 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 4 END: OK
  2016-03-03 18:19:41.683 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 6 START
  2016-03-03 18:19:41.734 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 5 END: OK
  2016-03-03 18:19:41.737 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 7 START
  2016-03-03 18:19:42.092 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 6 END: OK
  2016-03-03 18:19:42.095 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 8 START
  2016-03-03 18:19:42.269 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 7 END: OK
  2016-03-03 18:19:42.272 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 9 START
  2016-03-03 18:19:42.462 26693 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 8 END: OK
  2016-03-03 18:19:42.710 26692 INFO rally.task.runner [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | ITER: 9 END: OK
  2016-03-03 18:19:42.719 26488 INFO rally.plugins.openstack.context.cleanup [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  admin resources cleanup
  2016-03-03 18:19:43.946 26488 INFO rally.plugins.openstack.context.cleanup [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: admin resources cleanup
  2016-03-03 18:19:43.946 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Starting:  Exit context: `users`
  2016-03-03 18:19:46.803 26488 INFO rally.plugins.openstack.context.keystone.users [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Exit context: `users`
  2016-03-03 18:19:47.925 26488 INFO rally.task.engine [-] Task 0c401631-b728-49b9-90d1-7a5791ba44a2 | Completed: Benchmarking.

  --------------------------------------------------------------------------------
  Task 0c401631-b728-49b9-90d1-7a5791ba44a2: finished
  --------------------------------------------------------------------------------

  test scenario Quotas.nova_update_and_delete
  args position 0
  args values:
  {
    "runner": {
      "type": "constant", 
      "concurrency": 2, 
      "times": 10
    }, 
    "args": {
      "max_quota": 1024
    }, 
    "context": {
      "users": {
        "project_domain": "default", 
        "users_per_tenant": 2, 
        "tenants": 3, 
        "resource_management_workers": 30, 
        "user_domain": "default"
      }
    }
  }
  +-------------------------------------------------------------------------------------------+
  |                                   Response Times (sec)                                    |
  +----------------------+-------+--------+--------+--------+-------+-------+---------+-------+
  | action               | min   | median | 90%ile | 95%ile | max   | avg   | success | count |
  +----------------------+-------+--------+--------+--------+-------+-------+---------+-------+
  | quotas.update_quotas | 0.294 | 0.347  | 0.41   | 0.421  | 0.432 | 0.354 | 100.0%  | 10    |
  | quotas.delete_quotas | 0.021 | 0.119  | 0.142  | 0.15   | 0.158 | 0.092 | 90.0%   | 10    |
  | total                | 0.367 | 0.452  | 0.513  | 0.522  | 0.532 | 0.444 | 90.0%   | 10    |
  +----------------------+-------+--------+--------+--------+-------+-------+---------+-------+
  Load duration: 2.34418392181
  Full duration: 7.03046512604

  HINTS:
  * To plot HTML graphics with this data, run:
  	rally task report 0c401631-b728-49b9-90d1-7a5791ba44a2 --out output.html

  * To generate a JUnit report, run:
  	rally task report 0c401631-b728-49b9-90d1-7a5791ba44a2 --junit --out output.xml

  * To get raw JSON output of task results, run:
  	rally task results 0c401631-b728-49b9-90d1-7a5791ba44a2

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1552622/+subscriptions