Log and ignore transmit errors

Some more transient transmit errors have been observed. E.g. for some
peers transmission failed with
```
error: Os { code: 101, kind: Other, message: "Network is unreachable" }
```

That lead the endpoint to shut down and not process any messages for any
other clients.

To prevent this, this changes the behavior to ignore errors inside the endpoint.
In order to not lose all visibility, the change however adds low frequency
logging for the errors.

Author: Matthias247

quinn/src/platform/fallback.rs

@@ -2,13 +2,15 @@ use std::{
     io::{self, IoSliceMut},
     net::SocketAddr,
     task::{Context, Poll},
+    time::Instant,
 };
 
 use futures::ready;
 use proto::Transmit;
 use tokio::io::ReadBuf;
+use tracing::warn;
 
-use super::RecvMeta;
+use super::{RecvMeta, IO_ERROR_LOG_INTERVAL};
 
 /// Tokio-compatible UDP socket with some useful specializations.
 ///
@@ -17,18 +19,21 @@ use super::RecvMeta;
 #[derive(Debug)]
 pub struct UdpSocket {
     io: tokio::net::UdpSocket,
+    last_send_error: Instant,
 }
 
 impl UdpSocket {
     pub fn from_std(socket: std::net::UdpSocket) -> io::Result<UdpSocket> {
         socket.set_nonblocking(true)?;
+        let now = Instant::now();
         Ok(UdpSocket {
             io: tokio::net::UdpSocket::from_std(socket)?,
+            last_send_error: now.checked_sub(2 * IO_ERROR_LOG_INTERVAL).unwrap_or(now),
         })
     }
 
     pub fn poll_send(
-        &self,
+        &mut self,
         cx: &mut Context,
         transmits: &[Transmit],
     ) -> Poll<Result<usize, io::Error>> {
@@ -45,7 +50,23 @@ impl UdpSocket {
                 // errors being either harmlessly transient (in the case of WouldBlock) or
                 // recurring on the next call.
                 Poll::Ready(Err(_)) | Poll::Pending if sent != 0 => return Poll::Ready(Ok(sent)),
-                Poll::Ready(Err(e)) => return Poll::Ready(Err(e)),
+                Poll::Ready(Err(e)) => {
+                    // WouldBlock is expected to be returned as `Poll::Pending`
+                    debug_assert!(e.kind() != io::ErrorKind::WouldBlock);
+
+                    // Errors are ignored, since they will ususally be handled
+                    // by higher level retransmits and timeouts.
+                    // - PermissionDenied errors have been observed due to iptable rules.
+                    //   Those are not fatal errors, since the
+                    //   configuration can be dynamically changed.
+                    // - Destination unreachable errors have been observed for other
+                    let now = Instant::now();
+                    if now.saturating_duration_since(self.last_send_error) > IO_ERROR_LOG_INTERVAL {
+                        self.last_send_error = now;
+                        warn!("sendmsg error: {:?}, transmit: {:?}", e, transmit);
+                    }
+                    sent += 1;
+                }
                 Poll::Pending => return Poll::Pending,
             }
         }

quinn/src/platform/mod.rs

@@ -62,3 +62,7 @@ impl Default for RecvMeta {
         }
     }
 }
+
+/// Log at most 1 IO error per minute
+#[cfg(unix)]
+const IO_ERROR_LOG_INTERVAL: std::time::Duration = std::time::Duration::from_secs(60);

quinn/src/platform/unix.rs

@@ -6,14 +6,16 @@ use std::{
     os::unix::io::AsRawFd,
     ptr,
     task::{Context, Poll},
+    time::Instant,
 };
 
 use futures::ready;
 use lazy_static::lazy_static;
 use proto::{EcnCodepoint, Transmit};
 use tokio::io::unix::AsyncFd;
+use tracing::warn;
 
-use super::{cmsg, RecvMeta, UdpCapabilities};
+use super::{cmsg, RecvMeta, UdpCapabilities, IO_ERROR_LOG_INTERVAL};
 
 #[cfg(target_os = "freebsd")]
 type IpTosTy = libc::c_uchar;
@@ -27,26 +29,30 @@ type IpTosTy = libc::c_int;
 #[derive(Debug)]
 pub struct UdpSocket {
     io: AsyncFd<mio::net::UdpSocket>,
+    last_send_error: Instant,
 }
 
 impl UdpSocket {
     pub fn from_std(socket: std::net::UdpSocket) -> io::Result<UdpSocket> {
         socket.set_nonblocking(true)?;
         let io = mio::net::UdpSocket::from_std(socket);
         init(&io)?;
+        let now = Instant::now();
         Ok(UdpSocket {
             io: AsyncFd::new(io)?,
+            last_send_error: now.checked_sub(2 * IO_ERROR_LOG_INTERVAL).unwrap_or(now),
         })
     }
 
     pub fn poll_send(
-        &self,
+        &mut self,
         cx: &mut Context,
         transmits: &[Transmit],
     ) -> Poll<Result<usize, io::Error>> {
         loop {
+            let last_send_error = &mut self.last_send_error;
             let mut guard = ready!(self.io.poll_write_ready(cx))?;
-            if let Ok(res) = guard.try_io(|io| send(io.get_ref(), transmits)) {
+            if let Ok(res) = guard.try_io(|io| send(io.get_ref(), last_send_error, transmits)) {
                 return Poll::Ready(res);
             }
         }
@@ -184,7 +190,11 @@ fn init(io: &mio::net::UdpSocket) -> io::Result<()> {
 }
 
 #[cfg(not(any(target_os = "macos", target_os = "ios")))]
-fn send(io: &mio::net::UdpSocket, transmits: &[Transmit]) -> io::Result<usize> {
+fn send(
+    io: &mio::net::UdpSocket,
+    last_send_error: &mut Instant,
+    transmits: &[Transmit],
+) -> io::Result<usize> {
     let mut msgs: [libc::mmsghdr; BATCH_SIZE] = unsafe { mem::zeroed() };
     let mut iovecs: [libc::iovec; BATCH_SIZE] = unsafe { mem::zeroed() };
     let mut cmsgs = [cmsg::Aligned([0u8; CMSG_LEN]); BATCH_SIZE];
@@ -224,23 +234,38 @@ fn send(io: &mio::net::UdpSocket, transmits: &[Transmit]) -> io::Result<usize> {
                     // Retry the transmission
                     continue;
                 }
-                io::ErrorKind::PermissionDenied => {
-                    // Transmissions can fail with permission errors for example
-                    // due to iptable rules. Those are not fatal errors, since the
-                    // configuration can be dynamically changed.
-                    // In this case we drop the outgoing packets and let higher
-                    // layers retransmit if required.
-                    return Ok(num_transmits);
+                io::ErrorKind::WouldBlock => return Err(e),
+                _ => {
+                    // Other errors are ignored, since they will ususally be handled
+                    // by higher level retransmits and timeouts.
+                    // - PermissionDenied errors have been observed due to iptable rules.
+                    //   Those are not fatal errors, since the
+                    //   configuration can be dynamically changed.
+                    // - Destination unreachable errors have been observed for other
+                    let now = Instant::now();
+                    if now.saturating_duration_since(*last_send_error) > IO_ERROR_LOG_INTERVAL {
+                        *last_send_error = now;
+                        warn!("sendmmsg error: {:?}, transmits: {:?}", e, transmits);
+                    }
+
+                    // The ERRORS section in https://man7.org/linux/man-pages/man2/sendmmsg.2.html
+                    // describes that errors will only be returned if no message could be transmitted
+                    // at all. Therefore drop the first (problematic) message,
+                    // and retry the remaining ones.
+                    return Ok(num_transmits.min(1));
                 }
-                _ => return Err(e),
             }
         }
         return Ok(n as usize);
     }
 }
 
 #[cfg(any(target_os = "macos", target_os = "ios"))]
-fn send(io: &mio::net::UdpSocket, transmits: &[Transmit]) -> io::Result<usize> {
+fn send(
+    io: &mio::net::UdpSocket,
+    last_send_error: &mut Instant,
+    transmits: &[Transmit],
+) -> io::Result<usize> {
     let mut hdr: libc::msghdr = unsafe { mem::zeroed() };
     let mut iov: libc::iovec = unsafe { mem::zeroed() };
     let mut ctrl = cmsg::Aligned([0u8; CMSG_LEN]);
@@ -255,21 +280,22 @@ fn send(io: &mio::net::UdpSocket, transmits: &[Transmit]) -> io::Result<usize> {
                 io::ErrorKind::Interrupted => {
                     // Retry the transmission
                 }
-                io::ErrorKind::PermissionDenied => {
-                    // Transmissions can fail with permission errors for example
-                    // due to iptable rules. Those are not fatal errors, since the
-                    // configuration can be dynamically changed.
-                    // In this case we drop the outgoing packets and let higher
-                    // layers retransmit if required.
+                io::ErrorKind::WouldBlock if sent != 0 => return Ok(sent),
+                io::ErrorKind::WouldBlock => return Err(e),
+                _ => {
+                    // Other errors are ignored, since they will ususally be handled
+                    // by higher level retransmits and timeouts.
+                    // - PermissionDenied errors have been observed due to iptable rules.
+                    //   Those are not fatal errors, since the
+                    //   configuration can be dynamically changed.
+                    // - Destination unreachable errors have been observed for other
+                    let now = Instant::now();
+                    if now.saturating_duration_since(*last_send_error) > IO_ERROR_LOG_INTERVAL {
+                        *last_send_error = now;
+                        warn!("sendmsg error: {:?}, transmit: {:?}", e, &transmits[sent]);
+                    }
                     sent += 1;
                 }
-                _ if sent != 0 => {
-                    // We need to report that some packets were sent in this case, so we rely on
-                    // errors being either harmlessly transient (in the case of WouldBlock) or
-                    // recurring on the next call.
-                    return Ok(sent);
-                }
-                _ => return Err(e),
             }
         } else {
             sent += 1;