docker login returns 400 Bad Request #7159

nicholasamorim · 2019-03-15T18:45:59Z

If you are reporting a problem, please make sure the following information are provided:

Expected behavior and actual behavior:

Expected behaviour: for docker login to return sucessfully
Actual behaviour:

Error response from daemon: login attempt to https://harbor.mydomain.com/v2/ failed with status: 400 Bad Request

However, if I enter a wrong user/password, I get what's expected:

Error response from daemon: Get https://sm2harbor.mydomain.com/v2/: unauthorized: authentication required

Steps to reproduce the problem:

I've installed Harbor and I'm running it behind a Nginx that terminates the SSL. Due to conflict in ports/names, I have:

Changed redis to run under redisharbor / port 6380.
I've exposed the port 80 of harbor's nginx as 8798.

As per the troubleshooting section I have commented out the line below in Harbor's Nginx:

proxy_set_header X-Forwarded-Proto $scheme;

I can access the UI, I can login, I can use Harbor's API - all containers are healthy.

But I can't use docker login

Versions:
Please specify the versions of following systems.

harbor version: [1.7.4]
docker engine version: [18.03.1]
docker-compose version: [1.23.2]

Additional context:

My Nginx configuration:

server {
    listen 443 ssl;
    server_name harbor.mydomain.com;

    access_log /var/log/nginx/harbor-access.log;
    error_log /var/log/nginx/harbor-error.log;

    ssl_certificate /etc/nginx/ssl/mycert.crt;
    ssl_certificate_key /etc/nginx/ssl/mykey.key;

    client_max_body_size 20g;
    chunked_transfer_encoding on;

    location / {
        proxy_pass http://127.0.0.1:8798/;
        proxy_set_header Authorization $http_authorization;
        proxy_pass_header  Authorization;
        proxy_set_header  Host              $http_host;
        proxy_set_header  X-Real-IP         $remote_addr;
        proxy_set_header  X-Forwarded-For   $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Proto $scheme;

        proxy_buffering off;
        proxy_request_buffering off;
    }

}

Harbor configuration files attached:

config.zip

The text was updated successfully, but these errors were encountered:

reasonerjt · 2019-03-19T07:35:50Z

@nicholasamorim please reproduce this issue and attach the package containing all the log files.

nicholasamorim · 2019-03-19T13:47:04Z

registry.log

Mar 19 06:44:11 172.18.0.1 registry[16406]: time="2019-03-19T13:44:11.663675894Z" level=warning msg="error authorizing context: authorization token required" go.version=go1.7.3 http.request.host=sm2harbor.pagefreezer.com http.request.id=f9b60292-16fa-4083-97b1-4028f25704cc http.request.method=GET http.request.remoteaddr=192.168.52.54 http.request.uri="/v2/" http.request.useragent="docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \\(darwin\\))" instance.id=4b14ded7-42c0-47cb-b537-b4df71a8d2a0 service=registry version=v2.6.2
Mar 19 06:44:11 172.18.0.1 registry[16406]: 172.18.0.6 - - [19/Mar/2019:13:44:11 +0000] "GET /v2/ HTTP/1.1" 401 87 "" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \\(darwin\\))"
Mar 19 06:44:20 172.18.0.1 registry[16406]: time="2019-03-19T13:44:20.789905333Z" level=warning msg="error authorizing context: authorization token required" go.version=go1.7.3 http.request.host=sm2harbor.pagefreezer.com http.request.id=9e6243ba-9225-4147-804d-5f5d8b64163e http.request.method=GET http.request.remoteaddr=192.168.52.54 http.request.uri="/v2/" http.request.useragent="docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \\(darwin\\))" instance.id=4b14ded7-42c0-47cb-b537-b4df71a8d2a0 service=registry version=v2.6.2
Mar 19 06:44:20 172.18.0.1 registry[16406]: 172.18.0.6 - - [19/Mar/2019:13:44:20 +0000] "GET /v2/ HTTP/1.1" 401 87 "" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \\(darwin\\))"
Mar 19 06:44:22 172.18.0.1 registry[16406]: 127.0.0.1 - - [19/Mar/2019:13:44:22 +0000] "GET / HTTP/1.1" 200 0 "" "curl/7.59.0"

adminserver.log

Mar 19 06:44:43 172.18.0.1 adminserver[16406]: 172.18.0.6 - - [19/Mar/2019:13:44:43 +0000] "GET /api/configs HTTP/1.1" 200 1813

core.log

Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] Config path: /etc/core/app.conf
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] initializing configurations...
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] key path: /etc/core/key
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] initializing client for adminserver http://adminserver:8080 ...
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] initializing the project manager based on local database...
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] configurations initialization completed
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] Registering database: type-PostgreSQL host-postgresql port-5432 databse-registry sslmode-"disable"
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] Register database completed
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] User id: 1 already has its encrypted password.
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] Because SYNC_REGISTRY set false , no need to sync registry
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019-03-19T13:33:26Z [INFO] Init proxy
Mar 19 06:33:26 172.18.0.1 core[16406]: 2019/03/19 13:33:26 #033[1;34m[I] [asm_amd64.s:2337] http server Running on http://:8080#033[0m
Mar 19 06:45:11 172.18.0.1 core[16406]: 2019/03/19 13:45:11 #033[1;44m[D] [server.go:2619] |  192.168.52.54|#033[43m 401 #033[0m|   5.987507ms|   match|#033[44m GET     #033[0m /v2/   r:/v2/*#033[0m
Mar 19 06:45:12 172.18.0.1 core[16406]: 2019/03/19 13:45:12 #033[1;44m[D] [server.go:2619] |  192.168.52.54|#033[42m 200 #033[0m|  49.041364ms|   match|#033[44m GET     #033[0m /service/token   r:/service/token#033[0m

And this is what the Nginx that is acting like a proxy logs:

192.168.52.54 - - [19/Mar/2019:06:48:11 -0700] "GET /v2/ HTTP/1.1" 401 87 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))"
192.168.52.54 - admin [19/Mar/2019:06:48:12 -0700] "GET /service/token?account=admin&client_id=docker&offline_token=true&service=harbor-registry HTTP/1.1" 200 889 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))"
192.168.52.54 - - [19/Mar/2019:06:48:13 -0700] "GET /v2/ HTTP/1.1" 400 226 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))"

If I curl straight to the auth service, it is successfull:

curl -u admin:Harbor12345 "https://myregistry.mycompany.com/service/token?account=admin&client_id=docker&offline_token=true&service=harbor-registry"

This effectively returns:

{
  "token": "xxxxxx",
  "expires_in": 1800,
  "issued_at": "2019-03-19T03:42:27Z"
}

reasonerjt · 2019-03-20T09:12:21Z

@nicholasamorim
The error happens when docker cli tries to access the endpoint of registry, so the success of your curl command is not relevant as it was sent to core

I notice the timestamp in your log messages mismatch.
The 400 error in nginx log was in [19/Mar/2019:06:48:13 -0700]
The error in registry log was in Mar 19 06:44:22

Additionally is the nginx log the one you deployed in front of Harbor? There's another nginx container running when you deploy Harbor OSS, could you provide the logs of that container in the same time frame the error happened?

nicholasamorim · 2019-03-20T09:17:36Z

Ah, they mismatch because I issued several of the docker login. I'd have each log file open separately so I could copy and paste the exact logs of the request.

Sorry, forgot to paste the Harbor's nginx logs

proxy.log

Mar 20 02:17:11 172.18.0.1 proxy[16406]: 172.18.0.1 - "GET /v2/ HTTP/1.0" 401 87 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))" 0.008 0.008 .
Mar 20 02:17:12 172.18.0.1 proxy[16406]: 172.18.0.1 - "GET /service/token?account=admin&client_id=docker&offline_token=true&service=harbor-registry HTTP/1.0" 200 891 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))" 0.050 0.052 .
Mar 20 02:17:32 172.18.0.1 proxy[16406]: 127.0.0.1 - "GET / HTTP/1.1" 200 693 "-" "curl/7.59.0" 0.000 0.004 .

How can I even find out more about what's causing the 400 Bad Request? The logs (for me) don't seem too helpful.

reasonerjt · 2019-03-20T12:51:52Z

Did you reproduce the 400 error with in this timeframe of following messages?

Mar 20 02:17:11 172.18.0.1 proxy[16406]: 172.18.0.1 - "GET /v2/ HTTP/1.0" 401 87 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))" 0.008 0.008 .
Mar 20 02:17:12 172.18.0.1 proxy[16406]: 172.18.0.1 - "GET /service/token?account=admin&client_id=docker&offline_token=true&service=harbor-registry HTTP/1.0" 200 891 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))" 0.050 0.052 .
Mar 20 02:17:32 172.18.0.1 proxy[16406]: 127.0.0.1 - "GET / HTTP/1.1" 200 693 "-" "curl/7.59.0" 0.000 0.004 .

Based on these messages Harbor returned 200 , not 400 and everything looks good.
Could you capture the log of the proxy at your front end that maps to exact same requests and timestamps?

Normally by checking the log there should be some clue, but the information you provided has mismatch timestamps so I'm confused...

nicholasamorim · 2019-03-20T13:08:08Z

Okay, I'll provide logs from the same timestamp. The lines will be the same as the one I've sent already, though. Yeah, that's what bothers me, I can't find the source of the 400.

adminserver.log

Mar 20 06:06:05 172.18.0.1 adminserver[16406]: 172.18.0.6 - - [20/Mar/2019:13:06:05 +0000] "GET /api/configs HTTP/1.1" 200 1813
Mar 20 06:06:05 172.18.0.1 adminserver[16406]: 127.0.0.1 - - [20/Mar/2019:13:06:05 +0000] "GET /api/ping HTTP/1.1" 200 6

core.log

Mar 20 06:06:05 172.18.0.1 core[16406]: 2019/03/20 13:06:05 #033[1;44m[D] [server.go:2619] |  192.168.52.54|#033[43m 401 #033[0m|   6.960262ms|   match|#033[44m GET     #033[0m /v2/   r:/v2/*#033[0m
Mar 20 06:06:05 172.18.0.1 core[16406]: 2019/03/20 13:06:05 #033[1;44m[D] [server.go:2619] |  192.168.52.54|#033[42m 200 #033[0m|  48.831135ms|   match|#033[44m GET     #033[0m /service/token   r:/service/token#033[0m
Mar 20 06:06:18 172.18.0.1 core[16406]: 2019/03/20 13:06:18 #033[1;44m[D] [server.go:2619] |      127.0.0.1|#033[42m 200 #033[0m|   2.129484ms|   match|#033[44m GET     #033[0m /api/ping   r:/api/ping#033[0m

proxy.log

Mar 20 06:06:05 172.18.0.1 proxy[16406]: 172.18.0.1 - "GET /v2/ HTTP/1.0" 401 87 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))" 0.008 0.008 .
Mar 20 06:06:05 172.18.0.1 proxy[16406]: 172.18.0.1 - "GET /service/token?account=admin&client_id=docker&offline_token=true&service=harbor-registry HTTP/1.0" 200 894 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))" 0.050 0.048 .

registry.log

Mar 20 06:06:05 172.18.0.1 registry[16406]: time="2019-03-20T13:06:05.205839545Z" level=warning msg="error authorizing context: authorization token required" go.version=go1.7.3 http.request.host=sm2harbor.pagefreezer.com http.request.id=5de9e610-100c-4b3a-a513-fbec044e2988 http.request.method=GET http.request.remoteaddr=192.168.52.54 http.request.uri="/v2/" http.request.useragent="docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \\(darwin\\))" instance.id=457f3be0-7b50-47dc-9dca-eef5af3efa9a service=registry version=v2.6.2
Mar 20 06:06:05 172.18.0.1 registry[16406]: 172.18.0.6 - - [20/Mar/2019:13:06:05 +0000] "GET /v2/ HTTP/1.1" 401 87 "" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \\(darwin\\))"

my nginx access log:

192.168.52.54 - - [20/Mar/2019:06:06:05 -0700] "GET /v2/ HTTP/1.1" 401 87 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))"
192.168.52.54 - admin [20/Mar/2019:06:06:05 -0700] "GET /service/token?account=admin&client_id=docker&offline_token=true&service=harbor-registry HTTP/1.1" 200 894 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))"
192.168.52.54 - - [20/Mar/2019:06:06:06 -0700] "GET /v2/ HTTP/1.1" 400 226 "-" "docker/18.09.2 go/go1.10.6 git-commit/6247962 kernel/4.9.125-linuxkit os/linux arch/amd64 UpstreamClient(Docker-Client/18.09.2 \x5C(darwin\x5C))"

So the only 400 I can see is this last one, but I don't see any errors on registry.log - so I'm at loss on what to do or even investigate.

nicholasamorim · 2019-03-20T13:22:07Z

I have fixed this. I had applied the recommended settings by the dev-sec project on Nginx.

Turns out this was the culprit: large_client_header_buffers 2 1k;

Increasing the number made it work. docker login does not help by returning an opaque 400 and it was my bad that I didn't do the request to /v2/ manually before - that revealed the Nginx error of having the request headers too large.

Thank you for your time and sorry I didn't find the issue before.

cljk · 2020-09-04T05:27:16Z

Your nginx ssl config helped me to fix mine(!).

I had 400 Bad request upon push. Your header configuration (passing Authentication) solved it.
So thanks

andre161292 · 2024-02-21T14:43:51Z

For me, this issue came from an invalid registry.credentials.htpasswdString when configuring the Helm Chart. See goharbor/harbor-helm#1210 (comment)

ninjadq assigned reasonerjt Mar 18, 2019

nicholasamorim closed this as completed Mar 20, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

docker login returns 400 Bad Request #7159

docker login returns 400 Bad Request #7159

nicholasamorim commented Mar 15, 2019 •

edited

reasonerjt commented Mar 19, 2019

nicholasamorim commented Mar 19, 2019 •

edited

reasonerjt commented Mar 20, 2019 •

edited

nicholasamorim commented Mar 20, 2019 •

edited

reasonerjt commented Mar 20, 2019 •

edited

nicholasamorim commented Mar 20, 2019 •

edited

nicholasamorim commented Mar 20, 2019 •

edited

cljk commented Sep 4, 2020

andre161292 commented Feb 21, 2024

docker login returns 400 Bad Request #7159

docker login returns 400 Bad Request #7159

Comments

nicholasamorim commented Mar 15, 2019 • edited

reasonerjt commented Mar 19, 2019

nicholasamorim commented Mar 19, 2019 • edited

reasonerjt commented Mar 20, 2019 • edited

nicholasamorim commented Mar 20, 2019 • edited

reasonerjt commented Mar 20, 2019 • edited

nicholasamorim commented Mar 20, 2019 • edited

nicholasamorim commented Mar 20, 2019 • edited

cljk commented Sep 4, 2020

andre161292 commented Feb 21, 2024

nicholasamorim commented Mar 15, 2019 •

edited

nicholasamorim commented Mar 19, 2019 •

edited

reasonerjt commented Mar 20, 2019 •

edited

nicholasamorim commented Mar 20, 2019 •

edited

reasonerjt commented Mar 20, 2019 •

edited

nicholasamorim commented Mar 20, 2019 •

edited

nicholasamorim commented Mar 20, 2019 •

edited