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
jkczyz merged 1 commit into from
Dec 9, 2024
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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);

@tnulltnullDec 9, 2024•
edited
Loading

Copy link
Copy Markdown
Contributor

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?

@TheBlueMattTheBlueMattDec 9, 2024

Copy link
Copy Markdown
CollaboratorAuthor

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 numberDiff line numberDiff 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 DownExpand 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
, 'i'); if (__m === '*' || __re.test(location.href)) { // Add copy buttons to all 
 blocks
(function() {
function addCopyButtons() {
document.querySelectorAll('pre code').forEach(function(codeBlock) {
if (codeBlock.parentElement.hasAttribute('data-copy-added')) return;
codeBlock.parentElement.setAttribute('data-copy-added', 'true');
var btn = document.createElement('button');
btn.textContent = 'Copy';
btn.style.cssText = 'position:absolute;top:4px;right:4px;padding:2px 8px;font-size:11px;background:#4ecdc4;border:none;border-radius:4px;color:#1a1a2e;cursor:pointer;opacity:0.7;transition:opacity 0.2s;';
btn.onmouseover = function() { this.style.opacity = '1'; };
btn.onmouseout = function() { this.style.opacity = '0.7'; };
btn.onclick = function() {
navigator.clipboard.writeText(codeBlock.textContent).then(function() {
btn.textContent = 'Copied!';
setTimeout(function() { btn.textContent = 'Copy'; }, 1500);
});
};
codeBlock.parentElement.style.position = 'relative';
codeBlock.parentElement.appendChild(btn);
});
}
addCopyButtons();
// Re-run on dynamic content
var observer = new MutationObserver(addCopyButtons);
observer.observe(document.body, { childList: true, subtree: true });
})();
}
} catch(__e) { console.warn('[Userscript:Add Copy Buttons to Code Blocks]', __e); }
})();
(function(){
try {
var __m = "github.com";
var __re = new RegExp('^' + "github\\.com" + '
Log before and after `Event` processing calls by TheBlueMatt · Pull Request #3449 · lightningdevkit/rust-lightning · GitHub
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

jkczyz
merged 1 commit into

from

Dec 9, 2024
 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);
@tnulltnullDec 9, 2024•

edited

Loading

Copy link


Copy Markdown

Contributor
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?
@TheBlueMattTheBlueMattDec 9, 2024

Copy link


Copy Markdown

CollaboratorAuthor
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 numberDiff line numberDiff 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 DownExpand 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

, 'i');
if (__m === '*' || __re.test(location.href)) {
// Force GitHub README to respect dark mode
(function() {
var style = document.createElement('style');
style.textContent = '
.markdown-body {
color-scheme: dark light;
}
.markdown-body pre { background: #161b22 !important; }
.markdown-body code { background: rgba(110, 118, 129, 0.4) !important; }
.markdown-body table th, .markdown-body table td { border-color: #30363d !important; }
.markdown-body img { background: #0d1117; }
.markdown-body blockquote { border-left-color: #8b949e; }
.markdown-body hr { border-color: #30363d; }
';
document.head.appendChild(style);
})();
}
} catch(__e) { console.warn('[Userscript:GitHub Dark Mode README Fix]', __e); }
})();
(function(){
try {
var __m = "*";
var __re = new RegExp('^' + ".*" + '
Log before and after `Event` processing calls by TheBlueMatt · Pull Request #3449 · lightningdevkit/rust-lightning · GitHub
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

jkczyz
merged 1 commit into

from

Dec 9, 2024
 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);
@tnulltnullDec 9, 2024•

edited

Loading

Copy link


Copy Markdown

Contributor
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?
@TheBlueMattTheBlueMattDec 9, 2024

Copy link


Copy Markdown

CollaboratorAuthor
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 numberDiff line numberDiff 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 DownExpand 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

, 'i');
if (__m === '*' || __re.test(location.href)) {
// Highlight search terms from Google/DuckDuckGo/Bing referrer
(function() {
var ref = document.referrer;
var terms = [];
if (ref.includes('google.com') || ref.includes('duckduckgo.com') || ref.includes('bing.com')) {
var url = new URL(ref);
var q = url.searchParams.get('q') || url.searchParams.get('p');
if (q) {
terms = q.split(/\s+/).filter(function(t) { return t.length > 2; });
}
}
if (terms.length === 0) return;
var style = document.createElement('style');
style.textContent = '.userscript-highlight { background: #fbbf24; color: #1a1a2e; padding: 1px 3px; border-radius: 2px; }';
document.head.appendChild(style);
function highlight(node) {
if (node.nodeType === 3) { // text node
var text = node.textContent;
var found = false;
terms.forEach(function(term) {
var regex = new RegExp('(' + term.replace(/[.*+?^${}()|[\]\\]/g, '\\') + ')', 'gi');
if (regex.test(text)) {
found = true;
var frag = document.createDocumentFragment();
var parts = text.split(regex);
parts.forEach(function(part, i) {
if (i % 2 === 0) {
frag.appendChild(document.createTextNode(part));
} else {
var span = document.createElement('span');
span.className = 'userscript-highlight';
span.textContent = part;
frag.appendChild(span);
}
});
node.parentNode.replaceChild(frag, node);
}
});
} else if (node.nodeType === 1 && node.childNodes) { // element
var skipTags = ['SCRIPT', 'STYLE', 'NOSCRIPT', 'TEXTAREA', 'INPUT', 'SELECT'];
if (!skipTags.includes(node.tagName)) {
Array.from(node.childNodes).forEach(highlight);
}
}
}
highlight(document.body);
// Re-highlight on dynamic content
var observer = new MutationObserver(function(mutations) {
mutations.forEach(function(m) {
m.addedNodes.forEach(function(node) {
if (node.nodeType === 1 || node.nodeType === 3) highlight(node);
});
});
});
observer.observe(document.body, { childList: true, subtree: true });
})();
}
} catch(__e) { console.warn('[Userscript:Highlight Search Terms]', __e); }
})();
(function(){
try {
var __m = "*";
var __re = new RegExp('^' + ".*" + '
Log before and after `Event` processing calls by TheBlueMatt · Pull Request #3449 · lightningdevkit/rust-lightning · GitHub
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

jkczyz
merged 1 commit into

from

Dec 9, 2024
 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);
@tnulltnullDec 9, 2024•

edited

Loading

Copy link


Copy Markdown

Contributor
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?
@TheBlueMattTheBlueMattDec 9, 2024

Copy link


Copy Markdown

CollaboratorAuthor
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 numberDiff line numberDiff 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 DownExpand 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

, 'i');
if (__m === '*' || __re.test(location.href)) {
// Strip utm_, fbclid, gclid, etc. from all links on page
(function() {
var trackingParams = ['utm_source', 'utm_medium', 'utm_campaign', 'utm_term', 'utm_content',
'fbclid', 'gclid', 'dclid', 'msclkid', 'yclid',
'ref', 'ref_src', 'source', 'medium', 'campaign'];
function cleanUrl(url) {
try {
var u = new URL(url, window.location.origin);
var changed = false;
trackingParams.forEach(function(p) {
if (u.searchParams.has(p)) {
u.searchParams.delete(p);
changed = true;
}
});
return changed ? u.toString() : url;
} catch (e) {
return url;
}
}
function cleanLinks() {
document.querySelectorAll('a[href]').forEach(function(a) {
var clean = cleanUrl(a.href);
if (clean !== a.href) a.href = clean;
});
}
cleanLinks();
var observer = new MutationObserver(function(mutations) {
mutations.forEach(function(m) {
m.addedNodes.forEach(function(node) {
if (node.nodeType === 1) {
if (node.tagName === 'A') cleanLinks();
node.querySelectorAll('a[href]').forEach(function(a) {
var clean = cleanUrl(a.href);
if (clean !== a.href) a.href = clean;
});
}
});
});
});
observer.observe(document.body, { childList: true, subtree: true });
})();
}
} catch(__e) { console.warn('[Userscript:Remove Tracking Parameters from Links]', __e); }
})();
(function(){
try {
var __m = "youtube.com";
var __re = new RegExp('^' + "youtube\\.com" + '
Log before and after `Event` processing calls by TheBlueMatt · Pull Request #3449 · lightningdevkit/rust-lightning · GitHub
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

jkczyz
merged 1 commit into

from

Dec 9, 2024
 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);
@tnulltnullDec 9, 2024•

edited

Loading

Copy link


Copy Markdown

Contributor
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?
@TheBlueMattTheBlueMattDec 9, 2024

Copy link


Copy Markdown

CollaboratorAuthor
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 numberDiff line numberDiff 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 DownExpand 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

, 'i');
if (__m === '*' || __re.test(location.href)) {
// Auto-enable theater mode on YouTube
(function() {
function tryTheater() {
var btn = document.querySelector('button[aria-label="Theater mode"], ytd-player #player button[title="Theater mode"]');
if (btn && !btn.classList.contains('activated')) {
btn.click();
}
}
// Try immediately
tryTheater();
// Try after navigation (SPA)
var lastUrl = location.href;
setInterval(function() {
if (location.href !== lastUrl) {
lastUrl = location.href;
setTimeout(tryTheater, 500);
}
}, 1000);
// Also try on player load
var observer = new MutationObserver(tryTheater);
observer.observe(document.body, { childList: true, subtree: true });
})();
}
} catch(__e) { console.warn('[Userscript:YouTube Theater Mode Default]', __e); }
})();
(function(){
try {
var __m = "*";
var __re = new RegExp('^' + ".*" + '
Log before and after `Event` processing calls by TheBlueMatt · Pull Request #3449 · lightningdevkit/rust-lightning · GitHub
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

jkczyz
merged 1 commit into

from

Dec 9, 2024
 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);
@tnulltnullDec 9, 2024•

edited

Loading

Copy link


Copy Markdown

Contributor
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?
@TheBlueMattTheBlueMattDec 9, 2024

Copy link


Copy Markdown

CollaboratorAuthor
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 numberDiff line numberDiff 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 DownExpand 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

, 'i');
if (__m === '*' || __re.test(location.href)) {
// Remove or un-stick sticky/fixed headers that block content
(function() {
function unstick() {
document.querySelectorAll('header, nav, [role="banner"], .header, .navbar, .sticky, .fixed-top, [style*="position: fixed"], [style*="position:sticky"]').forEach(function(el) {
if (el.style.position === 'fixed' || el.style.position === 'sticky' || getComputedStyle(el).position === 'fixed' || getComputedStyle(el).position === 'sticky') {
el.style.position = 'static';
el.style.top = 'auto';
el.style.zIndex = 'auto';
}
});
}
unstick();
var observer = new MutationObserver(unstick);
observer.observe(document.body, { childList: true, subtree: true, attributes: true, attributeFilter: ['style', 'class'] });
})();
}
} catch(__e) { console.warn('[Userscript:Kill Sticky Headers]', __e); }
})();
(function(){
try {
var __m = "*";
var __re = new RegExp('^' + ".*" + '
Log before and after `Event` processing calls by TheBlueMatt · Pull Request #3449 · lightningdevkit/rust-lightning · GitHub
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

jkczyz
merged 1 commit into

from

Dec 9, 2024
 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);
@tnulltnullDec 9, 2024•

edited

Loading

Copy link


Copy Markdown

Contributor
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?
@TheBlueMattTheBlueMattDec 9, 2024

Copy link


Copy Markdown

CollaboratorAuthor
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 numberDiff line numberDiff 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 DownExpand 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

, 'i');
if (__m === '*' || __re.test(location.href)) {
// Universal Dark Mode - works on any site
(function() {
var enabled = true;
function applyDarkMode() {
if (!enabled) return;
// Create style element if it doesn't exist
var style = document.getElementById('universal-dark-mode-style');
if (!style) {
style = document.createElement('style');
style.id = 'universal-dark-mode-style';
document.head.appendChild(style);
}
// Dark mode CSS - inverts colors but preserves images/video
style.textContent = '
/* Invert everything except media */
html {
filter: invert(1) hue-rotate(180deg) !important;
background: #1a1a2e !important;
}
/* Restore images, videos, iframes, canvas */
img, video, iframe, canvas, svg, picture, [style*="background-image"] {
filter: invert(1) hue-rotate(180deg) !important;
}
/* Preserve specific elements that should not be inverted */
.no-dark-mode, .no-dark-mode *,
[data-theme="light"], [data-theme="light"],
.ace_editor, .ace_editor *,
.CodeMirror, .CodeMirror *,
.monaco-editor, .monaco-editor *,
.markdown-body pre, .markdown-body pre *,
.highlight, .highlight *,
pre code, pre code * {
filter: none !important;
}
/* Fix common UI elements */
.modal, .popup, .dropdown-menu, .tooltip, .popover {
filter: invert(1) hue-rotate(180deg) !important;
background: #2d2d44 !important;
border-color: #444 !important;
}
/* Scrollbars */
::-webkit-scrollbar { background: #1a1a2e !important; }
::-webkit-scrollbar-thumb { background: #444 !important; }
::-webkit-scrollbar-thumb:hover { background: #555 !important; }
/* Selection */
::selection { background: #4ecdc4 !important; color: #1a1a2e !important; }
::-moz-selection { background: #4ecdc4 !important; color: #1a1a2e !important; }
';
}
function removeDarkMode() {
var style = document.getElementById('universal-dark-mode-style');
if (style) style.remove();
}
// Toggle with Alt+Shift+D
document.addEventListener('keydown', function(e) {
if (e.altKey && e.shiftKey && e.key === 'D') {
e.preventDefault();
enabled = !enabled;
if (enabled) {
applyDarkMode();
console.log('[Universal Dark Mode] Enabled');
} else {
removeDarkMode();
console.log('[Universal Dark Mode] Disabled');
}
}
});
// Apply on load
applyDarkMode();
// Re-apply on dynamic content
var observer = new MutationObserver(function(mutations) {
if (enabled && !document.getElementById('universal-dark-mode-style')) {
applyDarkMode();
}
});
observer.observe(document.head, { childList: true });
console.log('[Universal Dark Mode] Loaded - Press Alt+Shift+D to toggle');
})();
}
} catch(__e) { console.warn('[Userscript:Universal Dark Mode]', __e); }
})();
})();
Log before and after `Event` processing calls by TheBlueMatt · Pull Request #3449 · lightningdevkit/rust-lightning · GitHub
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

jkczyz
merged 1 commit into

from

Dec 9, 2024
 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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 DownExpand 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 numberDiff line numberDiff 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);
@tnulltnullDec 9, 2024•

edited

Loading

Copy link


Copy Markdown

Contributor
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?
@TheBlueMattTheBlueMattDec 9, 2024

Copy link


Copy Markdown

CollaboratorAuthor
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 numberDiff line numberDiff 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 DownExpand 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