[pkg/stanza] Fileconsumer TestFlushPeriodEOF test failing on Windows

[crobert-1]

Component(s)

pkg/stanza

Describe the issue you're reporting

Failing CI/CD links:
https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/8849403200/job/24301322178
https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/8850888073/job/24306184699?pr=32529

Failure output:

=== Failed
=== FAIL: fileconsumer/internal/reader TestFlushPeriodEOF (3.01s)
    sink.go:114: 
        	Error Trace:	D:/a/opentelemetry-collector-contrib/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/internal/emittest/sink.go:114
        	            				D:/a/opentelemetry-collector-contrib/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/internal/reader/reader_test.go:209
        	Error:      	timeout: expected: 2, actual: 1
        	Test:       	TestFlushPeriodEOF

=== FAIL: fileconsumer/internal/reader TestFlushPeriodEOF (re-run 1) (3.02s)
    sink.go:114: 
        	Error Trace:	D:/a/opentelemetry-collector-contrib/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/internal/emittest/sink.go:114
        	            				D:/a/opentelemetry-collector-contrib/opentelemetry-collector-contrib/pkg/stanza/fileconsumer/internal/reader/reader_test.go:209
        	Error:      	timeout: expected: 2, actual: 1
        	Test:       	TestFlushPeriodEOF

DONE 2 runs, 3289 tests, 13 skipped, 2 failures in 112.066s

This has been failing pretty consistently (but not quite everytime) for the last few days, I haven't been able to determine why it recently started failing more frequently.

[github-actions]

Pinging code owners:

• pkg/stanza: @djaglowski

%s See Adding Labels via Comments if you do not have permissions to add labels yourself.

[djaglowski]

Could this be related to #32100? @OverOrion @ChrsMark

[OverOrion]

I think it is highly likely to be related. I'll try to have a look at it this week, not sure if I can before SIG though.

EDIT: maybe it has something to do with using \r\n instead of \n?

[ChrsMark]

maybe it has something to do with using \r\n instead of \n?

That's likely :) (windows 🙈).
Maybe using the the fmt library to add the new line (ie fmt.Sprintln) instead of adding it explicitly could help here?

[ChrsMark]

So for some reason on Windows the second token is not collected if we don't append a new line (\n) after it.
That's why we get the error expected: 2, actual: 1, because we were reading only 1 token instead of 2.

It seems to be fixed at #32734.
I'm trying to think though if this error indicates that there is an actual issue in the implementation with how we check for the EOFs.
@djaglowski @OverOrion would that be possible?
Do we have other tests already that would ensure the behavior on Windows?

[crobert-1]

+1 freq: https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/8940807269/job/24559739110

[crobert-1]

+1 freq: https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/8939477614/job/24555590652

[crobert-1]

+1 freq: https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/8993044783/job/24704110759?pr=32932

[OverOrion]

It seems to be fixed at #32734. I'm trying to think though if this error indicates that there is an actual issue in the implementation with how we check for the EOFs. @djaglowski @OverOrion would that be possible? Do we have other tests already that would ensure the behavior on Windows?

When I checked the related code there wasn't anything that stood out EOF / SplitFunc wise.

Maybe in the future it would be worth investigating all the skipped tests on Windows, hopefully they could be (re)enabled.

I think this issue could be closed since #32946 got merged @crobert-1.

[ChrsMark]

I still think that we might have an issue on windows 🤔 . To my mind the test clearly proves that on windows we don't manage the "hanging" situation properly (see #32734 (comment)), right?
So even if we skipped the flaky test for now maybe it would worth it to further investigate this?

[djaglowski]

Yes we should leave this open until the issue is fixed on windows. Skipping is just a hack to not get in everyone else's way.

[pjanotti]

I took a look at this and it seems a frequent issue when running tests on Windows: timing and synchronization. From my debugging the test code is relying on the 5ns flush period to ensure that the read of the second token, the b, is flushed. That, in turn, depends on the flush code check if time.Since(s.LastDataChange) > period succeeding on the first time that the test execution hits it. However, on Windows that doesn't succeeds on the first time the code reaches that check and then there are no other chances to flush the second token.

You can see the timing differences with the following code:

package main

import (
	"fmt"
	"runtime"
	"time"
)

func main() {
	// Count how many times the loop runs until 5 nanoseconds have passed.
	start := time.Now()
	count := 0
	for {
		count++
		if time.Since(start) > 5*time.Nanosecond {
			break
		}
	}
	end := time.Now()
	fmt.Println("GOOS:", runtime.GOOS)
	fmt.Println("Count:", count)
	fmt.Println("Duration:", end.Sub(start))
}

GOOS: windows
Count: 37838
Duration: 532µs

GOOS: darwin
Count: 1
Duration: 304ns

GOOS: linux
Count: 1
Duration: 300ns

[djaglowski]

Thanks for looking into and explaining this @pjanotti. The same problem is likely behind many of the flaky tests we've previously disabled on windows.

I spent a little time reading up on this and found that the core Golang packages have some strategies for dealing with this in their own tests and benchmarks. Notably, I found this PR which appears to implement a solution, but the latest source has moved away from it for reasons I didn't find.

I think it would be quite a benefit to the repo if we could figure out a reasonable solution like this and use it whenever timing is involved in tests.

[ChrsMark]

Maybe something like https://github.com/golang/go/blob/5881ae742fc7eaa9b7d61b4ba37598c42aaa4753/src/testing/testing_windows.go#L47-L70 could do the trick here?

However, is my assumption correct that the time precision issue can hit a real use case as well instead of only the tests?

I wonder if instead of if time.Since(s.LastDataChange) > period we could define+use a highPrecisionTimeSince to solve the timing issue at first place instead of just for the tests?

golang/go#67066 also looks related.

[djaglowski]

@ChrsMark, I looked briefly at the most recent testing/testing_windows.go and found that the underlying implementation relies on CGO. We've avoided taking a dependency on CGO but I don't have a clear understanding of whether or not we would have to in this case. (This isn't very clear direction but I want to call it out as something to consider with any implementation.)

[ChrsMark]

In any case this issue looks to be a valid one. Shall we remove the needs triage label?