Error: Ledger merkle tree doesn't acceptable for current tree

[kazarena]

Hi,

I'm trying to use the Python wrapper against the master of hyperledger/indy-node and it fails consistently when running open_pool_ledger. Initially I though there's something wrong with my Python code, but then I tried running the code from samples and got the same error: Ledger merkle tree doesn't acceptable for current tree:

cd samples/python
python3 src/main.py

Error:

...
 INFO|indy::services::pool          |           src/services/pool/mod.rs:544 | RemoteNode::send_str Node1 {"op":"LEDGER_STATUS","txnSeqNo":4,"merkleRoot":"EBEbqTXvTpgJ6z6W9YGme41TdcnWW6AQjqXt7duTnbRP","ledgerId":0,"ppSeqNo":null,"viewNo":null}
TRACE|indy::services::pool          |           src/services/pool/mod.rs:246 | zmq poll loop <<
TRACE|indy::services::pool          |           src/services/pool/mod.rs:240 | zmq poll loop >>
TRACE|indy::services::pool          |           src/services/pool/mod.rs:348 | get_zmq_poll_timeout first_event Tm { tm_sec: 21, tm_min: 59, tm_hour: 16, tm_mday: 15, tm_mon: 1, tm_year: 118, tm_wday: 4, tm_yday: 45, tm_isdst: 0, tm_utcoff: 0, tm_nsec: 454409000 }
TRACE|indy::services::pool          |           src/services/pool/mod.rs:349 | get_zmq_poll_timeout now_utc Tm { tm_sec: 31, tm_min: 58, tm_hour: 16, tm_mday: 15, tm_mon: 1, tm_year: 118, tm_wday: 4, tm_yday: 45, tm_isdst: 0, tm_utcoff: 0, tm_nsec: 534605000 }
TRACE|indy::services::pool          |           src/services/pool/mod.rs:351 | get_zmq_poll_timeout diff Duration Duration { secs: 49, nanos: 919804000 }
TRACE|indy::services::pool          |           src/services/pool/mod.rs:353 | get_zmq_poll_timeout diff ms 49919
TRACE|indy::services::pool          |           src/services/pool/mod.rs:293 | zmq poll 2
 INFO|indy::services::pool          |           src/services/pool/mod.rs:538 | RemoteNode::recv_msg Node4 {"viewNo":null,"op":"LEDGER_STATUS","ledgerId":0,"merkleRoot":"FTH83QNd84mnaXFD8vQdRHbRmmkZqz22pbHFjzy9mYt1","ppSeqNo":null,"txnSeqNo":4}
 INFO|indy::services::pool          |           src/services/pool/mod.rs:538 | RemoteNode::recv_msg Node3 {"merkleRoot":"FTH83QNd84mnaXFD8vQdRHbRmmkZqz22pbHFjzy9mYt1","ledgerId":0,"viewNo":null,"ppSeqNo":null,"op":"LEDGER_STATUS","txnSeqNo":4}
TRACE|indy::services::pool          |           src/services/pool/mod.rs:244 | process_actions - Invalid library state: Ledger merkle tree doesn't acceptable for current tree.
ERROR|indy::services::pool          |           src/services/pool/mod.rs:426 | Pool worker thread finished with error CommonError(InvalidState("Ledger merkle tree doesn\'t acceptable for current tree."))
 INFO|indy::commands                |                src/commands/mod.rs:99  | PoolCommand command received
 INFO|indy::commands::pool          |               src/commands/pool.rs:68  | OpenAck handle 4, pool_id 5, result Err(CommonError(InvalidState("Ledger merkle tree doesn\'t acceptable for current tree.")))
ERROR|indy::errors::indy            |                 src/errors/indy.rs:68  | Casting error to ErrorCode: Invalid library state: Ledger merkle tree doesn't acceptable for current tree.
WARNING:indy.libindy:_indy_loop_callback: Function returned error 112
Traceback (most recent call last):
  File "src/main.py", line 15, in <module>
    loop.run_until_complete(main())
  File "/usr/local/Cellar/python3/3.6.4_2/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/base_events.py", line 467, in run_until_complete
    return future.result()
  File "src/main.py", line 10, in main
    await ledger.demo()
  File "/Users/me/Projects/hyperledger/indy-sdk/samples/python/src/ledger.py", line 24, in demo
    pool_handle = await pool.open_pool_ledger(pool_name, None)
  File "/Users/me/Projects/hyperledger/indy-sdk/wrappers/python/indy/pool.py", line 82, in open_pool_ledger
    open_pool_ledger.cb)
indy.error.IndyError: ErrorCode.CommonInvalidState

Background

• I'm on OSX
• I have Indy running locally, following the instructions from https://github.com/hyperledger/indy-node/blob/master/environment/docker/pool/README.md with default parameters
• I compiled libindy as described in https://github.com/hyperledger/indy-sdk/blob/master/doc/mac-build.md and the build completed successfully
• I pointed at my local build/check-out of indy-sdk using LD_LIBRARY_PATH and PYTHONPATH

I tried many different ways of connecting to Indy using the Python wrapper but it always fails with CommonInvalidState.

I found this issue report: https://jira.hyperledger.org/browse/IS-355?page=com.atlassian.streams.streams-jira-plugin%3Aactivity-stream-issue-tab

My suspicion is that the version of indy-crypto may be inconsistent between indy-sdk and indy-node, but I can't see the way to roll it back for indy-sdk without losing the whole lot of recent changes.

Any guidance how to fix it would be highly appreciated.

Stan

[vimmerru]

I suggest to compare genesis transactions of ledger and genesis transactions of client you use. Most probable Node IPs are different.

Nodes use 10.0.0.2 ip from internal interface inside of VirtualBox, but most probable you are trying to connect to 127.0.0.1 ips.

[kazarena]

Thank you, @vimmerru. I'm using the environment variable TEST_POOL_IP to override the IPs to my docker IP.

Apologies, I'm new to Indy. Do I understand your recommendation correctly, that the transactions defined in https://github.com/hyperledger/indy-sdk/blob/master/samples/python/src/utils.py (see below)

def pool_genesis_txn_data():
    pool_ip = environ.get("TEST_POOL_IP", "127.0.0.1")

    return "\n".join([
        '{{"data":{{"alias":"Node1","blskey":"4N8aUNHSgjQVgkpm8nhNEfDf6txHznoYREg9kirmJrkivgL4oSEimFF6nsQ6M41QvhM2Z33nves5vfSn9n1UwNFJBYtWVnHYMATn76vLuL3zU88KyeAYcHfsih3He6UHcXDxcaecHVz6jhCYz1P2UZn2bDVruL5wXpehgBfBaLKm3Ba","client_ip":"{}","client_port":9702,"node_ip":"{}","node_port":9701,"services":["VALIDATOR"]}},"dest":"Gw6pDLhcBcoQesN72qfotTgFa7cbuqZpkX3Xo6pLhPhv","identifier":"Th7MpTaRZVRYnPiabds81Y","txnId":"fea82e10e894419fe2bea7d96296a6d46f50f93f9eeda954ec461b2ed2950b62","type":"0"}}'.format(
            pool_ip, pool_ip),
        '{{"data":{{"alias":"Node2","blskey":"37rAPpXVoxzKhz7d9gkUe52XuXryuLXoM6P6LbWDB7LSbG62Lsb33sfG7zqS8TK1MXwuCHj1FKNzVpsnafmqLG1vXN88rt38mNFs9TENzm4QHdBzsvCuoBnPH7rpYYDo9DZNJePaDvRvqJKByCabubJz3XXKbEeshzpz4Ma5QYpJqjk","client_ip":"{}","client_port":9704,"node_ip":"{}","node_port":9703,"services":["VALIDATOR"]}},"dest":"8ECVSk179mjsjKRLWiQtssMLgp6EPhWXtaYyStWPSGAb","identifier":"EbP4aYNeTHL6q385GuVpRV","txnId":"1ac8aece2a18ced660fef8694b61aac3af08ba875ce3026a160acbc3a3af35fc","type":"0"}}'.format(
            pool_ip, pool_ip),
        '{{"data":{{"alias":"Node3","blskey":"3WFpdbg7C5cnLYZwFZevJqhubkFALBfCBBok15GdrKMUhUjGsk3jV6QKj6MZgEubF7oqCafxNdkm7eswgA4sdKTRc82tLGzZBd6vNqU8dupzup6uYUf32KTHTPQbuUM8Yk4QFXjEf2Usu2TJcNkdgpyeUSX42u5LqdDDpNSWUK5deC5","client_ip":"{}","client_port":9706,"node_ip":"{}","node_port":9705,"services":["VALIDATOR"]}},"dest":"DKVxG2fXXTU8yT5N7hGEbXB3dfdAnYv1JczDUHpmDxya","identifier":"4cU41vWW82ArfxJxHkzXPG","txnId":"7e9f355dffa78ed24668f0e0e369fd8c224076571c51e2ea8be5f26479edebe4","type":"0"}}'.format(
            pool_ip, pool_ip),
        '{{"data":{{"alias":"Node4","blskey":"2zN3bHM1m4rLz54MJHYSwvqzPchYp8jkHswveCLAEJVcX6Mm1wHQD1SkPYMzUDTZvWvhuE6VNAkK3KxVeEmsanSmvjVkReDeBEMxeDaayjcZjFGPydyey1qxBHmTvAnBKoPydvuTAqx5f7YNNRAdeLmUi99gERUU7TD8KfAa6MpQ9bw","client_ip":"{}","client_port":9708,"node_ip":"{}","node_port":9707,"services":["VALIDATOR"]}},"dest":"4PS3EDQ3dW1tci1Bp6543CfuuebjFrg36kLAUcskGfaA","identifier":"TWwCRQRZ2ZHMJFn9TzLp7W","txnId":"aa5e817d7cc626170eca175822029339a444eb0ee8f0bd20d3b0b76e566fb008","type":"0"}}'.format(
            pool_ip, pool_ip)
    ])

don't match the genesis transactions in the Indy instance as defined in https://github.com/hyperledger/indy-node/blob/master/environment/docker/pool/?

[kazarena]

Update:

Here are the pool transactions taken from the ledger node (Node1, /home/indy/.indy-cli/networks/sandbox/pool_transactions_genesis):

{"data":{"alias":"Node1","blskey":"4N8aUNHSgjQVgkpm8nhNEfDf6txHznoYREg9kirmJrkivgL4oSEimFF6nsQ6M41QvhM2Z33nves5vfSn9n1UwNFJBYtWVnHYMATn76vLuL3zU88KyeAYcHfsih3He6UHcXDxcaecHVz6jhCYz1P2UZn2bDVruL5wXpehgBfBaLKm3Ba","client_ip":"10.0.0.2","client_port":9702,"node_ip":"10.0.0.2","node_port":9701,"services":["VALIDATOR"]},"dest":"Gw6pDLhcBcoQesN72qfotTgFa7cbuqZpkX3Xo6pLhPhv","identifier":"Th7MpTaRZVRYnPiabds81Y","txnId":"fea82e10e894419fe2bea7d96296a6d46f50f93f9eeda954ec461b2ed2950b62","type":"0"}
{"data":{"alias":"Node2","blskey":"37rAPpXVoxzKhz7d9gkUe52XuXryuLXoM6P6LbWDB7LSbG62Lsb33sfG7zqS8TK1MXwuCHj1FKNzVpsnafmqLG1vXN88rt38mNFs9TENzm4QHdBzsvCuoBnPH7rpYYDo9DZNJePaDvRvqJKByCabubJz3XXKbEeshzpz4Ma5QYpJqjk","client_ip":"10.0.0.3","client_port":9704,"node_ip":"10.0.0.3","node_port":9703,"services":["VALIDATOR"]},"dest":"8ECVSk179mjsjKRLWiQtssMLgp6EPhWXtaYyStWPSGAb","identifier":"EbP4aYNeTHL6q385GuVpRV","txnId":"1ac8aece2a18ced660fef8694b61aac3af08ba875ce3026a160acbc3a3af35fc","type":"0"}
{"data":{"alias":"Node3","blskey":"3WFpdbg7C5cnLYZwFZevJqhubkFALBfCBBok15GdrKMUhUjGsk3jV6QKj6MZgEubF7oqCafxNdkm7eswgA4sdKTRc82tLGzZBd6vNqU8dupzup6uYUf32KTHTPQbuUM8Yk4QFXjEf2Usu2TJcNkdgpyeUSX42u5LqdDDpNSWUK5deC5","client_ip":"10.0.0.4","client_port":9706,"node_ip":"10.0.0.4","node_port":9705,"services":["VALIDATOR"]},"dest":"DKVxG2fXXTU8yT5N7hGEbXB3dfdAnYv1JczDUHpmDxya","identifier":"4cU41vWW82ArfxJxHkzXPG","txnId":"7e9f355dffa78ed24668f0e0e369fd8c224076571c51e2ea8be5f26479edebe4","type":"0"}
{"data":{"alias":"Node4","blskey":"2zN3bHM1m4rLz54MJHYSwvqzPchYp8jkHswveCLAEJVcX6Mm1wHQD1SkPYMzUDTZvWvhuE6VNAkK3KxVeEmsanSmvjVkReDeBEMxeDaayjcZjFGPydyey1qxBHmTvAnBKoPydvuTAqx5f7YNNRAdeLmUi99gERUU7TD8KfAa6MpQ9bw","client_ip":"10.0.0.5","client_port":9708,"node_ip":"10.0.0.5","node_port":9707,"services":["VALIDATOR"]},"dest":"4PS3EDQ3dW1tci1Bp6543CfuuebjFrg36kLAUcskGfaA","identifier":"TWwCRQRZ2ZHMJFn9TzLp7W","txnId":"aa5e817d7cc626170eca175822029339a444eb0ee8f0bd20d3b0b76e566fb008","type":"0"}

And this is what https://github.com/hyperledger/indy-sdk/blob/master/samples/python/src/utils.py generates when I run the samples (~/.indy_client/pool/pool1/pool1.txn):

{"data":{"alias":"Node1","blskey":"4N8aUNHSgjQVgkpm8nhNEfDf6txHznoYREg9kirmJrkivgL4oSEimFF6nsQ6M41QvhM2Z33nves5vfSn9n1UwNFJBYtWVnHYMATn76vLuL3zU88KyeAYcHfsih3He6UHcXDxcaecHVz6jhCYz1P2UZn2bDVruL5wXpehgBfBaLKm3Ba","client_ip":"192.168.149.128","client_port":9702,"node_ip":"192.168.149.128","node_port":9701,"services":["VALIDATOR"]},"dest":"Gw6pDLhcBcoQesN72qfotTgFa7cbuqZpkX3Xo6pLhPhv","identifier":"Th7MpTaRZVRYnPiabds81Y","txnId":"fea82e10e894419fe2bea7d96296a6d46f50f93f9eeda954ec461b2ed2950b62","type":"0"}
{"data":{"alias":"Node2","blskey":"37rAPpXVoxzKhz7d9gkUe52XuXryuLXoM6P6LbWDB7LSbG62Lsb33sfG7zqS8TK1MXwuCHj1FKNzVpsnafmqLG1vXN88rt38mNFs9TENzm4QHdBzsvCuoBnPH7rpYYDo9DZNJePaDvRvqJKByCabubJz3XXKbEeshzpz4Ma5QYpJqjk","client_ip":"192.168.149.128","client_port":9704,"node_ip":"192.168.149.128","node_port":9703,"services":["VALIDATOR"]},"dest":"8ECVSk179mjsjKRLWiQtssMLgp6EPhWXtaYyStWPSGAb","identifier":"EbP4aYNeTHL6q385GuVpRV","txnId":"1ac8aece2a18ced660fef8694b61aac3af08ba875ce3026a160acbc3a3af35fc","type":"0"}
{"data":{"alias":"Node3","blskey":"3WFpdbg7C5cnLYZwFZevJqhubkFALBfCBBok15GdrKMUhUjGsk3jV6QKj6MZgEubF7oqCafxNdkm7eswgA4sdKTRc82tLGzZBd6vNqU8dupzup6uYUf32KTHTPQbuUM8Yk4QFXjEf2Usu2TJcNkdgpyeUSX42u5LqdDDpNSWUK5deC5","client_ip":"192.168.149.128","client_port":9706,"node_ip":"192.168.149.128","node_port":9705,"services":["VALIDATOR"]},"dest":"DKVxG2fXXTU8yT5N7hGEbXB3dfdAnYv1JczDUHpmDxya","identifier":"4cU41vWW82ArfxJxHkzXPG","txnId":"7e9f355dffa78ed24668f0e0e369fd8c224076571c51e2ea8be5f26479edebe4","type":"0"}
{"data":{"alias":"Node4","blskey":"2zN3bHM1m4rLz54MJHYSwvqzPchYp8jkHswveCLAEJVcX6Mm1wHQD1SkPYMzUDTZvWvhuE6VNAkK3KxVeEmsanSmvjVkReDeBEMxeDaayjcZjFGPydyey1qxBHmTvAnBKoPydvuTAqx5f7YNNRAdeLmUi99gERUU7TD8KfAa6MpQ9bw","client_ip":"192.168.149.128","client_port":9708,"node_ip":"192.168.149.128","node_port":9707,"services":["VALIDATOR"]},"dest":"4PS3EDQ3dW1tci1Bp6543CfuuebjFrg36kLAUcskGfaA","identifier":"TWwCRQRZ2ZHMJFn9TzLp7W","txnId":"aa5e817d7cc626170eca175822029339a444eb0ee8f0bd20d3b0b76e566fb008","type":"0"}

Everything seems to match, except the IP addresses (10.0.0.x is the Docker internal IP and 192.168.149.128 is the IP of my docker service on OSX)

Is there anything else I need to look at?

[vimmerru]

Everything seems to match, except the IP addresses (10.0.0.x is the Docker internal IP and 192.168.149.128 is the IP of my docker service on OSX)

Yes, and it is a cause of your problem. ip address must be the same.

[vimmerru]

IP is a part of Node transaction in pool ledger and present in merkle tree hashes.

[kazarena]

@vimmerru aha! So please correct me if I'm wrong, this means that if I wanted to run the Python client code against my test Indy instance (on OSX), I either need to do it inside a Docker container (so that I can use the internal IPs), or run Indy locally, and not through Docker?

And, forgive me for asking too many questions, is the hard-binding to the IP address done for security reasons? I'm just thinking about the implications in the future if there was ever a need to move Indy instances around.

[vimmerru]

The solution that we use:

1. Run all nodes inside of one docker container and use 127.0.0.1 address in genesis transactions
2. Use port mapping of local machine to docker ports and connect client to 127.0.0.1

You can use corresponded Docker config from indy-sdk repo: https://github.com/hyperledger/indy-sdk/blob/master/ci/indy-pool.dockerfile It runs all nodes in one container and by default uses 127.0.0.1 ip:

On windows the following commands will work:

docker build -f ci/indy-pool.dockerfile -t indy_pool .
docker run -itd -p 9701-9709:9701-9709 indy_pool

Please note that this port mapping between container and local host requires latest Docker for Windows (linux containers) and windows system with Hyper-V support.

On MacOS most probable you use some Docker distribution based on Virtual Box that can miss port mapping feature. You can use Virtual Box's port forwarding future to map 9701-9709 container ports to local 9701-9709 ports.

[kazarena]

@vimmerru Thank you, your suggestion works as a charm. I mapped the ports in VMWare Fusion by following the instructions from https://medium.com/@tuweizhong/how-to-setup-port-forward-at-vmware-fusion-8-for-os-x-742ad6ca1344 and adding the following to /Library/Preferences/VMware Fusion/vmnet8/nat.conf:

# Use these with care - anyone can enter into your VM through these...
# The format and example are as follows:
#<external port number> = <VM's IP address>:<VM's port number>
#8080 = 172.16.3.128:80
9709 = 192.168.149.128:9709
9707 = 192.168.149.128:9707
9702 = 192.168.149.128:9702
9701 = 192.168.149.128:9701
9708 = 192.168.149.128:9708
9703 = 192.168.149.128:9703
9704 = 192.168.149.128:9704
9706 = 192.168.149.128:9706
9705 = 192.168.149.128:9705

where 192.168.149.128 is my Docker host IP. Then, after rebooting my docker machine, the samples worked. There's another hicckup deep in the weeds (an exception at samples/python/src/getting_started.py, line 203), but that's a problem for another day.

Thank you so much for you help! We are planning to use Indy (and the SDK) in a proof-of-concept for our product. If everything goes well, we might even consider developing a wrapper for Golang. To be contributed to this project, if it happens.

Stan

[vimmerru]

@kazarena

Could you add this info to https://github.com/hyperledger/indy-sdk/blob/master/doc/mac-build.md instruction and send PR?

[kazarena]

@vimmerru will do

[kazarena]

@vimmerru Apologies for the delay. See my PR #632.