Unexpected message WIRE_ANNOUNCEMENT_SIGNATURES when connecting to LND

[Rav3nPL]

Running two LN nodes - c-lignning and lnd.
When trying to connect them, connection is dropped.

2019-10-22T13:42:15.189Z **BROKEN** lightningd(12751): lightning_openingd-028c2f98b483bccf9e2634d6d5dca5cc6606ed6afd17d209da1a95f4b138d11a87 chan #7681: Unexpected message WIRE_ANNOUNCEMENT_SIGNATURES
2019-10-22T13:42:15.189Z INFO lightningd(12751): lightning_openingd-028c2f98b483bccf9e2634d6d5dca5cc6606ed6afd17d209da1a95f4b138d11a87 chan #7681: Peer connection lost
2019-10-22T13:42:15.190Z INFO lightningd(12751): 028c2f98b483bccf9e2634d6d5dca5cc6606ed6afd17d209da1a95f4b138d11a87 chan #7681: Owning subdaemon lightning_openingd died (62208)

[Rav3nPL]

Also reported on lnd side
lightningnetwork/lnd#3623

[niftynei]

@Rav3nPL can you paste the output from lightning-cli getinfo? Looking specifically for your node version

[Rav3nPL]

lightning-cli getinfo
{
   "id": "031e8f3e16f06f78249497161f23fa50b3218c7a15c895149459942836ffc53f6c",
   "alias": "Rav3n_PL",
   "color": "031e8f",
   "num_peers": 4,
   "num_pending_channels": 0,
   "num_active_channels": 3,
   "num_inactive_channels": 0,
   "address": [
      {
         "type": "ipv4",
         "address": "51.68.251.200",
         "port": 9735
      }
   ],
   "binding": [
      {
         "type": "ipv6",
         "address": "::",
         "port": 9735
      },
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 9735
      }
   ],
   "version": "v0.7.3rc3",
   "blockheight": 600539,
   "network": "bitcoin",
   "msatoshi_fees_collected": 2000,
   "fees_collected_msat": "2000msat"
}

 lncli getinfo
{
        "version": "0.8.0-beta commit=v0.8.0-beta-20-g21a40daf5840a856240866fff49e8c07dac7283c",
        "identity_pubkey": "028c2f98b483bccf9e2634d6d5dca5cc6606ed6afd17d209da1a95f4b138d11a87",
        "alias": "Rav3n_PL",
        "color": "#3399ff",
        "num_pending_channels": 0,
        "num_active_channels": 12,
        "num_inactive_channels": 2,
        "num_peers": 13,
        "block_height": 600539,
        "block_hash": "00000000000000000005f64e1ba65775c0d17546df65aa2f39d35988f2e051c9",
        "best_header_timestamp": 1571753088,
        "synced_to_chain": true,
        "synced_to_graph": true,
        "testnet": false,
        "chains": [
                {
                        "chain": "bitcoin",
                        "network": "mainnet"
                }
        ],
        "uris": [
                "028c2f98b483bccf9e2634d6d5dca5cc6606ed6afd17d209da1a95f4b138d11a87@51.68.251.200:9736"
        ]
}

[wpaulino]

lnd sends announcement signatures for channels with 6 confs that need to be advertised upon reconnections until it receive the remote's.

[jooray]

This is happening to me as well. Willing to debug it, I am admin of both sides (lnd and clightning).

  {
     "type": "BROKEN",
     "time": "773.825736853",
     "node_id": "XXXXXXXXXXXXX",
     "source": "openingd-chan#5175",
     "log": "Unexpected message WIRE_ANNOUNCEMENT_SIGNATURES"
  },
  {
     "type": "INFO",
     "time": "773.825847754",
     "node_id": "XXXXXXXXXXXXX",
     "source": "openingd-chan#5175",
     "log": "Peer connection lost"
  },
  {
     "type": "INFO",
     "time": "773.825894751",
     "node_id": "XXXXXXXXXXXXX",
     "source": "chan#5175",
     "log": "Owning subdaemon openingd died (62208)"
  },

Version 0.9.3

[jooray]

lnd side (0.12.1-beta):

2021-05-13 23:28:16.362 [INF] SRVR: New inbound connection from XXXXXXXXXXXXXXX                                 [5/4534]
2021-05-13 23:28:16.362 [INF] SRVR: Finalizing connection to XXXXXX, inbound=true
2021-05-13 23:28:16.365 [INF] PEER: NodeKey(XXXXXX) loading Chan
nelPoint(XXXXXX:1)
2021-05-13 23:28:16.365 [INF] HSWC: ChannelLink(678713:644:1): starting
2021-05-13 23:28:16.365 [INF] HSWC: Trimming open circuits for chan_id=678713:644:1, start_htlc_id=0
2021-05-13 23:28:16.365 [INF] HSWC: Adding live link chan_id=4b087f7e2a6b0032d549855f11ecc51e54c55216c1be0f0d621b1f47ece05b2
6, short_chan_id=678713:644:1
2021-05-13 23:28:16.365 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(XXXXXX:1)
2021-05-13 23:28:16.365 [INF] HSWC: ChannelLink(678713:644:1): HTLC manager started, bandwidth=2641778000 mSAT
2021-05-13 23:28:16.365 [INF] HSWC: ChannelLink(678713:644:1): attempting to re-resynchronize
2021-05-13 23:28:16.365 [INF] PEER: Negotiated chan series queries with XXXXXX
2021-05-13 23:28:16.365 [INF] DISC: Creating new GossipSyncer for peer=XXXXXX

2021-05-13 23:28:16.381 [INF] PEER: unable to read message from XXXXXX: EOF

2021-05-13 23:28:16.381 [INF] PEER: disconnecting XXXXXX reason: read handler closed
2021-05-13 23:28:16.589 [INF] DISC: Removing GossipSyncer for peer=XXXXXX
2021-05-13 23:28:16.589 [INF] HSWC: Removing channel link with ChannelID(XXXXXX)
2021-05-13 23:28:16.589 [INF] HSWC: ChannelLink(678713:644:1): stopping
2021-05-13 23:28:16.589 [WRN] HSWC: ChannelLink(678713:644:1): error when syncing channel states: link shutting down
2021-05-13 23:28:16.589 [INF] HSWC: ChannelLink(678713:644:1): exited

Seems lnd just sees that peer closed connection.

[jooray]

This is still happening. There are two lnd nodes that I used to have channels with and the channels are both offline because of this error. One of them is my node.

0.13.1-beta on lnd side and clightning 0.10.1

[cdecker]

Yep, the specification is very clear that the announcement sig MUST be preceded by the corresponding channel_reestablish message. lnd seems to be using multiple unsynchronized goroutines to handle different aspects of the peer communication which means they may send the messages in the wrong order.

We're discussing whether it makes sense to relax the ordering or whether lnd should adhere to the specified order (which we expect in c-lightining).