Neo: JSON-RPC NEP-5 invokefunction calls returning incorrect results

[brianlenz]

There is an issue with every single JSON-RPC node (seedX.neo.org, seedX.cityofzion.io, seed8.antshares.org) that is resulting in out-of-date values being returned by invokescript and invokefunction calls.

I believe this to be the cause of the myriad of NEP-5 token complaints on https://github.com/CityOfZion/neon-wallet about balances not showing.

I've confirmed this issue exists for, at a minimum, totalSupply and balanceOf NEP-5 functions.

Here's the simplest example:

{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","totalSupply",[]],"id":1234}

cURL:

curl -H 'Content-Type: application/json' -v -d '{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","totalSupply",[]],"id":1234}' http://seed2.neo.org:10332

This returns:

{"jsonrpc":"2.0","id":1234,"result":{"state":"HALT, BREAK","gas_consumed":"0.628","stack":[{"type":"ByteArray","value":"00c0a9a4aa8b01"}]}}

That hex value (00c0a9a4aa8b01) corresponds to 435040000000000. This is not the correct value for totalSupply, however. In reality, the totalSupply is 1233800000000000, as evidenced by neo-python:

neo> testinvoke 2e25d2127e0240c6deaf35394702feb236d4d7fc totalSupply []
[test_mode][SmartContract.Execution.Success] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [b'\x00P\xb9r"b\x04']
Results ['ByteArray: bytearray(b\'\\x00P\\xb9r"b\\x04\')']

Here's one example of balanceOf that is actually working:

{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","balanceOf",[{"type":"Hash160","value":"d450b6c2d3f1ff1dff00307dceab009d1f5115e0"}]],"id":1234}

cURL:

curl -H 'Content-Type: application/json' -v -d '{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","balanceOf",[{"type":"Hash160","value":"d450b6c2d3f1ff1dff00307dceab009d1f5115e0"}]],"id":1234}' http://seed2.cityofzion.io:8080

That returns the proper value:

{"jsonrpc":"2.0","id":1234,"result":{"script":"14e015511f9d00abce7d3000ff1dfff1d3c2b650d451c10962616c616e63654f6667fcd7d436b2fe02473935afdec640027e12d2252e","state":"HALT, BREAK","gas_consumed":"0.675","stack":[{"type":"ByteArray","value":"00805fad236d"}]}}

But here is one that does not:

{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","balanceOf",[{"type":"Hash160","value":"e57d3afa4d95af5186121099fb5b55b7366aa8af"}]],"id":1234}

cURL:

curl -H 'Content-Type: application/json' -v -d '{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","balanceOf",[{"type":"Hash160","value":"e57d3afa4d95af5186121099fb5b55b7366aa8af"}]],"id":1234}' http://seed2.cityofzion.io:8080

That returns a balance of zero:

{"jsonrpc":"2.0","id":1234,"result":{"script":"14afa86a36b7555bfb9910128651af954dfa3a7de551c10962616c616e63654f6667fcd7d436b2fe02473935afdec640027e12d2252e","state":"HALT, BREAK","gas_consumed":"0.675","stack":[{"type":"ByteArray","value":""}]}}

but the actual balance:

neo> testinvoke 2e25d2127e0240c6deaf35394702feb236d4d7fc balanceOf ['AXnfejvXc7zoWD7reJ8hB3QUQd7jeCpLn1']
[test_mode][SmartContract.Execution.Success] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [b'\x00\x00QJ\x8d\x0e']
Results ["ByteArray: bytearray(b'\\x00\\x00QJ\\x8d\\x0e')"]

which corresponds to a real value of 16000000000000.

Some NEP-5 tokens don't seem to have this issue, but it does seem to affect quite a few ICOs based on the number of complaints in https://github.com/CityOfZion/neon-wallet.

Is there something in the JSON-RPC node implementation that results in the queried data potentially being out of date? The one address that balanceOf is returning properly for happens to be the first ICO contribution, so I don't know if that has anything to do with it.

[brianlenz]

I have forked the neo-python repository and created a branch with a test harness (test.py) that can be used to easily reproduce the issues. As you'd expect, it doesn't matter whether you use invokescript or invokefunction; the results are the same.

https://github.com/brianlenz/neo-python-rpc/blob/rpc-tests/test.py

[brianlenz]

Not surprisingly, calls to getstorage via JSON-RPC are returning results consistent with the above invokefunction calls, as well. For the total supply:

{"jsonrpc":"2.0","method":"getstorage","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","696e5f63697263756c6174696f6e"],"id":1234}

where 696e5f63697263756c6174696f6e is the "in_circulation" key, returns:

{"jsonrpc":"2.0","id":1234,"result":"00400952cef801"}

00400952cef801 is 5,550,400, which is not the accurate totalSupply. Per neo-python:

neo> testinvoke 2e25d2127e0240c6deaf35394702feb236d4d7fc totalSupply []
[test_mode][SmartContract.Storage.Get] [2e25d2127e0240c6deaf35394702feb236d4d7fc] ["b'in_circulation' -> bytearray(b'\\x00`\\x9f\\xd7\\xccG\\x05')"]
[test_mode][SmartContract.Execution.Success] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [b'\x00`\x9f\xd7\xccG\x05']

b'\x00`\x9f\xd7\xccG\x05' corresponds to the actual totalSupply of 14,863,200.

balanceOf for address AcCiYbGqADfcwN9sdacWw9CZuGYdAW3iYy (based on the address as the storage key):

{"jsonrpc":"2.0","method":"getstorage","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","e015511f9d00abce7d3000ff1dfff1d3c2b650d4"],"id":1234}

That properly returns the balance:

{"jsonrpc":"2.0","id":1234,"result":"00805fad236d"}

00805fad236d is 1,200,000, which is correct.

But, balanceOf for address AXnfejvXc7zoWD7reJ8hB3QUQd7jeCpLn1 (based on the address as the storage key):

{"jsonrpc":"2.0","method":"getstorage","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","afa86a36b7555bfb9910128651af954dfa3a7de5"],"id":1234}

does _not_ properly return the balance:

{"jsonrpc":"2.0","id":1234,"result":null}

Per neo-python:

neo> testinvoke 2e25d2127e0240c6deaf35394702feb236d4d7fc balanceOf ['AXnfejvXc7zoWD7reJ8hB3QUQd7jeCpLn1']
[test_mode][SmartContract.Storage.Get] [2e25d2127e0240c6deaf35394702feb236d4d7fc] ['AXnfejvXc7zoWD7reJ8hB3QUQd7jeCpLn1 -> 16000000000000']
[test_mode][SmartContract.Execution.Success] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [b'\x00\x00QJ\x8d\x0e']

it should be returning 160,000.

Now, having said all of this, it has crossed my mind that there could be a bug in the SC bytecode that is resulting in some non-deterministic behavior. My hope is that is not what it is (naturally), and the fact that everything is working perfectly in neo-python makes me hopeful. Also, we never ran into this issue when running on TestNet or privnet, so it _feels_ like some kind of JSON-RPC node issue.

Ultimately, these issues are manifesting themselves primarily through Neon wallet in two ways:
1) The "Total Supply" displayed in Neon wallet is incorrect.
2) Many users see a balance of 0 NRV in Neon wallet.

The other thing worth mentioning is the fact that our users who have supposed 0 balances in Neon wallet can access their tokens in Neotracker.io. Neotracker.io uses the NEP-5 transfer event to track balances (as opposed to balanceOf which is why neotracker is able to reflect the balances properly). Our users are confirming this, and other Neon wallet users have reported for other ICOs as well (that example is one of many that is still ongoing).

Finally, the fact that users are able to transfer the tokens at all seems to be a good indication that the data is stored on the blockchain properly. In addition to the fact that neo-python is showing the data properly, the fact that transfers are able to go through at all (via neotracker.io) indicates that the balance must be in storage (or else those transfers would be prevented due to data validation logic).

My ultimate assessment is just that it appears that the JSON-RPC nodes are not returning proper data, but I haven't had a chance to dig into the neo code sufficiently yet to confirm my assessment.

By the way, I am also asking for addresses from users with other tokens like TKY who are having 0 balance issues so that I can take a look at those to confirm if it's the same issue.

[brianlenz]

Here's a transaction executed on the blockchain via neo-python that is returning the proper result:

neo> testinvoke 2e25d2127e0240c6deaf35394702feb236d4d7fc totalSupply []
...
[I 180212 07:21:32 EventHub:89] [SmartContract.Storage.Get][1917279] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 9775d74e8adff9faff2bfb5d4203b42078a78279bb335fadc477bef1464700bd] ["b'in_circulation' -> bytearray(b'\\x00\\xd09Qg\\xa1\\x05')"]
[I 180212 07:21:32 EventHub:89] [SmartContract.Execution.Success][1917279] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 9775d74e8adff9faff2bfb5d4203b42078a78279bb335fadc477bef1464700bd] [b'\x00\xd09Qg\xa1\x05']

To me, that indicates that the bug is in JSON-RPC.

[brianlenz]

Here's a recent transaction as output by neo-python:

[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'sale_paused' -> bytearray(b'')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'kyc_oke\\x9d\\x87\\xb4\\x04\\xf75g\\xf9O)\\xb4\\xffW\\x07\\xfc\\xba\\xbd,\\x00' -> bytearray(b'\\x01')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'pre_end' -> bytearray(b'')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'pub_start' -> bytearray(b'')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'in_circulation' -> bytearray(b'\\x00\\xd0I\\xf6;\\x8a\\x06')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'r1e\\x9d\\x87\\xb4\\x04\\xf75g\\xf9O)\\xb4\\xffW\\x07\\xfc\\xba\\xbd,\\x00' -> bytearray(b'')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Put][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'r1e\\x9d\\x87\\xb4\\x04\\xf75g\\xf9O)\\xb4\\xffW\\x07\\xfc\\xba\\xbd,\\x00' -> bytearray(b'\\x00\\x00F\\xc3#')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ['AR3AcFnhppWtHfLg6KcxsjDwgtibtVfUeu -> 5000000000000']
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Put][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ['AR3AcFnhppWtHfLg6KcxsjDwgtibtVfUeu -> 66440000000000']
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Get][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'in_circulation' -> bytearray(b'\\x00\\xd0I\\xf6;\\x8a\\x06')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Storage.Put][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] ["b'in_circulation' -> bytearray(b'\\x00\\xd0\\xa9\\x13\\x1d\\xc2\\x06')"]
[I 180212 11:38:37 EventHub:89] [SmartContract.Runtime.Notify][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] [b'transfer', b'\xfc\xd7\xd46\xb2\xfe\x02G95\xaf\xde\xc6@\x02~\x12\xd2%.', b'e\x9d\x87\xb4\x04\xf75g\xf9O)\xb4\xffW\x07\xfc\xba\xbd,\x00', 61440000000000]
[I 180212 11:38:37 EventHub:89] [SmartContract.Runtime.Notify][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] [b'contribution', b'e\x9d\x87\xb4\x04\xf75g\xf9O)\xb4\xffW\x07\xfc\xba\xbd,\x00', 153600000000, 61440000000000]
[I 180212 11:38:37 EventHub:89] [SmartContract.Execution.Success][1917904] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 8925cf80f156c8b8689cdd2a428cd4e6dac5d2d5a595b5e7e327e26b22b65a25] [1]

It seems pretty clearly to store the value for in_circulation to b'\x00\xd0\xa9\x13\x1d\xc2\x06' (19,022,800e8).

Nevertheless, the JSON-RPC call:

{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","totalSupply",[]],"id":1234}

returns:

{"jsonrpc":"2.0","id":1234,"result":{"state":"HALT, BREAK","gas_consumed":"0.628","stack":[{"type":"ByteArray","value":"0050fe89cc0703"}]}}

0050fe89cc0703 is 8,530,000e8.

[brianlenz]

Here's another example. I initiated a balanceOf transaction from neo-gui via Invoke Contract for ScriptHash 2e25d2127e0240c6deaf35394702feb236d4d7fc with params:

• balanceOf (String)
• [431ed1576ad3c618bb62860dd3dc027357fc680f] (Array with one ByteArray element)
  Here's the output from neo-gui when running Test:

VM State: HALT, BREAK
Gas Consumed: 0.675
Evaluation Stack: [{"type":"ByteArray","value":""}]

Here's the output of that transaction once you actually invoke the transaction on the blockchain, as shown in neo-python:

[I 180212 17:55:30 EventHub:89] [SmartContract.Storage.Get][1918814] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 376d849468ff26264c2022444217500cfe20548fc87e88eeb3cdf403c7627334] ['AMtmqc3miofxvdaxBWcnYzzW7tHL8pdcmu -> 39080000000000']
[I 180212 17:55:30 EventHub:89] [SmartContract.Execution.Success][1918814] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 376d849468ff26264c2022444217500cfe20548fc87e88eeb3cdf403c7627334] [b'\x00\x90\x84\x05\x8b#']

b'\x00\x90\x84\x05\x8b#' is the correct value (390800e8).

Thus, again, it _appears_ that data is stored and accessed correctly on the blockchain in the context of a transaction, but outside of a transaction (e.g. neo-gui Test and JSON-RPC), the data accessed is out-of-date or otherwise incorrect.

[brianlenz]

I found one other interesting example of the discrepancy from the RHT SC (2328008e6f6c7bd157a342e789389eb034d9cbc4). totalSupply is also returning inconsistent results between neo-python and JSON-RPC.

Here's neo-python (actual transaction submitted to blockchain):

neo> testinvoke 2328008e6f6c7bd157a342e789389eb034d9cbc4 totalSupply []
[I 180212 18:58:05 EventHub:89] [SmartContract.Storage.Get][1918968] [2328008e6f6c7bd157a342e789389eb034d9cbc4] [tx 8537189a84d662ca306a37a07536a29f3aaa6a6b60ec2a3284ce53caec054c6a] ["b'in_circulation' -> bytearray(b'\\xad ')"]
[I 180212 18:58:05 EventHub:89] [SmartContract.Execution.Success][1918968] [2328008e6f6c7bd157a342e789389eb034d9cbc4] [tx 8537189a84d662ca306a37a07536a29f3aaa6a6b60ec2a3284ce53caec054c6a] [b'\xad ']

b'\xad ' is 8,365.

Here's a JSON-RPC call:

{"jsonrpc":"2.0","method":"invokefunction","params":["2328008e6f6c7bd157a342e789389eb034d9cbc4","totalSupply",[]],"id":1234}

and the result:

{"jsonrpc":"2.0","id":1234,"result":{"state":"HALT, BREAK","gas_consumed":"0.623","stack":[{"type":"ByteArray","value":"60ea00"}]}}

60ea00 is 60,000, which I understand is the proper value.

So, it seems the totalSupply behavior for RHT and NRV are reversed.

FWIW, RHT is also based off of the nex-ico-template (python).

[brianlenz]

Here's an address that is showing a zero balance on JSON-RPC (and Neon wallet): AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj

But in spite of that, he was able to transfer funds successfully. Here are the logs showing the successful transactions:

[I 180212 21:01:28 EventHub:89] [SmartContract.Storage.Get][1919268] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 56e88048e8acbff72b314464df675e73924fba9cd4bbe163b4a380138fdd4e71] ['AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj -> 33440000000000']
[I 180212 21:01:28 EventHub:89] [SmartContract.Storage.Put][1919268] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 56e88048e8acbff72b314464df675e73924fba9cd4bbe163b4a380138fdd4e71] ['AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj -> 33439900000000']
[I 180212 21:01:28 EventHub:89] [SmartContract.Storage.Get][1919268] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 56e88048e8acbff72b314464df675e73924fba9cd4bbe163b4a380138fdd4e71] ['ASYZgUDvJDMNdKjmxsEkY2H6CJW8DAfZ7s -> 0']
[I 180212 21:01:28 EventHub:89] [SmartContract.Storage.Put][1919268] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 56e88048e8acbff72b314464df675e73924fba9cd4bbe163b4a380138fdd4e71] ['ASYZgUDvJDMNdKjmxsEkY2H6CJW8DAfZ7s -> 100000000']
[I 180212 21:01:28 EventHub:89] [SmartContract.Runtime.Notify][1919268] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 56e88048e8acbff72b314464df675e73924fba9cd4bbe163b4a380138fdd4e71] [b'transfer', b')[\xd0\xbdZ\xb4\xf5\xe8\x17\x95\xfc\xf3"\x81"\x83\xbc\xc1\x9f\xf6', b'v$\xfa\x966!&\x9b\xde\x86*9\x9c\xf3dc\x97\xbf\xd6\x85', b'\x00\xe1\xf5\x05\x00']
[I 180212 21:01:28 EventHub:89] [SmartContract.Execution.Success][1919268] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 56e88048e8acbff72b314464df675e73924fba9cd4bbe163b4a380138fdd4e71] []

[I 180212 21:02:46 EventHub:89] [SmartContract.Storage.Get][1919271] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 4aa3fa70b156e99b6440281147ca3b6e13f22ca340b2a4af8a829b35f0a4c100] ['ASYZgUDvJDMNdKjmxsEkY2H6CJW8DAfZ7s -> 100000000']
[I 180212 21:02:46 EventHub:89] [SmartContract.Storage.Delete][1919271] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 4aa3fa70b156e99b6440281147ca3b6e13f22ca340b2a4af8a829b35f0a4c100] ['ASYZgUDvJDMNdKjmxsEkY2H6CJW8DAfZ7s']
[I 180212 21:02:46 EventHub:89] [SmartContract.Storage.Get][1919271] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 4aa3fa70b156e99b6440281147ca3b6e13f22ca340b2a4af8a829b35f0a4c100] ['AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj -> 33439900000000']
[I 180212 21:02:46 EventHub:89] [SmartContract.Storage.Put][1919271] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 4aa3fa70b156e99b6440281147ca3b6e13f22ca340b2a4af8a829b35f0a4c100] ['AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj -> 33440000000000']
[I 180212 21:02:46 EventHub:89] [SmartContract.Runtime.Notify][1919271] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 4aa3fa70b156e99b6440281147ca3b6e13f22ca340b2a4af8a829b35f0a4c100] [b'transfer', b'v$\xfa\x966!&\x9b\xde\x86*9\x9c\xf3dc\x97\xbf\xd6\x85', b')[\xd0\xbdZ\xb4\xf5\xe8\x17\x95\xfc\xf3"\x81"\x83\xbc\xc1\x9f\xf6', b'\x00\xe1\xf5\x05\x00']
[I 180212 21:02:46 EventHub:89] [SmartContract.Execution.Success][1919271] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 4aa3fa70b156e99b6440281147ca3b6e13f22ca340b2a4af8a829b35f0a4c100] []

And neo-python shows the proper balanceOf:

neo> testinvoke 2e25d2127e0240c6deaf35394702feb236d4d7fc balanceOf ['AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj']
[I 180212 21:18:15 EventHub:89] [SmartContract.Storage.Get][1919309] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 998b5c2280b5b35c548ebc7a4177ccbfaef1a6f11389a3b1d261e212f573f2d6] ['AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj -> 33440000000000']
[I 180212 21:18:15 EventHub:89] [SmartContract.Execution.Success][1919309] [2e25d2127e0240c6deaf35394702feb236d4d7fc] [tx 998b5c2280b5b35c548ebc7a4177ccbfaef1a6f11389a3b1d261e212f573f2d6] [b'\x00@R\xdbi\x1e']

b'\x00@R\xdbi\x1e' is the proper value (334400e8).

Yet JSON-RPC still says 0:

{"jsonrpc":"2.0","method":"invokefunction","params":["2e25d2127e0240c6deaf35394702feb236d4d7fc","balanceOf",[{"type":"Hash160","value":"f69fc1bc83228122f3fc9517e8f5b45abdd05b29"}]],"id":1234}

{"jsonrpc":"2.0","id":1234,"result":{"script":"14295bd0bd5ab4f5e81795fcf322812283bcc19ff651c10962616c616e63654f6667fcd7d436b2fe02473935afdec640027e12d2252e","state":"HALT, BREAK","gas_consumed":"0.675","stack":[{"type":"ByteArray","value":""}]}}

[erikzhang]

Can you believe this? I would say that it is a neo-python bug. I will look into it.

[erikzhang]

Where can I find the source code of SC 2e25d2127e0240c6deaf35394702feb236d4d7fc?

[brianlenz]

https://github.com/NarrativeNetwork/tokensale-neo-smartcontract

[shargon]

@erikzhang if testinvoke works, and RPC call fail. Can we trust that the storage is saved correctly? The public sale opens in 8 hours

Im dig into it, but without any advance.

[erikzhang]

I think the storage is incorrect. We didn't find the issue on any other SC except 2e25d2127e0240c6deaf35394702feb236d4d7fc(NRV). So I guess the problem may be in the smart contracts based on nex-ico-template (python).

[brianlenz]

Thanks for your help, @erikzhang!

What is the nature of the storage issue? If the storage is wrong, I don't understand how neo-python is returning accurate results 100% of the time, particularly on transactions submitted to the blockchain? And how would NEP5 transfer transactions function if the storage is truly incorrect?

[erikzhang]

The python nodes store the data in a wrong way, and read it in a wrong way. In this way, they get the "right" results.
Of course, this is only my guess, I will continue to dig into this issue.

[shargon]

This is the raw storage value of in_circulation variable:

Preffix   HASH                                     Preffix   in_circulation
70        FCD7D436B2FE02473935AFDEC640027E12D2252E 0E        696E5F63697263756C6174696F6E

And i think is not the expected (@brianlenz please confirm), but i can't understand, how is possible to obtain the right result with real TX

[brianlenz]

@erikzhang: for what it's worth, this issue never happened in testing on TestNet that we could see. We used Neon wallet with JSON-RPC, and did a full run-through of every feature of the smart contract (with many transactions), checking things in Neon wallet along the way. Never had an issue. The failure rate on MainNet seems to be rather high, so it's surprising none of those tests would have revealed an issue on TestNet.

Is there a reasonable explanation for why there would be such a major discrepancy between MainNet and TestNet?

[erikzhang]

I'm replaying all the NRV transactions locally to see how their execution is different from the python nodes. Can someone give me the logs of all the NRV transactions that executed on python node?

[brianlenz]

Sure, I'll work on getting that data right now.

[brianlenz]

Just to be clear, what format at you looking for? The only format I'm aware of is the sc-events output from neo-python (some of which I have posted as examples above). Is that what you're looking for?

[brianlenz]

Hi @erikzhang, just checking in to see if you have any updates? In the chance that the issue has to do with older nodes, I'm doing some tests against 2.4.1 nodes on PrivNet now.

[brianlenz]

Quick update on my end. I set up a 2.4.1 docker PrivNet to test with. I've seen zero issues thus far. neo-python reporting all data properly and JSON-RPC reporting all data properly. This is consistent with the behavior we experienced in doing tests against 2.6.0 docker PrivNet during development.

[erikzhang]

2e25d2127e0240c6deaf35394702feb236d4d7fc.log
I've uploaded the log of all storage operations of NRV. Please check it.

[brianlenz]

Thanks, @erikzhang! The first few transactions look ok, but then I think things go haywire. I picked out one address known to have issues:

https://neotracker.io/address/AKYZLoqvd2FyiumD8SuTZje6auQkf6pbHj

Here's the transaction where he bought the tokens:

https://neotracker.io/tx/f89f51eda6aa87bb9e681e152dee776d21ae0a3acade807c1cefab03b01ea6db

According to the storage logs, that transaction did nothing:

[1915968][0xf89f51eda6aa87bb9e681e152dee776d21ae0a3acade807c1cefab03b01ea6db][Neo.Storage.Get][k:sale_paused,v:]
[1915968][0xf89f51eda6aa87bb9e681e152dee776d21ae0a3acade807c1cefab03b01ea6db][Neo.Storage.Get][k:kyc_ok295bd0bd5ab4f5e81795fcf322812283bcc19ff6,v:]

(note that I replaced the hex key prefixes with their ASCII counterpart for readability)

If that was true, then the transaction should have stopped there. But based on the transaction on neotracker, it did not fail. In fact, the NEP5 transfer event was recorded as evidenced in the Transfers section. That is where the user's balance comes from on neotracker.

So here are the major discrepancies:

1) The address should have been whitelisted (and is currently), so the return value of kyc_ok should have been true. I don't see the transaction that whitelisted the address anywhere in your storage log either. If you search for this address 295bd0bd5ab4f5e81795fcf322812283bcc19ff6 all you see are empty Storage.Get calls.
2) Even if the return value was false, that should have ended the transaction right there and returned. But somehow, this transaction still logged a NEP5 transfer event.

I can't explain how the code path jumped from here:

https://github.com/NarrativeNetwork/tokensale-neo-smartcontract/blob/master/nrv/token/crowdsale.py#L258
to here:
https://github.com/NarrativeNetwork/tokensale-neo-smartcontract/blob/master/nrv/token/crowdsale.py#L401

without anything else in between taking place?

[dicarlo2]

I just want to jump in here real quick and mention that it's certainly possible that NEO Tracker has it wrong. We use a custom node implementation (an early version of NEO-ONE) which definitely had a gas calculation bug in it, and may have other bugs. With that said, it's definitely curious that both neo-python and NEO-ONE are reporting the same results that are inconsistent with the C# nodes.

[dicarlo2]

I'll take a closer look today to see if I can find the source of the discrepancy.

[brianlenz]

@dicarlo2 thanks for jumping in! From what I understand, neotracker is using the NEP5 transfer events to track balances. For the transaction listed above, it seems that there aren't _any_ Storage.Put operations. But it would _appear_ that the transfer event got logged due to the NEP5 balance showing up? I can't explain how that is possible.

What is even more peculiar is that these users are subsequently able to transfer the NEP5 tokens even though the blockchain has apparently not recorded the fact that the balance exists?

[dicarlo2]

On the former - it’s possible that within the NEO-ONE node, the storage has been erroneously committed along with the transfer events. I’ll look into that soon (on my way to the office).

On the latter - in theory this would be possible with NEO Tracker. Even though the transaction would have failed in the C# nodes, because the previous transaction that gave them the balance failed, NEO-ONE thinks the previous transaction succeeded so it also thinks subsequent transactions succeeded. In other words, NEO-ONE is consistently corrupted. I’ll check that as well.

[brianlenz]

Analyzing the logs, there are a few different types of transactions:

1) Successful mintTokens calls. These have 11 lines in the logs. Example
2) Unsuccessful (partially successful?) mintTokens calls. These have only 2 lines in the logs, as outlined above (two Storage.Get commands for sale_pause and kyc_ok). Example
3) Successful/proper NEP5 transfers. These have 4 lines in the logs. Example
4) Unsuccessful (partially successful?) NEP5 transfers. These have just a single line in the logs with a Storage.Get for an address (its balance) that returns an empty result. Example

The commonality I see between 2 and 4 is that there is an (unexpected) empty item returned from storage that causes the transaction to abort. I can't find an explanation for why the transaction works sometimes, but not others.

@dicarlo2, I think you may be on to something. Based on what I'm seeing here, it would make sense if data is being corrupted somehow on the NEO-ONE node which is allowing the NEP5 tokens to be displayed and "transferred" without actually being stored on the blockchain. It seems unlikely that the NEP5 transfer event is actually being recorded for these invalid transfers.

@localhuman suspects a storage issue could arise due to DB differences between the different node versions on MainNet (e.g. <=2.4.1 vs. 2.6.0+)

[brianlenz]

Update: we believe we may have this pinpointed. @localhuman and @dicarlo2 discussed the possibility of GAS fees contributing to transaction completion inconsistency between C# seed nodes and the neo-python/NEO-ONE nodes. The C# seed nodes are likely running out of GAS and aborting whitelisting transactions whereas the neo-python and NEO-ONE nodes are under-calculating the GAS fee and allowing those to process successfully. Thus, the whitelisting appears to take place normally when submitting transactions in neo-python even though they don't when processed on the C# seed nodes.

Assuming this all pans out, this would not be an issue of MainNet vs. TestNet/PrivNet, nor of node version. It's simply a GAS calculation discrepancy.

[erikzhang]

The result of that transaction (txid: f89f51eda6aa87bb9e681e152dee776d21ae0a3acade807c1cefab03b01ea6db) is (on my node):

{
  "jsonrpc": "2.0",
  "id": 1,
  "result": {
    "txid": "0xf89f51eda6aa87bb9e681e152dee776d21ae0a3acade807c1cefab03b01ea6db",
    "vmstate": "HALT, BREAK",
    "gas_consumed": "1.701",
    "stack": [
      {
        "type": "ByteArray",
        "value": ""
      }
    ],
    "notifications": [
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "726566756e64"
            },
            {
              "type": "ByteArray",
              "value": "295bd0bd5ab4f5e81795fcf322812283bcc19ff6"
            },
            {
              "type": "Integer",
              "value": "83600000000"
            }
          ]
        }
      }
    ]
  }
}

The stack has an empty byte array which means that the function returns false.
The gas_consumed field is 1.701, so it's not a GAS calculation discrepancy.

[localhuman]

@erikzhang

It returns false because a previous transaction for kyc_register failed, so the tokens were never minted properly. That previous transaction failed because of a GAS issue.

[erikzhang]

What is the txid of the previous transaction?

[brianlenz]

Should be this one: 01f992be33dcc8ebe1dd51058a2b8f511c9088a8d541a72c829382600c736640

It looks like it does 7 puts before it fails. It was supposed to do 32. neo-python reports this as using around 5.6 GAS, I believe.

I suppose this issue could be resolved and a new issue opened in neo-python?

[localhuman]

Sounds good.

[brianlenz]

Fix for neo-python is here: https://github.com/CityOfZion/neo-python/pull/220

[erikzhang]

Application log for tx 01f992be33dcc8ebe1dd51058a2b8f511c9088a8d541a72c829382600c736640:

{
  "jsonrpc": "2.0",
  "id": 1,
  "result": {
    "txid": "0x01f992be33dcc8ebe1dd51058a2b8f511c9088a8d541a72c829382600c736640",
    "vmstate": "FAULT, BREAK",
    "gas_consumed": "10.177",
    "stack": [
      {
        "type": "Integer",
        "value": "1"
      },
      {
        "type": "ByteArray",
        "value": "6b79635f6f6bace575f6847bc025bb30d752d73892bbb875e8d2"
      },
      { "type": "InteropInterface" }
    ],
    "notifications": [
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "6b79635f726567697374726174696f6e"
            },
            {
              "type": "ByteArray",
              "value": "5c2721a33bf665880fb2c1c0d504d92dcfe1616f"
            }
          ]
        }
      },
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "6b79635f726567697374726174696f6e"
            },
            {
              "type": "ByteArray",
              "value": "03a8b007549dd4d19f367d6b71ed5c6fe9aa8272"
            }
          ]
        }
      },
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "6b79635f726567697374726174696f6e"
            },
            {
              "type": "ByteArray",
              "value": "98d3602f1e4f5ba179481398e55593862a0df92c"
            }
          ]
        }
      },
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "6b79635f726567697374726174696f6e"
            },
            {
              "type": "ByteArray",
              "value": "62b9d04e2d8b2a989d72c3c9478c18f2ef714cf2"
            }
          ]
        }
      },
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "6b79635f726567697374726174696f6e"
            },
            {
              "type": "ByteArray",
              "value": "c2c1bac70b182dbf8434323013c72d66c57591d8"
            }
          ]
        }
      },
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "6b79635f726567697374726174696f6e"
            },
            {
              "type": "ByteArray",
              "value": "49b197c38b07107c7ac4097ba47c1c9c39a04409"
            }
          ]
        }
      },
      {
        "contract": "0x2e25d2127e0240c6deaf35394702feb236d4d7fc",
        "state": {
          "type": "Array",
          "value": [
            {
              "type": "ByteArray",
              "value": "6b79635f726567697374726174696f6e"
            },
            {
              "type": "ByteArray",
              "value": "dbfae7df8d49ad1319079604318ba12252ace7f1"
            }
          ]
        }
      }
    ]
  }
}

[brianlenz]

That confirms it. Transaction failed due to out of gas. It was supposed to have processed 25 more addresses, but failed after 7.

Thanks for all of your help diagnosing, @erikzhang! 👍