Flaky promtail test

[cyriltovena]

Describe the bug
It seems that a flaky promtail test is causing multiple CI to fail.

To Reproduce
https://circleci.com/gh/grafana/loki/16854?utm_campaign=vcs-integration-link&utm_medium=referral&utm_source=github-checks-link

[adityacs]

@cyriltovena Is my understanding correct? If we have below loglines

{"log":"11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] \"GET /1986.js HTTP/1.1\" 200 932 \"-\" \"Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6\"","stream":"stderr","time":"2019-04-30T02:12:41.8443515Z"},
{"log":"11.11.11.12 - - [19/May/2015:04:05:16 -0500] \"POST /blog HTTP/1.1\" 200 10975 \"http://grafana.com/test/\" \"Mozilla/5.0 (Windows NT 6.1; WOW64) Gecko/20091221 Firefox/3.5.7 GTB6\"","stream":"stdout","time":"2019-04-30T02:12:42.8443515Z"},

After Pipeline Processing we should have entries like below.

11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6",
11.11.11.12 - - [19/May/2015:04:05:16 -0500] "POST /blog HTTP/1.1" 200 10975 "http://grafana.com/test/" "Mozilla/5.0 (Windows NT 6.1; WOW64) Gecko/20091221 Firefox/3.5.7 GTB6"

In this run https://circleci.com/gh/grafana/loki/16854?utm_campaign=vcs-integration-link&utm_medium=referral&utm_source=github-checks-link, pipeline has returned the processed lines in reverse and that's why the error.

If there is no order for Pipeline processing then the logic should be changed here https://github.com/grafana/loki/blob/master/pkg/promtail/promtail_test.go#L133-L156.
Currently the expected labels and entries are appended to array and pipeline is expected to give the labels and entries in the same order.

[cyriltovena]

It should be ordered not sure what you mean

[adityacs]

@cyriltovena The expected labels and entries are

Labels

{action="POST", filename="/tmp/promtail_test_QZPnXQvpkg/logs/testPipeline.log", job="varlogs", localhost="", match="true", stream="stdout"}
{action="GET", filename="/tmp/promtail_test_QZPnXQvpkg/logs/testPipeline.log", job="varlogs", localhost="", match="true", stream="stderr"}

Returned Labels

{action="GET", filename="/tmp/promtail_test_QZPnXQvpkg/logs/testPipeline.log", job="varlogs", localhost="", match="true", stream="stderr"}
{action="POST", filename="/tmp/promtail_test_QZPnXQvpkg/logs/testPipeline.log", job="varlogs", localhost="", match="true", stream="stdout"}

Entries

11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"
11.11.11.12 - - [19/May/2015:04:05:16 -0500] "POST /blog HTTP/1.1" 200 10975 "http://grafana.com/test/" "Mozilla/5.0 (Windows NT 6.1; WOW64) Gecko/20091221 Firefox/3.5.7 GTB6"

Returned Entries

11.11.11.12 - - [19/May/2015:04:05:16 -0500] "POST /blog HTTP/1.1" 200 10975 "http://grafana.com/test/" "Mozilla/5.0 (Windows NT 6.1; WOW64) Gecko/20091221 Firefox/3.5.7 GTB6"
11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] "GET /1986.js HTTP/1.1" 200 932 "-" "Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6"

So, what I meant was if you see the expected labels and the returned labels it's actually in reversed order. So, pipeline has processed second log entry first and then the first log entry. I guess this is not the expected behaviour

[cyriltovena]

For sure that test is a big one there must be a race somewhere.

[cyriltovena]

I think the test is using files on the filesystem so may be one file is read before causing the race, I would be ok to not verify order but only assert exact entries expected. We have other tests that cover the ordering.

[adityacs]

@cyriltovena The entries belong to the same file.
https://github.com/grafana/loki/blob/master/pkg/promtail/promtail_test.go#L128-L132

logFile5 := testDir + "/testPipeline.log"
entries := []string{
    `{"log":"11.11.11.11 - frank [25/Jan/2000:14:00:01 -0500] \"GET /1986.js HTTP/1.1\" 200 932 \"-\" \"Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1.7) Gecko/20091221 Firefox/3.5.7 GTB6\"","stream":"stderr","time":"2019-04-30T02:12:41.8443515Z"}`,
    `{"log":"11.11.11.12 - - [19/May/2015:04:05:16 -0500] \"POST /blog HTTP/1.1\" 200 10975 \"http://grafana.com/test/\" \"Mozilla/5.0 (Windows NT 6.1; WOW64) Gecko/20091221 Firefox/3.5.7 GTB6\"","stream":"stdout","time":"2019-04-30T02:12:42.8443515Z"}`,
}

However, I will work on this to change the logic of matching expected labels/entries and returned labels/entries

[adityacs]

I am still confused. If this part of the test(https://github.com/grafana/loki/blob/master/pkg/promtail/promtail_test.go#L218-L222) is working correctly then even this(https://github.com/grafana/loki/blob/master/pkg/promtail/promtail_test.go#L225-L236) should work as well.

If there is no order in processing the entries, maybe something to do with pipeline stage?