Glance

glance add image failure

Bug #997918 reported by Aleksandr Dobdin
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Glance
Invalid
Undecided
Unassigned

Bug Description

ubuntu 12.04
#glance --version
 glance 2012.1

#glance --verbose --os_auth_token=17abb7f5279f46a58716e611dbfb90b7 add name="My Image" disk_format=qcow2 < t.img

Console output
Uploading image 'My Image'
Failed to add image. Got error:
unsupported operand type(s) for +=: 'int' and 'tuple'
Note: Your image metadata may still be in the registry, but the image's status will likely be 'killed'.
Completed in 0.0008 sec.

traceback:
2012-05-11 06:26:16 19155 DEBUG [routes.middleware] Initialized with method overriding = True, and path info altering = True
2012-05-11 06:26:16 19155 INFO [keystone.middleware.auth_token] Starting keystone auth_token middleware
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] ********************************************************************************
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] Configuration options gathered from:
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] command line args: None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] config files: ['/etc/glance/glance-api.conf']
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] ================================================================================
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] admin_role = admin
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] config_file = ['/etc/glance/glance-api.conf']
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] debug = True
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] default_store = file
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] filesystem_store_datadir = /var/lib/glance/images/
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] log_config = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] log_date_format = %Y-%m-%d %H:%M:%S
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] log_dir = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] log_file = /var/log/glance/api.log
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] log_format = %(asctime)s %(process)d %(levelname)8s [%(name)s] %(message)s
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] metadata_encryption_key = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] notifier_strategy = noop
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] owner_is_tenant = True
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] policy_default_rule = default
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] policy_file = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] rbd_store_ceph_conf = /etc/ceph/ceph.conf
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] rbd_store_chunk_size = 8
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] rbd_store_pool = images
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] rbd_store_user = glance
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] registry_client_ca_file = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] registry_client_cert_file = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] registry_client_key_file = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] registry_client_protocol = http
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] registry_host = 0.0.0.0
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] registry_port = 9191
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] s3_store_access_key = ************************
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] s3_store_bucket = <lowercased 20-char aws access key>glance
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] s3_store_create_bucket_on_put = False
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] s3_store_host = 127.0.0.1:8080/v1.0/
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] s3_store_object_buffer_dir = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] s3_store_secret_key = ************************
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_enable_snet = False
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_auth_address = 127.0.0.1:35357/v2.0/
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_auth_version = 2
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_container = glance
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_create_container_on_put = False
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_key = ********************************
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_large_object_chunk_size = 200
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_large_object_size = 5120
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] swift_store_user = *********
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] syslog_log_facility = LOG_USER
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] use_syslog = False
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] verbose = True
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] paste_deploy.config_file = None
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] paste_deploy.flavor = keystone
2012-05-11 06:26:16 19155 DEBUG [glance-api-keystone] ********************************************************************************
2012-05-11 06:26:16 19155 INFO [eventlet.wsgi.server] Starting single process server
2012-05-11 06:26:16 19155 DEBUG [eventlet.wsgi.server] (19155) wsgi starting up on http://0.0.0.0:9292/
2012-05-11 06:38:19 19155 DEBUG [glance.api.middleware.version_negotiation] Processing request: POST /v1/images Accept:
2012-05-11 06:38:19 19155 DEBUG [glance.api.middleware.version_negotiation] Matched versioned URI. Version: 1.0
2012-05-11 06:38:19 19155 DEBUG [keystone.middleware.auth_token] Authenticating user token
2012-05-11 06:38:19 19155 DEBUG [keystone.middleware.auth_token] Removing headers from request environment: X-Identity-Status,X-Tenant-Id,X-Tenant-Name,X-User-Id,X-User-Name,X-Roles,X-User,X-Tenant,X-Role
2012-05-11 06:38:19 19155 DEBUG [routes.middleware] Matched POST /images
2012-05-11 06:38:19 19155 DEBUG [routes.middleware] Route path: '/images', defaults: {'action': u'create', 'controller': <glance.common.wsgi.Resource object at 0x3d37bd0>}
2012-05-11 06:38:19 19155 DEBUG [routes.middleware] Match dict: {'action': u'create', 'controller': <glance.common.wsgi.Resource object at 0x3d37bd0>}
2012-05-11 06:38:19 19155 DEBUG [glance.registry] Adding image metadata...
2012-05-11 06:38:19 19155 DEBUG [glance.api.v1.images] Setting image a821d20e-d3b7-4011-a26b-244b868630a1, <LimitedLengthFile(<eventlet.wsgi.Input object at 0x3d54850>, maxlen=197120)>, 197120 to status 'saving'
2012-05-11 06:38:19 19155 DEBUG [glance.registry] Updating image metadata for image a821d20e-d3b7-4011-a26b-244b868630a1...
2012-05-11 06:38:20 19155 DEBUG [glance.api.v1.images] Uploading image data for image a821d20e-d3b7-4011-a26b-244b868630a1 to file store
2012-05-11 06:38:20 19155 ERROR [glance.api.v1.images] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/glance/api/v1/images.py", line 390, in _upload
    location, size, checksum = store.add(image_meta['id'], image_data, image_size)
  File "/usr/lib/python2.7/dist-packages/glance/store/filesystem.py", line 202, in add
    ChunkedFile.CHUNKSIZE):
  File "/usr/lib/python2.7/dist-packages/glance/common/utils.py", line 61, in chunkiter
    chunk = fp.read(chunk_size)
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1284, in read
    self._check_disconnect()
  File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1311, in _check_disconnect
    + "(%d more bytes were expected)" % self.remaining
DisconnectionError: The client disconnected while sending the POST/PUT body (131584 more bytes were expected)

2012-05-11 06:38:20 19155 DEBUG [glance.registry] Updating image metadata for image a821d20e-d3b7-4011-a26b-244b868630a1...
2012-05-11 06:38:20 19155 DEBUG [eventlet.wsgi.server] 127.0.0.1 - - [11/May/2012 06:38:20] "POST /v1/images HTTP/1.1" 400 380 0.317791

Revision history for this message
Eoghan Glynn (eglynn) wrote :

Hi Aleksandr,

To what extent is this image add failure reproducible? (does it only occur for certain image sizes, and/or only intermittently?)

Does the issue occur with the --silent-upload option?

Also can you put a quick temporary change to bin/glance to display the traceback for the exception? Something like:

  diff --git a/bin/glance b/bin/glance
  index 5bbc22d..3c415d8 100755
  --- a/bin/glance
  +++ b/bin/glance
  @@ -298,6 +298,9 @@ EXAMPLES
                   print piece
               print ("Note: Your image metadata may still be in the registry, "
                      "but the image's status will likely be 'killed'.")
  + import traceback
  + exc_type, exc_value, exc_traceback = sys.exc_info()
  + traceback.print_tb(exc_traceback, file=sys.stdout)
               return FAILURE
       else:
           print "Dry run. We would have done the following:"

Revision history for this message
Aleksandr Dobdin (dobdin) wrote :

after patch glance
glance --verbose --os_auth_token=0204f780ab1d42cb974e3443856094ed add name="My Image" --silent-upload is_public=true container_format=ovf disk_format=qcow2 < t.img
Failed to add image. Got error:
unsupported operand type(s) for +=: 'int' and 'tuple'
Note: Your image metadata may still be in the registry, but the image's status will likely be 'killed'.
  File "/usr/bin/glance", line 273, in image_add
    features=features)
  File "/usr/lib/python2.7/dist-packages/glance/client.py", line 161, in add_image
    res = self.do_request("POST", "/images", body, headers)
  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 438, 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 542, in _do_request
    _sendbody(c, iter)
  File "/usr/lib/python2.7/dist-packages/glance/common/client.py", line 509, in _sendbody
    for sent in iter:
  File "/usr/lib/python2.7/dist-packages/glance/common/client.py", line 155, in __iter__
    self.offset += sent
Completed in 0.0206 sec.

Thanks, in advance

Revision history for this message
Brian Waldon (bcwaldon) wrote :

This doesn't make much sense: it appears that 'sent' is being set in what appears to be a different scope, but is being used on line 155 in the sendfile loop. Can someone else confirm this?

Changed in glance:
status: New → Incomplete
Revision history for this message
Stuart McLaren (stuart-mclaren) wrote :

I wonder could this be related to the version of python-sendfile?

I saw something similar when running one of the unit tests -- upgrading to python-sendfile 2.0.0-5 seemed to help.

Revision history for this message
Brian Waldon (bcwaldon) wrote :

Aleksandr - is this still a problem for you? Did you try updating python-sendfile?

Brian Waldon (bcwaldon)
Changed in glance:
status: Incomplete → Invalid
Sascha Peilicke (saschpe)
Changed in glance:
status: Invalid → Confirmed
Revision history for this message
Sascha Peilicke (saschpe) wrote :
Download full text (3.6 KiB)

I can confirm the issue, it happens when running the testsuite without a virtualenv, i.e. with different Python module versions:

2012-12-12 17:07:38 ======================================================================
2012-12-12 17:07:38 ERROR: test_add_image_with_image_data_as_file_with_sendfile (glance.tests.unit.test_clients.TestClient)
2012-12-12 17:07:38 ----------------------------------------------------------------------
2012-12-12 17:07:38 Traceback (most recent call last):
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/tests/utils.py", line 109, in _skipper
2012-12-12 17:07:38 func(*args, **kw)
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/tests/unit/test_clients.py", line 1858, in test_add_image_with_image_data_as_file_with_sendfile
2012-12-12 17:07:38 self.add_image_with_image_data_as_file(sendfile=True)
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/tests/unit/test_clients.py", line 1814, in add_image_with_image_data_as_file
2012-12-12 17:07:38 new_image = self.client.add_image(fixture, open(tmp_image_filepath))
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/client.py", line 165, in add_image
2012-12-12 17:07:38 res = self.do_request("POST", "/images", body, headers)
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/common/client.py", line 63, in wrapped
2012-12-12 17:07:38 return func(self, *args, **kwargs)
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/common/client.py", line 444, in do_request
2012-12-12 17:07:38 headers=headers)
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/common/client.py", line 80, in wrapped
2012-12-12 17:07:38 return func(self, method, url, body, headers)
2012-12-12 17:07:38 File "/var/lib/openstack-glance-test/glance/common/client.py", line 589, in _do_request
2012-12-12 17:07:38 raise exception.ClientConnectionError(e)
2012-12-12 17:07:38 ClientConnectionError: The client disconnected while sending the POST/PUT body (19 more bytes were expected)

While I haven't yet found out why, I discovered something strange:

% ./run_tests.sh -N -s --pdb glance.tests.unit.test_clients:TestClient.test_add_image_with_image_data_as_file_with_sendfile
/root/Projects/suse/openstack/glance/glance/tests/unit/test_clients.py:22: UserWarning: The 'glance.client' module is deprecated in favor of the 'glanceclient' module provided by python-glanceclient (see http://github.com/openstack/python-glanceclient).
  from glance import client

TestClient
    test_add_image_with_image_data_as_file_with_sendfile > /root/Projects/suse/openstack/glance/glance/common/client.py(589)_do_request()
-> raise exception.ClientConnectionError(e)
(Pdb) l
584 else:
585 raise exception.UnexpectedStatus(status=status_code,
586 body=res.read())
587
588 except (socket.error, IOError), e:
589 -> raise exception.ClientConnectionError(e)
590
591 def _seekable(self, body):
592 # pipes are not seekable, avoids sendfile() failure on e.g.
593 ...

Read more...

Revision history for this message
Sascha Peilicke (saschpe) wrote :

Ok, it's another WebOb issue, it does happen when I upgrade it to version 1.2.3 in the venv.

Revision history for this message
Sascha Peilicke (saschpe) wrote :

Or maybe I misread, my issues seems unrelated to this one

Changed in glance:
status: Confirmed → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.