Cleanup error message for auth challenge

[HuKeping]

There's some MISSING in the output error message when we failed the challenge for authentication

* fatal: Get https://ihub.com:443/index/notary?account=hukeping&scope=repository%!A(MISSING)huawei.com%!A(MISSING)push%!C(MISSING)pull&service=notary: net/http: request canceled (Client.Timeout exceeded while awaiting headers)

Seems it was caused by the error message we get from roundtripper contains some URL code like %3A, and when the whole string be used as an format output, the warning we mentioned above will show up.

[riyazdf]

@HuKeping: which notary version (client + server) are you seeing this on? I ask because we had a similar issue #969 and the fix was to revendor docker/distribution: #972

This should be included in notary v0.4.1+

[HuKeping]

It should the latest version I suppose, but I'll check that the next Monday

[HuKeping]

Hi @riyazdf it was based on commit 303e1fe upstream.

[HuKeping]

The version info:

$ notary-server -debug
{"level":"info","msg":"Version: 0.5-dev, Git commit: 303e1fe","time":"2016-10-17T17:27:00+08:00"}
{"level":"info","msg":"Debug server listening on localhost:8080","time":"2016-10-17T17:27:00+08:00"}
{"level":"fatal","msg":"Could not read config at :, viper error: Unsupported Config Type \"\"","time":"2016-10-17T17:27:00+08:00"}
$ 
$ notary-signer -debug
{"level":"info","msg":"Version: 0.5-dev, Git commit: 303e1fe","time":"2016-10-17T17:27:10+08:00"}
{"level":"info","msg":"Debug server listening on localhost:8080","time":"2016-10-17T17:27:10+08:00"}
{"level":"fatal","msg":"Could not read config at :, viper error: Unsupported Config Type \"\"","time":"2016-10-17T17:27:10+08:00"}
$ 
$ notary version
notary
 Version:    0.5-dev
 Git commit: 303e1fe

The config info:

$ cat fixtures/signer-config-local.json
{
    "server": {
        "grpc_addr": ":7899",
        "tls_cert_file": "./notary-signer.crt",
        "tls_key_file": "./notary-signer.key",
        "client_ca_file": "./notary-server.crt"
    },
    "logging": {
        "level": "debug"
    },
    "storage": {
        "backend": "memory"
    }
}

$ cat fixtures/server-config-local.json 
{
    "server": {
        "http_addr": ":4443",
        "tls_key_file": "./notary-server.key",
        "tls_cert_file": "./notary-server.crt"
    },
    "trust_service": {
        "type": "remote",
        "hostname": "notarysigner",
        "port": "7899",
        "tls_ca_file": "./root-ca.crt",
        "key_algorithm": "ecdsa",
        "tls_client_cert": "./notary-server.crt",
        "tls_client_key": "./notary-server.key"
    },
    "auth": {
        "type": "token",
        "options": {
            "realm": "https://ihub.com:443/index/notary",
            "service": "notary",
            "issuer": "Super auth server",
            "rootcertbundle": "./hw_auth.pem"
        }
    },
    "logging": {
        "level": "debug"
    },
    "storage": {
        "backend": "memory"
    }
}

The file hierarchy:

$ tree ~/.notary/
/home/hukeping/.notary/
├── config.json
└── root-ca.crt

0 directories, 2 files

N.B. I've added the auth part for the config of notary-server

[HuKeping]

Steps for reproducing the problem:

# 1. start notary-signer with the local configuration file
$ notary-signer -config fixtures/signer-config-local.json 
{"level":"info","msg":"Version: 0.5-dev, Git commit: 303e1fe","time":"2016-10-17T17:34:38+08:00"}
{"level":"debug","msg":"Trusting 2 certs","time":"2016-10-17T17:34:38+08:00"}

# 2. start notary-server with the local configuration file
$ notary-server -config fixtures/server-config-local.json 
{"level":"info","msg":"Version: 0.5-dev, Git commit: 303e1fe","time":"2016-10-17T17:34:43+08:00"}
{"level":"debug","msg":"Trusting 1 certs","time":"2016-10-17T17:34:43+08:00"}
{"level":"info","msg":"Using remote signing service","time":"2016-10-17T17:34:43+08:00"}
{"level":"info","msg":"Using memory backend","time":"2016-10-17T17:34:43+08:00"}
{"level":"info","msg":"Starting Server","time":"2016-10-17T17:34:43+08:00"}
{"level":"info","msg":"Enabling TLS","time":"2016-10-17T17:34:43+08:00"}
{"level":"info","msg":"Starting on :4443","time":"2016-10-17T17:34:43+08:00"}

# 3 list a TUF repo (it has not been inited yet)
$ notary list huawei.com

* fatal: Get https://ihub.com:443/index/notary?scope=repository%!A(MISSING)huawei.com%!A(MISSING)pull&service=notary: x509: certificate signed by unknown authority

And with #1008 , the error message turn out as:

$ notary list huawei.com

* fatal: Get https://ihub.com:443/index/notary?scope=repository:huawei.com:pull&service=notary: x509: certificate signed by unknown authority

[HuKeping]

I think it was because we put the URL Encoded error message into a format of a printf. see
https://github.com/docker/notary/blob/master/cmd/notary/main.go#L207

and

https://play.golang.org/p/pUOgmcRmr-

[HuKeping]

We can fix this by refactoring the fatalf function, but it does not help to the error message from network, it's still not human readable. For example

Error is:Get https://ihub.com:443/index/notary?scope=repository%3Ahuawei.com%3Apull&service=notary: x509: certificate signed by unknown authority

[riyazdf]

@HuKeping: could you please try running the list command with the -D debug flag and posting that output?
I'm wondering if this should also be a fix in docker/distribution that we vendor.

[cyli]

@riyazdf @HuKeping The error seems to be coming from here (I replicated this error by pointing auth at google.com): https://github.com/docker/notary/blob/master/vendor/github.com/docker/distribution/registry/client/auth/session.go#L381. It seems like it's a golang url.Error error when we make a GET request. The golang HTTP library escapes the characters in the scope when they're being added as query params here, and the URL in the error reflects that. We'd likely get such an error in the notary codebase too if we ever made an HTTP request using query parameters with special characters (which currently we don't).

(The debug output is:)

DEBU[0000] Using the following trust directory: /Users/cyli/.notary 
DEBU[0000] Trusting 1 certs                             
DEBU[0000] No yubikey found, using alternative key storage: loaded library /usr/local/lib/libykcs11.dylib, but no HSM slots found 

* fatal: Get https://google.com/index/notary?scope=repository%!A(MISSING)huawei.com%!A(MISSING)pull&service=notary: x509: certificate signed by unknown authority

The question is whether we want to unescape the informational URL parameter in the error that comes back from the golang http library. If we did, then rather than blanket unescape all network errors, we might want to specifically specifically check for url.Error errors and unescape the URL.

Although at some point, we should definitely fix the fatalf function to only use the first arg as a format string if it's actually a string. :)

[HuKeping]

I am +1 for fixing the fatalf function at first, I'll file a separated PR to do so.

I supposed we may leave the url error for later discussing(I mean whether to unescape the whole message or sth)?

[cyli]

I supposed we may leave the url error for later discussing(I mean whether to unescape the whole message or sth)?

Since this is related to #1008 though I'll just leave a non-blocking comment there. Apologies, not sure what you mean - I think maybe "or sth" was meant to be "or not"? I'll just assume so for now, in which case - yep, I don't feel that strongly about it, so I'm happy to discuss it later/elsewhere :)