Lost UTXO (P2WKH) after (concurrent?) unilateral close and not claimed by c-lightning

my channel partner used eclair mobile and created a channel with me and paid an invoice which I have created. After a couple of days and a peer connection loss both sides unilaterally closed the channel. My channel partner seemed to be successful. However I cannot redeem my output (P2WKH) from his confirmed commitment transaction (though it should not be time locked) also even stranger my node directly was able to claim his funds (P2WSH).

Question: How can I look at the sqlite db (or my logs) to see which derivation of my key should be used in order to spend the "lost" UTOX.

My lightning node:

 036f464b54416ea583dcfae3872d28516dbe85414ed838513b1c34fb3a4aee4e7a@144.76.235.20:9735

I created an invoice which was paid (json):

{
      "label": "bitcoitechweekly2nd", 
      "bolt11": "lnbc4543210n1pdnlydqpp5u69x06u7d09slyjg69kdnx4xgm346ghgmmect8y0z5z4g5aeuedsdp4va6k2um5g9e8g6trd3j57mjvd9nksarwd9hxwnn9w3mk7unt235hqxqy2ljqcqpgsu9n53xcfsl95t2yxkh00np8rasxn6cfzkjf7lljnw9drwkxj47pzl9ml5uk7ypav20n8y8p8r26x38zmdewdrvc7zjdr3yazklksyqp64p4sq", 
      "payment_hash": "e68a67eb9e6bcb0f9248d16cd99aa646e35d22e8def3859c8f15055453b9e65b", 
      "msatoshi": 454321000, 
      "status": "paid", 
      "pay_index": 9, 
      "msatoshi_received": 454321000, 
      "paid_timestamp": 1530902807, 
      "paid_at": 1530902807, 
      "expiry_time": 1531252704, 
      "expires_at": 1531252704
    },

The channel partner created a channel with a founding of 500000 satoshi and paid the invoice. Before the channel closed the channel balance according to c-lighting looked like this:

  {
      "peer_id": "038c04b4c0dcaa2d315a452309f3251d271c5c7d7b08ec7070de355a0fc8dae4fa",
      "short_channel_id": "530765:2414:0",
      "channel_sat": 454321,
      "channel_total_sat": 500000,
      "funding_txid": "3a5cb1352889e405f27074151dd9641a6d6c5944d21546cf19f805e0420dffae"
    }

this is also reflected by the funding transaction (c.f.: https://www.smartbit.com.au/tx/3a5cb1352889e405f27074151dd9641a6d6c5944d21546cf19f805e0420dffae ) which was successfully spend by some commitment transaction: (c.f.: https://www.smartbit.com.au/tx/9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281 )

as you can see 9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281[0] was a pay 2 script hash (I assume with the time lock). Wich lets me assume that my channel partner was broadcasting his commitment transaction. My node was able to spend it (though it was the balance of my channel partner) but this is also written on the blockchain: (c.f.: https://www.smartbit.com.au/tx/03cfab7b726281065bacdefd1d750be218e1601dd1819972b44ea332da1940c8 ) and is reflected by listfunds:

 "outputs": [
    {
      "txid": "03cfab7b726281065bacdefd1d750be218e1601dd1819972b44ea332da1940c8", 
      "output": 0, 
      "value": 43798, 
      "address": "bc1qlz7cnvdyp92hzgvh68ud50j4tyh0mxwqrqpd8m", 
      "status": "confirmed"
    }
  ]

How ever there is 9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281[1] which according to the tx is an UTXO. I should have some key within my c-lightning client to be able to spent it. My node has not spend and redeemed the output yet.

I guess the problem is a concurrency problem: It seems that my channel partner and I both tried to unilaterally close the channel. So instead of redeeming the output from my channel partners commitment transaction my node tries to unsuccessfully broadcast his own commitment tx all the time (which can't be mined since the funding tx was successfully broadcased by my channel partner and mined):

02000000000101aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a0000000000e6090280024fab000000000000160014fa153649a345ec325daf7c62185494060dd77dc2b1ee0600000000002200204c61a0be9bfe850f28827d5d1e253f4a2a2998b1b9ae69c4bcaa3fb9b10868bc040047304402203c98efe3b9f7b24774385da5d7bf2982fe57ee24f56a0ad2f4d18dbfbc24416d0220423771f429065ccf2f0145c9eb010e962ec99e8532a468db90b5840fdc5d82e501483045022100dc8c33c09966b960391061065e02de268e9b767325d02a6dd2dda76b309ebf2b022033b1cde9f01874955b3384c0e78f126eb34983e83f6bf895e965f50f456c782101475221038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a9922103eef1d5811f6696f165a220370123d5ab0473de68e5222ddff6619c6392e0bc2d52aeaa177a20

which encodes to:

{
    "addresses": [], 
    "block_height": -1, 
    "block_index": -1, 
    "confirmations": 0, 
    "double_spend": false, 
    "fees": 1824, 
    "hash": "3eab5b9aa745cc49a9ff5200300486b42395230da9067d2948b58b7d25063a1f", 
    "inputs": [
        {
            "age": 530765, 
            "output_index": 0, 
            "output_value": 500000, 
            "prev_hash": "3a5cb1352889e405f27074151dd9641a6d6c5944d21546cf19f805e0420dffae", 
            "script_type": "pay-to-witness-script-hash", 
            "sequence": 2147617254, 
            "witness": [
                "", 
                "304402203c98efe3b9f7b24774385da5d7bf2982fe57ee24f56a0ad2f4d18dbfbc24416d0220423771f429065ccf2f0145c9eb010e962ec99e8532a468db90b5840fdc5d82e501", 
                "3045022100dc8c33c09966b960391061065e02de268e9b767325d02a6dd2dda76b309ebf2b022033b1cde9f01874955b3384c0e78f126eb34983e83f6bf895e965f50f456c782101", 
                "5221038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a9922103eef1d5811f6696f165a220370123d5ab0473de68e5222ddff6619c6392e0bc2d52ae"
            ]
        }
    ], 
    "lock_time": 544872362, 
    "opt_in_rbf": true, 
    "outputs": [
        {
            "addresses": null, 
            "script": "0014fa153649a345ec325daf7c62185494060dd77dc2", 
            "script_type": "pay-to-witness-pubkey-hash", 
            "value": 43855
        }, 
        {
            "addresses": null, 
            "script": "00204c61a0be9bfe850f28827d5d1e253f4a2a2998b1b9ae69c4bcaa3fb9b10868bc", 
            "script_type": "pay-to-witness-script-hash", 
            "value": 454321
        }
    ], 
    "preference": "medium", 
    "received": "2018-07-23T17:05:41.977939608Z", 
    "relayed_by": "54.81.11.238", 
    "size": 125, 
    "total": 498176, 
    "ver": 2, 
    "vin_sz": 1, 
    "vout_sz": 2
}

3 thoughts:

c-lightning would need an api such that I can chase down the key derivation for that particular output of the confirmed tx so that I can redeem my funds.
the channeld should probably have a way of fixing such a problem on its own if it unsuccessfully broadcasts his own commitment transaction. Apparently c-lightning does not even have an idea that it could redeem the funds (I guess it still wants to broadcast his own commitment tx (though it stoped trying by now)
I really don't get what went wrong so that I got the funds from my channel partner.

further debugging output:

git log 
commit 27a186be9ca0e552472041c71b012a7ef57c53fb 
...
./lightningd --network=bitcoin --max-locktime-blocks=600
lightning_channeld: channeld/channel.c:1701: resend_commitment: Assertion `peer->revocations_received == peer->next_index[REMOTE] - 2' failed.
lightning_channeld: Fatal signal 6
0x557d6b12f743 crashdump
        common/daemon.c:37
0x7f0a2b9d4f1f ???
        ???:0
0x7f0a2b9d4e97 ???
        ???:0
0x7f0a2b9d6800 ???
        ???:0
0x7f0a2b9c6399 ???
        ???:0
0x7f0a2b9c6411 ???
        ???:0
0x557d6b122566 resend_commitment
        channeld/channel.c:1701
0x557d6b1229fa peer_reconnect
        channeld/channel.c:1852
0x557d6b124502 init_channel
        channeld/channel.c:2509
0x557d6b124820 main
        channeld/channel.c:2570
0x7f0a2b9b7b96 ???
        ???:0
0x557d6b11d7d9 ???
        ???:0
0xffffffffffffffff ???
        ???:0

2018-07-16T16:38:17.011Z lightningd(17680): 038c04b4c0dcaa2d315a452309f3251d271c5c7d7b08ec7070de355a0fc8dae4fa chan #5: Peer permanent failure in CHANNELD_NORMAL: Funding transaction spent
2018-07-16T16:38:17.011Z lightningd(17680):      (tx 3eab5b9aa745cc49a9ff5200300486b42395230da9067d2948b58b7d25063a1f)
2018-07-16T16:38:17.016Z lightningd(17680): 038c04b4c0dcaa2d315a452309f3251d271c5c7d7b08ec7070de355a0fc8dae4fa chan #5: State changed from CHANNELD_NORMAL to FUNDING_SPEND_SEEN
2018-07-16T16:38:17.406Z lightningd(17680): 038c04b4c0dcaa2d315a452309f3251d271c5c7d7b08ec7070de355a0fc8dae4fa chan #5: State changed from FUNDING_SPEND_SEEN to ONCHAIN
2018-07-16T16:38:17.478Z lightningd(17680): Broadcasting tx 02000000000101aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a0000000000e6090280024fab000000000000160014fa153649a345ec325daf7c62185494060dd77dc2b1ee0600000000002200204c61a0be9bfe850f28827d5d1e253f4a2a2998b1b9ae69c4bcaa3fb9b10868bc040047304402203c98efe3b9f7b24774385da5d7bf2982fe57ee24f56a0ad2f4d18dbfbc24416d0220423771f429065ccf2f0145c9eb010e962ec99e8532a468db90b5840fdc5d82e501483045022100dc8c33c09966b960391061065e02de268e9b767325d02a6dd2dda76b309ebf2b022033b1cde9f01874955b3384c0e78f126eb34983e83f6bf895e965f50f456c782101475221038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a9922103eef1d5811f6696f165a220370123d5ab0473de68e5222ddff6619c6392e0bc2d52aeaa177a20: 25 error code: -25?error message:?Missing inputs?

`getinfo` output (I tried updating to v 0.6 in order to claim my funds but that didn't change anything)

{
  "id": "036f464b54416ea583dcfae3872d28516dbe85414ed838513b1c34fb3a4aee4e7a", 
  "port": 9735, 
  "address": [
    {
      "type": "ipv4", 
      "address": "144.76.235.20", 
      "port": 9735
    }
  ], 
  "binding": [
    {
      "type": "ipv4", 
      "address": "144.76.235.20", 
      "port": 9735
    }
  ], 
  "version": "v0.6", 
  "blockheight": 533429, 
  "network": "bitcoin"
}

Hi, I'm the mentioned channel partner. Currently using Eclair 0.3.4 on Android for the channel.

It is currently shown as CLOSING state although I did not initiate the close.

Here the raw channel data from the app:

{
 "nodeId": "036f464b54416ea583dcfae3872d28516dbe85414ed838513b1c34fb3a4aee4e7a",
 "channelId": "aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a",
 "state": "CLOSING",
 "data": {
  "$type": "fr.acinq.eclair.channel.DATA_CLOSING",
  "commitments": {
   "localParams": {
    "nodeId": "038c04b4c0dcaa2d315a452309f3251d271c5c7d7b08ec7070de355a0fc8dae4fa",
    "channelKeyPath": "m/98372128'/1241141296'/1379694160'/2096523612",
    "dustLimitSatoshis": "546",
    "maxHtlcValueInFlightMsat": "1000000000",
    "channelReserveSatoshis": "5000",
    "htlcMinimumMsat": "1",
    "toSelfDelay": 144,
    "maxAcceptedHtlcs": 30,
    "isFunder": true,
    "defaultFinalScriptPubKey": "a914eacd75ee4e0474c6df552465a9fdcd9e087f7eb287",
    "globalFeatures": "",
    "localFeatures": "88"
   },
   "remoteParams": {
    "nodeId": "036f464b54416ea583dcfae3872d28516dbe85414ed838513b1c34fb3a4aee4e7a",
    "dustLimitSatoshis": "546",
    "maxHtlcValueInFlightMsat": "18446744073709551615",
    "channelReserveSatoshis": "5000",
    "htlcMinimumMsat": "0",
    "toSelfDelay": 144,
    "maxAcceptedHtlcs": 483,
    "fundingPubKey": "038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a992",
    "revocationBasepoint": "03c76ebbde5566613155191d565c1bb9fc86aff8726b07103de1706fcd9c90daae",
    "paymentBasepoint": "0296604e4d32f2c950aa4fe1c94371b2fdd634ff076975c51366d6777a766ca664",
    "delayedPaymentBasepoint": "0341ec8806fe42d0f46d1e76ff9f0a159c8bb5c8ccbe513021d074f1b1bb605e19",
    "htlcBasepoint": "0354afefb6b0fa566493f51d9ca66df578c46cf552c77ffeeedd7e36869f834813",
    "globalFeatures": "",
    "localFeatures": "08"
   },
   "channelFlags": 0,
   "localCommit": {
    "index": "2",
    "spec": {
     "htlcs": [

     ],
     "feeratePerKw": "1265",
     "toLocalMsat": "45679000",
     "toRemoteMsat": "454321000"
    },
    "publishableTxs": {
     "commitTx": {
      "$type": "fr.acinq.eclair.transactions.Transactions.CommitTx",
      "input": {
       "outPoint": "aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a:0",
       "txOut": {
        "amount": {
         "$type": "fr.acinq.bitcoin.Satoshi",
         "amount": "500000"
        },
        "publicKeyScript": "0020f3d3b319417a8158a7ad40d3d52564ca21adf1701527711993d450eae01dfee2"
       },
       "redeemScript": "5221038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a9922103eef1d5811f6696f165a220370123d5ab0473de68e5222ddff6619c6392e0bc2d52ae"
      },
      "tx": "02000000000101aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a0000000000e609028002dcae000000000000220020b1d10636603ea1705a167964472438e833dc953da434b368454f5e0c8da5d8ebb1ee0600000000001600149c28b5bf5eb5fe1a44aa6f7b286d28b3ee812c19040047304402201b2d556725c094a0a53edae92b72be6deb7f996aebfdccf4deebf253bbc7567d022060ec588f212f811e4022074df3665299a87e765f6eda3036fd8bdd369841d89901473044022076f7e2c799981cdaf448980a06c16a0c31f2a69038186f452b1bbf54ffc036040220410c996d0bb37e5620ae27672f5405d9894b9c5631c1d3308dc64349e07a2bf001475221038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a9922103eef1d5811f6696f165a220370123d5ab0473de68e5222ddff6619c6392e0bc2d52aeab177a20"
     },
     "htlcTxsAndSigs": [

     ]
    }
   },
   "remoteCommit": {
    "index": "2",
    "spec": {
     "htlcs": [

     ],
     "feeratePerKw": "1265",
     "toLocalMsat": "454321000",
     "toRemoteMsat": "45679000"
    },
    "txid": "3d8542806dd6da7b178d632e1fa82aed77cb71dc430ea994856642209cc16d80",
    "remotePerCommitmentPoint": "024a3a02d2c885b914955fd344bf21eb9b6372301468729b8c9d3fdf4b902df6b3"
   },
   "localChanges": {
    "proposed": [

    ],
    "signed": [

    ],
    "acked": [

    ]
   },
   "remoteChanges": {
    "proposed": [

    ],
    "acked": [

    ],
    "signed": [

    ]
   },
   "localNextHtlcId": "1",
   "remoteNextHtlcId": "0",
   "originChannels": [

   ],
   "remoteNextCommitInfo": [
    1,
    "03dae3f5d68cb8d2afb4b31154c1f034679e7d7e6a451725333ec5ecd55a7cda17"
   ],
   "commitInput": {
    "outPoint": "aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a:0",
    "txOut": {
     "amount": {
      "$type": "fr.acinq.bitcoin.Satoshi",
      "amount": "500000"
     },
     "publicKeyScript": "0020f3d3b319417a8158a7ad40d3d52564ca21adf1701527711993d450eae01dfee2"
    },
    "redeemScript": "5221038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a9922103eef1d5811f6696f165a220370123d5ab0473de68e5222ddff6619c6392e0bc2d52ae"
   },
   "remotePerCommitmentSecrets": {
    "knownHashes": [
     [
      "-1",
      "1467d4f74418e0ce247b35c65dd0f0f845344e8f9cd5375e10cf6d9561bc0bbe"
     ]
    ],
    "lastIndex": [
     "281474976710654"
    ]
   },
   "channelId": "aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a"
  },
  "mutualCloseProposed": [

  ],
  "localCommitPublished": [
   {
    "commitTx": "02000000000101aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a0000000000e609028002dcae000000000000220020b1d10636603ea1705a167964472438e833dc953da434b368454f5e0c8da5d8ebb1ee0600000000001600149c28b5bf5eb5fe1a44aa6f7b286d28b3ee812c19040047304402201b2d556725c094a0a53edae92b72be6deb7f996aebfdccf4deebf253bbc7567d022060ec588f212f811e4022074df3665299a87e765f6eda3036fd8bdd369841d89901473044022076f7e2c799981cdaf448980a06c16a0c31f2a69038186f452b1bbf54ffc036040220410c996d0bb37e5620ae27672f5405d9894b9c5631c1d3308dc64349e07a2bf001475221038fa2fa7dca344bf44ccff0642a357731222895078c7c4ec7ddc2cf772585a9922103eef1d5811f6696f165a220370123d5ab0473de68e5222ddff6619c6392e0bc2d52aeab177a20",
    "claimMainDelayedOutputTx": [
     "0200000000010181d250990e76d84235736bead96bffa7fa48de994907b9b5ed8a6d5daaae0099000000000090000000016ead00000000000017a914eacd75ee4e0474c6df552465a9fdcd9e087f7eb28703483045022100813f5161d82cbf2fdafbe50f1fac3e8f0ba442a6f2a36650eefa757c333dbfe302207b13de22952e692a16b99c4f0b1882b63f74200a94eb8dd45f9e69b63c8e66d201004d6321022e46ab68549a0519359a37e667a1350ee3f4592d7999ab9057e5195b5667f36967029000b27521036452e7246ada4874c540e111e7fbb9042970a0d32c95e3e851e1db5f50ebe59668ac00000000"
    ],
    "htlcSuccessTxs": [

    ],
    "htlcTimeoutTxs": [

    ],
    "claimHtlcDelayedTxs": [

    ],
    "irrevocablySpent": [
     [
      "aeff0d42e005f819cf4615d244596c6d1a64d91d157470f205e4892835b15c3a:0",
      "9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281"
     ]
    ]
   }
  ]
 }
}

Here is what I don't get:

The c-lightning node detects 9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281:0 as its own, and seems to have swept it back into its wallet via 03cfab7b726281065bacdefd1d750be218e1601dd1819972b44ea332da1940c8
The 9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281:1 which has the balance matching the invoice, and the amount both clients believe is owned by c-lightning is not recognized by the c-lightning node (there is a chance this is due to it residing on a their_unilateral/to_us output which mixes in the commitment point

So @sp4ke, does you node claim to own any of the unspent outputs (03cfab7b726281065bacdefd1d750be218e1601dd1819972b44ea332da1940c8:0 or 9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281:1).

@renepickhardt we can probably figure out what key was used for that output, but we might need to do that manually. Also does your node crash upon restart? If not what's the peer's status? Is it being detected as spent?

the node starts perfectly (also after updating to c-lightning 0.6). list peers does not list the node of @sp4ke. also listfunds does not mention any open / active channel with @sp4ke. So it seems like c-lightning thinks the channel is gone. As mentioned I started reading channel.c (in channeld folder) also I am aware of BOLT3 key derivations. However until yesterday (when I tried chasing that bug) I was only blackboxing the process behind HD key derivation. So for me it would actually be a really good exercise doing this manually. (I have some python code available to start from my hsm_secret). Don't know if you have the time to do it together. Would obviously be a great learning opportunity for me. Doing it alone at this moment I am still lost. But this might change over the next couple days while reading more code / docs / specs.

Do I understand correctly that we would need to look at https://github.com/ElementsProject/lightning/blob/f8fa4213f1721f3c5e1e0bd027fb7153d60986e5/channeld/channel.c#L2485 (within init_channel since this is where the derivation of the commitment point takes place) or is the problem rather that the code gets never called as the peer seems to not exist anymore (this would make sense) since the node stoped broadcasting its own commitment transaction after some while

Eclair broadcast an old commitment transaction, and you stole the funds. You can see that c-lightning is trying to send commitment tx with locktime 544872362 and the one on-chain is 544872363

The real bug is that c-lightning should consider itself to own the other output, too, in this case. Indeed, that is missing...

Eclair broadcast an old commitment transaction, and you stole the funds. You can see that c-lightning is trying to send commitment tx with locktime 544872362 and the one on-chain is 544872363

The real bug is that c-lightning should consider itself to own the other output, too, in this case. Indeed, that is missing...

So we have an official cross-implementation cheat attempt? Nice :+1:

We need to recover the remote_commitment_point and should be able to recover those funds then :-)

@cdecker I don't think my node claims any of the unspent outputs you mention. The app shows the LN payment on the channel as PAID and the node doesn't own that amount anymore. I can't see more details on the android app than the raw channel data I already shared.

Might be interesting to get @pm47's and @sstone's view of the issue. Can a cheat attempt ever happen in normal circumstances?

Might be interesting to get @pm47's and @sstone's view of the issue.

I've got the same analysis as Rusty, eclair has published what it thinks was its latest commitment (9900aeaa5d6d8aedb5b9074999de48faa7ff6bd9ea6b733542d8760e9950d281), but it was in fact an old one, and one block later c-lightning was able to sweep eclair's main output.

Can a cheat attempt ever happen in normal circumstances?

No, we don't store revoked commitments, in order to avoid that very scenario. If @sp4ke was using eclair desktop I would have suspected he had restarted from an old backup, but that can't happen on eclair mobile, which has a protected datadir. That's a tough one! @sp4ke do you remember having done something particular with your phone around that time? Like a major OS upgrade, backup, something like that?

ElementsProject / lightning