mirrors/eclair
1
0
Fork 0
mirror of https://github.com/ACINQ/eclair.git synced 2024-11-19 01:43:22 +01:00
Code Issues Projects Releases Wiki Activity

Add logs to onion message relay (#2880)

Browse Source 
There weren't any logs when relaying onion messages, which makes it
impossible to troubleshoot. While we're working on cross-compatibility,
we keep those logs at the `INFO` level, and will change some of them to
`DEBUG` once stabilized.
This commit is contained in:
Bastien Teinturier 2024-07-15 09:50:50 +02:00 committed by GitHub
parent 14a4ea45b1
commit f8d6acb326
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
3 changed files with 28 additions and 8 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
eclair-core/src/main/scala/fr/acinq/eclair/Logs.scala
View File

@ -50,6 +50,7 @@ object Logs {
paymentId_opt: Option[UUID] = None,
paymentHash_opt: Option[ByteVector32] = None,
txPublishId_opt: Option[UUID] = None,
messageId_opt: Option[ByteVector32] = None,
nodeAlias_opt: Option[String] = None): Map[String, String] =
Seq(
// nb: we preformat MDC values so that there is no white spaces in logs when they are not defined
@ -60,6 +61,7 @@ object Logs {
paymentId_opt.map(i => "paymentId" -> s" i:$i"),
paymentHash_opt.map(h => "paymentHash" -> s" h:$h"),
txPublishId_opt.map(t => "txPublishId" -> s" t:$t"),
messageId_opt.map(m => "messageId" -> s" m:$m"),
nodeAlias_opt.map(a => "nodeAlias" -> s" a:$a"),
).flatten.toMap
@ -105,6 +107,10 @@ object Logs {
override def category: String = "SYN"
}
case object MESSAGE extends LogCategory {
override def category: String = "MSG"
}
case object PAYMENT extends LogCategory {
override def category: String = "PAY"
}
@ -133,6 +139,8 @@ object Logs {
case TickBroadcast => Some(LogCategory.ROUTING_SYNC)
case TickPruneStaleChannels => Some(LogCategory.ROUTING_SYNC)
case _: OnionMessage => Some(LogCategory.MESSAGE)
case _: HandshakeCompleted => Some(LogCategory.CONNECTION)
case _: Peer.Connect => Some(LogCategory.CONNECTION)
case _: Peer.Disconnect => Some(LogCategory.CONNECTION)

25
eclair-core/src/main/scala/fr/acinq/eclair/io/MessageRelay.scala
View File

@ -23,6 +23,7 @@ import akka.actor.typed.scaladsl.{ActorContext, Behaviors}
import akka.actor.{ActorRef, typed}
import fr.acinq.bitcoin.scalacompat.ByteVector32
import fr.acinq.bitcoin.scalacompat.Crypto.PublicKey
import fr.acinq.eclair.Logs.LogCategory
import fr.acinq.eclair.channel.Register
import fr.acinq.eclair.io.Monitoring.{Metrics, Tags}
import fr.acinq.eclair.io.Peer.{PeerInfo, PeerInfoResponse}
@ -31,7 +32,7 @@ import fr.acinq.eclair.message.OnionMessages
import fr.acinq.eclair.message.OnionMessages.DropReason
import fr.acinq.eclair.router.Router
import fr.acinq.eclair.wire.protocol.OnionMessage
import fr.acinq.eclair.{EncodedNodeId, NodeParams, ShortChannelId}
import fr.acinq.eclair.{EncodedNodeId, Logs, NodeParams, ShortChannelId}
object MessageRelay {
// @formatter:off
@ -79,8 +80,10 @@ object MessageRelay {
Behaviors.setup { context =>
Behaviors.receiveMessagePartial {
case RelayMessage(messageId, prevNodeId, nextNode, msg, policy, replyTo_opt) =>
val relay = new MessageRelay(nodeParams, messageId, prevNodeId, policy, switchboard, register, router, replyTo_opt, context)
relay.queryNextNodeId(msg, nextNode)
Behaviors.withMdc(Logs.mdc(category_opt = Some(LogCategory.MESSAGE), messageId_opt = Some(messageId), remoteNodeId_opt = Some(prevNodeId))) {
val relay = new MessageRelay(nodeParams, messageId, prevNodeId, policy, switchboard, register, router, replyTo_opt, context)
relay.queryNextNodeId(msg, nextNode)
}
}
}
}
@ -98,6 +101,8 @@ private class MessageRelay(nodeParams: NodeParams,
import MessageRelay._
private val log = context.log
def queryNextNodeId(msg: OnionMessage, nextNode: Either[ShortChannelId, EncodedNodeId]): Behavior[Command] = {
nextNode match {
case Left(outgoingChannelId) if outgoingChannelId == ShortChannelId.toSelf =>
@ -117,9 +122,11 @@ private class MessageRelay(nodeParams: NodeParams,
Behaviors.receiveMessagePartial {
case WrappedOptionalNodeId(None) =>
Metrics.OnionMessagesNotRelayed.withTag(Tags.Reason, Tags.Reasons.UnknownNextNodeId).increment()
log.info("could not find outgoing node for scid={}", channelId)
replyTo_opt.foreach(_ ! UnknownChannel(messageId, channelId))
Behaviors.stopped
case WrappedOptionalNodeId(Some(nextNodeId)) =>
log.info("found outgoing node {} for channel {}", nextNodeId, channelId)
withNextNodeId(msg, nextNodeId)
}
}
@ -146,7 +153,7 @@ private class MessageRelay(nodeParams: NodeParams,
waitForPreviousPeerForPolicyCheck(msg, nextNodeId)
case RelayAll =>
switchboard ! Peer.Connect(nextNodeId, None, context.messageAdapter(WrappedConnectionResult).toClassic, isPersistent = false)
waitForConnection(msg)
waitForConnection(msg, nextNodeId)
}
}
}
@ -155,33 +162,37 @@ private class MessageRelay(nodeParams: NodeParams,
Behaviors.receiveMessagePartial {
case WrappedPeerInfo(PeerInfo(_, _, _, _, channels)) if channels.nonEmpty =>
switchboard ! GetPeerInfo(context.messageAdapter(WrappedPeerInfo), nextNodeId)
waitForNextPeerForPolicyCheck(msg)
waitForNextPeerForPolicyCheck(msg, nextNodeId)
case _ =>
Metrics.OnionMessagesNotRelayed.withTag(Tags.Reason, Tags.Reasons.NoChannelWithPreviousPeer).increment()
log.info("dropping onion message to {}: relaying without channels with the previous node is disabled by policy", nextNodeId)
replyTo_opt.foreach(_ ! AgainstPolicy(messageId, RelayChannelsOnly))
Behaviors.stopped
}
}
private def waitForNextPeerForPolicyCheck(msg: OnionMessage): Behavior[Command] = {
private def waitForNextPeerForPolicyCheck(msg: OnionMessage, nextNodeId: PublicKey): Behavior[Command] = {
Behaviors.receiveMessagePartial {
case WrappedPeerInfo(PeerInfo(peer, _, _, _, channels)) if channels.nonEmpty =>
peer ! Peer.RelayOnionMessage(messageId, msg, replyTo_opt)
Behaviors.stopped
case _ =>
Metrics.OnionMessagesNotRelayed.withTag(Tags.Reason, Tags.Reasons.NoChannelWithNextPeer).increment()
log.info("dropping onion message to {}: relaying without channels with the next node is disabled by policy", nextNodeId)
replyTo_opt.foreach(_ ! AgainstPolicy(messageId, RelayChannelsOnly))
Behaviors.stopped
}
}
private def waitForConnection(msg: OnionMessage): Behavior[Command] = {
private def waitForConnection(msg: OnionMessage, nextNodeId: PublicKey): Behavior[Command] = {
Behaviors.receiveMessagePartial {
case WrappedConnectionResult(r: PeerConnection.ConnectionResult.HasConnection) =>
log.info("connected to {}: relaying onion message", nextNodeId)
r.peer ! Peer.RelayOnionMessage(messageId, msg, replyTo_opt)
Behaviors.stopped
case WrappedConnectionResult(f: PeerConnection.ConnectionResult.Failure) =>
Metrics.OnionMessagesNotRelayed.withTag(Tags.Reason, Tags.Reasons.ConnectionFailure).increment()
log.info("could not connect to {}: {}", nextNodeId, f.toString)
replyTo_opt.foreach(_ ! ConnectionFailure(messageId, f))
Behaviors.stopped
}

3
eclair-core/src/main/scala/fr/acinq/eclair/io/Peer.scala
View File

@ -284,9 +284,10 @@ class Peer(val nodeParams: NodeParams,
case Event(msg: OnionMessage, _: ConnectedData) =>
OnionMessages.process(nodeParams.privateKey, msg) match {
case OnionMessages.DropMessage(reason) =>
log.debug("dropping message from {}: {}", remoteNodeId.value.toHex, reason.toString)
log.info("dropping message from {}: {}", remoteNodeId.value.toHex, reason.toString)
case OnionMessages.SendMessage(nextNode, message) if nodeParams.features.hasFeature(Features.OnionMessages) =>
val messageId = randomBytes32()
log.info("relaying onion message with messageId={}", messageId)
val relay = context.spawn(Behaviors.supervise(MessageRelay(nodeParams, switchboard, register, router)).onFailure(typed.SupervisorStrategy.stop), s"relay-message-$messageId")
relay ! MessageRelay.RelayMessage(messageId, remoteNodeId, nextNode, message, nodeParams.onionMessageConfig.relayPolicy, None)
case OnionMessages.SendMessage(_, _) =>