Agent can't find all plugins when building with Docker elastic agent

[tomekgajdos]

Issue Type

Bug Report

Summary

The build fails with error: "Did not find 'task' plugin with id 'script-executor'. Looks like plugin is missing".

I added new task after script-executor task to check the content of plugin folders. When task script-executor fails then content of '/go/plugins/external/' and '/go/plugins_work/' differs (in case error for missing plugin is not thrown then content is the same). Folder '/go/plugins_work/' does not contain all the plugins. So the agent begins executing work, while the plugin initialisation has not completed. Seems the fix for #2872 does not catch all usecases.

Console:

[go] Task: Plugin with ID: script-executortook: 0.5s
    Error: Did not find 'task' plugin with id 'script-executor'. Looks like plugin is missing
    [go] Task status: failed, took: 0.5s

[go] Task: /bin/bash -c "ls -la /go/plugins/external/; ls -la /go/plugins_work/"took: 0.111s
    total 44772
    drwxr-xr-x    2 go       go            4096 Sep 14 13:38 .
    drwxr-xr-x    4 go       go            4096 Sep 14 13:38 ..
    -rw-r--r--    1 go       go         3708821 Sep 14 13:38 go-artifactory-pkg-plugin-0.9.jar
    -rw-r--r--    1 go       go         3709867 Sep 14 13:38 go-artifactory-scm-plugin-0.9.jar
    -rw-r--r--    1 go       go         4408963 Sep 14 13:38 go-maven-poller.jar
    -rw-r--r--    1 go       go         7925950 Sep 14 13:38 go-plugin-groovy-1.0.1.jar
    -rw-r--r--    1 go       go         8141908 Sep 14 13:38 gocd-git-path-material-plugin-1.2.3.jar
    -rw-r--r--    1 go       go         4301907 Sep 14 13:38 gocd-health-check-plugin-1.0.2.jar
    -rw-r--r--    1 go       go         6414493 Sep 14 13:38 gocd-sonar-qualitygates-plugin-2.0.0.jar
    -rw-r--r--    1 go       go         1184988 Sep 14 13:38 script-executor-0.3.0.jar
    -rw-r--r--    1 go       go         6018549 Sep 14 13:38 stash-pr-poller-1.3.4.jar
    total 36
    drwxr-xr-x    8 go       go            4096 Sep 14 13:38 .
    drwxr-xr-x    6 go       go            4096 Sep 14 13:38 ..
    drwxr-xr-x    5 go       go            4096 Sep 14 13:38 go-artifactory-scm-plugin-0.9.jar
    drwxr-xr-x    7 go       go            4096 Sep 14 13:38 go-maven-poller.jar
    drwxr-xr-x    5 go       go            4096 Sep 14 13:38 go-plugin-groovy-1.0.1.jar
    drwxr-xr-x    6 go       go            4096 Sep 14 13:38 gocd-sonar-qualitygates-plugin-2.0.0.jar
    drwxr-xr-x    5 go       go            4096 Sep 14 13:38 gocd-yum-repository-poller-plugin.jar
    drwxr-xr-x    6 go       go            4096 Sep 14 13:38 stash-pr-poller-1.3.4.jar
    [go] Task status: passed, took: 0.111s

[go] Current job status: failed

Environment

Basic environment details

Go Version: 18.8.0
Docker Elastic Agent Plugin Version: 3.0.1-116
Script Executor Plugin Version: 0.3.0

Expected Results

Plugin with id 'script-executor' is not missing and works fine.

Actual Results

Plugin with id 'script-executor' is missing and pipeline fails.

Log snippets

created directory: '/godata/config',
'/go/config' -> '/godata/config',
created directory: '/godata/logs',
'/go/logs' -> '/godata/logs',
created directory: '/godata/pipelines',
'/go/pipelines' -> '/godata/pipelines',
'/go-agent/config/agent-bootstrapper-logback-include.xml' -> '/go/config/agent-bootstrapper-logback-include.xml',
'/go-agent/config/agent-launcher-logback-include.xml' -> '/go/config/agent-launcher-logback-include.xml',
'/go-agent/config/agent-logback-include.xml' -> '/go/config/agent-logback-include.xml',
/docker-entrypoint.sh: Creating directories and symlinks to hold GoCD configuration, data, and logs,
$ mkdir /go,
$ chown go:go /go,
$ mkdir /godata,
$ chown go:go /go,
$ mkdir -v /godata/config,
$ chown go:go /godata/config,
$ ln -sv /godata/config /go/config,
$ chown go:go /go/config,
$ mkdir -v /godata/logs,
$ chown go:go /godata/logs,
$ ln -sv /godata/logs /go/logs,
$ chown go:go /go/logs,
$ mkdir -v /godata/pipelines,
$ chown go:go /godata/pipelines,
$ ln -sv /godata/pipelines /go/pipelines,
$ chown go:go /go/pipelines,
$ cp -rfv /go-agent/config/agent-bootstrapper-logback-include.xml /go/config/agent-bootstrapper-logback-include.xml,
$ chown go:go /godata/config/agent-bootstrapper-logback-include.xml,
$ cp -rfv /go-agent/config/agent-launcher-logback-include.xml /go/config/agent-launcher-logback-include.xml,
$ chown go:go /godata/config/agent-launcher-logback-include.xml,
$ cp -rfv /go-agent/config/agent-logback-include.xml /go/config/agent-logback-include.xml,
$ chown go:go /godata/config/agent-logback-include.xml,
$ chown go:go /go/config/autoregister.properties,
/docker-entrypoint.sh: Running custom scripts in /docker-entrypoint.d/ ...,
$ exec /usr/local/sbin/tini -- /usr/local/sbin/gosu go /docker-entrypoint.sh /go-agent/agent.sh,
$ exec /go-agent/agent.sh,
[Fri Sep 14 08:51:24 GMT 2018] Starting process: ,
[Fri Sep 14 08:51:24 GMT 2018]   Working directory    : /go,
[Fri Sep 14 08:51:24 GMT 2018]   Application arguments: [-serverUrl, https://pr-gocd-server:8154/go],
[Fri Sep 14 08:51:24 GMT 2018]            GoCD Version: 18.8.0-7433,
Could not find file `config/agent-bootstrapper-logback.xml'. Attempting to load from classpath.,
Using classpath resource `jar:onejar:lib/agent-bootstrapper-18.8.0-7433-classes.jar!/config/agent-bootstrapper-logback.xml'.,
2018-09-14 08:51:25,011 INFO  [main] DefaultAgentLauncherCreatorImpl:67 - Attempting to load com.thoughtworks.go.agent.launcher.AgentLauncherImpl as specified by manifest key Go-Agent-Launcher-Class,
2018-09-14 08:51:25,019 INFO  [main] ParentClassAccessFilteringClassloader:44 - Loading com.thoughtworks.cruise.agent.common.launcher.AgentLauncher using java.net.URLClassLoader,
SLF4J: Class path contains multiple SLF4J bindings.,
SLF4J: Found binding in [jar:onejar:lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class],
SLF4J: Found binding in [jar:file:/go/data/deps-ec042580dd6d8c66-agent-launcher.jar/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class],
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.,
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder],
2018-09-14 08:51:25,059 INFO  [main] AgentBootstrapper:77 - Attempting create and start launcher...,
2018-09-14 08:51:25,066 INFO  [main] ParentClassAccessFilteringClassloader:44 - Loading com.thoughtworks.cruise.agent.common.launcher.AgentLaunchDescriptor using java.net.URLClassLoader,
Could not find file `config/agent-launcher-logback.xml'. Attempting to load from classpath.,
Using classpath resource `jar:file:/go/data/deps-ec042580dd6d8c66-agent-launcher.jar/agent-launcher-18.8.0-7433-classes.jar!/config/agent-launcher-logback.xml'.,
2018-09-14 08:51:25,160 INFO  [TouchLoopThread-1] Lockfile:102 - Using lock file: /go/.agent-bootstrapper.running,
2018-09-14 08:51:25,668 INFO  [main] ServerBinaryDownloader:106 - Downloading agent.jar,
2018-09-14 08:51:25,708 INFO  [main] ServerBinaryDownloader:113 - Got server response,
2018-09-14 08:51:26,191 INFO  [main] ServerBinaryDownloader:121 - Piped the stream to admin/agent,
2018-09-14 08:51:26,193 INFO  [main] PerfTimer:53 - Performance: Downloading new admin/agent with md5 signature: c3699c3fa9089a211b63e97c977c5510 took 525ms,
2018-09-14 08:51:26,421 INFO  [main] AgentProcessParentImpl:51 - Agent is version: 18.8.0-7433,
2018-09-14 08:51:26,593 INFO  [main] ServerBinaryDownloader:106 - Downloading agent-plugins.zip,
2018-09-14 08:51:26,621 INFO  [main] ServerBinaryDownloader:113 - Got server response,
2018-09-14 08:51:27,537 INFO  [main] ServerBinaryDownloader:121 - Piped the stream to admin/agent-plugins.zip,
2018-09-14 08:51:27,537 INFO  [main] PerfTimer:53 - Performance: Downloading new admin/agent-plugins.zip with md5 signature: 94b1234195cd3d48d2d2ae757c56dbb5 took 944ms,
2018-09-14 08:51:27,561 INFO  [main] ServerBinaryDownloader:106 - Downloading tfs-impl.jar,
2018-09-14 08:51:27,587 INFO  [main] ServerBinaryDownloader:113 - Got server response,
2018-09-14 08:51:27,877 INFO  [main] ServerBinaryDownloader:121 - Piped the stream to admin/tfs-impl.jar,
2018-09-14 08:51:27,879 INFO  [main] PerfTimer:53 - Performance: Downloading new admin/tfs-impl.jar with md5 signature: e2e3dd243fce393bf8d20ba743650351 took 317ms,
2018-09-14 08:51:27,886 INFO  [main] AgentProcessParentImpl:69 - Launching Agent with command: /usr/lib/jvm/java-1.8-openjdk/jre/bin/java -Dcruise.console.publish.interval=10 -Xms128m -Xmx256m -Dgo.console.stdout=true -Djava.security.egd=file:/dev/./urandom -Dagent.plugins.md5=94b1234195cd3d48d2d2ae757c56dbb5 -Dagent.binary.md5=c3699c3fa9089a211b63e97c977c5510 -Dagent.launcher.md5=9d1651f877efbca068ed3fdcc6f1da3a -Dagent.tfs.md5=e2e3dd243fce393bf8d20ba743650351 -jar agent.jar -serverUrl https://pr-gocd-server:8154/go -sslVerificationMode NONE,
2018-09-14 08:51:28,116 [stderr] - [Fri Sep 14 08:51:28 GMT 2018] Starting process: ,
2018-09-14 08:51:28,116 [stderr] - [Fri Sep 14 08:51:28 GMT 2018]   Working directory    : /go,
2018-09-14 08:51:28,116 [stderr] - [Fri Sep 14 08:51:28 GMT 2018]   Application arguments: [-serverUrl, https://pr-gocd-server:8154/go, -sslVerificationMode, NONE],
2018-09-14 08:51:28,116 [stderr] - [Fri Sep 14 08:51:28 GMT 2018]            GoCD Version: 18.8.0-7433,
2018-09-14 08:51:28,529 [stderr] - Could not find file `config/agent-logback.xml'. Attempting to load from classpath.,
2018-09-14 08:51:28,529 [stderr] - Using classpath resource `jar:onejar:lib/agent-18.8.0-7433-classes.jar!/config/agent-logback.xml'.,
2018-09-14 08:51:28,723 [stdout] - 2018-09-14 08:51:28,720 INFO  [main] ClassPathXmlApplicationContext:583 - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@462d5aee: startup date [Fri Sep 14 08:51:28 GMT 2018]; root of context hierarchy,
2018-09-14 08:51:28,766 [stdout] - 2018-09-14 08:51:28,766 INFO  [main] XmlBeanDefinitionReader:317 - Loading XML bean definitions from class path resource [applicationContext.xml],
2018-09-14 08:51:28,987 [stdout] - 2018-09-14 08:51:28,986 INFO  [main] XmlBeanDefinitionReader:317 - Loading XML bean definitions from class path resource [applicationContext-plugin-infra.xml],
2018-09-14 08:51:29,570 [stdout] - 2018-09-14 08:51:29,570 INFO  [main] AutowiredAnnotationBeanPostProcessor:155 - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring,
2018-09-14 08:51:30,141 [stdout] - 2018-09-14 08:51:30,139 INFO  [main] AgentStatusHttpd:91 - Agent status HTTP API server running on http://localhost:8152.,
2018-09-14 08:51:30,334 [stdout] - 2018-09-14 08:51:30,333 INFO  [main] AgentControllerFactory:120 - Connecting to server using HTTP(S),
2018-09-14 08:51:30,373 [stdout] - 2018-09-14 08:51:30,373 INFO  [main] ThreadPoolTaskScheduler:165 - Initializing ExecutorService  'scheduler',
2018-09-14 08:51:31,606 [stdout] - 2018-09-14 08:51:31,605 INFO  [scheduler-1] SslInfrastructureService:98 - [Agent Registration] Starting to register agent.,
2018-09-14 08:51:31,606 [stdout] - 2018-09-14 08:51:31,606 INFO  [scheduler-1] SslInfrastructureService:108 - [Agent Registration] Fetching token from server.,
2018-09-14 08:51:31,618 [stdout] - 2018-09-14 08:51:31,617 INFO  [scheduler-1] TokenRequester:58 - The server has generated token for the agent.,
2018-09-14 08:51:31,618 [stdout] - 2018-09-14 08:51:31,618 INFO  [scheduler-1] SslInfrastructureService:111 - [Agent Registration] Got a token from server.,
2018-09-14 08:51:32,045 [stdout] - 2018-09-14 08:51:32,044 INFO  [scheduler-1] SslInfrastructureService:210 - This agent is now approved by the server.,
2018-09-14 08:51:32,124 [stdout] - 2018-09-14 08:51:32,123 INFO  [scheduler-1] SslInfrastructureService:140 - [Agent Registration] Retrieved registration from Go server.,
2018-09-14 08:51:32,130 [stdout] - 2018-09-14 08:51:32,129 INFO  [scheduler-1] SslInfrastructureService:148 - [Agent Registration] Stored registration for cert with hash code: 9a72387a925a56c26529d7a2775e6c119a6a03dc12d869d5d58eb1389304ac83 not valid before: Thu Jan 01 00:00:00 GMT 1970,
2018-09-14 08:51:32,196 [stdout] - 2018-09-14 08:51:32,195 INFO  [scheduler-1] SslInfrastructureService:102 - [Agent Registration] Successfully registered agent.,
2018-09-14 08:51:32,196 [stdout] - 2018-09-14 08:51:32,196 INFO  [scheduler-1] AgentHTTPClientController:115 - About to get cookie from the server.,
2018-09-14 08:51:32,558 [stdout] - 2018-09-14 08:51:32,557 INFO  [scheduler-1] AgentHTTPClientController:118 - Got cookie: 31d8d9b8-9ae0-4a61-8367-dd727bfd5d22,
2018-09-14 08:51:42,695 [stdout] - 2018-09-14 08:51:42,694 INFO  [scheduler-2] DefaultGoPublisher:94 - Agent [73fd58db1a93, 10.0.40.53, 3964d330-2ad4-4a87-852b-02eab3bef134] is reporting status [Preparing] to Go Server for Build [xyz-core-verification-partitioned-tgajdos/1/test/1/intTests_20/8366],
2018-09-14 08:51:42,709 [stdout] - 2018-09-14 08:51:42,708 INFO  [scheduler-2] DefaultGoPublisher:94 - Agent [73fd58db1a93, 10.0.40.53, 3964d330-2ad4-4a87-852b-02eab3bef134] is reporting status [Building] to Go Server for Build [xyz-core-verification-partitioned-tgajdos/1/test/1/intTests_20/8366],
2018-09-14 08:51:42,728 [stdout] - 2018-09-14 08:51:42,727 INFO  [scheduler-2] HttpService:138 - Got back 200 from server,
2018-09-14 08:51:42,728 [stdout] - 2018-09-14 08:51:42,728 INFO  [scheduler-2] PerfTimer:53 - Performance: Downloading from url [https://pr-gocd-server:8154/go/remoting/files/xyz-core-verification/162/build/1/gradleBuild/cruise-output/md5.checksum] took 11ms,
2018-09-14 08:51:42,729 [stdout] - 2018-09-14 08:51:42,728 INFO  [scheduler-2] ChecksumFileHandler:59 - [Agent Fetch Artifact] Saved checksum property file [pipelines/xyz-core-verification-partitioned-tgajdos/xyz-core-verification_build_gradleBuild_md5.checksum],
2018-09-14 08:51:43,901 [stdout] - 2018-09-14 08:51:43,900 INFO  [scheduler-2] HttpService:138 - Got back 200 from server,
2018-09-14 08:51:43,901 [stdout] - 2018-09-14 08:51:43,901 INFO  [scheduler-2] PerfTimer:53 - Performance: Downloading from url [https://pr-gocd-server:8154/go/remoting/files/xyz-core-verification/162/build/1/gradleBuild/abc.tar.gz] took 1171ms,
2018-09-14 08:51:43,902 [stdout] - 2018-09-14 08:51:43,901 INFO  [scheduler-2] FileHandler:66 - [Artifact File Download] [Fri Sep 14 08:51:43 GMT 2018] Download of artifact abc.tar.gz started,
2018-09-14 08:51:47,194 [stdout] - 2018-09-14 08:51:47,193 INFO  [scheduler-2] FileHandler:68 - [Artifact File Download] [Fri Sep 14 08:51:47 GMT 2018] Download of artifact abc.tar.gz ended,
2018-09-14 08:51:47,194 [stdout] - 2018-09-14 08:51:47,194 INFO  [scheduler-2] FileHandler:75 - [Artifact File Download] [Fri Sep 14 08:51:47 GMT 2018] Checksum computation of artifact abc.tar.gz started,
2018-09-14 08:51:48,135 [stdout] - 2018-09-14 08:51:48,134 INFO  [scheduler-2] FileHandler:78 - [Artifact File Download] [Fri Sep 14 08:51:48 GMT 2018] Checksum computation of artifact abc.tar.gz ended,
2018-09-14 08:51:48,146 [stdout] - 2018-09-14 08:51:48,145 ERROR [scheduler-2] Builder:116 - Did not find 'task' plugin with id 'script-executor'. Looks like plugin is missing,
2018-09-14 08:51:48,146 [stdout] - com.thoughtworks.go.plugin.access.PluginNotFoundException: Did not find 'task' plugin with id 'script-executor'. Looks like plugin is missing,
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.plugin.access.PluginRequestHelper.submitRequest(PluginRequestHelper.java:40),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.plugin.access.pluggabletask.JsonBasedPluggableTask.config(JsonBasedPluggableTask.java:42),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.domain.builder.pluggableTask.PluggableTaskBuilder.executeTask(PluggableTaskBuilder.java:90),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.domain.builder.pluggableTask.PluggableTaskBuilder.lambda$build$0(PluggableTaskBuilder.java:70),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.plugin.access.pluggabletask.TaskExtension.execute(TaskExtension.java:59),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.domain.builder.pluggableTask.PluggableTaskBuilder.build(PluggableTaskBuilder.java:70),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.remote.work.Builders.build(Builders.java:74),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.remote.work.BuildWork.execute(BuildWork.java:220),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.remote.work.BuildWork.buildJob(BuildWork.java:191),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.remote.work.BuildWork.build(BuildWork.java:137),
2018-09-14 08:51:48,146 [stdout] - 	at com.thoughtworks.go.remote.work.BuildWork.doWork(BuildWork.java:82),
2018-09-14 08:51:48,147 [stdout] - 	at com.thoughtworks.go.agent.JobRunner.run(JobRunner.java:54),
2018-09-14 08:51:48,147 [stdout] - 	at com.thoughtworks.go.agent.AgentHTTPClientController.retrieveWork(AgentHTTPClientController.java:134),
2018-09-14 08:51:48,147 [stdout] - 	at com.thoughtworks.go.agent.AgentHTTPClientController.work(AgentHTTPClientController.java:109),
2018-09-14 08:51:48,147 [stdout] - 	at com.thoughtworks.go.agent.AgentController.loop(AgentController.java:85),
2018-09-14 08:51:48,147 [stdout] - 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method),
2018-09-14 08:51:48,147 [stdout] - 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62),
2018-09-14 08:51:48,147 [stdout] - 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43),
2018-09-14 08:51:48,147 [stdout] - 	at java.lang.reflect.Method.invoke(Method.java:498),
2018-09-14 08:51:48,147 [stdout] - 	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65),
2018-09-14 08:51:48,148 [stdout] - 	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54),
2018-09-14 08:51:48,148 [stdout] - 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511),
2018-09-14 08:51:48,148 [stdout] - 	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308),
2018-09-14 08:51:48,148 [stdout] - 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180),
2018-09-14 08:51:48,148 [stdout] - 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294),
2018-09-14 08:51:48,148 [stdout] - 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149),
2018-09-14 08:51:48,148 [stdout] - 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624),
2018-09-14 08:51:48,148 [stdout] - 	at java.lang.Thread.run(Thread.java:748)

[ankitsri11]

I tried with the below setup and was unable to replicate the issue.

Go Version: 18.9.0
Docker Elastic Agent Plugin Version: 3.0.2-120
Script Executor Plugin Version: 0.3.0

I noticed that you are using Docker Elastic Agent Plugin Version: 3.0.1-116 which is nowhere available under plugins release tab. Can you try with the latest version (3.0.2-120) and see if you are able to replicate.

Here are the logs from my docker container:

/docker-entrypoint.sh: Creating directories and symlinks to hold GoCD configuration, data, and logs
$ mkdir /go
$ chown go:go /go
$ mkdir /godata
$ chown go:go /go
$ mkdir -v /godata/config
created directory: '/godata/config'
$ chown go:go /godata/config
$ ln -sv /godata/config /go/config
'/go/config' -> '/godata/config'
$ chown go:go /go/config
$ mkdir -v /godata/logs
created directory: '/godata/logs'
$ chown go:go /godata/logs
$ ln -sv /godata/logs /go/logs
'/go/logs' -> '/godata/logs'
$ chown go:go /go/logs
$ mkdir -v /godata/pipelines
created directory: '/godata/pipelines'
$ chown go:go /godata/pipelines
$ ln -sv /godata/pipelines /go/pipelines
'/go/pipelines' -> '/godata/pipelines'
$ chown go:go /go/pipelines
$ cp -rfv /go-agent/config/agent-bootstrapper-logback-include.xml /go/config/agent-bootstrapper-logback-include.xml
'/go-agent/config/agent-bootstrapper-logback-include.xml' -> '/go/config/agent-bootstrapper-logback-include.xml'
$ chown go:go /godata/config/agent-bootstrapper-logback-include.xml
$ cp -rfv /go-agent/config/agent-launcher-logback-include.xml /go/config/agent-launcher-logback-include.xml
'/go-agent/config/agent-launcher-logback-include.xml' -> '/go/config/agent-launcher-logback-include.xml'
$ chown go:go /godata/config/agent-launcher-logback-include.xml
$ cp -rfv /go-agent/config/agent-logback-include.xml /go/config/agent-logback-include.xml
'/go-agent/config/agent-logback-include.xml' -> '/go/config/agent-logback-include.xml'
$ chown go:go /godata/config/agent-logback-include.xml
$ chown go:go /go/config/autoregister.properties
/docker-entrypoint.sh: Running custom scripts in /docker-entrypoint.d/ ...
$ exec /usr/local/sbin/tini -- /usr/local/sbin/gosu go /docker-entrypoint.sh /go-agent/agent.sh
$ exec /go-agent/agent.sh
[Fri Sep 14 22:20:17 GMT 2018] Starting process: 
[Fri Sep 14 22:20:17 GMT 2018]   Working directory    : /go
[Fri Sep 14 22:20:17 GMT 2018]   Application arguments: [-serverUrl, https://10.19.20.118:8154/go]
[Fri Sep 14 22:20:17 GMT 2018]            GoCD Version: 18.9.0-7478
Could not find file `config/agent-bootstrapper-logback.xml'. Attempting to load from classpath.
Using classpath resource `jar:onejar:lib/agent-bootstrapper-18.9.0-7478-classes.jar!/config/agent-bootstrapper-logback.xml'.
2018-09-14 22:20:17,962 INFO  [main] DefaultAgentLauncherCreatorImpl:67 - Attempting to load com.thoughtworks.go.agent.launcher.AgentLauncherImpl as specified by manifest key Go-Agent-Launcher-Class
2018-09-14 22:20:17,969 INFO  [main] ParentClassAccessFilteringClassloader:44 - Loading com.thoughtworks.cruise.agent.common.launcher.AgentLauncher using java.net.URLClassLoader
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:onejar:lib/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/go/data/deps-733fe8e346578071-agent-launcher.jar/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
2018-09-14 22:20:18,003 INFO  [main] AgentBootstrapper:77 - Attempting create and start launcher...
2018-09-14 22:20:18,009 INFO  [main] ParentClassAccessFilteringClassloader:44 - Loading com.thoughtworks.cruise.agent.common.launcher.AgentLaunchDescriptor using java.net.URLClassLoader
Could not find file `config/agent-launcher-logback.xml'. Attempting to load from classpath.
Using classpath resource `jar:file:/go/data/deps-733fe8e346578071-agent-launcher.jar/agent-launcher-18.9.0-7478-classes.jar!/config/agent-launcher-logback.xml'.
2018-09-14 22:20:18,116 INFO  [TouchLoopThread-1] Lockfile:102 - Using lock file: /go/.agent-bootstrapper.running
2018-09-14 22:20:18,735 INFO  [main] ServerBinaryDownloader:106 - Downloading agent.jar
2018-09-14 22:20:18,850 INFO  [main] ServerBinaryDownloader:113 - Got server response
2018-09-14 22:20:19,478 INFO  [main] ServerBinaryDownloader:121 - Piped the stream to admin/agent
2018-09-14 22:20:19,479 INFO  [main] PerfTimer:53 - Performance: Downloading new admin/agent with md5 signature: 2901dcdcb32e09758d4c1c9d8cd6370e took 744ms
2018-09-14 22:20:19,678 INFO  [main] AgentProcessParentImpl:51 - Agent is version: 18.9.0-7478
2018-09-14 22:20:19,898 INFO  [main] ServerBinaryDownloader:106 - Downloading agent-plugins.zip
2018-09-14 22:20:19,935 INFO  [main] ServerBinaryDownloader:113 - Got server response
2018-09-14 22:20:20,019 INFO  [main] ServerBinaryDownloader:121 - Piped the stream to admin/agent-plugins.zip
2018-09-14 22:20:20,020 INFO  [main] PerfTimer:53 - Performance: Downloading new admin/agent-plugins.zip with md5 signature: ec7947e2a3b2c097edef84b5fec38923 took 122ms
2018-09-14 22:20:20,083 INFO  [main] ServerBinaryDownloader:106 - Downloading tfs-impl.jar
2018-09-14 22:20:20,132 INFO  [main] ServerBinaryDownloader:113 - Got server response
2018-09-14 22:20:20,585 INFO  [main] ServerBinaryDownloader:121 - Piped the stream to admin/tfs-impl.jar
2018-09-14 22:20:20,586 INFO  [main] PerfTimer:53 - Performance: Downloading new admin/tfs-impl.jar with md5 signature: d360568a777dedddfb485b2029eae6fb took 503ms
2018-09-14 22:20:20,592 INFO  [main] AgentProcessParentImpl:69 - Launching Agent with command: /usr/lib/jvm/java-1.8-openjdk/jre/bin/java -Dcruise.console.publish.interval=10 -Xms128m -Xmx256m -Dgo.console.stdout=true -Djava.security.egd=file:/dev/./urandom -Dagent.plugins.md5=ec7947e2a3b2c097edef84b5fec38923 -Dagent.binary.md5=2901dcdcb32e09758d4c1c9d8cd6370e -Dagent.launcher.md5=a8a6f1f95c44d11bd99b57c06f90a66b -Dagent.tfs.md5=d360568a777dedddfb485b2029eae6fb -jar agent.jar -serverUrl https://10.19.20.118:8154/go -sslVerificationMode NONE
2018-09-14 22:20:20,787 [stderr] - [Fri Sep 14 22:20:20 GMT 2018] Starting process: 
2018-09-14 22:20:20,788 [stderr] - [Fri Sep 14 22:20:20 GMT 2018]   Working directory    : /go
2018-09-14 22:20:20,788 [stderr] - [Fri Sep 14 22:20:20 GMT 2018]   Application arguments: [-serverUrl, https://10.19.20.118:8154/go, -sslVerificationMode, NONE]
2018-09-14 22:20:20,789 [stderr] - [Fri Sep 14 22:20:20 GMT 2018]            GoCD Version: 18.9.0-7478
2018-09-14 22:20:21,382 [stderr] - Could not find file `config/agent-logback.xml'. Attempting to load from classpath.
2018-09-14 22:20:21,383 [stderr] - Using classpath resource `jar:onejar:lib/agent-18.9.0-7478-classes.jar!/config/agent-logback.xml'.
2018-09-14 22:20:21,726 [stdout] - 2018-09-14 22:20:21,718 INFO  [main] ClassPathXmlApplicationContext:583 - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@462d5aee: startup date [Fri Sep 14 22:20:21 GMT 2018]; root of context hierarchy
2018-09-14 22:20:21,775 [stdout] - 2018-09-14 22:20:21,775 INFO  [main] XmlBeanDefinitionReader:317 - Loading XML bean definitions from class path resource [applicationContext.xml]
2018-09-14 22:20:21,976 [stdout] - 2018-09-14 22:20:21,975 INFO  [main] XmlBeanDefinitionReader:317 - Loading XML bean definitions from class path resource [applicationContext-plugin-infra.xml]
2018-09-14 22:20:22,486 [stdout] - 2018-09-14 22:20:22,485 INFO  [main] AutowiredAnnotationBeanPostProcessor:155 - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
2018-09-14 22:20:23,272 [stdout] - 2018-09-14 22:20:23,263 INFO  [main] AgentStatusHttpd:91 - Agent status HTTP API server running on http://localhost:8152.
2018-09-14 22:20:23,617 [stdout] - 2018-09-14 22:20:23,617 INFO  [main] AgentControllerFactory:120 - Connecting to server using HTTP(S)
2018-09-14 22:20:23,661 [stdout] - 2018-09-14 22:20:23,659 INFO  [main] ThreadPoolTaskScheduler:165 - Initializing ExecutorService  'scheduler'
2018-09-14 22:20:24,872 [stdout] - 2018-09-14 22:20:24,871 INFO  [scheduler-1] SslInfrastructureService:98 - [Agent Registration] Starting to register agent.
2018-09-14 22:20:24,874 [stdout] - 2018-09-14 22:20:24,872 INFO  [scheduler-1] SslInfrastructureService:108 - [Agent Registration] Fetching token from server.
2018-09-14 22:20:24,893 [stdout] - 2018-09-14 22:20:24,892 INFO  [scheduler-1] TokenRequester:58 - The server has generated token for the agent.
2018-09-14 22:20:24,893 [stdout] - 2018-09-14 22:20:24,893 INFO  [scheduler-1] SslInfrastructureService:111 - [Agent Registration] Got a token from server.
2018-09-14 22:20:25,499 [stdout] - 2018-09-14 22:20:25,497 INFO  [scheduler-1] SslInfrastructureService:210 - This agent is now approved by the server.
2018-09-14 22:20:25,553 [stdout] - 2018-09-14 22:20:25,552 INFO  [scheduler-1] SslInfrastructureService:140 - [Agent Registration] Retrieved registration from Go server.
2018-09-14 22:20:25,557 [stdout] - 2018-09-14 22:20:25,556 INFO  [scheduler-1] SslInfrastructureService:148 - [Agent Registration] Stored registration for cert with hash code: d3f2d0f5d1d84706588768e250db9abb419172653c0715d341999b5cd15d66e2 not valid before: Thu Jan 01 00:00:00 GMT 1970
2018-09-14 22:20:25,616 [stdout] - 2018-09-14 22:20:25,616 INFO  [scheduler-1] SslInfrastructureService:102 - [Agent Registration] Successfully registered agent.
2018-09-14 22:20:25,617 [stdout] - 2018-09-14 22:20:25,616 INFO  [scheduler-1] AgentHTTPClientController:115 - About to get cookie from the server.
2018-09-14 22:20:25,685 [stdout] - 2018-09-14 22:20:25,684 INFO  [scheduler-1] AgentHTTPClientController:118 - Got cookie: b7ce8797-0d5f-4f84-adf8-b77e621e2066
2018-09-14 22:20:35,833 [stdout] - 2018-09-14 22:20:35,832 INFO  [scheduler-2] DefaultGoPublisher:94 - Agent [75192ad0e77e, 172.17.0.5, 1e5ba2f5-bbb8-47d9-9483-d66617ff3e68] is reporting status [Preparing] to Go Server for Build [PipelineA/11/defaultStage/1/defaultJob/18]
2018-09-14 22:20:38,351 [stdout] - 2018-09-14 22:20:38,350 INFO  [scheduler-2] DefaultGoPublisher:94 - Agent [75192ad0e77e, 172.17.0.5, 1e5ba2f5-bbb8-47d9-9483-d66617ff3e68] is reporting status [Building] to Go Server for Build [PipelineA/11/defaultStage/1/defaultJob/18]
2018-09-14 22:20:38,454 [stdout] - 2018-09-14 22:20:38,453 INFO  [scheduler-2] CommandLine:366 - Running command: /bin/bash -c ls -la /go/plugins/external/; ls -la /go/plugins_work/
2018-09-14 22:20:38,458 [stdout] - 2018-09-14 22:20:38,458 INFO  [Thread-29] CommandLine:51 - total 1168
2018-09-14 22:20:38,463 [stdout] - 2018-09-14 22:20:38,462 INFO  [Thread-29] CommandLine:51 - drwxr-xr-x    2 go       go            4096 Sep 14 22:20 .
2018-09-14 22:20:38,464 [stdout] - 2018-09-14 22:20:38,463 INFO  [Thread-29] CommandLine:51 - drwxr-xr-x    4 go       go            4096 Sep 14 22:20 ..
2018-09-14 22:20:38,464 [stdout] - 2018-09-14 22:20:38,464 INFO  [Thread-29] CommandLine:51 - -rw-r--r--    1 go       go         1184988 Sep 14 22:20 script-executor-0.3.0.jar
2018-09-14 22:20:38,464 [stdout] - 2018-09-14 22:20:38,464 INFO  [Thread-29] CommandLine:51 - total 12
2018-09-14 22:20:38,465 [stdout] - 2018-09-14 22:20:38,464 INFO  [Thread-29] CommandLine:51 - drwxr-xr-x    3 go       go            4096 Sep 14 22:20 .
2018-09-14 22:20:38,465 [stdout] - 2018-09-14 22:20:38,465 INFO  [Thread-29] CommandLine:51 - drwxr-xr-x    6 go       go            4096 Sep 14 22:20 ..
2018-09-14 22:20:38,465 [stdout] - 2018-09-14 22:20:38,465 INFO  [Thread-29] CommandLine:51 - drwxr-xr-x    6 go       go            4096 Sep 14 22:20 script-executor-0.3.0.jar
2018-09-14 22:20:38,561 [stdout] - 2018-09-14 22:20:38,560 INFO  [scheduler-2] DefaultGoPublisher:99 - Agent [75192ad0e77e, 172.17.0.5, 1e5ba2f5-bbb8-47d9-9483-d66617ff3e68] is reporting build result [Passed] to Go Server for Build [PipelineA/11/defaultStage/1/defaultJob/18]
2018-09-14 22:20:38,574 [stdout] - 2018-09-14 22:20:38,573 INFO  [scheduler-2] DefaultGoPublisher:94 - Agent [75192ad0e77e, 172.17.0.5, 1e5ba2f5-bbb8-47d9-9483-d66617ff3e68] is reporting status [Completing] to Go Server for Build [PipelineA/11/defaultStage/1/defaultJob/18]
2018-09-14 22:20:38,585 [stdout] - 2018-09-14 22:20:38,584 INFO  [scheduler-2] ArtifactsPublisher:69 - Pluggable metadata folder is empty.
2018-09-14 22:20:38,586 [stdout] - 2018-09-14 22:20:38,585 INFO  [scheduler-2] DefaultGoPublisher:104 - Agent [75192ad0e77e, 172.17.0.5, 1e5ba2f5-bbb8-47d9-9483-d66617ff3e68] is reporting build result [Passed] to Go Server for Build [PipelineA/11/defaultStage/1/defaultJob/18]
2018-09-14 22:20:38,616 [stdout] - 2018-09-14 22:20:38,615 INFO  [scheduler-2] DefaultGoPublisher:89 - Stopping Transmission for Build [PipelineA/11/defaultStage/1/defaultJob/18]
2018-09-14 22:20:38,647 [stdout] - 2018-09-14 22:20:38,646 INFO  [scheduler-2] HttpService:138 - Got back 200 from server

[tomekgajdos]

This issue occurs randomly. It is caused by parallelism. Agent controller is called by scheduler https://github.com/gocd/gocd/blob/master/agent/src/main/resources/applicationContext.xml#L86-L95 before all plugins are initialized by component https://github.com/gocd/gocd/blob/master/agent/src/main/java/com/thoughtworks/go/agent/AgentPluginsInitializer.java#L62. Parameter 'initial-delay' should have higher value which indicating the number of milliseconds to wait before the first execution of the method OR there should be mechanism for checking if the agent is fully initialized. Agent controller cannot be called by scheduler before agent is fully initialized.

[arvindsv]

Sounds accurate. Moved it to 18.11 milestone, to check and decide what can be done.

[arvindsv]

/cc @bdpiparva @GaneshSPatil

[akshaydewan]

I was able to recreate this fairly consistently in a development environment without using Docker by adding a delay (using Thread.sleep) to DefaultPluginJarLocationMonitor.oneShot(). It will happen when a new agent is added. I've raised a PR with a potential fix.