TestSuite Timestamps Report All Constant

[cameron-dunn-sublime]

I recently began using go-junit-report and noticed that all the testsuite timestamp tags were the same for a given report, even though my tests are taking several minutes to run.

Some tools, such as DataDog CI Test Integration use these timestamps to calculate the total time for all tests.

I took a closer look at the code and can see that there's already functionality in place to use time.Now for each testsuite, e.g. here and here. However, CreatePackage is called within a loop that runs after all lines are read. This means that the timestamp represents the current time while generating the report, not the time the test result became available.

I've played around and was able to pretty quickly get a working solution. I was wondering if you'd consider accepting a pull request for this change? It passes existing tests at least, and seems to work as desired when run against my tests. If you are interested in this change, I can do some additional validation and look into expanding tests.

diff --git a/parser/gotest/gotest.go b/parser/gotest/gotest.go
index 2f38282..6d4a09a 100644
--- a/parser/gotest/gotest.go
+++ b/parser/gotest/gotest.go
@@ -8,6 +8,7 @@ import (
        "regexp"
        "strconv"
        "strings"
+       "sync"
        "time"

        "github.com/jstemmer/go-junit-report/v2/gtr"
@@ -136,6 +137,17 @@ func (p *Parser) Parse(r io.Reader) (gtr.Report, error) {

 func (p *Parser) parse(r reader.LineReader) (gtr.Report, error) {
        p.events = nil
+
+       var (
+               finalReport  gtr.Report
+               events       = make(chan Event)
+               waitOnReport sync.WaitGroup
+       )
+       waitOnReport.Add(1)
+       go func() {
+               finalReport = p.report(events)
+               waitOnReport.Add(-1)
+       }()
        for {
                line, metadata, err := r.ReadLine()
                if err == io.EOF {
@@ -162,21 +174,24 @@ func (p *Parser) parse(r reader.LineReader) (gtr.Report, error) {

                for _, ev := range evs {
                        ev.applyMetadata(metadata)
-                       p.events = append(p.events, ev)
+                       events <- ev
                }
        }
-       return p.report(p.events), nil
+       close(events)
+       waitOnReport.Wait()
+
+       return finalReport, nil
 }

 // report generates a gtr.Report from the given list of events.
-func (p *Parser) report(events []Event) gtr.Report {
+func (p *Parser) report(events <-chan Event) gtr.Report {
        rb := newReportBuilder()
        rb.packageName = p.packageName
        rb.subtestMode = p.subtestMode
        if p.timestampFunc != nil {
                rb.timestampFunc = p.timestampFunc
        }
-       for _, ev := range events {
+       for ev := range events {
                rb.ProcessEvent(ev)
        }
        return rb.Build()

By using a channel we can call ProcessEvent at about the same time the test is finished. An alternative approach would be to evaluate a timestamp function in *Parser.summary and add a time.Time to the Event.

Thanks for making and maintaining a great tool!

[jstemmer]

Thanks for the report.

Looks like the main problem is, as you pointed out, that the report is constructed only after everything has been parsed. Your suggested solution appears to work, but I think there's an alternative way to fix this that doesn't involve the added complexity of running report concurrently to parse and communicating via a channel. Instead, we can merge the report code into the parse function. I.e. move the report builder initialization before the for loop in parse and call rb.ProcessEvent at the same place where the events are added to the p.events slice.

Another potential problem I found is that the package timestamp in the report builder only gets set when we encounter a summary line (in CreatePackage), which is pretty much when the test has already completed. I'm not sure whether timestamp field was intended to contain the starting or ending timestamp of the testsuite, but I suspect it's the former. To fix this we'd have to modify the packageBuilder to store the creation timestamp in newPackageBuilder (which typically happens when we process the first event of a new package) and use that rather than the current timestamp in CreatePackage.

If you're interested in fixing these, feel free to send some PR's. Otherwise I'm happy to make the change once I have some time.

[cameron-dunn-sublime]

Thanks! I'll take a look at implementing it as you describe, that makes sense as well.

I'm not sure whether timestamp field was intended to contain the starting or ending timestamp of the testsuite, but I suspect it's the former. To fix this we'd have to modify the packageBuilder to store the creation timestamp in newPackageBuilder (which typically happens when we process the first event of a new package) and use that rather than the current timestamp in CreatePackage.

I suspect it's meant to be the start timestamp as well. This wasn't impacting for me, but it probably makes sense to address at the same time. I was thinking we could also use the timestamp function minus the duration. I think if it was based on the first event of a package the reported timestamps per test could be well before the test actually started. I might be misunderstanding the fields though!

[cameron-dunn-sublime]

Hey @jstemmer, sorry for the extreme delay/lack of comms. Anyways I finally took the time to take a closer look at implement the suggested solution. PR up and it works great!

[cameron-dunn-sublime]

@jstemmer, sorry for the extra ping -- I just wanted to see if you may have an opportunity to review and merge the change.

[jstemmer]

No problem. I've been busy lately, so didn't get a chance to take a look until just now. Thanks for taking the time to fix this!

[cameron-dunn-sublime]

Thanks, much appreciated and totally understand being busy -- took me 5 months to actually make the change 🤷‍♂️