Skip to content

Commit 9321b21

Browse files
joostjagerjoostjager
committed
Use TLS logger
1 parent 0d92869 commit 9321b21

File tree

2 files changed

+52
-54
lines changed

2 files changed

+52
-54
lines changed

‎lightning/src/chain/channelmonitor.rs‎

Lines changed: 44 additions & 52 deletions
Original file line numberDiff line numberDiff line change
@@ -66,7 +66,7 @@ use crate::sign::{
6666
use crate::types::features::ChannelTypeFeatures;
6767
use crate::types::payment::{PaymentHash, PaymentPreimage};
6868
use crate::util::byte_utils;
69-
use crate::util::logger::{Logger, Record};
69+
use crate::util::logger::{Logger, LoggerScope, Record};
7070
use crate::util::persist::MonitorName;
7171
use crate::util::ser::{
7272
MaybeReadable, Readable, ReadableArgs, RequiredWrapper, UpgradableRequired, Writeable, Writer,
@@ -3491,6 +3491,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
34913491
if !cur_claimables.iter()
34923492
.any(|(_, cur_source_opt)| cur_source_opt == source_opt)
34933493
{
3494+
log_trace_ctx!("Pruning fulfilled HTLC {:?}", SentHTLCId::from_source(source));
34943495
self.counterparty_fulfilled_htlcs.remove(&SentHTLCId::from_source(source));
34953496
}
34963497
}
@@ -3815,6 +3816,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
38153816
}
38163817
}));
38173818
}
3819+
log_trace_ctx!("Recording fulfillment of HTLC {:?}", claimed_htlc_id,);
38183820
self.counterparty_fulfilled_htlcs.insert(*claimed_htlc_id, *claimed_preimage);
38193821
}
38203822

@@ -4033,15 +4035,11 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
40334035
);
40344036
}
40354037

4036-
fn renegotiated_funding<L: Deref>(
4037-
&mut self, logger: &WithChannelMonitor<L>,
4038-
channel_parameters: &ChannelTransactionParameters,
4038+
fn renegotiated_funding(
4039+
&mut self, channel_parameters: &ChannelTransactionParameters,
40394040
alternative_holder_commitment_tx: &HolderCommitmentTransaction,
40404041
alternative_counterparty_commitment_tx: &CommitmentTransaction,
4041-
) -> Result<(), ()>
4042-
where
4043-
L::Target: Logger,
4044-
{
4042+
) -> Result<(), ()> {
40454043
let alternative_counterparty_commitment_txid =
40464044
alternative_counterparty_commitment_tx.trust().txid();
40474045

@@ -4057,8 +4055,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
40574055
self.funding.counterparty_claimable_outpoints.get(txid).unwrap()
40584056
} else {
40594057
debug_assert!(false);
4060-
log_error!(
4061-
logger,
4058+
log_error_ctx!(
40624059
"Received funding renegotiation while initial funding negotiation is still pending"
40634060
);
40644061
return Err(());
@@ -4073,10 +4070,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
40734070
.position(|(htlc, _)| htlc.transaction_output_index.is_none())
40744071
.unwrap_or(htlcs_with_sources.len());
40754072
if alternative_htlcs.len() != expected_non_dust_htlc_count {
4076-
log_error!(
4077-
logger,
4078-
"Received alternative counterparty commitment with HTLC count mismatch"
4079-
);
4073+
log_error_ctx!("Received alternative counterparty commitment with HTLC count mismatch");
40804074
return Err(());
40814075
}
40824076

@@ -4086,8 +4080,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
40864080
debug_assert!(htlc.transaction_output_index.is_some());
40874081
debug_assert!(alternative_htlc.transaction_output_index.is_some());
40884082
if !alternative_htlc.is_data_equal(htlc) {
4089-
log_error!(
4090-
logger,
4083+
log_error_ctx!(
40914084
"Received alternative counterparty commitment with non-dust HTLC mismatch"
40924085
);
40934086
return Err(());
@@ -4115,8 +4108,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
41154108
.iter()
41164109
.any(|funding| funding.funding_txid() == alternative_funding_outpoint.txid)
41174110
{
4118-
log_error!(
4119-
logger,
4111+
log_error_ctx!(
41204112
"Renegotiated funding transaction with a duplicate funding txid {}",
41214113
alternative_funding_outpoint.txid
41224114
);
@@ -4127,15 +4119,13 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
41274119
// Only one splice can be negotiated at a time after we've exchanged `channel_ready`
41284120
// (implying our funding is confirmed) that spends our currently locked funding.
41294121
if !self.pending_funding.is_empty() {
4130-
log_error!(
4131-
logger,
4122+
log_error_ctx!(
41324123
"Negotiated splice while channel is pending channel_ready/splice_locked"
41334124
);
41344125
return Err(());
41354126
}
41364127
if *parent_funding_txid != self.funding.funding_txid() {
4137-
log_error!(
4138-
logger,
4128+
log_error_ctx!(
41394129
"Negotiated splice that does not spend currently locked funding transaction"
41404130
);
41414131
return Err(());
@@ -4216,14 +4206,16 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
42164206
F::Target: FeeEstimator,
42174207
L::Target: Logger,
42184208
{
4209+
let _scope = LoggerScope::new(logger, "update_monitor");
4210+
42194211
if self.latest_update_id == LEGACY_CLOSED_CHANNEL_UPDATE_ID && updates.update_id == LEGACY_CLOSED_CHANNEL_UPDATE_ID {
4220-
log_info!(logger, "Applying pre-0.1 post-force-closed update to monitor {} with {} change(s).",
4212+
log_info_ctx!( "Applying pre-0.1 post-force-closed update to monitor {} with {} change(s).",
42214213
log_funding_info!(self), updates.updates.len());
42224214
} else if updates.update_id == LEGACY_CLOSED_CHANNEL_UPDATE_ID {
4223-
log_info!(logger, "Applying pre-0.1 force close update to monitor {} with {} change(s).",
4215+
log_info_ctx!( "Applying pre-0.1 force close update to monitor {} with {} change(s).",
42244216
log_funding_info!(self), updates.updates.len());
42254217
} else {
4226-
log_info!(logger, "Applying update, bringing update_id from {} to {} with {} change(s).",
4218+
log_info_ctx!( "Applying update, bringing update_id from {} to {} with {} change(s).",
42274219
self.latest_update_id, updates.update_id, updates.updates.len());
42284220
}
42294221

@@ -4245,7 +4237,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
42454237
ChannelMonitorUpdateStep::PaymentPreimage { .. } =>
42464238
debug_assert!(self.lockdown_from_offchain),
42474239
_ => {
4248-
log_error!(logger, "Attempted to apply post-force-close ChannelMonitorUpdate of type {}", updates.updates[0].variant_name());
4240+
log_error_ctx!("Attempted to apply post-force-close ChannelMonitorUpdate of type {}", updates.updates[0].variant_name());
42494241
panic!("Attempted to apply post-force-close ChannelMonitorUpdate that wasn't providing a payment preimage");
42504242
},
42514243
}
@@ -4260,82 +4252,82 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
42604252
for update in updates.updates.iter() {
42614253
match update {
42624254
ChannelMonitorUpdateStep::LatestHolderCommitmentTXInfo { commitment_tx, htlc_outputs, claimed_htlcs, nondust_htlc_sources } => {
4263-
log_trace!(logger, "Updating ChannelMonitor with latest holder commitment transaction info");
4255+
log_trace_ctx!("Updating ChannelMonitor with latest holder commitment transaction info");
42644256
if self.lockdown_from_offchain { panic!(); }
42654257
if let Err(e) = self.provide_latest_holder_commitment_tx(
42664258
commitment_tx.clone(), htlc_outputs, &claimed_htlcs,
42674259
nondust_htlc_sources.clone()
42684260
) {
4269-
log_error!(logger, "Failed updating latest holder commitment transaction info: {}", e);
4261+
log_error_ctx!("Failed updating latest holder commitment transaction info: {}", e);
42704262
ret = Err(());
42714263
}
42724264
}
42734265
ChannelMonitorUpdateStep::LatestHolderCommitment {
42744266
commitment_txs, htlc_data, claimed_htlcs,
42754267
} => {
4276-
log_trace!(logger, "Updating ChannelMonitor with {} latest holder commitment(s)", commitment_txs.len());
4268+
log_trace_ctx!("Updating ChannelMonitor with {} latest holder commitment(s)", commitment_txs.len());
42774269
assert!(!self.lockdown_from_offchain);
42784270
if let Err(e) = self.update_holder_commitment_data(
42794271
commitment_txs.clone(), htlc_data.clone(), claimed_htlcs,
42804272
) {
4281-
log_error!(logger, "Failed updating latest holder commitment state: {}", e);
4273+
log_error_ctx!("Failed updating latest holder commitment state: {}", e);
42824274
ret = Err(());
42834275
}
42844276
},
42854277
// Soon we will drop the `LatestCounterpartyCommitmentTXInfo` variant in favor of `LatestCounterpartyCommitment`.
42864278
// For now we just add the code to handle the new updates.
42874279
// Next step: in channel, switch channel monitor updates to use the `LatestCounterpartyCommitment` variant.
42884280
ChannelMonitorUpdateStep::LatestCounterpartyCommitmentTXInfo { commitment_txid, htlc_outputs, commitment_number, their_per_commitment_point, .. } => {
4289-
log_trace!(logger, "Updating ChannelMonitor with latest counterparty commitment transaction info");
4281+
log_trace_ctx!("Updating ChannelMonitor with latest counterparty commitment transaction info");
42904282
if self.pending_funding.is_empty() {
42914283
self.provide_latest_counterparty_commitment_tx(*commitment_txid, htlc_outputs.clone(), *commitment_number, *their_per_commitment_point)
42924284
} else {
4293-
log_error!(logger, "Received unexpected non-splice counterparty commitment monitor update");
4285+
log_error_ctx!("Received unexpected non-splice counterparty commitment monitor update");
42944286
ret = Err(());
42954287
}
42964288
},
42974289
ChannelMonitorUpdateStep::LatestCounterpartyCommitment {
42984290
commitment_txs, htlc_data,
42994291
} => {
4300-
log_trace!(logger, "Updating ChannelMonitor with {} latest counterparty commitments", commitment_txs.len());
4292+
log_trace_ctx!("Updating ChannelMonitor with {} latest counterparty commitments", commitment_txs.len());
43014293
if let Err(e) = self.update_counterparty_commitment_data(commitment_txs, htlc_data) {
4302-
log_error!(logger, "Failed updating latest counterparty commitment state: {}", e);
4294+
log_error_ctx!("Failed updating latest counterparty commitment state: {}", e);
43034295
ret = Err(());
43044296
}
43054297
},
43064298
ChannelMonitorUpdateStep::PaymentPreimage { payment_preimage, payment_info } => {
4307-
log_trace!(logger, "Updating ChannelMonitor with payment preimage");
4299+
log_trace_ctx!("Updating ChannelMonitor with payment preimage");
43084300
self.provide_payment_preimage(&PaymentHash(Sha256::hash(&payment_preimage.0[..]).to_byte_array()), &payment_preimage, payment_info, broadcaster, &bounded_fee_estimator, logger)
43094301
},
43104302
ChannelMonitorUpdateStep::CommitmentSecret { idx, secret } => {
4311-
log_trace!(logger, "Updating ChannelMonitor with commitment secret");
4303+
log_trace_ctx!("Updating ChannelMonitor with commitment secret");
43124304
if let Err(e) = self.provide_secret(*idx, *secret) {
43134305
debug_assert!(false, "Latest counterparty commitment secret was invalid");
4314-
log_error!(logger, "Providing latest counterparty commitment secret failed/was refused:");
4315-
log_error!(logger, " {}", e);
4306+
log_error_ctx!("Providing latest counterparty commitment secret failed/was refused:");
4307+
log_error_ctx!(" {}", e);
43164308
ret = Err(());
43174309
}
43184310
},
43194311
ChannelMonitorUpdateStep::RenegotiatedFunding {
43204312
channel_parameters, holder_commitment_tx, counterparty_commitment_tx,
43214313
} => {
4322-
log_trace!(logger, "Updating ChannelMonitor with alternative holder and counterparty commitment transactions for funding txid {}",
4314+
log_trace_ctx!("Updating ChannelMonitor with alternative holder and counterparty commitment transactions for funding txid {}",
43234315
channel_parameters.funding_outpoint.unwrap().txid);
43244316
if let Err(_) = self.renegotiated_funding(
4325-
logger, channel_parameters, holder_commitment_tx, counterparty_commitment_tx,
4317+
channel_parameters, holder_commitment_tx, counterparty_commitment_tx,
43264318
) {
43274319
ret = Err(());
43284320
}
43294321
},
43304322
ChannelMonitorUpdateStep::RenegotiatedFundingLocked { funding_txid } => {
4331-
log_trace!(logger, "Updating ChannelMonitor with locked renegotiated funding txid {}", funding_txid);
4323+
log_trace_ctx!("Updating ChannelMonitor with locked renegotiated funding txid {}", funding_txid);
43324324
if let Err(_) = self.promote_funding(*funding_txid) {
4333-
log_error!(logger, "Unknown funding with txid {} became locked", funding_txid);
4325+
log_error_ctx!("Unknown funding with txid {} became locked", funding_txid);
43344326
ret = Err(());
43354327
}
43364328
},
43374329
ChannelMonitorUpdateStep::ChannelForceClosed { should_broadcast } => {
4338-
log_trace!(logger, "Updating ChannelMonitor: channel force closed, should broadcast: {}", should_broadcast);
4330+
log_trace_ctx!("Updating ChannelMonitor: channel force closed, should broadcast: {}", should_broadcast);
43394331
self.lockdown_from_offchain = true;
43404332
if *should_broadcast {
43414333
// There's no need to broadcast our commitment transaction if we've seen one
@@ -4345,29 +4337,29 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
43454337
self.onchain_events_awaiting_threshold_conf.iter().any(
43464338
|event| matches!(event.event, OnchainEvent::FundingSpendConfirmation { .. }));
43474339
if detected_funding_spend {
4348-
log_trace!(logger, "Avoiding commitment broadcast, already detected confirmed spend onchain");
4340+
log_trace_ctx!("Avoiding commitment broadcast, already detected confirmed spend onchain");
43494341
continue;
43504342
}
43514343
self.queue_latest_holder_commitment_txn_for_broadcast(broadcaster, &bounded_fee_estimator, logger, true);
43524344
} else if !self.holder_tx_signed {
4353-
log_error!(logger, "WARNING: You have a potentially-unsafe holder commitment transaction available to broadcast");
4354-
log_error!(logger, " in channel monitor!");
4355-
log_error!(logger, " Read the docs for ChannelMonitor::broadcast_latest_holder_commitment_txn to take manual action!");
4345+
log_error_ctx!("WARNING: You have a potentially-unsafe holder commitment transaction available to broadcast");
4346+
log_error_ctx!(" in channel monitor!");
4347+
log_error_ctx!(" Read the docs for ChannelMonitor::broadcast_latest_holder_commitment_txn to take manual action!");
43564348
} else {
43574349
// If we generated a MonitorEvent::HolderForceClosed, the ChannelManager
43584350
// will still give us a ChannelForceClosed event with !should_broadcast, but we
43594351
// shouldn't print the scary warning above.
4360-
log_info!(logger, "Channel off-chain state closed after we broadcasted our latest commitment transaction.");
4352+
log_info_ctx!( "Channel off-chain state closed after we broadcasted our latest commitment transaction.");
43614353
}
43624354
},
43634355
ChannelMonitorUpdateStep::ShutdownScript { scriptpubkey } => {
4364-
log_trace!(logger, "Updating ChannelMonitor with shutdown script");
4356+
log_trace_ctx!("Updating ChannelMonitor with shutdown script");
43654357
if let Some(shutdown_script) = self.shutdown_script.replace(scriptpubkey.clone()) {
43664358
panic!("Attempted to replace shutdown script {} with {}", shutdown_script, scriptpubkey);
43674359
}
43684360
},
43694361
ChannelMonitorUpdateStep::ReleasePaymentComplete { htlc } => {
4370-
log_trace!(logger, "HTLC {htlc:?} permanently and fully resolved");
4362+
log_trace_ctx!("HTLC {htlc:?} permanently and fully resolved");
43714363
self.htlcs_resolved_to_user.insert(*htlc);
43724364
},
43734365
}
@@ -4406,7 +4398,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
44064398
}
44074399

44084400
if ret.is_ok() && self.no_further_updates_allowed() && is_pre_close_update {
4409-
log_error!(logger, "Refusing Channel Monitor Update as counterparty attempted to update commitment after funding was spent");
4401+
log_error_ctx!("Refusing Channel Monitor Update as counterparty attempted to update commitment after funding was spent");
44104402
Err(())
44114403
} else { ret }
44124404
}
@@ -4791,7 +4783,7 @@ impl<Signer: EcdsaChannelSigner> ChannelMonitorImpl<Signer> {
47914783
// insert it here.
47924784
self.counterparty_commitment_txn_on_chain.insert(commitment_txid, commitment_number);
47934785

4794-
log_info!(logger, "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid);
4786+
log_info_ctx!( "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid);
47954787
fail_unbroadcast_htlcs!(self, "counterparty", commitment_txid, commitment_tx, height, block_hash,
47964788
per_commitment_claimable_data.iter().map(|(htlc, htlc_source)|
47974789
(htlc, htlc_source.as_ref().map(|htlc_source| htlc_source.as_ref()))

‎lightning/src/ln/channelmanager.rs‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ use bitcoin::constants::ChainHash;
2222
use bitcoin::key::constants::SECRET_KEY_SIZE;
2323
use bitcoin::network::Network;
2424
use bitcoin::transaction::Transaction;
25+
use lightning_macros::log_scope;
2526

2627
use bitcoin::hash_types::{BlockHash, Txid};
2728
use bitcoin::hashes::hmac::Hmac;
@@ -5442,10 +5443,13 @@ where
54425443
/// [`UpdateHTLCs`]: MessageSendEvent::UpdateHTLCs
54435444
/// [`PeerManager::process_events`]: crate::ln::peer_handler::PeerManager::process_events
54445445
/// [`ChannelMonitorUpdateStatus::InProgress`]: crate::chain::ChannelMonitorUpdateStatus::InProgress
5446+
#[log_scope(name = "send_payment")]
54455447
pub fn send_payment(
54465448
&self, payment_hash: PaymentHash, recipient_onion: RecipientOnionFields,
54475449
payment_id: PaymentId, route_params: RouteParameters, retry_strategy: Retry,
54485450
) -> Result<(), RetryableSendFailure> {
5451+
log_info_ctx!("Send payment (TLS)");
5452+
54495453
let best_block_height = self.best_block.read().unwrap().height;
54505454
let _persistence_guard = PersistenceNotifierGuard::notify_on_drop(self);
54515455
self.pending_outbound_payments.send_payment(
@@ -8876,7 +8880,8 @@ where
88768880
ComplFunc: FnOnce(
88778881
Option<u64>,
88788882
bool,
8879-
) -> (Option<MonitorUpdateCompletionAction>, Option<RAAMonitorUpdateBlockingAction>),
8883+
)
8884+
-> (Option<MonitorUpdateCompletionAction>, Option<RAAMonitorUpdateBlockingAction>),
88808885
>(
88818886
&self, prev_hop: HTLCPreviousHopData, payment_preimage: PaymentPreimage,
88828887
payment_info: Option<PaymentClaimDetails>, attribution_data: Option<AttributionData>,
@@ -8914,7 +8919,8 @@ where
89148919
ComplFunc: FnOnce(
89158920
Option<u64>,
89168921
bool,
8917-
) -> (Option<MonitorUpdateCompletionAction>, Option<RAAMonitorUpdateBlockingAction>),
8922+
)
8923+
-> (Option<MonitorUpdateCompletionAction>, Option<RAAMonitorUpdateBlockingAction>),
89188924
>(
89198925
&self, prev_hop: HTLCClaimSource, payment_preimage: PaymentPreimage,
89208926
payment_info: Option<PaymentClaimDetails>, attribution_data: Option<AttributionData>,

0 commit comments

Comments
 (0)