search

gocd / gocd

GoCD - Continuous Delivery server main repository
https://www.gocd.org
Apache License 2.0
7.05k stars 973 forks source link

Personal access tokens taking too long to generate #6228

Closed omarmarquez closed 5 years ago

omarmarquez commented 5 years ago

When clicking on the [Generate] button nothing happens, the page stays the same, the javascript console shows no activity associated with the click action...

arvindsv commented 5 years ago

@omarmarquez Can you mention which authorization plugin you're using? Also, any steps to reproduce this or relevant screenshots might help [I understand you're saying nothing is happening when you click it, and so screenshots of that might not be useful].

I tried it with the built-in file-based password plugin and it worked fine. As mentioned in the release notes for 19.2, Google OAuth plugin does not support access tokens.

omarmarquez commented 5 years ago

I'm using both the cd.go.authentication.passwordfile and cd.go.authentication.ldap

Users are able to authenticate via either of the methods, and encounter the same issue.

The list of active plugins is below: Screenshot from 2019-04-23 11-52-02

omarmarquez commented 5 years ago

Something, that might be related is that in the Chrome browser developer console there is a stream of errors like this: system_notifications.ts:75 Uncaught (in promise) TypeError: t.map is not a function at new t (system_notifications.ts:75) at Function.t.fromJSON (system_notifications.ts:86) at system_notifications.ts:81 at new Promise () at Function.t.all (system_notifications.ts:79) at Object.repeaterFn (index.tsx:27) at t.fire (ajax_poller.ts:95)

bdpiprava commented 5 years ago

There was an small improvement on ui feedback is done as part of https://github.com/gocd/gocd/pull/6020. It will be available in 19.3.0 release.

omarmarquez commented 5 years ago

Also, occasionally if I log in a different window and go to the [ Admin / Access Token Management ] area I can see that some (not all) tokens are created, but because the UI never returned during Token creation the value (key) for the token is unknown.

Q: there is command line way of generating a token that we could use until this UI issue is more clear?

arvindsv commented 5 years ago

@omarmarquez Yes. Take a look at: https://api.gocd.org/current/#create-token-for-current-user

omarmarquez commented 5 years ago

In the screen shots below please notice how the network traffic response tab is empty for the Access Token Request:

Screenshot from 2019-04-23 14-00-02

Response: Screenshot from 2019-04-23 14-00-46

Also, is interesting that when I try to access the api using username:password I get an empty response: ` [ ~]$ curl -u 'admin:xxxx' -k 'https://gocd-dev:8154/go/api' -H 'Accept: application/vnd.go.cd.v1+json'

[ ~]$ curl -u 'admin:xxxx' -k 'https://gocd-dev:8154/go/api/pipelines' -H 'Accept: application/vnd.go.cd.v1+json' { "message": "The resource you requested was not found!" }

[ ~]$

`

ankitsri11 commented 5 years ago

@omarmarquez I tried below and couldn't able to replicate the behavior.

  1. Started the GoCD (v19.2.0) server with below.

docker run -v /tmp/godata:/godata -v /tmp/gohome:/home/go -p8153:8153 -p8154:8154 gocd/gocd-server:v19.2.0

  1. Setup file-based authentication.
<?xml version="1.0" encoding="utf-8"?>
<cruise xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="cruise-config.xsd" schemaVersion="115">
  <server artifactsdir="artifacts" agentAutoRegisterKey="68923759-6bb5-4a1c-8424-21a2119c9334" webhookSecret="f0b4c813-66db-4088-b115-bc1f44d38d67" commandRepositoryLocation="default" serverId="03a7ce84-59b0-4dca-971b-58daf145f930" tokenGenerationKey="8098dcef-3c9f-4630-9166-f2e44769b27f">
    <security>
      <authConfigs>
        <authConfig id="blah" pluginId="cd.go.authentication.passwordfile">
          <property>
            <key>PasswordFilePath</key>
            <value>/home/go/passwd</value>
          </property>
        </authConfig>
      </authConfigs>
    </security>
    <backup emailOnSuccess="true" emailOnFailure="true" />
  </server>
  <pipelines group="defaultGroup">
    <pipeline name="Sample">
      <materials>
        <git url="https://github.com/ankitsri11/gocd-sample-config-repo" />
      </materials>
      <stage name="defaultStage">
        <jobs>
          <job name="defaultJob">
            <tasks>
              <exec command="ls" />
            </tasks>
          </job>
        </jobs>
      </stage>
    </pipeline>
  </pipelines>
</cruise>
  1. Tried to generate a token (user_profile-->Personal access tokens) and was able to create without any issue.

I tried on below mentioned browsers: Chrome (Version 74.0.3729.108) Firefox (66.0.3)

Can let me know the browser version you are using? Also, can you try on a different browser and see if you are able to replicate.

omarmarquez commented 5 years ago
  1. I start the container with:

+ docker run -d --rm --name gocd -p8153:8153 -p8154:8154 -v /home/local/TMG/omar.marquez/gocd/mnt:/mnt -v /home/local/TMG/omar.marquez/gocd/godata:/godata -v /home/local/TMG/omar.marquez/gocd/user:/home/go gocd/gocd-server:v19.2.0

  1. Setup file based auth:
 <?xml version="1.0" encoding="utf-8"?>
 <cruise xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" 
 xsi:noNamespaceSchemaLocation="cruise-config.xsd" schemaVersion="115">
  <server artifactsdir="artifacts" siteUrl="http://gocd-dev:8153" secureSiteUrl="https://gocd-dev:8154" purgeStart="20.0" purgeUpto="30.0" agentAutoRegisterKey="343ae2de-12fe-4ade-9169-7d8733e74267" webhookSecret="ada53462-4b02-450c-ae30-834b44909e87" commandRepositoryLocation="default" serverId="3493149e-5b9e-4f93-81d7-e17bd7784702" tokenGenerationKey="0f8304b4-1e97-4c94-aa84-76e56f7b571f">
    <security>
      <authConfigs>
        <authConfig id="password" pluginId="cd.go.authentication.passwordfile">
          <property>
            <key>PasswordFilePath</key>
            <value>/godata/config/password.properties</value>
          </property>
        </authConfig>
        <authConfig id="TMGAD" pluginId="cd.go.authentication.ldap">
          <property>
            <key>Url</key>
            <value>ldap://chd-sv-dc01</value>
          </property>
          <property>
            <key>SearchBases</key>
            <value>ou=offices,dc=company,dc=com</value>
          </property>
          <property>
            <key>ManagerDN</key>
            <value>LDAP@company</value>
          </property>
          <property>
            <key>Password</key>
            <encryptedValue>AES:C+yoSz7x1mxvg4AvzZIi8k6g==:g443Ixd6Er6xOR28/4bmarA==</encryptedValue>
          </property>
          <property>
            <key>UserSearchFilter</key>
            <value>(sAMAccountName={0})</value>
          </property>
          <property>
            <key>UserLoginFilter</key>
            <value>(sAMAccountName={0})</value>
          </property>
          <property>
            <key>DisplayNameAttribute</key>
            <value>cn</value>
          </property>
          <property>
            <key>EmailAttribute</key>
            <value>mail</value>
          </property>
        </authConfig> <?xml version="1.0" encoding="utf-8"?>
 <cruise xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" 
 xsi:noNamespaceSchemaLocation="cruise-config.xsd" schemaVersion="115">
  <server artifactsdir="artifacts" siteUrl="http://gocd-dev:8153" secureSiteUrl="https://gocd-dev:8154" purgeStart="20.0" purgeUpto="30.0" agentAutoRegisterKey="343ae2de-12fe-4ade-9169-7d8733e74267" webhookSecret="ada53462-4b02-450c-ae30-834b44909e87" commandRepositoryLocation="default" serverId="3493149e-5b9e-4f93-81d7-e17bd7784702" tokenGenerationKey="0f8304b4-1e97-4c94-aa84-76e56f7b571f">
    <security>
      <authConfigs>
        <authConfig id="password" pluginId="cd.go.authentication.passwordfile">
          <property>
            <key>PasswordFilePath</key>
            <value>/godata/config/password.properties</value>
          </property>
        </authConfig>
        <authConfig id="TMGAD" pluginId="cd.go.authentication.ldap">
          <property>
            <key>Url</key>
            <value>ldap://chd-sv-dc01</value>
          </property>
          <property>
            <key>SearchBases</key>
            <value>ou=offices,dc=company,dc=com</value>
          </property>
          <property>
            <key>ManagerDN</key>
            <value>LDAP@company</value>
          </property>
          <property>
            <key>Password</key>
            <encryptedValue>AES:C+yoSz7x1mxvg4AvzZIi8k6g==:g443Ixd6Er6xOR28/4bmarA==</encryptedValue>
          </property>
          <property>
            <key>UserSearchFilter</key>
            <value>(sAMAccountName={0})</value>
          </property>
          <property>
            <key>UserLoginFilter</key>
            <value>(sAMAccountName={0})</value>
          </property>
          <property>
            <key>DisplayNameAttribute</key>
            <value>cn</value>
          </property>
          <property>
            <key>EmailAttribute</key>
            <value>mail</value>
          </property>
        </authConfig>
      </authConfigs>
      <admins>
        <user>admin</user>
        <user>omar.marquez</user>
      </admins>
    </security>
    <mailhost hostname="smtp.company" port="25" tls="false" from="admin@xxxx" admin="omar.marquez@xxxx" />
    <backup emailOnSuccess="true" emailOnFailure="true" />
  </server>

      </authConfigs>
      <admins>
        <user>admin</user>
        <user>omar.marquez</user>
      </admins>
    </security>
    <mailhost hostname="smtp.company" port="25" tls="false" from="admin@xxxx" admin="omar.marquez@xxxx" />
    <backup emailOnSuccess="true" emailOnFailure="true" />
  </server>
  1. Logout and log back in

  1. Got to Personal access tokens and Try to create a token. Enter a Description and click on Generate.

    • The from never changes or shows any response
    • looking at the Javascript console Network I see the request going out but the response remains empty

  2. When I try to reproduce from the command line I get an "incorrect url error message", see below first with an incorrect password, then wit the correct one: Screenshot from 2019-04-24 09-09-43

In general the Api seems not be available/served by the application, here is trying to get the api base page a 404 is returned: Screenshot from 2019-04-24 09-07-58

Also in the UI page the footer shows an Api link that points to https://api.gocd.org/19.2.0/ instead of pointing to my localserver api ... which as in the curl test above seems to be missing:

Screenshot from 2019-04-24 09-14-32

So at this point I blieve the root issue is the Api not being served by this image

ketan commented 5 years ago

looking at the Javascript console Network I see the request going out but the response remains empty

Do you see an HTTP status code? From the image that you provided here, I can see it saying "provisional headers" this indicates that the request is pending (or has not reached the server), do you have any browser plugins (try another browser, or in incognito mode, with no extensions)

When I try to reproduce from the command line I get an "incorrect url error message", see below first with an incorrect password, then wit the correct one:

You're expected to use the correct accept header described here and the right payload (in json format). None of the newer APIs support form based submission -d description=something

In general the Api seems not be available/served by the application, here is trying to get the API base page a 404 is returned:

If you're referring to the API documentation, we do not (deliberately) package it with the application.

I ran this and it seems to work. I was able to also create a token from the web interface.

git clone https://gist.github.com/a6796b470713d3415c0fce2a2fc1cd8a.git godata/config && docker run -d -v $(pwd)/godata:/godata -p8153:8153 -p8154:8154 gocd/gocd-server:v19.2.0

Once the server is available:

$ curl http://localhost:8153/go/api/current_user/access_tokens \
      -u admin:badger \
       -H 'Accept: application/vnd.go.cd.v1+json'
       -X POST \
      -H 'Content-Type: application/json' \
      -d '{
        "description": "my first token"
      }'
{
  "_links" : {
    "self" : {
      "href" : "http://localhost:8153/go/api/current_user/access_tokens/2"
    },
    "doc" : {
      "href" : "https://api.gocd.org/19.2.0/#access-tokens"
    },
    "find" : {
      "href" : "http://localhost:8153/go/api/current_user/access_tokens/:id"
    }
  },
  "id" : 2,
  "description" : "my first token",
  "username" : "admin",
  "revoked" : false,
  "revoke_cause" : null,
  "revoked_by" : null,
  "revoked_at" : null,
  "created_at" : "2019-04-24T14:30:48Z",
  "last_used_at" : null,
  "token" : "93f296d37fa62d7766bf4bf174846a3b23f43f1f"
omarmarquez commented 5 years ago

Hi, thanks ketan, still doesnt work for me. When I use the correct syntax that you showed above with curl, curl hangs there (same as th gui) ...

[omar.marquez@chd-ws-lxit05 ~]$ curl http://chd-dev-vlog01:8153/go/api/current_user/access_tokens \
>       -u admin:secret \
>        -H 'Accept: application/vnd.go.cd.v1+json' \
>        -X POST \
>       -H 'Content-Type: application/json' \
>       -d '{
>         "description": "my first token"
>       }'

Looking at the server logs I see this (No mapping found for /go/api) :

2019-04-24 15:16:33,848 WARN  [qtp1995616381-32] PageNotFound:1176 - No mapping found for HTTP request with URI [/go/api] in DispatcherServlet with name 'spring-all'
2019-04-24 15:16:36,565 ERROR [qtp1995616381-32] CustomSslContextFactory:61 - Client certificate was found to be invalid
sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
        at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:397)
        at sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:302)
        at sun.security.validator.Validator.validate(Validator.java:262)
        at sun.security.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:324)
        at sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:227)
        at sun.security.ssl.X509TrustManagerImpl.checkClientTrusted(X509TrustManagerImpl.java:99)
        at com.thoughtworks.go.server.util.CustomSslContextFactory$CustomX509TrustManager.checkClientTrusted(CustomSslContextFactory.java:59)
        at sun.security.ssl.AbstractTrustManagerWrapper.checkClientTrusted(SSLContextImpl.java:999)
        at sun.security.ssl.ServerHandshaker.clientCertificate(ServerHandshaker.java:1970)
        at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:232)
        at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1037)
        at sun.security.ssl.Handshaker$1.run(Handshaker.java:970)
        at sun.security.ssl.Handshaker$1.run(Handshaker.java:967)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1459)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:511)
        at org.eclipse.jetty.server.HttpConnection.fillRequestBuffer(HttpConnection.java:331)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:243)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:411)
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:305)
        at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
        at java.lang.Thread.run(Thread.java:748)
Caused by: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
        at sun.security.provider.certpath.SunCertPathBuilder.build(SunCertPathBuilder.java:141)
        at sun.security.provider.certpath.SunCertPathBuilder.engineBuild(SunCertPathBuilder.java:126)
        at java.security.cert.CertPathBuilder.build(CertPathBuilder.java:280)
        at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:392)
        ... 32 common frames omitted
2019-04-24 15:16:36,565 ERROR [qtp1995616381-32] CustomSslContextFactory:62 - Client certificate chain:
2019-04-24 15:16:36,566 ERROR [qtp1995616381-32] CustomSslContextFactory:66 - chain[0]: [
[
  Version: V3
  Subject: EMAILADDRESS=support@thoughtworks.com, CN=chd-dev-vlog01, OU=Cruise agent certificate
  Signature Algorithm: SHA256withRSA, OID = 1.2.840.113549.1.1.11

Would it be that we are using different images? I downloaded mine from docker hub:

[omar.marquez@chd-dev-vlog01 ~/gocd]$ docker images | grep gocd
gocd/gocd-agent-centos-7                           v19.2.0             0efc6333d0c8        7 weeks ago         547MB
gocd/gocd-server                                   v19.2.0             9ba21130e103        7 weeks ago         326MB

Does this match the one you have?

omarmarquez commented 5 years ago

Also my docker version:

$ docker version
Client:
 Version:           18.09.2
 API version:       1.39
 Go version:        go1.10.6
 Git commit:        6247962
 Built:             Sun Feb 10 04:13:27 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          18.09.2
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.10.6
  Git commit:       6247962
  Built:            Sun Feb 10 03:47:25 2019
  OS/Arch:          linux/amd64
  Experimental:     false
omarmarquez commented 5 years ago

Yes, I tried in an Incongnito Window and using a different browser (FireFox) with the same result.

ketan commented 5 years ago

2019-04-24 15:16:36,565 ERROR [qtp1995616381-32] CustomSslContextFactory:61 - Client certificate was found to be invalid

This seems to indicate possible errors with connections from an agent (which likely failed).

Would it be that we are using different images? I downloaded mine from docker hub:

I don't think so:

$ docker images | grep gocd
gocd/gocd-server    v19.2.0             9ba21130e103        7 weeks ago         326MB

At this point I'm wondering if this is a problem specific to POST requests, or all API requests. I'd consider turning on logging. Edit the file /godata/config/logback-include.xml in the container (docker exec -it $CONTAINER_ID vi /godata/config/logback-include.xml) and add the following snippet. Make sure that there are no incoming requests to this instance (or you may find it hard to sift through the logs)

<included>
 ...
 <logger name="com.thoughtworks.go.server.newsecurity" level="debug" />
</included>

Are you able to make any other HTTP GET/POST API calls? I'd probably try these to narrow the problem down:

Hopefully, you'd see logs about what filters are being invoked (and where the request is taking too long to process).

omarmarquez commented 5 years ago

Turned logging in as per the instruction above and then follow the logs of the running container with "docker logs -f gocd " did not see anything anomalous.

Yes the proposed test do work fine:

[omar.marquez@chd-ws-lxit05 ~]$ curl -X GET http://chd-dev-vlog01:8153/go/api/admin/config_repos       -u admin:secret        -H 'Accept: application/vnd.go.cd.v1+json'       -H 'Content-Type: application/json' 
{
  "_links" : {
    "self" : {
      "href" : "http://chd-dev-vlog01:8153/go/api/admin/config_repos"
    }
  },
  "_embedded" : {
    "config_repos" : [ ]
  }
}[omar.marquez@chd-ws-lxit05 ~]$ 
[omar.marquez@chd-ws-lxit05 ~]$ curl 'http://chd-dev-vlog01:8153/go/api/admin/config_repos' \
>   -u 'admin:secret' \
>   -H 'Accept:application/vnd.go.cd.v1+json' \
>   -H 'Content-Type:application/json' \
>   -X POST -d '{
>     "id": "repo-2",
>     "plugin_id": "json.config.plugin",
>     "material": {
>       "type": "git",
>       "attributes": {
>         "url": "https://github.com/config-repo/gocd-json-config-example2.git",
>         "branch": "master",
>         "auto_update": true
>       }
>     },
>     "configuration": [
>       {
>        "key": "pattern",
>        "value": "*.myextension"
>      }
>     ]
>   }'
{
  "_links" : {
    "self" : {
      "href" : "http://chd-dev-vlog01:8153/go/api/admin/config_repos/repo-2"
    },
    "doc" : {
      "href" : "https://api.gocd.org/19.2.0/#config-repos"
    },
    "find" : {
      "href" : "http://chd-dev-vlog01:8153/go/api/admin/config_repos/:id"
    }
  },
  "id" : "repo-2",
  "plugin_id" : "json.config.plugin",
  "material" : {
    "type" : "git",
    "attributes" : {
      "name" : null,
      "auto_update" : true,
      "url" : "https://github.com/config-repo/gocd-json-config-example2.git",
      "branch" : "master"
    }
  },
  "configuration" : [ {
    "key" : "pattern",
    "value" : "*.myextension"
  } ]
[omar.marquez@chd-ws-lxit05 ~]$ curl -X GET http://chd-dev-vlog01:8153/go/api/admin/config_repos       -u admin:secret        -H 'Accept: application/vnd.go.cd.v1+json'       -H 'Content-Type: application/json' 
{
  "_links" : {
    "self" : {
      "href" : "http://chd-dev-vlog01:8153/go/api/admin/config_repos"
    }
  },
  "_embedded" : {
    "config_repos" : [ {
      "_links" : {
        "self" : {
          "href" : "http://chd-dev-vlog01:8153/go/api/admin/config_repos/repo-2"
        },
        "doc" : {
          "href" : "https://api.gocd.org/19.2.0/#config-repos"
        },
        "find" : {
          "href" : "http://chd-dev-vlog01:8153/go/api/admin/config_repos/:id"
        }
      },
      "id" : "repo-2",
      "plugin_id" : "json.config.plugin",
      "material" : {
        "type" : "git",
        "attributes" : {
          "name" : null,
          "auto_update" : true,
          "url" : "https://github.com/config-repo/gocd-json-config-example2.git",
          "branch" : "master"
        }
      },
      "configuration" : [ {
        "key" : "pattern",
        "value" : "*.myextension"
      } ]
    } ]
  }
}

I see the added repo in the gui: Screenshot from 2019-04-24 12-08-55

omarmarquez commented 5 years ago

If I re-try the access token creation:

$ curl http://chd-dev-vlog01:8153/go/api/current_user/access_tokens       -u admin:secret        -H 'Accept: application/vnd.go.cd.v1+json'        -X POST       -H 'Content-Type: application/json'       -d '{
        "description": "my first token"
      }'

Now in the log i see this:

2019-04-24 17:15:03,493 DEBUG [qtp1995616381-2175] AlwaysCreateSessionFilter:40 - Session info for url: /go/api/current_user/access_tokens, Current session: node0fz2t3fxwus8xujbte09bqspo51, Requested session id: null
2019-04-24 17:15:03,493 DEBUG [qtp1995616381-2175] InvalidateAuthenticationOnSecurityConfigChangeFilter:88 - Authentication token is not created for the request.
2019-04-24 17:15:03,493 DEBUG [qtp1995616381-2175] ReAuthenticationWithChallengeFilter:74 - Continuing chain because authentication token is authenticated or null.
2019-04-24 17:15:03,494 DEBUG [qtp1995616381-2175] AssumeAnonymousUserFilter:60 - Security is enabled.
2019-04-24 17:15:03,494 DEBUG [qtp1995616381-2175] AnonymousAuthenticationProvider:54 - Authenticating as anonymous user with role(s) [ROLE_ANONYMOUS]
2019-04-24 17:15:03,494 DEBUG [qtp1995616381-2175] SessionUtils:51 - Setting authentication on existing session.
2019-04-24 17:15:03,494 DEBUG [qtp1995616381-2175] AssumeAnonymousUserFilter:64 - User authenticated as anonymous user AuthenticationToken{user=com.thoughtworks.go.server.security.userdetail.GoUserPrinciple@ffa921b6, authConfigId='null', authenticatedAt=1556126103494, pluginId='null', invalidated=false}
2019-04-24 17:15:03,495 DEBUG [qtp1995616381-2175] BasicAuthenticationWithChallengeFilter:63 - [Basic Authentication] Authorization header found for user 'admin'
2019-04-24 17:15:03,495 DEBUG [qtp1995616381-2175] BasicAuthenticationWithChallengeFilter:67 - Security is enabled.
2019-04-24 17:15:03,495 DEBUG [qtp1995616381-2175] BasicAuthenticationWithChallengeFilter:91 - authenticating user admin using basic auth credentials
2019-04-24 17:15:03,495 DEBUG [qtp1995616381-2175] PasswordBasedPluginAuthenticationProvider:118 - Authenticating user using the authorization plugin: `cd.go.authentication.passwordfile`
2019-04-24 17:15:03,500  INFO [qtp1995616381-2175] p.c.g.a.p.c.g.a.p.PasswordFilePlugin:73 [plugin-cd.go.authentication.passwordfile] - [Authenticate] User `admin` successfully authenticated using auth config: pass01
2019-04-24 17:15:03,502 DEBUG [qtp1995616381-2175] PasswordBasedPluginAuthenticationProvider:126 - Successfully authenticated user: `admin` using the authorization plugin: `cd.go.authentication.passwordfile`
2019-04-24 17:15:03,502 DEBUG [qtp1995616381-2175] SessionUtils:87 - Creating new session.
2019-04-24 17:15:03,502 DEBUG [qtp1995616381-2175] SessionUtils:58 - Setting authentication on new session.
2019-04-24 17:15:03,503 DEBUG [qtp1995616381-2175] AccessTokenAuthenticationFilter:85 - Security Enabled: true
2019-04-24 17:15:03,503 DEBUG [qtp1995616381-2175] AccessTokenAuthenticationFilter:123 - Bearer auth credentials are not provided in request.
2019-04-24 17:15:03,503 DEBUG [qtp1995616381-2175] ThreadLocalUserFilter:41 - Set loggedin user admin to thread local for request /go/api/current_user/access_tokens.
2019-04-24 17:15:03,504 DEBUG [qtp1995616381-2175] VerifyAuthorityFilter:57 - User admin authorized to access /go/api/current_user/access_tokens
2019-04-24 17:15:03,587 ERROR [qtp1995616381-2291] CustomSslContextFactory:61 - Client certificate was found to be invalid
sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
    at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:397)
    at sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:302)
    at sun.security.validator.Validator.validate(Validator.java:262)
    at sun.security.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:324)
    at sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:227)
    at sun.security.ssl.X509TrustManagerImpl.checkClientTrusted(X509TrustManagerImpl.java:99)
    at com.thoughtworks.go.server.util.CustomSslContextFactory$CustomX509TrustManager.checkClientTrusted(CustomSslContextFactory.java:59)
    at sun.security.ssl.AbstractTrustManagerWrapper.checkClientTrusted(SSLContextImpl.java:999)
    at sun.security.ssl.ServerHandshaker.clientCertificate(ServerHandshaker.java:1970)
    at sun.security.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:232)
    at sun.security.ssl.Handshaker.processLoop(Handshaker.java:1037)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:970)
    at sun.security.ssl.Handshaker$1.run(Handshaker.java:967)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.security.ssl.Handshaker$DelegatedTask.run(Handshaker.java:1459)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:511)
    at org.eclipse.jetty.server.HttpConnection.fillRequestBuffer(HttpConnection.java:331)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:243)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:411)
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:305)
    at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
    at java.lang.Thread.run(Thread.java:748)
Caused by: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
    at sun.security.provider.certpath.SunCertPathBuilder.build(SunCertPathBuilder.java:141)
    at sun.security.provider.certpath.SunCertPathBuilder.engineBuild(SunCertPathBuilder.java:126)
    at java.security.cert.CertPathBuilder.build(CertPathBuilder.java:280)
    at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:392)
    ... 32 common frames omitted
2019-04-24 17:15:03,587 ERROR [qtp1995616381-2291] CustomSslContextFactory:62 - Client certificate chain:
2019-04-24 17:15:03,587 ERROR [qtp1995616381-2291] CustomSslContextFactory:66 - chain[0]: [
[
  Version: V3
  Subject: EMAILADDRESS=support@thoughtworks.com, CN=chd-dev-vlog01, OU=Cruise agent certificate
  Signature Algorithm: SHA256withRSA, OID = 1.2.840.113549.1.1.11

  Key:  Sun RSA public key, 2048 bits
  modulus: 18649465707716651562642217465834715878375869103926646668821134836544840338679079829022007045654052318235961144698364264910944275594628615685633280644947075524180024193276423672139829245923706019494162140011153634376536031924845583369671753523015032119752941446739671533453930191075280276012850238012819186389444097636504466954275744184367157839650519480486649779750342234676925756345302758166969953528511554311920460540426196732296379501771576564430073486782356978056742382565588804026268471052392133351551565802340142962866617954280969914363853939610373135307965289872349372147418079269452214943010312271510637280651
  public exponent: 65537
  Validity: [From: Thu Jan 01 00:00:00 GMT 1970,
               To: Sun Apr 22 14:37:20 GMT 2029]
  Issuer: EMAILADDRESS=support@thoughtworks.com, OU=Cruise intermediate certificate
  SerialNumber: [    03]

Certificate Extensions: 2
[1]: ObjectId: 2.5.29.35 Criticality=false
AuthorityKeyIdentifier [
KeyIdentifier [
0000: 00 80 0E DA F8 31 86 E7   F0 35 AC 10 34 02 38 B5  .....1...5..4.8.
0010: CD 38 E3 44                                        .8.D
]
]

[2]: ObjectId: 2.5.29.14 Criticality=false
SubjectKeyIdentifier [
KeyIdentifier [
0000: 7D 05 06 23 31 B1 1A A0   8C 46 83 A3 B3 87 CC 9B  ...#1....F......
0010: 18 1F 35 7F                                        ..5.
]
]

]
  Algorithm: [SHA256withRSA]
  Signature:
0000: A4 70 D0 2F E5 E0 DC 53   EC A8 ED 51 EA FE 25 45  .p./...S...Q..%E
0010: A4 9C B7 B2 02 9C 82 B9   28 D2 22 BC 97 26 26 81  ........(."..&&.
0020: 16 0B 93 2A 80 5E 8D 54   0F E4 5A 71 4B 27 41 26  ...*.^.T..ZqK'A&
0030: 42 D4 43 E8 94 DE 53 6A   BE E4 2E E3 14 B6 BD A0  B.C...Sj........
0040: 84 14 EA D7 54 42 49 8E   36 05 0C DD 31 5A 1B AC  ....TBI.6...1Z..
0050: AD E5 A2 48 65 CD 7D DA   F9 0F E5 B5 42 C7 9F 82  ...He.......B...
0060: DA EF FF 4C 80 33 E6 6E   3E 41 E2 77 5E 0C 98 9E  ...L.3.n>A.w^...
0070: 22 58 20 4C B1 91 A7 96   2D E6 2F 28 49 09 71 61  "X L....-./(I.qa
0080: 30 0F E9 6A 22 97 80 2B   20 1F 05 F1 51 A5 0A 7C  0..j"..+ ...Q...
0090: F2 76 C2 70 25 35 94 B8   48 96 21 99 68 80 7D A4  .v.p%5..H.!.h...
00A0: 98 93 63 F6 10 7B 76 0B   4D D5 39 F8 7D 7E 2C 2F  ..c...v.M.9...,/
00B0: 5D 66 2A 0E 12 ED 0E 26   76 D7 4C 6F 3A 58 CE 72  ]f*....&v.Lo:X.r
00C0: 54 20 E8 1C 24 DC 56 2F   B1 D8 C9 33 86 A8 9F 7C  T ..$.V/...3....
00D0: AF 3A D8 D8 4C F0 A0 CF   6C 3E 12 E0 8E D9 58 E0  .:..L...l>....X.
00E0: 3A 75 F4 4A F8 E9 53 B8   2E AD 87 A5 C7 90 DF 6F  :u.J..S........o
00F0: A2 47 1E 4B 58 93 2F 06   09 B8 0F A0 E6 10 3D 11  .G.KX./.......=.

]
2019-04-24 17:15:03,587 ERROR [qtp1995616381-2291] CustomSslContextFactory:66 - chain[1]: [
[
  Version: V3
  Subject: EMAILADDRESS=support@thoughtworks.com, OU=Cruise intermediate certificate
  Signature Algorithm: SHA256withRSA, OID = 1.2.840.113549.1.1.11

  Key:  Sun RSA public key, 2048 bits
  modulus: 23137758914744068067038581829635528073992189409235186256238011809531245184773748679236912642689651686223839210109519556352069926767032352353665483773830283034372861600896732100953443718127821775991190835453412910794093454611816735479731823147851331705268446004426613843524551235662554254074939573684230854346021168524416212255652118738821466864718373054984133462065415286301710728723321702952603729382149566351297035268651019541175412324268512689147932481012703212984932402858600232911585919159924102396231844302576180309131855756367625800623179613149501615175103903369270397492565298336714030994243267588225962965093
  public exponent: 65537
  Validity: [From: Thu Jan 01 00:00:00 GMT 1970,
               To: Wed Apr 18 20:44:06 GMT 2029]
  Issuer: OU=Cruise Server primary certificate, CN=78e4da7015a1
  SerialNumber: [    08a47581 cbe9]

Certificate Extensions: 3
[1]: ObjectId: 2.5.29.35 Criticality=false
AuthorityKeyIdentifier [
KeyIdentifier [
0000: 47 D4 C9 3B 1D 82 27 F1   C9 81 5D 97 8A 19 AD F1  G..;..'...].....
0010: 96 62 6F 6F                                        .boo
]
[OU=Cruise Server primary certificate, CN=78e4da7015a1]
SerialNumber: [    016d65fd 3440]
]

[2]: ObjectId: 2.5.29.19 Criticality=true
BasicConstraints:[
  CA:true
  PathLen:0
]

[3]: ObjectId: 2.5.29.14 Criticality=false
SubjectKeyIdentifier [
KeyIdentifier [
0000: 00 80 0E DA F8 31 86 E7   F0 35 AC 10 34 02 38 B5  .....1...5..4.8.
0010: CD 38 E3 44                                        .8.D
]
]

]
  Algorithm: [SHA256withRSA]
  Signature:
0000: CB 8E B8 BC 00 61 D4 9D   08 9A 05 A1 EE CD D5 EF  .....a..........
0010: E9 F3 1C 3E D3 CD 7A 61   23 B7 73 CB E9 61 B6 04  ...>..za#.s..a..
0020: 3A 6F 83 BF E1 57 7D F2   D8 6B 2C BC A0 55 C5 D0  :o...W...k,..U..
0030: B6 84 5E 73 7A C7 73 C5   C1 E3 74 C1 5D 42 84 8F  ..^sz.s...t.]B..
0040: 1B 31 CF 6F 81 45 A4 99   18 AD 97 A9 E3 34 E3 C2  .1.o.E.......4..
0050: D8 7B 40 F2 FB 0D 2F 95   D2 50 EC B6 5E 86 51 1F  ..@.../..P..^.Q.
0060: A0 C4 0A 3F 24 27 47 F1   14 7B 3F FF 9A DD EE AC  ...?$'G...?.....
0070: 6F C9 07 54 B1 92 33 F9   30 E8 3F 6E A2 3D A9 C0  o..T..3.0.?n.=..
0080: 10 AA 83 07 81 75 4B 0A   B7 CC 8B DF 10 83 B2 B1  .....uK.........
0090: BD B0 F4 23 E9 36 99 8D   6D 5D 41 23 C4 35 E5 01  ...#.6..m]A#.5..
00A0: D9 3A D2 D4 26 4B 98 82   BA 92 2E 38 26 58 6B 0D  .:..&K.....8&Xk.
00B0: A9 2D 81 F5 13 E3 3A BA   94 00 19 6A AB B1 A6 89  .-....:....j....
00C0: 6F 82 4F 56 3D 0F 45 4C   31 FA 77 72 E6 5A F5 B9  o.OV=.EL1.wr.Z..
00D0: F2 B0 8C 8D DB 5E A1 7E   15 25 5A 8F 7E 32 42 C1  .....^...%Z..2B.
00E0: BD 1D 10 32 B5 09 78 60   F0 CC 71 50 F1 57 CE 6D  ...2..x`..qP.W.m
00F0: B7 84 B7 87 19 9E CE 15   BE C7 AB 22 0F 5E 77 24  ...........".^w$

]
2019-04-24 17:15:03,588 ERROR [qtp1995616381-2291] CustomSslContextFactory:66 - chain[2]: [
[
  Version: V1
  Subject: OU=Cruise Server primary certificate, CN=78e4da7015a1
  Signature Algorithm: SHA512withRSA, OID = 1.2.840.113549.1.1.13

  Key:  Sun RSA public key, 2048 bits
  modulus: 28109323308882761645009850768783689126274130842829248124375740097323717110827401207673068320423091616093757707548837989995722674571347689894407653525672160304834641843813719246068888179867735800795277233711898655166364255155404128609627939566323993583998194161396433405825811894368183541097263096589971123308650263782019975927189933668867331359580344068487815520846393291986616186112870316452550738977526575050720351352034064363579162003036003053601278761377169115303936254205310210089488944794643673517527287806001673313481324902423421876801830980983761856480633747533553709682029547650296451642242680398466582557253
  public exponent: 65537
  Validity: [From: Thu Jan 01 00:00:00 GMT 1970,
               To: Wed Apr 18 20:44:06 GMT 2029]
  Issuer: OU=Cruise Server primary certificate, CN=78e4da7015a1
  SerialNumber: [    016d65fd 3440]

]
  Algorithm: [SHA512withRSA]
  Signature:
0000: 46 CC 89 1D E2 02 2F 88   D0 5F B0 54 9E 54 73 D9  F...../.._.T.Ts.
0010: 2B 2C 30 E3 35 EF 16 A5   44 4A BD 48 44 31 6D C6  +,0.5...DJ.HD1m.
0020: 52 F1 98 A5 78 78 86 7E   64 15 89 0F 8D 31 51 85  R...xx..d....1Q.
0030: 5C D1 EF 35 49 A5 18 13   93 4A A3 1B C4 C6 D2 5D  \..5I....J.....]
0040: 2B FF D6 1F 18 FB D6 10   FA 25 E0 B2 36 88 03 51  +........%..6..Q
0050: E5 60 57 6A 30 DE EE E1   51 26 42 49 9E E8 11 FB  .`Wj0...Q&BI....
0060: 2D C8 94 C0 70 E2 12 CB   01 8B 6B 64 09 63 23 12  -...p.....kd.c#.
0070: 00 0C 1F D7 AC 7E 21 07   9B D2 2A 43 37 D5 5A 9C  ......!...*C7.Z.
0080: 64 25 97 28 43 5A 9D 56   59 D3 06 BE D0 6C D0 A1  d%.(CZ.VY....l..
0090: 31 54 1B B6 97 9C 0C 5E   ED B1 F4 9D B5 89 87 AE  1T.....^........
00A0: EB 50 93 AD 69 5A 5D 30   D4 42 E4 40 8F DE 3D 3B  .P..iZ]0.B.@..=;
00B0: EF A3 65 5A 4E 82 0F A9   F8 54 F8 81 8D B4 4D 47  ..eZN....T....MG
00C0: 1F 8D 99 62 CC 0B 62 C8   C2 1D 2D 8F 5D 71 C7 00  ...b..b...-.]q..
00D0: D5 FC 3B 14 7C 56 D3 73   93 9C 9F 29 17 08 FD 60  ..;..V.s...)...`
00E0: 66 B7 7B ED 1E 16 C4 0C   A8 14 BD 51 EC 41 2C C8  f..........Q.A,.
00F0: 74 8D C8 7B 5C D8 3C 66   C2 79 9C 56 F5 23 F3 CC  t...\.<f.y.V.#..

]
2019-04-24 17:15:03,588 ERROR [qtp1995616381-2291] CustomSslContextFactory:73 - The accepted certificates are:
2019-04-24 17:15:03,588 ERROR [qtp1995616381-2291] CustomSslContextFactory:75 - [
[
  Version: V3
  Subject: EMAILADDRESS=support@thoughtworks.com, OU=Cruise intermediate certificate
  Signature Algorithm: SHA256withRSA, OID = 1.2.840.113549.1.1.11

  Key:  Sun RSA public key, 2048 bits
  modulus: 22023042852374312029512822466111246089461747195727523396798058911348400057839843038466957007072412838791582736384941496906277822861948575090142231943341913182948923269581968350492657667177958567353967134086092107089903382723011732321363923200008313635257777910426341430916616324771436008574913340295979654780760136660301529767151809178272110836696388289797280702380461590212278462810966381753376812657730436256532179958187160039928423505114061910650309301402282906630221177185727514881915208039657606314034983586861663937243764317853877477741023254451631417945978187408226244312418262557681817543899965675645764346537
  public exponent: 65537
  Validity: [From: Thu Jan 01 00:00:00 GMT 1970,
               To: Tue Apr 24 15:06:26 GMT 2029]
  Issuer: OU=Cruise Server primary certificate, CN=1ae79ad4cc07
  SerialNumber: [    02b599ce bcae]

Certificate Extensions: 3
[1]: ObjectId: 2.5.29.35 Criticality=false
AuthorityKeyIdentifier [
KeyIdentifier [
0000: 8F E7 62 5C 7C D1 21 B2   70 7E 84 B9 5B 22 DB 7D  ..b\..!.p...["..
0010: E2 9F 3A CE                                        ..:.
]
[OU=Cruise Server primary certificate, CN=1ae79ad4cc07]
SerialNumber: [    085bc2dc ecc7]
]

[2]: ObjectId: 2.5.29.19 Criticality=true
BasicConstraints:[
  CA:true
  PathLen:0
]

[3]: ObjectId: 2.5.29.14 Criticality=false
SubjectKeyIdentifier [
KeyIdentifier [
0000: F1 CC A2 47 31 44 4B 1C   18 16 58 0C 8C B1 0C 2D  ...G1DK...X....-
0010: 9A F7 21 2D                                        ..!-
]
]

]
  Algorithm: [SHA256withRSA]
  Signature:
0000: 83 2C 1C 70 6E EA 33 82   27 9B 45 BA B2 D9 A9 B4  .,.pn.3.'.E.....
0010: 6A 8E E7 74 2A EE 38 82   80 05 FD 64 E9 75 B6 15  j..t*.8....d.u..
0020: C0 94 3B 2E 73 FB 7C 2D   13 D8 41 15 A9 22 D1 8A  ..;.s..-..A.."..
0030: 12 25 FB 2D 6F B7 22 83   CB EC 23 5B 6B F0 26 F6  .%.-o."...#[k.&.
0040: E9 85 B9 3F C4 BF FC 4F   43 E0 0B 92 1B E1 79 C1  ...?...OC.....y.
0050: 98 A0 7D 80 C6 BD E6 0C   93 4E 61 64 58 49 66 DA  .........NadXIf.
0060: 4B 0B 33 89 C1 1F 70 A8   CD 2E 8A 63 A4 49 3B C7  K.3...p....c.I;.
0070: D5 3D A0 F3 EA 4B 04 AF   85 77 05 56 AE E3 D0 62  .=...K...w.V...b
0080: F5 7C 43 18 69 92 51 EA   5D D4 E0 0A C8 60 EA 87  ..C.i.Q.]....`..
0090: 61 CF 29 96 64 F4 EA 36   31 75 7D BC 77 87 9B C4  a.).d..61u..w...
00A0: 32 EA ED 06 6C 17 EF FB   99 CF 07 1A 7C 05 66 BD  2...l.........f.
00B0: 05 0B 28 BE 0F 1E 50 93   A9 03 8C 65 2A B1 F1 92  ..(...P....e*...
00C0: 5B E9 0E 88 8F 58 3A 0F   2D 60 62 5D 57 D4 5F C1  [....X:.-`b]W._.
00D0: 23 E2 9D D6 E8 77 F9 F3   3D B0 71 6E 4F FF D8 AB  #....w..=.qnO...
00E0: 27 17 71 48 D9 F5 79 3F   A6 DE 27 07 28 3A DE 3C  '.qH..y?..'.(:.<
00F0: 55 09 E4 85 B7 1C A2 53   F9 45 DF C2 91 B3 D2 2E  U......S.E......

]
omarmarquez commented 5 years ago

The tokens were created though, I see then in the UI below, but never got the response back in curl showing the token value:

Screenshot from 2019-04-24 12-26-03

omarmarquez commented 5 years ago

The SSL error seems , as indicated above, be related to a previous agent running and attempting to connect to the server.

arvindsv commented 5 years ago

@omarmarquez Do you see any difference if you docker exec into the container and run curl?

Something like:

docker exec -it my-docker-container bash
curl ... http://localhost:8153/go/...
ketan commented 5 years ago 
> 2019-04-24 17:15:03,503 DEBUG [qtp1995616381-2175] ThreadLocalUserFilter:41 - Set loggedin user admin to thread local for request /go/api/current_user/access_tokens.
> 2019-04-24 17:15:03,504 DEBUG [qtp1995616381-2175] VerifyAuthorityFilter:57 - User admin authorized to access /go/api/current_user/access_tokens
> 2019-04-24 17:15:03,587 ERROR [qtp1995616381-2291] CustomSslContextFactory:61 - Client certificate was found to be invalid
> sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
>   at sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:397)

These are logs from 2 different threads (qtp1995616381-2175 and qtp1995616381-2291) (one from your curl request, and another from an agent). Are there any additional logs for the thread qtp1995616381-2175 after the exceptions?

Would it be possible for you to run the curl commands on a gocd server running using a regular installer from https://www.gocd.org/downloads instead of the docker image?

omarmarquez commented 5 years ago

No difference the call never returns: Screenshot from 2019-04-25 07-46-14

omarmarquez commented 5 years ago

Update: I download ran the server as suggested above without docker. Initially the behavior was the same not return, but it turns out that If i leave the screen for 20 minutes or so it will return and show the token ian about 19 minutes.

I reverted then back to the docker container and yes it takes about 19 minutes to return via the gui. Trying the same from the command line I see returning after 16 minutes as in below:

Screenshot from 2019-04-25 16-58-41

So the issue is not that it never returns but the long wait required. Should not this be immediate ?

omarmarquez commented 5 years ago

This is a trace that shows the problem happening, 31 minutes to create the token!

Client side:

$ date && time curl -k https://chd-dev-vlog01:8154/go/api/current_user/access_tokens       -u admin:secret        -H 'Accept: application/vnd.go.cd.v1+json'        -X POST       -H 'Content-Type: application/json'       -d '{
        "description": "timing token creation with docker server "
      }' && date
Fri Apr 26 10:00:05 CDT 2019
{
  "_links" : {
    "self" : {
      "href" : "https://chd-dev-vlog01:8154/go/api/current_user/access_tokens/167"
    },
    "doc" : {
      "href" : "https://api.gocd.org/19.2.0/#access-tokens"
    },
    "find" : {
      "href" : "https://chd-dev-vlog01:8154/go/api/current_user/access_tokens/:id"
    }
  },
  "id" : 167,
  "description" : "timing token creation with docker server ",
  "username" : "admin",
  "revoked" : false,
  "revoke_cause" : null,
  "revoked_by" : null,
  "revoked_at" : null,
  "created_at" : "2019-04-26T15:31:27Z",
  "last_used_at" : null,
  "token" : "f6be060ae79e9cb106e7071dbce9b1d11b677eb7"
}
real    31m22.403s
user    0m0.098s
sys 0m0.116s
Fri Apr 26 10:31:27 CDT 2019

Here is the transaction log in the server side:

2019-04-26 15:00:05,386 DEBUG [qtp665372494-26] AlwaysCreateSessionFilter:40 - Session info for url: /go/api/current_user/access_tokens, Current session: node01eh5cxlsoo7vojh10ujenan2713, Requested session id: null
2019-04-26 15:00:05,386 DEBUG [qtp665372494-26] InvalidateAuthenticationOnSecurityConfigChangeFilter:88 - Authentication token is not created for the request.
2019-04-26 15:00:05,386 DEBUG [qtp665372494-26] ReAuthenticationWithChallengeFilter:74 - Continuing chain because authentication token is authenticated or null.
2019-04-26 15:00:05,386 DEBUG [qtp665372494-26] AssumeAnonymousUserFilter:60 - Security is enabled.
2019-04-26 15:00:05,386 DEBUG [qtp665372494-26] AnonymousAuthenticationProvider:54 - Authenticating as anonymous user with role(s) [ROLE_ANONYMOUS]
2019-04-26 15:00:05,387 DEBUG [qtp665372494-26] SessionUtils:51 - Setting authentication on existing session.
2019-04-26 15:00:05,387 DEBUG [qtp665372494-26] AssumeAnonymousUserFilter:64 - User authenticated as anonymous user AuthenticationToken{user=com.thoughtworks.go.server.security.userdetail.GoUserPrinciple@ffa921b6, authConfigId='null', authenticatedAt=1556290805386, pluginId='null', invalidated=false}
2019-04-26 15:00:05,387 DEBUG [qtp665372494-26] BasicAuthenticationWithChallengeFilter:63 - [Basic Authentication] Authorization header found for user 'admin'
2019-04-26 15:00:05,387 DEBUG [qtp665372494-26] BasicAuthenticationWithChallengeFilter:67 - Security is enabled.
2019-04-26 15:00:05,388 DEBUG [qtp665372494-26] BasicAuthenticationWithChallengeFilter:91 - authenticating user admin using basic auth credentials
2019-04-26 15:00:05,388 DEBUG [qtp665372494-26] PasswordBasedPluginAuthenticationProvider:118 - Authenticating user using the authorization plugin: `cd.go.authentication.passwordfile`
2019-04-26 15:00:05,392  INFO [qtp665372494-26] p.c.g.a.p.c.g.a.p.PasswordFilePlugin:73 [plugin-cd.go.authentication.passwordfile] - [Authenticate] User `admin` successfully authenticated using auth config: pass01
2019-04-26 15:00:05,393 DEBUG [qtp665372494-26] PasswordBasedPluginAuthenticationProvider:126 - Successfully authenticated user: `admin` using the authorization plugin: `cd.go.authentication.passwordfile`
2019-04-26 15:00:05,393 DEBUG [qtp665372494-26] SessionUtils:87 - Creating new session.
2019-04-26 15:00:05,394 DEBUG [qtp665372494-26] SessionUtils:58 - Setting authentication on new session.
2019-04-26 15:00:05,394 DEBUG [qtp665372494-26] AccessTokenAuthenticationFilter:85 - Security Enabled: true
2019-04-26 15:00:05,394 DEBUG [qtp665372494-26] AccessTokenAuthenticationFilter:123 - Bearer auth credentials are not provided in request.
2019-04-26 15:00:05,394 DEBUG [qtp665372494-26] ThreadLocalUserFilter:41 - Set loggedin user admin to thread local for request /go/api/current_user/access_tokens.
2019-04-26 15:00:05,395 DEBUG [qtp665372494-26] VerifyAuthorityFilter:57 - User admin authorized to access /go/api/current_user/access_tokens
2019-04-26 15:20:12,169 DEBUG [qtp665372494-29] ThreadLocalUserFilter:45 - Unset loggedin user from thread local for request /go/api/current_user/access_tokens.
2019-04-26 15:20:12,170 DEBUG [qtp665372494-29] ApiSessionReduceIdleTimeoutFilter:51 - Setting max inactive interval for request: /go/api/current_user/access_tokens to 300.
2019-04-26 15:31:27,634 DEBUG [qtp665372494-26] ThreadLocalUserFilter:45 - Unset loggedin user from thread local for request /go/api/current_user/access_tokens.
2019-04-26 15:31:27,634 DEBUG [qtp665372494-26] ApiSessionReduceIdleTimeoutFilter:51 - Setting max inactive interval for request: /go/api/current_user/access_tokens to 300.
omarmarquez commented 5 years ago

As requested in the support site thread I'm attaching here the full server log from startup until the end of the client iteration below:

$ date && time curl -k https://chd-dev-vlog01:8154/go/api/current_user/access_tokens       -u admin:secret        -H 'Accept: application/vnd.go.cd.v1+json'        -X POST       -H 'Content-Type: application/json'       -d '{
        "description": "timing token creation with docker server "
      }' && date
Fri Apr 26 13:40:42 CDT 2019
{
  "_links" : {
    "self" : {
      "href" : "https://chd-dev-vlog01:8154/go/api/current_user/access_tokens/193"
    },
    "doc" : {
      "href" : "https://api.gocd.org/19.2.0/#access-tokens"
    },
    "find" : {
      "href" : "https://chd-dev-vlog01:8154/go/api/current_user/access_tokens/:id"
    }
  },
  "id" : 193,
  "description" : "timing token creation with docker server ",
  "username" : "admin",
  "revoked" : false,
  "revoke_cause" : null,
  "revoked_by" : null,
  "revoked_at" : null,
  "created_at" : "2019-04-26T18:58:13Z",
  "last_used_at" : null,
  "token" : "7dceef045b5ed8c30305fc2e4d642a09cad60fbe"
}
real    17m30.782s
user    0m0.060s
sys 0m0.085s
Fri Apr 26 13:58:13 CDT 2019

server.log

arvindsv commented 5 years ago

Should not this be immediate ?

Of course! No one should have to wait 31 minutes for a token. :)

I wish this was reproducible. It's an interesting issue, though! The only thing that comes to mind is that it's having trouble with entropy somewhere. When it's taking a lot of time to generate that token, can you do a kill -3 SERVER_PID? That should show a full thread list of where it's at in the GoCD stdout or stderr logs.

For reference, this is the code that generates the token. It does use a bit of SecureRandom, which needs entropy.

You can also try:

cat /proc/sys/kernel/random/entropy_avail

to see what your entropy situation looks like. You might need to also see it on the node, not just the docker container.

@omarmarquez Thank you for your patience. I know it can sometimes be frustrating.

omarmarquez commented 5 years ago

Hi the cat /proc/sys/.../entropy_avail returns quickly both in the node and inside the container. I also wonder since it happens as well when I run the java server if the encryption or key generation routine attempts to use some kind of network service ...

Any ways, attached is the server log when a kill -3 is issued: server-kill3.log

ketan commented 5 years ago

Thank you for sharing the thread dumps. Here's the particular thread appears to be busy generating a secure random string (the actual token)

"qtp665372494-18" #18 prio=5 os_prio=0 tid=0x00007f5833dc3800 nid=0x33 runnable [0x00007f5815f7a000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.ensureBufferValid(NativePRNG.java:525)
    at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:544)
    - locked <0x00000000c090cfb8> (a java.lang.Object)
    at sun.security.provider.NativePRNG$RandomIO.access$400(NativePRNG.java:331)
    at sun.security.provider.NativePRNG$Blocking.engineNextBytes(NativePRNG.java:268)
    at java.security.SecureRandom.nextBytes(SecureRandom.java:468)
    at com.thoughtworks.go.domain.AccessToken.generateSecureRandomString(AccessToken.java:98)
    at com.thoughtworks.go.domain.AccessToken.create(AccessToken.java:79)
    at com.thoughtworks.go.server.service.AccessTokenService.create(AccessTokenService.java:57)
    at com.thoughtworks.go.apiv1.accessToken.CurrentUserAccessTokenControllerV1.createAccessToken(CurrentUserAccessTokenControllerV1.java:94)

It seems like there's not enough entropy available on your system which is why the token generating is taking way longer than expected. While I put in a proper fix to ensure that the call is not blocking, there are a couple of options you may be able to explore. YMMV with either of the options:

Let me know which of these solutions gives you a reasonable results.

omarmarquez commented 5 years ago

Running haveged on startup did not alleviated the situation ... it might also been that haveged needs to be executed with different parameters (-F ? ) and then the container might need to run in privileged mode?

What seems to work fine was in the node (host) installing the rng-tools package and the run $ sudo rngd -r /dev/urandom followed by a restart of the gocd container. With this the token generation response is generated immediately:

$ date && time curl -k https://chd-dev-vlog01:8154/go/api/current_user/access_tokens       -u admin:secret        -H 'Accept: application/vnd.go.cd.v1+json'        -X POST       -H 'Content-Type: application/json'       -d '{
        "description": "timing token creation with docker server "
      }' && date
Mon Apr 29 13:33:34 CDT 2019
{
  "_links" : {
    "self" : {
      "href" : "https://chd-dev-vlog01:8154/go/api/current_user/access_tokens/260"
    },
    "doc" : {
      "href" : "https://api.gocd.org/19.2.0/#access-tokens"
    },
    "find" : {
      "href" : "https://chd-dev-vlog01:8154/go/api/current_user/access_tokens/:id"
    }
  },
  "id" : 260,
  "description" : "timing token creation with docker server ",
  "username" : "admin",
  "revoked" : false,
  "revoke_cause" : null,
  "revoked_by" : null,
  "revoked_at" : null,
  "created_at" : "2019-04-29T18:33:34Z",
  "last_used_at" : null,
  "token" : "607cffc56afc3c513f15af1415141ae0a61e8d07"
}
real    0m0.143s
user    0m0.041s
sys 0m0.066s
Mon Apr 29 13:33:34 CDT 2019

Since this effectively resolves my problem I think is Ok to close this issue. Switching to use a non-blocking generator could also be a good thing to prevent it from happening in the future.

ketan commented 5 years ago

I've kicked off a build for my PR. This is a commit on top of version 19.2, with just one commit on it. If you feel comfortable using that docker image, I can point you to a URL that

What seems to work fine was in the node (host) installing the rng-tools package and the run $ sudo rngd -r /dev/urandom

Thank you for letting us know. I've merged #6229 to not have this issue again. This change will move random number generator to use /dev/urandom instead of /dev/random. It seems acceptable (to me) to use a pseudo random number generator instead of a true random number generator.

Once you move over to version 19.4, you can remove the rng-tools package and kill the rng daemon.