Fix duplicate batches in retry queue #5520
Conversation
urso
force-pushed
the
fix/duplicates-in-retry-queue
branch
2 times, most recently
from
0f981b7 to
f7d82c4
Compare
|
This change seems to cause some issues: https://travis-ci.org/elastic/beats/jobs/298049838#L642 |
| err: nil, | ||
| } | ||
|
|
||
| debug("msgref(%p) new: batch=%p, cb=%p", r, &r.batch[0], cb) |
There was a problem hiding this comment.
This will create a lot of debug messages. I know that this info is for debugging, but I start to get the feeling we need something in between info and debug, something like info --verbose :-)
There was a problem hiding this comment.
Yeah, some extra-debug would be nice to have. Normally the debug messages create about 4 new debug messages per batch (2048) events. Not too bad, but super helpful to identify potential issues, should we still face some problems.
There was a problem hiding this comment.
Feel more like a trace level to me, but I am ok with debug since the noise wont be that much.
On error in the Logstash output sender, failed batches might get enqueued two times. This can lead to multiple resends and ACKs for the same events. In filebeat/winlogbeat, waiting for ACK from output, at most one ACK is required. With potentially multiple ACKs (especially with multiple consecutive IO errors) a deadlock in the outputs ACK handler can occur. This PR ensures batches can not be returned to the retry queue via 2 code paths (remove race between competing workers): - async output worker does not return events back into retry queue - async clients are required to always report retrieable errors via callbacks - add some more detailed debug logs to the LS output, that can help in identifiying ACKed batches still being retried
urso
force-pushed
the
fix/duplicates-in-retry-queue
branch
from
a65f57a to
22c6540
Compare
| } | ||
|
|
||
| return err | ||
| return w.client.AsyncPublishEvents(w.handleResults(msg), msg.data) |
There was a problem hiding this comment.
Change in semantics is here. We always require the w.client instance to use the callback build via handleResult to report success/failure within a batch. This allows the output client to decide on sync or async error reporting.
The async client as provided by go-lumber does require full async reporting, but the Logstash output did some sync reporting as well, leading to duplicates. PR changes to have go-lumber only trigger the async reporting, indirectly via msgRef.
|
@urso I am aware of the possible deadlock, but it could cause also just pure duplicates on retry right? I remember seen a few cases recently concerning duplicates. Do we also have an idea since when this problem occur, It might help debugging future past cases. |
|
@ph The bug could produce duplicates on retry if |
| err: nil, | ||
| } | ||
|
|
||
| debug("msgref(%p) new: batch=%p, cb=%p", r, &r.batch[0], cb) |
There was a problem hiding this comment.
Feel more like a trace level to me, but I am ok with debug since the noise wont be that much.
| @@ -28,6 +28,8 @@ https://github.com/elastic/beats/compare/v5.6.4...5.6[Check the HEAD diff] | |||
|
|
|||
| *Affecting all Beats* | |||
|
|
|||
| - Fix duplicate batches of events in retry queue. {pull}5520[5520] | |||
There was a problem hiding this comment.
I would probably mention deadlock, duplicates can be seen in other scenario.
On error in Logstash output sender, failed batches might get enqueued two
times. This can lead to multiple resends and ACKs for the same events.
In filebeat/winlogbeat, waiting for ACK from output, at most one ACK is
required. With potentially multiple ACKs (especially with multiple
consecutive IO errors) a deadlock in the outputs ACK handler can occur.
This PR ensures batches can not be returned to the retry queue via 2 code
paths (remove race between competing workers):
callbacks
identifiying ACKed batches still being retried