Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Add logs to onion message relay #2880

Merged
merged 3 commits into from
Jul 15, 2024
Merged

Add logs to onion message relay #2880

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
3c2a363
Add logs to onion message relay
t-bast Jul 12, 2024
14e8043
Use MDC instead of duplicating log contents
t-bast Jul 12, 2024
f52c807
Move logs in message handlers
t-bast Jul 15, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 8 additions & 0 deletions eclair-core/src/main/scala/fr/acinq/eclair/Logs.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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

Expand Down Expand Up @@ -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"
}
Expand Down Expand Up @@ -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)
Expand Down
25 changes: 18 additions & 7 deletions eclair-core/src/main/scala/fr/acinq/eclair/io/MessageRelay.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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}
Expand All @@ -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
Expand Down Expand Up @@ -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)
}
}
}
}
Expand All @@ -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 =>
Expand All @@ -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)
}
}
Expand All @@ -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)
}
}
}
Expand All @@ -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
}
Expand Down
3 changes: 2 additions & 1 deletion eclair-core/src/main/scala/fr/acinq/eclair/io/Peer.scala
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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(_, _) =>
Expand Down
Loading