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/e300bf1d-1d9c-46d9-bade-3b490cb8782cn%40googlegroups.com.
