Construction Automated Test: account balance is always zero for newly created addresses?

Hi, we are trying out the automated construction test. The test creates a newly account and request for funds. After we send some amount to it, it seems the test is not querying the account balance by /account/balance endpoint?

The amount is always 0.

Output from rosetta-cli (we added additional print lines):

2020/08/04 16:14:12 Syncing 1664035
Account balance for address zil1ecv6mkrgm06nhhvy0csmkyu7cu5lejj9f709wh - 0
Error: <nil>
Account balance for address zil1ecv6mkrgm06nhhvy0csmkyu7cu5lejj9f709wh - 0
Error: <nil>
Account balance for address zil1ecv6mkrgm06nhhvy0csmkyu7cu5lejj9f709wh - 0
Error: <nil>
2020/08/04 16:14:34 Syncing 1664036
Account balance for address zil1ecv6mkrgm06nhhvy0csmkyu7cu5lejj9f709wh - 0
Error: <nil>
Account balance for address zil1ecv6mkrgm06nhhvy0csmkyu7cu5lejj9f709wh - 0
Error: <nil>
2020/08/04 16:14:57 Syncing 1664037

This is not accurate as the account does indeed have sufficient balance: https://viewblock.io/zilliqa/address/zil1ecv6mkrgm06nhhvy0csmkyu7cu5lejj9f709wh?network=testnet

view:account is also displaying a valid amount:

2020/08/04 16:20:34 Amounts: [
 {
  "value": "10000000000000",
  "currency": {
   "symbol": "ZIL",
   "decimals": 12
  }
 }
]
2020/08/04 16:20:34 Coins: null
2020/08/04 16:20:34 Metadata: {
 "nonce": 0
}
2020/08/04 16:20:34 Balance Fetched At: {
 "index": 1664053,
 "hash": "55c96428b086aebce47ea96cfb277ea1d3f68c9667a4ef6696b5320bdbec0a84"
}

We have tweaked the configurations, e.g. to re-broadcast, set minimum balance, maximum fees, confirmation depth, etc but to no avail. Appreciate if anyone knows what might be the cause for such an observation.

Thanks in advance!

You are 100% correct that the test does not determine account balance by using the /account/balance endpoint. Rather, the automated Construction API test calculates the balance on the account by parsing block balance changes. I would NOT recommend running this test until you are able to run check:data without issue (not sure if you’ve been able to do that yet).

It looks like a deposit to that address arrived in block 1664021. Did you turn off the test while you funded the account (I only see logs for block 1664035)?
https://viewblock.io/zilliqa/tx/0xcbffa8ab54edc12a395bbb345f8868a5e4de9699988d0fee46fd1b6a0175b2c6?network=testnet

I’d be happy to help debug on this if your implementation is accessible! The automated Construction API test is new and want to make sure there isn’t a bug somewhere that is wasting your time.

Thank you @patrick.ogrady for prompt response!

The output logs are copied at a earlier time. Hence the discrepancies. But we left the checker running for 30 minutes past the transaction but to no avail.

I also observed the balance_storage_helper.go:

// AccountBalance attempts to fetch the balance
// for a missing account in storage. This is necessary
// for running the "check" command at an arbitrary height
// instead of syncing from genesis.
func (h *BalanceStorageHelper) AccountBalance(
	ctx context.Context,
	account *types.AccountIdentifier,
	currency *types.Currency,
	block *types.BlockIdentifier,
) (*types.Amount, error) {
	if !h.lookupBalanceByBlock {
		return &types.Amount{
			Value:    "0",
			Currency: currency,
		}, nil
	}

So, if the lookup by balance by block is disabled, it will never execute the reconcilier (in the later portion) which I believe does the actual computation of the account balance. I think this might be the issue we are facing. Although, we have set the historical_balance_lookup and other settings to false, it always executes this function during check:construction initial execution.

To add on to this, our blockchain does not support historical balance lookup or retrieve an account balance at a specific block. This is also probably why we are facing this issue.

Unfortunately, our team is not prepared to open up the repo yet but hopefully soon; so that we can resolve the issues together with rosetta’s team more efficiently.

At the moment, I guess we might be skipping the construction test or come out with our own end-to-end construction tests.

Thanks!

Would you mind starting over fresh and sending all logs from start? This should include the initial startup logs and the initial request for funds (would also appreciate it if you sent a link to the funding of the account on your block explorer). Very curious why this isn’t working for your team! We’ve seen this work without issue on a few networks that don’t support historical_balance_lookup.

The reconciler is not active during check:construction (regardless of the value of historical_balance_lookup) and is not responsible for computing any balance changes (that is done exclusively by BalanceStorage). Its job is to confirm that computed balance changes match what is returned by /account/balance.

In check:construction, we never call /account/balance and assume the balance of any new address (that we requested funds on) starts at 0. I see now that this code should be updated to always return 0 in the case we are running check:construction :man_facepalming: . Nonetheless, I don’t believe this is related to the problem you are facing (appreciate the debugging here!).

Hopefully, I can help debug more when I get the full logs! If you have any thoughts on how this tool could be improved please chime in on our feedback request!

Hi @patrick.ogrady, not sure whether this would be helpful but attached are the output logs from rosetta-cli (modified to display additional info) along with the “official” generated logs.

https://drive.google.com/drive/folders/1Qet6v68XS9G3INEwgIPATrca0qZC5gnm?usp=sharing

Funding of new account:
https://viewblock.io/zilliqa/tx/0x514d2a92e488039d235840cafdba19785027a3878d79b2764825129822d471af?network=testnet

construction.output.log (truncated)

2020/08/06 11:20:13 Syncing 1671301
popBal.Block: <nil>
popBal Amount: &{0 0xc00016d5a0 map[]}
Constructor helper AccountBalance - amount: &{0 0xc00016d5a0 map[]}
Account balance for address zil1jtaexgwp9597dqwest55gvcrm9xnfuv0tk968x - 0
Error: <nil>
Constructor.go requestFunds balance: 0
Constructor.go minimum balance: 1000000000
popBal.Block: <nil>
popBal Amount: &{0 0xc00016d920 map[]}
Constructor helper AccountBalance - amount: &{0 0xc00016d920 map[]}
Account balance for address zil1jtaexgwp9597dqwest55gvcrm9xnfuv0tk968x - 0
Error: <nil>
Constructor.go requestFunds balance: 0
Constructor.go minimum balance: 1000000000

Thank you!

[EDIT]
I finally discovered the issue. Our blockchain display addresses in two formats: (1) the bech32 format (zlixxxx) for front end and (2) base16 format for apis, low-level systems. When the checker queries /block for the account balance changes, it is not able to match to the correct address, thus, the balance is always zero.

Now, it seems like we are having issues with the metadata :frowning:

2020/08/07 10:59:51 POST /network/status 400.939668ms
2020/08/07 10:59:51 POST /block 407.491383ms
2020/08/07 10:59:52 POST /network/status 389.059111ms
2020/08/07 10:59:54 POST /construction/derive 366.296µs
2020/08/07 10:59:54 POST /construction/preprocess 338.742µs
2020/08/07 10:59:54 POST /construction/metadata 193.296182ms
no metadata
2020/08/07 10:59:54 POST /construction/payloads 375.369µs

-----

popBal.Block: &{1675301 0bdd8464f47536e3ba15bbc9044ed882cabd26508db91b5091643203d5a7bbcc}
popBal Amount: &{2000000000000 0xc0001ca740 map[]}
Constructor helper AccountBalance - amount: &{2000000000000 0xc0001ca740 map[]}
Account balance for address zil19j3yuv24ynuswqhc8xjwm4psn8szsnlyzwnstn - 2000000000000
Error: <nil>
Generating scenario...
[STATS] Transactions Confirmed: 0 (Created: 0, In Progress: 0, Stale: 0, Failed: 0) Addresses Created: 2
Check failed: {Code:507 Message:params error Retriable:true Details:map[]}: unable to construct payloads: unable to create transaction with operations [
 {
  "operation_identifier": {
   "index": 0
  },
  "type": "transfer",
  "status": "",
  "account": {
   "address": "zil19j3yuv24ynuswqhc8xjwm4psn8szsnlyzwnstn"
  },
  "amount": {
   "value": "-954097147072",
   "currency": {
    "symbol": "ZIL",
    "decimals": 12
   }
  }
 },
 {
  "operation_identifier": {
   "index": 1
  },
  "related_operations": [
   {
    "index": 0
   }
  ],
  "type": "transfer",
  "status": "",
  "account": {
   "address": "zil1uqkc97zwcx8fvrpnyygm0wklpkgrafl29dv34p"
  },
  "amount": {
   "value": "954097147072",
   "currency": {
    "symbol": "ZIL",
    "decimals": 12
   }
  }
 }
]

We retrieved metadata via /preprocess and /metadata. This information is used for /payloads as part of the recipient operation. The metadata includes blockchain version, nonce, gas price, gas limit, amount, recipient address, sender public key which are used as params to generate the unsigned_transaction string.

Sample request /payloads request:

{
    "network_identifier": {
        "blockchain": "zilliqa",
        "network": "testnet"
    },
	"operations": [
        {
            "operation_identifier": {
                "index": 0
            },
            "type": "transfer",
            "status": "",
            "account": {
                "address": "99f9d482abbdC5F05272A3C34a77E5933Bb1c615"
            },
            "amount": {
                "value": "-2000000000000",
                "currency": {
                    "symbol": "ZIL",
                    "decimals": 12
                }
            }
        },
        {
            "operation_identifier": {
                "index": 1
            },
            "related_operations": [
                {
                    "index": 0
                }
            ],
            "type": "transfer",
            "status": "",
            "account": {
                "address": "0x4978075dd607933122f4355B220915EFa51E84c7"
            },
            "amount": {
                "value": "2000000000000",
                "currency": {
                    "symbol": "ZIL",
                    "decimals": 12
                }
            },
            "metadata": {
                "amount": "2000000000000",
                "gasLimit": "1",
                "gasPrice": "1000000000",
                "nonce": 185,
                "pubKey": "02e44ef2c5c2031386faa6cafdf5f67318cc661871b0112a27458e65f37a35655e",
                "toAddr": "4978075dd607933122f4355B220915EFa51E84c7",
                "version": 21823489
            }
        }
    ],
    "metadata": {}
}

Sample response:

{
    "unsigned_transaction": "{\"amount\":2000000000000,\"code\":\"\",\"data\":\"\",\"gasLimit\":1,\"gasPrice\":1000000000,\"nonce\":185,\"pubKey\":\"02e44ef2c5c2031386faa6cafdf5f67318cc661871b0112a27458e65f37a35655e\",\"toAddr\":\"4978075dd607933122f4355B220915EFa51E84c7\",\"version\":21823489}",
    "payloads": [
        {
            "hex_bytes": "7b22616d6f756e74223a323030303030303030303030302c22636f6465223a22222c2264617461223a22222c226761734c696d6974223a312c226761735072696365223a313030303030303030302c226e6f6e6365223a3138352c227075624b6579223a22303265343465663263356332303331333836666161366361666466356636373331386363363631383731623031313261323734353865363566333761333536353565222c22746f41646472223a2234393738303735646436303739333331323266343335354232323039313545466135314538346337222c2276657273696f6e223a32313832333438397d",
            "address": "99f9d482abbdC5F05272A3C34a77E5933Bb1c615",
            "signature_type": "ecdsa"
        }
    ]
}

How do we define a metadata structure in the config.json which is only utilized during /payloads?

I think it would help developers if the team could display the input parameters and output for each of the construction tests endpoints. Perhaps something like a verbose:true flag in the config. This will help us to better debug in relation with the expected input.

Glad you could find the issue! If the bech32 format is the address used when depositing/withdrawing, I’d highly recommend using that exclusively in Rosetta (unless I am missing something about why using the other format would be useful here).

The retrieved metadata should be provided in ConstructionPayloadsRequest.Metadata instead of as the metadata of any particular Operation. If your implementation reads the Metadata from ConstructionPayloadsRequest, automated testing will “just work”!

Thanks, it is working. We would probably extract out the metadata from the operations and insert all them under the “main” metadata

1 Like

Hi @patrick.ogrady!

We are trying to send a transaction but we are facing something similar although we have the suspicious the problem is different.

You mean we need to run the whole data:check before being able to run construction:check?

Also, the following logs are quite strange for two reaons:

  1. It goes over block 1678853 but the transaction is not found, even if it’s there
  2. There are several fetch error: Post http://localhost:8080/network/status: EOF although I cannot se anything when looking at the app logs
2020/08/16 20:03:48 construction tester initialized with 0 addresses
[STATS] Transactions Confirmed: 0 (Created: 0, In Progress: 0, Stale: 0, Failed: 0) Addresses Created: 0
Waiting for funds on addr_test1vr74y8pak2xjjevuyhydszjmvqtmk69vxyte4hmnvt6vrrqtcdufa
2020/08/16 20:03:51 Syncing 1678850
[STATS] Transactions Confirmed: 0 (Created: 0, In Progress: 0, Stale: 0, Failed: 0) Addresses Created: 1
2020/08/16 20:03:59 Syncing 1678851
2020/08/16 20:04:19 Syncing 1678852
2020/08/16 20:04:26 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/16 20:04:26 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.365063s
2020/08/16 20:04:40 Syncing 1678853
^[[1;2D2020/08/16 20:04:59 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/16 20:04:59 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.666892s
2020/08/16 20:05:01 Syncing 1678854
2020/08/16 20:05:21 Syncing 1678855
2020/08/16 20:05:34 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/16 20:05:34 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.378012s

But, if I query the node:

$ echo '{
      "network_identifier": {
          "blockchain": "cardano",
          "network": "testnet"
      },
      "block_identifier": {
          "index": 1678853
      }
  }' | http post http://localhost:8080/block
HTTP/1.1 200 OK
Connection: keep-alive
Date: Sun, 16 Aug 2020 23:08:53 GMT
content-length: 1579
content-type: application/json; charset=utf-8

{
    "block": {
        "block_identifier": {
            "hash": "8804c72d5a6df4215b1b57626d6a6e81dc3e8dd7a60a55451ed0d1cdd04b00ad",
            "index": 1678853
        },
        "metadata": {
            "createdBy": "ShelleyGenesis-32a954b521c0b195",
            "epochNo": 77,
            "size": 270,
            "slotNo": 3249860,
            "transactionsCount": 1
        },
        "parent_block_identifier": {
            "hash": "0e48aff817ea3ec15ef6ed2569e17daf2fd6f00109f91a7f9d7d4419b963e787",
            "index": 1678852
        },
        "timestamp": 1597629876000,
        "transactions": [
            {
                "operations": [
                    {
                        "account": {
                            "address": "addr_test1qr5zz03x60sdr5exuqphv4p8hev8zz4u79sdj4d4ar6l8ecxu2hyfhlkwuxupa9d5085eunq2qywy7hvmvej456flkns4q89j9"
                        },
                        "amount": {
                            "currency": {
                                "decimals": 6,
                                "symbol": "ADA"
                            },
                            "value": "-9998999831551"
                        },
                        "coin_change": {
                            "coin_action": "coin_created",
                            "coin_identifier": {
                                "identifier": "57d295dd7bf4b130d5f77c692a65d144c3fb689976af149e6da6a1b6388bb8a7:0"
                            }
                        },
                        "operation_identifier": {
                            "index": 0
                        },
                        "status": "success",
                        "type": "transfer"
                    },
                    {
                        "account": {
                            "address": "addr_test1qzkneh3srn7vt2x66wj62d59v0d67truldjmln6x2y4tjhgxu2hyfhlkwuxupa9d5085eunq2qywy7hvmvej456flknsp3k23f"
                        },
                        "amount": {
                            "currency": {
                                "decimals": 6,
[N] alverbner@hal:~/Projects/iohk/rosetta-cli-test
$ echo '{  "network_identifier": { "blockchain": "cardano", "network": "testnet" }, 
    "account_identifier": {
      "address": "addr_test1vr74y8pak2xjjevuyhydszjmvqtmk69vxyte4hmnvt6vrrqtcdufa"
    }
  }' | http post http://localhost:8080/account/balance
HTTP/1.1 200 OK
Connection: keep-alive
Date: Sun, 16 Aug 2020 23:17:35 GMT
content-length: 406
content-type: application/json; charset=utf-8

{
    "balances": [
        {
            "currency": {
                "decimals": 6,
                "metadata": {},
                "symbol": "ADA"
            },
            "metadata": {},
            "value": "10000000000"
        }
    ],
    "block_identifier": {
        "hash": "2e1259a489ea58e6ef7c5031f8e44387363bbb878d658f488427c3c2894dd884",
        "index": 1678891
    },
    "coins": [
        {
            "amount": {
                "currency": {
                    "decimals": 6,
                    "symbol": "ADA"
                },
                "value": "10000000000"
            },
            "coin_identifier": {
                "identifier": "f320d20b7643d7ceffc2f770121e84780ade9de72255fc50372998a89ef8e04e:0"
            }
        }
    ]
}
1 Like

Nope! check:construction starts from the CurrentBlockIdentifier returned by /network/status. I mentioned this to clarify that check:construction requires block parsing to work correctly and if check:data does not work, it is unlikely that check:construction will work correctly.

The clip you provided does not contain a transfer to addr_test1vr74y8pak2xjjevuyhydszjmvqtmk69vxyte4hmnvt6vrrqtcdufa. Maybe it got cutoff?

{
    "block": {
        "block_identifier": {
            "hash": "8804c72d5a6df4215b1b57626d6a6e81dc3e8dd7a60a55451ed0d1cdd04b00ad",
            "index": 1678853
        },
        "metadata": {
            "createdBy": "ShelleyGenesis-32a954b521c0b195",
            "epochNo": 77,
            "size": 270,
            "slotNo": 3249860,
            "transactionsCount": 1
        },
        "parent_block_identifier": {
            "hash": "0e48aff817ea3ec15ef6ed2569e17daf2fd6f00109f91a7f9d7d4419b963e787",
            "index": 1678852
        },
        "timestamp": 1597629876000,
        "transactions": [
            {
                "operations": [
                    {
                        "account": {
                            "address": "addr_test1qr5zz03x60sdr5exuqphv4p8hev8zz4u79sdj4d4ar6l8ecxu2hyfhlkwuxupa9d5085eunq2qywy7hvmvej456flkns4q89j9"
                        },
                        "amount": {
                            "currency": {
                                "decimals": 6,
                                "symbol": "ADA"
                            },
                            "value": "-9998999831551"
                        },
                        "coin_change": {
                            "coin_action": "coin_created",
                            "coin_identifier": {
                                "identifier": "57d295dd7bf4b130d5f77c692a65d144c3fb689976af149e6da6a1b6388bb8a7:0"
                            }
                        },
                        "operation_identifier": {
                            "index": 0
                        },
                        "status": "success",
                        "type": "transfer"
                    },
                    {
                        "account": {
                            "address": "addr_test1qzkneh3srn7vt2x66wj62d59v0d67truldjmln6x2y4tjhgxu2hyfhlkwuxupa9d5085eunq2qywy7hvmvej456flknsp3k23f"
                        },
                        "amount": {
                            "currency": {
                                "decimals": 6,

These look to be transient errors (as syncing continues shortly after receiving them). I assume these are related to a low HTTP timeout setting where the fetcher is canceling the request after some number of seconds (could be related to elevated server response latency when syncing a block). Some server packages do not always log canceled requests. I’d try increasing http_timeout in your configuration file to 30 (defaults at 10).

@patrick.ogrady , I found check:data is time-consuming if want to check all the data from very beginning. Is there any chances to speed it up?

@PatrickWu, what we have tried and worked for us is increasing the concurrency values 1 but I guess @patrick.ogrady knows better

Hi @patrick.ogrady ,

We still think there is something not working here (and I’m 99% sure check:data works).

I’m attaching:

  1. rosetta-cli config and logs
  2. app logs

You will be able to see that:

  • addr_test1vz33ean6rjxx7xmnnnwd333ycj7eexzcdzh8vskdcqllz9sqfylez is generated
  • there is actually a transfer operation to that address
loaded configuration file: ./cardano.json
2020/08/19 08:43:06 {
 "network": {
  "blockchain": "cardano",
  "network": "testnet"
 },
 "online_url": "http://localhost:8080",
 "data_directory": "/home/alverbner/Projects/iohk/rosetta-cli-test/cardano-data",
 "http_timeout": 100000,
 "block_concurrency": 8,
 "transaction_concurrency": 16,
 "tip_delay": 10000,
 "construction": {
  "offline_url": "http://localhost:8080",
  "currency": {
   "symbol": "ADA",
   "decimals": 6
  },
  "minimum_balance": "600",
  "maximum_fee": "700000",
  "curve_type": "edwards25519",
  "accounting_model": "utxo",
  "scenario": [
   {
    "operation_identifier": {
     "index": 0
    },
    "type": "Vin",
    "status": "",
    "account": {
     "address": "{{ SENDER }}"
    },
    "amount": {
     "value": "{{ SENDER_VALUE }}",
     "currency": null
    },
    "coin_change": {
     "coin_identifier": {
      "identifier": "{{ COIN_IDENTIFIER }}"
     },
     "coin_action": "coin_spent"
    }
   },
   {
    "operation_identifier": {
     "index": 1
    },
    "type": "Vout",
    "status": "",
    "account": {
     "address": "{{ RECIPIENT }}"
    },
    "amount": {
     "value": "{{ RECIPIENT_VALUE }}",
     "currency": null
    }
   }
  ],
  "confirmation_depth": 10,
  "stale_depth": 5,
  "broadcast_limit": 3,
  "ignore_broadcast_failures": false,
  "change_scenario": {
   "operation_identifier": {
    "index": 2
   },
   "type": "Vout",
   "status": "",
   "account": {
    "address": "{{ CHANGE_ADDRESS }}"
   },
   "amount": {
    "value": "{{ CHANGE_VALUE }}",
    "currency": null
   }
  },
  "clear_broadcasts": false,
  "broadcast_behind_tip": false,
  "block_broadcast_limit": 5,
  "rebroadcast_all": false,
  "new_account_probability": 0.5,
  "max_addresses": 200
 },
 "data": {
  "active_reconciliation_concurrency": 16,
  "inactive_reconciliation_concurrency": 4,
  "inactive_reconciliation_frequency": 250,
  "log_blocks": false,
  "log_transactions": false,
  "log_balance_changes": false,
  "log_reconciliations": false,
  "ignore_reconciliation_error": false,
  "exempt_accounts": "",
  "bootstrap_balances": "",
  "historical_balance_disabled": false,
  "interesting_accounts": "",
  "reconciliation_disabled": false,
  "inactive_discrepency_search_disabled": false,
  "balance_tracking_disabled": false
 }
}
2020/08/19 08:43:08 construction tester initialized with 0 addresses
[STATS] Transactions Confirmed: 0 (Created: 0, In Progress: 0, Stale: 0, Failed: 0) Addresses Created: 0
Waiting for funds on addr_test1vz33ean6rjxx7xmnnnwd333ycj7eexzcdzh8vskdcqllz9sqfylez
2020/08/19 08:43:08 Syncing 1689768
2020/08/19 08:43:14 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:14 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.256978s
[STATS] Transactions Confirmed: 0 (Created: 0, In Progress: 0, Stale: 0, Failed: 0) Addresses Created: 1
2020/08/19 08:43:19 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:19 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.520733s
2020/08/19 08:43:20 Syncing 1689769
2020/08/19 08:43:26 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:26 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.507326s
2020/08/19 08:43:32 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:32 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.450887s
2020/08/19 08:43:37 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:37 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.661886s
2020/08/19 08:43:38 Syncing 1689770
2020/08/19 08:43:44 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:44 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.262099s
2020/08/19 08:43:50 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:50 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.566103s
2020/08/19 08:43:56 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:43:56 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.491513s
2020/08/19 08:44:01 network status { "blockchain": "cardano", "network": "testnet"} fetch error: Post http://localhost:8080/network/status: EOF
2020/08/19 08:44:01 retrying fetch for network status { "blockchain": "cardano", "network": "testnet"} after 0.309748s
[1597837419055] INFO  (1511452 on li2100-46): incoming request
    reqId: 19
    req: {
      "method": "POST",
      "url": "/block",
      "hostname": "localhost:8080",
      "remoteAddress": "127.0.0.1",
      "remotePort": 39030
    }
[1597837419057] INFO  (cardano-rosetta/1511452 on li2100-46): [block] Looking for block
    blockIdentifier: {
      "index": 1689770
    }
[1597837419057] INFO  (cardano-rosetta/1511452 on li2100-46): [findBlock] Looking for block:
    blockIdentifier: {
      "index": 1689770
    }
[1597837419058] INFO  (cardano-rosetta/1511452 on li2100-46): [findBlock] Do we have to look for genesisBlock? false
[1597837419058] INFO  (cardano-rosetta/1511452 on li2100-46): [findBlock] Do we have to look for latestBlock? false
[1597837419058] INFO  (cardano-rosetta/1511452 on li2100-46): [findBlock] Looking for block with blockNumber 1689770
[1597837419059] DEBUG (cardano-rosetta/1511452 on li2100-46): [findBlock] Parameters received for run query blockNumber: 1689770, blockHash: undefined
[1597837419064] DEBUG (cardano-rosetta/1511452 on li2100-46): [findBlock] Block found!
[1597837419065] INFO  (cardano-rosetta/1511452 on li2100-46): [findBlock] Block was found
[1597837419066] DEBUG (cardano-rosetta/1511452 on li2100-46): [findBlock] Returning response:
    response: {
      "number": 1689770,
      "hash": "2ebcde1b838f2a76c7b27ae2e8f54daaca4ada54855deca732297d028dd553d6",
      "createdAt": "2020-08-19T11:43:36.000Z",
      "previousBlockHash": "327a6629718b7903118241728358897cdfaa31672b7e12237078b9ae694e24d9",
      "previousBlockNumber": 1689769,
      "transactionsCount": "1",
      "createdBy": "ShelleyGenesis-4f4d7523e41e058a",
      "size": 270,
      "epochNo": 78,
      "slotNo": 3468200
    }
[1597837419066] INFO  (cardano-rosetta/1511452 on li2100-46): [block] Block was found
[1597837419067] DEBUG (cardano-rosetta/1511452 on li2100-46): [block] Does requested block contains transactions? true
[1597837419067] DEBUG (cardano-rosetta/1511452 on li2100-46): [findTransactionsByBlock] Parameters received for run query blockNumber: 1689770, blockHash: 2ebcde1b838f2a76c7b27ae2e8f54daaca4ada54855deca732297d028dd553d6
[1597837419068] DEBUG (cardano-rosetta/1511452 on li2100-46): [findTransactionsByBlock] About to run findTransactionsByBlock query with params
[1597837419072] DEBUG (cardano-rosetta/1511452 on li2100-46): [findTransactionsByBlock] Found 1 transactions
[1597837419073] INFO  (cardano-rosetta/1511452 on li2100-46): [block] Looking for blocks transactions full data
[1597837419074] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] About to query for inputs and outputs given 1 transaction's hashes
[1597837419074] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] About to query for inputs
[1597837419081] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] Found 1
[1597837419082] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] About to query for outputs
[1597837419087] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] Found 2
[1597837419089] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] Parsing inputs
[1597837419094] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] Parsing outputs
[1597837419095] DEBUG (cardano-rosetta/1511452 on li2100-46): [fillTransaction] Returning inputs and outputs as a transaction map
[1597837419101] DEBUG (cardano-rosetta/1511452 on li2100-46): Block to be returned
    block_identifier: {
      "hash": "2ebcde1b838f2a76c7b27ae2e8f54daaca4ada54855deca732297d028dd553d6",
      "index": 1689770
    }
    parent_block_identifier: {
      "index": 1689769,
      "hash": "327a6629718b7903118241728358897cdfaa31672b7e12237078b9ae694e24d9"
    }
    metadata: {
      "transactionsCount": "1",
      "createdBy": "ShelleyGenesis-4f4d7523e41e058a",
      "size": 270,
      "epochNo": 78,
      "slotNo": 3468200
    }
    transactions: [
      {
        "transaction_identifier": {
          "hash": "c161711f9c1bf42a8dc2f23e8016f9d2cc39590f5b9ec9c2ad1c0428feadbdcc"
        },
        "operations": [
          {
            "operation_identifier": {
              "index": 0
            },
            "type": "transfer",
            "status": "success",
            "account": {
              "address": "addr_test1qqr585tvlc7ylnqvz8pyqwauzrdu0mxag3m7q56grgmgu7sxu2hyfhlkwuxupa9d5085eunq2qywy7hvmvej456flknswgndm3"
            },
            "amount": {
              "value": "-10000000000000",
              "currency": {
                "symbol": "ADA",
                "decimals": 6
              }
            },
            "coin_change": {
              "coin_identifier": {
                "identifier": "59ff1269d6188afc1ff7a7158ec9262408875bb8dadb20a7604eadc10d43f00a:0"
              },
              "coin_action": "coin_created"
            }
          },
          {
            "operation_identifier": {
              "index": 1,
              "network_index": 1
            },
            "type": "transfer",
            "status": "success",
            "account": {
              "address": "addr_test1qzcwdlfwxmrj58t0pw9ualuma3jjkwy9j9uu9qz3tc8y9gsxu2hyfhlkwuxupa9d5085eunq2qywy7hvmvej456flknsynvrfh"
            },
            "amount": {
              "value": "9989999832607",
              "currency": {
                "symbol": "ADA",
                "decimals": 6
              }
            },
            "related_operations": [
              {
                "index": 0
              }
            ]
          },
          {
            "operation_identifier": {
              "index": 2,
              "network_index": 0
            },
            "type": "transfer",
            "status": "success",
            "account": {
              "address": "addr_test1vz33ean6rjxx7xmnnnwd333ycj7eexzcdzh8vskdcqllz9sqfylez"
            },
            "amount": {
              "value": "10000000000",
              "currency": {
                "symbol": "ADA",
                "decimals": 6
              }
            },
            "related_operations": [
              {
                "index": 0
              }
            ]
          }
        ]
      }
    ]
[1597837419109] INFO  (1511452 on li2100-46): request completed
    reqId: 19
    res: {
      "statusCode": 200
    }
    responseTime: 52.79507803916931

We have increased timeout to 10000 and it seems to still be throwing that message. It doesn’t make sense but, is it possible that it’s logging that when querying for status and the tip hasn’t changed? I’m kind of seeing that pattern but haven’t checked the rosetta-cli code to verify :thinking:

Thanks!

On v0.4.1, your best bet to decrease check time is to increase the sync_concurrency. By default this is set to 8, but I routinely set this to 64 or 128 while testing. Should give you a nice boost!

If you don’t see response latency increase when you ramp up sync_concurrency, I’d keep increasing it. You should be able to get up to 256 or even 512. You may encounter an error along the lines of too many files, in which case, you will need to increase your file limit: ulimit -n 65536.

We just updated master to provide much better error logging on retries. There was an issue where we were retrying on non-retriable errors and that was silencing some useful info. However, this error is only being thrown on /network/status requests, which shouldn’t impact our balance tracking loop.

:thinking:

1 Like

Thanks you! It works, and a nice boost :grinning:.

We are working on some storage optimizations that should >2x the sync speed. Will be sure to share when it is out!

1 Like

Thanks a lot for your help @patrick.ogrady … I’ll try to summarize our errors:

  1. Transaction operations. There were missing some coin_change.
  2. Status should be empty.
  3. coin_action for inputs should be coin_spent
  4. parse operation status should be empty
  5. coin_action wasn’t spent for inputs
  6. when parsing transaction, address prefix was not being properly set
  7. missing account information for input operations when parsing the encoded txs

This were hard to track bugs and I strongly suggest to add as many as logs as you can to the rosetta-cli check:construction tool. Verbosity is not problem but a feature on this tool IMO.

Thanks again!

2 Likes

Glad to see this working! We will take a pass at improving logging as part of the release of the new Construction API testing tool!

1 Like