Attempting next endpoint for pull after error: unauthorized: authentication required

[kennethkmp]

Output of docker version:

Client:
Version: 1.11.1
API version: 1.23
Go version: go1.5.4
Git commit: 5604cbe
Built: Wed Apr 27 00:34:42 2016
OS/Arch: linux/amd64

Server:
Version: 1.11.1
API version: 1.23
Go version: go1.5.4
Git commit: 5604cbe
Built: Wed Apr 27 00:34:42 2016
OS/Arch: linux/amd64

Output of docker info:

Containers: 0
Running: 0
Paused: 0
Stopped: 0
Images: 0
Server Version: 1.11.1
Storage Driver: devicemapper
Pool Name: docker-253:1-67168386-pool
Pool Blocksize: 65.54 kB
Base Device Size: 10.74 GB
Backing Filesystem: xfs
Data file: /dev/loop0
Metadata file: /dev/loop1
Data Space Used: 11.8 MB
Data Space Total: 107.4 GB
Data Space Available: 26.87 GB
Metadata Space Used: 581.6 kB
Metadata Space Total: 2.147 GB
Metadata Space Available: 2.147 GB
Udev Sync Supported: true
Deferred Removal Enabled: false
Deferred Deletion Enabled: false
Deferred Deleted Device Count: 0
Data loop file: /var/lib/docker/devicemapper/devicemapper/data
WARNING: Usage of loopback devices is strongly discouraged for production use. Either use --storage-opt dm.thinpooldev or use --storage-opt dm.no_warn_on_loop_devices=true to suppress this warning.
Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata
Library Version: 1.02.107-RHEL7 (2015-12-01)
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: null host bridge
Kernel Version: 3.10.0-327.10.1.el7.x86_64
Operating System: Red Hat Enterprise Linux Server 7.2 (Maipo)
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 7.64 GiB
Name: sysxxx-txx
ID: QQOP:OXDC:A55R:FIRL:2D4L:4CX3:DZSG:QCWP:4GY3:BOGM:DDPO:BCYB
Docker Root Dir: /var/lib/docker
Debug mode (client): false
Debug mode (server): false
Http Proxy: http://xxx:xxx@xxx.com:8080
Https Proxy: http://xxx:xxx@xxx.com:8080
Registry: https://index.docker.io/v1/
WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled

Additional environment details (AWS, VirtualBox, physical, etc.):
ESX VM

Steps to reproduce the issue:
1.

docker run hello-world

Unable to find image 'hello-world:latest' locally
Pulling repository docker.io/library/hello-world
docker: Could not reach any registry endpoint.
See 'docker run --help'.

Describe the results you received:

msg="Handler for POST /v1.23/containers/create returned error: No such image: hello-world:latest"
msg="Attempting next endpoint for pull after error: unauthorized: authentication required"
msg="unable to get remote tags: Could not reach any registry endpoint"
msg="Not continuing with pull after error: Could not reach any registry endpoint"

Describe the results you expected:

Image to be downloaded and run

Additional information you deem important (e.g. issue happens only occasionally):

The proxy has SSL interception, but the corporate certifica has been installed, curl with the same proxy settings against an htttps site works.

[jongiddy]

I'm seeing the same problem on VirtualBox, with SSL interception.

[vagrant@localhost ~]$ docker pull hello-world
Using default tag: latest
Pulling repository docker.io/library/hello-world
Could not reach any registry endpoint
[vagrant@localhost ~]$ curl -S https://index.docker.io/v1/repositories/library/hello-world/tags
[{"layer": "f1d956dc", "name": "latest"}]

From /var/log/messages:

May  9 06:19:00 localhost yum[12336]: Installed: docker-engine-selinux-1.11.1-1.
el7.centos.noarch
May  9 06:19:02 localhost yum[12336]: Installed: docker-engine-1.11.1-1.el7.cent
os.x86_64
May  9 06:19:02 localhost docker: time="2016-05-09T06:19:02.589911515-04:00" lev
el=info msg="New containerd process, pid: 12408\n"
May  9 06:19:03 localhost docker: time="2016-05-09T06:19:03.723571683-04:00" lev
el=warning msg="devmapper: Usage of loopback devices is strongly discouraged for
 production use. Please use `--storage-opt dm.thinpooldev` or use `man docker` t
o refer to dm.thinpooldev section."
May  9 06:19:03 localhost docker: time="2016-05-09T06:19:03.798796327-04:00" lev
el=info msg="devmapper: Creating filesystem xfs on device docker-253:0-394566-ba
se"
May  9 06:19:03 localhost docker: time="2016-05-09T06:19:03.897216214-04:00" lev
el=info msg="devmapper: Successfully created filesystem xfs on device docker-253
:0-394566-base"
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.000352952-04:00" lev
el=info msg="Graph migration to content-addressability took 0.00 seconds"
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.007765586-04:00" lev
el=warning msg="Running modprobe bridge br_netfilter failed with message: modpro
be: WARNING: Module br_netfilter not found.\ninsmod /lib/modules/3.10.0-327.13.1
.el7.x86_64/kernel/net/llc/llc.ko \ninsmod /lib/modules/3.10.0-327.13.1.el7.x86_
64/kernel/net/802/stp.ko \ninsmod /lib/modules/3.10.0-327.13.1.el7.x86_64/kernel
/net/bridge/bridge.ko \n, error: exit status 1"
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.023618581-04:00" lev
el=info msg="Firewalld running: false"
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.130708734-04:00" lev
el=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/
16. Daemon option --bip can be used to set a preferred IP address"
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): new Bridge dev
ice (carrier: OFF, driver: 'bridge', ifindex: 3)
May  9 06:19:04 localhost kernel: IPv6: ADDRCONF(NETDEV_UP): docker0: link is no
t ready
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
May  9 06:19:04 localhost NetworkManager[600]: <info>  ifcfg-rh: add connection
in-memory (5beb018f-533b-4a89-8def-becb94c43adb,"docker0")
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): Activation: st
arting connection 'docker0' (5beb018f-533b-4a89-8def-becb94c43adb)
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: disconnected -> prepare (reason 'none') [30 40 0]
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: prepare -> config (reason 'none') [40 50 0]
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: config -> ip-config (reason 'none') [50 70 0]
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: ip-config -> ip-check (reason 'none') [70 80 0]
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: ip-check -> secondaries (reason 'none') [80 90 0]
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): device state c
hange: secondaries -> activated (reason 'none') [90 100 0]
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.262128725-04:00" lev
el=warning msg="mountpoint for pids not found"
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.262555994-04:00" lev
el=info msg="Loading containers: start."
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.262588340-04:00" lev
el=info msg="Loading containers: done."
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.262595236-04:00" lev
el=info msg="Daemon has completed initialization"
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.262602612-04:00" lev
el=info msg="Docker daemon" commit=5604cbe graphdriver=devicemapper version=1.11
.1
May  9 06:19:04 localhost docker: time="2016-05-09T06:19:04.277856904-04:00" lev
el=info msg="API listen on /var/run/docker.sock"
May  9 06:19:04 localhost NetworkManager[600]: <info>  (docker0): Activation: su
ccessful, device activated.
May  9 06:19:04 localhost nm-dispatcher: Dispatching action 'up' for docker0
May  9 06:19:18 localhost docker: time="2016-05-09T06:19:18.285577603-04:00" lev
el=error msg="Attempting next endpoint for pull after error: unauthorized: authe
ntication required"
May  9 06:19:19 localhost docker: time="2016-05-09T06:19:19.277093085-04:00" lev
el=error msg="unable to get remote tags: Could not reach any registry endpoint"
May  9 06:19:19 localhost docker: time="2016-05-09T06:19:19.277118955-04:00" lev
el=error msg="Not continuing with pull after error: Could not reach any registry
 endpoint"

[jongiddy]

And in debug mode:

May  9 07:17:12 localhost docker: time="2016-05-09T07:17:12.210154222-04:00" lev
el=debug msg="Calling POST /v1.23/images/create?fromImage=hello-world%3Alatest"
May  9 07:17:12 localhost docker: time="2016-05-09T07:17:12.210313127-04:00" lev
el=debug msg="Trying to pull hello-world from https://registry-1.docker.io v2"
May  9 07:17:13 localhost docker: time="2016-05-09T07:17:13.190858568-04:00" lev
el=debug msg="Increasing token expiration to: 60 seconds"
May  9 07:17:13 localhost docker: time="2016-05-09T07:17:13.765029480-04:00" lev
el=error msg="Attempting next endpoint for pull after error: unauthorized: authe
ntication required"
May  9 07:17:13 localhost docker: time="2016-05-09T07:17:13.765058462-04:00" lev
el=debug msg="Trying to pull hello-world from https://index.docker.io v1"
May  9 07:17:13 localhost docker: time="2016-05-09T07:17:13.765072312-04:00" lev
el=debug msg="hostDir: /etc/docker/certs.d/docker.io"
May  9 07:17:13 localhost docker: time="2016-05-09T07:17:13.765209092-04:00" lev
el=debug msg="[registry] Calling GET https://index.docker.io/v1/repositories/lib
rary/hello-world/images"
May  9 07:17:14 localhost docker: time="2016-05-09T07:17:14.246876225-04:00" lev
el=debug msg="Retrieving the tag list"
May  9 07:17:14 localhost docker: time="2016-05-09T07:17:14.803252070-04:00" lev
el=debug msg="Got status code 401 from https://registry-1.docker.io/v1/repositor
ies/library/hello-world/tags/latest"
May  9 07:17:14 localhost docker: time="2016-05-09T07:17:14.803284123-04:00" lev
el=error msg="unable to get remote tags: Could not reach any registry endpoint"
May  9 07:17:14 localhost docker: time="2016-05-09T07:17:14.803295752-04:00" lev
el=error msg="Not continuing with pull after error: Could not reach any registry
 endpoint"

With curl:

[vagrant@localhost etc]$ curl -S https://registry-1.docker.io/v1/repositories/library/hello-world/tags/latest
{"error": "Requires authorization"}

[jongiddy]

In my case, I identified that the proxy has a rule that removes Authorization headers in requests unless an accompanying cookie is set. In web browsers, this cookie is returned by the response to an initial unauthorized request, and hence gets set for the subsequent authorized request. I believe this attempts to improve security by preventing credentials being sent when they are not necessary (note, I don't make the rules :).

The Docker daemon sends the Authorization in the initial request, without a cookie. This is valid behaviour. It just doesn't interact well with the proxy policies.

This link describes the problem.

This proxy rule works fine for web browsing, but was bound to break something one day. Hence, not really a bug in Docker.

I guess it would be nice if Docker supported configuring the daemon to allow adding headers without the X-Meta- prefix, or could fallback to more browser-like behaviour. But the real fix is to make the corporate proxy less strict.