TeamCity misreporting test Service Messages
Answered
The following is the console.log output when run locally:
##teamcity[testSuiteStarted name='components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx']
##teamcity[testStarted name='renders Staged Upgrades Groups']
##teamcity[testStarted name='renders Staged Upgrades Sequence']
##teamcity[testStarted name='can switch between groups and sequence view']
##teamcity[testFinished name='renders Staged Upgrades Groups' duration='1244']
##teamcity[testFinished name='renders Staged Upgrades Sequence' duration='332']
##teamcity[testFinished name='can switch between groups and sequence view' duration='443']
##teamcity[testSuiteFinished name='components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx']
And the following is the TC output:
[22:40:15] : [Step 6/9] <testsuites>
[22:40:15] : [Step 6/9] <testsuite name="components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx" timestamp="2022-06-03T03:40:15.564Z" hostname="sdg467.meraki.com" tests="3" failures="0" errors="0" skipped="0" time="4.1770000000">
[22:40:15] : [Step 6/9] <testcase classname="components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx" name="renders Staged Upgrades Groups" time="2.6570000000">
[22:40:15] : [Step 6/9] </testcase>
[22:40:15] : [Step 6/9] <testcase classname="components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx" name="renders Staged Upgrades Sequence" time="0.6040000000">
[22:40:15] : [Step 6/9] </testcase>
[22:40:15] : [Step 6/9] <testcase classname="components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx" name="can switch between groups and sequence view" time="0.9150000000">
[22:40:15] : [Step 6/9] </testcase>
[22:40:15] : [Step 6/9] </testsuite>
[22:40:15] : [Step 6/9] </testsuites>
Notice how all tests complete successfully. Unfortunately, team city reports the wrong test durations for all but the first test and drops the last test.
Output can be seen here in TC: https://teamcity.ikarem.io/buildConfiguration/ContainerDashboard_StaticAssets_Review/1867737?buildTab=tests
Update:
- upon closer inspection, I'm seeing out-of-memory errors in the logs and I'm wondering if that's the cause of this bug,
(node:793) UnhandledPromiseRejectionWarning: RangeError: WebAssembly.instantiate(): Out of memory: wasm memory
[18:06:59]W: [Step 6/9] (Use `node --trace-warnings ...` to show where the warning was created)
Please sign in to leave a comment.
Hello,
TeamCity assumes that after testStarted there will be testFinished service message with the same name. In your example this is not the case.
testStarted/testFinished messages can be intermixed if the tests are running in different threads. To handle this case the flowId attribute should be added to the service message. FlowId is just an arbitrary string id, but for the same test it should be the same. If you transform your example to:
##teamcity[testSuiteStarted name='components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx']
##teamcity[testStarted name='renders Staged Upgrades Groups' flowId='1']
##teamcity[testStarted name='renders Staged Upgrades Sequence' flowId='2']
##teamcity[testStarted name='can switch between groups and sequence view' flowId='3']
##teamcity[testFinished name='renders Staged Upgrades Groups' duration='1244' flowId='1']
##teamcity[testFinished name='renders Staged Upgrades Sequence' duration='332' flowId='2']
##teamcity[testFinished name='can switch between groups and sequence view' duration='443' flowId='3']
##teamcity[testSuiteFinished name='components/EnhancedStagedUpgrades/__tests__/MainPage-test.tsx']
Then test results will be reported properly with correct durations.