OpenStack Compute (nova)

Unexpected API Error in nova quotas update

Bug #1552622 reported by Juha Kosonen
22
This bug affects 5 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Confirmed
Low
Unassigned

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
Revision history for this message
Juha Kosonen (juha-kosonen) wrote :
jichenjc (jichenjc)
Changed in nova:
assignee: nobody → jichenjc (jichenjc)
tags: added: api
Revision history for this message
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
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

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

Changed in nova:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on nova (master)

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.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote :

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

Revision history for this message
Sean Dague (sdague) wrote :

There are no currently open reviews on this bug, changing the status back to the previous state and unassigning. If there are active reviews related to this bug, please include links in comments.

Changed in nova:
status: In Progress → Confirmed
assignee: jichenjc (jichenjc) → nobody
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.