Glance

Not able to upload images or use images in Glance

Asked by Graham Hemingway

I have a two node cloud. See http://imgur.com/7ADzf for details. I pulled the /trunk version of Glance last night in an apt-get upgrade and now Glance doesn't really work at all. I can go through the motions of uploading an image and it looks good, but nothing shows up in glance index. Here is my glance.conf:

root@openstack01:~/images# more /etc/glance/glance.conf
[DEFAULT]
# Show more verbose log output (sets INFO log level output)
verbose = True

# Show debugging output in logs (sets DEBUG log level output)
debug = False

[app:glance-api]
paste.app_factory = glance.server:app_factory

# Which backend store should Glance use by default is not specified
# in a request to add a new image to Glance? Default: 'file'
# Available choices are 'file', 'swift', and 's3'
default_store = file

# Address to bind the API server
bind_host = 0.0.0.0

# Port the bind the API server to
bind_port = 9292

# Address to find the registry server
registry_host = 0.0.0.0

# Port the registry server is listening on
registry_port = 9191

# Log to this file. Make sure you do not set the same log
# file for both the API and registry servers!
log_file = /var/log/glance/api.log

# ============ Filesystem Store Options ========================

# Directory that the Filesystem backend store
# writes image data to
filesystem_store_datadir = /var/lib/glance/images/

# ============ Swift Store Options =============================

# Address where the Swift authentication service lives
#swift_store_auth_address = 127.0.0.1:8080/v1.0/

# User to authenticate against the Swift authentication service
#swift_store_user = jdoe

# Auth key for the user authenticating against the
# Swift authentication service
#swift_store_key = a86850deb2742ec3cb41518e26aa2d89

# Container within the account that the account should use
# for storing images in Swift
#swift_store_container = glance

# Do we create the container if it does not exist?
#swift_store_create_container_on_put = False

[app:glance-registry]
paste.app_factory = glance.registry.server:app_factory

# Address to bind the registry server
bind_host = 0.0.0.0

# Port the bind the registry server to
bind_port = 9191

# Log to this file. Make sure you do not set the same log
# file for both the API and registry servers!
log_file = /var/log/glance/registry.log

# SQLAlchemy connection string for the reference implementation
# registry server. Any valid SQLAlchemy connection string is fine.
# See: http://www.sqlalchemy.org/docs/05/reference/sqlalchemy/connections.html#sqlalchemy.create_engine
sql_connection = sqlite:////var/lib/glance/glance.sqlite

# Period in seconds after which SQLAlchemy should reestablish its connection
# to the database.
#
# MySQL uses a default `wait_timeout` of 8 hours, after which it will drop
# idle connections. This can result in 'MySQL Gone Away' exceptions. If you
# notice this, you can lower this value to ensure that SQLAlchemy reconnects
# before MySQL can drop the connection.
sql_idle_timeout = 3600

Here are my attempts to upload and use an image:

root@openstack01:~/images# uec-publish-tarball ttylinux-uec-amd64-12.1_2.6.35-22_1.tar.gz tty_image
Wed Apr 27 08:11:24 CDT 2011: ====== extracting image ======
kernel : ttylinux-uec-amd64-12.1_2.6.35-22_1-vmlinuz
ramdisk: ttylinux-uec-amd64-12.1_2.6.35-22_1-initrd
image : ttylinux-uec-amd64-12.1_2.6.35-22_1.img
Wed Apr 27 08:11:24 CDT 2011: ====== bundle/upload kernel ======
Wed Apr 27 08:11:26 CDT 2011: ====== bundle/upload ramdisk ======
Wed Apr 27 08:11:27 CDT 2011: ====== bundle/upload image ======
Wed Apr 27 08:11:30 CDT 2011: ====== done ======
emi="ami-00000003"; eri="ari-00000002"; eki="aki-00000001";
root@openstack01:~/images# euca-describe-images
root@openstack01:~/images# glance index
No public images found.

I try to use ami-3 to run an instance, but after a status of scheduling it goes straight to shutdown:

root@openstack01:~/images# euca-run-instances -k heminggs ami-3
RESERVATION r-szatmgk8 vhf-sandbox default
INSTANCE i-00000010 ami-00000003 scheduling heminggs (vhf-sandbox, None) 0 m1.small 2011-04-27T13:12:29Z unknown zone
root@openstack01:~/images# euca-describe-instances
RESERVATION r-szatmgk8 vhf-sandbox default
INSTANCE i-00000010 ami-00000003 192.168.51.3 192.168.51.3 shutdown heminggs (vhf-sandbox, openstack02) 0 m1.small 2011-04-27T13:12:29Z nova

There is a whole bunch of error spew on the nova-compute log:

2011-04-27 08:12:20,071 DEBUG nova.rpc [-] received {'_context_request_id': '46XQZ7LU2XVNK6N6J7KV', '_context_read_deleted': False, 'args': {'instance_id': 16, 'injected_files': None, 'availability_zone': None}, '_context_is_admin': True, '_context_timestamp': '2011-04-27T13:12:29Z', '_context_user': 'heminggs', 'method': 'run_instance', '_context_project': 'vhf-sandbox', '_context_remote_address': '192.168.50.1'} from (pid=1883) _receive /usr/lib/pymodules/python2.6/nova/rpc.py:177
2011-04-27 08:12:20,071 DEBUG nova.rpc [-] unpacked context: {'timestamp': '2011-04-27T13:12:29Z', 'remote_address': '192.168.50.1', 'project': 'vhf-sandbox', 'is_admin': True, 'user': 'heminggs', 'request_id': '46XQZ7LU2XVNK6N6J7KV', 'read_deleted': False} from (pid=1883) _unpack_context /usr/lib/pymodules/python2.6/nova/rpc.py:350
2011-04-27 08:12:20,140 AUDIT nova.compute.manager [46XQZ7LU2XVNK6N6J7KV heminggs vhf-sandbox] instance 16: starting...
2011-04-27 08:12:20,296 DEBUG nova.rpc [-] Making asynchronous call on network.openstack01 ... from (pid=1883) call /usr/lib/pymodules/python2.6/nova/rpc.py:370
2011-04-27 08:12:20,297 DEBUG nova.rpc [-] MSG_ID is 1edfc9ddcc2a45e6bfba89d6a2d322a0 from (pid=1883) call /usr/lib/pymodules/python2.6/nova/rpc.py:373
2011-04-27 08:12:20,800 DEBUG nova.utils [-] Attempting to grab semaphore "ensure_bridge" for method "ensure_bridge"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:591
2011-04-27 08:12:20,801 DEBUG nova.utils [-] Attempting to grab file lock "ensure_bridge" for method "ensure_bridge"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:596
2011-04-27 08:12:20,801 DEBUG nova.utils [-] Running cmd (subprocess): ip link show dev br100 from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:20,808 DEBUG nova.utils [-] Running cmd (subprocess): sudo route -n from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:20,819 DEBUG nova.utils [-] Running cmd (subprocess): sudo ip addr show dev eth2 scope global from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:20,829 DEBUG nova.utils [-] Running cmd (subprocess): sudo brctl addif br100 eth2 from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:20,839 DEBUG nova.utils [-] Result was 1 from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:157
2011-04-27 08:12:20,917 DEBUG nova.virt.libvirt_conn [-] instance instance-00000010: starting toXML method from (pid=1883) to_xml /usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py:1002
2011-04-27 08:12:20,997 DEBUG nova.virt.libvirt_conn [-] instance instance-00000010: finished toXML method from (pid=1883) to_xml /usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py:1047
2011-04-27 08:12:21,016 INFO nova [-] called setup_basic_filtering in nwfilter
2011-04-27 08:12:21,016 INFO nova [-] ensuring static filters
2011-04-27 08:12:21,072 INFO nova [-] <nova.db.sqlalchemy.models.SecurityGroupIngressRule object at 0x2a03690>
2011-04-27 08:12:21,072 INFO nova [-] <nova.db.sqlalchemy.models.SecurityGroupIngressRule object at 0x2a03f50>
2011-04-27 08:12:21,080 DEBUG nova.utils [-] Attempting to grab semaphore "iptables" for method "apply"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:591
2011-04-27 08:12:21,080 DEBUG nova.utils [-] Attempting to grab file lock "iptables" for method "apply"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:596
2011-04-27 08:12:21,088 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-save -t filter from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:21,100 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-restore from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:21,118 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-save -t nat from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:21,130 DEBUG nova.utils [-] Running cmd (subprocess): sudo iptables-restore from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:21,170 DEBUG nova.utils [-] Running cmd (subprocess): mkdir -p /var/lib/nova/instances/instance-00000010/ from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:21,177 INFO nova.virt.libvirt_conn [-] instance instance-00000010: Creating image
2011-04-27 08:12:21,260 DEBUG nova.utils [-] Attempting to grab semaphore "00000001" for method "call_if_not_exists"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:591
2011-04-27 08:12:21,260 DEBUG nova.utils [-] Running cmd (subprocess): cp /var/lib/nova/instances/_base/00000001 /var/lib/nova/instances/instance-00000010/kernel from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:27,843 DEBUG nova.utils [-] Attempting to grab semaphore "00000002" for method "call_if_not_exists"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:591
2011-04-27 08:12:27,843 DEBUG nova.utils [-] Running cmd (subprocess): cp /var/lib/nova/instances/_base/00000002 /var/lib/nova/instances/instance-00000010/ramdisk from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:35,612 DEBUG nova.utils [-] Attempting to grab semaphore "00000003" for method "call_if_not_exists"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:591
2011-04-27 08:12:35,612 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img create -f qcow2 -o cluster_size=2M,backing_file=/var/lib/nova/instances/_base/00000003 /var/lib/nova/instances/instance-00000010/disk from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:35,961 DEBUG nova.utils [-] Attempting to grab semaphore "local_20" for method "call_if_not_exists"... from (pid=1883) inner /usr/lib/pymodules/python2.6/nova/utils.py:591
2011-04-27 08:12:35,961 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-00000010/disk.local from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:36,103 INFO nova.virt.libvirt_conn [-] instance instance-00000010: injecting key into image 3
2011-04-27 08:12:36,118 DEBUG nova.utils [-] Running cmd (subprocess): sudo qemu-nbd -c /dev/nbd15 /var/lib/nova/instances/instance-00000010/disk from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:37,369 DEBUG nova.utils [-] Running cmd (subprocess): sudo tune2fs -c 0 -i 0 /dev/nbd15 from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:37,421 DEBUG nova.utils [-] Result was 1 from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:157
2011-04-27 08:12:37,421 DEBUG nova.utils [-] Running cmd (subprocess): sudo qemu-nbd -d /dev/nbd15 from (pid=1883) execute /usr/lib/pymodules/python2.6/nova/utils.py:141
2011-04-27 08:12:37,433 WARNING nova.virt.libvirt_conn [-] instance instance-00000010: ignoring error injecting data into image 3 (Unexpected error while running command.
Command: sudo tune2fs -c 0 -i 0 /dev/nbd15
Exit code: 1
Stdout: 'tune2fs 1.41.12 (17-May-2010)\n'
Stderr: "tune2fs: Bad magic number in super-block while trying to open /dev/nbd15\nCouldn't find valid filesystem superblock.\n")
2011-04-27 08:12:42,202 ERROR nova.exception [-] Uncaught exception
(nova.exception): TRACE: Traceback (most recent call last):
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/exception.py", line 119, in _wrap
(nova.exception): TRACE: return f(*args, **kw)
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py", line 625, in spawn
(nova.exception): TRACE: domain = self._create_new_domain(xml)
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py", line 1096, in _create_new_domain
(nova.exception): TRACE: domain.createWithFlags(launch_flags)
(nova.exception): TRACE: File "/usr/lib/python2.6/dist-packages/libvirt.py", line 337, in createWithFlags
(nova.exception): TRACE: if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
(nova.exception): TRACE: libvirtError: operation failed: failed to retrieve chardev info in qemu with 'info chardev'
(nova.exception): TRACE:
2011-04-27 08:12:42,216 ERROR nova.compute.manager [46XQZ7LU2XVNK6N6J7KV heminggs vhf-sandbox] Instance '16' 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.6/nova/compute/manager.py", line 240, in run_instance
(nova.compute.manager): TRACE: self.driver.spawn(instance_ref)
(nova.compute.manager): TRACE: File "/usr/lib/pymodules/python2.6/nova/exception.py", line 125, in _wrap
(nova.compute.manager): TRACE: raise Error(str(e))
(nova.compute.manager): TRACE: Error: operation failed: failed to retrieve chardev info in qemu with 'info chardev'
(nova.compute.manager): TRACE:
2011-04-27 08:12:45,678 INFO nova.compute.manager [-] Found instance 'instance-00000010' in DB but no VM. State=5, so setting state to shutoff.
2011-04-27 08:13:45,716 INFO nova.compute.manager [-] Found instance 'instance-00000010' in DB but no VM. State=5, so setting state to shutoff.

Is this a known bug in Glance?
Thanks,
   Graham

Question information

Language:
English Edit question
Status:
Expired
For:
Glance Edit question
Assignee:
No assignee Edit question
Last query:
Last reply:
Revision history for this message
Jay Pipes (jaypipes) said : 		#1

Hi!

Could you pastebin your glance API and registry log contents? Thanks much!

jay

Revision history for this message
Graham Hemingway (graham-hemingway) said : 		#2

Jay,

I cleaned out the existing glance.sqlite and all of the image files, logs, and bucket data too. I rebooted the computer and then ran the following:

root@openstack01:~/images# uec-publish-tarball ttylinux-uec-amd64-12.1_2.6.35-22_1.tar.gz test_image
Wed Apr 27 13:02:55 CDT 2011: ====== extracting image ======
kernel : ttylinux-uec-amd64-12.1_2.6.35-22_1-vmlinuz
ramdisk: ttylinux-uec-amd64-12.1_2.6.35-22_1-initrd
image : ttylinux-uec-amd64-12.1_2.6.35-22_1.img
Wed Apr 27 13:02:56 CDT 2011: ====== bundle/upload kernel ======
Wed Apr 27 13:02:57 CDT 2011: ====== bundle/upload ramdisk ======
Wed Apr 27 13:02:59 CDT 2011: ====== bundle/upload image ======
Wed Apr 27 13:03:01 CDT 2011: ====== done ======
emi="ami-00000003"; eri="ari-00000002"; eki="aki-00000001";
root@openstack01:~/images# glance index
No public images found.
root@openstack01:~/images# glance details
No public images found.
root@openstack01:~/images# euca-describe-images
root@openstack01:~/images#

The resulting log info for all of the Glance logs is at http://pastebin.com/8CQNFSeJ.
Please let me know what else I can do.
Cheers,
   Graham

Revision history for this message
Dusan Pancevac (dusan-pancevac) said : 		#3

Hi
I had a same problem when upgraded glance last day. Something is wrong with new version 2011.3.
I have downloaded the source for glance from here https://launchpad.net/ubuntu/natty/+source/glance/2011.2-0ubuntu1.
I did apt-get remove glance
untared the source and installed it with
python setup.py install
At that time I was allready cleared glance and messed up the database but I have made a spare copy of glance.sqlite database, first time I have noticed that something is wrong. I've copied the database from backup and all my images are visible again.

Dusan

Revision history for this message
Graham Hemingway (graham-hemingway) said : 		#4

I would prefer to not have to revert the code (i.e. a fix), so I don't really consider this question answered. That being said, a third user has also opened a question with this same problem (see https://answers.launchpad.net/glance/+question/154460). Perhaps we can consolidate the questions.

Cheers,
   Graham

Revision history for this message
Jay Pipes (jaypipes) said : 		#5

We're trying to determine whether this is a bug in Glance or Nova. Please bear with us... Thanks.

Revision history for this message
Jay Pipes (jaypipes) said : 		#6

Graham, please also post your nova.conf so we can check the flags that deal with the image service. Thanks again.

Revision history for this message
Graham Hemingway (graham-hemingway) said : 		#7

Jay,

Full details on my nova configuration are here: http://imgur.com/7ADzf.
Thanks for working on this.

G

Revision history for this message
Jay Pipes (jaypipes) said : 		#8

Doh, sorry, I missed that the conf was in the image! :) OK, off to diagnose...

Revision history for this message
Launchpad Janitor (janitor) said : 		#9

This question was expired because it remained in the 'Open' state without activity for the last 15 days.