Allow for loki-canary to generate a percentage of out of order log lines

[cstyan]

Allows loki canary to generate a percentage of log lines with out of order timestamps, percentage and out of order time range is configurable.

Signed-off-by: Callum Styan callumstyan@gmail.com

[owen-d]

Some nits then lgtm

[owen-d]

Let's make these time.Duration instead of an int measuring seconds for ease of use.

[cstyan]

thought this would make the math ugly later on, but it's fine since <time.Duration>.Seconds() exists, so done

[owen-d]

Suggested change

	if i := rand.Intn(99) + 1; i <= w.outOfOrderPercentage {
	if i := rand.Intn(100) + 1; i <= w.outOfOrderPercentage {

I think this should be Intn(100) due to inclusivity ([0,n)).

edit: Oh I see, were you using 99 then adding one in order to ensure it was at least one second behind? I see the appeal, but I think it's unnecessarily complex as we're only guaranteeing it's older than time.Now(), not necessarily the log line previously sent.

[cstyan]

No you're right it should be 100, I misread the notation.

This rng is to decide whether the log line should be out of order in the first place, not how much time to subtract.

[owen-d]

I ran this locally and think there are a few pieces missing. Notably, the reader and comparator currently expect the data to be ordered and will likely need to be refactored to support unordered writes. This may end up being a nontrivial refactor, but worthwhile.

[cstyan]

Without unordered writes enabled we get log lines (stderr) like this in the canary

websocket missing entry: 1628791469549189937
websocket missing entry: 1628791474548965353
websocket missing entry: 1628791484548915584
websocket missing entry: 1628791497549229427
websocket missing entry: 1628791501548969567
websocket missing entry: 1628791513549245135
websocket missing entry: 1628791524549176662
websocket missing entry: 1628791518549201846
websocket missing entry: 1628791520549661233
websocket missing entry: 1628791527548708454
websocket missing entry: 1628791550548754504
websocket missing entry: 1628791550548966003

out of order entry 2021-08-12 11:07:55.548713535 -0700 PDT m=+182.013106001 was received before entries: [2021-08-12 11:06:54.54871262 -0700 PDT m=+121.013105152 2021-08-12 11:07:09.548973316 -0700 PDT m=+136.013365782]
out of order entry 2021-08-12 11:07:56.548824291 -0700 PDT m=+183.013216736 was received before entries: [2021-08-12 11:06:54.54871262 -0700 PDT m=+121.013105152 2021-08-12 11:07:09.548973316 -0700 PDT m=+136.013365782]
succesfull query!
out of order entry 2021-08-12 11:07:57.548959794 -0700 PDT m=+184.013352238 was received before entries: [2021-08-12 11:06:54.54871262 -0700 PDT m=+121.013105152 2021-08-12 11:07:09.548973316 -0700 PDT m=+136.013365782]
out of order entry 2021-08-12 11:07:58.548764825 -0700 PDT m=+185.013157267 was received before entries: [2021-08-12 11:06:54.54871262 -0700 PDT m=+121.013105152 2021-08-12 11:07:09.548973316 -0700 PDT m=+136.013365782]

The first block is from the pruneEntries routine, which is checking for each log line generated by the canary by running a query for that lines timestamp +/- 10 seconds. Note that the query is run after those log lines. This works because the tailing routine run by the reader code/websocket connection sends every timestamp it receives over the recv channel, and the comparator removes those timestamps from entries So pruneEntries/confirmMissing is only trying to query for logs we haven't seen come in over the tail connection yet. If the queries return some of the logs we're missing those are removed from the missingEntries slice, and eventually missing entries that are too old are removed as well.

The second block is from the comparators code entryReceived, which is called for each entry sent over the channel from the tailing routine. This is the part where we remove log lines from entries when we see each timestamp make it to Loki. The out of order entry message is printed since when we receive some timestamps the next timestamp we actually expected to receive was the out of order timestamp, but it was rejected by Loki.

c.entries = pruneList(c.entries,
        func(_ int, t *time.Time) bool {
	        return ts.Equal(*t)
        },
        func(i int, t *time.Time) {
	        matched = true
	        // If this isn't the first item in the list we received it out of order
	        if i != 0 {
		        outOfOrderEntries.Inc()
		        fmt.Fprintf(c.w, ErrOutOfOrderEntry, t, c.entries[:i])
	        }
	        responseLatency.Observe(time.Since(ts).Seconds())
	        // Put this element in the acknowledged entries list so we can use it to check for duplicates
	        c.ackdEntries = append(c.ackdEntries, c.entries[i])
        })

We don't see log lines from either of the above example blocks if unordered_writes_enabled is set to true.

EDIT: also note that we need to have promtail pipeline stages to use the generated timestamp from the canaries log lines as the actual timestamp, otherwise all the log lines are ordered as far as loki is concerned.

[owen-d]

If the queries return some of the logs we're missing those are removed from the missingEntries slice, and eventually missing entries that are too old are removed as well.

We should ensure that the out-of-order-max < spot-check-max.

Also, the equality matcher in pruneEntries is a little worrisome as it only checks the timestamp. Since we're now creating entries that may be older than time.Now(), it's possible, albeit unlikely (nanosecond collision) that we see duplicates here. We can likely leave that for a followup PR if necessary.

[slim-bean]

I think we should update the docs to include information about these changes and make it explicit you need to configure promtail time extraction from the log line for this to work.

Aside from adding some docs this LGTM!

[owen-d]

ref #1544