From 68209b804c3d83c7445b8e0a15f7dbc0b99c81bb Mon Sep 17 00:00:00 2001 From: Bastien Teinturier <31281497+t-bast@users.noreply.github.com> Date: Thu, 12 Nov 2020 11:05:00 +0100 Subject: [PATCH] Add more path finding logs (#1597) Since Phoenix has a low number of channels and discards the whole public network graph, we can be more aggressive with what we log without flooding the logs. This information will be very helpful to troubleshoot issues when users send multipart payments. --- .../send/MultiPartPaymentLifecycle.scala | 6 +++--- .../payment/send/PaymentLifecycle.scala | 4 ++-- .../eclair/router/RouteCalculation.scala | 1 + .../fr/acinq/eclair/router/Validation.scala | 20 ++++++++++--------- 4 files changed, 17 insertions(+), 14 deletions(-) diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/MultiPartPaymentLifecycle.scala b/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/MultiPartPaymentLifecycle.scala index e0c8665d9..664871d9e 100644 --- a/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/MultiPartPaymentLifecycle.scala +++ b/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/MultiPartPaymentLifecycle.scala @@ -70,7 +70,7 @@ class MultiPartPaymentLifecycle(nodeParams: NodeParams, cfg: SendPaymentConfig, case Event(r: SendMultiPartPayment, _) => val routeParams = r.getRouteParams(nodeParams, randomize = false) // we don't randomize the first attempt, regardless of configuration choices val maxFee = routeParams.getMaxFee(r.totalAmount) - log.debug("sending {} with maximum fee {}", r.totalAmount, maxFee) + log.info("sending {} with maximum fee {}", r.totalAmount, maxFee) val d = PaymentProgress(sender, r, r.maxAttempts, Map.empty, Ignore.empty, Nil) router ! createRouteRequest(nodeParams, r.totalAmount, maxFee, routeParams, d, cfg) goto(WAIT_FOR_ROUTES) using d @@ -106,7 +106,7 @@ class MultiPartPaymentLifecycle(nodeParams: NodeParams, cfg: SendPaymentConfig, // the payment. When we're retrying an MPP split, it may make sense to retry those ignored channels because with // a different split, they may have enough balance to forward the payment. val (toSend, maxFee) = remainingToSend(nodeParams, d.request, d.pending.values) - log.debug("retry sending {} with maximum fee {} without ignoring channels ({})", toSend, maxFee, d.ignore.channels.map(_.shortChannelId).mkString(",")) + log.info("retry sending {} with maximum fee {} without ignoring channels ({})", toSend, maxFee, d.ignore.channels.map(_.shortChannelId).mkString(",")) val routeParams = d.request.getRouteParams(nodeParams, randomize = true) // we randomize route selection when we retry router ! createRouteRequest(nodeParams, toSend, maxFee, routeParams, d, cfg).copy(ignore = d.ignore.emptyChannels()) retriedFailedChannels = true @@ -152,7 +152,7 @@ class MultiPartPaymentLifecycle(nodeParams: NodeParams, cfg: SendPaymentConfig, val ignore1 = PaymentFailure.updateIgnored(pf.failures, d.ignore) val stillPending = d.pending - pf.id val (toSend, maxFee) = remainingToSend(nodeParams, d.request, stillPending.values) - log.debug("child payment failed, retry sending {} with maximum fee {}", toSend, maxFee) + log.info("child payment failed, retry sending {} with maximum fee {}", toSend, maxFee) val routeParams = d.request.getRouteParams(nodeParams, randomize = true) // we randomize route selection when we retry val d1 = d.copy(pending = stillPending, ignore = ignore1, failures = d.failures ++ pf.failures) router ! createRouteRequest(nodeParams, toSend, maxFee, routeParams, d1, cfg) diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/PaymentLifecycle.scala b/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/PaymentLifecycle.scala index 565e96f22..d03d05ed2 100644 --- a/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/PaymentLifecycle.scala +++ b/eclair-core/src/main/scala/fr/acinq/eclair/payment/send/PaymentLifecycle.scala @@ -75,7 +75,7 @@ class PaymentLifecycle(nodeParams: NodeParams, cfg: SendPaymentConfig, router: A span.tag(Tags.Amount, c.finalPayload.amount.toLong) span.tag(Tags.TotalAmount, c.finalPayload.totalAmount.toLong) span.tag(Tags.Expiry, c.finalPayload.expiry.toLong) - log.debug("sending {} to route {}", c.finalPayload.amount, c.printRoute()) + log.info("sending {} to route {}", c.finalPayload.amount, c.printRoute()) val send = SendPayment(c.targetNodeId, c.finalPayload, maxAttempts = 1, assistedRoutes = c.assistedRoutes) c.route.fold( hops => router ! FinalizeRoute(c.finalPayload.amount, hops, c.assistedRoutes, paymentContext = Some(cfg.paymentContext)), @@ -91,7 +91,7 @@ class PaymentLifecycle(nodeParams: NodeParams, cfg: SendPaymentConfig, router: A span.tag(Tags.Amount, c.finalPayload.amount.toLong) span.tag(Tags.TotalAmount, c.finalPayload.totalAmount.toLong) span.tag(Tags.Expiry, c.finalPayload.expiry.toLong) - log.debug("sending {} to {}", c.finalPayload.amount, c.targetNodeId) + log.info("sending {} to {}", c.finalPayload.amount, c.targetNodeId) router ! RouteRequest(nodeParams.nodeId, c.targetNodeId, c.finalPayload.amount, c.getMaxFee(nodeParams), c.assistedRoutes, routeParams = c.routeParams, paymentContext = Some(cfg.paymentContext)) if (cfg.storeInDb) { paymentsDb.addOutgoingPayment(OutgoingPayment(id, cfg.parentId, cfg.externalId, paymentHash, PaymentType.Standard, c.finalPayload.amount, cfg.recipientAmount, cfg.recipientNodeId, System.currentTimeMillis, cfg.paymentRequest, OutgoingPaymentStatus.Pending)) diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/router/RouteCalculation.scala b/eclair-core/src/main/scala/fr/acinq/eclair/router/RouteCalculation.scala index bf1be1308..2dee8b84a 100644 --- a/eclair-core/src/main/scala/fr/acinq/eclair/router/RouteCalculation.scala +++ b/eclair-core/src/main/scala/fr/acinq/eclair/router/RouteCalculation.scala @@ -87,6 +87,7 @@ object RouteCalculation { log.info(s"finding routes ${r.source}->${r.target} with assistedChannels={} ignoreNodes={} ignoreChannels={} excludedChannels={}", assistedChannels.keys.mkString(","), r.ignore.nodes.map(_.value).mkString(","), r.ignore.channels.mkString(","), d.excludedChannels.mkString(",")) log.info("finding routes with randomize={} params={}", params.randomize, params) + log.info("routing graph: {}", d.graph.edgeSet().map(e => s"${e.desc.shortChannelId}->${e.balance_opt}/${e.capacity}").mkString(", ")) val tags = TagSet.Empty.withTag(Tags.MultiPart, r.allowMultiPart).withTag(Tags.Amount, Tags.amountBucket(r.amount)) KamonExt.time(Metrics.FindRouteDuration.withTags(tags.withTag(Tags.NumberOfRoutes, routesToFind.toLong))) { val result = if (r.allowMultiPart) { diff --git a/eclair-core/src/main/scala/fr/acinq/eclair/router/Validation.scala b/eclair-core/src/main/scala/fr/acinq/eclair/router/Validation.scala index c3a187b7a..86c5f3ed6 100644 --- a/eclair-core/src/main/scala/fr/acinq/eclair/router/Validation.scala +++ b/eclair-core/src/main/scala/fr/acinq/eclair/router/Validation.scala @@ -267,7 +267,9 @@ object Validation { def handleChannelUpdate(d: Data, db: NetworkDb, routerConf: RouterConf, update: Either[LocalChannelUpdate, RemoteChannelUpdate], wasStashed: Boolean = false)(implicit ctx: ActorContext, log: LoggingAdapter): Data = { implicit val sender: ActorRef = ctx.self // necessary to preserve origin when sending messages to other actors val (uOriginal: ChannelUpdate, origins: Set[GossipOrigin]) = update match { - case Left(lcu) => (lcu.channelUpdate, Set(LocalGossip)) + case Left(lcu) => + log.info("received local channel update for shortChannelId={}, balance={}", lcu.shortChannelId, lcu.commitments.availableBalanceForSend) + (lcu.channelUpdate, Set(LocalGossip)) case Right(rcu) => rcu.origins.collect { case RemoteGossip(peerConnection, _) if !wasStashed => // stashed changes have already been acknowledged @@ -350,11 +352,11 @@ object Validation { val pc = d.privateChannels(u.shortChannelId) val desc = getDesc(u, pc) if (StaleChannels.isStale(u)) { - log.debug("ignoring {} (stale)", u) + log.info("ignoring {} (stale)", u) sendDecision(origins, GossipDecision.Stale(u)) d } else if (pc.getChannelUpdateSameSideAs(u).exists(_.timestamp >= u.timestamp)) { - log.debug("ignoring {} (already know same or newer)", u) + log.info("ignoring {} (already know same or newer)", u) sendDecision(origins, GossipDecision.Duplicate(u)) d } else if (!Announcements.checkSig(u, desc.a)) { @@ -362,7 +364,7 @@ object Validation { sendDecision(origins, GossipDecision.InvalidSignature(u)) d } else if (pc.getChannelUpdateSameSideAs(u).isDefined) { - log.debug("updated channel_update for shortChannelId={} public={} flags={} {}", u.shortChannelId, publicChannel, u.channelFlags, u) + log.info("updated channel_update for shortChannelId={} public={} flags={} {}", u.shortChannelId, publicChannel, u.channelFlags, u) Metrics.channelUpdateRefreshed(u, pc.getChannelUpdateSameSideAs(u).get, publicChannel) sendDecision(origins, GossipDecision.Accepted(u)) ctx.system.eventStream.publish(ChannelUpdatesReceived(u :: Nil)) @@ -375,7 +377,7 @@ object Validation { } d.copy(privateChannels = d.privateChannels + (u.shortChannelId -> pc1), graph = graph1) } else { - log.debug("added channel_update for shortChannelId={} public={} flags={} {}", u.shortChannelId, publicChannel, u.channelFlags, u) + log.info("added channel_update for shortChannelId={} public={} flags={} {}", u.shortChannelId, publicChannel, u.channelFlags, u) sendDecision(origins, GossipDecision.Accepted(u)) ctx.system.eventStream.publish(ChannelUpdatesReceived(u :: Nil)) // we also need to update the graph @@ -444,7 +446,7 @@ object Validation { case None => // channel isn't announced and we never heard of it (maybe it is a private channel or maybe it is a public channel that doesn't yet have 6 confirmations) // let's create a corresponding private channel and process the channel_update - log.debug("adding unannounced local channel to remote={} shortChannelId={}", lcu.remoteNodeId, lcu.shortChannelId) + log.info("adding unannounced local channel to remote={} shortChannelId={}", lcu.remoteNodeId, lcu.shortChannelId) val pc = PrivateChannel(localNodeId, lcu.remoteNodeId, None, None, ChannelMeta(0 msat, 0 msat)).updateBalances(lcu.commitments) val d1 = d.copy(privateChannels = d.privateChannels + (lcu.shortChannelId -> pc)) handleChannelUpdate(d1, db, routerConf, Left(lcu)) @@ -461,7 +463,7 @@ object Validation { d } else if (d.privateChannels.contains(shortChannelId)) { // the channel was private or public-but-not-yet-announced, let's do the clean up - log.debug("removing private local channel and channel_update for channelId={} shortChannelId={}", channelId, shortChannelId) + log.info("removing private local channel and channel_update for channelId={} shortChannelId={}", channelId, shortChannelId) val desc1 = ChannelDesc(shortChannelId, localNodeId, remoteNodeId) val desc2 = ChannelDesc(shortChannelId, remoteNodeId, localNodeId) // we remove the corresponding updates from the graph @@ -480,7 +482,7 @@ object Validation { val (publicChannels1, graph1) = d.channels.get(e.shortChannelId) match { case Some(pc) => val pc1 = pc.updateBalances(e.commitments) - log.debug("public channel balance updated: {}", pc1) + log.info("public channel balance updated: {} -> {}", pc1.ann.shortChannelId, pc1.meta_opt) val update_opt = if (e.commitments.localParams.nodeId == pc1.ann.nodeId1) pc1.update_1_opt else pc1.update_2_opt val graph1 = update_opt.map(u => d.graph.addEdge(desc, u, pc1.capacity, pc1.getBalanceSameSideAs(u))).getOrElse(d.graph) (d.channels + (e.shortChannelId -> pc1), graph1) @@ -490,7 +492,7 @@ object Validation { val (privateChannels1, graph2) = d.privateChannels.get(e.shortChannelId) match { case Some(pc) => val pc1 = pc.updateBalances(e.commitments) - log.debug("private channel balance updated: {}", pc1) + log.info("private channel balance updated: {} -> {}", pc1.update_1_opt.orElse(pc1.update_2_opt).map(_.shortChannelId), pc1.meta) val update_opt = if (e.commitments.localParams.nodeId == pc1.nodeId1) pc1.update_1_opt else pc1.update_2_opt val graph2 = update_opt.map(u => graph1.addEdge(desc, u, pc1.capacity, pc1.getBalanceSameSideAs(u))).getOrElse(graph1) (d.privateChannels + (e.shortChannelId -> pc1), graph2)