[bug]: `fundchannel` command hangs due to missing grouped-asset support

[Liongrass]

Background

I'm running litd in integrated mode, tapd is set to commit 76ec8ac232e1076ff2564928ec3700c72fafd267 on Bitcoin testnet3.

I have recently created a new grouped asset with the command:

tapcli --tlscertpath ~/.lit/tls.cert --rpcserver=localhost:8443 --network=testnet assets mint --type normal --name neo2oin --supply 100000 --meta_bytes 66616e746173746963206d6f6e6579 --new_grouped_asset

I then finalized the batch with:

tapcli --tlscertpath ~/.lit/tls.cert --rpcserver=localhost:8443 --network=testnet assets mint finalize

I then tried to open a channel to another node:

litcli --network=testnet --macaroonpath=~/.lnd/data/chain/bitcoin/testnet/admin.macaroon ln fundchannel --node_key 03e347d089c071c27680e26299223e80a740cf3e3fc4b4237fa219bb67121a670b --sat_per_vbyte 101 --asset_amount 1000 --asset_id 9ce3596b3c88cf41bff26e1931cbc85d17ee19484f5e3e34357c1951d6831814

The ln fundchannel command just hangs. I have attached logs and an LND profile below.

goprofile.txt 2024-06-12_open channel hangs.txt

[jharveyb]

Looks like you hang waiting for funding ACK? It's the last log line from TCHN subsystem.

151:2024-06-12 06:54:01.313 [INF] TCHN: Waiting for funding ack...

Do you have logs from the other node as well?

[HannahMR]

Attached are the logs from my litd testnet node from a time period when Leo made an attempt to open a channel to me.

The logs are from 2024-06-13 15:51:31 UTC to 2024-06-13 15:55:58 UTC
Error logs.txt

[GeorgeTsagk]

Attached are the logs from my litd testnet node from a time period when Leo made an attempt to open a channel to me.

The logs are from 2024-06-13 15:51:31 UTC to 2024-06-13 15:55:58 UTC Error logs.txt

weird, couldn't find any funding related logs in your logs, are you sure the snapshot window is right?

You should be seeing at least some TCHN sub-system logs, which is the channel funding logic in tapd

[dstadulis]

weird, couldn't find any funding related logs in your logs

Leo is the initiator (and would be performing funding) Hannah would be accepting the channel

[HannahMR]

Right, my logs are from when Leo was opening a channel to me.

I can attempt to open a channel to Leo and send those logs if that would be helpful.

[dstadulis]

Current theory is that the failure is due to the asset being a group key

[Roasbeef]

Main action item here: refactor the existing itest in tapd to use a grouped asset.

[Liongrass]

I'm on litd 980ee938aa1e7a45633216aff8775ca8d05c12aa now, using the 0-19-staging branch. I have modified go.mod to be on tapd v0.3.3-0.20240617174248-daf9676006b0.

I have a newly minted asset with group key 020d3ee08cadd6e34ab08f9b40d31ef05fc28b14e2bffd4810f35329317b4c9909 that I would like to use to open a channel. I execute litcli --network=testnet --macaroonpath=~/.lnd/data/chain/bitcoin/testnet/admin.macaroon ln fundchannel --node_key 03e347d089c071c27680e26299223e80a740cf3e3fc4b4237fa219bb67121a670b --sat_per_vbyte 101 --asset_amount 1000 --asset_id 9ce3596b3c88cf41bff26e1931cbc85d17ee19484f5e3e34357c1951d6831814

The command just hangs. I have attached my logs from the moment that I execute the litcli ln fundchannel command. 2024-06-20_open channel hangs.txt

[HannahMR]

I was the receiving node in Leo's attempt to open a channel with asset_id 9ce3596b3c88cf41bff26e1931cbc85d17ee19484f5e3e34357c1951d6831814. I am also running litd using the 0-19-staging branch.

Attached are the logs form the attempt. lndsecondJune20.log

[ffranr]

I'm on litd 980ee938aa1e7a45633216aff8775ca8d05c12aa now, using the 0-19-staging branch. I have modified go.mod to be on tapd v0.3.3-0.20240617174248-daf9676006b0.

I have a newly minted asset with group key 020d3ee08cadd6e34ab08f9b40d31ef05fc28b14e2bffd4810f35329317b4c9909 that I would like to use to open a channel. I execute litcli --network=testnet --macaroonpath=~/.lnd/data/chain/bitcoin/testnet/admin.macaroon ln fundchannel --node_key 03e347d089c071c27680e26299223e80a740cf3e3fc4b4237fa219bb67121a670b --sat_per_vbyte 101 --asset_amount 1000 --asset_id 9ce3596b3c88cf41bff26e1931cbc85d17ee19484f5e3e34357c1951d6831814

The command just hangs. I have attached my logs from the moment that I execute the litcli ln fundchannel command. 2024-06-20_open channel hangs.txt

@Liongrass @HannahMR the litd 0-19-staging branch has now been updated to use the latest tapd and relevant lnd branch. A bunch of fixes are included. go.mod shouldn't require modification. If possible please re-run your test.

[Liongrass]

We both upgraded to the latest commit in the 0-19-staging branch (fa32097a4d0deee7e84872690194d18f108cf5a5) but still ran into the same issue. We used the same grouped asset. I have attached my logs below.

2024-06-24_open channel hangs.txt

We'll try again with a non-grouped asset!

[HannahMR]

My logs from the latest attempt lndJune24Grouped.log

[Liongrass]

I minted a non-grouped asset with asset_id 50079900c674b425b40b10d142c86a3cb8e463411e8477998384995e7befe895, but I was unable to open a channel with it nonetheless.

In this case, both nodes were unable to sync to the universe with the command tapcli --tlscertpath ~/.lit/tls.cert --rpcserver=localhost:8443 --network=testnet universe sync --universe_host testnet.universe.lightning.finance:10029 --asset_id 50079900c674b425b40b10d142c86a3cb8e463411e8477998384995e7befe895 with the error 2024-06-24 18:07:20.623 [ERR] RPCS: [/universerpc.Universe/SyncUniverse]: unable to sync universe: unable to fetch roots for universe sync: missing universe id

Logs:

2024-06-24 18:07:20.196 [INF] LITD: Handling gRPC request: /universerpc.Universe/SyncUniverse
2024-06-24 18:07:20.204 [DBG] RPCS: [/universerpc.Universe/SyncUniverse] requested
2024-06-24 18:07:20.206 [INF] UNIV: Attempting to sync universe: host=testnet.universe.lightning.finance:10029, sync_type=issuance, ids=([]universe.Identifier) (len=1 cap=1) {
 (universe.Identifier) issuance-50079900c674b425b40b10d142c86a3cb8e463411e8477998384995e7befe895
}

2024-06-24 18:07:20.225 [DBG] GRPC: [core] [Channel #217] Channel created
2024-06-24 18:07:20.225 [DBG] GRPC: [core] [Channel #217] original dial target is: "52.88.202.111:10029"
2024-06-24 18:07:20.225 [DBG] GRPC: [core] [Channel #217] dial target "52.88.202.111:10029" parse failed: parse "52.88.202.111:10029": first path segment in URL cannot contain colon
2024-06-24 18:07:20.225 [DBG] GRPC: [core] [Channel #217] fallback to scheme "passthrough"
2024-06-24 18:07:20.225 [DBG] GRPC: [core] [Channel #217] parsed dial target is: {URL:{Scheme:passthrough Opaque: User: Host: Path:/52.88.202.111:10029 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}
2024-06-24 18:07:20.225 [DBG] GRPC: [core] [Channel #217] Channel authority set to "52.88.202.111:10029"
2024-06-24 18:07:20.225 [DBG] GRPC: [core] [Channel #217] Resolver state updated: {
  "Addresses": [
    {
      "Addr": "52.88.202.111:10029",
      "ServerName": "",
      "Attributes": null,
      "BalancerAttributes": null,
      "Metadata": null
    }
  ],
  "Endpoints": [
    {
      "Addresses": [
        {
          "Addr": "52.88.202.111:10029",
          "ServerName": "",
          "Attributes": null,
          "BalancerAttributes": null,
          "Metadata": null
        }
      ],
      "Attributes": null
    }
  ],
  "ServiceConfig": null,
  "Attributes": null
} (resolver returned new addresses)
2024-06-24 18:07:20.226 [DBG] GRPC: [core] [Channel #217] Channel switches to new LB policy "pick_first"
2024-06-24 18:07:20.226 [DBG] GRPC: [core] [pick-first-lb 0xc002ab1260] Received new config {
  "shuffleAddressList": false
}, resolver state {
  "Addresses": [
    {
      "Addr": "52.88.202.111:10029",
      "ServerName": "",
      "Attributes": null,
      "BalancerAttributes": null,
      "Metadata": null
    }
  ],
  "Endpoints": [
    {
      "Addresses": [
        {
          "Addr": "52.88.202.111:10029",
          "ServerName": "",
          "Attributes": null,
          "BalancerAttributes": null,
          "Metadata": null
        }
      ],
      "Attributes": null
    }
  ],
  "ServiceConfig": null,
  "Attributes": null
}
2024-06-24 18:07:20.226 [DBG] GRPC: [core] [Channel #217 SubChannel #218] Subchannel created
2024-06-24 18:07:20.226 [DBG] GRPC: [core] [Channel #217] Channel Connectivity change to CONNECTING
2024-06-24 18:07:20.226 [INF] UNIV: Fetching 1 roots
2024-06-24 18:07:20.227 [INF] WTCL: (legacy) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2024-06-24 18:07:20.227 [INF] WTCL: (anchor) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2024-06-24 18:07:20.226 [INF] WTCL: (taproot) Client stats: tasks(received=0 accepted=0 ineligible=0) sessions(acquired=0 exhausted=0)
2024-06-24 18:07:20.227 [DBG] GRPC: [core] [Channel #217 SubChannel #218] Subchannel Connectivity change to CONNECTING
2024-06-24 18:07:20.227 [DBG] GRPC: [core] [Channel #217 SubChannel #218] Subchannel picks a new address "52.88.202.111:10029" to connect
2024-06-24 18:07:20.227 [DBG] GRPC: [core] [pick-first-lb 0xc002ab1260] Received SubConn state update: 0xc002ab1380, {ConnectivityState:CONNECTING ConnectionError:<nil>}
2024-06-24 18:07:20.533 [DBG] GRPC: [core] [Channel #217 SubChannel #218] Subchannel Connectivity change to READY
2024-06-24 18:07:20.533 [DBG] GRPC: [core] [pick-first-lb 0xc002ab1260] Received SubConn state update: 0xc002ab1380, {ConnectivityState:READY ConnectionError:<nil>}
2024-06-24 18:07:20.533 [DBG] GRPC: [core] [Channel #217] Channel Connectivity change to READY
2024-06-24 18:07:20.622 [DBG] GRPC: [core] [Channel #217] Channel Connectivity change to SHUTDOWN
2024-06-24 18:07:20.622 [DBG] GRPC: [core] [Channel #217] ccBalancerWrapper: closing
2024-06-24 18:07:20.622 [DBG] GRPC: [core] [Channel #217] Closing the name resolver
2024-06-24 18:07:20.623 [DBG] GRPC: [core] [Channel #217 SubChannel #218] Subchannel Connectivity change to SHUTDOWN
2024-06-24 18:07:20.623 [DBG] GRPC: [core] [Channel #217 SubChannel #218] Subchannel deleted
2024-06-24 18:07:20.623 [DBG] GRPC: [transport] [client-transport 0xc000903688] Closing: rpc error: code = Canceled desc = grpc: the client connection is closing
2024-06-24 18:07:20.623 [DBG] GRPC: [core] [Channel #217] Channel deleted
2024-06-24 18:07:20.623 [DBG] GRPC: [transport] [client-transport 0xc000903688] loopyWriter exiting with error: connection error: desc = "transport is closing"
2024-06-24 18:07:20.623 [ERR] RPCS: [/universerpc.Universe/SyncUniverse]: unable to sync universe: unable to fetch roots for universe sync: missing universe id
2024-06-24 18:07:20.624 [DBG] GRPC: [transport] [server-handler-transport 0xc003d4ab40] Closing: finished writing status

[dstadulis]

I minted a non-grouped asset with asset_id 50079900c674b425b40b10d142c86a3cb8e463411e8477998384995e7befe895, but I was unable to open a channel with it nonetheless [...]

@GeorgeTsagk ran local tests:

Changing the asset mint to be a NewGroupedAsset seems to be passing the channel funding phase (RPCs return no error, asserts are happy) It does crash later on though, when asserting that proofs have been uploaded to the universe ^ for this I'm not sure if I should be using some other key for the proof or smth But def doesn't look like a core issue with the channel funding flow

Current Action

• [ ] Add a grouped asset itest -- requiring debugging the universe related dysfunction https://github.com/lightninglabs/taproot-assets/issues/957

[dstadulis]

fundchannel should no longer indefinitely hang as a 30 second timeout has been added with https://github.com/lightninglabs/taproot-assets/pull/971

Will monitor these user flow to ensure functionality