Skip to content

Commit d3687d7

Browse files
t-bastt-bast
authored
Improve logs during reconnection (#835)
Include commitments MDC in `Offline` and `Syncing`: this helps figure out reconnection issues where the splice state doesn't match. We also include more logs in a few related places. We aren't consistent with regards to updating the `_channels` map and calling `processActions`: sometimes we do it first, sometimes second. It's really hard to reason about this and figure out whether this may have side effects or not, but it seems more consistent to update the channel state first, then process its follow-up actions.
1 parent 0b46790 commit d3687d7

File tree

5 files changed

+28
-21
lines changed

5 files changed

+28
-21
lines changed

‎modules/core/src/commonMain/kotlin/fr/acinq/lightning/channel/states/Channel.kt‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -290,6 +290,8 @@ sealed class ChannelState {
290290
/** A channel state that is persisted to the DB. */
291291
sealed class PersistedChannelState : ChannelState() {
292292
abstract val channelId: ByteVector32
293+
abstract val fundingTxId: TxId
294+
abstract val fundingTxIndex: Long
293295

294296
fun ChannelContext.channelKeys(): ChannelKeys = when (val state = this@PersistedChannelState) {
295297
is WaitForFundingSigned -> state.channelParams.localParams.channelKeys(keyManager)
@@ -397,6 +399,8 @@ sealed class ChannelStateWithCommitments : PersistedChannelState() {
397399
// Remote nonces that must be used when signing the next remote commitment transaction (one per active commitment).
398400
abstract val remoteNextCommitNonces: Map<TxId, IndividualNonce>
399401
override val channelId: ByteVector32 get() = commitments.channelId
402+
override val fundingTxId: TxId get() = commitments.latest.fundingTxId
403+
override val fundingTxIndex: Long get() = commitments.latest.fundingTxIndex
400404
val isChannelOpener: Boolean get() = commitments.channelParams.localParams.isChannelOpener
401405
val paysCommitTxFees: Boolean get() = commitments.channelParams.localParams.paysCommitTxFees
402406
val remoteNodeId: PublicKey get() = commitments.remoteNodeId

‎modules/core/src/commonMain/kotlin/fr/acinq/lightning/channel/states/Normal.kt‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -880,9 +880,9 @@ data class Normal(
880880
// We watch for confirmation in all cases, to allow pruning outdated commitments when transactions confirm.
881881
val fundingScript = action.commitment.commitInput(channelKeys()).txOut.publicKeyScript
882882
val watchConfirmed = WatchConfirmed(channelId, action.commitment.fundingTxId, fundingScript, staticParams.nodeParams.minDepthBlocks, WatchConfirmed.ChannelFundingDepthOk)
883-
val commitments = commitments.add(action.commitment)
883+
val commitments1 = commitments.add(action.commitment)
884884
val remoteNextCommitNonces1 = remoteNextCommitNonces + listOfNotNull(action.nextRemoteCommitNonce?.let { action.commitment.fundingTxId to it }).toMap()
885-
val nextState = this@Normal.copy(commitments = commitments, remoteNextCommitNonces = remoteNextCommitNonces1, spliceStatus = SpliceStatus.None)
885+
val nextState = this@Normal.copy(commitments = commitments1, remoteNextCommitNonces = remoteNextCommitNonces1, spliceStatus = SpliceStatus.None)
886886
val actions = buildList {
887887
add(ChannelAction.Storage.StoreState(nextState))
888888
action.fundingTx.signedTx?.let { add(ChannelAction.Blockchain.PublishTx(it, ChannelAction.Blockchain.PublishTx.Type.FundingTx)) }

‎modules/core/src/commonMain/kotlin/fr/acinq/lightning/channel/states/WaitForFundingSigned.kt‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ package fr.acinq.lightning.channel.states
22

33
import fr.acinq.bitcoin.ByteVector32
44
import fr.acinq.bitcoin.PublicKey
5+
import fr.acinq.bitcoin.TxId
56
import fr.acinq.bitcoin.crypto.Pack
67
import fr.acinq.bitcoin.utils.Either
78
import fr.acinq.lightning.ChannelEvents
@@ -47,6 +48,8 @@ data class WaitForFundingSigned(
4748
val channelOrigin: Origin?,
4849
) : PersistedChannelState() {
4950
override val channelId: ByteVector32 = channelParams.channelId
51+
override val fundingTxId: TxId = signingSession.fundingTxId
52+
override val fundingTxIndex: Long = signingSession.fundingParams.fundingTxIndex
5053

5154
override suspend fun ChannelContext.processInternal(cmd: ChannelCommand): Pair<ChannelState, List<ChannelAction>> {
5255
return when (cmd) {

‎modules/core/src/commonMain/kotlin/fr/acinq/lightning/io/Peer.kt‎

Lines changed: 7 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
package fr.acinq.lightning.io
22

33
import fr.acinq.bitcoin.*
4-
import fr.acinq.bitcoin.crypto.musig2.IndividualNonce
54
import fr.acinq.bitcoin.utils.Either
65
import fr.acinq.lightning.*
76
import fr.acinq.lightning.Lightning.randomKey
@@ -302,7 +301,6 @@ class Peer(
302301
delay(1.minutes)
303302
}
304303
}
305-
306304
}
307305
launch {
308306
suspend fun updateFeerates() {
@@ -339,8 +337,8 @@ class Peer(
339337
logger.info { "restoring channel ${it.channelId} from local storage" }
340338
val state = WaitForInit
341339
val (state1, actions) = state.process(ChannelCommand.Init.Restore(it))
342-
processActions(it.channelId, peerConnection, actions, state1)
343340
_channels = _channels + (it.channelId to state1)
341+
processActions(it.channelId, peerConnection, actions, state1)
344342
it.channelId
345343
}
346344
logger.info { "restored ${channelIds.size} channels" }
@@ -940,7 +938,7 @@ class Peer(
940938
}
941939
}
942940
is ChannelAction.Storage.StoreState -> {
943-
logger.info { "storing state=${action.data::class.simpleName}" }
941+
logger.info { "storing state=${action.data::class.simpleName} latestFundingTxId=${action.data.fundingTxId} latestFundingTxIndex=${action.data.fundingTxIndex}" }
944942
db.channels.addOrUpdateChannel(action.data)
945943
if (action.data is Closed) {
946944
updatePeerStorage(nodeParams, channels - channelId, peerConnection, theirInit?.features, logger)
@@ -1322,8 +1320,8 @@ class Peer(
13221320
_channels[msg.channelId]?.let { state ->
13231321
val event1 = ChannelCommand.MessageReceived(msg)
13241322
val (state1, actions) = state.process(event1)
1325-
processActions(msg.channelId, peerConnection, actions, state1)
13261323
_channels = _channels + (msg.channelId to state1)
1324+
processActions(msg.channelId, peerConnection, actions, state1)
13271325
} ?: run {
13281326
logger.error { "received ${msg::class.simpleName} for unknown channel ${msg.channelId}" }
13291327
peerConnection?.send(Error(msg.channelId, "unknown channel"))
@@ -1334,8 +1332,8 @@ class Peer(
13341332
_channels.values.filterIsInstance<Normal>().find { it.matchesShortChannelId(msg.shortChannelId) }?.let { state ->
13351333
val event1 = ChannelCommand.MessageReceived(msg)
13361334
val (state1, actions) = state.process(event1)
1337-
processActions(state.channelId, peerConnection, actions, state1)
13381335
_channels = _channels + (state.channelId to state1)
1336+
processActions(state.channelId, peerConnection, actions, state1)
13391337
}
13401338
}
13411339
is WillAddHtlc -> when {
@@ -1400,8 +1398,8 @@ class Peer(
14001398
val state = _channels[cmd.watch.channelId] ?: error("channel ${cmd.watch.channelId} not found")
14011399
val event1 = ChannelCommand.WatchReceived(cmd.watch)
14021400
val (state1, actions) = state.process(event1)
1403-
processActions(cmd.watch.channelId, peerConnection, actions, state1)
14041401
_channels = _channels + (cmd.watch.channelId to state1)
1402+
processActions(cmd.watch.channelId, peerConnection, actions, state1)
14051403
}
14061404
}
14071405
is OpenChannel -> {
@@ -1709,14 +1707,14 @@ class Peer(
17091707
// this is for all channels
17101708
_channels.forEach { (key, value) ->
17111709
val (state1, actions) = value.process(cmd.channelCommand)
1712-
processActions(key, peerConnection, actions, state1)
17131710
_channels = _channels + (key to state1)
1711+
processActions(key, peerConnection, actions, state1)
17141712
}
17151713
} else {
17161714
_channels[cmd.channelId]?.let { state ->
17171715
val (state1, actions) = state.process(cmd.channelCommand)
1718-
processActions(cmd.channelId, peerConnection, actions, state1)
17191716
_channels = _channels + (cmd.channelId to state1)
1717+
processActions(cmd.channelId, peerConnection, actions, state1)
17201718
} ?: logger.error { "received ${cmd.channelCommand::class.simpleName} for an unknown channel ${cmd.channelId}" }
17211719
}
17221720
}

‎modules/core/src/commonMain/kotlin/fr/acinq/lightning/logging/MDCLogger.kt‎

Lines changed: 12 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -51,8 +51,6 @@ suspend fun <T> MDCLogger.withMDC(mdc: Map<String, Any>, f: suspend (MDCLogger)
5151
return f(logger)
5252
}
5353

54-
55-
5654
/**
5755
* Utility functions to build MDC for various objects without polluting main classes
5856
*/
@@ -82,29 +80,33 @@ fun ChannelState.mdc(): Map<String, Any> {
8280
return buildMap {
8381
put("state", state.stateName)
8482
when (state) {
83+
WaitForInit -> {}
8584
is WaitForOpenChannel -> put("temporaryChannelId", state.temporaryChannelId)
8685
is WaitForAcceptChannel -> put("temporaryChannelId", state.temporaryChannelId)
8786
is WaitForFundingCreated -> put("channelId", state.channelId)
8887
is WaitForFundingSigned -> put("channelId", state.channelId)
8988
is ChannelStateWithCommitments -> put("channelId", state.channelId)
9089
is Offline -> put("channelId", state.state.channelId)
9190
is Syncing -> put("channelId", state.state.channelId)
92-
else -> {}
91+
Aborted -> {}
9392
}
94-
when(state) {
95-
is ChannelStateWithCommitments -> {
96-
put("commitments", "active=${state.commitments.active.map { it.fundingTxIndex }} inactive=${state.commitments.inactive.map { it.fundingTxIndex }}")
97-
put("balances", "toLocal=${state.commitments.latest.localCommit.spec.toLocal} toRemote=${state.commitments.latest.localCommit.spec.toRemote} capacity=${state.commitments.latest.fundingAmount}")
98-
}
99-
else -> {}
93+
val commitments = when (state) {
94+
is ChannelStateWithCommitments -> state.commitments
95+
is Offline if state.state is ChannelStateWithCommitments -> state.state.commitments
96+
is Syncing if state.state is ChannelStateWithCommitments -> state.state.commitments
97+
else -> null
98+
}
99+
commitments?.let { commitments ->
100+
put("commitments", "active=${commitments.active.map { it.fundingTxIndex }} inactive=${commitments.inactive.map { it.fundingTxIndex }}")
101+
put("balances", "toLocal=${commitments.latest.localCommit.spec.toLocal} toRemote=${commitments.latest.localCommit.spec.toRemote} capacity=${commitments.latest.fundingAmount}")
100102
}
101103
}
102104
}
103105

104106
fun LightningMessage.mdc(): Map<String, Any> {
105107
val msg = this
106108
return buildMap {
107-
when(msg) {
109+
when (msg) {
108110
is HasTemporaryChannelId -> put("temporaryChannelId", msg.temporaryChannelId)
109111
is HasChannelId -> put("channelId", msg.channelId)
110112
else -> {}

0 commit comments

Comments
 (0)