Skip to content

Commit 27497d0

Browse files
fix(shutdown): Update known lifecycle flow to warn not error (#25458)
* Update known lifecycle flow to warn not error * Adding changelog * Refactor the stat so its done on every shutdown regardless of cause * Adding tests * fix issue found by codex * update comment on new behavior * More doc updates * fmt update * Rename and move logic to call site * Move function to shared helper file * fmt pass
1 parent 08b6975 commit 27497d0

4 files changed

Lines changed: 259 additions & 2 deletions

File tree

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
TCP-based sources that emit acknowledgements (`fluent`, `logstash`) no longer log a spurious `Error writing acknowledgement, dropping connection.` at ERROR level when the ack write fails because the peer cleanly closed its TLS session (for example, during a rolling pod restart). These graceful shutdowns now log at WARN and no longer increment `component_errors_total{error_code="ack_failed", ...}`, preventing operator dashboards/alerts from firing on routine peer disconnects. Genuine ack write failures are still logged at ERROR and continue to increment `component_errors_total`.
2+
3+
The `connection_shutdown_total{mode="tcp"}` counter is now incremented exactly once per accepted source connection when its per-connection task exits, pairing with `ConnectionOpen` — regardless of cause (TLS handshake failure, shutdown signal during handshake, graceful peer EOF, decoder failure, downstream closed, ack write failure, tripwire, max connection duration). Previously it was not emitted by TCP sources at all.
4+
5+
authors: taylorchandleryoung

src/internal_events/tcp.rs

Lines changed: 107 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -46,6 +46,22 @@ impl InternalEvent for TcpSocketConnectionShutdown {
4646
}
4747
}
4848

49+
/// Emitted once per accepted TCP source connection, after the per-connection
50+
/// task exits — regardless of cause. This includes pre-loop exits (TLS
51+
/// handshake failure, shutdown signal arriving during handshake) as well as
52+
/// every read/ack loop exit (graceful peer EOF, decoder failure, downstream
53+
/// closed, ack write failure, shutdown signal, tripwire, max connection
54+
/// duration). Pairs exactly with `ConnectionOpen`.
55+
#[derive(Debug, NamedInternalEvent)]
56+
pub struct TcpSourceConnectionClosed;
57+
58+
impl InternalEvent for TcpSourceConnectionClosed {
59+
fn emit(self) {
60+
debug!(message = "Connection closed.");
61+
counter!(CounterName::ConnectionShutdownTotal, "mode" => "tcp").increment(1);
62+
}
63+
}
64+
4965
#[cfg(all(unix, feature = "sources-dnstap"))]
5066
#[derive(Debug, NamedInternalEvent)]
5167
pub struct TcpSocketError<'a, E> {
@@ -158,3 +174,94 @@ impl InternalEvent for TcpBytesReceived {
158174
.increment(self.byte_size as u64);
159175
}
160176
}
177+
178+
#[cfg(test)]
179+
mod tests {
180+
use std::io;
181+
182+
use serial_test::serial;
183+
use vector_lib::event::MetricValue;
184+
use vector_lib::internal_event::InternalEvent;
185+
use vector_lib::metrics::Controller;
186+
187+
use super::{TcpSendAckError, TcpSourceConnectionClosed};
188+
189+
/// Returns the current value of a counter matching `name` and all `tags`.
190+
/// Counters that have not yet been touched aren't in the snapshot and
191+
/// register as 0.0 here.
192+
fn counter_value(name: &str, tags: &[(&str, &str)]) -> f64 {
193+
Controller::get()
194+
.expect("metrics controller initialized")
195+
.capture_metrics()
196+
.into_iter()
197+
.find(|m| {
198+
m.name() == name
199+
&& tags
200+
.iter()
201+
.all(|(k, v)| m.tags().is_some_and(|t| t.get(k) == Some(*v)))
202+
})
203+
.map(|m| match m.value() {
204+
MetricValue::Counter { value } => *value,
205+
other => panic!("expected counter for {name}, got {other:?}"),
206+
})
207+
.unwrap_or(0.0)
208+
}
209+
210+
/// `TcpSourceConnectionClosed` MUST bump `connection_shutdown_total{mode="tcp"}`
211+
/// once per emit. Pins the contract that this event is the sole owner of the
212+
/// connection-close counter on the source side.
213+
#[test]
214+
#[serial]
215+
fn tcp_source_connection_closed_increments_shutdown_total() {
216+
crate::test_util::trace_init();
217+
let before = counter_value("connection_shutdown_total", &[("mode", "tcp")]);
218+
219+
TcpSourceConnectionClosed.emit();
220+
221+
let after = counter_value("connection_shutdown_total", &[("mode", "tcp")]);
222+
assert_eq!(after - before, 1.0);
223+
}
224+
225+
/// `TcpSendAckError` is an `*Error` event and per the instrumentation spec MUST
226+
/// only emit on real errors — bumping `component_errors_total` with the
227+
/// `ack_failed` error_code.
228+
#[test]
229+
#[serial]
230+
fn tcp_send_ack_error_emit_always_increments_component_errors_total() {
231+
crate::test_util::trace_init();
232+
let errors_before = counter_value(
233+
"component_errors_total",
234+
&[
235+
("error_code", "ack_failed"),
236+
("error_type", "writer_failed"),
237+
("stage", "sending"),
238+
("mode", "tcp"),
239+
],
240+
);
241+
let shutdown_before = counter_value("connection_shutdown_total", &[("mode", "tcp")]);
242+
243+
TcpSendAckError {
244+
error: io::Error::from(io::ErrorKind::ConnectionReset),
245+
}
246+
.emit();
247+
248+
assert_eq!(
249+
counter_value(
250+
"component_errors_total",
251+
&[
252+
("error_code", "ack_failed"),
253+
("error_type", "writer_failed"),
254+
("stage", "sending"),
255+
("mode", "tcp"),
256+
],
257+
) - errors_before,
258+
1.0,
259+
);
260+
assert_eq!(
261+
counter_value("connection_shutdown_total", &[("mode", "tcp")]),
262+
shutdown_before,
263+
"TcpSendAckError must not bump the connection-close counter — \
264+
that is TcpSourceConnectionClosed's responsibility.",
265+
);
266+
}
267+
}

src/net.rs

Lines changed: 126 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -50,3 +50,129 @@ where
5050
pub fn set_keepalive(socket: &TcpStream, ttl: Duration) -> io::Result<()> {
5151
SockRef::from(socket).set_tcp_keepalive(&TcpKeepalive::new().with_time(ttl))
5252
}
53+
54+
// SSL_R_PROTOCOL_IS_SHUTDOWN from openssl/include/openssl/sslerr.h. Stable across
55+
// OpenSSL 1.1.1 and 3.x. Not re-exported by the `openssl-sys` crate so we pin it here.
56+
const SSL_R_PROTOCOL_IS_SHUTDOWN: std::ffi::c_int = 207;
57+
58+
/// Returns true when an `io::Error` represents a peer-initiated, graceful TLS
59+
/// shutdown (close_notify), rather than a real I/O failure.
60+
///
61+
/// Two cases are recognized:
62+
/// - `SSL_ERROR_ZERO_RETURN`: the peer sent `close_notify` and we observed it
63+
/// during this I/O call.
64+
/// - `SSL_R_PROTOCOL_IS_SHUTDOWN`: a subsequent write after the session was
65+
/// already shut down ("ssl session has been shut down").
66+
pub fn is_graceful_tls_shutdown(err: &io::Error) -> bool {
67+
let Some(ssl) = err
68+
.get_ref()
69+
.and_then(|inner| inner.downcast_ref::<openssl::ssl::Error>())
70+
else {
71+
return false;
72+
};
73+
if ssl.code() == openssl::ssl::ErrorCode::ZERO_RETURN {
74+
return true;
75+
}
76+
ssl.ssl_error().is_some_and(|stack| {
77+
stack
78+
.errors()
79+
.iter()
80+
.any(|e| e.reason_code() == SSL_R_PROTOCOL_IS_SHUTDOWN)
81+
})
82+
}
83+
84+
#[cfg(test)]
85+
mod tests {
86+
use std::pin::Pin;
87+
88+
use openssl::ssl::{SslAcceptor, SslConnector, SslFiletype, SslMethod, SslVerifyMode};
89+
use tokio::io::{AsyncReadExt, AsyncWriteExt};
90+
use tokio::net::TcpListener;
91+
use tokio_openssl::SslStream;
92+
93+
use crate::tls::{TEST_PEM_CA_PATH, TEST_PEM_CRT_PATH, TEST_PEM_KEY_PATH};
94+
95+
use super::{TcpStream, io, is_graceful_tls_shutdown};
96+
97+
#[test]
98+
fn plain_io_errors_are_not_graceful() {
99+
for err in [
100+
io::Error::from(io::ErrorKind::BrokenPipe),
101+
io::Error::from(io::ErrorKind::ConnectionReset),
102+
io::Error::from(io::ErrorKind::UnexpectedEof),
103+
io::Error::other("not an ssl error"),
104+
] {
105+
assert!(
106+
!is_graceful_tls_shutdown(&err),
107+
"expected non-graceful, got graceful for {err:?}",
108+
);
109+
}
110+
}
111+
112+
// Drives a real TLS handshake between two local sockets and completes a
113+
// bidirectional SSL shutdown. A subsequent write surfaces a `std::io::Error`
114+
// wrapping an `openssl::ssl::Error` from the same code path production hits,
115+
// validating that the helper correctly identifies it as a graceful shutdown
116+
// — without having to synthesize an `openssl::ssl::Error` (whose fields are
117+
// crate-private). Bidirectional shutdown is what reliably elicits
118+
// SSL_R_PROTOCOL_IS_SHUTDOWN; a half-closed session would still permit
119+
// writes per RFC 5246.
120+
#[tokio::test]
121+
async fn detects_graceful_shutdown_from_real_ssl_stream() {
122+
let listener = TcpListener::bind("127.0.0.1:0").await.unwrap();
123+
let addr = listener.local_addr().unwrap();
124+
125+
let server = tokio::spawn(async move {
126+
let (stream, _) = listener.accept().await.unwrap();
127+
let mut acceptor = SslAcceptor::mozilla_intermediate(SslMethod::tls()).unwrap();
128+
acceptor
129+
.set_private_key_file(TEST_PEM_KEY_PATH, SslFiletype::PEM)
130+
.unwrap();
131+
acceptor
132+
.set_certificate_chain_file(TEST_PEM_CRT_PATH)
133+
.unwrap();
134+
let acceptor = acceptor.build();
135+
let ssl = openssl::ssl::Ssl::new(acceptor.context()).unwrap();
136+
let mut tls = SslStream::new(ssl, stream).unwrap();
137+
Pin::new(&mut tls).accept().await.unwrap();
138+
// Cleanly close the SSL session — sends close_notify and waits for the peer's.
139+
Pin::new(&mut tls).shutdown().await.unwrap();
140+
});
141+
142+
let mut connector = SslConnector::builder(SslMethod::tls()).unwrap();
143+
connector.set_ca_file(TEST_PEM_CA_PATH).unwrap();
144+
connector.set_verify(SslVerifyMode::NONE);
145+
let ssl = connector
146+
.build()
147+
.configure()
148+
.unwrap()
149+
.into_ssl("localhost")
150+
.unwrap();
151+
let stream = TcpStream::connect(addr).await.unwrap();
152+
let mut tls = SslStream::new(ssl, stream).unwrap();
153+
Pin::new(&mut tls).connect().await.unwrap();
154+
155+
// Drain the server's close_notify so our SSL state observes the peer shutdown.
156+
let mut buf = [0u8; 1];
157+
let n = tls.read(&mut buf).await.unwrap();
158+
assert_eq!(n, 0, "expected EOF from peer's close_notify");
159+
160+
// Complete the bidirectional SSL shutdown locally. Once both sides are
161+
// shut down, OpenSSL marks the session as SHUTDOWN and any further write
162+
// returns SSL_R_PROTOCOL_IS_SHUTDOWN ("ssl session has been shut down").
163+
Pin::new(&mut tls).shutdown().await.unwrap();
164+
165+
let err = tls
166+
.write_all(b"too late")
167+
.await
168+
.expect_err("write after bidirectional shutdown should fail");
169+
170+
assert!(
171+
is_graceful_tls_shutdown(&err),
172+
"expected graceful shutdown detection, got: {err:?} (inner: {:?})",
173+
err.get_ref(),
174+
);
175+
176+
server.await.unwrap();
177+
}
178+
}

src/sources/util/net/tcp/mod.rs

Lines changed: 21 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -37,8 +37,9 @@ use crate::{
3737
internal_events::{
3838
ConnectionOpen, OpenGauge, SocketBindError, SocketEventsReceived, SocketMode,
3939
SocketReceiveError, StreamClosedError, TcpBytesReceived, TcpSendAckError,
40-
TcpSocketTlsConnectionError,
40+
TcpSocketTlsConnectionError, TcpSourceConnectionClosed,
4141
},
42+
net::is_graceful_tls_shutdown,
4243
sources::util::{AfterReadExt, LenientFramedRead},
4344
};
4445

@@ -220,6 +221,12 @@ where
220221
tokio::spawn(
221222
fut.map(move |()| {
222223
drop(open_token);
224+
// Paired with the ConnectionOpen emit above:
225+
// fires exactly once per accepted connection,
226+
// including paths that return early from
227+
// handle_stream (TLS handshake failure,
228+
// shutdown during handshake).
229+
emit!(TcpSourceConnectionClosed);
223230
drop(tcp_connection_permit);
224231
})
225232
.instrument(span.or_current()),
@@ -401,7 +408,19 @@ async fn handle_stream<T>(
401408
if let Some(ack_bytes) = acker.build_ack(ack){
402409
let stream = reader.get_mut().get_mut();
403410
if let Err(error) = stream.write_all(&ack_bytes).await {
404-
emit!(TcpSendAckError{ error });
411+
// Per spec, `*Error` events MUST only be
412+
// emitted on real errors. A peer-initiated
413+
// graceful TLS shutdown during the ack
414+
// write is a lifecycle event, not an error
415+
// — log at warn and skip the emit.
416+
if is_graceful_tls_shutdown(&error) {
417+
warn!(
418+
message = "Connection closed by peer before acknowledgement could be sent.",
419+
error = %error,
420+
);
421+
} else {
422+
emit!(TcpSendAckError { error });
423+
}
405424
break;
406425
}
407426
}

0 commit comments

Comments
 (0)