Incorrect test duration time reported - configuration issue or bug getting times from message timestamps?

Hi, 

I'm having an issue where my test times (test output is coming from a command line script) are not correctly reported. In the help here:

https://confluence.jetbrains.com/display/TCDL/Build+Script+Interaction+with+TeamCity

and under this section "Test start/stop messages" it states that "duration (optional numeric attribute) - sets the test duration in milliseconds (should be an integer) to be reported in TeamCity UI. If omitted, the test duration will be calculated from the messages timestamps. If the timestamps are missing, from the actual time the messages were received on the server."

However all my tests get reported as < 1ms when some take more than a few minutes. My build log is below but an extract is:
 
[11:01:23][Step 1/1] Credit (3m:10s)
[11:01:23][Credit]
[11:01:23][Credit] 1..4
[11:01:25][Credit] ok 1 - MtM_Test/test1_swap
[11:01:26][Credit] ok 2 - MtM_Test/test1_cap
[11:01:31][Credit] ok 3 - TestEndToEndCreditRun_Test/test1_endToEndTest
[11:04:33][Credit] ok 4 - TestPFEEngine_Test/test1_swap
[11:04:33][Credit]
 
I'm running: TeamCity Professional 9.1.6 (build 37459)
 
Am I doing something wrong, is there a bug, or do I need to re-write the TAP plugin I have to explicitly put test durations at the end of each test?
 
Any help appreciated!
 
Thanks,
Stewart
 

Build log:

[11:01:05]Collecting changes in 1 VCS root
[11:01:05][Collecting changes in 1 VCS root] VCS Root details
[11:01:05][VCS Root details] "RiskTrunk" {instance id=7, parent internal id=2, parent id=RiskMatlabModels_RiskTrunk, description: "svn: svn://soe92134/matlab_code/"}
[11:01:06]Clearing temporary directory: C:\BuildAgent\temp\buildTmp
[11:01:06]Publishing internal artifacts
[11:01:06][Publishing internal artifacts] Publishing 1 file using [WebPublisher]
[11:01:06][Publishing internal artifacts] Publishing 1 file using [ArtifactsCachePublisher]
[11:01:06]Checkout directory: C:\BuildAgent\work\755d339e55c30f62
[11:01:06]Updating sources: server side checkout
[11:01:06][Updating sources] Using vcs information from agent file: 755d339e55c30f62.xml
[11:01:06][Updating sources] Building incremental patch for VCS root: RiskTrunk; checkout rules: =>; revision: 2574 --> 2575
[11:01:06][Updating sources] Repository sources transferred
[11:01:06][Updating sources] Updating C:\BuildAgent\work\755d339e55c30f62
[11:01:06]Step 1/1: Command Line (3m:33s)
[11:01:06][Step 1/1] Starting: C:\WINDOWS\system32\cmd.exe /c bash TestCases\teamcity_matlab_tests.sh
[11:01:06][Step 1/1] in directory: C:\BuildAgent\work\755d339e55c30f62
[11:01:23][Step 1/1] Credit (3m:10s)
[11:01:23][Credit]
[11:01:23][Credit] 1..4
[11:01:25][Credit] ok 1 - MtM_Test/test1_swap
[11:01:26][Credit] ok 2 - MtM_Test/test1_cap
[11:01:31][Credit] ok 3 - TestEndToEndCreditRun_Test/test1_endToEndTest
[11:04:33][Credit] ok 4 - TestPFEEngine_Test/test1_swap
[11:04:33][Credit]
[11:04:33][Step 1/1]
[11:04:33][Step 1/1] Libraries (3s)
[11:04:33][Libraries]
[11:04:33][Libraries] 1..7
[11:04:34][Libraries] ok 1 - ConnectToOracleDatabaseTest/test_bo
[11:04:34][Libraries] ok 2 - ConnectToOracleDatabaseTest/test_analytics
[11:04:34][Libraries] ok 3 - ConnectToOracleDatabaseTest/test_infoserver
[11:04:35][Libraries] ok 4 - ConnectToOracleDatabaseTest/test_eot_prod
[11:04:35][Libraries] ok 5 - ConnectToOracleDatabaseTest/test_portdata_dev_read
[11:04:35][Libraries] ok 6 - ConnectToOracleDatabaseTest/test_portdata_dev_write
[11:04:36][Libraries] ok 7 - ExpandData_Test/test1
[11:04:36][Libraries]
[11:04:36][Step 1/1]
[11:04:39][Step 1/1] TestCases\teamcity_matlab_tests.sh: line 16: 6672 Terminated tail -f $tapfile
[11:04:39][Step 1/1] Process exited with code 0
[11:04:39]Publishing internal artifacts
[11:04:39][Publishing internal artifacts] Publishing 1 file using [WebPublisher]
[11:04:39][Publishing internal artifacts] Publishing 1 file using [ArtifactsCachePublisher]
[11:04:40]Build finished

 

2 comments

Hi Stewart Bryce,

Could you please attach the whole output of your build, with all service messages? You can download it using the link at the upper right corner. 

0

Hi Alina, Please find the log below. Thanks! Stewart

 

Build 'Risk Matlab Models :: TestTest' #7 personal build by BRYCE Stewart (Ergon) (sb217)
Started 'Mon Feb 15 11:01:06 AEST 2016' on 'soe92134' by 'BRYCE Stewart (Ergon) (sb217)'
Finished 'Mon Feb 15 11:04:40 AEST 2016' with status 'NORMAL Tests passed: 11'
TeamCity URL http://soe03328/teamcity/viewLog.html?buildId=1071&buildTypeId=RiskMatlabModels_TestTest
TeamCity server version is 9.1.6 (build 37459)

[11:01:05]i: TeamCity server version is 9.1.6 (build 37459)
[11:01:05]W: bt6_2 (3m:34s)
[11:01:05] : Collecting changes in 1 VCS root
[11:01:05] : [Collecting changes in 1 VCS root] VCS Root details
[11:01:05] : [VCS Root details] "RiskTrunk" {instance id=7, parent internal id=2, parent id=RiskMatlabModels_RiskTrunk, description: "svn: svn://soe92134/matlab_code/"}
[11:01:06]i: [Collecting changes in 1 VCS root] Waiting for completion of current operations for the VCS root 'RiskTrunk'
[11:01:06]i: [Collecting changes in 1 VCS root] Detecting changes in VCS root 'RiskTrunk' (used in 'GMaR Overnight', 'TestCases' and 1 other configuration)
[11:01:06]i: [Collecting changes in 1 VCS root] Will collect changes for 'RiskTrunk' starting from revision 2575
[11:01:06]i: Waiting for the agent to start the build
[11:01:06]i: Agent time zone: Australia/Brisbane
[11:01:06]i: Agent is running under JRE: 1.7.0_72-b14
[11:01:06] : Clearing temporary directory: C:\BuildAgent\temp\buildTmp
[11:01:06] : Publishing internal artifacts
[11:01:06] : [Publishing internal artifacts] Publishing 1 file using [WebPublisher]
[11:01:06] : [Publishing internal artifacts] Publishing 1 file using [ArtifactsCachePublisher]
[11:01:06] : Checkout directory: C:\BuildAgent\work\755d339e55c30f62
[11:01:06] : Updating sources: server side checkout
[11:01:06] : [Updating sources] Using vcs information from agent file: 755d339e55c30f62.xml
[11:01:06] : [Updating sources] Building incremental patch for VCS root: RiskTrunk; checkout rules: =>; revision: 2574 --> 2575
[11:01:06] : [Updating sources] Repository sources transferred
[11:01:06] : [Updating sources] Updating C:\BuildAgent\work\755d339e55c30f62
[11:01:06]i: ##teamcity[buildStatisticValue key='buildStageDuration:sourcesUpdate' value='374.0']
[11:01:06] : Build preparation done
[11:01:06]W: Step 1/1: Command Line (3m:33s)
[11:01:06]i: [Step 1/1] ##teamcity[buildStatisticValue key='buildStageDuration:firstStepPreparation' value='78.0']
[11:01:06]i: [Step 1/1] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepRUNNER_1' value='0.0']
[11:01:06]i: [Step 1/1] Launching "bash" in working directory C:\BuildAgent\work\755d339e55c30f62 as it is not present in checkout directory C:\BuildAgent\work\755d339e55c30f62
[11:01:06]i: [Step 1/1] Running interpreter: C:\WINDOWS\system32\cmd.exe
[11:01:06] : [Step 1/1] Starting: C:\WINDOWS\system32\cmd.exe /c bash TestCases\teamcity_matlab_tests.sh
[11:01:06] : [Step 1/1] in directory: C:\BuildAgent\work\755d339e55c30f62
[11:01:23] : [Step 1/1] Credit (3m:10s)
[11:01:23] : [Credit]
[11:01:23] : [Credit] 1..4
[11:01:25]i: [Credit] MtM_Test/test1_swap
[11:01:25] : [Credit] ok 1 - MtM_Test/test1_swap
[11:01:26]i: [Credit] MtM_Test/test1_cap
[11:01:26] : [Credit] ok 2 - MtM_Test/test1_cap
[11:01:31]i: [Credit] TestEndToEndCreditRun_Test/test1_endToEndTest
[11:01:31] : [Credit] ok 3 - TestEndToEndCreditRun_Test/test1_endToEndTest
[11:04:33]i: [Credit] TestPFEEngine_Test/test1_swap
[11:04:33] : [Credit] ok 4 - TestPFEEngine_Test/test1_swap
[11:04:33] : [Credit]
[11:04:33] : [Step 1/1]
[11:04:33] : [Step 1/1] Libraries (3s)
[11:04:33] : [Libraries]
[11:04:33] : [Libraries] 1..7
[11:04:34]i: [Libraries] ConnectToOracleDatabaseTest/test_bo
[11:04:34] : [Libraries] ok 1 - ConnectToOracleDatabaseTest/test_bo
[11:04:34]i: [Libraries] ConnectToOracleDatabaseTest/test_analytics
[11:04:34] : [Libraries] ok 2 - ConnectToOracleDatabaseTest/test_analytics
[11:04:34]i: [Libraries] ConnectToOracleDatabaseTest/test_infoserver
[11:04:34] : [Libraries] ok 3 - ConnectToOracleDatabaseTest/test_infoserver
[11:04:35]i: [Libraries] ConnectToOracleDatabaseTest/test_eot_prod
[11:04:35] : [Libraries] ok 4 - ConnectToOracleDatabaseTest/test_eot_prod
[11:04:35]i: [Libraries] ConnectToOracleDatabaseTest/test_portdata_dev_read
[11:04:35] : [Libraries] ok 5 - ConnectToOracleDatabaseTest/test_portdata_dev_read
[11:04:35]i: [Libraries] ConnectToOracleDatabaseTest/test_portdata_dev_write
[11:04:35] : [Libraries] ok 6 - ConnectToOracleDatabaseTest/test_portdata_dev_write
[11:04:36]i: [Libraries] ExpandData_Test/test1
[11:04:36] : [Libraries] ok 7 - ExpandData_Test/test1
[11:04:36] : [Libraries]
[11:04:36] : [Step 1/1]
[11:04:39]W: [Step 1/1] TestCases\teamcity_matlab_tests.sh: line 16: 6672 Terminated tail -f $tapfile
[11:04:39] : [Step 1/1] Process exited with code 0
[11:04:39]i: [Step 1/1] ##teamcity[buildStatisticValue key='buildStageDuration:buildStepRUNNER_1' value='213041.0']
[11:04:39]i: ##teamcity[buildStatisticValue key='buildStageDuration:buildFinishing' value='31.0']
[11:04:39] : Publishing internal artifacts
[11:04:39] : [Publishing internal artifacts] Publishing 1 file using [WebPublisher]
[11:04:39] : [Publishing internal artifacts] Publishing 1 file using [ArtifactsCachePublisher]
[11:04:39]i: ##teamcity[buildStatisticValue key='buildStageDuration:artifactsPublishing' value='141.0']
[11:04:40] : Build finished

0

Please sign in to leave a comment.