The result is different when using sandbox.sh and using cmd

[thempp66]

Describe the bug
We missed some files such as 0.pem when using sandbox.sh to start CCF Node. But it worked when we use the same command line to run. Could you give us some idea to solve this problem?

To Reproduce
Print the cmd var in remote.py and run it manually.

Expected behavior
Generate files such as 0.pem

Environment information
commit b21c981
ccf-3.0.0-dev1
Linux 0ed7cf5f0771 5.10.60-9.al8.x86_64 #1 SMP Mon Sep 6 21:30:37 CST 2021 x86_64 x86_64 x86_64 GNU/Linux

LINUX KERNEL WITH BUILT-IN SGX SUPPORT (5.11+):
5.10.60-9.al8.x86_64


AESM DAEMON:
Not running


PSW INFO:
libsgx-ae-id-enclave/unknown,now 1.14.100.3-focal1 amd64 [installed,automatic]
libsgx-ae-pce/unknown,now 2.17.100.3-focal1 amd64 [installed]
libsgx-ae-qe3/unknown,now 1.14.100.3-focal1 amd64 [installed]
libsgx-ae-qve/unknown,now 1.14.100.3-focal1 amd64 [installed]
libsgx-dcap-ql-dev/unknown,now 1.14.100.3-focal1 amd64 [installed]
libsgx-dcap-ql/unknown,now 1.14.100.3-focal1 amd64 [installed]
libsgx-enclave-common/unknown,now 2.17.100.3-focal1 amd64 [installed]
libsgx-headers/unknown,now 2.17.100.3-focal1 amd64 [installed,automatic]
libsgx-pce-logic/unknown,now 1.14.100.3-focal1 amd64 [installed]
libsgx-qe3-logic/unknown,now 1.14.100.3-focal1 amd64 [installed]
libsgx-quote-ex/unknown,now 2.17.100.3-focal1 amd64 [installed]
libsgx-urts/unknown,now 2.17.100.3-focal1 amd64 [installed]


DCAP CLIENT INFO:
az-dcap-client/now 1.11.2 amd64 [installed,upgradable to: 1.11.2]


SGX INFO:
CPU supports SGX_FLC:Flexible Launch Control
CPU supports Software Guard Extensions:SGX2
SGX1
MaxEnclaveSize_64: 2^(56)
CPU supports Key Sharing & Separation (KSS): true
EPC size on the platform: 33285996544

[thempp66]

This is the output by using sandbox.sh

2022-07-22T08:10:06.470185Z        100 [info ] ../src/host/main.cpp:108             | CCF version: ccf-2.0.0-rc1-285-gb21c9810
2022-07-22T08:10:06.470239Z        100 [info ] ../src/host/main.cpp:117             | Check Ethereum Gateway
2022-07-22T08:10:06.470250Z        100 [info ] ../src/host/main.cpp:123             | Gateway endpoint: 127.0.0.1:8545
2022-07-22T08:10:06.771433Z        100 [info ] ../src/host/main.cpp:159             | Recovery threshold unset. Defaulting to number of initial consortium members with a public encryption key (1).
2022-07-22T08:10:07.211706Z        100 [info ] ../CCF/src/host/ledger.h:1021        | Recovered ledger entries up to 0, committed to 0
2022-07-22T08:10:07.211815Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP Node Server listening on 127.0.0.1:44259
2022-07-22T08:10:07.211889Z        100 [info ] ../src/host/main.cpp:337             | Registering RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:10:07.211904Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP RPC Client listening on 127.0.0.1:8000
2022-07-22T08:10:07.211911Z        100 [info ] ../src/host/main.cpp:348             | Registered RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:10:07.211961Z        100 [info ] ../src/host/main.cpp:417             | Startup host time: 2022-07-22 08:10:07
2022-07-22T08:10:07.212082Z        100 [info ] ../src/host/main.cpp:465             | Creating new node: new network (with 1 initial member(s) and 1 member(s) required for recovery)
2022-07-22T08:10:07.212088Z        100 [info ] ../src/host/main.cpp:539             | Initialising enclave: enclave_create_node
2022-07-22T08:10:07.312432Z        0   [info ] ./CCF/src/enclave/rpc_sessions.h:223 | Setting max open sessions on interface "primary_rpc_interface" (127.0.0.1:8000) to [1000, 1010] and endorsement authority to Service
2022-07-22T08:10:07.312457Z        0   [info ] ../CCF/src/node/node_state.h:1862    | Node TLS connections now accepted

And this is the output by using command line

2022-07-22T08:11:08.721549Z        100 [info ] ../src/host/main.cpp:108             | CCF version: ccf-2.0.0-rc1-285-gb21c9810
2022-07-22T08:11:08.721601Z        100 [info ] ../src/host/main.cpp:117             | Check Ethereum Gateway
2022-07-22T08:11:08.721615Z        100 [info ] ../src/host/main.cpp:123             | Gateway endpoint: 127.0.0.1:8545
2022-07-22T08:11:09.022790Z        100 [info ] ../src/host/main.cpp:159             | Recovery threshold unset. Defaulting to number of initial consortium members with a public encryption key (1).
2022-07-22T08:11:09.468343Z        100 [info ] ../CCF/src/host/ledger.h:1021        | Recovered ledger entries up to 0, committed to 0
2022-07-22T08:11:09.468376Z        100 [info ] ../CCF/src/host/snapshots.h:216      | Snapshots will be stored in existing directory: "0.snapshots"
2022-07-22T08:11:09.468386Z        100 [info ] ./CCF/src/host/lfs_file_handler.h:23 | Clearing contents from existing directory ".index"
2022-07-22T08:11:09.468521Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP Node Server listening on 127.0.0.1:45521
2022-07-22T08:11:09.468617Z        100 [info ] ../src/host/main.cpp:337             | Registering RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:11:09.468636Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP RPC Client listening on 127.0.0.1:8000
2022-07-22T08:11:09.468642Z        100 [info ] ../src/host/main.cpp:348             | Registered RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:11:09.468697Z        100 [info ] ../src/host/main.cpp:417             | Startup host time: 2022-07-22 08:11:09
2022-07-22T08:11:09.468822Z        100 [info ] ../src/host/main.cpp:465             | Creating new node: new network (with 1 initial member(s) and 1 member(s) required for recovery)
2022-07-22T08:11:09.468828Z        100 [info ] ../src/host/main.cpp:539             | Initialising enclave: enclave_create_node
2022-07-22T08:11:09.669007Z        0   [info ] ./CCF/src/enclave/rpc_sessions.h:223 | Setting max open sessions on interface "primary_rpc_interface" (127.0.0.1:8000) to [1000, 1010] and endorsement authority to Service
2022-07-22T08:11:09.669036Z        0   [info ] ../CCF/src/node/node_state.h:1862    | Node TLS connections now accepted
Azure Quote Provider: libdcap_quoteprov.so [ERROR]: Could not retrieve environment variable for 'AZDCAP_DEBUG_LOG_LEVEL'
2022-07-22T08:11:11.369996Z        0   [info ] ../CCF/src/consensus/aft/raft.h:1862 | Becoming leader n[df8084eb08caaf28720675621d24d2fd3b5a6ab28b7d63584da80c47e08f8a21]: 2
2022-07-22T08:11:11.370031Z        0   [info ] CF/src/node/rpc/node_frontend.h:1416 | Created service
2022-07-22T08:11:11.370163Z        0   [info ] ../CCF/src/node/node_state.h:419     | Created new node n[df8084eb08caaf28720675621d24d2fd3b5a6ab28b7d63584da80c47e08f8a21]
2022-07-22T08:11:11.370203Z        100 [info ] ../src/host/main.cpp:573             | Created new node
2022-07-22T08:11:11.370313Z        100 [info ] ../src/host/main.cpp:579             | Output self-signed node certificate to 0.pem
2022-07-22T08:11:11.370366Z        100 [info ] ../src/host/main.cpp:586             | Output service certificate to service_cert.pem
2022-07-22T08:11:11.370372Z        100 [info ] ../src/host/main.cpp:605             | Starting enclave thread(s)
2022-07-22T08:11:11.370399Z        100 [info ] ../src/host/main.cpp:613             | Entering event loop
2022-07-22T08:11:11.371486Z        0   [info ] ../src/enclave/main.cpp:329          | Starting thread: 0
2022-07-22T08:11:11.371493Z        0   [info ] ../src/enclave/main.cpp:335          | All threads are ready!
2022-07-22T08:11:12.429115Z -0.003 0   [info ] ../CCF/src/consensus/aft/raft.h:571  | Election timer has become active
2022-07-22T08:11:12.429159Z -0.003 0   [info ] ../CCF/src/node/node_state.h:1876    | Network TLS connections now accepted

[eddyashton]

@thempp66 You can add a -v (--verbose) argument to sandbox.sh, and it will print the commands it runs (amongst other things). This will show all of the setup done by the sandbox infra (creating a workspace directory, copying the sample constitution, creating test members for the sandbox service), and eventually the command it uses to start cchost (from the logging command just below the print you added):

$ /opt/ccf/bin/sandbox.sh -v
Setting up Python environment...
...
13:01:50.929 | INFO     | infra.remote:start:484 - [127.0.0.1] cd /data/src/1.CCF/build.debug/workspace/sandbox_0 && ./cchost --config /data/src/1.CCF/build.debug/workspace/sandbox_common/0.config.json 1> /data/src/1.CCF/build.debug/workspace/sandbox_0/out 2> /data/src/1.CCF/build.debug/workspace/sandbox_0/err (env: {})

The only differences I can see between the instance you ran by copying and pasting and this command run by sandbox.sh are the working directory, and the environment variables. The sandbox infra runs each node within its own directory in the workspace (build/workspace/sandbox_0/), whereas by copying and pasting just the command you are running it in the root build/ directory. This is why the 0.pem file generated by running cchost is at build/0.pem, rather than build/workspace/sandbox_0/0.pem. The environment variables generally shouldn't make a difference, but if you see any error related to those you may want to make sure the env you use when invoking cchost manually matches the env set by the sandbox infra.

[thempp66]

@thempp66 You can add a -v (--verbose) argument to sandbox.sh, and it will print the commands it runs (amongst other things). This will show all of the setup done by the sandbox infra (creating a workspace directory, copying the sample constitution, creating test members for the sandbox service), and eventually the command it uses to start cchost (from the logging command just below the print you added):

$ /opt/ccf/bin/sandbox.sh -v
Setting up Python environment...
...
13:01:50.929 | INFO     | infra.remote:start:484 - [127.0.0.1] cd /data/src/1.CCF/build.debug/workspace/sandbox_0 && ./cchost --config /data/src/1.CCF/build.debug/workspace/sandbox_common/0.config.json 1> /data/src/1.CCF/build.debug/workspace/sandbox_0/out 2> /data/src/1.CCF/build.debug/workspace/sandbox_0/err (env: {})

The only differences I can see between the instance you ran by copying and pasting and this command run by sandbox.sh are the working directory, and the environment variables. The sandbox infra runs each node within its own directory in the workspace (build/workspace/sandbox_0/), whereas by copying and pasting just the command you are running it in the root build/ directory. This is why the 0.pem file generated by running cchost is at build/0.pem, rather than build/workspace/sandbox_0/0.pem. The environment variables generally shouldn't make a difference, but if you see any error related to those you may want to make sure the env you use when invoking cchost manually matches the env set by the sandbox infra.

Thanks for your help. I notice that my system environment variables is reset by popen(CCF/tests/infra/remote.py:492)
I need to set SGX_AESM_ADDR=1(which is already set in runtime environment variables by export command). So, is there any suggestions I can use to pass value for setting env in a friendly way? Or let the environment variables work?
@eddyashton

[achamayou]

@thempp66 you would need to modify the testing infra itself. The current logic deliberately does not propagate external environment variables to make tests as deterministic as possible.

Sorry for the late answer, I assume this is no longer a ongoing concern, and so I am closing the ticket.

[thempp66]

@thempp66 you would need to modify the testing infra itself. The current logic deliberately does not propagate external environment variables to make tests as deterministic as possible.

Sorry for the late answer, I assume this is no longer a ongoing concern, and so I am closing the ticket.

OK, thanks!

[thempp66]

This is the output by using sandbox.sh

2022-07-22T08:10:06.470185Z        100 [info ] ../src/host/main.cpp:108             | CCF version: ccf-2.0.0-rc1-285-gb21c9810
2022-07-22T08:10:06.470239Z        100 [info ] ../src/host/main.cpp:117             | Check Ethereum Gateway
2022-07-22T08:10:06.470250Z        100 [info ] ../src/host/main.cpp:123             | Gateway endpoint: 127.0.0.1:8545
2022-07-22T08:10:06.771433Z        100 [info ] ../src/host/main.cpp:159             | Recovery threshold unset. Defaulting to number of initial consortium members with a public encryption key (1).
2022-07-22T08:10:07.211706Z        100 [info ] ../CCF/src/host/ledger.h:1021        | Recovered ledger entries up to 0, committed to 0
2022-07-22T08:10:07.211815Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP Node Server listening on 127.0.0.1:44259
2022-07-22T08:10:07.211889Z        100 [info ] ../src/host/main.cpp:337             | Registering RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:10:07.211904Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP RPC Client listening on 127.0.0.1:8000
2022-07-22T08:10:07.211911Z        100 [info ] ../src/host/main.cpp:348             | Registered RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:10:07.211961Z        100 [info ] ../src/host/main.cpp:417             | Startup host time: 2022-07-22 08:10:07
2022-07-22T08:10:07.212082Z        100 [info ] ../src/host/main.cpp:465             | Creating new node: new network (with 1 initial member(s) and 1 member(s) required for recovery)
2022-07-22T08:10:07.212088Z        100 [info ] ../src/host/main.cpp:539             | Initialising enclave: enclave_create_node
2022-07-22T08:10:07.312432Z        0   [info ] ./CCF/src/enclave/rpc_sessions.h:223 | Setting max open sessions on interface "primary_rpc_interface" (127.0.0.1:8000) to [1000, 1010] and endorsement authority to Service
2022-07-22T08:10:07.312457Z        0   [info ] ../CCF/src/node/node_state.h:1862    | Node TLS connections now accepted

And this is the output by using command line

2022-07-22T08:11:08.721549Z        100 [info ] ../src/host/main.cpp:108             | CCF version: ccf-2.0.0-rc1-285-gb21c9810
2022-07-22T08:11:08.721601Z        100 [info ] ../src/host/main.cpp:117             | Check Ethereum Gateway
2022-07-22T08:11:08.721615Z        100 [info ] ../src/host/main.cpp:123             | Gateway endpoint: 127.0.0.1:8545
2022-07-22T08:11:09.022790Z        100 [info ] ../src/host/main.cpp:159             | Recovery threshold unset. Defaulting to number of initial consortium members with a public encryption key (1).
2022-07-22T08:11:09.468343Z        100 [info ] ../CCF/src/host/ledger.h:1021        | Recovered ledger entries up to 0, committed to 0
2022-07-22T08:11:09.468376Z        100 [info ] ../CCF/src/host/snapshots.h:216      | Snapshots will be stored in existing directory: "0.snapshots"
2022-07-22T08:11:09.468386Z        100 [info ] ./CCF/src/host/lfs_file_handler.h:23 | Clearing contents from existing directory ".index"
2022-07-22T08:11:09.468521Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP Node Server listening on 127.0.0.1:45521
2022-07-22T08:11:09.468617Z        100 [info ] ../src/host/main.cpp:337             | Registering RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:11:09.468636Z        100 [info ] ../CCF/src/host/socket.h:45          | TCP RPC Client listening on 127.0.0.1:8000
2022-07-22T08:11:09.468642Z        100 [info ] ../src/host/main.cpp:348             | Registered RPC interface primary_rpc_interface, on tcp 127.0.0.1:8000
2022-07-22T08:11:09.468697Z        100 [info ] ../src/host/main.cpp:417             | Startup host time: 2022-07-22 08:11:09
2022-07-22T08:11:09.468822Z        100 [info ] ../src/host/main.cpp:465             | Creating new node: new network (with 1 initial member(s) and 1 member(s) required for recovery)
2022-07-22T08:11:09.468828Z        100 [info ] ../src/host/main.cpp:539             | Initialising enclave: enclave_create_node
2022-07-22T08:11:09.669007Z        0   [info ] ./CCF/src/enclave/rpc_sessions.h:223 | Setting max open sessions on interface "primary_rpc_interface" (127.0.0.1:8000) to [1000, 1010] and endorsement authority to Service
2022-07-22T08:11:09.669036Z        0   [info ] ../CCF/src/node/node_state.h:1862    | Node TLS connections now accepted
Azure Quote Provider: libdcap_quoteprov.so [ERROR]: Could not retrieve environment variable for 'AZDCAP_DEBUG_LOG_LEVEL'
2022-07-22T08:11:11.369996Z        0   [info ] ../CCF/src/consensus/aft/raft.h:1862 | Becoming leader n[df8084eb08caaf28720675621d24d2fd3b5a6ab28b7d63584da80c47e08f8a21]: 2
2022-07-22T08:11:11.370031Z        0   [info ] CF/src/node/rpc/node_frontend.h:1416 | Created service
2022-07-22T08:11:11.370163Z        0   [info ] ../CCF/src/node/node_state.h:419     | Created new node n[df8084eb08caaf28720675621d24d2fd3b5a6ab28b7d63584da80c47e08f8a21]
2022-07-22T08:11:11.370203Z        100 [info ] ../src/host/main.cpp:573             | Created new node
2022-07-22T08:11:11.370313Z        100 [info ] ../src/host/main.cpp:579             | Output self-signed node certificate to 0.pem
2022-07-22T08:11:11.370366Z        100 [info ] ../src/host/main.cpp:586             | Output service certificate to service_cert.pem
2022-07-22T08:11:11.370372Z        100 [info ] ../src/host/main.cpp:605             | Starting enclave thread(s)
2022-07-22T08:11:11.370399Z        100 [info ] ../src/host/main.cpp:613             | Entering event loop
2022-07-22T08:11:11.371486Z        0   [info ] ../src/enclave/main.cpp:329          | Starting thread: 0
2022-07-22T08:11:11.371493Z        0   [info ] ../src/enclave/main.cpp:335          | All threads are ready!
2022-07-22T08:11:12.429115Z -0.003 0   [info ] ../CCF/src/consensus/aft/raft.h:571  | Election timer has become active
2022-07-22T08:11:12.429159Z -0.003 0   [info ] ../CCF/src/node/node_state.h:1876    | Network TLS connections now accepted

[eddyashton]

@thempp66 You can add a -v (--verbose) argument to sandbox.sh, and it will print the commands it runs (amongst other things). This will show all of the setup done by the sandbox infra (creating a workspace directory, copying the sample constitution, creating test members for the sandbox service), and eventually the command it uses to start cchost (from the logging command just below the print you added):

$ /opt/ccf/bin/sandbox.sh -v
Setting up Python environment...
...
13:01:50.929 | INFO     | infra.remote:start:484 - [127.0.0.1] cd /data/src/1.CCF/build.debug/workspace/sandbox_0 && ./cchost --config /data/src/1.CCF/build.debug/workspace/sandbox_common/0.config.json 1> /data/src/1.CCF/build.debug/workspace/sandbox_0/out 2> /data/src/1.CCF/build.debug/workspace/sandbox_0/err (env: {})

The only differences I can see between the instance you ran by copying and pasting and this command run by sandbox.sh are the working directory, and the environment variables. The sandbox infra runs each node within its own directory in the workspace (build/workspace/sandbox_0/), whereas by copying and pasting just the command you are running it in the root build/ directory. This is why the 0.pem file generated by running cchost is at build/0.pem, rather than build/workspace/sandbox_0/0.pem. The environment variables generally shouldn't make a difference, but if you see any error related to those you may want to make sure the env you use when invoking cchost manually matches the env set by the sandbox infra.

[thempp66]

@thempp66 You can add a -v (--verbose) argument to sandbox.sh, and it will print the commands it runs (amongst other things). This will show all of the setup done by the sandbox infra (creating a workspace directory, copying the sample constitution, creating test members for the sandbox service), and eventually the command it uses to start cchost (from the logging command just below the print you added):

$ /opt/ccf/bin/sandbox.sh -v
Setting up Python environment...
...
13:01:50.929 | INFO     | infra.remote:start:484 - [127.0.0.1] cd /data/src/1.CCF/build.debug/workspace/sandbox_0 && ./cchost --config /data/src/1.CCF/build.debug/workspace/sandbox_common/0.config.json 1> /data/src/1.CCF/build.debug/workspace/sandbox_0/out 2> /data/src/1.CCF/build.debug/workspace/sandbox_0/err (env: {})

The only differences I can see between the instance you ran by copying and pasting and this command run by sandbox.sh are the working directory, and the environment variables. The sandbox infra runs each node within its own directory in the workspace (build/workspace/sandbox_0/), whereas by copying and pasting just the command you are running it in the root build/ directory. This is why the 0.pem file generated by running cchost is at build/0.pem, rather than build/workspace/sandbox_0/0.pem. The environment variables generally shouldn't make a difference, but if you see any error related to those you may want to make sure the env you use when invoking cchost manually matches the env set by the sandbox infra.

Thanks for your help. I notice that my system environment variables is reset by popen(CCF/tests/infra/remote.py:492)
I need to set SGX_AESM_ADDR=1(which is already set in runtime environment variables by export command). So, is there any suggestions I can use to pass value for setting env in a friendly way? Or let the environment variables work?
@eddyashton

[achamayou]

@thempp66 you would need to modify the testing infra itself. The current logic deliberately does not propagate external environment variables to make tests as deterministic as possible.

Sorry for the late answer, I assume this is no longer a ongoing concern, and so I am closing the ticket.

[thempp66]

@thempp66 you would need to modify the testing infra itself. The current logic deliberately does not propagate external environment variables to make tests as deterministic as possible.

Sorry for the late answer, I assume this is no longer a ongoing concern, and so I am closing the ticket.

OK, thanks!