Glance

Glance - HTTPInternalServerError (HTTP 500) - Help!

Asked by Richard Cunningham

Hi,

I am looking for some help debugging glance. My build is:

cunningr@OpenStack:/tmp/images$ uname -a
Linux OpenStack 3.5.0-17-generic #28-Ubuntu SMP Tue Oct 9 19:31:23 UTC
2012 x86_64 x86_64 x86_64 GNU/Linux

glance is the latest version:

cunningr@OpenStack:/tmp/images$ sudo apt-get install glance
[sudo] password for cunningr:
Reading package lists... Done
Building dependency tree
Reading state information... Done
glance is already the newest version.
0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded.

(not sure how to get the version from glance as "glance --version" is
not working)

When I try to add an image as per the install guidelines I get
"HTTPInternalServerError (HTTP 500)".

I worked through some authentication errors already with keystone and
I _think_ this part is working now. When I try to get an auth token
with curl using the same credentials it seems to work ok:

cunningr@OpenStack:/tmp/images$ curl -k -X 'POST' -v
http://127.0.0.1:5000/v2.0/tokens -d
'{"auth":{"passwordCredentials":{"username": "glance",
"password":"glance"}, "tenantId":"f931d6fac2ca4640b72c3e34bbbc7496"}}'
-H 'Content-type: application/json'
* About to connect() to 127.0.0.1 port 5000 (#0)
* Trying 127.0.0.1...
* connected
* Connected to 127.0.0.1 (127.0.0.1) port 5000 (#0)
> POST /v2.0/tokens HTTP/1.1
> User-Agent: curl/7.27.0
> Host: 127.0.0.1:5000
> Accept: */*
> Content-type: application/json
> Content-Length: 123
>
* upload completely sent off: 123 out of 123 bytes
* additional stuff not fine transfer.c:1037: 0 0
* HTTP 1.1 or later with persistent connection, pipelining supported
< HTTP/1.1 200 OK
< Vary: X-Auth-Token
< Content-Type: application/json
< Date: Wed, 16 Jan 2013 20:31:38 GMT
< Transfer-Encoding: chunked
<
* Connection #0 to host 127.0.0.1 left intact
{"access": {"token": {"expires": "2013-01-17T20:31:38Z", "id":
"29c7ab7bbd6d48edaf3c2348d4552605", "tenant": {"enabled": true,
"description": null, "name": "service", "id":
"f931d6fac2ca4640b72c3e34bbbc7496"}}, "serviceCatalog": [{"endpoints":
[{"adminURL": "http://192.168.1.77:9292", "region": "myregion",
"internalURL": "http://192.168.1.77:9292", "id":
"ed983128768d418a854e8bf7862fb12e", "publicURL":
"http://192.168.1.77:9292"}], "endpoints_links": [], "type": "image",
"name": "glance"}], "user": {"username": "glance", "roles_links": [],
"id": "4eedc5061093419a9ca95435f4f60cd4", "roles": [{"name":
"admin"}], "name": "glance"}, "metadata": {"is_admin": 0, "roles":
["ff3a8f105bee464d8ac9930ea0ae802d"]}}}* Closing connection #0

But when I try to add an image with Glance I get an internal server error:

cunningr@OpenStack:/tmp/images$ glance -dv --os_username=glance
--os_password=glance --os_tenant_name=demo
--os_auth_url=http://127.0.0.1:5000/v2.0 add name="tty-linux-kernel"
disk_format=aki container_format=aki <
ttylinux-uec-amd64-12.1_2.6.35-22_1-vmlinuz
No handlers could be found for logger "keystoneclient.v2_0.client"
curl -i -X POST -H 'x-image-meta-container_format: aki' -H
'x-image-meta-protected: False' -H 'x-image-meta-min_disk: 0' -H
'User-Agent: python-glanceclient' -H 'x-image-meta-size: 4404752' -H
'x-image-meta-is_public: False' -H 'x-image-meta-min_ram: 0' -H
'X-Auth-Token: 4cb5873786ee4945af95306ecf4dd630' -H 'Content-Type:
application/octet-stream' -H 'x-image-meta-disk_format: aki' -H
'x-image-meta-name: tty-linux-kernel' -d '<open file '<stdin>', mode
'r' at 0x7fbc1f677150>' http://192.168.1.77:9292/v1/images

HTTP/1.1 500 Internal Server Error
date: Wed, 16 Jan 2013 20:37:42 GMT
content-length: 4044
content-type: text/plain
connection: close

Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 382,
in handle_one_response
    result = self.application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 210, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/wsgi.py", line
326, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1086,
in get_response
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1055,
in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/keystone/middleware/auth_token.py",
line 278, in __call__
    return self.app(env, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 210, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/wsgi.py", line
326, in __call__
    response = req.get_response(self.application)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1086,
in get_response
    application, catch_exc_info=False)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1055,
in call_application
    app_iter = application(self.environ, start_response)
  File "/usr/lib/python2.7/dist-packages/paste/urlmap.py", line 203, in __call__
    return app(environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 159, in __call__
    return resp(environ, start_response)
  File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line
131, in __call__
    response = self.app(environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 159, in __call__
    return resp(environ, start_response)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
    resp = self.call_func(req, *args, **self.kwargs)
  File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 210, in call_func
    return self.func(req, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/wsgi.py", line
532, in __call__
    request, **action_args)
  File "/usr/lib/python2.7/dist-packages/glance/common/wsgi.py", line
549, in dispatch
    return method(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/utils.py", line
408, in wrapped
    return func(self, req, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/api/v1/images.py",
line 684, in create
    image_meta = self._reserve(req, image_meta)
  File "/usr/lib/python2.7/dist-packages/glance/api/v1/images.py",
line 362, in _reserve
    image_meta = registry.add_image_metadata(req.context, image_meta)
  File "/usr/lib/python2.7/dist-packages/glance/registry/__init__.py",
line 139, in add_image_metadata
    return c.add_image(image_meta)
  File "/usr/lib/python2.7/dist-packages/glance/registry/client.py",
line 140, in add_image
    res = self.do_request("POST", "/images", body=body, headers=headers)
  File "/usr/lib/python2.7/dist-packages/glance/registry/client.py",
line 89, in do_request
    action, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/client.py",
line 63, in wrapped
    return func(self, *args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/glance/common/client.py",
line 444, in do_request
    headers=headers)
  File "/usr/lib/python2.7/dist-packages/glance/common/client.py",
line 80, in wrapped
    return func(self, method, url, body, headers)
  File "/usr/lib/python2.7/dist-packages/glance/common/client.py",
line 581, in _do_request
    raise exception.ServerError()
ServerError: The request returned 500 Internal Server Error.

Request returned failure status.
None
HTTPInternalServerError (HTTP 500)

Can anyone help me debug this?

Cheers,

R

Question information

Language:
English Edit question
Status:
Solved
For:
Glance Edit question
Assignee:
No assignee Edit question
Solved by:
Richard Cunningham
Solved:
Last query:
Last reply:
Revision history for this message
Eoghan Glynn (eglynn) said : 		#1

The 500 is being thrown from the glance-registry service API call to persist the image metadata.

Check your /etc/glance/glance-registry.conf to ensure the sql_connection config option is set properly, for example:

  sql_connection = mysql://username:password@mysql/glance

(where username and password relate to the mysql credentials).

Check the /var/log/glance/registry.log for an indication as to why the metadata registration is failing. If there is nothing enlightening in the log, try up'ing the log verbosity with debug=True & verbose=True in /etc/glance/glance-api.conf, then restart the glance-registry service.

Revision history for this message
Richard Cunningham (cunningr) said : 		#2

Thanks for the response. Here are my sql_connection setting:

cunningr@OpenStack:~$ sudo grep sql_connection /etc/glance/glance-registry.conf
#sql_connection = sqlite:////var/lib/glance/glance.sqlite
sql_connection = mysql://glance:glance@192.168.1.77/glance
cunningr@OpenStack:~$ sudo grep sql_connection /etc/glance/glance-api.conf
#sql_connection = sqlite:////var/lib/glance/glance.sqlite
sql_connection = mysql://glance:glance@192.168.1.77/glance

I upped the verbosity for both the api and registry service and reran the command.

In the registry log I see:

2013-01-18 13:15:27 3512 INFO sqlalchemy.engine.base.Engine [-] BEGIN (implicit)
2013-01-18 13:15:27 3512 INFO sqlalchemy.engine.base.Engine [-] INSERT INTO images (created_at, updated_at, deleted_at, deleted, id, name, disk_format, container_format, size, status, is_public, location, checksum, min_disk, min_ram, owner, protected) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)
2013-01-18 13:15:27 3512 INFO sqlalchemy.engine.base.Engine [-] (datetime.datetime(2013, 1, 18, 13, 15, 27, 531373), datetime.datetime(2013, 1, 18, 13, 15, 27, 531381), None, 0, '53c06e6d-ced7-4ee0-9a92-acfc2d8219c7', 'tty-linux-kernel', 'aki', 'aki', 4404752, 'queued', 0, None, None, 0, 0, 'f9a70976a8064aceb3523191e03d8c1c', 0)
2013-01-18 13:15:27 3512 INFO sqlalchemy.engine.base.Engine [-] ROLLBACK

In the api log I see:

2013-01-18 13:16:59 3538 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: POST /v1/images Accept: process_request /usr/lib/python2.7/dist-packages/glance/api/middleware/version_negotiation.py:45
2013-01-18 13:16:59 3538 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /usr/lib/python2.7/dist-packages/glance/api/middleware/version_negotiation.py:58
2013-01-18 13:16:59 3538 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v1 process_request /usr/lib/python2.7/dist-packages/glance/api/middleware/version_negotiation.py:70
2013-01-18 13:16:59 3538 DEBUG glance.api.middleware.version_negotiation [-] new uri /v1/images process_request /usr/lib/python2.7/dist-packages/glance/api/middleware/version_negotiation.py:71
2013-01-18 13:16:59 DEBUG glance.api.policy [e217f215-4b10-4a50-b855-57cca1d90b92 4eedc5061093419a9ca95435f4f60cd4 f9a70976a8064aceb3523191e03d8c1c] Loaded policy rules: {u'default': [], u'manage_image_cache': [[u'role:admin']]} load_rules /usr/lib/python2.7/dist-packages/glance/api/policy.py:63
2013-01-18 13:16:59 DEBUG glance.registry [e217f215-4b10-4a50-b855-57cca1d90b92 4eedc5061093419a9ca95435f4f60cd4 f9a70976a8064aceb3523191e03d8c1c] Adding image metadata... add_image_metadata /usr/lib/python2.7/dist-packages/glance/registry/__init__.py:137
2013-01-18 13:16:59 DEBUG glance.common.client [e217f215-4b10-4a50-b855-57cca1d90b92 4eedc5061093419a9ca95435f4f60cd4 f9a70976a8064aceb3523191e03d8c1c] Constructed URL: http://127.0.0.1:9191/images _construct_url /usr/lib/python2.7/dist-packages/glance/common/client.py:464
2013-01-18 13:16:59 ERROR glance.registry.client [e217f215-4b10-4a50-b855-57cca1d90b92 4eedc5061093419a9ca95435f4f60cd4 f9a70976a8064aceb3523191e03d8c1c] Registry request POST /images Exception
2013-01-18 13:16:59 3538 TRACE glance.registry.client Traceback (most recent call last):
2013-01-18 13:16:59 3538 TRACE glance.registry.client File "/usr/lib/python2.7/dist-packages/glance/registry/client.py", line 89, in do_request
2013-01-18 13:16:59 3538 TRACE glance.registry.client action, **kwargs)
2013-01-18 13:16:59 3538 TRACE glance.registry.client File "/usr/lib/python2.7/dist-packages/glance/common/client.py", line 63, in wrapped
2013-01-18 13:16:59 3538 TRACE glance.registry.client return func(self, *args, **kwargs)
2013-01-18 13:16:59 3538 TRACE glance.registry.client File "/usr/lib/python2.7/dist-packages/glance/common/client.py", line 444, in do_request
2013-01-18 13:16:59 3538 TRACE glance.registry.client headers=headers)
2013-01-18 13:16:59 3538 TRACE glance.registry.client File "/usr/lib/python2.7/dist-packages/glance/common/client.py", line 80, in wrapped
2013-01-18 13:16:59 3538 TRACE glance.registry.client return func(self, method, url, body, headers)
2013-01-18 13:16:59 3538 TRACE glance.registry.client File "/usr/lib/python2.7/dist-packages/glance/common/client.py", line 581, in _do_request
2013-01-18 13:16:59 3538 TRACE glance.registry.client raise exception.ServerError()
2013-01-18 13:16:59 3538 TRACE glance.registry.client ServerError: The request returned 500 Internal Server Error.
2013-01-18 13:16:59 3538 TRACE glance.registry.client

Are there any clues here?

Revision history for this message
Eoghan Glynn (eglynn) said : 		#3

There's not much indication in the registry log as to why the attempted insertion failed.

Can you try the following with the mysql client:

$ echo "INSERT INTO images (created_at, updated_at, deleted_at, deleted, id, name, disk_format, \
     container_format, size, status, is_public, location, checksum, min_disk, min_ram, owner, protected) \
     VALUES ('2013-01-18 17:00:00', '2013-01-18 17:00:00', NULL, 0, '53c06e6d-ced7-4ee0-9a92-acfc2d8219c7', \
     'tty-linux-kernel', 'aki', 'aki', 4404752, 'queued', 0, NULL, NULL, 0, 0, 'f9a70976a8064aceb3523191e03d8c1c', 0);" \
      | mysql -u glance -pglance glance

and report back the error.

Revision history for this message
Richard Cunningham (cunningr) said : 		#4

Thanks a lot! When I ran that command I discovered that the glance DB tables did not exist in MYSQL also show with:

mysql> use glance;
Database changed
mysql> SHOW TABLES;
Empty set (0.00 sec)

mysql> exit
Bye

I had to run the " glance-manage db_sync" with sudo for some reason (it returned ok without but didn't actually instantiate anything). After I did this:

mysql> use glance
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> SHOW TABLES;
+------------------+
| Tables_in_glance |
 +------------------+
| image_members |
| image_properties |
| image_tags |
| images |
| migrate_version |
 +------------------+
5 rows in set (0.00 sec)

and now:

cunningr@OpenStack:/tmp/images$ glance -dv --os_username=glance --os_password=glance --os_tenant_name=demo --os_auth_url=http://127.0.0.1:5000/v2.0 add name="tty-linux-kernel" disk_format=aki container_format=aki < ttylinux-uec-amd64-12.1_2.6.35-22_1-vmlinuz
No handlers could be found for logger "keystoneclient.v2_0.client"
curl -i -X POST -H 'x-image-meta-container_format: aki' -H 'x-image-meta-protected: False' -H 'x-image-meta-min_disk: 0' -H 'User-Agent: python-glanceclient' -H 'x-image-meta-size: 4404752' -H 'x-image-meta-is_public: False' -H 'x-image-meta-min_ram: 0' -H 'X-Auth-Token: a3998fbd720f40808e49c305ae0e2748' -H 'Content-Type: application/octet-stream' -H 'x-image-meta-disk_format: aki' -H 'x-image-meta-name: tty-linux-kernel' -d '<open file '<stdin>', mode 'r' at 0x7f5f05ef9150>' http://192.168.1.77:9292/v1/images

HTTP/1.1 201 Created
content-length: 463
etag: 3ed2965d3f8d877a3ee3e061fd648e9a
location: http://192.168.1.77:9292/v1/images/cbb6423d-47ce-47db-9a1b-04a8b419fabe
date: Fri, 18 Jan 2013 19:01:30 GMT
content-type: application/json
x-openstack-request-id: req-0be4c470-b4a7-421a-8542-ba264af3a994

{"image": {"status": "active", "name": "tty-linux-kernel", "deleted": false, "container_format": "aki", "created_at": "2013-01-18T19:01:30", "disk_format": "aki", "updated_at": "2013-01-18T19:01:30", "properties": {}, "min_disk": 0, "protected": false, "id": "cbb6423d-47ce-47db-9a1b-04a8b419fabe", "checksum": "3ed2965d3f8d877a3ee3e061fd648e9a", "owner": "f9a70976a8064aceb3523191e03d8c1c", "is_public": false, "deleted_at": null, "min_ram": 0, "size": 4404752}}

Added new image with ID: cbb6423d-47ce-47db-9a1b-04a8b419fabe
Returned the following metadata for the new image:
                       checksum => 3ed2965d3f8d877a3ee3e061fd648e9a
               container_format => aki
                     created_at => 2013-01-18T19:01:30
                        deleted => False
                     deleted_at => None
                    disk_format => aki
                             id => cbb6423d-47ce-47db-9a1b-04a8b419fabe
                      is_public => False
                       min_disk => 0
                        min_ram => 0
                           name => tty-linux-kernel
                          owner => f9a70976a8064aceb3523191e03d8c1c
                     properties => {}
                      protected => False
                           size => 4404752
                         status => active
                     updated_at => 2013-01-18T19:01:30

Thanks for the help eglynn