channel stuck in CLOSINGD_SIGEXCHANGE

[fixone]

I think that this is a problem, given that the channel state doesn't seem to change, but also, more importantly, that the funding tx is intact (e749d06a404debfbb223d89b71b6b14d793a19f572ec89f389267c1a723f9388)

current version is 0eff28c (but at the closing channel initiation it was a different version, if that is important)

The last few lines pertaining this peer (03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d) are below, but more info is available at https://gist.github.com/fixone/b33378808477b03c80d0a038f0c2c950#file-peer-log-txt

2018-04-16T10:04:19.128Z lightningd(17699): 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: Funding tx e749d06a404debfbb223d89b71b6b14d793a19f572ec89f389267c1a723f9388 depth 248 of 3
2018-04-16T10:04:19.128Z lightningd(17699): 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: Funding tx confirmed, but channel state CLOSINGD_SIGEXCHANGE unowned
2018-04-16T10:04:19.128Z lightningd(17699): 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: Funding tx announce ready, but channel state CLOSINGD_SIGEXCHANGE owned by none
2018-04-16T10:06:19.030Z lightning_gossipd(17708): Failed connected out for 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d, will try again
2018-04-16T10:08:31.253Z lightning_gossipd(17708): Failed connected out for 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d, will try again
2018-04-16T10:08:36.316Z lightning_gossipd(17708): Connected out for 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d
2018-04-16T10:08:36.424Z lightningd(17699): 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: Peer has reconnected, state CLOSINGD_SIGEXCHANGE
2018-04-16T10:08:36.435Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: pid 21017, msgfd 24
2018-04-16T10:08:36.503Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: satoshi_out = 1000000/0
2018-04-16T10:08:36.504Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: dustlimit = 546
2018-04-16T10:08:36.504Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: fee = 183
2018-04-16T10:08:36.504Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: peer_out WIRE_CHANNEL_REESTABLISH
2018-04-16T10:08:36.554Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: peer_in WIRE_CHANNEL_REESTABLISH
2018-04-16T10:08:36.554Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: Got reestablish commit=7 revoke=6
2018-04-16T10:08:36.554Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: Making close tx at = 1000000/0 fee 183
2018-04-16T10:08:36.554Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: sending fee offer 183
2018-04-16T10:08:36.554Z lightningd(17699): lightning_closingd-03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d chan #13: peer_out WIRE_CLOSING_SIGNED
2018-04-16T10:08:55.188Z lightning_gossipd(17708): Received node_announcement for node 03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d

[ZmnSCPxj]

Your indicated version includes #1362, which fixes a bug in closing negotiation order, but assuming the other side is a pre-#1362 c-lightning node, it should still respond at least once to the WIRE_CLOSING_SIGNED we sent.

c-lightning seems to be doing the correct thing for this case (i.e. sending a closing_signed message after reestablish), do you control the other side of the channel?

Some info gleaned from the logs:

1. We are the funder of the channel.
2. We only received closing_signed once, ever, right after shutting down the channel. Then the logs end after that. We should have sent another closing_signed after that but bug send closing_signed twice #1361 meant we waited; presumably that is the point where you forced the node to shut down.

Looking at the logs, there are gaps where there are no activity with the peer and then we reconnect with them, did you shut down the local c-lightning at those points or did the peer go down?

We need to identify the node software on the other side and find out what happened on that side; after shutdown the channel being unuseable should have been persisted by the other side and it should now expect a closing_signed on reestablish.

[fixone]

This particular lightningd is running on my laptop - that's why it keeps going online and offline (I do have others instances running on proper servers that are mostly online). I don't control the peer / other end of the channel.
Also the log I provided is missing a lot of WIRE_PING and WIRE_PONG, other than that all the communication with that peer should be there

[cdecker]

It appears the other side is using lnd, hopefully not a regression.

[fixone]

Unchanged situation here as well

      "id": "03d3f875b88f083dd4d1d5af4bcd5483d7bf0303ec1f585879e2a1012961ec9a9d", 
      "connected": true, 
      "netaddr": [
        "212.47.234.226:9735"
      ], 
      "alias": "GRIZ [LND]", 
      "color": "68f442", 
      "channels": [
        {
          "state": "CLOSINGD_SIGEXCHANGE", 
          "owner": "lightning_closingd", 
          "short_channel_id": "1292865:112:0", 
          "channel_id": "88933f721a7c2689f389ec72f5193a794db1b6719bd823b2fbeb4d406ad049e7", 
          "funding_txid": "e749d06a404debfbb223d89b71b6b14d793a19f572ec89f389267c1a723f9388", 
          "msatoshi_to_us": 1000000000, 
          "msatoshi_to_us_min": 1000000000, 
          "msatoshi_to_us_max": 1000000000, 
          "msatoshi_total": 1000000000, 
          "dust_limit_satoshis": 546, 
          "max_htlc_value_in_flight_msat": 18446744073709551615, 
          "their_channel_reserve_satoshis": 0, 
          "our_channel_reserve_satoshis": 10000, 
          "channel_reserve_satoshis": 0, 
          "spendable_msatoshi": 990000000, 
          "htlc_minimum_msat": 0, 
          "their_to_self_delay": 6, 
 "our_to_self_delay": 144, 
          "to_self_delay": 6, 
          "max_accepted_htlcs": 483, 
          "status": [
            "CLOSINGD_SIGEXCHANGE:Negotiating closing fee between 183 and 183 satoshi (ideal 183)", 
            "CLOSINGD_SIGEXCHANGE:Waiting for their initial closing fee offer: ours was 183 satoshi"
          ], 
          "in_payments_offered": 0, 
          "in_msatoshi_offered": 0, 
          "in_payments_fulfilled": 0, 
          "in_msatoshi_fulfilled": 0, 
          "out_payments_offered": 0, 
          "out_msatoshi_offered": 0, 
          "out_payments_fulfilled": 0, 
          "out_msatoshi_fulfilled": 0
        }
      ]
    }, 

with current node version

{
  "id": "02bbca52b1719110792b5dcbf50fd113a34ecb53e31980b6ec04f6ac32226b41a8", 
  "port": 9735, 
  "address": [
  ], 
  "version": "v0.5.2-2016-11-21-2610-g91d149b", 
  "blockheight": 1294945, 
  "network": "testnet"
}

[2600box]

@fixone did this ever resolve? i am in the same position after several days

[fixone]

Edit: Nope, it's still there, was looking at a filtered view
With one of the latest commits the channel that was stuck in SIGEXCHANGE for 3+months cleared