JUnit time is 0

[jaredallard]

Hi! Reporting an issue I found :( Currently when I run the following:

# count is just to ensure that we always run the test
gotestsum --junitfile bin/unit-tests.xml --format dots-v2 ./... -count 1

I get a junit file that looks like so:

unit-tests.xml

<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
        <testsuite tests="0" failures="0" time="0.000000" name="github.com/getoutreach/discovery/cmd/discovery" timestamp="2021-08-24T14:44:12-07:00">
                <properties>
                        <property name="go.version" value="go1.16.5 darwin/arm64"></property>
                </properties>
        </testsuite>
        <testsuite tests="0" failures="0" time="0.000000" name="github.com/getoutreach/discovery/internal/config" timestamp="2021-08-24T14:44:12-07:00">
                <properties>
                        <property name="go.version" value="go1.16.5 darwin/arm64"></property>
                </properties>
        </testsuite>
        <testsuite tests="3" failures="0" time="0.000000" name="github.com/getoutreach/discovery/internal/discovery" timestamp="2021-08-24T14:44:12-07:00">
                <properties>
                        <property name="go.version" value="go1.16.5 darwin/arm64"></property>
                </properties>
                <testcase classname="github.com/getoutreach/discovery/internal/discovery" name="TestAll/TestHandlerReturnsBentos" time="0.000000"></testcase>
                <testcase classname="github.com/getoutreach/discovery/internal/discovery" name="TestAll/TestHandlerMissingRoute" time="0.000000"></testcase>
                <testcase classname="github.com/getoutreach/discovery/internal/discovery" name="TestAll" time="0.000000"></testcase>
        </testsuite>
        <testsuite tests="0" failures="0" time="0.000000" name="github.com/getoutreach/discovery/pkg/scraper" timestamp="2021-08-24T14:44:12-07:00">
                <properties>
                        <property name="go.version" value="go1.16.5 darwin/arm64"></property>
                </properties>
        </testsuite>
        <testsuite tests="1" failures="0" time="0.000000" name="github.com/getoutreach/discovery/pkg/scraper/scraper_test" timestamp="2021-08-24T14:44:12-07:00">
                <properties>
                        <property name="go.version" value="go1.16.5 darwin/arm64"></property>
                </properties>
                <testcase classname="github.com/getoutreach/discovery/pkg/scraper/scraper_test" name="TestShouldCorrectlyReturnBentos" time="0.000000"></testcase>
        </testsuite>
        <testsuite tests="0" failures="0" time="0.000000" name="github.com/getoutreach/discovery/pkg/web" timestamp="2021-08-24T14:44:12-07:00">
                <properties>
                        <property name="go.version" value="go1.16.5 darwin/arm64"></property>
                </properties>
        </testsuite>
</testsuites>

For some reason time is always equal to 0. What's slightly interesting is that if I use the json outputter, that doesn't seem to be the case:

unit-tests.json

{"Time":"2021-08-24T14:47:18.997192-07:00","Action":"output","Package":"github.com/getoutreach/discovery/cmd/discovery","Output":"?   \tgithub.com/getoutreach/discovery/cmd/discovery\t[no test files]\n"}
{"Time":"2021-08-24T14:47:18.997378-07:00","Action":"skip","Package":"github.com/getoutreach/discovery/cmd/discovery","Elapsed":0}
{"Time":"2021-08-24T14:47:18.997391-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/config","Output":"?   \tgithub.com/getoutreach/discovery/internal/config\t[no test files]\n"}
{"Time":"2021-08-24T14:47:18.997395-07:00","Action":"skip","Package":"github.com/getoutreach/discovery/internal/config","Elapsed":0}
{"Time":"2021-08-24T14:47:19.690272-07:00","Action":"run","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Test":"TestShouldCorrectlyReturnBentos"}
{"Time":"2021-08-24T14:47:19.690336-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Test":"TestShouldCorrectlyReturnBentos","Output":"=== RUN   TestShouldCorrectlyReturnBentos\n"}
{"Time":"2021-08-24T14:47:19.690364-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Test":"TestShouldCorrectlyReturnBentos","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.690155-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"running scrapers\"}\n"}
{"Time":"2021-08-24T14:47:19.690376-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Test":"TestShouldCorrectlyReturnBentos","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.690321-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"running scrapers\"}\n"}
{"Time":"2021-08-24T14:47:19.690385-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Test":"TestShouldCorrectlyReturnBentos","Output":"--- PASS: TestShouldCorrectlyReturnBentos (0.00s)\n"}
{"Time":"2021-08-24T14:47:19.690386-07:00","Action":"pass","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Test":"TestShouldCorrectlyReturnBentos","Elapsed":0}
{"Time":"2021-08-24T14:47:19.690392-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Output":"PASS\n"}
{"Time":"2021-08-24T14:47:19.690403-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.690327-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"error.error\":\"context canceled\",\"error.kind\":\"error\",\"error.message\":\"context canceled\",\"level\":\"WARN\",\"message\":\"context is done, stopping scraper\"}\n"}
{"Time":"2021-08-24T14:47:19.69084-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Output":"ok  \tgithub.com/getoutreach/discovery/pkg/scraper/scraper_test\t0.173s\n"}
{"Time":"2021-08-24T14:47:19.690864-07:00","Action":"pass","Package":"github.com/getoutreach/discovery/pkg/scraper/scraper_test","Elapsed":0.173}
{"Time":"2021-08-24T14:47:19.897476-07:00","Action":"run","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll"}
{"Time":"2021-08-24T14:47:19.897502-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll","Output":"=== RUN   TestAll\n"}
{"Time":"2021-08-24T14:47:19.897586-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll","Output":"    suite.go:57: Shuffling tests using seed 1629841639897473000\n"}
{"Time":"2021-08-24T14:47:19.897615-07:00","Action":"run","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute"}
{"Time":"2021-08-24T14:47:19.897619-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Output":"=== RUN   TestAll/TestHandlerMissingRoute\n"}
{"Time":"2021-08-24T14:47:19.897941-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.897684-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"No configuration file detected. Using default settings\"}\n"}
{"Time":"2021-08-24T14:47:19.897963-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.897922-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"Configuration data of the application:\\n\"}\n"}
{"Time":"2021-08-24T14:47:19.898899-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.898872-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"running scrapers\"}\n"}
{"Time":"2021-08-24T14:47:19.899143-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.899102-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"error.cause.cause.cause.kind\":\"cause\",\"error.cause.cause.cause.message\":\"input member Bucket must not be empty\",\"error.cause.cause.kind\":\"cause\",\"error.cause.cause.message\":\"serialization failed\",\"error.cause.kind\":\"cause\",\"error.cause.message\":\"serialization failed\",\"error.error\":\"operation error S3: GetObject, serialization failed: serialization failed: input member Bucket must not be empty\",\"error.kind\":\"error\",\"error.message\":\"operation error S3: GetObject, \",\"level\":\"ERROR\",\"message\":\"failed to discover\"}\n"}
{"Time":"2021-08-24T14:47:19.899162-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.899135-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"error.cause.cause.cause.kind\":\"cause\",\"error.cause.cause.cause.message\":\"input member Bucket must not be empty\",\"error.cause.cause.kind\":\"cause\",\"error.cause.cause.message\":\"serialization failed\",\"error.cause.kind\":\"cause\",\"error.cause.message\":\"serialization failed\",\"error.error\":\"operation error S3: GetObject, serialization failed: serialization failed: input member Bucket must not be empty\",\"error.kind\":\"error\",\"error.message\":\"operation error S3: GetObject, \",\"level\":\"ERROR\",\"message\":\"failed to start scraper\"}\n"}
{"Time":"2021-08-24T14:47:19.900358-07:00","Action":"run","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos"}
{"Time":"2021-08-24T14:47:19.900363-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Output":"=== RUN   TestAll/TestHandlerReturnsBentos\n"}
{"Time":"2021-08-24T14:47:19.900414-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.900363-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"No configuration file detected. Using default settings\"}\n"}
{"Time":"2021-08-24T14:47:19.900424-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.900404-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"Configuration data of the application:\\n\"}\n"}
{"Time":"2021-08-24T14:47:19.900571-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.900553-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"level\":\"INFO\",\"message\":\"running scrapers\"}\n"}
{"Time":"2021-08-24T14:47:19.900616-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.900578-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"error.cause.cause.cause.kind\":\"cause\",\"error.cause.cause.cause.message\":\"input member Bucket must not be empty\",\"error.cause.cause.kind\":\"cause\",\"error.cause.cause.message\":\"serialization failed\",\"error.cause.kind\":\"cause\",\"error.cause.message\":\"serialization failed\",\"error.error\":\"operation error S3: GetObject, serialization failed: serialization failed: input member Bucket must not be empty\",\"error.kind\":\"error\",\"error.message\":\"operation error S3: GetObject, \",\"level\":\"ERROR\",\"message\":\"failed to discover\"}\n"}
{"Time":"2021-08-24T14:47:19.900642-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Output":"{\"@timestamp\":\"2021-08-24T14:47:19.900614-07:00\",\"app.version\":\"Please see http://github.com/getoutreach/gobox/blob/master/docs/version.md\",\"error.cause.cause.cause.kind\":\"cause\",\"error.cause.cause.cause.message\":\"input member Bucket must not be empty\",\"error.cause.cause.kind\":\"cause\",\"error.cause.cause.message\":\"serialization failed\",\"error.cause.kind\":\"cause\",\"error.cause.message\":\"serialization failed\",\"error.error\":\"operation error S3: GetObject, serialization failed: serialization failed: input member Bucket must not be empty\",\"error.kind\":\"error\",\"error.message\":\"operation error S3: GetObject, \",\"level\":\"ERROR\",\"message\":\"failed to start scraper\"}\n"}
{"Time":"2021-08-24T14:47:19.901453-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll","Output":"--- PASS: TestAll (0.00s)\n"}
{"Time":"2021-08-24T14:47:19.901464-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Output":"    --- PASS: TestAll/TestHandlerMissingRoute (0.00s)\n"}
{"Time":"2021-08-24T14:47:19.901475-07:00","Action":"pass","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerMissingRoute","Elapsed":0}
{"Time":"2021-08-24T14:47:19.901485-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Output":"    --- PASS: TestAll/TestHandlerReturnsBentos (0.00s)\n"}
{"Time":"2021-08-24T14:47:19.901489-07:00","Action":"pass","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll/TestHandlerReturnsBentos","Elapsed":0}
{"Time":"2021-08-24T14:47:19.901493-07:00","Action":"pass","Package":"github.com/getoutreach/discovery/internal/discovery","Test":"TestAll","Elapsed":0}
{"Time":"2021-08-24T14:47:19.901497-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Output":"PASS\n"}
{"Time":"2021-08-24T14:47:19.902221-07:00","Action":"output","Package":"github.com/getoutreach/discovery/internal/discovery","Output":"ok  \tgithub.com/getoutreach/discovery/internal/discovery\t0.317s\n"}
{"Time":"2021-08-24T14:47:19.902236-07:00","Action":"pass","Package":"github.com/getoutreach/discovery/internal/discovery","Elapsed":0.317}
{"Time":"2021-08-24T14:47:19.903616-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/scraper","Output":"?   \tgithub.com/getoutreach/discovery/pkg/scraper\t[no test files]\n"}
{"Time":"2021-08-24T14:47:19.903632-07:00","Action":"skip","Package":"github.com/getoutreach/discovery/pkg/scraper","Elapsed":0}
{"Time":"2021-08-24T14:47:19.903669-07:00","Action":"output","Package":"github.com/getoutreach/discovery/pkg/web","Output":"?   \tgithub.com/getoutreach/discovery/pkg/web\t[no test files]\n"}
{"Time":"2021-08-24T14:47:19.903672-07:00","Action":"skip","Package":"github.com/getoutreach/discovery/pkg/web","Elapsed":0}

Any thoughts? 😄

[dnephin]

Thank you for the bug report!

I believe I know what is happening. Currently the TestSuite.Time is being set to the sum of the elapsed time of all tests. The elapsed time of the package is not being stored.

From the JSON output it looks like all tests run in 0.00s, but the package includes some other time which might come from init() functions, a TestMain, or maybe static declarations.

I think the TestSuite.Time should probably be the elapsed time reported on the package pass or fail event, instead of the sum of the elapsed time of all tests. That should fix this issue.