Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

Hi

The complete compute log from on of the failed attempts:

2011-07-11 19:04:50,445 DEBUG nova.rpc [-] received {u'_context_request_id': u'-RIGJJ30OIN-FTNX4TU4', u'_context_read_deleted': False, u'args': {u'instance_id': 26, u'injected_files': None, u'availability_zone': None}, u'_context_is_admin': True, u'_context_timestamp': u'2011-07-11T18:04:49Z', u'_context_user': u'howard', u'method': u'run_instance', u'_context_project': u'cloud5', u'_context_remote_address': u'192.168.1.100'} from (pid=1324) _receive /usr/lib/pymodules/python2.7/nova/rpc.py:167 2011-07-11 19:04:50,447 DEBUG nova.rpc [-] unpacked context: {'timestamp': u'2011-07-11T18:04:49Z', 'remote_address': u'192.168.1.100', 'project': u'cloud5', 'is_admin': True, 'user': u'howard', 'request_id': u'-RIGJJ30OIN-FTNX4TU4', 'read_deleted': False} from (pid=1324) _unpack_context /usr/lib/pymodules/python2.7/nova/rpc.py:331 2011-07-11 19:04:50,535 AUDIT nova.compute.manager [-RIGJJ30OIN-FTNX4TU4 howard cloud5] instance 26: starting... 2011-07-11 19:04:50,750 DEBUG nova.rpc [-] Making asynchronous call on network.nimbus ... from (pid=1324) call /usr/lib/pymodules/python2.7/nova/rpc.py:350 2011-07-11 19:04:50,751 DEBUG nova.rpc [-] MSG_ID is 74c4383a033f4aa5b6255e243481edf9 from (pid=1324) call /usr/lib/pymodules/python2.7/nova/rpc.py:353 2011-07-11 19:04:51,396 DEBUG nova.utils [-] Attempting to grab semaphore "ensure_bridge" for method "ensure_bridge"... from (pid=1324) inner /usr/lib/pymodules/python2.7/nova/utils.py:594 2011-07-11 19:04:51,396 DEBUG nova.utils [-] Attempting to grab file lock "ensure_bridge" for method "ensure_bridge"... from (pid=1324) inner /usr/lib/pymodules/python2.7/nova/utils.py:599 2011-07-11 19:04:51,397 DEBUG nova.utils [-] Running cmd (subprocess): ip link show dev br100 from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:51,418 DEBUG nova.utils [-] Running cmd (subprocess): sudo route -n from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:51,462 DEBUG nova.utils [-] Running cmd (subprocess): sudo ip addr show dev eth0 scope global from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:51,500 DEBUG nova.utils [-] Running cmd (subprocess): sudo brctl addif br100 eth0 from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:51,534 DEBUG nova.utils [-] Result was 1 from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:166 2011-07-11 19:04:51,641 DEBUG nova.virt.libvirt_conn [-] instance instance-0000001a: starting toXML method from (pid=1324) to_xml /usr/lib/pymodules/python2.7/nova/virt/libvirt_conn.py:996 2011-07-11 19:04:51,755 DEBUG nova.virt.libvirt_conn [-] instance instance-0000001a: finished toXML method from (pid=1324) to_xml /usr/lib/pymodules/python2.7/nova/virt/libvirt_conn.py:1041 2011-07-11 19:04:51,878 INFO nova [-] called setup_basic_filtering in nwfilter 2011-07-11 19:04:51,879 INFO nova [-] ensuring static filters 2011-07-11 19:04:51,954 INFO nova [-] <nova.db.sqlalchemy.models.securitygroupingressrule object="" at="" 0x3997110=""> 2011-07-11 19:04:51,955 INFO nova [-] <nova.db.sqlalchemy.models.securitygroupingressrule object="" at="" 0x3997cd0=""> 2011-07-11 19:04:51,965 DEBUG nova.utils [-] Attempting to grab semaphore "iptables" for method "apply"... from (pid=1324) inner /usr/lib/pymodules/python2.7/nova/utils.py:594 2011-07-11 19:04:51,966 DEBUG nova.utils [-] Attempting to grab file lock "iptables" for method "apply"... from (pid=1324) inner /usr/lib/pymodules/python2.7/nova/utils.py:599 2011-07-11 19:04:51,977 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-save -t filter from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,021 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-restore from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,069 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-save -t nat from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,119 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-restore from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,215 DEBUG nova.utils [-] Running cmd (subprocess): mkdir -p /var/lib/nova/instances/instance-0000001a/ from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,239 INFO nova.virt.libvirt_conn [-] instance instance-0000001a: Creating image 2011-07-11 19:04:52,371 DEBUG nova.utils [-] Attempting to grab semaphore "00000001" for method "call_if_not_exists"... from (pid=1324) inner /usr/lib/pymodules/python2.7/nova/utils.py:594 2011-07-11 19:04:52,371 DEBUG nova.utils [-] Running cmd (subprocess): cp /var/lib/nova/instances/_base/00000001 /var/lib/nova/instances/instance-0000001a/kernel from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,451 DEBUG nova.utils [-] Attempting to grab semaphore "00000002" for method "call_if_not_exists"... from (pid=1324) inner /usr/lib/pymodules/python2.7/nova/utils.py:594 2011-07-11 19:04:52,452 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img create -f qcow2 -o cluster_size=2M,backing_file=/var/lib/nova/instances/_base/00000002 /var/lib/nova/instances/instance-0000001a/disk from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,654 DEBUG nova.utils [-] Attempting to grab semaphore "local_20" for method "call_if_not_exists"... from (pid=1324) inner /usr/lib/pymodules/python2.7/nova/utils.py:594 2011-07-11 19:04:52,655 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img create -f qcow2 -o cluster_size=2M,backing_file=/var/lib/nova/instances/_base/local_20 /var/lib/nova/instances/instance-0000001a/disk.local from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:52,837 INFO nova.virt.libvirt_conn [-] instance instance-0000001a: injecting key into image 2 2011-07-11 19:04:52,859 DEBUG nova.utils [-] Running cmd (subprocess): sudo qemu-nbd -c /dev/nbd15 /var/lib/nova/instances/instance-0000001a/disk from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:53,930 DEBUG nova.utils [-] Running cmd (subprocess): sudo tune2fs -c 0 -i 0 /dev/nbd15 from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:53,975 DEBUG nova.utils [-] Result was 1 from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:166 2011-07-11 19:04:53,976 DEBUG nova.utils [-] Running cmd (subprocess): sudo qemu-nbd -d /dev/nbd15 from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:150 2011-07-11 19:04:54,024 WARNING nova.virt.libvirt_conn [-] instance instance-0000001a: ignoring error injecting data into image 2 (Unexpected error while running command. Command: sudo tune2fs -c 0 -i 0 /dev/nbd15 Exit code: 1 Stdout: 'tune2fs 1.41.14 (22-Dec-2010)\n' Stderr: "tune2fs: Invalid argument while trying to open /dev/nbd15\nCouldn't find valid filesystem superblock.\n") 2011-07-11 19:05:27,057 ERROR nova.exception [-] Uncaught exception (nova.exception): TRACE: Traceback (most recent call last): (nova.exception): TRACE: File "/usr/lib/pymodules/python2.7/nova/exception.py", line 120, in _wrap (nova.exception): TRACE: return f(args, *kw) (nova.exception): TRACE: File "/usr/lib/pymodules/python2.7/nova/virt/libvirt_conn.py", line 617, in spawn (nova.exception): TRACE: domain = self._create_new_domain(xml) (nova.exception): TRACE: File "/usr/lib/pymodules/python2.7/nova/virt/libvirt_conn.py", line 1079, in _create_new_domain (nova.exception): TRACE: domain.createWithFlags(launch_flags) (nova.exception): TRACE: File "/usr/lib/python2.7/dist-packages/libvirt.py", line 337, in createWithFlags (nova.exception): TRACE: if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self) (nova.exception): TRACE: libvirtError: internal error process exited while connecting to monitor: char device redirected to /dev/pts/1 (nova.exception): TRACE: qemu: could not load kernel '/var/lib/nova/instances/instance-0000001a/kernel': Inappropriate ioctl for device (nova.exception): TRACE: (nova.exception): TRACE: 2011-07-11 19:05:27,058 ERROR nova.compute.manager [-RIGJJ30OIN-FTNX4TU4 howard cloud5] Instance '26' failed to spawn. Is virtualization enabled in the BIOS? (nova.compute.manager): TRACE: Traceback (most recent call last): (nova.compute.manager): TRACE: File "/usr/lib/pymodules/python2.7/nova/compute/manager.py", line 234, in run_instance (nova.compute.manager): TRACE: self.driver.spawn(instance_ref) (nova.compute.manager): TRACE: File "/usr/lib/pymodules/python2.7/nova/exception.py", line 126, in _wrap (nova.compute.manager): TRACE: raise Error(str(e)) (nova.compute.manager): TRACE: Error: internal error process exited while connecting to monitor: char device redirected to /dev/pts/1 (nova.compute.manager): TRACE: qemu: could not load kernel '/var/lib/nova/instances/instance-0000001a/kernel': Inappropriate ioctl for device (nova.compute.manager): TRACE: (nova.compute.manager): TRACE: 2011-07-11 19:05:27,423 INFO nova.compute.manager [-] Found instance 'instance-0000001a' in DB but no VM. State=5, so setting state to shutoff.