[bug]: Troubleshoot discrepancy between command results: `asset balance` and `assets list` #665

ffranr · 2023-11-13T16:33:44Z

@HannahMR reported the following:

It seems there is an error in the tapcli assets balance command on v0.3.1. My balance is 10, but appears as 30.

So I was making demo videos and trasfering assets between an Alice node and a Bob node. The Alice node is my tapd demo node that I've been using for the demo videos, and my Bob node is the Velas Commerce testnet node. Both are running LND 0.17 and tapd 0.3.1

I minted two rounds of two different assets, 100 units each time, on my Alice node, one of which I named APIdemobux. On Friday I had sent two transactions of 10 APIdemobux to Leo, he send 10 of those back leaving me with a total of 190 APIdemobux.

Today, for a demo video, using the command line, I transfered 10 APIdemobux to the Bob node. At the time of recording, those assets were showing up as expected when using the $ tapcli assets balance command.

However, an hour or so later, when running that command on the Bob node, the balance showed as 20. And after restarting the tapd service on the server, the balances shows as 30!

I can however run the assets list command and the balance apears appropriately as 10.

The output of the tapcli assets balance and the assets list command on the Alice node are still showing the correct amounts.

I only put that transaction through one time... just went and double checked the video.

I can send logs if that's helpful. I also have the output of the balance and list commands from each node.

Just to summaries the issue I think you've encountered: the reported balance for an asset is different between these two commands:
tapcli asset balance and tapcli assets list. And also the result returned by tapcli asset balance changes over time after receiving an asset.

I've got a copy of Bob's tapd.db. I will inspect.

The text was updated successfully, but these errors were encountered:

HannahMR · 2023-11-14T16:43:37Z

tapd.log
tapd.log.5.gz
tapd.log.6.gz
tapd.log.7.gz

ffranr · 2023-11-14T19:04:47Z

Thank you Hannah for the logs. Unfortunately they aren't very useful for this issue. The syncer log messages are so numerous I think they've squeezed out any potentially interesting messages.

dstadulis · 2023-11-14T19:44:05Z

plan

turn off debugger
run node for 10 min (get sync logs)
Progress with further testing

Roasbeef · 2023-11-14T21:35:10Z

The syncer log messages are so numerous I think they've squeezed out any potentially interesting messages.

Those can be turned to info with SYNC=info on the command line for the debug logs.

HannahMR · 2023-11-15T12:53:09Z

Okay I set debuglevel=off in my config file, let it run for a min, then restarted via systemd and let it run a bit more, and here the logs. Github thinks the the db file is too big to post here. Can send separately if that's helpful.
[tapd.log]

HannahMR · 2023-11-15T12:53:23Z

tapd.log

Bug report: #665

ffranr · 2023-11-16T01:09:23Z

I've made an unsuccessful attempt at reproducing this bug here: #679

Just checking: @HannahMR was node Bob using release v0.3.1?

Bug report: #665

HannahMR · 2023-11-16T11:14:58Z

Yup, 0.3.1-alpha.

HannahMR · 2023-11-16T11:25:22Z

New log file after setting debuglevel=info
tapd.log

ffranr · 2023-11-16T11:44:24Z

The last bit of the latest log is interesting. The custodian spins up and immediately thinks it's receiving and asset.

2023-11-15 11:40:50.556 [INF] GRDN: New block at height 2538569
2023-11-15 11:45:06.240 [DBG] UNIV: Fetching all known Universe roots (with_amounts_by_id=false, sort_direction=0, offset=0, limit=512)
2023-11-15 11:45:06.319 [DBG] UNIV: Fetching all known Universe roots (with_amounts_by_id=false, sort_direction=0, offset=512, limit=512)
2023-11-15 11:45:06.320 [INF] TADB: populating root cache...
2023-11-15 11:45:06.330 [DBG] TADB: Populating 0 root nodes into cache, took=10.173646ms
2023-11-15 11:45:06.330 [DBG] TADB: caching num_roots=0
2023-11-15 11:47:06.817 [INF] TAPD: Received terminated
2023-11-15 11:47:06.818 [INF] TAPD: Shutting down...
2023-11-15 11:47:06.818 [INF] TAPD: Gracefully shutting down.
2023-11-15 11:47:06.818 [INF] SRVR: Received SIGINT (Ctrl+C). Shutting down...
2023-11-15 11:47:06.818 [INF] RPCS: Stopping RPC Server
2023-11-15 11:47:06.828 [INF] SRVR: Shutdown complete

2023-11-15 11:47:06.965 [INF] CONF: Attempting to establish connection to lnd...
2023-11-15 11:47:08.383 [INF] CONF: lnd connection initialized
2023-11-15 11:47:08.383 [INF] CONF: Opening sqlite3 database at: /home/ubuntu/.tapd/data/testnet/tapd.db
2023-11-15 11:47:08.388 [INF] CONF: Configuring testnet.universe.lightning.finance:10029 as initial Universe federation server
2023-11-15 11:47:09.030 [INF] CONF: Starting HTTPS REST proxy listener at 0.0.0.0:8089
2023-11-15 12:39:45.278 [INF] CONF: Attempting to establish connection to lnd...
2023-11-15 12:39:46.371 [INF] CONF: lnd connection initialized
2023-11-15 12:39:46.371 [INF] CONF: Opening sqlite3 database at: /home/ubuntu/.tapd/data/testnet/tapd.db
2023-11-15 12:39:46.375 [INF] CONF: Configuring testnet.universe.lightning.finance:10029 as initial Universe federation server
2023-11-15 12:39:47.048 [INF] CONF: Starting HTTPS REST proxy listener at 0.0.0.0:8089
2023-11-16 11:18:23.381 [INF] CONF: Attempting to establish connection to lnd...
2023-11-16 11:18:24.693 [INF] CONF: lnd connection initialized
2023-11-16 11:18:24.693 [INF] CONF: Opening sqlite3 database at: /home/ubuntu/.tapd/data/testnet/tapd.db
2023-11-16 11:18:24.698 [INF] CONF: Configuring testnet.universe.lightning.finance:10029 as initial Universe federation server
2023-11-16 11:18:24.699 [INF] SRVR: Version: 0.3.1-alpha commit=v0.3.1, build=production, logging=default, debuglevel=info
2023-11-16 11:18:24.699 [INF] SRVR: Active network: testnet3
2023-11-16 11:18:24.699 [INF] RPCS: Validating RPC requests based on macaroon at: /home/ubuntu/.tapd/data/testnet/admin.macaroon
2023-11-16 11:18:24.700 [INF] GRDN: Starting ChainPlanter
2023-11-16 11:18:24.701 [INF] GRDN: Retrieved 0 non-finalized batches from DB
2023-11-16 11:18:24.701 [INF] GRDN: Starting asset custodian
2023-11-16 11:18:24.702 [INF] GRDN: Gardener for ChainPlanter now active!
2023-11-16 11:18:24.702 [INF] GRDN: Loading pending inbound asset events
2023-11-16 11:18:24.702 [INF] GRDN: Starting re-org watcher
2023-11-16 11:18:24.707 [INF] GRDN: Resuming 0 pending inbound asset events
2023-11-16 11:18:24.708 [INF] GRDN: Loading wallet transactions starting at block height 0
2023-11-16 11:18:24.709 [INF] GRDN: New block at height 2538739
2023-11-16 11:18:24.803 [INF] GRDN: Checking 509 wallet transactions for inbound assets, this might take a while
2023-11-16 11:18:24.816 [INF] GRDN: Found inbound asset transfer (asset_id=efcc499aaa628bf15021a2e53f467cc24c4f63e9836de69ac6ed3b72a30c6cb3) for Taproot Asset address taptb1qqqsqqspqqzzpm7vfxd25c5t79gzrgh98ar8esjvfa37nqmdu6dvdmfmw23scm9nq5ssy3kjwyrxps6j3fycf0dkp43umry2r4fnay6wpqnjdj95jmh79hqhqcssypztwwrwpkkle9z33gcrpnyquhpnyk207g2qu4g50s3gnv7mtuj8pqss9gzpwm7ac8yespjjqwa8eldav5je5fjajszdw5zm7s7fkgwl5n74pgqs5rpkw4hxjan9wfek2unsvvaz7tm5v4ehgmn9wsh82mnfwejhyum99ekxjemgw3hxjmn89enxjmnpde3k2w33xqcrywg3tfymf in b2c1aad652ce9eb02d966870e4e1df666ad2728cfec897efb42d15599c5ceac5:1
2023-11-16 11:18:24.949 [INF] GRDN: Starting main custodian event loop
2023-11-16 11:18:25.285 [INF] FRTR: Starting ChainPorter
2023-11-16 11:18:25.286 [INF] UNIV: Starting FederationEnvoy
2023-11-16 11:18:25.556 [INF] UNIV: Adding new Universe server to Federation, addrs=([]universe.ServerAddr) (len=1 cap=1) {
 (universe.ServerAddr) {
  ID: (int64) 0,
  addrStr: (string) (len=40) "testnet.universe.lightning.finance:10029",
  addr: (net.Addr) <nil>
 }
}

2023-11-16 11:18:25.561 [INF] RPCS: Starting RPC Server
2023-11-16 11:18:25.562 [INF] RPCS: RPC server listening on 0.0.0.0:10029
2023-11-16 11:18:25.564 [INF] CONF: Starting HTTPS REST proxy listener at 0.0.0.0:8089
2023-11-16 11:18:25.564 [INF] RPCS: gRPC proxy started at 0.0.0.0:8089
2023-11-16 11:18:25.575 [INF] SRVR: Taproot Asset Daemon fully active!
2023-11-16 11:18:29.828 [INF] PROF: Starting proof transfer backoff procedure for proof (transfer_type=receive, locator_hash=64039d94f6ab31d848f3095e668a391d2b46a00c8e5dddefde74cf7fdf290c85)
2023-11-16 11:18:29.895 [INF] PROF: Starting proof transfer backoff procedure for proof (transfer_type=receive, locator_hash=bb90144e4a3a9e4e0d7241138775e8dab36f518a78803a899dd9f9d18c539e76)
2023-11-16 11:18:29.989 [INF] GRDN: Received new proof file, version=0, num_proofs=2
2023-11-16 11:21:08.250 [INF] TAPD: Received terminated
2023-11-16 11:21:08.250 [INF] TAPD: Shutting down...
2023-11-16 11:21:08.250 [INF] TAPD: Gracefully shutting down.
2023-11-16 11:21:08.251 [INF] SRVR: Received SIGINT (Ctrl+C). Shutting down...
2023-11-16 11:21:08.251 [INF] RPCS: Stopping RPC Server
2023-11-16 11:21:08.252 [INF] SRVR: Shutdown complete

2023-11-16 11:21:08.325 [INF] CONF: Attempting to establish connection to lnd...
2023-11-16 11:21:09.257 [INF] CONF: lnd connection initialized
2023-11-16 11:21:09.257 [INF] CONF: Opening sqlite3 database at: /home/ubuntu/.tapd/data/testnet/tapd.db
2023-11-16 11:21:09.261 [INF] CONF: Configuring testnet.universe.lightning.finance:10029 as initial Universe federation server
2023-11-16 11:21:09.262 [INF] SRVR: Version: 0.3.1-alpha commit=v0.3.1, build=production, logging=default, debuglevel=info
2023-11-16 11:21:09.262 [INF] SRVR: Active network: testnet3
2023-11-16 11:21:09.262 [INF] RPCS: Validating RPC requests based on macaroon at: /home/ubuntu/.tapd/data/testnet/admin.macaroon
2023-11-16 11:21:09.263 [INF] GRDN: Starting ChainPlanter
2023-11-16 11:21:09.263 [INF] GRDN: Retrieved 0 non-finalized batches from DB
2023-11-16 11:21:09.263 [INF] GRDN: Starting asset custodian
2023-11-16 11:21:09.265 [INF] GRDN: Starting re-org watcher
2023-11-16 11:21:09.265 [INF] GRDN: Loading pending inbound asset events
2023-11-16 11:21:09.266 [INF] GRDN: Resuming 0 pending inbound asset events
2023-11-16 11:21:09.267 [INF] GRDN: Loading wallet transactions starting at block height 0
2023-11-16 11:21:09.264 [INF] GRDN: Gardener for ChainPlanter now active!
2023-11-16 11:21:09.312 [INF] GRDN: New block at height 2538739
2023-11-16 11:21:09.323 [INF] GRDN: Checking 509 wallet transactions for inbound assets, this might take a while
2023-11-16 11:21:09.333 [INF] GRDN: Found inbound asset transfer (asset_id=efcc499aaa628bf15021a2e53f467cc24c4f63e9836de69ac6ed3b72a30c6cb3) for Taproot Asset address taptb1qqqsqqspqqzzpm7vfxd25c5t79gzrgh98ar8esjvfa37nqmdu6dvdmfmw23scm9nq5ssy3kjwyrxps6j3fycf0dkp43umry2r4fnay6wpqnjdj95jmh79hqhqcssypztwwrwpkkle9z33gcrpnyquhpnyk207g2qu4g50s3gnv7mtuj8pqss9gzpwm7ac8yespjjqwa8eldav5je5fjajszdw5zm7s7fkgwl5n74pgqs5rpkw4hxjan9wfek2unsvvaz7tm5v4ehgmn9wsh82mnfwejhyum99ekxjemgw3hxjmn89enxjmnpde3k2w33xqcrywg3tfymf in b2c1aad652ce9eb02d966870e4e1df666ad2728cfec897efb42d15599c5ceac5:1
2023-11-16 11:21:09.403 [INF] GRDN: Starting main custodian event loop
2023-11-16 11:21:09.632 [INF] FRTR: Starting ChainPorter
2023-11-16 11:21:09.633 [INF] UNIV: Starting FederationEnvoy
2023-11-16 11:21:09.897 [INF] UNIV: Adding new Universe server to Federation, addrs=([]universe.ServerAddr) (len=1 cap=1) {
 (universe.ServerAddr) {
  ID: (int64) 0,
  addrStr: (string) (len=40) "testnet.universe.lightning.finance:10029",
  addr: (net.Addr) <nil>
 }
}

2023-11-16 11:21:09.898 [INF] RPCS: Starting RPC Server
2023-11-16 11:21:09.898 [INF] RPCS: RPC server listening on 0.0.0.0:10029
2023-11-16 11:21:09.900 [INF] CONF: Starting HTTPS REST proxy listener at 0.0.0.0:8089
2023-11-16 11:21:09.900 [INF] RPCS: gRPC proxy started at 0.0.0.0:8089
2023-11-16 11:21:09.900 [INF] SRVR: Taproot Asset Daemon fully active!
2023-11-16 11:21:14.337 [INF] PROF: Starting proof transfer backoff procedure for proof (transfer_type=receive, locator_hash=64039d94f6ab31d848f3095e668a391d2b46a00c8e5dddefde74cf7fdf290c85)
2023-11-16 11:21:14.406 [INF] PROF: Starting proof transfer backoff procedure for proof (transfer_type=receive, locator_hash=bb90144e4a3a9e4e0d7241138775e8dab36f518a78803a899dd9f9d18c539e76)
2023-11-16 11:21:14.501 [INF] GRDN: Received new proof file, version=0, num_proofs=2

ffranr · 2023-11-16T13:24:09Z

I think this bug is possible in part because of a defective UNIQUE constraint in the assets SQL table. The UNIQUE constraint is currently:

UNIQUE(asset_id, genesis_id, script_key_id)

However, asset_id is not the asset.ID of the asset. It is a BIGINT primary key. Basically an integer which is incremented with each new entry in the assets table. Given that asset_id is included in the UNIQUE constraint, it's always possible to add an asset into the table even if it already exists. Which means we can have duplicate assets in this table.

I think we should change this UNIQUE constraint to:

UNIQUE(anchor_utxo_id, genesis_id, script_key_id)

For a utxo, a asset genesis profile, and a script key there should not be a duplicate entry in the assets table.

ffranr · 2023-11-16T14:06:04Z

In addition to the above proposed change. We should also make the InsertNewAsset SQL query and upsert. This will make our code more robust. But it isn't strictly necessary. And it could effectively hide a bug in another part of the code. But still, more robust.

ffranr · 2023-11-16T14:12:11Z

And the last improvement I think we should make in fixing this bug is to ensure that the Custodian does not attempt to re-import a an asset and proof which it has already imported.

Custodian.inspectWalletTx should check to see if an asset (coin) and its corresponding proof already exists in the local db before attempting to import again. This method is actually call before the Custodian event loop here. At that point, on tapd restart, all wallet transactions are re-inspected. And it's ultimately from there that the known assets are erroneously duplicated.

jharveyb · 2023-11-16T16:16:11Z

I think we should change this UNIQUE constraint to:
UNIQUE(anchor_utxo_id, genesis_id, script_key_id)

This looks equivalent to the path for that proof in a universe tree, which seems like the right direction. Wondering if it's correct for grouped assets though (I think so?)

ffranr · 2023-11-16T16:18:52Z

Wondering if it's correct for grouped assets though (I think so?)

@jharveyb Well the genesis_id seems correct for a grouped asset. At least in the tapd db I inspected for this bug. But we should definitely test to cover!

Roasbeef · 2023-11-16T18:48:56Z

I think this bug is possible in part because of a defective UNIQUE constraint in the assets SQL table. The UNIQUE constraint is currently

Before we get to this phase, why is it being inserted twice in the first place? Shouldn't it detect that the recv is already complete? Or is the design that we assume the operation is idempotent so this behavior is fine?

Roasbeef · 2023-11-16T18:51:28Z

UNIQUE(asset_id, genesis_id, script_key_id)

I think we did this the first time to enable script key re-use? Otherwise, we can also add a chain level identifier here. So if we add a UNIQUE constraint on the actual outpoint where the asset is stored. That gives a unique path all the way down into the chain, so I think this would permit the addr re-use, while also giving a fully unique identifier.

jharveyb · 2023-11-16T19:04:24Z

Script key re-use for addr re-use would still be different anchor outpoints, so that should be fine?

IIUC adding the anchor outpoint makes this key globally unique (a specific transfer of this specific leaf) vs. just unique in the tree.

ffranr · 2023-11-16T19:12:40Z

I think this bug is possible in part because of a defective UNIQUE constraint in the assets SQL table. The UNIQUE constraint is currently

Before we get to this phase, why is it being inserted twice in the first place? Shouldn't it detect that the recv is already complete? Or is the design that we assume the operation is idempotent so this behavior is fine?

@Roasbeef see #665 (comment)

jharveyb · 2023-11-16T19:13:29Z

Part of this should also be enforcing address uniqueness within a transfer request, to prevent collisions.

ffranr · 2023-11-16T19:17:03Z

UNIQUE(asset_id, genesis_id, script_key_id)

I think we did this the first time to enable script key re-use? Otherwise, we can also add a chain level identifier here. So if we add a UNIQUE constraint on the actual outpoint where the asset is stored. That gives a unique path all the way down into the chain, so I think this would permit the addr re-use, while also giving a fully unique identifier.

@Roasbeef Yes. My idea with proposing UNIQUE(anchor_utxo_id, genesis_id, script_key_id) was to continue to facilitate address re-use. We basically want rows in the assets table to be tied to an asset transfer and to the chain.

Bug report: #665

ffranr · 2023-11-20T12:43:55Z

#687 is a simpler and safer solution than #684. I think we should focus on #687 for 0.3.2.

ffranr · 2023-11-27T15:45:40Z

Closed in favour of
#691
#699

These two issues break down the changes that we've discussed in this issue.

ffranr added bug Something isn't working needs triage labels Nov 13, 2023

ffranr self-assigned this Nov 13, 2023

ffranr changed the title ~~[bug]: Discrepancy between command results: asset balance and assets list~~ [bug]: Troubleshoot discrepancy between command results: asset balance and assets list Nov 13, 2023

ffranr added this to Taproot-Assets Project Board Nov 13, 2023

github-project-automation bot moved this to 🆕 New in Taproot-Assets Project Board Nov 13, 2023

ffranr moved this from 🆕 New to 🏗 In progress in Taproot-Assets Project Board Nov 13, 2023

ffranr added a commit that referenced this issue Nov 16, 2023

itest: attempt to reproduce asset balance bug report

12efdb6

Bug report: #665

ffranr mentioned this issue Nov 16, 2023

itest: attempt to reproduce asset balance bug report #679

Closed

ffranr added a commit that referenced this issue Nov 16, 2023

itest: attempt to reproduce asset balance bug report

5a0dccf

Bug report: #665

dstadulis added assets accounting and removed needs triage labels Nov 16, 2023

ffranr mentioned this issue Nov 17, 2023

Change SQL statement InsertNewAsset into an upsert. #684

Closed

ffranr added a commit that referenced this issue Nov 17, 2023

itest: ensure that asset balance does not increase on tapd restart

98c2233

Bug report: #665

ffranr added a commit that referenced this issue Nov 20, 2023

itest: ensure that asset balance does not increase on tapd restart

a51368f

Bug report: #665

ffranr mentioned this issue Nov 20, 2023

Check for existing asset in db before attempting to insert a new asset. #687

Merged

ffranr moved this from 🏗 In progress to 👀 In review in Taproot-Assets Project Board Nov 20, 2023

ffranr mentioned this issue Nov 21, 2023

Fix assets SQL table unique constrinat #691

Closed

ffranr closed this as completed Nov 27, 2023

github-project-automation bot moved this from 👀 In review to ✅ Done in Taproot-Assets Project Board Nov 27, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[bug]: Troubleshoot discrepancy between command results: `asset balance` and `assets list` #665

[bug]: Troubleshoot discrepancy between command results: `asset balance` and `assets list` #665

ffranr commented Nov 13, 2023 •

edited

Loading

HannahMR commented Nov 14, 2023

ffranr commented Nov 14, 2023

dstadulis commented Nov 14, 2023

Roasbeef commented Nov 14, 2023

HannahMR commented Nov 15, 2023

HannahMR commented Nov 15, 2023

ffranr commented Nov 16, 2023 •

edited

Loading

HannahMR commented Nov 16, 2023

HannahMR commented Nov 16, 2023

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 16, 2023

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 16, 2023 •

edited

Loading

jharveyb commented Nov 16, 2023

ffranr commented Nov 16, 2023 •

edited

Loading

Roasbeef commented Nov 16, 2023

Roasbeef commented Nov 16, 2023

jharveyb commented Nov 16, 2023

ffranr commented Nov 16, 2023

jharveyb commented Nov 16, 2023

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 20, 2023

ffranr commented Nov 27, 2023 •

edited

Loading

[bug]: Troubleshoot discrepancy between command results: asset balance and assets list #665

[bug]: Troubleshoot discrepancy between command results: asset balance and assets list #665

Comments

ffranr commented Nov 13, 2023 • edited Loading

HannahMR commented Nov 14, 2023

ffranr commented Nov 14, 2023

dstadulis commented Nov 14, 2023

Roasbeef commented Nov 14, 2023

HannahMR commented Nov 15, 2023

HannahMR commented Nov 15, 2023

ffranr commented Nov 16, 2023 • edited Loading

HannahMR commented Nov 16, 2023

HannahMR commented Nov 16, 2023

ffranr commented Nov 16, 2023 • edited Loading

ffranr commented Nov 16, 2023

ffranr commented Nov 16, 2023 • edited Loading

ffranr commented Nov 16, 2023 • edited Loading

jharveyb commented Nov 16, 2023

ffranr commented Nov 16, 2023 • edited Loading

Roasbeef commented Nov 16, 2023

Roasbeef commented Nov 16, 2023

jharveyb commented Nov 16, 2023

ffranr commented Nov 16, 2023

jharveyb commented Nov 16, 2023

ffranr commented Nov 16, 2023 • edited Loading

ffranr commented Nov 20, 2023

ffranr commented Nov 27, 2023 • edited Loading

[bug]: Troubleshoot discrepancy between command results: `asset balance` and `assets list` #665

[bug]: Troubleshoot discrepancy between command results: `asset balance` and `assets list` #665

ffranr commented Nov 13, 2023 •

edited

Loading

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 16, 2023 •

edited

Loading

ffranr commented Nov 27, 2023 •

edited

Loading