Thank you so much Chad. Those points are really helpful. I will go through the list of recommendations and see where we can optimize.
-Veenu On Monday, December 19, 2022 at 8:59:21 PM UTC-6 Chad Wilson wrote: > 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/6a8695dc-61d8-48e4-9032-71e4d4ec201en%40googlegroups.com.
