Attachment 914967 Details for Bug 914648 – migration fails

migration fails

other.log (text/x-log), 181.05 KB, created by Jaroslav Henner on 2014-07-06 14:51:42 UTC

(hide)

Description:

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

Actions: View

Attachments on bug 914648: 914967