Temporary Client not working

[matteosuppo]

If I start up docker-compose for the first time it creates a temporary root client, with which I can connect and create the other clients.

If I stop docker-compose and start it again the temporary client doesn't work anymore. Is it intended?

[aeneasr]

Did you user rethinkdb? Sounds like no database was used

[matteosuppo]

Yes I used rethinkdb, and I can see the data in the database, but the same command that worked before now gives me:

hydra_1      | time="2016-06-17T07:42:33Z" level=info msg="Got error." error="Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)" stack="*errors.Error Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)\n/go/src/github.com/ory-am/hydra/vendor/github.com/ory-am/fosite/access_request_handler.go:71 (0x75d588)\n\t(*Fosite).NewAccessRequest: return accessRequest, errors.New(ErrInvalidClient)\n/go/src/github.com/ory-am/hydra/oauth2/handler.go:34 (0x7761d4)\n\t(*Handler).TokenHandler: accessRequest, err := o.OAuth2.NewAccessRequest(ctx, r, &session)\n/go/src/github.com/ory-am/hydra/oauth2/handler.go:25 (0x777aac)\n\t(*Handler).TokenHandler-fm: r.POST(\"/oauth2/token\", h.TokenHandler)\n/go/src/github.com/ory-am/hydra/vendor/github.com/julienschmidt/httprouter/router.go:344 (0x5cf545)\n\t(*Router).ServeHTTP: handle(w, req, ps)\n/usr/local/go/src/net/http/server.go:1910 (0x55b76d)\n\t(*ServeMux).ServeHTTP: h.ServeHTTP(w, r)\n/usr/local/go/src/net/http/server.go:2081 (0x55c1ee)\n\tserverHandler.ServeHTTP: handler.ServeHTTP(rw, req)\n/usr/local/go/src/net/http/server.go:1472 (0x558c5e)\n\t(*conn).serve: serverHandler{c.server}.ServeHTTP(w, w.req)\n/usr/local/go/src/runtime/asm_amd64.s:1998 (0x45f451)\n\tgoexit: BYTE\t$0x90\t// NOP\n" 

[aeneasr]

Could you list the commands you entered 1-by-1 plus the logs? I cannot reproduce this.

[aeneasr]

Here's what I did:

tty1$> cd $GOPATH/src/github.com/ory-am/hydra
tty1$> DOCKER_IP=$(docker-machine ip default) docker-compose build
tty1$> SYSTEM_SECRET=passwordtutorial DOCKER_IP=$(docker-machine ip default) docker-compose up
tty2$> hydra token client --skip-tls-verify
tty1$>ctrl+c
tty1$> SYSTEM_SECRET=passwordtutorial DOCKER_IP=$(docker-machine ip default) docker-compose up
tty2$> hydra token client --skip-tls-verify

[matteosuppo]

    ctx := context.WithValue(context.Background(), oauth2.HTTPClient, &http.Client{Transport: &http.Transport{
        TLSClientConfig: &tls.Config{InsecureSkipVerify: true},
    }})

    oauthConfig := clientcredentials.Config{
        ClientID:     "a836d46c-9984-46b1-9d3a-5f6909e9c8a2",
        ClientSecret: "hyB-d$XWYs6bk!T9",
        TokenURL:     "https://hydra:4444/oauth2/token",
        Scopes: []string{
            "core",
            "hydra",
        },
    }

    t, err := oauthConfig.Token(ctx)

[matteosuppo]

Now I'll try with the commands

[matteosuppo]

$ SYSTEM_SECRET=passwordtutorial DOCKER_IP=localhost docker-compose up --build
Creating volume "hydra_hydravolume" with local driver
Building hydra
[...]
hydra_1      | time="2016-06-17T08:25:56Z" level=warning msg="Expected system secret to be at least 32 characters long but only got 16 characters." 
hydra_1      | time="2016-06-17T08:25:56Z" level=warning msg="Generating a random system secret..." 
hydra_1      | time="2016-06-17T08:25:56Z" level=warning msg="Generated system secret: )s0ZeNIoAzgPG_gdTHlLivRo4skO&fW." 
hydra_1      | time="2016-06-17T08:25:56Z" level=warning msg="Do not auto-generate system secrets in production." 
hydra_1      | time="2016-06-17T08:25:56Z" level=info msg="DATABASE_URL set, connecting to RethinkDB." 
hydra_1      | time="2016-06-17T08:25:56Z" level=info msg="Connecting with RethinkDB: rethinkdb://database:28015/hydra (database:28015) (hydra)" 
hydra_1      | Pointing cluster at https://localhost:4444
hydra_1      | time="2016-06-17T08:25:56Z" level=info msg="Connected to RethinkDB!" 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Could not find OpenID Connect singing keys. Generating a new keypair..." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Keypair generated." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="WARNING: Automated key creation causes low entropy. Replace the keys as soon as possible." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Key pair for signing consent.endpoint is missing. Creating new one." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Key pair for signing consent.challenge is missing. Creating new one." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="No clients were found. Creating a temporary root client..." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Temporary root client created." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="client_id: fbd1843c-7e5b-4b6b-8360-a210179e1924" 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="client_secret: w2J-ESub2)y,W_-r" 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="The root client must be removed in production. The root's credentials could be accidentally logged." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Do not use flag --dangerous-auto-logon in production." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Key for TLS not found. Creating new one." 
hydra_1      | time="2016-06-17T08:26:19Z" level=warning msg="Temporary key created." 
hydra_1      | time="2016-06-17T08:26:19Z" level=info msg="Starting server on :4444" 

$ hydra connect
Cluster URL [https://localhost:4444]: 
Client ID: fbd1843c-7e5b-4b6b-8360-a210179e1924
Client Secret: w2J-ESub2)y,W_-r
Done.

$ hydra clients create --skip-tls-verify
Warning: Skipping TLS Certificate Verification.
Client ID: 75972b5b-8c94-4c09-bb96-10ec5178c226
Client Secret: Cvszrw>IC_FsQorhrEn$p8VYnb

REBOOT

$ SYSTEM_SECRET=")s0ZeNIoAzgPG_gdTHlLivRo4skO&fW." DOCKER_IP=localhost docker-compose up
hydra_1      | time="2016-06-17T08:30:38Z" level=info msg="DATABASE_URL set, connecting to RethinkDB." 
hydra_1      | time="2016-06-17T08:30:38Z" level=info msg="Connecting with RethinkDB: rethinkdb://database:28015/hydra (database:28015) (hydra)" 
hydra_1      | time="2016-06-17T08:30:38Z" level=info msg="Connected to RethinkDB!" 
hydra_1      | time="2016-06-17T08:30:38Z" level=warning msg="Do not use flag --dangerous-auto-logon in production." 
hydra_1      | time="2016-06-17T08:30:38Z" level=info msg="Starting server on :4444" 

$ hydra connect
Cluster URL [https://localhost:4444]: 
Client ID: fbd1843c-7e5b-4b6b-8360-a210179e1924
Client Secret: w2J-ESub2)y,W_-r
Done.

$ hydra clients create --skip-tls-verify
Warning: Skipping TLS Certificate Verification.
Could not authenticate, because: oauth2: cannot fetch token: 400 Bad Request
Response: {"name":"invalid_client","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","statusCode":400}
Did you forget to log on? Run `hydra connect`.
Did you run Hydra without a valid TLS certificate? Make sure to use the `--skip-tls-verify` flag.
Did you know you can skip `hydra connect` when running `hydra host --dangerous-auto-logon`? DO NOT use this flag in production!

hydra_1      | time="2016-06-17T08:55:00Z" level=info msg="Got error." error="Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)" stack="*errors.Error Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)\n/go/src/github.com/ory-am/hydra/vendor/github.com/ory-am/fosite/access_request_handler.go:71 (0x74fa18)\n\t(*Fosite).NewAccessRequest: return accessRequest, errors.New(ErrInvalidClient)\n/go/src/github.com/ory-am/hydra/oauth2/handler.go:34 (0x7684f4)\n\t(*Handler).TokenHandler: accessRequest, err := o.OAuth2.NewAccessRequest(ctx, r, &session)\n/go/src/github.com/ory-am/hydra/oauth2/handler.go:25 (0x769dcc)\n\t(*Handler).TokenHandler-fm: r.POST(\"/oauth2/token\", h.TokenHandler)\n/go/src/github.com/ory-am/hydra/vendor/github.com/julienschmidt/httprouter/router.go:344 (0x591035)\n\t(*Router).ServeHTTP: handle(w, req, ps)\n/usr/local/go/src/net/http/server.go:1910 (0x524e0d)\n\t(*ServeMux).ServeHTTP: h.ServeHTTP(w, r)\n/usr/local/go/src/net/http/server.go:2081 (0x52588e)\n\tserverHandler.ServeHTTP: handler.ServeHTTP(rw, req)\n/usr/local/go/src/net/http/server.go:1472 (0x5222fe)\n\t(*conn).serve: serverHandler{c.server}.ServeHTTP(w, w.req)\n/usr/local/go/src/runtime/asm_amd64.s:1998 (0x45f451)\n\tgoexit: BYTE\t$0x90\t// NOP\n" 

[aeneasr]

You are using two different SYSTEM_SECRETS:

$ SYSTEM_SECRET=passwordtutorial DOCKER_IP=localhost docker-compose up --build
$ SYSTEM_SECRET=")s0ZeNIoAzgPG_gdTHlLivRo4skO&fW." DOCKER_IP=localhost docker-compose up

[aeneasr]

Can you try running:

docker-compose rm -f
SYSTEM_SECRET=passwordtutorial DOCKER_IP=localhost docker-compose up -d --build
hydra connect (you will need `docker logs` to get the temporary client credentials)
hydra token client --skip-tls-verify
docker-compose kill
SYSTEM_SECRET=passwordtutorial DOCKER_IP=localhost docker-compose up -d
hydra token client --skip-tls-verify

[matteosuppo]

According to these lines:

hydra_1      | time="2016-06-17T08:25:56Z" level=warning msg="Expected system secret to be at least 32 characters long but only got 16 characters." 
hydra_1      | time="2016-06-17T08:25:56Z" level=warning msg="Generating a random system secret..." 
hydra_1      | time="2016-06-17T08:25:56Z" level=warning msg="Generated system secret: )s0ZeNIoAzgPG_gdTHlLivRo4skO&fW." 

I needed to use that new secret. If I use the previous one I get

hydra_1      | time="2016-06-17T09:24:24Z" level=warning msg="Expected system secret to be at least 32 characters long but only got 16 characters." 
hydra_1      | time="2016-06-17T09:24:24Z" level=warning msg="Generating a random system secret..." 
hydra_1      | time="2016-06-17T09:24:24Z" level=warning msg="Generated system secret: KUnnXjHr8,JqOt1kInv$m03,4(Dn!(Cr" 
hydra_1      | time="2016-06-17T09:24:24Z" level=warning msg="Do not auto-generate system secrets in production." 
hydra_1      | time="2016-06-17T09:24:24Z" level=info msg="DATABASE_URL set, connecting to RethinkDB." 
hydra_1      | time="2016-06-17T09:24:24Z" level=info msg="Connecting with RethinkDB: rethinkdb://database:28015/hydra (database:28015) (hydra)" 
hydra_1      | time="2016-06-17T09:24:24Z" level=info msg="Connected to RethinkDB!" 
hydra_1      | time="2016-06-17T09:24:24Z" level=fatal msg="Could not fetch initial state: cipher: message authentication failed"

The problem by the way exists only if I reboot the computer. Which is strange.

[aeneasr]

Hm, is there maybe a docker cleanup job on reboot? Can you connect to the rethinkdb instance and check if the data is still there once you rebooted?

[matteosuppo]

The data is still there, and hydra can connect with the proper secret and do not generate other client_id and client_secret.

[aeneasr]

What does cat ~/.hydra.yml say?

[aeneasr]

what happens if you do

docker-compose rm -f
SYSTEM_SECRET=passwordtutorial DOCKER_IP=localhost docker-compose up -d --build
hydra connect (you will need `docker logs` to get the temporary client credentials)
hydra token client --skip-tls-verify

REBOOT

SYSTEM_SECRET=passwordtutorial DOCKER_IP=localhost docker-compose up -d
hydra connect (the credentials from before)
hydra token client --skip-tls-verify

[aeneasr]

Could it be possible that another instance of hydra is running on that port when booting? This is so akward, no idea why it happens.