[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[bot]]

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 https://github.com/open-telemetry/opentelemetry-collector-contrib/pull/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 https://github.com/open-telemetry/opentelemetry-collector-contrib/pull/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 https://github.com/open-telemetry/opentelemetry-collector-contrib/pull/32734#discussion_r1585286407), 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?

https://github.com/golang/go/issues/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?

[pjanotti]

Perhaps finding a way to mock the actual clock? Like done at https://github.com/open-telemetry/opentelemetry-collector-contrib/pull/33443 using https://github.com/tilinna/clock

[ChrsMark]

Perhaps finding a way to mock the actual clock? Like done at #33443 using https://github.com/tilinna/clock

I can give it a try but I think that would mean to pass a Clock instance down to the flush Func?

[pjanotti]

@ChrsMark I'm not that familiar with the component, but, shooting from the hip: what about a private var that by default points to time.Now and something else in the tests?

[ChrsMark]

Thank's for the suggestion @pjanotti! For the specific case it might be doable to do sth similar without the need of a private var. I will send a draft PR to continue the discussion there.

[crobert-1]

Looks like there hasn't been more frequency posed on this issue since #34128 has been merged, closing as resolved.

[djaglowski]

Reopening as this was observed here: https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/10216168544/job/28267069529#step:6:385

[songy23]

+1 https://github.com/open-telemetry/opentelemetry-collector-contrib/actions/runs/10374104032/job/28720802539?pr=34639

[github-actions[bot]]

This issue has been inactive for 60 days. It will be closed in 60 days if there is no activity. To ping code owners by adding a component label, see Adding Labels via Comments, or if you are unsure of which component this issue relates to, please ping @open-telemetry/collector-contrib-triagers. If this issue is still relevant, please ping the code owners or leave a comment explaining why it is still relevant. Otherwise, please close it.

Pinging code owners:

• pkg/stanza: @djaglowski

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