Thanks! That helps.
So what you see there in the errors is the background 5 second ping to
check connection. This is a symptom but not the root cause of the problem.
Before this scheduled check can go healthy, the agent has to fully
initialise and start to obtain work. The root cause of the start-up delay
appears to be that the plugin load is slow (the stuff you see on the *[main]
*thread in the logs).
If we remove this background thread noise, we see the below.
2022-12-19 19:03:24,972 INFO [main] ThreadPoolTaskScheduler:166 -
Initializing ExecutorService 'scheduler'
2022-12-19 19:03:26,004 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting:
/go/plugins/bundled/gocd-yum-repository-poller-plugin.jar
2022-12-19 19:03:26,337 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished:
/go/plugins/bundled/gocd-yum-repository-poller-plugin.jar
2022-12-19 19:03:26,346 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting:
/go/plugins/external/abcd-gocd-generic-nexus-task-plugin-1.1.jar
2022-12-19 19:03:28,110 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished:
/go/plugins/external/abcd-gocd-generic-nexus-task-plugin-1.1.jar
2022-12-19 19:03:28,119 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting:
/go/plugins/external/abcd-gocd-nexus-task-plugin-1.6.jar
2022-12-19 19:03:30,554 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished:
/go/plugins/external/abcd-gocd-nexus-task-plugin-1.6.jar
2022-12-19 19:03:30,562 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting:
/go/plugins/external/gocd-git-path-material-plugin-2.2.0-164.jar
2022-12-19 19:03:33,363 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished:
/go/plugins/external/gocd-git-path-material-plugin-2.2.0-164.jar
2022-12-19 19:03:33,370 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting: /go/plugins/external/script-executor-0.3.0.jar
2022-12-19 19:03:35,825 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished: /go/plugins/external/script-executor-0.3.0.jar
2022-12-19 19:03:35,836 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting:
/go/plugins/external/abcd-gocd-nexus-material-plugin-1.1.jar
2022-12-19 19:03:38,530 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished:
/go/plugins/external/abcd-gocd-nexus-material-plugin-1.1.jar
2022-12-19 19:03:38,540 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting:
/go/plugins/external/abcd-gocd-nexus-component-task-plugin-1.2.jar
2022-12-19 19:03:42,754 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished:
/go/plugins/external/abcd-gocd-nexus-component-task-plugin-1.2.jar
2022-12-19 19:03:42,762 INFO [main] DefaultPluginJarChangeListener:67
- Plugin load starting:
/go/plugins/external/epcc-nexus-gocd-2.0-SNAPSHOT.jar
2022-12-19 19:03:46,231 INFO [main] DefaultPluginJarChangeListener:74
- Plugin load finished:
/go/plugins/external/epcc-nexus-gocd-2.0-SNAPSHOT.jar
2022-12-19 19:03:46,232 INFO [scheduler-1]
AgentHTTPClientController:139 - About to get cookie from the server.
What I observe is that some of your plugins are very slow to load and it's
taking about *20 seconds *to load all plugins into the agent which is the
main delay to start-up time. Builds cannot be scheduled (and the cookie
obtained) before all the plugins are loaded into the agent.
Several of them are taking 3-4 seconds to do so (seems to get slower over
time? - 330ms, 1.7s, 2.3s, 2.8s, 2.5s, 2.7s, 4.3s, 3.5s) and even very
basic ones are rather slow like script-executor-0.3.0.jar (which are
unlikely to do anything special during plugin initialisation). While I
haven't looked in detail at slow plugin loading before or compared to other
environments, you might want to consider:
- Remove/rationalise plugins that are not needed/used from your server.
- Some of these plugins appear to be custom ones you may have
built/written rather than community plugins, so I am unsure what they are
doing, how big they are, whether they are loading a lot of things into
memory or have huge numbers of dependencies inside them.
- Consider updating plugins to later versions on your server. Some
have had dependnencies rationalised and might make them quicker
to load if
the issue is with their raw size and dependencies. (script-executor,
git-path-material) You'd have to review that yourself for your custom
plugins.
- Each plugin has some logs specific to that plugin stored in the
logs dir. Often they dont log much, but perhaps worth looking to see
whether there are any hints at anything that is slow due to internals of
the plugin, rather than something the agent plugin infrastructure is doing.
- Consider whether the storage that is sitting behind
*/go/plugins/external* and your agent is slow and whether disk access
speed could be the bottleneck here. Plugins need to be downloaded, unpacked
and then loaded of this storage, whcih is effectively temporary (and has to
be done every startup) for an elastic agent, so you'll want it to be as
fast as possible.
- You might be able to also check whether the plugin *download* is slow
in earlier logs to see whether this is a possible area of investigation.
- Check the CPU usage during this 20 seconds to see what is happening
- does it look like the main thread is CPU limited, i.e constantly at 100%
during this plugin load time? Or garbage collection threads? This might
help determine whether the issue is likely to be I/O speed or something
more intrinsic to work required to load plugins.
- Try allocating a bigger memory/heap to your agent (both container
memory limits and JVM limits) and see if this changes the plugin load
speed. This might be relevant if your plugins are very large.
Hope that helps.
-Chad
On Tue, Dec 20, 2022 at 3:55 AM Veenu Official <[email protected]>
wrote:
> Please find the logs below, these are just "agent" logs I got from the
> container :
>
> 2022-12-19 19:03:22,364 INFO [main] ClassPathXmlApplicationContext:583 -
> Refreshing
> org.springframework.context.support.ClassPathXmlApplicationContext@74e52303:
> startup date [Mon Dec 19 19:03:22 UTC 2022]; root of context hierarchy
> 2022-12-19 19:03:22,398 INFO [main] XmlBeanDefinitionReader:317 - Loading
> XML bean definitions from class path resource [applicationContext.xml]
> 2022-12-19 19:03:22,677 INFO [main] XmlBeanDefinitionReader:317 - Loading
> XML bean definitions from class path resource
> [applicationContext-plugin-infra.xml]
> 2022-12-19 19:03:23,301 INFO [main] DefaultListableBeanFactory:821 -
> Overriding bean definition for bean 'pluginLoader' with a different
> definition: replacing [Generic bean: class
> [com.thoughtworks.go.plugin.infra.PluginLoader]; scope=singleton;
> abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0;
> autowireCandidate=true; primary=false; factoryBeanName=null;
> factoryMethodName=null; initMethodName=null; destroyMethodName=null;
> defined in URL
> [jar:onejar:lib/go-plugin-infra-22.1.0-13913.jar!/com/thoughtworks/go/plugin/infra/PluginLoader.class]]
> with [Generic bean: class [com.thoughtworks.go.plugin.infra.PluginLoader];
> scope=; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0;
> autowireCandidate=true; primary=false; factoryBeanName=null;
> factoryMethodName=null; initMethodName=null; destroyMethodName=null;
> defined in class path resource [applicationContext-plugin-infra.xml]]
> 2022-12-19 19:03:23,633 INFO [main]
> AutowiredAnnotationBeanPostProcessor:156 - JSR-330 'javax.inject.Inject'
> annotation found and supported for autowiring
> 2022-12-19 19:03:24,869 INFO [main] AgentStatusHttpd:90 - Agent status
> HTTP API server running on http://localhost:8152.
> 2022-12-19 19:03:24,954 INFO [main] AgentHTTPClientController:96 -
> Configured remoting type: RemotingClient
> 2022-12-19 19:03:24,972 INFO [main] ThreadPoolTaskScheduler:166 -
> Initializing ExecutorService 'scheduler'
> 2022-12-19 19:03:26,004 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting:
> /go/plugins/bundled/gocd-yum-repository-poller-plugin.jar
> 2022-12-19 19:03:26,185 INFO [scheduler-1] SslInfrastructureService:78 -
> [Agent Registration] Starting to register agent.
> 2022-12-19 19:03:26,185 INFO [scheduler-1] SslInfrastructureService:88 -
> [Agent Registration] Fetching token from server.
> 2022-12-19 19:03:26,193 INFO [scheduler-1] TokenRequester:56 - The server
> has generated token for the agent.
> 2022-12-19 19:03:26,195 INFO [scheduler-1] SslInfrastructureService:91 -
> [Agent Registration] Got a token from server.
> 2022-12-19 19:03:26,205 INFO [scheduler-1] SslInfrastructureService:170 -
> This agent is now approved by the server.
> 2022-12-19 19:03:26,205 INFO [scheduler-1] SslInfrastructureService:119 -
> [Agent Registration] Retrieved registration from Go server.
> 2022-12-19 19:03:26,237 INFO [scheduler-1] SslInfrastructureService:81 -
> [Agent Registration] Successfully registered agent.
> 2022-12-19 19:03:26,337 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished:
> /go/plugins/bundled/gocd-yum-repository-poller-plugin.jar
> 2022-12-19 19:03:26,346 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting:
> /go/plugins/external/abcd-gocd-generic-nexus-task-plugin-1.1.jar
> 2022-12-19 19:03:26,554 ERROR [scheduler-2] RemotingClient:166 - Server
> responded to action `ping` with: status[422 Unprocessable Entity], body[{
> "message" : "Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set; nested
> exception is com.thoughtworks.go.server.service.AgentNoCookieSetException:
> Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set"
> }]
> 2022-12-19 19:03:26,556 ERROR [scheduler-2] AgentHTTPClientController:114
> - Error occurred when agent tried to ping server:
> java.lang.RuntimeException:
> org.apache.http.client.ClientProtocolException: The server returned status
> code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:118)
> at
> com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
> at
> com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown
> Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
> Source)
> at java.base/java.lang.reflect.Method.invoke(Unknown Source)
> at
> org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
> at
> org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
> at
> java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown
> Source)
> at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown
> Source)
> at
> java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown
> Source)
> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown
> Source)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
> at java.base/java.lang.Thread.run(Unknown Source)
> Caused by: org.apache.http.client.ClientProtocolException: The server
> returned status code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at
> com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:114)
> ... 14 common frames omitted
> 2022-12-19 19:03:28,110 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished:
> /go/plugins/external/abcd-gocd-generic-nexus-task-plugin-1.1.jar
> 2022-12-19 19:03:28,119 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting:
> /go/plugins/external/abcd-gocd-nexus-task-plugin-1.6.jar
> 2022-12-19 19:03:30,554 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished:
> /go/plugins/external/abcd-gocd-nexus-task-plugin-1.6.jar
> 2022-12-19 19:03:30,562 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting:
> /go/plugins/external/gocd-git-path-material-plugin-2.2.0-164.jar
> 2022-12-19 19:03:31,564 ERROR [scheduler-2] RemotingClient:166 - Server
> responded to action `ping` with: status[422 Unprocessable Entity], body[{
> "message" : "Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set; nested
> exception is com.thoughtworks.go.server.service.AgentNoCookieSetException:
> Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set"
> }]
> 2022-12-19 19:03:31,564 ERROR [scheduler-2] AgentHTTPClientController:114
> - Error occurred when agent tried to ping server:
> java.lang.RuntimeException:
> org.apache.http.client.ClientProtocolException: The server returned status
> code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:118)
> at
> com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
> at
> com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown
> Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
> Source)
> at java.base/java.lang.reflect.Method.invoke(Unknown Source)
> at
> org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
> at
> org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
> at
> java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown
> Source)
> at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown
> Source)
> at
> java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown
> Source)
> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown
> Source)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
> at java.base/java.lang.Thread.run(Unknown Source)
> Caused by: org.apache.http.client.ClientProtocolException: The server
> returned status code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at
> com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:114)
> ... 14 common frames omitted
> 2022-12-19 19:03:33,363 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished:
> /go/plugins/external/gocd-git-path-material-plugin-2.2.0-164.jar
> 2022-12-19 19:03:33,370 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting: /go/plugins/external/script-executor-0.3.0.jar
> 2022-12-19 19:03:35,825 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished: /go/plugins/external/script-executor-0.3.0.jar
> 2022-12-19 19:03:35,836 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting:
> /go/plugins/external/abcd-gocd-nexus-material-plugin-1.1.jar
> 2022-12-19 19:03:36,571 ERROR [scheduler-2] RemotingClient:166 - Server
> responded to action `ping` with: status[422 Unprocessable Entity], body[{
> "message" : "Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set; nested
> exception is com.thoughtworks.go.server.service.AgentNoCookieSetException:
> Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set"
> }]
> 2022-12-19 19:03:36,571 ERROR [scheduler-2] AgentHTTPClientController:114
> - Error occurred when agent tried to ping server:
> java.lang.RuntimeException:
> org.apache.http.client.ClientProtocolException: The server returned status
> code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:118)
> at
> com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
> at
> com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown
> Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
> Source)
> at java.base/java.lang.reflect.Method.invoke(Unknown Source)
> at
> org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
> at
> org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
> at
> java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown
> Source)
> at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown
> Source)
> at
> java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown
> Source)
> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown
> Source)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
> at java.base/java.lang.Thread.run(Unknown Source)
> Caused by: org.apache.http.client.ClientProtocolException: The server
> returned status code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at
> com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:114)
> ... 14 common frames omitted
> 2022-12-19 19:03:38,530 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished:
> /go/plugins/external/abcd-gocd-nexus-material-plugin-1.1.jar
> 2022-12-19 19:03:38,540 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting:
> /go/plugins/external/abcd-gocd-nexus-component-task-plugin-1.2.jar
> 2022-12-19 19:03:41,578 ERROR [scheduler-2] RemotingClient:166 - Server
> responded to action `ping` with: status[422 Unprocessable Entity], body[{
> "message" : "Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set; nested
> exception is com.thoughtworks.go.server.service.AgentNoCookieSetException:
> Agent [Agent [3ba812767907, 172.17.0.2,
> d1330c5c-f60e-4de2-beca-bc21859ee99b, null]] has no cookie set"
> }]
> 2022-12-19 19:03:41,579 ERROR [scheduler-2] AgentHTTPClientController:114
> - Error occurred when agent tried to ping server:
> java.lang.RuntimeException:
> org.apache.http.client.ClientProtocolException: The server returned status
> code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:118)
> at
> com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
> at
> com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method)
> at
> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown
> Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
> Source)
> at java.base/java.lang.reflect.Method.invoke(Unknown Source)
> at
> org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
> at
> org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
> at
> java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown
> Source)
> at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown
> Source)
> at
> java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown
> Source)
> at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown
> Source)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
> at java.base/java.lang.Thread.run(Unknown Source)
> Caused by: org.apache.http.client.ClientProtocolException: The server
> returned status code 422. Possible reasons include:
> - This agent has been deleted from the configuration
> - This agent is pending approval
> - There is possibly a reverse proxy (or load balancer) that has been
> misconfigured. See
> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
> for details.
> at
> com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
> at com.thoughtworks.go.agent.RemotingClient.post
> (RemotingClient.java:114)
> ... 14 common frames omitted
> 2022-12-19 19:03:42,754 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished:
> /go/plugins/external/abcd-gocd-nexus-component-task-plugin-1.2.jar
> 2022-12-19 19:03:42,762 INFO [main] DefaultPluginJarChangeListener:67 -
> Plugin load starting: /go/plugins/external/epcc-nexus-gocd-2.0-SNAPSHOT.jar
> 2022-12-19 19:03:46,231 INFO [main] DefaultPluginJarChangeListener:74 -
> Plugin load finished: /go/plugins/external/epcc-nexus-gocd-2.0-SNAPSHOT.jar
> 2022-12-19 19:03:46,232 INFO [scheduler-1] AgentHTTPClientController:139
> - About to get cookie from the server.
> 2022-12-19 19:03:46,243 INFO [scheduler-1] AgentHTTPClientController:142
> - Got cookie: 0838ac28-be1e-4965-a6ca-833b2c2ba63b
> 2022-12-19 19:03:56,343 INFO [scheduler-1] HttpService:125 - Got back 200
> from server
> 2022-12-19 19:03:56,344 INFO [scheduler-1] DefaultGoPublisher:88 - Agent
> [3ba812767907, 172.17.0.2, d1330c5c-f60e-4de2-beca-bc21859ee99b] is
> reporting status [Preparing] to Go Server for Build
> [Q3UNIT-Infra-QA/9/GetNexusArtifact/37/GetNexusArtifact/142012]
> 2022-12-19 19:03:56,393 INFO [scheduler-1] HttpService:125 - Got back 200
> from server
> 2022-12-19 19:03:56,394 INFO [scheduler-1] DefaultGoPublisher:88 - Agent
> [3ba812767907, 172.17.0.2, d1330c5c-f60e-4de2-beca-bc21859ee99b] is
> reporting status [Building] to Go Server for Build
> [Q3UNIT-Infra-QA/9/GetNexusArtifact/37/GetNexusArtifact/142012]
> 2022-12-19 19:03:57,122 INFO [scheduler-1] HttpService:125 - Got back 200
> from server
> 2022-12-19 19:03:57,123 INFO [scheduler-1] DefaultGoPublisher:94 - Agent
> [3ba812767907, 172.17.0.2, d1330c5c-f60e-4de2-beca-bc21859ee99b] is
> reporting build result [Passed] to Go Server for Build
> [Q3UNIT-Infra-QA/9/GetNexusArtifact/37/GetNexusArtifact/142012]
> 2022-12-19 19:03:57,153 INFO [scheduler-1] HttpService:125 - Got back 200
> from server
> 2022-12-19 19:03:57,154 INFO [scheduler-1] DefaultGoPublisher:88 - Agent
> [3ba812767907, 172.17.0.2, d1330c5c-f60e-4de2-beca-bc21859ee99b] is
> reporting status [Completing] to Go Server for Build
> [Q3UNIT-Infra-QA/9/GetNexusArtifact/37/GetNexusArtifact/142012]
> 2022-12-19 19:03:57,180 INFO [scheduler-1] ArtifactsPublisher:68 -
> Pluggable metadata folder is empty.
> 2022-12-19 19:03:57,180 INFO [scheduler-1] DefaultGoPublisher:100 - Agent
> [3ba812767907, 172.17.0.2, d1330c5c-f60e-4de2-beca-bc21859ee99b] is
> reporting build result [Passed] to Go Server for Build
> [Q3UNIT-Infra-QA/9/GetNexusArtifact/37/GetNexusArtifact/142012]
> 2022-12-19 19:03:57,185 INFO [scheduler-1] HttpService:125 - Got back 200
> from server
> 2022-12-19 19:03:57,238 INFO [scheduler-1] DefaultGoPublisher:82 -
> Stopping Transmission for Build
> [Q3UNIT-Infra-QA/9/GetNexusArtifact/37/GetNexusArtifact/142012]
>
>
> On Monday, December 19, 2022 at 8:46:30 AM UTC-6 Veenu Official wrote:
>
>> Thank you so much Chad. I will analyse the logs /godata/logs/agent.log
>> and get back to you soon.
>>
>> On Saturday, December 17, 2022 at 10:37:18 PM UTC-6 Chad Wilson wrote:
>>
>>> Hi
>>>
>>> I haven't looked into your specific case in detail (there's not enough
>>> logging here as it is), however the general challenge of "ensure elastic
>>> agent startup time is as optimal as possible" is one I am interested in
>>> improving, especially with some help from the community in figuring out
>>> what is happening.
>>>
>>> In 22.3.0 I made a change to reduce some redundant sleeps
>>> <https://github.com/gocd/gocd/pull/10759/commits/41d67fa7b4d9618ee50c35739af62400824a534c>
>>> specific to when the agent needs to update the version to synchronize with
>>> the server at startup (very common for elastic agents, which tend to not
>>> have any persistent storage to cache the up-to-date agent launcher and jar
>>> versions), however that doesn't specifically deal with the errors below
>>> where the agent tries to negotiate with the server to become authorised. It
>>> might take 20s in "total" time" with earlier versions, but I don't think
>>> you should see those "no cookie set" errors for *all* of those 20
>>> seconds, if working correctly - perhaps just one at the end.
>>>
>>> The *ping* operation is independent of the main loop that retrieves
>>> work and ensures the cookie is present, so it's conceptually possible you
>>> can get some of these *ping *errors during startup before it has fully
>>> registered and retrieved the cookie, but not exactly sure what is going on
>>> there.
>>>
>>> To understand further, you might want to look at the fuller logs from an
>>> agent's perspective. IIRC not all the logs that might be useful will be
>>> seen in the agent's stdout, but you should be able to see the fuller
>>> lifecycle of what is happening from the agent's perspective inside the
>>> /godata/logs/agent.log (if running as a container) which should show which
>>> part of the start-up and work loop the agent is working on. If you can
>>> build a timeline of important events we can probably figure out what is
>>> going on and the right bits to be optimised.
>>>
>>> -Chad
>>>
>>> On Fri, Dec 16, 2022 at 11:53 PM Veenu Official <[email protected]>
>>> wrote:
>>>
>>>> We have these errors coming up on Elastic Agent Container Start up and
>>>> it occurs 4 times or more. Every time it takes 5 seconds and then it is a
>>>> loop of 5 seconds for 4 times, so we are trying to optimize the time by
>>>> getting rid of these errors.
>>>>
>>>> Please let me know if anyone has been able to resolve these errors. It
>>>> would be greatly helpful.
>>>>
>>>>
>>>>
>>>> 2022-12-13T09:20:50.605-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - 2022-12-13 15:20:50,583 ERROR [scheduler-2] RemotingClient:166 -
>>>> Server responded to action `ping` with: status[422 Unprocessable Entity],
>>>> body[{
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - "message" : "Agent [Agent [d1c6f1714063, 172.17.0.3,
>>>> 50392830-07ba-4475-8061-67293edd1015, null]] has no cookie set; nested
>>>> exception is com.thoughtworks.go.server.service.AgentNoCookieSetException:
>>>> Agent [Agent [d1c6f1714063, 172.17.0.3,
>>>> 50392830-07ba-4475-8061-67293edd1015, null]] has no cookie set"
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - }]
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - 2022-12-13 15:20:50,584 ERROR [scheduler-2]
>>>> AgentHTTPClientController:114 - Error occurred when agent tried to ping
>>>> server:
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - java.lang.RuntimeException:
>>>> org.apache.http.client.ClientProtocolException: The server returned status
>>>> code 422. Possible reasons include:
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - - This agent has been deleted from the configuration
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - - This agent is pending approval
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - - There is possibly a reverse proxy (or load balancer) that has
>>>> been misconfigured. See
>>>> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
>>>> for details.
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at com.thoughtworks.go.agent.RemotingClient.post
>>>> (RemotingClient.java:118)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> com.thoughtworks.go.agent.RemotingClient.ping(RemotingClient.java:74)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> com.thoughtworks.go.agent.AgentHTTPClientController.ping(AgentHTTPClientController.java:109)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native
>>>> Method)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown
>>>> Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
>>>> Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at java.base/java.lang.reflect.Method.invoke(Unknown Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown
>>>> Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown
>>>> Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown
>>>> Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,584
>>>> [stdout] - at
>>>> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - at
>>>> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown
>>>> Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - at java.base/java.lang.Thread.run(Unknown Source)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - Caused by: org.apache.http.client.ClientProtocolException: The
>>>> server returned status code 422. Possible reasons include:
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - - This agent has been deleted from the configuration
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - - This agent is pending approval
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - - There is possibly a reverse proxy (or load balancer) that has
>>>> been misconfigured. See
>>>> https://docs.gocd.org/22.1.0/installation/configure-reverse-proxy.html#agents-and-reverse-proxies
>>>> for details.
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - at
>>>> com.thoughtworks.go.agent.RemotingClient.validateResponse(RemotingClient.java:141)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - at com.thoughtworks.go.agent.RemotingClient.post
>>>> (RemotingClient.java:114)
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:50,585
>>>> [stdout] - ... 14 common frames omitted
>>>> 2022-12-13T09:20:51.811-06:00 jvm 1 | 2022-12-13 15:20:51,714
>>>> [stdout] - 2022-12-13 15:20:51,713 INFO [main]
>>>> DefaultPluginJarChangeListener:74 - Plugin load finished:
>>>> /go/plugins/external/epsilon-gocd-nexus-component-task-plugin-1.2.jar
>>>> 2022-12-13T09:21:06.760-06:00 jvm 1 | 2022-12-13 15:20:51,724
>>>> [stdout] - 2022-12-13 15:20:51,724 INFO [main] Defaul
>>>> No newer events at this moment. Auto retrying...
>>>> Pause
>>>>
>>>> --
>>>> You received this message because you are subscribed to the Google
>>>> Groups "go-cd" group.
>>>> To unsubscribe from this group and stop receiving emails from it, send
>>>> an email to [email protected].
>>>> To view this discussion on the web visit
>>>> https://groups.google.com/d/msgid/go-cd/6f655dc5-fd6a-4fa5-8272-0bc2b1799413n%40googlegroups.com
>>>> <https://groups.google.com/d/msgid/go-cd/6f655dc5-fd6a-4fa5-8272-0bc2b1799413n%40googlegroups.com?utm_medium=email&utm_source=footer>
>>>> .
>>>>
>>> --
> You received this message because you are subscribed to the Google Groups
> "go-cd" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to [email protected].
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/go-cd/e8ff3aca-ccc8-41cb-a2d1-3b2db5818895n%40googlegroups.com
> <https://groups.google.com/d/msgid/go-cd/e8ff3aca-ccc8-41cb-a2d1-3b2db5818895n%40googlegroups.com?utm_medium=email&utm_source=footer>
> .
>
--
You received this message because you are subscribed to the Google Groups
"go-cd" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/go-cd/CAA1RwH_f%2Bq_Y-23C78RRMxydkZgbUdv2yX8FCKNXi6UgWrDn_w%40mail.gmail.com.
