Hide Forgot
Description of problem: After calling: su -c ". ./novarc && euca-run-instances assy1-F15 -k nova_key" asalkeld (from python - pacemaker-cloud) I get a crash in glance-api. After this the VM is unusable (it can't boot). Version-Release number of selected component (if applicable): openstack-glance-2011.3-1.fc16.noarch How reproducible: Occasional Steps to Reproduce: I'll add more as I can (just capturing for now). Note: selinux is permissive [snip from logs] Nov 22 13:38:45 localhost assy1-F16 336: [INFO] starting foo:assy1-F16 Nov 22 13:38:45 localhost assy1-F16 338: [INFO] cmd: su -c ". ./novarc && euca-run-instances assy1-F16 -k nova_key" asalkeld Nov 22 13:38:47 localhost assy1-F16 341: [INFO] cmd out: RESERVATION#011r-0u8kzn12#011foo#011default#012INSTANCE#011i-00000026#011ami-00000020#011#011#011pending#011nova_key (foo, None)#0110#011#011m1.small#0112011-11-22T02:38:46Z#011unknown zone#011ami-00000000#011ami-00000000 Nov 22 13:38:47 localhost assy1-F15 336: [INFO] starting foo:assy1-F15 Nov 22 13:38:47 localhost assy1-F15 336: [INFO] starting foo:assy1-F15 Nov 22 13:38:47 localhost assy1-F15 338: [INFO] cmd: su -c ". ./novarc && euca-run-instances assy1-F15 -k nova_key" asalkeld Nov 22 13:38:47 localhost assy1-F15 338: [INFO] cmd: su -c ". ./novarc && euca-run-instances assy1-F15 -k nova_key" asalkeld Nov 22 13:38:47 localhost dpe[17094]: MAIN [debug] start result: 0 Nov 22 13:38:48 localhost assy1-F15 341: [INFO] cmd out: RESERVATION#011r-97pjyq35#011foo#011default#012INSTANCE#011i-00000027#011ami-00000021#011#011#011pending#011nova_key (foo, None)#0110#011#011m1.small#0112011-11-22T02:38:47Z#011unknown zone#011ami-00000000#011ami-00000000 Nov 22 13:38:48 localhost assy1-F15 341: [INFO] cmd out: RESERVATION#011r-97pjyq35#011foo#011default#012INSTANCE#011i-00000027#011ami-00000021#011#011#011pending#011nova_key (foo, None)#0110#011#011m1.small#0112011-11-22T02:38:47Z#011unknown zone#011ami-00000000#011ami-00000000 Nov 22 13:38:48 localhost dnsmasq[11912]: read /etc/hosts - 2 addresses Nov 22 13:38:48 localhost dnsmasq-dhcp[11912]: read /var/lib/nova/networks/nova-br0.conf Nov 22 13:38:48 localhost dpe[17094]: MAIN [debug] start result: 0 Nov 22 13:38:49 localhost dnsmasq[11912]: read /etc/hosts - 2 addresses Nov 22 13:38:49 localhost dnsmasq-dhcp[11912]: read /var/lib/nova/networks/nova-br0.conf Nov 22 13:38:51 localhost kernel: [364087.941038] type=1400 audit(1321929531.542:36): avc: denied { search } for pid=11720 comm="glance-api" name="images" dev=sda5 ino=3278046 scontext=system_u:system_r:glance_api_t:s0 tcontext=system_u:object_r:virt_image_t:s0 tclass=dir Nov 22 13:38:51 localhost kernel: [364087.941281] type=1400 audit(1321929531.543:37): avc: denied { getattr } for pid=11720 comm="glance-api" path="/var/lib/libvirt/images/assy1-F16.qcow2" dev=sda5 ino=3277382 scontext=system_u:system_r:glance_api_t:s0 tcontext=system_u:object_r:virt_image_t:s0 tclass=file Nov 22 13:38:51 localhost kernel: [364087.941363] type=1400 audit(1321929531.543:38): avc: denied { read } for pid=11720 comm="glance-api" name="assy1-F16.qcow2" dev=sda5 ino=3277382 scontext=system_u:system_r:glance_api_t:s0 tcontext=system_u:object_r:virt_image_t:s0 tclass=file Nov 22 13:38:51 localhost kernel: [364087.941386] type=1400 audit(1321929531.543:39): avc: denied { open } for pid=11720 comm="glance-api" name="assy1-F16.qcow2" dev=sda5 ino=3277382 scontext=system_u:system_r:glance_api_t:s0 tcontext=system_u:object_r:virt_image_t:s0 tclass=file Nov 22 13:38:51 localhost glance-api[11720]: Traceback (most recent call last): Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/greenpool.py", line 80, in _spawn_n_impl Nov 22 13:38:51 localhost glance-api[11720]: func(*args, **kwargs) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/wsgi.py", line 514, in process_request Nov 22 13:38:51 localhost glance-api[11720]: proto = self.protocol(socket, address, self) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib64/python2.7/SocketServer.py", line 641, in __init__ Nov 22 13:38:51 localhost glance-api[11720]: self.finish() Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/wsgi.py", line 456, in finish Nov 22 13:38:51 localhost glance-api[11720]: BaseHTTPServer.BaseHTTPRequestHandler.finish(self) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib64/python2.7/SocketServer.py", line 694, in finish Nov 22 13:38:51 localhost glance-api[11720]: self.wfile.flush() Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib64/python2.7/socket.py", line 303, in flush Nov 22 13:38:51 localhost glance-api[11720]: self._sock.sendall(view[write_offset:write_offset+buffer_size]) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/greenio.py", line 283, in sendall Nov 22 13:38:51 localhost glance-api[11720]: tail = self.send(data, flags) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/greenio.py", line 269, in send Nov 22 13:38:51 localhost glance-api[11720]: total_sent += fd.send(data[total_sent:], flags) Nov 22 13:38:51 localhost glance-api[11720]: error: [Errno 32] Broken pipe Nov 22 13:38:51 localhost glance-api[11720]: Traceback (most recent call last): Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/greenpool.py", line 80, in _spawn_n_impl Nov 22 13:38:51 localhost glance-api[11720]: func(*args, **kwargs) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/wsgi.py", line 514, in process_request Nov 22 13:38:51 localhost glance-api[11720]: proto = self.protocol(socket, address, self) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib64/python2.7/SocketServer.py", line 641, in __init__ Nov 22 13:38:51 localhost glance-api[11720]: self.finish() Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/wsgi.py", line 456, in finish Nov 22 13:38:51 localhost glance-api[11720]: BaseHTTPServer.BaseHTTPRequestHandler.finish(self) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib64/python2.7/SocketServer.py", line 694, in finish Nov 22 13:38:51 localhost glance-api[11720]: self.wfile.flush() Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib64/python2.7/socket.py", line 303, in flush Nov 22 13:38:51 localhost glance-api[11720]: self._sock.sendall(view[write_offset:write_offset+buffer_size]) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/greenio.py", line 283, in sendall Nov 22 13:38:51 localhost glance-api[11720]: tail = self.send(data, flags) Nov 22 13:38:51 localhost glance-api[11720]: File "/usr/lib/python2.7/site-packages/eventlet/greenio.py", line 269, in send Nov 22 13:38:51 localhost glance-api[11720]: total_sent += fd.send(data[total_sent:], flags) Nov 22 13:38:51 localhost glance-api[11720]: error: [Errno 32] Broken pipe Nov 22 13:38:53 localhost kernel: [364089.765577] nbd14: NBD_DISCONNECT Nov 22 13:38:53 localhost kernel: [364089.765703] nbd14: Receive control failed (result -32) Nov 22 13:38:53 localhost kernel: [364089.765837] nbd14: queue cleared Nov 22 13:38:53 localhost kernel: [364089.773628] nbd15: NBD_DISCONNECT Nov 22 13:38:53 localhost kernel: [364089.773779] nbd15: Receive control failed (result -32) Nov 22 13:38:53 localhost kernel: [364089.774379] nbd15: queue cleared
In /var/log/nova/compute.log is ... 2011-11-22 22:00:22,363 WARNING nova.compute.manager [-] Error during power_state sync: (OperationalError) database is locked (and heaps of sql) this might be the sqlite problem (I'll change over to mysql and report back)
I still get the following crash: Nov 29 09:40:36 troll glance-api[29898]: Traceback (most recent call last): Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib/python2.7/site-packages/eventlet/greenpool.py", line 80, in _spawn_n_impl Nov 29 09:40:36 troll glance-api[29898]: func(*args, **kwargs) Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib/python2.7/site-packages/eventlet/wsgi.py", line 514, in process_request Nov 29 09:40:36 troll glance-api[29898]: proto = self.protocol(socket, address, self) Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib64/python2.7/SocketServer.py", line 641, in __init__ Nov 29 09:40:36 troll glance-api[29898]: self.finish() Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib/python2.7/site-packages/eventlet/wsgi.py", line 456, in finish Nov 29 09:40:36 troll glance-api[29898]: BaseHTTPServer.BaseHTTPRequestHandler.finish(self) Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib64/python2.7/SocketServer.py", line 694, in finish Nov 29 09:40:36 troll glance-api[29898]: self.wfile.flush() Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib64/python2.7/socket.py", line 303, in flush Nov 29 09:40:36 troll glance-api[29898]: self._sock.sendall(view[write_offset:write_offset+buffer_size]) Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib/python2.7/site-packages/eventlet/greenio.py", line 283, in sendall Nov 29 09:40:36 troll glance-api[29898]: tail = self.send(data, flags) Nov 29 09:40:36 troll glance-api[29898]: File "/usr/lib/python2.7/site-packages/eventlet/greenio.py", line 269, in send Nov 29 09:40:36 troll glance-api[29898]: total_sent += fd.send(data[total_sent:], flags) Nov 29 09:40:36 troll glance-api[29898]: error: [Errno 32] Broken pipe
(Just to avoid this: http://xkcd.com/979/ :-) According to Angus, the underlying issue here turned out to be that the nova-volumes service was failing on startup because the loopback image based nova-volumes LVM volume group wasn't available.