search

JetBrains / teamcity-azure-agent

TeamCity support for Azure cloud build agents
Apache License 2.0
48 stars 22 forks source link

Azure Classic, Start-Stop Mode - Agent connects as "unauthorized" #30

Closed PashaPash closed 8 years ago

PashaPash commented 8 years ago

Cloud agent connects as "Unauthorized" if started by azure service.

Teamcity successfully started the VM, Agent went to "upgrading" state, then to "unauthorized". image

Agent is displayed as "Launched" on Cloud tab:

image

but it not available on new build dialog, so it seems to stuck in some "starting" state: image

teamcity-clouds.log:

[2016-08-01 16:58:50,570]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Exit: 30 
[2016-08-01 16:58:50,570]   INFO ['{id=azure-1} 1] - louds.base.AbstractCloudClient - Cloud profile 'profile 'Azure'{id=azure-1}' initialized 
[2016-08-01 16:58:50,967]   INFO [uled executor 2] - .server.impl.CloudEventsLogger - Cloud instance entered 'stopped' state, profile 'Azure'{id=azure-1}, AzureCloudInstance{myName='azbuild-d2-1'} 
[2016-08-01 16:58:51,028]   WARN [1 Flush Queue 1] - e.impl.FlushQueueVirtualAction - Failed to start agent. Unable to find agent type by key: azure/azure-1/azbuild-d2-1 
[2016-08-01 16:58:56,031]   INFO [6 Flush Queue 1] - .instances.StartInstanceAction - Starting cloud instance: profile 'Azure'{id=azure-1}, AzureCloudImage{myName='azbuild-d2-1'}, hash=LbfymWcVZVvs62kqLCIzkRFVBcHFS9rN, reason=Automatic start: Start instance to get instance agent details 
[2016-08-01 16:58:56,032]   INFO [6 Flush Queue 1] - uds.base.AbstractCloudInstance - Changing azbuild-d2-1(54a8f3) status from Stopped to Scheduled to start  
[2016-08-01 16:58:56,033]   INFO [6 Flush Queue 1] - re.connector.ConditionalRunner - Added conditional 'Start handler of 'start new instance: azbuild-d2-1'' 
[2016-08-01 16:58:56,033]   WARN [6 Flush Queue 1] - .instances.StoppedInstanceTask - Instance has changed status from stopped to Scheduled to start: AzureCloudInstance{myName='azbuild-d2-1'}, profile 'Azure'{id=azure-1} 
[2016-08-01 16:58:56,033]   INFO [6 Flush Queue 1] - .server.impl.CloudEventsLogger - Cloud instance start succeeded: profile 'Azure'{id=azure-1}, AzureCloudInstance{myName='azbuild-d2-1'} 
[2016-08-01 16:58:58,134]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Enter: 31, getDetailedAsync 
[2016-08-01 16:58:58,134]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(31):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/services/hostedservices/logicbuild3?embed-detail=true 
[2016-08-01 16:58:59,322]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(31):
<HostedService ...> 
[2016-08-01 16:58:59,323]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Exit: 31 
[2016-08-01 16:58:59,323]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Enter: 32, beginStartingAsync 
[2016-08-01 16:58:59,325]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(32):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/services/hostedservices/logicbuild3/deployments/azbuild-d2-1/roleinstances/azbuild-d2-1/Operations 
[2016-08-01 16:59:00,970]   INFO [uled executor 1] - .server.impl.CloudEventsLogger - Cloud instance entered 'scheduled to start' state, profile 'Azure'{id=azure-1}, AzureCloudInstance{myName='azbuild-d2-1'} 
[2016-08-01 16:59:01,000]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(32):

[2016-08-01 16:59:01,001]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Exit: 32 
[2016-08-01 16:59:01,001]   INFO ['{id=azure-1} 1] - uds.base.AbstractCloudInstance - Changing azbuild-d2-1(54a8f3) status from Scheduled to start to Starting  
[2016-08-01 16:59:01,001]   INFO ['{id=azure-1} 1] - re.connector.ConditionalRunner - Added conditional 'Finish handler of 'start new instance: azbuild-d2-1'' 
[2016-08-01 16:59:01,001]   INFO ['{id=azure-1} 1] - re.connector.ConditionalRunner - Executing Start handler of 'start new instance: azbuild-d2-1'. Result: true 
[2016-08-01 16:59:05,970]   INFO [uled executor 4] - .server.impl.CloudEventsLogger - Cloud instance entered 'starting' state, profile 'Azure'{id=azure-1}, AzureCloudInstance{myName='azbuild-d2-1'} 
[2016-08-01 16:59:06,002]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Enter: 33, getOperationStatusAsync 
[2016-08-01 16:59:06,002]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(33):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/operations/78d42c3931610daa8155a743d7eacbaf 
[2016-08-01 16:59:07,128]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(33):
<Operation xmlns="http://schemas.microsoft.com/windowsazure" xmlns:i="http://www.w3.org/2001/XMLSchema-instance"><ID>78d42c39-3161-0daa-8155-a743d7eacbaf</ID><Status>InProgress</Status></Operation> 
[2016-08-01 16:59:07,130]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Exit: 33 
[2016-08-01 16:59:08,134]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Enter: 34, getOperationStatusAsync 
[2016-08-01 16:59:08,134]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(34):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/operations/78d42c3931610daa8155a743d7eacbaf 
[2016-08-01 16:59:09,488]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(34):
<Operation xmlns="http://schemas.microsoft.com/windowsazure" xmlns:i="http://www.w3.org/2001/XMLSchema-instance"><ID>78d42c39-3161-0daa-8155-a743d7eacbaf</ID><Status>InProgress</Status></Operation> 
[2016-08-01 16:59:09,489]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Exit: 34 
[2016-08-01 16:59:12,130]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Enter: 35, getOperationStatusAsync 
[2016-08-01 16:59:12,130]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(35):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/operations/78d42c3931610daa8155a743d7eacbaf 
[2016-08-01 16:59:13,408]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(35):
<Operation xmlns="http://schemas.microsoft.com/windowsazure" xmlns:i="http://www.w3.org/2001/XMLSchema-instance"><ID>78d42c39-3161-0daa-8155-a743d7eacbaf</ID><Status>InProgress</Status></Operation> 
[2016-08-01 16:59:13,409]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Exit: 35 
[2016-08-01 16:59:18,411]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Enter: 36, getOperationStatusAsync 
[2016-08-01 16:59:18,411]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(36):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/operations/78d42c3931610daa8155a743d7eacbaf 
[2016-08-01 16:59:19,549]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(36):
<Operation xmlns="http://schemas.microsoft.com/windowsazure" xmlns:i="http://www.w3.org/2001/XMLSchema-instance"><ID>78d42c39-3161-0daa-8155-a743d7eacbaf</ID><Status>Succeeded</Status><HttpStatusCode>200</HttpStatusCode></Operation> 
[2016-08-01 16:59:19,550]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Exit: 36 
[2016-08-01 16:59:19,550]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Enter: 37, getOperationStatusAsync 
[2016-08-01 16:59:19,550]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(37):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/operations/78d42c3931610daa8155a743d7eacbaf 
[2016-08-01 16:59:20,639]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Request(37):
<Operation xmlns="http://schemas.microsoft.com/windowsazure" xmlns:i="http://www.w3.org/2001/XMLSchema-instance"><ID>78d42c39-3161-0daa-8155-a743d7eacbaf</ID><Status>Succeeded</Status><HttpStatusCode>200</HttpStatusCode></Operation> 
[2016-08-01 16:59:20,640]   INFO ['{id=azure-1} 2] - sm.connector.AzureApiConnector - Exit: 37 
[2016-08-01 16:59:20,640]   INFO ['{id=azure-1} 2] - uds.base.AbstractCloudInstance - Changing azbuild-d2-1(54a8f3) status from Starting to Running  
[2016-08-01 16:59:20,640]   INFO ['{id=azure-1} 2] - re.connector.ConditionalRunner - Executing Finish handler of 'start new instance: azbuild-d2-1'. Result: true 
[2016-08-01 16:59:20,974]   INFO [uled executor 2] - .server.impl.CloudEventsLogger - Cloud instance entered 'running' state, profile 'Azure'{id=azure-1}, AzureCloudInstance{myName='azbuild-d2-1'} 
[2016-08-01 16:59:50,571]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Enter: 38, getDetailedAsync 
[2016-08-01 16:59:50,571]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(38):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/services/hostedservices/logicbuild3?embed-detail=true 
[2016-08-01 16:59:51,802]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(38):
<HostedService ...> 
[2016-08-01 16:59:51,803]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Exit: 38 
[2016-08-01 17:00:51,804]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Enter: 39, getDetailedAsync 
[2016-08-01 17:00:51,804]   INFO ['{id=azure-1} 1] - sm.connector.AzureApiConnector - Request(39):
https://management.core.windows.net/2aff8090-921d-45a7-accb-73cbc9e3ad5a/services/hostedservices/logicbuild3?embed-detail=true

then just a number of repeated getDetailedAsync calls.

Agent-side log:

[2016-08-01 14:03:57,085]   INFO - s.buildServer.agent.AgentMain2 - =========================================================== 
[2016-08-01 14:03:57,100]   INFO - s.buildServer.agent.AgentMain2 - TeamCity Build Agent 10.0 (build 42002), OS: Windows Server 2012 R2, User: Logic, Java: 1.8.0_66, Java HotSpot(TM) Client VM (32 bit) (25.66-b17, mixed mode), Java(TM) SE Runtime Environment (1.8.0_66-b17), Oracle Corporation, JVM parameters: -ea -Xmx512m -XX:+HeapDumpOnOutOfMemoryError -Xrs -Dlog4j.configuration=file:../conf/teamcity-agent-log4j.xml -Dteamcity_logs=../logs/ 
[2016-08-01 14:03:57,100]   INFO - s.buildServer.agent.AgentMain2 - Starting... 
[2016-08-01 14:03:57,178]   INFO - buildServer.agent.AgentMain2$2 - Refreshing jetbrains.buildServer.agent.AgentMain2$2@c03f1f: startup date [Mon Aug 01 14:03:57 UTC 2016]; root of context hierarchy 
[2016-08-01 14:03:58,194]   INFO -    jetbrains.buildServer.AGENT - Calculating CPU benchmark index... 
[2016-08-01 14:04:04,671]   INFO -    jetbrains.buildServer.AGENT - CPU benchmark index is set to 497 
[2016-08-01 14:04:04,842]   INFO - dAgentConfigurationInitializer - Loading build agent configuration from C:\BuildAgent\conf\buildAgent.properties 
[2016-08-01 14:04:04,889]   INFO - s.buildServer.agent.AgentMain2 - Working dir: C:\W 
[2016-08-01 14:04:04,889]   INFO - s.buildServer.agent.AgentMain2 - Temp dir: C:\BuildAgent\temp 
[2016-08-01 14:04:04,889]   INFO - ugins.files.PluginsRemoverImpl - Removing plugin: C:\BuildAgent\plugins\cloud-azure 
[2016-08-01 14:04:04,889]   INFO - ugins.files.PluginsRemoverImpl - Removing plugin: C:\BuildAgent\tools\NuGet.CommandLine.1.6.0 
[2016-08-01 14:04:04,967]   INFO - ugins.files.PluginsRemoverImpl - Removing plugin: C:\BuildAgent\tools\NuGet.CommandLine.2.8.1 
[2016-08-01 14:04:04,983]   INFO - rver.plugins.PluginManagerImpl - =========================================================== 
[2016-08-01 14:04:04,983]   INFO - rver.plugins.PluginManagerImpl - Plugins initialization started... 
[2016-08-01 14:04:04,983]   INFO - rver.plugins.PluginManagerImpl - Scanning plugins folders 
[2016-08-01 14:04:05,014]   INFO - ugins.files.NewPluginsUnpacker - Unpacking plugin "C:\BuildAgent\plugins\cloud-azure.zip" (size: 19902) to "C:\BuildAgent\plugins\cloud-azure", unpack prefix "" 
[2016-08-01 14:04:05,014]   INFO - .plugins.files.JarSearcherBase - Scanning plugin folder: C:\BuildAgent\plugins 
[2016-08-01 14:04:05,092]   INFO - .plugins.files.JarSearcherBase - Scanning plugin folder: C:\BuildAgent\tools 
[2016-08-01 14:04:05,124]   INFO - rver.plugins.PluginManagerImpl - Found 59 non bundled plugins: [agentSystemInfo, amazonEC2, ant, ant-net-tasks, antPlugin, clearcase-agent, cloud-azure, cloud-vmware-agent, commandLineRunner, coveragePlugin, crashDetector, cvsAgent, deploy-runner-agent, dotCover, dotnet-tools, dotnetPlugin, dotNetRunners, duplicatePlugin, environment-fetcher, file-content-replacer, fxcop, gant, gantPlugin, gradle-runner, idea, idea-runner, inspectionPlugin, ipr-runner, jacoco, java-dowser, jetbrains.git, jps, jps-old, junitPlugin, jvm-update, maven, maven3, maven3_1, maven3_2, maven3_3, mavenPlugin, mercurial, meta-runner, nuget-agent, perfmon, perforce-agent, powershell-agent, rake-runner, remoteAccess, sbt-runner-agent, ssh-manager, stacktracesPlugin, svnAgent, swabra, testNGPlugin, tfs-agent, visualstudiotest, xcode-runner, xml-report-plugin] 
[2016-08-01 14:04:05,124]   INFO - rver.plugins.PluginManagerImpl - Found 0 bundled plugins: [] 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\ant 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\antRun 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\ant.bat 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\ant.cmd 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\antenv.cmd 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\envset.cmd 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\lcp.bat 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\runrc.cmd 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\antRun.pl 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\complete-ant-cmd.pl 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\runant.pl 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\plugins\ant\bin\runant.py 
[2016-08-01 14:04:05,124]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\tools\maven3\bin\mvn 
[2016-08-01 14:04:05,139]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\tools\maven3_1\bin\mvn 
[2016-08-01 14:04:05,139]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\tools\maven\bin\mvn 
[2016-08-01 14:04:05,139]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\tools\maven3_2\bin\mvn 
[2016-08-01 14:04:05,139]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\tools\gant\bin\gant 
[2016-08-01 14:04:05,139]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\tools\gant\bin\startGroovy 
[2016-08-01 14:04:05,139]   INFO - les.ExecutableAttributesSetter - Setting executable bit for: C:\BuildAgent\tools\maven3_3\bin\mvn 
[2016-08-01 14:04:05,139]   INFO - rver.plugins.PluginsCollection - Load shared classloader for 25 plugins [agentSystemInfo, amazonEC2, ant, clearcase-agent, commandLineRunner, crashDetector, cvsAgent, dotnet-tools, dotnetPlugin, dotNetRunners, environment-fetcher, file-content-replacer, fxcop, gradle-runner, java-dowser, jetbrains.git, mercurial, perfmon, powershell-agent, remoteAccess, ssh-manager, stacktracesPlugin, swabra, tfs-agent, xml-report-plugin] 
[2016-08-01 14:04:05,171]   INFO - rver.plugins.PluginsCollection - Load standalone classloaders for 22 plugins [antPlugin, cloud-azure, cloud-vmware-agent, coveragePlugin, deploy-runner-agent, duplicatePlugin, gantPlugin, idea-runner, inspectionPlugin, ipr-runner, junitPlugin, jvm-update, mavenPlugin, meta-runner, nuget-agent, perforce-agent, rake-runner, sbt-runner-agent, svnAgent, testNGPlugin, visualstudiotest, xcode-runner] 
[2016-08-01 14:04:05,514]   INFO - .vmware.VMWarePropertiesReader - VSphere plugin initializing... 
[2016-08-01 14:04:05,514]   INFO - .vmware.VMWarePropertiesReader - Unable to locate vmware-rpctool. Looks like not a VMWare VM or VWWare tools are not installed 
[2016-08-01 14:04:07,171]   INFO - ds.azure.AzurePropertiesReader - Azure plugin initializing... 
[2016-08-01 14:04:07,561]   INFO - rver.plugins.PluginManagerImpl - Plugins initialization completed: 
[2016-08-01 14:04:07,561]   INFO - rver.plugins.PluginManagerImpl - Loaded 59 plugins: [agentSystemInfo, amazonEC2, ant, ant-net-tasks, antPlugin, clearcase-agent, cloud-azure, cloud-vmware-agent, commandLineRunner, coveragePlugin, crashDetector, cvsAgent, deploy-runner-agent, dotCover, dotnet-tools, dotnetPlugin, dotNetRunners, duplicatePlugin, environment-fetcher, file-content-replacer, fxcop, gant, gantPlugin, gradle-runner, idea, idea-runner, inspectionPlugin, ipr-runner, jacoco, java-dowser, jetbrains.git, jps, jps-old, junitPlugin, jvm-update, maven, maven3, maven3_1, maven3_2, maven3_3, mavenPlugin, mercurial, meta-runner, nuget-agent, perfmon, perforce-agent, powershell-agent, rake-runner, remoteAccess, sbt-runner-agent, ssh-manager, stacktracesPlugin, svnAgent, swabra, testNGPlugin, tfs-agent, visualstudiotest, xcode-runner, xml-report-plugin] 
[2016-08-01 14:04:07,561]   INFO - rver.plugins.PluginManagerImpl - =========================================================== 
[2016-08-01 14:04:07,592]   INFO -    jetbrains.buildServer.AGENT - Build Agent version: 42002, plugins signature: 42002-md5-a88c7cc9701b920eb9ee7aab7f17c2f9 
[2016-08-01 14:04:07,639]   INFO - ggers.vcs.mercurial.HgDetector - Cannot detect installed mercurial 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 2.0(2.0.50727) x32 at C:\Windows\Microsoft.NET\Framework\v2.0.50727 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 3.0(3.0.30729.4926) x32 at C:\Windows\Microsoft.NET\Framework\v3.0 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 3.5(3.5.30729.4926) x32 at C:\Windows\Microsoft.NET\Framework\v3.5 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 4.6(4.6.01055) x32 at C:\Windows\Microsoft.NET\Framework\v4.0.30319 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 2.0(2.0.50727) x64 at C:\Windows\Microsoft.NET\Framework64\v2.0.50727 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 3.0(3.0.30729.4926) x64 at C:\Windows\Microsoft.NET\Framework64\v3.0 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 3.5(3.5.30729.4926) x64 at C:\Windows\Microsoft.NET\Framework64\v3.5 
[2016-08-01 14:04:09,557]   INFO - etFrameworkPropertiesExtension - Found .Net Framework runtime 4.6(4.6.01055) x64 at C:\Windows\Microsoft.NET\Framework64\v4.0.30319 
[2016-08-01 14:04:09,796]   INFO - javaDowser.JavaDowserAgentImpl - JavaDowser: Found 1 java installations:
    1.7/32 (1.7.0_55) at C:\Program Files (x86)\Java\jdk1.7.0_55 (JDK) [200] 
[2016-08-01 14:04:09,893]   INFO - gent.detect.PowerShellDetector - Found: PowerShell v4.0 x86(C:\Windows\SysWOW64\WindowsPowerShell\v1.0) 
[2016-08-01 14:04:10,002]   INFO - gent.detect.PowerShellDetector - Found: PowerShell v4.0 x64(C:\Windows\System32\WindowsPowerShell\v1.0) 
[2016-08-01 14:04:10,002]   INFO - dAgentConfigurationInitializer - Loading build agent configuration from C:\BuildAgent\conf\buildAgent.properties 
[2016-08-01 14:04:10,049]   INFO - r.mono.MonoPropertiesExtension - HKLM\SOFTWARE\Novell\Mono\DefaultCLR wasn't found => no mono 
[2016-08-01 14:04:17,078]   INFO - n.AmazonInstanceMetadataReader - Amazon is not available. Amazon EC2 integration is not active: Failed to connect to http://169.254.169.254/latest. The host did not accept the connection within timeout of 7000 ms 
[2016-08-01 14:04:17,078]   INFO - .agent.AmazonPropertiesUpdater - Fetched AmazonEC2 instance metadata:  
[2016-08-01 14:04:17,078]   INFO - zon.agent.AmazonMetadataChecks - Amazon EC instance metadata contains no keys 
[2016-08-01 14:04:17,078]   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? 
[2016-08-01 14:04:17,140]   INFO - .agent.AgentStartupGitDetector - Detect git at C:\Program Files\Git\bin\git.exe 
[2016-08-01 14:04:17,140]   INFO - ver.clouds.azure.FileUtilsImpl - Parent directory not found at C:\AzureData 
[2016-08-01 14:04:17,140]   INFO - ouds.azure.WindowsConfigReader - Azure custom data file C:\AzureData\CustomData.bin is empty: integration is disabled 
[2016-08-01 14:04:17,234]   INFO - .agent.impl.OsArchBitsDetector - Detecting via "wmic computersystem get systemtype", exit code: 0, output: SystemType x64-based PC 
[2016-08-01 14:04:17,234]   INFO - .agent.impl.OsArchBitsDetector - "teamcity.agent.os.arch.bits" detected as "64" 
[2016-08-01 14:04:17,234]   INFO - cher.DotNetPropertiesExtension - Start Microsoft .NET Framework SDK Search 
[2016-08-01 14:04:17,297]   INFO - cher.DotNetPropertiesExtension - Finished Microsoft .NET Framework SDK Search 
[2016-08-01 14:04:17,297]   INFO - cher.DotNetPropertiesExtension - Start Microsoft Visual Studio Search 
[2016-08-01 14:04:17,515]   INFO - cher.DotNetPropertiesExtension - Found Microsoft Visual Studio 2015 at C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE, reporting parameters: {VS2015=14.0.24720.0, VS2015_Path=C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE} 
[2016-08-01 14:04:17,515]   INFO - cher.DotNetPropertiesExtension - Found Microsoft Visual Studio 2010 at C:\Program Files (x86)\Microsoft Visual Studio 10.0\Common7\IDE, reporting parameters: {VS2010=10.0.40219.1, VS2010_Path=C:\Program Files (x86)\Microsoft Visual Studio 10.0\Common7\IDE} 
[2016-08-01 14:04:17,515]   INFO - cher.DotNetPropertiesExtension - Finished Microsoft Visual Studio Search 
[2016-08-01 14:04:17,515]   INFO - cher.DotNetPropertiesExtension - Start Microsoft Windows SDK Search 
[2016-08-01 14:04:18,618]   INFO - earcher.sdk.WindowsSDKSearcher - Windows SDK found: 8.1.51641,10.0.10586.0,8.0,7.1.51106,6.2..9200,6.3..9600 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Found Windows SDK v10.0, reporting parameters: {WindowsSDKv10.0_Path=C:\Program Files (x86)\Windows Kits\10, WindowsSDKv10.0=10.0.10586.0} 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Found Windows SDK v7.1A, reporting parameters: {WindowsSDKv7.1A=7.1.51106, WindowsSDKv7.1A_Path=C:\Program Files (x86)\Microsoft SDKs\Windows\v7.1A} 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Found Windows SDK v8.0, reporting parameters: {WindowsSDKv8.0_Path=C:\Program Files (x86)\Windows Kits\8.0, WindowsSDKv8.0=6.2..9200} 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Found Windows SDK v8.1, reporting parameters: {WindowsSDKv8.1=6.3..9600, WindowsSDKv8.1_Path=C:\Program Files (x86)\Windows Kits\8.1} 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Found Windows SDK v8.1A, reporting parameters: {WindowsSDKv8.1A_Path=C:\Program Files (x86)\Microsoft SDKs\Windows\v8.1A, WindowsSDKv8.1A=8.1.51641} 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Found Windows SDK 8.0, reporting parameters: {WindowsSDK8.0_Path=C:\Program Files (x86)\Windows Kits\8.0, WindowsSDK8.0=8.0} 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Finished Microsoft Windows SDK Search 
[2016-08-01 14:04:18,618]   INFO - cher.DotNetPropertiesExtension - Start MSBuild Search 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 12.0 (x86) at C:\Program Files (x86)\MSBuild\12.0\bin, reporting parameters: {MSBuildTools12.0_x86_Path=C:\Program Files (x86)\MSBuild\12.0\bin} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 14.0 (x86) at C:\Program Files (x86)\MSBuild\14.0\bin, reporting parameters: {MSBuildTools14.0_x86_Path=C:\Program Files (x86)\MSBuild\14.0\bin} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 2.0 (x86) at C:\Windows\Microsoft.NET\Framework\v2.0.50727, reporting parameters: {MSBuildTools2.0_x86_Path=C:\Windows\Microsoft.NET\Framework\v2.0.50727} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 3.5 (x86) at C:\Windows\Microsoft.NET\Framework\v3.5, reporting parameters: {MSBuildTools3.5_x86_Path=C:\Windows\Microsoft.NET\Framework\v3.5} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 4.0 (x86) at C:\Windows\Microsoft.NET\Framework\v4.0.30319, reporting parameters: {MSBuildTools4.0_x86_Path=C:\Windows\Microsoft.NET\Framework\v4.0.30319} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 12.0 (x64) at C:\Program Files (x86)\MSBuild\12.0\bin\amd64, reporting parameters: {MSBuildTools12.0_x64_Path=C:\Program Files (x86)\MSBuild\12.0\bin\amd64} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 14.0 (x64) at C:\Program Files (x86)\MSBuild\14.0\bin\amd64, reporting parameters: {MSBuildTools14.0_x64_Path=C:\Program Files (x86)\MSBuild\14.0\bin\amd64} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 2.0 (x64) at C:\Windows\Microsoft.NET\Framework64\v2.0.50727, reporting parameters: {MSBuildTools2.0_x64_Path=C:\Windows\Microsoft.NET\Framework64\v2.0.50727} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 3.5 (x64) at C:\Windows\Microsoft.NET\Framework64\v3.5, reporting parameters: {MSBuildTools3.5_x64_Path=C:\Windows\Microsoft.NET\Framework64\v3.5} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Found MSBuild Toolset 4.0 (x64) at C:\Windows\Microsoft.NET\Framework64\v4.0.30319, reporting parameters: {MSBuildTools4.0_x64_Path=C:\Windows\Microsoft.NET\Framework64\v4.0.30319} 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Finished MSBuild Search 
[2016-08-01 14:04:18,987]   INFO - cher.DotNetPropertiesExtension - Start MSTest Searcher 
[2016-08-01 14:04:19,534]   INFO - cher.DotNetPropertiesExtension - Found MSTest 14.0, reporting parameters: {teamcity.dotnet.mstest.14.0=C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE\MSTest.exe} 
[2016-08-01 14:04:19,534]   INFO - cher.DotNetPropertiesExtension - Finished MSTest Searcher 
[2016-08-01 14:04:19,534]   INFO - cher.DotNetPropertiesExtension - Start Microsoft .NET Framework Target Packs Search 
[2016-08-01 14:04:19,674]   INFO - NetFrameworkTargetPackDetector - .NET Framework Target Pack found: .NET Framework Target Pack 2.0,.NET Framework Target Pack 4.0,.NET Framework Target Pack 3.5,.NET Framework Target Pack 4.5,.NET Framework Target Pack 4.5.1,.NET Framework Target Pack 4.6,.NET Framework Target Pack 4.5.2,.NET Framework Target Pack 4.6.1 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 2.0, reporting parameters: {DotNetFrameworkTargetingPack2.0_Path=C:\Windows\Microsoft.NET\Framework\v2.0.50727} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 4.0, reporting parameters: {DotNetFrameworkTargetingPack4.0_Path=C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.0} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 3.5, reporting parameters: {DotNetFrameworkTargetingPack3.5_Path=C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v3.5} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 4.5, reporting parameters: {DotNetFrameworkTargetingPack4.5_Path=C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 4.5.1, reporting parameters: {DotNetFrameworkTargetingPack4.5.1_Path=C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.1} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 4.6, reporting parameters: {DotNetFrameworkTargetingPack4.6_Path=C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.6} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 4.5.2, reporting parameters: {DotNetFrameworkTargetingPack4.5.2_Path=C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.5.2} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Found .NET Framework Target Pack 4.6.1, reporting parameters: {DotNetFrameworkTargetingPack4.6.1_Path=C:\Program Files (x86)\Reference Assemblies\Microsoft\Framework\.NETFramework\v4.6.1} 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Finished Microsoft .NET Framework Target Packs Search 
[2016-08-01 14:04:19,674]   INFO - cher.DotNetPropertiesExtension - Start VSTest.Console Searcher 
[2016-08-01 14:04:19,831]   INFO - cher.DotNetPropertiesExtension - Found VSTest 2015 at C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE\CommonExtensions\Microsoft\TestWindow, reporting parameters: {teamcity.dotnet.vstest.14.0=C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE\CommonExtensions\Microsoft\TestWindow\vstest.console.exe} 
[2016-08-01 14:04:19,831]   INFO - cher.DotNetPropertiesExtension - Finished VSTest.Console Searcher 
[2016-08-01 14:04:19,862]   INFO - rver.fxcop.agent.FxCopSearcher - .fxcop file association wasn't found in CLASSES_ROOT 
[2016-08-01 14:04:19,862]   INFO - rver.fxcop.agent.FxCopSearcher - FxCopCmd.exe found at path "C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\IDE\..\..\Team Tools\Static Analysis Tools\FxCop\FxCopCmd.exe" 
[2016-08-01 14:04:19,862]   INFO - rver.fxcop.agent.FxCopSearcher - Found FxCopCmd file version: 14.0.23107.0 
[2016-08-01 14:04:19,862]   INFO -    jetbrains.buildServer.AGENT - Start build agent 
[2016-08-01 14:04:19,909]   INFO -    jetbrains.buildServer.AGENT - Agent Web server started on port 9091 
[2016-08-01 14:04:19,909]   INFO - agent.impl.AgentPortFileWriter - Writing agent runtime file to C:\BuildAgent\logs\buildAgent.xmlRpcPort 
[2016-08-01 14:04:19,909]   INFO - agent.impl.AgentPortFileWriter - Launcher version is 42002 
[2016-08-01 14:04:19,909]   INFO - agent.impl.AgentPortFileWriter - Writing agent runtime file to C:\BuildAgent\logs\buildAgent.xmlRpcPort :DONE! 
[2016-08-01 14:04:19,924]   INFO -    jetbrains.buildServer.AGENT - Build agent started 
[2016-08-01 14:04:20,413]   INFO - r.artifacts.impl.HttpDiskCache - Cleaning up items with life time in cache greater than 172800 seconds 
[2016-08-01 14:04:20,413]   INFO - r.artifacts.impl.HttpDiskCache - Finished cleaning up expired items, 0 items removed 
[2016-08-01 14:04:20,413]   INFO - dDirectoryBasedCleanupRegistry - Removing files from C:\W\.old 
[2016-08-01 14:04:20,456]   INFO - l.directories.DirectoryMapImpl - Cleaning up old checkout directories. Default lifetime = 192 hour(s) 
[2016-08-01 14:04:20,487]   INFO - dDirectoryBasedCleanupRegistry - Removing files from C:\BuildAgent\temp\.old 
[2016-08-01 14:04:20,752]   INFO - se.agent.ClearCaseAgentSupport - ClearCase agent checkout is disabled: Could not find executable: 'cleartool'. Original message: Cannot run program "cleartool" (in directory "."): CreateProcess error=2, The system cannot find the file specified 
[2016-08-01 14:04:20,768]   INFO - buildServer.AGENT.registration - Registering on server http://dev.logicsoftware.net:8888, AgentDetails{Name='azbuild-d2-1', AgentId=null, BuildId=null, AgentOwnAddress='logicbuild3.cloudapp.net', AlternativeAddresses=[10.95.248.33, 2001:0:9d38:90d7:10dd:fbff:d786:64c0], Port=9091, Version='42002', PluginsVersion='42002-md5-a88c7cc9701b920eb9ee7aab7f17c2f9', AvailableRunners=[Ant, cargo-deploy-runner, dotnet-tools-dupfinder, dotnet-tools-inspectcode, Duplicator, ftp-deploy-runner, FxCop, gradle-runner, Inspection, Ipr, jb.nuget.installer, jb.nuget.pack, jb.nuget.publish, jetbrains.dotNetGenericRunner, jetbrains.mspec, jetbrains_powershell, JPS, Maven2, MSBuild, NAnt, NUnit, rake-runner, SBT, simpleRunner, sln2003, smb-deploy-runner, ssh-deploy-runner, ssh-exec-runner, VisualStudioTest, VS.Solution], AvailableVcs=[tfs, cvs, jetbrains.git, mercurial, svn, perforce], AuthorizationToken='67ea397fb82641cb2d2cfa03a5a8adbe', PingCode='gVvLThFFW2FUNrdxIH4AAj3LARgvuza3'} 
[2016-08-01 14:04:21,167]   INFO - buildServer.AGENT.registration - Server supports the following communication protocols: [polling, xml-rpc] 
[2016-08-01 14:04:21,167]   INFO - buildServer.AGENT.registration - Trying to register using 'polling' protocol. 
[2016-08-01 14:04:21,722]   INFO - buildServer.AGENT.registration - Registered: id:1, authorizationToken:67ea397fb82641cb2d2cfa03a5a8adbe 
[2016-08-01 14:04:21,722]   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. 
[2016-08-01 14:04:21,722]   INFO - ldServer.AGENT.PollingProtocol - Start polling server for commands 
[2016-08-01 14:04:21,870]   INFO - ldServer.AGENT.PollingProtocol - New command is received from server "testLocal" {id = 1} 
[2016-08-01 14:04:24,491]   INFO -    jetbrains.buildServer.AGENT - Updating agent parameters on the server: AgentDetails{Name='azbuild-d2-1', AgentId=1, BuildId=null, AgentOwnAddress='logicbuild3.cloudapp.net', AlternativeAddresses=[10.95.248.33, 2001:0:9d38:90d7:10dd:fbff:d786:64c0], Port=9091, Version='42002', PluginsVersion='42002-md5-a88c7cc9701b920eb9ee7aab7f17c2f9', AvailableRunners=[Ant, cargo-deploy-runner, dotnet-tools-dupfinder, dotnet-tools-inspectcode, Duplicator, ftp-deploy-runner, FxCop, gradle-runner, Inspection, Ipr, jb.nuget.installer, jb.nuget.pack, jb.nuget.publish, jetbrains.dotNetGenericRunner, jetbrains.mspec, jetbrains_powershell, JPS, Maven2, MSBuild, NAnt, NUnit, rake-runner, SBT, simpleRunner, sln2003, smb-deploy-runner, ssh-deploy-runner, ssh-exec-runner, VisualStudioTest, VS.Solution], AvailableVcs=[tfs, cvs, jetbrains.git, mercurial, svn, perforce], AuthorizationToken='67ea397fb82641cb2d2cfa03a5a8adbe', PingCode='gVvLThFFW2FUNrdxIH4AAj3LARgvuza3'}

Could be related to #25, but I'm using pre-configured VM and it just starts and fails to authorize.

Please advise.

dtretyakov commented 8 years ago

@PashaPash, thanks for reporting, we'll check this case.

PashaPash commented 8 years ago

@dtretyakov I also noticed that cloud instance is now marked with exclamation mark / "No agents connected after instance start" and it remains in that state even if agent is manually started/connected/authorized.

It seems that TeamCity just cannot match the cloud instance with the connected agent. Please let me know if you will need any additional info to reproduce the issue.

PashaPash commented 8 years ago

@dtretyakov it seems that I found a workaround - server-side plugin expects the azure.instance.name parameter set on agent side.

For image-based instances that parameter is passed as a part of a CloudData and mixed in to the agent properties by AgentConfigReader. For pre-configured VMs that parameter remains blank (because of no provisioning/no CloudData availble), and server-side plugin fails to match the agent with could instance.

Workaround is to manually specify that parameter in buildAgent.properties:

azure.instance.name=azbuild-d2-1
dtretyakov commented 8 years ago

@PashaPash, you can try to download latest azure classic plugin version, where automatic authorization was fixed: https://github.com/JetBrains/teamcity-azure-plugin#classic

PashaPash commented 8 years ago

@dtretyakov installed a new version, agent authorization works correctly now. Thanks for a quick fix!