Gocd elastic agent high bootstrap time

[deepak jain]

Gocd elastic agent takes upto 90 sec  to complete the bootstrap in many cases. we are using k8s elastic agent in gocd.
- after starting to search for high bootstrap time i found out the main culprit was pluing loader. it aws loading plugin sequentially. so after removing plugin which we don't need, i was able to bring bootup time to 36 second.

```
jvm 1    | 2022-02-07 16:27:31,128 [stdout] - 2022-02-07 16:27:31,127 INFO  [main] DefaultPluginJarChangeListener:67 - Plugin load starting: /go/plugins/external/github_feature_branch.jar
jvm 1    | 2022-02-07 16:27:34,774 [stdout] - 2022-02-07 16:27:34,773 ERROR [scheduler-3] RemotingClient:166 - Server responded to action `ping` with: status[422 Unprocessable Entity], body[{
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -   "message" : "Agent [Agent [prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e, 10.1.134.86, 226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set; nested exception is com.thoughtworks.go.server.service.AgentNoCookieSetException: Agent [Agent [prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e, 10.1.134.86, 226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set"
jvm 1    | 2022-02-07 16:27:34,774 [stdout] - }]
jvm 1    | 2022-02-07 16:27:34,774 [stdout] - 2022-02-07 16:27:34,773 ERROR [scheduler-3] AgentHTTPClientController:114 - Error occurred when agent tried to ping server:
jvm 1    | 2022-02-07 16:27:34,774 [stdout] - java.lang.RuntimeException: org.apache.http.client.ClientProtocolException: The server returned status code 422. Possible reasons include:
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -    - This agent has been deleted from the configuration
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -    - This agent is pending approval
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -    - There is possibly a reverse proxy (or load balancer) that has been misconfigured. See https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies for details.
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:118)
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at java.base/java.lang.reflect.Method.invoke(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,774 [stdout] -         at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at java.base/java.lang.Thread.run(Unknown Source)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] - Caused by: org.apache.http.client.ClientProtocolException: The server returned status code 422. Possible reasons include:
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -    - This agent has been deleted from the configuration
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -    - This agent is pending approval
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -    - There is possibly a reverse proxy (or load balancer) that has been misconfigured. See https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies for details.
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:114)
jvm 1    | 2022-02-07 16:27:34,775 [stdout] -         ... 14 common frames omitted
jvm 1    | 2022-02-07 16:27:35,544 [stdout] - 2022-02-07 16:27:35,544 INFO  [main] DefaultPluginJarChangeListener:74 - Plugin load finished: /go/plugins/external/github_feature_branch.jar
jvm 1    | 2022-02-07 16:27:35,553 [stdout] - 2022-02-07 16:27:35,552 INFO  [main] DefaultPluginJarChangeListener:67 - Plugin load starting: /go/plugins/external/git-path-material-plugin.jar
jvm 1    | 2022-02-07 16:27:35,674 [stdout] - 2022-02-07 16:27:35,674  INFO [main] p.G.c.t.g.s.p.GitPathMaterialPlugin:72 [plugin-GitPathMaterial] - Loading GitPathMaterialPlugin...
jvm 1    | 2022-02-07 16:27:39,782 [stdout] - 2022-02-07 16:27:39,781 ERROR [scheduler-3] RemotingClient:166 - Server responded to action `ping` with: status[422 Unprocessable Entity], body[{
jvm 1    | 2022-02-07 16:27:39,782 [stdout] -   "message" : "Agent [Agent [prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e, 10.1.134.86, 226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set; nested exception is com.thoughtworks.go.server.service.AgentNoCookieSetException: Agent [Agent [prod-default-gocd-agent-37129320-c0ff-400b-adcf-0cbcfb07456e, 10.1.134.86, 226c9178-3fe6-49e0-93fa-e5884eee8bca, null]] has no cookie set"
jvm 1    | 2022-02-07 16:27:39,782 [stdout] - }]
jvm 1    | 2022-02-07 16:27:39,783 [stdout] - 2022-02-07 16:27:39,782 ERROR [scheduler-3] AgentHTTPClientController:114 - Error occurred when agent tried to ping server:
jvm 1    | 2022-02-07 16:27:39,783 [stdout] - java.lang.RuntimeException: org.apache.http.client.ClientProtocolException: The server returned status code 422. Possible reasons include:
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -    - This agent has been deleted from the configuration
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -    - This agent is pending approval
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -    - There is possibly a reverse proxy (or load balancer) that has been misconfigured. See https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies for details.
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:118)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/java.lang.reflect.Method.invoke(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at java.base/java.lang.Thread.run(Unknown Source)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] - Caused by: org.apache.http.client.ClientProtocolException: The server returned status code 422. Possible reasons include:
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -    - This agent has been deleted from the configuration
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -    - This agent is pending approval
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -    - There is possibly a reverse proxy (or load balancer) that has been misconfigured. See https://docs.gocd.org/21.3.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies for details.
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         at com.thoughtworks.go.agent.RemotingClient.post(RemotingClient.java:114)
jvm 1    | 2022-02-07 16:27:39,783 [stdout] -         ... 14 common frames omitted
jvm 1    | 2022-02-07 16:27:40,213 [stdout] - 2022-02-07 16:27:40,212 INFO  [main] DefaultPluginJarChangeListener:74 - Plugin load finished: /go/plugins/external/git-path-material-plugin.jar
```

- after above steps there 2 log lines which had 10 sec gap each if we can tune it, it can reduce the bootstrap time considerably.
1st one is

```
jvm 1    | 2022-02-07 16:26:47,893 INFO  [WrapperJarAppMain] DefaultAgentLauncherCreatorImpl:87 - Attempt No: 1 to cleanup launcher temp files
jvm 1    | 2022-02-07 16:26:47,919 INFO  [WrapperJarAppMain] AgentBootstrapper:104 - Waiting for 10000 ms before re-launch....
jvm 1    | 2022-02-07 16:26:58,018 INFO  [WrapperJarAppMain] DefaultAgentLauncherCreatorImpl:67 - Attempting to load com.thoughtworks.go.agent.launcher.AgentLauncherImpl as specified by manifest key Go-Agent-Launcher-Class
```

i found out the system property which we can use to reduce this time. but still haven't tried it

2nd one is
```
jvm 1    | 2022-02-07 16:27:40,230 [stdout] - 2022-02-07 16:27:40,230 INFO  [scheduler-1] AgentHTTPClientController:142 - Got cookie: 2df451e8-a5fb-4d9a-b8e2-e38efb52b27f
jvm 1    | 2022-02-07 16:27:50,362 [stdout] - 2022-02-07 16:27:50,361 INFO  [scheduler-1] HttpService:125 - Got back 200 from server
```

i couldn't find out as to why there is this 10 sec gap. so reason of this ticket to understand this 10 sec wait time.

* Go Version: 21.3.0 (13067-4c4bb4780eb0d3fc4cacfc4cfcc0b07e2eaf0595)

[deepak jain]

I was able to reduce the first 10 sec interval by setting this

```
export AGENT_BOOTSTRAPPER_JVM_ARGS="-Dagent.bootstrapper.wait.time.before.relaunch.in.ms=200

```

[Sifu Tian]

Hi Jainee,

Im using k8s elastic agent as well.  Can you tell me exactly where you set this?  On a ec2 agent its normally set in /etc/default/....