Log and ignore transmit errors

[Matthias247]

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.

[Ralith]

General approach looks sound. I'm concerned that someone might be very confused by the subsampled logging, but then logging isn't really a well-defined interface anyway so it's not a huge issue. Still, might be good to document somewhere.

This will also avoid surprising misbehavior when connecting to an unsupported address family, a common issue on OSs which don't default to dual-stack sockets.

[Ralith]

Do we really want to log the contents of the packets being sent? That seems very verbose and uninteresting.

[Matthias247]

yes, the contents are too verbose. However I thought it was interesting to see the src and destination address as well as if e.g. GSO is used. Could either manually log those fields, or add a Debug impl for Transmit which does not log the contents.

[Ralith]

My knee-jerk thought is to favor manually logging, probably pulled out into a helper function.

[Matthias247]

It would need at least 2 helper functions to accommodate for Transmit vs [Transmit] (mmsg case). Not sure whether that's favorable.

[Matthias247]

Added the helper function, after I recognized we only need to log the first Transmits content (which will always be the "offending" one). Also moved the debounce check there, which makes things a bit cleaner

[Matthias247]

Still, might be good to document somewhere.

Where should that be? I actually think most of the error/warning logs need to be sampled, because otherwise the amount of logging that can be caused by peers is immense (servers can be easily DOSd by forcing them to log).

[Ralith]

I actually think most of the error/warning logs need to be sampled, because otherwise the amount of logging that can be caused by peers is immense (servers can be easily DOSd by forcing them to log).

Hmm, that's worrying. Should we push for tracing to provide subsampled events out of the box, and adopt them pervasively? Seems like addressing it in this specific case alone is of comparatively limited value, particularly as this condition should be pretty difficult for a peer to induce.

[djc]

I'm pretty sure tracing subscribers usually have sampling functionality built-in? I know the opentelemetry ecosystem does, at least.

[Matthias247]

I'm pretty sure tracing subscribers usually have sampling functionality built-in? I know the opentelemetry ecosystem does, at least.

Well, that would only help you if you have such a subscriber. The only application that I've worked with so far used tracing purely for debug logs, which dumps everything in log files or console. And not even sure how the tracing usage of quinn and other libraries would be a good fit for a structured logging system, since it doesn't emit metrics/telemetry but random text. On the projects I've worked so far we've usually used different solutions for metrics - but I'm also not experienced enough with tracing to see how to make it work.

Back to the problem: Yes, tracing could either directly offer such an API, but it might have the same challenge you have when e.g. implementing a sampled_warn! macro: Where to store the last timestamp? It can't be part of the span, because that doesn't know all the events emitted in it. It could be a thread-local, which means you potentially get more samples than anticipated on a multithreaded runtime. Or a global, which synchronization for logging - and would suppress messages even if they come from different runtime/connection instances.

Probably both not the end of the world, and quinn including and using those kind of macros could make sense.

[djc]

If you use tracing for debug logs, you're probably using a tracing-subscriber to turn traces into debug logs? Which means a subscriber is involved. I think the right way to implement this would then be to compose this subscriber with a tracing_subscriber::Layer which knows how to sample.

[Ralith]

If our logging is dangerously verbose in general, and general tools are available to solve the problem, does it make sense to go out of our way to sample this one specific message?

[Matthias247]

If our logging is dangerously verbose in general, and general tools are available to solve the problem, does it make sense to go out of our way to sample this one specific message?

My take on this is that everything that is in the info/warn/error category, and can be triggered by sending a single picket, and especially can happen before a connection is established has the potential to flood logs and thereby to slow down the local end of the connection. That should be avoided. But I don't think there are too many of those logs.

Regarding the "general tools" - I'm not familiar with that enough. People (including me) just set a log level on tracing and assume they are good :)

[Ralith]

I suppose we can revisit this logic if needed in an audit pass to address other instances.