Expose agent properties before first build

[jeandet]

This plugin is awesome, it allow to have many container with different features. I added some parameters in my docker containers to expose their functionalities such as compilers or tools availability. The problem seems to be that you have to run one build on it to expose this parameters, so the first time you configure your new image you won't get agent parameters. Then if you rely on this parameters to choose compatible agent/Docker image, by default TC will not use your new image. When you add a new Docker image you have this test button, maybe the parameters could be exposed here.

[JeanRev]

There is indeed a known limitation related to agent capabilities. Every time a new cloud image is detected (typically, just after you save a cloud profile), the TC server will automatically start a new cloud instance to gather the agent capabilities related to this image. So, strictly speaking, you should not necessarily have to wait for the first build for the initial capabilities to be discovered.

However, if you updated afterward the underlying Docker image to install new tools, it will be then indeed required to either start manually a new cloud instance or wait for the next triggered build, in order for the agent to connect and have the cloud image build capabilities updated.

Is this what you experienced?

[jeandet]

Ok, in fact this is damn slow. I didn't wait enough time, it takes 5 minutes to start the first image. I was killing the container... So yes, after image setup it starts the container and then I get all the informations. I get this warning on all my images: Some plugins in cloud image are missing/outdated. This affects the time necessary to start the agent Is it the reason why it takes so much time? How do you solve that?

[JeanRev]

Hum... 5 minutes seems too much indeed. The TC server should issue the instance start request, and the agent container created, almost instantaneously after saving the cloud profile settings.

Did you had at least one agent license available at the time the cloud profile was saved?

Once the agent process has been started it should not take more than two minutes for the agent to connect, upgrade if required, and starting accepting build jobs (when using the official agent image, depending on your server and agent setup it may takes a bit longer).

The message you are seeing can be safely ignored. It simply means that the agents created from the Docker image you specified will need to upgrade on their first connection (the upgrade process takes approximately 20-30 seconds). It will always be displayed if you are using the official agent image. To avoid this, you'll just have to commit the container after the upgrade, and use the resulting image as cloud agent image.

Can you try to create a new cloud profile, save it, wait until the agent is available, and attach to this issue the "teamcity-clouds.log" file from your TC server "log" folders? Thanks

[jeandet]

The log is below, this time it was not so slow. I guess the pull time was the reason, now the image is already in the computer.

[2017-06-23 17:40:35,185]   WARN [pr-8111-exec-10] - .beans.CloudTabFormFactoryImpl - Can't find projectId by projectExtId '' 
[2017-06-23 17:40:44,346]   WARN [apr-8111-exec-6] - ker.client.DockerClientFactory - Target version 1.26 is greater than daemon current API version (1.24, minimal: undefined). Will use the daemon API version. 
[2017-06-23 17:40:53,430]   WARN [apr-8111-exec-2] - ker.client.DockerClientFactory - Target version 1.26 is greater than daemon current API version (1.24, minimal: undefined). Will use the daemon API version. 
[2017-06-23 17:41:54,228]   INFO [apr-8111-exec-1] - cloud.docker.DockerImageConfig - Loading cloud profile configuration version 4. 
[2017-06-23 17:41:54,228]   INFO [apr-8111-exec-1] - cloud.docker.DockerImageConfig - Loading cloud profile configuration version 4. 
[2017-06-23 17:41:54,228]   INFO [apr-8111-exec-1] - .web.admin.UpdateProfileAction - Updating cloud profile: id=VRDC-2 
[2017-06-23 17:41:54,230]   INFO [apr-8111-exec-1] - ocker.DefaultDockerCloudClient - Starting disposal of client. 
[2017-06-23 17:41:54,247]   INFO [apr-8111-exec-1] - .server.impl.CloudEventsLogger - Profile reloaded: VRDC-2 and is enabled 
[2017-06-23 17:41:54,270]   INFO [apr-8111-exec-2] - cloud.docker.DockerImageConfig - Loading cloud profile configuration version 4. 
[2017-06-23 17:41:54,270]   INFO [apr-8111-exec-2] - cloud.docker.DockerImageConfig - Loading cloud profile configuration version 4. 
[2017-06-23 17:41:54,271]   INFO [apr-8111-exec-2] - ocker.DefaultDockerCloudClient - 2 image definitions loaded: {9fd082cc-01ac-4fe3-a4fb-6a1e9ac9ea5e=TestTimeToStartImage (jeandet/teamcity-docker-complete-agent) / 9fd082cc-01ac-4fe3-a4fb-6a1e9ac9ea5e, 2de7d643-b7b0-4a1f-ac30-d3ddf288789a=Fedora_SciQLop (jeandet/teamcity-docker-complete-agent) / 2de7d643-b7b0-4a1f-ac30-d3ddf288789a} 
[2017-06-23 17:41:54,375]   WARN [erTaskScheduler] - ker.client.DockerClientFactory - Target version 1.26 is greater than daemon current API version (1.24, minimal: undefined). Will use the daemon API version. 
[2017-06-23 17:41:54,375]   INFO [erTaskScheduler] - ocker.DefaultDockerCloudClient - Docker client instantiated. 
[2017-06-23 17:41:54,821]   INFO [4 Flush Queue 1] - .instances.StartInstanceAction - Starting cloud instance: profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, TestTimeToStartImage (jeandet/teamcity-docker-complete-agent) / 9fd082cc-01ac-4fe3-a4fb-6a1e9ac9ea5e, hash=VN0dc3DSQDr5e54z4n8NvCdk9O6MWUe4, reason=Automatic start: Start instance to get instance agent details 
[2017-06-23 17:41:54,821]   INFO [4 Flush Queue 1] - ocker.DefaultDockerCloudClient - Creating new instance from image: TestTimeToStartImage (jeandet/teamcity-docker-complete-agent) / 9fd082cc-01ac-4fe3-a4fb-6a1e9ac9ea5e 
[2017-06-23 17:41:54,821]   INFO [4 Flush Queue 1] - ocker.DefaultDockerCloudClient - Created cloud instance 8abd980a-5942-4784-bd6c-9c9340745ec9. 
[2017-06-23 17:41:54,822]   INFO [erTaskScheduler] - ocker.DefaultDockerCloudClient - Starting container 8abd980a-5942-4784-bd6c-9c9340745ec9 
[2017-06-23 17:41:54,822]   INFO [4 Flush Queue 1] - .server.impl.CloudEventsLogger - Cloud instance entered 'starting' state, profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, <Unknown> 
[2017-06-23 17:41:54,823]   INFO [4 Flush Queue 1] - .server.impl.CloudEventsLogger - Cloud instance start succeeded: profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, <Unknown> 
[2017-06-23 17:41:58,391]   INFO [erTaskScheduler] - ocker.DefaultDockerCloudClient - New container 2405b9b6487b02394547cc84094d2827a58faeca41f1845f53c9a70ea3f8437a created. 
[2017-06-23 17:41:58,622]   INFO [erTaskScheduler] - ocker.DefaultDockerCloudClient - Container 2405b9b6487b02394547cc84094d2827a58faeca41f1845f53c9a70ea3f8437a started. 
[2017-06-23 17:41:58,622]   INFO [erTaskScheduler] - r.impl.DBCloudStateManagerImpl - Image: TestTimeToStartImage, Instance: 8abd980a-5942-4784-bd6c-9c9340745ec9, profile=VRDC-2 is marked with state: running. 
[2017-06-23 17:42:00,016]   INFO [uled executor 1] - .server.impl.CloudEventsLogger - Cloud instance entered 'running' state, profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, admiring_dubinsky 
[2017-06-23 17:42:15,165]   INFO [apr-8111-exec-9] - r.impl.DBCloudStateManagerImpl - Image: TestTimeToStartImage (jeandet/teamcity-docker-complete-agent:latest) / 9fd082cc-01ac-4fe3-a4fb-6a1e9ac9ea5e, profile: profile 'pc-solar5'{id=VRDC-2, projectId=_Root} was marked to CONTAIN agent 
[2017-06-23 17:42:15,166]   INFO [apr-8111-exec-9] - .server.impl.CloudEventsLogger - Detected cloud agent "pc-solar5" {id=13}, profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, admiring_dubinsky 
[2017-06-23 17:42:20,019]   WARN [uled executor 3] - .instances.RunningInstanceTask - Failed to find agent by id=13 for profile:profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, admiring_dubinsky 
[2017-06-23 17:42:54,626]   INFO [apr-8111-exec-2] - r.impl.DBCloudStateManagerImpl - Image: TestTimeToStartImage (jeandet/teamcity-docker-complete-agent:latest) / 9fd082cc-01ac-4fe3-a4fb-6a1e9ac9ea5e, profile: profile 'pc-solar5'{id=VRDC-2, projectId=_Root} was marked to CONTAIN agent 
[2017-06-23 17:42:54,627]   INFO [apr-8111-exec-2] - .server.impl.CloudEventsLogger - Detected cloud agent "admiring_dubinsky/pc-solar5" {id=13}, profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, admiring_dubinsky 
[2017-06-23 17:43:50,239]   WARN [apr-8111-exec-2] - ker.client.DockerClientFactory - Target version 1.26 is greater than daemon current API version (1.24, minimal: undefined). Will use the daemon API version. 
[2017-06-23 17:44:30,531]   INFO [pr-8111-exec-10] - l.instances.StopInstanceAction - Terminating instance: admiring_dubinsky, profile 'pc-solar5'{id=VRDC-2, projectId=_Root}, reason: User adminlpp terminated instance 
[2017-06-23 17:44:30,532]   INFO [pr-8111-exec-10] - r.impl.DBCloudStateManagerImpl - Image: TestTimeToStartImage (jeandet/teamcity-docker-complete-agent:latest) / 9fd082cc-01ac-4fe3-a4fb-6a1e9ac9ea5e, profile: profile 'pc-solar5'{id=VRDC-2, projectId=_Root} was marked to CONTAIN agent 
[2017-06-23 17:44:30,534]   INFO [pr-8111-exec-10] - ocker.DefaultDockerCloudClient - Request for terminating instance: admiring_dubinsky 
[2017-06-23 17:44:30,534]   INFO [pr-8111-exec-10] - ocker.DefaultDockerCloudClient - Scheduling cloud instance termination: admiring_dubinsky (client disposed: false). 
[2017-06-23 17:44:30,972]   INFO [erTaskScheduler] - ocker.DefaultDockerCloudClient - Container 2405b9b6487b02394547cc84094d2827a58faeca41f1845f53c9a70ea3f8437a stopped in 438ms. 
[2017-06-23 17:44:30,973]   INFO [erTaskScheduler] - ocker.DefaultDockerCloudClient - Destroying container: 2405b9b6487b02394547cc84094d2827a58faeca41f1845f53c9a70ea3f8437a 
[2017-06-23 17:44:32,221]   INFO [erTaskScheduler] - r.impl.DBCloudStateManagerImpl - Image: TestTimeToStartImage, Instance: 8abd980a-5942-4784-bd6c-9c9340745ec9, profile=VRDC-2 is marked with state: stopped. 
[2017-06-23 17:44:35,029]   INFO [uled executor 5] - .server.impl.CloudEventsLogger - Cloud agent "admiring_dubinsky/pc-solar5" {id=13} is no longer recognized as cloud agent because instance has gone: profileId=VRDC-2, imageId=TestTimeToStartImage, instanceId=8abd980a-5942-4784-bd6c-9c9340745ec9 
[2017-06-23 17:44:35,029]   INFO [uled executor 5] - .server.impl.CloudEventsLogger - Cloud instance has gone (is not reported by cloud profile): profileId=VRDC-2, imageId=TestTimeToStartImage, instanceId=8abd980a-5942-4784-bd6c-9c9340745ec9 

[JeanRev]

Yes, this seems more acceptable, your logs look fine.

Still, I think that the handling of outdated agent capabilities should be better handled. Such issue will become even more obvious once agent containers will have the ability to be preserved across reconfigurations and shutdown of the TeamCity server (#23). I'll create a separate issue to try to address this.

From your perspective, can this issue be closed?

[jeandet]

Yes, you can close it, sorry for the noise.

[JeanRev]

No problem, thank you for reporting.