Log before and after Event processing calls
#3449
Conversation
| let future = ResultFuture::Pending(handler(ev)); | ||
| futures.push(future); | ||
| } | ||
| // Let the `OnionMessageIntercepted` events finish before moving on to peer_connecteds | ||
| let res = MultiResultFuturePoller::new(futures).await; | ||
| log_trace!(self.logger, "Completed async events, got results {:?}", res); |
There was a problem hiding this comment.
nit: Is following phrasing correct? Maybe this will feel clearer:
| log_trace!(self.logger, "Completed async events, got results {:?}", res); | |
| log_trace!(self.logger, "Async event processing completed. Results: {:?}", res); |
| let future = ResultFuture::Pending(handler(event)); | ||
| futures.push(future); | ||
| } | ||
| let res = MultiResultFuturePoller::new(futures).await; | ||
| log_trace!(self.logger, "Completed async events, got results {:?}", res); |
At various points we've had issues where `Event` processing for a user possibly is taking a long time, causing other things to stall. However, due to lack of logging during `Event` processing itself this can be rather difficult to debug. In 85eb814 we attempted to add logging for this, but in doing so ended up with more verbose logging than we were comfortable with. Instead, here, we log only when we actually process an `Event`, directly in the callsite passing the `Event` to the user. Fixes lightningdevkit#3331
TheBlueMatt
force-pushed
the
2024-12-event-processing-logging
branch
from
f59d2fa to
e2b964e
Compare
|
Unified logging around |
| @@ -3321,8 +3321,11 @@ macro_rules! process_events_body { | |||
|
|
|||
| let mut num_handled_events = 0; | |||
| for (event, action_opt) in pending_events { | |||
| log_trace!($self.logger, "Handling event {:?}...", event); | |||
There was a problem hiding this comment.
Hmm, I could imagine this full Debug logging to be pretty spammy/verbose for some of the larger Event variants. I might be mistaken, but for larger nodes with a lot of traffic this might render TRACE logging infeasible? I wonder if we should either reuse (a renamed) GOSSIP level or introduce another finer-grained log level for this?
There was a problem hiding this comment.
Hmm, I'm skeptical - I don't think there's any Events that will be generated without printing at least one other log somewhere, if not 10s of other logs. Worst case for a node is probably some kind of onion messages that we'd already print once or twice for receiving and now print a third time. I think that's fine and honestly more visibility there is probably good.
At various points we've had issues where
Eventprocessing for a user possibly is taking a long time, causing other things to stall. However, due to lack of logging duringEventprocessing itself this can be rather difficult to debug. In85eb814 we attempted to add logging for this, but in doing so ended up with more verbose logging than we were comfortable with.
Instead, here, we log only when we actually process an
Event, directly in the callsite passing theEventto the user.Fixes #3331