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/CAA1RwH8cD%2BrxcOrV_LmsTtxKMTVHJ6nLWO2kg73CybzjmKSSNQ%40mail.gmail.com.
