Setting environment variables from build fails silently sporadically

Hi,

for many of my builds, I set a environment variable from a metarunner. It has 2 "runners", one that sets the variable, one that dumps all vars to double check ("Get-ChildItem Env:" in Powershell). See below for the metarunner definition.

Usually, this works fine,and I can see in the log both the "##" line that sets the variable, and the corresponding variable in the dump.

However, once in while (like every 40 runs), I can see the "##" line as usual, but in the next step, it's not in the dump. Since subsequent build steps depend on this variable, the whole builds fail, and the upstream builds too.

Has anyone see this before ? Any idea about the cause or further troubleshooting steps ?

Cheers

Olivier

Edit: using TeamCity 8.1 (build 29879)

<?xml version="1.0" encoding="UTF-8"?>
<meta-runner name="Extend TeamCity environment variables">
  <description>Extend TeamCity environment variables</description>
  <settings>
    <parameters />
    <build-runners>
      <runner name="Extend TeamCity environment variables" type="jetbrains_powershell">
        <parameters>
          <param name="jetbrains_powershell_bitness" value="x86" />
          <param name="jetbrains_powershell_execution" value="STDIN" />
          <param name="jetbrains_powershell_noprofile" value="true" />
          <param name="jetbrains_powershell_script_code"><![CDATA[$host.UI.RawUI.BufferSize = New-Object System.Management.Automation.Host.Size(8192,50)

echo "##teamcity[setParameter name='env.VAR' value='...']"

# End of PowerShell]]></param>
          <param name="jetbrains_powershell_script_mode" value="CODE" />
          <param name="teamcity.step.mode" value="default" />
        </parameters>
      </runner>
      <runner name="Print environment variable with PowerShell" type="jetbrains_powershell">
        <parameters>
          <param name="jetbrains_powershell_bitness" value="x86" />
          <param name="jetbrains_powershell_execution" value="STDIN" />
          <param name="jetbrains_powershell_noprofile" value="true" />
          <param name="jetbrains_powershell_script_code" value="Get-ChildItem Env:" />
          <param name="jetbrains_powershell_script_mode" value="CODE" />
          <param name="teamcity.step.mode" value="default" />
        </parameters>
      </runner>
    </build-runners>
    <requirements />
  </settings>
</meta-runner>

18 comments
Comment actions Permalink

Olivier,

Would it be possible to attach raw build logs (avaialble for download when viewing build log with "Verbose" level) for several builds which do not have the environment set and for several working in due way?

0
Comment actions Permalink

Hello Yegor,

please find below the raw log. I just replaced internal names by placeholders.

Best regards

Olivier

Build 'System :: PROD :: PROD-VAR' #120 
Started 'Thu Mar 20 18:49:36 CET 2014' on 'agent-o2-a4' by 'Git; System :: Run all supported builds'
Finished 'Thu Mar 20 18:51:15 CET 2014' with status 'NORMAL 1 muted problem'
TeamCity URL https://xxx/tc/viewLog.html?buildId=17391&buildTypeId=System_Np5ecatStd
TeamCity server version is 8.1 (build 29879)

[18:49:36]E: bt58 (1m:38s)
[18:49:36] : TeamCity server version is 8.1 (build 29879)
[18:49:36] : Skip checking for changes - changes are already collected (running for 1m:38s)
[17:59:42] : Will collect changes in 4 VCS roots
[17:59:42] : Waiting for completion of current operations for the VCS roots
[17:59:42] : Loading current repository state for VCS root 'repo1'
[17:59:42] : Loading current repository state for VCS root 'repo2'
[17:59:43] : Loading current repository state for VCS root 'repo3'
[17:59:43] : Loading current repository state for VCS root 'repo4'
[17:59:43] : Detecting changes in VCS root 'repo1' (used in PROD-VAR2, PROD-VAR3 and 31 other configurations)
[17:59:43] : Detecting changes in VCS root 'repo3' (used in PROD-VAR2, PROD-VAR3 and 32 other configurations)
[17:59:43] : Detecting changes in VCS root 'repo4' (used in PROD-VAR2, PROD-VAR3 and 32 other configurations)
[17:59:43] : Detecting changes in VCS root 'repo2' (used in PROD-VAR2, PROD-VAR3 and 33 other configurations)
[18:49:36] : Agent time zone: Europe/Berlin
[18:49:54] : Agent is running under JRE: 1.7.0_51-b13
[18:49:57] : Publishing internal artifacts
[18:49:57] :      [Publishing internal artifacts] Sending using ArtifactsCachePublisher
[18:49:57] :      [Publishing internal artifacts] Sending using WebPublisher
[18:49:57] : Clearing temporary directory: C:\TC\agent-a4\temp\buildTmp
[18:49:57] : Using vcs information from agent file: 6d2a007f7499a5a5.xml
[18:49:57] : Clean build enabled: removing old files from C:\TC\agent-a4\work\6d2a007f7499a5a5
[18:50:31] : Checkout directory: C:\TC\agent-a4\work\6d2a007f7499a5a5
[18:50:31] : Updating sources: server side checkout (37s)
[18:50:12] :      [Updating sources] Will perform clean checkout. Reason: Checkout directory is empty or doesn't exist
[18:50:12] :      [Updating sources] Transferring cached clean patch for VCS root: repo4
[18:50:12] :      [Updating sources] Transferring cached clean patch for VCS root: repo3
[18:50:14] :      [Updating sources] Transferring cached clean patch for VCS root: repo1
[18:50:16] :      [Updating sources] Transferring cached clean patch for VCS root: repo2
[18:50:20] :      [Updating sources] Building incremental patch over the cached patch
[18:50:39] :      [Updating sources] Repository sources transferred: 77.08 MB total
[18:50:39] :      [Updating sources] Removing C:\TC\agent-a4\work\6d2a007f7499a5a5
[18:50:39] :      [Updating sources] Updating C:\TC\agent-a4\work\6d2a007f7499a5a5\repo1
[18:50:40] :      [Updating sources] Updating C:\TC\agent-a4\work\6d2a007f7499a5a5\repo2
[18:50:46] :      [Updating sources] Updating C:\TC\agent-a4\work\6d2a007f7499a5a5\repo3
[18:50:49] :      [Updating sources] Updating C:\TC\agent-a4\work\6d2a007f7499a5a5\repo4
[18:51:08] : ##teamcity[buildStatisticValue key='buildStageDuration:sourcesUpdate' value='73733.0']
[18:51:08] : Build preparation done
[18:51:08] : Step 1/4: Extend TeamCity environment variables (1s)
[18:51:08] :      [Step 1/4] Step 1/2: Extend TeamCity environment variables (Powershell)
[18:51:08] :           [Step 1/2] ##teamcity[buildStatisticValue key='buildStageDuration:firstStepPreparation' value='52.0']
[18:51:08] :           [Step 1/2] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepExtendTeamCityEnvironmentVariables_0' value='0.0']
[18:51:08] :           [Step 1/2] Starting:  C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive -ExecutionPolicy ByPass -Command - < C:\TC\agent-a4\temp\buildTmp\powershell3672686390342850961.ps1
[18:51:08] :           [Step 1/2] in directory: C:\TC\agent-a4\work\6d2a007f7499a5a5
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_BUILD_ID' value='17391']
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_BUILD_COUNTER' value='120']
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_BUILD_NUMBER' value='120']
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_SHA1_REPO1' value='c8d8fba2673c1898df5370a0f7716a0083389993']
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_SHA1_REPO2' value='05b44045d028348776faefc8ad0bc6a5e854abe5']
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_SHA1_REPO3' value='89d05a31deb87c0df8a16f40548e0462c3dc9e07']
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_SHA1_REPO4' value='2c6da8f897c6064514500e944ec90f4b9c843eaa']
[18:51:09] :           [Step 1/2] ##teamcity[setParameter name='env.TEAMCITY_MY_BUILD_ID' value='DEV-B17391']
[18:51:09] :           [Step 1/2] Process exited with code 0
[18:51:09] :           [Step 1/2] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepExtendTeamCityEnvironmentVariables_0' value='949.0']
[18:51:09] :      [Step 1/4] Step 2/2: Print environment variable with PowerShell (Powershell)
[18:51:09] :           [Step 2/2] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepExtendTeamCityEnvironmentVariables_1' value='0.0']
[18:51:09] :           [Step 2/2] Starting:  C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive -ExecutionPolicy ByPass -Command - < C:\TC\agent-a4\temp\buildTmp\powershell6523663956218219633.ps1
[18:51:09] :           [Step 2/2] in directory: C:\TC\agent-a4\work\6d2a007f7499a5a5
[18:51:09] :           [Step 2/2]
[18:51:09] :           [Step 2/2] Name                           Value                                                               
[18:51:09] :           [Step 2/2] ----                           -----                                                               
[18:51:09] :           [Step 2/2] ALLUSERSPROFILE                C:\ProgramData                                                      
[18:51:09] :           [Step 2/2] APPDATA                        C:\Users\User\AppData\Roaming                              
[18:51:09] :           [Step 2/2] BUILD_NUMBER                   120                                                                 
[18:51:09] :           [Step 2/2] BUILD_VCS_NUMBER_System_Build  89d05a31deb87c0df8a16f40548e0462c3dc9e07                            
[18:51:09] :           [Step 2/2] BUILD_VCS_NUMBER_System_Fir... 05b44045d028348776faefc8ad0bc6a5e854abe5                            
[18:51:09] :           [Step 2/2] BUILD_VCS_NUMBER_System_Fir... c8d8fba2673c1898df5370a0f7716a0083389993                            
[18:51:09] :           [Step 2/2] BUILD_VCS_NUMBER_System_repo1 2c6da8f897c6064514500e944ec90f4b9c843eaa                            
[18:51:09] :           [Step 2/2] CommonProgramFiles             C:\Program Files\Common Files                                       
[18:51:09] :           [Step 2/2] COMPUTERNAME                   AGENT
[18:51:09] :           [Step 2/2] ComSpec                        C:\Windows\system32\cmd.exe                                         
[18:51:09] :           [Step 2/2] FP_NO_HOST_CHECK               NO                                                                  
[18:51:09] :           [Step 2/2] GROOVY_HOME                    C:\Groovy                                                           
[18:51:09] :           [Step 2/2] HOMEDRIVE                      C:                                                                  
[18:51:09] :           [Step 2/2] HOMEPATH                       \Users\User                                                
[18:51:09] :           [Step 2/2] JAVA_EXE                       C:\Program Files\Java\jre7\bin\java.exe                             
[18:51:09] :           [Step 2/2] JAVA_HOME                      C:\Program Files\Java\jre7                                          
[18:51:09] :           [Step 2/2] JRE_17                         C:\Program Files\Java\jre7                                          
[18:51:09] :           [Step 2/2] JRE_HOME                       C:\Program Files\Java\jre7                                          
[18:51:09] :           [Step 2/2] LOCALAPPDATA                   C:\Users\User\AppData\Local                                
[18:51:09] :           [Step 2/2] LOGONSERVER                    \\AGENT
[18:51:09] :           [Step 2/2] LUA_DEV                        C:\Program Files\Lua\5.1                                            
[18:51:09] :           [Step 2/2] LUA_PATH                       ;;C:\Program Files\Lua\5.1\lua\?.luac                               
[18:51:09] :           [Step 2/2] NUMBER_OF_PROCESSORS           8                                                                   
[18:51:09] :           [Step 2/2] OS                             Windows_NT                                                          
[18:51:09] :           [Step 2/2] Path                           C:\Program Files\Intel\iCLS Client\;C:\Windows\system32;C:\Window...
[18:51:09] :           [Step 2/2] PATHEXT                        .COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC;.wlua;.lexe   
[18:51:09] :           [Step 2/2] PROCESSOR_ARCHITECTURE         x86                                                                 
[18:51:09] :           [Step 2/2] PROCESSOR_IDENTIFIER           x86 Family 6 Model 60 Stepping 3, GenuineIntel                      
[18:51:09] :           [Step 2/2] PROCESSOR_LEVEL                6                                                                   
[18:51:09] :           [Step 2/2] PROCESSOR_REVISION             3c03                                                                
[18:51:09] :           [Step 2/2] ProgramData                    C:\ProgramData                                                      
[18:51:09] :           [Step 2/2] ProgramFiles                   C:\Program Files                                                    
[18:51:09] :           [Step 2/2] PROMPT                         $P$G                                                                
[18:51:09] :           [Step 2/2] PSExecutionPolicyPreference    Bypass                                                              
[18:51:09] :           [Step 2/2] PSModulePath                   C:\Users\User\Documents\WindowsPowerShell\Modules;C:\Win...
[18:51:09] :           [Step 2/2] PUBLIC                         C:\Users\Public                                                     
[18:51:09] :           [Step 2/2] SESSIONNAME                    Console                                                             
[18:51:09] :           [Step 2/2] SystemDrive                    C:                                                                  
[18:51:09] :           [Step 2/2] SystemRoot                     C:\Windows                                                          
[18:51:09] :           [Step 2/2] TEAMCITY_AGENT_CONFIG_FILE     C:\TC\agent-a4\\buildAgent.properties       
[18:51:09] :           [Step 2/2] TEAMCITY_AGENT_CURRENT_DIR     C:\TC\agent-a4                              
[18:51:09] :           [Step 2/2] TEAMCITY_AGENT_LOG_DIR         ../logs/                                                            
[18:51:09] :           [Step 2/2] TEAMCITY_AGENT_MEM_OPTS_ACTUAL -Xmx384m                                                            
[18:51:09] :           [Step 2/2] TEAMCITY_AGENT_OPTS_ACTUAL     -ea -Xmx384m -Dlog4j.configuration=file:../conf/teamcity-agent-lo...
[18:51:09] :           [Step 2/2] TEAMCITY_BUILD_PROPERTIES_FILE C:\TC\agent-a4\temp\buildTmp\teamcity.bui...
[18:51:09] :           [Step 2/2] TEAMCITY_BUILDCONF_NAME        PROD-VAR                                                        
[18:51:09] :           [Step 2/2] TEAMCITY_CAPTURE_ENV           C:\Program Files\Java\jre7\bin\java.exe -jar C:\Users\Olivier-Lok...
[18:51:09] :           [Step 2/2] TEAMCITY_GIT_PATH              C:\Program Files\Git\bin\git.exe                                    
[18:51:09] :           [Step 2/2] TEAMCITY_LAUNCHER_CLASSPATH    ..\launcher\lib\launcher.jar                                        
[18:51:09] :           [Step 2/2] TEAMCITY_LAUNCHER_OPTS_ACTUAL  -ea                                                                 
[18:51:09] :           [Step 2/2] TEAMCITY_PROCESS_FLOW_ID       747203092019237                                                     
[18:51:09] :           [Step 2/2] TEAMCITY_PROCESS_PARENT_FLO...                                                                     
[18:51:09] :           [Step 2/2] TEAMCITY_PROJECT_NAME          PROD                                                                 
[18:51:09] :           [Step 2/2] TEAMCITY_VERSION               8.1 (build 29879)                                                   
[18:51:09] :           [Step 2/2] TEMP                           C:\TC\agent-a4\temp\buildTmp                
[18:51:09] :           [Step 2/2] TMP                            C:\TC\agent-a4\temp\buildTmp                
[18:51:09] :           [Step 2/2] TMPDIR                         C:\TC\agent-a4\temp\buildTmp                
[18:51:09] :           [Step 2/2] USERDOMAIN                     agent-o                                                     
[18:51:09] :           [Step 2/2] USERNAME                       User                                                       
[18:51:09] :           [Step 2/2] USERPROFILE                    C:\Users\User                                              
[18:51:09] :           [Step 2/2] VS100COMNTOOLS                 C:\Program Files\Microsoft Visual Studio 10.0\Common7\Tools\        
[18:51:09] :           [Step 2/2] windir                         C:\Windows                                                          
[18:51:09] :           [Step 2/2] windows_tracing_flags          3                                                                   
[18:51:09] :           [Step 2/2] windows_tracing_logfile        C:\BVTBin\Tests\installpackage\csilogfile.log                       
[18:51:09] :           [Step 2/2]
[18:51:09] :           [Step 2/2]
[18:51:09] :           [Step 2/2] Process exited with code 0
[18:51:10] :           [Step 2/2] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepExtendTeamCityEnvironmentVariables_1' value='426.0']
[18:51:10] : Step 2/4: Create paths.txt for the Lua build system (Powershell) (4s)
[18:51:10] :      [Step 2/4] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepRUNNER_21' value='0.0']
[18:51:10] :      [Step 2/4] Starting:  C:\Windows\System32\WindowsPowerShell\v1.0\powershell.exe -NoProfile -NonInteractive -ExecutionPolicy ByPass -Command - < C:\TC\agent-a4\temp\buildTmp\powershell3312750819565884262.ps1
[18:51:10] :      [Step 2/4] in directory: C:\TC\agent-a4\work\6d2a007f7499a5a5\build
[18:51:10] :      [Step 2/4] Process exited with code 0
[18:51:14] :      [Step 2/4] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepRUNNER_21' value='4483.0']
[18:51:14]E: Step 3/4: [...]
[18:51:14]E: Step 4/4: [...]
[18:51:32] : ##teamcity[buildStatisticValue key='buildStageDuration:buildFinishing' value='571.0']
[18:51:32] : Publishing internal artifacts
[18:51:32] :      [Publishing internal artifacts] Sending using ArtifactsCachePublisher
[18:51:32] :      [Publishing internal artifacts] Sending using WebPublisher
[18:51:32]W: Publishing artifacts
[18:51:32] :      [Publishing artifacts] Collecting files to publish: [src/build/*/** => .]
[18:51:32]W:      [Publishing artifacts] Artifacts path 'src/build/*/**' not found
[18:51:33] : ##teamcity[buildStatisticValue key='buildStageDuration:artifactsPublishing' value='559.0']
[18:51:15] : Build finished
0
Comment actions Permalink

One of our nightly builds failed early today because of this issue :( I checked the server logs, there isn't anything suspicious there.
I just set up a troubleshooting build configuration that runs every minute, trying to reproduce the issue.
Is there anything else I can do on my side to pinpoint the origin of the problem ?

In case it makes any difference, the build configurations run on 4 agents running on the same Windows 7 machine, 32bit.

0
Comment actions Permalink

Olivier,

Would it be possible to attach raw build log files? These come in an archive, see my previous comment.
Could you please also attach those for both bad and good builds?
Please also attach .teamcity/properties/build.finish.properties.gz files from the hidden build artifacts for the builds.

So when this reproduces none of the set environment variables are passed to te next step?
Would it be possible to use plan command line runner instead of PowerShell to eliminate possible PowerShell issues?

Please also keep us updated on the results you have with the testing build.

0
Comment actions Permalink

Thanks for the feedback. I just sent you the requested files by email.

The values of the variables are computed dynamically, and the runners do even more than that, so CMD is not an option. It's too cumbersome and limited for this purpose.

0
Comment actions Permalink

Olivier,

Quite strange. I cannot reproduce this locally...

How often does this reprodcue?
What are the results of the troubleshooting build you have set up?

0
Comment actions Permalink

Seems that this is the consequence of an internal "NoRunningBuildException" error.

I have filed the case as http://youtrack.jetbrains.com/issue/TW-35871

0
Comment actions Permalink

Thank you Yegor. I hope it will be an easy bug to fix :)

0
Comment actions Permalink

A few questions:
1) Does the problem occur for all configurations or the only one? Or all ones that contain meta-runner you've mentioned?
2) Does it happen for all build agents, or just a single one?

I suspect, it might be a networking issue, when agent receives signal to stop the build, while it's in process of execution. And since build type uses service messages, it fails.

0
Comment actions Permalink

It happened last night again. The same exception could be found in the agent log (NoRunningBuildException).

We have 4 agents running on the same machine, the problem occurs on at least 3.

All our builds are based on a template that uses this meta-runner. Several of these builds have been impacted in the past.

The "troubleshooting build configuration" never failed so far (it's running every 5 minutes). It's based on the same template as the productive builds.

The network issue sounds interesting, I will investigate in this direction. However I don't see why an agent would receive a signal to stop the build.

0
Comment actions Permalink

Please attach build log and teamcity-agent.log to the issue http://youtrack.jetbrains.com/issue/TW-35871.

0
Comment actions Permalink

Actually, I fixed the issue. Will have a build for you to try tonight or tomorrow.

0
Comment actions Permalink

That's great news, thanks !

0
Comment actions Permalink

Thanks Sergey. I have a few questions, to help us defining our stategy to test and deploy this build.

  • What are the differences between 29879 and 29981 ? Is it only the fix for this bug ?
  • Do you consider it safe for production ?
  • When is it roughly scheduled for official release ?
  • Do you need our feedback ?
0
Comment actions Permalink

This build is a build from branch that includes this bugfix (and other bugfixes as well).

As long as this one works properly, I would recommend you to update to 8.1.2 which is going to be released this week and that cointains the bugfix as well.

0
Comment actions Permalink

We will wait for 8.1.2. Thank you for the great support.

0
Comment actions Permalink

I have installed 8.1.2 three days ago, and I didn't see the problem since. It looks good. Thanks !

0

Please sign in to leave a comment.