From: Matt Corallo <649246+TheBlueMatt@users.noreply.github.com>
Date: Tue, 29 Jun 2021 20:13:50 +0000 (+0000)
Subject: Merge pull request #965 from TheBlueMatt/2021-06-log-cleanups
X-Git-Tag: v0.0.99~12
X-Git-Url: http://git.bitcoin.ninja/index.cgi?a=commitdiff_plain;h=f4729075cbfef9f99e8316335dd1e8d15671674d;hp=-c;p=rust-lightning

Merge pull request #965 from TheBlueMatt/2021-06-log-cleanups

Cleanup logging
---

f4729075cbfef9f99e8316335dd1e8d15671674d
diff --combined lightning/src/chain/channelmonitor.rs
index 3463d1c8,eba96ea6..00928195
--- a/lightning/src/chain/channelmonitor.rs
+++ b/lightning/src/chain/channelmonitor.rs
@@@ -95,7 -95,7 +95,7 @@@ impl Writeable for ChannelMonitorUpdat
  		for update_step in self.updates.iter() {
  			update_step.write(w)?;
  		}
 -		write_tlv_fields!(w, {}, {});
 +		write_tlv_fields!(w, {});
  		Ok(())
  	}
  }
@@@ -108,7 -108,7 +108,7 @@@ impl Readable for ChannelMonitorUpdate 
  		for _ in 0..len {
  			updates.push(Readable::read(r)?);
  		}
 -		read_tlv_fields!(r, {}, {});
 +		read_tlv_fields!(r, {});
  		Ok(Self { update_id, updates })
  	}
  }
@@@ -202,10 -202,11 +202,10 @@@ pub struct HTLCUpdate 
  	pub(crate) source: HTLCSource
  }
  impl_writeable_tlv_based!(HTLCUpdate, {
 -	(0, payment_hash),
 -	(2, source),
 -}, {
 -	(4, payment_preimage)
 -}, {});
 +	(0, payment_hash, required),
 +	(2, source, required),
 +	(4, payment_preimage, option),
 +});
  
  /// If an HTLC expires within this many blocks, don't try to claim it in a shared transaction,
  /// instead claiming it in its own individual transaction.
@@@ -272,14 -273,15 +272,14 @@@ struct HolderSignedTx 
  	htlc_outputs: Vec<(HTLCOutputInCommitment, Option<Signature>, Option<HTLCSource>)>,
  }
  impl_writeable_tlv_based!(HolderSignedTx, {
 -	(0, txid),
 -	(2, revocation_key),
 -	(4, a_htlc_key),
 -	(6, b_htlc_key),
 -	(8, delayed_payment_key),
 -	(10, per_commitment_point),
 -	(12, feerate_per_kw),
 -}, {}, {
 -	(14, htlc_outputs)
 +	(0, txid, required),
 +	(2, revocation_key, required),
 +	(4, a_htlc_key, required),
 +	(6, b_htlc_key, required),
 +	(8, delayed_payment_key, required),
 +	(10, per_commitment_point, required),
 +	(12, feerate_per_kw, required),
 +	(14, htlc_outputs, vec_type)
  });
  
  /// We use this to track counterparty commitment transactions and htlcs outputs and
@@@ -303,10 -305,10 +303,10 @@@ impl Writeable for CounterpartyCommitme
  			}
  		}
  		write_tlv_fields!(w, {
 -			(0, self.counterparty_delayed_payment_base_key),
 -			(2, self.counterparty_htlc_base_key),
 -			(4, self.on_counterparty_tx_csv),
 -		}, {});
 +			(0, self.counterparty_delayed_payment_base_key, required),
 +			(2, self.counterparty_htlc_base_key, required),
 +			(4, self.on_counterparty_tx_csv, required),
 +		});
  		Ok(())
  	}
  }
@@@ -331,10 -333,10 +331,10 @@@ impl Readable for CounterpartyCommitmen
  			let mut counterparty_htlc_base_key = OptionDeserWrapper(None);
  			let mut on_counterparty_tx_csv: u16 = 0;
  			read_tlv_fields!(r, {
 -				(0, counterparty_delayed_payment_base_key),
 -				(2, counterparty_htlc_base_key),
 -				(4, on_counterparty_tx_csv),
 -			}, {});
 +				(0, counterparty_delayed_payment_base_key, required),
 +				(2, counterparty_htlc_base_key, required),
 +				(4, on_counterparty_tx_csv, required),
 +			});
  			CounterpartyCommitmentTransaction {
  				counterparty_delayed_payment_base_key: counterparty_delayed_payment_base_key.0.unwrap(),
  				counterparty_htlc_base_key: counterparty_htlc_base_key.0.unwrap(),
@@@ -392,19 -394,19 +392,19 @@@ enum OnchainEvent 
  }
  
  impl_writeable_tlv_based!(OnchainEventEntry, {
 -	(0, txid),
 -	(2, height),
 -	(4, event),
 -}, {}, {});
 +	(0, txid, required),
 +	(2, height, required),
 +	(4, event, required),
 +});
  
  impl_writeable_tlv_based_enum!(OnchainEvent,
  	(0, HTLCUpdate) => {
 -		(0, source),
 -		(2, payment_hash),
 -	}, {}, {},
 +		(0, source, required),
 +		(2, payment_hash, required),
 +	},
  	(1, MaturingOutput) => {
 -		(0, descriptor),
 -	}, {}, {},
 +		(0, descriptor, required),
 +	},
  ;);
  
  #[cfg_attr(any(test, feature = "fuzztarget", feature = "_test_utils"), derive(PartialEq))]
@@@ -438,25 -440,27 +438,25 @@@ pub(crate) enum ChannelMonitorUpdateSte
  
  impl_writeable_tlv_based_enum!(ChannelMonitorUpdateStep,
  	(0, LatestHolderCommitmentTXInfo) => {
 -		(0, commitment_tx),
 -	}, {}, {
 -		(2, htlc_outputs),
 +		(0, commitment_tx, required),
 +		(2, htlc_outputs, vec_type),
  	},
  	(1, LatestCounterpartyCommitmentTXInfo) => {
 -		(0, commitment_txid),
 -		(2, commitment_number),
 -		(4, their_revocation_point),
 -	}, {}, {
 -		(6, htlc_outputs),
 +		(0, commitment_txid, required),
 +		(2, commitment_number, required),
 +		(4, their_revocation_point, required),
 +		(6, htlc_outputs, vec_type),
  	},
  	(2, PaymentPreimage) => {
 -		(0, payment_preimage),
 -	}, {}, {},
 +		(0, payment_preimage, required),
 +	},
  	(3, CommitmentSecret) => {
 -		(0, idx),
 -		(2, secret),
 -	}, {}, {},
 +		(0, idx, required),
 +		(2, secret, required),
 +	},
  	(4, ChannelForceClosed) => {
 -		(0, should_broadcast),
 -	}, {}, {},
 +		(0, should_broadcast, required),
 +	},
  ;);
  
  /// A ChannelMonitor handles chain events (blocks connected and disconnected) and generates
@@@ -788,7 -792,7 +788,7 @@@ impl<Signer: Sign> Writeable for Channe
  		self.lockdown_from_offchain.write(writer)?;
  		self.holder_tx_signed.write(writer)?;
  
 -		write_tlv_fields!(writer, {}, {});
 +		write_tlv_fields!(writer, {});
  
  		Ok(())
  	}
@@@ -1539,7 -1543,7 +1539,7 @@@ impl<Signer: Sign> ChannelMonitorImpl<S
  			// Last, track onchain revoked commitment transaction and fail backward outgoing HTLCs as payment path is broken
  			if !claimable_outpoints.is_empty() || per_commitment_option.is_some() { // ie we're confident this is actually ours
  				// We're definitely a counterparty commitment transaction!
- 				log_trace!(logger, "Got broadcast of revoked counterparty commitment transaction, going to generate general spend tx with {} inputs", claimable_outpoints.len());
+ 				log_error!(logger, "Got broadcast of revoked counterparty commitment transaction, going to generate general spend tx with {} inputs", claimable_outpoints.len());
  				for (idx, outp) in tx.output.iter().enumerate() {
  					watch_outputs.push((idx as u32, outp.clone()));
  				}
@@@ -1595,7 -1599,7 +1595,7 @@@
  			}
  			self.counterparty_commitment_txn_on_chain.insert(commitment_txid, commitment_number);
  
- 			log_trace!(logger, "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid);
+ 			log_info!(logger, "Got broadcast of non-revoked counterparty commitment transaction {}", commitment_txid);
  
  			macro_rules! check_htlc_fails {
  				($txid: expr, $commitment_tx: expr, $id: tt) => {
@@@ -1713,7 -1717,7 +1713,7 @@@
  		let per_commitment_key = ignore_error!(SecretKey::from_slice(&secret));
  		let per_commitment_point = PublicKey::from_secret_key(&self.secp_ctx, &per_commitment_key);
  
- 		log_trace!(logger, "Counterparty HTLC broadcast {}:{}", htlc_txid, 0);
+ 		log_error!(logger, "Got broadcast of revoked counterparty HTLC transaction, spending {}:{}", htlc_txid, 0);
  		let revk_outp = RevokedOutput::build(per_commitment_point, self.counterparty_tx_cache.counterparty_delayed_payment_base_key, self.counterparty_tx_cache.counterparty_htlc_base_key, per_commitment_key, tx.output[0].value, self.counterparty_tx_cache.on_counterparty_tx_csv);
  		let justice_package = PackageTemplate::build_package(htlc_txid, 0, PackageSolvingData::RevokedOutput(revk_outp), height + self.counterparty_tx_cache.on_counterparty_tx_csv as u32, true, height);
  		let claimable_outpoints = vec!(justice_package);
@@@ -1804,14 -1808,14 +1804,14 @@@
  
  		if self.current_holder_commitment_tx.txid == commitment_txid {
  			is_holder_tx = true;
- 			log_trace!(logger, "Got latest holder commitment tx broadcast, searching for available HTLCs to claim");
+ 			log_info!(logger, "Got broadcast of latest holder commitment tx {}, searching for available HTLCs to claim", commitment_txid);
  			let res = self.get_broadcasted_holder_claims(&self.current_holder_commitment_tx, height);
  			let mut to_watch = self.get_broadcasted_holder_watch_outputs(&self.current_holder_commitment_tx, tx);
  			append_onchain_update!(res, to_watch);
  		} else if let &Some(ref holder_tx) = &self.prev_holder_signed_commitment_tx {
  			if holder_tx.txid == commitment_txid {
  				is_holder_tx = true;
- 				log_trace!(logger, "Got previous holder commitment tx broadcast, searching for available HTLCs to claim");
+ 				log_info!(logger, "Got broadcast of previous holder commitment tx {}, searching for available HTLCs to claim", commitment_txid);
  				let res = self.get_broadcasted_holder_claims(holder_tx, height);
  				let mut to_watch = self.get_broadcasted_holder_watch_outputs(holder_tx, tx);
  				append_onchain_update!(res, to_watch);
@@@ -1841,7 -1845,7 +1841,7 @@@
  	}
  
  	pub fn get_latest_holder_commitment_txn<L: Deref>(&mut self, logger: &L) -> Vec<Transaction> where L::Target: Logger {
- 		log_trace!(logger, "Getting signed latest holder commitment transaction!");
+ 		log_debug!(logger, "Getting signed latest holder commitment transaction!");
  		self.holder_tx_signed = true;
  		let commitment_tx = self.onchain_tx_handler.get_fully_signed_holder_tx(&self.funding_redeemscript);
  		let txid = commitment_tx.txid();
@@@ -1875,7 -1879,7 +1875,7 @@@
  	#[cfg(any(test,feature = "unsafe_revoked_tx_signing"))]
  	/// Note that this includes possibly-locktimed-in-the-future transactions!
  	fn unsafe_get_latest_holder_commitment_txn<L: Deref>(&mut self, logger: &L) -> Vec<Transaction> where L::Target: Logger {
- 		log_trace!(logger, "Getting signed copy of latest holder commitment transaction!");
+ 		log_debug!(logger, "Getting signed copy of latest holder commitment transaction!");
  		let commitment_tx = self.onchain_tx_handler.get_fully_signed_copy_holder_tx(&self.funding_redeemscript);
  		let txid = commitment_tx.txid();
  		let mut holder_transactions = vec![commitment_tx];
@@@ -2082,7 -2086,7 +2082,7 @@@
  						matured_htlcs.push(source.clone());
  					}
  
- 					log_trace!(logger, "HTLC {} failure update has got enough confirmations to be passed upstream", log_bytes!(payment_hash.0));
+ 					log_debug!(logger, "HTLC {} failure update has got enough confirmations to be passed upstream", log_bytes!(payment_hash.0));
  					self.pending_monitor_events.push(MonitorEvent::HTLCEvent(HTLCUpdate {
  						payment_hash: payment_hash,
  						payment_preimage: None,
@@@ -2090,7 -2094,7 +2090,7 @@@
  					}));
  				},
  				OnchainEvent::MaturingOutput { descriptor } => {
- 					log_trace!(logger, "Descriptor {} has got enough confirmations to be passed upstream", log_spendable!(descriptor));
+ 					log_debug!(logger, "Descriptor {} has got enough confirmations to be passed upstream", log_spendable!(descriptor));
  					self.pending_events.push(Event::SpendableOutputs {
  						outputs: vec![descriptor]
  					});
@@@ -2394,7 -2398,7 +2394,7 @@@
  						height,
  						event: OnchainEvent::HTLCUpdate { source: source, payment_hash: payment_hash },
  					};
- 					log_info!(logger, "Failing HTLC with payment_hash {} timeout by a spend tx, waiting for confirmation (at height{})", log_bytes!(payment_hash.0), entry.confirmation_threshold());
+ 					log_info!(logger, "Failing HTLC with payment_hash {} timeout by a spend tx, waiting for confirmation (at height {})", log_bytes!(payment_hash.0), entry.confirmation_threshold());
  					self.onchain_events_awaiting_threshold_conf.push(entry);
  				}
  			}
@@@ -2459,7 -2463,7 +2459,7 @@@
  				height: height,
  				event: OnchainEvent::MaturingOutput { descriptor: spendable_output.clone() },
  			};
- 			log_trace!(logger, "Maturing {} until {}", log_spendable!(spendable_output), entry.confirmation_threshold());
+ 			log_info!(logger, "Received spendable output {}, spendable at height {}", log_spendable!(spendable_output), entry.confirmation_threshold());
  			self.onchain_events_awaiting_threshold_conf.push(entry);
  		}
  	}
@@@ -2736,7 -2740,7 +2736,7 @@@ impl<'a, Signer: Sign, K: KeysInterface
  		let lockdown_from_offchain = Readable::read(reader)?;
  		let holder_tx_signed = Readable::read(reader)?;
  
 -		read_tlv_fields!(reader, {}, {});
 +		read_tlv_fields!(reader, {});
  
  		let mut secp_ctx = Secp256k1::new();
  		secp_ctx.seeded_randomize(&keys_manager.get_secure_random_bytes());
diff --combined lightning/src/chain/onchaintx.rs
index 7e616ef2,19bbed58..23b05afe
--- a/lightning/src/chain/onchaintx.rs
+++ b/lightning/src/chain/onchaintx.rs
@@@ -79,18 -79,18 +79,18 @@@ enum OnchainEvent 
  }
  
  impl_writeable_tlv_based!(OnchainEventEntry, {
 -	(0, txid),
 -	(2, height),
 -	(4, event),
 -}, {}, {});
 +	(0, txid, required),
 +	(2, height, required),
 +	(4, event, required),
 +});
  
  impl_writeable_tlv_based_enum!(OnchainEvent,
  	(0, Claim) => {
 -		(0, claim_request),
 -	}, {}, {},
 +		(0, claim_request, required),
 +	},
  	(1, ContentiousOutpoint) => {
 -		(0, package),
 -	}, {}, {},
 +		(0, package, required),
 +	},
  ;);
  
  impl Readable for Option<Vec<Option<(usize, Signature)>>> {
@@@ -236,7 -236,7 +236,7 @@@ impl<ChannelSigner: Sign> OnchainTxHand
  			entry.write(writer)?;
  		}
  
 -		write_tlv_fields!(writer, {}, {});
 +		write_tlv_fields!(writer, {});
  		Ok(())
  	}
  }
@@@ -298,7 -298,7 +298,7 @@@ impl<'a, K: KeysInterface> ReadableArgs
  			onchain_events_awaiting_threshold_conf.push(Readable::read(reader)?);
  		}
  
 -		read_tlv_fields!(reader, {}, {});
 +		read_tlv_fields!(reader, {});
  
  		let mut secp_ctx = Secp256k1::new();
  		secp_ctx.seeded_randomize(&keys_manager.get_secure_random_bytes());
@@@ -382,7 -382,7 +382,7 @@@ impl<ChannelSigner: Sign> OnchainTxHand
  		      F::Target: FeeEstimator,
  					L::Target: Logger,
  	{
- 		log_trace!(logger, "Updating claims view at height {} with {} matched transactions and {} claim requests", height, txn_matched.len(), requests.len());
+ 		log_debug!(logger, "Updating claims view at height {} with {} matched transactions and {} claim requests", height, txn_matched.len(), requests.len());
  		let mut preprocessed_requests = Vec::with_capacity(requests.len());
  		let mut aggregated_request = None;
  
@@@ -391,20 -391,20 +391,20 @@@
  		for req in requests {
  			// Don't claim a outpoint twice that would be bad for privacy and may uselessly lock a CPFP input for a while
  			if let Some(_) = self.claimable_outpoints.get(req.outpoints()[0]) {
- 				log_trace!(logger, "Ignoring second claim for outpoint {}:{}, already registered its claiming request", req.outpoints()[0].txid, req.outpoints()[0].vout);
+ 				log_info!(logger, "Ignoring second claim for outpoint {}:{}, already registered its claiming request", req.outpoints()[0].txid, req.outpoints()[0].vout);
  			} else {
  				let timelocked_equivalent_package = self.locktimed_packages.iter().map(|v| v.1.iter()).flatten()
  					.find(|locked_package| locked_package.outpoints() == req.outpoints());
  				if let Some(package) = timelocked_equivalent_package {
- 					log_trace!(logger, "Ignoring second claim for outpoint {}:{}, we already have one which we're waiting on a timelock at {} for.",
+ 					log_info!(logger, "Ignoring second claim for outpoint {}:{}, we already have one which we're waiting on a timelock at {} for.",
  						req.outpoints()[0].txid, req.outpoints()[0].vout, package.package_timelock());
  					continue;
  				}
  
  				if req.package_timelock() > height + 1 {
- 					log_debug!(logger, "Delaying claim of package until its timelock at {} (current height {}), the following outpoints are spent:", req.package_timelock(), height);
+ 					log_info!(logger, "Delaying claim of package until its timelock at {} (current height {}), the following outpoints are spent:", req.package_timelock(), height);
  					for outpoint in req.outpoints() {
- 						log_debug!(logger, "  Outpoint {}", outpoint);
+ 						log_info!(logger, "  Outpoint {}", outpoint);
  					}
  					self.locktimed_packages.entry(req.package_timelock()).or_insert(Vec::new()).push(req);
  					continue;
@@@ -441,11 -441,11 +441,11 @@@
  				req.set_feerate(new_feerate);
  				let txid = tx.txid();
  				for k in req.outpoints() {
- 					log_trace!(logger, "Registering claiming request for {}:{}", k.txid, k.vout);
+ 					log_info!(logger, "Registering claiming request for {}:{}", k.txid, k.vout);
  					self.claimable_outpoints.insert(k.clone(), (txid, height));
  				}
  				self.pending_claim_requests.insert(txid, req);
- 				log_trace!(logger, "Broadcasting onchain {}", log_tx!(tx));
+ 				log_info!(logger, "Broadcasting onchain {}", log_tx!(tx));
  				broadcaster.broadcast_transaction(&tx);
  			}
  		}
@@@ -536,11 -536,14 +536,14 @@@
  						// been aggregated in a single tx and claimed so atomically
  						if let Some(request) = self.pending_claim_requests.remove(&claim_request) {
  							for outpoint in request.outpoints() {
+ 								log_debug!(logger, "Removing claim tracking for {} due to maturation of claim tx {}.", outpoint, claim_request);
  								self.claimable_outpoints.remove(&outpoint);
  							}
  						}
  					},
  					OnchainEvent::ContentiousOutpoint { package } => {
+ 						log_debug!(logger, "Removing claim tracking due to maturation of claim tx for outpoints:");
+ 						log_debug!(logger, " {:?}", package.outpoints());
  						self.claimable_outpoints.remove(&package.outpoints()[0]);
  					}
  				}
@@@ -562,7 -565,7 +565,7 @@@
  		log_trace!(logger, "Bumping {} candidates", bump_candidates.len());
  		for (first_claim_txid, request) in bump_candidates.iter() {
  			if let Some((new_timer, new_feerate, bump_tx)) = self.generate_claim_tx(height, &request, &*fee_estimator, &*logger) {
- 				log_trace!(logger, "Broadcasting onchain {}", log_tx!(bump_tx));
+ 				log_info!(logger, "Broadcasting RBF-bumped onchain {}", log_tx!(bump_tx));
  				broadcaster.broadcast_transaction(&bump_tx);
  				if let Some(request) = self.pending_claim_requests.get_mut(first_claim_txid) {
  					request.set_timer(new_timer);
diff --combined lightning/src/chain/package.rs
index b1e7d60a,bda924d5..b5c1ffdf
--- a/lightning/src/chain/package.rs
+++ b/lightning/src/chain/package.rs
@@@ -87,14 -87,14 +87,14 @@@ impl RevokedOutput 
  }
  
  impl_writeable_tlv_based!(RevokedOutput, {
 -	(0, per_commitment_point),
 -	(2, counterparty_delayed_payment_base_key),
 -	(4, counterparty_htlc_base_key),
 -	(6, per_commitment_key),
 -	(8, weight),
 -	(10, amount),
 -	(12, on_counterparty_tx_csv),
 -}, {}, {});
 +	(0, per_commitment_point, required),
 +	(2, counterparty_delayed_payment_base_key, required),
 +	(4, counterparty_htlc_base_key, required),
 +	(6, per_commitment_key, required),
 +	(8, weight, required),
 +	(10, amount, required),
 +	(12, on_counterparty_tx_csv, required),
 +});
  
  /// A struct to describe a revoked offered output and corresponding information to generate a
  /// solving witness.
@@@ -131,14 -131,14 +131,14 @@@ impl RevokedHTLCOutput 
  }
  
  impl_writeable_tlv_based!(RevokedHTLCOutput, {
 -	(0, per_commitment_point),
 -	(2, counterparty_delayed_payment_base_key),
 -	(4, counterparty_htlc_base_key),
 -	(6, per_commitment_key),
 -	(8, weight),
 -	(10, amount),
 -	(12, htlc),
 -}, {}, {});
 +	(0, per_commitment_point, required),
 +	(2, counterparty_delayed_payment_base_key, required),
 +	(4, counterparty_htlc_base_key, required),
 +	(6, per_commitment_key, required),
 +	(8, weight, required),
 +	(10, amount, required),
 +	(12, htlc, required),
 +});
  
  /// A struct to describe a HTLC output on a counterparty commitment transaction.
  ///
@@@ -168,12 -168,12 +168,12 @@@ impl CounterpartyOfferedHTLCOutput 
  }
  
  impl_writeable_tlv_based!(CounterpartyOfferedHTLCOutput, {
 -	(0, per_commitment_point),
 -	(2, counterparty_delayed_payment_base_key),
 -	(4, counterparty_htlc_base_key),
 -	(6, preimage),
 -	(8, htlc),
 -}, {}, {});
 +	(0, per_commitment_point, required),
 +	(2, counterparty_delayed_payment_base_key, required),
 +	(4, counterparty_htlc_base_key, required),
 +	(6, preimage, required),
 +	(8, htlc, required),
 +});
  
  /// A struct to describe a HTLC output on a counterparty commitment transaction.
  ///
@@@ -199,11 -199,11 +199,11 @@@ impl CounterpartyReceivedHTLCOutput 
  }
  
  impl_writeable_tlv_based!(CounterpartyReceivedHTLCOutput, {
 -	(0, per_commitment_point),
 -	(2, counterparty_delayed_payment_base_key),
 -	(4, counterparty_htlc_base_key),
 -	(6, htlc),
 -}, {}, {});
 +	(0, per_commitment_point, required),
 +	(2, counterparty_delayed_payment_base_key, required),
 +	(4, counterparty_htlc_base_key, required),
 +	(6, htlc, required),
 +});
  
  /// A struct to describe a HTLC output on holder commitment transaction.
  ///
@@@ -236,10 -236,11 +236,10 @@@ impl HolderHTLCOutput 
  }
  
  impl_writeable_tlv_based!(HolderHTLCOutput, {
 -	(0, amount),
 -	(2, cltv_expiry),
 -}, {
 -	(4, preimage),
 -}, {});
 +	(0, amount, required),
 +	(2, cltv_expiry, required),
 +	(4, preimage, option)
 +});
  
  /// A struct to describe the channel output on the funding transaction.
  ///
@@@ -258,8 -259,8 +258,8 @@@ impl HolderFundingOutput 
  }
  
  impl_writeable_tlv_based!(HolderFundingOutput, {
 -	(0, funding_redeemscript),
 -}, {}, {});
 +	(0, funding_redeemscript, required),
 +});
  
  /// A wrapper encapsulating all in-protocol differing outputs types.
  ///
@@@ -602,18 -603,18 +602,18 @@@ impl PackageTemplate 
  					});
  				}
  				for (i, (outpoint, out)) in self.inputs.iter().enumerate() {
- 					log_trace!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout);
+ 					log_debug!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout);
  					if !out.finalize_input(&mut bumped_tx, i, onchain_handler) { return None; }
  				}
- 				log_trace!(logger, "Finalized transaction {} ready to broadcast", bumped_tx.txid());
+ 				log_debug!(logger, "Finalized transaction {} ready to broadcast", bumped_tx.txid());
  				return Some(bumped_tx);
  			},
  			PackageMalleability::Untractable => {
  				debug_assert_eq!(value, 0, "value is ignored for non-malleable packages, should be zero to ensure callsites are correct");
  				if let Some((outpoint, outp)) = self.inputs.first() {
  					if let Some(final_tx) = outp.get_finalized_tx(outpoint, onchain_handler) {
- 						log_trace!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout);
- 						log_trace!(logger, "Finalized transaction {} ready to broadcast", final_tx.txid());
+ 						log_debug!(logger, "Adding claiming input for outpoint {}:{}", outpoint.txid, outpoint.vout);
+ 						log_debug!(logger, "Finalized transaction {} ready to broadcast", final_tx.txid());
  						return Some(final_tx);
  					}
  					return None;
@@@ -689,11 -690,10 +689,11 @@@ impl Writeable for PackageTemplate 
  			rev_outp.write(writer)?;
  		}
  		write_tlv_fields!(writer, {
 -			(0, self.soonest_conf_deadline),
 -			(2, self.feerate_previous),
 -			(4, self.height_original),
 -		}, { (6, self.height_timer) });
 +			(0, self.soonest_conf_deadline, required),
 +			(2, self.feerate_previous, required),
 +			(4, self.height_original, required),
 +			(6, self.height_timer, option)
 +		});
  		Ok(())
  	}
  }
@@@ -722,11 -722,10 +722,11 @@@ impl Readable for PackageTemplate 
  		let mut height_timer = None;
  		let mut height_original = 0;
  		read_tlv_fields!(reader, {
 -			(0, soonest_conf_deadline),
 -			(2, feerate_previous),
 -			(4, height_original)
 -		}, { (6, height_timer) });
 +			(0, soonest_conf_deadline, required),
 +			(2, feerate_previous, required),
 +			(4, height_original, required),
 +			(6, height_timer, option),
 +		});
  		Ok(PackageTemplate {
  			inputs,
  			malleability,
@@@ -795,13 -794,13 +795,13 @@@ fn feerate_bump<F: Deref, L: Deref>(pre
  			// ...else just increase the previous feerate by 25% (because that's a nice number)
  			let new_fee = previous_feerate * (predicted_weight as u64) / 750;
  			if input_amounts <= new_fee {
- 				log_trace!(logger, "Can't 25% bump new claiming tx, amount {} is too small", input_amounts);
+ 				log_warn!(logger, "Can't 25% bump new claiming tx, amount {} is too small", input_amounts);
  				return None;
  			}
  			new_fee
  		}
  	} else {
- 		log_trace!(logger, "Can't new-estimation bump new claiming tx, amount {} is too small", input_amounts);
+ 		log_warn!(logger, "Can't new-estimation bump new claiming tx, amount {} is too small", input_amounts);
  		return None;
  	};
  
diff --combined lightning/src/ln/channel.rs
index 9c81f797,06308b01..5f5bc51d
--- a/lightning/src/ln/channel.rs
+++ b/lightning/src/ln/channel.rs
@@@ -434,15 -434,6 +434,15 @@@ pub(super) struct Channel<Signer: Sign
  	next_local_commitment_tx_fee_info_cached: Mutex<Option<CommitmentTxInfoCached>>,
  	#[cfg(any(test, feature = "fuzztarget"))]
  	next_remote_commitment_tx_fee_info_cached: Mutex<Option<CommitmentTxInfoCached>>,
 +
 +	/// lnd has a long-standing bug where, upon reconnection, if the channel is not yet confirmed
 +	/// they will not send a channel_reestablish until the channel locks in. Then, they will send a
 +	/// funding_locked *before* sending the channel_reestablish (which is clearly a violation of
 +	/// the BOLT specs). We copy c-lightning's workaround here and simply store the funding_locked
 +	/// message until we receive a channel_reestablish.
 +	///
 +	/// See-also <https://github.com/lightningnetwork/lnd/issues/4006>
 +	pub workaround_lnd_bug_4006: Option<msgs::FundingLocked>,
  }
  
  #[cfg(any(test, feature = "fuzztarget"))]
@@@ -642,8 -633,6 +642,8 @@@ impl<Signer: Sign> Channel<Signer> 
  			next_local_commitment_tx_fee_info_cached: Mutex::new(None),
  			#[cfg(any(test, feature = "fuzztarget"))]
  			next_remote_commitment_tx_fee_info_cached: Mutex::new(None),
 +
 +			workaround_lnd_bug_4006: None,
  		})
  	}
  
@@@ -887,8 -876,6 +887,8 @@@
  			next_local_commitment_tx_fee_info_cached: Mutex::new(None),
  			#[cfg(any(test, feature = "fuzztarget"))]
  			next_remote_commitment_tx_fee_info_cached: Mutex::new(None),
 +
 +			workaround_lnd_bug_4006: None,
  		};
  
  		Ok(chan)
@@@ -922,7 -909,10 +922,10 @@@
  		let mut local_htlc_total_msat = 0;
  		let mut value_to_self_msat_offset = 0;
  
- 		log_trace!(logger, "Building commitment transaction number {} (really {} xor {}) for {}, generated by {} with fee {}...", commitment_number, (INITIAL_COMMITMENT_NUMBER - commitment_number), get_commitment_transaction_number_obscure_factor(&self.get_holder_pubkeys().payment_point, &self.get_counterparty_pubkeys().payment_point, self.is_outbound()), if local { "us" } else { "remote" }, if generated_by_local { "us" } else { "remote" }, feerate_per_kw);
+ 		log_trace!(logger, "Building commitment transaction number {} (really {} xor {}) for channel {} for {}, generated by {} with fee {}...",
+ 			commitment_number, (INITIAL_COMMITMENT_NUMBER - commitment_number),
+ 			get_commitment_transaction_number_obscure_factor(&self.get_holder_pubkeys().payment_point, &self.get_counterparty_pubkeys().payment_point, self.is_outbound()),
+ 			log_bytes!(self.channel_id), if local { "us" } else { "remote" }, if generated_by_local { "us" } else { "remote" }, feerate_per_kw);
  
  		macro_rules! get_htlc_in_commitment {
  			($htlc: expr, $offered: expr) => {
@@@ -1304,7 -1294,7 +1307,7 @@@
  					_ => {}
  				}
  			}
- 			log_trace!(logger, "Adding HTLC claim to holding_cell! Current state: {}", self.channel_state);
+ 			log_trace!(logger, "Adding HTLC claim to holding_cell in channel {}! Current state: {}", log_bytes!(self.channel_id()), self.channel_state);
  			self.holding_cell_htlc_updates.push(HTLCUpdateAwaitingACK::ClaimHTLC {
  				payment_preimage: payment_preimage_arg, htlc_id: htlc_id_arg,
  			});
@@@ -1318,7 -1308,7 +1321,7 @@@
  				debug_assert!(false, "Have an inbound HTLC we tried to claim before it was fully committed to");
  				return Ok((None, Some(monitor_update)));
  			}
- 			log_trace!(logger, "Upgrading HTLC {} to LocalRemoved with a Fulfill!", log_bytes!(htlc.payment_hash.0));
+ 			log_trace!(logger, "Upgrading HTLC {} to LocalRemoved with a Fulfill in channel {}!", log_bytes!(htlc.payment_hash.0), log_bytes!(self.channel_id));
  			htlc.state = InboundHTLCState::LocalRemoved(InboundHTLCRemovalReason::Fulfill(payment_preimage_arg.clone()));
  		}
  
@@@ -1404,7 -1394,7 +1407,7 @@@
  					_ => {}
  				}
  			}
- 			log_trace!(logger, "Placing failure for HTLC ID {} in holding cell", htlc_id_arg);
+ 			log_trace!(logger, "Placing failure for HTLC ID {} in holding cell in channel {}.", htlc_id_arg, log_bytes!(self.channel_id()));
  			self.holding_cell_htlc_updates.push(HTLCUpdateAwaitingACK::FailHTLC {
  				htlc_id: htlc_id_arg,
  				err_packet,
@@@ -1412,7 -1402,7 +1415,7 @@@
  			return Ok(None);
  		}
  
- 		log_trace!(logger, "Failing HTLC ID {} back with a update_fail_htlc message", htlc_id_arg);
+ 		log_trace!(logger, "Failing HTLC ID {} back with a update_fail_htlc message in channel {}.", htlc_id_arg, log_bytes!(self.channel_id()));
  		{
  			let htlc = &mut self.pending_inbound_htlcs[pending_idx];
  			htlc.state = InboundHTLCState::LocalRemoved(InboundHTLCRemovalReason::FailRelay(err_packet.clone()));
@@@ -1544,7 -1534,10 +1547,10 @@@
  			let initial_commitment_bitcoin_tx = trusted_tx.built_transaction();
  			let sighash = initial_commitment_bitcoin_tx.get_sighash_all(&funding_script, self.channel_value_satoshis);
  			// They sign the holder commitment transaction...
- 			log_trace!(logger, "Checking funding_created tx signature {} by key {} against tx {} (sighash {}) with redeemscript {}", log_bytes!(sig.serialize_compact()[..]), log_bytes!(self.counterparty_funding_pubkey().serialize()), encode::serialize_hex(&initial_commitment_bitcoin_tx.transaction), log_bytes!(sighash[..]), encode::serialize_hex(&funding_script));
+ 			log_trace!(logger, "Checking funding_created tx signature {} by key {} against tx {} (sighash {}) with redeemscript {} for channel {}.",
+ 				log_bytes!(sig.serialize_compact()[..]), log_bytes!(self.counterparty_funding_pubkey().serialize()),
+ 				encode::serialize_hex(&initial_commitment_bitcoin_tx.transaction), log_bytes!(sighash[..]),
+ 				encode::serialize_hex(&funding_script), log_bytes!(self.channel_id()));
  			secp_check!(self.secp_ctx.verify(&sighash, &sig, self.counterparty_funding_pubkey()), "Invalid funding_created signature from peer".to_owned());
  		}
  
@@@ -1553,7 -1546,8 +1559,8 @@@
  
  		let counterparty_trusted_tx = counterparty_initial_commitment_tx.trust();
  		let counterparty_initial_bitcoin_tx = counterparty_trusted_tx.built_transaction();
- 		log_trace!(logger, "Initial counterparty ID {} tx {}", counterparty_initial_bitcoin_tx.txid, encode::serialize_hex(&counterparty_initial_bitcoin_tx.transaction));
+ 		log_trace!(logger, "Initial counterparty tx for channel {} is: txid {} tx {}",
+ 			log_bytes!(self.channel_id()), counterparty_initial_bitcoin_tx.txid, encode::serialize_hex(&counterparty_initial_bitcoin_tx.transaction));
  
  		let counterparty_signature = self.holder_signer.sign_counterparty_commitment(&counterparty_initial_commitment_tx, &self.secp_ctx)
  				.map_err(|_| ChannelError::Close("Failed to get signatures for new commitment_signed".to_owned()))?.0;
@@@ -1629,6 -1623,8 +1636,8 @@@
  		self.cur_counterparty_commitment_transaction_number -= 1;
  		self.cur_holder_commitment_transaction_number -= 1;
  
+ 		log_info!(logger, "Generated funding_signed for peer for channel {}", log_bytes!(self.channel_id()));
+ 
  		Ok((msgs::FundingSigned {
  			channel_id: self.channel_id,
  			signature
@@@ -1657,7 -1653,8 +1666,8 @@@
  		let counterparty_trusted_tx = counterparty_initial_commitment_tx.trust();
  		let counterparty_initial_bitcoin_tx = counterparty_trusted_tx.built_transaction();
  
- 		log_trace!(logger, "Initial counterparty ID {} tx {}", counterparty_initial_bitcoin_tx.txid, encode::serialize_hex(&counterparty_initial_bitcoin_tx.transaction));
+ 		log_trace!(logger, "Initial counterparty tx for channel {} is: txid {} tx {}",
+ 			log_bytes!(self.channel_id()), counterparty_initial_bitcoin_tx.txid, encode::serialize_hex(&counterparty_initial_bitcoin_tx.transaction));
  
  		let holder_signer = self.build_holder_transaction_keys(self.cur_holder_commitment_transaction_number)?;
  		let initial_commitment_tx = self.build_commitment_transaction(self.cur_holder_commitment_transaction_number, &holder_signer, true, false, self.feerate_per_kw, logger).0;
@@@ -1699,13 -1696,14 +1709,15 @@@
  		self.cur_holder_commitment_transaction_number -= 1;
  		self.cur_counterparty_commitment_transaction_number -= 1;
  
+ 		log_info!(logger, "Received funding_signed from peer for channel {}", log_bytes!(self.channel_id()));
+ 
  		Ok((channel_monitor, self.funding_transaction.as_ref().cloned().unwrap()))
  	}
  
- 	pub fn funding_locked(&mut self, msg: &msgs::FundingLocked) -> Result<(), ChannelError> {
+ 	pub fn funding_locked<L: Deref>(&mut self, msg: &msgs::FundingLocked, logger: &L) -> Result<(), ChannelError> where L::Target: Logger {
  		if self.channel_state & (ChannelState::PeerDisconnected as u32) == ChannelState::PeerDisconnected as u32 {
 -			return Err(ChannelError::Close("Peer sent funding_locked when we needed a channel_reestablish".to_owned()));
 +			self.workaround_lnd_bug_4006 = Some(msg.clone());
 +			return Err(ChannelError::Ignore("Peer sent funding_locked when we needed a channel_reestablish. The peer is likely lnd, see https://github.com/lightningnetwork/lnd/issues/4006".to_owned()));
  		}
  
  		let non_shutdown_state = self.channel_state & (!MULTI_STATE_FLAGS);
@@@ -1733,6 -1731,9 +1745,9 @@@
  
  		self.counterparty_prev_commitment_point = self.counterparty_cur_commitment_point;
  		self.counterparty_cur_commitment_point = Some(msg.next_per_commitment_point);
+ 
+ 		log_info!(logger, "Received funding_locked from peer for channel {}", log_bytes!(self.channel_id()));
+ 
  		Ok(())
  	}
  
@@@ -2042,7 -2043,7 +2057,7 @@@
  			if pending_remote_value_msat - msg.amount_msat - chan_reserve_msat < remote_fee_cost_incl_stuck_buffer_msat {
  				// Note that if the pending_forward_status is not updated here, then it's because we're already failing
  				// the HTLC, i.e. its status is already set to failing.
- 				log_info!(logger, "Attempting to fail HTLC due to fee spike buffer violation");
+ 				log_info!(logger, "Attempting to fail HTLC due to fee spike buffer violation in channel {}. Rebalancing is required.", log_bytes!(self.channel_id()));
  				pending_forward_status = create_pending_htlc_status(self, pending_forward_status, 0x1000|7);
  			}
  		} else {
@@@ -2174,7 -2175,10 +2189,10 @@@
  				let bitcoin_tx = trusted_tx.built_transaction();
  				let sighash = bitcoin_tx.get_sighash_all(&funding_script, self.channel_value_satoshis);
  
- 				log_trace!(logger, "Checking commitment tx signature {} by key {} against tx {} (sighash {}) with redeemscript {}", log_bytes!(msg.signature.serialize_compact()[..]), log_bytes!(self.counterparty_funding_pubkey().serialize()), encode::serialize_hex(&bitcoin_tx.transaction), log_bytes!(sighash[..]), encode::serialize_hex(&funding_script));
+ 				log_trace!(logger, "Checking commitment tx signature {} by key {} against tx {} (sighash {}) with redeemscript {} in channel {}",
+ 					log_bytes!(msg.signature.serialize_compact()[..]),
+ 					log_bytes!(self.counterparty_funding_pubkey().serialize()), encode::serialize_hex(&bitcoin_tx.transaction),
+ 					log_bytes!(sighash[..]), encode::serialize_hex(&funding_script), log_bytes!(self.channel_id()));
  				if let Err(_) = self.secp_ctx.verify(&sighash, &msg.signature, &self.counterparty_funding_pubkey()) {
  					return Err((None, ChannelError::Close("Invalid commitment tx signature from peer".to_owned())));
  				}
@@@ -2221,7 -2225,9 +2239,9 @@@
  				let htlc_tx = self.build_htlc_transaction(&commitment_txid, &htlc, true, &keys, feerate_per_kw);
  				let htlc_redeemscript = chan_utils::get_htlc_redeemscript(&htlc, &keys);
  				let htlc_sighash = hash_to_message!(&bip143::SigHashCache::new(&htlc_tx).signature_hash(0, &htlc_redeemscript, htlc.amount_msat / 1000, SigHashType::All)[..]);
- 				log_trace!(logger, "Checking HTLC tx signature {} by key {} against tx {} (sighash {}) with redeemscript {}", log_bytes!(msg.htlc_signatures[idx].serialize_compact()[..]), log_bytes!(keys.countersignatory_htlc_key.serialize()), encode::serialize_hex(&htlc_tx), log_bytes!(htlc_sighash[..]), encode::serialize_hex(&htlc_redeemscript));
+ 				log_trace!(logger, "Checking HTLC tx signature {} by key {} against tx {} (sighash {}) with redeemscript {} in channel {}.",
+ 					log_bytes!(msg.htlc_signatures[idx].serialize_compact()[..]), log_bytes!(keys.countersignatory_htlc_key.serialize()),
+ 					encode::serialize_hex(&htlc_tx), log_bytes!(htlc_sighash[..]), encode::serialize_hex(&htlc_redeemscript), log_bytes!(self.channel_id()));
  				if let Err(_) = self.secp_ctx.verify(&htlc_sighash, &msg.htlc_signatures[idx], &keys.countersignatory_htlc_key) {
  					return Err((None, ChannelError::Close("Invalid HTLC tx signature from peer".to_owned())));
  				}
@@@ -2271,6 -2277,8 +2291,8 @@@
  				Some(forward_info.clone())
  			} else { None };
  			if let Some(forward_info) = new_forward {
+ 				log_trace!(logger, "Updating HTLC {} to AwaitingRemoteRevokeToAnnounce due to commitment_signed in channel {}.",
+ 					log_bytes!(htlc.payment_hash.0), log_bytes!(self.channel_id));
  				htlc.state = InboundHTLCState::AwaitingRemoteRevokeToAnnounce(forward_info);
  				need_commitment = true;
  			}
@@@ -2279,6 -2287,8 +2301,8 @@@
  			if let Some(fail_reason) = if let &mut OutboundHTLCState::RemoteRemoved(ref mut fail_reason) = &mut htlc.state {
  				Some(fail_reason.take())
  			} else { None } {
+ 				log_trace!(logger, "Updating HTLC {} to AwaitingRemoteRevokeToRemove due to commitment_signed in channel {}.",
+ 					log_bytes!(htlc.payment_hash.0), log_bytes!(self.channel_id));
  				htlc.state = OutboundHTLCState::AwaitingRemoteRevokeToRemove(fail_reason);
  				need_commitment = true;
  			}
@@@ -2304,6 -2314,8 +2328,8 @@@
  				self.latest_monitor_update_id = monitor_update.update_id;
  				monitor_update.updates.append(&mut additional_update.updates);
  			}
+ 			log_debug!(logger, "Received valid commitment_signed from peer in channel {}, updated HTLC state but awaiting a monitor update resolution to reply.",
+ 				log_bytes!(self.channel_id));
  			// TODO: Call maybe_propose_first_closing_signed on restoration (or call it here and
  			// re-send the message on restoration)
  			return Err((Some(monitor_update), ChannelError::Ignore("Previous monitor update failure prevented generation of RAA".to_owned())));
@@@ -2323,6 -2335,9 +2349,9 @@@
  			(None, self.maybe_propose_first_closing_signed(fee_estimator))
  		} else { (None, None) };
  
+ 		log_debug!(logger, "Received valid commitment_signed from peer in channel {}, updating HTLC state and responding with{} a revoke_and_ack.",
+ 			log_bytes!(self.channel_id()), if commitment_signed.is_some() { " our own commitment_signed and" } else { "" });
+ 
  		Ok((msgs::RevokeAndACK {
  			channel_id: self.channel_id,
  			per_commitment_secret,
@@@ -2345,7 -2360,8 +2374,8 @@@
  	fn free_holding_cell_htlcs<L: Deref>(&mut self, logger: &L) -> Result<(Option<(msgs::CommitmentUpdate, ChannelMonitorUpdate)>, Vec<(HTLCSource, PaymentHash)>), ChannelError> where L::Target: Logger {
  		assert_eq!(self.channel_state & ChannelState::MonitorUpdateFailed as u32, 0);
  		if self.holding_cell_htlc_updates.len() != 0 || self.holding_cell_update_fee.is_some() {
- 			log_trace!(logger, "Freeing holding cell with {} HTLC updates{}", self.holding_cell_htlc_updates.len(), if self.holding_cell_update_fee.is_some() { " and a fee update" } else { "" });
+ 			log_trace!(logger, "Freeing holding cell with {} HTLC updates{} in channel {}", self.holding_cell_htlc_updates.len(),
+ 				if self.holding_cell_update_fee.is_some() { " and a fee update" } else { "" }, log_bytes!(self.channel_id()));
  
  			let mut monitor_update = ChannelMonitorUpdate {
  				update_id: self.latest_monitor_update_id + 1, // We don't increment this yet!
@@@ -2371,7 -2387,8 +2401,8 @@@
  							Err(e) => {
  								match e {
  									ChannelError::Ignore(ref msg) => {
- 										log_info!(logger, "Failed to send HTLC with payment_hash {} due to {}", log_bytes!(payment_hash.0), msg);
+ 										log_info!(logger, "Failed to send HTLC with payment_hash {} due to {} in channel {}",
+ 											log_bytes!(payment_hash.0), msg, log_bytes!(self.channel_id()));
  										// If we fail to send here, then this HTLC should
  										// be failed backwards. Failing to send here
  										// indicates that this HTLC may keep being put back
@@@ -2435,6 -2452,10 +2466,10 @@@
  			self.latest_monitor_update_id = monitor_update.update_id;
  			monitor_update.updates.append(&mut additional_update.updates);
  
+ 			log_debug!(logger, "Freeing holding cell in channel {} resulted in {}{} HTLCs added, {} HTLCs fulfilled, and {} HTLCs failed.",
+ 				log_bytes!(self.channel_id()), if update_fee.is_some() { "a fee update, " } else { "" },
+ 				update_add_htlcs.len(), update_fulfill_htlcs.len(), update_fail_htlcs.len());
+ 
  			Ok((Some((msgs::CommitmentUpdate {
  				update_add_htlcs,
  				update_fulfill_htlcs,
@@@ -2510,7 -2531,7 +2545,7 @@@
  		self.counterparty_cur_commitment_point = Some(msg.next_per_commitment_point);
  		self.cur_counterparty_commitment_transaction_number -= 1;
  
- 		log_trace!(logger, "Updating HTLCs on receipt of RAA...");
+ 		log_trace!(logger, "Updating HTLCs on receipt of RAA in channel {}...", log_bytes!(self.channel_id()));
  		let mut to_forward_infos = Vec::new();
  		let mut revoked_htlcs = Vec::new();
  		let mut update_fail_htlcs = Vec::new();
@@@ -2547,10 -2568,8 +2582,8 @@@
  			});
  			for htlc in pending_inbound_htlcs.iter_mut() {
  				let swap = if let &InboundHTLCState::AwaitingRemoteRevokeToAnnounce(_) = &htlc.state {
- 					log_trace!(logger, " ...promoting inbound AwaitingRemoteRevokeToAnnounce {} to Committed", log_bytes!(htlc.payment_hash.0));
  					true
  				} else if let &InboundHTLCState::AwaitingAnnouncedRemoteRevoke(_) = &htlc.state {
- 					log_trace!(logger, " ...promoting inbound AwaitingAnnouncedRemoteRevoke {} to Committed", log_bytes!(htlc.payment_hash.0));
  					true
  				} else { false };
  				if swap {
@@@ -2558,11 -2577,13 +2591,13 @@@
  					mem::swap(&mut state, &mut htlc.state);
  
  					if let InboundHTLCState::AwaitingRemoteRevokeToAnnounce(forward_info) = state {
+ 						log_trace!(logger, " ...promoting inbound AwaitingRemoteRevokeToAnnounce {} to AwaitingAnnouncedRemoteRevoke", log_bytes!(htlc.payment_hash.0));
  						htlc.state = InboundHTLCState::AwaitingAnnouncedRemoteRevoke(forward_info);
  						require_commitment = true;
  					} else if let InboundHTLCState::AwaitingAnnouncedRemoteRevoke(forward_info) = state {
  						match forward_info {
  							PendingHTLCStatus::Fail(fail_msg) => {
+ 								log_trace!(logger, " ...promoting inbound AwaitingAnnouncedRemoteRevoke {} to LocalRemoved due to PendingHTLCStatus indicating failure", log_bytes!(htlc.payment_hash.0));
  								require_commitment = true;
  								match fail_msg {
  									HTLCFailureMsg::Relay(msg) => {
@@@ -2576,6 -2597,7 +2611,7 @@@
  								}
  							},
  							PendingHTLCStatus::Forward(forward_info) => {
+ 								log_trace!(logger, " ...promoting inbound AwaitingAnnouncedRemoteRevoke {} to Committed", log_bytes!(htlc.payment_hash.0));
  								to_forward_infos.push((forward_info, htlc.htlc_id));
  								htlc.state = InboundHTLCState::Committed;
  							}
@@@ -2633,6 -2655,7 +2669,7 @@@
  			}
  			self.monitor_pending_forwards.append(&mut to_forward_infos);
  			self.monitor_pending_failures.append(&mut revoked_htlcs);
+ 			log_debug!(logger, "Received a valid revoke_and_ack for channel {} but awaiting a monitor update resolution to reply.", log_bytes!(self.channel_id()));
  			return Ok((None, Vec::new(), Vec::new(), None, monitor_update, Vec::new()))
  		}
  
@@@ -2663,6 -2686,8 +2700,8 @@@
  					self.latest_monitor_update_id = monitor_update.update_id;
  					monitor_update.updates.append(&mut additional_update.updates);
  
+ 					log_debug!(logger, "Received a valid revoke_and_ack for channel {}. Responding with a commitment update with {} HTLCs failed.",
+ 						log_bytes!(self.channel_id()), update_fail_htlcs.len() + update_fail_malformed_htlcs.len());
  					Ok((Some(msgs::CommitmentUpdate {
  						update_add_htlcs: Vec::new(),
  						update_fulfill_htlcs: Vec::new(),
@@@ -2672,6 -2697,7 +2711,7 @@@
  						commitment_signed
  					}), to_forward_infos, revoked_htlcs, None, monitor_update, htlcs_to_fail))
  				} else {
+ 					log_debug!(logger, "Received a valid revoke_and_ack for channel {} with no reply necessary.", log_bytes!(self.channel_id()));
  					Ok((None, to_forward_infos, revoked_htlcs, self.maybe_propose_first_closing_signed(fee_estimator), monitor_update, htlcs_to_fail))
  				}
  			}
@@@ -2770,7 -2796,7 +2810,7 @@@
  		}
  
  		self.channel_state |= ChannelState::PeerDisconnected as u32;
- 		log_debug!(logger, "Peer disconnection resulted in {} remote-announced HTLC drops on channel {}", inbound_drop_count, log_bytes!(self.channel_id()));
+ 		log_trace!(logger, "Peer disconnection resulted in {} remote-announced HTLC drops on channel {}", inbound_drop_count, log_bytes!(self.channel_id()));
  	}
  
  	/// Indicates that a ChannelMonitor update failed to be stored by the client and further
@@@ -2837,10 -2863,9 +2877,9 @@@
  		self.monitor_pending_revoke_and_ack = false;
  		self.monitor_pending_commitment_signed = false;
  		let order = self.resend_order.clone();
- 		log_trace!(logger, "Restored monitor updating resulting in {}{} commitment update and {} RAA, with {} first",
- 			if funding_broadcastable.is_some() { "a funding broadcastable, " } else { "" },
- 			if commitment_update.is_some() { "a" } else { "no" },
- 			if raa.is_some() { "an" } else { "no" },
+ 		log_debug!(logger, "Restored monitor updating in channel {} resulting in {}{} commitment update and {} RAA, with {} first",
+ 			log_bytes!(self.channel_id()), if funding_broadcastable.is_some() { "a funding broadcastable, " } else { "" },
+ 			if commitment_update.is_some() { "a" } else { "no" }, if raa.is_some() { "an" } else { "no" },
  			match order { RAACommitmentOrder::CommitmentFirst => "commitment", RAACommitmentOrder::RevokeAndACKFirst => "RAA"});
  		(raa, commitment_update, order, forwards, failures, funding_broadcastable, funding_locked)
  	}
@@@ -2918,8 -2943,8 +2957,8 @@@
  			}
  		}
  
- 		log_trace!(logger, "Regenerated latest commitment update with {} update_adds, {} update_fulfills, {} update_fails, and {} update_fail_malformeds",
- 				update_add_htlcs.len(), update_fulfill_htlcs.len(), update_fail_htlcs.len(), update_fail_malformed_htlcs.len());
+ 		log_trace!(logger, "Regenerated latest commitment update in channel {} with {} update_adds, {} update_fulfills, {} update_fails, and {} update_fail_malformeds",
+ 				log_bytes!(self.channel_id()), update_add_htlcs.len(), update_fulfill_htlcs.len(), update_fail_htlcs.len(), update_fail_malformed_htlcs.len());
  		msgs::CommitmentUpdate {
  			update_add_htlcs, update_fulfill_htlcs, update_fail_htlcs, update_fail_malformed_htlcs,
  			update_fee: None,
@@@ -3604,12 -3629,13 +3643,13 @@@
  					// send it immediately instead of waiting for a best_block_updated call (which
  					// may have already happened for this block).
  					if let Some(funding_locked) = self.check_get_funding_locked(height) {
+ 						log_info!(logger, "Sending a funding_locked to our peer for channel {}", log_bytes!(self.channel_id));
  						return Ok(Some(funding_locked));
  					}
  				}
  				for inp in tx.input.iter() {
  					if inp.previous_output == funding_txo.into_bitcoin_outpoint() {
- 						log_trace!(logger, "Detected channel-closing tx {} spending {}:{}, closing channel {}", tx.txid(), inp.previous_output.txid, inp.previous_output.vout, log_bytes!(self.channel_id()));
+ 						log_info!(logger, "Detected channel-closing tx {} spending {}:{}, closing channel {}", tx.txid(), inp.previous_output.txid, inp.previous_output.vout, log_bytes!(self.channel_id()));
  						return Err(msgs::ErrorMessage {
  							channel_id: self.channel_id(),
  							data: "Commitment or closing transaction was confirmed on chain.".to_owned()
@@@ -3632,7 -3658,8 +3672,8 @@@
  	///
  	/// May return some HTLCs (and their payment_hash) which have timed out and should be failed
  	/// back.
- 	pub fn best_block_updated(&mut self, height: u32, highest_header_time: u32) -> Result<(Option<msgs::FundingLocked>, Vec<(HTLCSource, PaymentHash)>), msgs::ErrorMessage> {
+ 	pub fn best_block_updated<L: Deref>(&mut self, height: u32, highest_header_time: u32, logger: &L)
+ 			-> Result<(Option<msgs::FundingLocked>, Vec<(HTLCSource, PaymentHash)>), msgs::ErrorMessage> where L::Target: Logger {
  		let mut timed_out_htlcs = Vec::new();
  		let unforwarded_htlc_cltv_limit = height + HTLC_FAIL_BACK_BUFFER;
  		self.holding_cell_htlc_updates.retain(|htlc_update| {
@@@ -3650,6 -3677,7 +3691,7 @@@
  		self.update_time_counter = cmp::max(self.update_time_counter, highest_header_time);
  
  		if let Some(funding_locked) = self.check_get_funding_locked(height) {
+ 			log_info!(logger, "Sending a funding_locked to our peer for channel {}", log_bytes!(self.channel_id));
  			return Ok((Some(funding_locked), timed_out_htlcs));
  		}
  
@@@ -3682,7 -3710,7 +3724,7 @@@
  	/// Indicates the funding transaction is no longer confirmed in the main chain. This may
  	/// force-close the channel, but may also indicate a harmless reorganization of a block or two
  	/// before the channel has reached funding_locked and we can just wait for more blocks.
- 	pub fn funding_transaction_unconfirmed(&mut self) -> Result<(), msgs::ErrorMessage> {
+ 	pub fn funding_transaction_unconfirmed<L: Deref>(&mut self, logger: &L) -> Result<(), msgs::ErrorMessage> where L::Target: Logger {
  		if self.funding_tx_confirmation_height != 0 {
  			// We handle the funding disconnection by calling best_block_updated with a height one
  			// below where our funding was connected, implying a reorg back to conf_height - 1.
@@@ -3691,7 -3719,7 +3733,7 @@@
  			// larger. If we don't know that time has moved forward, we can just set it to the last
  			// time we saw and it will be ignored.
  			let best_time = self.update_time_counter;
- 			match self.best_block_updated(reorg_height, best_time) {
+ 			match self.best_block_updated(reorg_height, best_time, logger) {
  				Ok((funding_locked, timed_out_htlcs)) => {
  					assert!(funding_locked.is_none(), "We can't generate a funding with 0 confirmations?");
  					assert!(timed_out_htlcs.is_empty(), "We can't have accepted HTLCs with a timeout before our funding confirmation?");
@@@ -3947,13 -3975,13 +3989,13 @@@
  		let dummy_pubkey = PublicKey::from_slice(&pk).unwrap();
  		let data_loss_protect = if self.cur_counterparty_commitment_transaction_number + 1 < INITIAL_COMMITMENT_NUMBER {
  			let remote_last_secret = self.commitment_secrets.get_secret(self.cur_counterparty_commitment_transaction_number + 2).unwrap();
- 			log_trace!(logger, "Enough info to generate a Data Loss Protect with per_commitment_secret {}", log_bytes!(remote_last_secret));
+ 			log_trace!(logger, "Enough info to generate a Data Loss Protect with per_commitment_secret {} for channel {}", log_bytes!(remote_last_secret), log_bytes!(self.channel_id()));
  			OptionalField::Present(DataLossProtect {
  				your_last_per_commitment_secret: remote_last_secret,
  				my_current_per_commitment_point: dummy_pubkey
  			})
  		} else {
- 			log_info!(logger, "Sending a data_loss_protect with no previous remote per_commitment_secret");
+ 			log_info!(logger, "Sending a data_loss_protect with no previous remote per_commitment_secret for channel {}", log_bytes!(self.channel_id()));
  			OptionalField::Present(DataLossProtect {
  				your_last_per_commitment_secret: [0;32],
  				my_current_per_commitment_point: dummy_pubkey,
@@@ -4220,18 -4248,17 +4262,17 @@@
  			signature = res.0;
  			htlc_signatures = res.1;
  
- 			log_trace!(logger, "Signed remote commitment tx {} (txid {}) with redeemscript {} -> {}",
+ 			log_trace!(logger, "Signed remote commitment tx {} (txid {}) with redeemscript {} -> {} in channel {}",
  				encode::serialize_hex(&counterparty_commitment_tx.0.trust().built_transaction().transaction),
- 				&counterparty_commitment_txid,
- 				encode::serialize_hex(&self.get_funding_redeemscript()),
- 				log_bytes!(signature.serialize_compact()[..]));
+ 				&counterparty_commitment_txid, encode::serialize_hex(&self.get_funding_redeemscript()),
+ 				log_bytes!(signature.serialize_compact()[..]), log_bytes!(self.channel_id()));
  
  			for (ref htlc_sig, ref htlc) in htlc_signatures.iter().zip(htlcs) {
- 				log_trace!(logger, "Signed remote HTLC tx {} with redeemscript {} with pubkey {} -> {}",
+ 				log_trace!(logger, "Signed remote HTLC tx {} with redeemscript {} with pubkey {} -> {} in channel {}",
  					encode::serialize_hex(&chan_utils::build_htlc_transaction(&counterparty_commitment_txid, feerate_per_kw, self.get_holder_selected_contest_delay(), htlc, &counterparty_keys.broadcaster_delayed_payment_key, &counterparty_keys.revocation_key)),
  					encode::serialize_hex(&chan_utils::get_htlc_redeemscript(&htlc, &counterparty_keys)),
  					log_bytes!(counterparty_keys.broadcaster_htlc_key.serialize()),
- 					log_bytes!(htlc_sig.serialize_compact()[..]));
+ 					log_bytes!(htlc_sig.serialize_compact()[..]), log_bytes!(self.channel_id()));
  			}
  		}
  
@@@ -4620,7 -4647,7 +4661,7 @@@ impl<Signer: Sign> Writeable for Channe
  
  		self.channel_update_status.write(writer)?;
  
 -		write_tlv_fields!(writer, {}, {(0, self.announcement_sigs)});
 +		write_tlv_fields!(writer, {(0, self.announcement_sigs, option)});
  
  		Ok(())
  	}
@@@ -4793,7 -4820,7 +4834,7 @@@ impl<'a, Signer: Sign, K: Deref> Readab
  		let channel_update_status = Readable::read(reader)?;
  
  		let mut announcement_sigs = None;
 -		read_tlv_fields!(reader, {}, {(0, announcement_sigs)});
 +		read_tlv_fields!(reader, {(0, announcement_sigs, option)});
  
  		let mut secp_ctx = Secp256k1::new();
  		secp_ctx.seeded_randomize(&keys_source.get_secure_random_bytes());
@@@ -4877,8 -4904,6 +4918,8 @@@
  			next_local_commitment_tx_fee_info_cached: Mutex::new(None),
  			#[cfg(any(test, feature = "fuzztarget"))]
  			next_remote_commitment_tx_fee_info_cached: Mutex::new(None),
 +
 +			workaround_lnd_bug_4006: None,
  		})
  	}
  }
diff --combined lightning/src/ln/channelmanager.rs
index edf6ba3d,a9e714ce..f72c76e7
--- a/lightning/src/ln/channelmanager.rs
+++ b/lightning/src/ln/channelmanager.rs
@@@ -776,7 -776,7 +776,7 @@@ macro_rules! convert_chan_err 
  				(false, MsgHandleErrInternal::from_chan_no_close(ChannelError::Ignore(msg), $channel_id.clone()))
  			},
  			ChannelError::Close(msg) => {
- 				log_trace!($self.logger, "Closing channel {} due to close-required error: {}", log_bytes!($channel_id[..]), msg);
+ 				log_error!($self.logger, "Closing channel {} due to close-required error: {}", log_bytes!($channel_id[..]), msg);
  				if let Some(short_id) = $channel.get_short_channel_id() {
  					$short_to_id.remove(&short_id);
  				}
@@@ -1243,7 -1243,7 +1243,7 @@@ impl<Signer: Sign, M: Deref, T: Deref, 
  	#[inline]
  	fn finish_force_close_channel(&self, shutdown_res: ShutdownResult) {
  		let (monitor_update_option, mut failed_htlcs) = shutdown_res;
- 		log_trace!(self.logger, "Finishing force-closure of channel {} HTLCs to fail", failed_htlcs.len());
+ 		log_debug!(self.logger, "Finishing force-closure of channel with {} HTLCs to fail", failed_htlcs.len());
  		for htlc_source in failed_htlcs.drain(..) {
  			self.fail_htlc_backwards_internal(self.channel_state.lock().unwrap(), htlc_source.0, &htlc_source.1, HTLCFailReason::Reason { failure_code: 0x4000 | 8, data: Vec::new() });
  		}
@@@ -1274,7 -1274,7 +1274,7 @@@
  				return Err(APIError::ChannelUnavailable{err: "No such channel".to_owned()});
  			}
  		};
- 		log_trace!(self.logger, "Force-closing channel {}", log_bytes!(channel_id[..]));
+ 		log_error!(self.logger, "Force-closing channel {}", log_bytes!(channel_id[..]));
  		self.finish_force_close_channel(chan.force_shutdown(true));
  		if let Ok(update) = self.get_channel_update(&chan) {
  			let mut channel_state = self.channel_state.lock().unwrap();
@@@ -1671,6 -1671,7 +1671,7 @@@
  							return Err(APIError::MonitorUpdateFailed);
  						}
  
+ 						log_debug!(self.logger, "Sending payment along path resulted in a commitment_signed for channel {}", log_bytes!(chan.get().channel_id()));
  						channel_state.pending_msg_events.push(events::MessageSendEvent::UpdateHTLCs {
  							node_id: path.first().unwrap().pubkey,
  							updates: msgs::CommitmentUpdate {
@@@ -2060,7 -2061,7 +2061,7 @@@
  											onion_packet, ..
  										}, incoming_shared_secret, payment_hash, amt_to_forward, outgoing_cltv_value },
  										prev_funding_outpoint } => {
- 									log_trace!(self.logger, "Adding HTLC from short id {} with payment_hash {} to channel with short id {} after delay", log_bytes!(payment_hash.0), prev_short_channel_id, short_chan_id);
+ 									log_trace!(self.logger, "Adding HTLC from short id {} with payment_hash {} to channel with short id {} after delay", prev_short_channel_id, log_bytes!(payment_hash.0), short_chan_id);
  									let htlc_source = HTLCSource::PreviousHopData(HTLCPreviousHopData {
  										short_channel_id: prev_short_channel_id,
  										outpoint: prev_funding_outpoint,
@@@ -2100,11 -2101,11 +2101,11 @@@
  									panic!("short_channel_id != 0 should imply any pending_forward entries are of type Forward");
  								},
  								HTLCForwardInfo::FailHTLC { htlc_id, err_packet } => {
- 									log_trace!(self.logger, "Failing HTLC back to channel with short id {} after delay", short_chan_id);
+ 									log_trace!(self.logger, "Failing HTLC back to channel with short id {} (backward HTLC ID {}) after delay", short_chan_id, htlc_id);
  									match chan.get_mut().get_update_fail_htlc(htlc_id, err_packet, &self.logger) {
  										Err(e) => {
  											if let ChannelError::Ignore(msg) = e {
- 												log_trace!(self.logger, "Failed to fail backwards to short_id {}: {}", short_chan_id, msg);
+ 												log_trace!(self.logger, "Failed to fail HTLC with ID {} backwards to short_id {}: {}", htlc_id, short_chan_id, msg);
  											} else {
  												panic!("Stated return value requirements in get_update_fail_htlc() were not met");
  											}
@@@ -2158,6 -2159,8 +2159,8 @@@
  								handle_errors.push((chan.get().get_counterparty_node_id(), handle_monitor_err!(self, e, channel_state, chan, RAACommitmentOrder::CommitmentFirst, false, true)));
  								continue;
  							}
+ 							log_debug!(self.logger, "Forwarding HTLCs resulted in a commitment update with {} HTLCs added and {} HTLCs failed for channel {}",
+ 								add_htlc_msgs.len(), fail_htlc_msgs.len(), log_bytes!(chan.get().channel_id()));
  							channel_state.pending_msg_events.push(events::MessageSendEvent::UpdateHTLCs {
  								node_id: chan.get().get_counterparty_node_id(),
  								updates: msgs::CommitmentUpdate {
@@@ -2664,6 -2667,8 +2667,8 @@@
  						}
  					}
  					if let Some((msg, commitment_signed)) = msgs {
+ 						log_debug!(self.logger, "Claiming funds for HTLC with preimage {} resulted in a commitment_signed for channel {}",
+ 							log_bytes!(payment_preimage.0), log_bytes!(chan.get().channel_id()));
  						channel_state.pending_msg_events.push(events::MessageSendEvent::UpdateHTLCs {
  							node_id: chan.get().get_counterparty_node_id(),
  							updates: msgs::CommitmentUpdate {
@@@ -2927,7 -2932,7 +2932,7 @@@
  				if chan.get().get_counterparty_node_id() != *counterparty_node_id {
  					return Err(MsgHandleErrInternal::send_err_msg_no_close("Got a message for a channel from the wrong node!".to_owned(), msg.channel_id));
  				}
- 				try_chan_entry!(self, chan.get_mut().funding_locked(&msg), channel_state, chan);
+ 				try_chan_entry!(self, chan.get_mut().funding_locked(&msg, &self.logger), channel_state, chan);
  				if let Some(announcement_sigs) = self.get_announcement_sigs(chan.get()) {
  					log_trace!(self.logger, "Sending announcement_signatures for {} in response to funding_locked", log_bytes!(chan.get().channel_id()));
  					// If we see locking block before receiving remote funding_locked, we broadcast our
@@@ -3354,8 -3359,13 +3359,13 @@@
  		match channel_state.by_id.entry(chan_id) {
  			hash_map::Entry::Occupied(mut chan) => {
  				if chan.get().get_counterparty_node_id() != *counterparty_node_id {
- 					// TODO: see issue #153, need a consistent behavior on obnoxious behavior from random node
- 					return Err(MsgHandleErrInternal::send_err_msg_no_close("Got a message for a channel from the wrong node!".to_owned(), chan_id));
+ 					if chan.get().should_announce() {
+ 						// If the announcement is about a channel of ours which is public, some
+ 						// other peer may simply be forwarding all its gossip to us. Don't provide
+ 						// a scary-looking error message and return Ok instead.
+ 						return Ok(());
+ 					}
+ 					return Err(MsgHandleErrInternal::send_err_msg_no_close("Got a channel_update for a channel from the wrong node - it shouldn't know about our private channels!".to_owned(), chan_id));
  				}
  				try_chan_entry!(self, chan.get_mut().channel_update(&msg), channel_state, chan);
  			},
@@@ -3365,7 -3375,7 +3375,7 @@@
  	}
  
  	fn internal_channel_reestablish(&self, counterparty_node_id: &PublicKey, msg: &msgs::ChannelReestablish) -> Result<(), MsgHandleErrInternal> {
 -		let (htlcs_failed_forward, chan_restoration_res) = {
 +		let (htlcs_failed_forward, need_lnd_workaround, chan_restoration_res) = {
  			let mut channel_state_lock = self.channel_state.lock().unwrap();
  			let channel_state = &mut *channel_state_lock;
  
@@@ -3386,19 -3396,13 +3396,19 @@@
  							msg,
  						});
  					}
 -					(htlcs_failed_forward, handle_chan_restoration_locked!(self, channel_state_lock, channel_state, chan, revoke_and_ack, commitment_update, order, monitor_update_opt, Vec::new(), None, funding_locked))
 +					let need_lnd_workaround = chan.get_mut().workaround_lnd_bug_4006.take();
 +					(htlcs_failed_forward, need_lnd_workaround,
 +						handle_chan_restoration_locked!(self, channel_state_lock, channel_state, chan, revoke_and_ack, commitment_update, order, monitor_update_opt, Vec::new(), None, funding_locked))
  				},
  				hash_map::Entry::Vacant(_) => return Err(MsgHandleErrInternal::send_err_msg_no_close("Failed to find corresponding channel".to_owned(), msg.channel_id))
  			}
  		};
  		post_handle_chan_restoration!(self, chan_restoration_res);
  		self.fail_holding_cell_htlcs(htlcs_failed_forward, msg.channel_id);
 +
 +		if let Some(funding_locked_msg) = need_lnd_workaround {
 +			self.internal_funding_locked(counterparty_node_id, &funding_locked_msg)?;
 +		}
  		Ok(())
  	}
  
@@@ -3434,6 -3438,7 +3444,7 @@@
  						if let Err(_e) = self.chain_monitor.update_channel(chan.get().get_funding_txo().unwrap(), monitor_update) {
  							unimplemented!();
  						}
+ 						log_debug!(self.logger, "Updating fee resulted in a commitment_signed for channel {}", log_bytes!(chan.get().channel_id()));
  						channel_state.pending_msg_events.push(events::MessageSendEvent::UpdateHTLCs {
  							node_id: chan.get().get_counterparty_node_id(),
  							updates: msgs::CommitmentUpdate {
@@@ -3810,7 -3815,7 +3821,7 @@@ wher
  			*best_block = BestBlock::new(header.prev_blockhash, new_height)
  		}
  
- 		self.do_chain_event(Some(new_height), |channel| channel.best_block_updated(new_height, header.time));
+ 		self.do_chain_event(Some(new_height), |channel| channel.best_block_updated(new_height, header.time, &self.logger));
  	}
  }
  
@@@ -3846,7 -3851,7 +3857,7 @@@ wher
  
  		*self.best_block.write().unwrap() = BestBlock::new(block_hash, height);
  
- 		self.do_chain_event(Some(height), |channel| channel.best_block_updated(height, header.time));
+ 		self.do_chain_event(Some(height), |channel| channel.best_block_updated(height, header.time, &self.logger));
  
  		macro_rules! max_time {
  			($timestamp: expr) => {
@@@ -3888,7 -3893,7 +3899,7 @@@
  		self.do_chain_event(None, |channel| {
  			if let Some(funding_txo) = channel.get_funding_txo() {
  				if funding_txo.txid == *txid {
- 					channel.funding_transaction_unconfirmed().map(|_| (None, Vec::new()))
+ 					channel.funding_transaction_unconfirmed(&self.logger).map(|_| (None, Vec::new()))
  				} else { Ok((None, Vec::new())) }
  			} else { Ok((None, Vec::new())) }
  		});
@@@ -4326,22 -4331,22 +4337,22 @@@ const MIN_SERIALIZATION_VERSION: u8 = 1
  
  impl_writeable_tlv_based_enum!(PendingHTLCRouting,
  	(0, Forward) => {
 -		(0, onion_packet),
 -		(2, short_channel_id),
 -	}, {}, {},
 +		(0, onion_packet, required),
 +		(2, short_channel_id, required),
 +	},
  	(1, Receive) => {
 -		(0, payment_data),
 -		(2, incoming_cltv_expiry),
 -	}, {}, {}
 +		(0, payment_data, required),
 +		(2, incoming_cltv_expiry, required),
 +	}
  ;);
  
  impl_writeable_tlv_based!(PendingHTLCInfo, {
 -	(0, routing),
 -	(2, incoming_shared_secret),
 -	(4, payment_hash),
 -	(6, amt_to_forward),
 -	(8, outgoing_cltv_value)
 -}, {}, {});
 +	(0, routing, required),
 +	(2, incoming_shared_secret, required),
 +	(4, payment_hash, required),
 +	(6, amt_to_forward, required),
 +	(8, outgoing_cltv_value, required)
 +});
  
  impl_writeable_tlv_based_enum!(HTLCFailureMsg, ;
  	(0, Relay),
@@@ -4353,58 -4358,60 +4364,58 @@@ impl_writeable_tlv_based_enum!(PendingH
  );
  
  impl_writeable_tlv_based!(HTLCPreviousHopData, {
 -	(0, short_channel_id),
 -	(2, outpoint),
 -	(4, htlc_id),
 -	(6, incoming_packet_shared_secret)
 -}, {}, {});
 +	(0, short_channel_id, required),
 +	(2, outpoint, required),
 +	(4, htlc_id, required),
 +	(6, incoming_packet_shared_secret, required)
 +});
  
  impl_writeable_tlv_based!(ClaimableHTLC, {
 -	(0, prev_hop),
 -	(2, value),
 -	(4, payment_data),
 -	(6, cltv_expiry),
 -}, {}, {});
 +	(0, prev_hop, required),
 +	(2, value, required),
 +	(4, payment_data, required),
 +	(6, cltv_expiry, required),
 +});
  
  impl_writeable_tlv_based_enum!(HTLCSource,
  	(0, OutboundRoute) => {
 -		(0, session_priv),
 -		(2, first_hop_htlc_msat),
 -	}, {}, {
 -		(4, path),
 -	};
 +		(0, session_priv, required),
 +		(2, first_hop_htlc_msat, required),
 +		(4, path, vec_type),
 +	}, ;
  	(1, PreviousHopData)
  );
  
  impl_writeable_tlv_based_enum!(HTLCFailReason,
  	(0, LightningError) => {
 -		(0, err),
 -	}, {}, {},
 +		(0, err, required),
 +	},
  	(1, Reason) => {
 -		(0, failure_code),
 -	}, {}, {
 -		(2, data),
 +		(0, failure_code, required),
 +		(2, data, vec_type),
  	},
  ;);
  
  impl_writeable_tlv_based_enum!(HTLCForwardInfo,
  	(0, AddHTLC) => {
 -		(0, forward_info),
 -		(2, prev_short_channel_id),
 -		(4, prev_htlc_id),
 -		(6, prev_funding_outpoint),
 -	}, {}, {},
 +		(0, forward_info, required),
 +		(2, prev_short_channel_id, required),
 +		(4, prev_htlc_id, required),
 +		(6, prev_funding_outpoint, required),
 +	},
  	(1, FailHTLC) => {
 -		(0, htlc_id),
 -		(2, err_packet),
 -	}, {}, {},
 +		(0, htlc_id, required),
 +		(2, err_packet, required),
 +	},
  ;);
  
  impl_writeable_tlv_based!(PendingInboundPayment, {
 -	(0, payment_secret),
 -	(2, expiry_time),
 -	(4, user_payment_id),
 -	(6, payment_preimage),
 -	(8, min_value_msat),
 -}, {}, {});
 +	(0, payment_secret, required),
 +	(2, expiry_time, required),
 +	(4, user_payment_id, required),
 +	(6, payment_preimage, required),
 +	(8, min_value_msat, required),
 +});
  
  impl<Signer: Sign, M: Deref, T: Deref, K: Deref, F: Deref, L: Deref> Writeable for ChannelManager<Signer, M, T, K, F, L>
  	where M::Target: chain::Watch<Signer>,
@@@ -4499,7 -4506,7 +4510,7 @@@
  			session_priv.write(writer)?;
  		}
  
 -		write_tlv_fields!(writer, {}, {});
 +		write_tlv_fields!(writer, {});
  
  		Ok(())
  	}
@@@ -4646,6 -4653,11 +4657,11 @@@ impl<'a, Signer: Sign, M: Deref, T: Der
  						channel.get_cur_counterparty_commitment_transaction_number() < monitor.get_cur_counterparty_commitment_number() ||
  						channel.get_latest_monitor_update_id() > monitor.get_latest_update_id() {
  					// If the channel is ahead of the monitor, return InvalidValue:
+ 					log_error!(args.logger, "A ChannelMonitor is stale compared to the current ChannelManager! This indicates a potentially-critical violation of the chain::Watch API!");
+ 					log_error!(args.logger, " The ChannelMonitor for channel {} is at update_id {} but the ChannelManager is at update_id {}.",
+ 						log_bytes!(channel.channel_id()), monitor.get_latest_update_id(), channel.get_latest_monitor_update_id());
+ 					log_error!(args.logger, " The chain::Watch API *requires* that monitors are persisted durably before returning,");
+ 					log_error!(args.logger, " client applications must ensure that ChannelMonitor data is always available and the latest to avoid funds loss!");
  					return Err(DecodeError::InvalidValue);
  				} else if channel.get_cur_holder_commitment_transaction_number() > monitor.get_cur_holder_commitment_number() ||
  						channel.get_revoked_counterparty_commitment_transaction_number() > monitor.get_min_seen_secret() ||
@@@ -4662,6 -4674,9 +4678,9 @@@
  					by_id.insert(channel.channel_id(), channel);
  				}
  			} else {
+ 				log_error!(args.logger, "Missing ChannelMonitor for channel {} needed by ChannelManager.", log_bytes!(channel.channel_id()));
+ 				log_error!(args.logger, " The chain::Watch API *requires* that monitors are persisted durably before returning,");
+ 				log_error!(args.logger, " client applications must ensure that ChannelMonitor data is always available and the latest to avoid funds loss!");
  				return Err(DecodeError::InvalidValue);
  			}
  		}
@@@ -4744,7 -4759,7 +4763,7 @@@
  			}
  		}
  
 -		read_tlv_fields!(reader, {}, {});
 +		read_tlv_fields!(reader, {});
  
  		let mut secp_ctx = Secp256k1::new();
  		secp_ctx.seeded_randomize(&args.keys_manager.get_secure_random_bytes());
diff --combined lightning/src/ln/functional_tests.rs
index 0471cd08,04490656..8eae9cc2
--- a/lightning/src/ln/functional_tests.rs
+++ b/lightning/src/ln/functional_tests.rs
@@@ -1694,7 -1694,8 +1694,8 @@@ fn test_fee_spike_violation_fails_htlc(
  		},
  		_ => panic!("Unexpected event"),
  	};
- 	nodes[1].logger.assert_log("lightning::ln::channel".to_string(), "Attempting to fail HTLC due to fee spike buffer violation".to_string(), 1);
+ 	nodes[1].logger.assert_log("lightning::ln::channel".to_string(),
+ 		format!("Attempting to fail HTLC due to fee spike buffer violation in channel {}. Rebalancing is required.", ::hex::encode(raa_msg.channel_id)), 1);
  
  	check_added_monitors!(nodes[1], 2);
  }
@@@ -3605,20 -3606,15 +3606,20 @@@ fn test_simple_peer_disconnect() 
  	fail_payment(&nodes[0], &vec!(&nodes[1], &nodes[2]), payment_hash_6);
  }
  
 -fn do_test_drop_messages_peer_disconnect(messages_delivered: u8) {
 +fn do_test_drop_messages_peer_disconnect(messages_delivered: u8, simulate_broken_lnd: bool) {
  	// Test that we can reconnect when in-flight HTLC updates get dropped
  	let chanmon_cfgs = create_chanmon_cfgs(2);
  	let node_cfgs = create_node_cfgs(2, &chanmon_cfgs);
  	let node_chanmgrs = create_node_chanmgrs(2, &node_cfgs, &[None, None]);
  	let mut nodes = create_network(2, &node_cfgs, &node_chanmgrs);
 +
 +	let mut as_funding_locked = None;
  	if messages_delivered == 0 {
 -		create_chan_between_nodes_with_value_a(&nodes[0], &nodes[1], 100000, 10001, InitFeatures::known(), InitFeatures::known());
 +		let (funding_locked, _, _) = create_chan_between_nodes_with_value_a(&nodes[0], &nodes[1], 100000, 10001, InitFeatures::known(), InitFeatures::known());
 +		as_funding_locked = Some(funding_locked);
  		// nodes[1] doesn't receive the funding_locked message (it'll be re-sent on reconnect)
 +		// Note that we store it so that if we're running with `simulate_broken_lnd` we can deliver
 +		// it before the channel_reestablish message.
  	} else {
  		create_announced_chan_between_nodes(&nodes, 0, 1, InitFeatures::known(), InitFeatures::known());
  	}
@@@ -3673,17 -3669,6 +3674,17 @@@
  	nodes[0].node.peer_disconnected(&nodes[1].node.get_our_node_id(), false);
  	nodes[1].node.peer_disconnected(&nodes[0].node.get_our_node_id(), false);
  	if messages_delivered < 3 {
 +		if simulate_broken_lnd {
 +			// lnd has a long-standing bug where they send a funding_locked prior to a
 +			// channel_reestablish if you reconnect prior to funding_locked time.
 +			//
 +			// Here we simulate that behavior, delivering a funding_locked immediately on
 +			// reconnect. Note that we don't bother skipping the now-duplicate funding_locked sent
 +			// in `reconnect_nodes` but we currently don't fail based on that.
 +			//
 +			// See-also <https://github.com/lightningnetwork/lnd/issues/4006>
 +			nodes[1].node.handle_funding_locked(&nodes[0].node.get_our_node_id(), &as_funding_locked.as_ref().unwrap().0);
 +		}
  		// Even if the funding_locked messages get exchanged, as long as nothing further was
  		// received on either side, both sides will need to resend them.
  		reconnect_nodes(&nodes[0], &nodes[1], (true, true), (0, 1), (0, 0), (0, 0), (0, 0), (false, false));
@@@ -3827,18 -3812,17 +3828,18 @@@
  
  #[test]
  fn test_drop_messages_peer_disconnect_a() {
 -	do_test_drop_messages_peer_disconnect(0);
 -	do_test_drop_messages_peer_disconnect(1);
 -	do_test_drop_messages_peer_disconnect(2);
 -	do_test_drop_messages_peer_disconnect(3);
 +	do_test_drop_messages_peer_disconnect(0, true);
 +	do_test_drop_messages_peer_disconnect(0, false);
 +	do_test_drop_messages_peer_disconnect(1, false);
 +	do_test_drop_messages_peer_disconnect(2, false);
  }
  
  #[test]
  fn test_drop_messages_peer_disconnect_b() {
 -	do_test_drop_messages_peer_disconnect(4);
 -	do_test_drop_messages_peer_disconnect(5);
 -	do_test_drop_messages_peer_disconnect(6);
 +	do_test_drop_messages_peer_disconnect(3, false);
 +	do_test_drop_messages_peer_disconnect(4, false);
 +	do_test_drop_messages_peer_disconnect(5, false);
 +	do_test_drop_messages_peer_disconnect(6, false);
  }
  
  #[test]
@@@ -6251,8 -6235,9 +6252,9 @@@ fn test_fail_holding_cell_htlc_upon_fre
  	// us to surface its failure to the user.
  	chan_stat = get_channel_value_stat!(nodes[0], chan.2);
  	assert_eq!(chan_stat.holding_cell_outbound_amount_msat, 0);
- 	nodes[0].logger.assert_log("lightning::ln::channel".to_string(), "Freeing holding cell with 1 HTLC updates".to_string(), 1);
- 	let failure_log = format!("Failed to send HTLC with payment_hash {} due to Cannot send value that would put our balance under counterparty-announced channel reserve value ({})", log_bytes!(our_payment_hash.0), chan_stat.channel_reserve_msat);
+ 	nodes[0].logger.assert_log("lightning::ln::channel".to_string(), format!("Freeing holding cell with 1 HTLC updates in channel {}", hex::encode(chan.2)), 1);
+ 	let failure_log = format!("Failed to send HTLC with payment_hash {} due to Cannot send value that would put our balance under counterparty-announced channel reserve value ({}) in channel {}",
+ 		hex::encode(our_payment_hash.0), chan_stat.channel_reserve_msat, hex::encode(chan.2));
  	nodes[0].logger.assert_log("lightning::ln::channel".to_string(), failure_log.to_string(), 1);
  
  	// Check that the payment failed to be sent out.
@@@ -6331,8 -6316,9 +6333,9 @@@ fn test_free_and_fail_holding_cell_htlc
  	// to surface its failure to the user. The first payment should succeed.
  	chan_stat = get_channel_value_stat!(nodes[0], chan.2);
  	assert_eq!(chan_stat.holding_cell_outbound_amount_msat, 0);
- 	nodes[0].logger.assert_log("lightning::ln::channel".to_string(), "Freeing holding cell with 2 HTLC updates".to_string(), 1);
- 	let failure_log = format!("Failed to send HTLC with payment_hash {} due to Cannot send value that would put our balance under counterparty-announced channel reserve value ({})", log_bytes!(payment_hash_2.0), chan_stat.channel_reserve_msat);
+ 	nodes[0].logger.assert_log("lightning::ln::channel".to_string(), format!("Freeing holding cell with 2 HTLC updates in channel {}", hex::encode(chan.2)), 1);
+ 	let failure_log = format!("Failed to send HTLC with payment_hash {} due to Cannot send value that would put our balance under counterparty-announced channel reserve value ({}) in channel {}",
+ 		hex::encode(payment_hash_2.0), chan_stat.channel_reserve_msat, hex::encode(chan.2));
  	nodes[0].logger.assert_log("lightning::ln::channel".to_string(), failure_log.to_string(), 1);
  
  	// Check that the second payment failed to be sent out.
diff --combined lightning/src/ln/msgs.rs
index a64bbc01,c45e2277..fa3c6034
--- a/lightning/src/ln/msgs.rs
+++ b/lightning/src/ln/msgs.rs
@@@ -38,6 -38,7 +38,7 @@@ use core::fmt::Debug
  use std::io::Read;
  
  use util::events::MessageSendEventsProvider;
+ use util::logger;
  use util::ser::{Readable, Writeable, Writer, FixedLengthReader, HighZeroBytesDroppedVarInt};
  
  use ln::{PaymentPreimage, PaymentHash, PaymentSecret};
@@@ -688,7 -689,11 +689,11 @@@ pub enum ErrorAction 
  		msg: Option<ErrorMessage>
  	},
  	/// The peer did something harmless that we weren't able to process, just log and ignore
+ 	// New code should *not* use this. New code must use IgnoreAndLog, below!
  	IgnoreError,
+ 	/// The peer did something harmless that we weren't able to meaningfully process.
+ 	/// If the error is logged, log it at the given level.
+ 	IgnoreAndLog(logger::Level),
  	/// The peer did something incorrect. Tell them.
  	SendErrorMessage {
  		/// The message to send.
@@@ -1295,19 -1300,20 +1300,19 @@@ impl Writeable for OnionHopData 
  			},
  			OnionHopDataFormat::NonFinalNode { short_channel_id } => {
  				encode_varint_length_prefixed_tlv!(w, {
 -					(2, HighZeroBytesDroppedVarInt(self.amt_to_forward)),
 -					(4, HighZeroBytesDroppedVarInt(self.outgoing_cltv_value)),
 -					(6, short_channel_id)
 -				}, { });
 +					(2, HighZeroBytesDroppedVarInt(self.amt_to_forward), required),
 +					(4, HighZeroBytesDroppedVarInt(self.outgoing_cltv_value), required),
 +					(6, short_channel_id, required)
 +				});
  			},
  			OnionHopDataFormat::FinalNode { ref payment_data } => {
  				if let Some(final_data) = payment_data {
  					if final_data.total_msat > MAX_VALUE_MSAT { panic!("We should never be sending infinite/overflow onion payments"); }
  				}
  				encode_varint_length_prefixed_tlv!(w, {
 -					(2, HighZeroBytesDroppedVarInt(self.amt_to_forward)),
 -					(4, HighZeroBytesDroppedVarInt(self.outgoing_cltv_value))
 -				}, {
 -					(8, payment_data)
 +					(2, HighZeroBytesDroppedVarInt(self.amt_to_forward), required),
 +					(4, HighZeroBytesDroppedVarInt(self.outgoing_cltv_value), required),
 +					(8, payment_data, option)
  				});
  			},
  		}
@@@ -1330,11 -1336,12 +1335,11 @@@ impl Readable for OnionHopData 
  			let mut cltv_value = HighZeroBytesDroppedVarInt(0u32);
  			let mut short_id: Option<u64> = None;
  			let mut payment_data: Option<FinalOnionHopData> = None;
 -			decode_tlv!(&mut rd, {
 -				(2, amt),
 -				(4, cltv_value)
 -			}, {
 -				(6, short_id),
 -				(8, payment_data)
 +			decode_tlv_stream!(&mut rd, {
 +				(2, amt, required),
 +				(4, cltv_value, required),
 +				(6, short_id, option),
 +				(8, payment_data, option),
  			});
  			rd.eat_remaining().map_err(|_| DecodeError::ShortRead)?;
  			let format = if let Some(short_channel_id) = short_id {
diff --combined lightning/src/routing/network_graph.rs
index 7f086603,6fe8912b..80a7010b
--- a/lightning/src/routing/network_graph.rs
+++ b/lightning/src/routing/network_graph.rs
@@@ -28,7 -28,7 +28,7 @@@ use ln::msgs::{ChannelAnnouncement, Cha
  use ln::msgs::{QueryChannelRange, ReplyChannelRange, QueryShortChannelIds, ReplyShortChannelIdsEnd};
  use ln::msgs;
  use util::ser::{Writeable, Readable, Writer};
- use util::logger::Logger;
+ use util::logger::{Logger, Level};
  use util::events::{MessageSendEvent, MessageSendEventsProvider};
  use util::scid_utils::{block_from_scid, scid_from_parts, MAX_SCID_BLOCK};
  
@@@ -169,12 -169,16 +169,16 @@@ impl<C: Deref , L: Deref > RoutingMessa
  	fn handle_htlc_fail_channel_update(&self, update: &msgs::HTLCFailChannelUpdate) {
  		match update {
  			&msgs::HTLCFailChannelUpdate::ChannelUpdateMessage { ref msg } => {
+ 				let chan_enabled = msg.contents.flags & (1 << 1) != (1 << 1);
+ 				log_debug!(self.logger, "Updating channel with channel_update from a payment failure. Channel {} is {}abled.", msg.contents.short_channel_id, if chan_enabled { "en" } else { "dis" });
  				let _ = self.network_graph.write().unwrap().update_channel(msg, &self.secp_ctx);
  			},
  			&msgs::HTLCFailChannelUpdate::ChannelClosed { short_channel_id, is_permanent } => {
+ 				log_debug!(self.logger, "{} channel graph entry for {} due to a payment failure.", if is_permanent { "Removing" } else { "Disabling" }, short_channel_id);
  				self.network_graph.write().unwrap().close_channel_from_update(short_channel_id, is_permanent);
  			},
  			&msgs::HTLCFailChannelUpdate::NodeFailure { ref node_id, is_permanent } => {
+ 				log_debug!(self.logger, "{} node graph entry for {} due to a payment failure.", if is_permanent { "Removing" } else { "Disabling" }, node_id);
  				self.network_graph.write().unwrap().fail_node(node_id, is_permanent);
  			},
  		}
@@@ -460,14 -464,14 +464,14 @@@ impl fmt::Display for DirectionalChanne
  }
  
  impl_writeable_tlv_based!(DirectionalChannelInfo, {
 -	(0, last_update),
 -	(2, enabled),
 -	(4, cltv_expiry_delta),
 -	(6, htlc_minimum_msat),
 -	(8, htlc_maximum_msat),
 -	(10, fees),
 -	(12, last_update_message),
 -}, {}, {});
 +	(0, last_update, required),
 +	(2, enabled, required),
 +	(4, cltv_expiry_delta, required),
 +	(6, htlc_minimum_msat, required),
 +	(8, htlc_maximum_msat, required),
 +	(10, fees, required),
 +	(12, last_update_message, required),
 +});
  
  #[derive(Clone, Debug, PartialEq)]
  /// Details about a channel (both directions).
@@@ -501,14 -505,14 +505,14 @@@ impl fmt::Display for ChannelInfo 
  }
  
  impl_writeable_tlv_based!(ChannelInfo, {
 -	(0, features),
 -	(2, node_one),
 -	(4, one_to_two),
 -	(6, node_two),
 -	(8, two_to_one),
 -	(10, capacity_sats),
 -	(12, announcement_message),
 -}, {}, {});
 +	(0, features, required),
 +	(2, node_one, required),
 +	(4, one_to_two, required),
 +	(6, node_two, required),
 +	(8, two_to_one, required),
 +	(10, capacity_sats, required),
 +	(12, announcement_message, required),
 +});
  
  
  /// Fees for routing via a given channel or a node
@@@ -521,10 -525,7 +525,10 @@@ pub struct RoutingFees 
  	pub proportional_millionths: u32,
  }
  
 -impl_writeable_tlv_based!(RoutingFees, {(0, base_msat), (2, proportional_millionths)}, {}, {});
 +impl_writeable_tlv_based!(RoutingFees, {
 +	(0, base_msat, required),
 +	(2, proportional_millionths, required)
 +});
  
  #[derive(Clone, Debug, PartialEq)]
  /// Information received in the latest node_announcement from this node.
@@@ -550,12 -551,14 +554,12 @@@ pub struct NodeAnnouncementInfo 
  }
  
  impl_writeable_tlv_based!(NodeAnnouncementInfo, {
 -	(0, features),
 -	(2, last_update),
 -	(4, rgb),
 -	(6, alias),
 -}, {
 -	(8, announcement_message),
 -}, {
 -	(10, addresses),
 +	(0, features, required),
 +	(2, last_update, required),
 +	(4, rgb, required),
 +	(6, alias, required),
 +	(8, announcement_message, option),
 +	(10, addresses, vec_type),
  });
  
  #[derive(Clone, Debug, PartialEq)]
@@@ -581,10 -584,11 +585,10 @@@ impl fmt::Display for NodeInfo 
  	}
  }
  
 -impl_writeable_tlv_based!(NodeInfo, {}, {
 -	(0, lowest_inbound_channel_fees),
 -	(2, announcement_info),
 -}, {
 -	(4, channels),
 +impl_writeable_tlv_based!(NodeInfo, {
 +	(0, lowest_inbound_channel_fees, option),
 +	(2, announcement_info, option),
 +	(4, channels, vec_type),
  });
  
  const SERIALIZATION_VERSION: u8 = 1;
@@@ -606,7 -610,7 +610,7 @@@ impl Writeable for NetworkGraph 
  			node_info.write(writer)?;
  		}
  
 -		write_tlv_fields!(writer, {}, {});
 +		write_tlv_fields!(writer, {});
  		Ok(())
  	}
  }
@@@ -630,7 -634,7 +634,7 @@@ impl Readable for NetworkGraph 
  			let node_info = Readable::read(reader)?;
  			nodes.insert(node_id, node_info);
  		}
 -		read_tlv_fields!(reader, {}, {});
 +		read_tlv_fields!(reader, {});
  
  		Ok(NetworkGraph {
  			genesis_hash,
@@@ -713,7 -717,7 +717,7 @@@ impl NetworkGraph 
  			Some(node) => {
  				if let Some(node_info) = node.announcement_info.as_ref() {
  					if node_info.last_update  >= msg.timestamp {
- 						return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreError});
+ 						return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)});
  					}
  				}
  
@@@ -834,7 -838,7 +838,7 @@@
  					Self::remove_channel_in_nodes(&mut self.nodes, &entry.get(), msg.short_channel_id);
  					*entry.get_mut() = chan_info;
  				} else {
- 					return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreError})
+ 					return Err(LightningError{err: "Already have knowledge of channel".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)})
  				}
  			},
  			BtreeEntry::Vacant(entry) => {
@@@ -936,7 -940,7 +940,7 @@@
  					( $target: expr, $src_node: expr) => {
  						if let Some(existing_chan_info) = $target.as_ref() {
  							if existing_chan_info.last_update >= msg.timestamp {
- 								return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreError});
+ 								return Err(LightningError{err: "Update older than last processed update".to_owned(), action: ErrorAction::IgnoreAndLog(Level::Trace)});
  							}
  							chan_was_enabled = existing_chan_info.enabled;
  						} else {
diff --combined lightning/src/routing/router.rs
index 12374bad,06bf581c..b12b960d
--- a/lightning/src/routing/router.rs
+++ b/lightning/src/routing/router.rs
@@@ -49,13 -49,13 +49,13 @@@ pub struct RouteHop 
  }
  
  impl_writeable_tlv_based!(RouteHop, {
 -	(0, pubkey),
 -	(2, node_features),
 -	(4, short_channel_id),
 -	(6, channel_features),
 -	(8, fee_msat),
 -	(10, cltv_expiry_delta),
 -}, {}, {});
 +	(0, pubkey, required),
 +	(2, node_features, required),
 +	(4, short_channel_id, required),
 +	(6, channel_features, required),
 +	(8, fee_msat, required),
 +	(10, cltv_expiry_delta, required),
 +});
  
  /// A route directs a payment from the sender (us) to the recipient. If the recipient supports MPP,
  /// it can take multiple paths. Each path is composed of one or more hops through the network.
@@@ -83,7 -83,7 +83,7 @@@ impl Writeable for Route 
  				hop.write(writer)?;
  			}
  		}
 -		write_tlv_fields!(writer, {}, {});
 +		write_tlv_fields!(writer, {});
  		Ok(())
  	}
  }
@@@ -101,7 -101,7 +101,7 @@@ impl Readable for Route 
  			}
  			paths.push(hops);
  		}
 -		read_tlv_fields!(reader, {}, {});
 +		read_tlv_fields!(reader, {});
  		Ok(Route { paths })
  	}
  }
@@@ -168,7 -168,7 +168,7 @@@ struct DummyDirectionalChannelInfo 
  /// so that we can choose cheaper paths (as per Dijkstra's algorithm).
  /// Fee values should be updated only in the context of the whole path, see update_value_and_recompute_fees.
  /// These fee values are useful to choose hops as we traverse the graph "payee-to-payer".
- #[derive(Clone)]
+ #[derive(Clone, Debug)]
  struct PathBuildingHop<'a> {
  	// The RouteHintHop fields which will eventually be used if this hop is used in a final Route.
  	// Note that node_features is calculated separately after our initial graph walk.
@@@ -506,6 -506,8 +506,8 @@@ pub fn get_route<L: Deref>(our_node_id
  	// - when we want to stop looking for new paths.
  	let mut already_collected_value_msat = 0;
  
+ 	log_trace!(logger, "Building path from {} (payee) to {} (us/payer) for value {} msat.", payee, our_node_id, final_value_msat);
+ 
  	macro_rules! add_entry {
  		// Adds entry which goes from $src_node_id to $dest_node_id
  		// over the channel with id $chan_id with fees described in
@@@ -891,6 -893,8 +893,8 @@@
  			}
  		}
  
+ 		log_trace!(logger, "Starting main path collection loop with {} nodes pre-filled from first/last hops.", targets.len());
+ 
  		// At this point, targets are filled with the data from first and
  		// last hops communicated by the caller, and the payment receiver.
  		let mut found_new_path = false;
@@@ -954,6 -958,9 +958,9 @@@
  				ordered_hops.last_mut().unwrap().0.hop_use_fee_msat = 0;
  				ordered_hops.last_mut().unwrap().0.cltv_expiry_delta = final_cltv;
  
+ 				log_trace!(logger, "Found a path back to us from the target with {} hops contributing up to {} msat: {:?}",
+ 					ordered_hops.len(), value_contribution_msat, ordered_hops);
+ 
  				let mut payment_path = PaymentPath {hops: ordered_hops};
  
  				// We could have possibly constructed a slightly inconsistent path: since we reduce
@@@ -989,8 -996,9 +996,9 @@@
  					// If we weren't capped by hitting a liquidity limit on a channel in the path,
  					// we'll probably end up picking the same path again on the next iteration.
  					// Decrease the available liquidity of a hop in the middle of the path.
- 					let victim_liquidity = bookkeeped_channels_liquidity_available_msat.get_mut(
- 						&payment_path.hops[(payment_path.hops.len() - 1) / 2].0.short_channel_id).unwrap();
+ 					let victim_scid = payment_path.hops[(payment_path.hops.len() - 1) / 2].0.short_channel_id;
+ 					log_trace!(logger, "Disabling channel {} for future path building iterations to avoid duplicates.", victim_scid);
+ 					let victim_liquidity = bookkeeped_channels_liquidity_available_msat.get_mut(&victim_scid).unwrap();
  					*victim_liquidity = 0;
  				}
  
@@@ -1032,6 -1040,8 +1040,8 @@@
  		// In the latter case, making another path finding attempt won't help,
  		// because we deterministically terminated the search due to low liquidity.
  		if already_collected_value_msat >= recommended_value_msat || !found_new_path {
+ 			log_trace!(logger, "Have now collected {} msat (seeking {} msat) in paths. Last path loop {} a new path.",
+ 				already_collected_value_msat, recommended_value_msat, if found_new_path { "found" } else { "did not find" });
  			break 'paths_collection;
  		} else if found_new_path && already_collected_value_msat == final_value_msat && payment_paths.len() == 1 {
  			// Further, if this was our first walk of the graph, and we weren't limited by an
@@@ -1040,8 -1050,10 +1050,10 @@@
  			// potentially allowing us to pay fees to meet the htlc_minimum on the new path while
  			// still keeping a lower total fee than this path.
  			if !hit_minimum_limit {
+ 				log_trace!(logger, "Collected exactly our payment amount on the first pass, without hitting an htlc_minimum_msat limit, exiting.");
  				break 'paths_collection;
  			}
+ 			log_trace!(logger, "Collected our payment amount on the first pass, but running again to collect extra paths with a potentially higher limit.");
  			path_value_msat = recommended_value_msat;
  		}
  	}
@@@ -1152,7 -1164,7 +1164,7 @@@
  	}
  
  	let route = Route { paths: selected_paths };
- 	log_trace!(logger, "Got route: {}", log_route!(route));
+ 	log_info!(logger, "Got route to {}: {}", payee, log_route!(route));
  	Ok(route)
  }