Skip to content

Commit

Permalink
chore: Don't log expected errors (#3016)
Browse files Browse the repository at this point in the history
## Description

<!-- A summary of what this pull request achieves and a rough list of
changes. -->
I'm frequently seeing stuff like this in logs when running tests:
```
2024-12-06T11:33:18.547916Z ERROR iroh::magicsock: 515: failed to send udp: operation would block node=m4suaktjwmn62wiz dst=172.17.0.1:60377
2024-12-06T11:33:18.548017Z ERROR iroh::magicsock: 560: no UDP or relay paths available for node node=m4suaktjwmn62wiz
```

These two logs are totally non-fatal and actually expected.
The first one *especially* since `try_send_upd` can simply return
`io::ErrorKind::WouldBlock` and that's totally normal.

So we avoid printing an error in that case.

I've also made the "no UDP or relay paths available for node" and
another similar log debug level, as that's a state that we routinely
encounter, is expected, and handled.

## Notes & open questions

Just quickly noting that this log was in fact *so* annoying, I kept
seeing the `WouldBlock` stuff a *lot* when running `iroh-doctor` with
you on a train ride back then. It would mess up the whole terminal
rendering :face_with_spiral_eyes:

## Change checklist

- [x] Self-review.
- ~~[ ] Documentation updates following the [style
guide](https://rust-lang.github.io/rfcs/1574-more-api-documentation-conventions.html#appendix-a-full-conventions-text),
if relevant.~~
- ~~[ ] Tests if relevant.~~
- [x] All breaking changes documented.
  • Loading branch information
matheus23 authored Dec 11, 2024
1 parent 0fe7e8b commit fdb687f
Showing 1 changed file with 21 additions and 5 deletions.
26 changes: 21 additions & 5 deletions iroh/src/magicsock.rs
Original file line number Diff line number Diff line change
Expand Up @@ -518,8 +518,14 @@ impl MagicSock {
udp_sent = true;
}
Err(err) => {
error!(node = %node_id.fmt_short(), dst = %addr,
"failed to send udp: {err:#}");
// No need to print "WouldBlock" errors to the console
if err.kind() != io::ErrorKind::WouldBlock {
warn!(
node = %node_id.fmt_short(),
dst = %addr,
"failed to send udp: {err:#}"
);
}
udp_error = Some(err);
}
}
Expand Down Expand Up @@ -563,16 +569,26 @@ impl MagicSock {
// at any time so these errors should be treated as transient and
// are just timeouts. Hence we opt for returning Ok. See
// test_try_send_no_udp_addr_or_relay_url to explore this further.
error!(
debug!(
node = %node_id.fmt_short(),
"no UDP or relay paths available for node",
"no UDP or relay paths available for node, voiding transmit",
);
// We log this as debug instead of error, because this is a
// situation that comes up under normal operation. If this were an
// error log, it would unnecessarily pollute logs.
// This situation happens essentially when `pings_sent` is false,
// `relay_url` is `None`, so `relay_sent` is false, and the UDP
// path is blocking, so `udp_sent` is false and `udp_pending` is
// true.
// Alternatively returning a WouldBlock error here would
// potentially needlessly block sending on the relay path for the
// next datagram.
}
Ok(())
}
}
None => {
error!(%dest, "no NodeState for mapped address");
error!(%dest, "no NodeState for mapped address, voiding transmit");
// Returning Ok here means we let QUIC timeout. Returning WouldBlock
// triggers a hot loop. Returning an error would immediately fail a
// connection. The philosophy of quinn-udp is that a UDP connection could
Expand Down

0 comments on commit fdb687f

Please sign in to comment.