Attachment 911547 Details for Bug 1112360 – nova compute log - normal output (no debug)

nova compute log - normal output (no debug)

compute.log (text/plain), 17.67 KB, created by Judd Maltin on 2014-06-23 18:55:58 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Judd Maltin

Created: 2014-06-23 18:55:58 UTC

Size: 17.67 KB

patch

obsolete

>2014-06-23 07:07:44.790 2178 INFO nova.openstack.common.service [-] Caught SIGTERM, exiting
>2014-06-23 07:07:45.662 453 INFO nova.openstack.common.periodic_task [-] Skipping periodic task _periodic_update_dns because its interval is negative
>2014-06-23 07:07:45.706 453 INFO nova.virt.driver [-] Loading compute driver 'libvirt.LibvirtDriver'
>2014-06-23 07:07:45.797 453 INFO nova.openstack.common.rpc.impl_qpid [req-af9b6cc0-6944-4037-8c0b-5bc492f189c8 None None] Connected to AMQP server on 192.168.124.51:5672
>2014-06-23 07:07:45.810 453 INFO nova.openstack.common.rpc.impl_qpid [req-af9b6cc0-6944-4037-8c0b-5bc492f189c8 None None] Connected to AMQP server on 192.168.124.51:5672
>2014-06-23 07:07:45.855 453 AUDIT nova.service [-] Starting compute node (version 2013.2.3-7.el6ost)
>2014-06-23 07:07:46.197 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:07:46.630 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 7247
>2014-06-23 07:07:46.630 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:07:46.630 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 0
>2014-06-23 07:07:46.706 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:07:46.740 453 INFO nova.openstack.common.rpc.impl_qpid [-] Connected to AMQP server on 192.168.124.51:5672
>2014-06-23 07:08:18.897 453 AUDIT nova.compute.manager [req-9193b87f-6387-44ed-9d91-52bbe36a46bb 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: 78f79c4a-7306-48f2-977c-56802f59e705] Get console output
>2014-06-23 07:08:18.939 453 ERROR nova.openstack.common.rpc.amqp [req-9193b87f-6387-44ed-9d91-52bbe36a46bb 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] Exception during message handling
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     **args)
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     result = getattr(proxyobj, method)(ctxt, **kwargs)
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 90, in wrapped
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     payload)
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/exception.py", line 73, in wrapped
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     return f(self, context, *args, **kw)
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 259, in decorated_function
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3521, in get_console_output
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     output = self.driver.get_console_output(instance)
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 2122, in get_console_output
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     virt_dom = self._lookup_by_name(instance['name'])
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 3129, in _lookup_by_name
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp     raise exception.InstanceNotFound(instance_id=instance_name)
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp InstanceNotFound: Instance instance-00000016 could not be found.
>2014-06-23 07:08:18.939 453 TRACE nova.openstack.common.rpc.amqp 
>2014-06-23 07:08:18.966 453 ERROR nova.openstack.common.rpc.common [req-9193b87f-6387-44ed-9d91-52bbe36a46bb 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] Returning exception Instance instance-00000016 could not be found. to caller
>2014-06-23 07:08:18.967 453 ERROR nova.openstack.common.rpc.common [req-9193b87f-6387-44ed-9d91-52bbe36a46bb 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/amqp.py", line 461, in _process_data\n    **args)\n', '  File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/dispatcher.py", line 172, in dispatch\n    result = getattr(proxyobj, method)(ctxt, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 90, in wrapped\n    payload)\n', '  File "/usr/lib/python2.6/site-packages/nova/exception.py", line 73, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 259, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/nova/compute/manager.py", line 3521, in get_console_output\n    output = self.driver.get_console_output(instance)\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 2122, in get_console_output\n    virt_dom = self._lookup_by_name(instance[\'name\'])\n', '  File "/usr/lib/python2.6/site-packages/nova/virt/libvirt/driver.py", line 3129, in _lookup_by_name\n    raise exception.InstanceNotFound(instance_id=instance_name)\n', 'InstanceNotFound: Instance instance-00000016 could not be found.\n']
>2014-06-23 07:08:31.994 453 INFO nova.ceilometer.notifier [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] processing compute.instance.delete.start
>2014-06-23 07:08:32.165 453 INFO ceilometer.compute.pollsters.net [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] checking instance 22
>2014-06-23 07:08:32.173 453 INFO ceilometer.compute.pollsters.net [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] checking instance 22
>2014-06-23 07:08:32.179 453 INFO ceilometer.compute.pollsters.net [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] checking instance 22
>2014-06-23 07:08:32.187 453 INFO ceilometer.compute.pollsters.net [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] checking instance 22
>2014-06-23 07:08:32.194 453 INFO ceilometer.compute.pollsters.cpu [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] checking instance 22
>2014-06-23 07:08:32.211 453 AUDIT nova.compute.manager [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: 78f79c4a-7306-48f2-977c-56802f59e705] Terminating instance
>2014-06-23 07:08:32.431 453 ERROR nova.virt.libvirt.driver [-] [instance: 78f79c4a-7306-48f2-977c-56802f59e705] During wait destroy, instance disappeared.
>2014-06-23 07:08:32.434 453 INFO nova.virt.libvirt.firewall [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: 78f79c4a-7306-48f2-977c-56802f59e705] Attempted to unfilter instance which is not filtered
>2014-06-23 07:08:32.560 453 INFO nova.virt.libvirt.driver [req-dce536ab-3bd2-4b4c-88fa-68d882d0a965 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: 78f79c4a-7306-48f2-977c-56802f59e705] Deletion of /var/lib/nova/instances/78f79c4a-7306-48f2-977c-56802f59e705 complete
>2014-06-23 07:08:43.782 453 AUDIT nova.compute.resource_tracker [req-cbbfbf08-ecff-425c-89cd-7e6143a4919f None None] Auditing locally available compute resources
>2014-06-23 07:08:44.046 453 AUDIT nova.compute.resource_tracker [req-cbbfbf08-ecff-425c-89cd-7e6143a4919f None None] Free ram (MB): 15439
>2014-06-23 07:08:44.046 453 AUDIT nova.compute.resource_tracker [req-cbbfbf08-ecff-425c-89cd-7e6143a4919f None None] Free disk (GB): 49
>2014-06-23 07:08:44.047 453 AUDIT nova.compute.resource_tracker [req-cbbfbf08-ecff-425c-89cd-7e6143a4919f None None] Free VCPUS: 2
>2014-06-23 07:08:44.100 453 INFO nova.compute.resource_tracker [req-cbbfbf08-ecff-425c-89cd-7e6143a4919f None None] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:09:22.538 453 AUDIT nova.compute.manager [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Starting instance...
>2014-06-23 07:09:22.813 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Attempting claim: memory 2048 MB, disk 40 GB, VCPUs 1
>2014-06-23 07:09:22.813 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Total Memory: 15951 MB, used: 512.00 MB
>2014-06-23 07:09:22.814 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Memory limit: 23926.50 MB, free: 23414.50 MB
>2014-06-23 07:09:22.814 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Total Disk: 49 GB, used: 0.00 GB
>2014-06-23 07:09:22.814 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Disk limit not specified, defaulting to unlimited
>2014-06-23 07:09:22.815 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Total CPU: 2 VCPUs, used: 0.00 VCPUs
>2014-06-23 07:09:22.815 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] CPU limit not specified, defaulting to unlimited
>2014-06-23 07:09:22.816 453 AUDIT nova.compute.claims [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Claim successful
>2014-06-23 07:09:23.091 453 INFO nova.openstack.common.rpc.impl_qpid [-] Connected to AMQP server on 192.168.124.51:5672
>2014-06-23 07:09:23.339 453 INFO nova.virt.libvirt.driver [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Creating image
>2014-06-23 07:09:42.009 453 WARNING nova.virt.disk.vfs.guestfs [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] Failed to close augeas aug_close: do_aug_close: you must call 'aug-init' first to initialize Augeas
>2014-06-23 07:09:44.217 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:09:44.494 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:09:44.495 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:09:44.495 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:09:44.552 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:09:51.910 453 INFO nova.virt.libvirt.driver [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Injecting key into image 7835b037-514e-4a24-9f9c-36431c0ea7ff
>2014-06-23 07:10:02.679 453 INFO nova.virt.libvirt.firewall [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Called setup_basic_filtering in nwfilter
>2014-06-23 07:10:02.680 453 INFO nova.virt.libvirt.firewall [req-0bd7f786-3e8f-48b9-b0c0-13b82bcad3ba 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Ensuring static filters
>2014-06-23 07:10:04.367 453 INFO nova.compute.manager [-] Lifecycle event 0 on VM ae71dde5-6dfe-486f-bbf1-5d71bd2cf167
>2014-06-23 07:10:04.523 453 INFO nova.compute.manager [req-d8ef072a-a11f-4ad9-9f57-5b2b2820fac1 None None] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] During sync_power_state the instance has a pending task. Skip.
>2014-06-23 07:10:04.562 453 INFO nova.virt.libvirt.driver [-] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Instance spawned successfully.
>2014-06-23 07:10:44.840 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:10:45.226 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:10:45.227 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:10:45.227 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:10:45.278 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:11:40.747 453 AUDIT nova.compute.manager [req-040e8818-b15e-4a54-aad0-f3f42b375dfc 939a54b23956453e9d0c770870874a44 4648f46a5b4b422f90d311db1df637c1] [instance: ae71dde5-6dfe-486f-bbf1-5d71bd2cf167] Get console output
>2014-06-23 07:11:45.558 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:11:45.923 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:11:45.924 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:11:45.924 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:11:45.970 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:12:45.764 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:12:46.239 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:12:46.239 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:12:46.240 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:12:46.285 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:13:46.588 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:13:46.959 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:13:46.959 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:13:46.959 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:13:47.005 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:14:47.281 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:14:47.724 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:14:47.725 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:14:47.725 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:14:47.770 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:15:48.040 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:15:48.405 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:15:48.405 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:15:48.405 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:15:48.454 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:16:48.728 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:16:49.096 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:16:49.097 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:16:49.097 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:16:49.142 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:17:45.744 453 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
>2014-06-23 07:17:46.169 453 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 13391
>2014-06-23 07:17:46.169 453 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 9
>2014-06-23 07:17:46.170 453 AUDIT nova.compute.resource_tracker [-] Free VCPUS: 1
>2014-06-23 07:17:46.219 453 INFO nova.compute.resource_tracker [-] Compute_service record updated for openshift2.rcbd.lab:openshift2.rcbd.lab
>2014-06-23 07:17:46.256 453 INFO nova.compute.manager [-] Updating bandwidth usage cache
>2014-06-23 07:17:46.295 453 WARNING nova.compute.manager [-] Bandwidth usage not supported by hypervisor.

Actions: View

Attachments on bug 1112360: 911547