aries-agent-test-harness
aries-agent-test-harness copied to clipboard
hyperledger
ACA-Py Backchannel using main with Poetry not working
I think I have figured out what is wrong with the ACA-Py Backchannel since the change to use Poetry in ACA-Py. There is a fix in AATH that gets around the problem, but I think I know where the problem is -- although not enough about Python to know why. I'm hoping those that know Python can help.
Recall:
- ACA-Py switched from using PIP to Poetry for requirements. In doing that, the file
bin/aca-pywas removed from the source code, and instead it is (AFAIK) created as part of the requirements processing. - AATH test runs immediately started failing -- the first couple of tests would pass, but subsequent ones would fail.
- It was determined that it was failing because the backchannel is restarting ACA-Py at the start of some tests, and the restart was failing because of a problem with
bin/aca-py - A theory was that the
aca-pybinary was not in/usr/local/bin/aca-pyafter requirements processing as was expected, and so the AATH was not able to put it into the expected place. - A solution was implemented #727 that added the
bin/aca-pyinto the AATH codebase and in the dockerfile, putting it into the place expected by the ACA-Py backchannel -- and things started working again. - But later we found that the
aca-pybin was in/usr/local/binand it was thought that "undoing" the #727 solution would be OK. That was tested and it didn't work.
What I now think is the issue is that the contents of aca-py produced since the Poetry change is different than the "old way" (and the one is #727), and the real problem is that the way the ACA-Py Backchannel invokes ACA-Py doesn't work with the new aca-py.
To demonstrate that:
- I replaced the
aca-pybin added to AATH in #727 with the one generated by ACA-Py now, and it failed in the same way.
Looking for help as to why this doesn't work:
- Here's the contents of the file generated by ACA-Py and that doesn't wor:
#!/usr/local/bin/python
# -*- coding: utf-8 -*-
import re
import sys
from aries_cloudagent.__main__ import script_main
if __name__ == '__main__':
sys.argv[0] = re.sub(r'(-script\.pyw|\.exe)?$', '', sys.argv[0])
sys.exit(script_main())
- Here's the contents of the file that used to be ACA-Py, and is now being used in AATH (as of #727 )
#!/bin/sh
if [ -z "$PYTHON" ]; then
PYTHON=`command -v python3`
if [ -z "$PYTHON" ]; then
PYTHON=python
fi
fi
$PYTHON -m aries_cloudagent "$@"
- Here is the invocation in the Aries Backchannel that is failing:
subprocess.TimeoutExpired: Command '['./bin/aca-py', 'start', '--label', 'aca-py.Acme', '--admin', '0.0.0.0', '9022', '--admin-insecure-mode', '--public-invites', '--wallet-type', 'askar', '--wallet-name', 'aca-py.acme814895', '--wallet-key', 'aca-py.Acme814895', '--monitor-revocation-notification', '--requests-through-public-did', '--notify-revocation', '--open-mediation', '--enable-undelivered-queue', '--preserve-exchange-records', '--auto-provision', '--recreate-wallet', '--genesis-transactions', '{"reqSignature":{},"txn":{"data":{"data":{"alias":"Node1","blskey":"4N8aUNHSgjQVgkpm8nhNEfDf6txHznoYREg9kirmJrkivgL4oSEimFF6nsQ6M41QvhM2Z33nves5vfSn9n1UwNFJBYtWVnHYMATn76vLuL3zU88KyeAYcHfsih3He6UHcXDxcaecHVz6jhCYz1P2UZn2bDVruL5wXpehgBfBaLKm3Ba","blskey_pop":"RahHYiCvoNCtPTrVtP7nMC5eTYrsUA8WjXbdhNc8debh1agE9bGiJxWBXYNFbnJXoXhWFMvyqhqhRoq737YQemH5ik9oL7R4NTTCz2LEZhkgLJzB3QRQqJyBNyv7acbdHrAT8nQ9UkLbaVL9NBpnWXBTw4LEMePaSHEw66RzPNdAX1","client_ip":"172.17.0.1","client_port":9702,"node_ip":"172.17.0.1","node_port":9701,"services":["VALIDATOR"]},"dest":"Gw6pDLhcBcoQesN72qfotTgFa7cbuqZpkX3Xo6pLhPhv"},"metadata":{"from":"Th7MpTaRZVRYnPiabds81Y"},"type":"0"},"txnMetadata":{"seqNo":1,"txnId":"fea82e10e894419fe2bea7d96296a6d46f50f93f9eeda954ec461b2ed2950b62"},"ver":"1"}\n{"reqSignature":{},"txn":{"data":{"data":{"alias":"Node2","blskey":"37rAPpXVoxzKhz7d9gkUe52XuXryuLXoM6P6LbWDB7LSbG62Lsb33sfG7zqS8TK1MXwuCHj1FKNzVpsnafmqLG1vXN88rt38mNFs9TENzm4QHdBzsvCuoBnPH7rpYYDo9DZNJePaDvRvqJKByCabubJz3XXKbEeshzpz4Ma5QYpJqjk","blskey_pop":"Qr658mWZ2YC8JXGXwMDQTzuZCWF7NK9EwxphGmcBvCh6ybUuLxbG65nsX4JvD4SPNtkJ2w9ug1yLTj6fgmuDg41TgECXjLCij3RMsV8CwewBVgVN67wsA45DFWvqvLtu4rjNnE9JbdFTc1Z4WCPA3Xan44K1HoHAq9EVeaRYs8zoF5","client_ip":"172.17.0.1","client_port":9704,"node_ip":"172.17.0.1","node_port":9703,"services":["VALIDATOR"]},"dest":"8ECVSk179mjsjKRLWiQtssMLgp6EPhWXtaYyStWPSGAb"},"metadata":{"from":"EbP4aYNeTHL6q385GuVpRV"},"type":"0"},"txnMetadata":{"seqNo":2,"txnId":"1ac8aece2a18ced660fef8694b61aac3af08ba875ce3026a160acbc3a3af35fc"},"ver":"1"}\n{"reqSignature":{},"txn":{"data":{"data":{"alias":"Node3","blskey":"3WFpdbg7C5cnLYZwFZevJqhubkFALBfCBBok15GdrKMUhUjGsk3jV6QKj6MZgEubF7oqCafxNdkm7eswgA4sdKTRc82tLGzZBd6vNqU8dupzup6uYUf32KTHTPQbuUM8Yk4QFXjEf2Usu2TJcNkdgpyeUSX42u5LqdDDpNSWUK5deC5","blskey_pop":"QwDeb2CkNSx6r8QC8vGQK3GRv7Yndn84TGNijX8YXHPiagXajyfTjoR87rXUu4G4QLk2cF8NNyqWiYMus1623dELWwx57rLCFqGh7N4ZRbGDRP4fnVcaKg1BcUxQ866Ven4gw8y4N56S5HzxXNBZtLYmhGHvDtk6PFkFwCvxYrNYjh","client_ip":"172.17.0.1","client_port":9706,"node_ip":"172.17.0.1","node_port":9705,"services":["VALIDATOR"]},"dest":"DKVxG2fXXTU8yT5N7hGEbXB3dfdAnYv1JczDUHpmDxya"},"metadata":{"from":"4cU41vWW82ArfxJxHkzXPG"},"type":"0"},"txnMetadata":{"seqNo":3,"txnId":"7e9f355dffa78ed24668f0e0e369fd8c224076571c51e2ea8be5f26479edebe4"},"ver":"1"}\n{"reqSignature":{},"txn":{"data":{"data":{"alias":"Node4","blskey":"2zN3bHM1m4rLz54MJHYSwvqzPchYp8jkHswveCLAEJVcX6Mm1wHQD1SkPYMzUDTZvWvhuE6VNAkK3KxVeEmsanSmvjVkReDeBEMxeDaayjcZjFGPydyey1qxBHmTvAnBKoPydvuTAqx5f7YNNRAdeLmUi99gERUU7TD8KfAa6MpQ9bw","blskey_pop":"RPLagxaR5xdimFzwmzYnz4ZhWtYQEj8iR5ZU53T2gitPCyCHQneUn2Huc4oeLd2B2HzkGnjAff4hWTJT6C7qHYB1Mv2wU5iHHGFWkhnTX9WsEAbunJCV2qcaXScKj4tTfvdDKfLiVuU2av6hbsMztirRze7LvYBkRHV3tGwyCptsrP","client_ip":"172.17.0.1","client_port":9708,"node_ip":"172.17.0.1","node_port":9707,"services":["VALIDATOR"]},"dest":"4PS3EDQ3dW1tci1Bp6543CfuuebjFrg36kLAUcskGfaA"},"metadata":{"from":"TWwCRQRZ2ZHMJFn9TzLp7W"},"type":"0"},"txnMetadata":{"seqNo":4,"txnId":"aa5e817d7cc626170eca175822029339a444eb0ee8f0bd20d3b0b76e566fb008"},"ver":"1"}', '--seed', 'd_000000000000000000000000814895', '--storage-type', 'askar', '--webhook-url', 'http://172.17.0.1:9023/webhooks', '--tails-server-base-url', 'http://172.17.0.1:6543', '--plugin', 'universal_resolver', '--plugin-config', '/data-mount/plugin-config.yml', '--plugin', 'redis_queue.v1_0.events', '--plugin-config', '/data-mount/plugin-config.yml', '--log-level', 'DEBUG', '--endpoint', 'http://172.17.0.1:9021', '--inbound-transport', 'http', '0.0.0.0', '9021', '--outbound-transport', 'http']' timed out after 0.5 seconds
Am I reading it right that in the Poetry-generated bin file, only argv[0] is sent and other arguments are ignored?
Just guessing, haven't checked it out yet...
Either the subprocess doesn't have access to /usr/local/bin/python or name is not main (__name__ == '__main__')
To look around what is installed, you can:
./manage build -a acapy-main./manage start -d acapy-main. # Starts everything, but doesn’t run any testsdocker exec -i -t acme-agent /bin/bash
In loking around I can see that /usr/local/bin/python is there and is version 3.9 right now.
I don’t know enough to know about what name may or may not be main.
For fun, I went formatted the command that failed (from the log, earlier comment) so I could run it from the command line:
./bin/aca-py start --label aca-py.Acme --admin 0.0.0.0 9022 --admin-insecure-mode --public-invites --wallet-type askar --wallet-name aca-py.acme814895 --wallet-key aca-py.Acme814895 --monitor-revocation-notification --requests-through-public-did --notify-revocation --open-mediation --enable-undelivered-queue --preserve-exchange-records --auto-provision --recreate-wallet --storage-type askar --webhook-url http://172.17.0.1:9023/webhooks --tails-server-base-url http://172.17.0.1:6543 --plugin universal_resolver --plugin-config /data-mount/plugin-config.yml --plugin redis_queue.v1_0.events --plugin-config /data-mount/plugin-config.yml --log-level DEBUG --endpoint http://172.17.0.1:9021 --inbound-transport http 0.0.0.0 9021 --outbound-transport http --no-ledger
And it ran…
I left off the genesis file (using —no-ledger) instead, although I might try to run it with genesis file as well. Weird...
Tried it with this command and got — bash: ./bin/aca-py: Argument list too long. but I assume that is a bash issue...
./bin/aca-py start --label aca-py.Acme --admin 0.0.0.0 9022 --admin-insecure-mode --public-invites --wallet-type askar --wallet-name aca-py.acme814895 --wallet-key aca-py.Acme814895 --monitor-revocation-notification --requests-through-public-did --notify-revocation --open-mediation --enable-undelivered-queue --preserve-exchange-records --auto-provision --recreate-wallet --storage-type askar --webhook-url http://172.17.0.1:9023/webhooks --tails-server-base-url http://172.17.0.1:6543 --plugin universal_resolver --plugin-config /data-mount/plugin-config.yml --plugin redis_queue.v1_0.events --plugin-config /data-mount/plugin-config.yml --log-level DEBUG --endpoint http://172.17.0.1:9021 --inbound-transport http 0.0.0.0 9021 --outbound-transport http --genesis-transactions {"reqSignature":{},"txn":{"data":{"data":{"alias":"Node1","blskey":"4N8aUNHSgjQVgkpm8nhNEfDf6txHznoYREg9kirmJrkivgL4oSEimFF6nsQ6M41QvhM2Z33nves5vfSn9n1UwNFJBYtWVnHYMATn76vLuL3zU88KyeAYcHfsih3He6UHcXDxcaecHVz6jhCYz1P2UZn2bDVruL5wXpehgBfBaLKm3Ba","blskey_pop":"RahHYiCvoNCtPTrVtP7nMC5eTYrsUA8WjXbdhNc8debh1agE9bGiJxWBXYNFbnJXoXhWFMvyqhqhRoq737YQemH5ik9oL7R4NTTCz2LEZhkgLJzB3QRQqJyBNyv7acbdHrAT8nQ9UkLbaVL9NBpnWXBTw4LEMePaSHEw66RzPNdAX1","client_ip":"172.17.0.1","client_port":9702,"node_ip":"172.17.0.1","node_port":9701,"services":["VALIDATOR"]},"dest":"Gw6pDLhcBcoQesN72qfotTgFa7cbuqZpkX3Xo6pLhPhv"},"metadata":{"from":"Th7MpTaRZVRYnPiabds81Y"},"type":"0"},"txnMetadata":{"seqNo":1,"txnId":"fea82e10e894419fe2bea7d96296a6d46f50f93f9eeda954ec461b2ed2950b62"},"ver":"1"}\n{"reqSignature":{},"txn":{"data":{"data":{"alias":"Node2","blskey":"37rAPpXVoxzKhz7d9gkUe52XuXryuLXoM6P6LbWDB7LSbG62Lsb33sfG7zqS8TK1MXwuCHj1FKNzVpsnafmqLG1vXN88rt38mNFs9TENzm4QHdBzsvCuoBnPH7rpYYDo9DZNJePaDvRvqJKByCabubJz3XXKbEeshzpz4Ma5QYpJqjk","blskey_pop":"Qr658mWZ2YC8JXGXwMDQTzuZCWF7NK9EwxphGmcBvCh6ybUuLxbG65nsX4JvD4SPNtkJ2w9ug1yLTj6fgmuDg41TgECXjLCij3RMsV8CwewBVgVN67wsA45DFWvqvLtu4rjNnE9JbdFTc1Z4WCPA3Xan44K1HoHAq9EVeaRYs8zoF5","client_ip":"172.17.0.1","client_port":9704,"node_ip":"172.17.0.1","node_port":9703,"services":["VALIDATOR"]},"dest":"8ECVSk179mjsjKRLWiQtssMLgp6EPhWXtaYyStWPSGAb"},"metadata":{"from":"EbP4aYNeTHL6q385GuVpRV"},"type":"0"},"txnMetadata":{"seqNo":2,"txnId":"1ac8aece2a18ced660fef8694b61aac3af08ba875ce3026a160acbc3a3af35fc"},"ver":"1"}\n{"reqSignature":{},"txn":{"data":{"data":{"alias":"Node3","blskey":"3WFpdbg7C5cnLYZwFZevJqhubkFALBfCBBok15GdrKMUhUjGsk3jV6QKj6MZgEubF7oqCafxNdkm7eswgA4sdKTRc82tLGzZBd6vNqU8dupzup6uYUf32KTHTPQbuUM8Yk4QFXjEf2Usu2TJcNkdgpyeUSX42u5LqdDDpNSWUK5deC5","blskey_pop":"QwDeb2CkNSx6r8QC8vGQK3GRv7Yndn84TGNijX8YXHPiagXajyfTjoR87rXUu4G4QLk2cF8NNyqWiYMus1623dELWwx57rLCFqGh7N4ZRbGDRP4fnVcaKg1BcUxQ866Ven4gw8y4N56S5HzxXNBZtLYmhGHvDtk6PFkFwCvxYrNYjh","client_ip":"172.17.0.1","client_port":9706,"node_ip":"172.17.0.1","node_port":9705,"services":["VALIDATOR"]},"dest":"DKVxG2fXXTU8yT5N7hGEbXB3dfdAnYv1JczDUHpmDxya"},"metadata":{"from":"4cU41vWW82ArfxJxHkzXPG"},"type":"0"},"txnMetadata":{"seqNo":3,"txnId":"7e9f355dffa78ed24668f0e0e369fd8c224076571c51e2ea8be5f26479edebe4"},"ver":"1"}\n{"reqSignature":{},"txn":{"data":{"data":{"alias":"Node4","blskey":"2zN3bHM1m4rLz54MJHYSwvqzPchYp8jkHswveCLAEJVcX6Mm1wHQD1SkPYMzUDTZvWvhuE6VNAkK3KxVeEmsanSmvjVkReDeBEMxeDaayjcZjFGPydyey1qxBHmTvAnBKoPydvuTAqx5f7YNNRAdeLmUi99gERUU7TD8KfAa6MpQ9bw","blskey_pop":"RPLagxaR5xdimFzwmzYnz4ZhWtYQEj8iR5ZU53T2gitPCyCHQneUn2Huc4oeLd2B2HzkGnjAff4hWTJT6C7qHYB1Mv2wU5iHHGFWkhnTX9WsEAbunJCV2qcaXScKj4tTfvdDKfLiVuU2av6hbsMztirRze7LvYBkRHV3tGwyCptsrP","client_ip":"172.17.0.1","client_port":9708,"node_ip":"172.17.0.1","node_port":9707,"services":["VALIDATOR"]},"dest":"4PS3EDQ3dW1tci1Bp6543CfuuebjFrg36kLAUcskGfaA"},"metadata":{"from":"TWwCRQRZ2ZHMJFn9TzLp7W"},"type":"0"},"txnMetadata":{"seqNo":4,"txnId":"aa5e817d7cc626170eca175822029339a444eb0ee8f0bd20d3b0b76e566fb008"},"ver":"1"} --seed d_000000000000000000000000814895
Yes, "Argument list too long" is bash - usually for file listing commands. Anyway, that is a good find! In a bash shell I can get that error using all the parameters and passing it to python -m aries_cloudagent too... maybe there is a reason that act-py script is running in the bare/system shell (bin/sh).
From a bash shell...
exec sh
$ python -m aries_cloudagent start <all the parameters>
...
Traceback (most recent call last):
File "/usr/local/lib/python3.9/runpy.py", line 197, in _run_module_as_main
return _run_code(code, main_globals, None,
File "/usr/local/lib/python3.9/runpy.py", line 87, in _run_code
exec(code, run_globals)
File "/workspaces/aries-cloudagent-python/aries_cloudagent/__main__.py", line 79, in <module>
script_main()
File "/workspaces/aries-cloudagent-python/aries_cloudagent/__main__.py", line 69, in script_main
main(sys.argv)
File "/workspaces/aries-cloudagent-python/aries_cloudagent/__main__.py", line 75, in main
run(args)
File "/workspaces/aries-cloudagent-python/aries_cloudagent/__main__.py", line 64, in run
run_command(command, args)
File "/workspaces/aries-cloudagent-python/aries_cloudagent/commands/__init__.py", line 38, in run_command
module.execute(argv)
File "/workspaces/aries-cloudagent-python/aries_cloudagent/commands/start.py", line 49, in execute
settings = get_settings(args)
File "/workspaces/aries-cloudagent-python/aries_cloudagent/config/argparse.py", line 94, in get_settings
settings.update(group.get_settings(args))
File "/workspaces/aries-cloudagent-python/aries_cloudagent/config/argparse.py", line 672, in get_settings
with open(args.plugin_config, "r") as stream:
FileNotFoundError: [Errno 2] No such file or directory: '/data-mount/plugin-config.yml'
Which is cool, the argument list is parsed, I just don't have the files around. So I think you've landed on the underlying issue and we cannot use bash to start with that many arguements, we need the system shell!
I don’t think that is it. I think it is what is different between the two versions of aca-py main. What do they do that is different?
the old one, the one we are copying in spawns a system shell #!/bin/sh, the newer one (the one poetry generates) just uses python (apparently in a bash shell with that Argument error).
I guess we can do a little test where we change the old script to be a bash script and see if that argument list error happens...
Sounds good. I’m running now with the dockerfile using sh instead of bash.
what command are you running the tests with?
currently, (locally) looks successful using bash when I run: ./manage runset acapy (after building)...
which I guess disproves the theory that the shell matters...
#!/bin/bash
if [ -z "$PYTHON" ]; then
PYTHON=`command -v python3`
if [ -z "$PYTHON" ]; then
PYTHON=python
fi
fi
$PYTHON -m aries_cloudagent "$@"
Yes — that’s the fix you did to get things working again — using the old script from pre-Poetry days in ACA-Py.
What I tried was change that script to be the new script from ACA-Py and that failed.
ah, gotcha. kind of at a loss then I suppose. since AATH is a fairly unique use case - spawning acapy in subprocesses - that we just live with AATH having it's own way of launching (the old script)?
Its why I’ve said don’t worry about it :-). I’ve been trying things in the background though, and I think I might have found a solution. Uses the script from ACA-Py (so we’ll get changes as they occur — which is what I want), but has a slightly different invocation mechanism. PR pending. Still don’t really know why it works though...
