Cinder

Create volume from image fails with "AttributeError: owner"

Bug #1314133 reported by Matt Aitchison
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Cinder
New
Undecided
Unassigned
cinder-direct-attach (CentOS)
New
Undecided
Unassigned

Bug Description

http://hastebin.com/ximebodufu.py

matt@flume:~/images/www.cloudbase.it$ tail /var/log/cinder/*.log /var/log/nova/*.log /var/log/keystone/*.log /var/log/neutron/*.log -f
==> /var/log/cinder/cinder-api.log <==
2014-04-28 21:37:28.012 2789 INFO cinder.api.openstack.wsgi [req-45f14c87-beab-4b54-b7d4-9c3551b055a7 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/os-availability-zone returned with HTTP 200
2014-04-28 21:37:28.013 2789 INFO eventlet.wsgi.server [req-45f14c87-beab-4b54-b7d4-9c3551b055a7 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:28] "GET /v1/26234fc874d347cf897b515d4abc898d/os-availability-zone HTTP/1.1" 200 320 0.006801
2014-04-28 21:37:28.063 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48010)
2014-04-28 21:37:28.065 2789 INFO cinder.api.openstack.wsgi [req-bfeed298-c1f5-4eba-8f3a-259d20e94eed c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/limits
2014-04-28 21:37:28.085 2789 INFO cinder.api.openstack.wsgi [req-bfeed298-c1f5-4eba-8f3a-259d20e94eed c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/limits returned with HTTP 200
2014-04-28 21:37:28.085 2789 INFO eventlet.wsgi.server [req-bfeed298-c1f5-4eba-8f3a-259d20e94eed c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:28] "GET /v1/26234fc874d347cf897b515d4abc898d/limits HTTP/1.1" 200 431 0.022071
2014-04-28 21:37:28.088 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48011)
2014-04-28 21:37:28.090 2789 INFO cinder.api.openstack.wsgi [req-175c3412-1117-43ed-aad1-0ddf4af72c7f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes/detail
2014-04-28 21:37:28.103 2789 INFO cinder.api.openstack.wsgi [req-175c3412-1117-43ed-aad1-0ddf4af72c7f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes/detail returned with HTTP 200
2014-04-28 21:37:28.104 2789 INFO eventlet.wsgi.server [req-175c3412-1117-43ed-aad1-0ddf4af72c7f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:28] "GET /v1/26234fc874d347cf897b515d4abc898d/volumes/detail HTTP/1.1" 200 253 0.015474

==> /var/log/cinder/cinder-scheduler.log <==
2014-04-28 21:28:04.322 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:29:04.325 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:30:04.327 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:31:04.330 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:32:04.331 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:33:04.333 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:34:04.335 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:35:04.335 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:36:04.335 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}
2014-04-28 21:37:04.340 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}

==> /var/log/cinder/cinder-volume.log <==
2014-04-28 21:28:04.321 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:29:04.326 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:30:04.328 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:31:04.329 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:32:04.330 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:33:04.333 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:34:04.334 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:35:04.334 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:36:04.334 2683 INFO cinder.volume.manager [-] Updating volume status
2014-04-28 21:37:04.337 2683 INFO cinder.volume.manager [-] Updating volume status

==> /var/log/nova/nova-api.log <==
2014-04-28 21:28:32.808 3011 INFO nova.api.ec2 [-] 0.542s 10.1.5.5 GET /openstack/2013-04-04/meta_data.json None:None 200 [Python-httplib2/0.8 (gzip)] text/plain text/html
2014-04-28 21:28:32.809 3011 INFO nova.metadata.wsgi.server [-] 192.168.1.11,10.1.5.5 "GET /openstack/2013-04-04/meta_data.json HTTP/1.1" status: 200 len: 1416 time: 0.0012870
2014-04-28 21:28:33.431 3011 INFO nova.api.ec2 [-] 0.142778s 10.1.5.5 POST /openstack/2013-04-04/password None:None 200 [Python-httplib2/0.8 (gzip)] text/plain text/html
2014-04-28 21:28:33.432 3011 INFO nova.metadata.wsgi.server [-] 192.168.1.11,10.1.5.5 "POST /openstack/2013-04-04/password HTTP/1.1" status: 200 len: 115 time: 0.1436419
2014-04-28 21:32:29.772 2910 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): flume
2014-04-28 21:32:29.880 2910 INFO nova.osapi_compute.wsgi.server [req-b74f56f1-7fb7-4ec6-905c-b5c31ecd5654 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] 10.1.5.5 "GET /v2/26234fc874d347cf897b515d4abc898d/servers/detail?project_id=26234fc874d347cf897b515d4abc898d HTTP/1.1" status: 200 len: 1847 time: 0.1120059
2014-04-28 21:32:30.095 2910 INFO nova.osapi_compute.wsgi.server [req-2454eeeb-31c2-4e9e-8436-11c42497ac87 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] 10.1.5.5 "GET /v2/26234fc874d347cf897b515d4abc898d/os-quota-sets/26234fc874d347cf897b515d4abc898d HTTP/1.1" status: 200 len: 495 time: 0.0105751
2014-04-28 21:32:30.151 2910 INFO nova.osapi_compute.wsgi.server [req-f49c1008-eb9e-44f6-81ad-5545682140c2 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] 10.1.5.5 "GET /v2/26234fc874d347cf897b515d4abc898d/flavors/detail HTTP/1.1" status: 200 len: 2193 time: 0.0107231
2014-04-28 21:32:30.220 2910 INFO nova.osapi_compute.wsgi.server [req-c6dc22d0-b224-455b-821d-f492e47a2321 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] 10.1.5.5 "GET /v2/26234fc874d347cf897b515d4abc898d/servers/detail?project_id=26234fc874d347cf897b515d4abc898d HTTP/1.1" status: 200 len: 1847 time: 0.0659859
2014-04-28 21:37:28.060 2910 INFO nova.osapi_compute.wsgi.server [req-cb476120-1f79-4739-b06d-c1f4259f661f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] 10.1.5.5 "GET /v2/26234fc874d347cf897b515d4abc898d/limits HTTP/1.1" status: 200 len: 607 time: 0.0170729

==> /var/log/nova/nova-cert.log <==
2014-04-28 10:06:17.879 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 18.163488 sec
2014-04-28 10:06:30.916 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 3.036258 sec
2014-04-28 10:07:25.485 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 44.568617 sec
2014-04-28 10:07:39.479 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 3.990659 sec
2014-04-28 10:07:52.672 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 3.192654 sec
2014-04-28 10:08:04.090 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 1.416772 sec
2014-04-28 10:08:27.603 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 3.507283 sec
2014-04-28 10:09:09.408 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 1.791616 sec
2014-04-28 10:09:20.739 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 1.329155 sec
2014-04-28 20:04:54.891 2463 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 11.473195 sec

==> /var/log/nova/nova-compute.log <==
2014-04-28 21:36:23.603 9112 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
2014-04-28 21:36:24.238 9112 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 34964
2014-04-28 21:36:24.238 9112 AUDIT nova.compute.resource_tracker [-] Free disk (GB): -77
2014-04-28 21:36:24.238 9112 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
2014-04-28 21:36:24.404 9112 INFO nova.compute.resource_tracker [-] Compute_service record updated for flume:flume.lanciv.com
2014-04-28 21:37:24.629 9112 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
2014-04-28 21:37:25.242 9112 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 34964
2014-04-28 21:37:25.242 9112 AUDIT nova.compute.resource_tracker [-] Free disk (GB): -77
2014-04-28 21:37:25.242 9112 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
2014-04-28 21:37:25.331 9112 INFO nova.compute.resource_tracker [-] Compute_service record updated for flume:flume.lanciv.com

==> /var/log/nova/nova-conductor.log <==
2014-04-28 10:09:20.744 2772 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 1.206707 sec
2014-04-28 11:28:46.145 2783 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 0.358885 sec
2014-04-28 11:28:46.146 2772 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 1.9543 sec
2014-04-28 19:02:00.078 2777 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 0.958631 sec
2014-04-28 20:04:54.400 2783 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 5.881343 sec
2014-04-28 20:04:54.890 2760 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 5.322474 sec
2014-04-28 20:04:54.890 2756 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 11.459042 sec
2014-04-28 20:04:54.891 2761 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 9.843164 sec
2014-04-28 20:04:54.892 2764 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 5.446801 sec
2014-04-28 20:04:54.895 2777 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 3.378416 sec

==> /var/log/nova/nova-consoleauth.log <==
2014-04-28 20:50:53.929 2495 AUDIT nova.consoleauth.manager [req-26aede4e-b24d-4ce4-a9a8-43907c3f526f ed6625d177d14dd194e9385fae35c04d c8c0ee4e5be74f46adc1160705ebbd9f] Received Token: 76e0bc9b-e821-498f-b377-f958df3d543c, {'instance_uuid': u'6d0efe65-83b4-4358-8f5f-4e9ac6956388', 'internal_access_path': None, 'last_activity_at': 1398736253.928705, 'console_type': u'novnc', 'host': u'10.1.5.5', 'token': u'76e0bc9b-e821-498f-b377-f958df3d543c', 'port': u'5901'}
2014-04-28 20:50:54.253 2495 AUDIT nova.consoleauth.manager [req-717d4756-a199-464b-95ab-18a11b701069 None None] Checking Token: 76e0bc9b-e821-498f-b377-f958df3d543c, True
2014-04-28 20:53:05.051 2495 AUDIT nova.consoleauth.manager [req-5f1dee56-c8d4-4d27-9275-cff49522c89c ed6625d177d14dd194e9385fae35c04d c8c0ee4e5be74f46adc1160705ebbd9f] Received Token: 2733a541-c95a-4501-b133-0ed4ce2c0967, {'instance_uuid': u'6d0efe65-83b4-4358-8f5f-4e9ac6956388', 'internal_access_path': None, 'last_activity_at': 1398736385.050764, 'console_type': u'novnc', 'host': u'10.1.5.5', 'token': u'2733a541-c95a-4501-b133-0ed4ce2c0967', 'port': u'5901'}
2014-04-28 20:53:05.317 2495 AUDIT nova.consoleauth.manager [req-5a62adf6-8103-4373-831b-6d10b9be80d0 None None] Checking Token: 2733a541-c95a-4501-b133-0ed4ce2c0967, True
2014-04-28 20:59:26.886 2495 AUDIT nova.consoleauth.manager [req-88ea7781-2829-43fa-8a3f-9310fd373f3a ed6625d177d14dd194e9385fae35c04d c8c0ee4e5be74f46adc1160705ebbd9f] Received Token: 3ea62901-c94a-4098-bb50-267b7731ef7d, {'instance_uuid': u'6d0efe65-83b4-4358-8f5f-4e9ac6956388', 'internal_access_path': None, 'last_activity_at': 1398736766.885984, 'console_type': u'novnc', 'host': u'10.1.5.5', 'token': u'3ea62901-c94a-4098-bb50-267b7731ef7d', 'port': u'5901'}
2014-04-28 20:59:27.459 2495 AUDIT nova.consoleauth.manager [req-472f7092-3669-4c44-b2ec-b6ed7981670e None None] Checking Token: 3ea62901-c94a-4098-bb50-267b7731ef7d, True
2014-04-28 20:59:28.458 2495 AUDIT nova.consoleauth.manager [req-26783c50-4845-44f3-b989-ed96fac33b3f None None] Checking Token: 8cd98e32-980e-4317-a508-da7e8685f200, False
2014-04-28 20:59:32.740 2495 AUDIT nova.consoleauth.manager [req-3749a6df-3180-4f09-b3ac-e4954ae363e2 ed6625d177d14dd194e9385fae35c04d c8c0ee4e5be74f46adc1160705ebbd9f] Received Token: aa50af6a-b25b-4dc5-ab69-1bfd966b064d, {'instance_uuid': u'6d0efe65-83b4-4358-8f5f-4e9ac6956388', 'internal_access_path': None, 'last_activity_at': 1398736772.740633, 'console_type': u'novnc', 'host': u'10.1.5.5', 'token': u'aa50af6a-b25b-4dc5-ab69-1bfd966b064d', 'port': u'5901'}
2014-04-28 20:59:33.038 2495 AUDIT nova.consoleauth.manager [req-726d4584-9263-4dee-bddc-1150411138b5 None None] Checking Token: aa50af6a-b25b-4dc5-ab69-1bfd966b064d, True
2014-04-28 20:59:44.168 2495 AUDIT nova.consoleauth.manager [req-60eae261-7f25-4f7f-b40b-048fea004156 None None] Checking Token: aa50af6a-b25b-4dc5-ab69-1bfd966b064d, True

==> /var/log/nova/nova-manage.log <==

==> /var/log/nova/nova-scheduler.log <==
2014-04-28 20:13:20.590 2502 INFO nova.scheduler.filter_scheduler [req-70a28ad4-a9a2-4d02-abba-a9c64fdc5557 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Attempting to build 1 instance(s) uuids: [u'5154a42a-76b3-484d-a05a-25d70450eb83']
2014-04-28 20:13:20.602 2502 INFO nova.scheduler.filter_scheduler [req-70a28ad4-a9a2-4d02-abba-a9c64fdc5557 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Choosing host WeighedHost [host: flume, weight: 1.0] for instance 5154a42a-76b3-484d-a05a-25d70450eb83
2014-04-28 20:39:24.524 2502 INFO nova.scheduler.filter_scheduler [req-8b85d6db-9ee8-4f11-be5e-a6c0b23bc13c ed6625d177d14dd194e9385fae35c04d c8c0ee4e5be74f46adc1160705ebbd9f] Attempting to build 1 instance(s) uuids: [u'6d0efe65-83b4-4358-8f5f-4e9ac6956388']
2014-04-28 20:39:24.535 2502 INFO nova.scheduler.filter_scheduler [req-8b85d6db-9ee8-4f11-be5e-a6c0b23bc13c ed6625d177d14dd194e9385fae35c04d c8c0ee4e5be74f46adc1160705ebbd9f] Choosing host WeighedHost [host: flume, weight: 1.0] for instance 6d0efe65-83b4-4358-8f5f-4e9ac6956388
2014-04-28 20:47:06.228 2502 INFO nova.scheduler.filter_scheduler [req-b3eed68f-8822-4ab3-a852-9f604eab31e6 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Attempting to build 1 instance(s) uuids: [u'dcc52db6-fe89-4650-a542-c7324d4bccea']
2014-04-28 20:47:06.240 2502 INFO nova.scheduler.filter_scheduler [req-b3eed68f-8822-4ab3-a852-9f604eab31e6 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Choosing host WeighedHost [host: flume, weight: 1.0] for instance dcc52db6-fe89-4650-a542-c7324d4bccea
2014-04-28 21:21:55.802 2502 INFO nova.scheduler.filter_scheduler [req-40eca3ae-2d34-490e-b2ba-d5ff6975b00f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Attempting to build 1 instance(s) uuids: [u'01588994-7e77-4c33-b44a-965f0ee58d95']
2014-04-28 21:21:55.813 2502 INFO nova.scheduler.filter_scheduler [req-40eca3ae-2d34-490e-b2ba-d5ff6975b00f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Choosing host WeighedHost [host: flume, weight: 1.0] for instance 01588994-7e77-4c33-b44a-965f0ee58d95
2014-04-28 21:24:56.738 2502 INFO nova.scheduler.filter_scheduler [req-fb69cbe7-a78e-49d7-8b91-c3e588e7fc2f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Attempting to build 1 instance(s) uuids: [u'609332b1-c840-4d4c-9f23-c9c85a7f53e5']
2014-04-28 21:24:56.751 2502 INFO nova.scheduler.filter_scheduler [req-fb69cbe7-a78e-49d7-8b91-c3e588e7fc2f c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] Choosing host WeighedHost [host: flume, weight: 1.0] for instance 609332b1-c840-4d4c-9f23-c9c85a7f53e5
tail: cannot open ‘/var/log/keystone/*.log’ for reading: Permission denied

==> /var/log/neutron/dhcp-agent.log <==
2014-04-28 09:16:21.917 3122 TRACE neutron.agent.dhcp_agent self.state_rpc.report_state(ctx, self.agent_state, self.use_call)
2014-04-28 09:16:21.917 3122 TRACE neutron.agent.dhcp_agent File "/usr/lib/python2.7/dist-packages/neutron/agent/rpc.py", line 72, in report_state
2014-04-28 09:16:21.917 3122 TRACE neutron.agent.dhcp_agent return self.call(context, msg, topic=self.topic)
2014-04-28 09:16:21.917 3122 TRACE neutron.agent.dhcp_agent File "/usr/lib/python2.7/dist-packages/neutron/openstack/common/rpc/proxy.py", line 129, in call
2014-04-28 09:16:21.917 3122 TRACE neutron.agent.dhcp_agent exc.info, real_topic, msg.get('method'))
2014-04-28 09:16:21.917 3122 TRACE neutron.agent.dhcp_agent Timeout: Timeout while waiting on RPC response - topic: "q-plugin", RPC method: "report_state" info: "<unknown>"
2014-04-28 09:16:21.917 3122 TRACE neutron.agent.dhcp_agent
2014-04-28 09:16:22.595 3122 WARNING neutron.openstack.common.loopingcall [-] task run outlasted interval by 31.790928 sec
2014-04-28 09:16:26.908 3122 INFO neutron.agent.dhcp_agent [req-83899913-e4ff-4852-9c24-35b3970e3d92 None] Synchronizing state
2014-04-28 09:16:30.284 3122 INFO neutron.agent.dhcp_agent [req-83899913-e4ff-4852-9c24-35b3970e3d92 None] Synchronizing state complete

==> /var/log/neutron/l3-agent.log <==
2014-04-28 09:16:22.435 3123 TRACE neutron.agent.l3_agent exc.info, real_topic, msg.get('method'))
2014-04-28 09:16:22.435 3123 TRACE neutron.agent.l3_agent Timeout: Timeout while waiting on RPC response - topic: "q-l3-plugin", RPC method: "sync_routers" info: "<unknown>"
2014-04-28 09:16:22.435 3123 TRACE neutron.agent.l3_agent
2014-04-28 09:16:22.437 3123 WARNING neutron.openstack.common.loopingcall [req-473fefa8-d2f5-42f2-afb3-8cc81f069ef6 None] task run outlasted interval by 58.54877 sec
2014-04-28 09:16:22.437 3123 WARNING neutron.openstack.common.loopingcall [req-473fefa8-d2f5-42f2-afb3-8cc81f069ef6 None] task run outlasted interval by 20.440026 sec
2014-04-28 09:16:22.448 3123 INFO neutron.openstack.common.rpc.common [req-473fefa8-d2f5-42f2-afb3-8cc81f069ef6 None] Connected to AMQP server on flume:5672
2014-04-28 09:16:32.751 3123 WARNING neutron.openstack.common.loopingcall [req-473fefa8-d2f5-42f2-afb3-8cc81f069ef6 None] task run outlasted interval by 8.312066 sec
2014-04-28 11:44:22.893 3123 WARNING neutron.agent.l3_agent [-] Info for router ae8a82e5-3934-4685-85b3-2b33353b752e were not found. Skipping router removal
2014-04-28 20:38:40.272 3123 WARNING neutron.openstack.common.loopingcall [-] task run outlasted interval by 1.145496 sec
2014-04-28 20:38:59.478 3123 WARNING neutron.openstack.common.loopingcall [-] task run outlasted interval by 0.198984 sec

==> /var/log/neutron/metadata-agent.log <==
2014-04-28 21:28:32.486 26602 INFO eventlet.wsgi.server [req-ec0f7ef2-ba5b-4a46-a9ae-78da144e52cc None] 192.168.1.11,<local> - - [28/Apr/2014 21:28:32] "GET /openstack/2013-04-04/password HTTP/1.1" 200 115 0.030492

2014-04-28 21:28:32.777 26602 INFO eventlet.wsgi.server [req-ec0f7ef2-ba5b-4a46-a9ae-78da144e52cc None] (26602) accepted ''

2014-04-28 21:28:32.810 26602 INFO eventlet.wsgi.server [req-ec0f7ef2-ba5b-4a46-a9ae-78da144e52cc None] 192.168.1.11,<local> - - [28/Apr/2014 21:28:32] "GET /openstack/2013-04-04/meta_data.json HTTP/1.1" 200 1416 0.032203

2014-04-28 21:28:33.255 26602 INFO eventlet.wsgi.server [req-ec0f7ef2-ba5b-4a46-a9ae-78da144e52cc None] (26602) accepted ''

2014-04-28 21:28:33.433 26602 INFO eventlet.wsgi.server [req-ec0f7ef2-ba5b-4a46-a9ae-78da144e52cc None] 192.168.1.11,<local> - - [28/Apr/2014 21:28:33] "POST /openstack/2013-04-04/password HTTP/1.1" 200 115 0.177125

==> /var/log/neutron/neutron-ns-metadata-proxy-1261f02e-2ac4-48c9-a23c-49b744df868a.log <==
2014-04-28 21:28:32.487 4027 INFO neutron.wsgi [-] 192.168.1.11 - - [28/Apr/2014 21:28:32] "GET /openstack/2013-04-04/password HTTP/1.1" 200 134 0.032471

2014-04-28 21:28:32.775 4027 INFO neutron.wsgi [-] (4027) accepted ('192.168.1.11', 49161)

2014-04-28 21:28:32.810 4027 INFO neutron.wsgi [-] 192.168.1.11 - - [28/Apr/2014 21:28:32] "GET /openstack/2013-04-04/meta_data.json HTTP/1.1" 200 1435 0.034477

2014-04-28 21:28:33.254 4027 INFO neutron.wsgi [-] (4027) accepted ('192.168.1.11', 49162)

2014-04-28 21:28:33.434 4027 INFO neutron.wsgi [-] 192.168.1.11 - - [28/Apr/2014 21:28:33] "POST /openstack/2013-04-04/password HTTP/1.1" 200 134 0.179928

==> /var/log/neutron/neutron-ns-metadata-proxy-149dc669-cfee-45b1-b489-ecd16aa30ec6.log <==

2014-04-26 10:04:04.747 5583 INFO neutron.common.config [-] Logging enabled!
2014-04-26 10:04:04.826 5587 INFO neutron.wsgi [-] (5587) wsgi starting up on http://0.0.0.0:9697/

2014-04-26 10:10:31.040 3869 INFO neutron.common.config [-] Logging enabled!
2014-04-26 10:10:31.168 3873 INFO neutron.wsgi [-] (3873) wsgi starting up on http://0.0.0.0:9697/

2014-04-26 11:01:55.041 3688 INFO neutron.common.config [-] Logging enabled!
2014-04-26 11:01:55.147 3692 INFO neutron.wsgi [-] (3692) wsgi starting up on http://0.0.0.0:9697/

==> /var/log/neutron/neutron-ns-metadata-proxy-181e9515-ea47-4256-bdd0-1e0ec1893457.log <==
2014-04-28 20:43:04.523 29292 INFO neutron.wsgi [-] 192.168.0.2 - - [28/Apr/2014 20:43:04] "GET /openstack/2013-04-04/password HTTP/1.1" 200 134 0.393876

2014-04-28 20:43:04.824 29292 INFO neutron.wsgi [-] (29292) accepted ('192.168.0.2', 49161)

2014-04-28 20:43:04.858 29292 INFO neutron.wsgi [-] 192.168.0.2 - - [28/Apr/2014 20:43:04] "GET /openstack/2013-04-04/meta_data.json HTTP/1.1" 200 1419 0.033082

2014-04-28 20:43:05.292 29292 INFO neutron.wsgi [-] (29292) accepted ('192.168.0.2', 49162)

2014-04-28 20:43:05.471 29292 INFO neutron.wsgi [-] 192.168.0.2 - - [28/Apr/2014 20:43:05] "POST /openstack/2013-04-04/password HTTP/1.1" 200 134 0.177814

==> /var/log/neutron/neutron-ns-metadata-proxy-284ef019-2fc1-446a-99c2-adf5c9ad18fd.log <==
2014-04-26 10:22:29.935 4476 INFO neutron.common.config [-] Logging enabled!
2014-04-26 10:22:29.959 4480 INFO neutron.wsgi [-] (4480) wsgi starting up on http://0.0.0.0:9697/

2014-04-26 11:01:55.927 3808 INFO neutron.common.config [-] Logging enabled!
2014-04-26 11:01:55.993 3823 INFO neutron.wsgi [-] (3823) wsgi starting up on http://0.0.0.0:9697/

==> /var/log/neutron/neutron-ns-metadata-proxy-328bd670-dc6e-4362-b347-43f96bbb68f2.log <==
2014-04-27 01:14:06.241 4372 INFO neutron.wsgi [-] 192.168.1.6 - - [27/Apr/2014 01:14:06] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.197331

2014-04-27 01:14:08.249 4372 INFO neutron.wsgi [-] (4372) accepted ('192.168.1.6', 46624)

2014-04-27 01:14:08.517 4372 INFO neutron.wsgi [-] 192.168.1.6 - - [27/Apr/2014 01:14:08] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.267550

2014-04-27 01:14:10.524 4372 INFO neutron.wsgi [-] (4372) accepted ('192.168.1.6', 46625)

2014-04-27 01:14:10.729 4372 INFO neutron.wsgi [-] 192.168.1.6 - - [27/Apr/2014 01:14:10] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.204088

==> /var/log/neutron/neutron-ns-metadata-proxy-4b36b951-fe23-4696-9c6f-8511125122f7.log <==

2014-04-27 06:27:05.890 12844 INFO neutron.wsgi [-] 192.168.1.5 - - [27/Apr/2014 06:27:05] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.212561

2014-04-27 06:27:07.898 12844 INFO neutron.wsgi [-] (12844) accepted ('192.168.1.5', 48273)

2014-04-27 06:27:08.115 12844 INFO neutron.wsgi [-] 192.168.1.5 - - [27/Apr/2014 06:27:08] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.217242

2014-04-27 06:51:28.989 4322 INFO neutron.common.config [-] Logging enabled!
2014-04-27 06:51:29.123 4326 INFO neutron.wsgi [-] (4326) wsgi starting up on http://0.0.0.0:9697/

==> /var/log/neutron/neutron-ns-metadata-proxy-63d615ea-4fd2-4063-bae8-57550d655ba8.log <==
2014-04-28 06:05:58.471 26705 INFO neutron.wsgi [-] 10.50.1.6 - - [28/Apr/2014 06:05:58] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.180699

2014-04-28 06:06:00.477 26705 INFO neutron.wsgi [-] (26705) accepted ('10.50.1.6', 46489)

2014-04-28 06:06:00.698 26705 INFO neutron.wsgi [-] 10.50.1.6 - - [28/Apr/2014 06:06:00] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.219553

2014-04-28 06:06:02.708 26705 INFO neutron.wsgi [-] (26705) accepted ('10.50.1.6', 46490)

2014-04-28 06:06:02.902 26705 INFO neutron.wsgi [-] 10.50.1.6 - - [28/Apr/2014 06:06:02] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.192956

==> /var/log/neutron/neutron-ns-metadata-proxy-80784bda-6c65-4d1d-8fca-15f810aaa8ce.log <==
2014-04-27 08:21:46.225 7324 INFO neutron.wsgi [-] 192.168.10.2 - - [27/Apr/2014 08:21:46] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.209950

2014-04-27 08:21:48.232 7324 INFO neutron.wsgi [-] (7324) accepted ('192.168.10.2', 60786)

2014-04-27 08:21:48.706 7324 INFO neutron.wsgi [-] 192.168.10.2 - - [27/Apr/2014 08:21:48] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.473246

2014-04-27 08:21:50.712 7324 INFO neutron.wsgi [-] (7324) accepted ('192.168.10.2', 60787)

2014-04-27 08:21:50.948 7324 INFO neutron.wsgi [-] 192.168.10.2 - - [27/Apr/2014 08:21:50] "GET /2009-04-04/meta-data/instance-id HTTP/1.1" 500 342 0.169464

==> /var/log/neutron/openvswitch-agent.log <==
2014-04-28 21:08:50.392 3120 INFO neutron.agent.securitygroups_rpc [req-16b46867-6e97-4f5f-b9b7-79c53fd2742f None] Security group rule updated [u'94bedfcb-8f85-4623-ab68-460541244bd1']
2014-04-28 21:08:52.367 3120 INFO neutron.agent.securitygroups_rpc [-] Refresh firewall rules
2014-04-28 21:09:14.842 3120 INFO neutron.agent.securitygroups_rpc [req-0d8b9664-50ef-45bc-9a9d-1ee2875ca8eb None] Security group rule updated [u'94bedfcb-8f85-4623-ab68-460541244bd1']
2014-04-28 21:09:16.384 3120 INFO neutron.agent.securitygroups_rpc [-] Refresh firewall rules
2014-04-28 21:21:56.568 3120 INFO neutron.agent.securitygroups_rpc [req-12fcfdad-3f40-4f8d-9783-92c94e9260cf None] Security group member updated [u'04a4cf75-6a14-45e0-be17-6bbd665e134c']
2014-04-28 21:22:03.915 3120 INFO neutron.agent.securitygroups_rpc [req-306af193-7f90-4f5d-b792-39560b5e3a24 None] Security group member updated [u'04a4cf75-6a14-45e0-be17-6bbd665e134c']
2014-04-28 21:24:57.509 3120 INFO neutron.agent.securitygroups_rpc [req-24b71c5e-3da8-4a6c-94da-e24afeca23ae None] Security group member updated [u'04a4cf75-6a14-45e0-be17-6bbd665e134c']
2014-04-28 21:24:58.919 3120 INFO neutron.agent.securitygroups_rpc [-] Preparing filters for devices set([u'd4a2dbd4-7422-435f-8a25-5d1b180b8941'])
2014-04-28 21:24:59.383 3120 INFO neutron.plugins.openvswitch.agent.ovs_neutron_agent [-] Port d4a2dbd4-7422-435f-8a25-5d1b180b8941 updated. Details: {u'admin_state_up': True, u'network_id': u'7641b7f0-9ad5-40a8-9191-0cda900309db', u'segmentation_id': 2, u'physical_network': None, u'device': u'd4a2dbd4-7422-435f-8a25-5d1b180b8941', u'port_id': u'd4a2dbd4-7422-435f-8a25-5d1b180b8941', u'network_type': u'gre'}
2014-04-28 21:24:59.565 3120 INFO neutron.plugins.openvswitch.agent.ovs_neutron_agent [-] Configuration for device d4a2dbd4-7422-435f-8a25-5d1b180b8941 completed.

==> /var/log/neutron/ovs-cleanup.log <==
2014-04-28 08:30:27.244 2039 INFO neutron.agent.ovs_cleanup_util [-] Cleaning br-ex
2014-04-28 08:30:27.804 2039 INFO neutron.agent.ovs_cleanup_util [-] OVS cleanup completed successfully
2014-04-28 09:00:31.313 2069 INFO neutron.common.config [-] Logging enabled!
2014-04-28 09:00:32.221 2069 INFO neutron.agent.ovs_cleanup_util [-] Cleaning br-int
2014-04-28 09:00:33.312 2069 INFO neutron.agent.ovs_cleanup_util [-] Cleaning br-ex
2014-04-28 09:00:33.800 2069 INFO neutron.agent.ovs_cleanup_util [-] OVS cleanup completed successfully
2014-04-28 09:15:17.959 2177 INFO neutron.common.config [-] Logging enabled!
2014-04-28 09:15:19.306 2177 INFO neutron.agent.ovs_cleanup_util [-] Cleaning br-int
2014-04-28 09:15:20.088 2177 INFO neutron.agent.ovs_cleanup_util [-] Cleaning br-ex
2014-04-28 09:15:20.425 2177 INFO neutron.agent.ovs_cleanup_util [-] OVS cleanup completed successfully

==> /var/log/neutron/server.log <==
2014-04-28 21:37:25.537 2500 INFO neutron.wsgi [req-702e272c-0b9f-46b1-a38a-ddac53e5e3c8 None] 10.1.5.5 - - [28/Apr/2014 21:37:25] "GET /v2.0/floatingips.json?fixed_ip_address=192.168.0.2&port_id=a356e11b-8ae6-4277-b28f-dba0c0c6a426 HTTP/1.1" 200 208 0.004599

2014-04-28 21:37:25.538 2500 INFO neutron.wsgi [req-702e272c-0b9f-46b1-a38a-ddac53e5e3c8 None] (2500) accepted ('10.1.5.5', 36143)

2014-04-28 21:37:25.548 2500 INFO neutron.wsgi [req-120f0fed-059f-4739-bdd2-a5d318300026 None] 10.1.5.5 - - [28/Apr/2014 21:37:25] "GET /v2.0/subnets.json?id=d7abcb10-2dbb-46de-862a-c859ae708287 HTTP/1.1" 200 607 0.009567

2014-04-28 21:37:25.550 2500 INFO neutron.wsgi [req-120f0fed-059f-4739-bdd2-a5d318300026 None] (2500) accepted ('10.1.5.5', 36144)

2014-04-28 21:37:25.562 2500 INFO neutron.wsgi [req-fc63a5c1-e9ad-462e-b197-61c13439494b None] 10.1.5.5 - - [28/Apr/2014 21:37:25] "GET /v2.0/ports.json?network_id=37f760ea-611a-4c9d-a671-678560397c13&device_owner=network%3Adhcp HTTP/1.1" 200 924 0.011039

==> /var/log/cinder/cinder-api.log <==
2014-04-28 21:37:49.916 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48015)
2014-04-28 21:37:49.922 2789 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): flume
2014-04-28 21:37:49.950 2789 INFO cinder.api.openstack.wsgi [req-42684ec6-ea65-4492-94a1-9797aefbc1d9 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/types
2014-04-28 21:37:49.958 2789 INFO cinder.api.openstack.wsgi [req-42684ec6-ea65-4492-94a1-9797aefbc1d9 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/types returned with HTTP 200
2014-04-28 21:37:49.959 2789 INFO eventlet.wsgi.server [req-42684ec6-ea65-4492-94a1-9797aefbc1d9 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:49] "GET /v1/26234fc874d347cf897b515d4abc898d/types HTTP/1.1" 200 343 0.041763
2014-04-28 21:37:49.963 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48017)
2014-04-28 21:37:49.966 2789 INFO cinder.api.openstack.wsgi [req-097ddcd8-36f0-47e5-b869-d8690200edd9 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/extensions
2014-04-28 21:37:49.967 2789 INFO cinder.api.openstack.wsgi [req-097ddcd8-36f0-47e5-b869-d8690200edd9 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/extensions returned with HTTP 200
2014-04-28 21:37:49.968 2789 INFO eventlet.wsgi.server [req-097ddcd8-36f0-47e5-b869-d8690200edd9 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:49] "GET /v1/26234fc874d347cf897b515d4abc898d/extensions HTTP/1.1" 200 6611 0.004159
2014-04-28 21:37:49.971 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48018)
2014-04-28 21:37:49.974 2789 INFO cinder.api.openstack.wsgi [req-3e5f7322-c8e0-44db-9d1b-30afe52833e4 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/os-availability-zone
2014-04-28 21:37:49.978 2789 INFO cinder.api.openstack.wsgi [req-3e5f7322-c8e0-44db-9d1b-30afe52833e4 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/os-availability-zone returned with HTTP 200
2014-04-28 21:37:49.978 2789 INFO eventlet.wsgi.server [req-3e5f7322-c8e0-44db-9d1b-30afe52833e4 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:49] "GET /v1/26234fc874d347cf897b515d4abc898d/os-availability-zone HTTP/1.1" 200 320 0.006833

==> /var/log/nova/nova-api.log <==
2014-04-28 21:37:50.023 2910 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): flume
2014-04-28 21:37:50.049 2910 INFO nova.osapi_compute.wsgi.server [req-d551f87c-7c83-4dd3-bbc1-ca95fdf9ebcb c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] 10.1.5.5 "GET /v2/26234fc874d347cf897b515d4abc898d/limits HTTP/1.1" status: 200 len: 607 time: 0.0290120

==> /var/log/cinder/cinder-api.log <==
2014-04-28 21:37:50.052 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48023)
2014-04-28 21:37:50.055 2789 INFO cinder.api.openstack.wsgi [req-626a1af1-9042-4eb2-bec0-9e03fdb10acd c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/limits
2014-04-28 21:37:50.075 2789 INFO cinder.api.openstack.wsgi [req-626a1af1-9042-4eb2-bec0-9e03fdb10acd c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/limits returned with HTTP 200
2014-04-28 21:37:50.076 2789 INFO eventlet.wsgi.server [req-626a1af1-9042-4eb2-bec0-9e03fdb10acd c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:50] "GET /v1/26234fc874d347cf897b515d4abc898d/limits HTTP/1.1" 200 431 0.023542
2014-04-28 21:37:50.079 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48024)
2014-04-28 21:37:50.081 2789 INFO cinder.api.openstack.wsgi [req-47f3b79f-d75a-4a98-bbdc-207c5bf042f4 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes/detail
2014-04-28 21:37:50.094 2789 INFO cinder.api.openstack.wsgi [req-47f3b79f-d75a-4a98-bbdc-207c5bf042f4 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes/detail returned with HTTP 200
2014-04-28 21:37:50.095 2789 INFO eventlet.wsgi.server [req-47f3b79f-d75a-4a98-bbdc-207c5bf042f4 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:50] "GET /v1/26234fc874d347cf897b515d4abc898d/volumes/detail HTTP/1.1" 200 253 0.015919
2014-04-28 21:37:50.097 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48025)
2014-04-28 21:37:50.100 2789 INFO cinder.api.openstack.wsgi [req-efb24b98-b273-4145-bc38-df7f99acf385 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] POST http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes
2014-04-28 21:37:50.108 2789 AUDIT cinder.api.v1.volumes [req-efb24b98-b273-4145-bc38-df7f99acf385 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] Create volume of 20 GB
2014-04-28 21:37:50.151 2789 ERROR cinder.api.middleware.fault [req-efb24b98-b273-4145-bc38-df7f99acf385 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] Caught error: owner
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault Traceback (most recent call last):
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/api/middleware/fault.py", line 75, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return req.get_response(self.application)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1320, in send
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault application, catch_exc_info=False)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in call_application
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault app_iter = application(self.environ, start_response)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py", line 582, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return self.app(env, start_response)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault response = self.app(environ, start_response)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return resp(environ, start_response)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault resp = self.call_func(req, *args, **self.kwargs)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return self.func(req, *args, **kwargs)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/api/openstack/wsgi.py", line 895, in __call__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault content_type, body, accept)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/api/openstack/wsgi.py", line 943, in _process_stack
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault action_result = self.dispatch(meth, request, action_args)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/api/openstack/wsgi.py", line 1019, in dispatch
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return method(req=request, **action_args)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/api/v1/volumes.py", line 432, in create
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault **kwargs)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/volume/api.py", line 189, in create
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault flow_engine.run()
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/taskflow/utils/lock_utils.py", line 53, in wrapper
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return f(*args, **kwargs)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 111, in run
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault self._run()
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 121, in _run
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault self._revert(misc.Failure())
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 78, in _revert
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault misc.Failure.reraise_if_any(failures.values())
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 558, in reraise_if_any
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault failures[0].reraise()
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 565, in reraise
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault six.reraise(*self._exc_info)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 36, in _execute_task
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault result = task.execute(**arguments)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/volume/flows/api/create_volume.py", line 341, in execute
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault self._check_image_metadata(context, image_id, size)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/volume/flows/api/create_volume.py", line 180, in _check_image_metadata
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault image_meta = self.image_service.show(context, image_id)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/image/glance.py", line 228, in show
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault base_image_meta = self._translate_from_glance(image)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/image/glance.py", line 336, in _translate_from_glance
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault image_meta = _extract_attributes(image)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/cinder/image/glance.py", line 434, in _extract_attributes
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault output[attr] = getattr(image, attr)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/glanceclient/common/base.py", line 95, in __getattr__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault return self.__getattr__(k)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault File "/usr/lib/python2.7/dist-packages/glanceclient/common/base.py", line 97, in __getattr__
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault raise AttributeError(k)
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault AttributeError: owner
2014-04-28 21:37:50.151 2789 TRACE cinder.api.middleware.fault
2014-04-28 21:37:50.154 2789 INFO cinder.api.middleware.fault [req-efb24b98-b273-4145-bc38-df7f99acf385 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes returned with HTTP 500
2014-04-28 21:37:50.155 2789 INFO eventlet.wsgi.server [req-efb24b98-b273-4145-bc38-df7f99acf385 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:50] "POST /v1/26234fc874d347cf897b515d4abc898d/volumes HTTP/1.1" 500 401 0.057002

==> /var/log/nova/nova-api.log <==
2014-04-28 21:37:50.171 2910 INFO nova.osapi_compute.wsgi.server [req-24939cc3-59f6-48e2-9cf9-56eddde156e2 c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d] 10.1.5.5 "GET /v2/26234fc874d347cf897b515d4abc898d/limits HTTP/1.1" status: 200 len: 607 time: 0.0129089

==> /var/log/cinder/cinder-api.log <==
2014-04-28 21:37:50.175 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48030)
2014-04-28 21:37:50.177 2789 INFO cinder.api.openstack.wsgi [req-140d392b-ef13-411d-98b8-02aff9bb67fd c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/limits
2014-04-28 21:37:50.198 2789 INFO cinder.api.openstack.wsgi [req-140d392b-ef13-411d-98b8-02aff9bb67fd c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/limits returned with HTTP 200
2014-04-28 21:37:50.199 2789 INFO eventlet.wsgi.server [req-140d392b-ef13-411d-98b8-02aff9bb67fd c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:50] "GET /v1/26234fc874d347cf897b515d4abc898d/limits HTTP/1.1" 200 431 0.023247
2014-04-28 21:37:50.201 2789 INFO eventlet.wsgi.server [-] (2789) accepted ('10.1.5.5', 48031)
2014-04-28 21:37:50.203 2789 INFO cinder.api.openstack.wsgi [req-c6dd2eb9-4626-42cb-a8ef-0f305a4c190a c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] GET http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes/detail
2014-04-28 21:37:50.216 2789 INFO cinder.api.openstack.wsgi [req-c6dd2eb9-4626-42cb-a8ef-0f305a4c190a c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] http://flume:8776/v1/26234fc874d347cf897b515d4abc898d/volumes/detail returned with HTTP 200
2014-04-28 21:37:50.216 2789 INFO eventlet.wsgi.server [req-c6dd2eb9-4626-42cb-a8ef-0f305a4c190a c19760f045ec4064af6ede82eab2b98d 26234fc874d347cf897b515d4abc898d - - -] 10.1.5.5 - - [28/Apr/2014 21:37:50] "GET /v1/26234fc874d347cf897b515d4abc898d/volumes/detail HTTP/1.1" 200 253 0.014744

==> /var/log/nova/nova-compute.log <==
2014-04-28 21:38:02.799 9112 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
2014-04-28 21:38:03.431 9112 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 34964
2014-04-28 21:38:03.432 9112 AUDIT nova.compute.resource_tracker [-] Free disk (GB): -77
2014-04-28 21:38:03.432 9112 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
2014-04-28 21:38:03.492 9112 INFO nova.compute.resource_tracker [-] Compute_service record updated for flume:flume.lanciv.com

==> /var/log/cinder/cinder-volume.log <==
2014-04-28 21:38:04.337 2683 INFO cinder.volume.manager [-] Updating volume status

==> /var/log/cinder/cinder-scheduler.log <==
2014-04-28 21:38:04.338 2504 WARNING cinder.context [-] Arguments dropped when creating context: {'user': None, 'tenant': None, 'user_identity': u'- - - - -'}

Revision history for this message
git-harry (git-harry) wrote :

This looks to be a duplicate of https://bugs.launchpad.net/cinder/+bug/1308058

Revision history for this message
Matt Aitchison (o-matt-7) wrote :

That may be correct. I ran the following command and I was able to create a volume."glance image-update CoreOS --owner TENANT_ID"

It seems that for some reason glance is not setting an owner for images.

Revision history for this message
gadLinux (gad-aguilardelgado) wrote :

I can confirm this, setting the owner fixed this.

I have glance with a local storage and cinder with the rbd.

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

Other bug subscribers

Remote bug watches

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