Core-Lightning and Eclair interoperability: Channel is not closing

[evd0kim]

I have two instances of strange behavior:

1. Mainnet issue. Channel between Eclair and CLightning is in closing state for month or so. The closing was started due to fee mismatch and this is known interoperability issue. The concern of this report is why channel is in closing state for one month. What I see from logs:

2022-08-03 07:06:23,528 ERROR f.a.e.c.TransportHandler CON n:020fc7e62c9956a34bcdba309a4809ccfd7adcae4b8b644cac81b4dc58d43a2479 - cannot deserialize ByteVector(53 bytes, 0xa4657b2276657273696f6e223a302c22617373657473223a5b22627463225d2c22706565725f616c6c6f776564223a66616c73657d): message: cannot acquire 252176 bits from a vector that contains 392 bits

2. Testnet issue. I tried to open a channel from my Simple Bitcoin Wallen which uses some Eclair code but mostly works on Immortan library. The channel was in pending state even some other channel I've opened simultaneously but with Eclair, successfully opened. I tried to close it from CLN and now CLN shows CHANNELD_SHUTTING_DOWN but funds aren't moving anywhere. I couldn't retrieve logs from SBW but it looks like I observe similar behavior as reported with Eclair mainnet node.

This is a debug-level output from CLN

2022-08-04T07:56:24.962Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-connectd: Connect IN
2022-08-04T07:56:24.962Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-connectd: peer_out WIRE_INIT
2022-08-04T07:56:25.105Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-connectd: peer_in WIRE_INIT
2022-08-04T07:56:25.130Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-chan#16: Peer has reconnected, state CHANNELD_SHUTTING_DOWN: telling connectd to make active
2022-08-04T07:56:25.134Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-connectd: Handed peer, entering loop
2022-08-04T07:56:25.137Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: pid 365247, msgfd 50
2022-08-04T07:56:25.137Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-chan#16: Waiting for funding confirmations
2022-08-04T07:56:25.137Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-chan#16: Ignoring fee limits!
2022-08-04T07:56:25.137Z DEBUG   hsmd: new_client: 16
2022-08-04T07:56:25.139Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: option_static_remotekey = 1, option_anchor_outputs = 0
2022-08-04T07:56:25.139Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: init REMOTE: remote_per_commit = 03a81497edcd9fd91379ea257e7d5ef5009ff6f3d98e0517fa0ea45e9128bb59e9, old_remote_per_commit = 0295966eea998009a9d9dd2a0be8f678eecca0188f071cd877f8d2bbd6bb2aa18d next_idx_local = 1 next_idx_remote = 1 revocations_received = 0 feerates { RCVD_ADD_ACK_REVOCATION:1000 } range 253-4294967295 blockheights { RCVD_ADD_ACK_REVOCATION:0 }, our current 2280895
2022-08-04T07:56:25.139Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-08-04T07:56:25.139Z DEBUG   hsmd: Client: Received message 18 from client
2022-08-04T07:56:25.140Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-08-04T07:56:25.140Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: peer_out WIRE_CHANNEL_REESTABLISH
2022-08-04T07:56:25.140Z DEBUG   hsmd: Client: Received message 18 from client
2022-08-04T07:56:25.140Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: billboard: Sent reestablish, waiting for theirs
2022-08-04T07:56:25.196Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: peer_in WIRE_CHANNEL_REESTABLISH
2022-08-04T07:56:25.197Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: Got reestablish commit=1 revoke=0
2022-08-04T07:56:25.197Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: next_revocation_number = 0
2022-08-04T07:56:25.197Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: option_static_remotekey: fields are correct
2022-08-04T07:56:25.197Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: peer_out WIRE_SHUTDOWN
2022-08-04T07:56:25.197Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: billboard: They've confirmed funding, we haven't yet. They've sent shutdown, waiting for ours
2022-08-04T07:56:25.197Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: billboard perm: Reconnected, and reestablished.
2022-08-04T07:56:25.197Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: billboard: They've confirmed funding, we haven't yet. They've sent shutdown, waiting for ours
2022-08-04T07:56:25.207Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: Can't send commit: final shutdown phase
2022-08-04T07:56:25.221Z DEBUG   lightningd: Adding block 2280896: 00000000000000a9a96eb34c93e8070a6e76c08f58df77a18eef729b6faedcf8
2022-08-04T07:56:25.295Z DEBUG   0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813-channeld-chan#16: peer_in WIRE_FUNDING_LOCKED

I do not uderstand what CLN actually tries to do since I see this output while command is being hanged in other terminal window.

clg-cli close 0226bf21845783173ec66fd44a5e6c73d4279b1207f59ad314d2f130a8c9128813

[rustyrussell]

OK, first, our message is backwards: "We've send shutdown, waiting for theirs" (which, shown above, they never send!).

Now I can't see from their error message what message they're upset about. But we can probably figure it out if you do "log-level:io" (This will produce a lot of output, but we can see what we send that might contain "a4657b2276657273696f6e223a302c22617373657473223a5b22627463225d2c22706565725f616c6c6f776564223a66616c73657d"...