Closed Trefex closed 9 years ago
Hey @Trefex
Can you copy your docker registry logs?
i've seen this happen if the X-Registry-Auth
header is missing from the request, are you sure that's getting through?
@dmp42
Here it is, to me it doesn't look very promising
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "GET /v2/ HTTP/1.0" 404 233 "-" "Go 1.1 package http"
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "GET /v1/_ping HTTP/1.0" 200 1517 "-" "Go 1.1 package http"
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "GET /v1/_ping HTTP/1.0" 200 1517 "-" "Go 1.1 package http"
10/Apr/2015:19:45:20 +0000 DEBUG: args = {'namespace': u'trefex', 'repository': u'toto'}
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "PUT /v1/repositories/trefex/toto/ HTTP/1.0" 200 2 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10/Apr/2015:19:45:20 +0000 DEBUG: args = {'image_id': u'ea13149945cb6b1e746bf28032f02e9b5a793523481a0a18645fc77ad53c4ea2'}
10/Apr/2015:19:45:20 +0000 DEBUG: api_error: Image not found
10/Apr/2015:19:45:20 +0000 DEBUG: args = {'image_id': u'4986bf8c15363d1c5d15512d5266f8777bfba4974ac56e3270e7760f6f0a8125'}
10/Apr/2015:19:45:20 +0000 DEBUG: api_error: Image not found
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "GET /v1/images/4986bf8c15363d1c5d15512d5266f8777bfba4974ac56e3270e7760f6f0a8125/json HTTP/1.0" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "GET /v1/images/ea13149945cb6b1e746bf28032f02e9b5a793523481a0a18645fc77ad53c4ea2/json HTTP/1.0" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10/Apr/2015:19:45:20 +0000 DEBUG: args = {'image_id': u'df7546f9f060a2268024c8a230d8639878585defcc1bc6f79d2728a13957871b'}
10/Apr/2015:19:45:20 +0000 DEBUG: api_error: Image not found
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "GET /v1/images/df7546f9f060a2268024c8a230d8639878585defcc1bc6f79d2728a13957871b/json HTTP/1.0" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10/Apr/2015:19:45:20 +0000 DEBUG: args = {'image_id': u'511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158'}
10/Apr/2015:19:45:20 +0000 DEBUG: api_error: Image is being uploaded, retry later
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "GET /v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/json HTTP/1.0" 400 49 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10/Apr/2015:19:45:20 +0000 DEBUG: args = {'image_id': u'511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158'}
172.17.42.1 - - [10/Apr/2015:19:45:20 +0000] "PUT /v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/json HTTP/1.0" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
Anything in nginx logs?
@dmp42
==> /var/log/nginx/access.log <==
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "GET /v2/ HTTP/1.1" 404 233 "-" "Go 1.1 package http"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "GET /v1/_ping HTTP/1.1" 200 1517 "-" "Go 1.1 package http"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "GET /v1/_ping HTTP/1.1" 200 1517 "-" "Go 1.1 package http"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "PUT /v1/repositories/trefex/toto/ HTTP/1.1" 200 2 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "GET /v1/images/df7546f9f060a2268024c8a230d8639878585defcc1bc6f79d2728a13957871b/json HTTP/1.1" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "GET /v1/images/ea13149945cb6b1e746bf28032f02e9b5a793523481a0a18645fc77ad53c4ea2/json HTTP/1.1" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "GET /v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/json HTTP/1.1" 400 49 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "GET /v1/images/4986bf8c15363d1c5d15512d5266f8777bfba4974ac56e3270e7760f6f0a8125/json HTTP/1.1" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10.4.0.51 - - [10/Apr/2015:21:59:40 +0200] "PUT /v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/json HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
10.4.0.51 - - [10/Apr/2015:22:00:10 +0200] "PUT /v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer HTTP/1.1" 400 0 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
No errors of any kind, neither in registry or nginx? If the client connection is closed, that should show somewhere...
@dmp42
Here some more verbose log for the PUT part after switching on debug in nginx
What surprises me is the fact that it says connection closed prematurely by client, but I don't see why this could be.
Also, the first layer is only like 1 MB or something.
2015/04/10 22:04:50 [debug] 5933#0: *16 http request line: "PUT /v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer HTTP/1.1"
2015/04/10 22:04:50 [debug] 5933#0: *16 http uri: "/v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer"
2015/04/10 22:04:50 [debug] 5933#0: *16 http args: ""
2015/04/10 22:04:50 [debug] 5933#0: *16 http exten: ""
2015/04/10 22:04:50 [debug] 5933#0: *16 http process request header line
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "Host: docker-r3lab.uni.lu"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "User-Agent: docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.2.0-61-generic os/linux arch/amd64"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "Transfer-Encoding: chunked"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "Authorization: Basic Og=="
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "Content-Type: application/octet-stream"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "Accept-Encoding: gzip"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "Client-ip: 10.79.2.28"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "X-Forwarded-For: 10.79.2.28"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header: "Via: https/1.1 aratis.uni.lu[FE80000000000000025056FFFE844D03] (ApacheTrafficServer/3.2.4)"
2015/04/10 22:04:50 [debug] 5933#0: *16 http header done
2015/04/10 22:04:50 [debug] 5933#0: *16 event timer del: 17: 1428696350062
2015/04/10 22:04:50 [debug] 5933#0: *16 generic phase: 0
2015/04/10 22:04:50 [debug] 5933#0: *16 rewrite phase: 1
2015/04/10 22:04:50 [debug] 5933#0: *16 test location: "/"
2015/04/10 22:04:50 [debug] 5933#0: *16 test location: "v1/_ping"
2015/04/10 22:04:50 [debug] 5933#0: *16 test location: "v1/search"
2015/04/10 22:04:50 [debug] 5933#0: *16 using configuration "/"
2015/04/10 22:04:50 [debug] 5933#0: *16 http cl:-1 max:0
2015/04/10 22:04:50 [debug] 5933#0: *16 rewrite phase: 3
2015/04/10 22:04:50 [debug] 5933#0: *16 post rewrite phase: 4
2015/04/10 22:04:50 [debug] 5933#0: *16 generic phase: 5
2015/04/10 22:04:50 [debug] 5933#0: *16 generic phase: 6
2015/04/10 22:04:50 [debug] 5933#0: *16 generic phase: 7
2015/04/10 22:04:50 [debug] 5933#0: *16 access phase: 8
2015/04/10 22:04:50 [debug] 5933#0: *16 access phase: 9
2015/04/10 22:04:50 [debug] 5933#0: *16 access phase: 10
2015/04/10 22:04:50 [debug] 5933#0: *16 post access phase: 11
2015/04/10 22:04:50 [debug] 5933#0: *16 posix_memalign: 00000000008A9450:4096 @16
2015/04/10 22:04:50 [debug] 5933#0: *16 http request body chunked filter
2015/04/10 22:04:50 [debug] 5933#0: *16 malloc: 00000000008AA460:8192
2015/04/10 22:04:50 [debug] 5933#0: *16 http read client request body
2015/04/10 22:04:50 [debug] 5933#0: *16 SSL_read: -1
2015/04/10 22:04:50 [debug] 5933#0: *16 SSL_get_error: 2
2015/04/10 22:04:50 [debug] 5933#0: *16 http client request body recv -2
2015/04/10 22:04:50 [debug] 5933#0: *16 http client request body rest 3
2015/04/10 22:04:50 [debug] 5933#0: *16 event timer add: 17: 60000:1428696350070
2015/04/10 22:04:50 [debug] 5933#0: *16 http finalize request: -4, "/v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer?" a:1, c:2
2015/04/10 22:04:50 [debug] 5933#0: *16 http request count:2 blk:0
2015/04/10 22:05:20 [debug] 5933#0: *16 post event 000000000086C240
2015/04/10 22:05:20 [debug] 5933#0: *16 delete posted event 000000000086C240
2015/04/10 22:05:20 [debug] 5933#0: *16 http run request: "/v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer?"
2015/04/10 22:05:20 [debug] 5933#0: *16 http read client request body
2015/04/10 22:05:20 [debug] 5933#0: *16 SSL_read: 0
2015/04/10 22:05:20 [debug] 5933#0: *16 SSL_get_error: 5
2015/04/10 22:05:20 [debug] 5933#0: *16 peer shutdown SSL cleanly
2015/04/10 22:05:20 [debug] 5933#0: *16 http client request body recv 0
2015/04/10 22:05:20 [info] 5933#0: *16 client prematurely closed connection, client: 10.4.0.51, server: docker-r3lab-server.uni.lu, request: "PUT /v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer HTTP/1.1", host: "docker-r3lab.uni.lu"
2015/04/10 22:05:20 [debug] 5933#0: *16 http finalize request: 400, "/v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer?" a:1, c:1
2015/04/10 22:05:20 [debug] 5933#0: *16 http terminate request count:1
2015/04/10 22:05:20 [debug] 5933#0: *16 http terminate cleanup count:1 blk:0
2015/04/10 22:05:20 [debug] 5933#0: *16 http posted request: "/v1/images/511136ea3c5a64f264b78b5433614aec563103b4d4702f3ba7d4d2698e22c158/layer?"
2015/04/10 22:05:20 [debug] 5933#0: *16 http terminate handler count:1
2015/04/10 22:05:20 [debug] 5933#0: *16 http request count:1 blk:0
2015/04/10 22:05:20 [debug] 5933#0: *16 http close request
2015/04/10 22:05:20 [debug] 5933#0: *16 http log handler
2015/04/10 22:05:20 [debug] 5933#0: *16 free: 00000000008AA460
2015/04/10 22:05:20 [debug] 5933#0: *16 free: 00000000008A13B0, unused: 4
2015/04/10 22:05:20 [debug] 5933#0: *16 free: 00000000008A9450, unused: 2293
2015/04/10 22:05:20 [debug] 5933#0: *16 close http connection: 17
2015/04/10 22:05:20 [debug] 5933#0: *16 SSL_shutdown: 1
2015/04/10 22:05:20 [debug] 5933#0: *16 event timer del: 17: 1428696350070
2015/04/10 22:05:20 [debug] 5933#0: *16 reusable connection: 0
2015/04/10 22:05:20 [debug] 5933#0: *16 free: 0000000000895740
2015/04/10 22:05:20 [debug] 5933#0: *16 free: 0000000000893ED0, unused: 0
2015/04/10 22:05:20 [debug] 5933#0: *16 free: 0000000000893FE0, unused: 72
2015/04/10 22:05:54 [debug] 5933#0: *1 event timer del: 11: 1428696354803
2015/04/10 22:05:54 [debug] 5933#0: *1 http keepalive handler
2015/04/10 22:05:54 [debug] 5933#0: *1 close http connection: 11
2015/04/10 22:05:54 [debug] 5933#0: *1 SSL_shutdown: 1
2015/04/10 22:05:54 [debug] 5933#0: *1 reusable connection: 0
2015/04/10 22:05:54 [debug] 5933#0: *1 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *1 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *1 free: 0000000000839E40, unused: 0
2015/04/10 22:05:54 [debug] 5933#0: *1 free: 000000000086A060, unused: 56
2015/04/10 22:05:54 [debug] 5933#0: *1 free: 0000000000842400, unused: 144
2015/04/10 22:05:54 [debug] 5933#0: *3 event timer del: 12: 1428696354958
2015/04/10 22:05:54 [debug] 5933#0: *3 http keepalive handler
2015/04/10 22:05:54 [debug] 5933#0: *3 close http connection: 12
2015/04/10 22:05:54 [debug] 5933#0: *3 SSL_shutdown: 1
2015/04/10 22:05:54 [debug] 5933#0: *3 reusable connection: 0
2015/04/10 22:05:54 [debug] 5933#0: *3 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *3 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *3 free: 00000000008431D0, unused: 0
2015/04/10 22:05:54 [debug] 5933#0: *3 free: 00000000008A2B00, unused: 56
2015/04/10 22:05:54 [debug] 5933#0: *3 free: 00000000008A2E70, unused: 144
2015/04/10 22:05:54 [debug] 5933#0: *5 event timer del: 13: 1428696354963
2015/04/10 22:05:54 [debug] 5933#0: *5 http keepalive handler
2015/04/10 22:05:54 [debug] 5933#0: *5 close http connection: 13
2015/04/10 22:05:54 [debug] 5933#0: *5 SSL_shutdown: 1
2015/04/10 22:05:54 [debug] 5933#0: *5 reusable connection: 0
2015/04/10 22:05:54 [debug] 5933#0: *5 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *5 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *5 free: 0000000000848EC0, unused: 0
2015/04/10 22:05:54 [debug] 5933#0: *5 free: 0000000000848FD0, unused: 56
2015/04/10 22:05:54 [debug] 5933#0: *5 free: 00000000008A23C0, unused: 144
2015/04/10 22:05:54 [debug] 5933#0: *7 event timer del: 14: 1428696354966
2015/04/10 22:05:54 [debug] 5933#0: *7 http keepalive handler
2015/04/10 22:05:54 [debug] 5933#0: *7 close http connection: 14
2015/04/10 22:05:54 [debug] 5933#0: *7 SSL_shutdown: 1
2015/04/10 22:05:54 [debug] 5933#0: *7 reusable connection: 0
2015/04/10 22:05:54 [debug] 5933#0: *7 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *7 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *7 free: 00000000008A6FA0, unused: 0
2015/04/10 22:05:54 [debug] 5933#0: *7 free: 00000000008A70B0, unused: 32
2015/04/10 22:05:54 [debug] 5933#0: *7 free: 00000000008A78F0, unused: 144
2015/04/10 22:05:54 [debug] 5933#0: *12 event timer del: 15: 1428696354974
2015/04/10 22:05:54 [debug] 5933#0: *12 http keepalive handler
2015/04/10 22:05:54 [debug] 5933#0: *12 close http connection: 15
2015/04/10 22:05:54 [debug] 5933#0: *12 SSL_shutdown: 1
2015/04/10 22:05:54 [debug] 5933#0: *12 reusable connection: 0
2015/04/10 22:05:54 [debug] 5933#0: *12 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *12 free: 0000000000000000
2015/04/10 22:05:54 [debug] 5933#0: *12 free: 00000000008A74E0, unused: 0
2015/04/10 22:05:54 [debug] 5933#0: *12 free: 00000000008A75F0, unused: 56
2015/04/10 22:05:54 [debug] 5933#0: *12 free: 00000000008A7700, unused: 144
2015/04/10 22:05:55 [debug] 5933#0: *14 event timer del: 16: 1428696355041
2015/04/10 22:05:55 [debug] 5933#0: *14 http keepalive handler
2015/04/10 22:05:55 [debug] 5933#0: *14 close http connection: 16
2015/04/10 22:05:55 [debug] 5933#0: *14 SSL_shutdown: 1
2015/04/10 22:05:55 [debug] 5933#0: *14 reusable connection: 0
2015/04/10 22:05:55 [debug] 5933#0: *14 free: 0000000000000000
2015/04/10 22:05:55 [debug] 5933#0: *14 free: 0000000000000000
2015/04/10 22:05:55 [debug] 5933#0: *14 free: 00000000008933E0, unused: 0
2015/04/10 22:05:55 [debug] 5933#0: *14 free: 0000000000893BD0, unused: 32
2015/04/10 22:05:55 [debug] 5933#0: *14 free: 0000000000897A10, unused: 144
Hey @Trefex
From our irc chitchat, you mentioned that your proxy was responsible for the messup?
So, is this still an issue or can we close this?
The error seems to have come from our proxy indeed.
@Trefex I'm experiencing a similar issue, how did you determine that it was your proxy at fault?
I'd also be interested in the details of the resolution here
@dmg3 I won't be able to be super helpful, but I did debug this by not using the proxy, which means changing the DNS, opening ports temporarily internally and so on.
Without proxy, everything was fine, with the proxy, all hell broke loose.
@luxifr I'm not sure what was done on the proxy side, because I'm not in control of that component :(
Dear all,
When pushing to my registry, I get the following error:
I am behind an Apache Traffic Server, which maps docker-r3lab to docker-r3lab-server.
Here is my nginx config
Does anybody have any ideas? Where to start? How to debug?
root@docker-r3lab:~# docker -v Docker version 1.5.0, build a8a31ef
root@boot2docker:~# docker -v Docker version 1.5.0, build a8a31ef
boot2docker docker daemon log excerpt
Launch settings of docker registry
Docker registry config