Problems running agent on Nano Server

Created August 30, 2017 11:26

I know there is no official support for running TeamCity Build Agents on Nano Server, but I made a shot and feel I am not that far from succeeding. Using containers is the only option in Nano Server vNext, so I

Downloaded the microsoft/nanoserver:latest image
Added Java 8.144 to the image
Added the Build Agent BUILD_46961 to the image
Added my server to the buildAgent.properties
Tried to start the agent

After starting the agent, it made contact with the server. I authorized it and it disconnected, leaving the agent state at "Agent has unregistered (will upgrade)" on the server. The agent updated it's checksum and everything looked normal. However after managing to contact the server and fetching the info it needed, the agent is unable to load giving the error message of Connection reset from Java.

---- teamcity-agent.log ----

[2017-08-30 13:21:15,332] INFO - s.buildServer.agent.AgentMain2 - ===========================================================
[2017-08-30 13:21:15,364] INFO - s.buildServer.agent.AgentMain2 - TeamCity Build Agent 2017.1.3 (build 46961)
[2017-08-30 13:21:15,379] INFO - s.buildServer.agent.AgentMain2 - OS: Windows Server 2016, version 10.0, amd64, Current user: ContainerAdministrator, Time zone: CEST (UTC+02:00)
[2017-08-30 13:21:15,379] INFO - s.buildServer.agent.AgentMain2 - Java: 1.8.0_144, Java HotSpot(TM) 64-Bit Server VM (25.144-b01, mixed mode), Java(TM) SE Runtime Environment (1.8.0_144-b01), Oracle Corporation; JVM parameters: -ea -Xmx384m -Dlog4j.configuration=file:../conf/teamcity-agent-log4j.xml -Dteamcity_logs=../logs/
[2017-08-30 13:21:15,387] INFO - s.buildServer.agent.AgentMain2 - Starting...
[2017-08-30 13:21:15,625] INFO - buildServer.agent.AgentMain2$2 - Refreshing jetbrains.buildServer.agent.AgentMain2$2@3b0143d3: startup date [Wed Aug 30 13:21:15 CEST 2017]; root of context hierarchy
[2017-08-30 13:21:18,187] INFO - jetbrains.buildServer.AGENT - Calculating CPU benchmark index...
[2017-08-30 13:21:22,465] INFO - jetbrains.buildServer.AGENT - CPU benchmark index is set to 765
[2017-08-30 13:21:22,637] INFO - jetbrains.buildServer.AGENT - Agent tools download temp directory created on path C:\BuildAgent\buildAgent\temp\tools
[2017-08-30 13:21:22,902] INFO - dAgentConfigurationInitializer - Loading build agent configuration from C:\BuildAgent\buildAgent\conf\buildAgent.properties
[2017-08-30 13:21:22,949] INFO - s.buildServer.agent.AgentMain2 - Working dir: C:\BuildAgent\buildAgent\work
[2017-08-30 13:21:22,949] INFO - s.buildServer.agent.AgentMain2 - Temp dir: C:\BuildAgent\buildAgent\temp
[2017-08-30 13:21:22,949] INFO - rver.plugins.PluginManagerImpl - ===========================================================
[2017-08-30 13:21:22,949] INFO - rver.plugins.PluginManagerImpl - Plugins initialization started...
[2017-08-30 13:21:22,949] INFO - rver.plugins.PluginManagerImpl - Scanning plugins folders
[2017-08-30 13:21:22,949] INFO - .plugins.files.JarSearcherBase - Scanning plugin folder: C:\BuildAgent\buildAgent\plugins
[2017-08-30 13:21:22,949] INFO - .plugins.files.JarSearcherBase - Scanning plugin folder: C:\BuildAgent\buildAgent\tools
[2017-08-30 13:21:22,965] INFO - rver.plugins.PluginManagerImpl - Found 1 non bundled plugins: [amazonEC2]
[2017-08-30 13:21:22,965] INFO - rver.plugins.PluginManagerImpl - Found 0 bundled plugins: []
[2017-08-30 13:21:22,965] INFO - rver.plugins.PluginsCollection - Load shared classloader for 1 plugins [amazonEC2]
[2017-08-30 13:21:22,996] INFO - rver.plugins.PluginsCollection - No plugins were loaded with standalone classloaders
[2017-08-30 13:21:23,199] INFO - rver.plugins.PluginManagerImpl - Plugins initialization completed (1 plugins loaded): [amazonEC2]
[2017-08-30 13:21:23,199] INFO - rver.plugins.PluginManagerImpl - ===========================================================
[2017-08-30 13:21:23,199] INFO - jetbrains.buildServer.AGENT - Build Agent version: 46961, plugins signature: NA
[2017-08-30 13:21:23,277] INFO - dAgentConfigurationInitializer - Loading build agent configuration from C:\BuildAgent\buildAgent\conf\buildAgent.properties
[2017-08-30 13:21:30,340] INFO - n.AmazonInstanceMetadataReader - Amazon is not available. Amazon EC2 integration is not active: Failed to connect to http://169.254.169.254/2016-04-19. The host did not accept the connection within timeout of 7000 ms
[2017-08-30 13:21:30,340] INFO - .agent.AmazonPropertiesUpdater - Fetched AmazonEC2 instance metadata:
[2017-08-30 13:21:30,340] INFO - zon.agent.AmazonMetadataChecks - Amazon EC instance metadata contains no keys
[2017-08-30 13:21:30,340] WARN - .agent.AmazonPropertiesUpdater - Fetched Amazon EC2 instance metadata does not contain required values. Probably this agent was not started inside Amazon EC2. Is proxy server used?
[2017-08-30 13:21:30,590] INFO - .agent.impl.OsArchBitsDetector - Detecting via "wmic computersystem get systemtype", exit code: 0, output: SystemType = x64-based PC
[2017-08-30 13:21:30,590] INFO - .agent.impl.OsArchBitsDetector - "teamcity.agent.os.arch.bits" detected as "64"
[2017-08-30 13:21:30,590] INFO - jetbrains.buildServer.AGENT - Start build agent
[2017-08-30 13:21:30,622] INFO - jetbrains.buildServer.AGENT - Agent Web server started on port 9090
[2017-08-30 13:21:30,622] INFO - agent.impl.AgentPortFileWriter - Writing agent runtime file to C:\BuildAgent\buildAgent\logs\buildAgent.xmlRpcPort
[2017-08-30 13:21:30,637] INFO - agent.impl.AgentPortFileWriter - Launcher version is 46961
[2017-08-30 13:21:30,637] INFO - agent.impl.AgentPortFileWriter - Writing agent runtime file to C:\BuildAgent\buildAgent\logs\buildAgent.xmlRpcPort :DONE!
[2017-08-30 13:21:30,637] INFO - jetbrains.buildServer.AGENT - Build agent started
[2017-08-30 13:21:30,653] INFO - buildServer.AGENT.registration - Registering on server via URL http://cwbyggmester:124: AgentDetails{Name='NanoAgent-1', AgentId=null, BuildId=null, AgentOwnAddress='10.0.1.182', AlternativeAddresses=[172.21.42.68], Port=9090, Version='46961', PluginsVersion='NA', AvailableRunners=[], AvailableVcs=[], AuthorizationToken='c79fb6c7ae3b0367f7b8a7f74fcc51a5', PingCode='a9w3JAxtJPEdPbZpdw2M0kbNVdxYqGC7'}
[2017-08-30 13:21:30,825] INFO - buildServer.AGENT.registration - Server supports the following communication protocols: [polling]
[2017-08-30 13:21:30,825] INFO - buildServer.AGENT.registration - Trying to register on server using 'polling' protocol.
[2017-08-30 13:21:31,135] INFO - r.artifacts.impl.HttpDiskCache - Cleaning up items with life time in cache greater than 172800 seconds
[2017-08-30 13:21:31,135] INFO - r.artifacts.impl.HttpDiskCache - Finished cleaning up expired items, 0 items removed
[2017-08-30 13:21:31,135] INFO - dDirectoryBasedCleanupRegistry - Removing files from C:\BuildAgent\buildAgent\work\.old
[2017-08-30 13:21:31,229] INFO - l.directories.DirectoryMapImpl - Cleaning up old checkout directories. Default lifetime = 192 hour(s)
[2017-08-30 13:21:31,276] INFO - dDirectoryBasedCleanupRegistry - Removing files from C:\BuildAgent\buildAgent\temp\.old
[2017-08-30 13:21:33,197] INFO - buildServer.AGENT.registration - Registered on server with id 15 and authorization token 'e8b837e9d5c43aa315e17743fd302c58'
[2017-08-30 13:21:33,197] INFO - buildServer.AGENT.registration - If this is the first time this agent registered on the server make sure it is authorized by administrator in the server web UI.
[2017-08-30 13:21:33,212] INFO - ldServer.AGENT.PollingProtocol - Start polling server for commands
[2017-08-30 13:21:33,228] INFO - ldServer.AGENT.PollingProtocol - New command is received from server "testLocal" {id = 1}
[2017-08-30 13:21:33,775] INFO - ldServer.AGENT.PollingProtocol - New command is received from server "upgrade" {id = 2}
[2017-08-30 13:21:33,775] INFO - jetbrains.buildServer.AGENT - Upgrade call received from the build server
[2017-08-30 13:21:33,775] INFO - jetbrains.buildServer.AGENT - Will upgrade when become idle
[2017-08-30 13:21:33,775] INFO - jetbrains.buildServer.AGENT - Wait for build agent registration to finish
[2017-08-30 13:21:33,775] INFO - jetbrains.buildServer.AGENT - Registration of build agent is finished.
[2017-08-30 13:21:33,775] INFO - jetbrains.buildServer.AGENT - Stop command was not performed. No build to stop with reason: BuildInterruptReason.AGENT_SHUTDOWN
[2017-08-30 13:21:33,775] INFO - jetbrains.buildServer.AGENT - Starting agent shutdown sequence, reason: Restart agent, failed to download upgrade from server
[2017-08-30 13:21:33,792] INFO - jetbrains.buildServer.AGENT - Url for downloading updates: http://cwbyggmester:124
[2017-08-30 13:21:33,792] INFO - jetbrains.buildServer.AGENT - Downloading http://cwbyggmester:124/update/teamcity-agent.xml ==> C:\BuildAgent\buildAgent\temp\gcIphskwi3fP0z88r5s4tRxUP8IOm7oR
[2017-08-30 13:21:33,807] INFO - agent.impl.AgentPortFileWriter - Delete agent runtime file from C:\BuildAgent\buildAgent\logs\buildAgent.xmlRpcPort
[2017-08-30 13:21:33,807] INFO - ldServer.AGENT.PollingProtocol - Stop polling server for commands
[2017-08-30 13:21:33,807] INFO - jetbrains.buildServer.AGENT - Unregistering from the server. Agent id: 15
[2017-08-30 13:21:33,994] INFO - jetbrains.buildServer.AGENT - Shutdown agent WebServer start
[2017-08-30 13:21:33,994] INFO - jetbrains.buildServer.AGENT - Shutdown agent WebServer finish
[2017-08-30 13:21:33,994] INFO - jetbrains.buildServer.AGENT - Shutdown agent finish
[2017-08-30 13:21:53,229] INFO - jetbrains.buildServer.AGENT - Downloading http://cwbyggmester:124/update/teamcity-agent.xml ==> C:\BuildAgent\buildAgent\temp\gcIphskwi3fP0z88r5s4tRxUP8IOm7oR
[2017-08-30 13:22:12,708] INFO - jetbrains.buildServer.AGENT - Downloading http://cwbyggmester:124/update/teamcity-agent.xml ==> C:\BuildAgent\buildAgent\temp\gcIphskwi3fP0z88r5s4tRxUP8IOm7oR
[2017-08-30 13:22:32,151] WARN - ade.UpgradeFilesDownloaderImpl - Failed to download AgentUpdateInfo from server. Failed to download file http://cwbyggmester:124/update/teamcity-agent.xml to C:\BuildAgent\buildAgent\temp\gcIphskwi3fP0z88r5s4tRxUP8IOm7oR. Connection reset
jetbrains.buildServer.agent.impl.upgrade.UpgradeFailedException: Failed to download file http://cwbyggmester:124/update/teamcity-agent.xml to C:\BuildAgent\buildAgent\temp\gcIphskwi3fP0z88r5s4tRxUP8IOm7oR. Connection reset
at jetbrains.buildServer.agent.impl.upgrade.HttpFilesDownloaderImpl$DownloaderImpl.downloadFile(HttpFilesDownloaderImpl.java:88)
at jetbrains.buildServer.agent.impl.upgrade.HttpFilesDownloaderImpl.downloadFile(HttpFilesDownloaderImpl.java:33)
at jetbrains.buildServer.agent.impl.upgrade.RecoverableFilesDownloaderImpl.downloadFile(RecoverableFilesDownloaderImpl.java:33)
at jetbrains.buildServer.agent.impl.upgrade.UpgradeFilesDownloaderImpl.downloadContentsXmlFile(UpgradeFilesDownloaderImpl.java:60)
at jetbrains.buildServer.agent.impl.upgrade.UpgradesProcessor.downloadUpdates(UpgradesProcessor.java:42)
at jetbrains.buildServer.agent.impl.upgrade.UpgradeThread.downloadUpdates(UpgradeThread.java:104)
at jetbrains.buildServer.agent.impl.upgrade.UpgradeThread.prepareUpgrade(UpgradeThread.java:72)
at jetbrains.buildServer.agent.impl.upgrade.UpgradeThread.run(UpgradeThread.java:57)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.SocketException: Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:210)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
at org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:78)
at org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:106)
at org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:1116)
at org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1973)
at org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1735)
at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1098)
at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398)
at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
at jetbrains.buildServer.agent.impl.upgrade.HttpFilesDownloaderImpl$DownloaderImpl.downloadFile(HttpFilesDownloaderImpl.java:73)
... 8 more
[2017-08-30 13:22:32,152] INFO - ade.modes.OldServerUpgradeMode - Server does not provide teamcity-agent.xml. Will download only buildAgent.zip.
[2017-08-30 13:22:32,152] INFO - jetbrains.buildServer.AGENT - Downloading http://cwbyggmester:124/update/buildAgent.zip ==> C:\BuildAgent\buildAgent\update\buildAgent.zip

---- buildAgent.properties ----

serverUrl=http://cwbyggmester:124
name=NanoAgent-1
workDir=../work
tempDir=../temp
systemDir=../system
authorizationToken=e8b837e9d5c43aa315e17743fd302c58

----

Any clues on what is causing this?

3 comments

Denis Lapuente

Created August 30, 2017 11:49

Having a connection reset on the server side is pretty rare. Could you check whether there is any errors on the server side logs? Any firewall in between? Or are they in the same server?

Dagh

Created August 30, 2017 13:12

Thanks, Denis.

No errors - the only relevant info I can find in any of the server logs are those below.

Pings are OK
Manual download of the same files using Powershell are OK (http://cwbyggmester:124/update/teamcity-agent.xml, http://cwbyggmester:124/update/buildAgent.zip)
Firewall is open on port 124. I've also stopped the server firewall and tested without any success

The only thing I can think of is - there is a VPN network between the Docker host machine and the TeamCity server. But still, the agent communicates with the server when registering and fetching the authorizationToken - and this token is also updated in the local buidAgent.properties. To me, this confirms that VPN is not the cause. The agent docker images should be polling all the time (unidirectional polling scheme), so only a one way communication should take place. The server logs confirm that this scheme is chosen.

(To be 100% certain, I also set the values of ownPort=9090, ownAddress=10.0.1.192 (host ip) in the buildAgent-properties file, initialize the docker container with -p 9090:9090 and open the firewall on the local machine in port 9090/tcp in case the undirectional scheme is not 100% solid)

DagH

---- teamcity-server.log ----
[2017-08-30 14:39:28,654] WARN - jetbrains.buildServer.AGENT - While registering agent "NanoAgent-1" {id=0, protocol=unidirectional, host=10.0.1.182:9090, agentTypeId=0, registered since 2017-08-30 14:39:28.654}, found registered agent "CW2PUBLISERING4-1" {id=14, protocol=unidirectional, host=10.0.1.191:9090, agentTypeId=15, pool=Default, registered since 2017-08-30 09:30:48.713} with the same authorization token 'c79fb6c7ae3b0367f7b8a7f74fcc51a5'
[2017-08-30 14:39:28,654] INFO - jetbrains.buildServer.AGENT - New agent authorization token "b42df53397bbfbe2e34aa517f7138edd" was generated for agent "NanoAgent-1" {id=0}
[2017-08-30 14:39:28,654] INFO - jetbrains.buildServer.AGENT - Did not find agent by its authorization token 'b42df53397bbfbe2e34aa517f7138edd' and will search by name, agent details: "NanoAgent-1" {id=0}.
[2017-08-30 14:39:28,669] INFO - s.buildServer.ACTIVITIES.AUDIT - agent_unauthorize: Agent ""NanoAgent-1" {id=15}" was unauthorized with comment "Agent authorization token does not match the stored one."
[2017-08-30 14:39:28,685] INFO - jetbrains.buildServer.AGENT - Agent "NanoAgent-1" {id=15} is unauthorized because its authorization token (b42df53397bbfbe2e34aa517f7138edd) does not match the stored one (e8b837e9d5c43aa315e17743fd302c58).
[2017-08-30 14:39:28,685] INFO - jetbrains.buildServer.AGENT - Upgrade of agent "NanoAgent-1" {id=15} has been scheduled, agent version: 46961, plugins signature: NA. Current version: 46961, plugins signature: 46961-md5-f37268a77f597f4d2478c72526f7f6c5
[2017-08-30 14:39:28,701] INFO - jetbrains.buildServer.AGENT - Agent has been registered: "NanoAgent-1" {id=15, protocol=unidirectional, host=10.0.1.182:9090, agentTypeId=17, pool=Default, registered since 2017-08-30 14:39:28.654}, not running a build
[2017-08-30 14:39:28,701] INFO - ldServer.AGENT.PollingProtocol - Polling Agent session 'OkFFzdR...' was created, agent: "NanoAgent-1" {id=15}
[2017-08-30 14:39:28,794] WARN - jetbrains.buildServer.AGENT - Agent "NanoAgent-1" {id=15} is unauthorized on registration, last comment: Agent authorization token does not match the stored one.
[2017-08-30 14:39:29,326] INFO - jetbrains.buildServer.AGENT - Agent "NanoAgent-1" {id=15} has confirmed upgrade. Upgrade command has been sent to this agent 14 times.
[2017-08-30 14:39:29,373] INFO - ldServer.AGENT.PollingProtocol - Polling Agent session 'OkFFzdR...' was closed, agent: "NanoAgent-1" {id=15}
[2017-08-30 14:39:29,373] INFO - jetbrains.buildServer.AGENT - Agent "NanoAgent-1" {id=15} has been unregistered. Reason: Agent has unregistered (will upgrade)
[2017-08-30 14:39:43,137] INFO - s.buildServer.ACTIVITIES.AUDIT - agent_authorize: Agent "Unregistered agent "NanoAgent-1" {id=15}" was authorized by "'daghb' (Dag Håkon Baardsen) {id=14}"

After that:
[2017-08-30 14:51:42,333] INFO - jetbrains.buildServer.AGENT - Upgrade of agent "NanoAgent-1" {id=15} has been scheduled, agent version: 46961, plugins signature: NA. Current version: 46961, plugins signature: 46961-md5-f37268a77f597f4d2478c72526f7f6c5
[2017-08-30 14:51:42,333] INFO - jetbrains.buildServer.AGENT - Agent has been registered: "NanoAgent-1" {id=15, protocol=unidirectional, host=10.0.1.182:9090, agentTypeId=17, pool=Default, registered since 2017-08-30 14:51:42.302}, not running a build
[2017-08-30 14:51:42,349] INFO - ldServer.AGENT.PollingProtocol - Polling Agent session '6NMiOgY...' was created, agent: "NanoAgent-1" {id=15}
[2017-08-30 14:51:42,411] INFO - jetbrains.buildServer.AGENT - Agent "NanoAgent-1" {id=15} has confirmed upgrade. Upgrade command has been sent to this agent 16 times.
[2017-08-30 14:51:42,442] INFO - ldServer.AGENT.PollingProtocol - Polling Agent session '6NMiOgY...' was closed, agent: "NanoAgent-1" {id=15}
[2017-08-30 14:51:42,458] INFO - jetbrains.buildServer.AGENT - Agent "NanoAgent-1" {id=15} has been unregistered. Reason: Agent has unregistered (will upgrade)

---- teamcity-winservice.log ----
[2017-08-30 14:39:28,716] console [Info] [2017-08-30 14:39:28,654] WARN - jetbrains.buildServer.AGENT - While registering agent "NanoAgent-1" {id=0, protocol=unidirectional, host=10.0.1.182:9090, agentTypeId=0, registered since 2017-08-30 14:39:28.654}, found registered agent "CW2PUBLISERING4-1" {id=14, protocol=unidirectional, host=10.0.1.191:9090, agentTypeId=15, pool=Default, registered since 2017-08-30 09:30:48.713} with the same authorization token 'c79fb6c7ae3b0367f7b8a7f74fcc51a5'
[2017-08-30 14:39:28,826] console [Info] [2017-08-30 14:39:28,794] WARN - jetbrains.buildServer.AGENT - Agent "NanoAgent-1" {id=15} is unauthorized on registration, last comment: Agent authorization token does not match the stored one.

Dagh

Created August 30, 2017 14:04

Ah, the problem was with the VPN. I guess the bindings do not work as I foresee, so I have to dive into it. I ran the nanoserver/tcbuildagent container closer to the server and it worked.

Please sign in to leave a comment.