Glance image delivery not working on compute nodes

Asked by Howard Taylor on 2011-07-09

Hi all,

Glance image delivery doesn't seem to be working for me!

I have a three server set-up with Glance running on the cloud controller which also runs compute. Instances that start on the cloud controller work fine but those that attempt to start on the compute nodes always fail. I have the same nova.conf on the nodes and controller. The relevant part of the compute log on the node is:

2011-07-09 15:07:52,811 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-09 15:07:52,856 DEBUG nova.utils [-] Result was 1 from (pid=1324) execute /usr/lib/pymodules/python2.7/nova/utils.py:166
2011-07-09 15:07:52,857 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-09 15:07:52,906 WARNING nova.virt.libvirt_conn [-] instance instance-00000018: 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-09 15:08:25,952 ERROR nova.exception [-] Uncaught exception
(nova.exception): TRACE: Traceback (most recent call last):

Additionally, the files in /var/lib/nova/instances/_base are zero length; I've seen that others have copied the contents of the controller's version of this directory into here but this seems to defeat the object of Glance.

Also, "glance index --host=10.0.0.100" on a node gives the following error (it works fine on the controller):

Failed to show index. Got error:
Unknown error occurred! {"versions": [{"status": "CURRENT", "id": "v1.0", "links": [{"href": "http://0.0.0.0:9292/v1/", "rel": "self"}]}]}
howard@stratus:~$ ping 192.168.1.44

Can anyone give me some suggestions of a solution or further diagnostic steps--others have posted the same problem but I've not seen a solution.

Thanks

Question information

Language:
English Edit question
Status:
Answered
For:
Glance Edit question
Assignee:
No assignee Edit question
Last query:
2011-07-29
Last reply:
2011-08-11
Brian Lamar (blamar) said : #1

Can you please post the entire trace? It seems that the last line of logging you provided was a traceback that could be helpful in debugging this situation. http://paste.openstack.org might be easier for pasting large logs/tracebacks. Thanks!

Howard Taylor (howard-h) said : #2

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.

Jay Pipes (jaypipes) said : #3

Hi Howard, could you paste the glance API log please :) Thanks!
-jay

Howard Taylor (howard-h) said : #4

The Glance API logs on the controller and the node haven't had any additions for a couple of days.

The controller has entries like this--I've changed the permissions on the file but nothing further's been written:

IOError: [Errno 13] Permission denied: '/var/log/glance/api.log'
Traceback (most recent call last):
  File "/usr/bin/glance-api", line 60, in <module>
    conf, app = config.load_paste_app('glance-api', options, args)
  File "/usr/lib/pymodules/python2.7/glance/common/config.py", line 279, in load_paste_app
    setup_logging(options, conf)
  File "/usr/lib/pymodules/python2.7/glance/common/config.py", line 168, in setup_logging
    logfile = logging.FileHandler(logfile)
  File "/usr/lib/python2.7/logging/__init__.py", line 893, in __init__
    StreamHandler.__init__(self, self._open())
  File "/usr/lib/python2.7/logging/__init__.py", line 912, in _open
    stream = open(self.baseFilename, self.mode)
IOError: [Errno 13] Permission denied: '/var/log/glance/api.log'
Traceback (most recent call last):
  File "/usr/bin/glance-api", line 60, in <module>
    conf, app = config.load_paste_app('glance-api', options, args)
  File "/usr/lib/pymodules/python2.7/glance/common/config.py", line 279, in load_paste_app
    setup_logging(options, conf)
  File "/usr/lib/pymodules/python2.7/glance/common/config.py", line 168, in setup_logging
    logfile = logging.FileHandler(logfile)
  File "/usr/lib/python2.7/logging/__init__.py", line 893, in __init__
    StreamHandler.__init__(self, self._open())
  File "/usr/lib/python2.7/logging/__init__.py", line 912, in _open
    stream = open(self.baseFilename, self.mode)
IOError: [Errno 13] Permission denied: '/var/log/glance/api.log'

the node looks like this at the end:

Session terminated, terminating shell... ...terminated.
2011-07-06 20:30:08 DEBUG [glance-api] ********************************************************************************
2011-07-06 20:30:08 DEBUG [glance-api] Configuration options gathered from config file:
2011-07-06 20:30:08 DEBUG [glance-api] /etc/glance/glance.conf
2011-07-06 20:30:08 DEBUG [glance-api] ================================================
2011-07-06 20:30:08 DEBUG [glance-api] bind_host 0.0.0.0
2011-07-06 20:30:08 DEBUG [glance-api] bind_port 9292
2011-07-06 20:30:08 DEBUG [glance-api] debug False
2011-07-06 20:30:08 DEBUG [glance-api] default_store file
2011-07-06 20:30:08 DEBUG [glance-api] filesystem_store_datadir /var/lib/glance/images/
2011-07-06 20:30:08 DEBUG [glance-api] registry_host 0.0.0.0
2011-07-06 20:30:08 DEBUG [glance-api] registry_port 9191
2011-07-06 20:30:08 DEBUG [glance-api] swift_store_auth_address 127.0.0.1:8080/v1.0/
2011-07-06 20:30:08 DEBUG [glance-api] swift_store_container glance
2011-07-06 20:30:08 DEBUG [glance-api] swift_store_create_container_on_put False
2011-07-06 20:30:08 DEBUG [glance-api] swift_store_key a86850deb2742ec3cb41518e26aa2d89
2011-07-06 20:30:08 DEBUG [glance-api] swift_store_user jdoe
2011-07-06 20:30:08 DEBUG [glance-api] verbose True
2011-07-06 20:30:08 DEBUG [glance-api] ********************************************************************************
2011-07-06 20:30:08 DEBUG [routes.middleware] Initialized with method overriding = True, and path info altering = True
2011-07-06 20:30:08 DEBUG [eventlet.wsgi.server] (1320) wsgi starting up on http://0.0.0.0:9292/
2011-07-09 12:10:15 DEBUG [routes.middleware] Matched GET /images/1
2011-07-09 12:10:15 DEBUG [routes.middleware] Route path: '/images/:(id)', defaults: {'action': u'show', 'controller': <glance.server.Controller object at 0x24b1f10>}
2011-07-09 12:10:15 DEBUG [routes.middleware] Match dict: {'action': u'show', 'controller': <glance.server.Controller object at 0x24b1f10>, 'id': u'1'}
2011-07-09 12:10:15 DEBUG [glance.server] Image with identifier 1 not found
2011-07-09 12:10:15 DEBUG [eventlet.wsgi.server] 10.0.0.101 - - [09/Jul/2011 12:10:15] "GET /images/1 HTTP/1.1" 404 209 0.053769
2011-07-09 12:10:25 DEBUG [routes.middleware] Matched GET /images/2
2011-07-09 12:10:25 DEBUG [routes.middleware] Route path: '/images/:(id)', defaults: {'action': u'show', 'controller': <glance.server.Controller object at 0x24b1f10>}
2011-07-09 12:10:25 DEBUG [routes.middleware] Match dict: {'action': u'show', 'controller': <glance.server.Controller object at 0x24b1f10>, 'id': u'2'}
2011-07-09 12:10:25 DEBUG [glance.server] Image with identifier 2 not found
2011-07-09 12:10:25 DEBUG [eventlet.wsgi.server] 10.0.0.101 - - [09/Jul/2011 12:10:25] "GET /images/2 HTTP/1.1" 404 209 0.014333

Jay Pipes (jaypipes) said : #5

OK, so it looks like you've run into this bug: https://bugs.launchpad.net/glance/+bug/784837. What version of Glance are you running and on which operating system version?

-jay

Howard Taylor (howard-h) said : #6

Ubuntu 11.04; how do I establish the Glance version?

Jay Pipes (jaypipes) said : #7

You can do glance --version.

OK, so the fix for the api.log permissions thing is only in the packaging for Oneric (11.10) it seems. I'll check into it and see if there's a backport to Natty planned.

Cheers,
jay

Howard Taylor (howard-h) said : #8

glance 2011.3-dev

Jay Pipes (jaypipes) said : #9

Howard, the fix for the api.log permissions issue is in the bug report above:

touch /var/log/glance/api.log and chown it to the glance user

Are there any files in /var/lib/glance/images? If not, check the permissions of that directory, since when you add images to your Glance installation, by default, that's where Glance will try to write to.

-jay

Howard Taylor (howard-h) said : #10

Ok.

The /var/lib/glance/images does contain files. I don't have any problems running compute instances on the cloud controller, it's only on the separate compute nodes that the images never seem to be downloaded and I can't get a 'glance index result' .

Jay Pipes (jaypipes) said : #11

Hi again, Howard. I think I've figured out what the problem is. I believe you've been stung by this bug: https://bugs.launchpad.net/nova/+bug/808990. I suspect that on your compute nodes, you need to set the new glance_api_servers FLAG, which changed recently to allow multiple Glance servers in Nova.

Howard Taylor (howard-h) said : #12

Hi

I already have the new flag set:

--dhcpbridge_flagfile=/etc/nova/nova.conf
--dhcpbridge=/usr/bin/nova-dhcpbridge
--logdir=/var/log/nova
--state_path=/var/lib/nova
--lock_path=/var/lock/nova
--verbose
--s3_host=10.0.0.100
--rabbit_host=10.0.0.100
--cc_host=10.0.0.100
--ec2_url=http://10.0.0.100:8773/services/Cloud
--fixed_range=10.0.0.0/12
--network_size=99
--FAKE_subdomain=ec2
--routing_source_ip=10.0.0.100
--verbose
--sql_connection=mysql://root:axolotl@10.0.0.100/nova
--glance_api_servers=10.0.0.100:9292
--image_service=nova.image.glance.GlanceImageService
--network_manager=nova.network.manager.FlatDHCPManager
--flat_network_dhcp_start=10.0.0.2
--public_interface=eth1
--flat_interface=eth0
--flat_injected=False

The various curl commands on the compute node give these responses:

curl http://10.0.0.100:9191
{"images": [{"name": null, "container_format": "ami", "disk_format": "ami", "checksum": "af31c50d70519eba7fb4f52105cb7033", "id": 2, "size": 1476395008}, {"name": null, "container_format": "aki", "disk_format": "aki", "checksum": "d896f8c1577c2a89aa958ab2442817d2", "id": 1, "size": 4106528}]}

curl http://10.0.0.100:9292
{"versions": [{"status": "CURRENT", "id": "v1.0", "links": [{"href": "http://0.0.0.0:9292/v1/", "rel": "self"}]}]}

curl http://10.0.0.100:9292/vl/images
{"versions": [{"status": "CURRENT", "id": "v1.0", "links": [{"href": "http://0.0.0.0:9292/v1/", "rel": "self"}]}]}

the 'glance index --host=10.0.0.100' gives an error message:

Failed to show index. Got error:
Unknown error occurred! {"versions": [{"status": "CURRENT", "id": "v1.0", "links": [{"href": "http://0.0.0.0:9292/v1/", "rel": "self"}]}]}

Does any of this help?

Jay Pipes (jaypipes) said : #13

curl http://10.0.0.100:9292/vl/images

should be

curl http://10.0.0.100:9292/v1/images

Also, is there nothing at all in the glance API log? Please set debug
= True in your config file if not set.

Cheers,
jay

Howard Taylor (howard-h) said : #14

Jay

The correct curl gives:

curl http://10.0.0.100:9292/v1/images
{"images": [{"name": null, "container_format": "ami", "disk_format": "ami", "checksum": "af31c50d70519eba7fb4f52105cb7033", "id": 2, "size": 1476395008}, {"name": null, "container_format": "aki", "disk_format": "aki", "checksum": "d896f8c1577c2a89aa958ab2442817d2", "id": 1, "size": 4106528}]}

I've now got Glance debug logging on and it gives the following after a failed spawn:

2011-07-13 08:32:31 DEBUG [glance-api] ********************************************************************************
2011-07-13 08:32:31 DEBUG [glance-api] Configuration options gathered from config file:
2011-07-13 08:32:31 DEBUG [glance-api] /etc/glance/glance-api.conf
2011-07-13 08:32:31 DEBUG [glance-api] ================================================
2011-07-13 08:32:31 DEBUG [glance-api] bind_host 0.0.0.0
2011-07-13 08:32:31 DEBUG [glance-api] bind_port 9292
2011-07-13 08:32:31 DEBUG [glance-api] debug True
2011-07-13 08:32:31 DEBUG [glance-api] default_store file
2011-07-13 08:32:31 DEBUG [glance-api] filesystem_store_datadir /var/lib/glance/images/
2011-07-13 08:32:31 DEBUG [glance-api] log_file /var/log/glance/api.log
2011-07-13 08:32:31 DEBUG [glance-api] registry_host 0.0.0.0
2011-07-13 08:32:31 DEBUG [glance-api] registry_port 9191
2011-07-13 08:32:31 DEBUG [glance-api] swift_store_auth_address 127.0.0.1:8080/v1.0/
2011-07-13 08:32:31 DEBUG [glance-api] swift_store_container glance
2011-07-13 08:32:31 DEBUG [glance-api] swift_store_create_container_on_put False
2011-07-13 08:32:31 DEBUG [glance-api] swift_store_key a86850deb2742ec3cb41518e26aa2d89
2011-07-13 08:32:31 DEBUG [glance-api] swift_store_user jdoe
2011-07-13 08:32:31 DEBUG [glance-api] verbose True
2011-07-13 08:32:31 DEBUG [glance-api] ********************************************************************************
2011-07-13 08:32:31 DEBUG [routes.middleware] Initialized with method overriding = True, and path info altering = True
2011-07-13 08:32:31 DEBUG [eventlet.wsgi.server] (18272) wsgi starting up on http://0.0.0.0:9292/
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Processing request: HEAD /v1/images/1 Accept:
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Matched versioned URI. Version: 1.0
2011-07-13 08:33:47 DEBUG [routes.middleware] Matched HEAD /images/1
2011-07-13 08:33:47 DEBUG [routes.middleware] Route path: '/images/{id}', defaults: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>}
2011-07-13 08:33:47 DEBUG [routes.middleware] Match dict: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>, 'id': u'1'}
2011-07-13 08:33:47 DEBUG [eventlet.wsgi.server] 192.168.1.100 - - [13/Jul/2011 08:33:47] "HEAD /v1/images/1 HTTP/1.1" 200 904 0.022955
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Processing request: HEAD /v1/images/2 Accept:
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Matched versioned URI. Version: 1.0
2011-07-13 08:33:47 DEBUG [routes.middleware] Matched HEAD /images/2
2011-07-13 08:33:47 DEBUG [routes.middleware] Route path: '/images/{id}', defaults: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>}
2011-07-13 08:33:47 DEBUG [routes.middleware] Match dict: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>, 'id': u'2'}
2011-07-13 08:33:47 DEBUG [eventlet.wsgi.server] 192.168.1.100 - - [13/Jul/2011 08:33:47] "HEAD /v1/images/2 HTTP/1.1" 200 931 0.008692
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Processing request: HEAD /v1/images/2 Accept:
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Matched versioned URI. Version: 1.0
2011-07-13 08:33:47 DEBUG [routes.middleware] Matched HEAD /images/2
2011-07-13 08:33:47 DEBUG [routes.middleware] Route path: '/images/{id}', defaults: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>}
2011-07-13 08:33:47 DEBUG [routes.middleware] Match dict: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>, 'id': u'2'}
2011-07-13 08:33:47 DEBUG [eventlet.wsgi.server] 192.168.1.100 - - [13/Jul/2011 08:33:47] "HEAD /v1/images/2 HTTP/1.1" 200 931 0.008874
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Processing request: HEAD /v1/images/1 Accept:
2011-07-13 08:33:47 DEBUG [glance.api.middleware.version_negotiation] Matched versioned URI. Version: 1.0
2011-07-13 08:33:47 DEBUG [routes.middleware] Matched HEAD /images/1
2011-07-13 08:33:47 DEBUG [routes.middleware] Route path: '/images/{id}', defaults: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>}
2011-07-13 08:33:47 DEBUG [routes.middleware] Match dict: {'action': u'meta', 'controller': <glance.common.wsgi.Resource object at 0x3006cd0>, 'id': u'1'}
2011-07-13 08:33:47 DEBUG [eventlet.wsgi.server] 192.168.1.100 - - [13/Jul/2011 08:33:47] "HEAD /v1/images/1 HTTP/1.1" 200 904 0.008663

I not that the bind_host's are 0.0.0.0, is this correct?

Thanks

Howard

Jay Pipes (jaypipes) said : #15

I don't see any problems with anything in the log. The bind_host is 0.0.0.0 since the glance-api is bound on the localhost of the compute-controller. The log is on that machine...

I have a feeling that what the problem is is that on the compute node (the node where you can't connect properly to Glance from Nova), the old Cactus Glance release is installed (which is the case if you installed Nova but not Glance). Nova's packages have a dependency on the old Glance Cactus package, but the Glance server you are running is on the Diablo package.

I think if you manually install glance on the compute node, things will start working.

I'll file a bug to get the latest Diablo packaging up on PyPI so the Nova installer installs the most up-to-date Glance client package.

Howard Taylor (howard-h) said : #16

Thanks.

I've attempted to install Glance manually now on two different compute nodes but get the error below:

Can you assist, further, please?

sudo add-apt-repository ppa:glance-core/trunk
sudo apt-get update
sudo apt-get install glance

Reading package lists... Done
Building dependency tree
Reading state information... Done
The following packages were automatically installed and are no longer required:
  linux-headers-2.6.38-8-generic linux-headers-2.6.38-8
  linux-headers-2.6.38-8-server socat libreadline5 vlan
Use 'apt-get autoremove' to remove them.
The following extra packages will be installed:
  python-glance
The following packages will be upgraded:
  glance python-glance
2 upgraded, 0 newly installed, 0 to remove and 34 not upgraded.
Need to get 91.5 kB of archives.
After this operation, 233 kB of additional disk space will be used.
Do you want to continue [Y/n]? Y
Get:1 http://ppa.launchpad.net/glance-core/trunk/ubuntu/ natty/main glance all 2011.3~d3~20110709.152-0ubuntu0ppa1~natty1 [14.6 kB]
Get:2 http://ppa.launchpad.net/glance-core/trunk/ubuntu/ natty/main python-glance all 2011.3~d3~20110709.152-0ubuntu0ppa1~natty1 [77.0 kB]
Fetched 91.5 kB in 0s (442 kB/s)
(Reading database ... 176462 files and directories currently installed.)
Preparing to replace glance 2011.2-0ubuntu1 (using .../glance_2011.3~d3~20110709.152-0ubuntu0ppa1~natty1_all.deb) ...
glance-registry stop/waiting
glance-api stop/waiting
Unpacking replacement glance ...
Preparing to replace python-glance 2011.2-0ubuntu1 (using .../python-glance_2011.3~d3~20110709.152-0ubuntu0ppa1~natty1_all.deb) ...
Unpacking replacement python-glance ...
Processing triggers for ureadahead ...
Processing triggers for python-support ...
Setting up python-glance (2011.3~d3~20110709.152-0ubuntu0ppa1~natty1) ...
Setting up glance (2011.3~d3~20110709.152-0ubuntu0ppa1~natty1) ...
Installing new version of config file /etc/init/glance-api.conf ...
Installing new version of config file /etc/init/glance-registry.conf ...
Traceback (most recent call last):
  File "/usr/bin/glance-manage", line 141, in <module>
    main()
  File "/usr/bin/glance-manage", line 137, in main
    dispatch_cmd(options, args)
  File "/usr/bin/glance-manage", line 109, in dispatch_cmd
    cmd_func(options, args)
  File "/usr/bin/glance-manage", line 97, in do_db_sync
    glance.registry.db.migration.db_sync(options, version=db_version)
  File "/usr/lib/pymodules/python2.7/glance/registry/db/migration.py", line 123, in db_sync
    upgrade(options, version=version)
  File "/usr/lib/pymodules/python2.7/glance/registry/db/migration.py", line 66, in upgrade
    return versioning_api.upgrade(sql_connection, repo_path, version)
  File "/usr/lib/pymodules/python2.7/migrate/versioning/api.py", line 185, in upgrade
    return _migrate(url, repository, version, upgrade=True, err=err, **opts)
  File "<string>", line 2, in _migrate
  File "/usr/lib/pymodules/python2.7/migrate/versioning/util/__init__.py", line 160, in with_engine
    return f(*a, **kw)
  File "/usr/lib/pymodules/python2.7/migrate/versioning/api.py", line 364, in _migrate
    schema.runchange(ver, change, changeset.step)
  File "/usr/lib/pymodules/python2.7/migrate/versioning/schema.py", line 83, in runchange
    change.run(self.engine, step)
  File "/usr/lib/pymodules/python2.7/migrate/versioning/script/py.py", line 140, in run
    script_func(engine)
  File "/usr/lib/pymodules/python2.7/glance/registry/db/migrate_repo/versions/001_add_images_table.py", line 49, in upgrade
    create_tables(tables)
  File "/usr/lib/pymodules/python2.7/glance/registry/db/migrate_repo/schema.py", line 97, in create_tables
    table.create()
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/schema.py", line 439, in create
    bind.create(self, checkfirst=checkfirst)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1701, in create
    connection=connection, **kwargs)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1743, in _run_visitor
    **kwargs).traverse_single(element)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/visitors.py", line 77, in traverse_single
    return meth(obj, **kw)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/ddl.py", line 58, in visit_table
    self.connection.execute(schema.CreateTable(table))
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1194, in execute
    params)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1247, in _execute_ddl
    return self.__execute_context(context)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1305, in __execute_context
    context.parameters[0], context=context)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1404, in _cursor_execute
    context)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1397, in _cursor_execute
    context)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 299, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.OperationalError: (OperationalError) table images already exists u'\nCREATE TABLE images (\n\tid INTEGER NOT NULL, \n\tname VARCHAR(255), \n\ttype VARCHAR(30), \n\tsize INTEGER, \n\tstatus VARCHAR(30) NOT NULL, \n\tis_public BOOLEAN NOT NULL, \n\tlocation TEXT, \n\tcreated_at DATETIME NOT NULL, \n\tupdated_at DATETIME, \n\tdeleted_at DATETIME, \n\tdeleted BOOLEAN NOT NULL, \n\tPRIMARY KEY (id), \n\tCHECK (is_public IN (0, 1)), \n\tCHECK (deleted IN (0, 1))\n)\n\n' ()
dpkg: error processing glance (--configure):
 subprocess installed post-installation script returned error exit status 1
Processing triggers for python-support ...
Errors were encountered while processing:
 glance
E: Sub-process /usr/bin/dpkg returned an error code (1)

Jay Pipes (jaypipes) said : #17

Well, we've made a mess of things, haven't we Howard... ;)

OK, this is a totally separate issue (there's been like 4 separate bugs you've run into in this single question!). I will get with the Glance devs and figure out a solution. This was solved before, but the "fix" for this was removed because it broke other things...

I'll update you as soon as I can,
jay

Launchpad Janitor (janitor) said : #18

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

Howard Taylor (howard-h) said : #19

Is there no further word on this?

Jay Pipes (jaypipes) said : #20

Hi Howard,

I'm not sure what I can do here. There's been some sort of corruption of the registry database, where the db_sync command is bombing out. The corruption is due to the registry database apparently not having the correct database version record in the migration table. I'm not sure what I can recommend other than re-installing Glance's database. Perhaps the only other solution would to make a tarball of the SQL dump of your glance registry, email me the tarball and I can try to figure out how to uncorrupt it.

-jay

daniel yin (r8921039) said : #21

we faced the same issue and after following Jay's advice, we issued the following commands to Compute node and then it worked! (so that now we no longer need to manually move /var/lib/nova/instances/_base from Controller node to Compute node to launch/run instances on Compute node.)

sudo apt-get purge nova-compute
sudo apt-get install glance
sudo purge nova-common
sudo apt-get install nova-compute
mkdir /var/lib/nova/instances
chmod 777 /var/lib/nova/instances
sudo /etc/init.d/libvirt-bin restart
sudo restart nova-compute

(note: we didn't do sync_db on Compute node)

daniel

daniel yin (r8921039) said : #22

forgot to mention that we're using "diablo d3" from the ppa:nova-core/milestone

Howard Taylor (howard-h) said : #23

I'll give that a go and post an update--I'm using Cactus.

Can you help with this problem?

Provide an answer of your own, or ask Howard Taylor for more information if necessary.

To post a message you must log in.