Unexpected API Error in nova quotas update

Bug #1552622 reported by Juha Kosonen on 2016-03-03
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Low
jichenjc

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

Tags: api Edit Tag help
Juha Kosonen (juha-kosonen) wrote :
jichenjc (jichenjc) on 2016-03-03
Changed in nova:
assignee: nobody → jichenjc (jichenjc)
tags: added: api
jichenjc (jichenjc) wrote :

guess this is a rare case due to race condition

2016-03-03 18:19:40.679 INFO nova.osapi_compute.wsgi.server [req-c49d4de4-4dba-44d4-9d8f-b945c806af28 admin admin] 192.168.132.1 "PUT /v2.1/42e2752b7b24407fa051cae30400d5d1/os-quota-sets/861450f94f6c4e22a44faf440e6977c8 HTTP/1.1" status: 200 len: 596 time: 0.1933990

2016-03-03 18:19:40.838 INFO nova.osapi_compute.wsgi.server [req-f13d93c2-f917-4f18-a380-79c194414934 admin admin] 192.168.132.1 "DELETE /v2.1/42e2752b7b24407fa051cae30400d5d1/os-quota-sets/861450f94f6c4e22a44faf440e6977c8 HTTP/1.1" status: 202 len: 272 time: 0.1546450

the original PUT method want to create the limit and it found limit was created then retry with update method
however, delete action was executed during above 2 actions and nova didn't handle it well

set to low because it's a very rare case ..

Changed in nova:
status: New → Confirmed
importance: Undecided → Low

Fix proposed to branch: master
Review: https://review.openstack.org/288153

Changed in nova:
status: Confirmed → In Progress

Change abandoned by Michael Still (<email address hidden>) on branch: master
Review: https://review.openstack.org/288153
Reason: This patch has been sitting unchanged for more than 12 weeks. I am therefore going to abandon it to keep the nova review queue sane. Please feel free to restore the change if you're still working on it.

Change abandoned by jichenjc (<email address hidden>) on branch: master
Review: https://review.openstack.org/288153

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Bug attachments