Malicious force close event in logs

[DerEwige]

Over the last few days my funds in eclair steadily increased until I finally arrived at about 1’000’000 Satoshi more than I should have.

When it started, I did not really think much about it. Force closes happen all the time, for whatever reason and then the money comes back in after the timelock expires and sometimes individual expired HTLCs.

As 1m Sats is the default channel size I’m using I believe my channel punished someone for an attempted malicious force close. I only realized this might be the case when the amount hit that number.

I have about 50 mb of log files per hour and I have no clue, what event I am looking for in the log.
If you could provide me a keyword, I could filter for in the logs that would be great?

[t-bast]

I have about 50 mb of log files per hour

That sounds like a lot, even our node doesn't have that much logs!
What logging level are you using?
I would recommend using info by default, with an exception for routing messages where warn is probably enough (otherwise this can be quite spammy).

In order to do that, follow the instructions here and add this line:

<logger name="fr.acinq.eclair.router" level="WARN"/>

If you could provide me a keyword, I could filter for in the logs that would be great?

Usually for everything exceptional, you should grep for WARN or ERROR (case-sensitive), there should be very few such logs.
This will for example yield all channel force-close attempts.
For malicious force-close, you can grep a revoked commit has been published which is using the WARN level:

eclair/eclair-core/src/main/scala/fr/acinq/eclair/channel/Helpers.scala

Line 1042 in c1daaf3

log.warning(s"a revoked commit has been published with txnumber=$txNumber")

[DerEwige]

Actually I may have an idea. In this channel there was about two dozens htlcs pending. Do you know if those are payments initiated by your node, as opposed to routed payments?

Those were payments I was paying to myself for rebalancing.
Those payments were outgoing through that channel.

Do you still need the logs grepped by the channel?

[DerEwige]

@pm47

Ok I pinned it down.
It is closing-> localCloseBalance -> htlcsUnpublished

So when the channel was force closed I had a lot of rebalancing htlcs on the flight.
Once all closing balance and htlcs arrived it still showed

"htlcsUnpublished": 0.00307485

Then that just wen't to zero and the total got reduced by the same amount.

$ ./eclair-cli globalbalance
{
  "total": 0.21297364,
  "onChain": {
    "confirmed": 0.00901942,
    "unconfirmed": 0
  },
  "offChain": {
    "waitForFundingConfirmed": 0,
    "waitForFundingLocked": 0,
    "normal": {
      "toLocal": 0.18755855,
      "htlcs": 0.01014287
    },
    "shutdown": {
      "toLocal": 0,
      "htlcs": 0
    },
    "negotiating": 0,
    "closing": {
      "localCloseBalance": {
        "toLocal": {},
        "htlcs": {
          "07f406eb4bc29bf3fb8da2b257581c00a76f92071faf8605e08d824924290641": 0.00158711,
          "60cf108b8497b540182881c7be1609b9f9371d7eeeb716bda64560ff15d0344b": 0.00018662,
          "a6bbae8e1043cef496c655a55033ded8594d3c609ddda7a0b683eab5f065882c": 0.00038662,
          "55969d5de1dd226f14cc7c4fa81890cfcc2516bbaeaf5c268de13a10e364c113": 0.00043093,
          "3a3a5e671502ed0a317acf87273b18c0ebeb732411de4a03e8233660819d5875": 0.00038667
        },
        "htlcsUnpublished": 0.00327485
      },
      "remoteCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "mutualCloseBalance": {
        "toLocal": {}
      },
      "unknownCloseBalance": {
        "toLocal": 0,
        "htlcs": 0
      }
    },
    "waitForPublishFutureCommitment": 0
  }
}


$ ./eclair-cli globalbalance
{
  "total": 0.21277708,
  "onChain": {
    "confirmed": 0.01156644,
    "unconfirmed": 0.00043093
  },
  "offChain": {
    "waitForFundingConfirmed": 0,
    "waitForFundingLocked": 0,
    "normal": {
      "toLocal": 0.18750075,
      "htlcs": 0.01020411
    },
    "shutdown": {
      "toLocal": 0,
      "htlcs": 0
    },
    "negotiating": 0,
    "closing": {
      "localCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0.00307485
      },
      "remoteCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "mutualCloseBalance": {
        "toLocal": {}
      },
      "unknownCloseBalance": {
        "toLocal": 0,
        "htlcs": 0
      }
    },
    "waitForPublishFutureCommitment": 0
  }
}

$ ./eclair-cli globalbalance
{
  "total": 0.20970621,
  "onChain": {
    "confirmed": 0.01199737,
    "unconfirmed": 0
  },
  "offChain": {
    "waitForFundingConfirmed": 0,
    "waitForFundingLocked": 0,
    "normal": {
      "toLocal": 0.18966771,
      "htlcs": 0.00804113
    },
    "shutdown": {
      "toLocal": 0,
      "htlcs": 0
    },
    "negotiating": 0,
    "closing": {
      "localCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "remoteCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "mutualCloseBalance": {
        "toLocal": {}
      },
      "unknownCloseBalance": {
        "toLocal": 0,
        "htlcs": 0
      }
    },
    "waitForPublishFutureCommitment": 0
  }
}

[pm47]

Thanks for the follow up! Will take a look when I have a minute

[pm47]

Which version of eclair were you running?

If it's 0.7.0, then the htlcsUnpublished indeed includes amount that was being sent by your node as part as rebalancing. Before #2410, this amount would be counted in the balance, which would explain what you are seeing. Those payment eventually succeed on-chain, and get removed from the balance.

[DerEwige]

It is indeed 0.7.0 (version=0.7.0 commit=a804905)

[thomash-acinq]

You can also query the audit database:

SELECT channel_id, node_id, timestamp FROM audit.transactions_published WHERE tx_type = 'revoked-commit'

[thomash-acinq]

No, that's only for payments. Here there is no payment involved.

[DerEwige]

Ok I went into the DB. But got no result, for that querry.
So, I still have no clue, what is going on

[pm47]

Revoked commit is a false lead, you would see a sudden increase of balance (not progressive over few days), and it's not consistent with the globalance output that you pasted above.

[DerEwige]

You are right, that was just my first thought, but proved to be false.

I suspect there might be something wrong with
localClosingBalance -> htlcs
localClosingBalance -> htlcsUnpublished

Here are 3 globalbalance requests a few hours apart
The last one shows the correct balance once all HTLC’s from closing arrived

$ ./eclair-cli globalbalance
{
  "total": 0.14402952,
  "onChain": {
    "confirmed": 0.0019349299999999999,
    "unconfirmed": 0
  },
  "offChain": {
    "waitForFundingConfirmed": 0,
    "waitForFundingLocked": 0,
    "normal": {
      "toLocal": 0.12900586,
      "htlcs": 0.00350095
    },
    "shutdown": {
      "toLocal": 0,
      "htlcs": 0
    },
    "negotiating": 0,
    "closing": {
      "localCloseBalance": {
        "toLocal": {},
        "htlcs": {
          "aa77fcdc34503ff23ef7f89398ad09ce64e0543e3d5ac60c96393a654c53fe58": 0.00158947,
          "7617dd6b5d7f58e9fbb61e0fff288a6b0f539de829daf8f96f5952a2f28bd417": 0.00319812
        },
        "htlcsUnpublished": 0.00480019
      },
      "remoteCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "mutualCloseBalance": {
        "toLocal": {}
      },
      "unknownCloseBalance": {
        "toLocal": 0,
        "htlcs": 0
      }
    },
    "waitForPublishFutureCommitment": 0
  }
}

$ ./eclair-cli globalbalance
{
  "total": 0.14082787,
  "onChain": {
    "confirmed": 0.00513305,
    "unconfirmed": 0
  },
  "offChain": {
    "waitForFundingConfirmed": 0,
    "waitForFundingLocked": 0,
    "normal": {
      "toLocal": 0.12530437,
      "htlcs": 0.00720082
    },
    "shutdown": {
      "toLocal": 0,
      "htlcs": 0
    },
    "negotiating": 0,
    "closing": {
      "localCloseBalance": {
        "toLocal": {},
        "htlcs": {
          "aa77fcdc34503ff23ef7f89398ad09ce64e0543e3d5ac60c96393a654c53fe58": 0.00158947
        },
        "htlcsUnpublished": 0.00160016
      },
      "remoteCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "mutualCloseBalance": {
        "toLocal": {}
      },
      "unknownCloseBalance": {
        "toLocal": 0,
        "htlcs": 0
      }
    },
    "waitForPublishFutureCommitment": 0
  }
}

$ ./eclair-cli globalbalance
{
  "total": 0.13922508,
  "onChain": {
    "confirmed": 0.00672252,
    "unconfirmed": 0
  },
  "offChain": {
    "waitForFundingConfirmed": 0,
    "waitForFundingLocked": 0,
    "normal": {
      "toLocal": 0.13250256,
      "htlcs": 0
    },
    "shutdown": {
      "toLocal": 0,
      "htlcs": 0
    },
    "negotiating": 0,
    "closing": {
      "localCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "remoteCloseBalance": {
        "toLocal": {},
        "htlcs": {},
        "htlcsUnpublished": 0
      },
      "mutualCloseBalance": {
        "toLocal": {}
      },
      "unknownCloseBalance": {
        "toLocal": 0,
        "htlcs": 0
      }
    },
    "waitForPublishFutureCommitment": 0
  }
}

[pm47]

Got it, let's follow up in the thread above.