"nil pointer" error when notary-server is configured with an "auth section"

[reasonerjt]

Hi,
I pulled latest code and could successfully setup notary using the default docker compose template.

However when I added "auth section" to server-config.json, like this:

"auth": {
        "type": "token",
        "options": {
            "realm": "https://10.117.4.142/service/token",
            "service": "notary-server",
            "issuer": "registry-token-issuer",
            "rootcertbundle": "/go/src/github.com/docker/notary/fixtures/token_root.crt"
        }
    }

In which case the url "https://10.117.4.142/service/token" points to a jwt token service I wrote.
I tried to execute notary list and got error:

# notary -D -s https://10.117.4.142:4443 list 10.117.4.142/notary-test-4/hello-world:1.0
DEBU[0000] Configuration file not found, using defaults
DEBU[0000] Using the following trust directory: /root/.notary
ERRO[0001] could not reach https://10.117.4.142:4443: Get https://10.117.4.142:4443/v2/: EOF
INFO[0001] continuing in offline mode
DEBU[0001] No yubikey found, using alternative key storage: no library found

* fatal: client is offline

Checked the output of notary server container via docker-compose, the error looks like this:

server_1  | {"level":"info","msg":"Version: 0.5.0, Git commit: 905fffb","time":"2017-02-14T08:33:30Z"}
server_1  | {"level":"debug","msg":"Trusting 1 certs","time":"2017-02-14T08:33:30Z"}
server_1  | {"level":"info","msg":"Using remote signing service","time":"2017-02-14T08:33:30Z"}
server_1  | {"level":"info","msg":"Using mysql backend","time":"2017-02-14T08:33:30Z"}
server_1  | {"level":"info","msg":"Starting Server","time":"2017-02-14T08:33:30Z"}
server_1  | {"level":"info","msg":"Enabling TLS","time":"2017-02-14T08:33:30Z"}
server_1  | {"level":"info","msg":"Starting on :4443","time":"2017-02-14T08:33:30Z"}
server_1  | 2017/02/14 08:33:37 http: panic serving 10.166.17.43:57117: runtime error: invalid memory address or nil pointer dereference
server_1  | goroutine 92 [running]:
server_1  | net/http.(*conn).serve.func1(0xc4201a1400)
server_1  |     /usr/local/go/src/net/http/server.go:1491 +0x12a
server_1  | panic(0xa4c600, 0xc420012060)
server_1  |     /usr/local/go/src/runtime/panic.go:458 +0x243
server_1  | github.com/docker/notary/vendor/github.com/docker/distribution/context.getLogrusLogger(0x0, 0x0, 0xc4201a9998, 0x3, 0x3, 0x0)
server_1  |     /go/src/github.com/docker/notary/vendor/github.com/docker/distribution/context/logger.go:86 +0x5d
server_1  | github.com/docker/notary/vendor/github.com/docker/distribution/context.GetResponseLogger(0x0, 0x0, 0x8, 0xc42005e000)
server_1  |     /go/src/github.com/docker/notary/vendor/github.com/docker/distribution/context/http.go:176 +0x187
server_1  | github.com/docker/notary/utils.(*rootHandler).ServeHTTP.func1(0xc4201a9b30)
server_1  |     /go/src/github.com/docker/notary/utils/http.go:61 +0x3b
server_1  | github.com/docker/notary/utils.(*rootHandler).ServeHTTP(0xc420225180, 0xe16720, 0xc420143930, 0xc4200df4a0)
server_1  |     /go/src/github.com/docker/notary/utils/http.go:69 +0x7c4
server_1  | github.com/docker/notary/vendor/github.com/gorilla/mux.(*Router).ServeHTTP(0xc4202250e0, 0xe16720, 0xc420143930, 0xc4200df4a0)
server_1  |     /go/src/github.com/docker/notary/vendor/github.com/gorilla/mux/mux.go:98 +0x255
server_1  | net/http.serverHandler.ServeHTTP(0xc4201af000, 0xe16720, 0xc420143930, 0xc4200df4a0)
server_1  |     /usr/local/go/src/net/http/server.go:2202 +0x7d
server_1  | net/http.(*conn).serve(0xc4201a1400, 0xe17560, 0xc42025d540)
server_1  |     /usr/local/go/src/net/http/server.go:1579 +0x4b7
server_1  | created by net/http.(*Server).Serve
server_1  |     /usr/local/go/src/net/http/server.go:2293 +0x44d

I don't get much information from this output, seems the error is thrown when initializing the logger.
Checked the log of my token service, the endpoint didn't receive any request.

Any idea for further debug???
I appreciate your help.

[HuKeping]

I'd like to take a took into this when I get back to my office.

ADDED:
Appreciate any rapid fixing.

[reasonerjt]

This fixed my issue:

# git diff utils/http.go
diff --git a/utils/http.go b/utils/http.go
index ea47a3c..c6c4b41 100644
--- a/utils/http.go
+++ b/utils/http.go
@@ -58,7 +58,9 @@ func (root *rootHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
        ctx = context.WithValue(ctx, notary.CtxKeyCryptoSvc, root.trust)

        defer func() {
-               ctxu.GetResponseLogger(ctx).Info("response completed")
+               if ctx != nil {
+                       ctxu.GetResponseLogger(ctx).Info("response completed")
+               }
        }()

Root cause is that in doAuth() it returns a nil Context when it requires challenge.

[reasonerjt]

I can submit a PR if you think it is OK.

[HuKeping]

Thanks for the fixing @reasonerjt !

[ecordell]

There was some discussion about whether this should be:

 defer func(ctx Context) {
      ctxu.GetResponseLogger(ctx).Info("response completed")
 }(ctx)

but I don't remember where we landed?

[endophage]

@ecordell this is the existing discussion: https://github.com/docker/notary/pull/1081/files#diff-aa3046143cd12bfccc02a859a56d1036R64