search

JetBrains / teamcity-deployer-plugin

Deployer plugin for TeamCity CI server
http://confluence.jetbrains.net/display/TW/Deployer+plugin
Apache License 2.0
39 stars 29 forks source link

SMB Deployer hangs, repeated check for server messages in agent log #42

Open nskvortsov opened 9 years ago

nskvortsov commented 9 years ago

Not sure this is a deployer specific problem, but the deployer worked on August 20th and just hangs now. The plugin was updated recently, but I don't have a copy of the older version to validate that it still works. TeamCity version is 8.1.4.

#!java

[2014-09-17 13:42:04,713]  DEBUG -    jetbrains.buildServer.AGENT - Trying to connect with following parameters:
username=[*******]
domain=[SPILLMAN]
target=[smb://NGAGE/d$/repos/ServicesPlatform/] 
[2014-09-17 13:42:04,768]  DEBUG -    jetbrains.buildServer.AGENT - Uploading source=[/sti/work2/393e0d4867cfdff5/.gitignore] to 
destDirectory=[smb://NGAGE/d$/repos/ServicesPlatform/] destFile=[smb://NGAGE/d$/repos/ServicesPlatform/.gitignore] 
[2014-09-17 13:42:07,207]  DEBUG - r.agent.impl.AgentLogProxyImpl - Flush messages for AgentLogProxyImpl::executor 
[2014-09-17 13:42:07,207]  DEBUG - r.agent.impl.AgentLogProxyImpl - Later executor invocation for 3 remote commands, requestor: AgentLogProxyImpl::executor 
[2014-09-17 13:42:07,208]  DEBUG -   jetbrains.buildServer.XMLRPC - >>> XML-RPC request >>> 
[2014-09-17 13:42:07,208]  DEBUG -   jetbrains.buildServer.XMLRPC - <?xml version="1.0"?><methodCall><methodName>buildServer.log</methodName><params><param><value><![CDATA[969900]]></value></param><param><value><array><data><value><![CDATA[<bm><f2>ProgressStage</f2><f4>1410982922227</f4><v1 class="java.lang.String">Removing /sti/work2/393e0d4867cfdff5</v1></bm>]]></value><value><![CDATA[<bm><f2>ProgressStage</f2><f4>1410982922229</f4><v1 class="java.lang.String">Updating /sti/work2/393e0d4867cfdff5</v1></bm>]]></value></data></array></value></param></params></methodCall> 
[2014-09-17 13:42:07,212]  DEBUG -   jetbrains.buildServer.XMLRPC - <<< XML-RPC response <<< 
[2014-09-17 13:42:07,212]  DEBUG -   jetbrains.buildServer.XMLRPC - <?xml version="1.0"?><methodResponse><params><param><value><boolean>1</boolean></value></param></params></methodResponse> 
[2014-09-17 13:42:07,212]  DEBUG - r.agent.impl.AgentLogProxyImpl - Action performed 2 log messages for 969900 
[2014-09-17 13:42:07,213]  DEBUG -   jetbrains.buildServer.XMLRPC - >>> XML-RPC request >>> 
[2014-09-17 13:42:07,214]  DEBUG -   jetbrains.buildServer.XMLRPC - <?xml version="1.0"?><methodCall><methodName>buildServer.markCheckoutDirClean</methodName><params><param><value><![CDATA[969900]]></value></param></params></methodCall> 
[2014-09-17 13:42:07,658]  DEBUG -   jetbrains.buildServer.XMLRPC - <<< XML-RPC response <<< 
[2014-09-17 13:42:07,658]  DEBUG -   jetbrains.buildServer.XMLRPC - <?xml version="1.0"?><methodResponse><params><param><value><boolean>1</boolean></value></param></params></methodResponse> 
[2014-09-17 13:42:07,658]  DEBUG - r.agent.impl.AgentLogProxyImpl - Action performed markCheckoutDirClean for 969900 
[2014-09-17 13:42:07,659]  DEBUG -   jetbrains.buildServer.XMLRPC - >>> XML-RPC request >>> 
[2014-09-17 13:42:07,659]  DEBUG -   jetbrains.buildServer.XMLRPC - <?xml version="1.0"?><methodCall><methodName>buildServer.log</methodName><params><param><value><![CDATA[969900]]></value></param><param><value><array><data><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982923770</f4><v1 class="BlockData"><blockName>Updating sources</blockName><blockType>checkout</blockType></v1></bm>]]></value><value><![CDATA[<bm><f6>tc:internal</f6><f2>Text</f2><f4>1410982923770</f4><v1 class="java.lang.String">##teamcity[buildStatisticValue key=&apos;buildStageDuration:sourcesUpdate&apos; value=&apos;5953.0&apos;]</v1></bm>]]></value><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982923771</f4><v1 class="BlockData"><blockName></blockName><blockType>$BUILD_PROGRESS$</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982923771</f4><v1 class="BlockData"><blockName></blockName><blockType>$BUILD_PROGRESS$</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982923773</f4><v1 class="BlockData"><blockName></blockName><blockType>$BUILD_PROGRESS$</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982923780</f4><v1 class="BlockData"><blockName></blockName><blockType>$BUILD_PROGRESS$</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>BlockStart</f2><f4>1410982923781</f4><v1 class="BlockData"><blockName>Resolving artifact dependencies</blockName><blockType>agentResolvingArtifacts</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>Text</f2><f4>1410982923783</f4><v1 class="java.lang.String">Destination directory [/sti/work2/393e0d4867cfdff5/tcFunctions] does not exist, will be created</v1></bm>]]></value><value><![CDATA[<bm><f2>Text</f2><f4>1410982924066</f4><v1 class="java.lang.String">49 files retrieved from &lt;Agent Tools :: Plugins :: tcFunctions, build #407 [id 968323]&gt; for pattern [tcFunctions.zip!** =&gt; tcFunctions]</v1></bm>]]></value><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982924066</f4><v1 class="BlockData"><blockName>Resolving artifact dependencies</blockName><blockType>agentResolvingArtifacts</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982924067</f4><v1 class="BlockData"><blockName></blockName><blockType>$BUILD_PROGRESS$</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>PreparationEndStage</f2><f4>1410982924068</f4><v1 class="java.lang.String"></v1></bm>]]></value><value><![CDATA[<bm><f2>BlockEnd</f2><f4>1410982924069</f4><v1 class="BlockData"><blockName></blockName><blockType>$BUILD_PROGRESS$</blockType></v1></bm>]]></value><value><![CDATA[<bm><f2>BlockStart</f2><f4>1410982924069</f4><v1 class="BlockData"><blockName>Step 1/1</blockName><blockType>teamcity-build-step-type</blockType><blockDescription>SMB Deployer</blockDescription></v1></bm>]]></value><value><![CDATA[<bm><f6>tc:internal</f6><f2>Text</f2><f4>1410982924442</f4><v1 class="java.lang.String">##teamcity[buildStatisticValue key=&apos;buildStageDuration:firstStepPreparation&apos; value=&apos;672.0&apos;]</v1></bm>]]></value><value><![CDATA[<bm><f6>tc:internal</f6><f2>Text</f2><f4>1410982924443</f4><v1 class="java.lang.String">##teamcity[buildStatisticValue key=&apos;buildStageDuration:buildStepRUNNER_746&apos; value=&apos;0.0&apos;]</v1></bm>]]></value><value><![CDATA[<bm><f2>Text</f2><f4>1410982924713</f4><v1 class="java.lang.String">Starting upload via SMB to \\NGAGE\d$\repos\ServicesPlatform</v1></bm>]]></value></data></array></value></param></params></methodCall> 
[2014-09-17 13:42:07,665]  DEBUG -   jetbrains.buildServer.XMLRPC - <<< XML-RPC response <<< 
[2014-09-17 13:42:07,665]  DEBUG -   jetbrains.buildServer.XMLRPC - <?xml version="1.0"?><methodResponse><params><param><value><boolean>1</boolean></value></param></params></methodResponse> 
[2014-09-17 13:42:07,665]  DEBUG - r.agent.impl.AgentLogProxyImpl - Action performed 17 log messages for 969900 
[2014-09-17 13:42:07,665]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:42:10,674]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:42:12,669]  DEBUG - r.agent.impl.AgentLogProxyImpl - Flush messages for AgentLogProxyImpl::executor 
[2014-09-17 13:42:12,669]  DEBUG - r.agent.impl.AgentLogProxyImpl - Later executor invocation for 0 remote commands, requestor: AgentLogProxyImpl::executor 
[2014-09-17 13:42:13,681]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:42:16,682]  DEBUG - buildServer.AGENT.registration - Check for server 
...
[2014-09-17 13:53:25,306]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:27,994]  DEBUG - r.agent.impl.AgentLogProxyImpl - Flush messages for AgentLogProxyImpl::executor 
[2014-09-17 13:53:27,994]  DEBUG - r.agent.impl.AgentLogProxyImpl - Later executor invocation for 0 remote commands, requestor: AgentLogProxyImpl::executor 
[2014-09-17 13:53:28,314]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:31,322]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:32,995]  DEBUG - r.agent.impl.AgentLogProxyImpl - Flush messages for AgentLogProxyImpl::executor 
[2014-09-17 13:53:32,996]  DEBUG - r.agent.impl.AgentLogProxyImpl - Later executor invocation for 0 remote commands, requestor: AgentLogProxyImpl::executor 
[2014-09-17 13:53:34,350]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:37,353]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:38,004]  DEBUG - r.agent.impl.AgentLogProxyImpl - Flush messages for AgentLogProxyImpl::executor 
[2014-09-17 13:53:38,004]  DEBUG - r.agent.impl.AgentLogProxyImpl - Later executor invocation for 0 remote commands, requestor: AgentLogProxyImpl::executor 
[2014-09-17 13:53:40,354]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:43,006]  DEBUG - r.agent.impl.AgentLogProxyImpl - Flush messages for AgentLogProxyImpl::executor 
[2014-09-17 13:53:43,006]  DEBUG - r.agent.impl.AgentLogProxyImpl - Later executor invocation for 0 remote commands, requestor: AgentLogProxyImpl::executor 
[2014-09-17 13:53:43,356]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:46,362]  DEBUG - buildServer.AGENT.registration - Check for server 
[2014-09-17 13:53:47,020]  DEBUG -    jetbrains.buildServer.AGENT - Agent ping from server 
[2014-09-17 13:53:47,021]  DEBUG - buildServer.AGENT.registration - Check for server
nskvortsov commented 9 years ago

@dave_neeley Please, try using recently updated version of plugin: http://teamcity.jetbrains.com/guestAuth/app/rest/builds/id:174538/artifacts/files/deploy-runner.zip

Original comment by: Nikita Skvortsov

nskvortsov commented 9 years ago

I will do that. However, the plugin started working again after removing the bittorrent plugin.

Original comment by: Dave Neeley

nskvortsov commented 9 years ago

I see. Thank you for the follow up.

Original comment by: Nikita Skvortsov

nskvortsov commented 9 years ago

This exception occurred yesterday before I had a chance to update the plugin. It took an 1h 17mins for this to happen. I have updated the plugin and will run that build to see if it still occurs.

#!java

[Step 1/1] jcifs.smb.SmbException: Transport1 timedout waiting for response to SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,errorCode=0,flags=0x0018,flags2=0xC803,signSeq=0,tid=2048,pid=592,uid=2048,mid=8956,wordCount=14,byteCount=4097,andxCommand=0xFF,andxOffset=0,fid=16384,offset=589824,writeMode=0,remaining=0,dataLength=4096,dataOffset=64]
jcifs.util.transport.TransportException: Transport1 timedout waiting for response to SmbComWriteAndX[command=SMB_COM_WRITE_ANDX,received=false,errorCode=0,flags=0x0018,flags2=0xC803,signSeq=0,tid=2048,pid=592,uid=2048,mid=8956,wordCount=14,byteCount=4097,andxCommand=0xFF,andxOffset=0,fid=16384,offset=589824,writeMode=0,remaining=0,dataLength=4096,dataOffset=64]
    at jcifs.util.transport.Transport.sendrecv(Transport.java:73)
    at jcifs.smb.SmbTransport.send(SmbTransport.java:655)
    at jcifs.smb.SmbSession.send(SmbSession.java:238)
    at jcifs.smb.SmbTree.send(SmbTree.java:119)
    at jcifs.smb.SmbFile.send(SmbFile.java:775)
    at jcifs.smb.SmbFileOutputStream.writeDirect(SmbFileOutputStream.java:245)
    at jcifs.smb.SmbFileOutputStream.write(SmbFileOutputStream.java:216)
    at jetbrains.buildServer.deployer.agent.smb.SMBBuildProcessAdapter.copyInterruptibly(SMBBuildProcessAdapter.java:141)
    at jetbrains.buildServer.deployer.agent.smb.SMBBuildProcessAdapter.upload(SMBBuildProcessAdapter.java:124)
    at jetbrains.buildServer.deployer.agent.smb.SMBBuildProcessAdapter.runProcess(SMBBuildProcessAdapter.java:84)
    at jetbrains.buildServer.deployer.agent.SyncBuildProcessAdapter.start(SyncBuildProcessAdapter.java:58)
    at jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.CallRunnerStage.doBuildStage(CallRunnerStage.java:58)
    at jetbrains.buildServer.agent.impl.buildStages.RunnerStagesExecutor$1.callStage(RunnerStagesExecutor.java:25)
    at jetbrains.buildServer.agent.impl.buildStages.RunnerStagesExecutor$1.callStage(RunnerStagesExecutor.java:18)
    at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.callRunStage(StagesExecutor.java:78)
    at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.doStages(StagesExecutor.java:37)
    at jetbrains.buildServer.agent.impl.buildStages.RunnerStagesExecutor.doStages(RunnerStagesExecutor.java:18)
    at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.RunnerContextExecutor.callRunnerStages(RunnerContextExecutor.java:43)
    at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.StepExecutor.processNextStep(StepExecutor.java:25)
    at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.ForEachBuildRunnerStage.executeRunnerStep(ForEachBuildRunnerStage.java:138)
    at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.ForEachBuildRunnerStage.runStep(ForEachBuildRunnerStage.java:123)
    at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.ForEachBuildRunnerStage.executeBuildRunners(ForEachBuildRunnerStage.java:83)
    at jetbrains.buildServer.agent.impl.buildStages.startStages.steps.ForEachBuildRunnerStage.doBuildStage(ForEachBuildRunnerStage.java:44)
    at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor$1.callStage(BuildStagesExecutor.java:31)
    at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor$1.callStage(BuildStagesExecutor.java:24)
    at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.callRunStage(StagesExecutor.java:78)
    at jetbrains.buildServer.agent.impl.buildStages.StagesExecutor.doStages(StagesExecutor.java:37)
    at jetbrains.buildServer.agent.impl.buildStages.BuildStagesExecutor.doStages(BuildStagesExecutor.java:24)
    at jetbrains.buildServer.agent.impl.BuildRunAction.doStages(BuildRunAction.java:70)
    at jetbrains.buildServer.agent.impl.BuildRunAction.runBuild(BuildRunAction.java:50)
    at jetbrains.buildServer.agent.impl.BuildAgentImpl.doActualBuild(BuildAgentImpl.java:265)
    at jetbrains.buildServer.agent.impl.BuildAgentImpl.access$100(BuildAgentImpl.java:52)
    at jetbrains.buildServer.agent.impl.BuildAgentImpl$1.run(BuildAgentImpl.java:231)
    at java.lang.Thread.run(Thread.java:722)

Original comment by: Dave Neeley

nskvortsov commented 9 years ago

It is hanging with the new plugin now as well. Last attempt ran for two hours before I killed it. last few lines from the agent log:

#!java

[2014-10-17 13:02:39,038]   INFO - ace.DirectoryCleanerForceClean - Free disk space under directory /sti/work2/393e0d4867cfdff5 is 18.41 GB, required 18 GB. 
[2014-10-17 13:02:39,038]   INFO - uildStages.BuildStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.startStages.ReportPreparationEndStage 
[2014-10-17 13:02:39,039]   INFO - uildStages.BuildStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.startStages.steps.ForEachBuildRunnerStage 
[2014-10-17 13:02:39,040]   INFO - mpl$TeamCitySpringSubConatiner - Refreshing SubContext: running build runner context id=1,031,004 runner 1 of 1: startup date [Fri Oct 17 13:02:39 MDT 2014]; parent: SubContext: running build context id=1031004 
[2014-10-17 13:02:39,153]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.CreateBuildWorkingDirectoryStage 
[2014-10-17 13:02:39,153]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.startStages.CreateBuildTempDirectoryStage 
[2014-10-17 13:02:39,153]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.startStages.CreateAgentTempDirectoryStage 
[2014-10-17 13:02:39,153]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.startStages.CreateCheckoutDirectoryStage 
[2014-10-17 13:02:39,153]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.RegisterPerBuildFileWriterPropertiesRunnerStage 
[2014-10-17 13:02:39,153]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.FireBeforeRunnerStartedStage 
[2014-10-17 13:02:39,159]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.CallBuildRunnerPrecondition 
[2014-10-17 13:02:39,159]   INFO - rt.CallBuildRunnerPrecondition - Call BuildRunnerPrecondition: class jetbrains.buildServer.agent.feature.RubyEnvConfiguratorService 
[2014-10-17 13:02:39,159]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.startStages.PerformFinalParametersResolveStage 
[2014-10-17 13:02:39,159]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.SavePropertiesToFilesStage 
[2014-10-17 13:02:39,171]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.CallRunnerStage 
[2014-10-17 13:02:39,171]   INFO - .impl.runner.CallRunnerService - Found runner smb-deploy-runner for 1031004 
[2014-10-17 13:02:39,533]   INFO - erStages.start.CallRunnerStage - Found runner smb-deploy-runner for 1031004 
[2014-10-17 13:02:39,533]   INFO - erStages.start.CallRunnerStage - Start build runner for build 1031004 smb-deploy-runner 
[2014-10-17 13:02:39,533]   INFO - erStages.start.CallRunnerStage - ----------------------------------------- [ Agent Tools::ServicesPlatform Promote #34 (buildId = 1031004) ] -----------------------------------------

By deleting the folder to be deployed before running the build, I can see that the plugin is actually transferring files -- about one per minute.

Original comment by: Dave Neeley

nskvortsov commented 9 years ago

Do you currently have torrent plugin installed?

Original comment by: Nikita Skvortsov

nskvortsov commented 9 years ago

No, the torrent plugin is not installed.

Original comment by: Dave Neeley