Hans Schmidt :  April 20th 2022

hans_schm1dt@protonmail.com


RVN_Bug- Testnet Block 1127354 Sync Hang- SubQualifier Not Found
*An explanation of how the bug fails and why the chosen Pull Request is the correct solution*
Please refer to https://github.com/RavenProject/Ravencoin/pull/1189 for the Pull Request which fixes this bug.

Where Reported:
Issue #1188

When Reported:
2022-03-07

Description:
Many people on testnet reported that their node stopped syncing when they reached block #1127354.

The problem could be corrected by issuing a "reconsiderblock  000000025a39fa0d11c24815aa78f843ba342b8694b93513e6a7f6283def617c" command on that block, after which syncing continued.

Core Log Output:
2022-03-20 01:11:31 UpdateTip: new best=00000003ca8624c9a3ce647767f319f361e34ab65efef57804c066a089b43bd0 height=1127352 version=0x30000000 log2_work=51.791538 tx=129
4621 date='2022-03-10 00:27:41' progress=0.986789 cache=2.1MiB(15285txo)
2022-03-20 01:11:31 UpdateTip: new best=0000000c62d766a35f783a39799fe5e7cca6b894e85b3e50084795e17be9a229 height=1127353 version=0x30000000 log2_work=51.791538 tx=1294622 date='2022-03-10 00:28:15' progress=0.986789 cache=2.1MiB(15287txo)
2022-03-20 01:11:31 ERROR: ContextualCheckVerifierString : The address mnzcdtNKpTY7kpuaW7Th88HPnzxes3BLEd failed to verify against: KYCTEST. Is null 1
2022-03-20 01:11:31 ERROR: ContextualCheckTransferAsset : bad-txns-null-verifier-address-failed-verification
2022-03-20 01:11:31 ERROR: ConnectBlock: Consensus::CheckTxAssets: 39f584821bfaeb6472969f008d219d6886a9ea430ac948858530a2e252f7ba58,  (code 16)
2022-03-20 01:11:31 InvalidChainFound: invalid block=000000025a39fa0d11c24815aa78f843ba342b8694b93513e6a7f6283def617c  height=1127354  log2_work=51.791538  date=2022-03-10 00:28:27
2022-03-20 01:11:31 InvalidChainFound:  current best=0000000c62d766a35f783a39799fe5e7cca6b894e85b3e50084795e17be9a229  height=1127353  log2_work=51.791538  date=2022-03-10 00:28:15
2022-03-20 01:11:31 ERROR: ConnectTip(): ConnectBlock 000000025a39fa0d11c24815aa78f843ba342b8694b93513e6a7f6283def617c failed

Relevant Information:
The following Restricted Asset activity occurred leading up to the failure:
Time                                Transaction                                                                                                                       Height                    Comment
2022-03-07 18:50:13 a2791de8bfca034f9801ac3a6411d6a8302d9e08a8064abe8e83c2a206e317cc     1124545        $RENEWABLOX asset created
2022-03-07 19:01:32 bac49094ae3ce2d80668672276af44a05034abd3234062d393b2a8769cd7f253     1124562        #KYCTEST tagged to address
2022-03-07 19:05:44 b949ef7f1e64ab67b9d16fb08bbc658cb0f78024ad4cab47ad1ac1a049fe67af     1124568        $RENEWABLOX transferred to address
2022-03-07 19:32:12 ccebd395b263817f2f1ccf6e9a76a287332b1a5ed98d7fcd29ca1970739b3540     1124625        #KYCTEST untagged from address
2022-03-07 21:43:01 744ae2f262efdab76d2398430cd9fe5213ee06e1925d709435d684e2e5afed23     1124809        #KYCTEST/#RNBX1_TEST tagged to address
2022-03-10 00:28:27 39f584821bfaeb6472969f008d219d6886a9ea430ac948858530a2e252f7ba58     1127354        $RENEWABLOX transferred to address




Analysis

ConnectBlock calls
CheckTxAssets calls
ContextualCheckTransferAsset calls
ContextualAgainstCheckVerifierString calls
ContextualCheckVerifierString which generates the error message
    "The address mnzcdtNKpTY7kpuaW7Th88HPnzxes3BLEd failed to verify against: KYCTEST."
    based on results it got by calling
CheckForAddressQualifier (the function which is the source of the problem)


CheckForAddressQualifier action analysis
in src/assets/assets.cpp

First off, the code related to TempCache (dirty cache) can be ignored because the function is called with fSkipTempCache = true. In fact, this is true in all cases except when called from the rpc client in src/rpc/assets.cpp. In all other cases, we only want to check against states that are deterministic and created by successful blocks being added to the chain.

The sequence Restricted Asset activity during the relevant transactions is as follows (this is all in-memory activity; no database actions):

1. **bac49094ae3ce2d80668672276af44a05034abd3234062d393b2a8769cd7f253**
  a. #KYCTEST - with type=add added to assetcache->setNewQualifierAddressToAdd
  b. on block connected and validated assetcache flushes to *passets** object
  c. Final - passets->setNewQualifierAddressToAdd contains #KYCTEST with type=add

2. **b949ef7f1e64ab67b9d16fb08bbc658cb0f78024ad4cab47ad1ac1a049fe67af**
  a. transfer of asset occured

3. **ccebd395b263817f2f1ccf6e9a76a287332b1a5ed98d7fcd29ca1970739b3540**
  a. #KYCTEST - with type=remove added to assetcache->setNewQualifierAddressToAdd
  b. on block connected and validated assetcache flushes to **passets** object
  c. During flush, passets->setNewQualifierAddressToAdd removes current #KYCTEST object with type=add
  d. During flush, passets->setNewQualifierAddressToAdd add new #KYCTEST object with type=remove

4. **744ae2f262efdab76d2398430cd9fe5213ee06e1925d709435d684e2e5afed23**
  a. #KYCTEST/#RNBX1_TEST with type=add is modifed to #KYCTEST and added to assetCache->mapRootQualifierAddressAdd
  b. #KYCTEST/#RNBX1_TEST with type=add is added to assetCache->setNewQualifierAddressToAdd
  c. On block connected and validate assetcache flushes to **passets** object
  d. During flush, passets->mapRootQualifierAddressAdd adds new #KYCTEST with type=add
  e. During flush, passets->setNewQualifierAddressToAdd add new #KYCTEST/#RNBX1_TEST with type=add

5. **39f584821bfaeb6472969f008d219d6886a9ea430ac948858530a2e252f7ba58**
  a. Transfer of restricted asset tx come in
  b Code pulls verify string for address. Seeing #KYCTEST
  c. Code goes and sees if address has the tag KYCTEST
  d When examining if the address contains the tag, the following happens in this order.
    1. Check passets->setNewQualifierAddressToRemove (This is only used when undoing blocks, can be ignored for this example)
    2. Check passets->setNewQualifierAddressToAdd
      a. Here we find a result, the same result that step (3.d) has. which is  passets->setNewQualifierAddressToAdd add new #KYCTEST object with type=remove
      b. This check sees the the #KYCTEST has been removed from that address as a qualifier, so this check returns false and the validation fails.

Conclusion

  • The bug occurs when reading the cache to look for the Qualifiers tagged to an address
  • The bug only applies to the specific sequence of actions:
    • addtag Qualifier, removetag Qualifier, addtag SubQualifier
  • It will not happen in the sequence:
    • addtag SubQualifier, removetag SubQualifier, addtag Qualifier
  • After sufficient time has passed, the cache is written to the database, after which this bug will no longer cause failures
The code fix in PR #1189 adds an additional check to look for the SubQualifier in the cache

Scope

The bug is present in all versions of Ravencoin core which support Restricted assets.  Since it happens during a cache read operation, the bug may or may not occur depending on the speed of the node, the compiling method used, and other items which affect timing



Thanks go to Jeremy for his help analyzing and patching this bug.

Copyright 2022 by Hans Schmidt