nova-docker

pull image failed

Bug #1418803 reported by boh.ricky
18
This bug affects 4 people
Affects Status Importance Assigned to Milestone
nova-docker
Incomplete
Undecided
Ashish Billore

Bug Description

When boot a docker container(image is not exist in the nova-compute node), the pull images failed.
But in fact the image is successfully downloaded( verify by "docker images" command).
The problem is repeatable.

nova-compute.log information:
[root@A-172 ~]# tail -f /var/log/nova/nova-compute.log|grep ac103eeb-a2b0-4b49-a863-c39bcb43975f
2015-02-02 04:11:55.326 28983 DEBUG nova.compute.utils [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Cannot load repository file: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=10) notify_about_instance_usage /usr/lib/python2.7/site-packages/nova/compute/utils.py:307
2015-02-02 04:11:55.331 28983 DEBUG nova.compute.manager [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Build of instance ac103eeb-a2b0-4b49-a863-c39bcb43975f was re-scheduled: Cannot load repository file: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=10) _do_build_and_run_instance /usr/lib/python2.7/site-packages/nova/compute/manager.py:2032
2015-02-02 04:11:55.530 28983 DEBUG nova.openstack.common.lockutils [-] Releasing semaphore "ac103eeb-a2b0-4b49-a863-c39bcb43975f" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:238

[root@A-172 ~]# grep ac103eeb-a2b0-4b49-a863-c39bcb43975f /var/log/nova/nova-compute.log
2015-02-02 04:11:39.952 28983 DEBUG nova.openstack.common.lockutils [-] Created new semaphore "ac103eeb-a2b0-4b49-a863-c39bcb43975f" internal_lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206
2015-02-02 04:11:39.952 28983 DEBUG nova.openstack.common.lockutils [-] Acquired semaphore "ac103eeb-a2b0-4b49-a863-c39bcb43975f" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:229
2015-02-02 04:11:39.971 28983 AUDIT nova.compute.manager [req-94c8a6ed-40c5-4af3-b096-9b1360407c46 None] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Starting instance...
2015-02-02 04:11:40.074 28983 AUDIT nova.compute.claims [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Attempting claim: memory 512 MB, disk 1 GB
2015-02-02 04:11:40.074 28983 AUDIT nova.compute.claims [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Total memory: 48131 MB, used: 2560.00 MB
2015-02-02 04:11:40.074 28983 AUDIT nova.compute.claims [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] memory limit: 72196.50 MB, free: 69636.50 MB
2015-02-02 04:11:40.074 28983 AUDIT nova.compute.claims [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Total disk: 49 GB, used: 20.00 GB
2015-02-02 04:11:40.074 28983 AUDIT nova.compute.claims [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] disk limit not specified, defaulting to unlimited
2015-02-02 04:11:40.085 28983 AUDIT nova.compute.claims [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Claim successful
2015-02-02 04:11:40.318 28983 DEBUG nova.compute.manager [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Allocating IP information in the background. _allocate_network_async /usr/lib/python2.7/site-packages/nova/compute/manager.py:1628
2015-02-02 04:11:40.318 28983 DEBUG nova.network.neutronv2.api [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] allocate_for_instance() allocate_for_instance /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:279
REQ: curl -i http://186.100.21.172:9696/v2.0/ports.json -X POST -H "X-Auth-Token: 2ea4ae5d5cf7412da7b07cdb94d1f81a" -H "User-Agent: python-neutronclient" -d '{"port": {"binding:host_id": "A-172", "admin_state_up": true, "network_id": "2510a249-1665-4184-afc8-62a2eccf6c3b", "tenant_id": "3cf2410b5f554653a93796982657984b", "device_owner": "compute:nova", "security_groups": ["462e4fb8-539a-489e-8d41-14f0234f71cf"], "device_id": "ac103eeb-a2b0-4b49-a863-c39bcb43975f"}}'
2015-02-02 04:11:40.748 28983 DEBUG neutronclient.client [-] RESP:201 {'date': 'Mon, 02 Feb 2015 09:11:40 GMT', 'content-length': '724', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-4e7661be-9921-4d16-b5d7-89cadc9e6185'} {"port": {"status": "DOWN", "binding:host_id": "A-172", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "compute:nova", "binding:profile": {}, "fixed_ips": [{"subnet_id": "5c057651-2193-48b2-9883-f57e352ff344", "ip_address": "10.0.0.11"}], "id": "2fee26da-9b54-46bc-af80-0c2daee06f6e", "security_groups": ["462e4fb8-539a-489e-8d41-14f0234f71cf"], "device_id": "ac103eeb-a2b0-4b49-a863-c39bcb43975f", "name": "", "admin_state_up": true, "network_id": "2510a249-1665-4184-afc8-62a2eccf6c3b", "tenant_id": "3cf2410b5f554653a93796982657984b", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:5a:a4:93"}}
2015-02-02 04:11:40.753 28983 DEBUG nova.network.neutronv2.api [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Successfully created port: 2fee26da-9b54-46bc-af80-0c2daee06f6e _create_port /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:216
2015-02-02 04:11:40.753 28983 DEBUG nova.openstack.common.lockutils [-] Created new semaphore "refresh_cache-ac103eeb-a2b0-4b49-a863-c39bcb43975f" internal_lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:206
2015-02-02 04:11:40.753 28983 DEBUG nova.openstack.common.lockutils [-] Acquired semaphore "refresh_cache-ac103eeb-a2b0-4b49-a863-c39bcb43975f" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:229
2015-02-02 04:11:40.753 28983 DEBUG nova.network.neutronv2.api [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py:610
REQ: curl -i http://186.100.21.172:9696/v2.0/ports.json?tenant_id=3cf2410b5f554653a93796982657984b&device_id=ac103eeb-a2b0-4b49-a863-c39bcb43975f -X GET -H "X-Auth-Token: 2ea4ae5d5cf7412da7b07cdb94d1f81a" -H "User-Agent: python-neutronclient"
2015-02-02 04:11:41.346 28983 DEBUG neutronclient.client [-] RESP:200 {'date': 'Mon, 02 Feb 2015 09:11:40 GMT', 'content-length': '727', 'content-type': 'application/json; charset=UTF-8', 'x-openstack-request-id': 'req-f0322351-f75a-4a25-b8b9-f089e63474fb'} {"ports": [{"status": "DOWN", "binding:host_id": "A-172", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "compute:nova", "binding:profile": {}, "fixed_ips": [{"subnet_id": "5c057651-2193-48b2-9883-f57e352ff344", "ip_address": "10.0.0.11"}], "id": "2fee26da-9b54-46bc-af80-0c2daee06f6e", "security_groups": ["462e4fb8-539a-489e-8d41-14f0234f71cf"], "device_id": "ac103eeb-a2b0-4b49-a863-c39bcb43975f", "name": "", "admin_state_up": true, "network_id": "2510a249-1665-4184-afc8-62a2eccf6c3b", "tenant_id": "3cf2410b5f554653a93796982657984b", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:5a:a4:93"}]}
2015-02-02 04:11:43.671 28983 DEBUG nova.openstack.common.lockutils [-] Releasing semaphore "refresh_cache-ac103eeb-a2b0-4b49-a863-c39bcb43975f" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:238
2015-02-02 04:11:43.671 28983 DEBUG nova.compute.manager [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Instance network_info: |[VIF({'profile': {}, 'ovs_interfaceid': u'2fee26da-9b54-46bc-af80-0c2daee06f6e', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.0.0.11'})], 'version': 4, 'meta': {'dhcp_server': u'10.0.0.3'}, 'dns': [], 'routes': [], 'cidr': u'10.0.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.0.0.1'})})], 'meta': {'injected': False, 'tenant_id': u'3cf2410b5f554653a93796982657984b'}, 'id': u'2510a249-1665-4184-afc8-62a2eccf6c3b', 'label': u'private'}), 'devname': u'tap2fee26da-9b', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:5a:a4:93', 'active': False, 'type': u'ovs', 'id': u'2fee26da-9b54-46bc-af80-0c2daee06f6e', 'qbg_params': None})]| _allocate_network_async /usr/lib/python2.7/site-packages/nova/compute/manager.py:1645
2015-02-02 04:11:53.529 28983 WARNING novadocker.virt.docker.driver [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Cannot load repository file: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=10)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Traceback (most recent call last):
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/driver.py", line 351, in _pull_missing_image
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] out_path
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/client.py", line 36, in wrapper
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] out = f(*args, **kwds)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/client.py", line 94, in load_repository_file
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] self.load_image(fh)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/client.py", line 36, in wrapper
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] out = f(*args, **kwds)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/docker/client.py", line 724, in load_image
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] res = self._post(self._url("/images/load"), data=data)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/docker/client.py", line 78, in _post
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] return self.post(url, **self._set_request_timeout(kwargs))
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/client.py", line 36, in wrapper
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] out = f(*args, **kwds)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 498, in post
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] return self.request('POST', url, data=data, **kwargs)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/client.py", line 36, in wrapper
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] out = f(*args, **kwds)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 456, in request
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] resp = self.send(prep, **send_kwargs)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/client.py", line 36, in wrapper
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] out = f(*args, **kwds)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 559, in send
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] r = adapter.send(request, **kwargs)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/requests/adapters.py", line 384, in send
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] raise Timeout(e, request=request)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Timeout: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=10)
2015-02-02 04:11:53.529 28983 TRACE novadocker.virt.docker.driver [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f]
2015-02-02 04:11:53.621 28983 ERROR nova.compute.manager [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Instance failed to spawn
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Traceback (most recent call last):
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2243, in _build_resources
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] yield resources
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2113, in _build_and_run_instance
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] block_device_info=block_device_info)
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/driver.py", line 394, in spawn
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] image = self._pull_missing_image(context, image_meta, instance)
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] File "/usr/lib/python2.7/site-packages/novadocker/virt/docker/driver.py", line 358, in _pull_missing_image
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] instance_id=image_meta['name'])
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] NovaException: Cannot load repository file: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=10)
2015-02-02 04:11:53.621 28983 TRACE nova.compute.manager [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f]
2015-02-02 04:11:53.622 28983 AUDIT nova.compute.manager [req-94c8a6ed-40c5-4af3-b096-9b1360407c46 None] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Terminating instance
2015-02-02 04:11:53.642 28983 DEBUG nova.compute.claims [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Aborting claim: [Claim: 512 MB memory, 1 GB disk] abort /usr/lib/python2.7/site-packages/nova/compute/claims.py:128
2015-02-02 04:11:55.326 28983 DEBUG nova.compute.utils [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Cannot load repository file: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=10) notify_about_instance_usage /usr/lib/python2.7/site-packages/nova/compute/utils.py:307
2015-02-02 04:11:55.331 28983 DEBUG nova.compute.manager [-] [instance: ac103eeb-a2b0-4b49-a863-c39bcb43975f] Build of instance ac103eeb-a2b0-4b49-a863-c39bcb43975f was re-scheduled: Cannot load repository file: UnixHTTPConnectionPool(host='localhost', port=None): Read timed out. (read timeout=10) _do_build_and_run_instance /usr/lib/python2.7/site-packages/nova/compute/manager.py:2032
2015-02-02 04:11:55.530 28983 DEBUG nova.openstack.common.lockutils [-] Releasing semaphore "ac103eeb-a2b0-4b49-a863-c39bcb43975f" lock /usr/lib/python2.7/site-packages/nova/openstack/common/lockutils.py:238

Ashish Billore (ashish.billore)
Changed in nova-docker:
assignee: nobody → Ashish Billore (ashish.billore)
Revision history for this message
Ashish Billore (ashish.billore) wrote :

I faced this issue with the latest Nova Docker Driver. This happened the first time for a given image.

One quick workaround is: configure "timeout" property in /usr/lib/python2.7/site-packages/novadocker/virt/docker/client.py::DockerHTTPClient::_ini_ to something more, say 30, currently it is set to 10.

Suspecting this is related to number of layers in a image, scenario is more likely for images with more layers compared to images with less layers. Needs more investigation here.

Another observation: Even though this error is seen, image is still there, reason could be: When NovaDocker client times out, the deamon in the back continues loading the image. so, when we check the image seems to be already there, despite the above error.

Investigating more on the above observation.

Ashish Billore (ashish.billore)
Changed in nova-docker:
status: New → In Progress
Revision history for this message
LiangChen (hs-chen) wrote :

@Ashish Billore (ashish.billore)
Should we use a CONF parameter in the configure file rather than use a hard code value(timeout 30)?

Revision history for this message
Ashish Billore (ashish.billore) wrote :

@LiangChen, regrets for delay on getting back on this.
So, I looked at the possibility of removing the hardcoding and making it configurable, however, my view is this may partially address the problem. Reason being this timeout is related to number of layers in a image being pulled. Even with configurable timeout, this issue will again be seen for images with more layers compared to images with less layers.
I am working on to get the layer or progress of pull and then based on it, wait for it to finish. I am planning to put up a working implemetation by this week and based on how it works for various images (with varying number of layers) will take it forward.
Hope this is fine, thanks.

Revision history for this message
LiangChen (hs-chen) wrote :

@Ashish Billore
I agree with you, It is the best way of controlling the time to avoid timeout by getting the layer or the progress when pulling image.
I hope it is fine, otherwise, we only make it configurable.
I'm waiting for your good news.
Thanks.

Revision history for this message
Davanum Srinivas (DIMS) (dims-v) wrote :

With latest docker-py

DEFAULT_TIMEOUT_SECONDS = 60

https://github.com/docker/docker-py/blob/master/docker/constants.py#L2

Do we still need a configurable option?

Changed in nova-docker:
status: In Progress → Incomplete
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.