Event stuck in buffer and remains unprocessed
A note for the community
Summary
We have vector-0.46.0 installed, running, and successfully reporting logs from our device (armv7 architecture) to our custom vector_sink endpoint. vector_sink configuration looks like the following:
vector_sink:
type: http
inputs:
- <source_input>
encoding:
codec: json
uri: "<custom_endpoint>”
tls:
crt_file: <crt_file_path>
key_file: <key_file_path>
batch:
max_events: 5
timeout_secs: 60
request:
rate_limit_num: 1
rate_limit_duration_secs: 60
retry_initial_backoff_secs: 60
retry_max_duration_secs: 600
retry_jitter_mode: Full
buffer:
type: disk
max_size: 268435488
when_full: blockWe also ran vector in debug mode to capture helpful logs.
Normal behavior
Whenever an event passes through the buffer, the event should get flushed immediately, ensuring vector can successfully reach the sink endpoint. Hence, the “vector_buffer_events” metric should return to zero indicating that the event was flushed. This behavior is shown in the following snapshot visualizing the “vector_buffer_events” metric: we have three events that passed through the buffer and got flushed right after.
In all of the previous three cases, we got the following debug logs indicating that the event was indeed flushed:
Apr 23 HH:MM:SS <device_id> bash[11916]: 2025-04-23THH:MM:SS.xxxZ DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=1}:http: hyper::client::connect::http: connecting to <sink_endpoint_ip>:443
Apr 23 HH:MM:SS <device_id> bash[11916]: 2025-04-23THH:MM:SS.xxxZ DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=1}:http: hyper::client::connect::http: connected to <sink_endpoint_ip>:443
Apr 23 HH:MM:SS <device_id> bash[11916]: 2025-04-23THH:MM:SS.xxxZ DEBUG hyper::proto::h1::io: flushed 806 bytesFlaky behavior
We’ve been experiencing a flaky behavior that is occurring quite frequently. Sometimes, events get stuck in the buffer, and remain unprocessed. We ensured there were no connectivity issues while the event was stuck in the buffer. Debug logs did not capture any helpful clues related to this behavior. We were unable to find the debug logs shown in the “normal behavior” block at the time where the event was stuck in the buffer, which indicates that vector did not even try to connect to the sink endpoint, as if it did not even recognize that an event was added to the buffer.
In the previous snapshot, we had:
- First event flushed at around 12:21
- Second event flushed at around 12:25
- Third event stuck in the buffer
Simplified debug logs related to the previous snapshot were retrieved by running the following command:
cat vector.log | grep "hyper::"Apr 23 08:21:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:07.388096Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:21:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:07.388277Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:21:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:07.436677Z DEBUG hyper::proto::h1::io: flushed 7727 bytes
Apr 23 08:21:55 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:55.212853Z DEBUG hyper::client::connect::dns: resolving host="<sink_endpoint_url>"
Apr 23 08:21:55 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:55.417021Z DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=1}:http: hyper::client::connect::http: connecting to <sink_endpoint_ip>:443
Apr 23 08:21:55 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:55.470642Z DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=1}:http: hyper::client::connect::http: connected to <sink_endpoint_ip>:443
Apr 23 08:21:55 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:55.675285Z DEBUG hyper::proto::h1::io: flushed 806 bytes
Apr 23 08:21:56 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:56.011657Z DEBUG hyper::proto::h1::io: parsed 8 headers
Apr 23 08:21:56 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:56.011772Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:21:56 <DEVICE_ID> bash[6287]: 2025-04-23T12:21:56.012018Z DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=1}:http: hyper::client::pool: pooling idle connection for ("https", <sink_endpoint_url>)
Apr 23 08:22:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:22:07.384037Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:22:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:22:07.384124Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:22:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:22:07.434042Z DEBUG hyper::proto::h1::io: flushed 8651 bytes
Apr 23 08:23:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:23:07.384158Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:23:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:23:07.384247Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:23:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:23:07.432680Z DEBUG hyper::proto::h1::io: flushed 8675 bytes
Apr 23 08:24:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:07.383881Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:24:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:07.383960Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:24:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:07.438449Z DEBUG hyper::proto::h1::io: flushed 8684 bytes
Apr 23 08:24:26 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:26.928667Z DEBUG hyper::client::connect::dns: resolving host="<sink_endpoint_url>"
Apr 23 08:24:26 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:26.930799Z DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=2}:http: hyper::client::connect::http: connecting to <sink_endpoint_ip>:443
Apr 23 08:24:26 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:26.984226Z DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=2}:http: hyper::client::connect::http: connected to <sink_endpoint_ip>:443
Apr 23 08:24:27 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:27.192817Z DEBUG hyper::proto::h1::io: flushed 806 bytes
Apr 23 08:24:27 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:27.544361Z DEBUG hyper::proto::h1::io: parsed 8 headers
Apr 23 08:24:27 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:27.544453Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:24:27 <DEVICE_ID> bash[6287]: 2025-04-23T12:24:27.544646Z DEBUG sink{component_kind="sink" component_id=vector_sink component_type=http}:request{request_id=2}:http: hyper::client::pool: pooling idle connection for ("https", <sink_endpoint_url>)
Apr 23 08:25:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:25:07.383671Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:25:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:25:07.383757Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:25:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:25:07.429686Z DEBUG hyper::proto::h1::io: flushed 8741 bytes
Apr 23 08:26:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:26:07.383964Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:26:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:26:07.384047Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:26:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:26:07.429463Z DEBUG hyper::proto::h1::io: flushed 8754 bytes
Apr 23 08:27:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:27:07.384315Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:27:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:27:07.384392Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:27:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:27:07.429674Z DEBUG hyper::proto::h1::io: flushed 8739 bytes
Apr 23 08:28:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:28:07.383742Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:28:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:28:07.383832Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:28:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:28:07.435978Z DEBUG hyper::proto::h1::io: flushed 8774 bytes
Apr 23 08:29:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:29:07.384128Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:29:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:29:07.384218Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:29:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:29:07.445796Z DEBUG hyper::proto::h1::io: flushed 8788 bytes
Apr 23 08:30:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:30:07.384132Z DEBUG hyper::proto::h1::io: parsed 5 headers
Apr 23 08:30:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:30:07.384213Z DEBUG hyper::proto::h1::conn: incoming body is empty
Apr 23 08:30:07 <DEVICE_ID> bash[6287]: 2025-04-23T12:30:07.439902Z DEBUG hyper::proto::h1::io: flushed 8777 bytesIndeed, vector did not try to connect to the sink endpoint url while the event was stuck in the buffer (as it did for the first 2 events at exactly the following timings: 12:21:55 and 12:24:26
We also realized that events that are being stuck in the buffer are not being flushed until one of the following scenarios occur:
We restart the vector service, and the event gets flushed when the service goes back up. This behavior is shown in the following snapshot, visualizing the “vector_buffer_events” metric: vector service was restarted at 14:38
We send another event, in which case both events get processed together. This behavior is shown in the following snapshot also monitoring the “vector_buffer_events” metric: First event sent at 11:30 Second event sent at 12:01
Problem
Vector is occasionally failing to recognize that an event is preset in the buffer, and as a result, that event gets stuck and remains unprocessed until either restarting vector service or adding another event to the buffer.
Version
0.46.0
Steps to reproduce
Generate one event at a time, and monitor the "vector_buffer_events" metric. Wait for the event to get flushed (metric returns to 0). Once the event is flushed, regenerate another one, and keep on doing so until the event gets stuck in the buffer. The issue is indeed flaky but occurs quite often.
Source: vectordotdev/vector