2020-04-20 21:41:22.708 7 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:41:22.709 7 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:41:22.709 7 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils [-] Unexpected exception in CLI: rally.exceptions.DBRecordNotFound: Record for uuid or name is opnfv-rally not found in table envs
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils Traceback (most recent call last):
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/cli/cliutils.py", line 657, in run
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     ret = fn(*fn_args, **fn_kwargs)
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "<decorator-gen-16>", line 2, in destroy
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/cli/envutils.py", line 135, in default_from_global
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     return f(*args, **kwargs)
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "<decorator-gen-15>", line 2, in destroy
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/plugins/__init__.py", line 59, in ensure_plugins_are_loaded
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     return f(*args, **kwargs)
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/cli/commands/deployment.py", line 154, in destroy
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     api.deployment.destroy(deployment=deployment)
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/api.py", line 115, in destroy
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     deploy = objects.Deployment.get(deployment)
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/common/objects/deploy.py", line 124, in get
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     return Deployment(env_mgr.EnvManager.get(deploy))
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/env/env_mgr.py", line 212, in get
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     return cls(db.env_get(uuid_or_name))
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/common/db/api.py", line 133, in wrapper
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     result = f(session, *args, **kwargs)
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils   File "/usr/lib/python3.8/site-packages/rally/common/db/api.py", line 518, in env_get
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils     raise exceptions.DBRecordNotFound(
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils rally.exceptions.DBRecordNotFound: Record for uuid or name is opnfv-rally not found in table envs
2020-04-20 21:41:24.085 7 ERROR rally.cli.cliutils 
2020-04-20 21:41:25.299 9 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:41:25.299 9 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:41:25.299 9 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:41:28.216 11 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:41:28.217 11 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:41:28.217 11 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:41:31.518 14 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:41:31.518 14 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:41:31.519 14 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:41:32.832 17 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:41:32.832 17 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:41:32.832 17 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:41:34.314 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Starting:  Task validation.
2020-04-20 21:41:34.326 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Starting:  Task validation of syntax.
2020-04-20 21:41:34.371 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Completed: Task validation of syntax.
2020-04-20 21:41:34.371 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Starting:  Task validation of required platforms.
2020-04-20 21:41:34.399 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Completed: Task validation of required platforms.
2020-04-20 21:41:34.399 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Starting:  Task validation of semantic.
2020-04-20 21:41:34.399 17 INFO rally.task.engine [-] Check health of the environment 'c0ed3a33-627c-4a9a-a8b3-617044cdac07'.
2020-04-20 21:41:34.799 17 INFO rally.task.engine [-] Platform existing@openstack (available: True): OK!
2020-04-20 21:41:34.810 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 1 tenants using 1 threads
2020-04-20 21:41:35.191 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 1 users using 1 threads
2020-04-20 21:41:35.812 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack setup()  finished in 1.00 sec
2020-04-20 21:41:35.844 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() started
2020-04-20 21:41:37.825 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() finished in 1.98 sec
2020-04-20 21:41:37.826 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Completed: Task validation of semantic.
2020-04-20 21:41:37.826 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Completed: Task validation.
2020-04-20 21:41:37.826 17 INFO rally.api [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 input file is valid.
2020-04-20 21:41:37.827 17 INFO rally.api [-] Run Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 against Deployment c0ed3a33-627c-4a9a-a8b3-617044cdac07
2020-04-20 21:41:37.827 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Starting:  Running task.
2020-04-20 21:41:37.875 17 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=bb58f5b3-7f73-4d48-b460-0e2a308a788d)",
   "subtasks": [
      {
         "title": "Authenticate.keystone",
         "description": "Check Keystone Client.",
         "scenario": {
            "Authenticate.keystone": {}
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:41:37.891 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:41:38.305 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:41:39.107 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack setup()  finished in 1.22 sec
2020-04-20 21:41:39.115 17 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 1ef694a3-38ba-4f6e-91ae-83fca7433568).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:41:39.126 72 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.Keystone'>
	method_name: run
	args: {}
2020-04-20 21:41:39.128 73 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.Keystone'>
	method_name: run
	args: {}
2020-04-20 21:41:39.130 74 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.Keystone'>
	method_name: run
	args: {}
2020-04-20 21:41:39.131 72 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 START
2020-04-20 21:41:39.133 73 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 START
2020-04-20 21:41:39.133 75 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.Keystone'>
	method_name: run
	args: {}
2020-04-20 21:41:39.135 74 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 START
2020-04-20 21:41:39.138 75 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 START
2020-04-20 21:41:39.338 74 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 END: OK
2020-04-20 21:41:39.341 74 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 START
2020-04-20 21:41:39.344 73 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 END: OK
2020-04-20 21:41:39.348 73 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 START
2020-04-20 21:41:39.349 75 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 END: OK
2020-04-20 21:41:39.354 75 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 START
2020-04-20 21:41:39.425 72 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 END: OK
2020-04-20 21:41:39.429 72 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 START
2020-04-20 21:41:39.466 74 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 END: OK
2020-04-20 21:41:39.469 74 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 START
2020-04-20 21:41:39.550 72 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 END: OK
2020-04-20 21:41:39.551 75 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 END: OK
2020-04-20 21:41:39.553 72 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 START
2020-04-20 21:41:39.562 73 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 END: OK
2020-04-20 21:41:39.580 74 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 END: OK
2020-04-20 21:41:39.668 72 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 END: OK
2020-04-20 21:41:39.691 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() started
2020-04-20 21:41:42.169 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() finished in 2.48 sec
2020-04-20 21:41:43.939 17 INFO rally.task.engine [-] Load duration is: 0.53587
2020-04-20 21:41:43.940 17 INFO rally.task.engine [-] Full runner duration is: 0.576602
2020-04-20 21:41:43.940 17 INFO rally.task.engine [-] Full duration is: 4.27925
2020-04-20 21:41:44.022 17 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=19b03353-5f35-4c25-80c0-3432055f99c2)",
   "subtasks": [
      {
         "title": "Authenticate.validate_cinder",
         "description": "Check Cinder Client to ensure validation of token.",
         "scenario": {
            "Authenticate.validate_cinder": {
               "repetitions": 2
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:41:44.039 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:41:44.521 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:41:45.236 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack setup()  finished in 1.20 sec
2020-04-20 21:41:45.245 17 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 1ef694a3-38ba-4f6e-91ae-83fca7433568).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:41:45.255 145 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateCinder'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:45.257 146 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateCinder'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:45.260 147 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateCinder'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:45.260 145 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 START
2020-04-20 21:41:45.262 146 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 START
2020-04-20 21:41:45.262 148 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateCinder'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:45.265 147 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 START
2020-04-20 21:41:45.267 148 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 START
2020-04-20 21:41:45.606 145 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 END: OK
2020-04-20 21:41:45.610 145 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 START
2020-04-20 21:41:45.612 147 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 END: OK
2020-04-20 21:41:45.617 147 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 START
2020-04-20 21:41:45.618 148 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 END: OK
2020-04-20 21:41:45.622 148 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 START
2020-04-20 21:41:45.651 146 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 END: OK
2020-04-20 21:41:45.655 146 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 START
2020-04-20 21:41:45.816 145 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 END: OK
2020-04-20 21:41:45.819 145 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 START
2020-04-20 21:41:45.889 148 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 END: OK
2020-04-20 21:41:45.889 146 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 END: OK
2020-04-20 21:41:45.891 148 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 START
2020-04-20 21:41:45.893 147 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 END: OK
2020-04-20 21:41:46.048 148 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 END: OK
2020-04-20 21:41:46.053 145 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 END: OK
2020-04-20 21:41:46.079 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() started
2020-04-20 21:41:51.189 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() finished in 5.11 sec
2020-04-20 21:41:52.109 17 INFO rally.task.engine [-] Load duration is: 0.791692
2020-04-20 21:41:52.109 17 INFO rally.task.engine [-] Full runner duration is: 0.834132
2020-04-20 21:41:52.110 17 INFO rally.task.engine [-] Full duration is: 7.151396
2020-04-20 21:41:52.194 17 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=5b527087-23f0-4f1b-b95f-3246327e0a59)",
   "subtasks": [
      {
         "title": "Authenticate.validate_glance",
         "description": "Check Glance Client to ensure validation of token.",
         "scenario": {
            "Authenticate.validate_glance": {
               "repetitions": 2
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:41:52.214 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:41:52.724 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:41:53.572 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack setup()  finished in 1.36 sec
2020-04-20 21:41:53.579 17 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 1ef694a3-38ba-4f6e-91ae-83fca7433568).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:41:53.590 218 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateGlance'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:53.592 219 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateGlance'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:53.595 220 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateGlance'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:53.596 218 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 START
2020-04-20 21:41:53.598 219 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 START
2020-04-20 21:41:53.597 221 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateGlance'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:53.601 220 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 START
2020-04-20 21:41:53.603 221 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 START
2020-04-20 21:41:53.961 220 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 END: OK
2020-04-20 21:41:53.965 218 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 END: OK
2020-04-20 21:41:53.966 220 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 START
2020-04-20 21:41:53.970 218 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 START
2020-04-20 21:41:53.979 219 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 END: OK
2020-04-20 21:41:53.983 221 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 END: OK
2020-04-20 21:41:53.984 219 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 START
2020-04-20 21:41:53.987 221 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 START
2020-04-20 21:41:54.207 218 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 END: OK
2020-04-20 21:41:54.211 218 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 START
2020-04-20 21:41:54.240 221 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 END: OK
2020-04-20 21:41:54.243 221 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 START
2020-04-20 21:41:54.273 220 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 END: OK
2020-04-20 21:41:54.326 219 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 END: OK
2020-04-20 21:41:54.538 221 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 END: OK
2020-04-20 21:41:54.565 218 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 END: OK
2020-04-20 21:41:54.589 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() started
2020-04-20 21:41:57.930 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() finished in 3.34 sec
2020-04-20 21:41:58.266 17 INFO rally.task.engine [-] Load duration is: 0.967236
2020-04-20 21:41:58.267 17 INFO rally.task.engine [-] Full runner duration is: 1.010151
2020-04-20 21:41:58.267 17 INFO rally.task.engine [-] Full duration is: 5.716532
2020-04-20 21:41:58.356 17 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=d7167409-4d76-41f9-a4c4-c817a512efb7)",
   "subtasks": [
      {
         "title": "Authenticate.validate_heat",
         "description": "Check Heat Client to ensure validation of token.",
         "scenario": {
            "Authenticate.validate_heat": {
               "repetitions": 2
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:41:58.379 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:41:58.793 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:41:59.694 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack setup()  finished in 1.31 sec
2020-04-20 21:41:59.701 17 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 1ef694a3-38ba-4f6e-91ae-83fca7433568).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:41:59.711 291 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateHeat'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:59.714 292 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateHeat'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:59.716 293 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateHeat'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:59.716 291 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 START
2020-04-20 21:41:59.718 294 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateHeat'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:41:59.720 292 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 START
2020-04-20 21:41:59.720 293 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 START
2020-04-20 21:41:59.723 294 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 START
2020-04-20 21:42:00.129 291 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 END: OK
2020-04-20 21:42:00.133 291 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 START
2020-04-20 21:42:00.136 293 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 END: OK
2020-04-20 21:42:00.138 292 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 END: OK
2020-04-20 21:42:00.138 294 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 END: OK
2020-04-20 21:42:00.141 293 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 START
2020-04-20 21:42:00.142 294 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 START
2020-04-20 21:42:00.142 292 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 START
2020-04-20 21:42:00.310 293 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 END: OK
2020-04-20 21:42:00.313 293 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 START
2020-04-20 21:42:00.322 292 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 END: OK
2020-04-20 21:42:00.323 294 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 END: OK
2020-04-20 21:42:00.326 292 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 START
2020-04-20 21:42:00.456 291 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 END: OK
2020-04-20 21:42:00.525 293 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 END: OK
2020-04-20 21:42:00.587 292 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 END: OK
2020-04-20 21:42:00.607 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() started
2020-04-20 21:42:04.397 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() finished in 3.79 sec
2020-04-20 21:42:04.505 17 INFO rally.task.engine [-] Load duration is: 0.86913
2020-04-20 21:42:04.506 17 INFO rally.task.engine [-] Full runner duration is: 0.905875
2020-04-20 21:42:04.506 17 INFO rally.task.engine [-] Full duration is: 6.019452
2020-04-20 21:42:04.588 17 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=714aeda3-20ed-4b68-896f-e01b26355667)",
   "subtasks": [
      {
         "title": "Authenticate.validate_neutron",
         "description": "Check Neutron Client to ensure validation of token.",
         "scenario": {
            "Authenticate.validate_neutron": {
               "repetitions": 2
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:42:04.604 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:42:05.012 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:42:05.674 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack setup()  finished in 1.07 sec
2020-04-20 21:42:05.682 17 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 1ef694a3-38ba-4f6e-91ae-83fca7433568).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:42:05.690 364 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNeutron'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:05.694 365 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNeutron'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:05.695 364 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 START
2020-04-20 21:42:05.695 366 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNeutron'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:05.697 367 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNeutron'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:05.699 365 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 START
2020-04-20 21:42:05.700 366 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 START
2020-04-20 21:42:05.702 367 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 START
2020-04-20 21:42:06.295 367 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 END: OK
2020-04-20 21:42:06.299 367 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 START
2020-04-20 21:42:06.479 365 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 END: OK
2020-04-20 21:42:06.483 365 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 START
2020-04-20 21:42:06.490 366 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 END: OK
2020-04-20 21:42:06.494 366 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 START
2020-04-20 21:42:06.769 367 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 END: OK
2020-04-20 21:42:06.774 367 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 START
2020-04-20 21:42:07.145 364 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 END: OK
2020-04-20 21:42:07.149 364 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 START
2020-04-20 21:42:07.174 366 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 END: OK
2020-04-20 21:42:07.178 366 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 START
2020-04-20 21:42:07.198 365 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 END: OK
2020-04-20 21:42:07.519 367 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 END: OK
2020-04-20 21:42:07.712 364 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 END: OK
2020-04-20 21:42:07.721 366 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 END: OK
2020-04-20 21:42:07.741 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() started
2020-04-20 21:42:10.725 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() finished in 2.98 sec
2020-04-20 21:42:12.665 17 INFO rally.task.engine [-] Load duration is: 2.024463
2020-04-20 21:42:12.665 17 INFO rally.task.engine [-] Full runner duration is: 2.059586
2020-04-20 21:42:12.665 17 INFO rally.task.engine [-] Full duration is: 6.1213
2020-04-20 21:42:12.748 17 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=a2f03996-eab9-4ad8-a836-f182379b39d4)",
   "subtasks": [
      {
         "title": "Authenticate.validate_nova",
         "description": "Check Nova Client to ensure validation of token.",
         "scenario": {
            "Authenticate.validate_nova": {
               "repetitions": 2
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:42:12.763 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:42:13.235 17 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:42:14.058 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack setup()  finished in 1.30 sec
2020-04-20 21:42:14.066 17 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 1ef694a3-38ba-4f6e-91ae-83fca7433568).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:42:14.075 437 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNova'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:14.077 438 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNova'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:14.079 439 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNova'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:14.081 437 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 START
2020-04-20 21:42:14.081 440 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.authenticate.authenticate.ValidateNova'>
	method_name: run
	args: {"repetitions": 2}
2020-04-20 21:42:14.082 438 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 START
2020-04-20 21:42:14.084 439 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 START
2020-04-20 21:42:14.086 440 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 START
2020-04-20 21:42:14.494 438 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 2 END: OK
2020-04-20 21:42:14.498 438 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 START
2020-04-20 21:42:14.525 439 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 3 END: OK
2020-04-20 21:42:14.529 439 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 START
2020-04-20 21:42:14.538 437 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 1 END: OK
2020-04-20 21:42:14.542 437 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 START
2020-04-20 21:42:14.548 440 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 4 END: OK
2020-04-20 21:42:14.552 440 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 START
2020-04-20 21:42:14.693 438 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 5 END: OK
2020-04-20 21:42:14.697 438 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 START
2020-04-20 21:42:14.711 439 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 6 END: OK
2020-04-20 21:42:14.715 439 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 START
2020-04-20 21:42:14.738 440 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 8 END: OK
2020-04-20 21:42:14.785 437 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 7 END: OK
2020-04-20 21:42:14.911 439 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 10 END: OK
2020-04-20 21:42:14.974 438 INFO rally.task.runner [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | ITER: 9 END: OK
2020-04-20 21:42:15.002 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() started
2020-04-20 21:42:17.761 17 INFO rally.task.context [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Context users@openstack cleanup() finished in 2.76 sec
2020-04-20 21:42:18.809 17 INFO rally.task.engine [-] Load duration is: 0.891513
2020-04-20 21:42:18.809 17 INFO rally.task.engine [-] Full runner duration is: 0.936305
2020-04-20 21:42:18.810 17 INFO rally.task.engine [-] Full duration is: 4.99921
2020-04-20 21:42:18.888 17 INFO rally.task.engine [-] Task 1ef694a3-38ba-4f6e-91ae-83fca7433568 | Completed: Running task.
2020-04-20 21:42:20.356 499 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:42:20.357 499 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:42:20.357 499 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:42:21.607 501 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:42:21.608 501 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:42:21.608 501 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:42:22.842 503 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:42:22.843 503 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:42:22.843 503 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:42:24.392 503 INFO rally.api [-] Building 'json' report for the following task(s): '1ef694a3-38ba-4f6e-91ae-83fca7433568'.
2020-04-20 21:42:24.399 503 INFO rally.api [-] The report has been successfully built.
2020-04-20 21:42:25.601 505 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:42:25.601 505 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:42:25.601 505 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:42:27.262 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Starting:  Task validation.
2020-04-20 21:42:27.276 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Starting:  Task validation of syntax.
2020-04-20 21:42:27.369 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Completed: Task validation of syntax.
2020-04-20 21:42:27.370 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Starting:  Task validation of required platforms.
2020-04-20 21:42:27.416 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Completed: Task validation of required platforms.
2020-04-20 21:42:27.416 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Starting:  Task validation of semantic.
2020-04-20 21:42:27.416 505 INFO rally.task.engine [-] Check health of the environment 'c0ed3a33-627c-4a9a-a8b3-617044cdac07'.
2020-04-20 21:42:27.866 505 INFO rally.task.engine [-] Platform existing@openstack (available: True): OK!
2020-04-20 21:42:27.874 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 1 tenants using 1 threads
2020-04-20 21:42:28.188 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 1 users using 1 threads
2020-04-20 21:42:28.739 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 0.86 sec
2020-04-20 21:42:29.681 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:42:30.882 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 1.20 sec
2020-04-20 21:42:30.882 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Completed: Task validation of semantic.
2020-04-20 21:42:30.882 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Completed: Task validation.
2020-04-20 21:42:30.883 505 INFO rally.api [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 input file is valid.
2020-04-20 21:42:30.883 505 INFO rally.api [-] Run Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 against Deployment c0ed3a33-627c-4a9a-a8b3-617044cdac07
2020-04-20 21:42:30.883 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Starting:  Running task.
2020-04-20 21:42:30.934 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=b1d29a4b-f527-4b9f-b7ee-735cf25eb282)",
   "subtasks": [
      {
         "title": "GlanceImages.create_and_delete_image",
         "description": "Create and then delete an image.",
         "scenario": {
            "GlanceImages.create_and_delete_image": {
               "container_format": "bare",
               "disk_format": "qcow2",
               "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:42:30.949 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:42:31.401 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:42:32.209 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.26 sec
2020-04-20 21:42:32.209 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack setup()  finished in 0.00 msec
2020-04-20 21:42:32.217 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:42:32.227 560 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeleteImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:32.229 561 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeleteImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:32.231 560 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:42:32.231 562 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeleteImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:32.234 563 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeleteImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:32.234 561 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:42:32.235 562 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:42:32.240 563 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:42:34.700 562 RALLYDEBUG rally.task.utils [-] Waiting for resource '4de41c15-be2e-4ed6-bc09-dfdf2baeace9'. Status changed: NONE => QUEUED in 0.041414499282836914
2020-04-20 21:42:34.700 561 RALLYDEBUG rally.task.utils [-] Waiting for resource '032783d0-0fa2-4703-a3e7-6f89afd6bad4'. Status changed: NONE => QUEUED in 0.04527449607849121
2020-04-20 21:42:34.821 563 RALLYDEBUG rally.task.utils [-] Waiting for resource 'ff6d41e6-32a9-4c76-ac3b-f9e12c94afe5'. Status changed: NONE => QUEUED in 0.04360222816467285
2020-04-20 21:42:34.913 560 RALLYDEBUG rally.task.utils [-] Waiting for resource 'c2d6a540-d8e3-4298-bfd2-aac21f141079'. Status changed: NONE => QUEUED in 0.038475751876831055
2020-04-20 21:42:35.250 561 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_pAOmF70q. Status changed: QUEUED => ACTIVE in 0.024296045303344727
2020-04-20 21:42:35.262 562 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_otcG2L07. Status changed: QUEUED => ACTIVE in 0.022606849670410156
2020-04-20 21:42:35.276 563 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_zFVT1CJ8. Status changed: QUEUED => ACTIVE in 0.028193235397338867
2020-04-20 21:42:35.313 560 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_kVwqRiUW. Status changed: QUEUED => ACTIVE in 0.024806976318359375
2020-04-20 21:42:35.499 561 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:42:35.503 561 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:42:35.533 562 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:42:35.536 562 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:42:35.540 563 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:42:35.544 563 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:42:35.574 560 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:42:35.578 560 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:42:37.838 561 RALLYDEBUG rally.task.utils [-] Waiting for resource '01045be5-0e20-4a13-8e9f-7f08ddb128e8'. Status changed: NONE => QUEUED in 0.044895172119140625
2020-04-20 21:42:37.861 563 RALLYDEBUG rally.task.utils [-] Waiting for resource '6e553927-cc59-40e3-8fb6-5afde3302205'. Status changed: NONE => QUEUED in 0.03939056396484375
2020-04-20 21:42:37.900 560 RALLYDEBUG rally.task.utils [-] Waiting for resource '5328f7b6-ce5a-4b2b-a3d2-53ee891855e7'. Status changed: NONE => QUEUED in 0.03916525840759277
2020-04-20 21:42:37.962 562 RALLYDEBUG rally.task.utils [-] Waiting for resource 'b9700658-c0de-47ea-8059-f54bb433c352'. Status changed: NONE => QUEUED in 0.034461259841918945
2020-04-20 21:42:38.334 561 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_wCGjJ9aP. Status changed: QUEUED => ACTIVE in 0.024346590042114258
2020-04-20 21:42:38.345 563 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_FTXWPtwm. Status changed: QUEUED => ACTIVE in 0.020452022552490234
2020-04-20 21:42:38.369 560 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_uUB79H7Q. Status changed: QUEUED => ACTIVE in 0.029921770095825195
2020-04-20 21:42:38.392 562 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_NBh2QHl9. Status changed: QUEUED => ACTIVE in 0.02616405487060547
2020-04-20 21:42:38.600 561 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:42:38.602 561 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:42:38.609 563 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:42:38.612 563 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:42:38.650 560 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:42:38.683 562 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:42:40.909 563 RALLYDEBUG rally.task.utils [-] Waiting for resource 'dccf5611-f843-4ba8-b123-24224a1d1ae6'. Status changed: NONE => QUEUED in 0.040018320083618164
2020-04-20 21:42:40.986 561 RALLYDEBUG rally.task.utils [-] Waiting for resource 'ce374ce8-5b3c-43e4-9b54-a1315b2b71aa'. Status changed: NONE => QUEUED in 0.04151153564453125
2020-04-20 21:42:41.347 563 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_Eabm8M6p. Status changed: QUEUED => ACTIVE in 0.0278928279876709
2020-04-20 21:42:41.408 561 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_b1d29a4b_kSkj20O2. Status changed: QUEUED => ACTIVE in 0.029759883880615234
2020-04-20 21:42:41.616 563 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:42:41.643 561 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:42:41.666 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() started
2020-04-20 21:42:41.670 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up glance images objects
2020-04-20 21:42:42.414 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() finished in 0.75 sec
2020-04-20 21:42:42.414 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:42:48.646 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 6.23 sec
2020-04-20 21:42:49.046 505 INFO rally.task.engine [-] Load duration is: 9.204885
2020-04-20 21:42:49.047 505 INFO rally.task.engine [-] Full runner duration is: 9.448585
2020-04-20 21:42:49.047 505 INFO rally.task.engine [-] Full duration is: 17.698241
2020-04-20 21:42:49.127 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=5f08f283-aa5f-455e-b406-eb71901a9c1f)",
   "subtasks": [
      {
         "title": "GlanceImages.create_and_list_image",
         "description": "Create an image and then list all images.",
         "scenario": {
            "GlanceImages.create_and_list_image": {
               "container_format": "bare",
               "disk_format": "qcow2",
               "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:42:49.138 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:42:49.563 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:42:50.456 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.32 sec
2020-04-20 21:42:50.457 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack setup()  finished in 0.01 msec
2020-04-20 21:42:50.469 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:42:50.479 653 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndListImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:50.480 654 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndListImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:50.482 655 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndListImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:50.484 656 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndListImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:42:50.486 654 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:42:50.486 653 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:42:50.488 655 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:42:50.489 656 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:42:52.917 654 RALLYDEBUG rally.task.utils [-] Waiting for resource 'd90bbad1-f0ee-4bd1-a278-30553417f4d8'. Status changed: NONE => QUEUED in 0.0415494441986084
2020-04-20 21:42:52.926 653 RALLYDEBUG rally.task.utils [-] Waiting for resource '334bfb7c-0dd2-428e-8c7a-c3b147edf7bd'. Status changed: NONE => QUEUED in 0.04098629951477051
2020-04-20 21:42:52.935 656 RALLYDEBUG rally.task.utils [-] Waiting for resource '1435d711-b506-445e-82b1-17aa8bf954a0'. Status changed: NONE => QUEUED in 0.040918827056884766
2020-04-20 21:42:52.949 655 RALLYDEBUG rally.task.utils [-] Waiting for resource 'fe954468-7cda-4d0c-b7d3-3409d0a46df9'. Status changed: NONE => QUEUED in 0.04773569107055664
2020-04-20 21:42:53.556 654 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_iGSh30xI. Status changed: QUEUED => ACTIVE in 0.02267765998840332
2020-04-20 21:42:53.566 653 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_crQqoMDQ. Status changed: QUEUED => ACTIVE in 0.02565741539001465
2020-04-20 21:42:53.570 655 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_u76UFsiM. Status changed: QUEUED => ACTIVE in 0.028041362762451172
2020-04-20 21:42:53.573 656 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_u0pyi8FP. Status changed: QUEUED => ACTIVE in 0.02803969383239746
2020-04-20 21:42:53.602 654 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:42:53.606 654 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:42:53.619 655 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:42:53.620 653 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:42:53.623 655 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:42:53.625 653 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:42:53.628 656 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:42:53.631 656 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:42:56.073 656 RALLYDEBUG rally.task.utils [-] Waiting for resource 'd0b6e802-8efb-49b6-b02d-3190731b76aa'. Status changed: NONE => QUEUED in 0.04560708999633789
2020-04-20 21:42:56.096 654 RALLYDEBUG rally.task.utils [-] Waiting for resource '2581ffa6-32a4-41ff-8948-53c443a8d29a'. Status changed: NONE => QUEUED in 0.040129661560058594
2020-04-20 21:42:56.098 653 RALLYDEBUG rally.task.utils [-] Waiting for resource 'cc2b84b0-555f-4b63-94a5-ccff5199a231'. Status changed: NONE => QUEUED in 0.06011533737182617
2020-04-20 21:42:56.184 655 RALLYDEBUG rally.task.utils [-] Waiting for resource '6fb958d8-97ed-43c0-b467-19bd7c03085b'. Status changed: NONE => QUEUED in 0.0376279354095459
2020-04-20 21:42:56.667 655 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_y0JlPXrK. Status changed: QUEUED => ACTIVE in 0.01981806755065918
2020-04-20 21:42:56.684 653 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_q3L427wZ. Status changed: QUEUED => ACTIVE in 0.028294086456298828
2020-04-20 21:42:56.691 654 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_HRPL34GX. Status changed: QUEUED => ACTIVE in 0.024236202239990234
2020-04-20 21:42:56.699 656 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_QLf9wjpH. Status changed: QUEUED => ACTIVE in 0.02442646026611328
2020-04-20 21:42:56.718 655 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:42:56.721 655 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:42:56.747 653 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:42:56.750 653 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:42:56.759 654 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:42:56.764 656 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:42:59.132 655 RALLYDEBUG rally.task.utils [-] Waiting for resource 'b3a458d0-91c8-4dfc-a4a4-14a3c7fd486c'. Status changed: NONE => QUEUED in 0.03843832015991211
2020-04-20 21:42:59.221 653 RALLYDEBUG rally.task.utils [-] Waiting for resource '238d9cd3-3474-46c8-9425-8ea09d32efff'. Status changed: NONE => QUEUED in 0.039737701416015625
2020-04-20 21:42:59.603 655 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_q9BEoZXz. Status changed: QUEUED => ACTIVE in 0.02418684959411621
2020-04-20 21:42:59.661 653 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_5f08f283_BCWGScKq. Status changed: QUEUED => ACTIVE in 0.02857518196105957
2020-04-20 21:42:59.666 655 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:42:59.747 653 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:42:59.773 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() started
2020-04-20 21:42:59.782 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up glance images objects
2020-04-20 21:43:00.492 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_q3L427wZ (cc2b84b0-555f-4b63-94a5-ccff5199a231)
2020-04-20 21:43:00.492 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_QLf9wjpH (d0b6e802-8efb-49b6-b02d-3190731b76aa)
2020-04-20 21:43:00.493 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_q9BEoZXz (b3a458d0-91c8-4dfc-a4a4-14a3c7fd486c)
2020-04-20 21:43:00.501 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_crQqoMDQ (334bfb7c-0dd2-428e-8c7a-c3b147edf7bd)
2020-04-20 21:43:00.508 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_BCWGScKq (238d9cd3-3474-46c8-9425-8ea09d32efff)
2020-04-20 21:43:00.527 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_y0JlPXrK (6fb958d8-97ed-43c0-b467-19bd7c03085b)
2020-04-20 21:43:00.532 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_u76UFsiM (fe954468-7cda-4d0c-b7d3-3409d0a46df9)
2020-04-20 21:43:00.541 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_u0pyi8FP (1435d711-b506-445e-82b1-17aa8bf954a0)
2020-04-20 21:43:00.547 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_HRPL34GX (2581ffa6-32a4-41ff-8948-53c443a8d29a)
2020-04-20 21:43:00.553 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_5f08f283_iGSh30xI (d90bbad1-f0ee-4bd1-a278-30553417f4d8)
2020-04-20 21:43:00.977 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.003 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.015 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.018 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.057 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.058 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.060 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.065 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.077 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.078 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.080 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.081 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.086 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.100 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.105 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.107 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.114 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.116 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.120 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:01.122 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:43:02.125 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() finished in 2.35 sec
2020-04-20 21:43:02.126 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:43:05.262 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 3.14 sec
2020-04-20 21:43:07.230 505 INFO rally.task.engine [-] Load duration is: 9.083578
2020-04-20 21:43:07.230 505 INFO rally.task.engine [-] Full runner duration is: 9.304949
2020-04-20 21:43:07.231 505 INFO rally.task.engine [-] Full duration is: 16.124624
2020-04-20 21:43:07.311 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=bcd6d48a-ea19-4287-a486-dab398b8ae0f)",
   "subtasks": [
      {
         "title": "GlanceImages.list_images",
         "description": "List all images.",
         "scenario": {
            "GlanceImages.list_images": {}
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:43:07.325 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:43:07.778 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:43:08.578 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.25 sec
2020-04-20 21:43:08.587 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:43:08.600 746 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.ListImages'>
	method_name: run
	args: {}
2020-04-20 21:43:08.604 746 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:43:08.604 747 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.ListImages'>
	method_name: run
	args: {}
2020-04-20 21:43:08.607 748 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.ListImages'>
	method_name: run
	args: {}
2020-04-20 21:43:08.609 747 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:43:08.611 751 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.ListImages'>
	method_name: run
	args: {}
2020-04-20 21:43:08.613 748 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:43:08.616 751 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:43:08.979 748 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:43:08.982 748 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:43:08.995 746 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:43:08.999 746 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:43:09.006 751 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:43:09.011 751 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:43:09.163 747 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:43:09.166 747 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:43:09.225 746 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:43:09.229 746 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:43:09.270 748 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:43:09.274 748 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:43:09.282 751 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:43:09.406 747 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:43:09.453 746 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:43:09.509 748 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:43:09.536 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:43:13.144 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 3.61 sec
2020-04-20 21:43:13.371 505 INFO rally.task.engine [-] Load duration is: 0.72689
2020-04-20 21:43:13.371 505 INFO rally.task.engine [-] Full runner duration is: 0.948855
2020-04-20 21:43:13.371 505 INFO rally.task.engine [-] Full duration is: 5.819733
2020-04-20 21:43:13.453 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=0a8e6191-53ca-48b4-be50-b9f840674b27)",
   "subtasks": [
      {
         "title": "GlanceImages.create_image_and_boot_instances",
         "description": "Create an image and boot several instances from it.",
         "scenario": {
            "GlanceImages.create_image_and_boot_instances": {
               "container_format": "bare",
               "disk_format": "qcow2",
               "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img",
               "flavor": {
                  "name": "rally_full-flavor_f4478be8-a962-4178-b739-ae67f4f2966c"
               },
               "number_instances": 2,
               "boot_server_kwargs": {
                  "nics": [
                     {
                        "net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"
                     }
                  ]
               }
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            },
            "quotas": {
               "nova": {
                  "cores": -1,
                  "floating_ips": -1,
                  "instances": -1,
                  "ram": -1,
                  "security_group_rules": -1,
                  "security_groups": -1
               }
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:43:13.467 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:43:13.907 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:43:14.654 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.19 sec
2020-04-20 21:43:15.528 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context quotas@openstack setup()  finished in 0.87 sec
2020-04-20 21:43:15.528 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack setup()  finished in 0.01 msec
2020-04-20 21:43:15.688 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:43:15.698 819 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateImageAndBootInstances'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img", "flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "number_instances": 2, "boot_server_kwargs": {"nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}}
2020-04-20 21:43:15.703 820 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateImageAndBootInstances'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img", "flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "number_instances": 2, "boot_server_kwargs": {"nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}}
2020-04-20 21:43:15.704 819 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:43:15.706 821 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateImageAndBootInstances'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img", "flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "number_instances": 2, "boot_server_kwargs": {"nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}}
2020-04-20 21:43:15.708 820 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:43:15.708 824 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateImageAndBootInstances'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img", "flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "number_instances": 2, "boot_server_kwargs": {"nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}}
2020-04-20 21:43:15.711 821 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:43:15.716 824 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:43:18.149 820 RALLYDEBUG rally.task.utils [-] Waiting for resource 'dda71579-475e-4453-8f73-2fc151684523'. Status changed: NONE => QUEUED in 0.042176008224487305
2020-04-20 21:43:18.154 821 RALLYDEBUG rally.task.utils [-] Waiting for resource '256fd6ff-bcd4-4cd1-a75f-d6cbd6741f76'. Status changed: NONE => QUEUED in 0.041242361068725586
2020-04-20 21:43:18.161 819 RALLYDEBUG rally.task.utils [-] Waiting for resource '49f28d83-f1b4-4f61-96d0-373223c20073'. Status changed: NONE => QUEUED in 0.04168868064880371
2020-04-20 21:43:18.167 824 RALLYDEBUG rally.task.utils [-] Waiting for resource '0cec08bb-05d1-446d-8b16-a201fb9acc09'. Status changed: NONE => QUEUED in 0.04022502899169922
2020-04-20 21:43:18.775 820 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_6ixvIEKA. Status changed: QUEUED => ACTIVE in 0.0264132022857666
2020-04-20 21:43:18.786 824 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_hrtNIBUb. Status changed: QUEUED => ACTIVE in 0.02577352523803711
2020-04-20 21:43:18.786 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_zFqF92vm. Status changed: QUEUED => ACTIVE in 0.030417203903198242
2020-04-20 21:43:18.792 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_GmA96o7u. Status changed: QUEUED => ACTIVE in 0.030211687088012695
2020-04-20 21:43:28.722 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_j4bJu662_1. Status changed: BUILD => ACTIVE in 7.220791578292847
2020-04-20 21:43:30.029 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_j4bJu662_0. Status changed: BUILD => ACTIVE in 1.306253433227539
2020-04-20 21:43:30.029 821 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:43:30.033 821 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:43:32.291 824 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_D5WjVbD4_1. Status changed: BUILD => ACTIVE in 10.734145402908325
2020-04-20 21:43:32.424 821 RALLYDEBUG rally.task.utils [-] Waiting for resource '09f394c1-6419-4ea8-a619-9b9b3c7f37e8'. Status changed: NONE => QUEUED in 0.03092479705810547
2020-04-20 21:43:32.519 824 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_D5WjVbD4_0. Status changed: BUILD => ACTIVE in 0.22736096382141113
2020-04-20 21:43:32.520 824 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:43:32.523 824 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:43:32.808 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_rzvBpRrB. Status changed: QUEUED => ACTIVE in 0.020784616470336914
2020-04-20 21:43:33.622 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_Gw7evIeF_1. Status changed: BUILD => ACTIVE in 10.567842960357666
2020-04-20 21:43:33.983 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_Gw7evIeF_0. Status changed: BUILD => ACTIVE in 0.36032795906066895
2020-04-20 21:43:33.983 819 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:43:33.986 819 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:43:34.781 824 RALLYDEBUG rally.task.utils [-] Waiting for resource 'ad0a3f46-3697-4029-8e07-2712d4b7c12e'. Status changed: NONE => QUEUED in 0.030157804489135742
2020-04-20 21:43:35.211 824 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_QdhELrxj. Status changed: QUEUED => ACTIVE in 0.028168916702270508
2020-04-20 21:43:35.418 820 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_Lwtd9rrG_1. Status changed: BUILD => ACTIVE in 12.896250009536743
2020-04-20 21:43:36.036 820 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_Lwtd9rrG_0. Status changed: BUILD => ACTIVE in 0.6170828342437744
2020-04-20 21:43:36.037 820 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:43:36.041 820 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:43:36.389 819 RALLYDEBUG rally.task.utils [-] Waiting for resource '81614b28-8b12-47c0-9f59-94ffa75b9182'. Status changed: NONE => QUEUED in 0.03757739067077637
2020-04-20 21:43:36.791 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_f3sx5LC5. Status changed: QUEUED => ACTIVE in 0.025426149368286133
2020-04-20 21:43:38.329 820 RALLYDEBUG rally.task.utils [-] Waiting for resource '544d28ee-561c-4a53-95e2-0757f7266156'. Status changed: NONE => QUEUED in 0.035794973373413086
2020-04-20 21:43:38.713 820 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_mQoH2CVT. Status changed: QUEUED => ACTIVE in 0.02056407928466797
2020-04-20 21:43:43.494 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_PSsnd1UL_1. Status changed: BUILD => ACTIVE in 7.0603063106536865
2020-04-20 21:43:43.779 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_PSsnd1UL_0. Status changed: BUILD => ACTIVE in 0.28416013717651367
2020-04-20 21:43:43.781 821 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:43:43.787 821 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:43:46.263 821 RALLYDEBUG rally.task.utils [-] Waiting for resource '0827c251-034c-4ff5-ac2f-7d81af9141c9'. Status changed: NONE => QUEUED in 0.037229299545288086
2020-04-20 21:43:46.909 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_sOfZsViH. Status changed: QUEUED => ACTIVE in 0.02932453155517578
2020-04-20 21:43:47.087 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_c74vnALd_1. Status changed: BUILD => ACTIVE in 7.794224500656128
2020-04-20 21:43:47.405 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_c74vnALd_0. Status changed: BUILD => ACTIVE in 0.3155243396759033
2020-04-20 21:43:47.405 819 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:43:47.411 819 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:43:48.014 824 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_bcFuPehN_1. Status changed: BUILD => ACTIVE in 8.990647077560425
2020-04-20 21:43:48.304 824 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_bcFuPehN_0. Status changed: BUILD => ACTIVE in 0.2891886234283447
2020-04-20 21:43:48.305 824 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:43:49.876 819 RALLYDEBUG rally.task.utils [-] Waiting for resource '57d7bdf2-66f9-49e4-b34c-0223100c210f'. Status changed: NONE => QUEUED in 0.04154014587402344
2020-04-20 21:43:50.388 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_IoE4sDKD. Status changed: QUEUED => ACTIVE in 0.026901960372924805
2020-04-20 21:43:50.509 820 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_xdq142eb_1. Status changed: BUILD => ACTIVE in 8.873086929321289
2020-04-20 21:43:52.030 820 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_xdq142eb_0. Status changed: BUILD => ACTIVE in 1.5197076797485352
2020-04-20 21:43:52.031 820 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:44:00.408 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_oBnUXh1h_1. Status changed: BUILD => ACTIVE in 10.616344690322876
2020-04-20 21:44:01.948 821 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_oBnUXh1h_0. Status changed: BUILD => ACTIVE in 1.5385327339172363
2020-04-20 21:44:01.948 821 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:44:02.748 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_WECPIy1Y_1. Status changed: BUILD => ACTIVE in 7.453617095947266
2020-04-20 21:44:03.030 819 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0a8e6191_WECPIy1Y_0. Status changed: BUILD => ACTIVE in 0.2810637950897217
2020-04-20 21:44:03.031 819 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:44:03.062 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() started
2020-04-20 21:44:03.069 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up nova servers objects
2020-04-20 21:44:05.516 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_xdq142eb_0 (5537aaf5-2444-4ee3-8547-f267947440f6)
2020-04-20 21:44:05.521 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_xdq142eb_1 (b0a92622-cc75-49ea-8fed-e183ae70368b)
2020-04-20 21:44:05.529 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_Gw7evIeF_1 (fe588885-2419-4dfd-83d9-00cfbab6584b)
2020-04-20 21:44:05.534 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_Gw7evIeF_0 (0fefd943-2eb2-4c5f-b5d8-16d356749356)
2020-04-20 21:44:05.544 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_Lwtd9rrG_1 (7615e203-c503-4acb-99ae-ca7f2242e92e)
2020-04-20 21:44:05.561 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_D5WjVbD4_1 (8029c424-c3b0-4797-b787-5ac9d5715ef8)
2020-04-20 21:44:05.569 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_Lwtd9rrG_0 (960f1f9d-cd22-4e30-a3e6-b77c25584891)
2020-04-20 21:44:05.577 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_D5WjVbD4_0 (a7de1e57-d28c-4cf0-a92f-39877830a6bd)
2020-04-20 21:44:05.581 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_WECPIy1Y_1 (4a0a88f6-d718-4ddf-b063-513f5e8aa04a)
2020-04-20 21:44:05.591 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_WECPIy1Y_0 (65c13a01-08d0-4d5e-acce-882fe165f602)
2020-04-20 21:44:05.603 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_oBnUXh1h_1 (6d137ea4-bbb7-4f4f-8f48-0bc17afb50a1)
2020-04-20 21:44:05.610 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_oBnUXh1h_0 (a5ec9a6b-0f66-4f20-a3a4-ee8bcb2525ac)
2020-04-20 21:44:05.619 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_bcFuPehN_1 (4d6c2fd3-7e11-47b7-901b-8055a1088723)
2020-04-20 21:44:05.645 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_bcFuPehN_0 (1c6638c4-6f56-49b7-bcf0-44d8be905a93)
2020-04-20 21:44:05.657 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_PSsnd1UL_1 (ea3bfd3c-e699-48da-8b68-b598b6e96e1a)
2020-04-20 21:44:05.662 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_PSsnd1UL_0 (e6d03713-b30e-413f-9e6f-3fc6e74abb9d)
2020-04-20 21:44:05.677 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_j4bJu662_1 (33965da7-343b-4933-aed7-66ea2dbc6ecc)
2020-04-20 21:44:05.699 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_j4bJu662_0 (a393d2ee-132e-42fb-a5c7-7dc65ad332a9)
2020-04-20 21:44:05.740 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_c74vnALd_0 (4c398bbc-55a3-4542-8ee9-e608ddd2209e)
2020-04-20 21:44:05.761 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting nova.servers object s_rally_0a8e6191_c74vnALd_1 (f768b9c7-7e42-4ac8-8d52-5cdf5d308b80)
2020-04-20 21:44:16.017 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up nova server_groups objects
2020-04-20 21:44:16.702 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up nova keypairs objects
2020-04-20 21:44:17.686 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up glance images objects
2020-04-20 21:44:18.625 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_mQoH2CVT (544d28ee-561c-4a53-95e2-0757f7266156)
2020-04-20 21:44:18.629 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_6ixvIEKA (dda71579-475e-4453-8f73-2fc151684523)
2020-04-20 21:44:18.638 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_GmA96o7u (49f28d83-f1b4-4f61-96d0-373223c20073)
2020-04-20 21:44:18.651 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_hrtNIBUb (0cec08bb-05d1-446d-8b16-a201fb9acc09)
2020-04-20 21:44:18.657 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_IoE4sDKD (57d7bdf2-66f9-49e4-b34c-0223100c210f)
2020-04-20 21:44:18.666 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_sOfZsViH (0827c251-034c-4ff5-ac2f-7d81af9141c9)
2020-04-20 21:44:18.671 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_QdhELrxj (ad0a3f46-3697-4029-8e07-2712d4b7c12e)
2020-04-20 21:44:18.675 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_rzvBpRrB (09f394c1-6419-4ea8-a619-9b9b3c7f37e8)
2020-04-20 21:44:18.681 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_zFqF92vm (256fd6ff-bcd4-4cd1-a75f-d6cbd6741f76)
2020-04-20 21:44:18.689 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0a8e6191_f3sx5LC5 (81614b28-8b12-47c0-9f59-94ffa75b9182)
2020-04-20 21:44:19.280 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.302 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.332 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.348 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.352 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.372 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.389 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.410 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.418 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.438 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.447 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.457 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.458 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.471 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.484 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.503 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.510 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.525 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.528 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:19.548 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:20.552 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() finished in 17.49 sec
2020-04-20 21:44:20.553 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context quotas@openstack cleanup() started
2020-04-20 21:44:20.644 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context quotas@openstack cleanup() finished in 91.57 msec
2020-04-20 21:44:20.645 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:44:22.671 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 2.03 sec
2020-04-20 21:44:23.880 505 INFO rally.task.engine [-] Load duration is: 46.131632
2020-04-20 21:44:23.880 505 INFO rally.task.engine [-] Full runner duration is: 47.373955
2020-04-20 21:44:23.881 505 INFO rally.task.engine [-] Full duration is: 69.205112
2020-04-20 21:44:23.968 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=efc0d381-9e84-4e6f-babe-610b7504e7ca)",
   "subtasks": [
      {
         "title": "GlanceImages.create_and_deactivate_image",
         "description": "Create an image, then deactivate it.",
         "scenario": {
            "GlanceImages.create_and_deactivate_image": {
               "container_format": "bare",
               "disk_format": "qcow2",
               "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:44:23.990 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:44:24.435 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:44:25.238 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.25 sec
2020-04-20 21:44:25.238 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack setup()  finished in 0.02 msec
2020-04-20 21:44:25.246 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:44:25.255 972 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeactivateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:25.257 973 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeactivateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:25.260 974 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeactivateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:25.261 972 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:44:25.263 973 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:44:25.262 975 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDeactivateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:25.265 974 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:44:25.268 975 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:44:27.675 974 RALLYDEBUG rally.task.utils [-] Waiting for resource '78c4873f-d105-4af9-8732-6e56ed4b8f33'. Status changed: NONE => QUEUED in 0.0392148494720459
2020-04-20 21:44:27.677 973 RALLYDEBUG rally.task.utils [-] Waiting for resource 'b3269c18-6038-40cb-b4f6-c82b7c2f54e5'. Status changed: NONE => QUEUED in 0.04115486145019531
2020-04-20 21:44:27.714 975 RALLYDEBUG rally.task.utils [-] Waiting for resource '921cb3a4-b486-4271-bf03-48f3dc208bc1'. Status changed: NONE => QUEUED in 0.038489341735839844
2020-04-20 21:44:27.715 972 RALLYDEBUG rally.task.utils [-] Waiting for resource '3e950c88-f811-4651-8216-35e5c1c518a6'. Status changed: NONE => QUEUED in 0.03724503517150879
2020-04-20 21:44:28.286 975 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_2ZYIiYYc. Status changed: QUEUED => ACTIVE in 0.02688765525817871
2020-04-20 21:44:28.293 973 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_sqD33Gq9. Status changed: QUEUED => ACTIVE in 0.027576208114624023
2020-04-20 21:44:28.295 972 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_utmBigw0. Status changed: QUEUED => ACTIVE in 0.023081541061401367
2020-04-20 21:44:28.308 974 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_ELj4wqiR. Status changed: QUEUED => ACTIVE in 0.02672743797302246
2020-04-20 21:44:28.355 975 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:44:28.358 975 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:44:28.364 973 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:44:28.367 973 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:44:28.378 972 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:44:28.379 974 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:44:28.381 972 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:44:28.382 974 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:44:30.653 973 RALLYDEBUG rally.task.utils [-] Waiting for resource '4311942b-2cbf-4728-afcb-500a6efe50b7'. Status changed: NONE => QUEUED in 0.052355051040649414
2020-04-20 21:44:30.732 975 RALLYDEBUG rally.task.utils [-] Waiting for resource 'c19eaa96-79b6-408d-be16-bd282cb64f82'. Status changed: NONE => QUEUED in 0.037954092025756836
2020-04-20 21:44:30.748 974 RALLYDEBUG rally.task.utils [-] Waiting for resource '6c2e8ddb-b8a9-424c-8c9e-27775ede6ba0'. Status changed: NONE => QUEUED in 0.040699005126953125
2020-04-20 21:44:30.883 972 RALLYDEBUG rally.task.utils [-] Waiting for resource '808c09ba-f75f-4ef3-af23-92247d2b3d04'. Status changed: NONE => QUEUED in 0.0369415283203125
2020-04-20 21:44:31.067 973 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_oofUbZrI. Status changed: QUEUED => ACTIVE in 0.0224759578704834
2020-04-20 21:44:31.140 973 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:44:31.143 973 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:44:31.183 974 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_Mbalui5k. Status changed: QUEUED => ACTIVE in 0.02617502212524414
2020-04-20 21:44:31.200 975 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_stjuo4hh. Status changed: QUEUED => ACTIVE in 0.0258026123046875
2020-04-20 21:44:31.260 974 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:44:31.263 974 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:44:31.266 975 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:44:31.303 972 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_fow7uJkc. Status changed: QUEUED => ACTIVE in 0.026166915893554688
2020-04-20 21:44:31.362 972 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:44:33.433 973 RALLYDEBUG rally.task.utils [-] Waiting for resource '1ac5f005-e8c9-4a78-add3-6f64038af6ed'. Status changed: NONE => QUEUED in 0.038358211517333984
2020-04-20 21:44:33.581 974 RALLYDEBUG rally.task.utils [-] Waiting for resource '89a6cae2-d8d3-47f0-8525-145d7004d674'. Status changed: NONE => QUEUED in 0.04694318771362305
2020-04-20 21:44:33.858 973 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_jRMNZ9OT. Status changed: QUEUED => ACTIVE in 0.02462148666381836
2020-04-20 21:44:33.931 973 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:44:34.010 974 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_efc0d381_FXS51Qpc. Status changed: QUEUED => ACTIVE in 0.02417135238647461
2020-04-20 21:44:34.088 974 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:44:34.112 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() started
2020-04-20 21:44:34.116 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up glance images objects
2020-04-20 21:44:34.887 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_jRMNZ9OT (1ac5f005-e8c9-4a78-add3-6f64038af6ed)
2020-04-20 21:44:34.891 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_fow7uJkc (808c09ba-f75f-4ef3-af23-92247d2b3d04)
2020-04-20 21:44:34.904 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_sqD33Gq9 (b3269c18-6038-40cb-b4f6-c82b7c2f54e5)
2020-04-20 21:44:34.913 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_ELj4wqiR (78c4873f-d105-4af9-8732-6e56ed4b8f33)
2020-04-20 21:44:34.923 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_FXS51Qpc (89a6cae2-d8d3-47f0-8525-145d7004d674)
2020-04-20 21:44:34.933 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_utmBigw0 (3e950c88-f811-4651-8216-35e5c1c518a6)
2020-04-20 21:44:34.948 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_stjuo4hh (c19eaa96-79b6-408d-be16-bd282cb64f82)
2020-04-20 21:44:34.971 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_Mbalui5k (6c2e8ddb-b8a9-424c-8c9e-27775ede6ba0)
2020-04-20 21:44:34.983 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_oofUbZrI (4311942b-2cbf-4728-afcb-500a6efe50b7)
2020-04-20 21:44:34.994 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_efc0d381_2ZYIiYYc (921cb3a4-b486-4271-bf03-48f3dc208bc1)
2020-04-20 21:44:35.445 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.468 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.489 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.513 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.515 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.552 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.561 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.562 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.568 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.573 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.575 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.584 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.586 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.591 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.602 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.603 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.606 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.613 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.614 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:35.623 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:36.627 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() finished in 2.51 sec
2020-04-20 21:44:36.627 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:44:40.646 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 4.02 sec
2020-04-20 21:44:42.091 505 INFO rally.task.engine [-] Load duration is: 8.668476
2020-04-20 21:44:42.091 505 INFO rally.task.engine [-] Full runner duration is: 8.866103
2020-04-20 21:44:42.091 505 INFO rally.task.engine [-] Full duration is: 16.657054
2020-04-20 21:44:42.172 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=32cd3bb7-594b-40a9-a0c7-c5882707045f)",
   "subtasks": [
      {
         "title": "GlanceImages.create_and_download_image",
         "description": "Create an image, then download data of the image.",
         "scenario": {
            "GlanceImages.create_and_download_image": {
               "container_format": "bare",
               "disk_format": "qcow2",
               "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:44:42.187 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:44:42.613 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:44:43.350 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.16 sec
2020-04-20 21:44:43.351 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack setup()  finished in 0.01 msec
2020-04-20 21:44:43.359 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:44:43.369 1065 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDownloadImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:43.372 1066 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDownloadImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:43.374 1067 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDownloadImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:43.375 1065 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:44:43.377 1066 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:44:43.377 1067 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:44:43.377 1068 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndDownloadImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:44:43.382 1068 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:44:45.805 1068 RALLYDEBUG rally.task.utils [-] Waiting for resource 'cdcf5fde-3b45-488f-aae7-c42d055a1779'. Status changed: NONE => QUEUED in 0.041741371154785156
2020-04-20 21:44:45.807 1067 RALLYDEBUG rally.task.utils [-] Waiting for resource '37919fc7-6b65-465c-826e-652cb3068794'. Status changed: NONE => QUEUED in 0.04337930679321289
2020-04-20 21:44:45.810 1065 RALLYDEBUG rally.task.utils [-] Waiting for resource '9a4018d4-5555-4a65-93b8-f8ebb20c8f72'. Status changed: NONE => QUEUED in 0.03883194923400879
2020-04-20 21:44:45.830 1066 RALLYDEBUG rally.task.utils [-] Waiting for resource 'b65b86d1-d0b0-4065-b167-c6e875531093'. Status changed: NONE => QUEUED in 0.041838645935058594
2020-04-20 21:44:46.419 1067 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_Hub51fz1. Status changed: QUEUED => ACTIVE in 0.021475553512573242
2020-04-20 21:44:46.435 1065 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_snkgNHDB. Status changed: QUEUED => ACTIVE in 0.02799844741821289
2020-04-20 21:44:46.440 1066 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_tR1tHojG. Status changed: QUEUED => ACTIVE in 0.02638101577758789
2020-04-20 21:44:46.447 1068 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_hNEBz3GS. Status changed: QUEUED => ACTIVE in 0.028295040130615234
2020-04-20 21:44:46.604 1067 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:44:46.607 1067 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:44:46.627 1065 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:44:46.630 1065 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:44:46.631 1066 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:44:46.634 1066 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:44:46.644 1068 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:44:46.649 1068 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:44:48.935 1065 RALLYDEBUG rally.task.utils [-] Waiting for resource '8a52a12d-6420-4fbf-91fe-780d371f768a'. Status changed: NONE => QUEUED in 0.043264150619506836
2020-04-20 21:44:48.955 1066 RALLYDEBUG rally.task.utils [-] Waiting for resource '6d6b7e3f-37e9-4213-a24e-da1d403f5b9a'. Status changed: NONE => QUEUED in 0.04419684410095215
2020-04-20 21:44:48.992 1067 RALLYDEBUG rally.task.utils [-] Waiting for resource '925d371b-7b48-4044-811e-3685339a5f33'. Status changed: NONE => QUEUED in 0.03588986396789551
2020-04-20 21:44:49.032 1068 RALLYDEBUG rally.task.utils [-] Waiting for resource '329d108a-4b8c-46b4-b01f-972468e6d3b3'. Status changed: NONE => QUEUED in 0.04187774658203125
2020-04-20 21:44:49.459 1065 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_etYaQEFj. Status changed: QUEUED => ACTIVE in 0.025691986083984375
2020-04-20 21:44:49.473 1066 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_QB62BedG. Status changed: QUEUED => ACTIVE in 0.030714035034179688
2020-04-20 21:44:49.477 1067 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_fcsUuoy4. Status changed: QUEUED => ACTIVE in 0.02535247802734375
2020-04-20 21:44:49.481 1068 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_1D8wzEfO. Status changed: QUEUED => ACTIVE in 0.02694416046142578
2020-04-20 21:44:49.639 1065 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:44:49.642 1065 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:44:49.649 1066 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:44:49.652 1066 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:44:49.660 1068 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:44:49.684 1067 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:44:51.950 1065 RALLYDEBUG rally.task.utils [-] Waiting for resource '92438352-8329-462b-982d-de3a56e4c7f0'. Status changed: NONE => QUEUED in 0.03880596160888672
2020-04-20 21:44:51.957 1066 RALLYDEBUG rally.task.utils [-] Waiting for resource 'ba432049-2e8d-47cc-8a20-d73c8a92e292'. Status changed: NONE => QUEUED in 0.047855377197265625
2020-04-20 21:44:52.392 1066 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_fRoPm68N. Status changed: QUEUED => ACTIVE in 0.026343345642089844
2020-04-20 21:44:52.416 1065 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_32cd3bb7_MY73C9PE. Status changed: QUEUED => ACTIVE in 0.026806116104125977
2020-04-20 21:44:52.587 1066 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:44:52.603 1065 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:44:52.629 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() started
2020-04-20 21:44:52.636 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up glance images objects
2020-04-20 21:44:53.387 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_etYaQEFj (8a52a12d-6420-4fbf-91fe-780d371f768a)
2020-04-20 21:44:53.396 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_tR1tHojG (b65b86d1-d0b0-4065-b167-c6e875531093)
2020-04-20 21:44:53.404 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_MY73C9PE (92438352-8329-462b-982d-de3a56e4c7f0)
2020-04-20 21:44:53.413 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_QB62BedG (6d6b7e3f-37e9-4213-a24e-da1d403f5b9a)
2020-04-20 21:44:53.419 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_1D8wzEfO (329d108a-4b8c-46b4-b01f-972468e6d3b3)
2020-04-20 21:44:53.432 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_snkgNHDB (9a4018d4-5555-4a65-93b8-f8ebb20c8f72)
2020-04-20 21:44:53.440 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_Hub51fz1 (37919fc7-6b65-465c-826e-652cb3068794)
2020-04-20 21:44:53.449 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_fRoPm68N (ba432049-2e8d-47cc-8a20-d73c8a92e292)
2020-04-20 21:44:53.456 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_fcsUuoy4 (925d371b-7b48-4044-811e-3685339a5f33)
2020-04-20 21:44:53.470 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_32cd3bb7_hNEBz3GS (cdcf5fde-3b45-488f-aae7-c42d055a1779)
2020-04-20 21:44:53.855 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.876 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.892 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.899 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.902 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.904 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.909 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.915 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.922 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.932 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.934 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.937 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.943 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.949 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.954 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.967 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.979 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.979 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:53.984 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:54.000 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:44:55.003 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() finished in 2.37 sec
2020-04-20 21:44:55.004 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:44:59.304 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 4.30 sec
2020-04-20 21:45:00.312 505 INFO rally.task.engine [-] Load duration is: 9.053378
2020-04-20 21:45:00.312 505 INFO rally.task.engine [-] Full runner duration is: 9.269743
2020-04-20 21:45:00.312 505 INFO rally.task.engine [-] Full duration is: 17.118676
2020-04-20 21:45:00.402 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=e6ea79ee-2983-43d1-97d9-c8cdf757b970)",
   "subtasks": [
      {
         "title": "GlanceImages.create_and_get_image",
         "description": "Create and get detailed information of an image.",
         "scenario": {
            "GlanceImages.create_and_get_image": {
               "container_format": "bare",
               "disk_format": "qcow2",
               "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:45:00.413 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:45:00.882 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:45:01.805 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.39 sec
2020-04-20 21:45:01.806 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack setup()  finished in 0.01 msec
2020-04-20 21:45:01.815 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:45:01.825 1158 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndGetImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:01.827 1159 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndGetImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:01.830 1160 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndGetImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:01.831 1158 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:45:01.832 1161 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndGetImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:01.833 1159 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:45:01.835 1160 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:45:01.838 1161 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:45:04.250 1159 RALLYDEBUG rally.task.utils [-] Waiting for resource '1198e7fb-b625-4a9f-92fa-420954592d7c'. Status changed: NONE => QUEUED in 0.039621829986572266
2020-04-20 21:45:04.297 1161 RALLYDEBUG rally.task.utils [-] Waiting for resource 'c2011edf-627a-4d6e-9afb-579a2c0b9014'. Status changed: NONE => QUEUED in 0.03796648979187012
2020-04-20 21:45:04.298 1158 RALLYDEBUG rally.task.utils [-] Waiting for resource 'b008d487-ad1f-4dec-8fef-cadf92d11dfa'. Status changed: NONE => QUEUED in 0.03419828414916992
2020-04-20 21:45:04.323 1160 RALLYDEBUG rally.task.utils [-] Waiting for resource '21174273-ddc7-49ee-acad-828ba7fa47d7'. Status changed: NONE => QUEUED in 0.041388750076293945
2020-04-20 21:45:04.827 1158 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_sbELRGyn. Status changed: QUEUED => ACTIVE in 0.02477574348449707
2020-04-20 21:45:04.835 1160 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_YTG2vzsw. Status changed: QUEUED => ACTIVE in 0.021507978439331055
2020-04-20 21:45:04.836 1161 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_NVyiF9NB. Status changed: QUEUED => ACTIVE in 0.022359848022460938
2020-04-20 21:45:04.844 1159 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_o1cEohB4. Status changed: QUEUED => ACTIVE in 0.029258012771606445
2020-04-20 21:45:04.848 1158 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:45:04.852 1158 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:45:04.861 1160 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:45:04.861 1161 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:45:04.864 1160 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:45:04.865 1161 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:45:04.869 1159 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:45:04.873 1159 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:45:07.168 1158 RALLYDEBUG rally.task.utils [-] Waiting for resource '6940d335-5864-4c6c-8890-2bdd6dc2089f'. Status changed: NONE => QUEUED in 0.04105234146118164
2020-04-20 21:45:07.168 1160 RALLYDEBUG rally.task.utils [-] Waiting for resource '4f26c6db-2c7e-4d6d-8282-7fad76622bf5'. Status changed: NONE => QUEUED in 0.046634674072265625
2020-04-20 21:45:07.264 1159 RALLYDEBUG rally.task.utils [-] Waiting for resource 'ff63662b-1b84-4f2a-b1f9-a550baf7e37f'. Status changed: NONE => QUEUED in 0.041937828063964844
2020-04-20 21:45:07.265 1161 RALLYDEBUG rally.task.utils [-] Waiting for resource 'ff11c353-bbd6-4681-9126-1cecab1f99d3'. Status changed: NONE => QUEUED in 0.04941153526306152
2020-04-20 21:45:07.583 1158 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_OUGbsqL6. Status changed: QUEUED => ACTIVE in 0.025597095489501953
2020-04-20 21:45:07.584 1160 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_6b5d3K95. Status changed: QUEUED => ACTIVE in 0.02722764015197754
2020-04-20 21:45:07.608 1160 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:45:07.609 1158 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:45:07.612 1158 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:45:07.612 1160 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:45:07.689 1159 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_ZJvA9DzM. Status changed: QUEUED => ACTIVE in 0.025552988052368164
2020-04-20 21:45:07.714 1159 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:45:07.744 1161 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_VhUa9Ibk. Status changed: QUEUED => ACTIVE in 0.022337675094604492
2020-04-20 21:45:07.769 1161 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:45:09.903 1160 RALLYDEBUG rally.task.utils [-] Waiting for resource '01195c39-7772-42ee-b3f6-af6c81afb9eb'. Status changed: NONE => QUEUED in 0.04572772979736328
2020-04-20 21:45:09.999 1158 RALLYDEBUG rally.task.utils [-] Waiting for resource '9922e2f1-051e-41c9-8d69-fdced74ddde5'. Status changed: NONE => QUEUED in 0.043282270431518555
2020-04-20 21:45:10.299 1160 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_n7XLk6Zo. Status changed: QUEUED => ACTIVE in 0.02625870704650879
2020-04-20 21:45:10.415 1160 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:45:10.438 1158 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_e6ea79ee_O468idsa. Status changed: QUEUED => ACTIVE in 0.027050256729125977
2020-04-20 21:45:10.461 1158 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:45:10.488 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() started
2020-04-20 21:45:10.491 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up glance images objects
2020-04-20 21:45:11.195 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_ZJvA9DzM (ff63662b-1b84-4f2a-b1f9-a550baf7e37f)
2020-04-20 21:45:11.199 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_VhUa9Ibk (ff11c353-bbd6-4681-9126-1cecab1f99d3)
2020-04-20 21:45:11.207 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_sbELRGyn (b008d487-ad1f-4dec-8fef-cadf92d11dfa)
2020-04-20 21:45:11.216 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_o1cEohB4 (1198e7fb-b625-4a9f-92fa-420954592d7c)
2020-04-20 21:45:11.223 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_6b5d3K95 (4f26c6db-2c7e-4d6d-8282-7fad76622bf5)
2020-04-20 21:45:11.230 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_YTG2vzsw (21174273-ddc7-49ee-acad-828ba7fa47d7)
2020-04-20 21:45:11.246 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_O468idsa (9922e2f1-051e-41c9-8d69-fdced74ddde5)
2020-04-20 21:45:11.254 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_n7XLk6Zo (01195c39-7772-42ee-b3f6-af6c81afb9eb)
2020-04-20 21:45:11.261 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_OUGbsqL6 (6940d335-5864-4c6c-8890-2bdd6dc2089f)
2020-04-20 21:45:11.270 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_e6ea79ee_NVyiF9NB (c2011edf-627a-4d6e-9afb-579a2c0b9014)
2020-04-20 21:45:11.629 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.649 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.652 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.673 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.712 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.713 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.738 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.741 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.750 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.757 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.758 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.760 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.765 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.770 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.777 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.779 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.787 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.792 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.799 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:11.801 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:12.804 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() finished in 2.32 sec
2020-04-20 21:45:12.805 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:45:19.003 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 6.20 sec
2020-04-20 21:45:20.515 505 INFO rally.task.engine [-] Load duration is: 8.456444
2020-04-20 21:45:20.515 505 INFO rally.task.engine [-] Full runner duration is: 8.673131
2020-04-20 21:45:20.516 505 INFO rally.task.engine [-] Full duration is: 18.590564
2020-04-20 21:45:20.595 505 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=0d44f965-c88f-40ae-a204-2b85b07d4edb)",
   "subtasks": [
      {
         "title": "GlanceImages.create_and_update_image",
         "description": "Create an image then update it.",
         "scenario": {
            "GlanceImages.create_and_update_image": {
               "container_format": "bare",
               "disk_format": "qcow2",
               "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:45:20.608 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:45:21.025 505 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:45:21.858 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack setup()  finished in 1.25 sec
2020-04-20 21:45:21.859 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack setup()  finished in 0.01 msec
2020-04-20 21:45:21.868 505 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: e4ab92d1-44b6-43c9-9ffc-b01114483a93).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:45:21.878 1251 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndUpdateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:21.881 1252 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndUpdateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:21.884 1251 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 START
2020-04-20 21:45:21.884 1253 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndUpdateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:21.886 1252 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 START
2020-04-20 21:45:21.886 1254 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.glance.images.CreateAndUpdateImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "qcow2", "image_location": "/home/opnfv/functest/images/cirros-0.4.0-x86_64-disk.img"}
2020-04-20 21:45:21.889 1253 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 START
2020-04-20 21:45:21.891 1254 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 START
2020-04-20 21:45:24.334 1251 RALLYDEBUG rally.task.utils [-] Waiting for resource '0d732a9c-28ff-405b-b021-ea4046abddf1'. Status changed: NONE => QUEUED in 0.039298295974731445
2020-04-20 21:45:24.342 1253 RALLYDEBUG rally.task.utils [-] Waiting for resource 'e8226f6f-ba4d-40f5-aa9f-400e71f7624e'. Status changed: NONE => QUEUED in 0.036727190017700195
2020-04-20 21:45:24.349 1254 RALLYDEBUG rally.task.utils [-] Waiting for resource '0464e2da-3103-4e1e-a74f-cb9b2712badb'. Status changed: NONE => QUEUED in 0.03425788879394531
2020-04-20 21:45:24.350 1252 RALLYDEBUG rally.task.utils [-] Waiting for resource 'a67a68c4-2984-4e78-9320-03e2422fcc77'. Status changed: NONE => QUEUED in 0.03899884223937988
2020-04-20 21:45:24.902 1251 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_uL1VKzVC. Status changed: QUEUED => ACTIVE in 0.02204751968383789
2020-04-20 21:45:24.902 1253 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_qTJbaMlz. Status changed: QUEUED => ACTIVE in 0.028660297393798828
2020-04-20 21:45:24.907 1252 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_GjiD0V9a. Status changed: QUEUED => ACTIVE in 0.027409076690673828
2020-04-20 21:45:25.038 1254 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_2JTyLFiJ. Status changed: QUEUED => ACTIVE in 0.027163982391357422
2020-04-20 21:45:25.040 1251 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 1 END: OK
2020-04-20 21:45:25.044 1251 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 START
2020-04-20 21:45:25.057 1252 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 2 END: OK
2020-04-20 21:45:25.061 1252 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 START
2020-04-20 21:45:25.066 1253 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 3 END: OK
2020-04-20 21:45:25.070 1253 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 START
2020-04-20 21:45:25.182 1254 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 4 END: OK
2020-04-20 21:45:25.185 1254 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 START
2020-04-20 21:45:27.511 1251 RALLYDEBUG rally.task.utils [-] Waiting for resource 'adc8882c-411c-4750-b5f8-c919b4422b85'. Status changed: NONE => QUEUED in 0.043534278869628906
2020-04-20 21:45:27.574 1252 RALLYDEBUG rally.task.utils [-] Waiting for resource '4a44efb8-d32d-4df3-9585-e110b2c6d163'. Status changed: NONE => QUEUED in 0.04007387161254883
2020-04-20 21:45:27.584 1253 RALLYDEBUG rally.task.utils [-] Waiting for resource '7d75aad6-4c27-474c-a4f1-b5f182578158'. Status changed: NONE => QUEUED in 0.04162406921386719
2020-04-20 21:45:27.597 1254 RALLYDEBUG rally.task.utils [-] Waiting for resource '50e549d3-d398-409a-8a59-26be932f1400'. Status changed: NONE => QUEUED in 0.0461728572845459
2020-04-20 21:45:28.125 1253 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_1f0fr8x2. Status changed: QUEUED => ACTIVE in 0.0253903865814209
2020-04-20 21:45:28.127 1251 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_mdvquAHc. Status changed: QUEUED => ACTIVE in 0.03422188758850098
2020-04-20 21:45:28.128 1252 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_laPn9WRG. Status changed: QUEUED => ACTIVE in 0.023935317993164062
2020-04-20 21:45:28.135 1254 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_SivlS8Ve. Status changed: QUEUED => ACTIVE in 0.02457141876220703
2020-04-20 21:45:28.271 1253 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 7 END: OK
2020-04-20 21:45:28.275 1253 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 START
2020-04-20 21:45:28.276 1251 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 5 END: OK
2020-04-20 21:45:28.279 1251 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 START
2020-04-20 21:45:28.280 1252 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 6 END: OK
2020-04-20 21:45:28.291 1254 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 8 END: OK
2020-04-20 21:45:30.558 1253 RALLYDEBUG rally.task.utils [-] Waiting for resource 'a6d50ef5-7052-4eb9-987d-0363c5fe794a'. Status changed: NONE => QUEUED in 0.042818307876586914
2020-04-20 21:45:30.644 1251 RALLYDEBUG rally.task.utils [-] Waiting for resource 'a3f34bef-c5d3-4e59-903f-d4282c0ddbe5'. Status changed: NONE => QUEUED in 0.03888750076293945
2020-04-20 21:45:30.991 1253 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_gc7MfDpG. Status changed: QUEUED => ACTIVE in 0.02896857261657715
2020-04-20 21:45:31.042 1251 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_0d44f965_pzSQuEW6. Status changed: QUEUED => ACTIVE in 0.025745868682861328
2020-04-20 21:45:31.143 1253 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 9 END: OK
2020-04-20 21:45:31.191 1251 INFO rally.task.runner [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | ITER: 10 END: OK
2020-04-20 21:45:31.218 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() started
2020-04-20 21:45:31.222 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up glance images objects
2020-04-20 21:45:32.013 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_GKo5dp81 (a3f34bef-c5d3-4e59-903f-d4282c0ddbe5)
2020-04-20 21:45:32.017 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_R2dq0IVL (0d732a9c-28ff-405b-b021-ea4046abddf1)
2020-04-20 21:45:32.029 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_IXiwLYbW (a6d50ef5-7052-4eb9-987d-0363c5fe794a)
2020-04-20 21:45:32.041 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_KFrL2paE (adc8882c-411c-4750-b5f8-c919b4422b85)
2020-04-20 21:45:32.055 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_2luSMiUR (7d75aad6-4c27-474c-a4f1-b5f182578158)
2020-04-20 21:45:32.060 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_OhqJb9Fk (4a44efb8-d32d-4df3-9585-e110b2c6d163)
2020-04-20 21:45:32.074 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_pl8h2q1n (e8226f6f-ba4d-40f5-aa9f-400e71f7624e)
2020-04-20 21:45:32.083 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_g6YUKbsn (a67a68c4-2984-4e78-9320-03e2422fcc77)
2020-04-20 21:45:32.088 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_xGUXjf2H (50e549d3-d398-409a-8a59-26be932f1400)
2020-04-20 21:45:32.092 505 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting glance.images object s_rally_0d44f965_LanLx3mh (0464e2da-3103-4e1e-a74f-cb9b2712badb)
2020-04-20 21:45:32.499 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.506 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.512 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.525 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.533 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.534 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.537 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.542 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.543 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.568 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.574 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.575 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.588 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.593 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.599 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.604 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.612 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.630 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.631 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:32.654 505 DEBUG glanceclient.common.http [-] Request returned failure status 404. _handle_response /usr/lib/python3.8/site-packages/glanceclient/common/http.py:125
2020-04-20 21:45:33.657 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context cleanup@openstack cleanup() finished in 2.44 sec
2020-04-20 21:45:33.658 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() started
2020-04-20 21:45:38.152 505 INFO rally.task.context [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Context users@openstack cleanup() finished in 4.49 sec
2020-04-20 21:45:38.702 505 INFO rally.task.engine [-] Load duration is: 9.100639
2020-04-20 21:45:38.703 505 INFO rally.task.engine [-] Full runner duration is: 9.350446
2020-04-20 21:45:38.703 505 INFO rally.task.engine [-] Full duration is: 17.545187
2020-04-20 21:45:38.776 505 INFO rally.task.engine [-] Task e4ab92d1-44b6-43c9-9ffc-b01114483a93 | Completed: Running task.
2020-04-20 21:45:40.624 1333 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:45:40.624 1333 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:45:40.625 1333 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:45:42.079 1335 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:45:42.080 1335 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:45:42.080 1335 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:45:43.586 1337 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:45:43.587 1337 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:45:43.587 1337 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:45:45.531 1337 INFO rally.api [-] Building 'json' report for the following task(s): 'e4ab92d1-44b6-43c9-9ffc-b01114483a93'.
2020-04-20 21:45:45.551 1337 INFO rally.api [-] The report has been successfully built.
2020-04-20 21:45:47.017 1339 RALLYDEBUG rally.api [-] INFO logs from urllib3 and requests module are hide.
2020-04-20 21:45:47.018 1339 RALLYDEBUG rally.api [-] urllib3 insecure warnings are hidden.
2020-04-20 21:45:47.018 1339 RALLYDEBUG rally.api [-] ERROR log from boto module is hide.
2020-04-20 21:45:49.159 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Starting:  Task validation.
2020-04-20 21:45:49.173 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Starting:  Task validation of syntax.
2020-04-20 21:45:49.551 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Completed: Task validation of syntax.
2020-04-20 21:45:49.552 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Starting:  Task validation of required platforms.
2020-04-20 21:45:49.709 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Completed: Task validation of required platforms.
2020-04-20 21:45:49.710 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Starting:  Task validation of semantic.
2020-04-20 21:45:49.710 1339 INFO rally.task.engine [-] Check health of the environment 'c0ed3a33-627c-4a9a-a8b3-617044cdac07'.
2020-04-20 21:45:50.257 1339 INFO rally.task.engine [-] Platform existing@openstack (available: True): OK!
2020-04-20 21:45:50.275 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 1 tenants using 1 threads
2020-04-20 21:45:50.615 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 1 users using 1 threads
2020-04-20 21:45:51.252 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack setup()  finished in 0.98 sec
2020-04-20 21:45:55.441 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() started
2020-04-20 21:45:57.994 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() finished in 2.55 sec
2020-04-20 21:45:57.995 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Completed: Task validation of semantic.
2020-04-20 21:45:57.995 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Completed: Task validation.
2020-04-20 21:45:57.996 1339 INFO rally.api [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 input file is valid.
2020-04-20 21:45:57.996 1339 INFO rally.api [-] Run Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 against Deployment c0ed3a33-627c-4a9a-a8b3-617044cdac07
2020-04-20 21:45:57.996 1339 INFO rally.task.engine [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Starting:  Running task.
2020-04-20 21:45:58.053 1339 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=744eff82-d90f-41d9-8e46-c4e06d3cbdad)",
   "subtasks": [
      {
         "title": "CinderVolumes.create_and_attach_volume",
         "description": "Create a VM and attach a volume to it.",
         "scenario": {
            "CinderVolumes.create_and_attach_volume": {
               "flavor": {
                  "name": "rally_full-flavor_f4478be8-a962-4178-b739-ae67f4f2966c"
               },
               "image": {
                  "name": "rally_full-img_f4478be8-a962-4178-b739-ae67f4f2966c"
               },
               "size": 1,
               "nics": [
                  {
                     "net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"
                  }
               ]
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            },
            "quotas": {
               "cinder": {
                  "gigabytes": -1,
                  "snapshots": -1,
                  "volumes": -1
               }
            },
            "api_versions": {
               "cinder": {
                  "version": 3,
                  "service_type": "volumev3"
               }
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:45:58.067 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:45:58.490 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:45:59.323 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack setup()  finished in 1.26 sec
2020-04-20 21:45:59.441 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack setup()  finished in 0.12 sec
2020-04-20 21:46:00.103 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack setup()  finished in 0.66 sec
2020-04-20 21:46:00.103 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack setup()  finished in 0.00 msec
2020-04-20 21:46:00.536 1339 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:46:00.546 1394 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndAttachVolume'>
	method_name: run
	args: {"flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1, "nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}
2020-04-20 21:46:00.550 1395 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndAttachVolume'>
	method_name: run
	args: {"flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1, "nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}
2020-04-20 21:46:00.552 1394 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 START
2020-04-20 21:46:00.552 1396 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndAttachVolume'>
	method_name: run
	args: {"flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1, "nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}
2020-04-20 21:46:00.555 1397 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndAttachVolume'>
	method_name: run
	args: {"flavor": "697d9e45-0658-4e54-8e82-18be1f35850a", "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1, "nics": [{"net-id": "5973c671-22dc-4c9c-8245-6e1e4d8a9468"}]}
2020-04-20 21:46:00.556 1395 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 START
2020-04-20 21:46:00.557 1396 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 START
2020-04-20 21:46:00.560 1397 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 START
2020-04-20 21:46:17.380 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_O4OyqBo3. Status changed: BUILD => ACTIVE in 13.04054570198059
2020-04-20 21:46:18.675 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_fDpRsNEl. Status changed: BUILD => ACTIVE in 15.88279128074646
2020-04-20 21:46:19.227 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_3hx6aM8D. Status changed: BUILD => ACTIVE in 14.71340560913086
2020-04-20 21:46:19.693 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_vaIYAt3v. Status changed: BUILD => ACTIVE in 16.581959009170532
2020-04-20 21:46:20.468 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_FW4HxmFM. Status changed: AVAILABLE => RESERVED in 0.21142888069152832
2020-04-20 21:46:21.917 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_WEZlN0Ep. Status changed: AVAILABLE => RESERVED in 0.327392578125
2020-04-20 21:46:22.303 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_SuXO0MXW. Status changed: AVAILABLE => RESERVED in 0.1865372657775879
2020-04-20 21:46:22.699 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_KrKP7iVH. Status changed: AVAILABLE => RESERVED in 0.17205452919006348
2020-04-20 21:46:22.703 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_FW4HxmFM. Status changed: RESERVED => IN-USE in 2.235100507736206
2020-04-20 21:46:24.155 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_WEZlN0Ep. Status changed: RESERVED => IN-USE in 2.2388534545898438
2020-04-20 21:46:24.175 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_FW4HxmFM. Status changed: AVAILABLE => DETACHING in 0.21003365516662598
2020-04-20 21:46:24.492 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_SuXO0MXW. Status changed: RESERVED => IN-USE in 2.1890439987182617
2020-04-20 21:46:24.616 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_WEZlN0Ep. Status changed: AVAILABLE => DETACHING in 0.1907031536102295
2020-04-20 21:46:24.887 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_KrKP7iVH. Status changed: RESERVED => IN-USE in 2.1882200241088867
2020-04-20 21:46:24.960 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_SuXO0MXW. Status changed: AVAILABLE => DETACHING in 0.2306363582611084
2020-04-20 21:46:25.355 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_KrKP7iVH. Status changed: AVAILABLE => DETACHING in 0.18932485580444336
2020-04-20 21:46:26.392 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_FW4HxmFM. Status changed: DETACHING => AVAILABLE in 2.216787338256836
2020-04-20 21:46:26.534 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_FW4HxmFM. Status changed: AVAILABLE => DELETING in 0.06741857528686523
2020-04-20 21:46:26.802 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_WEZlN0Ep. Status changed: DETACHING => AVAILABLE in 2.185685634613037
2020-04-20 21:46:26.969 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_WEZlN0Ep. Status changed: AVAILABLE => DELETING in 0.07418560981750488
2020-04-20 21:46:27.165 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_SuXO0MXW. Status changed: DETACHING => AVAILABLE in 2.2040340900421143
2020-04-20 21:46:27.319 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_SuXO0MXW. Status changed: AVAILABLE => DELETING in 0.07152271270751953
2020-04-20 21:46:27.548 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_KrKP7iVH. Status changed: DETACHING => AVAILABLE in 2.1932337284088135
2020-04-20 21:46:27.719 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_KrKP7iVH. Status changed: AVAILABLE => DELETING in 0.0675513744354248
2020-04-20 21:46:31.970 1395 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 END: OK
2020-04-20 21:46:31.975 1395 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 START
2020-04-20 21:46:33.332 1397 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 END: OK
2020-04-20 21:46:33.337 1397 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 START
2020-04-20 21:46:33.827 1394 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 END: OK
2020-04-20 21:46:33.833 1394 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 START
2020-04-20 21:46:34.784 1396 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 END: OK
2020-04-20 21:46:34.789 1396 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 START
2020-04-20 21:46:45.709 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_OVHdaoXB. Status changed: BUILD => ACTIVE in 9.976632595062256
2020-04-20 21:46:46.919 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_bMTnBtqZ. Status changed: BUILD => ACTIVE in 9.286436319351196
2020-04-20 21:46:48.718 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_9AfJVB17. Status changed: AVAILABLE => RESERVED in 0.1663827896118164
2020-04-20 21:46:49.154 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_UcUhV82O. Status changed: BUILD => ACTIVE in 13.739102602005005
2020-04-20 21:46:49.388 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_lWI50j1T. Status changed: BUILD => ACTIVE in 14.181687593460083
2020-04-20 21:46:50.152 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_YQGChTmn. Status changed: AVAILABLE => RESERVED in 0.3379402160644531
2020-04-20 21:46:50.908 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_9AfJVB17. Status changed: RESERVED => IN-USE in 2.1898648738861084
2020-04-20 21:46:51.336 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_9AfJVB17. Status changed: AVAILABLE => DETACHING in 0.18331646919250488
2020-04-20 21:46:52.319 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_YQGChTmn. Status changed: RESERVED => IN-USE in 2.1672558784484863
2020-04-20 21:46:52.321 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_lLApElJA. Status changed: AVAILABLE => RESERVED in 0.1699206829071045
2020-04-20 21:46:52.484 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_dFgbTYO7. Status changed: AVAILABLE => RESERVED in 0.21429181098937988
2020-04-20 21:46:52.734 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_YQGChTmn. Status changed: AVAILABLE => DETACHING in 0.18444299697875977
2020-04-20 21:46:53.531 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_9AfJVB17. Status changed: DETACHING => AVAILABLE in 2.19547700881958
2020-04-20 21:46:53.702 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_9AfJVB17. Status changed: AVAILABLE => DELETING in 0.09408807754516602
2020-04-20 21:46:54.513 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_lLApElJA. Status changed: RESERVED => IN-USE in 2.1920206546783447
2020-04-20 21:46:54.669 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_dFgbTYO7. Status changed: RESERVED => IN-USE in 2.186081647872925
2020-04-20 21:46:54.924 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_YQGChTmn. Status changed: DETACHING => AVAILABLE in 2.189850091934204
2020-04-20 21:46:54.934 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_lLApElJA. Status changed: AVAILABLE => DETACHING in 0.20546221733093262
2020-04-20 21:46:55.066 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_YQGChTmn. Status changed: AVAILABLE => DELETING in 0.06623077392578125
2020-04-20 21:46:55.108 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_dFgbTYO7. Status changed: AVAILABLE => DETACHING in 0.19114446640014648
2020-04-20 21:46:57.106 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_lLApElJA. Status changed: DETACHING => AVAILABLE in 2.1719391345977783
2020-04-20 21:46:57.250 1397 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_lLApElJA. Status changed: AVAILABLE => DELETING in 0.06363987922668457
2020-04-20 21:46:57.296 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_dFgbTYO7. Status changed: DETACHING => AVAILABLE in 2.188065528869629
2020-04-20 21:46:57.455 1395 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_dFgbTYO7. Status changed: AVAILABLE => DELETING in 0.06938290596008301
2020-04-20 21:47:00.924 1394 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 END: OK
2020-04-20 21:47:00.929 1394 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 START
2020-04-20 21:47:01.923 1396 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 END: OK
2020-04-20 21:47:01.926 1396 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 START
2020-04-20 21:47:04.571 1395 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 END: OK
2020-04-20 21:47:04.830 1397 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 END: OK
2020-04-20 21:47:12.707 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_QyWMk404. Status changed: BUILD => ACTIVE in 8.444738388061523
2020-04-20 21:47:14.624 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_to5DWB5o. Status changed: BUILD => ACTIVE in 10.934774160385132
2020-04-20 21:47:15.753 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_asuheDTW. Status changed: AVAILABLE => RESERVED in 0.19593262672424316
2020-04-20 21:47:17.530 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_798WBMXa. Status changed: AVAILABLE => RESERVED in 0.15636253356933594
2020-04-20 21:47:17.970 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_asuheDTW. Status changed: RESERVED => IN-USE in 2.2172343730926514
2020-04-20 21:47:18.396 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_asuheDTW. Status changed: AVAILABLE => DETACHING in 0.18997693061828613
2020-04-20 21:47:19.747 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_798WBMXa. Status changed: RESERVED => IN-USE in 2.2167372703552246
2020-04-20 21:47:20.167 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_798WBMXa. Status changed: AVAILABLE => DETACHING in 0.19876790046691895
2020-04-20 21:47:20.586 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_asuheDTW. Status changed: DETACHING => AVAILABLE in 2.1893491744995117
2020-04-20 21:47:20.723 1396 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_asuheDTW. Status changed: AVAILABLE => DELETING in 0.06934809684753418
2020-04-20 21:47:22.355 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_798WBMXa. Status changed: DETACHING => AVAILABLE in 2.1885986328125
2020-04-20 21:47:22.507 1394 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_744eff82_798WBMXa. Status changed: AVAILABLE => DELETING in 0.0728769302368164
2020-04-20 21:47:25.204 1396 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 END: OK
2020-04-20 21:47:30.399 1394 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 END: OK
2020-04-20 21:47:30.424 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() started
2020-04-20 21:47:30.435 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up nova servers objects
2020-04-20 21:47:31.086 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up nova server_groups objects
2020-04-20 21:47:31.525 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up nova keypairs objects
2020-04-20 21:47:32.395 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder backups objects
2020-04-20 21:47:32.799 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volume_snapshots objects
2020-04-20 21:47:33.213 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder transfers objects
2020-04-20 21:47:33.583 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volumes objects
2020-04-20 21:47:34.099 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() finished in 3.68 sec
2020-04-20 21:47:34.100 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() started
2020-04-20 21:47:34.194 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() finished in 94.28 msec
2020-04-20 21:47:34.195 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() started
2020-04-20 21:47:34.195 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() finished in 0.25 msec
2020-04-20 21:47:34.195 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() started
2020-04-20 21:47:36.112 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() finished in 1.92 sec
2020-04-20 21:47:36.475 1339 INFO rally.task.engine [-] Load duration is: 88.842839
2020-04-20 21:47:36.476 1339 INFO rally.task.engine [-] Full runner duration is: 89.888268
2020-04-20 21:47:36.476 1339 INFO rally.task.engine [-] Full duration is: 98.046766
2020-04-20 21:47:36.559 1339 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=9f65fc01-886e-4328-a706-fdbcd90d72f8)",
   "subtasks": [
      {
         "title": "CinderVolumes.create_and_list_snapshots",
         "description": "Create and then list a volume-snapshot.",
         "scenario": {
            "CinderVolumes.create_and_list_snapshots": {
               "detailed": true,
               "force": false
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            },
            "quotas": {
               "cinder": {
                  "gigabytes": -1,
                  "snapshots": -1,
                  "volumes": -1
               }
            },
            "api_versions": {
               "cinder": {
                  "version": 3,
                  "service_type": "volumev3"
               }
            },
            "volumes": {
               "size": 1,
               "volumes_per_tenant": 1
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:47:36.581 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:47:37.033 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:47:37.909 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack setup()  finished in 1.33 sec
2020-04-20 21:47:38.051 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack setup()  finished in 0.14 sec
2020-04-20 21:47:38.671 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack setup()  finished in 0.62 sec
2020-04-20 21:47:46.614 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context volumes@openstack setup()  finished in 7.94 sec
2020-04-20 21:47:46.615 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack setup()  finished in 0.14 msec
2020-04-20 21:47:46.624 1339 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:47:46.636 1607 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListSnapshots'>
	method_name: run
	args: {"detailed": true, "force": false}
2020-04-20 21:47:46.639 1608 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListSnapshots'>
	method_name: run
	args: {"detailed": true, "force": false}
2020-04-20 21:47:46.642 1609 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListSnapshots'>
	method_name: run
	args: {"detailed": true, "force": false}
2020-04-20 21:47:46.644 1607 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 START
2020-04-20 21:47:46.644 1610 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListSnapshots'>
	method_name: run
	args: {"detailed": true, "force": false}
2020-04-20 21:47:46.647 1608 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 START
2020-04-20 21:47:46.650 1609 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 START
2020-04-20 21:47:46.651 1610 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 START
2020-04-20 21:47:49.238 1607 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 END: OK
2020-04-20 21:47:49.243 1607 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 START
2020-04-20 21:47:49.264 1608 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 END: OK
2020-04-20 21:47:49.268 1608 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 START
2020-04-20 21:47:49.283 1610 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 END: OK
2020-04-20 21:47:49.288 1610 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 START
2020-04-20 21:47:49.361 1609 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 END: OK
2020-04-20 21:47:49.365 1609 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 START
2020-04-20 21:47:51.727 1607 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 END: OK
2020-04-20 21:47:51.730 1607 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 START
2020-04-20 21:47:51.786 1610 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 END: OK
2020-04-20 21:47:51.786 1608 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 END: OK
2020-04-20 21:47:51.789 1610 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 START
2020-04-20 21:47:51.803 1609 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 END: OK
2020-04-20 21:47:54.189 1610 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 END: OK
2020-04-20 21:47:54.214 1607 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 END: OK
2020-04-20 21:47:54.237 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() started
2020-04-20 21:47:54.241 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder backups objects
2020-04-20 21:47:54.729 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volume_snapshots objects
2020-04-20 21:47:55.185 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_N5A9o87J (f35a9eb8-b169-4ef3-829a-7107c8eb575b)
2020-04-20 21:47:55.186 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_4rfWjwgk (96d9ed78-300e-4c38-823c-1f2054ce2935)
2020-04-20 21:47:55.190 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_K9qMJZaD (0e4d7188-b659-4b20-83a5-6160550282b0)
2020-04-20 21:47:55.198 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_omOdlwl6 (172b612f-a99c-4f84-a2b4-fdad8b99ba3f)
2020-04-20 21:47:55.198 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_FH1zAPA7 (ca32b9f6-7167-4860-bba7-57551d389d9f)
2020-04-20 21:47:55.202 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_eeMaz0Xz (eb289660-fab4-4e9e-a633-a7ac6f6a5341)
2020-04-20 21:47:55.220 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_EnuKTTdr (97fde640-3330-400c-ad69-d7a3313d7a0f)
2020-04-20 21:47:55.233 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_yK2hLRTP (f05809ba-e569-4ce6-a378-7117f0237728)
2020-04-20 21:47:55.246 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_ZHBSnMv2 (fd6a0a3f-4222-400c-9a02-522d281efe10)
2020-04-20 21:47:55.264 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volume_snapshots object s_rally_9f65fc01_qrxTU2Zu (4517693d-de87-4a07-8ea3-401daa391342)
2020-04-20 21:47:58.662 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder transfers objects
2020-04-20 21:47:59.063 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volumes objects
2020-04-20 21:47:59.605 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() finished in 5.37 sec
2020-04-20 21:47:59.605 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context volumes@openstack cleanup() started
2020-04-20 21:47:59.606 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volumes objects
2020-04-20 21:48:00.132 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object c_rally_9f65fc01_WAkwpldX (2682d8b4-35a6-439a-b880-1badd5e82221)
2020-04-20 21:48:00.133 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object c_rally_9f65fc01_Umh3oYkK (bc7d3fe4-e3a2-4ff3-910d-f435ef53381d)
2020-04-20 21:48:00.138 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object c_rally_9f65fc01_gfWKWRlf (36b319ab-6c9a-4c5f-bc5f-5c312d463c61)
2020-04-20 21:48:02.519 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context volumes@openstack cleanup() finished in 2.91 sec
2020-04-20 21:48:02.520 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() started
2020-04-20 21:48:02.604 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() finished in 83.87 msec
2020-04-20 21:48:02.605 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() started
2020-04-20 21:48:02.605 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() finished in 0.31 msec
2020-04-20 21:48:02.605 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() started
2020-04-20 21:48:05.399 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() finished in 2.79 sec
2020-04-20 21:48:06.730 1339 INFO rally.task.engine [-] Load duration is: 7.567171
2020-04-20 21:48:06.730 1339 INFO rally.task.engine [-] Full runner duration is: 7.612779
2020-04-20 21:48:06.730 1339 INFO rally.task.engine [-] Full duration is: 28.820262
2020-04-20 21:48:06.821 1339 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=23fa1b34-e8ba-4fa1-b69e-3c323a091006)",
   "subtasks": [
      {
         "title": "CinderVolumes.create_and_list_volume",
         "description": "Create a volume and list all volumes.",
         "scenario": {
            "CinderVolumes.create_and_list_volume": {
               "detailed": true,
               "image": {
                  "name": "rally_full-img_f4478be8-a962-4178-b739-ae67f4f2966c"
               },
               "size": 1
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            },
            "quotas": {
               "cinder": {
                  "gigabytes": -1,
                  "snapshots": -1,
                  "volumes": -1
               }
            },
            "api_versions": {
               "cinder": {
                  "version": 3,
                  "service_type": "volumev3"
               }
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:48:06.836 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:48:07.434 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:48:08.267 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack setup()  finished in 1.43 sec
2020-04-20 21:48:08.410 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack setup()  finished in 0.14 sec
2020-04-20 21:48:09.081 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack setup()  finished in 0.67 sec
2020-04-20 21:48:09.082 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack setup()  finished in 0.00 msec
2020-04-20 21:48:09.316 1339 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:48:09.325 1780 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1}
2020-04-20 21:48:09.327 1781 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1}
2020-04-20 21:48:09.329 1782 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1}
2020-04-20 21:48:09.331 1780 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 START
2020-04-20 21:48:09.331 1781 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 START
2020-04-20 21:48:09.332 1783 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "image": "3156e1a5-5ba1-4f2d-91a6-5e180f0a8869", "size": 1}
2020-04-20 21:48:09.335 1782 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 START
2020-04-20 21:48:09.336 1783 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 START
2020-04-20 21:48:14.170 1782 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_qwAKbz0P. Status changed: DOWNLOADING => AVAILABLE in 2.2392616271972656
2020-04-20 21:48:14.175 1783 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_R1F0dybH. Status changed: DOWNLOADING => AVAILABLE in 2.2187142372131348
2020-04-20 21:48:14.192 1781 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_j3KZ9tGy. Status changed: DOWNLOADING => AVAILABLE in 2.205228805541992
2020-04-20 21:48:14.216 1780 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_di8fiHUD. Status changed: DOWNLOADING => AVAILABLE in 2.212083578109741
2020-04-20 21:48:14.236 1783 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 END: OK
2020-04-20 21:48:14.240 1783 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 START
2020-04-20 21:48:14.241 1782 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 END: OK
2020-04-20 21:48:14.244 1782 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 START
2020-04-20 21:48:14.254 1781 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 END: OK
2020-04-20 21:48:14.258 1781 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 START
2020-04-20 21:48:14.278 1780 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 END: OK
2020-04-20 21:48:14.282 1780 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 START
2020-04-20 21:48:18.961 1781 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_12Mo8bpa. Status changed: DOWNLOADING => AVAILABLE in 2.206559896469116
2020-04-20 21:48:18.986 1783 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_UEnwElWu. Status changed: DOWNLOADING => AVAILABLE in 2.2194466590881348
2020-04-20 21:48:18.988 1782 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_AS0976Ig. Status changed: DOWNLOADING => AVAILABLE in 2.2018306255340576
2020-04-20 21:48:19.037 1781 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 END: OK
2020-04-20 21:48:19.041 1781 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 START
2020-04-20 21:48:19.067 1782 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 END: OK
2020-04-20 21:48:19.067 1783 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 END: OK
2020-04-20 21:48:19.071 1782 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 START
2020-04-20 21:48:19.152 1780 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_CLmk4UpQ. Status changed: DOWNLOADING => AVAILABLE in 2.2269623279571533
2020-04-20 21:48:19.223 1780 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 END: OK
2020-04-20 21:48:23.845 1782 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_RFcekDcd. Status changed: DOWNLOADING => AVAILABLE in 2.2085025310516357
2020-04-20 21:48:23.891 1781 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_23fa1b34_gDdzKmxQ. Status changed: DOWNLOADING => AVAILABLE in 2.2085914611816406
2020-04-20 21:48:23.911 1782 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 END: OK
2020-04-20 21:48:23.959 1781 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 END: OK
2020-04-20 21:48:23.983 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() started
2020-04-20 21:48:23.987 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder backups objects
2020-04-20 21:48:24.415 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volume_snapshots objects
2020-04-20 21:48:24.799 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder transfers objects
2020-04-20 21:48:25.184 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volumes objects
2020-04-20 21:48:25.697 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_gDdzKmxQ (01d19839-c55f-4fc3-9c3f-4d56fa1338b8)
2020-04-20 21:48:25.700 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_UEnwElWu (eb1f99e6-f211-43fa-b5e9-f7803cf08279)
2020-04-20 21:48:25.711 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_AS0976Ig (b5c6897c-5f39-492a-9792-fb09c28b855b)
2020-04-20 21:48:25.721 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_j3KZ9tGy (5a86c84d-9dce-4afe-abe6-0af57c51890d)
2020-04-20 21:48:25.733 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_RFcekDcd (b0ae4ee0-92e8-4dcc-973d-645d175e18f1)
2020-04-20 21:48:25.738 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_12Mo8bpa (cca1e40f-03b0-4aa5-b28c-9a7e389b455d)
2020-04-20 21:48:25.754 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_R1F0dybH (ccaad745-919f-416d-a1ee-ee4b197191de)
2020-04-20 21:48:25.774 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_qwAKbz0P (ad385b8c-08ea-4bf1-9d98-0207039a83b0)
2020-04-20 21:48:25.791 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_CLmk4UpQ (72d820d1-9a8c-4c28-b2c0-27b9f1f40e4b)
2020-04-20 21:48:25.806 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_23fa1b34_di8fiHUD (90aa1493-fec5-4de9-93d7-fa6792f4aa74)
2020-04-20 21:48:28.224 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() finished in 4.24 sec
2020-04-20 21:48:28.225 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() started
2020-04-20 21:48:28.309 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() finished in 84.58 msec
2020-04-20 21:48:28.310 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() started
2020-04-20 21:48:28.310 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() finished in 0.29 msec
2020-04-20 21:48:28.310 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() started
2020-04-20 21:48:34.464 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() finished in 6.15 sec
2020-04-20 21:48:34.974 1339 INFO rally.task.engine [-] Load duration is: 14.624593
2020-04-20 21:48:34.975 1339 INFO rally.task.engine [-] Full runner duration is: 14.667994
2020-04-20 21:48:34.975 1339 INFO rally.task.engine [-] Full duration is: 27.62933
2020-04-20 21:48:35.032 1339 INFO rally.task.engine [-] Running workload: 
  position = 1
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=423d6229-f953-458d-8186-32364d0ebd03)",
   "subtasks": [
      {
         "title": "CinderVolumes.create_and_list_volume",
         "description": "Create a volume and list all volumes.",
         "scenario": {
            "CinderVolumes.create_and_list_volume": {
               "detailed": true,
               "size": 1
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            },
            "quotas": {
               "cinder": {
                  "gigabytes": -1,
                  "snapshots": -1,
                  "volumes": -1
               }
            },
            "api_versions": {
               "cinder": {
                  "version": 3,
                  "service_type": "volumev3"
               }
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:48:35.053 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:48:35.540 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:48:36.395 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack setup()  finished in 1.34 sec
2020-04-20 21:48:36.537 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack setup()  finished in 0.14 sec
2020-04-20 21:48:37.118 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack setup()  finished in 0.58 sec
2020-04-20 21:48:37.118 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack setup()  finished in 0.01 msec
2020-04-20 21:48:37.126 1339 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:48:37.136 1933 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "size": 1}
2020-04-20 21:48:37.138 1934 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "size": 1}
2020-04-20 21:48:37.140 1935 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "size": 1}
2020-04-20 21:48:37.142 1933 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 START
2020-04-20 21:48:37.142 1936 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndListVolume'>
	method_name: run
	args: {"detailed": true, "size": 1}
2020-04-20 21:48:37.143 1934 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 START
2020-04-20 21:48:37.145 1935 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 START
2020-04-20 21:48:37.147 1936 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 START
2020-04-20 21:48:39.893 1934 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 END: OK
2020-04-20 21:48:39.897 1934 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 START
2020-04-20 21:48:39.925 1933 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 END: OK
2020-04-20 21:48:39.929 1935 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 END: OK
2020-04-20 21:48:39.929 1933 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 START
2020-04-20 21:48:39.933 1935 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 START
2020-04-20 21:48:39.950 1936 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 END: OK
2020-04-20 21:48:39.953 1936 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 START
2020-04-20 21:48:42.586 1934 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 END: OK
2020-04-20 21:48:42.589 1934 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 START
2020-04-20 21:48:42.599 1935 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 END: OK
2020-04-20 21:48:42.602 1935 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 START
2020-04-20 21:48:42.628 1936 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 END: OK
2020-04-20 21:48:42.661 1933 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 END: OK
2020-04-20 21:48:45.294 1934 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 END: OK
2020-04-20 21:48:45.303 1935 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 END: OK
2020-04-20 21:48:45.331 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() started
2020-04-20 21:48:45.338 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder backups objects
2020-04-20 21:48:45.887 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volume_snapshots objects
2020-04-20 21:48:46.320 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder transfers objects
2020-04-20 21:48:46.718 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Cleaning up cinder volumes objects
2020-04-20 21:48:47.271 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_wvsGWSwq (f3295a92-1c73-465e-9cd4-80f724ca7ff7)
2020-04-20 21:48:47.275 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_d3nHidwW (c4bdd79a-eecd-4a7e-8138-a9edb77fafcf)
2020-04-20 21:48:47.281 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_A3U5EbCQ (9c90d025-d90c-4686-85e2-1bf372aebca4)
2020-04-20 21:48:47.297 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_CqIfL6nV (3ee4e471-ced4-4a5c-83cb-a8f12c7f07f0)
2020-04-20 21:48:47.303 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_JvyBCXEw (e58914f4-8c72-4cfe-9cf3-888134e26251)
2020-04-20 21:48:47.308 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_UIgHKy07 (64b90c5d-01d4-4d06-a78c-5016975e2306)
2020-04-20 21:48:47.316 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_tc1YtZIC (e51b48ac-ca0f-403b-8dc6-40416cb3549f)
2020-04-20 21:48:47.324 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_38oFfiUL (b16e3df7-9e4e-46ec-8853-6c7b1b7b4714)
2020-04-20 21:48:47.330 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_vPptfpHn (6b9e8d5e-f3cc-440c-958e-5b173385d774)
2020-04-20 21:48:47.345 1339 RALLYDEBUG rally_openstack.task.cleanup.manager [-] Deleting cinder.volumes object s_rally_423d6229_E9rwasG6 (5040322a-63f4-4565-9381-98a140a8073b)
2020-04-20 21:48:49.874 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack cleanup() finished in 4.54 sec
2020-04-20 21:48:49.874 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() started
2020-04-20 21:48:49.954 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack cleanup() finished in 80.15 msec
2020-04-20 21:48:49.955 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() started
2020-04-20 21:48:49.955 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack cleanup() finished in 0.33 msec
2020-04-20 21:48:49.956 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() started
2020-04-20 21:48:54.561 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack cleanup() finished in 4.60 sec
2020-04-20 21:48:55.161 1339 INFO rally.task.engine [-] Load duration is: 8.157381
2020-04-20 21:48:55.162 1339 INFO rally.task.engine [-] Full runner duration is: 8.204628
2020-04-20 21:48:55.162 1339 INFO rally.task.engine [-] Full duration is: 19.511101
2020-04-20 21:48:55.246 1339 INFO rally.task.engine [-] Running workload: 
  position = 0
  config = {
   "version": 2,
   "title": "A cropped version of a bigger task.",
   "description": "Auto-generated task from a single workload (uuid=63844d9d-3f71-4884-9481-a10a59eecf5f)",
   "subtasks": [
      {
         "title": "CinderVolumes.create_and_upload_volume_to_image",
         "description": "Create and upload a volume to image.",
         "scenario": {
            "CinderVolumes.create_and_upload_volume_to_image": {
               "container_format": "bare",
               "disk_format": "raw",
               "do_delete": true,
               "force": false,
               "size": 1
            }
         },
         "contexts": {
            "users": {
               "tenants": 3,
               "users_per_tenant": 2
            },
            "quotas": {
               "cinder": {
                  "gigabytes": -1,
                  "snapshots": -1,
                  "volumes": -1
               }
            },
            "api_versions": {
               "cinder": {
                  "version": 3,
                  "service_type": "volumev3"
               }
            }
         },
         "runner": {
            "constant": {
               "concurrency": 4,
               "times": 10
            }
         },
         "hooks": [],
         "sla": {
            "failure_rate": {
               "max": 0
            }
         }
      }
   ]
}
2020-04-20 21:48:55.264 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 3 tenants using 3 threads
2020-04-20 21:48:55.716 1339 RALLYDEBUG rally_openstack.task.contexts.keystone.users [-] Creating 6 users using 6 threads
2020-04-20 21:48:56.571 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context users@openstack setup()  finished in 1.31 sec
2020-04-20 21:48:56.678 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context api_versions@openstack setup()  finished in 0.11 sec
2020-04-20 21:48:57.266 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context quotas@openstack setup()  finished in 0.59 sec
2020-04-20 21:48:57.267 1339 INFO rally.task.context [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | Context cleanup@openstack setup()  finished in 0.11 msec
2020-04-20 21:48:57.275 1339 RALLYDEBUG rally.task.runner [-] Starting the constant runner (task UUID: 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1).
	times: 10
	concurrency: 4
	timeout: 0
	max_cpu_used: 88
	processes_to_start: 4
	concurrency_per_worker: 1
	concurrency_overhead: 0
2020-04-20 21:48:57.284 2086 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndUploadVolumeToImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "raw", "do_delete": true, "force": false, "size": 1}
2020-04-20 21:48:57.288 2087 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndUploadVolumeToImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "raw", "do_delete": true, "force": false, "size": 1}
2020-04-20 21:48:57.289 2088 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndUploadVolumeToImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "raw", "do_delete": true, "force": false, "size": 1}
2020-04-20 21:48:57.292 2087 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 START
2020-04-20 21:48:57.292 2086 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 START
2020-04-20 21:48:57.293 2088 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 START
2020-04-20 21:48:57.301 2095 RALLYDEBUG rally.task.runner [-] Starting a worker.
	times: 10
	duration: None
	concurrency: 1
	timeout: 0
	cls: <class 'rally_openstack.task.scenarios.cinder.volumes.CreateAndUploadVolumeToImage'>
	method_name: run
	args: {"container_format": "bare", "disk_format": "raw", "do_delete": true, "force": false, "size": 1}
2020-04-20 21:48:57.307 2095 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 4 START
2020-04-20 21:49:00.232 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_6pfJKAtW. Status changed: AVAILABLE => UPLOADING in 0.06055164337158203
2020-04-20 21:49:00.240 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_XGgQwVxV. Status changed: AVAILABLE => UPLOADING in 0.07541871070861816
2020-04-20 21:49:00.269 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_5PcgK2Pr. Status changed: AVAILABLE => UPLOADING in 0.07624340057373047
2020-04-20 21:49:12.704 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_XGgQwVxV. Status changed: UPLOADING => AVAILABLE in 12.464247703552246
2020-04-20 21:49:12.724 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_6pfJKAtW. Status changed: UPLOADING => AVAILABLE in 12.491576433181763
2020-04-20 21:49:12.729 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_5PcgK2Pr. Status changed: UPLOADING => AVAILABLE in 12.460055112838745
2020-04-20 21:49:12.929 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_XGgQwVxV. Status changed: AVAILABLE => DELETING in 0.08190345764160156
2020-04-20 21:49:12.945 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_6pfJKAtW. Status changed: AVAILABLE => DELETING in 0.0725247859954834
2020-04-20 21:49:12.955 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_5PcgK2Pr. Status changed: AVAILABLE => DELETING in 0.07542967796325684
2020-04-20 21:49:15.303 2088 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 3 END: OK
2020-04-20 21:49:15.303 2087 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 2 END: OK
2020-04-20 21:49:15.309 2087 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 START
2020-04-20 21:49:15.309 2088 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 START
2020-04-20 21:49:15.323 2086 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 1 END: OK
2020-04-20 21:49:15.327 2086 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 START
2020-04-20 21:49:18.102 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_T3ZSQiCv. Status changed: AVAILABLE => UPLOADING in 0.07366776466369629
2020-04-20 21:49:18.185 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_6sSBSjw1. Status changed: AVAILABLE => UPLOADING in 0.061356306076049805
2020-04-20 21:49:18.188 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_PXVqbKkR. Status changed: AVAILABLE => UPLOADING in 0.07437443733215332
2020-04-20 21:49:32.638 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_T3ZSQiCv. Status changed: UPLOADING => AVAILABLE in 14.535666227340698
2020-04-20 21:49:32.681 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_6sSBSjw1. Status changed: UPLOADING => AVAILABLE in 14.495695114135742
2020-04-20 21:49:32.681 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_PXVqbKkR. Status changed: UPLOADING => AVAILABLE in 14.492234945297241
2020-04-20 21:49:32.848 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_T3ZSQiCv. Status changed: AVAILABLE => DELETING in 0.07230806350708008
2020-04-20 21:49:32.902 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_PXVqbKkR. Status changed: AVAILABLE => DELETING in 0.07459664344787598
2020-04-20 21:49:32.917 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_6sSBSjw1. Status changed: AVAILABLE => DELETING in 0.07250452041625977
2020-04-20 21:49:35.210 2088 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 6 END: OK
2020-04-20 21:49:35.214 2088 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 START
2020-04-20 21:49:35.260 2086 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 7 END: OK
2020-04-20 21:49:35.265 2086 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 START
2020-04-20 21:49:35.270 2087 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 5 END: OK
2020-04-20 21:49:35.274 2087 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 START
2020-04-20 21:49:38.087 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_9UmrlGxP. Status changed: AVAILABLE => UPLOADING in 0.07173871994018555
2020-04-20 21:49:38.090 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_hZuvHykd. Status changed: AVAILABLE => UPLOADING in 0.052843332290649414
2020-04-20 21:49:38.100 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_rQJgLUqT. Status changed: AVAILABLE => UPLOADING in 0.07544231414794922
2020-04-20 21:49:50.509 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_rQJgLUqT. Status changed: UPLOADING => AVAILABLE in 12.409071922302246
2020-04-20 21:49:50.516 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_hZuvHykd. Status changed: UPLOADING => AVAILABLE in 12.425772428512573
2020-04-20 21:49:50.573 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_9UmrlGxP. Status changed: UPLOADING => AVAILABLE in 12.486027479171753
2020-04-20 21:49:50.714 2088 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_rQJgLUqT. Status changed: AVAILABLE => DELETING in 0.07133769989013672
2020-04-20 21:49:50.745 2086 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_hZuvHykd. Status changed: AVAILABLE => DELETING in 0.08539271354675293
2020-04-20 21:49:50.798 2087 RALLYDEBUG rally.task.utils [-] Waiting for resource s_rally_63844d9d_9UmrlGxP. Status changed: AVAILABLE => DELETING in 0.07001543045043945
2020-04-20 21:49:53.058 2088 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 8 END: OK
2020-04-20 21:49:53.089 2086 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 9 END: OK
2020-04-20 21:49:53.149 2087 INFO rally.task.runner [-] Task 242a8f34-1e4f-40ec-9e6d-d5bdb182d8c1 | ITER: 10 END: OK
