Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 914967 Details for
Bug 914648
Packstack should create and distribute nova keys
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
migration fails
other.log (text/x-log), 181.05 KB, created by
Jaroslav Henner
on 2014-07-06 14:51:42 UTC
(
hide
)
Description:
migration fails
Filename:
MIME Type:
Creator:
Jaroslav Henner
Created:
2014-07-06 14:51:42 UTC
Size:
181.05 KB
patch
obsolete
>2014-07-06 10:38:25.377 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "write_to_disk_info_file" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:25.378 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "f190f25a-c45c-4e20-967e-3e64cdf16211" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:25.379 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "f190f25a-c45c-4e20-967e-3e64cdf16211" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:38:25.380 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "f190f25a-c45c-4e20-967e-3e64cdf16211" at /var/lib/nova/instances/locks/nova-f190f25a-c45c-4e20-967e-3e64cdf16211 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:38:25.380 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "fetch_func_sync" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:25.380 18332 DEBUG stevedore.extension [-] found extension EntryPoint.parse('file = nova.image.download.file') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156 >2014-07-06 10:38:25.381 18332 DEBUG stevedore.extension [-] found extension EntryPoint.parse('file = nova.image.download.file') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156 >2014-07-06 10:38:25.382 18332 DEBUG glanceclient.common.http [-] curl -i -X GET -H 'X-Service-Catalog: [{"endpoints": [{"adminURL": "http://172.16.32.37:8776/v1/36ece03b5a6845c9b40b23aac94ab9ec", "region": "RegionOne", "id": "39290fc80cb8405d9cb7df74f0f7cb65", "internalURL": "http://172.16.32.37:8776/v1/36ece03b5a6845c9b40b23aac94ab9ec", "publicURL": "http://172.16.32.37:8776/v1/36ece03b5a6845c9b40b23aac94ab9ec"}], "endpoints_links": [], "type": "volume", "name": "cinder"}]' -H 'X-Identity-Status: Confirmed' -H 'X-Roles: admin' -H 'User-Agent: python-glanceclient' -H 'X-Tenant-Id: 36ece03b5a6845c9b40b23aac94ab9ec' -H 'X-User-Id: 1ccf92dd7cec4c079a1a33289257a3fe' -H 'X-Auth-Token: MIISkAYJKoZIhvcNAQcCoIISgTCCEn0CAQExCTAHBgUrDgMCGjCCEOYGCSqGSIb3DQEHAaCCENcEghDTeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxNC0wNy0wNlQxNDozODoyNC4zNTMxMDciLCAiZXhwaXJlcyI6ICIyMDE0LTA3LTA2VDE1OjM4OjI0WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogImFkbWluIHRlbmFudCIsICJlbmFibGVkIjogdHJ1ZSwgImlkIjogIjM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgIm5hbWUiOiAiYWRtaW4ifX0sICJzZXJ2aWNlQ2F0YWxvZyI6IFt7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92Mi8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92Mi8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyIsICJpZCI6ICIxOWRmZGVkYjEzODg0MGJmYjY2MjAxZTgyNjgyMjYwYyIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc0L3YyLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogImNvbXB1dGUiLCAibmFtZSI6ICJub3ZhIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YyLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YyLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgImlkIjogIjAwYmE1ZGFlYzE0NzQyMjViMDRhMWZkZGMxNTAyYmE1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzYvdjIvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAidm9sdW1ldjIiLCAibmFtZSI6ICJjaW5kZXJ2MiJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92MyIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92MyIsICJpZCI6ICIyZmQ1MzdjOGYzYTk0Y2M2YWQzZGQzZTViNTdlNmFkNyIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc0L3YzIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogImNvbXB1dGV2MyIsICJuYW1lIjogIm5vdmEifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwODAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwODAiLCAiaWQiOiAiMTZkMWMxNDA2ZTEwNGVlYWE5MThjYmQ3YjZmYzEwNGQiLCAicHVibGljVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODA4MCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJzMyIsICJuYW1lIjogInN3aWZ0X3MzIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo5MjkyIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo5MjkyIiwgImlkIjogIjI4N2ZjOTAzNWQ3MTRkNWZhYTE4MDU4N2ZiNjZjMzdkIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjkyOTIifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaW1hZ2UiLCAibmFtZSI6ICJnbGFuY2UifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzciLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzciLCAiaWQiOiAiNTk1ZWZjM2RlZGQ2NDUyMWJjMmQwNjRkODk1MGQ5MDQiLCAicHVibGljVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJtZXRlcmluZyIsICJuYW1lIjogImNlaWxvbWV0ZXIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwMDAvdjEvIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4MDAwL3YxLyIsICJpZCI6ICI1OGJlYTg1OTY5NTY0ODk3OTU2ZjIyNWE2NjNmZmUzOSIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4MDAwL3YxLyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjbG91ZGZvcm1hdGlvbiIsICJuYW1lIjogImhlYXQtY2ZuIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YxLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YxLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgImlkIjogIjM5MjkwZmM4MGNiODQwNWQ5Y2I3ZGY3NGYwZjdjYjY1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzYvdjEvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAidm9sdW1lIiwgIm5hbWUiOiAiY2luZGVyIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4NzczL3NlcnZpY2VzL0FkbWluIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4NzczL3NlcnZpY2VzL0Nsb3VkIiwgImlkIjogIjAwZmQyNzkzNWZlMjQyMTdiZjc4NmZhMzRiYzU1YzM1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzMvc2VydmljZXMvQ2xvdWQifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiZWMyIiwgIm5hbWUiOiAibm92YV9lYzIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwMDQvdjEvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwMDQvdjEvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMiLCAiaWQiOiAiMTBhYWNhNDAzYjdiNGM0ZmJlOWNmMzAwNjFhZGFmYjAiLCAicHVibGljVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODAwNC92MS8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJvcmNoZXN0cmF0aW9uIiwgIm5hbWUiOiAiaGVhdCJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODA4MC8iLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwODAvdjEvQVVUSF8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyIsICJpZCI6ICIwNmRlYzgxZGZkMTE0NTIwYTA0OWRhZWJiOGMyMDU0ZiIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4MDgwL3YxL0FVVEhfMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAib2JqZWN0LXN0b3JlIiwgIm5hbWUiOiAic3dpZnQifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjM1MzU3L3YyLjAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjUwMDAvdjIuMCIsICJpZCI6ICIwNTBhNjA2NmZhMWE0NDcxYjU3ZGJmMDBlMWFjZDEwOCIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo1MDAwL3YyLjAifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaWRlbnRpdHkiLCAibmFtZSI6ICJrZXlzdG9uZSJ9XSwgInVzZXIiOiB7InVzZXJuYW1lIjogImFkbWluIiwgInJvbGVzX2xpbmtzIjogW10sICJpZCI6ICIxY2NmOTJkZDdjZWM0YzA3OWExYTMzMjg5MjU3YTNmZSIsICJyb2xlcyI6IFt7Im5hbWUiOiAiYWRtaW4ifV0sICJuYW1lIjogImFkbWluIn0sICJtZXRhZGF0YSI6IHsiaXNfYWRtaW4iOiAwLCAicm9sZXMiOiBbIjg1ZjMzNDYyMTQ0ZjQ2M2Y4NmMwYjMxNzM5NDMxOTllIl19fX0xggGBMIIBfQIBATBcMFcxCzAJBgNVBAYTAlVTMQ4wDAYDVQQIDAVVbnNldDEOMAwGA1UEBwwFVW5zZXQxDjAMBgNVBAoMBVVuc2V0MRgwFgYDVQQDDA93d3cuZXhhbXBsZS5jb20CAQEwBwYFKw4DAhowDQYJKoZIhvcNAQEBBQAEggEA2Vh4TSthqnLXNqulUjYiCskK-jyBAqM4M1b6J0oT0K5iX85jWfUmUVesqqTu9saDJyh7FE6HnCCeJBJii2GVHTnJA9WrHOKY4VtCSLRya-a1ld3k6n9AzhCO3JrgRMazxiQc4zMigePgbI9poaAYsEc0VWq6U1NiUQ-CG+uLTZS6FG2psMc1jE35P3r-3O-5Wg+uHcj3zOUIcCL0aF6vv-fVV-TSKTSEaX8wNYisGgyWVBualnXWSK5VP1gKFQNgqbDBxI9G4nBpDIEwLlJTzyU7fwLAcF-PUc6NmcT0aZYIfHb6EBVkznRGqf36n1LdVeI3RkbWwTEoyoAQoVYc0g==' -H 'Content-Type: application/octet-stream' http://172.16.32.37:9292/v1/images/f190f25a-c45c-4e20-967e-3e64cdf16211 log_curl_request /usr/lib/python2.7/site-packages/glanceclient/common/http.py:142 >2014-07-06 10:38:25.417 18332 DEBUG glanceclient.common.http [-] >HTTP/1.1 200 OK >content-length: 3723817 >x-image-meta-id: f190f25a-c45c-4e20-967e-3e64cdf16211 >date: Sun, 06 Jul 2014 14:38:26 GMT >x-image-meta-deleted: False >x-image-meta-checksum: 68085af2609d03e51c7662395b5b6e4b >x-image-meta-container_format: ari >x-image-meta-protected: False >x-image-meta-min_disk: 0 >x-image-meta-created_at: 2014-07-06T14:13:22 >x-image-meta-size: 3723817 >x-image-meta-status: active >etag: 68085af2609d03e51c7662395b5b6e4b >location: http://172.16.32.37:9292/v1/images/f190f25a-c45c-4e20-967e-3e64cdf16211 >x-image-meta-is_public: True >x-image-meta-min_ram: 0 >x-image-meta-owner: 36ece03b5a6845c9b40b23aac94ab9ec >x-image-meta-updated_at: 2014-07-06T14:13:22 >content-type: application/octet-stream >x-openstack-request-id: req-e42a70cc-dd8e-457b-9acb-164c22d176d7 >x-image-meta-disk_format: ari >x-image-meta-name: cirros-0.3.2-x86_64-uec-ramdisk > log_http_response /usr/lib/python2.7/site-packages/glanceclient/common/http.py:152 >2014-07-06 10:38:25.461 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/f190f25a-c45c-4e20-967e-3e64cdf16211.part execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.481 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.482 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "f190f25a-c45c-4e20-967e-3e64cdf16211" at /var/lib/nova/instances/locks/nova-f190f25a-c45c-4e20-967e-3e64cdf16211 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:38:25.483 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "fetch_func_sync" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:25.484 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "f190f25a-c45c-4e20-967e-3e64cdf16211" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:25.484 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "f190f25a-c45c-4e20-967e-3e64cdf16211" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:38:25.485 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "f190f25a-c45c-4e20-967e-3e64cdf16211" at /var/lib/nova/instances/locks/nova-f190f25a-c45c-4e20-967e-3e64cdf16211 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:38:25.485 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "copy_raw_image" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:25.486 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): cp /var/lib/nova/instances/_base/f190f25a-c45c-4e20-967e-3e64cdf16211 /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/ramdisk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.506 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.507 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "f190f25a-c45c-4e20-967e-3e64cdf16211" at /var/lib/nova/instances/locks/nova-f190f25a-c45c-4e20-967e-3e64cdf16211 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:38:25.508 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "copy_raw_image" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:25.509 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/ramdisk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.529 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.530 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk.info" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:25.531 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "write_to_disk_info_file" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:25.532 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "write_to_disk_info_file" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:25.534 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk.info" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:25.534 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "write_to_disk_info_file" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:25.535 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "write_to_disk_info_file" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:25.536 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "378699fccd74fe8791aa53fabb7ff2af52719984" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:25.537 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "378699fccd74fe8791aa53fabb7ff2af52719984" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:38:25.537 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "378699fccd74fe8791aa53fabb7ff2af52719984" at /var/lib/nova/instances/locks/nova-378699fccd74fe8791aa53fabb7ff2af52719984 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:38:25.538 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "fetch_func_sync" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:25.538 18332 DEBUG stevedore.extension [-] found extension EntryPoint.parse('file = nova.image.download.file') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156 >2014-07-06 10:38:25.539 18332 DEBUG stevedore.extension [-] found extension EntryPoint.parse('file = nova.image.download.file') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156 >2014-07-06 10:38:25.540 18332 DEBUG glanceclient.common.http [-] curl -i -X GET -H 'X-Service-Catalog: [{"endpoints": [{"adminURL": "http://172.16.32.37:8776/v1/36ece03b5a6845c9b40b23aac94ab9ec", "region": "RegionOne", "id": "39290fc80cb8405d9cb7df74f0f7cb65", "internalURL": "http://172.16.32.37:8776/v1/36ece03b5a6845c9b40b23aac94ab9ec", "publicURL": "http://172.16.32.37:8776/v1/36ece03b5a6845c9b40b23aac94ab9ec"}], "endpoints_links": [], "type": "volume", "name": "cinder"}]' -H 'X-Identity-Status: Confirmed' -H 'X-Roles: admin' -H 'User-Agent: python-glanceclient' -H 'X-Tenant-Id: 36ece03b5a6845c9b40b23aac94ab9ec' -H 'X-User-Id: 1ccf92dd7cec4c079a1a33289257a3fe' -H 'X-Auth-Token: MIISkAYJKoZIhvcNAQcCoIISgTCCEn0CAQExCTAHBgUrDgMCGjCCEOYGCSqGSIb3DQEHAaCCENcEghDTeyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxNC0wNy0wNlQxNDozODoyNC4zNTMxMDciLCAiZXhwaXJlcyI6ICIyMDE0LTA3LTA2VDE1OjM4OjI0WiIsICJpZCI6ICJwbGFjZWhvbGRlciIsICJ0ZW5hbnQiOiB7ImRlc2NyaXB0aW9uIjogImFkbWluIHRlbmFudCIsICJlbmFibGVkIjogdHJ1ZSwgImlkIjogIjM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgIm5hbWUiOiAiYWRtaW4ifX0sICJzZXJ2aWNlQ2F0YWxvZyI6IFt7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92Mi8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92Mi8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyIsICJpZCI6ICIxOWRmZGVkYjEzODg0MGJmYjY2MjAxZTgyNjgyMjYwYyIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc0L3YyLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogImNvbXB1dGUiLCAibmFtZSI6ICJub3ZhIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YyLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YyLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgImlkIjogIjAwYmE1ZGFlYzE0NzQyMjViMDRhMWZkZGMxNTAyYmE1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzYvdjIvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAidm9sdW1ldjIiLCAibmFtZSI6ICJjaW5kZXJ2MiJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92MyIsICJyZWdpb24iOiAiUmVnaW9uT25lIiwgImludGVybmFsVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NC92MyIsICJpZCI6ICIyZmQ1MzdjOGYzYTk0Y2M2YWQzZGQzZTViNTdlNmFkNyIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc0L3YzIn1dLCAiZW5kcG9pbnRzX2xpbmtzIjogW10sICJ0eXBlIjogImNvbXB1dGV2MyIsICJuYW1lIjogIm5vdmEifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwODAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwODAiLCAiaWQiOiAiMTZkMWMxNDA2ZTEwNGVlYWE5MThjYmQ3YjZmYzEwNGQiLCAicHVibGljVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODA4MCJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJzMyIsICJuYW1lIjogInN3aWZ0X3MzIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo5MjkyIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo5MjkyIiwgImlkIjogIjI4N2ZjOTAzNWQ3MTRkNWZhYTE4MDU4N2ZiNjZjMzdkIiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjkyOTIifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaW1hZ2UiLCAibmFtZSI6ICJnbGFuY2UifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzciLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzciLCAiaWQiOiAiNTk1ZWZjM2RlZGQ2NDUyMWJjMmQwNjRkODk1MGQ5MDQiLCAicHVibGljVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODc3NyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJtZXRlcmluZyIsICJuYW1lIjogImNlaWxvbWV0ZXIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwMDAvdjEvIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4MDAwL3YxLyIsICJpZCI6ICI1OGJlYTg1OTY5NTY0ODk3OTU2ZjIyNWE2NjNmZmUzOSIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4MDAwL3YxLyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJjbG91ZGZvcm1hdGlvbiIsICJuYW1lIjogImhlYXQtY2ZuIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YxLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4Nzc2L3YxLzM2ZWNlMDNiNWE2ODQ1YzliNDBiMjNhYWM5NGFiOWVjIiwgImlkIjogIjM5MjkwZmM4MGNiODQwNWQ5Y2I3ZGY3NGYwZjdjYjY1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzYvdjEvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAidm9sdW1lIiwgIm5hbWUiOiAiY2luZGVyIn0sIHsiZW5kcG9pbnRzIjogW3siYWRtaW5VUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4NzczL3NlcnZpY2VzL0FkbWluIiwgInJlZ2lvbiI6ICJSZWdpb25PbmUiLCAiaW50ZXJuYWxVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4NzczL3NlcnZpY2VzL0Nsb3VkIiwgImlkIjogIjAwZmQyNzkzNWZlMjQyMTdiZjc4NmZhMzRiYzU1YzM1IiwgInB1YmxpY1VSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3Ojg3NzMvc2VydmljZXMvQ2xvdWQifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiZWMyIiwgIm5hbWUiOiAibm92YV9lYzIifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwMDQvdjEvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwMDQvdjEvMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMiLCAiaWQiOiAiMTBhYWNhNDAzYjdiNGM0ZmJlOWNmMzAwNjFhZGFmYjAiLCAicHVibGljVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODAwNC92MS8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyJ9XSwgImVuZHBvaW50c19saW5rcyI6IFtdLCAidHlwZSI6ICJvcmNoZXN0cmF0aW9uIiwgIm5hbWUiOiAiaGVhdCJ9LCB7ImVuZHBvaW50cyI6IFt7ImFkbWluVVJMIjogImh0dHA6Ly8xNzIuMTYuMzIuMzc6ODA4MC8iLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjgwODAvdjEvQVVUSF8zNmVjZTAzYjVhNjg0NWM5YjQwYjIzYWFjOTRhYjllYyIsICJpZCI6ICIwNmRlYzgxZGZkMTE0NTIwYTA0OWRhZWJiOGMyMDU0ZiIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo4MDgwL3YxL0FVVEhfMzZlY2UwM2I1YTY4NDVjOWI0MGIyM2FhYzk0YWI5ZWMifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAib2JqZWN0LXN0b3JlIiwgIm5hbWUiOiAic3dpZnQifSwgeyJlbmRwb2ludHMiOiBbeyJhZG1pblVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjM1MzU3L3YyLjAiLCAicmVnaW9uIjogIlJlZ2lvbk9uZSIsICJpbnRlcm5hbFVSTCI6ICJodHRwOi8vMTcyLjE2LjMyLjM3OjUwMDAvdjIuMCIsICJpZCI6ICIwNTBhNjA2NmZhMWE0NDcxYjU3ZGJmMDBlMWFjZDEwOCIsICJwdWJsaWNVUkwiOiAiaHR0cDovLzE3Mi4xNi4zMi4zNzo1MDAwL3YyLjAifV0sICJlbmRwb2ludHNfbGlua3MiOiBbXSwgInR5cGUiOiAiaWRlbnRpdHkiLCAibmFtZSI6ICJrZXlzdG9uZSJ9XSwgInVzZXIiOiB7InVzZXJuYW1lIjogImFkbWluIiwgInJvbGVzX2xpbmtzIjogW10sICJpZCI6ICIxY2NmOTJkZDdjZWM0YzA3OWExYTMzMjg5MjU3YTNmZSIsICJyb2xlcyI6IFt7Im5hbWUiOiAiYWRtaW4ifV0sICJuYW1lIjogImFkbWluIn0sICJtZXRhZGF0YSI6IHsiaXNfYWRtaW4iOiAwLCAicm9sZXMiOiBbIjg1ZjMzNDYyMTQ0ZjQ2M2Y4NmMwYjMxNzM5NDMxOTllIl19fX0xggGBMIIBfQIBATBcMFcxCzAJBgNVBAYTAlVTMQ4wDAYDVQQIDAVVbnNldDEOMAwGA1UEBwwFVW5zZXQxDjAMBgNVBAoMBVVuc2V0MRgwFgYDVQQDDA93d3cuZXhhbXBsZS5jb20CAQEwBwYFKw4DAhowDQYJKoZIhvcNAQEBBQAEggEA2Vh4TSthqnLXNqulUjYiCskK-jyBAqM4M1b6J0oT0K5iX85jWfUmUVesqqTu9saDJyh7FE6HnCCeJBJii2GVHTnJA9WrHOKY4VtCSLRya-a1ld3k6n9AzhCO3JrgRMazxiQc4zMigePgbI9poaAYsEc0VWq6U1NiUQ-CG+uLTZS6FG2psMc1jE35P3r-3O-5Wg+uHcj3zOUIcCL0aF6vv-fVV-TSKTSEaX8wNYisGgyWVBualnXWSK5VP1gKFQNgqbDBxI9G4nBpDIEwLlJTzyU7fwLAcF-PUc6NmcT0aZYIfHb6EBVkznRGqf36n1LdVeI3RkbWwTEoyoAQoVYc0g==' -H 'Content-Type: application/octet-stream' http://172.16.32.37:9292/v1/images/36f73756-3132-457d-820e-931e1e973bd8 log_curl_request /usr/lib/python2.7/site-packages/glanceclient/common/http.py:142 >2014-07-06 10:38:25.573 18332 DEBUG glanceclient.common.http [-] >HTTP/1.1 200 OK >content-length: 25165824 >x-image-meta-status: active >x-image-meta-owner: 36ece03b5a6845c9b40b23aac94ab9ec >x-image-meta-name: cirros-0.3.2-x86_64-uec >x-image-meta-container_format: ami >x-image-meta-created_at: 2014-07-06T14:13:22 >etag: 4eada48c2843d2a262c814ddc92ecf2c >location: http://172.16.32.37:9292/v1/images/36f73756-3132-457d-820e-931e1e973bd8 >x-image-meta-min_ram: 0 >x-image-meta-updated_at: 2014-07-06T14:13:23 >x-image-meta-id: 36f73756-3132-457d-820e-931e1e973bd8 >x-image-meta-property-ramdisk_id: f190f25a-c45c-4e20-967e-3e64cdf16211 >date: Sun, 06 Jul 2014 14:38:26 GMT >x-image-meta-property-kernel_id: d94f71c2-6d07-441d-9c3a-2cb3a94c9b5a >x-openstack-request-id: req-2f96fe57-df1e-46f5-987d-e0a210da2110 >x-image-meta-deleted: False >x-image-meta-checksum: 4eada48c2843d2a262c814ddc92ecf2c >x-image-meta-protected: False >x-image-meta-min_disk: 0 >x-image-meta-size: 25165824 >x-image-meta-is_public: True >content-type: application/octet-stream >x-image-meta-disk_format: ami > log_http_response /usr/lib/python2.7/site-packages/glanceclient/common/http.py:152 >2014-07-06 10:38:25.800 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/378699fccd74fe8791aa53fabb7ff2af52719984.part execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.822 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.823 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "378699fccd74fe8791aa53fabb7ff2af52719984" at /var/lib/nova/instances/locks/nova-378699fccd74fe8791aa53fabb7ff2af52719984 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:38:25.824 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "fetch_func_sync" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:25.825 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "378699fccd74fe8791aa53fabb7ff2af52719984" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:25.825 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "378699fccd74fe8791aa53fabb7ff2af52719984" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:38:25.826 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "378699fccd74fe8791aa53fabb7ff2af52719984" at /var/lib/nova/instances/locks/nova-378699fccd74fe8791aa53fabb7ff2af52719984 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:38:25.826 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "copy_qcow2_image" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:25.827 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/378699fccd74fe8791aa53fabb7ff2af52719984 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.849 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.851 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/378699fccd74fe8791aa53fabb7ff2af52719984 /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.878 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.879 18332 DEBUG nova.virt.disk.api [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Checking if we can resize image /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk. size=1073741824 can_resize_image /usr/lib/python2.7/site-packages/nova/virt/disk/api.py:185 >2014-07-06 10:38:25.879 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.902 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.903 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): qemu-img resize /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk 1073741824 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:38:25.931 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:38:25.932 18332 DEBUG nova.virt.disk.api [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Checking if we can resize filesystem inside /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk. CoW=True is_image_partitionless /usr/lib/python2.7/site-packages/nova/virt/disk/api.py:199 >2014-07-06 10:38:25.932 18332 DEBUG nova.virt.disk.vfs.api [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Instance for image imgfile=/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk imgfmt=qcow2 partition=None instance_for_image /usr/lib/python2.7/site-packages/nova/virt/disk/vfs/api.py:29 >2014-07-06 10:38:25.933 18332 DEBUG nova.virt.disk.vfs.api [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Trying to import guestfs instance_for_image /usr/lib/python2.7/site-packages/nova/virt/disk/vfs/api.py:32 >2014-07-06 10:38:25.947 18332 DEBUG nova.virt.disk.vfs.api [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Using primary VFSGuestFS instance_for_image /usr/lib/python2.7/site-packages/nova/virt/disk/vfs/api.py:39 >2014-07-06 10:38:25.948 18332 DEBUG nova.virt.disk.vfs.guestfs [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Setting up appliance for /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk qcow2 setup /usr/lib/python2.7/site-packages/nova/virt/disk/vfs/guestfs.py:106 >2014-07-06 10:38:27.828 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:38:27.839 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance network_info: |[VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})]| _allocate_network_async /usr/lib/python2.7/site-packages/nova/compute/manager.py:1512 >2014-07-06 10:38:27.896 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:27.896 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:27.912 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:32.110 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.111 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.111 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.111 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:38:32.111 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:38:32.112 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:38:32.112 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:38:32.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7453 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:38:32.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:38:32.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 2 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:38:32.169 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:38:32.223 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:38:32.224 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:38:32.224 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:38:32.241 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:38:32.241 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:38:32.261 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.261 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.261 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:38:32.262 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.262 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.262 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.262 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:38:32.263 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:38:32.263 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:38:32.283 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Skipping network cache update for instance because it is Building. _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4843 >2014-07-06 10:38:32.283 18332 DEBUG nova.compute.manager [-] Didn't find any instances for network info cache update. _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4895 >2014-07-06 10:38:32.283 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 56.78 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:38:53.019 18332 DEBUG nova.virt.disk.vfs.guestfs [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Mount guest OS image /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk partition None setup_os_static /usr/lib/python2.7/site-packages/nova/virt/disk/vfs/guestfs.py:52 >2014-07-06 10:39:00.025 18332 DEBUG nova.virt.disk.vfs.guestfs [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Tearing down appliance teardown /usr/lib/python2.7/site-packages/nova/virt/disk/vfs/guestfs.py:141 >2014-07-06 10:39:00.324 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "378699fccd74fe8791aa53fabb7ff2af52719984" at /var/lib/nova/instances/locks/nova-378699fccd74fe8791aa53fabb7ff2af52719984 lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:39:00.325 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "copy_qcow2_image" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:00.325 18332 DEBUG nova.virt.libvirt.driver [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Start to_xml network_info=[VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] disk_info={'disk_bus': 'virtio', 'cdrom_bus': 'ide', 'mapping': {'disk': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': 'vda'}, 'root': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': 'vda'}}} image_meta={u'status': u'active', u'name': u'cirros-0.3.2-x86_64-uec', u'deleted': False, u'container_format': u'ami', u'created_at': u'2014-07-06T14:13:22.000000', u'disk_format': u'ami', u'updated_at': u'2014-07-06T14:13:23.000000', u'properties': {u'kernel_id': u'd94f71c2-6d07-441d-9c3a-2cb3a94c9b5a', u'ramdisk_id': u'f190f25a-c45c-4e20-967e-3e64cdf16211'}, u'min_disk': 0, u'min_ram': 0, u'checksum': u'4eada48c2843d2a262c814ddc92ecf2c', u'owner': u'36ece03b5a6845c9b40b23aac94ab9ec', u'is_public': True, u'deleted_at': None, u'id': u'36f73756-3132-457d-820e-931e1e973bd8', u'size': 25165824} rescue=Noneblock_device_info={'block_device_mapping': [], 'root_device_name': '/dev/vda', 'ephemerals': [], 'swap': None} to_xml /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:3436 >2014-07-06 10:39:00.402 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:00.402 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:00.419 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:00.421 18332 DEBUG nova.virt.libvirt.driver [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Path '/var/lib/nova/instances' supports direct I/O _supports_direct_io /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:2414 >2014-07-06 10:39:00.423 18332 DEBUG nova.virt.libvirt.vif [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] vif_type=bridge instance=<nova.objects.instance.Instance object at 0x29caa50> vif=VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None}) get_config /usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py:336 >2014-07-06 10:39:00.424 18332 DEBUG nova.objects.instance [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Lazy-loading `pci_devices' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:39:00.472 18332 DEBUG nova.virt.libvirt.config [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Generated XML ('<domain type="qemu">\n <uuid>b51594ec-9171-489f-9f8c-e60835ba46cc</uuid>\n <name>instance-00000001</name>\n <memory>524288</memory>\n <vcpu>1</vcpu>\n <sysinfo type="smbios">\n <system>\n <entry name="manufacturer">Red Hat</entry>\n <entry name="product">OpenStack Compute</entry>\n <entry name="version">2014.1-7.el7ost</entry>\n <entry name="serial">29bf0200-607d-482a-a484-2d1b6f1330bb</entry>\n <entry name="uuid">b51594ec-9171-489f-9f8c-e60835ba46cc</entry>\n </system>\n </sysinfo>\n <os>\n <type>hvm</type>\n <kernel>/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/kernel</kernel>\n <initrd>/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/ramdisk</initrd>\n <cmdline>root=/dev/vda console=tty0 console=ttyS0</cmdline>\n <smbios mode="sysinfo"/>\n </os>\n <features>\n <acpi/>\n <apic/>\n </features>\n <clock offset="utc"/>\n <devices>\n <disk type="file" device="disk">\n <driver name="qemu" type="qcow2" cache="none"/>\n <source file="/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk"/>\n <target bus="virtio" dev="vda"/>\n </disk>\n <interface type="bridge">\n <mac address="fa:16:3e:54:49:0b"/>\n <model type="virtio"/>\n <driver name="qemu"/>\n <source bridge="br100"/>\n <filterref filter="nova-instance-instance-00000001-fa163e54490b"/>\n </interface>\n <serial type="file">\n <source path="/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/console.log"/>\n </serial>\n <serial type="pty"/>\n <input type="tablet" bus="usb"/>\n <graphics type="vnc" autoport="yes" keymap="en-us" listen="0.0.0.0"/>\n <video>\n <model type="cirrus"/>\n </video>\n </devices>\n</domain>\n',) to_xml /usr/lib/python2.7/site-packages/nova/virt/libvirt/config.py:71 >2014-07-06 10:39:00.472 18332 DEBUG nova.virt.libvirt.driver [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] End to_xml xml=<domain type="qemu"> > <uuid>b51594ec-9171-489f-9f8c-e60835ba46cc</uuid> > <name>instance-00000001</name> > <memory>524288</memory> > <vcpu>1</vcpu> > <sysinfo type="smbios"> > <system> > <entry name="manufacturer">Red Hat</entry> > <entry name="product">OpenStack Compute</entry> > <entry name="version">2014.1-7.el7ost</entry> > <entry name="serial">29bf0200-607d-482a-a484-2d1b6f1330bb</entry> > <entry name="uuid">b51594ec-9171-489f-9f8c-e60835ba46cc</entry> > </system> > </sysinfo> > <os> > <type>hvm</type> > <kernel>/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/kernel</kernel> > <initrd>/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/ramdisk</initrd> > <cmdline>root=/dev/vda console=tty0 console=ttyS0</cmdline> > <smbios mode="sysinfo"/> > </os> > <features> > <acpi/> > <apic/> > </features> > <clock offset="utc"/> > <devices> > <disk type="file" device="disk"> > <driver name="qemu" type="qcow2" cache="none"/> > <source file="/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk"/> > <target bus="virtio" dev="vda"/> > </disk> > <interface type="bridge"> > <mac address="fa:16:3e:54:49:0b"/> > <model type="virtio"/> > <driver name="qemu"/> > <source bridge="br100"/> > <filterref filter="nova-instance-instance-00000001-fa163e54490b"/> > </interface> > <serial type="file"> > <source path="/var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/console.log"/> > </serial> > <serial type="pty"/> > <input type="tablet" bus="usb"/> > <graphics type="vnc" autoport="yes" keymap="en-us" listen="0.0.0.0"/> > <video> > <model type="cirrus"/> > </video> > </devices> ></domain> > to_xml /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:3447 >2014-07-06 10:39:00.474 18332 DEBUG nova.virt.libvirt.vif [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] vif_type=bridge instance=<nova.objects.instance.Instance object at 0x29caa50> vif=VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None}) plug /usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py:592 >2014-07-06 10:39:00.474 18332 DEBUG nova.virt.libvirt.vif [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Ensuring bridge br100 plug_bridge /usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py:408 >2014-07-06 10:39:00.474 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "lock_bridge" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:00.475 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "lock_bridge" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:39:00.475 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "lock_bridge" at /var/lib/nova/tmp/nova-lock_bridge lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:39:00.475 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "ensure_bridge" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:00.475 18332 DEBUG nova.network.linux_net [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Starting Bridge br100 ensure_bridge /usr/lib/python2.7/site-packages/nova/network/linux_net.py:1518 >2014-07-06 10:39:00.476 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addbr br100 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.544 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.545 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl setfd br100 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.597 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.597 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl stp br100 off execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.648 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.649 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set br100 up execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.701 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.701 18332 DEBUG nova.network.linux_net [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Adding interface lo to bridge br100 ensure_bridge /usr/lib/python2.7/site-packages/nova/network/linux_net.py:1531 >2014-07-06 10:39:00.702 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif br100 lo execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.750 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 1 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.751 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set lo up execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.800 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.800 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): ip route show dev lo execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.809 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.809 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): ip addr show dev lo scope global execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.818 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.819 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "lock_bridge" at /var/lib/nova/tmp/nova-lock_bridge lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:39:00.819 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "ensure_bridge" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:00.819 18332 INFO nova.virt.libvirt.firewall [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Called setup_basic_filtering in nwfilter >2014-07-06 10:39:00.820 18332 INFO nova.virt.libvirt.firewall [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Ensuring static filters >2014-07-06 10:39:00.833 18332 DEBUG nova.virt.libvirt.firewall [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] iptables firewall: Setup Basic Filtering setup_basic_filtering /usr/lib/python2.7/site-packages/nova/virt/libvirt/firewall.py:291 >2014-07-06 10:39:00.834 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:00.834 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:39:00.834 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:39:00.834 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "_do_refresh_provider_fw_rules" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:00.848 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:39:00.848 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "_do_refresh_provider_fw_rules" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:00.848 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:00.848 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:39:00.849 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:39:00.849 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "_apply" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:00.849 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.901 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.903 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:00.955 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:00.956 18332 DEBUG nova.network.linux_net [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] IPTablesManager.apply completed with success _apply /usr/lib/python2.7/site-packages/nova/network/linux_net.py:458 >2014-07-06 10:39:00.956 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:39:00.956 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "_apply" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:01.109 18332 DEBUG nova.virt.firewall [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Filters added to instance prepare_instance_filter /usr/lib/python2.7/site-packages/nova/virt/firewall.py:186 >2014-07-06 10:39:01.109 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:01.110 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:39:01.111 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:39:01.111 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "_do_refresh_provider_fw_rules" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:01.186 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:39:01.187 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "_do_refresh_provider_fw_rules" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:01.187 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:01.188 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:39:01.188 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:39:01.189 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "_apply" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:01.190 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:01.302 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:01.304 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:01.424 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:01.425 18332 DEBUG nova.network.linux_net [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] IPTablesManager.apply completed with success _apply /usr/lib/python2.7/site-packages/nova/network/linux_net.py:458 >2014-07-06 10:39:01.426 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:39:01.426 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "_apply" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:01.427 18332 DEBUG nova.virt.firewall [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Provider Firewall Rules refreshed prepare_instance_filter /usr/lib/python2.7/site-packages/nova/virt/firewall.py:188 >2014-07-06 10:39:01.427 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:01.428 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Attempting to grab file lock "iptables" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:178 >2014-07-06 10:39:01.428 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206 >2014-07-06 10:39:01.429 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Got semaphore / lock "_apply" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:01.430 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-save -c execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:01.547 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:01.549 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf iptables-restore -c execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:01.677 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:01.678 18332 DEBUG nova.network.linux_net [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] IPTablesManager.apply completed with success _apply /usr/lib/python2.7/site-packages/nova/network/linux_net.py:458 >2014-07-06 10:39:01.679 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Released file lock "iptables" at /var/lib/nova/tmp/nova-iptables lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:210 >2014-07-06 10:39:01.679 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "_apply" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:02.609 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/vnet0/brport/hairpin_mode execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:02.735 18332 DEBUG nova.openstack.common.processutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:02.737 18332 DEBUG nova.virt.libvirt.driver [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance is running spawn /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:2261 >2014-07-06 10:39:02.745 18332 INFO nova.virt.libvirt.driver [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance spawned successfully. >2014-07-06 10:39:02.746 18332 DEBUG nova.compute.manager [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Checking state _get_power_state /usr/lib/python2.7/site-packages/nova/compute/manager.py:1043 >2014-07-06 10:39:02.752 18332 DEBUG nova.objects.instance [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Lazy-loading `info_cache' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:39:02.892 18332 DEBUG nova.openstack.common.lockutils [req-2bb1ffce-3f41-45e4-91e6-609cc6e50ae5 admin admin] Semaphore / lock released "do_run_instance" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:29.065 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.066 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.066 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.067 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:29.067 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:29.067 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:39:29.067 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:39:29.096 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:29.119 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:29.119 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:29.138 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:29.167 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7256 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:39:29.167 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:39:29.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:39:29.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:39:29.213 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:39:29.214 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:39:29.214 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:39:29.232 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:39:29.232 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:29.254 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.255 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.255 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:39:29.255 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.256 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.256 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._run_pending_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.256 18332 DEBUG nova.compute.manager [-] Cleaning up deleted instances _run_pending_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5682 >2014-07-06 10:39:29.276 18332 DEBUG nova.compute.manager [-] There are 0 instances to clean _run_pending_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5691 >2014-07-06 10:39:29.276 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:29.276 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 2.99 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:39:30.231 18332 DEBUG nova.network.api [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:39:30.344 18332 DEBUG nova.virt.libvirt.driver [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Starting migrate_disk_and_power_off migrate_disk_and_power_off /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:4916 >2014-07-06 10:39:30.349 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:30.369 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:30.370 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:30.387 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:30.390 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Running cmd (subprocess): ssh 172.16.32.40 touch /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/5c919c35fe63448b91f4f119f6791ce3.tmp execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:30.743 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Result was 1 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:30.744 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Running cmd (subprocess): ssh 172.16.32.40 mkdir -p /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:31.060 18332 DEBUG nova.openstack.common.processutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Result was 1 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:31.061 18332 ERROR nova.compute.manager [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Setting instance vm_state to ERROR >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Traceback (most recent call last): >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5566, in _error_out_instance_on_exception >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] yield >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3440, in resize_instance >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] block_device_info) >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4940, in migrate_disk_and_power_off >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] utils.execute('ssh', dest, 'mkdir', '-p', inst_base) >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] File "/usr/lib/python2.7/site-packages/nova/utils.py", line 164, in execute >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] return processutils.execute(*cmd, **kwargs) >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] File "/usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py", line 193, in execute >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] cmd=' '.join(cmd)) >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] ProcessExecutionError: Unexpected error while running command. >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Command: ssh 172.16.32.40 mkdir -p /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Exit code: 1 >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Stdout: 'This account is currently not available.\n' >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Stderr: "Warning: Permanently added '172.16.32.40' (ECDSA) to the list of known hosts.\r\n" >2014-07-06 10:39:31.061 18332 TRACE nova.compute.manager [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] >2014-07-06 10:39:31.131 18332 DEBUG nova.openstack.common.lockutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:31.132 18332 DEBUG nova.openstack.common.lockutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Got semaphore / lock "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:31.151 18332 DEBUG nova.openstack.common.lockutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Semaphore / lock released "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:31.233 18332 DEBUG nova.openstack.common.lockutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:31.233 18332 DEBUG nova.openstack.common.lockutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Got semaphore / lock "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:31.250 18332 DEBUG nova.openstack.common.lockutils [req-07630bc4-cdfd-4df8-80ee-133f8847c283 admin admin] Semaphore / lock released "update_usage" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:31.258 18332 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: Unexpected error while running command. >Command: ssh 172.16.32.40 mkdir -p /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc >Exit code: 1 >Stdout: 'This account is currently not available.\n' >Stderr: "Warning: Permanently added '172.16.32.40' (ECDSA) to the list of known hosts.\r\n" >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last): >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher incoming.message)) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/exception.py", line 88, in wrapped >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher payload) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__ >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/exception.py", line 71, in wrapped >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher return f(self, context, *args, **kw) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 280, in decorated_function >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher pass >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__ >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 266, in decorated_function >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 333, in decorated_function >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher function(self, context, *args, **kwargs) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 254, in decorated_function >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher break >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__ >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 235, in decorated_function >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 309, in decorated_function >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher e, sys.exc_info()) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__ >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 296, in decorated_function >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher return function(self, context, *args, **kwargs) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3440, in resize_instance >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher block_device_info) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4940, in migrate_disk_and_power_off >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher utils.execute('ssh', dest, 'mkdir', '-p', inst_base) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/utils.py", line 164, in execute >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher return processutils.execute(*cmd, **kwargs) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py", line 193, in execute >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher cmd=' '.join(cmd)) >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher ProcessExecutionError: Unexpected error while running command. >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher Command: ssh 172.16.32.40 mkdir -p /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher Exit code: 1 >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher Stdout: 'This account is currently not available.\n' >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher Stderr: "Warning: Permanently added '172.16.32.40' (ECDSA) to the list of known hosts.\r\n" >2014-07-06 10:39:31.258 18332 TRACE oslo.messaging.rpc.dispatcher >2014-07-06 10:39:31.260 18332 ERROR oslo.messaging._drivers.common [-] Returning exception Unexpected error while running command. >Command: ssh 172.16.32.40 mkdir -p /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc >Exit code: 1 >Stdout: 'This account is currently not available.\n' >Stderr: "Warning: Permanently added '172.16.32.40' (ECDSA) to the list of known hosts.\r\n" to caller >2014-07-06 10:39:31.260 18332 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n', ' File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, **new_args)\n', ' File "/usr/lib/python2.7/site-packages/nova/exception.py", line 88, in wrapped\n payload)\n', ' File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.7/site-packages/nova/exception.py", line 71, in wrapped\n return f(self, context, *args, **kw)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 280, in decorated_function\n pass\n', ' File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 266, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 333, in decorated_function\n function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 254, in decorated_function\n break\n', ' File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 235, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 309, in decorated_function\n e, sys.exc_info())\n', ' File "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py", line 68, in __exit__\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 296, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 3440, in resize_instance\n block_device_info)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4940, in migrate_disk_and_power_off\n utils.execute(\'ssh\', dest, \'mkdir\', \'-p\', inst_base)\n', ' File "/usr/lib/python2.7/site-packages/nova/utils.py", line 164, in execute\n return processutils.execute(*cmd, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py", line 193, in execute\n cmd=\' \'.join(cmd))\n', 'ProcessExecutionError: Unexpected error while running command.\nCommand: ssh 172.16.32.40 mkdir -p /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc\nExit code: 1\nStdout: \'This account is currently not available.\\n\'\nStderr: "Warning: Permanently added \'172.16.32.40\' (ECDSA) to the list of known hosts.\\r\\n"\n'] >2014-07-06 10:39:32.263 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.264 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.264 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.264 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:39:32.264 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:39:32.265 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:39:32.265 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:39:32.299 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:32.315 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:32.316 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:39:32.334 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:39:32.365 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7255 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:39:32.365 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:39:32.366 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:39:32.366 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:39:32.420 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:39:32.420 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:39:32.421 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:39:32.421 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:39:32.440 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:39:32.440 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:39:32.462 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.462 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.462 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:39:32.463 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.463 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.463 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.463 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:39:32.464 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:39:32.464 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:39:32.486 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:39:32.698 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:39:32.711 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:39:32.711 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:40:32.712 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.712 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.712 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.713 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:40:32.713 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:40:32.713 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:40:32.713 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:40:32.737 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:40:32.750 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:40:32.751 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:40:32.762 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:40:32.787 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7253 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:40:32.787 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:40:32.787 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:40:32.787 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:40:32.839 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:40:32.840 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:40:32.840 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:40:32.840 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:40:32.856 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:40:32.856 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:40:32.874 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.874 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.874 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:40:32.874 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.875 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.875 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.875 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:40:32.875 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:40:32.875 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:40:32.894 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:40:33.074 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:40:33.083 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:40:33.084 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:41:33.085 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.087 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.088 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.088 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:41:33.089 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:41:33.089 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:41:33.090 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:41:33.154 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:41:33.180 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:41:33.181 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:41:33.203 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:41:33.260 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7249 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:41:33.260 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:41:33.261 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:41:33.261 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:41:33.317 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:41:33.318 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:41:33.318 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:41:33.318 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:41:33.336 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:41:33.336 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:41:33.356 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.357 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.358 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:41:33.358 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.359 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.359 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.360 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:41:33.360 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:41:33.361 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:41:33.386 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:41:33.565 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:41:33.576 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:41:33.576 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:42:33.577 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.578 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.578 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.579 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:42:33.579 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:42:33.579 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:42:33.580 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:42:33.627 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:42:33.650 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:42:33.652 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:42:33.671 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:42:33.718 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7219 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:42:33.718 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:42:33.719 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:42:33.719 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:42:33.777 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:42:33.778 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:42:33.778 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:42:33.779 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:42:33.796 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:42:33.797 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:42:33.817 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.817 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.817 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:42:33.818 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.818 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.819 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.819 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:42:33.820 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:42:33.820 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:42:33.842 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:42:34.027 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:42:34.039 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:42:34.039 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:43:34.040 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.041 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.041 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.042 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:43:34.042 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:43:34.043 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:43:34.043 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:43:34.105 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:43:34.133 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:43:34.134 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:43:34.156 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:43:34.213 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7120 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:43:34.214 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:43:34.214 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:43:34.214 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:43:34.276 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:43:34.276 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:43:34.277 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:43:34.277 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:43:34.298 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:43:34.299 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:43:34.320 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.321 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.321 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:43:34.322 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.322 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.323 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.323 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:43:34.324 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:43:34.324 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:43:34.347 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:43:34.519 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:43:34.531 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:43:34.531 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 54.40 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:44:28.936 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:28.937 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:28.937 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:28.938 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:44:28.938 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:44:28.939 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:44:28.939 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:44:28.983 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:44:28.997 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:44:28.997 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:44:29.008 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:44:29.030 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7119 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:44:29.030 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:44:29.030 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:44:29.031 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:44:29.080 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:44:29.081 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:44:29.081 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:44:29.081 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:44:29.095 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:44:29.096 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:44:29.114 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.114 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._cleanup_running_deleted_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.136 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.136 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:44:29.136 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.136 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.136 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_bandwidth_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.137 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._run_pending_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.137 18332 DEBUG nova.compute.manager [-] Cleaning up deleted instances _run_pending_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5682 >2014-07-06 10:44:29.153 18332 DEBUG nova.compute.manager [-] There are 0 instances to clean _run_pending_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5691 >2014-07-06 10:44:29.154 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:29.154 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 5.17 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:44:34.325 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.325 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.326 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.327 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:44:34.327 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:44:34.327 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:44:34.328 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:44:34.383 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:44:34.407 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:44:34.408 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:44:34.431 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:44:34.488 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7120 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:44:34.489 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:44:34.489 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:44:34.490 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:44:34.554 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:44:34.554 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:44:34.555 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:44:34.555 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:44:34.574 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:44:34.574 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:44:34.597 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.597 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.598 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:44:34.598 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.599 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.600 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.600 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:34.601 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:44:34.601 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:44:34.624 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:44:34.808 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:44:34.820 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:44:34.821 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 21.12 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:44:55.938 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:55.939 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:55.940 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:55.940 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:44:55.941 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:44:55.941 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:44:55.942 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:44:55.998 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:44:56.021 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:44:56.023 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:44:56.044 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:44:56.101 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7120 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:44:56.102 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:44:56.102 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:44:56.103 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:44:56.161 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:44:56.161 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:44:56.162 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:44:56.162 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:44:56.180 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:44:56.180 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:44:56.205 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:56.205 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:56.206 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:44:56.206 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:56.207 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._sync_power_states run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:56.291 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:56.291 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:44:56.292 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 38.31 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:45:34.601 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.602 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.602 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.602 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:45:34.603 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:45:34.603 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:45:34.603 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:45:34.629 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:45:34.642 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:45:34.643 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:45:34.655 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:45:34.680 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7119 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:45:34.680 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:45:34.680 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:45:34.681 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:45:34.731 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:45:34.732 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:45:34.732 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:45:34.732 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:45:34.748 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:45:34.749 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:45:34.766 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.766 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.767 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:45:34.767 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.767 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.767 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.768 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:45:34.768 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:45:34.768 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:45:34.790 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:45:35.027 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:45:35.036 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:45:35.036 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:46:35.037 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.038 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.038 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.039 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:46:35.039 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:46:35.039 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:46:35.039 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:46:35.083 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:46:35.102 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:46:35.103 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:46:35.121 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:46:35.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7119 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:46:35.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:46:35.168 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:46:35.169 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:46:35.222 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:46:35.222 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:46:35.223 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:46:35.223 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:46:35.240 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:46:35.241 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:46:35.259 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.260 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.260 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:46:35.261 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.261 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.262 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.262 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:46:35.262 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:46:35.263 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:46:35.286 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:46:35.463 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:46:35.474 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:46:35.475 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:47:35.476 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.476 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.477 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.477 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:47:35.478 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:47:35.478 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:47:35.478 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:47:35.526 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:47:35.547 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:47:35.548 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:47:35.567 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:47:35.615 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7120 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:47:35.615 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:47:35.616 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:47:35.616 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:47:35.667 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:47:35.668 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:47:35.668 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:47:35.668 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:47:35.684 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:47:35.685 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:47:35.705 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.706 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.706 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:47:35.706 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.707 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.707 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.708 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:47:35.708 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:47:35.708 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:47:35.731 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:47:35.899 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:47:35.912 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:47:35.912 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 60.00 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132 >2014-07-06 10:48:35.913 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:35.913 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._instance_usage_audit run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:35.913 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:35.914 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:168 >2014-07-06 10:48:35.914 18332 DEBUG nova.openstack.common.lockutils [-] Got semaphore / lock "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:248 >2014-07-06 10:48:35.914 18332 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources >2014-07-06 10:48:35.914 18332 DEBUG nova.virt.libvirt.driver [-] Updating host stats update_status /usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:5280 >2014-07-06 10:48:35.938 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:48:35.950 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:48:35.951 18332 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/b51594ec-9171-489f-9f8c-e60835ba46cc/disk execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:154 >2014-07-06 10:48:35.961 18332 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:187 >2014-07-06 10:48:35.984 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 7120 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:409 >2014-07-06 10:48:35.985 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 38 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:410 >2014-07-06 10:48:35.985 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: free VCPUs: 1 _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:415 >2014-07-06 10:48:35.985 18332 DEBUG nova.compute.resource_tracker [-] Hypervisor: assignable PCI devices: [] _report_hypervisor_resource_view /usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py:422 >2014-07-06 10:48:36.035 18332 WARNING nova.compute.resource_tracker [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Instance not resizing, skipping migration. >2014-07-06 10:48:36.035 18332 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 6800 >2014-07-06 10:48:36.035 18332 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 38 >2014-07-06 10:48:36.035 18332 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1 >2014-07-06 10:48:36.051 18332 INFO nova.compute.resource_tracker [-] Compute_service record updated for jhenner-node-7v0-3.novalocal:jhenner-node-7v0-3.novalocal >2014-07-06 10:48:36.051 18332 DEBUG nova.openstack.common.lockutils [-] Semaphore / lock released "update_available_resource" inner /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:252 >2014-07-06 10:48:36.068 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rebooting_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:36.069 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._reclaim_queued_deletes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:36.069 18332 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... _reclaim_queued_deletes /usr/lib/python2.7/site-packages/nova/compute/manager.py:5404 >2014-07-06 10:48:36.069 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:36.069 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_rescued_instances run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:36.069 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._check_instance_build_time run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:36.070 18332 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._heal_instance_info_cache run_periodic_tasks /usr/lib/python2.7/site-packages/nova/openstack/common/periodic_task.py:178 >2014-07-06 10:48:36.070 18332 DEBUG nova.compute.manager [-] Starting heal instance info cache _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4829 >2014-07-06 10:48:36.070 18332 DEBUG nova.compute.manager [-] Rebuilding the list of instances to heal _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4833 >2014-07-06 10:48:36.091 18332 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b51594ec-9171-489f-9f8c-e60835ba46cc obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:519 >2014-07-06 10:48:36.261 18332 DEBUG nova.network.api [-] Updating cache with info: [VIF({'ovs_interfaceid': None, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'192.168.32.2'})], 'version': 4, 'meta': {u'dhcp_server': u'192.168.32.1'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'192.168.32.0/22', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'192.168.32.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': None}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'should_create_bridge': True, u'bridge_interface': u'lo'}, 'id': u'a1146a4c-678e-4b99-905b-0c9e1fc02ac0', 'label': u'novanetwork'}), 'devname': None, 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:54:49:0b', 'active': False, 'type': u'bridge', 'id': u'8f9db434-cd40-4961-8829-7464bc3fb5d1', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/site-packages/nova/network/api.py:74 >2014-07-06 10:48:36.272 18332 DEBUG nova.compute.manager [-] [instance: b51594ec-9171-489f-9f8c-e60835ba46cc] Updated the network info_cache for instance _heal_instance_info_cache /usr/lib/python2.7/site-packages/nova/compute/manager.py:4890 >2014-07-06 10:48:36.272 18332 DEBUG nova.openstack.common.loopingcall [-] Dynamic looping call sleeping for 53.07 seconds _inner /usr/lib/python2.7/site-packages/nova/openstack/common/loopingcall.py:132
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 914648
: 914967