Logs from different streams can arrive out of order #401
Conversation
| next if check_for_duplicate && likely_duplicate?(timestamp) | ||
| check_for_duplicate = false # logs are ordered, so once we've seen a new one, assume all subsequent logs are new | ||
| parsed_lines = logs.map { |line| split_timestamped_line(line) } | ||
| sorted_lines = parsed_lines.sort do |a, b| |
There was a problem hiding this comment.
how about something like
sort do |(t1, _), (t2, _)|then you can avoid the [0] below (and the name t makes it bit more obvious that it's the timestamp that's being sorted by).
There was a problem hiding this comment.
I'ld probably go so far as to call the timestamp1 and timestamp2
| logs.each do |line| | ||
| timestamp, msg = split_timestamped_line(line) | ||
| next if check_for_duplicate && likely_duplicate?(timestamp) | ||
| check_for_duplicate = false # logs are ordered, so once we've seen a new one, assume all subsequent logs are new |
| @@ -62,16 +62,23 @@ def rfc3339_timestamp(time) | |||
|
|
|||
| def deduplicate(logs) | |||
There was a problem hiding this comment.
maybe this deserves a new name now? sort_and_deduplicate? sort_and_uniq?
| sorted_lines.each do |line| | ||
| timestamp = line[0] | ||
| msg = line[1] | ||
| next if likely_duplicate?(timestamp) |
There was a problem hiding this comment.
Hm. likely_duplicate? means that timestamp <= @last_timestamp. But how can this ever be true now that we've sorted the logs by timestamp? Or is it possibly true because of a previous call to this method? i.e. an older value of @last_timestamp, not one that was set during this method call?
There was a problem hiding this comment.
Or is it possibly true because of a previous call to this method
Exactly. We fetch logs (and then process them here) repeatedly, and since the API does not support subsecond granularity, we inevitably sometimes get the same log lines in more than one batch.
| end | ||
| end | ||
|
|
||
| sorted_lines.each do |line| |
There was a problem hiding this comment.
sorted_lines.each do |timestamp, msg|saves you the next two lines
| parsed_lines = logs.map { |line| split_timestamped_line(line) } | ||
| sorted_lines = parsed_lines.sort do |a, b| | ||
| if a[0].nil? || b[0].nil? | ||
| 0 |
There was a problem hiding this comment.
Hm. Not sure I'm following this logic. 0 here means the two elements are treated as equal, right? Why is that what we want? I would have expected something like
if a[0].nil?
-1
elsif b[0].nil?
+1
else
a[0] <=> b[0]
endor maybe something like
(a[0] || 0) <=> (b[0] || 0)There was a problem hiding this comment.
My thought was that considering them equal was equivalent to leaving them alone, but that's completely wrong. It totally messes up the sort. Since the actual known case where the timestamp is missing is one where that defective line is the first, I think the second suggestion (assuming no timestamp means earliest) is a good approach.
|
Thanks for fixing this! |
| next if check_for_duplicate && likely_duplicate?(timestamp) | ||
| check_for_duplicate = false # logs are ordered, so once we've seen a new one, assume all subsequent logs are new | ||
| parsed_lines = logs.map { |line| split_timestamped_line(line) } | ||
| sorted_lines = parsed_lines.sort do |a, b| |
There was a problem hiding this comment.
I'ld probably go so far as to call the timestamp1 and timestamp2
What are you trying to accomplish with this PR?
Fix a bug in log streaming when we receive logs out of order: when the last line of the last batch was not the newest, we'd re-print the entire last batch indefinitely. It seems this can happen when stdout and stderr are being interspersed. In the screenshot below, the logs appear in the correct order. The blue numbers indicate the order in which we (reliably) get them back from Kubernetes. Unfortunately the API does not let us request streams separately.
How is this accomplished?
When we receive a batch of logs, sort them before deduplicating them.
What could go wrong?