Skip to content

Log before and after Event processing calls #3449

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Dec 9, 2024
+40 −15
Merged

Log before and after Event processing calls #3449

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions lightning/src/chain/chainmonitor.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -573,7 +573,7 @@ where C::Target: chain::Filter,
for funding_txo in mons_to_process {
let mut ev;
match super::channelmonitor::process_events_body!(
self.monitors.read().unwrap().get(&funding_txo).map(|m| &m.monitor), ev, handler(ev).await) {
self.monitors.read().unwrap().get(&funding_txo).map(|m| &m.monitor), self.logger, ev, handler(ev).await) {
Ok(()) => {},
Err(ReplayEvent ()) => {
self.event_notifier.notify();
Expand Down Expand Up @@ -909,7 +909,7 @@ impl<ChannelSigner: EcdsaChannelSigner, C: Deref, T: Deref, F: Deref, L: Deref,
/// [`BumpTransaction`]: events::Event::BumpTransaction
fn process_pending_events<H: Deref>(&self, handler: H) where H::Target: EventHandler {
for monitor_state in self.monitors.read().unwrap().values() {
match monitor_state.monitor.process_pending_events(&handler) {
match monitor_state.monitor.process_pending_events(&handler, &self.logger) {
Ok(()) => {},
Err(ReplayEvent ()) => {
self.event_notifier.notify();
Expand Down
23 changes: 15 additions & 8 deletions lightning/src/chain/channelmonitor.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1236,7 +1236,7 @@ impl<Signer: EcdsaChannelSigner> Writeable for ChannelMonitorImpl<Signer> {
}

macro_rules! _process_events_body {
($self_opt: expr, $event_to_handle: expr, $handle_event: expr) => {
($self_opt: expr, $logger: expr, $event_to_handle: expr, $handle_event: expr) => {
loop {
let mut handling_res = Ok(());
let (pending_events, repeated_events);
Expand All @@ -1253,8 +1253,11 @@ macro_rules! _process_events_body {

let mut num_handled_events = 0;
for event in pending_events {
log_trace!($logger, "Handling event {:?}...", event);
$event_to_handle = event;
match $handle_event {
let event_handling_result = $handle_event;
log_trace!($logger, "Done handling event, result: {:?}", event_handling_result);
match event_handling_result {
Ok(()) => num_handled_events += 1,
Err(e) => {
// If we encounter an error we stop handling events and make sure to replay
Expand Down Expand Up @@ -1614,19 +1617,23 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitor<Signer> {
///
/// [`SpendableOutputs`]: crate::events::Event::SpendableOutputs
/// [`BumpTransaction`]: crate::events::Event::BumpTransaction
pub fn process_pending_events<H: Deref>(&self, handler: &H) -> Result<(), ReplayEvent> where H::Target: EventHandler {
pub fn process_pending_events<H: Deref, L: Deref>(&self, handler: &H, logger: &L)
-> Result<(), ReplayEvent> where H::Target: EventHandler, L::Target: Logger {
let mut ev;
process_events_body!(Some(self), ev, handler.handle_event(ev))
process_events_body!(Some(self), logger, ev, handler.handle_event(ev))
}

/// Processes any events asynchronously.
///
/// See [`Self::process_pending_events`] for more information.
pub async fn process_pending_events_async<Future: core::future::Future<Output = Result<(), ReplayEvent>>, H: Fn(Event) -> Future>(
&self, handler: &H
) -> Result<(), ReplayEvent> {
pub async fn process_pending_events_async<
Future: core::future::Future<Output = Result<(), ReplayEvent>>, H: Fn(Event) -> Future,
L: Deref,
>(
&self, handler: &H, logger: &L,
) -> Result<(), ReplayEvent> where L::Target: Logger {
let mut ev;
process_events_body!(Some(self), ev, { handler(ev).await })
process_events_body!(Some(self), logger, ev, { handler(ev).await })
}

#[cfg(test)]
Expand Down
5 changes: 4 additions & 1 deletion lightning/src/ln/channelmanager.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Copy link
Contributor

@tnull tnull Dec 9, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

$event_to_handle = event;
match $handle_event {
let event_handling_result = $handle_event;
log_trace!($self.logger, "Done handling event, result: {:?}", event_handling_result);
match event_handling_result {
Ok(()) => {
if let Some(action) = action_opt {
post_event_actions.push(action);
Expand Down
23 changes: 19 additions & 4 deletions lightning/src/onion_message/messenger.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1427,7 +1427,9 @@ where
for (node_id, recipient) in self.message_recipients.lock().unwrap().iter_mut() {
if let OnionMessageRecipient::PendingConnection(_, addresses, _) = recipient {
if let Some(addresses) = addresses.take() {
let future = ResultFuture::Pending(handler(Event::ConnectionNeeded { node_id: *node_id, addresses }));
let event = Event::ConnectionNeeded { node_id: *node_id, addresses };
log_trace!(self.logger, "Handling event {:?} async...", event);
let future = ResultFuture::Pending(handler(event));
futures.push(future);
}
}
Expand All @@ -1439,11 +1441,13 @@ where

for ev in intercepted_msgs {
if let Event::OnionMessageIntercepted { .. } = ev {} else { debug_assert!(false); }
log_trace!(self.logger, "Handling event {:?} async...", ev);
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, "Done handling events async, results: {:?}", res);
let mut res_iter = res.iter().skip(intercepted_msgs_offset);
drop_handled_events_and_abort!(self, res_iter, self.pending_intercepted_msgs_events);
}
Expand All @@ -1464,10 +1468,12 @@ where
} else {
let mut futures = Vec::new();
for event in peer_connecteds {
log_trace!(self.logger, "Handling event {:?} async...", event);
let future = ResultFuture::Pending(handler(event));
futures.push(future);
}
let res = MultiResultFuturePoller::new(futures).await;
log_trace!(self.logger, "Done handling events async, results: {:?}", res);
let mut res_iter = res.iter();
drop_handled_events_and_abort!(self, res_iter, self.pending_peer_connected_events);
}
Expand Down Expand Up @@ -1520,7 +1526,10 @@ where
for (node_id, recipient) in self.message_recipients.lock().unwrap().iter_mut() {
if let OnionMessageRecipient::PendingConnection(_, addresses, _) = recipient {
if let Some(addresses) = addresses.take() {
let _ = handler.handle_event(Event::ConnectionNeeded { node_id: *node_id, addresses });
let event = Event::ConnectionNeeded { node_id: *node_id, addresses };
log_trace!(self.logger, "Handling event {:?}...", event);
let res = handler.handle_event(event);
log_trace!(self.logger, "Done handling event, ignoring result: {:?}", res);
}
}
}
Expand All @@ -1544,7 +1553,10 @@ where
let mut handling_intercepted_msgs_failed = false;
let mut num_handled_intercepted_events = 0;
for ev in intercepted_msgs {
match handler.handle_event(ev) {
log_trace!(self.logger, "Handling event {:?}...", ev);
let res = handler.handle_event(ev);
log_trace!(self.logger, "Done handling event, result: {:?}", res);
match res {
Ok(()) => num_handled_intercepted_events += 1,
Err(ReplayEvent ()) => {
handling_intercepted_msgs_failed = true;
Expand All @@ -1566,7 +1578,10 @@ where

let mut num_handled_peer_connecteds = 0;
for ev in peer_connecteds {
match handler.handle_event(ev) {
log_trace!(self.logger, "Handling event {:?}...", ev);
let res = handler.handle_event(ev);
log_trace!(self.logger, "Done handling event, result: {:?}", res);
match res {
Ok(()) => num_handled_peer_connecteds += 1,
Err(ReplayEvent ()) => {
self.event_notifier.notify();
Expand Down
Loading