Hi there Sorry for the delayed reply, hadn't got around to digging into this a bit. Few observations from the log/files.
1. The initial agent bootstrap is taking about 5-6 seconds. This isn't terrible, but the dockerfile you attached says the agent bootstrapper is *21*.1.0 even though your server is 22.1.0. This will be faster if your agent bootstrapper matches, or is closer to the server version. Your Dockerfile also seems to be copy+pasted from an old version of https://github.com/gocd/docker-gocd-agent-centos-7/blob/master/Dockerfile and then customised. It would probably be better to build on top of the pre-built GoCD agent images published to Dockerhub (*FROM gocd/gocd-agent-centos-7:v22.1.0* etc) rather than copy and paste all the instructions - to make it easier to update periodically. Not sure how often you rebuild, but that is likely rather old and I would suggest you rebuild on something more recent. 2. Hacking the relaunch time is happening because your agent is needing to update (version mismatch mentioned above). Additionally, you probably don't need to hack the relaunch time if you update to 22.3.0 - that's the tweak I made to relaunch immediately on version updates. 3. Your plugin loads are still very slow (18s overall). This is not normal and I have not seen it so slow before. I suspect something is amiss with the container or host, but there's not enough information to know. Looks like you are allocating 2 cores to the agent in the elastic profile. Does it improve massively if you allocate more? Again, I would try a more detailed level of inspection of what is going on within your ECS instance when the agent comes up. Try creating an agent in a different environment (e.g just running locally) with the same set of plugins. Are the plugin loads also slow in a simpler environment? 4. Are you using the ECS optimized AMIs from Amazon or something custom/proprietary? You could try updating them. If it's the latter, you might need to dig yourself into what is happening. 5. There are some more tips at https://github.com/gocd/gocd/issues/11215#issuecomment-1397268015 for reducing the amount of time it takes for the agent to start doing work (you will likely see a 10 second gap after it first tries to get work before a second attempt by default). -Dgocd.agent.extra.properties=agent.get.work.interval=1000 will reduce this to 1s - but please read the caveats for this on the GitHub issue above. 6. Your server looks reasonably big in number of pipelines and materials, but you seem to have the default memory allocated to it (1G max). You might get a better experience with more memory available to the server. Doesn't seem to be the main issue with the agent start-up speed, but might be contributing to other slowness. Overall, your agent just looks sluggish though, so there is a bigger challenge than tweaks to sleeps/polling within GoCD logic. -Chad On Thu, Jan 5, 2023 at 11:33 AM Veenu Official <veenuofficial...@gmail.com> wrote: > Hi Chad, > > Took some time to gather all the info. > Please take a look at the files attached. > > I tried loading less plugins, but the test GoCD environment my Operations > team has created gives very inconsistent timings, so that is not helping me > to test with selective plugin loading. > I would may be try upgrading to new GoCD in the new test environment but > that is another team so will have to wait till I get approval. > > Also as you mentioned, how do we increase disk speed and network speed, I > could see only CPU and memory in the Elastic Profile. > > Really appreciate your time and inputs. Thanks ! > Veenu > > On Tuesday, January 3, 2023 at 8:28:04 PM UTC-6 Chad Wilson wrote: > >> Hi Veenu >> >> >> - What type of elastic agents are these? ECS? Kubernetes? Something >> else? >> - From your description, it *sounds like* the ECS one. If so, the >> config you are referring to on the cluster profile keeps *instances >> (VMs)* online within the cluster, but individual containers and >> thus agent processes are not re-used, they are always booted clean and >> bootstrapped from the server for each job - either on an existing >> instance, >> or a new instance if there aren't enough resources.* You're right, >> it is ECS. Thanks for the information. I wish we could re-use agent and >> that would save us a lot of time spent in bootstrapping a new one each >> time. * >> - Which specific agent container image and version are you using? >> (your server is 22.1.0 I believe) *Yes 22.1.0, attached Dockerfile >> and docker-entrypoint.sh* >> - Might help if you share a (redacted) output from /go/api/support >> so we are not guessing about your server configuration, plugin versions >> etc. *Attached* >> - And share your elastic agent cluster profile and elastic profile >> configuration. *Attached* >> - Are you able to share what you did to address the weird >> unexplained plugin delays noted earlier? >> - Which suggested steps have you taken or not taken? *CPU >> monitoring on the ECS instances running the container is usually >> 15-20%.* >> - How long are all the plugin loads taking from start -> finish >> *now* - the same as before? *I would say same as before.* >> - Did you try increasing the container level resources available >> to the agent container (CPU or memory limits)? *Increased JVM on >> the container for both agent-bootstrapper and agent jar. (-Xms1024m >> -Xmx2g) This looks like has helped with couple of seconds I feel.* >> - How are you measuring the 46 seconds? >> - What are the start/complete times you are considering? From the >> perspective of the server? What is "Complete"? When the agent reports >> as >> online in the logs on the server agent console and starts executing >> tasks? * >> Yes agent bootup time as reported on the Go CD server, ready to execute >> tasks* >> - Please share a representative breakdown/timeline of the time >> spent doing various steps, from server initiating agent creation, to >> when >> the agent reports as online. It's difficult to give anything but >> generic >> suggestions unless you share the methodology for measurement and the >> data >> you've collected, based on which logging. *Attached both server >> logs and Agent container logs* >> - Additional logging is a bit of a pain to configure on elastic >> agents. The generic detail is at >> https://docs.gocd.org/current/advanced_usage/logging.html however for >> containers this generally means mounting some logging config file >> overrides >> into /godata/config which is not so easy (personally I haven't done it for >> agents, so would be doing trial+error also). To reiterate, debug logs on >> their own are not likely to tell us the major constraint without >> considering other metrics on resources. *Thanks for the info. * >> >> -Chad >> >> On Wed, Jan 4, 2023 at 5:01 AM Veenu Official <veenuoff...@gmail.com> >> wrote: >> >>> Hi Chad, >>> >>> Wishing you a happy new year! >>> >>> For some reason, we always have a new agent spinning up for each Stage >>> (instead of picking a running agent), even if multiple stages are using the >>> same Elastic Profile. Even though we have number of minimum Running agents >>> as 10 for elastic agents cluster profile, our next stage (that uses the >>> same Elastic profile for the agent container) is always spinning up a new >>> agent instead of picking up a running agent. Is there a flag to set up to >>> not stop an agent container when it is done with a stage? >>> As of now, for us each stage with elastic agent still takes around 46 >>> seconds to launch an agent even after increasing JVM startup arguments, >>> reducing the relaunch time from 10 sec to 200 ms, please suggest. >>> >>> Also, where do we set the logging to debug level ? >>> >>> Thanks, >>> Veenu >>> On Wednesday, December 21, 2022 at 2:33:17 PM UTC-6 Veenu Official wrote: >>> >>>> I got that information on chat.openai.com :) I could not find the >>>> actual source though! >>>> I was trying to see if a Go Agent can load selective plugins instead of >>>> picking everything under the Go server folders /plugins/bundled and >>>> /plugins/external. >>>> >>>> Anyways, thanks for all your inputs. >>>> >>>> >>>> >>>> On Tuesday, December 20, 2022 at 11:20:20 PM UTC-6 Chad Wilson wrote: >>>> >>>>> If you have a random two minute gap, it points to a general slowness >>>>> in your agent, maybe not just plugin loads. There are lots of things that >>>>> are happening in start-up there inside the JVM, but they shouldn't take >>>>> two >>>>> minutes unless your agent has some resource constraints (slow disk, CPU >>>>> etc). I would focus in these more general areas as it looks like plugin >>>>> load time isn't the sole problem here. >>>>> >>>>> You could increase the logging to DEBUG level but it will be very >>>>> noisy so not sure how much you will get out of it without detailed >>>>> knowledge of GoCD internals, spring applications etc. >>>>> >>>>> I'm not sure where you read about PLUGIN_LOCATOR - could you share >>>>> where this is documented/shared? I am not familiar with this capability >>>>> and >>>>> have never used it, but maybe it exists. :-) In any case, if you have >>>>> other >>>>> random slowness, in "non plugin-load" parts of the start-up your effort is >>>>> probably better spent looking there at the standard resource constraints >>>>> for software - disk speed, CPU, memory, network speed. >>>>> >>>>> -Chad >>>>> >>>>> On Wed, Dec 21, 2022 at 3:18 AM Veenu Official <veenuoff...@gmail.com> >>>>> wrote: >>>>> >>>>>> 1. While testing on a new environment, we are also seeing 2 minutes >>>>>> in the logs to just configure RemotingType, do you know what can be the >>>>>> reason for that? >>>>>> >>>>>> >>>>>> 2022-12-20 16:46:39,192 INFO [main] >>>>>> AutowiredAnnotationBeanPostProcessor:156 - JSR-330 'javax.inject.Inject' >>>>>> annotation found and supported for autowiring >>>>>> 2022-12-20 16:46:40,448 INFO [main] AgentStatusHttpd:90 - Agent >>>>>> status HTTP API server running on http://localhost:8152. >>>>>> >>>>>> 2022-12-20 16:48:50,532 INFO [main] AgentHTTPClientController:96 - >>>>>> Configured remoting type: RemotingClient >>>>>> 2022-12-20 16:48:50,548 INFO [main] ThreadPoolTaskScheduler:166 - >>>>>> Initializing ExecutorService 'scheduler' >>>>>> 2022-12-20 16:48:51,098 INFO [main] >>>>>> DefaultPluginJarChangeListener:67 - Plugin load starting: >>>>>> /go/plugins/bundled/gocd-yum-repository-poller-plugin.jar >>>>>> 2022-12-20 16:48:51,420 INFO [main] >>>>>> DefaultPluginJarChangeListener:74 - Plugin load finished: >>>>>> /go/plugins/bundled/gocd-yum-repository-poller-plugin.jar >>>>>> >>>>>> >>>>>> >>>>>> 2. Also, while reading how to limit the number of plugins being >>>>>> loaded by an agent, I came across this suggestion, do you also think it >>>>>> is >>>>>> a good idea to configure: >>>>>> >>>>>> Can Go CD agent load only few plugins as compared to all plugins from >>>>>> Go CD Server >>>>>> >>>>>> >>>>>> >>>>>> Yes, a Go CD agent can be configured to load only a subset of the >>>>>> plugins that are available on the Go CD server. This can be useful if you >>>>>> have a large number of plugins installed on the server and you only want >>>>>> a >>>>>> specific set of plugins to be available on the agent. >>>>>> >>>>>> To configure an agent to load only specific plugins, you can use the >>>>>> PLUGIN_LOCATOR environment variable when starting the agent. The >>>>>> PLUGIN_LOCATOR variable specifies the path to a JSON file that lists the >>>>>> plugins that should be loaded by the agent. The JSON file should contain >>>>>> an >>>>>> array of plugin IDs, with each ID corresponding to a plugin that is >>>>>> installed on the Go CD server. >>>>>> >>>>>> For example, if you have the following JSON file: >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> [ "github.com/gocd-contrib/gocd-json-config-plugin", " >>>>>> github.com/gocd-contrib/gocd-yaml-config-plugin"] >>>>>> >>>>>> Then the agent will only load the gocd-json-config-plugin and >>>>>> gocd-yaml-config-plugin plugins, even if there are other plugins >>>>>> available >>>>>> on the Go CD server. >>>>>> >>>>>> It's also possible to use wildcards in the plugin IDs to load >>>>>> multiple plugins at once. For example, the following JSON file will load >>>>>> all plugins that start with github.com/gocd-contrib/gocd-: >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> [ "github.com/gocd-contrib/gocd-*"] >>>>>> >>>>>> Note that the PLUGIN_LOCATOR variable only affects the plugins that >>>>>> are loaded by the agent. It does not affect the plugins that are >>>>>> available >>>>>> on the Go CD server, or the plugins that are loaded by other agents. >>>>>> >>>>>> On Tuesday, December 20, 2022 at 9:00:32 AM UTC-6 Veenu Official >>>>>> wrote: >>>>>> >>>>>>> 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 < >>>>>>>> veenuoff...@gmail.com> 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 < >>>>>>>>>>> veenuoff...@gmail.com> 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 go-cd+un...@googlegroups.com. >>>>>>>>>>>> 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 go-cd+un...@googlegroups.com. >>>>>>>>> >>>>>>>> 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 go-cd+un...@googlegroups.com. >>>>>> >>>>> To view this discussion on the web visit >>>>>> https://groups.google.com/d/msgid/go-cd/633c01a9-1ee7-47a3-b94c-0e94f519295bn%40googlegroups.com >>>>>> <https://groups.google.com/d/msgid/go-cd/633c01a9-1ee7-47a3-b94c-0e94f519295bn%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 go-cd+un...@googlegroups.com. >>> >> To view this discussion on the web visit >>> https://groups.google.com/d/msgid/go-cd/185f8f78-53e2-45e8-b073-25f2adb7e9e1n%40googlegroups.com >>> <https://groups.google.com/d/msgid/go-cd/185f8f78-53e2-45e8-b073-25f2adb7e9e1n%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 go-cd+unsubscr...@googlegroups.com. > To view this discussion on the web visit > https://groups.google.com/d/msgid/go-cd/5254f871-ef87-416a-adfb-ce9827d53048n%40googlegroups.com > <https://groups.google.com/d/msgid/go-cd/5254f871-ef87-416a-adfb-ce9827d53048n%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 go-cd+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/go-cd/CAA1RwH9LTUVf_NVgt7Qam2dUK_v7UVTq4vn3y_zo_2S0LiRU_g%40mail.gmail.com.
